Jobsub ID 266179.0@dunegpschedd01.fnal.gov

Jobsub ID	266179.0@dunegpschedd01.fnal.gov
Workflow ID	11103
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-10 17:05:11
Site	US_FNAL-FermiGrid
Entry	FNAL_GPGrid_ce03_mcore_op_duneonly
Last heartbeat	2025-12-10 21:03:11
From worker node	Hostname	dunegli-7872681-0-fnpc9002.fnal.gov
	cpuinfo	Intel(R) Xeon(R) CPU E5-2680 v4 @ 2.40GHz
	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-10 19:26:06
Input files	usertests:pdhd_prod_beam__241630_22_1_20251112T003559Z_gen_g4_IonScintPDExt.root_258115_1_1_20251205T174532Z_PDInt.root
Jobscript	Exit code	0
	Real time	1h (5590s)
	CPU time	1h (5350s = 95%)
	Max RSS bytes	6836232192 (6519 MiB)
Outputting started	2025-12-10 20:59:17
Output files	usertests:pdhd_prod_beam__241630_22_1_20251112T003559Z_gen_g4_IonScintPDExt.root_258115_1_1_20251205T174532Z_PDInt.root_266179_0_1_20251210T192611Z_detsim_reco1.root
Finished	2025-12-10 21:03:11
Saved logs	justin-logs:266179.0-dunegpschedd01.fnal.gov.logs.tgz
List job events Cached HTCondor job logs

Jobscript log (last 10,000 characters)

0: frame: ident=109 time=0 tick=512 with 56810 traces.  frame tags:[ "sigproc" ] 2 tagged trace sets:[ "gauss0":26406 [0] "wiener0":30404 [30404] ] cmm:[ bad:0 lf_noisy:353 ] input 1: frame: ident=109 time=0 tick=512 with 50377 traces.  frame tags:[ "sigproc" ] 2 tagged trace sets:[ "gauss1":20499 [0] "wiener1":29878 [29878] ] cmm:[ bad:0 ] input 2: frame: ident=109 time=0 tick=512 with 41700 traces.  frame tags:[ "sigproc" ] 2 tagged trace sets:[ "gauss2":17869 [0] "wiener2":23831 [23831] ] cmm:[ bad:0 ] input 3: frame: ident=109 time=0 tick=512 with 46455 traces.  frame tags:[ "sigproc" ] 2 tagged trace sets:[ "gauss3":18857 [0] "wiener3":27598 [27598] ] cmm:[ bad:0 ] output: frame: ident=109 time=0 tick=512 with 195342 traces.  frame tags:[ "framefanin" ] 8 tagged trace sets:[ "gauss0":26406 [0] "gauss1":20499 [0] "gauss2":17869 [0] "gauss3":18857 [0] "wiener0":30404 [30404] "wiener1":29878 [29878] "wiener2":23831 [23831] "wiener3":27598 [27598] ] cmm:[ bad:0 lf_noisy:353 ] 
Retagger: tagging trace set: wiener with 111711 traces, 111711 summary
Retagger: tagging trace set: gauss with 83631 traces, 0 summary
[20:57:58.152] D [  glue  ] sink frame: #109 @0 with 195342 traces, frame tags:[retagger], trace tags:[gauss, wiener]
[20:57:58.152] D [  glue  ] <FrameFanout:sn_mag_nf> call=19: see EOS 
[20:57:58.152] D [  glue  ] <ChannelSelector:chsel3> see EOS at call=9 
[20:57:58.152] D [sigproc ] <OmnibusNoiseFilter:nf3> EOS at call=19 
[20:57:58.152] D [sigproc ] <OmnibusSigProc:apa3sigproc3> EOS at call=19 anode=3 
[20:57:58.152] D [  glue  ] <ChannelSelector:chsel2> see EOS at call=9 
[20:57:58.152] D [sigproc ] <OmnibusNoiseFilter:nf2> EOS at call=19 
[20:57:58.152] D [sigproc ] <OmnibusSigProc:apa2sigproc2> EOS at call=19 anode=2 
[20:57:58.152] D [  glue  ] <ChannelSelector:chsel1> see EOS at call=9 
[20:57:58.152] D [sigproc ] <OmnibusNoiseFilter:nf1> EOS at call=19 
[20:57:58.152] D [sigproc ] <OmnibusSigProc:apa1sigproc1> EOS at call=19 anode=1 
[20:57:58.152] D [  glue  ] <ChannelSelector:chsel0> see EOS at call=9 
[20:57:58.152] D [sigproc ] <OmnibusNoiseFilter:nf0> EOS at call=19 
[20:57:58.152] D [sigproc ] <OmnibusSigProc:apa0sigproc0> EOS at call=19 anode=0 
[20:57:58.152] D [  glue  ] <FrameFanin:sn_mag_nf> EOS at call=19 with 4 
[20:57:58.152] D [  glue  ] frame sink sees EOS
[20:57:58.152] D [ pgraph ] <Pgrapher:> graph execution complete 
[20:57:58.152] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 18.23 sec
[20:57:58.152] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 12.85 sec
[20:57:58.152] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 12.82 sec
[20:57:58.152] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 12.48 sec
[20:57:58.152] I [ timer  ] Timer: WireCell::SigProc::OmnibusNoiseFilter : 3.23 sec
[20:57:58.152] I [ timer  ] Timer: WireCell::SigProc::OmnibusNoiseFilter : 3.14 sec
[20:57:58.152] I [ timer  ] Timer: WireCell::SigProc::OmnibusNoiseFilter : 3.06 sec
[20:57:58.152] I [ timer  ] Timer: WireCell::SigProc::OmnibusNoiseFilter : 3.04 sec
[20:57:58.152] I [ timer  ] Timer: WireCell::Gen::FrameFanin : 0.07 sec
[20:57:58.152] I [ timer  ] Timer: WireCell::Gen::Retagger : 0.03 sec
[20:57:58.152] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[20:57:58.153] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[20:57:58.153] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[20:57:58.153] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[20:57:58.153] I [ timer  ] Timer: WireCell::Gen::FrameFanout : 0 sec
[20:57:58.153] I [ timer  ] Timer: wcls::RawFrameSource : 0 sec
[20:57:58.153] I [ timer  ] Timer: wcls::FrameSaver : 0 sec
[20:57:58.153] I [ timer  ] Timer: WireCell::Gen::DumpFrames : 0 sec
[20:57:58.153] I [ timer  ] Timer: Total node execution : 68.97999918833375 sec
wclsFrameSaver saving cooked to 6000 ticks
wclsFrameSaver: saving 83631 traces tagged "gauss"
FrameSaver: q=2.75787e+06 n=1242393 tag=gauss
wclsFrameSaver: saving 111711 traces tagged "wiener"
FrameSaver: q=3.54231e+06 n=1187936 tag=wiener
0 X, 0 U, 0 V bad channels
Finding XUV coincidences...
C:0 T:2 44545 XUs and 60145 XVs -> 1514 XUVs
C:0 T:3 6 XUs and 13 XVs -> 1 XUVs
C:0 T:4 12 XUs and 17 XVs -> 1 XUVs
C:0 T:5 32928 XUs and 25686 XVs -> 1087 XUVs
C:0 T:6 75334 XUs and 55432 XVs -> 2057 XUVs
C:0 T:7 18 XUs and 11 XVs -> 0 XUVs
4660 XUVs total
1797 collection wire objects
4660 potential space points
Neighbour search...
165428 tests to find 97022 neighbours
Iterating with no regularization...
Begin: 3.29389e+07
0 3.04548e+07
1 3.03041e+07
2 3.02825e+07
Now with regularization...
Begin: 2.81149e+07
0 2.81073e+07
10-Dec-2025 20:59:14 UTC  Closed output file "pdhd_prod_beam__241630_22_1_20251112T003559Z_gen_g4_IonScintPDExt.root_258115_1_1_20251205T174532Z_PDInt.root_266179_0_1_20251210T192611Z_detsim_reco1.root"
10-Dec-2025 20:59:14 UTC  Closed input file "temp_detsim.root"

=====================================================================================================================================
TimeTracker printout (sec)                             Min           Avg           Max         Median          RMS         nEvts   
=====================================================================================================================================
Full event                                           97.4252       124.834       149.306       127.906       16.3321        10     
-------------------------------------------------------------------------------------------------------------------------------------
source:RootInput(read)                             0.00394835     0.0128108     0.0351955    0.00818546    0.00996418       10     
reco:wclsdatahd:WireCellToolkit                      62.2605       69.8965       87.4834       66.8696       6.93402        10     
reco:wirefilter:WireFilter                          0.0440689     0.0655876     0.0959168     0.0630505     0.0146516       10     
reco:gaushit:GausHitFinder                          0.429353       0.69619      0.993333      0.697934      0.160176        10     
reco:nhitsfilter:NumberOfHitsFilter                0.000393462   0.00061989    0.000960178   0.000624526   0.000146215      10     
reco:reco3d:SpacePointSolver                        0.251793      0.946327       3.39535       0.5873       0.888325        10     
reco:hitpdune:DisambigFromSpacePoints                0.23199      0.619001       0.94582      0.655724      0.256001        10     
reco:pandora:StandardPandora                         4.97456       12.4957       19.9003       14.2482       4.90445        10     
reco:pandoraWriter:StandardPandora                  0.180827      0.303911      0.437796      0.306297      0.0750787       10     
reco:pandoraTrack:LArPandoraTrackCreation           0.938204       2.31187       3.39807       2.18968      0.645819        10     
reco:pandoraShower:LArPandoraShowerCreation         0.824717       2.77134       4.19629       2.84148       1.09097        10     
reco:pandoracalo:Calorimetry                        0.438703       1.11987       1.63302       1.09179       0.33184        10     
reco:pandoracalonosce:Calorimetry                   0.411609       1.05428       1.61519       1.05551       0.34532        10     
reco:pandoraShowercalo:ShowerCalorimetry            0.462728       2.2427        3.60742       2.48902      0.991145        10     
reco:pandoraShowercalonosce:ShowerCalorimetry       0.495965       2.24287       3.37056       2.47939      0.911928        10     
reco:pandoraGnocchiCalo:GnocchiCalorimetry          0.0377299     0.0729429     0.111092      0.0696178     0.0207369       10     
reco:pandoraGnocchiCalonosce:GnocchiCalorimetry     0.0373732     0.0705152     0.102945      0.070186      0.0214318       10     
reco:emtrkmichelid:EmTrackMichelId                   16.9422       26.2327       33.0509       27.7418       4.72234        10     
[art]:TriggerResults:TriggerResultInserter         4.3143e-05    0.000109024   0.000307481   8.9022e-05    7.21721e-05      10     
end_path:out1:RootOutput                           1.2915e-05    2.64186e-05   0.000115444   1.4749e-05    2.98989e-05      10     
end_path:out1:RootOutput(write)                     0.845529       1.56755       2.98945       1.38909       0.6184         10     
=====================================================================================================================================

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

  Peak virtual memory usage (VmPeak)  : 6118.87 MB
  Peak resident set size usage (VmHWM): 3958.31 MB
  Details saved in: 'mem.db'
====================================================================================================
Art has completed and will exit with status 0.
Reco returns 0
.:
total 11103060
-rw-r--r-- 1 dunegli fnalgrid     231340 Dec 10 20:59 jobscript.log
-rw-r--r-- 1 dunegli fnalgrid        199 Dec 10 20:59 justin-processed-pfns.txt
-rw-r--r-- 1 dunegli fnalgrid        519 Dec 10 20:59 reco_protodunehd_hist.root
-rw-r--r-- 1 dunegli fnalgrid       3574 Dec 10 20:59 Pandora_Geometry.xml
-rw-r--r-- 1 dunegli fnalgrid     139264 Dec 10 20:59 mem.db
-rw-r--r-- 1 dunegli fnalgrid      28672 Dec 10 20:59 time.db
-rw-r--r-- 1 dunegli fnalgrid 5755657652 Dec 10 20:59 pdhd_prod_beam__241630_22_1_20251112T003559Z_gen_g4_IonScintPDExt.root_258115_1_1_20251205T174532Z_PDInt.root_266179_0_1_20251210T192611Z_detsim_reco1.root
-rw-r--r-- 1 dunegli fnalgrid   31867790 Dec 10 20:58 Pandora_Events.pndr
-rw-r--r-- 1 dunegli fnalgrid          0 Dec 10 20:34 debugprod.log
-rw-r--r-- 1 dunegli fnalgrid        519 Dec 10 20:33 detsim_single_protodunehd_hist.root
-rw-r--r-- 1 dunegli fnalgrid 5581475618 Dec 10 20:33 temp_detsim.root
-rw-r--r-- 1 dunegli fnalgrid        120 Dec 10 19:26 all-input-dids.txt