Debug flags

[AndersenFred]

Starting guarding all debug messages via

#ifdef __GENIE_LOW_LEVEL_MESG_ENABLED__
  LOG(...,pDEBUG)<< Message;
#endif

as at some point, my log exploded to something like 80GB.
This potentially could also improve (slightly) performance.

[nusense]

Yike, Ah, I don't think we want this modification. The messenger service has different "streams" and "priorities":

   The priority (in descending importance order) can be
    FATAL, ALERT, CRIT, ERROR, WARN, NOTICE, INFO, DEBUG

And each stream can be controlled by an entry in the Messenger XML file (default is $GENIE/config/Messenger.xml). For most applications this default can be overridden by supplying an alternative file and telling the app to use that file.

There exist some predefined alternative configurations: Messenger_laconic.xml, Messenger_rambling.xml and Messenger_whisper.xml , or you can use one of those as a template for your own. For streams that aren't listed in the XML file I believe the default priority is pINFO (tested this). If there's a stream that needs an entry, one should add it to all of the 4 existing files at an appropriate priority. If it exists and you got too many messages, either the particular instance needs a lower priority in the code, or a higher priority in the XML file.

Generally the code isn't built on most sites with __GENIE_LOW_LEVEL_MESG_ENABLED__ so bracketing the logging messages with that defeats the purpose of priorities by disallowing the message from being enabled. The overhead of the Message service isn't very onerous except in very, very tight loops that are repeated frequently. Not all pDEBUG messages need to be in the #ifdef/#endif

I'm very surprised that you got 80 GB of messages unless you somehow enabled that priority for that stream.

[AndersenFred]

On the one hand yes, but every log costs time and a lot of these messages are clearly for debugging and do not contain useful information for the user. I will revise the messages, but I would recommend at least to guard log in parts that get called verry often and do not contribute much.

The 80 GB happens after setting splines and something false to debug.

[sjgardiner]

@AndersenFred @nusense Perhaps there's a middle ground here. It sounds like a handful of spline-related debugging messages are filling logs, so maybe that subset could be demoted to use the #ifdef __GENIE_LOW_LEVEL_MESG_ENABLED__ #endif wrapping?

[AndersenFred]

We should definitely guard more log statements, at the current stage creating

gmkspl -p   14 -t 1000010010,1000000010,1000080160,1000060120 -n 50 -e 100 -o "$FILENAME"_mu.xml     --event-generator-list DIS    --tune G18_10a_02_11b &
gmkspl -p  -14 -t 1000010010,1000000010,1000080160,1000060120 -n 50 -e 100 -o "$FILENAME"_mubar.xml  --event-generator-list DIS    --tune G18_10a_02_11b 
wait
gspl2root -f "$FILENAME"_mu.xml     --event-generator-list DIS      --tune G18_10a_02_11b  -p   14 -t 1000010010,1000000010,1000080160,1000060120 -n 50 -e 100 -o "$FILENAME".root
gspl2root -f "$FILENAME"_mubar.xml  --event-generator-list DIS      --tune G18_10a_02_11b  -p  -14 -t 1000010010,1000000010,1000080160,1000060120 -n 50 -e 100 -o "$FILENAME".root

with the last release version

real    33m23.205s
user    82m11.769s
sys     2m21.068s

vs this branch at the current stage

real    18m45.822s
user    48m39.894s
sys     1m40.524s

meaning a huge difference.
We don't have to guard all of those statements but at least those which are called very often.
I first would continue guarding all and then reviewing them one by one which make sense to keep and which we should guard.
I suspect that most of the time difference arise from the spline evaluation as it gets called the most.

[nusense]

For these times, are these run with the default Messenger.xml levels or with something more verbose?

[AndersenFred]

Both are using the default configs

[nusense]

Looking again at the numbers, it looks like a large improvement for this particular use case. But I'm confused by the numbers you quote. The real is the wall clock time, while user + sys are CPU time spent executing code. So how can real be less than user?

[nusense]

Also it would be useful to split gmkspl separate from gspl2root. Not everyone does the later, while I suspect gmkspl is the real code to target for improvements. You also say "spline evaluation" being a concern; are you talking about the time in gspl2root, because I suspect that gmkspl will far exceed it for a different choice of knots and energy range.

The number of points in the TGraph is fixed (300 I believe, though that's something we should allow users to change because it's a bit problematic at low energies if you want to cover up to, say, 120 GeV), while generally when I'm producing splines for the Fermilab neutrino community I generate 250 knots up to 1000 GeV (logarithmically spaced).

[AndersenFred]

real in this context means the actual time the process took and sys the cpu time and as I ran two in parallel the factor two is expected.
gspl2root takes only on the order of seconds and should not affect the time that much.

What I meant is that I think the spline class contributes to most of the timing improvement