Jobsub ID 236682.47@dunegpschedd02.fnal.gov
Jobscript log (last 10,000 characters)
<FrameFanin:nfsp> EOS at call=43 with 8 
[14:41:13.285] D [  glue  ] frame sink sees EOS
[14:41:13.285] D [ pgraph ] <Pgrapher:> graph execution complete 
[14:41:13.285] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 35.05 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 12.9 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 12.88 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 12.66 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 12.59 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 12.04 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 11.57 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 10.76 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.61 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.59 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.59 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.59 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::Gen::FrameFanin : 0.04 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.02 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::Gen::Retagger : 0.01 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::Gen::DumpFrames : 0 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[14:41:13.285] I [ timer  ] Timer: WireCell::Gen::FrameFanout : 0 sec
[14:41:13.285] I [ timer  ] Timer: wcls::RawFrameSource : 0 sec
[14:41:13.285] I [ timer  ] Timer: wcls::FrameSaver : 0 sec
[14:41:13.285] I [ timer  ] Timer: Total node execution : 122.91999878920615 sec
wclsFrameSaver saving cooked to 10000 ticks
wclsFrameSaver: saving 54842 traces tagged "gauss"
FrameSaver: q=3.25595e+07 n=1445930 tag=gauss
wclsFrameSaver: saving 69129 traces tagged "wiener"
FrameSaver: q=3.48223e+07 n=1408541 tag=wiener
0 X, 0 U, 0 V bad channels
Finding XUV coincidences...
C:0 T:0 2148 XUs and 1838 XVs -> 80 XUVs
C:0 T:1 1618 XUs and 1061 XVs -> 103 XUVs
C:0 T:2 3592 XUs and 2329 XVs -> 142 XUVs
C:0 T:3 46062 XUs and 42099 XVs -> 2973 XUVs
C:0 T:4 144 XUs and 180 XVs -> 2 XUVs
C:0 T:5 695 XUs and 624 XVs -> 113 XUVs
C:0 T:6 30003 XUs and 26057 XVs -> 2759 XUVs
C:0 T:7 831 XUs and 624 XVs -> 237 XUVs
C:0 T:8 3837 XUs and 7617 XVs -> 545 XUVs
C:0 T:9 178 XUs and 235 XVs -> 12 XUVs
C:0 T:10 1947 XUs and 3692 XVs -> 210 XUVs
C:0 T:11 472 XUs and 607 XVs -> 38 XUVs
C:0 T:12 1278 XUs and 1267 XVs -> 161 XUVs
C:0 T:13 747 XUs and 682 XVs -> 45 XUVs
C:0 T:14 1342 XUs and 1670 XVs -> 149 XUVs
C:0 T:15 710 XUs and 822 XVs -> 48 XUVs
7617 XUVs total
2962 collection wire objects
7617 potential space points
Neighbour search...
367421 tests to find 93970 neighbours
Iterating with no regularization...
Begin: 4.07656e+11
0 3.78438e+11
1 3.74527e+11
2 3.74462e+11
Now with regularization...
Begin: 3.72639e+11
0 3.7262e+11
BdtBeamParticleIdTool::SliceFeatures::GetLeadingCaloHits - empty calo hit list
03-Nov-2025 14:44:18 GMT  Closed output file "np02vd_raw_run040346_3462_df-s04-d1_dw_0_20251103T123838_reco_stage1_20251103T144418_keepup.root"
==================================================================================================================================
TimeTracker printout (sec)                          Min           Avg           Max         Median          RMS         nEvts   
==================================================================================================================================
Full event                                        181.392       243.854       379.993       230.646       54.2829        22     
----------------------------------------------------------------------------------------------------------------------------------
source:HDF5RawInput3(read)                      8.8896e-05    0.000138227   0.000266719   0.000129917   3.82298e-05      22     
produce:tpcrawdecoder:PDVDTPCReader               53.8962       88.7077       146.541       79.0715       24.9873        22     
produce:triggerrawdecoder:PDVDTriggerReader4     0.590706      0.795536       1.41293      0.761299      0.187485        22     
produce:pdvddaphne:DAPHNEReaderPDVD             0.000301072   0.000504615   0.000970373   0.000487496   0.000124602      22     
produce:ophit:OpHitFinder                       7.6042e-05    0.000156844   0.000787241   0.000124167   0.000141442      22     
produce:opflash:OpFlashFinderVerticalDrift      6.1385e-05    0.00011458    0.00048128    0.000103499   8.22277e-05      22     
produce:wclsdatavd:WireCellToolkit                63.2284       91.8013       150.517       89.3837       21.045         22     
produce:gaushit:GausHitFinder                     1.01862       1.56136       2.29435       1.52607      0.323268        22     
produce:nhitsfilter:NumberOfHitsFilter          0.000336489   0.000619156   0.00110479    0.000525436   0.000218493      22     
produce:reco3d:SpacePointSolver                   7.93135       13.6066       20.0977       12.6377       2.96093        22     
produce:hitpdune:DisambigFromSpacePoints         0.110818      0.237221      0.450637      0.206571       0.08409        22     
produce:pandora:StandardPandora                   12.7919       39.4025       152.326       31.6409       28.9508        22     
produce:pandoraTrack:LArPandoraTrackCreation     0.540142       1.42427       2.99306       1.1961        0.70193        22     
produce:pandoraGnocalo:GnocchiCalorimetry        0.0255733     0.0459207     0.0718129     0.047162      0.0111676       22     
[art]:TriggerResults:TriggerResultInserter      3.0897e-05    5.40609e-05   0.00012861    4.9457e-05    2.04178e-05      22     
end_path:out1:RootOutput                         5.461e-06    1.13575e-05   3.4815e-05    1.02995e-05   6.06891e-06      22     
end_path:out1:RootOutput(write)                   4.84026       6.17004       9.17854       6.06626       0.9388         22     
==================================================================================================================================
====================================================================================================
MemoryTracker summary (base-10 MB units used)
  Peak virtual memory usage (VmPeak)  : 5624.15 MB
  Peak resident set size usage (VmHWM): 3548.04 MB
  Details saved in: 'mem.db'
====================================================================================================
Art has completed and will exit with status 0.
Output files:
\tReco: np02vd_raw_run040346_3462_df-s04-d1_dw_0_20251103T123838_reco_stage1_20251103T144418_keepup.root
\tHists: np02vd_raw_run040346_3462_df-s04-d1_dw_0_20251103T123838_reco_stage1_20251103T144418_keepup_hists.root
Forming reco metadata
Successfully opened file np02vd_raw_run040346_3462_df-s04-d1_dw_0_20251103T123838_reco_stage1_20251103T144418_keepup.root
Ran successfully
{
  "name": "np02vd_raw_run040346_3462_df-s04-d1_dw_0_20251103T123838_reco_stage1_20251103T144418_keepup.root",
  "namespace": "vd-protodune-det-reco",
  "metadata": {
    "core.file_format": "artroot",
    "core.application.name": "reco",
    "core.application.family": "dunesw",
    "core.application.version": "v10_11_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": 1762181059.0,
    "core.end_time": 1762181059.0,
    "core.events": [
      319697,
      319701,
      319705,
      319709,
      319713,
      319717,
      319721,
      319725,
      319729,
      319733,
      319737,
      319741,
      319745,
      319749,
      319753,
      319757,
      319761,
      319765,
      319769,
      319773,
      319777,
      319781
    ],
    "core.event_count": 22,
    "core.first_event_number": 319697,
    "core.last_event_number": 319781,
    "core.data_stream": "cosmics",
    "core.file_content_status": "good",
    "core.file_type": "detector",
    "core.run_type": "vd-protodune",
    "core.runs": [
      40346
    ],
    "core.runs_subruns": [
      4034600001
    ],
    "dune.daq_test": false,
    "retention.status": "active",
    "retention.class": "physics"
  },
  "parents": [
    {
      "did": "vd-protodune:np02vd_raw_run040346_3462_df-s04-d1_dw_0_20251103T123838.hdf5"
    }
  ]
}Forming hist metadata
formed
{
  "name": "np02vd_raw_run040346_3462_df-s04-d1_dw_0_20251103T123838_reco_stage1_20251103T144418_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_11_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": 1762181059.0,
    "core.end_time": 1762181059.0,
    "core.data_stream": "cosmics",
    "core.file_content_status": "good",
    "core.file_type": "detector",
    "core.run_type": "vd-protodune",
    "core.runs": [
      40346
    ],
    "core.runs_subruns": [
      4034600001
    ],
    "dune.daq_test": false,
    "retention.status": "active",
    "retention.class": "physics"
  },
  "parents": [
    {
      "did": "vd-protodune:np02vd_raw_run040346_3462_df-s04-d1_dw_0_20251103T123838.hdf5"
    }
  ]
}