timing.py 7.22 KB
Newer Older
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47
# encoding: utf-8
# 2008 © Václav Šmilauer <eudoxos@arcig.cz>
"""Functions for accessing timing information stored in engines and functors.

See :ref:`timing` section of the programmer's manual, `wiki page <http://yade-dem.org/index.php/Speed_profiling_using_TimingInfo_and_TimingDeltas_classes>`_ for some examples.

"""

from yade.wrapper import *


def _resetEngine(e):
	if e.timingDeltas: e.timingDeltas.reset()
	if isinstance(e,Functor): return
	if isinstance(e,Dispatcher):
		for f in e.functors: _resetEngine(f)
	elif isinstance(e,ParallelEngine):
		for s in e.slaves: _resetEngine(s)
	e.execTime,e.execCount=0,0

def reset():
	"Zero all timing data."
	for e in O.engines: _resetEngine(e)

_statCols={'label':40,'count':20,'time':20,'relTime':20}
_maxLev=3

def _formatLine(label,time,count,totalTime,level):
	sp,negSp=' '*level*2,' '*(_maxLev-level)*2
	raw=[]
	raw.append(label)
	raw.append(str(count) if count>=0 else '')
	raw.append((str(time/1000)+u'us') if time>=0 else '')
	raw.append(('%6.2f%%'%(time*100./totalTime)) if totalTime>0 else '')
	return u' '.join([
		(sp+raw[0]).ljust(_statCols['label']),
		(raw[1]+negSp).rjust(_statCols['count']),
		(raw[2]+negSp).rjust(_statCols['time']),
		(raw[3]+negSp).rjust(_statCols['relTime']),
	])

def _delta_stats(deltas,totalTime,level):
	ret=0
	deltaTime=sum([d[1] for d in deltas.data])
	for d in deltas.data:
		print _formatLine(d[0],d[1],d[2],totalTime,level); ret+=1
	if len(deltas.data)>1:
48
		print _formatLine('TOTAL',deltaTime,sum(d[2] for d in deltas.data),totalTime,level); ret+=1
49 50 51 52 53
	return ret

def _engines_stats(engines,totalTime,level):
	lines=0; hereLines=0
	for e in engines:
54 55
		if not isinstance(e,Functor):
			print _formatLine(u'"'+e.label+'"' if e.label else e.__class__.__name__,e.execTime,e.execCount,totalTime,level); lines+=1; hereLines+=1
56 57
		if e.timingDeltas: 
			if isinstance(e,Functor):
58
				print _formatLine(e.__class__.__name__,sum(d[1] for d in e.timingDeltas.data),sum(d[2] for d in e.timingDeltas.data),totalTime,level); lines+=1; hereLines+=1
59 60 61 62 63 64 65 66
				execTime=sum([d[1] for d in e.timingDeltas.data])
			else: execTime=e.execTime
			lines+=_delta_stats(e.timingDeltas,execTime,level+1)
		if isinstance(e,Dispatcher): lines+=_engines_stats(e.functors,e.execTime,level+1)
		if isinstance(e,InteractionLoop):
			lines+=_engines_stats(e.geomDispatcher.functors,e.execTime,level+1)
			lines+=_engines_stats(e.physDispatcher.functors,e.execTime,level+1)
			lines+=_engines_stats(e.lawDispatcher.functors,e.execTime,level+1)
67 68 69 70 71 72 73 74 75 76 77 78 79 80 81
		elif isinstance(e,ParallelEngine):
			for slave in e.slaves:
				print "\\"
#<<<<<<< Updated upstream
				#if not isinstance(slave,list): lines+=_engines_stats([slave],slave.execTime,level+1)
				#else:
					#for se in slave:
						#lines+=_engines_stats([se],se.execTime,level+1)
				
#=======
				if not isinstance(slave,list): lines+=_engines_stats([slave],e.execTime,level+1)
				else:
					for el in slave: _engines_stats([el],e.execTime,level+1)
			print "/"
#>>>>>>> Stashed changes
82
	if hereLines>1 and not isinstance(e,Functor):
83 84 85 86 87 88 89 90
		print _formatLine('TOTAL',totalTime,-1,totalTime,level); lines+=1
	return lines

def stats():
	"""Print summary table of timing information from engines and functors. Absolute times as well as percentages are given. Sample output:

	.. code-block:: none

91 92 93 94 95 96 97 98 99 100 101 102 103
		Name                                                    Count                 Time            Rel. time
		-------------------------------------------------------------------------------------------------------
		ForceResetter                                       102               2150us                0.02%      
		"collider"                                            5              64200us                0.60%      
		InteractionLoop                                     102           10571887us               98.49%      
		"combEngine"                                        102               8362us                0.08%      
		"newton"                                            102              73166us                0.68%      
		"cpmStateUpdater"                                     1               9605us                0.09%      
		PyRunner                                              1                136us                0.00%      
		"plotDataCollector"                                   1                291us                0.00%      
		TOTAL                                                             10733564us              100.00%


104
	sample output (compiled with -DENABLE_PROFILING=1 option):
105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131

	.. code-block:: none

		Name                                                    Count                 Time            Rel. time
		-------------------------------------------------------------------------------------------------------
		ForceResetter                                       102               2150us                0.02%      
		"collider"                                            5              64200us                0.60%      
		InteractionLoop                                     102           10571887us               98.49%      
		  Ig2_Sphere_Sphere_ScGeom                        1222186            1723168us               16.30%    
		    Ig2_Sphere_Sphere_ScGeom                        1222186            1723168us              100.00%  
		  Ig2_Facet_Sphere_ScGeom                             753               1157us                0.01%    
		    Ig2_Facet_Sphere_ScGeom                             753               1157us              100.00%  
		  Ip2_CpmMat_CpmMat_CpmPhys                         11712              26015us                0.25%    
		    end of Ip2_CpmPhys                                11712              26015us              100.00%  
		  Ip2_FrictMat_CpmMat_FrictPhys                         0                  0us                0.00%    
		  Law2_ScGeom_CpmPhys_Cpm                         3583872            4819289us               45.59%    
		    GO A                                            1194624            1423738us               29.54%  
		    GO B                                            1194624            1801250us               37.38%  
		    rest                                            1194624            1594300us               33.08%  
		    TOTAL                                           3583872            4819289us              100.00%  
		  Law2_ScGeom_FrictPhys_CundallStrack                   0                  0us                0.00%    
		"combEngine"                                        102               8362us                0.08%      
		"newton"                                            102              73166us                0.68%      
		"cpmStateUpdater"                                     1               9605us                0.09%      
		PyRunner                                              1                136us                0.00%      
		"plotDataCollector"                                   1                291us                0.00%      
		TOTAL                                                             10733564us              100.00%
132 133

	"""
134

135 136 137 138
	print 'Name'.ljust(_statCols['label'])+' '+'Count'.rjust(_statCols['count'])+' '+'Time'.rjust(_statCols['time'])+' '+'Rel. time'.rjust(_statCols['relTime'])
	print '-'*(sum([_statCols[k] for k in _statCols])+len(_statCols)-1)
	_engines_stats(O.engines,sum([e.execTime for e in O.engines]),0)
	print