Timing report from different analyzer about cmg-cmssw HOT 5 CLOSED

Here the report of the timing from the run_susyMT2_cfg.py.

Posted the profileMT2.out in the twiki page
https://twiki.cern.ch/twiki/bin/viewauth/CMS/SUSYCMGfwk#Checking_your_timing

Test done on 1000 ev of /TTJets_MSDecaysCKM_central_Tune4C_13TeV-madgraph-tauola/Phys14DR-PU20bx25_PHYS14_25_V1-v1/MINIAODSIM

Ordering by cumulative time, the worst offender are those

ncalls tottime percall cumtime percall filename:lineno(function)
1000 0.050 0.000 40.352 0.040 IsoTrackAnalyzer.py:193(process)
1000 21.960 0.022 40.256 0.040 IsoTrackAnalyzer.py:65(makeIsoTrack)
1000 0.015 0.000 35.843 0.036 SkimAnalyzerCount.py:59(process)
1000 0.367 0.000 12.741 0.013 JetAnalyzer.py:80(process)
1000 0.029 0.000 9.250 0.009 PhotonAnalyzer.py:163(process)
1000 0.017 0.000 8.367 0.008 LeptonAnalyzer.py:424(process)
1000 0.133 0.000 7.935 0.008 LeptonAnalyzer.py:98(makeLeptons)
1000 0.008 0.000 6.851 0.007 GeneratorAnalyzer.py:214(process)
1000 2.429 0.002 6.837 0.007 GeneratorAnalyzer.py:63(makeMCInfo)
1000 3.641 0.004 6.748 0.007 PhotonAnalyzer.py:104(matchPhotons)

from cmg-cmssw.

Hi Maria,

where exactly do you get these numbers from?
I ran:
python -m cProfile -o profile1Lep.out $CMSSW_BASE/src/PhysicsTools/HeppyCore/python/framework/heppy.py Trash run_susySinglelepton_cfg.py -f -N 1000
on the same TTbar sample, but when I look into the output file (profile1Lep.out), I see some binary content mixed with what looks like my LD_LIBRARY_PATH.

Thanks,
Artur

On 4 Feb 2015, at 18:01, mariadalfonso [email protected] wrote:

Here the report of the timing from the run_susyMT2_cfg.py.

Posted the profileMT2.out in the twiki page
https://twiki.cern.ch/twiki/bin/viewauth/CMS/SUSYCMGfwk#Checking_your_timing https://twiki.cern.ch/twiki/bin/viewauth/CMS/SUSYCMGfwk#Checking_your_timing
Test done on 1000 ev of /TTJets_MSDecaysCKM_central_Tune4C_13TeV-madgraph-tauola/Phys14DR-PU20bx25_PHYS14_25_V1-v1/MINIAODSIM

Ordering by cumulative time, the worst offender are those

ncalls tottime percall cumtime percall filename:lineno(function)
1000 0.050 0.000 40.352 0.040 IsoTrackAnalyzer.py:193(process)
1000 21.960 0.022 40.256 0.040 IsoTrackAnalyzer.py:65(makeIsoTrack)
1000 0.015 0.000 35.843 0.036 SkimAnalyzerCount.py:59(process)
1000 0.367 0.000 12.741 0.013 JetAnalyzer.py:80(process)
1000 0.029 0.000 9.250 0.009 PhotonAnalyzer.py:163(process)
1000 0.017 0.000 8.367 0.008 LeptonAnalyzer.py:424(process)
1000 0.133 0.000 7.935 0.008 LeptonAnalyzer.py:98(makeLeptons)
1000 0.008 0.000 6.851 0.007 GeneratorAnalyzer.py:214(process)
1000 2.429 0.002 6.837 0.007 GeneratorAnalyzer.py:63(makeMCInfo)
1000 3.641 0.004 6.748 0.007 PhotonAnalyzer.py:104(matchPhotons)

—
Reply to this email directly or view it on GitHub #230 (comment).

from cmg-cmssw.

@artlbv
In the twiki there are the extra lines you need to type into python
https://twiki.cern.ch/twiki/bin/viewauth/CMS/SUSYCMGfwk#Checking_your_timing

import pstats
p = pstats.Stats('profile1Lep.out ')
p.strip_dirs().sort_stats('cumulative').print_stats('Analyzer',20)

from cmg-cmssw.

Thanks @mariadalfonso! I didn't realise the "In pyroot" part is the second step.

Here's the result for the run_susySinglelepton with the recent MVA updates:

Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1000 0.009 0.000 610.299 0.610 SkimAnalyzerCount.py:59(process)
1000 0.010 0.000 68.045 0.068 LeptonAnalyzer.py:424(process)
1000 0.103 0.000 67.657 0.068 LeptonAnalyzer.py:98(makeLeptons)
423 0.012 0.000 43.893 0.104 IsoTrackAnalyzer.py:193(process)
423 9.022 0.021 43.859 0.104 IsoTrackAnalyzer.py:65(makeIsoTrack)
423 0.010 0.000 37.444 0.089 PhotonAnalyzer.py:163(process)
1000 0.174 0.000 36.289 0.036 LeptonAnalyzer.py:182(makeAllMuons)
423 0.108 0.000 33.646 0.080 JetAnalyzer.py:80(process)
1000 0.066 0.000 30.963 0.031 LeptonAnalyzer.py:253(makeAllElectrons)
1000 0.004 0.000 19.959 0.020 GeneratorAnalyzer.py:214(process)
1000 2.506 0.003 19.950 0.020 GeneratorAnalyzer.py:63(makeMCInfo)
423 0.003 0.000 19.525 0.046 TauAnalyzer.py:104(process)
423 0.036 0.000 19.515 0.046 TauAnalyzer.py:48(makeTaus)
423 0.019 0.000 19.132 0.045 PhotonAnalyzer.py:45(makePhotons)
1000 0.033 0.000 18.361 0.018 VertexAnalyzer.py:90(process)
423 1.610 0.004 18.300 0.043 PhotonAnalyzer.py:104(matchPhotons)
423 4.274 0.010 15.040 0.036 ttHHeavyFlavourHadronAnalyzer.py:15(process)
1000 0.077 0.000 12.020 0.012 PileUpAnalyzer.py:97(process)
846 6.012 0.007 8.277 0.010 TriggerBitAnalyzer.py:51(process)
423 2.501 0.006 8.184 0.019 ttHSVAnalyzer.py:48(process)

from cmg-cmssw.

Hi Maria, all,

I have run a time report after the IsoTrack analyzer was implemented in C. I notice significant timing improvements. (15 ev/s -> 30/40 ev/s interactively).

Along with this, any skimmers were optimally rearranged to occur first for the analyzers that took the least amount of time.

The results from this latest timing report are:

Thu Feb 12 17:32:40 2015 profileRa1Fix.out

     5831585 function calls (5762137 primitive calls) in 43.377 seconds

Ordered by: cumulative time
List reduced from 2055 to 237 due to restriction <'Analyzer'>
List reduced from 237 to 20 due to restriction <20>

ncalls tottime percall cumtime percall filename:lineno(function)
657 0.147 0.000 6.800 0.010 JetAnalyzer.py:80(process)
1000 0.004 0.000 5.019 0.005 GeneratorAnalyzer.py:214(process)
1000 2.610 0.003 5.011 0.005 GeneratorAnalyzer.py:63(makeMCInfo)
658 0.015 0.000 4.702 0.007 PhotonAnalyzer.py:163(process)
658 2.716 0.004 4.072 0.006 PhotonAnalyzer.py:104(matchPhotons)
1000 0.009 0.000 3.960 0.004 LeptonAnalyzer.py:424(process)
1000 0.100 0.000 3.597 0.004 LeptonAnalyzer.py:98(makeLeptons)
657 0.535 0.001 3.470 0.005 ttHCoreEventAnalyzer.py:145(process)
1 0.000 0.000 2.005 2.005 ttHCoreEventAnalyzer.py:10(init)
657 0.025 0.000 1.666 0.003 JetAnalyzer.py:302(matchJets)
1000 0.159 0.000 1.623 0.002 LeptonAnalyzer.py:182(makeAllMuons)
1000 0.067 0.000 1.572 0.002 LeptonAnalyzer.py:253(makeAllElectrons)
32 0.001 0.000 1.542 0.048 IsoTrackAnalyzer.py:254(process)
32 0.527 0.016 1.541 0.048 IsoTrackAnalyzer.py:71(makeIsoTrack)
1000 0.008 0.000 1.195 0.001 SkimAnalyzerCount.py:59(process)
657 0.003 0.000 0.953 0.001 METAnalyzer.py:119(process)
657 0.068 0.000 0.930 0.001 METAnalyzer.py:95(makeMETs)
657 0.327 0.000 0.884 0.001 JetAnalyzer.py:266(jetFlavour)
657 0.003 0.000 0.883 0.001 TauAnalyzer.py:104(process)
657 0.049 0.000 0.869 0.001 TauAnalyzer.py:48(makeTaus)

I’ll put the file profileRa1.out on the twiki for people’s reference.

Cheers,
Adam

On 4 Feb 2015, at 18:38, mariadalfonso <[email protected]mailto:[email protected]> wrote:

@artlbvhttps://github.com/artlbv
In the twiki there are the extra lines you need to type into python
https://twiki.cern.ch/twiki/bin/viewauth/CMS/SUSYCMGfwk#Checking_your_timing

import pstats
p = pstats.Stats('profile1Lep.out ')
p.strip_dirs().sort_stats('cumulative').print_stats('Analyzer',20)

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/230#issuecomment-72900649.

from cmg-cmssw.