From fb2f29811a938c3c11dd06cb57640c07e86a48cf Mon Sep 17 00:00:00 2001 From: Han Gao Date: Mon, 9 Mar 2020 16:36:43 +0100 Subject: [PATCH 1/2] Added timers around IO operations for benchmarking purposes. --- charmdet/drifttubeMonitoring.py | 79 ++++++++++++++++++++++++++++++++- 1 file changed, 78 insertions(+), 1 deletion(-) diff --git a/charmdet/drifttubeMonitoring.py b/charmdet/drifttubeMonitoring.py index 35f2080..0c44ef2 100644 --- a/charmdet/drifttubeMonitoring.py +++ b/charmdet/drifttubeMonitoring.py @@ -1,7 +1,22 @@ #import yep import ROOT,os,time,sys,operator,atexit ROOT.gROOT.ProcessLine('typedef std::unordered_map>>> nestedList;') - +#---------log for benchmarking----------------------------------------------------------- +import logging +# Define log file to record output of method execution time as benchmarking +log_file = logging.FileHandler(filename='benchmarking.log', mode='a', encoding='utf-8') +fmt = logging.Formatter() +log_file.setFormatter(fmt) + +# Define logger and logger type +logger = logging.Logger(name='benchmarking', level=logging.INFO) +logger.addHandler(log_file) +# logger.info is used to write msg to the log file +# Write the log file's header. +logger.info(msg=time.strftime("%Y-%m-%d %H:%M:%S", time.localtime())) +logger.info(msg='Benchmarking start - Record code execution time :') +logger.info(msg='Method_name wall_time cpu_time') +#-------------------------------------------------------------------- from decorators import * import __builtin__ as builtin ROOT.gStyle.SetPalette(ROOT.kGreenPink) @@ -164,6 +179,10 @@ def pyExit(): daniel = {} # For T1 and 2, the survey target is placed above/below the endplates, offset in y. # For T3 it is placed 7cm in front and for T4 7cm behind the endplate, so there is an offset in z + +wall_time_start = time.time() +cpu_time_start = time.clock() + survey['T1_MA_01']=[ 9.0527, 0.2443, 0.7102 ] daniel['T1_MA_01']=[244.30,531.85,9052.70] survey['T1_MA_02']=[ 9.0502, -0.2078, 0.7092 ] @@ -272,6 +291,10 @@ def pyExit(): survey['RPC5_L']= [ 20.2852, 1.1677, 1.1945 ] survey['RPC5_R']= [ 20.2891, -1.2614, 1.1943 ] +cpu_time_end = time.clock() +wall_time_end = time.time() +logger.info(msg='Get daniel and survey by hard code%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) + Lcorrection={} # length of the bolt 150mm on the top and 50mm on the bottom Lcorrection['T1_MA_01'] = -(20.+150.+8.65)/10. @@ -5409,9 +5432,17 @@ def makeAlignmentConstantsPersistent(): vbot,vtop = strawPositionsBotTop[straw] strawPositionsP[straw]={'top':[vtop[0],vtop[1],vtop[2]],'bot':[vbot[0],vbot[1],vbot[2]]} alignConstants={'strawPositions':strawPositionsP,'alignCorrection':alignCorrection} + + wall_time_start = time.time() + cpu_time_start = time.clock() + pkl = Pickler(ftemp) pkl.dump(alignConstants,'alignConstants') + cpu_time_end = time.clock() + wall_time_end = time.time() + logger.info(msg='add alignConstants to file%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) + def importAlignmentConstants(): global alignConstants alignConstants = {} @@ -5422,14 +5453,28 @@ def importAlignmentConstants(): strawPositionsBotTop[hit.GetDetectorID()]=correctAlignment(hit) print "importing alignment constants from code" return + + wall_time_start = time.time() + cpu_time_start = time.clock() + upkl = Unpickler(sTree.GetCurrentFile()) try: + alignConstants = upkl.load('alignConstants') + + cpu_time_end = time.clock() + wall_time_end = time.time() + logger.info(msg='importAlignmentConstants from file%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) + print "importing alignment constants from file",sTree.GetCurrentFile().GetName() strawPosition() except: print "loading of alignment constants failed for file",sTree.GetCurrentFile().GetName() def importRTrel(): + + wall_time_start = time.time() + cpu_time_start = time.clock() + for fname in fnames: if len(fnames)==1: f=sTree.GetCurrentFile() else: f = ROOT.TFile.Open(fname) @@ -5444,6 +5489,11 @@ def importRTrel(): except: print "loading of RT failed for file",rname if len(fnames)!=1: f.Close() + + cpu_time_end = time.clock() + wall_time_end = time.time() + logger.info(msg='importRTrel%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) + importRTCorrection() def importRTCorrection(): pars = {} @@ -5507,7 +5557,16 @@ def analyzeRTrel(): zeroFieldData=['SPILLDATA_8000_0515970150_20180715_220030.root'] def init(database='muflux_RTrelations.pkl',remake=False,withReco=False): global withTDC,RTrelations + + wall_time_start = time.time() + cpu_time_start = time.clock() + if os.path.exists(database): RTrelations = pickle.load(open(database)) + + cpu_time_end = time.clock() + wall_time_end = time.time() + logger.info(msg='loading_muflux_RTrelations%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) + N = sTree.GetEntries() if not RTrelations.has_key(rname) or remake: withTDC = False @@ -5518,8 +5577,17 @@ def init(database='muflux_RTrelations.pkl',remake=False,withReco=False): RTrelations[rname] = {'tMinAndTmax':h['tMinAndTmax']} for s in h['tMinAndTmax']: RTrelations[rname]['rt'+s] = h['rt'+s] fpkl=open(database,'w') + + wall_time_start = time.time() + cpu_time_start = time.clock() + pickle.dump(RTrelations,fpkl) fpkl.close() + + cpu_time_end = time.clock() + wall_time_end = time.time() + logger.info(msg='writing_muflux_RTrelations%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) + else: h['tMinAndTmax'] = RTrelations[rname]['tMinAndTmax'] for s in h['tMinAndTmax']: h['rt'+s] = RTrelations[rname]['rt'+s] @@ -7814,7 +7882,16 @@ def anaResiduals(): elif sTree.GetCurrentFile().GetKey('RT'): importRTrel() elif os.path.exists(database): + + wall_time_start = time.time() + cpu_time_start = time.clock() + RTrelations = pickle.load(open(database)) + + cpu_time_end = time.clock() + wall_time_end = time.time() + logger.info(msg='loading_RTrelations%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) + if not RTrelations.has_key(rname): print "You should run init() to determine the RT relations or use _RT file" else: From 260f426117536d262e5c03685d28021b49a7ecaa Mon Sep 17 00:00:00 2001 From: Raha Sadeghi Date: Mon, 30 Mar 2020 21:06:42 +0200 Subject: [PATCH 2/2] Added benchmarking for original drifttubemonitoring implementation. --- charmdet/drifttubeMonitoring.py | 100 ++++++++++++++++++++++++++------ 1 file changed, 83 insertions(+), 17 deletions(-) diff --git a/charmdet/drifttubeMonitoring.py b/charmdet/drifttubeMonitoring.py index 0c44ef2..3a82cad 100644 --- a/charmdet/drifttubeMonitoring.py +++ b/charmdet/drifttubeMonitoring.py @@ -180,6 +180,7 @@ def pyExit(): # For T1 and 2, the survey target is placed above/below the endplates, offset in y. # For T3 it is placed 7cm in front and for T4 7cm behind the endplate, so there is an offset in z +#benchmarking: calculate time for getting daniel and survey conditions data wall_time_start = time.time() cpu_time_start = time.clock() @@ -4629,6 +4630,10 @@ def debugRPCYCoordinate(): withCorrections=True if MCdata: withCorrections=False if withCorrections: + #calculate time for getting alignCorrection + cpu_time_start = time.clock() + wall_time_start = time.time() + alignCorrection[0]=[ 0, 0, 0] # by hand alignCorrection[1]=[ 0, 0, 0] alignCorrection[2]=[ 0, 0, 0] @@ -4667,6 +4672,10 @@ def debugRPCYCoordinate(): alignCorrection[30]=[ 0.0, 0, 0] alignCorrection[31]=[ 0.0, 0, 0] + cpu_time_end = time.clock() + wall_time_end = time.time() + logger.info(msg='alignCorrection%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) + slopeX = {2:[-0.001,-0.001,-0.001,-0.001], 3:[-0.0048,-0.0048,-0.0048,-0.0048]} # 7Feb slopeY = {2:[0.0065,0.0065,0.0065,0.0065]} @@ -5432,7 +5441,7 @@ def makeAlignmentConstantsPersistent(): vbot,vtop = strawPositionsBotTop[straw] strawPositionsP[straw]={'top':[vtop[0],vtop[1],vtop[2]],'bot':[vbot[0],vbot[1],vbot[2]]} alignConstants={'strawPositions':strawPositionsP,'alignCorrection':alignCorrection} - + #benchmarking: calculate time required for dumping "alignConstants" wall_time_start = time.time() cpu_time_start = time.clock() @@ -5453,25 +5462,21 @@ def importAlignmentConstants(): strawPositionsBotTop[hit.GetDetectorID()]=correctAlignment(hit) print "importing alignment constants from code" return - + #benchmarking: calculate time required for unpickling "alignConstants" wall_time_start = time.time() cpu_time_start = time.clock() - upkl = Unpickler(sTree.GetCurrentFile()) try: - alignConstants = upkl.load('alignConstants') - cpu_time_end = time.clock() wall_time_end = time.time() logger.info(msg='importAlignmentConstants from file%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) - print "importing alignment constants from file",sTree.GetCurrentFile().GetName() strawPosition() except: print "loading of alignment constants failed for file",sTree.GetCurrentFile().GetName() def importRTrel(): - + #benchmarking: calculate time required for importing RTrelations wall_time_start = time.time() cpu_time_start = time.clock() @@ -7694,7 +7699,7 @@ def recoStep0(): RTrelations = {'tMinAndTmax':h['tMinAndTmax']} for s in h['tMinAndTmax']: RTrelations['rt'+s] = h['rt'+s] makeRTrelPersistent(RTrelations) -def recoStep1(PR=11): +def recoStep1(PR=11,cpu_time_start=time.clock(), wall_time_start=time.time()): # make fitted tracks #disableBranches() global MCdata @@ -7740,9 +7745,13 @@ def recoStep1(PR=11): ftemp=sTree.GetCurrentFile() ftemp.Write("",ROOT.TFile.kOverwrite) ftemp.Close() - print "finished adding fitted tracks",options.listOfFiles + # Benchmarking: calculate time required for executing recoStep1 (start times via function params) + cpu_time_end = time.clock() + wall_time_end = time.time() + logger.info(msg='recoStep1%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) + print "finished adding fitted tracks", options.listOfFiles print "make suicid" - os.system('kill '+str(os.getpid())) + os.system('kill ' + str(os.getpid())) def getParOfRTcorrectio(): keys = h.keys() for x in keys: @@ -7753,7 +7762,7 @@ def getParOfRTcorrectio(): txt+=" %7.5F, "%(x) txt+=']' print txt.replace(', ]',']') -def recoStep2(): +def recoStep2(cpu_time_start, wall_time_start): # refit tracks with improved RT relation global MCdata fGenFitArray = ROOT.TClonesArray("genfit::Track") @@ -7761,7 +7770,7 @@ def recoStep2(): fitTracks = sTree.Branch("FitTracks_refitted", fGenFitArray,32000,-1) fTrackInfoArray = ROOT.TClonesArray("TrackInfo") fTrackInfoArray.BypassStreamer(ROOT.kTRUE) - TrackInfos = sTree.Branch("TrackInfos_refitted", fTrackInfoArray,32000,-1) + TrackInfos = sTree.Branch("TrackInfos_refitted", fTrackInfoArray,32000,-1) if sTree.GetBranch('MCTrack'): MCdata = True for n in range(sTree.GetEntries()): if n%10000==0: print "Now at event",n,"of",sTree.GetEntries(),sTree.GetCurrentFile().GetName(),time.ctime() @@ -7781,9 +7790,13 @@ def recoStep2(): ftemp=sTree.GetCurrentFile() ftemp.Write("",ROOT.TFile.kOverwrite) ftemp.Close() - print "finished adding fitted tracks",options.listOfFiles + # Benchmarking: calculate time required for executing recoStep2 (start times via function params) + cpu_time_end = time.clock() + wall_time_end = time.time() + logger.info(msg='recoStep2%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) + print "finished adding fitted tracks", options.listOfFiles print "make suicid" - os.system('kill '+str(os.getpid())) + os.system('kill ' + str(os.getpid())) def recoMuonTaggerTracks(): global MCdata global sTree @@ -7873,7 +7886,9 @@ def anaResiduals(): print " --- printScalers()" print " --- init(): outdated! do boostrapping, determine RT relation using fitted tracks, do plotBiasedResiduals and plotRPCExtrap with TDC" print " --- momResolution(), with MC data" - + #benchmarking: calculate time required for running drifttubesmonitoring.py without passing any command arguments + cpu_time_start = time.clock() + wall_time_start = time.time() vetoLayer = [] database='muflux_RTrelations.pkl' if sTree.GetBranch('MCTrack'): @@ -7899,14 +7914,26 @@ def anaResiduals(): for s in h['tMinAndTmax']: h['rt'+s] = RTrelations[rname]['rt'+s] withCorrections = False importAlignmentConstants() + cpu_time_end = time.clock() + wall_time_end = time.time() + logger.info(msg='NoCommand%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) # if options.command == "recoStep0": + #benchmarking: calculate time required for running recoStep0 + cpu_time_start = time.clock() + wall_time_start = time.time() withTDC=False print "make clean TDC distributions" importAlignmentConstants() recoStep0() print "finished making RT relations" + cpu_time_end = time.clock() + wall_time_end = time.time() + logger.info(msg='recoStep0%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) elif options.command == "recoStep1": + #benchmarking: calculate time required for running this script by passing recoStep1 as argument + cpu_time_start = time.clock() + wall_time_start = time.time() if sTree.GetBranch('MCTrack'): MCdata = True withDefaultAlignment = True @@ -7920,8 +7947,11 @@ def anaResiduals(): withCorrections = True print "add fitted tracks" importAlignmentConstants() - recoStep1(PR=11) + recoStep1(PR=11,cpu_time_start = cpu_time_start, wall_time_start = wall_time_start) elif options.command == "recoStep2": + #benchmarking: calculate time required for running this script by passing recoStep2 as argument + cpu_time_start = time.clock() + wall_time_start = time.time() if sTree.GetBranch('MCTrack'): MCdata = True withDefaultAlignment = True @@ -7935,8 +7965,11 @@ def anaResiduals(): withCorrections = True print "add refitted tracks" importAlignmentConstants() - recoStep2() + recoStep2(cpu_time_start, wall_time_start) elif options.command == "anaResiduals": + #benchmarking: calculate time required for running this script by "anaResiduals" argument as command + cpu_time_start = time.clock() + wall_time_start = time.time() ROOT.gROOT.SetBatch(True) if sTree.GetEntries()>0: if sTree.GetBranch('MCTrack'): @@ -7948,7 +7981,13 @@ def anaResiduals(): anaResiduals() print "finished with analysis step",options.listOfFiles else: print "no events, exit ",sTree.GetCurrentFile() + cpu_time_end = time.clock() + wall_time_end = time.time() + logger.info(msg='anaResiduals%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) elif options.command == "alignment": + #benchmarking: calculate time required for running this script by "alignment" argument as command + cpu_time_start = time.clock() + wall_time_start = time.time() ROOT.gROOT.SetBatch(True) if sTree.GetBranch('MCTrack'): MCdata = True @@ -7965,22 +8004,43 @@ def anaResiduals(): plotBiasedResiduals(PR=13,minP=10) ut.writeHists(h,'histos-residuals-'+rname) hitMapsFromFittedTracks() + cpu_time_end = time.clock() + wall_time_end = time.time() + logger.info(msg='alignment%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) elif options.command == "plotResiduals": + #benchmarking: calculate time required for running this script by "plotResiduals" argument as command + cpu_time_start = time.clock() + wall_time_start = time.time() print "reading histograms with residuals" ut.readHists(h,options.listOfFiles) plotBiasedResiduals(onlyPlotting=True) if h.has_key('RPCResY_10'): plotRPCExtrap(onlyPlotting=True) + cpu_time_end = time.clock() + wall_time_end = time.time() + logger.info(msg='plotResiduals%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) elif options.command == "recoMuonTaggerTracks": + #benchmarking: calculate time required for running this script by "recoMuonTaggerTracks" argument as command + cpu_time_start = time.clock() + wall_time_start = time.time() importAlignmentConstants() recoMuonTaggerTracks() + cpu_time_end = time.clock() + wall_time_end = time.time() + logger.info(msg='recoMuonTaggerTracks%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) elif options.command == "momResolution": + #benchmarking: calculate time required for running this script by "momResolution" argument as command + cpu_time_start = time.clock() + wall_time_start = time.time() MCdata = True withDefaultAlignment = True sigma_spatial = 0.25 withCorrections = False importAlignmentConstants() momResolution(PR=1,onlyPlotting=False) + cpu_time_end = time.clock() + wall_time_end = time.time() + logger.info(msg='momResolution%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) elif options.command == "splitOffBoostedEvents": splitOffBoostedEvents() elif options.command == "countTracks": countTracks() elif options.command == "plotDTPoints": plotDTPoints() @@ -7996,6 +8056,9 @@ def anaResiduals(): elif options.command == "MCJpsiProd": MCJpsiProd() elif options.command == "test": + #benchmarking: calculate time required for running this script by "test" argument as command + cpu_time_start = time.clock() + wall_time_start = time.time() yep.start('output.prof') for x in sTree.GetListOfBranches(): sTree.SetBranchStatus(x.GetName(),0) # sTree.SetBranchStatus('RPCTrackY',1) @@ -8004,4 +8067,7 @@ def anaResiduals(): rc=sTree.GetEvent(n) yep.stop() print "finished" + cpu_time_end = time.clock() + wall_time_end = time.time() + logger.info(msg='test%15.6f%13.6f' % (wall_time_end - wall_time_start, cpu_time_end - cpu_time_start)) #alignConstants.pop('strawPositions') # if recorded alignment constants should not be used.