What to do when something fails
Learning Objectives
Learn how to read the logs to know where things are breaking
Learn how to get a glimpse of where algorithms are writing in the TES
When chaining complex workflows (building particles, combining them, etc) we find that our ntuple is not written while we don’t have any errors. The first step is to look at the logs. Let’s first go back at what we learned when building our own decays and rerun again (saving the output to a log file!).
We can scroll through the log until we find our selections, where we will see something like this:
Sel_D0 SUCCESS Number of counters : 10
| Counter | # | sum | mean/eff^* | rms/err^* | min | max |
| "# D0 -> K- K+ " | 1000 | 95 | 0.095000 | 0.29661 | 0.0000 | 2.0000 |
| "# D~0 -> K+ K- " | 1000 | 95 | 0.095000 | 0.29661 | 0.0000 | 2.0000 |
| "# K+" | 1000 | 723 | 0.72300 | 0.89122 | 0.0000 | 6.0000 |
| "# K-" | 1000 | 691 | 0.69100 | 0.85995 | 0.0000 | 6.0000 |
| "# Phys/StdAllLooseKaons" | 1000 | 20491 | 20.491 | 13.579 | 1.0000 | 90.000 |
| "# input particles" | 1000 | 20491 | 20.491 | 13.579 | 1.0000 | 90.000 |
| "# selected" | 1000 | 190 | 0.19000 | 0.59321 | 0.0000 | 4.0000 |
|*"#accept" | 1000 | 94 |( 9.40000 +- 0.922843 )%| ------- | ------- |
|*"#pass combcut" | 1308 | 234 |( 17.8899 +- 1.05974 )%| ------- | ------- |
|*"#pass mother cut" | 234 | 190 |( 81.1966 +- 2.55434 )%| ------- | ------- |
SelFilterPhys_S...SUCCESS Number of counters : 1
| Counter | # | sum | mean/eff^* | rms/err^* | min | max |
|*"#passed" | 94 | 94 |( 100.000 +- 1.06383 )%| ------- | ------- |
Sel_Dstar SUCCESS Number of counters : 14
| Counter | # | sum | mean/eff^* | rms/err^* | min | max |
| "# D*(2010)+ -> D0 pi+ " | 94 | 30 | 0.31915 | 0.48844 | 0.0000 | 2.0000 |
| "# D*(2010)- -> D~0 pi- " | 94 | 31 | 0.32979 | 0.51340 | 0.0000 | 2.0000 |
| "# D0" | 94 | 95 | 1.0106 | 0.10259 | 1.0000 | 2.0000 |
| "# D~0" | 94 | 95 | 1.0106 | 0.10259 | 1.0000 | 2.0000 |
| "# Phys/Sel_D0" | 94 | 190 | 2.0213 | 0.20518 | 2.0000 | 4.0000 |
| "# Phys/StdAllNoPIDsPions" | 94 | 3699 | 39.351 | 19.111 | 7.0000 | 95.000 |
| "# input particles" | 94 | 3889 | 41.372 | 19.174 | 9.0000 | 99.000 |
| "# pi+" | 94 | 1767 | 18.798 | 8.8949 | 3.0000 | 42.000 |
| "# pi-" | 94 | 1743 | 18.543 | 9.4381 | 3.0000 | 49.000 |
| "# selected" | 94 | 61 | 0.64894 | 0.55940 | 0.0000 | 2.0000 |
|*"#accept" | 94 | 57 |( 60.6383 +- 5.03902 )%| ------- | ------- |
|*"#pass combcut" | 3601 | 843 |( 23.4102 +- 0.705629 )%| ------- | ------- |
|*"#pass mother cut" | 843 | 61 |( 7.23606 +- 0.892333 )%| ------- | ------- |
| "Error from IParticleCombiner, skip the combinat| 5 | 5 | 1.0000 | 0.0000 | 1.0000 | 1.0000 |
Here we have information of the input containers, types of particles, etc, with all the counters corresponding to our run on 1000 events.
Understanding the log
How many excited D* mesons do we expect in our ntuple? Can you check it? Can you change some cuts and see how the counters change? Try to free the D* mass window requirement and see if you get more of those.
Now, let’s make the particle builder fail silently and see if we can debug this.
For example, imagine we forgot to add the Kaons as inputs in Sel_D0, and instead by mistake added the Pions:
d0_sel = Selection('Sel_D0',
Algorithm=d0,
RequiredSelections=[Pions])
Then we get
Sel_D0 SUCCESS Number of counters : 10
| Counter | # | sum | mean/eff^* | rms/err^* | min | max |
| "# D0 -> K- K+ " | 1000 | 0 | 0.0000 | 0.0000 | 0.0000 | 0.0000 |
| "# D~0 -> K+ K- " | 1000 | 0 | 0.0000 | 0.0000 | 0.0000 | 0.0000 |
| "# K+" | 1000 | 0 | 0.0000 | 0.0000 | 0.0000 | 0.0000 |
| "# K-" | 1000 | 0 | 0.0000 | 0.0000 | 0.0000 | 0.0000 |
| "# Phys/StdAllNoPIDsPions" | 1000 | 38848 | 38.848 | 21.700 | 1.0000 | 128.00 |
| "# input particles" | 1000 | 38848 | 38.848 | 21.700 | 1.0000 | 128.00 |
| "# selected" | 1000 | 0 | 0.0000 | 0.0000 | 0.0000 | 0.0000 |
|*"#accept" | 1000 | 0 |( 0.00000 +- 0.100000 )%| ------- | ------- |
| "#pass combcut" | 0 | 0 | 0.0000 | 0.0000 | 1.7977e+308 |-1.7977e+308 |
| "#pass mother cut" | 0 | 0 | 0.0000 | 0.0000 | 1.7977e+308 |-1.7977e+308 |
It’s easy to see we have 0 input kaons and we can see we only get input pions!
Another problem: we messed up with a cut, for example in building the \(` D^* `\),
dstar_mother = (
"(abs(M-MAXTREE('D0'==ABSID,M)-145.42) < 10*MeV)"
'& (VFASPF(VCHI2/VDOF) < 0)'
)
Running this, we get
Sel_Dstar SUCCESS Number of counters : 14
| Counter | # | sum | mean/eff^* | rms/err^* | min | max |
| "# D*(2010)+ -> D0 pi+ " | 94 | 0 | 0.0000 | 0.0000 | 0.0000 | 0.0000 |
| "# D*(2010)- -> D~0 pi- " | 94 | 0 | 0.0000 | 0.0000 | 0.0000 | 0.0000 |
| "# D0" | 94 | 95 | 1.0106 | 0.10259 | 1.0000 | 2.0000 |
| "# D~0" | 94 | 95 | 1.0106 | 0.10259 | 1.0000 | 2.0000 |
| "# Phys/Sel_D0" | 94 | 190 | 2.0213 | 0.20518 | 2.0000 | 4.0000 |
| "# Phys/StdAllNoPIDsPions" | 94 | 3699 | 39.351 | 19.111 | 7.0000 | 95.000 |
| "# input particles" | 94 | 3889 | 41.372 | 19.174 | 9.0000 | 99.000 |
| "# pi+" | 94 | 1767 | 18.798 | 8.8949 | 3.0000 | 42.000 |
| "# pi-" | 94 | 1743 | 18.543 | 9.4381 | 3.0000 | 49.000 |
| "# selected" | 94 | 0 | 0.0000 | 0.0000 | 0.0000 | 0.0000 |
|*"#accept" | 94 | 0 |( 0.00000 +- 1.06383 )%| ------- | ------- |
|*"#pass combcut" | 3601 | 843 |( 23.4102 +- 0.705629 )%| ------- | ------- |
|*"#pass mother cut" | 843 | 0 |( 0.00000 +- 0.118624 )%| ------- | ------- |
| "Error from IParticleCombiner, skip the combinat| 5 | 5 | 1.0000 | 0.0000 | 1.0000 | 1.0000 |
And we would get suspicious about the MotherCut…
The final trick is to use the StoreExplorerAlg, which shows us the state of the TES in the middle of execution.
We can configure it very easily and insert it in the DaVinci sequence to see what is happening.
from Configurables import StoreExplorerAlg
DaVinci().UserAlgorithms += [StoreExplorerAlg("Before"),
dstar_seq.sequence(),
StoreExplorerAlg("After")]
And then run it:
EventSelector SUCCESS Reading Event record 1. Record number within stream 1: 1
...
Before INFO ========= /Event[0x2f009e70@EventDataSvc]:
Before INFO +--> /Event [Address: CLID=0x1 Type=0x2] DataObject
Before INFO | +--> /Gen [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | +--> /PrevPrev [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | +--> /Prev [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | +--> /Next [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | +--> /NextNext [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | +--> /MC [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | +--> /Link [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | +--> /pSim [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | +--> /Rec [Address: CLID=0x1 Type=0x2] DataObject
Before INFO | | +--> /Header [Address: CLID=0x69 Type=0x2] LHCb::RecHeader
Before INFO | | +--> /Status [Address: CLID=0x1389 Type=0x2] (Unloaded)
Before INFO | | +--> /Summary [Address: CLID=0x6a Type=0x2] (Unloaded)
Before INFO | | +--> /ProtoP [No Address] DataObject
Before INFO | | | +--> /Charged [No Address] KeyedContainer<LHCb::ProtoPartic [0x1d]
Before INFO | | +--> /Muon [No Address] DataObject
Before INFO | | | +--> /MuonPID [No Address] KeyedContainer<LHCb::MuonPID,Con [0x17]
Before INFO | | +--> /Track [No Address] DataObject
Before INFO | | | +--> /Best [No Address] KeyedContainer<LHCb::Track,Conta [0x45]
Before INFO | | | +--> /FittedHLT1VeloTracks [No Address] KeyedContainer<LHCb::Track,Conta [0x20]
Before INFO | | +--> /Rich [No Address] DataObject
Before INFO | | | +--> /PIDs [No Address] KeyedContainer<LHCb::RichPID,Con [0x18]
Before INFO | | +--> /Vertex [No Address] DataObject
Before INFO | | +--> /Primary [No Address] KeyedContainer<LHCb::RecVertex,C [0x3]
Before INFO | +--> /Calo [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | +--> /Unstripped [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | +--> /HC [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | +--> /Tracker [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | +--> /Velo [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | +--> /Muon [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | +--> /Rich [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | +--> /Trigger [Address: CLID=0x1 Type=0x2] DataObject
Before INFO | | +--> /RawEvent [Address: CLID=0x3ea Type=0x2] LHCb::RawEvent
Before INFO | +--> /pRec [Address: CLID=0x1 Type=0x2] DataObject
Before INFO | | +--> /Track [Address: CLID=0x1 Type=0x2] DataObject
Before INFO | | | +--> /Best [Address: CLID=0x60e Type=0x2] LHCb::PackedTracks
Before INFO | | | +--> /FittedHLT1VeloTracks [Address: CLID=0x60e Type=0x2] LHCb::PackedTracks
Before INFO | | | +--> /Muon [Address: CLID=0x60e Type=0x2] (Unloaded)
Before INFO | | +--> /Rich [Address: CLID=0x1 Type=0x2] DataObject
Before INFO | | | +--> /PIDs [Address: CLID=0x619 Type=0x2] LHCb::PackedRichPIDs
Before INFO | | +--> /Muon [Address: CLID=0x1 Type=0x2] DataObject
Before INFO | | | +--> /MuonPID [Address: CLID=0x623 Type=0x2] LHCb::PackedMuonPIDs
Before INFO | | +--> /Calo [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | | +--> /ProtoP [Address: CLID=0x1 Type=0x2] DataObject
Before INFO | | | +--> /Charged [Address: CLID=0x610 Type=0x2] LHCb::PackedProtoParticles
Before INFO | | | +--> /Neutrals [Address: CLID=0x610 Type=0x2] (Unloaded)
Before INFO | | +--> /Vertex [Address: CLID=0x1 Type=0x2] DataObject
Before INFO | | | +--> /Primary [Address: CLID=0x611 Type=0x2] LHCb::PackedRecVertices
Before INFO | | +--> /V0 [Address: CLID=0x612 Type=0x2] (Unloaded)
Before INFO | +--> /Turbo [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | +--> /Strip [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | +--> /AllStreams [Address: CLID=0x1 Type=0x2] (Unloaded)
Before INFO | +--> /DAQ [No Address] DataObject
Before INFO | | +--> /ODIN [No Address] LHCb::ODIN
Before INFO +--> /Phys [No Address] DataObject
Before INFO | +--> /StdAllLooseKaons [No Address] DataObject
Before INFO | | +--> /Particles [No Address] KeyedContainer<LHCb::Particle,Co [0x9]
Before INFO | | +--> /decayVertices [No Address] KeyedContainer<LHCb::Vertex,Cont [0]
Before INFO | | +--> /Particle2VertexRelations [No Address] LHCb::Relation1D<LHCb::Particle,
Before INFO | | +--> /_RefitPVs [No Address] KeyedContainer<LHCb::RecVertex,C [0]
Before INFO | +--> /Sel_D0 [No Address] DataObject
Before INFO | | +--> /Particles [No Address] KeyedContainer<LHCb::Particle,Co [0]
Before INFO +--> /TupleDstToD0pi_D0ToKK [No Address] DataObject
Before INFO +--> /Particles [No Address] KeyedContainer<LHCb::Particle,Co [0]
After INFO ========= /Event[0x2f009e70@EventDataSvc]:
After INFO +--> /Event [Address: CLID=0x1 Type=0x2] DataObject
After INFO | +--> /Gen [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | +--> /PrevPrev [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | +--> /Prev [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | +--> /Next [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | +--> /NextNext [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | +--> /MC [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | +--> /Link [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | +--> /pSim [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | +--> /Rec [Address: CLID=0x1 Type=0x2] DataObject
After INFO | | +--> /Header [Address: CLID=0x69 Type=0x2] LHCb::RecHeader
After INFO | | +--> /Status [Address: CLID=0x1389 Type=0x2] (Unloaded)
After INFO | | +--> /Summary [Address: CLID=0x6a Type=0x2] (Unloaded)
After INFO | | +--> /ProtoP [No Address] DataObject
After INFO | | | +--> /Charged [No Address] KeyedContainer<LHCb::ProtoPartic [0x1d]
After INFO | | +--> /Muon [No Address] DataObject
After INFO | | | +--> /MuonPID [No Address] KeyedContainer<LHCb::MuonPID,Con [0x17]
After INFO | | +--> /Track [No Address] DataObject
After INFO | | | +--> /Best [No Address] KeyedContainer<LHCb::Track,Conta [0x45]
After INFO | | | +--> /FittedHLT1VeloTracks [No Address] KeyedContainer<LHCb::Track,Conta [0x20]
After INFO | | +--> /Rich [No Address] DataObject
After INFO | | | +--> /PIDs [No Address] KeyedContainer<LHCb::RichPID,Con [0x18]
After INFO | | +--> /Vertex [No Address] DataObject
After INFO | | +--> /Primary [No Address] KeyedContainer<LHCb::RecVertex,C [0x3]
After INFO | +--> /Calo [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | +--> /Unstripped [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | +--> /HC [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | +--> /Tracker [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | +--> /Velo [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | +--> /Muon [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | +--> /Rich [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | +--> /Trigger [Address: CLID=0x1 Type=0x2] DataObject
After INFO | | +--> /RawEvent [Address: CLID=0x3ea Type=0x2] LHCb::RawEvent
After INFO | +--> /pRec [Address: CLID=0x1 Type=0x2] DataObject
After INFO | | +--> /Track [Address: CLID=0x1 Type=0x2] DataObject
After INFO | | | +--> /Best [Address: CLID=0x60e Type=0x2] LHCb::PackedTracks
After INFO | | | +--> /FittedHLT1VeloTracks [Address: CLID=0x60e Type=0x2] LHCb::PackedTracks
After INFO | | | +--> /Muon [Address: CLID=0x60e Type=0x2] (Unloaded)
After INFO | | +--> /Rich [Address: CLID=0x1 Type=0x2] DataObject
After INFO | | | +--> /PIDs [Address: CLID=0x619 Type=0x2] LHCb::PackedRichPIDs
After INFO | | +--> /Muon [Address: CLID=0x1 Type=0x2] DataObject
After INFO | | | +--> /MuonPID [Address: CLID=0x623 Type=0x2] LHCb::PackedMuonPIDs
After INFO | | +--> /Calo [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | | +--> /ProtoP [Address: CLID=0x1 Type=0x2] DataObject
After INFO | | | +--> /Charged [Address: CLID=0x610 Type=0x2] LHCb::PackedProtoParticles
After INFO | | | +--> /Neutrals [Address: CLID=0x610 Type=0x2] (Unloaded)
After INFO | | +--> /Vertex [Address: CLID=0x1 Type=0x2] DataObject
After INFO | | | +--> /Primary [Address: CLID=0x611 Type=0x2] LHCb::PackedRecVertices
After INFO | | +--> /V0 [Address: CLID=0x612 Type=0x2] (Unloaded)
After INFO | +--> /Turbo [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | +--> /Strip [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | +--> /AllStreams [Address: CLID=0x1 Type=0x2] (Unloaded)
After INFO | +--> /DAQ [No Address] DataObject
After INFO | | +--> /ODIN [No Address] LHCb::ODIN
After INFO +--> /Phys [No Address] DataObject
After INFO | +--> /StdAllLooseKaons [No Address] DataObject
After INFO | | +--> /Particles [No Address] KeyedContainer<LHCb::Particle,Co [0x9]
After INFO | | +--> /decayVertices [No Address] KeyedContainer<LHCb::Vertex,Cont [0]
After INFO | | +--> /Particle2VertexRelations [No Address] LHCb::Relation1D<LHCb::Particle,
After INFO | | +--> /_RefitPVs [No Address] KeyedContainer<LHCb::RecVertex,C [0]
After INFO | +--> /Sel_D0 [No Address] DataObject
After INFO | | +--> /Particles [No Address] KeyedContainer<LHCb::Particle,Co [0]
After INFO +--> /TupleDstToD0pi_D0ToKK [No Address] DataObject
After INFO +--> /Particles [No Address] KeyedContainer<LHCb::Particle,Co [0]
Here we can see where our decays are being put and we can debug problems with inputs and outputs. It can also be useful to know where things are written for accessing them interactively, if we want to further explore and debug.
Configuring the algorithm
The StoreExplorerAlg has the same print frequency as DaVinci, but it can be configured by modifying PrintFreq (fraction of events that are printed) or PrintEvt.
Have a look at the class Doxygen to see what they do.