Jobsub ID 234457.174@dunegpschedd02.fnal.gov
Jobscript log (last 10,000 characters)
> EOS at call=47 anode=0 
[12:56:10.551] D [  glue  ] <FrameFanin:nfsp> EOS at call=47 with 8 
[12:56:10.551] D [  glue  ] frame sink sees EOS
[12:56:10.551] D [ pgraph ] <Pgrapher:> graph execution complete 
[12:56:10.551] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 13.82 sec
[12:56:10.551] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 13.39 sec
[12:56:10.551] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 13.33 sec
[12:56:10.551] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 12.52 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 12.5 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 12.24 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 11.97 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 10.55 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.42 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.36 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.31 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.31 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::Gen::FrameFanin : 0.05 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::Gen::Retagger : 0.01 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::Gen::DumpFrames : 0 sec
[12:56:10.552] I [ timer  ] Timer: WireCell::Gen::FrameFanout : 0 sec
[12:56:10.552] I [ timer  ] Timer: wcls::RawFrameSource : 0 sec
[12:56:10.552] I [ timer  ] Timer: wcls::FrameSaver : 0 sec
[12:56:10.552] I [ timer  ] Timer: Total node execution : 101.83000065386295 sec
wclsFrameSaver saving cooked to 10000 ticks
wclsFrameSaver: saving 57333 traces tagged "gauss"
FrameSaver: q=1.37798e+07 n=1255805 tag=gauss
wclsFrameSaver: saving 71083 traces tagged "wiener"
FrameSaver: q=1.47116e+07 n=1206677 tag=wiener
0 X, 0 U, 0 V bad channels
Finding XUV coincidences...
C:0 T:0 365 XUs and 456 XVs -> 15 XUVs
C:0 T:1 258 XUs and 234 XVs -> 2 XUVs
C:0 T:2 205 XUs and 281 XVs -> 4 XUVs
C:0 T:3 847 XUs and 890 XVs -> 29 XUVs
C:0 T:4 430 XUs and 562 XVs -> 17 XUVs
C:0 T:5 13284 XUs and 16948 XVs -> 714 XUVs
C:0 T:6 671 XUs and 691 XVs -> 37 XUVs
C:0 T:7 6502 XUs and 8240 XVs -> 405 XUVs
C:0 T:8 351 XUs and 432 XVs -> 27 XUVs
C:0 T:9 1417 XUs and 1113 XVs -> 107 XUVs
C:0 T:10 1018 XUs and 839 XVs -> 49 XUVs
C:0 T:11 1909 XUs and 2339 XVs -> 105 XUVs
C:0 T:12 261 XUs and 362 XVs -> 18 XUVs
C:0 T:13 8262 XUs and 13378 XVs -> 2343 XUVs
C:0 T:14 6142 XUs and 7112 XVs -> 714 XUVs
C:0 T:15 4395 XUs and 8397 XVs -> 861 XUVs
5447 XUVs total
1676 collection wire objects
5447 potential space points
Neighbour search...
636637 tests to find 263664 neighbours
Iterating with no regularization...
Begin: 2.93582e+09
0 2.77052e+09
1 2.76391e+09
2 2.76349e+09
Now with regularization...
Begin: 2.72203e+09
0 2.72184e+09
29-Oct-2025 12:57:48 CET  Closed output file "np02vd_raw_run040267_0721_df-s04-d3_dw_0_20251026T144456_reco_stage1_20251029T115748_keepup.root"
==================================================================================================================================
TimeTracker printout (sec)                          Min           Avg           Max         Median          RMS         nEvts   
==================================================================================================================================
Full event                                        182.02        294.813       393.742       307.181       61.5152        24     
----------------------------------------------------------------------------------------------------------------------------------
source:HDF5RawInput3(read)                      9.2894e-05    0.000132208   0.000305472   0.000117325   4.54935e-05      24     
produce:tpcrawdecoder:PDVDTPCReader               44.655        93.7888       182.325       82.9204       40.8992        24     
produce:triggerrawdecoder:PDVDTriggerReader4     0.306253      0.436958      0.851873      0.355176      0.150034        24     
produce:pdvddaphne:DAPHNEReaderPDVD             0.000413614   0.000783471   0.00152824    0.000743226   0.000239909      24     
produce:ophit:OpHitFinder                       7.3768e-05    0.000188738   0.00092945    0.000123837   0.000170285      24     
produce:opflash:OpFlashFinderVerticalDrift      5.1547e-05    0.000112353   0.000506278   7.3728e-05    0.000100049      24     
produce:wclsdatavd:WireCellToolkit                83.6671       121.499       204.875       109.59        28.4422        24     
produce:gaushit:GausHitFinder                     1.24934       1.88779       2.81773       1.85356      0.420596        24     
produce:nhitsfilter:NumberOfHitsFilter          0.000493804   0.000987147   0.00172707    0.00100004    0.000301506      24     
produce:reco3d:SpacePointSolver                   10.3182       16.6104       23.324        15.6933       3.28798        24     
produce:hitpdune:DisambigFromSpacePoints          0.13929      0.282754       0.45498      0.258689      0.0914302       24     
produce:pandora:StandardPandora                   23.4535       48.8991       117.927       38.3933       26.2168        24     
produce:pandoraTrack:LArPandoraTrackCreation      1.13306       3.24563       7.73079       3.08699       1.59794        24     
produce:pandoraGnocalo:GnocchiCalorimetry        0.0362024     0.0672173      0.14711      0.0597716     0.0255148       24     
[art]:TriggerResults:TriggerResultInserter      3.4084e-05    0.000105653    0.0002083    9.96765e-05   4.92233e-05      24     
end_path:out1:RootOutput                         5.47e-06     1.96497e-05   6.8729e-05    1.79085e-05   1.43499e-05      24     
end_path:out1:RootOutput(write)                   6.34844       7.92642       10.2756       7.87653      0.960524        24     
==================================================================================================================================
====================================================================================================
MemoryTracker summary (base-10 MB units used)
  Peak virtual memory usage (VmPeak)  : 5304.88 MB
  Peak resident set size usage (VmHWM): 3379.8 MB
  Details saved in: 'mem.db'
====================================================================================================
Art has completed and will exit with status 0.
Output files:
\tReco: np02vd_raw_run040267_0721_df-s04-d3_dw_0_20251026T144456_reco_stage1_20251029T115748_keepup.root
\tHists: np02vd_raw_run040267_0721_df-s04-d3_dw_0_20251026T144456_reco_stage1_20251029T115749_keepup_hists.root
Forming reco metadata
Successfully opened file np02vd_raw_run040267_0721_df-s04-d3_dw_0_20251026T144456_reco_stage1_20251029T115748_keepup.root
Ran successfully
{
  "name": "np02vd_raw_run040267_0721_df-s04-d3_dw_0_20251026T144456_reco_stage1_20251029T115748_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": 1761739070.0,
    "core.end_time": 1761739070.0,
    "core.events": [
      133359,
      133367,
      133375,
      133383,
      133391,
      133399,
      133407,
      133415,
      133423,
      133431,
      133439,
      133447,
      133455,
      133463,
      133471,
      133479,
      133487,
      133495,
      133503,
      133511,
      133519,
      133527,
      133535,
      133543
    ],
    "core.event_count": 24,
    "core.first_event_number": 133359,
    "core.last_event_number": 133543,
    "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_0721_df-s04-d3_dw_0_20251026T144456.hdf5"
    }
  ]
}Forming hist metadata
formed
{
  "name": "np02vd_raw_run040267_0721_df-s04-d3_dw_0_20251026T144456_reco_stage1_20251029T115749_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": 1761739070.0,
    "core.end_time": 1761739070.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_0721_df-s04-d3_dw_0_20251026T144456.hdf5"
    }
  ]
}