/data/refman/pasoursint/CMSSW_5_3_10_patch2/src/Validation/Performance/python/parserTimingReport.py

Go to the documentation of this file.

#!/usr/bin/env python2.4
import sys
import math
import re
from cmssw_exportdb_xml import *
from FileNamesHelper import *

"""
Performance profiling:
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   71.618   71.618 <stdin>:1(foo)
        1    0.315    0.315   71.933   71.933 <string>:1(<module>)
        1   47.561   47.561   71.618   71.618 parserTimingReport.py:27(loadTimeLog)
     8000    0.191    0.000    0.343    0.000 parserTimingReport.py:8(extractRSS_VSIZE)
        1    0.000    0.000    0.000    0.000 {len}
  2384000    3.239    0.000    3.239    0.000 {method 'append' of 'list' objects}
        1    0.000    0.000    0.000    0.000 {method 'close' of 'file' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
    24000    0.041    0.000    0.041    0.000 {method 'partition' of 'str' objects}
  2392000    5.804    0.000    5.804    0.000 {method 'split' of 'str' objects}
 10791332   14.782    0.000   14.782    0.000 {method 'strip' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method 'xreadlines' of 'file' objects}
        1    0.000    0.000    0.000    0.000 {open}

"""


""" given two lines returns the VSIZE and RSS values along with event number """
def extractRSS_VSIZE(line1, line2, record_number):
        """ 
        >>> extractRSS_VSIZE("%MSG-w MemoryCheck:  PostModule 19-Jun-2009 13:06:08 CEST Run: 1 Event: 1", \
                             "MemoryCheck: event : VSIZE 923.07 0 RSS 760.25 0")
        (('1', '760.25'), ('1', '923.07'))
        """

        if ("Run" in line1) and  ("Event" in line1): # the first line
                event_number = line1.split('Event:')[1].strip() 
        else: return False

        """ it's first or second MemoryCheck line """
        if ("VSIZE" in line2) and ("RSS" in line2): # the second line
                RSS = line2.split("RSS")[1].strip().split(" ")[0].strip() #changed partition into split for backward compatability with py2.3
                VSIZE = line2.split("RSS")[0].strip().split("VSIZE")[1].strip().split(" ")[0].strip()
                #Hack to return the record number instea of event number for now... can always switch back of add event number on top
                #return ((event_number, RSS), (event_number, VSIZE))
                return ((record_number, RSS), (record_number, VSIZE))
        else: return False


def loadTimeLog(log_filename, maxsize_rad = 0): #TODO: remove maxsize to read, used for debugging
        """ gets the timing data from the logfile
         returns 4 lists:

                * ModuleTime data (event_number, module_label, module_name, seconds) and
                * EventTime data
                        - with granularity of event (initial - not processed data)
                * RSS per event
                * VSIZE per event
         """
        # ----- format of logfile ----
        # Report columns headings for modules: eventnum runnum modulelabel modulename timetakeni"
        # e.g. TimeModule> 1 1 csctfDigis CSCTFUnpacker 0.0624561

        mod_data = []
        evt_data = []
        rss_data = []
        vsize_data = []
        # open file and read it and fill the structure!
        logfile = open(log_filename, 'r')
        
        # get only the lines which have time report data
        #TODO: reading and processing line by line might speed up the process!
                                
        memcheck_line1 = False

        record_number=0
        last_record=0
        last_event=0
        for line in logfile.xreadlines():
                if 'TimeModule>' in line.strip():
                        line = line.strip()
                        line_content_list = line.split(' ')[0:]
                        #Hack to avoid issues with the non-consecutive run numbers:
                        event_number = int(line_content_list[1])
                        if event_number != last_event:
                                record_number=record_number+1
                                last_event=event_number
                                # module label and name were mixed up in the original doc
                        module_label = str(line_content_list[4])
                        module_name = str(line_content_list[3])
                        seconds = float(line_content_list[5])
                        #For now let's try to switch to the record_number... if we need to also have the event_number we can always add it back.
                        #mod_data.append((event_number, module_label, module_name, seconds))
                        mod_data.append((record_number, module_label, module_name, seconds))
                if 'TimeEvent>' in line.strip():
                        line = line.strip()
                        line_content_list = line.split(' ')[0:]
                        #Hack to avoid issues with the non-consecutive run numbers:
                        event_number = int(line_content_list[1])
                        if event_number != last_event:
                                record_number=record_number+1
                                last_event=event_number
                                # module label and name were mixed up in the original doc
                        time_seconds = str(line_content_list[3])
                        
                        #TODO: what are the other [last two] numbers? Real time? smf else? TimeEvent> 1 1 15.3982 13.451 13.451
                        #For now let's try to switch to the record_number... if we need to also have the event_number we can always add it back.
                        #evt_data.append((event_number, time_seconds))
                        evt_data.append((record_number, time_seconds))
                """ 
                        %MSG-w MemoryCheck:  PostModule 19-Jun-2009 13:06:08 CEST Run: 1 Event: 1
                        MemoryCheck: event : VSIZE 923.07 0 RSS 760.25 0
                """
                if 'MemoryCheck:' in line.strip():
                        # this is the first line out of two
                        if (not memcheck_line1):
                                memcheck_line1 = line.strip()
                        else:
                                #FIXME (eventually)
                                #Hacking in the record_number extracted from the TimeEvent and TimeModule parsing... NOT ROBUST...
                                (rss, vsize) = extractRSS_VSIZE(memcheck_line1, line.strip(), record_number)
                                rss_data.append(rss)
                                vsize_data.append(vsize)
                else: 
                        memcheck_line1 = False                                                                                                                                                                                                                                                                                          

        logfile.close()
        
        return (mod_data, evt_data, rss_data, vsize_data)




def calcRMS(items,avg):
        """ returns RootMeanSquare  of items in a list """ 
        # sqrt(sum(x^2))
        # Not statistics RMS... "physics" RMS, i.e. standard deviation: sqrt(sum((x-avg)**2)/N)
        # return math.sqrt(reduce(lambda x: (x - avg)**2, items) / len(items))  
        return math.sqrt(sum([(x-avg)**2 for x in items])/len(items))

def calc_MinMaxAvgRMS(items, remove_first = True, f_time = lambda x: x[0], f_evt_num = lambda x: x[1],):
        """ returns a dict of avg, min, max, rms """
        # save the cpu time of first event before removing the first result!
        cpu_time_first = f_time(items[0])

        if len(items) > 1 and remove_first == True:
                items.remove(items[0]) #TODO: if there is only one event - we have a problem -> do we eliminate the whole module?
                # TODO: it removes it completely from all the data because we do not save/ do not copy it

        items_time = map(f_time, items)
        min_value = min(items_time)
        max_value = max(items_time)
        max_index = items_time.index(max_value)
        avg_value = float(sum(items_time)) / float(len(items_time))
        rms_value = calcRMS(items_time,avg_value)

        return {"min":  min_value, "max": max_value, "cputime_first": cpu_time_first,
                        "rms": rms_value, "avg": avg_value,
                        "event_number_of_max": f_evt_num(items[max_index])}
        
        
def processModuleTimeLogData(modules_timelog, groupBy = "module_name"):
        """ Processes the timelog data grouping events by module and calculates min, max, avg, rms 
        Returns data as a list of dicts like: !
        
         {
                <module_name>: 
                        {name:, label:, 
                                stats: {num_events, avg, min, max, rms} 
         } 
         
         """
        # group by module_name, we save a list for each module name
        times_bymod = {}
        
        # print "Num of useful TimeLog lines: %s" % len(modules_timelog)
        
        for time_data in modules_timelog:
                (event_number, module_label, module_name, seconds) = time_data
                
                # group times of modules By label or name, TODO: maybe both 
                if groupBy == "module_label":
                        key = module_label
                else:
                        if groupBy =="name+label": 
                                key = module_name + "_" + module_label
                        else:
                                key = module_name

                        
                try:
                        # is the list for current module initialized?
                        times_bymod[key]
                except KeyError:
                        #Changing this from a list to a dict (see comments below):
                        #times_bymod[key] = []
                        times_bymod[key] = {}
                #Running out of memory!
                #times_bymod[key].append({"label": module_label, "name": module_name, "time": seconds, "event_number": event_number})
                #Let's do it right:
                #Instead of times_bymod[key]=[{"label": module_label, "name": module_name, "time": seconds, "event_number": event_number}]
                #let's do times_bymod[key]={"module_label":{"module_name":[(seconds,event_number)]}} so we do not repeat label and name and especially they are not a pair of key/value
                #During the first event all the keys will be initialized, then from event 2 on it will be just appending the (seconds,event_number) tuple to the list with the appropriate keys:

                #Check/Set up the module label dict:
                try:
                        times_bymod[key][module_label]
                except KeyError:
                        times_bymod[key].update({module_label:{}})
                
                #Check/Set up the module name dict:
                try:
                        times_bymod[key][module_label][module_name]
                except KeyError:
                        times_bymod[key][module_label].update({module_name:[]})
                
                #We're now ready to add the info as a tuple in the list!
                times_bymod[key][module_label][module_name].append((seconds,event_number))
                
                
        # calculate Min,Max, Avg, RMS for each module and in this way get the final data to be imported
        ##for mod_name in times_bymod.keys():
        ##      #copy needed data
        ##      #mod_data = {"label": times_bymod[mod_name][0]["label"], "name": times_bymod[mod_name][0]["name"]}
        ##      #New data structure:
        ##      mod_data = {"label":times_bymod[mod_name].keys()[0],"name":times_bymod[mod_name][times_bymod[mod_name].keys()[0]].keys()[0]}
        ##      # add statistical data
        ##
        ##      mod_data["stats"] =calc_MinMaxAvgRMS(f_time = lambda x: x["time"], f_evt_num = lambda x: x["event_number"], items = times_bymod[mod_name])
        ##
        ##      mod_data["stats"]["num_events"] = len(times_bymod[mod_name])
        ##      
        ##      times_bymod[mod_name] = mod_data
        #Let's rewrite this using the dictionary we now have without any logical change (could do with some...):
        for key in times_bymod.keys():
                for label in times_bymod[key].keys():
                        mod_data={'label':label}
                        for name in times_bymod[key][label].keys():
                                mod_data.update({'name':name})
                                mod_data['stats']= calc_MinMaxAvgRMS(f_time= lambda x:x[0],f_evt_num=lambda x:x[1],items=times_bymod[key][label][name])
                                mod_data['stats']['num_events']=len(times_bymod[key][label][name])
                times_bymod[key]=mod_data
        return times_bymod

def manual_run():
        timelog_f = "TTBAR__RAW2DIGI,RECO_TimingReport.log"
        timelog_f = "TTBAR__GEN,SIM,DIGI,L1,DIGI2RAW,HLT_TimingReport.log"      
        #TODO: get STEP name from filename
        release_files = {
                         
                         "CMSSW_3_1_0_pre9": 
                         (
                         "CMSSW_3_1_0_pre9/MINBIAS__RAW2DIGI,RECO_TimingReport.log", 
                          "CMSSW_3_1_0_pre9/TTBAR__RAW2DIGI,RECO_TimingReport.log")
                         ## "CMSSW_3_1_0_pre10": 
                         }
        for release, files in release_files.items():
                print "Processing release: %s" % release
                for timelog_f in files:
                        print "Processing file: %s" % timelog_f
                        
                        # TODO: automaticaly detect type of report file!!!
                        (mod_timelog, evt_timelog, rss_data, vsize_data) =loadTimeLog(timelog_f)
                        
                        mod_timelog= processModuleTimeLogData(mod_timelog, groupBy = "module_label")
                        print "Number of modules grouped by (module_label): %s" % len(mod_timelog)

                        (candle, step, pileup_type, conditions, event_content) = getJobID_fromTimeReportLogName(timelog_f)
                        
                        """ We could get release from the path but that's quite ugly! """
                        export_xml(jobID = jobID, release=release, timelog_result=(mod_timelog, evt_timelog, rss_data, vsize_data))     

""" use to run performance profiling """
def perf_profile():
        timelog_f = "test_data/TTBAR__RAW2DIGI,RECO_TimingReport.log"
        (modules_timelog, evt_timelog, rss_data, vsize_data) = loadTimeLog(timelog_f)   

        mod_timelog= processModuleTimeLogData(modules_timelog, groupBy = "module_label")

        (candle, step, pileup_type, conditions, event_content) = getJobID_fromTimeReportLogName(timelog_f)
        
        xmldoc = minidom.Document()
        export_xml(step = step, candle = candle, release="test", timelog_result=(mod_timelog, evt_timelog, rss_data, vsize_data), xml_doc = xmldoc)     
        write_xml(xmldoc, "test_xml_output.xml")
        
if (__name__ == "__main__"):
        perf_profile()