Jobsub ID 236694.6@dunegpschedd02.fnal.gov
Jobscript log (last 10,000 characters)
3 
[18:18:14.824] D [sigproc ] <OmnibusSigProc:anode0sigproc0> EOS at call=43 anode=0 
[18:18:14.824] D [  glue  ] <FrameFanin:nfsp> EOS at call=43 with 8 
[18:18:14.824] D [  glue  ] frame sink sees EOS
[18:18:14.824] D [ pgraph ] <Pgrapher:> graph execution complete 
[18:18:14.824] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 11.68 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 10.02 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 9.68 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 9.67 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 9.65 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 9.62 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 9.53 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::SigProc::OmnibusSigProc : 9.41 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.35 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.35 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.35 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::Aux::Resampler : 0.34 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::Gen::FrameFanin : 0.02 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::Gen::Retagger : 0.02 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0.01 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::Gen::DumpFrames : 0 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::SigProc::ChannelSelector : 0 sec
[18:18:14.824] I [ timer  ] Timer: WireCell::Gen::FrameFanout : 0 sec
[18:18:14.824] I [ timer  ] Timer: wcls::RawFrameSource : 0 sec
[18:18:14.824] I [ timer  ] Timer: wcls::FrameSaver : 0 sec
[18:18:14.824] I [ timer  ] Timer: Total node execution : 80.73000021278858 sec
wclsFrameSaver saving cooked to 10000 ticks
wclsFrameSaver: saving 47415 traces tagged "gauss"
FrameSaver: q=1.31561e+07 n=988538 tag=gauss
wclsFrameSaver: saving 60755 traces tagged "wiener"
FrameSaver: q=1.42404e+07 n=931174 tag=wiener
0 X, 0 U, 0 V bad channels
Finding XUV coincidences...
C:0 T:0 4870 XUs and 5727 XVs -> 278 XUVs
C:0 T:1 188 XUs and 232 XVs -> 9 XUVs
C:0 T:2 24238 XUs and 26964 XVs -> 1731 XUVs
C:0 T:3 127 XUs and 139 XVs -> 6 XUVs
C:0 T:4 363 XUs and 517 XVs -> 23 XUVs
C:0 T:5 852 XUs and 1051 XVs -> 40 XUVs
C:0 T:6 649 XUs and 999 XVs -> 69 XUVs
C:0 T:7 1894 XUs and 1960 XVs -> 89 XUVs
C:0 T:8 776 XUs and 1346 XVs -> 72 XUVs
C:0 T:9 471 XUs and 450 XVs -> 30 XUVs
C:0 T:10 573 XUs and 932 XVs -> 45 XUVs
C:0 T:11 548 XUs and 858 XVs -> 37 XUVs
C:0 T:12 1001 XUs and 689 XVs -> 25 XUVs
C:0 T:13 1863 XUs and 2847 XVs -> 123 XUVs
C:0 T:14 469 XUs and 279 XVs -> 15 XUVs
C:0 T:15 1410 XUs and 1741 XVs -> 89 XUVs
2681 XUVs total
1706 collection wire objects
2681 potential space points
Neighbour search...
63481 tests to find 16248 neighbours
Iterating with no regularization...
Begin: 5.91435e+10
0 5.84595e+10
1 5.84428e+10
Now with regularization...
Begin: 5.79236e+10
0 5.79234e+10
03-Nov-2025 18:19:13 GMT  Closed output file "np02vd_raw_run040346_2417_df-s04-d0_dw_0_20251102T215414_reco_stage1_20251103T181913_keepup.root"
==================================================================================================================================
TimeTracker printout (sec)                          Min           Avg           Max         Median          RMS         nEvts   
==================================================================================================================================
Full event                                        176.182       806.55        8449.69       438.724       1674.73        22     
----------------------------------------------------------------------------------------------------------------------------------
source:HDF5RawInput3(read)                      4.1801e-05    6.1557e-05    0.000150242    5.087e-05    2.48323e-05      22     
produce:tpcrawdecoder:PDVDTPCReader               75.4315       284.021       500.623       301.925       108.472        22     
produce:triggerrawdecoder:PDVDTriggerReader4     0.869757       1.99442       3.99478       1.90952      0.712767        22     
produce:pdvddaphne:DAPHNEReaderPDVD             0.000323318   0.000366996   0.00063347    0.000354904   6.07401e-05      22     
produce:ophit:OpHitFinder                       4.3896e-05    7.37299e-05   0.000463692   4.90665e-05   8.59461e-05      22     
produce:opflash:OpFlashFinderVerticalDrift      3.4664e-05    5.1611e-05    0.000262268   3.95065e-05   4.63983e-05      22     
produce:wclsdatavd:WireCellToolkit                48.8701       79.8467       184.351       70.1259       33.9905        22     
produce:gaushit:GausHitFinder                    0.793562       1.37853       4.59228       1.2886       0.745572        22     
produce:nhitsfilter:NumberOfHitsFilter          0.000202051   0.000386502   0.00113509    0.000356979   0.000179318      22     
produce:reco3d:SpacePointSolver                   6.85071       15.2617       88.4242       12.0686       16.3267        22     
produce:hitpdune:DisambigFromSpacePoints         0.0941949      0.31838       2.48396      0.204859      0.480528        22     
produce:pandora:StandardPandora                   13.8793       417.562       8083.58       24.963        1674.46        22     
produce:pandoraTrack:LArPandoraTrackCreation     0.431142       2.00237       20.6961       1.1128        4.10335        22     
produce:pandoraGnocalo:GnocchiCalorimetry        0.0147894     0.0296215     0.0904918     0.0266834     0.0144628       22     
[art]:TriggerResults:TriggerResultInserter      1.4781e-05    2.06298e-05   6.1207e-05    1.68925e-05   9.77696e-06      22     
end_path:out1:RootOutput                         7.125e-06    9.22586e-06   2.5055e-05    8.3425e-06    3.58674e-06      22     
end_path:out1:RootOutput(write)                   3.3951        4.10027       7.23445       3.84401      0.843223        22     
==================================================================================================================================
====================================================================================================
MemoryTracker summary (base-10 MB units used)
  Peak virtual memory usage (VmPeak)  : 8053.74 MB
  Peak resident set size usage (VmHWM): 6019.53 MB
  Details saved in: 'mem.db'
====================================================================================================
Art has completed and will exit with status 0.
Output files:
\tReco: np02vd_raw_run040346_2417_df-s04-d0_dw_0_20251102T215414_reco_stage1_20251103T181913_keepup.root
\tHists: np02vd_raw_run040346_2417_df-s04-d0_dw_0_20251102T215414_reco_stage1_20251103T181917_keepup_hists.root
Forming reco metadata
Successfully opened file np02vd_raw_run040346_2417_df-s04-d0_dw_0_20251102T215414_reco_stage1_20251103T181913_keepup.root
Ran successfully
{
  "name": "np02vd_raw_run040346_2417_df-s04-d0_dw_0_20251102T215414_reco_stage1_20251103T181913_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": 1762193957.0,
    "core.end_time": 1762193957.0,
    "core.events": [
      223104,
      223108,
      223112,
      223116,
      223120,
      223124,
      223128,
      223132,
      223136,
      223140,
      223144,
      223148,
      223152,
      223156,
      223160,
      223164,
      223168,
      223172,
      223176,
      223180,
      223184,
      223188
    ],
    "core.event_count": 22,
    "core.first_event_number": 223104,
    "core.last_event_number": 223188,
    "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_2417_df-s04-d0_dw_0_20251102T215414.hdf5"
    }
  ]
}Forming hist metadata
formed
{
  "name": "np02vd_raw_run040346_2417_df-s04-d0_dw_0_20251102T215414_reco_stage1_20251103T181917_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": 1762193957.0,
    "core.end_time": 1762193957.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_2417_df-s04-d0_dw_0_20251102T215414.hdf5"
    }
  ]
}