Jobsub ID 267333.1@dunegpschedd01.fnal.gov

Jobsub ID	267333.1@dunegpschedd01.fnal.gov
Workflow ID	11142
Stage ID	1
User name	avizcaya@fnal.gov
Requested	Processors	1
	GPU	No
	RSS bytes	9437184000 (9000 MiB)
	Wall seconds limit	80000 (22 hours)
Submitted time	2025-12-12 11:31:20
Site	US_FNAL-FermiGrid
Entry	FNAL_GPGrid_ce03_mcore_op_duneonly
Last heartbeat	2025-12-12 13:57:13
From worker node	Hostname	dunegli-7890435-0-fnpc17109.fnal.gov
	cpuinfo	Intel(R) Xeon(R) Gold 6140 CPU @ 2.30GHz
	OS release	Scientific Linux release 7.9 (Nitrogen)
	Processors	1
	RSS bytes	10485760000 (10000 MiB)
	Wall seconds limit	172800 (48 hours)
	GPU
	Inner Apptainer?	True
Job state	finished
Started	2025-12-12 11:37:11
Input files	usertests:pdhd_prod_beam__242496_11_1_20251112T224205Z_gen_g4_IonScintPDExt.root_258178_84_1_20251205T214826Z_PDInt.root
Jobscript	Exit code	0
	Real time	2h (8222s)
	CPU time	2h (7898s = 96%)
	Max RSS bytes	6815076352 (6499 MiB)
Outputting started	2025-12-12 13:54:14
Output files	usertests:pdhd_prod_beam__242496_11_1_20251112T224205Z_gen_g4_IonScintPDExt.root_258178_84_1_20251205T214826Z_PDInt.root_267333_1_1_20251212T113715Z_detsim_reco1.root
Finished	2025-12-12 13:57:13
Saved logs	justin-logs:267333.1-dunegpschedd01.fnal.gov.logs.tgz
List job events Cached HTCondor job logs

Jobscript log (last 10,000 characters)

ue  ] <FrameFanin:sn_mag_nf> call=18 input 0: frame: ident=139 time=0 tick=512 with 59542 traces.  frame tags:[ "sigproc" ] 2 tagged trace sets:[ "gauss0":28055 [0] "wiener0":31487 [31487] ] cmm:[ bad:0 lf_noisy:176 ] input 1: frame: ident=139 time=0 tick=512 with 42055 traces.  frame tags:[ "sigproc" ] 2 tagged trace sets:[ "gauss1":17580 [0] "wiener1":24475 [24475] ] cmm:[ bad:0 ] input 2: frame: ident=139 time=0 tick=512 with 32250 traces.  frame tags:[ "sigproc" ] 2 tagged trace sets:[ "gauss2":14252 [0] "wiener2":17998 [17998] ] cmm:[ bad:0 ] input 3: frame: ident=139 time=0 tick=512 with 55099 traces.  frame tags:[ "sigproc" ] 2 tagged trace sets:[ "gauss3":23582 [0] "wiener3":31517 [31517] ] cmm:[ bad:0 ] output: frame: ident=139 time=0 tick=512 with 188946 traces.  frame tags:[ "framefanin" ] 8 tagged trace sets:[ "gauss0":28055 [0] "gauss1":17580 [0] "gauss2":14252 [0] "gauss3":23582 [0] "wiener0":31487 [31487] "wiener1":24475 [24475] "wiener2":17998 [17998] "wiener3":31517 [31517] ] cmm:[ bad:0 lf_noisy:176 ] 
Retagger: tagging trace set: wiener with 105477 traces, 105477 summary
Retagger: tagging trace set: gauss with 83469 traces, 0 summary
[13:53:13.116] D [  glue  ] sink frame: #139 @0 with 188946 traces, frame tags:[retagger], trace tags:[gauss, wiener]
[13:53:13.117] D [  glue  ] <FrameFanout:sn_mag_nf> call=19: see EOS 
[13:53:13.117] D [  glue  ] <ChannelSelector:chsel3> see EOS at call=9 
[13:53:13.117] D [sigproc ] <OmnibusNoiseFilter:nf3> EOS at call=19 
[13:53:13.117] D [sigproc ] <OmnibusSigProc:apa3sigproc3> EOS at call=19 anode=3 
[13:53:13.117] D [  glue  ] <ChannelSelector:chsel2> see EOS at call=9 
[13:53:13.117] D [sigproc ] <OmnibusNoiseFilter:nf2> EOS at call=19 
[13:53:13.117] D [sigproc ] <OmnibusSigProc:apa2sigproc2> EOS at call=19 anode=2 
[13:53:13.117] D [  glue  ] <ChannelSelector:chsel1> see EOS at call=9 
[13:53:13.117] D [sigproc ] <OmnibusNoiseFilter:nf1> EOS at call=19 
[13:53:13.117] D [sigproc ] <OmnibusSigProc:apa1sigproc1> EOS at call=19 anode=1 
[13:53:13.117] D [  glue  ] <ChannelSelector:chsel0> see EOS at call=9 
[13:53:13.117] D [sigproc ] <OmnibusNoiseFilter:nf0> EOS at call=19 
[13:53:13.117] D [sigproc ] <OmnibusSigProc:apa0sigproc0> EOS at call=19 anode=0 
[13:53:13.117] D [  glue  ] <FrameFanin:sn_mag_nf> EOS at call=19 with 4 
[13:53:13.117] D [  glue  ] frame sink sees EOS
[13:53:13.117] D [ pgraph ] <Pgrapher:> graph execution complete 
[13:53:13.117] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 22.56 sec
[13:53:13.117] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 15.8 sec
[13:53:13.117] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 15.57 sec
[13:53:13.117] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 15.42 sec
[13:53:13.117] I [ timer  ] Timer: WireCell::SigProc::OmnibusNoiseFilter : 4.48 sec
[13:53:13.117] I [ timer  ] Timer: WireCell::SigProc::OmnibusNoiseFilter : 3.27 sec
[13:53:13.117] I [ timer  ] Timer: WireCell::SigProc::OmnibusNoiseFilter : 3.23 sec
[13:53:13.117] I [ timer  ] Timer: WireCell::SigProc::OmnibusNoiseFilter : 3.18 sec
[13:53:13.117] I [ timer  ] Timer: WireCell::Gen::FrameFanin : 0.09 sec
[13:53:13.117] I [ timer  ] Timer: WireCell::Gen::Retagger : 0.04 sec
[13:53:13.117] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.02 sec
[13:53:13.117] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[13:53:13.117] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[13:53:13.117] I [ timer  ] Timer: WireCell::Gen::FrameFanout : 0 sec
[13:53:13.117] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[13:53:13.117] I [ timer  ] Timer: wcls::RawFrameSource : 0 sec
[13:53:13.117] I [ timer  ] Timer: wcls::FrameSaver : 0 sec
[13:53:13.117] I [ timer  ] Timer: WireCell::Gen::DumpFrames : 0 sec
[13:53:13.117] I [ timer  ] Timer: Total node execution : 83.66999951563776 sec
wclsFrameSaver saving cooked to 6000 ticks
wclsFrameSaver: saving 83469 traces tagged "gauss"
FrameSaver: q=2.93979e+06 n=1348933 tag=gauss
wclsFrameSaver: saving 105477 traces tagged "wiener"
FrameSaver: q=3.82651e+06 n=1309806 tag=wiener
0 X, 0 U, 0 V bad channels
Finding XUV coincidences...
C:0 T:2 28548 XUs and 33061 XVs -> 3205 XUVs
C:0 T:4 5 XUs and 8 XVs -> 2 XUVs
C:0 T:5 8435 XUs and 9875 XVs -> 457 XUVs
C:0 T:6 60142 XUs and 49870 XVs -> 1443 XUVs
C:0 T:7 5 XUs and 6 XVs -> 0 XUVs
5107 XUVs total
1856 collection wire objects
5107 potential space points
Neighbour search...
203863 tests to find 125366 neighbours
Iterating with no regularization...
Begin: 3.07781e+07
0 2.93468e+07
1 2.92028e+07
2 2.91768e+07
Now with regularization...
Begin: 2.71923e+07
0 2.71807e+07
12-Dec-2025 13:54:11 UTC  Closed output file "pdhd_prod_beam__242496_11_1_20251112T224205Z_gen_g4_IonScintPDExt.root_258178_84_1_20251205T214826Z_PDInt.root_267333_1_1_20251212T113715Z_detsim_reco1.root"
12-Dec-2025 13:54:11 UTC  Closed input file "temp_detsim.root"

=====================================================================================================================================
TimeTracker printout (sec)                             Min           Avg           Max         Median          RMS         nEvts   
=====================================================================================================================================
Full event                                           131.167       173.793       326.998       160.635       54.3877        10     
-------------------------------------------------------------------------------------------------------------------------------------
source:RootInput(read)                              0.0013423     0.0102351     0.021524      0.0070714    0.00593394       10     
reco:wclsdatahd:WireCellToolkit                      77.8852       91.4775       121.71        85.7907       14.0634        10     
reco:wirefilter:WireFilter                          0.055288       0.07563      0.140828      0.069865      0.0245955       10     
reco:gaushit:GausHitFinder                          0.613594      0.945181       1.86185      0.875199       0.32962        10     
reco:nhitsfilter:NumberOfHitsFilter                0.000539679   0.000956764   0.00204238    0.000845551   0.000390324      10     
reco:reco3d:SpacePointSolver                        0.352272      0.947797       2.78697      0.857957      0.673276        10     
reco:hitpdune:DisambigFromSpacePoints               0.393378      0.825353       2.33227      0.717203      0.533594        10     
reco:pandora:StandardPandora                         7.35505       20.5095       51.3358       13.1914       14.883         10     
reco:pandoraWriter:StandardPandora                  0.246761       0.39938      0.764119      0.366226      0.137855        10     
reco:pandoraTrack:LArPandoraTrackCreation            1.81348       4.17792       14.1436       2.98072       3.50773        10     
reco:pandoraShower:LArPandoraShowerCreation          1.32776       4.81165       17.8305       3.36641       4.47406        10     
reco:pandoracalo:Calorimetry                        0.845233       2.2155        7.41946       1.65353       1.82843        10     
reco:pandoracalonosce:Calorimetry                   0.669837       2.08386       7.27277       1.52405       1.82647        10     
reco:pandoraShowercalo:ShowerCalorimetry             1.14323       4.44744       19.0669       2.72021       5.01083        10     
reco:pandoraShowercalonosce:ShowerCalorimetry        1.18911       4.29574       18.0664       2.58295       4.72005        10     
reco:pandoraGnocchiCalo:GnocchiCalorimetry          0.0535173      0.10252      0.192866      0.0867953     0.0429782       10     
reco:pandoraGnocchiCalonosce:GnocchiCalorimetry     0.0536637     0.100994      0.187825      0.088543      0.0406629       10     
reco:emtrkmichelid:EmTrackMichelId                   20.8325       33.9846       58.1156       30.3889       10.7337        10     
[art]:TriggerResults:TriggerResultInserter         5.6138e-05    9.52036e-05   0.000133453   0.00010221    2.39946e-05      10     
end_path:out1:RootOutput                            9.085e-06    1.99754e-05   3.3535e-05    1.9564e-05    7.97805e-06      10     
end_path:out1:RootOutput(write)                      1.40936       2.21626       3.40265       2.22346      0.504482        10     
=====================================================================================================================================

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

  Peak virtual memory usage (VmPeak)  : 5734.37 MB
  Peak resident set size usage (VmHWM): 3583.97 MB
  Details saved in: 'mem.db'
====================================================================================================
Art has completed and will exit with status 0.
Reco returns 0
.:
total 11962856
-rw-r--r-- 1 dunegli fnalgrid     231322 Dec 12 13:54 jobscript.log
-rw-r--r-- 1 dunegli fnalgrid        194 Dec 12 13:54 justin-processed-pfns.txt
-rw-r--r-- 1 dunegli fnalgrid        519 Dec 12 13:54 reco_protodunehd_hist.root
-rw-r--r-- 1 dunegli fnalgrid       3574 Dec 12 13:54 Pandora_Geometry.xml
-rw-r--r-- 1 dunegli fnalgrid     139264 Dec 12 13:54 mem.db
-rw-r--r-- 1 dunegli fnalgrid      28672 Dec 12 13:54 time.db
-rw-r--r-- 1 dunegli fnalgrid 6206393156 Dec 12 13:54 pdhd_prod_beam__242496_11_1_20251112T224205Z_gen_g4_IonScintPDExt.root_258178_84_1_20251205T214826Z_PDInt.root_267333_1_1_20251212T113715Z_detsim_reco1.root
-rw-r--r-- 1 dunegli fnalgrid   37976640 Dec 12 13:53 Pandora_Events.pndr
-rw-r--r-- 1 dunegli fnalgrid          0 Dec 12 13:21 debugprod.log
-rw-r--r-- 1 dunegli fnalgrid        519 Dec 12 13:21 detsim_single_protodunehd_hist.root
-rw-r--r-- 1 dunegli fnalgrid 6005150799 Dec 12 13:21 temp_detsim.root
-rw-r--r-- 1 dunegli fnalgrid        121 Dec 12 11:37 all-input-dids.txt