ExternalGeneratorFilter timing out

[vlimant]

they were complications during the validation of similar requests and https://cms-pdmv-prod.web.cern.ch/mcm/requests?prepid=BPH-Run3Summer22EEGS-00172 is failing massively on:

Fatal Exception (Exit code: 8001)
An exception of category 'ExternalFailed' occurred while
[0] Processing Event run: 1 lumi: 16885 event: 3889891464 stream: 3
[1] Running path 'simulation_step'
[2] Calling method for module ExternalGeneratorFilter/'generator'
Exception Message:
failed waiting for external process 997_3. Timed out after 300 seconds.

https://cms-unified.web.cern.ch/cms-unified/report/cmsunified_task_BPH-Run3Summer22EEGS-00172__v1_T_250416_160139_6446#BPH-Run3Summer22EEGS-00172_0:8001

log files, including the configuration can be found under https://cms-unified.web.cern.ch/cms-unified/joblogs/cmsunified_task_BPH-Run3Summer22EEGS-00172__v1_T_250416_160139_6446/8001/BPH-Run3Summer22EEGS-00172_0/

it might go away with resubmissions but it's not efficient for anyone. This is a 12.4.24 request, but the issue is also present in more recent release (14.0 at least)

[cmsbuild]

cms-bot internal usage

[cmsbuild]

A new Issue was created by @vlimant.

@Dr15Jones, @antoniovilela, @makortel, @mandrenguyen, @rappoccio, @sextonkennedy, @smuzaffar can you please review it and eventually sign/assign? Thanks.

cms-bot commands are listed here

[vlimant]

assign generators

[cmsbuild]

New categories assigned: generators

@bbilin,@lviliani,@menglu21,@mkirsano you have been requested to review this Pull request/Issue and eventually sign? Thanks

[Dr15Jones]

One of the logs contains the following just before the failure

%MSGEvtGen:Tried 10000000 times to generate decay of pi0 with mass=0
EvtGen:Will take first kinematically allowed decay in the decay table
EvtGen:Could not decay:pi0 with mass:0 will throw event away! 
EvtGen:Your event has been rejected 10000 times!
EvtGen:Will now abort.
-w EvtGenInterface::decay error: incorrect status!: 

%MSG
901_5 process: SIGNAL CAUGHT: unlock
%MSG-w EvtGenInterface::decay error: empty end vertex!: 
Worker: SIGNAL CAUGHT 6

Where process 901_5 is the one that was unresponsive for 300s.

NOTE: signal 6 is an abort so it looks like the EvtGen code called abort().

[Dr15Jones]

A Quick Look at evtgen code and one easily finds

https://github.com/cms-externals/evtgen/blob/55e2778c3ced7e21ea580978536b4d712fa395de/src/EvtGen.cpp#L195-L199

[Kiarendil]

Hi, let me add 5 cents as BPH MC contact.
while this error with EvtGen is expected to be related with generator (fragment, etc), its origin is highly unclear for me.
If smth very wrong with generator we would expect failure with 100% cases. However local tests are good and we have a lot of successful jobs, so the failure happens only partially, and I do not understand how to control it.
Digging a bit deeper to the logs:

%MSG
%MSG-w EvtGenInterface::decay error: empty end vertex!:
%MSG
Begin processing the 2034068th record. Run 1, Event 4273656605, LumiSection 72178 on stream 6 at 18-Apr-2025 18:36:43.976 UTC
EvtGen:Tried 10000000 times to generate decay of pi0 with mass=0
EvtGen:Will take first kinematically allowed decay in the decay table
EvtGen:Could not decay:pi0 with mass:0 will throw event away!
EvtGen:Your event has been rejected 10000 times!
EvtGen:Will now abort.
991_5 process: SIGNAL CAUGHT: unlock
Worker: SIGNAL CAUGHT 6
Begin processing the 2034069th record. Run 1, Event 4273656606, LumiSection 72178 on stream 0 at 18-Apr-2025 18:36:43.982 UTC
----- Begin Fatal Exception 18-Apr-2025 18:36:43 UTC------------------—---

An exception of category 'ExternalFailed' occurred while
   [0] Processing  Event run: 1 lumi: 72178 event: 4272530394 stream: 5
   [1] Running path 'simulation_step'
   [2] Calling method for module ExternalGeneratorFilter/'generator'
Exception Message:
failed waiting for external process 991_5. Timed out after 300 seconds.
----- End Fatal Exception --------------------------------------------——-
%MSG-w EvtGenInterface::decay error: incorrect status!:

%MSG
%MSG-w EvtGenInterface::decay error: empty end vertex!:

%MSG
%MSG-w EvtGenInterface::decay error: incorrect status!:

%MSG
%MSG-w EvtGenInterface::decay error: empty end vertex!:

We see additionally warnings related with this check:

cmssw/GeneratorInterface/EvtGenInterface/plugins/EvtGen/EvtGenInterface.cc

Lines 528 to 534 in e24f895

	// add code to ensure all particles have an end vertex and if they are undecayed with no end vertes set to status 1
	for (HepMC::GenEvent::particle_const_iterator p = evt->particles_begin(); p != evt->particles_end(); ++p) {
	if ((*p)->end_vertex() && (*p)->status() == 1)
	edm::LogWarning("EvtGenInterface::decay error: incorrect status!"); //(*p)->set_status(2);
	if ((*p)->end_vertex() && (*p)->end_vertex()->particles_out_size() == 0)
	edm::LogWarning("EvtGenInterface::decay error: empty end vertex!");
	}

I may suggest it happens since we force to decay K0L which is long-lived and normally decays by Geant etc. I would also naively suggest, that while I do not deeply understand these warnings, maybe they are not a show-stopper for the successful production. Still it seems that in some cases the events were produced in the end:

------------------------------------
GenXsecAnalyzer:
------------------------------------
Before Filter: total cross section = 5.596e+10 +- 0.000e+00 pb
Filter efficiency (taking into account weights)= (10) / (2.03407e+06) = 4.916e-06 +- 1.555e-06
Filter efficiency (event-level)= (10) / (2.03407e+06) = 4.916e-06 +- 1.555e-06    [TO BE USED IN MCM]

The efficiency is very low, however it is expected from physics of the filters applied.

The error with EvtGen:Tried 10000000 times to generate decay of pi0 with mass=0 is something really odd. There is no pi0 related with the generated decay, no way our fragment can cause pi0 mass change.
I have found some old LHC@ home fora with some mentions of this error:
https://lhcathomedev.cern.ch/lhcathome-dev/forum_thread.php?id=260&sort_style=&start=0
https://lhcathomedev.cern.ch/lhcathome-dev/forum_thread.php?id=306&sort_style=&start=60

From these discussions I may suggest that the problem can be related not with the physics / generator itself but with some computing multithreaded environment, also maybe some memory issues?
This would explain why we have successful jobs in many cases, if this is configuration-depended.

Hope this may help a bit to understand.

[Dr15Jones]

computing multithreaded environment

In this configuration, the code associated with EvtGen is run in its own single threaded application. This was done precisely to avoid EvtGen's threading issues.

[vlimant]

@Kiarendil While not a showstopper, we need to figure out why we need to throw away 1M CPUh into running this workflow and generator configuration.
Throwing failures at computing operation is not the way I see things, when we can avoid them. Then they can concentrate on the things that matters.
Last but not least, I would not trust 100% a sample that is generated with a configuration that gives pions no mass ; it might bias the analysis in very pernicious ways.

[Kiarendil]

Last but not least, I would not trust 100% a sample that is generated with a configuration that gives pions no mass ; it might bias the analysis in very pernicious ways.

AFAIK, there is no configuration which gives pion no mass, nowhere in Pythia or EvtGen You may see Pythia output in the start of the log — pi0 is with m = 0.13498 GeV:

 111  pi0                                 1   0   0    0.13498    0.00000    0.13498    0.13498  2.55313e-05   0   0   0   1   0
              0     1   0.9879900    0       22       22
              1     1   0.0119800   11       22       11      -11
              2     1   0.0000300   13       11      -11       11      -11

The fragment uses EvtGen particle data file which again has m = 013498 GeV:

add  p Particle  pi0                              111  1.3497700e-01  7.7300000e-09  0.0000000e+00     0     0  0.0000000e+00        111

While we do not know why somehow EvtGen starts to state its mass is zero and abort the process, I'm not sure we can trust it and it is not some strange artefact related with memory error etc.

While not a showstopper, we need to figure out why we need to throw away 1M CPUh into running this workflow and generator configuration.

I'm not sure I fully understand here. I agree it would be great to understand these problems, my only point was to highlight that it seems these warning does not stop cmsRun from producing the output with expected low efficiency, so this can be a clue for better understanding the problem and its origin. There are errors which results with 0 output, and this is not the one. So maybe the warnings with %MSG-w EvtGenInterface::decay error: empty end vertex!: are not the reason of the failure in general, but rather expected for the long-lived decays?...

I'd like also to highlight the efficiency is still expected to be low, so in general we had to waste a lot of Computing resources for such rare decays of long-lived particles even if we solve these failures, since we forcing the decays within tracker for the particles which normally fly to HCAL.
You may see in JIRA CMSBPHMC-91: if we use decays with softer filters, it results in too little amount of reconstructed event.

As far as I understand, there are several similar samples with rare K0 decays were already produced and the analyzers team is using them successfully.

FYI @drkovalskyi , maybe you can comment on such kind of requests as member of the analysis team and BPH & Comps L2.

[Kiarendil]

Important thing also is that these failures are hard to reproduce locally ... So this is why I think (maybe naively) why Computing configuration maybe more crucial than the physics of the fragment / generator.