Jobsub ID 234629.66@dunegpschedd02.fnal.gov
Jobscript log (last 10,000 characters)
node0sigproc0> EOS at call=47 anode=0 
[14:21:21.239] D [  glue  ] <FrameFanin:nfsp> EOS at call=47 with 8 
[14:21:21.239] D [  glue  ] frame sink sees EOS
[14:21:21.239] D [ pgraph ] <Pgrapher:> graph execution complete 
[14:21:21.239] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 12.01 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 11.34 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 10.98 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 10.15 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 10.04 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 9.85 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 9.3 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 8.91 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.3 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.28 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.27 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.27 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::Gen::FrameFanin : 0.04 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.02 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::Gen::Retagger : 0.02 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::Gen::DumpFrames : 0 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[14:21:21.239] I [ timer  ] Timer: WireCell::Gen::FrameFanout : 0 sec
[14:21:21.239] I [ timer  ] Timer: wcls::RawFrameSource : 0 sec
[14:21:21.239] I [ timer  ] Timer: wcls::FrameSaver : 0 sec
[14:21:21.239] I [ timer  ] Timer: Total node execution : 83.79999995604157 sec
wclsFrameSaver saving cooked to 10000 ticks
wclsFrameSaver: saving 56590 traces tagged "gauss"
FrameSaver: q=1.58719e+07 n=1267312 tag=gauss
wclsFrameSaver: saving 70942 traces tagged "wiener"
FrameSaver: q=1.71323e+07 n=1213807 tag=wiener
0 X, 0 U, 0 V bad channels
Finding XUV coincidences...
C:0 T:0 8682 XUs and 9240 XVs -> 655 XUVs
C:0 T:1 204 XUs and 166 XVs -> 4 XUVs
C:0 T:2 1232 XUs and 1442 XVs -> 56 XUVs
C:0 T:3 1171 XUs and 1496 XVs -> 47 XUVs
C:0 T:4 939 XUs and 1266 XVs -> 97 XUVs
C:0 T:5 753 XUs and 1168 XVs -> 33 XUVs
C:0 T:6 68 XUs and 77 XVs -> 1 XUVs
C:0 T:7 1906 XUs and 3233 XVs -> 133 XUVs
C:0 T:8 12468 XUs and 28202 XVs -> 5997 XUVs
C:0 T:9 5045 XUs and 12868 XVs -> 1575 XUVs
C:0 T:10 3050 XUs and 7322 XVs -> 1495 XUVs
C:0 T:11 6199 XUs and 7811 XVs -> 885 XUVs
C:0 T:12 15326 XUs and 20128 XVs -> 1945 XUVs
C:0 T:13 1698 XUs and 1786 XVs -> 140 XUVs
C:0 T:14 6007 XUs and 10809 XVs -> 1716 XUVs
C:0 T:15 10724 XUs and 7801 XVs -> 1544 XUVs
16323 XUVs total
2344 collection wire objects
16323 potential space points
Neighbour search...
2275483 tests to find 935756 neighbours
Iterating with no regularization...
Begin: 1.90751e+10
0 1.82493e+10
1 1.8066e+10
2 1.80646e+10
Now with regularization...
Begin: 1.79501e+10
0 1.79495e+10
29-Oct-2025 14:22:46 GMT  Closed output file "np02vd_raw_run040267_0278_df-s04-d1_dw_0_20251026T022139_reco_stage1_20251029T142246_keepup.root"
==================================================================================================================================
TimeTracker printout (sec)                          Min           Avg           Max         Median          RMS         nEvts   
==================================================================================================================================
Full event                                        170.583       232.451       428.126       200.724       61.7787        24     
----------------------------------------------------------------------------------------------------------------------------------
source:HDF5RawInput3(read)                      5.5361e-05    7.34522e-05   0.000186622   6.5096e-05    2.6675e-05       24     
produce:tpcrawdecoder:PDVDTPCReader               68.4371       71.8142       85.694        70.8283       3.62247        24     
produce:triggerrawdecoder:PDVDTriggerReader4     0.505051      0.528771      0.676264      0.520605      0.0327363       24     
produce:pdvddaphne:DAPHNEReaderPDVD             0.000437223   0.000481877   0.000867032   0.00045687    8.46069e-05      24     
produce:ophit:OpHitFinder                       6.3975e-05    0.000114257   0.000581838   9.22845e-05   9.96572e-05      24     
produce:opflash:OpFlashFinderVerticalDrift      5.3615e-05    7.58658e-05   0.000345039   6.1055e-05    5.67435e-05      24     
produce:wclsdatavd:WireCellToolkit                69.6029       94.1023       159.171       79.3086       26.3074        24     
produce:gaushit:GausHitFinder                     1.04771       1.5974        2.48381       1.56894      0.365234        24     
produce:nhitsfilter:NumberOfHitsFilter          0.000278011   0.000396422   0.000707155   0.00037734    9.52993e-05      24     
produce:reco3d:SpacePointSolver                   7.25168       13.7585       26.5705       12.958        4.79159        24     
produce:hitpdune:DisambigFromSpacePoints         0.129897      0.284026      0.633745      0.256056      0.134437        24     
produce:pandora:StandardPandora                   16.889        43.7368       159.132       30.1901       31.4007        24     
produce:pandoraTrack:LArPandoraTrackCreation     0.765033       1.69486       3.3365        1.63842      0.744669        24     
produce:pandoraGnocalo:GnocchiCalorimetry        0.0181145     0.0368548     0.0549845     0.0371249    0.00891131       24     
[art]:TriggerResults:TriggerResultInserter      2.6645e-05    3.80215e-05   9.6423e-05    3.5302e-05    1.29796e-05      24     
end_path:out1:RootOutput                         5.162e-06    8.11008e-06   2.7743e-05     7.249e-06    4.17668e-06      24     
end_path:out1:RootOutput(write)                   4.33951       4.84423       6.18558       4.70659      0.432241        24     
==================================================================================================================================
====================================================================================================
MemoryTracker summary (base-10 MB units used)
  Peak virtual memory usage (VmPeak)  : 5267.23 MB
  Peak resident set size usage (VmHWM): 3376.28 MB
  Details saved in: 'mem.db'
====================================================================================================
Art has completed and will exit with status 0.
Output files:
\tReco: np02vd_raw_run040267_0278_df-s04-d1_dw_0_20251026T022139_reco_stage1_20251029T142246_keepup.root
\tHists: np02vd_raw_run040267_0278_df-s04-d1_dw_0_20251026T022139_reco_stage1_20251029T142246_keepup_hists.root
Forming reco metadata
Successfully opened file np02vd_raw_run040267_0278_df-s04-d1_dw_0_20251026T022139_reco_stage1_20251029T142246_keepup.root
Ran successfully
{
  "name": "np02vd_raw_run040267_0278_df-s04-d1_dw_0_20251026T022139_reco_stage1_20251029T142246_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": 1761747766.0,
    "core.end_time": 1761747766.0,
    "core.events": [
      51645,
      51653,
      51661,
      51669,
      51677,
      51685,
      51693,
      51701,
      51709,
      51717,
      51725,
      51733,
      51741,
      51749,
      51757,
      51765,
      51773,
      51781,
      51789,
      51797,
      51805,
      51813,
      51821,
      51829
    ],
    "core.event_count": 24,
    "core.first_event_number": 51645,
    "core.last_event_number": 51829,
    "core.data_stream": "cosmics",
    "core.file_content_status": "good",
    "core.file_type": "detector",
    "core.run_type": "vd-protodune",
    "core.runs": [
      40267
    ],
    "core.runs_subruns": [
      4026700001
    ],
    "dune.daq_test": false,
    "retention.status": "active",
    "retention.class": "physics"
  },
  "parents": [
    {
      "did": "vd-protodune:np02vd_raw_run040267_0278_df-s04-d1_dw_0_20251026T022139.hdf5"
    }
  ]
}Forming hist metadata
formed
{
  "name": "np02vd_raw_run040267_0278_df-s04-d1_dw_0_20251026T022139_reco_stage1_20251029T142246_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": 1761747766.0,
    "core.end_time": 1761747766.0,
    "core.data_stream": "cosmics",
    "core.file_content_status": "good",
    "core.file_type": "detector",
    "core.run_type": "vd-protodune",
    "core.runs": [
      40267
    ],
    "core.runs_subruns": [
      4026700001
    ],
    "dune.daq_test": false,
    "retention.status": "active",
    "retention.class": "physics"
  },
  "parents": [
    {
      "did": "vd-protodune:np02vd_raw_run040267_0278_df-s04-d1_dw_0_20251026T022139.hdf5"
    }
  ]
}