[16:23:00.007] INFO: *** Welcome to pxar ***
[16:23:00.007] INFO: *** Today: 2016/09/29
[16:23:01.256] INFO: *** Version: v1.9.0-818-g96727
[16:23:01.256] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//dacParameters35_C15.dat
[16:23:01.306] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:23:01.335] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//defaultMaskFile.dat
[16:23:01.374] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C15.dat
[16:23:01.788] INFO: clk: 4
[16:23:01.788] INFO: ctr: 4
[16:23:01.788] INFO: sda: 19
[16:23:01.788] INFO: tin: 9
[16:23:01.788] INFO: level: 15
[16:23:01.788] INFO: triggerdelay: 0
[16:23:01.788] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[16:23:01.788] INFO: Log level: INFO
[16:23:01.804] QUIET: Connection to board DTB_WREKRL opened.
[16:23:01.807] 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:
------------------------------------------------------
[16:23:01.810] INFO: RPC call hashes of host and DTB match: 398089610
[16:23:03.379] INFO: DUT info:
[16:23:03.379] INFO: The DUT currently contains the following objects:
[16:23:03.379] INFO: 2 TBM Cores tbm08c (2 ON)
[16:23:03.393] INFO: TBM Core alpha (0): 7 registers set
[16:23:03.393] INFO: TBM Core beta (1): 7 registers set
[16:23:03.393] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[16:23:03.393] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[16:23:03.393] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[16:23:03.393] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[16:23:03.393] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[16:23:03.393] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[16:23:03.393] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[16:23:03.393] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[16:23:03.393] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[16:23:03.393] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[16:23:03.393] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[16:23:03.393] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[16:23:03.393] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[16:23:03.393] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[16:23:03.394] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[16:23:03.394] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[16:23:03.394] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[16:23:03.920] INFO: enter 'restricted' command line mode
[16:23:03.921] INFO: enter test to run
[16:23:06.315] INFO: test: PixelAlive no parameter change
[16:23:06.315] INFO: running: pixelalive
[16:23:06.394] INFO: ----------------------------------------------------------------------
[16:23:06.394] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[16:23:06.395] INFO: ----------------------------------------------------------------------
[16:23:06.746] INFO: Expecting 41600 events.
[16:23:11.033] INFO: 41600 events read in total (3569ms).
[16:23:11.201] INFO: Test took 4804ms.
[16:23:11.212] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:23:11.542] INFO: PixTestAlive::aliveTest() done
[16:23:11.542] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[16:23:11.570] INFO: enter test to run
[16:23:15.899] INFO: test: timing no parameter change
[16:23:15.899] INFO: running: timing
[16:23:15.902] INFO: ######################################################################
[16:23:15.902] INFO: PixTestTiming::doTest()
[16:23:15.902] INFO: ######################################################################
[16:23:15.902] INFO: ----------------------------------------------------------------------
[16:23:15.902] INFO: PixTestTiming::TBMPhaseScan()
[16:23:15.902] INFO: ----------------------------------------------------------------------
[16:29:12.664] INFO: TBM Phase Settings: 236
[16:29:12.664] INFO: 400MHz Phase: 3
[16:29:12.664] INFO: 160MHz Phase: 7
[16:29:12.664] INFO: Functional Phase Area: 5
[16:29:12.667] INFO: Test took 356765 ms.
[16:29:12.667] INFO: PixTestTiming::TBMPhaseScan() done.
[16:29:12.667] INFO: ----------------------------------------------------------------------
[16:29:12.667] INFO: PixTestTiming::ROCDelayScan()
[16:29:12.667] INFO: ----------------------------------------------------------------------
[16:31:16.624] INFO: ROC Delay Settings: 228
[16:31:16.624] INFO: ROC Header-Trailer/Token Delay: 11
[16:31:16.624] INFO: ROC Port 0 Delay: 4
[16:31:16.624] INFO: ROC Port 1 Delay: 4
[16:31:16.624] INFO: Functional ROC Area: 5
[16:31:16.627] INFO: Test took 123960 ms.
[16:31:16.627] INFO: PixTestTiming::ROCDelayScan() done.
[16:31:16.628] INFO: ----------------------------------------------------------------------
[16:31:16.628] INFO: PixTestTiming::TimingTest()
[16:31:16.628] INFO: ----------------------------------------------------------------------
[16:31:32.771] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:31:47.719] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:32:02.656] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:32:17.623] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:32:32.540] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:32:47.493] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:02.469] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:17.396] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:32.359] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:47.384] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:47.762] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:47.780] INFO: ----------------------------------------------------------------------
[16:33:47.780] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[16:33:47.780] INFO: ----------------------------------------------------------------------
[16:33:47.780] INFO: ----------------------------------------------------------------------
[16:33:47.780] INFO: Read back bit status: 1
[16:33:47.780] INFO: ----------------------------------------------------------------------
[16:33:47.780] INFO: ----------------------------------------------------------------------
[16:33:47.780] INFO: Timings are good!
[16:33:47.780] INFO: ----------------------------------------------------------------------
[16:33:47.780] INFO: Test took 151152 ms.
[16:33:47.780] INFO: PixTestTiming::TimingTest() done.
[16:33:47.780] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//tbmParameters_C0a.dat
[16:33:47.780] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:33:47.781] INFO: PixTestTiming::doTest took 631882 ms.
[16:33:47.781] INFO: PixTestTiming::doTest() done
[16:33:47.781] INFO: Write out TBMPhaseScan_0_V0
[16:33:47.781] INFO: Write out TBMPhaseScan_1_V0
[16:33:47.781] INFO: Write out CombinedTBMPhaseScan_V0
[16:33:47.808] INFO: Write out ROCDelayScan3_V0
[16:33:47.809] INFO: enter test to run
[16:34:21.366] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[16:34:21.366] INFO: running: highrate
[16:34:21.393] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[16:34:21.667] INFO: ----------------------------------------------------------------------
[16:34:21.667] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[16:34:21.667] INFO: ----------------------------------------------------------------------
[16:34:21.667] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[16:34:21.667] INFO: edge/corner pixel THR is adjusted
[16:34:21.667] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:34:22.640] INFO: Collecting data for 5 seconds...
[16:34:27.655] INFO: Done with hot pixel readout
[16:34:39.691] INFO: PixTest:: pg_setup set to default.
[16:34:39.692] INFO: 18 hot pixels found in step 0
[16:34:40.689] INFO: Collecting data for 5 seconds...
[16:34:45.707] INFO: Done with hot pixel readout
[16:34:57.760] INFO: PixTest:: pg_setup set to default.
[16:34:57.761] INFO: 22 hot pixels found in step 1
[16:34:58.757] INFO: Collecting data for 5 seconds...
[16:35:03.776] INFO: Done with hot pixel readout
[16:35:15.987] INFO: PixTest:: pg_setup set to default.
[16:35:15.987] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[16:35:15.988] INFO: 20 hot pixels found in step 2
[16:35:16.984] INFO: Collecting data for 5 seconds...
[16:35:21.002] INFO: Done with hot pixel readout
[16:35:34.119] INFO: PixTest:: pg_setup set to default.
[16:35:34.120] INFO: 16 hot pixels found in step 3
[16:35:35.116] INFO: Collecting data for 5 seconds...
[16:35:40.136] INFO: Done with hot pixel readout
[16:35:52.352] INFO: PixTest:: pg_setup set to default.
[16:35:52.353] INFO: 10 hot pixels found in step 4
[16:35:53.349] INFO: Collecting data for 5 seconds...
[16:35:58.367] INFO: Done with hot pixel readout
[16:36:10.459] INFO: PixTest:: pg_setup set to default.
[16:36:10.460] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[16:36:10.460] INFO: 22 hot pixels found in step 5
[16:36:11.457] INFO: Collecting data for 5 seconds...
[16:36:16.474] INFO: Done with hot pixel readout
[16:36:28.601] INFO: PixTest:: pg_setup set to default.
[16:36:28.601] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[16:36:28.602] INFO: 14 hot pixels found in step 6
[16:36:29.598] INFO: Collecting data for 5 seconds...
[16:36:34.616] INFO: Done with hot pixel readout
[16:36:46.664] INFO: PixTest:: pg_setup set to default.
[16:36:46.665] INFO: 12 hot pixels found in step 7
[16:36:47.661] INFO: Collecting data for 5 seconds...
[16:36:52.680] INFO: Done with hot pixel readout
[16:37:04.910] INFO: PixTest:: pg_setup set to default.
[16:37:04.910] INFO: 18 hot pixels found in step 8
[16:37:05.906] INFO: Collecting data for 5 seconds...
[16:37:10.925] INFO: Done with hot pixel readout
[16:37:22.739] INFO: PixTest:: pg_setup set to default.
[16:37:22.740] INFO: 22 hot pixels found in step 9
[16:37:23.736] INFO: Collecting data for 5 seconds...
[16:37:28.753] INFO: Done with hot pixel readout
[16:37:40.166] INFO: PixTest:: pg_setup set to default.
[16:37:40.167] INFO: 11 hot pixels found in step 10
[16:37:41.164] INFO: Collecting data for 5 seconds...
[16:37:46.182] INFO: Done with hot pixel readout
[16:37:58.145] INFO: PixTest:: pg_setup set to default.
[16:37:58.145] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[16:37:58.146] INFO: 18 hot pixels found in step 11
[16:37:59.143] INFO: Collecting data for 5 seconds...
[16:38:04.161] INFO: Done with hot pixel readout
[16:38:15.952] INFO: PixTest:: pg_setup set to default.
[16:38:15.953] INFO: 14 hot pixels found in step 12
[16:38:16.949] INFO: Collecting data for 5 seconds...
[16:38:21.968] INFO: Done with hot pixel readout
[16:38:34.122] INFO: PixTest:: pg_setup set to default.
[16:38:34.122] INFO: 14 hot pixels found in step 13
[16:38:35.119] INFO: Collecting data for 5 seconds...
[16:38:40.138] INFO: Done with hot pixel readout
[16:38:52.449] INFO: PixTest:: pg_setup set to default.
[16:38:52.449] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[16:38:52.450] INFO: 13 hot pixels found in step 14
[16:38:52.490] INFO: 13 hot pixels could not be trimmed and have been masked.
[16:38:52.494] INFO: PixTest::trimHotPixels() done
[16:38:52.494] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C0.dat
[16:38:52.499] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C1.dat
[16:38:52.505] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C2.dat
[16:38:52.511] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C3.dat
[16:38:52.517] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C4.dat
[16:38:52.522] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C5.dat
[16:38:52.527] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C6.dat
[16:38:52.533] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C7.dat
[16:38:52.538] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C8.dat
[16:38:52.544] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C9.dat
[16:38:52.549] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C10.dat
[16:38:52.554] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C11.dat
[16:38:52.560] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C12.dat
[16:38:52.565] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C13.dat
[16:38:52.570] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C14.dat
[16:38:52.576] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C15.dat
[16:38:52.602] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//defaultMaskFile.dat
[16:38:52.614] INFO: enter test to run
[16:39:32.860] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[16:39:32.860] INFO: running: highrate
[16:39:32.865] INFO: ----------------------------------------------------------------------
[16:39:32.865] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[16:39:32.865] INFO: ----------------------------------------------------------------------
[16:39:32.865] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[16:39:32.865] INFO: edge/corner pixel THR is adjusted
[16:39:32.865] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:39:33.822] INFO: Collecting data for 1 seconds...
[16:39:34.827] INFO: Done with hot pixel readout
[16:39:38.985] INFO: PixTest:: pg_setup set to default.
[16:39:38.986] INFO: 0 hot pixels found in step 0
[16:39:38.991] INFO: 0 hot pixels could not be trimmed and have been masked.
[16:39:39.069] INFO: PixTest::trimHotPixels() done
[16:39:39.070] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C0.dat
[16:39:39.085] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C1.dat
[16:39:39.091] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C2.dat
[16:39:39.097] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C3.dat
[16:39:39.102] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C4.dat
[16:39:39.108] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C5.dat
[16:39:39.113] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C6.dat
[16:39:39.118] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C7.dat
[16:39:39.124] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C8.dat
[16:39:39.129] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C9.dat
[16:39:39.135] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C10.dat
[16:39:39.140] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C11.dat
[16:39:39.145] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C12.dat
[16:39:39.151] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C13.dat
[16:39:39.156] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C14.dat
[16:39:39.162] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C15.dat
[16:39:39.167] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-7-35_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//defaultMaskFile.dat
[16:39:39.182] INFO: enter test to run
[16:40:15.988] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[16:40:15.988] INFO: running: xray
[16:40:15.990] INFO: ----------------------------------------------------------------------
[16:40:15.990] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:40:15.990] INFO: ----------------------------------------------------------------------
[16:40:16.952] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:40:27.983] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[16:40:57.358] INFO: Resuming triggers.
[16:41:08.385] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[16:41:37.720] INFO: Resuming triggers.
[16:41:48.746] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[16:42:18.236] INFO: Resuming triggers.
[16:42:29.264] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[16:42:58.690] INFO: Resuming triggers.
[16:43:09.719] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[16:43:39.050] INFO: Resuming triggers.
[16:43:50.084] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[16:44:19.321] INFO: Resuming triggers.
[16:44:30.355] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[16:44:59.811] INFO: Resuming triggers.
[16:45:10.842] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[16:45:40.261] INFO: Resuming triggers.
[16:45:51.294] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[16:46:20.736] INFO: Resuming triggers.
[16:46:21.795] INFO: data taking finished, elapsed time: 100 seconds.
[16:46:25.046] INFO: PixTest:: pg_setup set to default.
[16:46:25.050] INFO: PixTestXray::doPhRun() done
[16:46:25.253] INFO: enter test to run
[16:47:06.969] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[16:47:06.969] INFO: running: xray
[16:47:06.970] INFO: ----------------------------------------------------------------------
[16:47:06.982] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:47:06.983] INFO: ----------------------------------------------------------------------
[16:47:07.960] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:47:14.295] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[16:47:44.301] INFO: Resuming triggers.
[16:47:50.628] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[16:48:20.818] INFO: Resuming triggers.
[16:48:27.150] INFO: run duration 18 seconds, buffer almost full (81%), pausing triggers.
[16:48:57.655] INFO: Resuming triggers.
[16:49:03.988] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[16:49:34.521] INFO: Resuming triggers.
[16:49:40.849] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[16:50:11.756] INFO: Resuming triggers.
[16:50:18.088] INFO: run duration 37 seconds, buffer almost full (81%), pausing triggers.
[16:50:48.697] INFO: Resuming triggers.
[16:50:55.023] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[16:51:25.376] INFO: Resuming triggers.
[16:51:31.706] INFO: run duration 50 seconds, buffer almost full (81%), pausing triggers.
[16:52:01.909] INFO: Resuming triggers.
[16:52:08.242] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[16:52:40.095] INFO: Resuming triggers.
[16:52:46.424] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[16:53:17.474] INFO: Resuming triggers.
[16:53:23.810] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[16:53:54.440] INFO: Resuming triggers.
[16:54:00.776] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[16:54:31.685] INFO: Resuming triggers.
[16:54:38.016] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[16:55:09.169] INFO: Resuming triggers.
[16:55:15.501] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[16:55:45.495] INFO: Resuming triggers.
[16:55:51.827] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[16:56:21.625] INFO: Resuming triggers.
[16:56:26.006] INFO: data taking finished, elapsed time: 100 seconds.
[16:56:52.682] INFO: PixTest:: pg_setup set to default.
[16:56:52.685] INFO: PixTestXray::doPhRun() done
[16:56:52.833] INFO: enter test to run
[16:58:08.077] INFO: test: HighRate no parameter change
[16:58:08.077] INFO: running: highrate
[16:58:08.089] INFO: ----------------------------------------------------------------------
[16:58:08.089] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[16:58:08.089] INFO: ----------------------------------------------------------------------
[16:58:08.248] INFO: Expecting 768 events.
[16:58:09.382] INFO: 768 events read in total (418ms).
[16:58:09.383] INFO: Test took 1270ms.
[16:58:10.186] INFO: Expecting 41600 events.
[16:58:13.310] INFO: 41600 events read in total (2597ms).
[16:58:13.311] INFO: Test took 3888ms.
[16:58:13.346] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:14.072] INFO: Expecting 41600 events.
[16:58:17.292] INFO: 41600 events read in total (2693ms).
[16:58:17.293] INFO: Test took 3928ms.
[16:58:17.329] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:18.048] INFO: Expecting 41600 events.
[16:58:21.281] INFO: 41600 events read in total (2707ms).
[16:58:21.282] INFO: Test took 3934ms.
[16:58:21.318] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:22.040] INFO: Expecting 41600 events.
[16:58:25.299] INFO: 41600 events read in total (2732ms).
[16:58:25.300] INFO: Test took 3963ms.
[16:58:25.336] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:26.056] INFO: Expecting 41600 events.
[16:58:29.316] INFO: 41600 events read in total (2733ms).
[16:58:29.317] INFO: Test took 3961ms.
[16:58:29.354] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:30.071] INFO: Expecting 41600 events.
[16:58:33.317] INFO: 41600 events read in total (2719ms).
[16:58:33.318] INFO: Test took 3945ms.
[16:58:33.355] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:34.075] INFO: Expecting 41600 events.
[16:58:37.334] INFO: 41600 events read in total (2732ms).
[16:58:37.335] INFO: Test took 3962ms.
[16:58:37.372] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:38.091] INFO: Expecting 41600 events.
[16:58:41.342] INFO: 41600 events read in total (2725ms).
[16:58:41.343] INFO: Test took 3952ms.
[16:58:41.379] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:42.100] INFO: Expecting 41600 events.
[16:58:45.375] INFO: 41600 events read in total (2748ms).
[16:58:45.376] INFO: Test took 3979ms.
[16:58:45.413] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:46.133] INFO: Expecting 41600 events.
[16:58:49.385] INFO: 41600 events read in total (2725ms).
[16:58:49.386] INFO: Test took 3953ms.
[16:58:49.423] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:50.143] INFO: Expecting 41600 events.
[16:58:53.414] INFO: 41600 events read in total (2744ms).
[16:58:53.415] INFO: Test took 3972ms.
[16:58:53.452] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:54.171] INFO: Expecting 41600 events.
[16:58:57.412] INFO: 41600 events read in total (2714ms).
[16:58:57.413] INFO: Test took 3943ms.
[16:58:57.451] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:58.171] INFO: Expecting 41600 events.
[16:59:01.441] INFO: 41600 events read in total (2743ms).
[16:59:01.442] INFO: Test took 3972ms.
[16:59:01.479] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:59:02.194] INFO: Expecting 41600 events.
[16:59:05.463] INFO: 41600 events read in total (2742ms).
[16:59:05.464] INFO: Test took 3965ms.
[16:59:05.500] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:59:06.220] INFO: Expecting 41600 events.
[16:59:09.495] INFO: 41600 events read in total (2748ms).
[16:59:09.497] INFO: Test took 3977ms.
[16:59:09.533] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:59:10.253] INFO: Expecting 41600 events.
[16:59:13.504] INFO: 41600 events read in total (2724ms).
[16:59:13.505] INFO: Test took 3952ms.
[16:59:13.542] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:59:14.263] INFO: Expecting 41600 events.
[16:59:17.517] INFO: 41600 events read in total (2727ms).
[16:59:17.518] INFO: Test took 3956ms.
[16:59:17.555] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:59:18.277] INFO: Expecting 41600 events.
[16:59:21.485] INFO: 41600 events read in total (2681ms).
[16:59:21.486] INFO: Test took 3911ms.
[16:59:21.523] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:59:22.243] INFO: Expecting 41600 events.
[16:59:25.481] INFO: 41600 events read in total (2711ms).
[16:59:25.482] INFO: Test took 3938ms.
[16:59:25.519] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:59:26.240] INFO: Expecting 41600 events.
[16:59:29.333] INFO: 41600 events read in total (2566ms).
[16:59:29.334] INFO: Test took 3795ms.
[16:59:29.371] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:59:29.715] INFO: enter test to run
[16:59:45.284] INFO: test: HighRate no parameter change
[16:59:45.284] INFO: running: highrate
[16:59:45.285] INFO: ----------------------------------------------------------------------
[16:59:45.285] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:59:45.285] INFO: ----------------------------------------------------------------------
[16:59:45.904] INFO: Expecting 208000 events.
[16:59:57.929] INFO: 208000 events read in total (11498ms).
[16:59:57.932] INFO: Test took 12638ms.
[16:59:58.092] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:59:58.351] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[16:59:58.351] INFO: number of red-efficiency pixels: 60 49 102 117 168 191 178 123 97 139 145 151 118 65 24 25
[16:59:58.351] INFO: number of X-ray hits detected: 68196 45392 69735 111035 119999 124998 124538 87805 88634 112298 111673 97864 101072 57969 24539 26464
[16:59:58.351] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:59:58.351] INFO: number of Vcal hits detected: 207939 207950 207896 207883 207827 207804 207818 207873 207900 207856 207851 207848 207881 207934 207976 207975
[16:59:58.351] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[16:59:58.351] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[16:59:58.351] INFO: X-ray hit rate [MHz/cm2]: 20.0 13.3 20.4 32.5 35.2 36.6 36.5 25.7 26.0 32.9 32.7 28.7 29.6 17.0 7.2 7.8
[16:59:58.351] INFO: PixTestHighRate::doXPixelAlive() done
[16:59:58.404] INFO: PixTest:: pg_setup set to default.
[16:59:58.420] INFO: enter test to run
[17:00:20.076] INFO: test: HighRate no parameter change
[17:00:20.076] INFO: running: highrate
[17:00:20.077] INFO: ----------------------------------------------------------------------
[17:00:20.077] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[17:00:20.077] INFO: ----------------------------------------------------------------------
[17:00:20.691] INFO: Expecting 208000 events.
[17:00:34.644] INFO: 208000 events read in total (13426ms).
[17:00:34.650] INFO: Test took 14564ms.
[17:00:34.965] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:00:35.275] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[17:00:35.275] INFO: number of red-efficiency pixels: 222 169 301 423 613 666 692 328 298 409 493 455 405 233 50 52
[17:00:35.275] INFO: number of X-ray hits detected: 140087 93798 143605 228415 246806 255545 255839 179406 182384 231195 229572 202330 207084 119605 50729 55047
[17:00:35.275] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[17:00:35.275] INFO: number of Vcal hits detected: 207768 207823 207659 207546 207319 207246 207212 207636 207685 207563 207455 207496 207568 207743 207949 207946
[17:00:35.275] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.7 99.7 99.8 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[17:00:35.275] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.8 99.7 99.6 99.6 99.8 99.8 99.8 99.7 99.8 99.8 99.9 100.0 100.0
[17:00:35.275] INFO: X-ray hit rate [MHz/cm2]: 41.1 27.5 42.1 67.0 72.3 74.9 75.0 52.6 53.5 67.8 67.3 59.3 60.7 35.1 14.9 16.1
[17:00:35.275] INFO: PixTestHighRate::doXPixelAlive() done
[17:00:35.322] INFO: PixTest:: pg_setup set to default.
[17:00:35.336] INFO: enter test to run
[17:01:01.267] INFO: test: HighRate no parameter change
[17:01:01.267] INFO: running: highrate
[17:01:01.269] INFO: ----------------------------------------------------------------------
[17:01:01.269] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[17:01:01.269] INFO: ----------------------------------------------------------------------
[17:01:01.888] INFO: Expecting 208000 events.
[17:01:18.013] INFO: 208000 events read in total (15598ms).
[17:01:18.021] INFO: Test took 16743ms.
[17:01:18.510] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:01:18.874] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[17:01:18.874] INFO: number of red-efficiency pixels: 421 303 724 1069 1453 1582 1602 703 642 963 1146 1088 906 557 85 92
[17:01:18.874] INFO: number of X-ray hits detected: 211583 142059 216221 344546 372215 386120 388160 272793 276240 350404 347209 307794 313473 181462 77523 83951
[17:01:18.874] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[17:01:18.874] INFO: number of Vcal hits detected: 207516 207658 207003 206674 206026 205728 205645 207142 207257 206839 206530 206571 206927 207320 207911 207907
[17:01:18.874] INFO: Vcal hit fiducial efficiency (%): 99.8 99.8 99.6 99.4 99.1 99.0 99.0 99.6 99.7 99.5 99.4 99.4 99.5 99.7 100.0 100.0
[17:01:18.874] INFO: Vcal hit overall efficiency (%): 99.8 99.8 99.5 99.4 99.1 98.9 98.9 99.6 99.6 99.4 99.3 99.3 99.5 99.7 100.0 100.0
[17:01:18.874] INFO: X-ray hit rate [MHz/cm2]: 62.0 41.6 63.4 101.0 109.1 113.2 113.8 80.0 81.0 102.7 101.8 90.2 91.9 53.2 22.7 24.6
[17:01:18.874] INFO: PixTestHighRate::doXPixelAlive() done
[17:01:18.923] INFO: PixTest:: pg_setup set to default.
[17:01:18.941] INFO: enter test to run
[17:01:55.291] INFO: test: exit no parameter change
[17:01:55.846] QUIET: Connection to board 33 closed.
[17:01:55.859] INFO: pXar: this is the end, my friend