[10:12:50.819] INFO: *** Welcome to pxar ***
[10:12:50.819] INFO: *** Today: 2016/05/13
[10:12:50.839] INFO: *** Version: v1.9.0-796-gef167-dirty
[10:12:50.839] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//dacParameters35_C15.dat
[10:12:50.839] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:12:50.840] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//defaultMaskFile.dat
[10:12:50.840] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C15.dat
[10:12:50.908] INFO: clk: 4
[10:12:50.908] INFO: ctr: 4
[10:12:50.908] INFO: sda: 19
[10:12:50.908] INFO: tin: 9
[10:12:50.908] INFO: level: 15
[10:12:50.908] INFO: triggerdelay: 0
[10:12:50.908] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[10:12:50.908] INFO: Log level: INFO
[10:12:50.927] QUIET: Connection to board DTB_WREKRL opened.
[10:12:50.930] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 33
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREKRL
MAC address: 40D855118021
Hostname: pixelDTB033
Comment:
------------------------------------------------------
[10:12:50.933] INFO: RPC call hashes of host and DTB match: 398089610
[10:12:52.461] INFO: DUT info:
[10:12:52.461] INFO: The DUT currently contains the following objects:
[10:12:52.461] INFO: 2 TBM Cores tbm08c (2 ON)
[10:12:52.461] INFO: TBM Core alpha (0): 7 registers set
[10:12:52.461] INFO: TBM Core beta (1): 7 registers set
[10:12:52.461] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[10:12:52.461] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[10:12:52.461] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[10:12:52.461] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[10:12:52.461] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[10:12:52.461] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[10:12:52.461] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[10:12:52.461] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[10:12:52.461] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[10:12:52.461] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[10:12:52.461] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[10:12:52.461] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[10:12:52.461] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[10:12:52.462] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[10:12:52.462] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[10:12:52.462] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[10:12:52.462] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[10:12:52.865] INFO: enter 'restricted' command line mode
[10:12:52.865] INFO: enter test to run
[10:12:57.565] INFO: test: timing no parameter change
[10:12:57.566] INFO: running: timing
[10:12:57.575] INFO: ######################################################################
[10:12:57.575] INFO: PixTestTiming::doTest()
[10:12:57.575] INFO: ######################################################################
[10:12:57.575] INFO: ----------------------------------------------------------------------
[10:12:57.575] INFO: PixTestTiming::TBMPhaseScan()
[10:12:57.575] INFO: ----------------------------------------------------------------------
[10:19:27.479] INFO: TBM Phase Settings: 232
[10:19:27.479] INFO: 400MHz Phase: 2
[10:19:27.479] INFO: 160MHz Phase: 7
[10:19:27.479] INFO: Functional Phase Area: 3
[10:19:27.502] INFO: Test took 389927 ms.
[10:19:27.502] INFO: PixTestTiming::TBMPhaseScan() done.
[10:19:27.502] INFO: ----------------------------------------------------------------------
[10:19:27.502] INFO: PixTestTiming::ROCDelayScan()
[10:19:27.502] INFO: ----------------------------------------------------------------------
[10:21:33.381] INFO: ROC Delay Settings: 228
[10:21:33.381] INFO: ROC Header-Trailer/Token Delay: 11
[10:21:33.381] INFO: ROC Port 0 Delay: 4
[10:21:33.381] INFO: ROC Port 1 Delay: 4
[10:21:33.381] INFO: Functional ROC Area: 4
[10:21:33.384] INFO: Test took 125882 ms.
[10:21:33.384] INFO: PixTestTiming::ROCDelayScan() done.
[10:21:33.384] INFO: ----------------------------------------------------------------------
[10:21:33.384] INFO: PixTestTiming::TimingTest()
[10:21:33.384] INFO: ----------------------------------------------------------------------
[10:21:49.583] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:22:04.590] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:22:19.603] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:22:34.613] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:22:49.614] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:23:04.635] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:23:19.641] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:23:34.676] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:23:49.690] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:24:04.699] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:24:05.076] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:24:05.094] INFO: ----------------------------------------------------------------------
[10:24:05.094] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[10:24:05.094] INFO: ----------------------------------------------------------------------
[10:24:05.094] INFO: ----------------------------------------------------------------------
[10:24:05.094] INFO: Read back bit status: 1
[10:24:05.094] INFO: ----------------------------------------------------------------------
[10:24:05.094] INFO: ----------------------------------------------------------------------
[10:24:05.094] INFO: Timings are good!
[10:24:05.094] INFO: ----------------------------------------------------------------------
[10:24:05.094] INFO: Test took 151710 ms.
[10:24:05.094] INFO: PixTestTiming::TimingTest() done.
[10:24:05.094] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//tbmParameters_C0a.dat
[10:24:05.094] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:24:05.094] INFO: PixTestTiming::doTest took 667524 ms.
[10:24:05.094] INFO: PixTestTiming::doTest() done
[10:24:05.094] INFO: Write out TBMPhaseScan_0_V0
[10:24:05.121] INFO: Write out TBMPhaseScan_1_V0
[10:24:05.121] INFO: Write out CombinedTBMPhaseScan_V0
[10:24:05.151] INFO: Write out ROCDelayScan3_V0
[10:24:05.153] INFO: enter test to run
[10:24:55.296] INFO: test: PixelAlive no parameter change
[10:24:55.296] INFO: running: pixelalive
[10:24:55.301] INFO: ----------------------------------------------------------------------
[10:24:55.301] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[10:24:55.301] INFO: ----------------------------------------------------------------------
[10:24:55.619] INFO: Expecting 41600 events.
[10:24:59.954] INFO: 41600 events read in total (3620ms).
[10:24:59.955] INFO: Test took 4652ms.
[10:24:59.961] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:25:00.359] INFO: PixTestAlive::aliveTest() done
[10:25:00.359] INFO: number of dead pixels (per ROC): 0 0 2 0 0 0 0 0 0 0 0 1 0 0 0 0
[10:25:00.361] INFO: enter test to run
[10:25:28.032] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[10:25:28.032] INFO: running: highrate
[10:25:28.033] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[10:25:28.187] INFO: ----------------------------------------------------------------------
[10:25:28.187] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[10:25:28.187] INFO: ----------------------------------------------------------------------
[10:25:28.187] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[10:25:28.187] INFO: edge/corner pixel THR is adjusted
[10:25:28.187] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:25:29.146] INFO: Collecting data for 5 seconds...
[10:25:34.163] INFO: Done with hot pixel readout
[10:25:45.216] INFO: PixTest:: pg_setup set to default.
[10:25:45.217] INFO: 0 hot pixels found in step 0
[10:25:45.247] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:25:45.250] INFO: PixTest::trimHotPixels() done
[10:25:45.251] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C0.dat
[10:25:45.256] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C1.dat
[10:25:45.263] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C2.dat
[10:25:45.268] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C3.dat
[10:25:45.274] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C4.dat
[10:25:45.279] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C5.dat
[10:25:45.284] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C6.dat
[10:25:45.289] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C7.dat
[10:25:45.295] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C8.dat
[10:25:45.300] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C9.dat
[10:25:45.305] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C10.dat
[10:25:45.310] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C11.dat
[10:25:45.315] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C12.dat
[10:25:45.321] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C13.dat
[10:25:45.326] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C14.dat
[10:25:45.331] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C15.dat
[10:25:45.336] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//defaultMaskFile.dat
[10:25:45.351] INFO: enter test to run
[10:26:04.216] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[10:26:04.216] INFO: running: highrate
[10:26:04.220] INFO: ----------------------------------------------------------------------
[10:26:04.220] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[10:26:04.220] INFO: ----------------------------------------------------------------------
[10:26:04.220] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[10:26:04.220] INFO: edge/corner pixel THR is adjusted
[10:26:04.220] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:26:05.178] INFO: Collecting data for 1 seconds...
[10:26:06.182] INFO: Done with hot pixel readout
[10:26:09.927] INFO: PixTest:: pg_setup set to default.
[10:26:09.928] INFO: 0 hot pixels found in step 0
[10:26:09.933] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:26:10.030] INFO: PixTest::trimHotPixels() done
[10:26:10.030] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C0.dat
[10:26:10.042] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C1.dat
[10:26:10.049] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C2.dat
[10:26:10.054] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C3.dat
[10:26:10.060] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C4.dat
[10:26:10.065] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C5.dat
[10:26:10.070] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C6.dat
[10:26:10.075] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C7.dat
[10:26:10.081] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C8.dat
[10:26:10.086] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C9.dat
[10:26:10.091] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C10.dat
[10:26:10.096] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C11.dat
[10:26:10.102] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C12.dat
[10:26:10.107] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C13.dat
[10:26:10.112] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C14.dat
[10:26:10.117] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//trimParameters35_C15.dat
[10:26:10.123] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-N-2-34_FPIXTest-17C-FNAL-160510-1257_2016-05-10_12h57m_1462903071/000_FPIXTest_p17//defaultMaskFile.dat
[10:26:10.132] INFO: enter test to run
[10:26:51.407] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[10:26:51.407] INFO: running: xray
[10:26:51.409] INFO: ----------------------------------------------------------------------
[10:26:51.409] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:26:51.409] INFO: ----------------------------------------------------------------------
[10:26:52.372] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:27:04.504] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[10:27:33.713] INFO: Resuming triggers.
[10:27:45.849] INFO: run duration 24 seconds, buffer almost full (81%), pausing triggers.
[10:28:15.420] INFO: Resuming triggers.
[10:28:27.556] INFO: run duration 36 seconds, buffer almost full (81%), pausing triggers.
[10:28:56.694] INFO: Resuming triggers.
[10:29:08.828] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[10:29:38.116] INFO: Resuming triggers.
[10:29:50.251] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[10:30:19.859] INFO: Resuming triggers.
[10:30:31.995] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[10:31:01.433] INFO: Resuming triggers.
[10:31:13.567] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[10:31:42.724] INFO: Resuming triggers.
[10:31:54.861] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[10:32:24.179] INFO: Resuming triggers.
[10:32:27.447] INFO: data taking finished, elapsed time: 100 seconds.
[10:32:35.657] INFO: PixTest:: pg_setup set to default.
[10:32:35.661] INFO: PixTestXray::doPhRun() done
[10:32:35.795] INFO: enter test to run
[10:32:57.485] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[10:32:57.485] INFO: running: xray
[10:32:57.486] INFO: ----------------------------------------------------------------------
[10:32:57.486] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:32:57.486] INFO: ----------------------------------------------------------------------
[10:32:58.450] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:33:05.647] INFO: run duration 7 seconds, buffer almost full (81%), pausing triggers.
[10:33:35.726] INFO: Resuming triggers.
[10:33:42.929] INFO: run duration 14 seconds, buffer almost full (81%), pausing triggers.
[10:34:13.016] INFO: Resuming triggers.
[10:34:20.215] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[10:34:50.323] INFO: Resuming triggers.
[10:34:57.522] INFO: run duration 28 seconds, buffer almost full (81%), pausing triggers.
[10:35:27.619] INFO: Resuming triggers.
[10:35:34.818] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[10:36:04.931] INFO: Resuming triggers.
[10:36:12.130] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[10:36:42.229] INFO: Resuming triggers.
[10:36:49.426] INFO: run duration 50 seconds, buffer almost full (81%), pausing triggers.
[10:37:19.545] INFO: Resuming triggers.
[10:37:26.742] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[10:37:56.894] INFO: Resuming triggers.
[10:38:04.092] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[10:38:34.121] INFO: Resuming triggers.
[10:38:41.321] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[10:39:11.750] INFO: Resuming triggers.
[10:39:18.952] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[10:39:49.554] INFO: Resuming triggers.
[10:39:56.752] INFO: run duration 86 seconds, buffer almost full (81%), pausing triggers.
[10:40:27.227] INFO: Resuming triggers.
[10:40:34.425] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[10:41:05.472] INFO: Resuming triggers.
[10:41:12.217] INFO: data taking finished, elapsed time: 100 seconds.
[10:41:41.880] INFO: PixTest:: pg_setup set to default.
[10:41:41.883] INFO: PixTestXray::doPhRun() done
[10:41:42.034] INFO: enter test to run
[10:42:01.129] INFO: test: HighRate no parameter change
[10:42:01.129] INFO: running: highrate
[10:42:01.130] INFO: ----------------------------------------------------------------------
[10:42:01.130] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[10:42:01.130] INFO: ----------------------------------------------------------------------
[10:42:01.271] INFO: Expecting 768 events.
[10:42:02.403] INFO: 768 events read in total (417ms).
[10:42:02.404] INFO: Test took 1267ms.
[10:42:03.207] INFO: Expecting 41600 events.
[10:42:06.233] INFO: 41600 events read in total (2499ms).
[10:42:06.234] INFO: Test took 3823ms.
[10:42:06.262] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:42:06.000] INFO: Expecting 41600 events.
[10:42:10.133] INFO: 41600 events read in total (2606ms).
[10:42:10.134] INFO: Test took 3855ms.
[10:42:10.163] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:42:10.896] INFO: Expecting 41600 events.
[10:42:14.069] INFO: 41600 events read in total (2647ms).
[10:42:14.070] INFO: Test took 3890ms.
[10:42:14.101] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:42:14.829] INFO: Expecting 41600 events.
[10:42:18.019] INFO: 41600 events read in total (2664ms).
[10:42:18.020] INFO: Test took 3903ms.
[10:42:18.049] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:42:18.783] INFO: Expecting 41600 events.
[10:42:21.977] INFO: 41600 events read in total (2668ms).
[10:42:21.978] INFO: Test took 3912ms.
[10:42:22.008] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:42:22.738] INFO: Expecting 41600 events.
[10:42:25.930] INFO: 41600 events read in total (2666ms).
[10:42:25.930] INFO: Test took 3906ms.
[10:42:25.960] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:42:26.694] INFO: Expecting 41600 events.
[10:42:29.898] INFO: 41600 events read in total (2677ms).
[10:42:29.899] INFO: Test took 3922ms.
[10:42:29.928] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:42:30.660] INFO: Expecting 41600 events.
[10:42:33.869] INFO: 41600 events read in total (2682ms).
[10:42:33.870] INFO: Test took 3925ms.
[10:42:33.900] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:42:34.630] INFO: Expecting 41600 events.
[10:42:37.821] INFO: 41600 events read in total (2664ms).
[10:42:37.822] INFO: Test took 3905ms.
[10:42:37.852] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:42:38.586] INFO: Expecting 41600 events.
[10:42:41.791] INFO: 41600 events read in total (2678ms).
[10:42:41.792] INFO: Test took 3922ms.
[10:42:41.822] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:42:42.554] INFO: Expecting 41600 events.
[10:42:45.749] INFO: 41600 events read in total (2669ms).
[10:42:45.750] INFO: Test took 3911ms.
[10:42:45.780] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:42:46.509] INFO: Expecting 41600 events.
[10:42:49.701] INFO: 41600 events read in total (2665ms).
[10:42:49.702] INFO: Test took 3907ms.
[10:42:49.732] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:42:50.465] INFO: Expecting 41600 events.
[10:42:53.660] INFO: 41600 events read in total (2668ms).
[10:42:53.661] INFO: Test took 3912ms.
[10:42:53.690] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:42:54.424] INFO: Expecting 41600 events.
[10:42:57.643] INFO: 41600 events read in total (2692ms).
[10:42:57.644] INFO: Test took 3939ms.
[10:42:57.673] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:42:58.405] INFO: Expecting 41600 events.
[10:43:01.601] INFO: 41600 events read in total (2669ms).
[10:43:01.602] INFO: Test took 3913ms.
[10:43:01.632] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:43:02.360] INFO: Expecting 41600 events.
[10:43:05.554] INFO: 41600 events read in total (2667ms).
[10:43:05.555] INFO: Test took 3906ms.
[10:43:05.585] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:43:06.319] INFO: Expecting 41600 events.
[10:43:09.522] INFO: 41600 events read in total (2676ms).
[10:43:09.523] INFO: Test took 3922ms.
[10:43:09.553] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:43:10.283] INFO: Expecting 41600 events.
[10:43:13.483] INFO: 41600 events read in total (2673ms).
[10:43:13.484] INFO: Test took 3914ms.
[10:43:13.513] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:43:14.244] INFO: Expecting 41600 events.
[10:43:17.419] INFO: 41600 events read in total (2648ms).
[10:43:17.420] INFO: Test took 3889ms.
[10:43:17.450] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:43:18.182] INFO: Expecting 41600 events.
[10:43:21.208] INFO: 41600 events read in total (2499ms).
[10:43:21.209] INFO: Test took 3741ms.
[10:43:21.238] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:43:21.610] INFO: enter test to run
[10:43:25.832] INFO: test: HighRate no parameter change
[10:43:25.832] INFO: running: highrate
[10:43:25.833] INFO: ----------------------------------------------------------------------
[10:43:25.833] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:43:25.833] INFO: ----------------------------------------------------------------------
[10:43:26.444] INFO: Expecting 208000 events.
[10:43:38.079] INFO: 208000 events read in total (11108ms).
[10:43:38.082] INFO: Test took 12242ms.
[10:43:38.205] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:43:38.452] INFO: number of dead pixels (per ROC): 0 0 2 0 0 0 0 0 0 0 0 1 0 0 0 0
[10:43:38.452] INFO: number of red-efficiency pixels: 65 38 68 105 108 128 102 74 65 77 71 71 63 35 16 27
[10:43:38.452] INFO: number of X-ray hits detected: 55790 37229 57483 90226 100194 106659 95603 70235 67440 73460 75667 68215 67306 40056 17544 22880
[10:43:38.452] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:43:38.452] INFO: number of Vcal hits detected: 207935 207962 207832 207893 207890 207870 207896 207926 207935 207922 207929 207880 207937 207965 207984 207973
[10:43:38.452] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[10:43:38.452] INFO: Vcal hit overall efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0 100.0 100.0 99.9 100.0 100.0 100.0 100.0
[10:43:38.452] INFO: X-ray hit rate [MHz/cm2]: 16.4 10.9 16.8 26.4 29.4 31.3 28.0 20.6 19.8 21.5 22.2 20.0 19.7 11.7 5.1 6.7
[10:43:38.452] INFO: PixTestHighRate::doXPixelAlive() done
[10:43:38.503] INFO: PixTest:: pg_setup set to default.
[10:43:38.514] INFO: enter test to run
[10:43:53.320] INFO: test: HighRate no parameter change
[10:43:53.320] INFO: running: highrate
[10:43:53.321] INFO: ----------------------------------------------------------------------
[10:43:53.321] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:43:53.321] INFO: ----------------------------------------------------------------------
[10:43:53.935] INFO: Expecting 208000 events.
[10:44:07.164] INFO: 208000 events read in total (12702ms).
[10:44:07.169] INFO: Test took 13840ms.
[10:44:07.420] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:44:07.707] INFO: number of dead pixels (per ROC): 0 0 2 0 0 0 0 0 0 0 0 1 0 0 0 0
[10:44:07.707] INFO: number of red-efficiency pixels: 170 72 253 309 348 404 328 215 221 203 240 191 232 129 31 48
[10:44:07.707] INFO: number of X-ray hits detected: 121604 80864 123952 195712 216268 230699 208219 154033 147001 159099 163753 148750 146110 87637 38602 49388
[10:44:07.707] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:44:07.707] INFO: number of Vcal hits detected: 207820 207927 207631 207666 207631 207570 207657 207776 207772 207787 207757 207753 207761 207866 207969 207949
[10:44:07.707] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 99.9 99.9 99.8 99.8 99.8 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0
[10:44:07.707] INFO: Vcal hit overall efficiency (%): 99.9 100.0 99.8 99.8 99.8 99.8 99.8 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0
[10:44:07.707] INFO: X-ray hit rate [MHz/cm2]: 35.6 23.7 36.3 57.4 63.4 67.6 61.0 45.1 43.1 46.6 48.0 43.6 42.8 25.7 11.3 14.5
[10:44:07.707] INFO: PixTestHighRate::doXPixelAlive() done
[10:44:07.752] INFO: PixTest:: pg_setup set to default.
[10:44:07.768] INFO: enter test to run
[10:44:20.272] INFO: test: HighRate no parameter change
[10:44:20.272] INFO: running: highrate
[10:44:20.273] INFO: ----------------------------------------------------------------------
[10:44:20.273] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:44:20.273] INFO: ----------------------------------------------------------------------
[10:44:20.886] INFO: Expecting 208000 events.
[10:44:35.765] INFO: 208000 events read in total (14352ms).
[10:44:35.771] INFO: Test took 15490ms.
[10:44:36.169] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:44:36.498] INFO: number of dead pixels (per ROC): 0 0 2 0 0 0 0 0 0 0 0 1 0 0 0 0
[10:44:36.498] INFO: number of red-efficiency pixels: 386 167 557 695 786 965 750 502 483 449 487 407 465 256 71 111
[10:44:36.498] INFO: number of X-ray hits detected: 184272 123030 190405 297728 329103 351908 315634 233111 223956 242157 249585 226412 220799 134166 58804 75906
[10:44:36.498] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:44:36.498] INFO: number of Vcal hits detected: 207564 207827 207203 207206 207094 206853 207115 207418 207483 207506 207477 207498 207491 207719 207927 207885
[10:44:36.498] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.6 99.6 99.5 99.6 99.7 99.8 99.8 99.8 99.8 99.8 99.9 100.0 99.9
[10:44:36.498] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.6 99.6 99.6 99.4 99.6 99.7 99.8 99.8 99.7 99.8 99.8 99.9 100.0 99.9
[10:44:36.498] INFO: X-ray hit rate [MHz/cm2]: 54.0 36.1 55.8 87.3 96.5 103.1 92.5 68.3 65.6 71.0 73.2 66.4 64.7 39.3 17.2 22.2
[10:44:36.498] INFO: PixTestHighRate::doXPixelAlive() done
[10:44:36.546] INFO: PixTest:: pg_setup set to default.
[10:44:36.559] INFO: enter test to run
[10:44:39.423] INFO: test: exit no parameter change
[10:44:39.897] QUIET: Connection to board 33 closed.
[10:44:39.899] INFO: pXar: this is the end, my friend