Performance/scripts/cmsTiming_parser.py

0001 #! /usr/bin/env python3
0002
0003 from builtins import range
0004 import sys, os
0005 import time
0006 import optparse
0007 from math import sqrt, log10, floor
0008
0009 import ROOT
0010
0011 def manipulate_log(outdir, logfile_name, secsperbin):
0012     """ Parses logfile_name and create an html report
0013         with information and plots, at the outdir path.
0014         Graphs' production is also done here.
0015     """
0016     ################################
0017     #### Parse of the log file. ####
0018     ################################
0019     logfile = open(logfile_name,'r')
0020     logfile_lines = iter(logfile.readlines())
0021     logfile.close()
0022     data = {}
0023     report = ''
0024     for line in logfile_lines:
0025         # Retrieve cpu time of every event.
0026         if 'TimeEvent>' in line:
0027             line = line[:-1] #no \n!
0028             content = line.split(' ')
0029             event =  int(content[1])
0030             seconds = float(content[3])
0031             data[event] = seconds
0032         # Fill the time report.
0033         elif 'TimeReport' in line:
0034             if '[sec]' in line:
0035                 report += line.replace('TimeReport', '\n')
0036             elif 'headings' in line:
0037                 continue
0038             elif 'complete' in line:
0039                 report += line.replace('TimeReport', '\n')
0040                 for count in range(12):
0041                     line = next(logfile_lines)
0042                     report += line
0043                 break
0044             else:
0045                 report += line.replace('TimeReport', '')
0046
0047     ##############################
0048     #### Graph and Histogram  ####
0049     ##############################
0050     __argv = sys.argv # trick for a strange behaviour of the TApp..
0051     sys.argv = sys.argv[:1]
0052     ROOT.gROOT.SetStyle("Plain") # style paranoia
0053     sys.argv = __argv
0054     #Cannot use this option when the logfile includes
0055     #a large number of events... PyRoot seg-faults.
0056     #Set ROOT in batch mode to avoid canvases popping up!
0057     ROOT.gROOT.SetBatch(1)
0058
0059     # Save in file
0060     rootfilename = '%s/graphs.root' %outdir
0061     myfile = ROOT.TFile(rootfilename,'RECREATE')
0062
0063     # Set limits
0064     min_val = data[min(data, key=data.get)]
0065     max_val = data[max(data, key=data.get)]
0066     interval = max_val-min_val
0067     min_val = min_val - (interval*0.2)
0068     max_val = max_val + (interval*0.2)
0069     interval = max_val - min_val
0070     nbins = int(interval/secsperbin)
0071
0072     # Initialize Histogram
0073     histo = ROOT.TH1F('Seconds per event','Seconds per event', nbins, min_val, max_val)
0074     histo.GetXaxis().SetTitle("s")
0075     # Initialize Graph
0076     npoints = len(data)
0077     graph = ROOT.TGraph(npoints)
0078     graph.SetMarkerStyle(8)
0079     graph.SetMarkerSize(.7)
0080     graph.SetMarkerColor(1)
0081     graph.SetLineWidth(3)
0082     graph.SetLineColor(2)
0083     graph.SetTitle('Seconds per event')
0084     graph.SetName('SecondsPerEvent')
0085     graph.GetXaxis().SetTitle("Event")
0086     last_event = max(data)
0087     graph.GetXaxis().SetLimits(0, last_event)
0088     graph.GetYaxis().SetTitleOffset(1.3)
0089     graph.GetYaxis().SetTitle("s")
0090     graph.GetYaxis().SetRangeUser(0, max_val)
0091     # Fill them
0092     total_time = 0
0093     for event_num in data.keys():
0094         seconds = data[event_num]
0095         graph.SetPoint(event_num-1, event_num, seconds)
0096         histo.Fill(seconds)
0097         total_time += seconds
0098     # A line which represents the average is drawn in the TGraph
0099     avg = histo.GetMean()
0100     avg_line = ROOT.TLine(1,avg,last_event, avg)
0101     avg_line.SetLineColor(4)
0102     avg_line.SetLineWidth(2)
0103     # Draw and save!
0104     graph_canvas = ROOT.TCanvas('graph_canvas')
0105     graph_canvas.cd()
0106     graph.Draw("ALP")
0107     avg_line.Draw("Same")
0108
0109
0110     # Write graph to file
0111     graph_canvas.Print("%s/graph.png" %outdir,"png")
0112     graph.Write()
0113     graph_canvas.Write()
0114     histo_canvas = ROOT.TCanvas('histo_canvas')
0115     histo_canvas.cd()
0116     histo.Draw('')
0117
0118     # Write histogram to file
0119     histo_canvas.Print("%s/histo.png" %outdir,"png")
0120     histo.Write()
0121     histo_canvas.Write()
0122
0123     myfile.Close()
0124
0125     ########################
0126     #### The html page! ####
0127     ########################
0128     titlestring = '<b>Report executed with release %s on %s.</b>\n<br>\n<hr>\n'\
0129                                    %(os.environ['CMSSW_VERSION'], time.asctime())
0130     html_file_name = '%s/%s_TimingReport.html' %(outdir, logfile_name[:-4])
0131     html_file = open(html_file_name,'w')
0132     html_file.write('<html>\n<body>\n'+\
0133                     titlestring)
0134     html_file.write('<table>\n'+\
0135                     '<tr>\n<td><img  src=graph.png></img></td>\n'+\
0136                     '<td><img  src=histo.png></img></td>\n</tr>\n'+\
0137                     '</table>\n')
0138     html_file.write('<hr>\n<h2>Time Report</h2>\n<pre>\n' + report + '</pre>\n')
0139     html_file.write('</body>\n</html>')
0140     html_file.close()
0141
0142     ##########################
0143     #### Print statistics ####
0144     ##########################
0145     total_events = max(data)
0146     average_time = total_time / total_events
0147     sum = 0.
0148     for i in range(1, max(data)+1):
0149         sum += (data[i]-average_time)**2
0150     denominator = total_events**2 - total_events
0151     uncertainty = sqrt(sum/denominator)
0152     # Comment out next 2 line to round uncertainty to the most significant digit
0153     #rounded_uncertainty=round(uncertainty, -int(floor(log10(uncertainty))))
0154     #print 'Rounded uncertainty=' , rounded_uncertainty
0155     print('------ Statistics ------')
0156     print('last event = {}'.format(last_event))
0157     print('Minval = {} maxval = {} interval = {}'.format(min_val, max_val, interval))
0158     print('Total Time = {}'.format(total_time))
0159     print('Average Time = {}'.format(average_time))
0160     print('Uncertainty of Average Time = {} +/- {}'.format(average_time, uncertainty))
0161
0162 #################################################################################################
0163
0164 if __name__ == '__main__':
0165
0166     # Here we define an option parser to handle commandline options..
0167     usage = 'timing_parser.py <options>'
0168     parser = optparse.OptionParser(usage)
0169     parser.add_option('-i', '--in_  profile',
0170                       help='The profile to manipulate' ,
0171                       default='',
0172                       dest='profile')
0173
0174     parser.add_option('-o', '--outdir',
0175                       help='The directory of the output' ,
0176                       default='',
0177                       dest='outdir')
0178
0179     parser.add_option('-n',
0180                       help='Number of secs per bin. Default is 1.' ,
0181                       default='1',
0182                       dest='startevt')
0183     (options,args) = parser.parse_args()
0184
0185     # Now some fault control..If an error is found we raise an exception
0186     if options.profile == '' or\
0187        options.outdir == '':
0188         raise Exception('Please select a profile and an output dir!')
0189
0190     if not os.path.exists(options.profile) or\
0191        not os.path.exists(options.outdir):
0192         raise Exception('Outdir or input profile not present!')
0193
0194     try:
0195         startevt = float(options.startevt)
0196     except ValueError:
0197          print('Problems in convertng starting event value!')
0198
0199     # launch the function!
0200     manipulate_log(options.outdir,options.profile,startevt)