Jobsub ID 234960.0@dunegpschedd02.fnal.gov

Jobsub ID	234960.0@dunegpschedd02.fnal.gov
Workflow ID	9384
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:50:45
Site	US_UChicago
Entry	Engage_US_MWT2_uiuc_condce_mcore
Last heartbeat	2025-10-29 21:31:34
From worker node	Hostname	cit2-c044.mwt2.org
	cpuinfo	Intel(R) Xeon(R) CPU E5-2650 v3 @ 2.30GHz
	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	finished
Started	2025-10-29 18:59:13
Input files	usertests:pdhd_prod_beam__231901_2_1_20251008T212418Z_gen_g4_IonScintPDExt.root_226750_55_1_20251009T211039Z_PDInt.root
Jobscript	Exit code	0
	Real time	2h (8983s)
	CPU time	2h (8509s = 94%)
	Max RSS bytes	6204968960 (5917 MiB)
Outputting started	2025-10-29 21:28:57
Output files	usertests:pdhd_prod_beam__231901_2_1_20251008T212418Z_gen_g4_IonScintPDExt.root_226750_55_1_20251009T211039Z_PDInt.root_234960_0_1_20251029T185920Z_detsim_reco1.root
Finished	2025-10-29 21:31:34
Saved logs	justin-logs:234960.0-dunegpschedd02.fnal.gov.logs.tgz
List job events Cached HTCondor job logs

Jobscript log (last 10,000 characters)

"wiener0":24509 [24509] ] cmm:[ bad:0 lf_noisy:130 ] 
[17:27:50.069] D [  glue  ] <FrameFanin:sn_mag_nf> call=18 input 0: frame: ident=79 time=0 tick=512 with 46780 traces.  frame tags:[ "sigproc" ] 2 tagged trace sets:[ "gauss0":22271 [0] "wiener0":24509 [24509] ] cmm:[ bad:0 lf_noisy:130 ] input 1: frame: ident=79 time=0 tick=512 with 33779 traces.  frame tags:[ "sigproc" ] 2 tagged trace sets:[ "gauss1":14063 [0] "wiener1":19716 [19716] ] cmm:[ bad:0 ] input 2: frame: ident=79 time=0 tick=512 with 43819 traces.  frame tags:[ "sigproc" ] 2 tagged trace sets:[ "gauss2":18507 [0] "wiener2":25312 [25312] ] cmm:[ bad:0 lf_noisy:1 ] input 3: frame: ident=79 time=0 tick=512 with 34306 traces.  frame tags:[ "sigproc" ] 2 tagged trace sets:[ "gauss3":14559 [0] "wiener3":19747 [19747] ] cmm:[ bad:0 ] output: frame: ident=79 time=0 tick=512 with 158684 traces.  frame tags:[ "framefanin" ] 8 tagged trace sets:[ "gauss0":22271 [0] "gauss1":14063 [0] "gauss2":18507 [0] "gauss3":14559 [0] "wiener0":24509 [24509] "wiener1":19716 [19716] "wiener2":25312 [25312] "wiener3":19747 [19747] ] cmm:[ bad:0 lf_noisy:131 ] 
Retagger: tagging trace set: wiener with 89284 traces, 89284 summary
Retagger: tagging trace set: gauss with 69400 traces, 0 summary
[17:27:50.098] D [  glue  ] sink frame: #79 @0 with 158684 traces, frame tags:[retagger], trace tags:[gauss, wiener]
[17:27:50.098] D [  glue  ] <FrameFanout:sn_mag_nf> call=19: see EOS 
[17:27:50.098] D [  glue  ] <ChannelSelector:chsel3> see EOS at call=9 
[17:27:50.098] D [sigproc ] <OmnibusNoiseFilter:nf3> EOS at call=19 
[17:27:50.098] D [sigproc ] <OmnibusSigProc:apa3sigproc3> EOS at call=19 anode=3 
[17:27:50.098] D [  glue  ] <ChannelSelector:chsel2> see EOS at call=9 
[17:27:50.098] D [sigproc ] <OmnibusNoiseFilter:nf2> EOS at call=19 
[17:27:50.098] D [sigproc ] <OmnibusSigProc:apa2sigproc2> EOS at call=19 anode=2 
[17:27:50.098] D [  glue  ] <ChannelSelector:chsel1> see EOS at call=9 
[17:27:50.098] D [sigproc ] <OmnibusNoiseFilter:nf1> EOS at call=19 
[17:27:50.098] D [sigproc ] <OmnibusSigProc:apa1sigproc1> EOS at call=19 anode=1 
[17:27:50.098] D [  glue  ] <ChannelSelector:chsel0> see EOS at call=9 
[17:27:50.098] D [sigproc ] <OmnibusNoiseFilter:nf0> EOS at call=19 
[17:27:50.099] D [sigproc ] <OmnibusSigProc:apa0sigproc0> EOS at call=19 anode=0 
[17:27:50.099] D [  glue  ] <FrameFanin:sn_mag_nf> EOS at call=19 with 4 
[17:27:50.099] D [  glue  ] frame sink sees EOS
[17:27:50.099] D [ pgraph ] <Pgrapher:> graph execution complete 
[17:27:50.099] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 30.3 sec
[17:27:50.099] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 25.09 sec
[17:27:50.099] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 21.83 sec
[17:27:50.099] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 19.92 sec
[17:27:50.099] I [ timer  ] Timer: WireCell::SigProc::OmnibusNoiseFilter : 5.19 sec
[17:27:50.099] I [ timer  ] Timer: WireCell::SigProc::OmnibusNoiseFilter : 4.71 sec
[17:27:50.099] I [ timer  ] Timer: WireCell::SigProc::OmnibusNoiseFilter : 4.27 sec
[17:27:50.099] I [ timer  ] Timer: WireCell::SigProc::OmnibusNoiseFilter : 3.66 sec
[17:27:50.099] I [ timer  ] Timer: WireCell::Gen::FrameFanin : 0.04 sec
[17:27:50.099] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.02 sec
[17:27:50.099] I [ timer  ] Timer: WireCell::Gen::Retagger : 0.02 sec
[17:27:50.099] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[17:27:50.099] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[17:27:50.099] I [ timer  ] Timer: WireCell::Gen::FrameFanout : 0 sec
[17:27:50.099] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[17:27:50.099] I [ timer  ] Timer: wcls::RawFrameSource : 0 sec
[17:27:50.099] I [ timer  ] Timer: wcls::FrameSaver : 0 sec
[17:27:50.099] I [ timer  ] Timer: WireCell::Gen::DumpFrames : 0 sec
[17:27:50.099] I [ timer  ] Timer: Total node execution : 115.0699995495379 sec
wclsFrameSaver saving cooked to 6000 ticks
wclsFrameSaver: saving 69400 traces tagged "gauss"
FrameSaver: q=2.05375e+06 n=991108 tag=gauss
wclsFrameSaver: saving 89284 traces tagged "wiener"
FrameSaver: q=2.81938e+06 n=984996 tag=wiener
0 X, 0 U, 0 V bad channels
Finding XUV coincidences...
C:0 T:2 13955 XUs and 13751 XVs -> 594 XUVs
C:0 T:4 57 XUs and 25 XVs -> 4 XUVs
C:0 T:5 62820 XUs and 35896 XVs -> 2933 XUVs
C:0 T:6 28621 XUs and 10251 XVs -> 1426 XUVs
4957 XUVs total
1318 collection wire objects
4957 potential space points
Neighbour search...
228107 tests to find 123730 neighbours
Iterating with no regularization...
Begin: 4.1298e+07
0 3.31836e+07
1 3.25214e+07
2 3.24251e+07
3 3.24007e+07
Now with regularization...
Begin: 2.98544e+07
0 2.9839e+07
29-Oct-2025 17:28:52 EDT  Closed output file "pdhd_prod_beam__231901_2_1_20251008T212418Z_gen_g4_IonScintPDExt.root_226750_55_1_20251009T211039Z_PDInt.root_234960_0_1_20251029T185920Z_detsim_reco1.root"
29-Oct-2025 17:28:52 EDT  Closed input file "temp_detsim.root"

=====================================================================================================================================
TimeTracker printout (sec)                             Min           Avg           Max         Median          RMS         nEvts   
=====================================================================================================================================
Full event                                           157.44        172.795       189.804        174.9        9.28527        10     
-------------------------------------------------------------------------------------------------------------------------------------
source:RootInput(read)                             0.00146315    0.00611866     0.0133737    0.00572313    0.00299438       10     
reco:wclsdatahd:WireCellToolkit                      102.946       113.479       125.667       112.581       6.53758        10     
reco:wirefilter:WireFilter                           0.03184      0.0488628     0.0569834     0.0503967    0.00697639       10     
reco:gaushit:GausHitFinder                          0.699529       1.00368       1.21348      0.955327      0.151497        10     
reco:nhitsfilter:NumberOfHitsFilter                0.000310106   0.000427057   0.000704703   0.000410915   0.000101641      10     
reco:reco3d:SpacePointSolver                        0.289581       0.57743       0.95764      0.519705      0.182966        10     
reco:hitpdune:DisambigFromSpacePoints               0.546926      0.762499       1.13096      0.733748      0.179855        10     
reco:pandora:StandardPandora                         8.42828       11.6889       14.792        11.8923       1.75049        10     
reco:pandoraWriter:StandardPandora                  0.244472       0.33456      0.418564      0.321491      0.0512502       10     
reco:pandoraTrack:LArPandoraTrackCreation            1.26754       1.93675       2.89256       1.69548      0.517889        10     
reco:pandoraShower:LArPandoraShowerCreation          1.11092        1.741        2.36572       1.83665      0.390372        10     
reco:pandoracalo:Calorimetry                        0.576469      0.952573       1.40794      0.896104      0.285133        10     
reco:pandoracalonosce:Calorimetry                   0.612221      0.903716       1.36201      0.818734      0.273777        10     
reco:pandoraShowercalo:ShowerCalorimetry            0.952056       1.64282       2.23534       1.82569      0.446352        10     
reco:pandoraShowercalonosce:ShowerCalorimetry       0.928052       1.60088       2.23306       1.68834      0.452892        10     
reco:pandoraGnocchiCalo:GnocchiCalorimetry          0.0452467     0.0821132     0.114868      0.0855315     0.025097        10     
reco:pandoraGnocchiCalonosce:GnocchiCalorimetry     0.0454526     0.0804472     0.114467      0.0801553     0.023837        10     
reco:emtrkmichelid:EmTrackMichelId                   29.2798       34.0699       37.8993       33.9702       2.64044        10     
[art]:TriggerResults:TriggerResultInserter         5.4241e-05    8.01592e-05   0.000140057   7.87595e-05   2.2501e-05       10     
end_path:out1:RootOutput                            9.248e-06    1.32444e-05   3.6173e-05    1.02115e-05   7.82696e-06      10     
end_path:out1:RootOutput(write)                      1.36016       1.81516       2.17482       1.77379      0.256532        10     
=====================================================================================================================================

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

  Peak virtual memory usage (VmPeak)  : 5880.97 MB
  Peak resident set size usage (VmHWM): 3711.95 MB
  Details saved in: 'mem.db'
====================================================================================================
Art has completed and will exit with status 0.
Reco returns 0
.:
total 11058288
-rw-r--r--. 1 dune osgvo     230811 Oct 29 17:28 jobscript.log
-rw-r--r--. 1 dune osgvo        199 Oct 29 17:28 justin-processed-pfns.txt
-rw-r--r--. 1 dune osgvo        519 Oct 29 17:28 reco_protodunehd_hist.root
-rw-r--r--. 1 dune osgvo       3574 Oct 29 17:28 Pandora_Geometry.xml
-rw-r--r--. 1 dune osgvo     139264 Oct 29 17:28 mem.db
-rw-r--r--. 1 dune osgvo      28672 Oct 29 17:28 time.db
-rw-r--r--. 1 dune osgvo 5731944894 Oct 29 17:28 pdhd_prod_beam__231901_2_1_20251008T212418Z_gen_g4_IonScintPDExt.root_226750_55_1_20251009T211039Z_PDInt.root_234960_0_1_20251029T185920Z_detsim_reco1.root
-rw-r--r--. 1 dune osgvo   30890000 Oct 29 17:28 Pandora_Events.pndr
-rw-r--r--. 1 dune osgvo          0 Oct 29 16:55 debugprod.log
-rw-r--r--. 1 dune osgvo        519 Oct 29 16:54 detsim_single_protodunehd_hist.root
-rw-r--r--. 1 dune osgvo 5560406905 Oct 29 16:54 temp_detsim.root
-rw-r--r--. 1 dune osgvo        120 Oct 29 14:59 all-input-dids.txt