Jobsub ID 242287.2@dunegpschedd01.fnal.gov
Jobscript log (last 10,000 characters)
roc:anode0sigproc0> EOS at call=45 anode=0 
[12:56:03.386] D [  glue  ] <FrameFanin:nfsp> EOS at call=45 with 8 
[12:56:03.386] D [  glue  ] frame sink sees EOS
[12:56:03.386] D [ pgraph ] <Pgrapher:> graph execution complete 
[12:56:03.386] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 12 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 11.04 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 9.43 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 7.8 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 7.77 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 7.36 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 7.25 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 6.72 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.28 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.27 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.27 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.26 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::Gen::FrameFanin : 0.03 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.02 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::Gen::Retagger : 0.01 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::Gen::DumpFrames : 0 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[12:56:03.386] I [ timer  ] Timer: WireCell::Gen::FrameFanout : 0 sec
[12:56:03.386] I [ timer  ] Timer: wcls::RawFrameSource : 0 sec
[12:56:03.386] I [ timer  ] Timer: wcls::FrameSaver : 0 sec
[12:56:03.386] I [ timer  ] Timer: Total node execution : 70.53000037372112 sec
wclsFrameSaver saving cooked to 10000 ticks
wclsFrameSaver: saving 42363 traces tagged "gauss"
FrameSaver: q=3.21936e+07 n=1365763 tag=gauss
wclsFrameSaver: saving 55076 traces tagged "wiener"
FrameSaver: q=3.35176e+07 n=1320253 tag=wiener
0 X, 0 U, 0 V bad channels
Finding XUV coincidences...
C:0 T:0 809 XUs and 567 XVs -> 195 XUVs
C:0 T:1 23201 XUs and 24951 XVs -> 1899 XUVs
C:0 T:2 1205 XUs and 1878 XVs -> 106 XUVs
C:0 T:3 150 XUs and 190 XVs -> 5 XUVs
C:0 T:4 2610 XUs and 2626 XVs -> 322 XUVs
C:0 T:5 2134 XUs and 1652 XVs -> 529 XUVs
C:0 T:6 179 XUs and 265 XVs -> 7 XUVs
C:0 T:7 353 XUs and 439 XVs -> 11 XUVs
C:0 T:8 5961 XUs and 9673 XVs -> 1870 XUVs
C:0 T:9 14507 XUs and 17789 XVs -> 2309 XUVs
C:0 T:10 3531 XUs and 6570 XVs -> 1989 XUVs
C:0 T:11 1362 XUs and 1879 XVs -> 317 XUVs
C:0 T:12 6403 XUs and 7059 XVs -> 429 XUVs
C:0 T:13 33 XUs and 59 XVs -> 1 XUVs
C:0 T:14 1101 XUs and 1001 XVs -> 43 XUVs
C:0 T:15 379 XUs and 636 XVs -> 113 XUVs
10145 XUVs total
2356 collection wire objects
10145 potential space points
Neighbour search...
1196209 tests to find 494036 neighbours
Iterating with no regularization...
Begin: 6.85882e+10
0 6.70997e+10
1 6.70263e+10
2 6.70253e+10
Now with regularization...
Begin: 6.61466e+10
0 6.61454e+10
03-Nov-2025 12:57:02 GMT  Closed output file "np02vd_raw_run040346_3112_df-s04-d1_dw_0_20251103T073610_reco_stage1_20251103T125702_keepup.root"
==================================================================================================================================
TimeTracker printout (sec)                          Min           Avg           Max         Median          RMS         nEvts   
==================================================================================================================================
Full event                                        136.772       243.553       799.852       210.393       144.947        23     
----------------------------------------------------------------------------------------------------------------------------------
source:HDF5RawInput3(read)                      0.000110338   0.000155276   0.000314853   0.000149121   4.25934e-05      23     
produce:tpcrawdecoder:PDVDTPCReader               23.9407       27.036        63.7101       25.2574       7.88536        23     
produce:triggerrawdecoder:PDVDTriggerReader4     0.675975      0.719652      0.852451      0.707041      0.0428668       23     
produce:pdvddaphne:DAPHNEReaderPDVD             0.000338817   0.000533906   0.00115447    0.000490674   0.000155113      23     
produce:ophit:OpHitFinder                       7.9489e-05    0.000210716   0.00105637    0.000151615   0.000200859      23     
produce:opflash:OpFlashFinderVerticalDrift      4.4424e-05    0.000125921   0.000678958   8.9849e-05    0.000124048      23     
produce:wclsdatavd:WireCellToolkit                66.2721       98.3358       183.445       93.0739       29.884         23     
produce:gaushit:GausHitFinder                     1.17429       1.85757       2.58237       1.84665      0.400247        23     
produce:nhitsfilter:NumberOfHitsFilter          0.000348325   0.000462273   0.000797521   0.000443875   9.52316e-05      23     
produce:reco3d:SpacePointSolver                   9.53802       17.0532       26.6978       17.6762       4.89698        23     
produce:hitpdune:DisambigFromSpacePoints         0.183121      0.355529      0.663711      0.341179      0.133239        23     
produce:pandora:StandardPandora                   23.5216       89.7846       616.406       43.4873       123.735        23     
produce:pandoraTrack:LArPandoraTrackCreation     0.854609       2.22561       3.75891       2.03974      0.777997        23     
produce:pandoraGnocalo:GnocchiCalorimetry        0.0314912     0.0502902     0.0745136     0.0516932     0.009647        23     
[art]:TriggerResults:TriggerResultInserter      4.3492e-05     7.674e-05    0.000155513   7.7346e-05    2.17052e-05      23     
end_path:out1:RootOutput                         7.684e-06    1.58471e-05   4.0937e-05    1.5089e-05    6.5531e-06       23     
end_path:out1:RootOutput(write)                   5.0325        6.01193       7.89442       5.93095      0.614304        23     
==================================================================================================================================
====================================================================================================
MemoryTracker summary (base-10 MB units used)
  Peak virtual memory usage (VmPeak)  : 8941.5 MB
  Peak resident set size usage (VmHWM): 6856.6 MB
  Details saved in: 'mem.db'
====================================================================================================
Art has completed and will exit with status 0.
Output files:
\tReco: np02vd_raw_run040346_3112_df-s04-d1_dw_0_20251103T073610_reco_stage1_20251103T125702_keepup.root
\tHists: np02vd_raw_run040346_3112_df-s04-d1_dw_0_20251103T073610_reco_stage1_20251103T125702_keepup_hists.root
Forming reco metadata
Successfully opened file np02vd_raw_run040346_3112_df-s04-d1_dw_0_20251103T073610_reco_stage1_20251103T125702_keepup.root
Ran successfully
{
  "name": "np02vd_raw_run040346_3112_df-s04-d1_dw_0_20251103T073610_reco_stage1_20251103T125702_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": 1762174623.0,
    "core.end_time": 1762174623.0,
    "core.events": [
      287397,
      287401,
      287405,
      287409,
      287413,
      287417,
      287421,
      287425,
      287429,
      287433,
      287437,
      287441,
      287445,
      287449,
      287453,
      287457,
      287461,
      287465,
      287469,
      287473,
      287477,
      287481,
      287485
    ],
    "core.event_count": 23,
    "core.first_event_number": 287397,
    "core.last_event_number": 287485,
    "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_3112_df-s04-d1_dw_0_20251103T073610.hdf5"
    }
  ]
}Forming hist metadata
formed
{
  "name": "np02vd_raw_run040346_3112_df-s04-d1_dw_0_20251103T073610_reco_stage1_20251103T125702_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": 1762174623.0,
    "core.end_time": 1762174623.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_3112_df-s04-d1_dw_0_20251103T073610.hdf5"
    }
  ]
}