CMS MessageLogger: Controlling LogDebug Behavior

Code in user modules can be instrumented with LogDebug messages, intended for use when abnormal circumstances require the output of detailed information. In order that this instrumentation can be left in place without impacting performance under normal circumstances, it is important that LogDebug messages, by default, cost as little as possible in runtime overhead. That includes:

  • Avoiding sending the messages through the logic that gives each destination a chance to respond.
  • Measures to eliminate almost all of the cost of processing the operator<< operations that stream text or other items to the message.

Since LogDebug messages are (by default) rapidly discarded, the user can explicitly enable LogDebug messages issued by some or all modules. This is done without needing to re-compile code, via parameters in the .cfg file.

For time-critical running, there is also a way to eliminate the effect of LogDebug messages at compile-time. When this approach is used, the LogDebug calls will be optimized down to be truly zero-cost. The trade-off is that for code compiled with this switch set, the LogDebug messages cannot be explicitly enabled via parameters in the .cfg file.


Enabling LogDebug Messages in the new syntax

For an example with the "new syntax" made default in CMSSW_11_3_0_pre1 please see FWCore/MessageService/Readme.md.


Enabling LogDebug Messages

Code can be freely sprinkled with LogDebug messages, without fear of undue performance overhead: By default, each call to LogDebug("category") will consult a boolean variable to check whether debug messages are enabled for the current module. Unless debug messages have explicitly been enabled, LogDebug() will do no other work, and each operator<< to the LogDebug will merely check that same boolean and do no work either.

In order to "turn on" responses to LogDebug, the user does two things in the .cfg file, as illustrated by this example:

import FWCore.ParameterSet.Config as cms
process = cms.Process("MessageLoggerExample")
process.load("FWCore.MessageLogger.MessageLogger_cfi")
process.MessageLogger = cms.Service(
    "MessageLogger",
    destinations = cms.untracked.vstring(
        'detailedInfo',
         'critical'
         ),
    detailedInfo = cms.untracked.PSet(
        threshold = cms.untracked.string('DEBUG')
         ),
    debugModules = cms.untracked.vstring(
        'myAnalysisModule',
        'myOtherModule' 
        )
    )

# set the number of events
process.maxEvents = cms.untracked.PSet(
    input = cms.untracked.int32(5)
)
 
process.myAnalysisModule = cms.EDAnalyzer('ModuleThatIssuesDebugMessages')
process.myOtherModule = cms.EDAnalyzer('ModuleThatIssuesDebugMessages')
process.aThirdModule = cms.EDAnalyzer('ModuleThatIssuesDebugMessages')
process.p = cms.Path(process.myAnalysisModule,process.myOtherModule, process.aThirdModule)

The string threshold = "DEBUG" parameter in the Pset for detailedInfo.txt specifies that the destination writing to that file should respond to all messages of severity DEBUG or higher -- that is, to all messages. By default the threshold is INFO, so in the above example, the destination writing to critical.txt would not report the LogDebug messages.

The vstring debugModules = {...} list specifies all the modules for which LogDebug should be enabled. As illustrated, these modules are specified by their module labels. In this example, LogDebug messages issued while in

myAnalysisModule or myOtherModule would be enabled, while those issued while in aThirdModule would be rapidly discarded.

Enabling all LogDebug Messages

One further syntax is provided, for the convenience of users wishing to enable all LogDebug messages:
import FWCore.ParameterSet.Config as cms
process = cms.Process("MessageLoggerExample")
process.load("FWCore.MessageLogger.MessageLogger_cfi")
process.MessageLogger = cms.Service(
    "MessageLogger",
    destinations = cms.untracked.vstring(
        'detailedInfo',
         'critical'
         ),
    detailedInfo = cms.untracked.PSet(
        threshold  = cms.untracked.string('DEBUG') 
         ),
    debugModules = cms.untracked.vstring('*')
    )

# set the number of events
process.maxEvents = cms.untracked.PSet(
    input = cms.untracked.int32(5)
)
 
process.myAnalysisModule = cms.EDAnalyzer('ModuleThatIssuesDebugMessages')
process.myOtherModule = cms.EDAnalyzer('ModuleThatIssuesDebugMessages')
process.aThirdModule = cms.EDAnalyzer('ModuleThatIssuesDebugMessages')
process.p = cms.Path(process.myAnalysisModule,process.myOtherModule, process.aThirdModule)
(Remember that you still have to set one or more thresholds to DEBUG. Unless some destination(s) have their thresholds set at DEBUG, the LogDebug messages will be composed but no destination will report them.)

Compile-time Elimination of LogDebug Messages

If NDEBUG is defined (this is the same NDEBUG that would turn assert into nothingness), then the LogDebug macro will be transformed into a form that is easily optimized down to zero run-time cost.

If the code was compiled with NDEBUG defined, LogDebug messages will be completely suppressed (even if the .cfg file directs that they be enabled), since the code for testing whether such messages are enabled will not be present.

While the default behavior, as described above, is tied to the same NDEBUG that applies to assert macros, two additional symbols are provided to allow the user to over-ride that behavior.

  • If ML_NDEBUG is defined, then LogDebug message code will not be compiled (that is, LogDebug will be transformed into the zero-runtime-cost form) even if NDEBUG

    is not defined.

  • If ML_DEBUG is defined, then LogDebug message code will be compiled, not matter what.

Why are my LogDebug Messages Not Being Reported?

By design, the MessageLogger avoids (by default) reporting LogDebug messages, and discards such messages as rapidly as possible unless they are enabled. In addition, destinations' thresholds are set above that of DEBUG severity by default; again, users must specifically indicate that they want a destination to respond to LogDebug messages. This design choice was made so that users can instrument their code with (normally inactive) LogDebug diagnostics, and leave these in for future use without impacting performance when the information is not needed.

A consequence of this policy is that there are several points at which LogDebug message responses can be disabled, and the user requiring such output needs to enable both the issuing and the reporting of the messages.

If you are trying to get your LogDebug messages to be reported and they are not being shown, here is a checklist of reasons why LogDebug messages would not be reported by a destination:

  1. The purpose of !LogDebug messages is to aid the development and debugging of code. As such information in general is only useful to the developer of a certain part of the code, !LogDebug messages are disabled/discarded by default in CMSSW framework.

    To enable this from your configuration file first you addpkg the code with the messages in it and recompile it with

    USER_CXXFLAGS="-g -D=EDM_ML_DEBUG" scram b -v # for bash

    env USER_CXXFLAGS="-g -D=EDM_ML_DEBUG" scram b -v # for tcsh

  2. If the .cfg file does not explicitly enable LogDebug messages for a given module, such messages issued by that module will be discarded. Make sure the parameter vstring debugModules = { "myModuleLabel" } is present in the MessageLogger parameter set. Check the spelling of debugModules and check that the module label supplied is the correct label. This label will appear outside the MessageLogger parameter set, on the left side of a module myModuleLabel = parameter and in the path = { ..., myModuleLabel, ...} parameter.

    vstring debugModules = { "*" } enables LogDebug messages from all modules.

  3. The threshold for every destination is, by default, set above the level that would permit LogDebug messages to be reported. In the parameter set for the desired reporting destination, there must appear string threshold = "DEBUG"

-- SudhirMalik - 30-Aug-2011

Edit | Attach | Watch | Print version | History: r9 < r8 < r7 < r6 < r5 | Backlinks | Raw View | WYSIWYG | More topic actions
Topic revision: r9 - 2020-12-18 - MattiKortelainen
 
    • 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-2022 by the contributing authors. All material on this collaboration platform is the property of the contributing authors.
or Ideas, requests, problems regarding TWiki? use Discourse or Send feedback