Jobsub ID 234967.2@dunegpschedd02.fnal.gov

Jobsub ID	234967.2@dunegpschedd02.fnal.gov
Workflow ID	9455
Stage ID	1
User name	mwrobel@fnal.gov
HTCondor Group	group_dune
Requested	Processors	1
	GPU	No
	RSS bytes	9437184000 (9000 MiB)
	Wall seconds limit	80000 (22 hours)
Submitted time	2025-10-29 18:54:48
Site	US_UChicago
Entry	Engage_US_MWT2_uct2_condce_mcore
Last heartbeat	2025-10-29 20:30:38
From worker node	Hostname	mwt2-c053.campuscluster.illinois.edu
	cpuinfo	AMD EPYC 7443 24-Core Processor
	OS release	Scientific Linux release 7.9 (Nitrogen)
	Processors	1
	RSS bytes	10485760000 (10000 MiB)
	Wall seconds limit	86400 (24 hours)
	GPU
	Inner Apptainer?	True
Job state	outputting_failed
Started	2025-10-29 19:02:26
Input files	usertests:pdhd_prod_beam__231691_0_1_20251008T183036Z_gen_g4_IonScintPDExt.root_227038_91_1_20251010T163659Z_PDInt.root
Jobscript	Exit code	0
	Real time	1h (4879s)
	CPU time	1h (4704s = 96%)
	Max RSS bytes	6594150400 (6288 MiB)
Outputting started	2025-10-29 20:23:45
Output files
Finished	2025-10-29 20:30:38
List job events Cached HTCondor job logs
Jobscript log (last 10,000 characters)

] "wiener0":27322 [27322] ] cmm:[ bad:0 lf_noisy:95 ] 
[15:22:55.563] D [  glue  ] <FrameFanin:sn_mag_nf> call=18 input 0: frame: ident=89 time=0 tick=512 with 51592 traces.  frame tags:[ "sigproc" ] 2 tagged trace sets:[ "gauss0":24270 [0] "wiener0":27322 [27322] ] cmm:[ bad:0 lf_noisy:95 ] input 1: frame: ident=89 time=0 tick=512 with 41250 traces.  frame tags:[ "sigproc" ] 2 tagged trace sets:[ "gauss1":17534 [0] "wiener1":23716 [23716] ] cmm:[ bad:0 lf_noisy:1 ] input 2: frame: ident=89 time=0 tick=512 with 44966 traces.  frame tags:[ "sigproc" ] 2 tagged trace sets:[ "gauss2":19634 [0] "wiener2":25332 [25332] ] cmm:[ bad:0 ] input 3: frame: ident=89 time=0 tick=512 with 47556 traces.  frame tags:[ "sigproc" ] 2 tagged trace sets:[ "gauss3":19262 [0] "wiener3":28294 [28294] ] cmm:[ bad:0 ] output: frame: ident=89 time=0 tick=512 with 185364 traces.  frame tags:[ "framefanin" ] 8 tagged trace sets:[ "gauss0":24270 [0] "gauss1":17534 [0] "gauss2":19634 [0] "gauss3":19262 [0] "wiener0":27322 [27322] "wiener1":23716 [23716] "wiener2":25332 [25332] "wiener3":28294 [28294] ] cmm:[ bad:0 lf_noisy:96 ] 
Retagger: tagging trace set: wiener with 104664 traces, 104664 summary
Retagger: tagging trace set: gauss with 80700 traces, 0 summary
[15:22:55.576] D [  glue  ] sink frame: #89 @0 with 185364 traces, frame tags:[retagger], trace tags:[gauss, wiener]
[15:22:55.576] D [  glue  ] <FrameFanout:sn_mag_nf> call=19: see EOS 
[15:22:55.576] D [  glue  ] <ChannelSelector:chsel3> see EOS at call=9 
[15:22:55.576] D [sigproc ] <OmnibusNoiseFilter:nf3> EOS at call=19 
[15:22:55.576] D [sigproc ] <OmnibusSigProc:apa3sigproc3> EOS at call=19 anode=3 
[15:22:55.576] D [  glue  ] <ChannelSelector:chsel2> see EOS at call=9 
[15:22:55.576] D [sigproc ] <OmnibusNoiseFilter:nf2> EOS at call=19 
[15:22:55.576] D [sigproc ] <OmnibusSigProc:apa2sigproc2> EOS at call=19 anode=2 
[15:22:55.577] D [  glue  ] <ChannelSelector:chsel1> see EOS at call=9 
[15:22:55.577] D [sigproc ] <OmnibusNoiseFilter:nf1> EOS at call=19 
[15:22:55.577] D [sigproc ] <OmnibusSigProc:apa1sigproc1> EOS at call=19 anode=1 
[15:22:55.577] D [  glue  ] <ChannelSelector:chsel0> see EOS at call=9 
[15:22:55.577] D [sigproc ] <OmnibusNoiseFilter:nf0> EOS at call=19 
[15:22:55.577] D [sigproc ] <OmnibusSigProc:apa0sigproc0> EOS at call=19 anode=0 
[15:22:55.577] D [  glue  ] <FrameFanin:sn_mag_nf> EOS at call=19 with 4 
[15:22:55.577] D [  glue  ] frame sink sees EOS
[15:22:55.577] D [ pgraph ] <Pgrapher:> graph execution complete 
[15:22:55.577] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 11.4 sec
[15:22:55.577] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 7.42 sec
[15:22:55.577] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 7.42 sec
[15:22:55.577] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 7.17 sec
[15:22:55.577] I [ timer  ] Timer: WireCell::SigProc::OmnibusNoiseFilter : 2.79 sec
[15:22:55.577] I [ timer  ] Timer: WireCell::SigProc::OmnibusNoiseFilter : 2.72 sec
[15:22:55.577] I [ timer  ] Timer: WireCell::SigProc::OmnibusNoiseFilter : 2.69 sec
[15:22:55.577] I [ timer  ] Timer: WireCell::SigProc::OmnibusNoiseFilter : 2.46 sec
[15:22:55.577] I [ timer  ] Timer: WireCell::Gen::FrameFanin : 0.03 sec
[15:22:55.577] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.02 sec
[15:22:55.577] I [ timer  ] Timer: WireCell::Gen::Retagger : 0.01 sec
[15:22:55.577] I [ timer  ] Timer: WireCell::Gen::FrameFanout : 0 sec
[15:22:55.577] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[15:22:55.577] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[15:22:55.577] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[15:22:55.577] I [ timer  ] Timer: wcls::RawFrameSource : 0 sec
[15:22:55.577] I [ timer  ] Timer: wcls::FrameSaver : 0 sec
[15:22:55.577] I [ timer  ] Timer: WireCell::Gen::DumpFrames : 0 sec
[15:22:55.577] I [ timer  ] Timer: Total node execution : 44.12999993190169 sec
wclsFrameSaver saving cooked to 6000 ticks
wclsFrameSaver: saving 80700 traces tagged "gauss"
FrameSaver: q=2.66507e+06 n=1281043 tag=gauss
wclsFrameSaver: saving 104664 traces tagged "wiener"
FrameSaver: q=3.46939e+06 n=1230801 tag=wiener
0 X, 0 U, 0 V bad channels
Finding XUV coincidences...
C:0 T:2 30472 XUs and 44910 XVs -> 858 XUVs
C:0 T:4 37 XUs and 50 XVs -> 0 XUVs
C:0 T:5 50192 XUs and 38147 XVs -> 1964 XUVs
C:0 T:6 36753 XUs and 37202 XVs -> 948 XUVs
C:0 T:7 14 XUs and 67 XVs -> 4 XUVs
3774 XUVs total
2057 collection wire objects
3774 potential space points
Neighbour search...
122470 tests to find 52560 neighbours
Iterating with no regularization...
Begin: 3.27932e+07
0 3.076e+07
1 3.06265e+07
2 3.061e+07
Now with regularization...
Begin: 2.89613e+07
0 2.89559e+07
29-Oct-2025 15:23:44 CDT  Closed output file "pdhd_prod_beam__231691_0_1_20251008T183036Z_gen_g4_IonScintPDExt.root_227038_91_1_20251010T163659Z_PDInt.root_234967_2_1_20251029T190236Z_detsim_reco1.root"
29-Oct-2025 15:23:44 CDT  Closed input file "temp_detsim.root"

=====================================================================================================================================
TimeTracker printout (sec)                             Min           Avg           Max         Median          RMS         nEvts   
=====================================================================================================================================
Full event                                           59.761        77.1265       94.0283       75.8803       10.1245        10     
-------------------------------------------------------------------------------------------------------------------------------------
source:RootInput(read)                             0.00118573    0.00361266    0.00605055    0.00381652     0.0016146       10     
reco:wclsdatahd:WireCellToolkit                      42.5421       44.7827       46.1398       44.9637        1.106         10     
reco:wirefilter:WireFilter                          0.0112379     0.018349      0.0264773     0.0173499     0.0044824       10     
reco:gaushit:GausHitFinder                          0.303671      0.555754      0.748055      0.565334      0.122253        10     
reco:nhitsfilter:NumberOfHitsFilter                0.000142618   0.000248307   0.000483319   0.000229627   9.09503e-05      10     
reco:reco3d:SpacePointSolver                        0.173363      0.498159      0.990277       0.47203      0.275968        10     
reco:hitpdune:DisambigFromSpacePoints               0.114738      0.346854      0.682305      0.296058      0.165881        10     
reco:pandora:StandardPandora                         2.36919       6.92957       13.5425       6.52227       3.11471        10     
reco:pandoraWriter:StandardPandora                  0.123856      0.200496      0.273784      0.194987      0.0488439       10     
reco:pandoraTrack:LArPandoraTrackCreation           0.283602      0.721123       1.15592      0.764388      0.246864        10     
reco:pandoraShower:LArPandoraShowerCreation         0.207062      0.661991       1.19933      0.562583      0.315025        10     
reco:pandoracalo:Calorimetry                        0.184812      0.428995      0.672616      0.461305      0.142335        10     
reco:pandoracalonosce:Calorimetry                   0.178484      0.420023      0.629326      0.449315      0.130522        10     
reco:pandoraShowercalo:ShowerCalorimetry            0.172002      0.663562       1.17895      0.620406      0.314991        10     
reco:pandoraShowercalonosce:ShowerCalorimetry       0.163335      0.647219       1.15079      0.611608      0.306444        10     
reco:pandoraGnocchiCalo:GnocchiCalorimetry          0.0237592     0.0445206     0.070292      0.0445935     0.0132923       10     
reco:pandoraGnocchiCalonosce:GnocchiCalorimetry     0.0260137     0.0456909     0.0707717     0.0461053     0.0133129       10     
reco:emtrkmichelid:EmTrackMichelId                   11.9585       18.9913       25.8374       18.7992       4.17452        10     
[art]:TriggerResults:TriggerResultInserter         2.7442e-05    4.05213e-05   8.6243e-05     3.456e-05    1.66366e-05      10     
end_path:out1:RootOutput                            9.127e-06    1.34752e-05   2.8404e-05    1.03695e-05   6.45823e-06      10     
end_path:out1:RootOutput(write)                     0.844451       1.11008       1.45868       1.11417      0.198286        10     
=====================================================================================================================================

====================================================================================================
MemoryTracker summary (base-10 MB units used)

  Peak virtual memory usage (VmPeak)  : 5680.89 MB
  Peak resident set size usage (VmHWM): 3463.79 MB
  Details saved in: 'mem.db'
====================================================================================================
Art has completed and will exit with status 0.
Reco returns 0
.:
total 11239972
-rw-r--r-- 1 dune osgvo     231349 Oct 29 15:23 jobscript.log
-rw-r--r-- 1 dune osgvo        199 Oct 29 15:23 justin-processed-pfns.txt
-rw-r--r-- 1 dune osgvo        519 Oct 29 15:23 reco_protodunehd_hist.root
-rw-r--r-- 1 dune osgvo       3574 Oct 29 15:23 Pandora_Geometry.xml
-rw-r--r-- 1 dune osgvo     139264 Oct 29 15:23 mem.db
-rw-r--r-- 1 dune osgvo      28672 Oct 29 15:23 time.db
-rw-r--r-- 1 dune osgvo 5825406709 Oct 29 15:23 pdhd_prod_beam__231691_0_1_20251008T183036Z_gen_g4_IonScintPDExt.root_227038_91_1_20251010T163659Z_PDInt.root_234967_2_1_20251029T190236Z_detsim_reco1.root
-rw-r--r-- 1 dune osgvo   31730180 Oct 29 15:23 Pandora_Events.pndr
-rw-r--r-- 1 dune osgvo          0 Oct 29 15:09 debugprod.log
-rw-r--r-- 1 dune osgvo        519 Oct 29 15:08 detsim_single_protodunehd_hist.root
-rw-r--r-- 1 dune osgvo 5652147162 Oct 29 15:08 temp_detsim.root
-rw-r--r-- 1 dune osgvo        120 Oct 29 14:02 all-input-dids.txt