[12:31:58.088] INFO: *** Welcome to pxar ***
[12:31:58.089] INFO: *** Today: 2016/10/14
[12:31:59.276] INFO: *** Version: v1.9.0-818-g96727
[12:31:59.276] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//dacParameters35_C15.dat
[12:31:59.325] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:31:59.325] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//defaultMaskFile.dat
[12:31:59.330] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C15.dat
[12:31:59.460] INFO: clk: 4
[12:31:59.460] INFO: ctr: 4
[12:31:59.460] INFO: sda: 19
[12:31:59.460] INFO: tin: 9
[12:31:59.460] INFO: level: 15
[12:31:59.460] INFO: triggerdelay: 0
[12:31:59.460] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[12:31:59.460] INFO: Log level: INFO
[12:31:59.480] QUIET: Connection to board DTB_WREKRL opened.
[12:31:59.483] 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:
------------------------------------------------------
[12:31:59.486] INFO: RPC call hashes of host and DTB match: 398089610
[12:32:01.031] INFO: DUT info:
[12:32:01.031] INFO: The DUT currently contains the following objects:
[12:32:01.031] INFO: 2 TBM Cores tbm08c (2 ON)
[12:32:01.031] INFO: TBM Core alpha (0): 7 registers set
[12:32:01.031] INFO: TBM Core beta (1): 7 registers set
[12:32:01.031] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[12:32:01.031] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[12:32:01.031] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[12:32:01.031] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[12:32:01.031] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[12:32:01.031] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[12:32:01.031] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[12:32:01.031] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[12:32:01.031] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[12:32:01.032] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[12:32:01.032] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[12:32:01.032] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[12:32:01.032] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[12:32:01.032] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[12:32:01.032] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[12:32:01.032] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[12:32:01.032] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[12:32:01.455] INFO: enter 'restricted' command line mode
[12:32:01.455] INFO: enter test to run
[12:32:23.529] INFO: test: PixelAlive no parameter change
[12:32:23.529] INFO: running: pixelalive
[12:32:23.675] INFO: ----------------------------------------------------------------------
[12:32:23.675] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[12:32:23.675] INFO: ----------------------------------------------------------------------
[12:32:23.989] INFO: Expecting 41600 events.
[12:32:28.331] INFO: 41600 events read in total (3624ms).
[12:32:28.493] INFO: Test took 4816ms.
[12:32:28.504] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:32:29.042] INFO: PixTestAlive::aliveTest() done
[12:32:29.042] INFO: number of dead pixels (per ROC): 1 0 0 0 0 0 0 0 0 0 0 0 1 0 0 0
[12:32:29.197] INFO: enter test to run
[12:32:36.104] INFO: test: timing no parameter change
[12:32:36.104] INFO: running: timing
[12:32:36.107] INFO: ######################################################################
[12:32:36.107] INFO: PixTestTiming::doTest()
[12:32:36.107] INFO: ######################################################################
[12:32:36.107] INFO: ----------------------------------------------------------------------
[12:32:36.107] INFO: PixTestTiming::TBMPhaseScan()
[12:32:36.107] INFO: ----------------------------------------------------------------------
[12:36:45.078] INFO: TBM Phase Settings: 236
[12:36:45.078] INFO: 400MHz Phase: 3
[12:36:45.078] INFO: 160MHz Phase: 7
[12:36:45.078] INFO: Functional Phase Area: 3
[12:36:45.098] INFO: Test took 248991 ms.
[12:36:45.098] INFO: PixTestTiming::TBMPhaseScan() done.
[12:36:45.099] INFO: ----------------------------------------------------------------------
[12:36:45.099] INFO: PixTestTiming::ROCDelayScan()
[12:36:45.099] INFO: ----------------------------------------------------------------------
[12:38:44.243] INFO: ROC Delay Settings: 228
[12:38:44.244] INFO: ROC Header-Trailer/Token Delay: 11
[12:38:44.244] INFO: ROC Port 0 Delay: 4
[12:38:44.244] INFO: ROC Port 1 Delay: 4
[12:38:44.244] INFO: Functional ROC Area: 3
[12:38:44.247] INFO: Test took 119148 ms.
[12:38:44.247] INFO: PixTestTiming::ROCDelayScan() done.
[12:38:44.247] INFO: ----------------------------------------------------------------------
[12:38:44.247] INFO: PixTestTiming::TimingTest()
[12:38:44.247] INFO: ----------------------------------------------------------------------
[12:39:00.668] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:39:15.780] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:39:31.028] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:39:46.210] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:40:01.326] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:40:16.495] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:40:31.690] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:40:46.982] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:41:02.110] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:41:17.060] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:41:17.441] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:41:17.459] INFO: ----------------------------------------------------------------------
[12:41:17.459] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[12:41:17.459] INFO: ----------------------------------------------------------------------
[12:41:17.459] INFO: ----------------------------------------------------------------------
[12:41:17.459] INFO: Read back bit status: 1
[12:41:17.459] INFO: ----------------------------------------------------------------------
[12:41:17.459] INFO: ----------------------------------------------------------------------
[12:41:17.459] INFO: Timings are good!
[12:41:17.459] INFO: ----------------------------------------------------------------------
[12:41:17.459] INFO: Test took 153212 ms.
[12:41:17.459] INFO: PixTestTiming::TimingTest() done.
[12:41:17.459] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//tbmParameters_C0a.dat
[12:41:17.459] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:41:17.459] INFO: PixTestTiming::doTest took 521355 ms.
[12:41:17.459] INFO: PixTestTiming::doTest() done
[12:41:17.459] INFO: Write out TBMPhaseScan_0_V0
[12:41:17.460] INFO: Write out TBMPhaseScan_1_V0
[12:41:17.460] INFO: Write out CombinedTBMPhaseScan_V0
[12:41:17.461] INFO: Write out ROCDelayScan3_V0
[12:41:17.461] INFO: enter test to run
[12:42:13.972] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[12:42:13.972] INFO: running: highrate
[12:42:14.021] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[12:42:14.280] INFO: ----------------------------------------------------------------------
[12:42:14.280] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[12:42:14.280] INFO: ----------------------------------------------------------------------
[12:42:14.280] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[12:42:14.280] INFO: edge/corner pixel THR is adjusted
[12:42:14.280] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:42:15.237] INFO: Collecting data for 5 seconds...
[12:42:20.254] INFO: Done with hot pixel readout
[12:42:31.560] INFO: PixTest:: pg_setup set to default.
[12:42:31.561] INFO: 5 hot pixels found in step 0
[12:42:32.548] INFO: Collecting data for 5 seconds...
[12:42:37.565] INFO: Done with hot pixel readout
[12:42:48.782] INFO: PixTest:: pg_setup set to default.
[12:42:48.783] INFO: 4 hot pixels found in step 1
[12:42:49.772] INFO: Collecting data for 5 seconds...
[12:42:54.788] INFO: Done with hot pixel readout
[12:43:06.140] INFO: PixTest:: pg_setup set to default.
[12:43:06.141] INFO: 7 hot pixels found in step 2
[12:43:07.129] INFO: Collecting data for 5 seconds...
[12:43:12.145] INFO: Done with hot pixel readout
[12:43:23.492] INFO: PixTest:: pg_setup set to default.
[12:43:23.493] INFO: 6 hot pixels found in step 3
[12:43:24.481] INFO: Collecting data for 5 seconds...
[12:43:29.498] INFO: Done with hot pixel readout
[12:43:40.776] INFO: PixTest:: pg_setup set to default.
[12:43:40.777] INFO: 7 hot pixels found in step 4
[12:43:41.766] INFO: Collecting data for 5 seconds...
[12:43:46.782] INFO: Done with hot pixel readout
[12:43:58.131] INFO: PixTest:: pg_setup set to default.
[12:43:58.131] INFO: 3 hot pixels found in step 5
[12:43:59.120] INFO: Collecting data for 5 seconds...
[12:44:04.137] INFO: Done with hot pixel readout
[12:44:15.397] INFO: PixTest:: pg_setup set to default.
[12:44:15.398] INFO: 1 hot pixels found in step 6
[12:44:16.386] INFO: Collecting data for 5 seconds...
[12:44:21.404] INFO: Done with hot pixel readout
[12:44:32.747] INFO: PixTest:: pg_setup set to default.
[12:44:32.748] INFO: 0 hot pixels found in step 7
[12:44:32.780] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:44:32.783] INFO: PixTest::trimHotPixels() done
[12:44:32.784] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C0.dat
[12:44:32.789] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C1.dat
[12:44:32.796] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C2.dat
[12:44:32.801] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C3.dat
[12:44:32.807] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C4.dat
[12:44:32.812] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C5.dat
[12:44:32.817] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C6.dat
[12:44:32.823] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C7.dat
[12:44:32.828] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C8.dat
[12:44:32.833] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C9.dat
[12:44:32.838] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C10.dat
[12:44:32.844] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C11.dat
[12:44:32.849] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C12.dat
[12:44:32.854] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C13.dat
[12:44:32.859] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C14.dat
[12:44:32.865] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C15.dat
[12:44:32.870] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//defaultMaskFile.dat
[12:44:32.880] INFO: enter test to run
[12:45:28.339] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[12:45:28.339] INFO: running: highrate
[12:45:28.343] INFO: ----------------------------------------------------------------------
[12:45:28.343] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[12:45:28.344] INFO: ----------------------------------------------------------------------
[12:45:28.344] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[12:45:28.344] INFO: edge/corner pixel THR is adjusted
[12:45:28.344] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:45:29.302] INFO: Collecting data for 1 seconds...
[12:45:30.305] INFO: Done with hot pixel readout
[12:45:34.036] INFO: PixTest:: pg_setup set to default.
[12:45:34.037] INFO: 0 hot pixels found in step 0
[12:45:34.043] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:45:34.141] INFO: PixTest::trimHotPixels() done
[12:45:34.142] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C0.dat
[12:45:34.153] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C1.dat
[12:45:34.159] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C2.dat
[12:45:34.164] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C3.dat
[12:45:34.169] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C4.dat
[12:45:34.175] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C5.dat
[12:45:34.180] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C6.dat
[12:45:34.185] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C7.dat
[12:45:34.190] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C8.dat
[12:45:34.196] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C9.dat
[12:45:34.201] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C10.dat
[12:45:34.206] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C11.dat
[12:45:34.211] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C12.dat
[12:45:34.217] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C13.dat
[12:45:34.222] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C14.dat
[12:45:34.227] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C15.dat
[12:45:34.232] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-A-05_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//defaultMaskFile.dat
[12:45:34.242] INFO: enter test to run
[12:45:58.050] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[12:45:58.050] INFO: running: xray
[12:45:58.051] INFO: ----------------------------------------------------------------------
[12:45:58.052] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:45:58.052] INFO: ----------------------------------------------------------------------
[12:45:59.029] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:46:10.989] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[12:46:40.201] INFO: Resuming triggers.
[12:46:52.160] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[12:47:21.475] INFO: Resuming triggers.
[12:47:33.430] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[12:48:02.549] INFO: Resuming triggers.
[12:48:14.501] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[12:48:43.879] INFO: Resuming triggers.
[12:48:55.830] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[12:49:25.389] INFO: Resuming triggers.
[12:49:37.344] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[12:50:06.863] INFO: Resuming triggers.
[12:50:18.813] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[12:50:48.027] INFO: Resuming triggers.
[12:50:59.979] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[12:51:29.446] INFO: Resuming triggers.
[12:51:34.168] INFO: data taking finished, elapsed time: 100 seconds.
[12:51:45.779] INFO: PixTest:: pg_setup set to default.
[12:51:45.783] INFO: PixTestXray::doPhRun() done
[12:51:45.967] INFO: enter test to run
[12:52:26.656] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:52:26.656] INFO: running: xray
[12:52:26.657] INFO: ----------------------------------------------------------------------
[12:52:26.657] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:52:26.657] INFO: ----------------------------------------------------------------------
[12:52:27.620] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:52:34.955] INFO: run duration 7 seconds, buffer almost full (81%), pausing triggers.
[12:53:06.971] INFO: Resuming triggers.
[12:53:14.308] INFO: run duration 14 seconds, buffer almost full (81%), pausing triggers.
[12:53:45.658] INFO: Resuming triggers.
[12:53:52.996] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[12:54:24.891] INFO: Resuming triggers.
[12:54:32.230] INFO: run duration 29 seconds, buffer almost full (81%), pausing triggers.
[12:55:02.567] INFO: Resuming triggers.
[12:55:09.904] INFO: run duration 36 seconds, buffer almost full (81%), pausing triggers.
[12:55:40.166] INFO: Resuming triggers.
[12:55:47.505] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[12:56:17.736] INFO: Resuming triggers.
[12:56:25.074] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[12:56:55.279] INFO: Resuming triggers.
[12:57:02.621] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[12:57:32.783] INFO: Resuming triggers.
[12:57:40.121] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[12:58:10.425] INFO: Resuming triggers.
[12:58:17.761] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[12:58:47.979] INFO: Resuming triggers.
[12:58:55.318] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[12:59:25.599] INFO: Resuming triggers.
[12:59:32.932] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[13:00:03.300] INFO: Resuming triggers.
[13:00:10.632] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[13:00:40.793] INFO: Resuming triggers.
[13:00:45.759] INFO: data taking finished, elapsed time: 100 seconds.
[13:01:06.404] INFO: PixTest:: pg_setup set to default.
[13:01:06.407] INFO: PixTestXray::doPhRun() done
[13:01:06.556] INFO: enter test to run
[13:02:03.684] INFO: test: HighRate no parameter change
[13:02:03.684] INFO: running: highrate
[13:02:03.703] INFO: ----------------------------------------------------------------------
[13:02:03.704] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[13:02:03.704] INFO: ----------------------------------------------------------------------
[13:02:03.858] INFO: Expecting 768 events.
[13:02:04.000] INFO: 768 events read in total (419ms).
[13:02:04.000] INFO: Test took 1276ms.
[13:02:05.803] INFO: Expecting 41600 events.
[13:02:08.875] INFO: 41600 events read in total (2545ms).
[13:02:08.876] INFO: Test took 3841ms.
[13:02:08.906] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:09.638] INFO: Expecting 41600 events.
[13:02:12.826] INFO: 41600 events read in total (2661ms).
[13:02:12.827] INFO: Test took 3904ms.
[13:02:12.857] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:13.590] INFO: Expecting 41600 events.
[13:02:16.786] INFO: 41600 events read in total (2669ms).
[13:02:16.787] INFO: Test took 3913ms.
[13:02:16.817] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:17.549] INFO: Expecting 41600 events.
[13:02:20.781] INFO: 41600 events read in total (2705ms).
[13:02:20.782] INFO: Test took 3947ms.
[13:02:20.813] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:21.540] INFO: Expecting 41600 events.
[13:02:24.784] INFO: 41600 events read in total (2717ms).
[13:02:24.785] INFO: Test took 3956ms.
[13:02:24.817] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:25.536] INFO: Expecting 41600 events.
[13:02:28.777] INFO: 41600 events read in total (2714ms).
[13:02:28.777] INFO: Test took 3940ms.
[13:02:28.811] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:29.540] INFO: Expecting 41600 events.
[13:02:32.815] INFO: 41600 events read in total (2748ms).
[13:02:32.816] INFO: Test took 3988ms.
[13:02:32.847] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:33.573] INFO: Expecting 41600 events.
[13:02:36.850] INFO: 41600 events read in total (2750ms).
[13:02:36.851] INFO: Test took 3988ms.
[13:02:36.889] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:37.610] INFO: Expecting 41600 events.
[13:02:40.851] INFO: 41600 events read in total (2714ms).
[13:02:40.852] INFO: Test took 3947ms.
[13:02:40.883] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:41.612] INFO: Expecting 41600 events.
[13:02:44.870] INFO: 41600 events read in total (2731ms).
[13:02:44.871] INFO: Test took 3971ms.
[13:02:44.902] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:45.621] INFO: Expecting 41600 events.
[13:02:48.886] INFO: 41600 events read in total (2739ms).
[13:02:48.886] INFO: Test took 3967ms.
[13:02:48.919] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:49.646] INFO: Expecting 41600 events.
[13:02:52.921] INFO: 41600 events read in total (2748ms).
[13:02:52.922] INFO: Test took 3987ms.
[13:02:52.953] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:53.683] INFO: Expecting 41600 events.
[13:02:56.953] INFO: 41600 events read in total (2743ms).
[13:02:56.954] INFO: Test took 3984ms.
[13:02:56.985] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:57.700] INFO: Expecting 41600 events.
[13:03:00.932] INFO: 41600 events read in total (2705ms).
[13:03:00.933] INFO: Test took 3931ms.
[13:03:00.964] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:03:01.691] INFO: Expecting 41600 events.
[13:03:04.906] INFO: 41600 events read in total (2688ms).
[13:03:04.906] INFO: Test took 3925ms.
[13:03:04.938] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:03:05.665] INFO: Expecting 41600 events.
[13:03:09.010] INFO: 41600 events read in total (2819ms).
[13:03:09.010] INFO: Test took 4055ms.
[13:03:09.042] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:03:09.769] INFO: Expecting 41600 events.
[13:03:13.017] INFO: 41600 events read in total (2721ms).
[13:03:13.018] INFO: Test took 3959ms.
[13:03:13.049] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:03:13.775] INFO: Expecting 41600 events.
[13:03:17.025] INFO: 41600 events read in total (2723ms).
[13:03:17.026] INFO: Test took 3960ms.
[13:03:17.057] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:03:17.784] INFO: Expecting 41600 events.
[13:03:21.044] INFO: 41600 events read in total (2733ms).
[13:03:21.045] INFO: Test took 3971ms.
[13:03:21.077] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:03:21.802] INFO: Expecting 41600 events.
[13:03:24.870] INFO: 41600 events read in total (2541ms).
[13:03:24.871] INFO: Test took 3777ms.
[13:03:24.901] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:03:25.265] INFO: enter test to run
[13:03:45.787] INFO: test: HighRate no parameter change
[13:03:45.787] INFO: running: highrate
[13:03:45.789] INFO: ----------------------------------------------------------------------
[13:03:45.789] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:03:45.789] INFO: ----------------------------------------------------------------------
[13:03:46.415] INFO: Expecting 208000 events.
[13:03:57.983] INFO: 208000 events read in total (11042ms).
[13:03:57.986] INFO: Test took 12187ms.
[13:03:58.116] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:03:58.365] INFO: number of dead pixels (per ROC): 1 0 0 0 0 0 0 0 0 0 0 0 1 0 0 0
[13:03:58.365] INFO: number of red-efficiency pixels: 71 30 63 113 115 151 89 87 74 106 271 96 73 217 19 16
[13:03:58.365] INFO: number of X-ray hits detected: 57735 35840 58459 93433 98394 105055 103479 72184 66871 85858 81839 74110 74403 43420 18966 23505
[13:03:58.365] 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:03:58.365] INFO: number of Vcal hits detected: 207880 207970 207936 207886 207884 207846 207908 207910 207926 207891 204048 207902 207878 200901 207980 207984
[13:03:58.365] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 100.0 100.0 100.0 99.9 98.0 100.0 100.0 96.5 100.0 100.0
[13:03:58.365] INFO: Vcal hit overall efficiency (%): 99.9 100.0 100.0 99.9 99.9 99.9 100.0 100.0 100.0 99.9 98.1 100.0 99.9 96.6 100.0 100.0
[13:03:58.365] INFO: X-ray hit rate [MHz/cm2]: 16.9 10.5 17.1 27.4 28.8 30.8 30.3 21.2 19.6 25.2 24.0 21.7 21.8 12.7 5.6 6.9
[13:03:58.365] INFO: PixTestHighRate::doXPixelAlive() done
[13:03:58.411] INFO: PixTest:: pg_setup set to default.
[13:03:58.429] INFO: enter test to run
[13:04:39.099] INFO: test: HighRate no parameter change
[13:04:39.099] INFO: running: highrate
[13:04:39.100] INFO: ----------------------------------------------------------------------
[13:04:39.100] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:04:39.100] INFO: ----------------------------------------------------------------------
[13:04:39.733] INFO: Expecting 208000 events.
[13:04:52.924] INFO: 208000 events read in total (12665ms).
[13:04:52.928] INFO: Test took 13818ms.
[13:04:53.198] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:04:53.488] INFO: number of dead pixels (per ROC): 1 0 0 0 0 0 0 0 0 0 27 0 1 45 0 0
[13:04:53.488] INFO: number of red-efficiency pixels: 207 72 224 306 443 480 339 250 195 316 447 239 267 317 46 40
[13:04:53.488] INFO: number of X-ray hits detected: 117372 73137 120196 190107 200401 213801 210500 147923 137472 173738 166275 150659 152372 88097 38627 47990
[13:04:53.488] 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:04:53.488] INFO: number of Vcal hits detected: 207724 207924 207763 207680 207520 207469 207646 207732 207794 207674 202278 207743 207667 200042 207953 207960
[13:04:53.488] 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 97.8 99.9 99.9 97.1 100.0 100.0
[13:04:53.488] INFO: Vcal hit overall efficiency (%): 99.9 100.0 99.9 99.8 99.8 99.7 99.8 99.9 99.9 99.8 97.2 99.9 99.8 96.2 100.0 100.0
[13:04:53.488] INFO: X-ray hit rate [MHz/cm2]: 34.4 21.4 35.2 55.7 58.7 62.7 61.7 43.4 40.3 50.9 48.7 44.2 44.7 25.8 11.3 14.1
[13:04:53.488] INFO: PixTestHighRate::doXPixelAlive() done
[13:04:53.545] INFO: PixTest:: pg_setup set to default.
[13:04:53.561] INFO: enter test to run
[13:05:22.570] INFO: test: HighRate no parameter change
[13:05:22.570] INFO: running: highrate
[13:05:22.571] INFO: ----------------------------------------------------------------------
[13:05:22.571] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:05:22.571] INFO: ----------------------------------------------------------------------
[13:05:23.186] INFO: Expecting 208000 events.
[13:05:37.855] INFO: 208000 events read in total (14142ms).
[13:05:37.862] INFO: Test took 15282ms.
[13:05:38.252] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:05:38.584] INFO: number of dead pixels (per ROC): 1 0 0 0 0 0 0 0 0 0 10 0 1 113 0 0
[13:05:38.584] INFO: number of red-efficiency pixels: 441 157 459 624 938 1099 709 579 421 738 801 559 535 480 64 69
[13:05:38.584] INFO: number of X-ray hits detected: 176472 109669 179826 286954 299985 321954 317620 221557 207565 262599 250644 227428 229211 132234 57901 72627
[13:05:38.584] 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:05:38.584] INFO: number of Vcal hits detected: 207430 207829 207440 207297 206871 206584 207189 207294 207531 207147 204451 207372 207365 199684 207936 207930
[13:05:38.584] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.7 99.5 99.4 99.6 99.7 99.8 99.6 98.5 99.7 99.8 98.6 100.0 100.0
[13:05:38.584] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.7 99.7 99.5 99.3 99.6 99.7 99.8 99.6 98.3 99.7 99.7 96.0 100.0 100.0
[13:05:38.584] INFO: X-ray hit rate [MHz/cm2]: 51.7 32.1 52.7 84.1 87.9 94.4 93.1 64.9 60.8 77.0 73.5 66.7 67.2 38.8 17.0 21.3
[13:05:38.584] INFO: PixTestHighRate::doXPixelAlive() done
[13:05:38.633] INFO: PixTest:: pg_setup set to default.
[13:05:38.647] INFO: enter test to run
[13:05:48.426] INFO: test: exit no parameter change
[13:05:49.042] QUIET: Connection to board 33 closed.
[13:05:49.074] INFO: pXar: this is the end, my friend