[13:41:52.595] INFO: *** Welcome to pxar ***
[13:41:52.595] INFO: *** Today: 2016/10/20
[13:41:52.746] INFO: *** Version: v1.9.0-818-g96727
[13:41:52.746] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//dacParameters35_C15.dat
[13:41:52.747] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:41:52.747] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//defaultMaskFile.dat
[13:41:52.747] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C15.dat
[13:41:52.820] INFO: clk: 4
[13:41:52.820] INFO: ctr: 4
[13:41:52.820] INFO: sda: 19
[13:41:52.820] INFO: tin: 9
[13:41:52.820] INFO: level: 15
[13:41:52.820] INFO: triggerdelay: 0
[13:41:52.820] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[13:41:52.820] INFO: Log level: INFO
[13:41:52.836] QUIET: Connection to board DTB_WREKRL opened.
[13:41:52.839] 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:41:52.842] INFO: RPC call hashes of host and DTB match: 398089610
[13:41:54.376] INFO: DUT info:
[13:41:54.376] INFO: The DUT currently contains the following objects:
[13:41:54.376] INFO: 2 TBM Cores tbm08c (2 ON)
[13:41:54.376] INFO: TBM Core alpha (0): 7 registers set
[13:41:54.376] INFO: TBM Core beta (1): 7 registers set
[13:41:54.376] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[13:41:54.377] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:54.377] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:54.377] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:54.377] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:54.377] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:54.377] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:54.377] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:54.377] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:54.377] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:54.377] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:54.377] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:54.377] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:54.377] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:54.377] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:54.378] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:54.378] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:54.781] INFO: enter 'restricted' command line mode
[13:41:54.781] INFO: enter test to run
[13:42:05.458] INFO: test: PixelAlive no parameter change
[13:42:05.458] INFO: running: pixelalive
[13:42:05.465] INFO: ----------------------------------------------------------------------
[13:42:05.465] 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:42:05.465] INFO: ----------------------------------------------------------------------
[13:42:05.784] INFO: Expecting 41600 events.
[13:42:10.131] INFO: 41600 events read in total (3629ms).
[13:42:10.300] INFO: Test took 4833ms.
[13:42:10.313] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:42:10.577] INFO: PixTestAlive::aliveTest() done
[13:42:10.577] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 1 1 0 0 0 0 0 0 0
[13:42:10.632] INFO: enter test to run
[13:42:21.530] INFO: test: timing no parameter change
[13:42:21.530] INFO: running: timing
[13:42:21.533] INFO: ######################################################################
[13:42:21.534] INFO: PixTestTiming::doTest()
[13:42:21.534] INFO: ######################################################################
[13:42:21.534] INFO: ----------------------------------------------------------------------
[13:42:21.534] INFO: PixTestTiming::TBMPhaseScan()
[13:42:21.534] INFO: ----------------------------------------------------------------------
[13:47:23.070] INFO: TBM Phase Settings: 240
[13:47:23.071] INFO: 400MHz Phase: 4
[13:47:23.071] INFO: 160MHz Phase: 7
[13:47:23.071] INFO: Functional Phase Area: 4
[13:47:23.080] INFO: Test took 301546 ms.
[13:47:23.080] INFO: PixTestTiming::TBMPhaseScan() done.
[13:47:23.080] INFO: ----------------------------------------------------------------------
[13:47:23.080] INFO: PixTestTiming::ROCDelayScan()
[13:47:23.080] INFO: ----------------------------------------------------------------------
[13:50:12.876] INFO: ROC Delay Settings: 227
[13:50:12.876] INFO: ROC Header-Trailer/Token Delay: 11
[13:50:12.877] INFO: ROC Port 0 Delay: 3
[13:50:12.877] INFO: ROC Port 1 Delay: 4
[13:50:12.877] INFO: Functional ROC Area: 4
[13:50:12.880] INFO: Test took 169800 ms.
[13:50:12.880] INFO: PixTestTiming::ROCDelayScan() done.
[13:50:12.880] INFO: ----------------------------------------------------------------------
[13:50:12.880] INFO: PixTestTiming::TimingTest()
[13:50:12.880] INFO: ----------------------------------------------------------------------
[13:50:28.004] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:43.975] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:58.913] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:51:13.865] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:51:28.843] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:51:43.832] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:51:58.772] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:52:13.749] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:52:28.722] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:52:43.676] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:52:44.058] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:52:44.076] INFO: ----------------------------------------------------------------------
[13:52:44.076] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[13:52:44.076] INFO: ----------------------------------------------------------------------
[13:52:44.076] INFO: ----------------------------------------------------------------------
[13:52:44.076] INFO: Read back bit status: 1
[13:52:44.076] INFO: ----------------------------------------------------------------------
[13:52:44.076] INFO: ----------------------------------------------------------------------
[13:52:44.076] INFO: Timings are good!
[13:52:44.076] INFO: ----------------------------------------------------------------------
[13:52:44.076] INFO: Test took 151196 ms.
[13:52:44.076] INFO: PixTestTiming::TimingTest() done.
[13:52:44.092] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//tbmParameters_C0a.dat
[13:52:44.092] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:52:44.092] INFO: PixTestTiming::doTest took 622562 ms.
[13:52:44.092] INFO: PixTestTiming::doTest() done
[13:52:44.093] INFO: Write out TBMPhaseScan_0_V0
[13:52:44.093] INFO: Write out TBMPhaseScan_1_V0
[13:52:44.093] INFO: Write out CombinedTBMPhaseScan_V0
[13:52:44.118] INFO: Write out ROCDelayScan3_V0
[13:52:44.118] INFO: enter test to run
[13:53:29.269] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[13:53:29.269] INFO: running: highrate
[13:53:29.293] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[13:53:29.592] INFO: ----------------------------------------------------------------------
[13:53:29.592] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[13:53:29.593] INFO: ----------------------------------------------------------------------
[13:53:29.593] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[13:53:29.593] INFO: edge/corner pixel THR is adjusted
[13:53:29.593] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:53:30.563] INFO: Collecting data for 5 seconds...
[13:53:35.580] INFO: Done with hot pixel readout
[13:53:47.372] INFO: PixTest:: pg_setup set to default.
[13:53:47.373] INFO: 43 hot pixels found in step 0
[13:53:48.367] INFO: Collecting data for 5 seconds...
[13:53:53.384] INFO: Done with hot pixel readout
[13:54:05.129] INFO: PixTest:: pg_setup set to default.
[13:54:05.130] INFO: 42 hot pixels found in step 1
[13:54:06.123] INFO: Collecting data for 5 seconds...
[13:54:11.141] INFO: Done with hot pixel readout
[13:54:22.928] INFO: PixTest:: pg_setup set to default.
[13:54:22.929] INFO: 40 hot pixels found in step 2
[13:54:23.921] INFO: Collecting data for 5 seconds...
[13:54:28.938] INFO: Done with hot pixel readout
[13:54:40.689] INFO: PixTest:: pg_setup set to default.

[13:54:40.690] INFO: 37 hot pixels found in step 3
[13:54:41.685] INFO: Collecting data for 5 seconds...
[13:54:46.703] INFO: Done with hot pixel readout
[13:54:58.752] INFO: PixTest:: pg_setup set to default.
[13:54:58.753] INFO: 40 hot pixels found in step 4
[13:54:59.747] INFO: Collecting data for 5 seconds...
[13:55:04.765] INFO: Done with hot pixel readout
[13:55:16.546] INFO: PixTest:: pg_setup set to default.

[13:55:16.547] INFO: 37 hot pixels found in step 5
[13:55:17.541] INFO: Collecting data for 5 seconds...
[13:55:22.560] INFO: Done with hot pixel readout
[13:55:34.078] INFO: PixTest:: pg_setup set to default.

[13:55:34.079] INFO: 47 hot pixels found in step 6
[13:55:35.072] INFO: Collecting data for 5 seconds...
[13:55:40.090] INFO: Done with hot pixel readout
[13:55:51.636] INFO: PixTest:: pg_setup set to default.

[13:55:51.637] INFO: 31 hot pixels found in step 7
[13:55:52.630] INFO: Collecting data for 5 seconds...
[13:55:57.649] INFO: Done with hot pixel readout
[13:56:09.360] INFO: PixTest:: pg_setup set to default.



[13:56:09.361] INFO: 27 hot pixels found in step 8
[13:56:10.355] INFO: Collecting data for 5 seconds...
[13:56:15.373] INFO: Done with hot pixel readout
[13:56:27.103] INFO: PixTest:: pg_setup set to default.



[13:56:27.104] INFO: 24 hot pixels found in step 9
[13:56:28.097] INFO: Collecting data for 5 seconds...
[13:56:33.116] INFO: Done with hot pixel readout
[13:56:44.821] INFO: PixTest:: pg_setup set to default.



[13:56:44.822] INFO: 16 hot pixels found in step 10
[13:56:45.815] INFO: Collecting data for 5 seconds...
[13:56:50.833] INFO: Done with hot pixel readout
[13:57:02.699] INFO: PixTest:: pg_setup set to default.



[13:57:02.700] INFO: 14 hot pixels found in step 11
[13:57:03.693] INFO: Collecting data for 5 seconds...
[13:57:08.712] INFO: Done with hot pixel readout
[13:57:20.562] INFO: PixTest:: pg_setup set to default.


[13:57:20.563] INFO: 17 hot pixels found in step 12
[13:57:21.556] INFO: Collecting data for 5 seconds...
[13:57:26.574] INFO: Done with hot pixel readout
[13:57:38.509] INFO: PixTest:: pg_setup set to default.


[13:57:38.510] INFO: 18 hot pixels found in step 13
[13:57:39.502] INFO: Collecting data for 5 seconds...
[13:57:44.521] INFO: Done with hot pixel readout
[13:57:56.367] INFO: PixTest:: pg_setup set to default.



[13:57:56.368] INFO: 15 hot pixels found in step 14
[13:57:56.406] INFO: 15 hot pixels could not be trimmed and have been masked.
[13:57:56.409] INFO: PixTest::trimHotPixels() done
[13:57:56.409] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C0.dat
[13:57:56.428] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C1.dat
[13:57:56.434] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C2.dat
[13:57:56.439] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C3.dat
[13:57:56.444] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C4.dat
[13:57:56.450] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C5.dat
[13:57:56.455] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C6.dat
[13:57:56.461] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C7.dat
[13:57:56.467] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C8.dat
[13:57:56.472] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C9.dat
[13:57:56.478] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C10.dat
[13:57:56.483] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C11.dat
[13:57:56.489] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C12.dat
[13:57:56.494] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C13.dat
[13:57:56.500] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C14.dat
[13:57:56.505] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C15.dat
[13:57:56.510] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//defaultMaskFile.dat
[13:57:56.521] INFO: enter test to run
[13:58:09.723] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[13:58:09.723] INFO: running: highrate
[13:58:09.728] INFO: ----------------------------------------------------------------------
[13:58:09.728] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[13:58:09.728] INFO: ----------------------------------------------------------------------
[13:58:09.728] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[13:58:09.728] INFO: edge/corner pixel THR is adjusted
[13:58:09.728] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:58:10.686] INFO: Collecting data for 1 seconds...
[13:58:11.689] INFO: Done with hot pixel readout
[13:58:14.410] INFO: PixTest:: pg_setup set to default.
[13:58:14.411] INFO: 0 hot pixels found in step 0
[13:58:14.415] INFO: 0 hot pixels could not be trimmed and have been masked.
[13:58:14.562] INFO: PixTest::trimHotPixels() done
[13:58:14.562] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C0.dat
[13:58:14.574] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C1.dat
[13:58:14.584] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C2.dat
[13:58:14.589] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C3.dat
[13:58:14.595] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C4.dat
[13:58:14.600] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C5.dat
[13:58:14.605] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C6.dat
[13:58:14.611] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C7.dat
[13:58:14.616] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C8.dat
[13:58:14.622] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C9.dat
[13:58:14.627] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C10.dat
[13:58:14.632] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C11.dat
[13:58:14.638] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C12.dat
[13:58:14.643] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C13.dat
[13:58:14.648] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C14.dat
[13:58:14.654] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C15.dat
[13:58:14.659] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-9-06_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//defaultMaskFile.dat
[13:58:14.668] INFO: enter test to run
[13:59:34.955] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[13:59:34.955] INFO: running: xray
[13:59:34.957] INFO: ----------------------------------------------------------------------
[13:59:34.957] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:59:34.957] INFO: ----------------------------------------------------------------------
[13:59:36.014] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:59:47.437] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[14:00:18.320] INFO: Resuming triggers.
[14:00:29.743] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[14:01:00.696] INFO: Resuming triggers.
[14:01:12.125] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[14:01:42.707] INFO: Resuming triggers.
[14:01:54.131] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[14:02:24.972] INFO: Resuming triggers.
[14:02:36.402] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[14:03:06.542] INFO: Resuming triggers.
[14:03:17.962] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[14:03:47.727] INFO: Resuming triggers.
[14:03:59.149] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[14:04:28.002] INFO: Resuming triggers.
[14:04:40.431] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[14:05:10.164] INFO: Resuming triggers.
[14:05:19.135] INFO: data taking finished, elapsed time: 100 seconds.
[14:05:42.541] INFO: PixTest:: pg_setup set to default.
[14:05:42.545] INFO: PixTestXray::doPhRun() done
[14:05:42.739] INFO: enter test to run
[14:06:15.280] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[14:06:15.280] INFO: running: xray
[14:06:15.281] INFO: ----------------------------------------------------------------------
[14:06:15.281] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:06:15.281] INFO: ----------------------------------------------------------------------
[14:06:16.246] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:06:22.670] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[14:06:53.350] INFO: Resuming triggers.
[14:06:59.780] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[14:07:30.471] INFO: Resuming triggers.
[14:07:36.904] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[14:08:07.523] INFO: Resuming triggers.
[14:08:13.948] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[14:08:44.543] INFO: Resuming triggers.
[14:08:50.969] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[14:09:21.615] INFO: Resuming triggers.
[14:09:28.040] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[14:09:59.366] INFO: Resuming triggers.
[14:10:05.793] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[14:10:36.734] INFO: Resuming triggers.
[14:10:43.162] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[14:11:14.541] INFO: Resuming triggers.
[14:11:20.972] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[14:11:52.393] INFO: Resuming triggers.
[14:11:58.819] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[14:12:29.937] INFO: Resuming triggers.
[14:12:36.360] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[14:13:07.714] INFO: Resuming triggers.
[14:13:14.137] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[14:13:45.720] INFO: Resuming triggers.
[14:13:52.143] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[14:14:24.163] INFO: Resuming triggers.
[14:14:30.587] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[14:15:02.318] INFO: Resuming triggers.
[14:15:08.743] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[14:15:40.328] INFO: Resuming triggers.
[14:15:44.297] INFO: data taking finished, elapsed time: 100 seconds.
[14:16:04.136] INFO: PixTest:: pg_setup set to default.
[14:16:04.139] INFO: PixTestXray::doPhRun() done
[14:16:04.296] INFO: enter test to run
[14:16:37.500] INFO: test: HighRate no parameter change
[14:16:37.500] INFO: running: highrate
[14:16:37.590] INFO: ----------------------------------------------------------------------
[14:16:37.590] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[14:16:37.590] INFO: ----------------------------------------------------------------------
[14:16:37.789] INFO: Expecting 768 events.
[14:16:38.941] INFO: 768 events read in total (436ms).
[14:16:38.941] INFO: Test took 1306ms.
[14:16:39.744] INFO: Expecting 41600 events.
[14:16:42.920] INFO: 41600 events read in total (2649ms).
[14:16:42.921] INFO: Test took 3973ms.
[14:16:42.959] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:16:43.671] INFO: Expecting 41600 events.
[14:16:46.926] INFO: 41600 events read in total (2729ms).
[14:16:46.927] INFO: Test took 3948ms.
[14:16:46.966] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:16:47.681] INFO: Expecting 41600 events.
[14:16:51.207] INFO: 41600 events read in total (2999ms).
[14:16:51.208] INFO: Test took 4222ms.
[14:16:51.250] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:16:51.959] INFO: Expecting 41600 events.
[14:16:55.264] INFO: 41600 events read in total (2779ms).
[14:16:55.265] INFO: Test took 3994ms.
[14:16:55.305] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:16:56.017] INFO: Expecting 41600 events.
[14:16:59.414] INFO: 41600 events read in total (2871ms).
[14:16:59.415] INFO: Test took 4089ms.
[14:16:59.454] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:17:00.165] INFO: Expecting 41600 events.
[14:17:03.541] INFO: 41600 events read in total (2849ms).
[14:17:03.541] INFO: Test took 4067ms.
[14:17:03.581] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:17:04.288] INFO: Expecting 41600 events.
[14:17:07.615] INFO: 41600 events read in total (2800ms).
[14:17:07.616] INFO: Test took 4016ms.
[14:17:07.656] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:17:08.370] INFO: Expecting 41600 events.
[14:17:11.825] INFO: 41600 events read in total (2929ms).
[14:17:11.826] INFO: Test took 4150ms.
[14:17:11.866] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:17:12.578] INFO: Expecting 41600 events.
[14:17:15.857] INFO: 41600 events read in total (2752ms).
[14:17:15.858] INFO: Test took 3972ms.
[14:17:15.897] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:17:16.611] INFO: Expecting 41600 events.
[14:17:19.902] INFO: 41600 events read in total (2764ms).
[14:17:19.903] INFO: Test took 3986ms.
[14:17:19.943] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:17:20.658] INFO: Expecting 41600 events.
[14:17:23.959] INFO: 41600 events read in total (2774ms).
[14:17:23.961] INFO: Test took 3999ms.
[14:17:23.999] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:17:24.716] INFO: Expecting 41600 events.
[14:17:28.015] INFO: 41600 events read in total (2772ms).
[14:17:28.016] INFO: Test took 3996ms.
[14:17:28.056] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:17:28.772] INFO: Expecting 41600 events.
[14:17:32.066] INFO: 41600 events read in total (2767ms).
[14:17:32.067] INFO: Test took 3992ms.
[14:17:32.106] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:17:32.817] INFO: Expecting 41600 events.
[14:17:36.113] INFO: 41600 events read in total (2769ms).
[14:17:36.114] INFO: Test took 3987ms.
[14:17:36.153] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:17:36.870] INFO: Expecting 41600 events.
[14:17:40.157] INFO: 41600 events read in total (2760ms).
[14:17:40.158] INFO: Test took 3984ms.
[14:17:40.196] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:17:40.913] INFO: Expecting 41600 events.
[14:17:44.215] INFO: 41600 events read in total (2775ms).
[14:17:44.216] INFO: Test took 3999ms.
[14:17:44.254] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:17:44.972] INFO: Expecting 41600 events.
[14:17:48.259] INFO: 41600 events read in total (2761ms).
[14:17:48.260] INFO: Test took 3986ms.
[14:17:48.300] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:17:49.015] INFO: Expecting 41600 events.
[14:17:52.312] INFO: 41600 events read in total (2770ms).
[14:17:52.313] INFO: Test took 3992ms.
[14:17:52.352] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:17:53.068] INFO: Expecting 41600 events.
[14:17:56.321] INFO: 41600 events read in total (2726ms).
[14:17:56.322] INFO: Test took 3950ms.
[14:17:56.360] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:17:57.078] INFO: Expecting 41600 events.
[14:18:00.206] INFO: 41600 events read in total (2601ms).
[14:18:00.207] INFO: Test took 3827ms.
[14:18:00.245] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:18:00.607] INFO: enter test to run
[14:18:27.443] INFO: test: HighRate no parameter change
[14:18:27.443] INFO: running: highrate
[14:18:27.444] INFO: ----------------------------------------------------------------------
[14:18:27.444] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:18:27.444] INFO: ----------------------------------------------------------------------
[14:18:28.063] INFO: Expecting 208000 events.
[14:18:40.214] INFO: 208000 events read in total (11624ms).
[14:18:40.217] INFO: Test took 12764ms.
[14:18:40.385] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:18:40.645] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 1 1 0 0 0 0 0 0 0
[14:18:40.645] INFO: number of red-efficiency pixels: 99 193 96 166 202 165 195 108 138 138 151 106 154 69 20 37
[14:18:40.645] INFO: number of X-ray hits detected: 82939 50671 77007 123446 134453 131573 132691 90261 84355 114229 121480 99650 106390 62274 26253 30197
[14:18:40.645] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:18:40.645] INFO: number of Vcal hits detected: 207898 207806 207901 207832 207789 207828 207799 207842 207785 207860 207846 207891 207841 207930 207979 207963
[14:18:40.645] INFO: Vcal hit fiducial efficiency (%): 100.0 99.9 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[14:18:40.645] INFO: Vcal hit overall efficiency (%): 100.0 99.9 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[14:18:40.645] INFO: X-ray hit rate [MHz/cm2]: 24.3 14.9 22.6 36.2 39.4 38.6 38.9 26.5 24.7 33.5 35.6 29.2 31.2 18.3 7.7 8.9
[14:18:40.645] INFO: PixTestHighRate::doXPixelAlive() done
[14:18:40.690] INFO: PixTest:: pg_setup set to default.
[14:18:40.703] INFO: enter test to run
[14:19:48.451] INFO: test: HighRate no parameter change
[14:19:48.451] INFO: running: highrate
[14:19:48.452] INFO: ----------------------------------------------------------------------
[14:19:48.452] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:19:48.452] INFO: ----------------------------------------------------------------------
[14:19:49.065] INFO: Expecting 208000 events.
[14:20:02.894] INFO: 208000 events read in total (13302ms).
[14:20:02.899] INFO: Test took 14438ms.
[14:20:03.223] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:03.531] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 1 1 0 0 0 0 0 0 0
[14:20:03.531] INFO: number of red-efficiency pixels: 318 176 241 586 616 506 654 229 294 409 443 303 432 198 61 87
[14:20:03.531] INFO: number of X-ray hits detected: 155250 94464 144998 232818 252806 247519 247942 169749 159081 215239 227342 187298 199407 118453 49523 57217
[14:20:03.531] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:20:03.531] INFO: number of Vcal hits detected: 207640 207819 207732 207328 207313 207439 207267 207708 207577 207563 207501 207671 207541 207791 207936 207912
[14:20:03.531] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.9 99.7 99.7 99.8 99.7 99.9 99.8 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[14:20:03.531] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.9 99.7 99.7 99.7 99.6 99.9 99.8 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[14:20:03.531] INFO: X-ray hit rate [MHz/cm2]: 45.5 27.7 42.5 68.2 74.1 72.5 72.7 49.8 46.6 63.1 66.6 54.9 58.4 34.7 14.5 16.8
[14:20:03.531] INFO: PixTestHighRate::doXPixelAlive() done
[14:20:03.581] INFO: PixTest:: pg_setup set to default.
[14:20:03.595] INFO: enter test to run
[14:21:17.530] INFO: test: HighRate no parameter change
[14:21:17.530] INFO: running: highrate
[14:21:17.531] INFO: ----------------------------------------------------------------------
[14:21:17.531] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:21:17.531] INFO: ----------------------------------------------------------------------
[14:21:18.151] INFO: Expecting 208000 events.
[14:21:34.034] INFO: 208000 events read in total (15356ms).
[14:21:34.042] INFO: Test took 16500ms.
[14:21:34.528] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:34.885] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 1 1 0 0 0 0 0 0 0
[14:21:34.885] INFO: number of red-efficiency pixels: 676 428 542 1328 1388 1176 1437 580 584 929 983 685 1004 453 95 124
[14:21:34.885] INFO: number of X-ray hits detected: 232545 141486 217182 346532 375970 371146 371115 254563 238071 322177 341042 280433 298418 176937 74120 86250
[14:21:34.885] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:21:34.885] INFO: number of Vcal hits detected: 207065 207518 207317 206240 206065 206458 205973 207257 207101 206867 206770 207203 206785 207459 207898 207870
[14:21:34.885] INFO: Vcal hit fiducial efficiency (%): 99.6 99.8 99.7 99.2 99.2 99.3 99.1 99.7 99.6 99.5 99.5 99.7 99.5 99.8 100.0 99.9
[14:21:34.885] INFO: Vcal hit overall efficiency (%): 99.6 99.8 99.7 99.2 99.1 99.3 99.0 99.6 99.6 99.5 99.4 99.6 99.4 99.7 100.0 99.9
[14:21:34.885] INFO: X-ray hit rate [MHz/cm2]: 68.2 41.5 63.7 101.6 110.2 108.8 108.8 74.6 69.8 94.4 100.0 82.2 87.5 51.9 21.7 25.3
[14:21:34.885] INFO: PixTestHighRate::doXPixelAlive() done
[14:21:34.937] INFO: PixTest:: pg_setup set to default.
[14:21:34.958] INFO: enter test to run
[14:21:39.106] INFO: test: exit no parameter change
[14:21:39.547] QUIET: Connection to board 33 closed.
[14:21:39.559] INFO: pXar: this is the end, my friend