Jobsub ID 223125.177@dunegpschedd02.fnal.gov
Jobscript log (last 10,000 characters)
graph execution complete 
[09:10:30.114] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 24.06 sec
[09:10:30.114] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 10.91 sec
[09:10:30.114] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 10.26 sec
[09:10:30.114] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 10.04 sec
[09:10:30.114] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 8.73 sec
[09:10:30.114] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 8.52 sec
[09:10:30.114] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 8.3 sec
[09:10:30.114] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 7.84 sec
[09:10:30.114] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.24 sec
[09:10:30.114] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.23 sec
[09:10:30.114] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.22 sec
[09:10:30.114] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.22 sec
[09:10:30.115] I [ timer  ] Timer: WireCell::Gen::FrameFanin : 0.05 sec
[09:10:30.115] I [ timer  ] Timer: WireCell::Gen::Retagger : 0.03 sec
[09:10:30.115] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[09:10:30.115] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[09:10:30.115] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[09:10:30.115] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[09:10:30.115] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[09:10:30.115] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[09:10:30.115] I [ timer  ] Timer: WireCell::Gen::DumpFrames : 0 sec
[09:10:30.115] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[09:10:30.115] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[09:10:30.115] I [ timer  ] Timer: WireCell::Gen::FrameFanout : 0 sec
[09:10:30.115] I [ timer  ] Timer: wcls::RawFrameSource : 0 sec
[09:10:30.115] I [ timer  ] Timer: wcls::FrameSaver : 0 sec
[09:10:30.115] I [ timer  ] Timer: Total node execution : 89.65999984368682 sec
wclsFrameSaver saving cooked to 10000 ticks
wclsFrameSaver: saving 73818 traces tagged "gauss"
FrameSaver: q=1.74793e+07 n=1896246 tag=gauss
wclsFrameSaver: saving 95315 traces tagged "wiener"
FrameSaver: q=1.91464e+07 n=1818273 tag=wiener
0 X, 0 U, 0 V bad channels
Finding XUV coincidences...
C:0 T:0 4821 XUs and 6186 XVs -> 274 XUVs
C:0 T:1 10238 XUs and 12715 XVs -> 882 XUVs
C:0 T:2 606 XUs and 594 XVs -> 25 XUVs
C:0 T:3 572 XUs and 577 XVs -> 17 XUVs
C:0 T:4 1403 XUs and 1868 XVs -> 61 XUVs
C:0 T:5 446 XUs and 462 XVs -> 24 XUVs
C:0 T:6 1312 XUs and 1424 XVs -> 48 XUVs
C:0 T:7 743 XUs and 761 XVs -> 23 XUVs
C:0 T:8 81024 XUs and 183810 XVs -> 30250 XUVs
C:0 T:9 31007 XUs and 58379 XVs -> 5177 XUVs
C:0 T:10 18157 XUs and 36435 XVs -> 5500 XUVs
C:0 T:11 548 XUs and 530 XVs -> 46 XUVs
C:0 T:12 2596 XUs and 3083 XVs -> 154 XUVs
C:0 T:13 2243 XUs and 4203 XVs -> 658 XUVs
C:0 T:14 6673 XUs and 21768 XVs -> 2033 XUVs
C:0 T:15 18910 XUs and 26194 XVs -> 3800 XUVs
48972 XUVs total
5360 collection wire objects
48972 potential space points
Neighbour search...
7690818 tests to find 3039266 neighbours
Iterating with no regularization...
Begin: 3.88413e+09
0 3.56038e+09
1 3.53713e+09
2 3.53378e+09
Now with regularization...
Begin: 3.47223e+09
0 3.47042e+09
BdtBeamParticleIdTool::SliceFeatures::GetLeadingCaloHits - empty calo hit list
BdtBeamParticleIdTool::SliceFeatures::GetLeadingCaloHits - empty calo hit list
BdtBeamParticleIdTool::SliceFeatures::GetLeadingCaloHits - empty calo hit list
03-Oct-2025 09:18:20 BST  Closed output file "np02vd_raw_run039812_0296_df-s03-d1_dw_0_20251003T004310_reco_stage1_20251003T081820_keepup.root"
==================================================================================================================================
TimeTracker printout (sec)                          Min           Avg           Max         Median          RMS         nEvts   
==================================================================================================================================
Full event                                        203.09        434.719       1993.94       343.075       368.211        21     
----------------------------------------------------------------------------------------------------------------------------------
source:HDF5RawInput3(read)                      0.000102645   0.000132192   0.000191035   0.000125276   2.38376e-05      21     
produce:tpcrawdecoder:PDVDTPCReader               83.5169       151.581       234.837       138.277       45.5867        21     
produce:triggerrawdecoder:PDVDTriggerReader4     0.432843      0.638109      0.912285       0.61042      0.141408        21     
produce:pdvddaphne:DAPHNEReaderPDVD               9.57662       14.8734       22.2349       13.2674       3.60663        21     
produce:ophit:OpHitFinder                        0.0303803     0.0361523     0.038747      0.0361203    0.00204055       21     
produce:opflash:OpFlashFinderVerticalDrift      0.00595832     0.0106681     0.0145964     0.0111051    0.00220445       21     
produce:wclsdatavd:WireCellToolkit                52.2755       83.4542       183.842       83.2749       26.1208        21     
produce:gaushit:GausHitFinder                    0.706938       1.6711        4.25578       1.60095      0.768111        21     
produce:nhitsfilter:NumberOfHitsFilter          0.000248376   0.000477532   0.00100967    0.000457583   0.000163837      21     
produce:reco3d:SpacePointSolver                   5.11496       18.183        67.7897       15.0243       13.3311        21     
produce:hitpdune:DisambigFromSpacePoints         0.117359      0.438983       2.19576      0.238431      0.469699        21     
produce:pandora:StandardPandora                   15.5866       156.773       1573.78       61.5812       328.208        21     
produce:pandoraTrack:LArPandoraTrackCreation     0.633734       2.46753       16.9658       1.50362       3.35343        21     
produce:pandoraGnocalo:GnocchiCalorimetry        0.0171824     0.0316816     0.0664523     0.0304226     0.0110826       21     
[art]:TriggerResults:TriggerResultInserter      1.9863e-05    2.54065e-05   5.1385e-05     2.249e-05    7.6038e-06       21     
end_path:out1:RootOutput                         6.814e-06    8.14357e-06   1.9876e-05     7.684e-06    2.66398e-06      21     
end_path:out1:RootOutput(write)                   3.72045       4.51478       5.89148       4.47847      0.576823        21     
==================================================================================================================================
====================================================================================================
MemoryTracker summary (base-10 MB units used)
  Peak virtual memory usage (VmPeak)  : 7405.94 MB
  Peak resident set size usage (VmHWM): 5501.17 MB
  Details saved in: 'mem.db'
====================================================================================================
Art has completed and will exit with status 0.
Output files:
\tReco: np02vd_raw_run039812_0296_df-s03-d1_dw_0_20251003T004310_reco_stage1_20251003T081820_keepup.root
\tHists: np02vd_raw_run039812_0296_df-s03-d1_dw_0_20251003T004310_reco_stage1_20251003T081827_keepup_hists.root
Forming reco metadata
Successfully opened file np02vd_raw_run039812_0296_df-s03-d1_dw_0_20251003T004310_reco_stage1_20251003T081820_keepup.root
Ran successfully
{
  "name": "np02vd_raw_run039812_0296_df-s03-d1_dw_0_20251003T004310_reco_stage1_20251003T081820_keepup.root",
  "namespace": "vd-protodune-det-reco",
  "metadata": {
    "core.file_format": "artroot",
    "core.application.name": "reco",
    "core.application.family": "dunesw",
    "core.application.version": "v10_10_00d00",
    "core.data_tier": "full-reconstructed",
    "dune.config_file": "standard_reco_stage1_protodunevd_keepup_all.fcl",
    "dune.campaign": "vd-protodune-reco-keepup-v0",
    "core.start_time": 1759479508.0,
    "core.end_time": 1759479508.0,
    "core.events": [
      50273,
      50281,
      50289,
      50297,
      50305,
      50313,
      50321,
      50329,
      50337,
      50345,
      50353,
      50361,
      50369,
      50377,
      50385,
      50393,
      50401,
      50409,
      50417,
      50425,
      50433
    ],
    "core.event_count": 21,
    "core.first_event_number": 50273,
    "core.last_event_number": 50433,
    "core.data_stream": "cosmics",
    "core.file_content_status": "good",
    "core.file_type": "detector",
    "core.run_type": "vd-protodune",
    "core.runs": [
      39812
    ],
    "core.runs_subruns": [
      3981200001
    ],
    "dune.daq_test": true,
    "retention.status": "active",
    "retention.class": "physics"
  },
  "parents": [
    {
      "did": "vd-protodune:np02vd_raw_run039812_0296_df-s03-d1_dw_0_20251003T004310.hdf5"
    }
  ]
}Forming hist metadata
formed
{
  "name": "np02vd_raw_run039812_0296_df-s03-d1_dw_0_20251003T004310_reco_stage1_20251003T081827_keepup_hists.root",
  "namespace": "vd-protodune-det-reco",
  "metadata": {
    "core.file_format": "root",
    "core.application.name": "reco",
    "core.application.family": "dunesw",
    "core.application.version": "v10_10_00d00",
    "core.data_tier": "root-tuple-virtual",
    "dune.config_file": "standard_reco_stage1_protodunevd_keepup_all.fcl",
    "dune.campaign": "vd-protodune-reco-keepup-v0",
    "core.start_time": 1759479508.0,
    "core.end_time": 1759479508.0,
    "core.data_stream": "cosmics",
    "core.file_content_status": "good",
    "core.file_type": "detector",
    "core.run_type": "vd-protodune",
    "core.runs": [
      39812
    ],
    "core.runs_subruns": [
      3981200001
    ],
    "dune.daq_test": true,
    "retention.status": "active",
    "retention.class": "physics"
  },
  "parents": [
    {
      "did": "vd-protodune:np02vd_raw_run039812_0296_df-s03-d1_dw_0_20251003T004310.hdf5"
    }
  ]
}