[13:20:14.675] INFO: *** Welcome to pxar ***
[13:20:14.675] INFO: *** Today: 2016/10/25
[13:20:14.696] INFO: *** Version: v1.9.0-818-g96727
[13:20:14.696] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//dacParameters35_C15.dat
[13:20:14.697] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:20:14.697] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//defaultMaskFile.dat
[13:20:14.697] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C15.dat
[13:20:14.773] INFO: clk: 4
[13:20:14.773] INFO: ctr: 4
[13:20:14.773] INFO: sda: 19
[13:20:14.773] INFO: tin: 9
[13:20:14.773] INFO: level: 15
[13:20:14.773] INFO: triggerdelay: 0
[13:20:14.773] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[13:20:14.773] INFO: Log level: INFO
[13:20:14.790] QUIET: Connection to board DTB_WREHUL opened.
[13:20:14.794] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 30
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREHUL
MAC address: 40D85511801E
Hostname: pixelDTB030
Comment:
------------------------------------------------------
[13:20:14.796] INFO: RPC call hashes of host and DTB match: 398089610
[13:20:16.328] INFO: DUT info:
[13:20:16.328] INFO: The DUT currently contains the following objects:
[13:20:16.328] INFO: 2 TBM Cores tbm08c (2 ON)
[13:20:16.328] INFO: TBM Core alpha (0): 7 registers set
[13:20:16.328] INFO: TBM Core beta (1): 7 registers set
[13:20:16.328] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[13:20:16.328] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[13:20:16.328] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[13:20:16.328] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[13:20:16.328] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[13:20:16.328] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[13:20:16.328] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[13:20:16.328] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[13:20:16.329] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[13:20:16.329] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[13:20:16.329] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[13:20:16.329] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[13:20:16.329] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[13:20:16.329] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[13:20:16.329] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[13:20:16.329] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[13:20:16.329] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[13:20:16.732] INFO: enter 'restricted' command line mode
[13:20:16.732] INFO: enter test to run
[13:20:21.389] INFO: test: PixelAlive no parameter change
[13:20:21.389] INFO: running: pixelalive
[13:20:21.398] INFO: ----------------------------------------------------------------------
[13:20:21.398] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[13:20:21.398] INFO: ----------------------------------------------------------------------
[13:20:21.717] INFO: Expecting 41600 events.
[13:20:26.056] INFO: 41600 events read in total (3621ms).
[13:20:26.226] INFO: Test took 4825ms.
[13:20:26.237] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:20:26.498] INFO: PixTestAlive::aliveTest() done
[13:20:26.498] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0
[13:20:26.531] INFO: enter test to run
[13:20:43.821] INFO: test: timing no parameter change
[13:20:43.821] INFO: running: timing
[13:20:43.843] INFO: ######################################################################
[13:20:43.850] INFO: PixTestTiming::doTest()
[13:20:43.850] INFO: ######################################################################
[13:20:43.850] INFO: ----------------------------------------------------------------------
[13:20:43.851] INFO: PixTestTiming::TBMPhaseScan()
[13:20:43.851] INFO: ----------------------------------------------------------------------
[13:26:30.834] INFO: TBM Phase Settings: 232
[13:26:30.834] INFO: 400MHz Phase: 2
[13:26:30.834] INFO: 160MHz Phase: 7
[13:26:30.834] INFO: Functional Phase Area: 3
[13:26:30.837] INFO: Test took 346987 ms.
[13:26:30.837] INFO: PixTestTiming::TBMPhaseScan() done.
[13:26:30.837] INFO: ----------------------------------------------------------------------
[13:26:30.838] INFO: PixTestTiming::ROCDelayScan()
[13:26:30.838] INFO: ----------------------------------------------------------------------
[13:28:39.116] INFO: ROC Delay Settings: 228
[13:28:39.116] INFO: ROC Header-Trailer/Token Delay: 11
[13:28:39.116] INFO: ROC Port 0 Delay: 4
[13:28:39.116] INFO: ROC Port 1 Delay: 4
[13:28:39.116] INFO: Functional ROC Area: 5
[13:28:39.119] INFO: Test took 128282 ms.
[13:28:39.119] INFO: PixTestTiming::ROCDelayScan() done.
[13:28:39.120] INFO: ----------------------------------------------------------------------
[13:28:39.120] INFO: PixTestTiming::TimingTest()
[13:28:39.120] INFO: ----------------------------------------------------------------------
[13:28:55.296] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:29:10.267] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:29:25.253] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:29:40.209] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:29:55.196] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:30:10.159] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:30:25.156] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:30:40.144] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:30:55.147] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:31:10.138] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:31:10.520] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:31:10.537] INFO: ----------------------------------------------------------------------
[13:31:10.537] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[13:31:10.537] INFO: ----------------------------------------------------------------------
[13:31:10.537] INFO: ----------------------------------------------------------------------
[13:31:10.537] INFO: Read back bit status: 1
[13:31:10.537] INFO: ----------------------------------------------------------------------
[13:31:10.537] INFO: ----------------------------------------------------------------------
[13:31:10.537] INFO: Timings are good!
[13:31:10.537] INFO: ----------------------------------------------------------------------
[13:31:10.537] INFO: Test took 151417 ms.
[13:31:10.537] INFO: PixTestTiming::TimingTest() done.
[13:31:10.549] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//tbmParameters_C0a.dat
[13:31:10.549] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:31:10.549] INFO: PixTestTiming::doTest took 626709 ms.
[13:31:10.549] INFO: PixTestTiming::doTest() done
[13:31:10.550] INFO: Write out TBMPhaseScan_0_V0
[13:31:10.550] INFO: Write out TBMPhaseScan_1_V0
[13:31:10.550] INFO: Write out CombinedTBMPhaseScan_V0
[13:31:10.575] INFO: Write out ROCDelayScan3_V0
[13:31:10.575] INFO: enter test to run
[13:32:05.393] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[13:32:05.393] INFO: running: highrate
[13:32:05.393] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[13:32:05.617] INFO: ----------------------------------------------------------------------
[13:32:05.617] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[13:32:05.617] INFO: ----------------------------------------------------------------------
[13:32:05.617] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[13:32:05.617] INFO: edge/corner pixel THR is adjusted
[13:32:05.617] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:32:06.576] INFO: Collecting data for 5 seconds...
[13:32:11.592] INFO: Done with hot pixel readout
[13:32:23.138] INFO: PixTest:: pg_setup set to default.
[13:32:23.139] INFO: 0 hot pixels found in step 0
[13:32:23.178] INFO: 0 hot pixels could not be trimmed and have been masked.
[13:32:23.181] INFO: PixTest::trimHotPixels() done
[13:32:23.181] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C0.dat
[13:32:23.187] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C1.dat
[13:32:23.193] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C2.dat
[13:32:23.199] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C3.dat
[13:32:23.204] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C4.dat
[13:32:23.210] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C5.dat
[13:32:23.215] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C6.dat
[13:32:23.220] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C7.dat
[13:32:23.225] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C8.dat
[13:32:23.230] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C9.dat
[13:32:23.236] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C10.dat
[13:32:23.241] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C11.dat
[13:32:23.246] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C12.dat
[13:32:23.251] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C13.dat
[13:32:23.257] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C14.dat
[13:32:23.262] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C15.dat
[13:32:23.267] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//defaultMaskFile.dat
[13:32:23.284] INFO: enter test to run
[13:32:44.024] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[13:32:44.024] INFO: running: highrate
[13:32:44.029] INFO: ----------------------------------------------------------------------
[13:32:44.029] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[13:32:44.029] INFO: ----------------------------------------------------------------------
[13:32:44.029] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[13:32:44.029] INFO: edge/corner pixel THR is adjusted
[13:32:44.029] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:32:44.987] INFO: Collecting data for 1 seconds...
[13:32:45.991] INFO: Done with hot pixel readout
[13:32:49.896] INFO: PixTest:: pg_setup set to default.
[13:32:49.896] INFO: 0 hot pixels found in step 0
[13:32:49.902] INFO: 0 hot pixels could not be trimmed and have been masked.
[13:32:49.998] INFO: PixTest::trimHotPixels() done
[13:32:49.998] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C0.dat
[13:32:50.008] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C1.dat
[13:32:50.013] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C2.dat
[13:32:50.019] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C3.dat
[13:32:50.024] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C4.dat
[13:32:50.029] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C5.dat
[13:32:50.035] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C6.dat
[13:32:50.040] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C7.dat
[13:32:50.045] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C8.dat
[13:32:50.050] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C9.dat
[13:32:50.055] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C10.dat
[13:32:50.061] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C11.dat
[13:32:50.066] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C12.dat
[13:32:50.071] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C13.dat
[13:32:50.076] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C14.dat
[13:32:50.081] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//trimParameters35_C15.dat
[13:32:50.086] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-A-17_FPIXTest-17C-FNAL-161024-1220-150V_2016-10-24_12h20m_1477329620/000_FPIXTest_p17//defaultMaskFile.dat
[13:32:50.103] INFO: enter test to run
[13:33:09.712] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[13:33:09.712] INFO: running: xray
[13:33:09.714] INFO: ----------------------------------------------------------------------
[13:33:09.714] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:33:09.714] INFO: ----------------------------------------------------------------------
[13:33:10.677] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:33:22.326] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[13:33:51.486] INFO: Resuming triggers.
[13:34:03.141] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[13:34:32.889] INFO: Resuming triggers.
[13:34:44.543] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[13:35:14.475] INFO: Resuming triggers.
[13:35:26.129] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[13:35:55.823] INFO: Resuming triggers.
[13:36:07.474] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[13:36:37.207] INFO: Resuming triggers.
[13:36:48.860] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[13:37:18.479] INFO: Resuming triggers.
[13:37:30.130] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[13:37:59.260] INFO: Resuming triggers.
[13:38:10.910] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[13:38:41.608] INFO: Resuming triggers.
[13:38:48.757] INFO: data taking finished, elapsed time: 100 seconds.
[13:39:07.579] INFO: PixTest:: pg_setup set to default.
[13:39:07.582] INFO: PixTestXray::doPhRun() done
[13:39:07.801] INFO: enter test to run
[13:39:51.333] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[13:39:51.333] INFO: running: xray
[13:39:51.335] INFO: ----------------------------------------------------------------------
[13:39:51.335] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:39:51.335] INFO: ----------------------------------------------------------------------
[13:39:52.309] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:39:59.320] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[13:40:30.167] INFO: Resuming triggers.
[13:40:37.186] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[13:41:07.441] INFO: Resuming triggers.
[13:41:14.457] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[13:41:44.567] INFO: Resuming triggers.
[13:41:51.582] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[13:42:21.871] INFO: Resuming triggers.
[13:42:28.884] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[13:42:59.066] INFO: Resuming triggers.
[13:43:06.080] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[13:43:36.133] INFO: Resuming triggers.
[13:43:43.143] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[13:44:13.238] INFO: Resuming triggers.
[13:44:20.254] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[13:44:50.407] INFO: Resuming triggers.
[13:44:57.419] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[13:45:27.576] INFO: Resuming triggers.
[13:45:34.590] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[13:46:04.708] INFO: Resuming triggers.
[13:46:11.721] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[13:46:41.940] INFO: Resuming triggers.
[13:46:48.955] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[13:47:19.039] INFO: Resuming triggers.
[13:47:26.054] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[13:47:56.296] INFO: Resuming triggers.
[13:48:03.313] INFO: run duration 97 seconds, buffer almost full (81%), pausing triggers.
[13:48:34.519] INFO: Resuming triggers.
[13:48:36.668] INFO: data taking finished, elapsed time: 100 seconds.
[13:48:46.467] INFO: PixTest:: pg_setup set to default.
[13:48:46.470] INFO: PixTestXray::doPhRun() done
[13:48:46.621] INFO: enter test to run
[13:49:35.482] INFO: test: HighRate no parameter change
[13:49:35.482] INFO: running: highrate
[13:49:35.501] INFO: ----------------------------------------------------------------------
[13:49:35.502] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[13:49:35.502] INFO: ----------------------------------------------------------------------
[13:49:35.648] INFO: Expecting 768 events.
[13:49:36.797] INFO: 768 events read in total (434ms).
[13:49:36.797] INFO: Test took 1283ms.
[13:49:37.600] INFO: Expecting 41600 events.
[13:49:40.615] INFO: 41600 events read in total (2488ms).
[13:49:40.616] INFO: Test took 3812ms.
[13:49:40.649] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:41.377] INFO: Expecting 41600 events.
[13:49:44.578] INFO: 41600 events read in total (2674ms).
[13:49:44.579] INFO: Test took 3914ms.
[13:49:44.611] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:45.338] INFO: Expecting 41600 events.
[13:49:48.598] INFO: 41600 events read in total (2733ms).
[13:49:48.599] INFO: Test took 3970ms.
[13:49:48.633] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:49.354] INFO: Expecting 41600 events.
[13:49:52.610] INFO: 41600 events read in total (2729ms).
[13:49:52.610] INFO: Test took 3961ms.
[13:49:52.643] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:53.371] INFO: Expecting 41600 events.
[13:49:56.579] INFO: 41600 events read in total (2682ms).
[13:49:56.579] INFO: Test took 3917ms.
[13:49:56.613] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:57.335] INFO: Expecting 41600 events.
[13:50:00.565] INFO: 41600 events read in total (2703ms).
[13:50:00.566] INFO: Test took 3936ms.
[13:50:00.599] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:01.323] INFO: Expecting 41600 events.
[13:50:04.606] INFO: 41600 events read in total (2756ms).
[13:50:04.607] INFO: Test took 3991ms.
[13:50:04.640] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:05.363] INFO: Expecting 41600 events.
[13:50:08.591] INFO: 41600 events read in total (2701ms).
[13:50:08.592] INFO: Test took 3935ms.
[13:50:08.626] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:09.349] INFO: Expecting 41600 events.
[13:50:12.632] INFO: 41600 events read in total (2756ms).
[13:50:12.633] INFO: Test took 3990ms.
[13:50:12.668] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:13.381] INFO: Expecting 41600 events.
[13:50:16.625] INFO: 41600 events read in total (2718ms).
[13:50:16.626] INFO: Test took 3937ms.
[13:50:16.660] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:17.381] INFO: Expecting 41600 events.
[13:50:20.617] INFO: 41600 events read in total (2709ms).
[13:50:20.618] INFO: Test took 3941ms.
[13:50:20.651] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:21.376] INFO: Expecting 41600 events.
[13:50:24.621] INFO: 41600 events read in total (2718ms).
[13:50:24.622] INFO: Test took 3953ms.
[13:50:24.657] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:25.371] INFO: Expecting 41600 events.
[13:50:28.597] INFO: 41600 events read in total (2699ms).
[13:50:28.598] INFO: Test took 3918ms.
[13:50:28.632] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:29.356] INFO: Expecting 41600 events.
[13:50:32.615] INFO: 41600 events read in total (2733ms).
[13:50:32.616] INFO: Test took 3967ms.
[13:50:32.649] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:33.373] INFO: Expecting 41600 events.
[13:50:36.684] INFO: 41600 events read in total (2785ms).
[13:50:36.685] INFO: Test took 4019ms.
[13:50:36.718] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:37.437] INFO: Expecting 41600 events.
[13:50:40.692] INFO: 41600 events read in total (2728ms).
[13:50:40.693] INFO: Test took 3957ms.
[13:50:40.726] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:41.451] INFO: Expecting 41600 events.
[13:50:44.706] INFO: 41600 events read in total (2728ms).
[13:50:44.707] INFO: Test took 3963ms.
[13:50:44.741] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:45.461] INFO: Expecting 41600 events.
[13:50:48.737] INFO: 41600 events read in total (2749ms).
[13:50:48.738] INFO: Test took 3979ms.
[13:50:48.771] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:49.483] INFO: Expecting 41600 events.
[13:50:52.675] INFO: 41600 events read in total (2665ms).
[13:50:52.676] INFO: Test took 3888ms.
[13:50:52.710] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:53.428] INFO: Expecting 41600 events.
[13:50:56.585] INFO: 41600 events read in total (2630ms).
[13:50:56.586] INFO: Test took 3857ms.
[13:50:56.620] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:56.985] INFO: enter test to run
[13:51:02.249] INFO: test: HighRate no parameter change
[13:51:02.249] INFO: running: highrate
[13:51:02.250] INFO: ----------------------------------------------------------------------
[13:51:02.250] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:51:02.250] INFO: ----------------------------------------------------------------------
[13:51:02.868] INFO: Expecting 208000 events.
[13:51:14.512] INFO: 208000 events read in total (11117ms).
[13:51:14.515] INFO: Test took 12257ms.
[13:51:14.657] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:51:14.912] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0
[13:51:14.912] INFO: number of red-efficiency pixels: 76 31 57 108 107 96 134 76 99 118 115 117 100 50 21 29
[13:51:14.912] INFO: number of X-ray hits detected: 62207 36259 59991 91678 94268 105430 108488 69681 75588 105045 103696 86149 89386 54954 21507 23074
[13:51:14.912] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:51:14.912] INFO: number of Vcal hits detected: 207923 207968 207943 207892 207890 207904 207863 207921 207901 207879 207884 207882 207897 207949 207930 207970
[13:51:14.912] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 99.9 100.0 99.9 100.0 100.0 99.9 99.9 99.9 100.0 100.0 100.0 100.0
[13:51:14.912] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 100.0 99.9 100.0 100.0 99.9 99.9 99.9 100.0 100.0 100.0 100.0
[13:51:14.912] INFO: X-ray hit rate [MHz/cm2]: 18.2 10.6 17.6 26.9 27.6 30.9 31.8 20.4 22.2 30.8 30.4 25.3 26.2 16.1 6.3 6.8
[13:51:14.912] INFO: PixTestHighRate::doXPixelAlive() done
[13:51:14.958] INFO: PixTest:: pg_setup set to default.
[13:51:14.974] INFO: enter test to run
[13:52:05.208] INFO: test: HighRate no parameter change
[13:52:05.209] INFO: running: highrate
[13:52:05.210] INFO: ----------------------------------------------------------------------
[13:52:05.210] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:52:05.210] INFO: ----------------------------------------------------------------------
[13:52:05.831] INFO: Expecting 208000 events.
[13:52:19.691] INFO: 208000 events read in total (13333ms).
[13:52:19.696] INFO: Test took 14478ms.
[13:52:19.981] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:52:20.285] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0
[13:52:20.285] INFO: number of red-efficiency pixels: 161 85 187 390 272 346 369 216 281 376 333 348 226 174 55 54
[13:52:20.286] INFO: number of X-ray hits detected: 130186 76661 125053 192701 197081 218615 224669 146516 157199 219415 215980 179088 187600 114681 45103 48005
[13:52:20.286] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:52:20.286] INFO: number of Vcal hits detected: 207831 207911 207803 207590 207713 207636 207604 207767 207706 207576 207648 207629 207758 207816 207892 207946
[13:52:20.286] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 99.9 99.8 99.9 99.8 99.8 99.9 99.9 99.8 99.8 99.8 99.9 99.9 100.0 100.0
[13:52:20.286] INFO: Vcal hit overall efficiency (%): 99.9 100.0 99.9 99.8 99.9 99.8 99.8 99.9 99.9 99.8 99.8 99.8 99.9 99.9 99.9 100.0
[13:52:20.286] INFO: X-ray hit rate [MHz/cm2]: 38.2 22.5 36.7 56.5 57.8 64.1 65.9 42.9 46.1 64.3 63.3 52.5 55.0 33.6 13.2 14.1
[13:52:20.286] INFO: PixTestHighRate::doXPixelAlive() done
[13:52:20.331] INFO: PixTest:: pg_setup set to default.
[13:52:20.345] INFO: enter test to run
[13:52:36.584] INFO: test: HighRate no parameter change
[13:52:36.584] INFO: running: highrate
[13:52:36.586] INFO: ----------------------------------------------------------------------
[13:52:36.586] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:52:36.586] INFO: ----------------------------------------------------------------------
[13:52:37.215] INFO: Expecting 208000 events.
[13:52:52.961] INFO: 208000 events read in total (15219ms).
[13:52:52.968] INFO: Test took 16371ms.
[13:52:53.419] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:52:53.776] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0
[13:52:53.776] INFO: number of red-efficiency pixels: 355 208 423 839 677 781 830 436 570 790 787 741 608 370 64 82
[13:52:53.776] INFO: number of X-ray hits detected: 196258 115124 189279 290696 296942 330945 340915 221499 239009 331243 327710 271658 284145 173974 68519 72919
[13:52:53.776] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:52:53.776] INFO: number of Vcal hits detected: 207605 207771 207509 207003 207227 207095 207023 207505 207341 207055 207074 207149 207313 207563 207887 207918
[13:52:53.776] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.6 99.7 99.6 99.6 99.8 99.7 99.6 99.6 99.6 99.7 99.8 100.0 100.0
[13:52:53.776] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.5 99.6 99.6 99.5 99.8 99.7 99.5 99.6 99.6 99.7 99.8 99.9 100.0
[13:52:53.776] INFO: X-ray hit rate [MHz/cm2]: 57.5 33.7 55.5 85.2 87.0 97.0 99.9 64.9 70.1 97.1 96.1 79.6 83.3 51.0 20.1 21.4
[13:52:53.777] INFO: PixTestHighRate::doXPixelAlive() done
[13:52:53.826] INFO: PixTest:: pg_setup set to default.
[13:52:53.840] INFO: enter test to run
[13:53:12.776] INFO: test: exit no parameter change
[13:53:13.274] QUIET: Connection to board 30 closed.
[13:53:13.288] INFO: pXar: this is the end, my friend