Jobsub ID 236577.65@dunegpschedd02.fnal.gov
Jobscript log (last 10,000 characters)
<OmnibusSigProc:anode0sigproc0> EOS at call=45 anode=0 
[11:20:25.057] D [  glue  ] <FrameFanin:nfsp> EOS at call=45 with 8 
[11:20:25.057] D [  glue  ] frame sink sees EOS
[11:20:25.057] D [ pgraph ] <Pgrapher:> graph execution complete 
[11:20:25.057] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 11.01 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 9.11 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 9.05 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 8.64 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 8.35 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 8.27 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 8.18 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 7.98 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.26 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.26 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.26 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.25 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::Gen::FrameFanin : 0.02 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::Gen::Retagger : 0.01 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::Gen::DumpFrames : 0 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[11:20:25.057] I [ timer  ] Timer: WireCell::Gen::FrameFanout : 0 sec
[11:20:25.057] I [ timer  ] Timer: wcls::RawFrameSource : 0 sec
[11:20:25.057] I [ timer  ] Timer: wcls::FrameSaver : 0 sec
[11:20:25.057] I [ timer  ] Timer: Total node execution : 71.66000155359507 sec
wclsFrameSaver saving cooked to 10000 ticks
wclsFrameSaver: saving 59577 traces tagged "gauss"
FrameSaver: q=1.40694e+07 n=1178346 tag=gauss
wclsFrameSaver: saving 77775 traces tagged "wiener"
FrameSaver: q=1.53604e+07 n=1111476 tag=wiener
0 X, 0 U, 0 V bad channels
Finding XUV coincidences...
C:0 T:0 3564 XUs and 2916 XVs -> 123 XUVs
C:0 T:1 3555 XUs and 3127 XVs -> 163 XUVs
C:0 T:2 3219 XUs and 3127 XVs -> 204 XUVs
C:0 T:3 17296 XUs and 19201 XVs -> 1419 XUVs
C:0 T:4 941 XUs and 1347 XVs -> 64 XUVs
C:0 T:5 936 XUs and 870 XVs -> 43 XUVs
C:0 T:6 5923 XUs and 5597 XVs -> 370 XUVs
C:0 T:7 741 XUs and 886 XVs -> 60 XUVs
C:0 T:8 659 XUs and 956 XVs -> 44 XUVs
C:0 T:9 1886 XUs and 1682 XVs -> 80 XUVs
C:0 T:10 334 XUs and 549 XVs -> 14 XUVs
C:0 T:11 589 XUs and 784 XVs -> 40 XUVs
C:0 T:12 774 XUs and 1132 XVs -> 43 XUVs
C:0 T:13 862 XUs and 1315 XVs -> 88 XUVs
C:0 T:14 1677 XUs and 1674 XVs -> 85 XUVs
C:0 T:15 1049 XUs and 1306 XVs -> 79 XUVs
2919 XUVs total
1733 collection wire objects
2919 potential space points
Neighbour search...
67961 tests to find 20136 neighbours
Iterating with no regularization...
Begin: 3.40471e+09
0 3.16012e+09
1 3.14218e+09
2 3.14138e+09
Now with regularization...
Begin: 3.08448e+09
0 3.08422e+09
03-Nov-2025 11:21:35 CET  Closed output file "np02vd_raw_run040346_3113_df-s04-d3_dw_0_20251103T073524_reco_stage1_20251103T102135_keepup.root"
==================================================================================================================================
TimeTracker printout (sec)                          Min           Avg           Max         Median          RMS         nEvts   
==================================================================================================================================
Full event                                        116.985       180.424       349.008       158.087       53.4239        23     
----------------------------------------------------------------------------------------------------------------------------------
source:HDF5RawInput3(read)                       6.801e-05     8.942e-05    0.000139799    8.38e-05     1.92593e-05      23     
produce:tpcrawdecoder:PDVDTPCReader               14.1058       15.0594       21.0871       14.8138       1.35206        23     
produce:triggerrawdecoder:PDVDTriggerReader4     0.475449      0.500872      0.622157      0.496378      0.0279969       23     
produce:pdvddaphne:DAPHNEReaderPDVD             0.000377969   0.000454678   0.000752507   0.000438789   7.3987e-05       23     
produce:ophit:OpHitFinder                        6.968e-05    0.000128866   0.000562558   0.00010286    9.88958e-05      23     
produce:opflash:OpFlashFinderVerticalDrift       5.556e-05    8.18829e-05   0.000323849    6.251e-05    5.69204e-05      23     
produce:wclsdatavd:WireCellToolkit                61.4771       85.8564       130.283       77.3518       17.5065        23     
produce:gaushit:GausHitFinder                    0.991657       1.45756       2.31158       1.49147       0.30214        23     
produce:nhitsfilter:NumberOfHitsFilter          0.000268179   0.000386412   0.000902377   0.000350979   0.000134447      23     
produce:reco3d:SpacePointSolver                   8.07142       15.1885       29.4869       14.4458       4.76647        23     
produce:hitpdune:DisambigFromSpacePoints          0.12694      0.255345      0.559347      0.224531      0.105988        23     
produce:pandora:StandardPandora                   23.5686       52.9776       191.616       39.4017       39.3712        23     
produce:pandoraTrack:LArPandoraTrackCreation     0.474572       1.50534       6.05191       1.22924       1.07679        23     
produce:pandoraGnocalo:GnocchiCalorimetry        0.0244607     0.0383299     0.0533464     0.0380464    0.00842272       23     
[art]:TriggerResults:TriggerResultInserter       2.128e-05    2.94795e-05    7.594e-05     2.623e-05    1.0566e-05       23     
end_path:out1:RootOutput                         4.65e-06     9.61996e-06     3.6e-05      9.59e-06     6.69379e-06      23     
end_path:out1:RootOutput(write)                   5.38367        7.52         10.6021       7.17038       1.38001        23     
==================================================================================================================================
====================================================================================================
MemoryTracker summary (base-10 MB units used)
  Peak virtual memory usage (VmPeak)  : 8131.21 MB
  Peak resident set size usage (VmHWM): 6069.88 MB
  Details saved in: 'mem.db'
====================================================================================================
Art has completed and will exit with status 0.
Output files:
\tReco: np02vd_raw_run040346_3113_df-s04-d3_dw_0_20251103T073524_reco_stage1_20251103T102135_keepup.root
\tHists: np02vd_raw_run040346_3113_df-s04-d3_dw_0_20251103T073524_reco_stage1_20251103T102135_keepup_hists.root
Forming reco metadata
Successfully opened file np02vd_raw_run040346_3113_df-s04-d3_dw_0_20251103T073524_reco_stage1_20251103T102135_keepup.root
Ran successfully
{
  "name": "np02vd_raw_run040346_3113_df-s04-d3_dw_0_20251103T073524_reco_stage1_20251103T102135_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": 1762165296.0,
    "core.end_time": 1762165296.0,
    "core.events": [
      287311,
      287315,
      287319,
      287323,
      287327,
      287331,
      287335,
      287339,
      287343,
      287347,
      287351,
      287355,
      287359,
      287363,
      287367,
      287371,
      287375,
      287379,
      287383,
      287387,
      287391,
      287395,
      287399
    ],
    "core.event_count": 23,
    "core.first_event_number": 287311,
    "core.last_event_number": 287399,
    "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_3113_df-s04-d3_dw_0_20251103T073524.hdf5"
    }
  ]
}Forming hist metadata
formed
{
  "name": "np02vd_raw_run040346_3113_df-s04-d3_dw_0_20251103T073524_reco_stage1_20251103T102135_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": 1762165296.0,
    "core.end_time": 1762165296.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_3113_df-s04-d3_dw_0_20251103T073524.hdf5"
    }
  ]
}