From f136b330334aecbef4d37ebaf7b0f1c607241a9e Mon Sep 17 00:00:00 2001 From: Antony Lee Date: Tue, 26 Nov 2013 22:16:13 -0800 Subject: [PATCH 1/2] 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. --- pyqtgraph/debug.py | 163 ++++++++++--------- pyqtgraph/exporters/SVGExporter.py | 11 +- pyqtgraph/functions.py | 65 ++++---- pyqtgraph/graphicsItems/AxisItem.py | 33 ++-- pyqtgraph/graphicsItems/HistogramLUTItem.py | 9 +- pyqtgraph/graphicsItems/ImageItem.py | 42 +++-- pyqtgraph/graphicsItems/LinearRegionItem.py | 3 +- pyqtgraph/graphicsItems/PlotCurveItem.py | 24 ++- pyqtgraph/graphicsItems/PlotDataItem.py | 12 +- pyqtgraph/graphicsItems/PlotItem/PlotItem.py | 3 +- pyqtgraph/graphicsItems/ScatterPlotItem.py | 9 +- pyqtgraph/graphicsItems/ViewBox/ViewBox.py | 9 +- pyqtgraph/imageview/ImageView.py | 34 ++-- 13 files changed, 203 insertions(+), 214 deletions(-) diff --git a/pyqtgraph/debug.py b/pyqtgraph/debug.py index a175be9c..0ee65a33 100644 --- a/pyqtgraph/debug.py +++ b/pyqtgraph/debug.py @@ -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() diff --git a/pyqtgraph/exporters/SVGExporter.py b/pyqtgraph/exporters/SVGExporter.py index 62b49d30..19a7a6a7 100644 --- a/pyqtgraph/exporters/SVGExporter.py +++ b/pyqtgraph/exporters/SVGExporter.py @@ -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): diff --git a/pyqtgraph/functions.py b/pyqtgraph/functions.py index 3e16fe48..80e61404 100644 --- a/pyqtgraph/functions.py +++ b/pyqtgraph/functions.py @@ -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 diff --git a/pyqtgraph/graphicsItems/AxisItem.py b/pyqtgraph/graphicsItems/AxisItem.py index 429ff49c..3dd98cef 100644 --- a/pyqtgraph/graphicsItems/AxisItem.py +++ b/pyqtgraph/graphicsItems/AxisItem.py @@ -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']: diff --git a/pyqtgraph/graphicsItems/HistogramLUTItem.py b/pyqtgraph/graphicsItems/HistogramLUTItem.py index 5a3b63d6..70d8662f 100644 --- a/pyqtgraph/graphicsItems/HistogramLUTItem.py +++ b/pyqtgraph/graphicsItems/HistogramLUTItem.py @@ -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() diff --git a/pyqtgraph/graphicsItems/ImageItem.py b/pyqtgraph/graphicsItems/ImageItem.py index 5c4a09ef..f7a211d9 100644 --- a/pyqtgraph/graphicsItems/ImageItem.py +++ b/pyqtgraph/graphicsItems/ImageItem.py @@ -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() - def paint(self, p, *args): - prof = debug.Profiler('ImageItem.paint', disabled=True) + profile = debug.Profiler() if self.image is None: return if self.qimage is None: self.render() if self.qimage is None: return - prof.mark('render QImage') + profile('render QImage') if self.paintMode is not None: p.setCompositionMode(self.paintMode) - prof.mark('set comp mode') - + profile('set comp mode') + p.drawImage(QtCore.QPointF(0,0), self.qimage) - prof.mark('p.drawImage') + profile('p.drawImage') if self.border is not None: p.setPen(self.border) p.drawRect(self.boundingRect()) - prof.finish() def save(self, fileName, *args): """Save this image to file. Note that this saves the visible image (after scale/color changes), not the original data.""" diff --git a/pyqtgraph/graphicsItems/LinearRegionItem.py b/pyqtgraph/graphicsItems/LinearRegionItem.py index a35e8efc..08f7e198 100644 --- a/pyqtgraph/graphicsItems/LinearRegionItem.py +++ b/pyqtgraph/graphicsItems/LinearRegionItem.py @@ -140,12 +140,11 @@ class LinearRegionItem(UIGraphicsItem): return br.normalized() def paint(self, p, *args): - #prof = debug.Profiler('LinearRegionItem.paint') + profiler = debug.Profiler() UIGraphicsItem.paint(self, p, *args) p.setBrush(self.currentBrush) p.setPen(fn.mkPen(None)) p.drawRect(self.boundingRect()) - #prof.finish() def dataBounds(self, axis, frac=1.0, orthoRange=None): if axis == self.orientation: diff --git a/pyqtgraph/graphicsItems/PlotCurveItem.py b/pyqtgraph/graphicsItems/PlotCurveItem.py index 28214552..7ee06338 100644 --- a/pyqtgraph/graphicsItems/PlotCurveItem.py +++ b/pyqtgraph/graphicsItems/PlotCurveItem.py @@ -281,7 +281,7 @@ class PlotCurveItem(GraphicsObject): self.updateData(*args, **kargs) def updateData(self, *args, **kargs): - prof = debug.Profiler('PlotCurveItem.updateData', disabled=True) + profiler = debug.Profiler() if len(args) == 1: kargs['y'] = args[0] @@ -304,7 +304,7 @@ class PlotCurveItem(GraphicsObject): if 'complex' in str(data.dtype): raise Exception("Can not plot complex data types.") - prof.mark("data checks") + profiler("data checks") #self.setCacheMode(QtGui.QGraphicsItem.NoCache) ## Disabling and re-enabling the cache works around a bug in Qt 4.6 causing the cached results to display incorrectly ## Test this bug with test_PlotWidget and zoom in on the animated plot @@ -314,7 +314,7 @@ class PlotCurveItem(GraphicsObject): self.yData = kargs['y'].view(np.ndarray) self.xData = kargs['x'].view(np.ndarray) - prof.mark('copy') + profiler('copy') if 'stepMode' in kargs: self.opts['stepMode'] = kargs['stepMode'] @@ -346,12 +346,11 @@ class PlotCurveItem(GraphicsObject): self.opts['antialias'] = kargs['antialias'] - prof.mark('set') + profiler('set') self.update() - prof.mark('update') + profiler('update') self.sigPlotChanged.emit(self) - prof.mark('emit') - prof.finish() + profiler('emit') def generatePath(self, x, y): if self.opts['stepMode']: @@ -387,7 +386,7 @@ class PlotCurveItem(GraphicsObject): @pg.debug.warnOnException ## raising an exception here causes crash def paint(self, p, opt, widget): - prof = debug.Profiler('PlotCurveItem.paint '+str(id(self)), disabled=True) + profiler = debug.Profiler() if self.xData is None: return @@ -405,7 +404,7 @@ class PlotCurveItem(GraphicsObject): self.fillPath = None path = self.path - prof.mark('generate path') + profiler('generate path') if self._exportOpts is not False: aa = self._exportOpts.get('antialias', True) @@ -426,9 +425,9 @@ class PlotCurveItem(GraphicsObject): p2.closeSubpath() self.fillPath = p2 - prof.mark('generate fill path') + profiler('generate fill path') p.fillPath(self.fillPath, self.opts['brush']) - prof.mark('draw fill path') + profiler('draw fill path') sp = fn.mkPen(self.opts['shadowPen']) cp = fn.mkPen(self.opts['pen']) @@ -451,10 +450,9 @@ class PlotCurveItem(GraphicsObject): p.drawPath(path) p.setPen(cp) p.drawPath(path) - prof.mark('drawPath') + profiler('drawPath') #print "Render hints:", int(p.renderHints()) - prof.finish() #p.setPen(QtGui.QPen(QtGui.QColor(255,0,0))) #p.drawRect(self.boundingRect()) diff --git a/pyqtgraph/graphicsItems/PlotDataItem.py b/pyqtgraph/graphicsItems/PlotDataItem.py index 87b47227..2235711c 100644 --- a/pyqtgraph/graphicsItems/PlotDataItem.py +++ b/pyqtgraph/graphicsItems/PlotDataItem.py @@ -333,7 +333,7 @@ class PlotDataItem(GraphicsObject): See :func:`__init__() ` for details; it accepts the same arguments. """ #self.clear() - prof = debug.Profiler('PlotDataItem.setData (0x%x)' % id(self), disabled=True) + profiler = debug.Profiler() y = None x = None if len(args) == 1: @@ -383,7 +383,7 @@ class PlotDataItem(GraphicsObject): if 'y' in kargs: y = kargs['y'] - prof.mark('interpret data') + profiler('interpret data') ## pull in all style arguments. ## Use self.opts to fill in anything not present in kargs. @@ -432,10 +432,10 @@ class PlotDataItem(GraphicsObject): self.xClean = self.yClean = None self.xDisp = None self.yDisp = None - prof.mark('set data') + profiler('set data') self.updateItems() - prof.mark('update items') + profiler('update items') self.informViewBoundsChanged() #view = self.getViewBox() @@ -443,9 +443,7 @@ class PlotDataItem(GraphicsObject): #view.itemBoundsChanged(self) ## inform view so it can update its range if it wants self.sigPlotChanged.emit(self) - prof.mark('emit') - prof.finish() - + profiler('emit') def updateItems(self): diff --git a/pyqtgraph/graphicsItems/PlotItem/PlotItem.py b/pyqtgraph/graphicsItems/PlotItem/PlotItem.py index ec0960ba..7f817f81 100644 --- a/pyqtgraph/graphicsItems/PlotItem/PlotItem.py +++ b/pyqtgraph/graphicsItems/PlotItem/PlotItem.py @@ -339,9 +339,8 @@ class PlotItem(GraphicsWidget): self.ctrl.gridAlphaSlider.setValue(v) #def paint(self, *args): - #prof = debug.Profiler('PlotItem.paint', disabled=True) + #prof = debug.Profiler() #QtGui.QGraphicsWidget.paint(self, *args) - #prof.finish() ## bad idea. #def __getattr__(self, attr): ## wrap ms diff --git a/pyqtgraph/graphicsItems/ScatterPlotItem.py b/pyqtgraph/graphicsItems/ScatterPlotItem.py index f1a5201d..15be8be0 100644 --- a/pyqtgraph/graphicsItems/ScatterPlotItem.py +++ b/pyqtgraph/graphicsItems/ScatterPlotItem.py @@ -219,7 +219,7 @@ class ScatterPlotItem(GraphicsObject): """ Accepts the same arguments as setData() """ - prof = debug.Profiler('ScatterPlotItem.__init__', disabled=True) + profiler = debug.Profiler() GraphicsObject.__init__(self) self.picture = None # QPicture used for rendering when pxmode==False @@ -240,11 +240,10 @@ class ScatterPlotItem(GraphicsObject): self.setBrush(100,100,150, update=False) self.setSymbol('o', update=False) self.setSize(7, update=False) - prof.mark('1') + profiler() self.setData(*args, **kargs) - prof.mark('setData') - prof.finish() - + profiler('setData') + #self.setCacheMode(self.DeviceCoordinateCache) def setData(self, *args, **kargs): diff --git a/pyqtgraph/graphicsItems/ViewBox/ViewBox.py b/pyqtgraph/graphicsItems/ViewBox/ViewBox.py index 55d15757..17bd2207 100644 --- a/pyqtgraph/graphicsItems/ViewBox/ViewBox.py +++ b/pyqtgraph/graphicsItems/ViewBox/ViewBox.py @@ -1205,7 +1205,7 @@ class ViewBox(GraphicsWidget): [[xmin, xmax], [ymin, ymax]] Values may be None if there are no specific bounds for an axis. """ - prof = debug.Profiler('updateAutoRange', disabled=True) + profiler = debug.Profiler() if items is None: items = self.addedItems @@ -1282,7 +1282,7 @@ class ViewBox(GraphicsWidget): range[0] = [min(bounds.left(), range[0][0]), max(bounds.right(), range[0][1])] else: range[0] = [bounds.left(), bounds.right()] - prof.mark('2') + profiler() #print "range", range @@ -1306,10 +1306,7 @@ class ViewBox(GraphicsWidget): continue range[1][0] = min(range[1][0], bounds.top() - px*pxSize) range[1][1] = max(range[1][1], bounds.bottom() + px*pxSize) - - #print "final range", range - - prof.finish() + return range def childrenBoundingRect(self, *args, **kwds): diff --git a/pyqtgraph/imageview/ImageView.py b/pyqtgraph/imageview/ImageView.py index 77f34419..25700d93 100644 --- a/pyqtgraph/imageview/ImageView.py +++ b/pyqtgraph/imageview/ImageView.py @@ -190,7 +190,7 @@ class ImageView(QtGui.QWidget): image data. ================== ======================================================================= """ - prof = debug.Profiler('ImageView.setImage', disabled=True) + profiler = debug.Profiler() if hasattr(img, 'implements') and img.implements('MetaArray'): img = img.asarray() @@ -209,7 +209,7 @@ class ImageView(QtGui.QWidget): else: self.tVals = np.arange(img.shape[0]) - prof.mark('1') + profiler() if axes is None: if img.ndim == 2: @@ -234,13 +234,9 @@ class ImageView(QtGui.QWidget): for x in ['t', 'x', 'y', 'c']: self.axes[x] = self.axes.get(x, None) - prof.mark('2') - - self.imageDisp = None - - - prof.mark('3') - + + profiler() + self.currentIndex = 0 self.updateImage(autoHistogramRange=autoHistogramRange) if levels is None and autoLevels: @@ -250,9 +246,9 @@ class ImageView(QtGui.QWidget): if self.ui.roiBtn.isChecked(): self.roiChanged() - prof.mark('4') - - + + profiler() + if self.axes['t'] is not None: #self.ui.roiPlot.show() self.ui.roiPlot.setXRange(self.tVals.min(), self.tVals.max()) @@ -271,8 +267,8 @@ class ImageView(QtGui.QWidget): s.setBounds([start, stop]) #else: #self.ui.roiPlot.hide() - prof.mark('5') - + profiler() + self.imageItem.resetTransform() if scale is not None: self.imageItem.scale(*scale) @@ -280,15 +276,15 @@ class ImageView(QtGui.QWidget): self.imageItem.setPos(*pos) if transform is not None: self.imageItem.setTransform(transform) - prof.mark('6') - + + profiler() + if autoRange: self.autoRange() self.roiClicked() - prof.mark('7') - prof.finish() - + profiler() + def play(self, rate): """Begin automatically stepping frames forward at the given rate (in fps). This can also be accessed by pressing the spacebar.""" From 5b7f4124d973fca42412c43465a92ccfe3f69127 Mon Sep 17 00:00:00 2001 From: Luke Campagnola Date: Sun, 15 Dec 2013 09:07:09 -0500 Subject: [PATCH 2/2] * Made new profilers compatible with old API * Adjusted output formatting for clearer representation of nested profilers * Message string formatting deferred until finish to reduce overhead --- pyqtgraph/debug.py | 56 ++++++++++++++++++++++++++++++++++------------ 1 file changed, 42 insertions(+), 14 deletions(-) diff --git a/pyqtgraph/debug.py b/pyqtgraph/debug.py index 0ee65a33..685780d4 100644 --- a/pyqtgraph/debug.py +++ b/pyqtgraph/debug.py @@ -402,12 +402,27 @@ class Profiler(object): _profilers = os.environ.get("PYQTGRAPHPROFILE", "") _depth = 0 _msgs = [] + + class DisabledProfiler(object): + def __init__(self, *args, **kwds): + pass + def __call__(self, *args): + pass + def finish(self): + pass + def mark(self, msg=None): + pass + _disabledProfiler = DisabledProfiler() + if _profilers: _profilers = _profilers.split(",") - def __new__(cls, delayed=True): + def __new__(cls, msg=None, disabled='env', delayed=True): """Optionally create a new profiler based on caller's qualname. """ + if disabled is True: + return cls._disabledProfiler + # determine the qualified name of the caller function caller_frame = sys._getframe(1) try: @@ -418,15 +433,16 @@ class Profiler(object): 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 + return cls._disabledProfiler # create an actual profiling object cls._depth += 1 obj = super(Profiler, cls).__new__(cls) - obj._name = func_qualname + obj._name = msg or func_qualname obj._delayed = delayed obj._markCount = 0 + obj._finished = False obj._firstTime = obj._lastTime = ptime.time() - obj._newMsg("> Entering " + func_qualname) + obj._newMsg("> Entering " + obj._name) return obj else: def __new__(cls, delayed=True): @@ -439,26 +455,38 @@ class Profiler(object): msg = str(self._markCount) self._markCount += 1 newTime = ptime.time() - self._newMsg( - msg + ": " + str((newTime - self._lastTime) * 1000) + "ms") + self._newMsg(" %s: %0.4f ms", + msg, (newTime - self._lastTime) * 1000) self._lastTime = newTime + + def mark(self, msg=None): + self(msg) - def _newMsg(self, msg): - msg = " " * (self._depth - 1) + msg + def _newMsg(self, msg, *args): + msg = " " * (self._depth - 1) + msg if self._delayed: - self._msgs.append(msg) + self._msgs.append((msg, args)) else: - print(msg) + print(msg % args) def __del__(self): + self.finish() + + def finish(self, msg=None): """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") + if self._finished: + return + self._finished = True + if msg is not None: + self(msg) + self._newMsg("< Exiting %s, total time: %0.4f ms", + self._name, (ptime.time() - self._firstTime) * 1000) type(self)._depth -= 1 - if not self._depth and self._msgs: - print("\n".join(self._msgs)) + if self._depth < 1 and self._msgs: + print("\n".join([m[0]%m[1] for m in self._msgs])) type(self)._msgs = [] + def profile(code, name='profile_run', sort='cumulative', num=30):