Commit f136b330 authored by Antony Lee's avatar Antony Lee
Browse files

Profilers controllable via PYQTGRAPHPROFILE.

A new function profiling system is implemented.  Most importantly, this
allows one to profile various internal functions directly by setting the
`PYQTGRAPHPROFILE` environment variable to a comma separated list of
function and method names, e.g.

    PYQTGRAPHPROFILE=functions.makeARGB,ImageItem.render \
        python -mexamples

Specifically, items in `PYQTGRAPHPROFILE` must be of the form
`classname.methodname` or `dotted_module_name.functionname`, with the
initial "pyqtgraph." stripped from the dotted module name.

Moreover, the overhead of inactive profilers has been kept minimal: an
introspective check of the caller's name (only if `PYQTGRAPHPROFILE` is
set) and a trivial function (not method) call per profiler call.

The new profilers rely on `sys._getframe` to find the caller's name,
although the previous system (passing the caller's name explicitely)
could certainly have been kept instead.

Finally the API of profilers has been changed: register a
profiling point simply by calling the profiler, and profilers are
automatically flushed on garbage collection.  See the docstring of
`pyqtgraph.debug.Profiler` for more details.
parent c1f72b29
......@@ -5,6 +5,8 @@ Copyright 2010 Luke Campagnola
Distributed under MIT/X11 license. See license.txt for more infomation.
"""
from __future__ import print_function
import sys, traceback, time, gc, re, types, weakref, inspect, os, cProfile
from . import ptime
from numpy import ndarray
......@@ -365,84 +367,99 @@ class GarbageWatcher(object):
return self.objs[item]
class Profiler:
class Profiler(object):
"""Simple profiler allowing measurement of multiple time intervals.
Arguments:
msg: message to print at start and finish of profiling
disabled: If true, profiler does nothing (so you can leave it in place)
delayed: If true, all messages are printed after call to finish()
(this can result in more accurate time step measurements)
globalDelay: if True, all nested profilers delay printing until the top level finishes
By default, profilers are disabled. To enable profiling, set the
environment variable `PYQTGRAPHPROFILE` to a comma-separated list of
fully-qualified names of profiled functions.
Calling a profiler registers a message (defaulting to an increasing
counter) that contains the time elapsed since the last call. When the
profiler is about to be garbage-collected, the messages are passed to the
outer profiler if one is running, or printed to stdout otherwise.
If `delayed` is set to False, messages are immediately printed instead.
Example:
prof = Profiler('Function')
... do stuff ...
prof.mark('did stuff')
... do other stuff ...
prof.mark('did other stuff')
prof.finish()
def function(...):
profiler = Profiler()
... do stuff ...
profiler('did stuff')
... do other stuff ...
profiler('did other stuff')
# profiler is garbage-collected and flushed at function end
If this function is a method of class C, setting `PYQTGRAPHPROFILE` to
"C.function" (without the module name) will enable this profiler.
For regular functions, use the qualified name of the function, stripping
only the initial "pyqtgraph." prefix from the module.
"""
depth = 0
msgs = []
def __init__(self, msg="Profiler", disabled=False, delayed=True, globalDelay=True):
self.disabled = disabled
if disabled:
return
self.markCount = 0
self.finished = False
self.depth = Profiler.depth
Profiler.depth += 1
if not globalDelay:
self.msgs = []
self.delayed = delayed
self.msg = " "*self.depth + msg
msg2 = self.msg + " >>> Started"
if self.delayed:
self.msgs.append(msg2)
else:
print(msg2)
self.t0 = ptime.time()
self.t1 = self.t0
def mark(self, msg=None):
if self.disabled:
return
_profilers = os.environ.get("PYQTGRAPHPROFILE", "")
_depth = 0
_msgs = []
if _profilers:
_profilers = _profilers.split(",")
def __new__(cls, delayed=True):
"""Optionally create a new profiler based on caller's qualname.
"""
# determine the qualified name of the caller function
caller_frame = sys._getframe(1)
try:
caller_object_type = type(caller_frame.f_locals["self"])
except KeyError: # we are in a regular function
qualifier = caller_frame.f_globals["__name__"].split(".", 1)[1]
else: # we are in a method
qualifier = caller_object_type.__name__
func_qualname = qualifier + "." + caller_frame.f_code.co_name
if func_qualname not in cls._profilers: # don't do anything
return lambda msg=None: None
# create an actual profiling object
cls._depth += 1
obj = super(Profiler, cls).__new__(cls)
obj._name = func_qualname
obj._delayed = delayed
obj._markCount = 0
obj._firstTime = obj._lastTime = ptime.time()
obj._newMsg("> Entering " + func_qualname)
return obj
else:
def __new__(cls, delayed=True):
return lambda msg=None: None
def __call__(self, msg=None):
"""Register or print a new message with timing information.
"""
if msg is None:
msg = str(self.markCount)
self.markCount += 1
t1 = ptime.time()
msg2 = " "+self.msg+" "+msg+" "+"%gms" % ((t1-self.t1)*1000)
if self.delayed:
self.msgs.append(msg2)
else:
print(msg2)
self.t1 = ptime.time() ## don't measure time it took to print
def finish(self, msg=None):
if self.disabled or self.finished:
return
if msg is not None:
self.mark(msg)
t1 = ptime.time()
msg = self.msg + ' <<< Finished, total time: %gms' % ((t1-self.t0)*1000)
if self.delayed:
self.msgs.append(msg)
if self.depth == 0:
for line in self.msgs:
print(line)
Profiler.msgs = []
msg = str(self._markCount)
self._markCount += 1
newTime = ptime.time()
self._newMsg(
msg + ": " + str((newTime - self._lastTime) * 1000) + "ms")
self._lastTime = newTime
def _newMsg(self, msg):
msg = " " * (self._depth - 1) + msg
if self._delayed:
self._msgs.append(msg)
else:
print(msg)
Profiler.depth = self.depth
self.finished = True
def __del__(self):
"""Add a final message; flush the message list if no parent profiler.
"""
self._newMsg("< Exiting " + self._name + ", total time: " +
str((ptime.time() - self._firstTime) * 1000) + "ms")
type(self)._depth -= 1
if not self._depth and self._msgs:
print("\n".join(self._msgs))
type(self)._msgs = []
def profile(code, name='profile_run', sort='cumulative', num=30):
"""Common-use for cProfile"""
......@@ -943,4 +960,4 @@ class PrintDetector(object):
traceback.print_stack()
def flush(self):
self.stdout.flush()
\ No newline at end of file
self.stdout.flush()
......@@ -156,7 +156,7 @@ def _generateItemSvg(item, nodes=None, root=None):
##
## Both 2 and 3 can be addressed by drawing all items in world coordinates.
prof = pg.debug.Profiler('generateItemSvg %s' % str(item), disabled=True)
profiler = pg.debug.Profiler()
if nodes is None: ## nodes maps all node IDs to their XML element.
## this allows us to ensure all elements receive unique names.
......@@ -235,12 +235,12 @@ def _generateItemSvg(item, nodes=None, root=None):
print(doc.toxml())
raise
prof.mark('render')
profiler('render')
## Get rid of group transformation matrices by applying
## transformation to inner coordinates
correctCoordinates(g1, item)
prof.mark('correct')
profiler('correct')
## make sure g1 has the transformation matrix
#m = (tr.m11(), tr.m12(), tr.m21(), tr.m22(), tr.m31(), tr.m32())
#g1.setAttribute('transform', "matrix(%f,%f,%f,%f,%f,%f)" % m)
......@@ -290,7 +290,7 @@ def _generateItemSvg(item, nodes=None, root=None):
childGroup = g1.ownerDocument.createElement('g')
childGroup.setAttribute('clip-path', 'url(#%s)' % clip)
g1.appendChild(childGroup)
prof.mark('clipping')
profiler('clipping')
## Add all child items as sub-elements.
childs.sort(key=lambda c: c.zValue())
......@@ -299,8 +299,7 @@ def _generateItemSvg(item, nodes=None, root=None):
if cg is None:
continue
childGroup.appendChild(cg) ### this isn't quite right--some items draw below their parent (good enough for now)
prof.mark('children')
prof.finish()
profiler('children')
return g1
def correctCoordinates(node, item):
......
......@@ -775,7 +775,7 @@ def makeARGB(data, lut=None, levels=None, scale=None, useRGBA=False):
is BGRA).
============ ==================================================================================
"""
prof = debug.Profiler('functions.makeARGB', disabled=True)
profile = debug.Profiler()
if lut is not None and not isinstance(lut, np.ndarray):
lut = np.array(lut)
......@@ -794,8 +794,8 @@ def makeARGB(data, lut=None, levels=None, scale=None, useRGBA=False):
else:
print(levels)
raise Exception("levels argument must be 1D or 2D.")
prof.mark('1')
profile()
if scale is None:
if lut is not None:
......@@ -822,8 +822,8 @@ def makeARGB(data, lut=None, levels=None, scale=None, useRGBA=False):
if minVal == maxVal:
maxVal += 1e-16
data = rescaleData(data, scale/(maxVal-minVal), minVal, dtype=int)
prof.mark('2')
profile()
## apply LUT if given
if lut is not None:
......@@ -831,13 +831,13 @@ def makeARGB(data, lut=None, levels=None, scale=None, useRGBA=False):
else:
if data.dtype is not np.ubyte:
data = np.clip(data, 0, 255).astype(np.ubyte)
prof.mark('3')
profile()
## copy data into ARGB ordered array
imgData = np.empty(data.shape[:2]+(4,), dtype=np.ubyte)
prof.mark('4')
profile()
if useRGBA:
order = [0,1,2,3] ## array comes out RGBA
......@@ -857,7 +857,7 @@ def makeARGB(data, lut=None, levels=None, scale=None, useRGBA=False):
for i in range(0, data.shape[2]):
imgData[..., i] = data[..., order[i]]
prof.mark('5')
profile()
if data.ndim == 2 or data.shape[2] == 3:
alpha = False
......@@ -865,11 +865,9 @@ def makeARGB(data, lut=None, levels=None, scale=None, useRGBA=False):
else:
alpha = True
prof.mark('6')
prof.finish()
profile()
return imgData, alpha
def makeQImage(imgData, alpha=None, copy=True, transpose=True):
"""
......@@ -898,7 +896,7 @@ def makeQImage(imgData, alpha=None, copy=True, transpose=True):
=========== ===================================================================
"""
## create QImage from buffer
prof = debug.Profiler('functions.makeQImage', disabled=True)
profile = debug.Profiler()
## If we didn't explicitly specify alpha, check the array shape.
if alpha is None:
......@@ -922,7 +920,9 @@ def makeQImage(imgData, alpha=None, copy=True, transpose=True):
if transpose:
imgData = imgData.transpose((1, 0, 2)) ## QImage expects the row/column order to be opposite
profile()
if not imgData.flags['C_CONTIGUOUS']:
if copy is False:
extra = ' (try setting transpose=False)' if transpose else ''
......@@ -963,11 +963,10 @@ def makeQImage(imgData, alpha=None, copy=True, transpose=True):
#except AttributeError: ## happens when image data is non-contiguous
#buf = imgData.data
#prof.mark('1')
#profiler()
#qimage = QtGui.QImage(buf, imgData.shape[1], imgData.shape[0], imgFormat)
#prof.mark('2')
#profiler()
#qimage.data = imgData
#prof.finish()
#return qimage
def imageToArray(img, copy=False, transpose=True):
......@@ -1087,16 +1086,16 @@ def arrayToQPath(x, y, connect='all'):
path = QtGui.QPainterPath()
#prof = debug.Profiler('PlotCurveItem.generatePath', disabled=True)
#profiler = debug.Profiler()
n = x.shape[0]
# create empty array, pad with extra space on either end
arr = np.empty(n+2, dtype=[('x', '>f8'), ('y', '>f8'), ('c', '>i4')])
# write first two integers
#prof.mark('allocate empty')
#profiler('allocate empty')
byteview = arr.view(dtype=np.ubyte)
byteview[:12] = 0
byteview.data[12:20] = struct.pack('>ii', n, 0)
#prof.mark('pack header')
#profiler('pack header')
# Fill array with vertex values
arr[1:-1]['x'] = x
arr[1:-1]['y'] = y
......@@ -1117,11 +1116,11 @@ def arrayToQPath(x, y, connect='all'):
else:
raise Exception('connect argument must be "all", "pairs", or array')
#prof.mark('fill array')
#profiler('fill array')
# write last 0
lastInd = 20*(n+1)
byteview.data[lastInd:lastInd+4] = struct.pack('>i', 0)
#prof.mark('footer')
#profiler('footer')
# create datastream object and stream into path
## Avoiding this method because QByteArray(str) leaks memory in PySide
......@@ -1132,13 +1131,11 @@ def arrayToQPath(x, y, connect='all'):
buf = QtCore.QByteArray.fromRawData(path.strn)
except TypeError:
buf = QtCore.QByteArray(bytes(path.strn))
#prof.mark('create buffer')
#profiler('create buffer')
ds = QtCore.QDataStream(buf)
ds >> path
#prof.mark('load')
#prof.finish()
#profiler('load')
return path
......@@ -1865,7 +1862,7 @@ def isosurface(data, level):
faces = np.empty((totFaces, 3), dtype=np.uint32)
ptr = 0
#import debug
#p = debug.Profiler('isosurface', disabled=False)
#p = debug.Profiler()
## this helps speed up an indexing operation later on
cs = np.array(cutEdges.strides)//cutEdges.itemsize
......@@ -1877,32 +1874,32 @@ def isosurface(data, level):
for i in range(1,6):
### expensive:
#p.mark('1')
#profiler()
cells = np.argwhere(nFaces == i) ## all cells which require i faces (argwhere is expensive)
#p.mark('2')
#profiler()
if cells.shape[0] == 0:
continue
#cellInds = index[(cells*ins[np.newaxis,:]).sum(axis=1)]
cellInds = index[cells[:,0], cells[:,1], cells[:,2]] ## index values of cells to process for this round
#p.mark('3')
#profiler()
### expensive:
verts = faceShiftTables[i][cellInds]
#p.mark('4')
#profiler()
verts[...,:3] += cells[:,np.newaxis,np.newaxis,:] ## we now have indexes into cutEdges
verts = verts.reshape((verts.shape[0]*i,)+verts.shape[2:])
#p.mark('5')
#profiler()
### expensive:
#print verts.shape
verts = (verts * cs[np.newaxis, np.newaxis, :]).sum(axis=2)
#vertInds = cutEdges[verts[...,0], verts[...,1], verts[...,2], verts[...,3]] ## and these are the vertex indexes we want.
vertInds = cutEdges[verts]
#p.mark('6')
#profiler()
nv = vertInds.shape[0]
#p.mark('7')
#profiler()
faces[ptr:ptr+nv] = vertInds #.reshape((nv, 3))
#p.mark('8')
#profiler()
ptr += nv
return vertexes, faces
......
......@@ -404,25 +404,22 @@ class AxisItem(GraphicsWidget):
return self.mapRectFromParent(self.geometry()) | linkedView.mapRectToItem(self, linkedView.boundingRect())
def paint(self, p, opt, widget):
prof = debug.Profiler('AxisItem.paint', disabled=True)
profiler = debug.Profiler()
if self.picture is None:
try:
picture = QtGui.QPicture()
painter = QtGui.QPainter(picture)
specs = self.generateDrawSpecs(painter)
prof.mark('generate specs')
profiler('generate specs')
if specs is not None:
self.drawPicture(painter, *specs)
prof.mark('draw picture')
profiler('draw picture')
finally:
painter.end()
self.picture = picture
#p.setRenderHint(p.Antialiasing, False) ## Sometimes we get a segfault here ???
#p.setRenderHint(p.TextAntialiasing, True)
self.picture.play(p)
prof.finish()
def setTicks(self, ticks):
"""Explicitly determine which ticks to display.
......@@ -626,8 +623,8 @@ class AxisItem(GraphicsWidget):
be drawn, then generates from this a set of drawing commands to be
interpreted by drawPicture().
"""
prof = debug.Profiler("AxisItem.generateDrawSpecs", disabled=True)
profiler = debug.Profiler()
#bounds = self.boundingRect()
bounds = self.mapRectFromParent(self.geometry())
......@@ -706,7 +703,7 @@ class AxisItem(GraphicsWidget):
xMin = min(xRange)
xMax = max(xRange)
prof.mark('init')
profiler('init')
tickPositions = [] # remembers positions of previously drawn ticks
......@@ -744,7 +741,7 @@ class AxisItem(GraphicsWidget):
color.setAlpha(lineAlpha)
tickPen.setColor(color)
tickSpecs.append((tickPen, Point(p1), Point(p2)))
prof.mark('compute ticks')
profiler('compute ticks')
## This is where the long axis line should be drawn
......@@ -857,7 +854,7 @@ class AxisItem(GraphicsWidget):
#p.setPen(self.pen())
#p.drawText(rect, textFlags, vstr)
textSpecs.append((rect, textFlags, vstr))
prof.mark('compute text')
profiler('compute text')
## update max text size if needed.
self._updateMaxTextSize(textSize2)
......@@ -865,8 +862,8 @@ class AxisItem(GraphicsWidget):
return (axisSpec, tickSpecs, textSpecs)
def drawPicture(self, p, axisSpec, tickSpecs, textSpecs):
prof = debug.Profiler("AxisItem.drawPicture", disabled=True)
profiler = debug.Profiler()
p.setRenderHint(p.Antialiasing, False)
p.setRenderHint(p.TextAntialiasing, True)
......@@ -880,8 +877,8 @@ class AxisItem(GraphicsWidget):
for pen, p1, p2 in tickSpecs:
p.setPen(pen)
p.drawLine(p1, p2)
prof.mark('draw ticks')
profiler('draw ticks')
## Draw all text
if self.tickFont is not None:
p.setFont(self.tickFont)
......@@ -889,10 +886,8 @@ class AxisItem(GraphicsWidget):
for rect, flags, text in textSpecs:
p.drawText(rect, flags, text)
#p.drawRect(rect)
prof.mark('draw text')
prof.finish()
profiler('draw text')
def show(self):
if self.orientation in ['left', 'right']:
......
......@@ -184,19 +184,18 @@ class HistogramLUTItem(GraphicsWidget):
self.update()
def imageChanged(self, autoLevel=False, autoRange=False):
prof = debug.Profiler('HistogramLUTItem.imageChanged', disabled=True)
profiler = debug.Profiler()
h = self.imageItem.getHistogram()
prof.mark('get histogram')
profiler('get histogram')
if h[0] is None:
return
self.plot.setData(*h)
prof.mark('set plot')
profiler('set plot')
if autoLevel:
mn = h[0][0]
mx = h[0][-1]
self.region.setRegion([mn, mx])
prof.mark('set region')
prof.finish()
profiler('set region')
def getLevels(self):
return self.region.getRegion()
......
......@@ -188,8 +188,8 @@ class ImageItem(GraphicsObject):
border Sets the pen used when drawing the image border. Default is None.
================= =========================================================================
"""
prof = debug.Profiler('ImageItem.setImage', disabled=True)
profile = debug.Profiler()
gotNewData = False
if image is None:
if self.image is None:
......@@ -201,9 +201,9 @@ class ImageItem(GraphicsObject):
if shapeChanged:
self.prepareGeometryChange()
self.informViewBoundsChanged()
prof.mark('1')
profile()
if autoLevels is None:
if 'levels' in kargs:
autoLevels = False
......@@ -218,23 +218,22 @@ class ImageItem(GraphicsObject):
mn = 0
mx = 255
kargs['levels'] = [mn,mx]
prof.mark('2')
profile()
self.setOpts(update=False, **kargs)
prof.mark('3')
profile()
self.qimage = None
self.update()
prof.mark('4')
profile()
if gotNewData:
self.sigImageChanged.emit()
prof.finish()
def updateImage(self, *args, **kargs):
## used for re-rendering qimage from self.image.
......@@ -250,7 +249,7 @@ class ImageItem(GraphicsObject):
def render(self):
prof = debug.Profiler('ImageItem.render', disabled=True)
profile = debug.Profiler()
if self.image is None or self.image.size == 0:
return
if isinstance(self.lut, collections.Callable):
......@@ -262,28 +261,25 @@ class ImageItem(GraphicsObject):
argb, alpha = fn.makeARGB(self.image.transpose((1, 0, 2)[:self.image.ndim]), lut=lut, levels=self.levels)
self.qimage = fn.makeQImage(argb, alpha, transpose=False)
prof.finish()