[13:03:34.795] INFO: *** Welcome to pxar ***
[13:03:34.795] INFO: *** Today: 2016/09/23
[13:03:36.033] INFO: *** Version: v1.9.0-818-g96727
[13:03:36.033] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//dacParameters35_C15.dat
[13:03:36.324] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:03:36.325] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//defaultMaskFile.dat
[13:03:36.325] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C15.dat
[13:03:36.597] INFO: clk: 4
[13:03:36.597] INFO: ctr: 4
[13:03:36.597] INFO: sda: 19
[13:03:36.597] INFO: tin: 9
[13:03:36.597] INFO: level: 15
[13:03:36.597] INFO: triggerdelay: 0
[13:03:36.598] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[13:03:36.598] INFO: Log level: INFO
[13:03:36.614] QUIET: Connection to board DTB_WREKRL opened.
[13:03:36.618] 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:03:36.620] INFO: RPC call hashes of host and DTB match: 398089610
[13:03:38.162] INFO: DUT info:
[13:03:38.162] INFO: The DUT currently contains the following objects:
[13:03:38.162] INFO: 2 TBM Cores tbm08c (2 ON)
[13:03:38.162] INFO: TBM Core alpha (0): 7 registers set
[13:03:38.162] INFO: TBM Core beta (1): 7 registers set
[13:03:38.162] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[13:03:38.162] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:38.162] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:38.163] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:38.163] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:38.163] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:38.163] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:38.163] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:38.163] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:38.163] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:38.163] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:38.163] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:38.163] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:38.163] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:38.163] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:38.163] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:38.163] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:38.628] INFO: enter 'restricted' command line mode
[13:03:38.628] INFO: enter test to run
[13:03:48.117] INFO: test: PixelAlive no parameter change
[13:03:48.117] INFO: running: pixelalive
[13:03:48.129] INFO: ----------------------------------------------------------------------
[13:03:48.129] 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:03:48.129] INFO: ----------------------------------------------------------------------
[13:03:48.454] INFO: Expecting 41600 events.
[13:03:52.827] INFO: 41600 events read in total (3655ms).
[13:03:52.993] INFO: Test took 4862ms.
[13:03:53.007] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:03:53.285] INFO: PixTestAlive::aliveTest() done
[13:03:53.285] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[13:03:53.316] INFO: enter test to run
[13:04:39.716] INFO: test: timing no parameter change
[13:04:39.716] INFO: running: timing
[13:04:39.719] INFO: ######################################################################
[13:04:39.720] INFO: PixTestTiming::doTest()
[13:04:39.720] INFO: ######################################################################
[13:04:39.720] INFO: ----------------------------------------------------------------------
[13:04:39.720] INFO: PixTestTiming::TBMPhaseScan()
[13:04:39.720] INFO: ----------------------------------------------------------------------
[13:09:21.315] INFO: TBM Phase Settings: 240
[13:09:21.315] INFO: 400MHz Phase: 4
[13:09:21.315] INFO: 160MHz Phase: 7
[13:09:21.315] INFO: Functional Phase Area: 4
[13:09:21.319] INFO: Test took 281599 ms.
[13:09:21.319] INFO: PixTestTiming::TBMPhaseScan() done.
[13:09:21.319] INFO: ----------------------------------------------------------------------
[13:09:21.319] INFO: PixTestTiming::ROCDelayScan()
[13:09:21.319] INFO: ----------------------------------------------------------------------
[13:11:26.954] INFO: ROC Delay Settings: 227
[13:11:26.954] INFO: ROC Header-Trailer/Token Delay: 11
[13:11:26.954] INFO: ROC Port 0 Delay: 3
[13:11:26.954] INFO: ROC Port 1 Delay: 4
[13:11:26.954] INFO: Functional ROC Area: 5
[13:11:26.957] INFO: Test took 125638 ms.
[13:11:26.957] INFO: PixTestTiming::ROCDelayScan() done.
[13:11:26.957] INFO: ----------------------------------------------------------------------
[13:11:26.957] INFO: PixTestTiming::TimingTest()
[13:11:26.957] INFO: ----------------------------------------------------------------------
[13:11:43.129] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:11:58.112] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:12:13.099] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:12:28.065] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:12:43.037] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:12:58.024] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:13:12.995] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:13:27.970] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:13:42.956] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:13:57.906] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:13:58.284] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:13:58.302] INFO: ----------------------------------------------------------------------
[13:13:58.302] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[13:13:58.302] INFO: ----------------------------------------------------------------------
[13:13:58.302] INFO: ----------------------------------------------------------------------
[13:13:58.302] INFO: Read back bit status: 1
[13:13:58.302] INFO: ----------------------------------------------------------------------
[13:13:58.302] INFO: ----------------------------------------------------------------------
[13:13:58.302] INFO: Timings are good!
[13:13:58.302] INFO: ----------------------------------------------------------------------
[13:13:58.302] INFO: Test took 151345 ms.
[13:13:58.302] INFO: PixTestTiming::TimingTest() done.
[13:13:58.317] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//tbmParameters_C0a.dat
[13:13:58.317] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:13:58.317] INFO: PixTestTiming::doTest took 558601 ms.
[13:13:58.317] INFO: PixTestTiming::doTest() done
[13:13:58.317] INFO: Write out TBMPhaseScan_0_V0
[13:13:58.317] INFO: Write out TBMPhaseScan_1_V0
[13:13:58.318] INFO: Write out CombinedTBMPhaseScan_V0
[13:13:58.332] INFO: Write out ROCDelayScan3_V0
[13:13:58.333] INFO: enter test to run
[13:14:56.312] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[13:14:56.312] INFO: running: highrate
[13:14:56.313] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[13:14:56.576] INFO: ----------------------------------------------------------------------
[13:14:56.576] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[13:14:56.576] INFO: ----------------------------------------------------------------------
[13:14:56.576] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[13:14:56.576] INFO: edge/corner pixel THR is adjusted
[13:14:56.576] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:14:57.536] INFO: Collecting data for 5 seconds...
[13:15:02.552] INFO: Done with hot pixel readout
[13:15:14.569] INFO: PixTest:: pg_setup set to default.





[13:15:14.571] INFO: 79 hot pixels found in step 0
[13:15:15.565] INFO: Collecting data for 5 seconds...
[13:15:20.581] INFO: Done with hot pixel readout
[13:15:32.613] INFO: PixTest:: pg_setup set to default.


[13:15:32.614] INFO: 69 hot pixels found in step 1
[13:15:33.609] INFO: Collecting data for 5 seconds...
[13:15:38.625] INFO: Done with hot pixel readout
[13:15:50.662] INFO: PixTest:: pg_setup set to default.


[13:15:50.663] INFO: 59 hot pixels found in step 2
[13:15:51.658] INFO: Collecting data for 5 seconds...
[13:15:56.675] INFO: Done with hot pixel readout
[13:16:09.007] INFO: PixTest:: pg_setup set to default.



[13:16:09.008] INFO: 70 hot pixels found in step 3
[13:16:09.004] INFO: Collecting data for 5 seconds...
[13:16:15.022] INFO: Done with hot pixel readout
[13:16:27.135] INFO: PixTest:: pg_setup set to default.






[13:16:27.136] INFO: 66 hot pixels found in step 4
[13:16:28.131] INFO: Collecting data for 5 seconds...
[13:16:33.151] INFO: Done with hot pixel readout
[13:16:45.182] INFO: PixTest:: pg_setup set to default.






[13:16:45.183] INFO: 55 hot pixels found in step 5
[13:16:46.180] INFO: Collecting data for 5 seconds...
[13:16:51.198] INFO: Done with hot pixel readout
[13:17:03.397] INFO: PixTest:: pg_setup set to default.







[13:17:03.399] INFO: 60 hot pixels found in step 6
[13:17:04.395] INFO: Collecting data for 5 seconds...
[13:17:09.413] INFO: Done with hot pixel readout
[13:17:21.599] INFO: PixTest:: pg_setup set to default.





[13:17:21.600] INFO: 44 hot pixels found in step 7
[13:17:22.596] INFO: Collecting data for 5 seconds...
[13:17:27.616] INFO: Done with hot pixel readout
[13:17:39.795] INFO: PixTest:: pg_setup set to default.








[13:17:39.796] INFO: 49 hot pixels found in step 8
[13:17:40.792] INFO: Collecting data for 5 seconds...
[13:17:45.811] INFO: Done with hot pixel readout
[13:17:57.800] INFO: PixTest:: pg_setup set to default.





[13:17:57.801] INFO: 34 hot pixels found in step 9
[13:17:58.797] INFO: Collecting data for 5 seconds...
[13:18:04.166] INFO: Done with hot pixel readout
[13:18:16.865] INFO: PixTest:: pg_setup set to default.






















[13:18:16.867] INFO: 181 hot pixels found in step 10
[13:18:17.865] INFO: Collecting data for 5 seconds...
[13:18:22.884] INFO: Done with hot pixel readout
[13:18:34.683] INFO: PixTest:: pg_setup set to default.






[13:18:34.684] INFO: 34 hot pixels found in step 11
[13:18:35.679] INFO: Collecting data for 5 seconds...
[13:18:40.697] INFO: Done with hot pixel readout
[13:18:52.184] INFO: PixTest:: pg_setup set to default.





[13:18:52.186] INFO: 37 hot pixels found in step 12
[13:18:53.182] INFO: Collecting data for 5 seconds...
[13:18:58.200] INFO: Done with hot pixel readout
[13:19:10.279] INFO: PixTest:: pg_setup set to default.






[13:19:10.280] INFO: 33 hot pixels found in step 13
[13:19:11.275] INFO: Collecting data for 5 seconds...
[13:19:16.294] INFO: Done with hot pixel readout
[13:19:28.332] INFO: PixTest:: pg_setup set to default.







[13:19:28.333] INFO: 30 hot pixels found in step 14
[13:19:28.373] INFO: 30 hot pixels could not be trimmed and have been masked.
[13:19:28.376] INFO: PixTest::trimHotPixels() done
[13:19:28.376] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C0.dat
[13:19:28.401] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C1.dat
[13:19:28.410] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C2.dat
[13:19:28.420] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C3.dat
[13:19:28.425] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C4.dat
[13:19:28.431] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C5.dat
[13:19:28.436] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C6.dat
[13:19:28.442] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C7.dat
[13:19:28.447] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C8.dat
[13:19:28.453] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C9.dat
[13:19:28.458] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C10.dat
[13:19:28.463] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C11.dat
[13:19:28.469] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C12.dat
[13:19:28.474] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C13.dat
[13:19:28.480] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C14.dat
[13:19:28.485] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C15.dat
[13:19:28.490] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//defaultMaskFile.dat
[13:19:28.502] INFO: enter test to run
[13:19:49.654] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[13:19:49.654] INFO: running: highrate
[13:19:49.659] INFO: ----------------------------------------------------------------------
[13:19:49.659] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[13:19:49.659] INFO: ----------------------------------------------------------------------
[13:19:49.659] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[13:19:49.659] INFO: edge/corner pixel THR is adjusted
[13:19:49.659] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:19:50.616] INFO: Collecting data for 1 seconds...
[13:19:51.621] INFO: Done with hot pixel readout
[13:19:55.872] INFO: PixTest:: pg_setup set to default.
[13:19:55.873] INFO: 0 hot pixels found in step 0
[13:19:55.878] INFO: 0 hot pixels could not be trimmed and have been masked.
[13:19:55.961] INFO: PixTest::trimHotPixels() done
[13:19:55.961] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C0.dat
[13:19:55.971] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C1.dat
[13:19:55.977] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C2.dat
[13:19:55.982] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C3.dat
[13:19:55.987] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C4.dat
[13:19:55.993] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C5.dat
[13:19:55.998] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C6.dat
[13:19:55.004] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C7.dat
[13:19:56.009] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C8.dat
[13:19:56.015] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C9.dat
[13:19:56.020] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C10.dat
[13:19:56.026] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C11.dat
[13:19:56.031] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C12.dat
[13:19:56.037] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C13.dat
[13:19:56.042] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C14.dat
[13:19:56.048] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//trimParameters35_C15.dat
[13:19:56.053] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-32_FPIXTest-17C-FNAL-160919-1227-150V_2016-09-19_12h27m_1474306038/000_FPIXTest_p17//defaultMaskFile.dat
[13:19:56.079] INFO: enter test to run
[13:20:30.686] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[13:20:30.686] INFO: running: xray
[13:20:30.687] INFO: ----------------------------------------------------------------------
[13:20:30.687] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:20:30.687] INFO: ----------------------------------------------------------------------
[13:20:31.650] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:20:42.783] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[13:21:12.677] INFO: Resuming triggers.
[13:21:23.912] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[13:21:53.398] INFO: Resuming triggers.
[13:22:04.535] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[13:22:34.028] INFO: Resuming triggers.
[13:22:45.167] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[13:23:14.715] INFO: Resuming triggers.
[13:23:25.852] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[13:23:55.368] INFO: Resuming triggers.
[13:24:06.507] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[13:24:36.095] INFO: Resuming triggers.
[13:24:47.232] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[13:25:16.733] INFO: Resuming triggers.
[13:25:27.872] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[13:25:57.386] INFO: Resuming triggers.
[13:26:08.523] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[13:26:38.058] INFO: Resuming triggers.
[13:26:38.165] INFO: data taking finished, elapsed time: 100 seconds.
[13:26:38.986] INFO: PixTest:: pg_setup set to default.
[13:26:38.989] INFO: PixTestXray::doPhRun() done
[13:26:39.138] INFO: enter test to run
[13:27:36.963] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[13:27:36.963] INFO: running: xray
[13:27:36.964] INFO: ----------------------------------------------------------------------
[13:27:36.964] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:27:36.964] INFO: ----------------------------------------------------------------------
[13:27:37.949] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:27:44.321] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[13:28:14.470] INFO: Resuming triggers.
[13:28:20.839] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[13:28:51.086] INFO: Resuming triggers.
[13:28:57.456] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[13:29:28.472] INFO: Resuming triggers.
[13:29:34.841] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[13:30:06.050] INFO: Resuming triggers.
[13:30:12.417] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[13:30:43.515] INFO: Resuming triggers.
[13:30:49.889] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[13:31:20.842] INFO: Resuming triggers.
[13:31:27.212] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[13:31:57.955] INFO: Resuming triggers.
[13:32:04.322] INFO: run duration 50 seconds, buffer almost full (81%), pausing triggers.
[13:32:36.042] INFO: Resuming triggers.
[13:32:42.408] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[13:33:13.450] INFO: Resuming triggers.
[13:33:19.820] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[13:33:51.513] INFO: Resuming triggers.
[13:33:57.880] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[13:34:28.839] INFO: Resuming triggers.
[13:34:35.206] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[13:35:05.404] INFO: Resuming triggers.
[13:35:11.776] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[13:35:41.889] INFO: Resuming triggers.
[13:35:48.262] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[13:36:18.414] INFO: Resuming triggers.
[13:36:24.782] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[13:36:54.950] INFO: Resuming triggers.
[13:36:59.763] INFO: data taking finished, elapsed time: 100 seconds.
[13:37:22.741] INFO: PixTest:: pg_setup set to default.
[13:37:22.744] INFO: PixTestXray::doPhRun() done
[13:37:22.892] INFO: enter test to run
[13:38:00.087] INFO: test: HighRate no parameter change
[13:38:00.087] INFO: running: highrate
[13:38:00.097] INFO: ----------------------------------------------------------------------
[13:38:00.097] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[13:38:00.097] INFO: ----------------------------------------------------------------------
[13:38:00.252] INFO: Expecting 768 events.
[13:38:01.386] INFO: 768 events read in total (418ms).
[13:38:01.386] INFO: Test took 1268ms.
[13:38:02.189] INFO: Expecting 41600 events.
[13:38:05.302] INFO: 41600 events read in total (2586ms).
[13:38:05.303] INFO: Test took 3909ms.
[13:38:05.339] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:06.063] INFO: Expecting 41600 events.
[13:38:09.283] INFO: 41600 events read in total (2693ms).
[13:38:09.284] INFO: Test took 3925ms.
[13:38:09.321] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:10.035] INFO: Expecting 41600 events.
[13:38:13.285] INFO: 41600 events read in total (2724ms).
[13:38:13.286] INFO: Test took 3945ms.
[13:38:13.322] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:14.041] INFO: Expecting 41600 events.
[13:38:17.294] INFO: 41600 events read in total (2726ms).
[13:38:17.295] INFO: Test took 3953ms.
[13:38:17.331] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:18.052] INFO: Expecting 41600 events.
[13:38:21.294] INFO: 41600 events read in total (2715ms).
[13:38:21.295] INFO: Test took 3944ms.
[13:38:21.333] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:22.052] INFO: Expecting 41600 events.
[13:38:25.309] INFO: 41600 events read in total (2730ms).
[13:38:25.310] INFO: Test took 3957ms.
[13:38:25.346] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:26.064] INFO: Expecting 41600 events.
[13:38:29.332] INFO: 41600 events read in total (2741ms).
[13:38:29.333] INFO: Test took 3967ms.
[13:38:29.369] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:30.090] INFO: Expecting 41600 events.
[13:38:33.353] INFO: 41600 events read in total (2736ms).
[13:38:33.354] INFO: Test took 3964ms.
[13:38:33.391] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:34.111] INFO: Expecting 41600 events.
[13:38:37.361] INFO: 41600 events read in total (2723ms).
[13:38:37.362] INFO: Test took 3952ms.
[13:38:37.398] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:38.121] INFO: Expecting 41600 events.
[13:38:41.378] INFO: 41600 events read in total (2730ms).
[13:38:41.379] INFO: Test took 3961ms.
[13:38:41.414] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:42.134] INFO: Expecting 41600 events.
[13:38:45.407] INFO: 41600 events read in total (2746ms).
[13:38:45.408] INFO: Test took 3974ms.
[13:38:45.445] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:46.161] INFO: Expecting 41600 events.
[13:38:49.417] INFO: 41600 events read in total (2729ms).
[13:38:49.418] INFO: Test took 3952ms.
[13:38:49.455] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:50.173] INFO: Expecting 41600 events.
[13:38:53.438] INFO: 41600 events read in total (2738ms).
[13:38:53.439] INFO: Test took 3964ms.
[13:38:53.474] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:54.193] INFO: Expecting 41600 events.
[13:38:57.462] INFO: 41600 events read in total (2742ms).
[13:38:57.463] INFO: Test took 3968ms.
[13:38:57.500] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:58.221] INFO: Expecting 41600 events.
[13:39:01.480] INFO: 41600 events read in total (2732ms).
[13:39:01.481] INFO: Test took 3961ms.
[13:39:01.519] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:02.238] INFO: Expecting 41600 events.
[13:39:05.487] INFO: 41600 events read in total (2723ms).
[13:39:05.488] INFO: Test took 3949ms.
[13:39:05.524] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:06.244] INFO: Expecting 41600 events.
[13:39:09.518] INFO: 41600 events read in total (2747ms).
[13:39:09.519] INFO: Test took 3975ms.
[13:39:09.562] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:10.273] INFO: Expecting 41600 events.
[13:39:13.539] INFO: 41600 events read in total (2738ms).
[13:39:13.540] INFO: Test took 3957ms.
[13:39:13.577] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:14.297] INFO: Expecting 41600 events.
[13:39:17.534] INFO: 41600 events read in total (2710ms).
[13:39:17.535] INFO: Test took 3939ms.
[13:39:17.571] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:18.291] INFO: Expecting 41600 events.
[13:39:21.420] INFO: 41600 events read in total (2602ms).
[13:39:21.421] INFO: Test took 3831ms.
[13:39:21.457] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:21.816] INFO: enter test to run
[13:40:15.894] INFO: test: HighRate no parameter change
[13:40:15.894] INFO: running: highrate
[13:40:15.895] INFO: ----------------------------------------------------------------------
[13:40:15.895] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:40:15.895] INFO: ----------------------------------------------------------------------
[13:40:16.508] INFO: Expecting 208000 events.
[13:40:28.446] INFO: 208000 events read in total (11411ms).
[13:40:28.449] INFO: Test took 12545ms.
[13:40:28.606] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:40:28.860] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[13:40:28.861] INFO: number of red-efficiency pixels: 116 49 91 159 135 167 157 107 111 121 113 102 136 71 22 36
[13:40:28.861] INFO: number of X-ray hits detected: 73081 45535 73980 117337 122980 129715 127920 91155 82977 105377 100855 87487 92218 55680 20552 26824
[13:40:28.861] 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:28.861] INFO: number of Vcal hits detected: 207881 207950 207903 207836 207863 207823 207838 207889 207888 207877 207881 207896 207862 207929 207978 207963
[13:40:28.861] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 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
[13:40:28.861] INFO: Vcal hit overall efficiency (%): 99.9 100.0 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
[13:40:28.861] INFO: X-ray hit rate [MHz/cm2]: 21.4 13.3 21.7 34.4 36.0 38.0 37.5 26.7 24.3 30.9 29.6 25.6 27.0 16.3 6.0 7.9
[13:40:28.861] INFO: PixTestHighRate::doXPixelAlive() done
[13:40:28.912] INFO: PixTest:: pg_setup set to default.
[13:40:28.926] INFO: enter test to run
[13:40:58.422] INFO: test: HighRate no parameter change
[13:40:58.422] INFO: running: highrate
[13:40:58.423] INFO: ----------------------------------------------------------------------
[13:40:58.423] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:40:58.423] INFO: ----------------------------------------------------------------------
[13:40:59.038] INFO: Expecting 208000 events.
[13:41:12.930] INFO: 208000 events read in total (13365ms).
[13:41:12.935] INFO: Test took 14501ms.
[13:41:13.247] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:41:13.559] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[13:41:13.559] INFO: number of red-efficiency pixels: 295 123 314 657 484 551 511 378 252 370 338 277 404 253 58 72
[13:41:13.559] INFO: number of X-ray hits detected: 150667 93725 153350 242124 252854 267292 263787 188037 171912 219051 208223 180908 190925 114966 42877 55495
[13:41:13.559] 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:13.559] INFO: number of Vcal hits detected: 207664 207869 207664 207245 207475 207373 207442 207583 207736 207602 207632 207699 207569 207730 207940 207928
[13:41:13.559] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.7 99.8 99.7 99.8 99.8 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[13:41:13.559] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.6 99.7 99.7 99.7 99.8 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[13:41:13.559] INFO: X-ray hit rate [MHz/cm2]: 44.2 27.5 44.9 71.0 74.1 78.3 77.3 55.1 50.4 64.2 61.0 53.0 56.0 33.7 12.6 16.3
[13:41:13.559] INFO: PixTestHighRate::doXPixelAlive() done
[13:41:13.609] INFO: PixTest:: pg_setup set to default.
[13:41:13.625] INFO: enter test to run
[13:41:49.005] INFO: test: HighRate no parameter change
[13:41:49.005] INFO: running: highrate
[13:41:50.007] INFO: ----------------------------------------------------------------------
[13:41:50.007] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:41:50.007] INFO: ----------------------------------------------------------------------
[13:41:50.629] INFO: Expecting 208000 events.
[13:42:06.881] INFO: 208000 events read in total (15725ms).
[13:42:06.889] INFO: Test took 16873ms.
[13:42:07.416] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:42:07.784] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[13:42:07.784] INFO: number of red-efficiency pixels: 636 284 692 1455 1185 1470 1287 749 552 922 829 662 892 559 93 109
[13:42:07.784] INFO: number of X-ray hits detected: 228683 143268 234299 367994 384236 406499 400588 286246 263531 333511 317479 276580 291408 174865 66363 85455
[13:42:07.784] 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:42:07.784] INFO: number of Vcal hits detected: 207156 207688 207031 205968 206521 205986 206328 207000 207374 206898 207028 207216 206945 207309 207905 207886
[13:42:07.784] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.6 99.1 99.4 99.1 99.3 99.6 99.7 99.5 99.6 99.7 99.5 99.7 100.0 100.0
[13:42:07.784] INFO: Vcal hit overall efficiency (%): 99.6 99.9 99.5 99.0 99.3 99.0 99.2 99.5 99.7 99.5 99.5 99.6 99.5 99.7 100.0 99.9
[13:42:07.785] INFO: X-ray hit rate [MHz/cm2]: 67.0 42.0 68.7 107.9 112.6 119.1 117.4 83.9 77.2 97.8 93.1 81.1 85.4 51.3 19.5 25.0
[13:42:07.785] INFO: PixTestHighRate::doXPixelAlive() done
[13:42:07.829] INFO: PixTest:: pg_setup set to default.
[13:42:07.844] INFO: enter test to run
[13:42:36.421] INFO: test: exit no parameter change
[13:42:36.796] QUIET: Connection to board 33 closed.
[13:42:36.808] INFO: pXar: this is the end, my friend