[13:00:35.833] INFO: *** Welcome to pxar ***
[13:00:35.833] INFO: *** Today: 2016/06/08
[13:00:35.856] INFO: *** Version: v1.9.0-814-g7497
[13:00:35.857] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//dacParameters35_C15.dat
[13:00:35.857] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:00:35.857] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//defaultMaskFile.dat
[13:00:35.857] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C15.dat
[13:00:35.929] INFO: clk: 4
[13:00:35.929] INFO: ctr: 4
[13:00:35.929] INFO: sda: 19
[13:00:35.929] INFO: tin: 9
[13:00:35.929] INFO: level: 15
[13:00:35.929] INFO: triggerdelay: 0
[13:00:35.929] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[13:00:35.929] INFO: Log level: INFO
[13:00:35.945] QUIET: Connection to board DTB_WREKRL opened.
[13:00:35.948] 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:
------------------------------------------------------
[13:00:35.951] INFO: RPC call hashes of host and DTB match: 398089610
[13:00:37.488] INFO: DUT info:
[13:00:37.488] INFO: The DUT currently contains the following objects:
[13:00:37.488] INFO: 2 TBM Cores tbm08c (2 ON)
[13:00:37.488] INFO: TBM Core alpha (0): 7 registers set
[13:00:37.488] INFO: TBM Core beta (1): 7 registers set
[13:00:37.488] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[13:00:37.488] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[13:00:37.488] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[13:00:37.488] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[13:00:37.488] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[13:00:37.488] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[13:00:37.488] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[13:00:37.488] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[13:00:37.488] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[13:00:37.488] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[13:00:37.489] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[13:00:37.489] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[13:00:37.489] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[13:00:37.489] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[13:00:37.489] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[13:00:37.489] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[13:00:37.489] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[13:00:37.892] INFO: enter 'restricted' command line mode
[13:00:37.892] INFO: enter test to run
[13:00:39.499] INFO: test: timing no parameter change
[13:00:39.499] INFO: running: timing
[13:00:39.508] INFO: ######################################################################
[13:00:39.508] INFO: PixTestTiming::doTest()
[13:00:39.508] INFO: ######################################################################
[13:00:39.508] INFO: ----------------------------------------------------------------------
[13:00:39.509] INFO: PixTestTiming::TBMPhaseScan()
[13:00:39.509] INFO: ----------------------------------------------------------------------
[13:06:45.413] INFO: TBM Phase Settings: 236
[13:06:45.413] INFO: 400MHz Phase: 3
[13:06:45.413] INFO: 160MHz Phase: 7
[13:06:45.413] INFO: Functional Phase Area: 4
[13:06:45.416] INFO: Test took 365908 ms.
[13:06:45.416] INFO: PixTestTiming::TBMPhaseScan() done.
[13:06:45.416] INFO: ----------------------------------------------------------------------
[13:06:45.416] INFO: PixTestTiming::ROCDelayScan()
[13:06:45.416] INFO: ----------------------------------------------------------------------
[13:08:50.683] INFO: ROC Delay Settings: 228
[13:08:50.683] INFO: ROC Header-Trailer/Token Delay: 11
[13:08:50.683] INFO: ROC Port 0 Delay: 4
[13:08:50.683] INFO: ROC Port 1 Delay: 4
[13:08:50.683] INFO: Functional ROC Area: 5
[13:08:50.686] INFO: Test took 125270 ms.
[13:08:50.686] INFO: PixTestTiming::ROCDelayScan() done.
[13:08:50.686] INFO: ----------------------------------------------------------------------
[13:08:50.686] INFO: PixTestTiming::TimingTest()
[13:08:50.686] INFO: ----------------------------------------------------------------------
[13:09:06.816] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:09:21.805] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:09:36.783] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:09:51.744] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:10:06.687] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:10:21.661] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:10:36.638] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:10:51.587] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:11:06.556] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:11:21.723] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:11:22.101] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:11:22.119] INFO: ----------------------------------------------------------------------
[13:11:22.119] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[13:11:22.119] INFO: ----------------------------------------------------------------------
[13:11:22.119] INFO: ----------------------------------------------------------------------
[13:11:22.119] INFO: Read back bit status: 1
[13:11:22.119] INFO: ----------------------------------------------------------------------
[13:11:22.119] INFO: ----------------------------------------------------------------------
[13:11:22.119] INFO: Timings are good!
[13:11:22.119] INFO: ----------------------------------------------------------------------
[13:11:22.119] INFO: Test took 151433 ms.
[13:11:22.119] INFO: PixTestTiming::TimingTest() done.
[13:11:22.119] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//tbmParameters_C0a.dat
[13:11:22.119] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:11:22.119] INFO: PixTestTiming::doTest took 642615 ms.
[13:11:22.119] INFO: PixTestTiming::doTest() done
[13:11:22.119] INFO: Write out TBMPhaseScan_0_V0
[13:11:22.144] INFO: Write out TBMPhaseScan_1_V0
[13:11:22.144] INFO: Write out CombinedTBMPhaseScan_V0
[13:11:22.145] INFO: Write out ROCDelayScan3_V0
[13:11:22.145] INFO: enter test to run
[13:12:12.142] INFO: test: PixelAlive no parameter change
[13:12:12.142] INFO: running: pixelalive
[13:12:12.147] INFO: ----------------------------------------------------------------------
[13:12:12.147] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[13:12:12.147] INFO: ----------------------------------------------------------------------
[13:12:12.473] INFO: Expecting 41600 events.
[13:12:16.785] INFO: 41600 events read in total (3597ms).
[13:12:16.785] INFO: Test took 4635ms.
[13:12:16.792] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:12:17.188] INFO: PixTestAlive::aliveTest() done
[13:12:17.188] INFO: number of dead pixels (per ROC): 0 1 0 0 0 0 0 0 0 2 0 0 0 0 0 0
[13:12:17.193] INFO: enter test to run
[13:13:49.637] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[13:13:49.638] INFO: running: highrate
[13:13:49.638] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[13:13:49.798] INFO: ----------------------------------------------------------------------
[13:13:49.798] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[13:13:49.798] INFO: ----------------------------------------------------------------------
[13:13:49.798] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[13:13:49.798] INFO: edge/corner pixel THR is adjusted
[13:13:49.798] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:13:50.755] INFO: Collecting data for 5 seconds...
[13:13:55.776] INFO: Done with hot pixel readout
[13:14:08.115] INFO: PixTest:: pg_setup set to default.


[13:14:08.116] INFO: 11 hot pixels found in step 0
[13:14:09.112] INFO: Collecting data for 5 seconds...
[13:14:14.131] INFO: Done with hot pixel readout
[13:14:26.288] INFO: PixTest:: pg_setup set to default.



[13:14:26.289] INFO: 17 hot pixels found in step 1
[13:14:27.284] INFO: Collecting data for 5 seconds...
[13:14:32.304] INFO: Done with hot pixel readout
[13:14:44.588] INFO: PixTest:: pg_setup set to default.

[13:14:44.589] INFO: 13 hot pixels found in step 2
[13:14:45.585] INFO: Collecting data for 5 seconds...
[13:14:50.601] INFO: Done with hot pixel readout
[13:15:02.669] INFO: PixTest:: pg_setup set to default.


[13:15:02.670] INFO: 14 hot pixels found in step 3
[13:15:03.665] INFO: Collecting data for 5 seconds...
[13:15:08.681] INFO: Done with hot pixel readout
[13:15:20.766] INFO: PixTest:: pg_setup set to default.




[13:15:20.767] INFO: 15 hot pixels found in step 4
[13:15:21.762] INFO: Collecting data for 5 seconds...
[13:15:26.778] INFO: Done with hot pixel readout
[13:15:38.826] INFO: PixTest:: pg_setup set to default.




[13:15:38.827] INFO: 11 hot pixels found in step 5
[13:15:39.822] INFO: Collecting data for 5 seconds...
[13:15:44.838] INFO: Done with hot pixel readout
[13:15:56.879] INFO: PixTest:: pg_setup set to default.




[13:15:56.880] INFO: 13 hot pixels found in step 6
[13:15:57.876] INFO: Collecting data for 5 seconds...
[13:16:02.892] INFO: Done with hot pixel readout
[13:16:14.960] INFO: PixTest:: pg_setup set to default.



[13:16:14.961] INFO: 19 hot pixels found in step 7
[13:16:15.956] INFO: Collecting data for 5 seconds...
[13:16:20.972] INFO: Done with hot pixel readout
[13:16:33.020] INFO: PixTest:: pg_setup set to default.




[13:16:33.021] INFO: 13 hot pixels found in step 8
[13:16:34.016] INFO: Collecting data for 5 seconds...
[13:16:39.033] INFO: Done with hot pixel readout
[13:16:51.040] INFO: PixTest:: pg_setup set to default.


[13:16:51.041] INFO: 10 hot pixels found in step 9
[13:16:52.035] INFO: Collecting data for 5 seconds...
[13:16:57.052] INFO: Done with hot pixel readout
[13:17:09.095] INFO: PixTest:: pg_setup set to default.



[13:17:09.096] INFO: 14 hot pixels found in step 10
[13:17:10.091] INFO: Collecting data for 5 seconds...
[13:17:15.107] INFO: Done with hot pixel readout
[13:17:27.176] INFO: PixTest:: pg_setup set to default.



[13:17:27.177] INFO: 8 hot pixels found in step 11
[13:17:28.173] INFO: Collecting data for 5 seconds...
[13:17:33.189] INFO: Done with hot pixel readout
[13:17:45.238] INFO: PixTest:: pg_setup set to default.



[13:17:45.239] INFO: 8 hot pixels found in step 12
[13:17:46.235] INFO: Collecting data for 5 seconds...
[13:17:51.251] INFO: Done with hot pixel readout
[13:18:03.294] INFO: PixTest:: pg_setup set to default.




[13:18:03.294] INFO: 13 hot pixels found in step 13
[13:18:04.290] INFO: Collecting data for 5 seconds...
[13:18:09.307] INFO: Done with hot pixel readout
[13:18:21.412] INFO: PixTest:: pg_setup set to default.


[13:18:21.413] INFO: 14 hot pixels found in step 14
[13:18:21.452] INFO: 14 hot pixels could not be trimmed and have been masked.
[13:18:21.456] INFO: PixTest::trimHotPixels() done
[13:18:21.456] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C0.dat
[13:18:21.462] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C1.dat
[13:18:21.467] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C2.dat
[13:18:21.473] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C3.dat
[13:18:21.478] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C4.dat
[13:18:21.483] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C5.dat
[13:18:21.489] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C6.dat
[13:18:21.494] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C7.dat
[13:18:21.499] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C8.dat
[13:18:21.505] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C9.dat
[13:18:21.510] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C10.dat
[13:18:21.515] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C11.dat
[13:18:21.521] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C12.dat
[13:18:21.526] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C13.dat
[13:18:21.531] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C14.dat
[13:18:21.537] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C15.dat
[13:18:21.542] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//defaultMaskFile.dat
[13:18:21.553] INFO: enter test to run
[13:19:03.667] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[13:19:03.667] INFO: running: highrate
[13:19:03.672] INFO: ----------------------------------------------------------------------
[13:19:03.672] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[13:19:03.672] INFO: ----------------------------------------------------------------------
[13:19:03.672] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[13:19:03.672] INFO: edge/corner pixel THR is adjusted
[13:19:03.672] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:19:04.630] INFO: Collecting data for 1 seconds...
[13:19:05.634] INFO: Done with hot pixel readout
[13:19:09.711] INFO: PixTest:: pg_setup set to default.
[13:19:09.712] INFO: 0 hot pixels found in step 0
[13:19:09.717] INFO: 0 hot pixels could not be trimmed and have been masked.
[13:19:09.807] INFO: PixTest::trimHotPixels() done
[13:19:09.807] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C0.dat
[13:19:09.816] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C1.dat
[13:19:09.821] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C2.dat
[13:19:09.826] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C3.dat
[13:19:09.832] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C4.dat
[13:19:09.837] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C5.dat
[13:19:09.842] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C6.dat
[13:19:09.847] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C7.dat
[13:19:09.853] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C8.dat
[13:19:09.858] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C9.dat
[13:19:09.863] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C10.dat
[13:19:09.868] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C11.dat
[13:19:09.874] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C12.dat
[13:19:09.879] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C13.dat
[13:19:09.884] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C14.dat
[13:19:09.889] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//trimParameters35_C15.dat
[13:19:09.894] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-K-1-10_FPIXTest-17C-FNAL-160603-1303_2016-06-03_13h03m_1464977020/000_FPIXTest_p17//defaultMaskFile.dat
[13:19:09.904] INFO: enter test to run
[13:19:28.475] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[13:19:28.475] INFO: running: xray
[13:19:28.476] INFO: ----------------------------------------------------------------------
[13:19:28.476] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:19:28.476] INFO: ----------------------------------------------------------------------
[13:19:29.440] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:19:40.597] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[13:20:10.015] INFO: Resuming triggers.
[13:20:21.174] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[13:20:50.827] INFO: Resuming triggers.
[13:21:01.988] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[13:21:31.447] INFO: Resuming triggers.
[13:21:42.607] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[13:22:12.124] INFO: Resuming triggers.
[13:22:23.282] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[13:22:52.702] INFO: Resuming triggers.
[13:23:03.862] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[13:23:32.783] INFO: Resuming triggers.
[13:23:43.944] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[13:24:12.580] INFO: Resuming triggers.
[13:24:23.741] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[13:24:54.006] INFO: Resuming triggers.
[13:25:05.074] INFO: data taking finished, elapsed time: 100 seconds.
[13:25:35.036] INFO: PixTest:: pg_setup set to default.
[13:25:35.039] INFO: PixTestXray::doPhRun() done
[13:25:35.180] INFO: enter test to run
[13:26:50.816] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[13:26:50.816] INFO: running: xray
[13:26:50.817] INFO: ----------------------------------------------------------------------
[13:26:50.817] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:26:50.817] INFO: ----------------------------------------------------------------------
[13:26:51.801] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:26:58.259] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[13:27:28.410] INFO: Resuming triggers.
[13:27:34.870] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[13:28:04.850] INFO: Resuming triggers.
[13:28:11.313] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[13:28:41.566] INFO: Resuming triggers.
[13:28:48.026] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[13:29:18.176] INFO: Resuming triggers.
[13:29:24.634] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[13:29:54.835] INFO: Resuming triggers.
[13:30:01.292] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[13:30:31.391] INFO: Resuming triggers.
[13:30:37.844] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[13:31:08.090] INFO: Resuming triggers.
[13:31:14.547] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[13:31:44.558] INFO: Resuming triggers.
[13:31:51.015] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[13:32:21.117] INFO: Resuming triggers.
[13:32:27.571] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[13:32:57.687] INFO: Resuming triggers.
[13:33:04.144] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[13:33:34.278] INFO: Resuming triggers.
[13:33:40.737] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[13:34:11.212] INFO: Resuming triggers.
[13:34:17.674] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[13:34:48.896] INFO: Resuming triggers.
[13:34:55.355] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[13:35:25.974] INFO: Resuming triggers.
[13:35:32.436] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[13:36:03.882] INFO: Resuming triggers.
[13:36:07.339] INFO: data taking finished, elapsed time: 100 seconds.
[13:36:24.300] INFO: PixTest:: pg_setup set to default.
[13:36:24.303] INFO: PixTestXray::doPhRun() done
[13:36:24.466] INFO: enter test to run
[13:37:01.723] INFO: test: HighRate no parameter change
[13:37:01.724] INFO: running: highrate
[13:37:01.744] INFO: ----------------------------------------------------------------------
[13:37:01.744] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[13:37:01.744] INFO: ----------------------------------------------------------------------
[13:37:01.899] INFO: Expecting 768 events.
[13:37:03.034] INFO: 768 events read in total (419ms).
[13:37:03.034] INFO: Test took 1269ms.
[13:37:03.836] INFO: Expecting 41600 events.
[13:37:06.893] INFO: 41600 events read in total (2530ms).
[13:37:06.895] INFO: Test took 3854ms.
[13:37:06.930] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:07.656] INFO: Expecting 41600 events.
[13:37:10.921] INFO: 41600 events read in total (2738ms).
[13:37:10.922] INFO: Test took 3975ms.
[13:37:10.958] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:11.676] INFO: Expecting 41600 events.
[13:37:14.998] INFO: 41600 events read in total (2795ms).
[13:37:14.999] INFO: Test took 4022ms.
[13:37:15.036] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:15.756] INFO: Expecting 41600 events.
[13:37:19.006] INFO: 41600 events read in total (2723ms).
[13:37:19.007] INFO: Test took 3953ms.
[13:37:19.044] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:19.764] INFO: Expecting 41600 events.
[13:37:22.005] INFO: 41600 events read in total (2714ms).
[13:37:23.006] INFO: Test took 3944ms.
[13:37:23.042] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:23.763] INFO: Expecting 41600 events.
[13:37:27.020] INFO: 41600 events read in total (2730ms).
[13:37:27.021] INFO: Test took 3960ms.
[13:37:27.057] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:27.775] INFO: Expecting 41600 events.
[13:37:31.031] INFO: 41600 events read in total (2729ms).
[13:37:31.032] INFO: Test took 3956ms.
[13:37:31.069] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:31.789] INFO: Expecting 41600 events.
[13:37:35.048] INFO: 41600 events read in total (2732ms).
[13:37:35.049] INFO: Test took 3962ms.
[13:37:35.085] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:35.803] INFO: Expecting 41600 events.
[13:37:39.067] INFO: 41600 events read in total (2737ms).
[13:37:39.068] INFO: Test took 3964ms.
[13:37:39.104] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:39.824] INFO: Expecting 41600 events.
[13:37:43.079] INFO: 41600 events read in total (2729ms).
[13:37:43.080] INFO: Test took 3958ms.
[13:37:43.117] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:43.838] INFO: Expecting 41600 events.
[13:37:47.109] INFO: 41600 events read in total (2744ms).
[13:37:47.110] INFO: Test took 3973ms.
[13:37:47.146] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:47.866] INFO: Expecting 41600 events.
[13:37:51.129] INFO: 41600 events read in total (2736ms).
[13:37:51.130] INFO: Test took 3965ms.
[13:37:51.166] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:51.887] INFO: Expecting 41600 events.
[13:37:55.160] INFO: 41600 events read in total (2746ms).
[13:37:55.161] INFO: Test took 3975ms.
[13:37:55.197] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:55.916] INFO: Expecting 41600 events.
[13:37:59.179] INFO: 41600 events read in total (2736ms).
[13:37:59.181] INFO: Test took 3964ms.
[13:37:59.217] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:59.935] INFO: Expecting 41600 events.
[13:38:03.187] INFO: 41600 events read in total (2725ms).
[13:38:03.188] INFO: Test took 3952ms.
[13:38:03.224] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:03.941] INFO: Expecting 41600 events.
[13:38:07.200] INFO: 41600 events read in total (2732ms).
[13:38:07.201] INFO: Test took 3958ms.
[13:38:07.237] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:07.960] INFO: Expecting 41600 events.
[13:38:11.227] INFO: 41600 events read in total (2740ms).
[13:38:11.228] INFO: Test took 3971ms.
[13:38:11.264] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:11.983] INFO: Expecting 41600 events.
[13:38:15.247] INFO: 41600 events read in total (2737ms).
[13:38:15.248] INFO: Test took 3965ms.
[13:38:15.284] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:15.001] INFO: Expecting 41600 events.
[13:38:19.260] INFO: 41600 events read in total (2732ms).
[13:38:19.261] INFO: Test took 3958ms.
[13:38:19.297] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:20.018] INFO: Expecting 41600 events.
[13:38:23.252] INFO: 41600 events read in total (2707ms).
[13:38:23.253] INFO: Test took 3937ms.
[13:38:23.289] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:23.646] INFO: enter test to run
[13:39:24.154] INFO: test: HighRate no parameter change
[13:39:24.154] INFO: running: highrate
[13:39:24.155] INFO: ----------------------------------------------------------------------
[13:39:24.155] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:39:24.155] INFO: ----------------------------------------------------------------------
[13:39:24.771] INFO: Expecting 208000 events.
[13:39:36.689] INFO: 208000 events read in total (11391ms).
[13:39:36.692] INFO: Test took 12526ms.
[13:39:36.847] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:37.103] INFO: number of dead pixels (per ROC): 0 1 0 0 0 0 0 0 0 2 0 0 0 0 0 0
[13:39:37.103] INFO: number of red-efficiency pixels: 80 52 111 145 135 146 146 90 106 146 200 99 104 61 15 32
[13:39:37.103] INFO: number of X-ray hits detected: 72986 48296 74217 117622 121583 126605 125266 87688 94233 104047 101409 86282 86937 54437 24407 28131
[13:39:37.103] 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:39:37.103] INFO: number of Vcal hits detected: 207916 207898 207886 207850 207862 207851 207851 207908 207893 207751 207749 207900 207895 207939 207985 207968
[13:39:37.103] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[13:39:37.104] INFO: Vcal hit overall efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[13:39:37.104] INFO: X-ray hit rate [MHz/cm2]: 21.4 14.2 21.8 34.5 35.6 37.1 36.7 25.7 27.6 30.5 29.7 25.3 25.5 16.0 7.2 8.2
[13:39:37.104] INFO: PixTestHighRate::doXPixelAlive() done
[13:39:37.155] INFO: PixTest:: pg_setup set to default.
[13:39:37.172] INFO: enter test to run
[13:40:15.994] INFO: test: HighRate no parameter change
[13:40:15.994] INFO: running: highrate
[13:40:15.995] INFO: ----------------------------------------------------------------------
[13:40:15.995] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:40:15.995] INFO: ----------------------------------------------------------------------
[13:40:16.612] INFO: Expecting 208000 events.
[13:40:29.142] INFO: 208000 events read in total (12004ms).
[13:40:29.147] INFO: Test took 13143ms.
[13:40:29.450] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:40:29.755] INFO: number of dead pixels (per ROC): 0 1 0 0 0 0 0 0 0 2 0 0 0 0 0 0
[13:40:29.755] INFO: number of red-efficiency pixels: 228 156 364 569 389 500 452 263 339 459 456 241 299 233 59 69
[13:40:29.755] INFO: number of X-ray hits detected: 147702 99036 152919 239457 247943 257054 255869 178756 192693 212267 205542 176165 178120 110630 50412 57003
[13:40:29.755] 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:40:29.755] INFO: number of Vcal hits detected: 207759 207788 207586 207379 207583 207457 207507 207725 207638 207406 207471 207748 207691 207750 207941 207929
[13:40:29.755] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.7 99.8 99.8 99.8 99.9 99.8 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[13:40:29.755] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.7 99.8 99.7 99.8 99.9 99.8 99.7 99.7 99.9 99.9 99.9 100.0 100.0
[13:40:29.755] INFO: X-ray hit rate [MHz/cm2]: 43.3 29.0 44.8 70.2 72.7 75.3 75.0 52.4 56.5 62.2 60.2 51.6 52.2 32.4 14.8 16.7
[13:40:29.755] INFO: PixTestHighRate::doXPixelAlive() done
[13:40:29.802] INFO: PixTest:: pg_setup set to default.
[13:40:29.819] INFO: enter test to run
[13:40:55.521] INFO: test: HighRate no parameter change
[13:40:55.522] INFO: running: highrate
[13:40:55.523] INFO: ----------------------------------------------------------------------
[13:40:55.523] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:40:55.523] INFO: ----------------------------------------------------------------------
[13:40:56.138] INFO: Expecting 208000 events.
[13:41:12.009] INFO: 208000 events read in total (15344ms).
[13:41:12.017] INFO: Test took 16485ms.
[13:41:12.499] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:41:12.856] INFO: number of dead pixels (per ROC): 0 1 0 0 0 0 0 0 0 2 0 0 0 0 0 0
[13:41:12.856] INFO: number of red-efficiency pixels: 562 299 751 1252 982 1130 1090 617 798 1039 1028 555 693 461 141 114
[13:41:12.856] INFO: number of X-ray hits detected: 221968 148340 229045 359374 371073 385567 382238 268880 290664 318929 308672 263887 266650 166989 75499 86428
[13:41:12.856] 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:41:12.856] INFO: number of Vcal hits detected: 207297 207626 206958 206349 206790 206540 206650 207245 207090 206662 206756 207373 207207 207466 207852 207882
[13:41:12.856] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.6 99.3 99.5 99.4 99.4 99.7 99.6 99.5 99.4 99.7 99.7 99.8 99.9 99.9
[13:41:12.856] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.5 99.2 99.4 99.3 99.4 99.6 99.6 99.4 99.4 99.7 99.6 99.7 99.9 99.9
[13:41:12.856] INFO: X-ray hit rate [MHz/cm2]: 65.1 43.5 67.1 105.3 108.8 113.0 112.0 78.8 85.2 93.5 90.5 77.3 78.2 48.9 22.1 25.3
[13:41:12.856] INFO: PixTestHighRate::doXPixelAlive() done
[13:41:12.901] INFO: PixTest:: pg_setup set to default.
[13:41:12.913] INFO: enter test to run
[13:41:15.745] INFO: test: exit no parameter change
[13:41:16.173] QUIET: Connection to board 33 closed.
[13:41:16.175] INFO: pXar: this is the end, my friend