Jobsub ID 236577.13@dunegpschedd02.fnal.gov
Jobscript log (last 10,000 characters)
ibusSigProc:anode0sigproc0> EOS at call=45 anode=0 
[10:58:13.731] D [  glue  ] <FrameFanin:nfsp> EOS at call=45 with 8 
[10:58:13.731] D [  glue  ] frame sink sees EOS
[10:58:13.731] D [ pgraph ] <Pgrapher:> graph execution complete 
[10:58:13.731] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 40.54 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 38.5 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 13.26 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 12.06 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 10.15 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 10.03 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 9.56 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 9.4 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.43 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.42 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.42 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.4 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.02 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::Gen::FrameFanin : 0.01 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::Gen::Retagger : 0.01 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::Gen::DumpFrames : 0 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[10:58:13.731] I [ timer  ] Timer: WireCell::Gen::FrameFanout : 0 sec
[10:58:13.731] I [ timer  ] Timer: wcls::RawFrameSource : 0 sec
[10:58:13.731] I [ timer  ] Timer: wcls::FrameSaver : 0 sec
[10:58:13.731] I [ timer  ] Timer: Total node execution : 145.2300009392202 sec
wclsFrameSaver saving cooked to 10000 ticks
wclsFrameSaver: saving 51321 traces tagged "gauss"
FrameSaver: q=7.833e+07 n=1827640 tag=gauss
wclsFrameSaver: saving 65840 traces tagged "wiener"
FrameSaver: q=8.12864e+07 n=1776458 tag=wiener
0 X, 0 U, 0 V bad channels
Finding XUV coincidences...
C:0 T:0 665 XUs and 347 XVs -> 5 XUVs
C:0 T:1 88187 XUs and 120735 XVs -> 7856 XUVs
C:0 T:2 571 XUs and 1510 XVs -> 52 XUVs
C:0 T:3 52741 XUs and 67304 XVs -> 3064 XUVs
C:0 T:4 334 XUs and 356 XVs -> 23 XUVs
C:0 T:5 1029 XUs and 552 XVs -> 77 XUVs
C:0 T:6 1021 XUs and 1067 XVs -> 40 XUVs
C:0 T:7 1669 XUs and 1416 XVs -> 187 XUVs
C:0 T:8 1939 XUs and 1854 XVs -> 107 XUVs
C:0 T:9 803 XUs and 921 XVs -> 125 XUVs
C:0 T:10 635 XUs and 699 XVs -> 33 XUVs
C:0 T:11 750 XUs and 608 XVs -> 39 XUVs
C:0 T:12 525 XUs and 537 XVs -> 69 XUVs
C:0 T:13 925 XUs and 1110 XVs -> 46 XUVs
C:0 T:14 289 XUs and 365 XVs -> 26 XUVs
C:0 T:15 120 XUs and 119 XVs -> 6 XUVs
11755 XUVs total
4386 collection wire objects
11755 potential space points
Neighbour search...
516529 tests to find 107446 neighbours
Iterating with no regularization...
Begin: 1.95274e+12
0 1.8621e+12
1 1.85639e+12
2 1.85607e+12
Now with regularization...
Begin: 1.84866e+12
0 1.84861e+12
03-Nov-2025 11:04:21 CET  Closed output file "np02vd_raw_run040346_3082_df-s04-d2_dw_0_20251103T071127_reco_stage1_20251103T100421_keepup.root"
==================================================================================================================================
TimeTracker printout (sec)                          Min           Avg           Max         Median          RMS         nEvts   
==================================================================================================================================
Full event                                        103.686       183.591       757.98        132.014       147.905        23     
----------------------------------------------------------------------------------------------------------------------------------
source:HDF5RawInput3(read)                       6.706e-05    0.000108111   0.000321664   8.1851e-05    5.48441e-05      23     
produce:tpcrawdecoder:PDVDTPCReader               14.0809       14.8988       16.7977       14.6054      0.735728        23     
produce:triggerrawdecoder:PDVDTriggerReader4     0.476232      0.512837      0.610225      0.505349      0.0295547       23     
produce:pdvddaphne:DAPHNEReaderPDVD             0.000377315   0.000484186   0.00109087    0.000428285   0.000154819      23     
produce:ophit:OpHitFinder                       7.1261e-05    0.000154022   0.000808351   0.000124851   0.000145373      23     
produce:opflash:OpFlashFinderVerticalDrift       5.254e-05    8.73902e-05   0.000460436   7.0881e-05    8.01758e-05      23     
produce:wclsdatavd:WireCellToolkit                57.9296       79.5533       148.853       74.4964       23.4778        23     
produce:gaushit:GausHitFinder                    0.749462       1.23559       2.36387       1.09641      0.395387        23     
produce:nhitsfilter:NumberOfHitsFilter          0.000191452   0.000321683   0.000499197   0.000306864   8.26731e-05      23     
produce:reco3d:SpacePointSolver                   7.23822       13.3083       25.9491       12.4814       4.31438        23     
produce:hitpdune:DisambigFromSpacePoints          0.10322      0.224405      0.634927      0.206912      0.115675        23     
produce:pandora:StandardPandora                   13.1722        65.82        565.301       26.9866       124.032        23     
produce:pandoraTrack:LArPandoraTrackCreation     0.299719       1.06783       3.64392       0.84529      0.682109        23     
produce:pandoraGnocalo:GnocchiCalorimetry        0.0210553     0.037241      0.0569661     0.0394756    0.00894252       23     
[art]:TriggerResults:TriggerResultInserter       1.525e-05    2.29964e-05   6.4511e-05     1.927e-05    1.12013e-05      23     
end_path:out1:RootOutput                          3.3e-06     7.92626e-06   2.2751e-05     7.721e-06    3.72242e-06      23     
end_path:out1:RootOutput(write)                   4.88927       6.88665       10.7299       6.73502       1.35112        23     
==================================================================================================================================
====================================================================================================
MemoryTracker summary (base-10 MB units used)
  Peak virtual memory usage (VmPeak)  : 7333.38 MB
  Peak resident set size usage (VmHWM): 5242.93 MB
  Details saved in: 'mem.db'
====================================================================================================
Art has completed and will exit with status 0.
Output files:
\tReco: np02vd_raw_run040346_3082_df-s04-d2_dw_0_20251103T071127_reco_stage1_20251103T100421_keepup.root
\tHists: np02vd_raw_run040346_3082_df-s04-d2_dw_0_20251103T071127_reco_stage1_20251103T100421_keepup_hists.root
Forming reco metadata
Successfully opened file np02vd_raw_run040346_3082_df-s04-d2_dw_0_20251103T071127_reco_stage1_20251103T100421_keepup.root
Ran successfully
{
  "name": "np02vd_raw_run040346_3082_df-s04-d2_dw_0_20251103T071127_reco_stage1_20251103T100421_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": 1762164262.0,
    "core.end_time": 1762164262.0,
    "core.events": [
      284578,
      284582,
      284586,
      284590,
      284594,
      284598,
      284602,
      284606,
      284610,
      284614,
      284618,
      284622,
      284626,
      284630,
      284634,
      284638,
      284642,
      284646,
      284650,
      284654,
      284658,
      284662,
      284666
    ],
    "core.event_count": 23,
    "core.first_event_number": 284578,
    "core.last_event_number": 284666,
    "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_3082_df-s04-d2_dw_0_20251103T071127.hdf5"
    }
  ]
}Forming hist metadata
formed
{
  "name": "np02vd_raw_run040346_3082_df-s04-d2_dw_0_20251103T071127_reco_stage1_20251103T100421_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": 1762164262.0,
    "core.end_time": 1762164262.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_3082_df-s04-d2_dw_0_20251103T071127.hdf5"
    }
  ]
}