Using EDM Timing and Memory tools

Complete: 2

The Framework provides some basic services that measure timing and perform simple memory footprint checks at module boundaries. For more sophisticated profiling, see the Performance Suite.

Timing service

Configure the Timing service as follows:

process.Timing = cms.Service("Timing",
  summaryOnly = cms.untracked.bool(False),
  useJobReport = cms.untracked.bool(True)

If summaryOnly is true, then it only prints the report that is generated after endJob completes. The default is false. If useJobReport is true, some parts of the information get printed to the Job Report. The default is true.

The output of the module looks like this:

After beginJob completes this prints (JobTime is real time since 1970, JobCPU is CPU time between process start and the end of beginJob):

TimeReport> Report activated
TimeReport> Report columns headings for events: eventnum runnum timetaken
TimeReport> Report columns headings for modules: eventnum runnum modulelabel modulename timetakeni
TimeReport> JobTime=1.46194e+09 JobCPU=1.77573

After each event, it prints event number, run number and real time for the event.

TimeEvent> 3 1 0.0006001

After each module, it prints event number, run number, module label, module class name, and real time for the module.

TimeModule> 3 1 out PoolOutputModule 9.60827e-05

After endJob, it prints this summary:

TimeReport> Time report complete in 0.396469 seconds
 Time Summary: 
 - Min event:   0.0006001
 - Max event:   0.00141501
 - Avg event:   0.000872691
 - Total loop:  0.327604
 - Total job:   0.396469
 Event Throughput: 9.1574 ev/s
 CPU Summary: 
 - Total loop:  0.015998
 - Total job:   0.024996

"Real time" or "time" is wall clock time and its accurancy is that of gettimeofday(2). CPU time is that reported by getrusage and is the sum of regular and system CPU time.

The per module time is corrected by subtracted the time for other modules run on the same thread between the start and stop times of the module.

There are no corrections to the event time. It is simply the difference between the start and stop times for the event.

The loop time refers to the time between post beginJob and the end of the last global endRun transition. The job time refers to the time between post beginJob and the post endJob transitions. The throughput is calculated using the loop time. Note that neither of these includes the startup time before the end of beginJob or the time after endJob. In a short job these can be significant compared to the total time.

Note the average and max time per event are calculated including the first event which usually takes significantly longer than other events.

The time on the first line of the post endJob summary is redundant. It is the same as the total job time.

SimpleMemoryCheck service

Configure the service as follows:

process.SimpleMemoryCheck = cms.Service("SimpleMemoryCheck",
    ignoreTotal = cms.untracked.int32(1)

There are more parameters than the one shown above. One can determine the full set of parameters available using the edmPluginHelp utility. In release series 8_1_X, this yields:

edmPluginHelp -b -p SimpleMemoryCheck
1  SimpleMemoryCheck  (Service)  ""
  1.1 SimpleMemoryCheck
    ignoreTotal          untracked int32  1
    showMallocInfo       untracked bool   False
    oncePerEventMode     untracked bool   False
    jobReportOutputOnly  untracked bool   False
    monitorPssAndPrivate untracked bool   False
    moduleMemorySummary  untracked bool   False
    M_MMAP_MAX           untracked int32  -1
    M_TRIM_THRESHOLD     untracked int32  -1
    M_TOP_PAD            untracked int32  -1
    M_MMAP_THRESHOLD     untracked int32  -1
    dump                 untracked bool   False

WARNING: I updated this section to this point on 29 April 2016 by replacing things that were obviously many years out of date. The rest of the content I am leaving as it was, but the following content needs to be reviewed by someone familiar with the details of this service. Some or all of it may be out of date. It is incomplete. It does not describe what all the configuration parameters are for.

This service keeps a record of the largest virtual memory (VSIZE) and resident set size (RSS) achieved so far by the process. For every event, after each module has run, this service reads the VSIZE/RSS and compares it to the maximum. If the current module caused an increase in memory used, a warning message is issues indicating the module name and the old and new values of VSIZE and RSS.

The parameter "ignoreTotal" defines for how many events the service won't report any memory memory footprint increases. The default is to start reporting after the first event.

This is a crude and coarse form of checking. The service is merely pointing out that a memory increase has been observed after a particular module has executed. In most circumstances, it does turn out to be the reported module that has caused the increase. In more rare cases, the module previous to the current could have come right up to the current limit. The current module, just in its normal operation, might push the limit up and not really be responsible.

Please note that many utility libraries (like STL containers) will allocate lots of memory the first time they are used and hold it for a long time. Only rarely will they need more (if, for example, a working container doubles in size because of a complex event). This service will report the increase. Sometimes these are important depending on how much more memory is needed.

Most useful is seeing a per-event trend where memory usage is slowly rising. Another is to see certain types of events cause memory use to rise sharply

There is a configuration option named monitorPssAndPrivate which enables monitoring of PSS and private memory in both the printed output and the output that goes to the job report. Private memory is that memory which is in physical memory and not shared with other processes. PSS is the sum of private memory and shared memory where the shared memory has been divided by the number processes sharing it. To function this option requires reading the smaps file in the proc file system. This takes a significant amount of system CPU time. In a process with a high event rate, this can take more CPU time than everything else combined. It is strongly recommended this option not be turned in production configurations intended for high event rate processes. When it was originally implemented this monitoring was always on and caused problems at several sites, wasting CPU resources. By default it is turned off.

There is a further use for the services here, and that's in Production, where worker nodes are often shared between experiments. It has often happened that a job is running fine on a node, but that another job starts up and takes all the memory (typically leaking), causing excessive paging. The symptoms in one of our jobs would then be a sharp drop in RSS and a great increase in wall-clock time per event (but not CPU time).

The impact of this on our wall-clock time can be a slowdown of 2-3 orders of magnitude, and our best response is to kill our job and restart it on another node. Production throughput CMS-wide will be improved if we can spot this problem early, so please consider what it would need to make it easy to do so. (from Tony Wildish).

Review status

Reviewer/Editor and Date (copy from screen) Comments
Main.jbk - 30 Jan 2006 created page
JennyWilliams - 31 Jan 2007 editing to include in SWGuide
DavidDagenhart - 29 Jan 2016 update Timing Service documentation to match code that has existed for a long time

Responsible: Main.jbk
Last reviewed by: Reviewer

Edit | Attach | Watch | Print version | History: r12 < r11 < r10 < r9 < r8 | Backlinks | Raw View | WYSIWYG | More topic actions
Topic revision: r12 - 2016-04-29 - DavidDagenhart

    • Cern Search Icon Cern Search
    • TWiki Search Icon TWiki Search
    • Google Search Icon Google Search

    CMSPublic All webs login

This site is powered by the TWiki collaboration platform Powered by PerlCopyright & 2008-2019 by the contributing authors. All material on this collaboration platform is the property of the contributing authors.
Ideas, requests, problems regarding TWiki? Send feedback