CMS MessageLogger Service: Obtaining Message Statistics

"New syntax" (CMSSW_11_2_0_pre10 and after)

The statistics printout can be enabled and disabled for each destination with a simple boolean flag. See FWCore/MessageService/Readme.md for an example.

"Old syntax" (CMSSW_11_3_0_pre2 and before)

The MessageLogger service can provide statistics about the message issued during the course of a job. The information is placed in tables either at the end of a log file or in an individual file. The user code can also trigger statistics summaries of messages issued thus far --
see The edm::LogStatistics() Function and The edm::GroupLogStatistics() Function

These statistics tables, written when the MessageLogger service encounters its postEndJob callback, include:

• Counts of how many times a message with each combination of category, severity and module has been issued. (That is, if messages in the identical category are issued by two different modules, or one by LogWarning and another by LogInfo, these will be counted distinctly in the statistics.)
• Samples of the run/event contexts for the first two and the last one message of each type that were issued.
• Indications of whether there were any messages of a given type which were issued but were not reported (due to limits) by any destination.

import FWCore.ParameterSet.Config as cms
process.load("FWCore.MessageLogger.MessageLogger_cfi")
process.MessageLogger = cms.Service("MessageLogger",
       destinations   = cms.untracked.vstring('detailedInfo'),
       statistics     = cms.untracked.vstring('statistics1',
                                              'another_stats',
                                              'error_messages'
                        ),
        statistics1 = cms.untracked.PSet(threshold = cms.untracked.string('WARNING')
        ),
        another_stats  = cms.untracked.PSet(output = cms.untracked.string('more_stats.txt')
        ),
        error_messages = cms.untracked.PSet(threshold = cms.untracked.string('ERROR')
        )
   )

process.source = cms.Source("PoolSource", fileNames = cms.untracked.vstring())
process.maxEvents = cms.untracked.PSet( input       = cms.untracked.int32(10) )
process.options   = cms.untracked.PSet( wantSummary = cms.untracked.bool(True) )

The vstring statistics = ('statistics1', 'another_stats', 'error_messages') directs the system to attach a three statistics destinations, to be controlled by parameter sets named statistics1, another_stats, and error_messages. (Normally, only one statistics destination is desired; here we use three to illustrate various control options.)

statistics1 = cms.untracked.PSet(threshold = cms.untracked.string('WARNING') directs statistics1 to respond to (and keep track of) only LogError and LogWarning messages. Statistics destinations do not impose limits for each category (they only count the messages anyway) but they are sensitive to thresholds of which severities to report about.

another_stats = cms.untracked.PSet(output = cms.untracked.string('more_stats.txt') directs the statistics1 destination controlled by the another_stats PSet to write its output to the file more_stats.txt. If no output were specified, then the statistics destination would write its summary to a file with the name listed in the statistics vstring. For example, with the above .cfg file, the statistics destination would write to statistics1.log.

error_messages = cms.untracked.PSet(threshold = cms.untracked.string('ERROR') controls both the error_messages output destination, and the error_messages statistics destination. Thus that statistics destination will respond with a threshold of LogError, and will write its end-of-job summary to the end of the file error_messages.log.

In general, any statistics destination whose output file name (as determined either by an explicit output string or implicitly as the same name used to control the destination) matches the file of an ordinary destination, will write its summary output at the end of that ordinary destination's file.

---

Here is a sample statistics summary output:

=============================================

MessageLogger Summary

 type     category        sev    module        subroutine        count    total
 ---- -------------------- -- ---------------- ----------------  -----    -----
    1 CondDBESSource       -i AfterSource                         1058     1058
    2 CondDBESSource       -i PostEndLumi                            2        2
    3 CondDBESSource       -i PostModule                             2        2
    4 DCacheFileInfo       -i file_open                              1        1
    5 EventSetupDependency -i AfterSource                            4        4
    6 FwkReport            -i AfterSource                            5        5
    7 HCAL                 -i (NoModuleName)                         1        1
    8 HCAL                 -i AfterSource                            1        1
    9 Root_Information     -i AfterFile        TClass::TClass        4        4
   10 Root_Information     -i HiMassTauAnalysi TClass::TClass        2        2
   11 SiPixelQualityESProd -i (NoModuleName)                         1        1
   12 SiStripDetInfoFileRe -i (NoModuleName)                         1        1
   13 SiStripDetInfoFileRe -i (NoModuleName)                         1        1
   14 SiStripLorentzAngleD -i (NoModuleName)                         1        1
   15 SiStripQualityESProd -i (NoModuleName)                         1        1
   16 path                 -i AfterModConstruc                       1        1
   17 fileAction           -s file_close                             1        1
   18 fileAction           -s file_open                              2        2

 type    category    Examples: run/evt        run/evt          run/evt
 ---- -------------------- ---------------- ---------------- ----------------
    1 CondDBESSource       BeforeEvents     BeforeEvents     PostProcessEvent
    2 CondDBESSource       PostEndLumi      PostEndLumi
    3 CondDBESSource       PostProcessEvent PostProcessEvent
    4 DCacheFileInfo       pre-events
    5 EventSetupDependency BeforeEvents     BeforeEvents     BeforeEvents
    6 FwkReport            PostBeginLumi    PostProcessEvent PostProcessEvent
    7 HCAL                 pre-events
    8 HCAL                 BeforeEvents
    9 Root_Information     pre-events       pre-events       pre-events
   10 Root_Information     1/5465152        1/5465152
   11 SiPixelQualityESProducer::SiPixelQualityESProducer pre-events
   12 SiStripDetInfoFileReader pre-events
   13 SiStripDetInfoFileReader::SiStripDetInfoFileReader - END of file reached pre-events
   14 SiStripLorentzAngleDepESProducer pre-events
   15 SiStripQualityESProducer pre-events
   16 path                 pre-events
   17 fileAction           PostEndRun
   18 fileAction           pre-events       pre-events

Severity    # Occurrences   Total Occurrences
--------    -------------   -----------------
Info                 1086                1086
System                  3                   3

---

The edm::LogStatistics() Function

The user program can force each statistics destination to write its current message counts and summary to its file or stream, before the end of job automatically causes that writing. To do this, invoke the function

edm::LogStatistics();

(Just as for edm::LogError() and the other message commands, this function is defined by including MessageLogger.h).

While ordinary analysis code probably has no need to invoke this, one can use the framework's features to set up a sensible schedule of outputting statistics. For example, one can place a call to edm::LogStatistics() in a postRun callback.

The default behavior is to output the statistics thus far accumulated, and then to continue collecting statistics. If, for some statistics destination, it is preferable that the statistics be reset to zero after each summary output, this can be directed in the PSet for that statistics destination:

import FWCore.ParameterSet.Config as cms
process = cms.Process('TEST')
process.load("FWCore.MessageLogger.MessageLogger_cfi")
process.MessageLogger = cms.Service("MessageLogger",
       destinations   = cms.untracked.vstring('error_messages.txt'),
       statistics     = cms.untracked.vstring('statistics1', 'runstats'),   
  statistics1 = cms.untracked.PSet(threshold = cms.untracked.string('WARNING')
        ),
  runstats  = cms.untracked.PSet(reset = cms.untracked.bool(True))
   )
process.source = cms.Source("PoolSource", fileNames = cms.untracked.vstring())
process.maxEvents = cms.untracked.PSet( input       = cms.untracked.int32(10) )
process.options   = cms.untracked.PSet( wantSummary = cms.untracked.bool(True) )

In this example, the statistics kept by runstats.log will be reset after each statistics output triggered by edm::LogStatistics().

Of course, the bool reset parameter is moot if the program never explicitly invokes edm::LogStatistics(), since it is immaterial whether the statistics are reset after the final automatic end-of-job summary is output.

---

The edm::GroupLogStatistics() Function

Ordinarily, the statistics output is broken down by a key of category and module. That is, if hundreds of modules are issuing messages in the category "timer", then the statistics table will separately list the number of such messages issued by each module.

In some cases, particularly if the message outputs are throttled back by limits or thresholds, it is desirable to group all the various modules issuing some category of message together into a single line in the statistics output. The user program can force this for a given category by invoking the function

edm::GroupLogStatistics("category");

(This function is defined by including MessageLogger.h).

In the example mentioned above, the category name supplied would be "timer". Multiple calls to GroupLogStatistics are permitted, to set up grouping for several categories.

See FWCore/MessageService/test/u23.cfg and UnitTestClient_Q.h for an example of a program that uses this feature.

-- SudhirMalik - 30-Aug-2011