Debugging

Sometimes your options files don’t do what you expect them to. Analysing the output is a good first step, but there are a few other techniques that can be useful.

This page will continue to use the two options files made in the Running Moore tutorial.

Dry runs

When the problem is with the configuration, you often don’t need to actually run the application itself, just the configuration step. You can do this with the -n flag that gaudirun.py supports:

./Moore/run gaudirun.py -n input_data.py hlt1_example.py

This will stop just before running the application, so will also generate the Data and control flow graphs described above.

An easy way to see DEBUG level messages from Python is to pass --debug to gaudirun.py:

./Moore/run gaudirun.py -n --debug input_data.py hlt1_example.py

Dumping the configuration

When executed together, a set of options files define the configuration of a number of Gaudi Configurable objects, and this configuration can be dumped to a file. We can create a dump with our example options using the --all-opts and --output flags to gaudirun.py (combined with the dry runs technique, as we don’t need the application itself to run):

./Moore/run gaudirun.py -n --all-opts --output default_example.opts.py input_data.py hlt1_example.py

Have a poke around the created file, default_example.opts.py, and see what it contains. This can be very useful by itself.

Inspecting differences

By dumping the configuration of two runs of some options files, we can compare them. The diffopts.py script included in Moore let’s you _see_ how a change to your options file affects the configuration of the application.

As an example, create a new options file called input_data_digi.py that loads a different key from the test file database:

from Moore import options

options.evt_max = 100
options.set_input_and_conds_from_testfiledb("MiniBrunel_2018_MinBias_FTv4_DIGI")

This loads files with the .digi extension, rather than the .mdf extension we’ve been using.

Create an options file dump as before, but substitute input_data.py with the new file, and give a different name to the --output argument of gaudirun.py, say digi_example.opts.py.

Finally, run the diff script:

./Moore/run diffopts.py default_example.opts.py digi_example.opts.py

This prints out the diff in the same style the git diff command does:

diff --git default_example.opts.py/EventSelector digi_example.opts.py/EventSelector
index 4e66aef..f59a649 100644
--- default_example.opts.py/EventSelector
+++ digi_example.opts.py/EventSelector
@@ -8,16 +8,12 @@
 "EvtMax": 2147483647
 "FirstEvent": 0
 "Input": [
-    "DATAFILE='mdf:root://eoslhcb.cern.ch//eos/lhcb/grid/prod/lhcb/swtest/lhcb/swtest/MiniBrunel/00067189.mdf' SVC='LHCb::MDFSelector' OPT='READ' IgnoreChecksum='YES'",
-    "DATAFILE='mdf:root://eoslhcb.cern.ch//eos/lhcb/grid/prod/lhcb/swtest/lhcb/swtest/MiniBrunel/00067189.mdf' SVC='LHCb::MDFSelector' OPT='READ' IgnoreChecksum='YES'",
-    "DATAFILE='mdf:root://eoslhcb.cern.ch//eos/lhcb/grid/prod/lhcb/swtest/lhcb/swtest/MiniBrunel/00067189.mdf' SVC='LHCb::MDFSelector' OPT='READ' IgnoreChecksum='YES'",
-    "DATAFILE='mdf:root://eoslhcb.cern.ch//eos/lhcb/grid/prod/lhcb/swtest/lhcb/swtest/MiniBrunel/00067189.mdf' SVC='LHCb::MDFSelector' OPT='READ' IgnoreChecksum='YES'",
-    "DATAFILE='mdf:root://eoslhcb.cern.ch//eos/lhcb/grid/prod/lhcb/swtest/lhcb/swtest/MiniBrunel/00067189.mdf' SVC='LHCb::MDFSelector' OPT='READ' IgnoreChecksum='YES'",
-    "DATAFILE='mdf:root://eoslhcb.cern.ch//eos/lhcb/grid/prod/lhcb/swtest/lhcb/swtest/MiniBrunel/00067189.mdf' SVC='LHCb::MDFSelector' OPT='READ' IgnoreChecksum='YES'",
-    "DATAFILE='mdf:root://eoslhcb.cern.ch//eos/lhcb/grid/prod/lhcb/swtest/lhcb/swtest/MiniBrunel/00067189.mdf' SVC='LHCb::MDFSelector' OPT='READ' IgnoreChecksum='YES'",
-    "DATAFILE='mdf:root://eoslhcb.cern.ch//eos/lhcb/grid/prod/lhcb/swtest/lhcb/swtest/MiniBrunel/00067189.mdf' SVC='LHCb::MDFSelector' OPT='READ' IgnoreChecksum='YES'",
-    "DATAFILE='mdf:root://eoslhcb.cern.ch//eos/lhcb/grid/prod/lhcb/swtest/lhcb/swtest/MiniBrunel/00067189.mdf' SVC='LHCb::MDFSelector' OPT='READ' IgnoreChecksum='YES'",
-    "DATAFILE='mdf:root://eoslhcb.cern.ch//eos/lhcb/grid/prod/lhcb/swtest/lhcb/swtest/MiniBrunel/00067189.mdf' SVC='LHCb::MDFSelector' OPT='READ' IgnoreChecksum='YES'"
+    "DATAFILE='root://eoslhcb.cern.ch//eos/lhcb/wg/SciFi/Simulation/MinBiasRawBankv5/00067189_1.digi.digi' SVC='Gaudi::RootEvtSelector' OPT='READ' IgnoreChecksum='YES'",
+    "DATAFILE='root://eoslhcb.cern.ch//eos/lhcb/wg/SciFi/Simulation/MinBiasRawBankv5/00067189_2.digi.digi' SVC='Gaudi::RootEvtSelector' OPT='READ' IgnoreChecksum='YES'",
+    "DATAFILE='root://eoslhcb.cern.ch//eos/lhcb/wg/SciFi/Simulation/MinBiasRawBankv5/00067189_3.digi.digi' SVC='Gaudi::RootEvtSelector' OPT='READ' IgnoreChecksum='YES'",
+    "DATAFILE='root://eoslhcb.cern.ch//eos/lhcb/wg/SciFi/Simulation/MinBiasRawBankv5/00067189_4.digi.digi' SVC='Gaudi::RootEvtSelector' OPT='READ' IgnoreChecksum='YES'",
+    "DATAFILE='root://eoslhcb.cern.ch//eos/lhcb/wg/SciFi/Simulation/MinBiasRawBankv5/00067189_5.digi.digi' SVC='Gaudi::RootEvtSelector' OPT='READ' IgnoreChecksum='YES'",
+    "DATAFILE='root://eoslhcb.cern.ch//eos/lhcb/wg/SciFi/Simulation/MinBiasRawBankv5/00067189_6.digi.digi' SVC='Gaudi::RootEvtSelector' OPT='READ' IgnoreChecksum='YES'"
 ]
 "OutputLevel": 0
 "PrintFreq": 10000

You can see here that the only difference is that the input file paths and xml catalogue are different. So we can already deduce many useful things that might help ourdebugging, such as the fact that the database tags are the same between the two sets of options (otherwise we would see different values in the diff).

Profiling

When your options files are slow, it can be useful to profile them. PyConf ships with an options file that will set up a profiler for you. Combined with dry runs, this allows you to quickly iterate on a slow-down:

./Moore/run gaudirun.py -n '$PYCONFROOT/options/profile_config.py' input_data.py hlt1_example.py

This prints out a timing table like this:

Elapsed CPU time 4.8
         4380348 function calls (4359554 primitive calls) in 6.796 seconds

   Ordered by: cumulative time
   List reduced from 1639 to 164 due to restriction <0.1>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        2    0.000    0.000    6.777    3.388 /home/apearce/stack/Gaudi/InstallArea/x86_64-centos7-gcc8-dbg/python/GaudiKernel/ProcessJobOptions.py:481(importOptions)
        2    0.000    0.000    6.776    3.388 /home/apearce/stack/Gaudi/InstallArea/x86_64-centos7-gcc8-dbg/python/GaudiKernel/ProcessJobOptions.py:457(_import_python)
        1    0.000    0.000    4.795    4.795 /home/apearce/stack/hlt1_example.py:1(<module>)
        1    0.000    0.000    4.612    4.612 /home/apearce/stack/Moore/Hlt/Moore/python/Moore/config.py:125(run_moore)
        1    0.000    0.000    3.434    3.434 /home/apearce/stack/Moore/PyConf/python/PyConf/application.py:430(configure)
        ...

If certain functions are taking a lot of time, you’ll be able to see them here.

The debug helper

The configuration framework ‘behind’ Moore is called PyConf, whose Tonic component provides the @configurable helper you’ll see decorating various functions.

If you want to get some more feedback about what Tonic is doing, you can use the debug context manager:

from PyConf.tonic import debug

with debug():
    # Do stuff

Inside the debug context, the verbosity of the logging from Tonic will be increased.

Gaudi Auditors

The Gaudi framework has a number of Auditors that provide useful optional debugging capabilities. They span from basic ones, like the ‘NameAuditor’ that simply prints a message whenever an algorithm is entered or exited, to more complicated ones like support for using the Google or Intel profilers. For more details on all that are available see the Gaudi doxygen documentation.

The configuration framework has support for enabling any number of these, by passing their names to the application configuration:

option.auditors = ['NameAuditor']