[14:25:50.414] INFO: *** Welcome to pxar ***
[14:25:50.414] INFO: *** Today: 2016/10/03
[14:25:51.205] INFO: *** Version: v1.9.0-818-g96727
[14:25:51.205] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//dacParameters35_C15.dat
[14:25:51.236] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:25:51.241] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//defaultMaskFile.dat
[14:25:51.254] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C15.dat
[14:25:51.367] INFO: clk: 4
[14:25:51.367] INFO: ctr: 4
[14:25:51.367] INFO: sda: 19
[14:25:51.367] INFO: tin: 9
[14:25:51.367] INFO: level: 15
[14:25:51.367] INFO: triggerdelay: 0
[14:25:51.367] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[14:25:51.367] INFO: Log level: INFO
[14:25:51.385] QUIET: Connection to board DTB_WREKRL opened.
[14:25:51.389] 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:
------------------------------------------------------
[14:25:51.391] INFO: RPC call hashes of host and DTB match: 398089610
[14:25:52.920] INFO: DUT info:
[14:25:52.920] INFO: The DUT currently contains the following objects:
[14:25:52.920] INFO: 2 TBM Cores tbm08c (2 ON)
[14:25:52.920] INFO: TBM Core alpha (0): 7 registers set
[14:25:52.920] INFO: TBM Core beta (1): 7 registers set
[14:25:52.921] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[14:25:52.921] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[14:25:52.921] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[14:25:52.921] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[14:25:52.921] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[14:25:52.921] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[14:25:52.921] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[14:25:52.921] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[14:25:52.921] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[14:25:52.921] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[14:25:52.921] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[14:25:52.921] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[14:25:52.921] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[14:25:52.921] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[14:25:52.921] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[14:25:52.921] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[14:25:52.921] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[14:25:53.325] INFO: enter 'restricted' command line mode
[14:25:53.325] INFO: enter test to run
[14:26:01.705] INFO: test: PixelAlive no parameter change
[14:26:01.705] INFO: running: pixelalive
[14:26:01.759] INFO: ----------------------------------------------------------------------
[14:26:01.759] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[14:26:01.759] INFO: ----------------------------------------------------------------------
[14:26:02.092] INFO: Expecting 41600 events.
[14:26:06.423] INFO: 41600 events read in total (3612ms).
[14:26:06.591] INFO: Test took 4815ms.
[14:26:06.604] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:26:06.939] INFO: PixTestAlive::aliveTest() done
[14:26:06.939] INFO: number of dead pixels (per ROC): 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[14:26:06.970] INFO: enter test to run
[14:26:13.441] INFO: test: timing no parameter change
[14:26:13.441] INFO: running: timing
[14:26:13.459] INFO: ######################################################################
[14:26:13.459] INFO: PixTestTiming::doTest()
[14:26:13.459] INFO: ######################################################################
[14:26:13.459] INFO: ----------------------------------------------------------------------
[14:26:13.459] INFO: PixTestTiming::TBMPhaseScan()
[14:26:13.459] INFO: ----------------------------------------------------------------------
[14:33:46.516] INFO: TBM Phase Settings: 248
[14:33:46.516] INFO: 400MHz Phase: 6
[14:33:46.516] INFO: 160MHz Phase: 7
[14:33:46.516] INFO: Functional Phase Area: 3
[14:33:46.525] INFO: Test took 453066 ms.
[14:33:46.525] INFO: PixTestTiming::TBMPhaseScan() done.
[14:33:46.525] INFO: ----------------------------------------------------------------------
[14:33:46.525] INFO: PixTestTiming::ROCDelayScan()
[14:33:46.525] INFO: ----------------------------------------------------------------------
[14:35:42.754] INFO: ROC Delay Settings: 228
[14:35:42.754] INFO: ROC Header-Trailer/Token Delay: 11
[14:35:42.754] INFO: ROC Port 0 Delay: 4
[14:35:42.754] INFO: ROC Port 1 Delay: 4
[14:35:42.754] INFO: Functional ROC Area: 4
[14:35:42.757] INFO: Test took 116232 ms.
[14:35:42.757] INFO: PixTestTiming::ROCDelayScan() done.
[14:35:42.758] INFO: ----------------------------------------------------------------------
[14:35:42.758] INFO: PixTestTiming::TimingTest()
[14:35:42.758] INFO: ----------------------------------------------------------------------
[14:35:58.810] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:36:13.840] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:36:28.842] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:36:43.832] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:36:58.874] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:37:13.893] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:37:28.930] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:37:43.894] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:37:58.878] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:38:13.844] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:38:14.225] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:38:14.244] INFO: ----------------------------------------------------------------------
[14:38:14.244] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[14:38:14.244] INFO: ----------------------------------------------------------------------
[14:38:14.244] INFO: ----------------------------------------------------------------------
[14:38:14.244] INFO: Read back bit status: 1
[14:38:14.244] INFO: ----------------------------------------------------------------------
[14:38:14.244] INFO: ----------------------------------------------------------------------
[14:38:14.244] INFO: Timings are good!
[14:38:14.244] INFO: ----------------------------------------------------------------------
[14:38:14.244] INFO: Test took 151487 ms.
[14:38:14.244] INFO: PixTestTiming::TimingTest() done.
[14:38:14.255] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//tbmParameters_C0a.dat
[14:38:14.270] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:38:14.270] INFO: PixTestTiming::doTest took 720814 ms.
[14:38:14.270] INFO: PixTestTiming::doTest() done
[14:38:14.270] INFO: Write out TBMPhaseScan_0_V0
[14:38:14.270] INFO: Write out TBMPhaseScan_1_V0
[14:38:14.270] INFO: Write out CombinedTBMPhaseScan_V0
[14:38:14.305] INFO: Write out ROCDelayScan3_V0
[14:38:14.306] INFO: enter test to run
[14:39:52.155] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[14:39:52.155] INFO: running: highrate
[14:39:52.172] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[14:39:52.463] INFO: ----------------------------------------------------------------------
[14:39:52.463] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[14:39:52.463] INFO: ----------------------------------------------------------------------
[14:39:52.463] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[14:39:52.463] INFO: edge/corner pixel THR is adjusted
[14:39:52.463] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:39:53.443] INFO: Collecting data for 5 seconds...
[14:39:58.460] INFO: Done with hot pixel readout
[14:40:09.925] INFO: PixTest:: pg_setup set to default.
[14:40:09.926] INFO: 23 hot pixels found in step 0
[14:40:10.917] INFO: Collecting data for 5 seconds...
[14:40:15.934] INFO: Done with hot pixel readout
[14:40:27.517] INFO: PixTest:: pg_setup set to default.
[14:40:27.518] INFO: 20 hot pixels found in step 1
[14:40:28.509] INFO: Collecting data for 5 seconds...
[14:40:33.526] INFO: Done with hot pixel readout
[14:40:45.033] INFO: PixTest:: pg_setup set to default.
[14:40:45.034] INFO: 21 hot pixels found in step 2
[14:40:46.026] INFO: Collecting data for 5 seconds...
[14:40:51.043] INFO: Done with hot pixel readout
[14:41:02.557] INFO: PixTest:: pg_setup set to default.
[14:41:02.558] INFO: 23 hot pixels found in step 3
[14:41:03.549] INFO: Collecting data for 5 seconds...
[14:41:08.565] INFO: Done with hot pixel readout
[14:41:20.126] INFO: PixTest:: pg_setup set to default.
[14:41:20.127] INFO: 21 hot pixels found in step 4
[14:41:21.119] INFO: Collecting data for 5 seconds...
[14:41:26.136] INFO: Done with hot pixel readout
[14:41:37.656] INFO: PixTest:: pg_setup set to default.
[14:41:37.657] INFO: 21 hot pixels found in step 5
[14:41:38.649] INFO: Collecting data for 5 seconds...
[14:41:43.666] INFO: Done with hot pixel readout
[14:41:55.236] INFO: PixTest:: pg_setup set to default.
[14:41:55.237] INFO: 18 hot pixels found in step 6
[14:41:56.228] INFO: Collecting data for 5 seconds...
[14:42:01.245] INFO: Done with hot pixel readout
[14:42:12.644] INFO: PixTest:: pg_setup set to default.
[14:42:12.645] INFO: 18 hot pixels found in step 7
[14:42:13.637] INFO: Collecting data for 5 seconds...
[14:42:18.653] INFO: Done with hot pixel readout
[14:42:29.834] INFO: PixTest:: pg_setup set to default.
[14:42:29.835] INFO: 9 hot pixels found in step 8
[14:42:30.827] INFO: Collecting data for 5 seconds...
[14:42:35.844] INFO: Done with hot pixel readout
[14:42:47.104] INFO: PixTest:: pg_setup set to default.

[14:42:47.105] INFO: 8 hot pixels found in step 9
[14:42:48.097] INFO: Collecting data for 5 seconds...
[14:42:53.115] INFO: Done with hot pixel readout
[14:43:04.359] INFO: PixTest:: pg_setup set to default.
[14:43:04.360] INFO: 7 hot pixels found in step 10
[14:43:05.352] INFO: Collecting data for 5 seconds...
[14:43:10.370] INFO: Done with hot pixel readout
[14:43:21.783] INFO: PixTest:: pg_setup set to default.
[14:43:21.784] INFO: 3 hot pixels found in step 11
[14:43:22.777] INFO: Collecting data for 5 seconds...
[14:43:27.795] INFO: Done with hot pixel readout
[14:43:39.065] INFO: PixTest:: pg_setup set to default.

[14:43:39.066] INFO: 3 hot pixels found in step 12
[14:43:40.058] INFO: Collecting data for 5 seconds...
[14:43:45.075] INFO: Done with hot pixel readout
[14:43:56.729] INFO: PixTest:: pg_setup set to default.

[14:43:56.730] INFO: 2 hot pixels found in step 13
[14:43:57.722] INFO: Collecting data for 5 seconds...
[14:44:02.741] INFO: Done with hot pixel readout
[14:44:14.451] INFO: PixTest:: pg_setup set to default.

[14:44:14.452] INFO: 6 hot pixels found in step 14
[14:44:14.488] INFO: 6 hot pixels could not be trimmed and have been masked.
[14:44:14.492] INFO: PixTest::trimHotPixels() done
[14:44:14.598] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C0.dat
[14:44:14.637] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C1.dat
[14:44:14.648] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C2.dat
[14:44:14.657] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C3.dat
[14:44:14.662] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C4.dat
[14:44:14.668] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C5.dat
[14:44:14.673] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C6.dat
[14:44:14.678] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C7.dat
[14:44:14.684] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C8.dat
[14:44:14.689] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C9.dat
[14:44:14.694] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C10.dat
[14:44:14.700] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C11.dat
[14:44:14.705] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C12.dat
[14:44:14.711] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C13.dat
[14:44:14.716] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C14.dat
[14:44:14.721] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C15.dat
[14:44:14.727] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//defaultMaskFile.dat
[14:44:14.737] INFO: enter test to run
[14:46:26.456] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[14:46:26.456] INFO: running: highrate
[14:46:26.461] INFO: ----------------------------------------------------------------------
[14:46:26.461] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[14:46:26.461] INFO: ----------------------------------------------------------------------
[14:46:26.461] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[14:46:26.461] INFO: edge/corner pixel THR is adjusted
[14:46:26.461] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:46:27.419] INFO: Collecting data for 1 seconds...
[14:46:28.423] INFO: Done with hot pixel readout
[14:46:32.443] INFO: PixTest:: pg_setup set to default.
[14:46:32.444] INFO: 0 hot pixels found in step 0
[14:46:32.449] INFO: 0 hot pixels could not be trimmed and have been masked.
[14:46:32.540] INFO: PixTest::trimHotPixels() done
[14:46:32.540] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C0.dat
[14:46:32.548] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C1.dat
[14:46:32.555] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C2.dat
[14:46:32.560] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C3.dat
[14:46:32.565] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C4.dat
[14:46:32.571] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C5.dat
[14:46:32.576] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C6.dat
[14:46:32.582] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C7.dat
[14:46:32.587] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C8.dat
[14:46:32.592] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C9.dat
[14:46:32.597] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C10.dat
[14:46:32.603] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C11.dat
[14:46:32.608] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C12.dat
[14:46:32.614] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C13.dat
[14:46:32.619] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C14.dat
[14:46:32.624] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//trimParameters35_C15.dat
[14:46:32.629] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-9-23_FPIXTest-17C-FNAL-160927-1236-150V_2016-09-27_12h36m_1474997785/000_FPIXTest_p17//defaultMaskFile.dat
[14:46:32.648] INFO: enter test to run
[14:46:50.489] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[14:46:50.489] INFO: running: xray
[14:46:50.509] INFO: ----------------------------------------------------------------------
[14:46:50.509] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:46:50.509] INFO: ----------------------------------------------------------------------
[14:46:51.495] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:47:03.241] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[14:47:32.973] INFO: Resuming triggers.
[14:47:44.718] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[14:48:14.098] INFO: Resuming triggers.
[14:48:25.842] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[14:48:55.891] INFO: Resuming triggers.
[14:49:07.638] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[14:49:38.091] INFO: Resuming triggers.
[14:49:49.835] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[14:50:20.210] INFO: Resuming triggers.
[14:50:31.960] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[14:51:01.612] INFO: Resuming triggers.
[14:51:13.356] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[14:51:42.759] INFO: Resuming triggers.
[14:51:54.503] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[14:52:23.767] INFO: Resuming triggers.
[14:52:30.176] INFO: data taking finished, elapsed time: 100 seconds.
[14:52:46.453] INFO: PixTest:: pg_setup set to default.
[14:52:46.457] INFO: PixTestXray::doPhRun() done
[14:52:46.719] INFO: enter test to run
[14:53:01.630] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[14:53:01.630] INFO: running: xray
[14:53:01.631] INFO: ----------------------------------------------------------------------
[14:53:01.631] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:53:01.631] INFO: ----------------------------------------------------------------------
[14:53:02.595] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:53:09.482] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[14:53:39.696] INFO: Resuming triggers.
[14:53:46.579] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[14:54:16.868] INFO: Resuming triggers.
[14:54:23.753] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[14:54:53.904] INFO: Resuming triggers.
[14:55:00.791] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[14:55:31.126] INFO: Resuming triggers.
[14:55:37.005] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[14:56:08.209] INFO: Resuming triggers.
[14:56:15.095] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[14:56:45.239] INFO: Resuming triggers.
[14:56:52.121] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[14:57:22.338] INFO: Resuming triggers.
[14:57:29.220] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[14:57:59.834] INFO: Resuming triggers.
[14:58:06.715] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[14:58:37.806] INFO: Resuming triggers.
[14:58:44.692] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[14:59:15.609] INFO: Resuming triggers.
[14:59:22.494] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[14:59:53.279] INFO: Resuming triggers.
[15:00:00.167] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[15:00:30.522] INFO: Resuming triggers.
[15:00:37.408] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[15:01:06.460] INFO: Resuming triggers.
[15:01:13.351] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[15:01:41.976] INFO: Resuming triggers.
[15:01:45.931] INFO: data taking finished, elapsed time: 100 seconds.
[15:02:03.714] INFO: PixTest:: pg_setup set to default.
[15:02:03.717] INFO: PixTestXray::doPhRun() done
[15:02:03.892] INFO: enter test to run
[15:03:06.002] INFO: test: HighRate no parameter change
[15:03:06.002] INFO: running: highrate
[15:03:07.011] INFO: ----------------------------------------------------------------------
[15:03:07.011] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[15:03:07.011] INFO: ----------------------------------------------------------------------
[15:03:07.176] INFO: Expecting 768 events.
[15:03:08.306] INFO: 768 events read in total (414ms).
[15:03:08.306] INFO: Test took 1276ms.
[15:03:09.109] INFO: Expecting 41600 events.
[15:03:12.165] INFO: 41600 events read in total (2529ms).
[15:03:12.166] INFO: Test took 3824ms.
[15:03:12.217] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:03:12.921] INFO: Expecting 41600 events.
[15:03:16.202] INFO: 41600 events read in total (2754ms).
[15:03:16.203] INFO: Test took 3970ms.
[15:03:16.237] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:03:16.965] INFO: Expecting 41600 events.
[15:03:20.242] INFO: 41600 events read in total (2751ms).
[15:03:20.243] INFO: Test took 3990ms.
[15:03:20.276] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:03:20.000] INFO: Expecting 41600 events.
[15:03:24.396] INFO: 41600 events read in total (2869ms).
[15:03:24.397] INFO: Test took 4104ms.
[15:03:24.429] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:03:25.157] INFO: Expecting 41600 events.
[15:03:28.211] INFO: 41600 events read in total (2527ms).
[15:03:28.212] INFO: Test took 3766ms.
[15:03:28.244] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:03:28.973] INFO: Expecting 41600 events.
[15:03:32.158] INFO: 41600 events read in total (2658ms).
[15:03:32.159] INFO: Test took 3899ms.
[15:03:32.191] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:03:32.918] INFO: Expecting 41600 events.
[15:03:36.237] INFO: 41600 events read in total (2793ms).
[15:03:36.238] INFO: Test took 4030ms.
[15:03:36.270] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:03:36.995] INFO: Expecting 41600 events.
[15:03:40.237] INFO: 41600 events read in total (2716ms).
[15:03:40.238] INFO: Test took 3951ms.
[15:03:40.270] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:03:40.998] INFO: Expecting 41600 events.
[15:03:44.279] INFO: 41600 events read in total (2754ms).
[15:03:44.280] INFO: Test took 3992ms.
[15:03:44.312] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:03:45.039] INFO: Expecting 41600 events.
[15:03:48.060] INFO: 41600 events read in total (2494ms).
[15:03:48.061] INFO: Test took 3731ms.
[15:03:48.095] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:03:48.819] INFO: Expecting 41600 events.
[15:03:52.163] INFO: 41600 events read in total (2818ms).
[15:03:52.164] INFO: Test took 4053ms.
[15:03:52.204] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:03:52.898] INFO: Expecting 41600 events.
[15:03:56.130] INFO: 41600 events read in total (2705ms).
[15:03:56.130] INFO: Test took 3903ms.
[15:03:56.163] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:03:56.892] INFO: Expecting 41600 events.
[15:04:00.106] INFO: 41600 events read in total (2688ms).
[15:04:00.107] INFO: Test took 3927ms.
[15:04:00.139] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:04:00.871] INFO: Expecting 41600 events.
[15:04:04.090] INFO: 41600 events read in total (2692ms).
[15:04:04.091] INFO: Test took 3936ms.
[15:04:04.123] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:04:04.854] INFO: Expecting 41600 events.
[15:04:08.124] INFO: 41600 events read in total (2744ms).
[15:04:08.125] INFO: Test took 3984ms.
[15:04:08.164] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:04:08.884] INFO: Expecting 41600 events.
[15:04:12.105] INFO: 41600 events read in total (2694ms).
[15:04:12.105] INFO: Test took 3922ms.
[15:04:12.138] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:04:12.868] INFO: Expecting 41600 events.
[15:04:16.112] INFO: 41600 events read in total (2718ms).
[15:04:16.113] INFO: Test took 3958ms.
[15:04:16.145] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:04:16.873] INFO: Expecting 41600 events.
[15:04:20.169] INFO: 41600 events read in total (2769ms).
[15:04:20.170] INFO: Test took 4008ms.
[15:04:20.202] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:04:20.929] INFO: Expecting 41600 events.
[15:04:24.233] INFO: 41600 events read in total (2778ms).
[15:04:24.234] INFO: Test took 4013ms.
[15:04:24.271] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:04:24.986] INFO: Expecting 41600 events.
[15:04:27.910] INFO: 41600 events read in total (2397ms).
[15:04:27.911] INFO: Test took 3624ms.
[15:04:27.942] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:04:28.309] INFO: enter test to run
[15:05:06.809] INFO: test: HighRate no parameter change
[15:05:06.809] INFO: running: highrate
[15:05:06.810] INFO: ----------------------------------------------------------------------
[15:05:06.810] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:05:06.810] INFO: ----------------------------------------------------------------------
[15:05:07.431] INFO: Expecting 208000 events.
[15:05:19.328] INFO: 208000 events read in total (11371ms).
[15:05:19.331] INFO: Test took 12511ms.
[15:05:19.467] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:19.716] INFO: number of dead pixels (per ROC): 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:05:19.716] INFO: number of red-efficiency pixels: 78 36 65 123 137 116 105 67 73 97 102 83 88 67 18 17
[15:05:19.716] INFO: number of X-ray hits detected: 63911 40707 57914 96381 98936 104283 96093 68567 68802 89780 88462 74676 76140 47228 20252 24428
[15:05:19.716] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:05:19.716] INFO: number of Vcal hits detected: 207873 207963 207935 207873 207861 207881 207892 207932 207926 207903 207895 207915 207909 207931 207982 207983
[15:05:19.716] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[15:05:19.716] INFO: Vcal hit overall efficiency (%): 99.9 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0
[15:05:19.716] INFO: X-ray hit rate [MHz/cm2]: 18.7 11.9 17.0 28.2 29.0 30.6 28.2 20.1 20.2 26.3 25.9 21.9 22.3 13.8 5.9 7.2
[15:05:19.716] INFO: PixTestHighRate::doXPixelAlive() done
[15:05:19.765] INFO: PixTest:: pg_setup set to default.
[15:05:19.781] INFO: enter test to run
[15:05:40.801] INFO: test: HighRate no parameter change
[15:05:40.801] INFO: running: highrate
[15:05:40.802] INFO: ----------------------------------------------------------------------
[15:05:40.802] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:05:40.802] INFO: ----------------------------------------------------------------------
[15:05:41.425] INFO: Expecting 208000 events.
[15:05:55.044] INFO: 208000 events read in total (13092ms).
[15:05:55.051] INFO: Test took 14240ms.
[15:05:55.341] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:55.638] INFO: number of dead pixels (per ROC): 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:05:55.638] INFO: number of red-efficiency pixels: 198 98 192 476 483 408 309 182 255 360 303 308 270 173 44 59
[15:05:55.638] INFO: number of X-ray hits detected: 138751 89822 127371 210565 216375 226712 209240 149217 151654 196077 195210 163373 166485 103839 45453 53665
[15:05:55.638] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:05:55.638] INFO: number of Vcal hits detected: 207741 207894 207797 207492 207481 207563 207676 207809 207737 207620 207662 207677 207721 207816 207956 207940
[15:05:55.638] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 99.9 99.8 99.8 99.8 99.9 99.9 99.9 99.8 99.9 99.9 99.9 99.9 100.0 100.0
[15:05:55.638] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.8 99.8 99.8 99.9 99.9 100.0 100.0
[15:05:55.638] INFO: X-ray hit rate [MHz/cm2]: 40.7 26.3 37.3 61.7 63.4 66.5 61.3 43.7 44.5 57.5 57.2 47.9 48.8 30.4 13.3 15.7
[15:05:55.638] INFO: PixTestHighRate::doXPixelAlive() done
[15:05:55.687] INFO: PixTest:: pg_setup set to default.
[15:05:55.700] INFO: enter test to run
[15:06:09.497] INFO: test: HighRate no parameter change
[15:06:09.497] INFO: running: highrate
[15:06:09.498] INFO: ----------------------------------------------------------------------
[15:06:09.498] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:06:09.498] INFO: ----------------------------------------------------------------------
[15:06:10.115] INFO: Expecting 208000 events.
[15:06:25.664] INFO: 208000 events read in total (15022ms).
[15:06:25.671] INFO: Test took 16164ms.
[15:06:26.122] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:06:26.468] INFO: number of dead pixels (per ROC): 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:06:26.468] INFO: number of red-efficiency pixels: 474 194 435 1120 1210 987 770 436 541 839 691 673 665 438 92 90
[15:06:26.468] INFO: number of X-ray hits detected: 213458 137723 194749 322818 333290 349705 322152 230029 232958 300157 297930 251397 255623 160537 69366 83051
[15:06:26.468] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:06:26.468] INFO: number of Vcal hits detected: 207386 207783 207486 206576 206470 206799 207096 207506 207363 207019 207192 207230 207238 207487 207906 207904
[15:06:26.468] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.4 99.3 99.5 99.6 99.8 99.7 99.6 99.6 99.7 99.7 99.8 100.0 100.0
[15:06:26.468] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.8 99.3 99.3 99.4 99.6 99.8 99.7 99.5 99.6 99.6 99.6 99.8 100.0 100.0
[15:06:26.468] INFO: X-ray hit rate [MHz/cm2]: 62.6 40.4 57.1 94.6 97.7 102.5 94.4 67.4 68.3 88.0 87.3 73.7 74.9 47.1 20.3 24.3
[15:06:26.468] INFO: PixTestHighRate::doXPixelAlive() done
[15:06:26.517] INFO: PixTest:: pg_setup set to default.
[15:06:26.532] INFO: enter test to run
[15:06:42.448] INFO: test: exit no parameter change
[15:06:43.049] QUIET: Connection to board 33 closed.
[15:06:43.205] INFO: pXar: this is the end, my friend