[16:27:54.173] INFO: *** Welcome to pxar ***
[16:27:54.173] INFO: *** Today: 2016/05/30
[16:27:54.194] INFO: *** Version: v1.9.0-796-gef167-dirty
[16:27:54.194] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//dacParameters35_C15.dat
[16:27:54.195] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:27:54.195] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//defaultMaskFile.dat
[16:27:54.195] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C15.dat
[16:27:54.270] INFO: clk: 4
[16:27:54.270] INFO: ctr: 4
[16:27:54.270] INFO: sda: 19
[16:27:54.271] INFO: tin: 9
[16:27:54.271] INFO: level: 15
[16:27:54.271] INFO: triggerdelay: 0
[16:27:54.271] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[16:27:54.271] INFO: Log level: INFO
[16:27:54.289] QUIET: Connection to board DTB_WREKRL opened.
[16:27:54.292] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 33
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREKRL
MAC address: 40D855118021
Hostname: pixelDTB033
Comment:
------------------------------------------------------
[16:27:54.295] INFO: RPC call hashes of host and DTB match: 398089610
[16:27:55.828] INFO: DUT info:
[16:27:55.828] INFO: The DUT currently contains the following objects:
[16:27:55.828] INFO: 2 TBM Cores tbm08c (2 ON)
[16:27:55.828] INFO: TBM Core alpha (0): 7 registers set
[16:27:55.829] INFO: TBM Core beta (1): 7 registers set
[16:27:55.829] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[16:27:55.829] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[16:27:55.829] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[16:27:55.829] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[16:27:55.829] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[16:27:55.829] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[16:27:55.829] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[16:27:55.829] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[16:27:55.829] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[16:27:55.829] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[16:27:55.829] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[16:27:55.829] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[16:27:55.829] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[16:27:55.829] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[16:27:55.829] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[16:27:55.829] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[16:27:55.829] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[16:27:56.233] INFO: enter 'restricted' command line mode
[16:27:56.233] INFO: enter test to run
[16:28:13.654] INFO: test: timing no parameter change
[16:28:13.654] INFO: running: timing
[16:28:13.663] INFO: ######################################################################
[16:28:13.663] INFO: PixTestTiming::doTest()
[16:28:13.663] INFO: ######################################################################
[16:28:13.663] INFO: ----------------------------------------------------------------------
[16:28:13.663] INFO: PixTestTiming::TBMPhaseScan()
[16:28:13.663] INFO: ----------------------------------------------------------------------
[16:32:38.766] INFO: TBM Phase Settings: 252
[16:32:38.766] INFO: 400MHz Phase: 7
[16:32:38.766] INFO: 160MHz Phase: 7
[16:32:38.766] INFO: Functional Phase Area: 3
[16:32:38.769] INFO: Test took 265106 ms.
[16:32:38.769] INFO: PixTestTiming::TBMPhaseScan() done.
[16:32:38.769] INFO: ----------------------------------------------------------------------
[16:32:38.769] INFO: PixTestTiming::ROCDelayScan()
[16:32:38.769] INFO: ----------------------------------------------------------------------
[16:34:34.793] INFO: ROC Delay Settings: 228
[16:34:34.793] INFO: ROC Header-Trailer/Token Delay: 11
[16:34:34.793] INFO: ROC Port 0 Delay: 4
[16:34:34.793] INFO: ROC Port 1 Delay: 4
[16:34:34.793] INFO: Functional ROC Area: 3
[16:34:34.796] INFO: Test took 116027 ms.
[16:34:34.796] INFO: PixTestTiming::ROCDelayScan() done.
[16:34:34.797] INFO: ----------------------------------------------------------------------
[16:34:34.797] INFO: PixTestTiming::TimingTest()
[16:34:34.797] INFO: ----------------------------------------------------------------------
[16:34:50.938] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:35:05.909] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:35:20.861] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:35:35.818] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:35:50.774] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:05.717] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:20.676] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:35.632] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:50.582] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:37:05.537] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:37:05.920] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:37:05.936] INFO: ----------------------------------------------------------------------
[16:37:05.936] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[16:37:05.936] INFO: ----------------------------------------------------------------------
[16:37:05.936] INFO: ----------------------------------------------------------------------
[16:37:05.936] INFO: Read back bit status: 1
[16:37:05.936] INFO: ----------------------------------------------------------------------
[16:37:05.936] INFO: ----------------------------------------------------------------------
[16:37:05.936] INFO: Timings are good!
[16:37:05.936] INFO: ----------------------------------------------------------------------
[16:37:05.936] INFO: Test took 151139 ms.
[16:37:05.936] INFO: PixTestTiming::TimingTest() done.
[16:37:05.937] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//tbmParameters_C0a.dat
[16:37:05.937] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:37:05.937] INFO: PixTestTiming::doTest took 532279 ms.
[16:37:05.937] INFO: PixTestTiming::doTest() done
[16:37:05.937] INFO: Write out TBMPhaseScan_0_V0
[16:37:05.968] INFO: Write out TBMPhaseScan_1_V0
[16:37:05.968] INFO: Write out CombinedTBMPhaseScan_V0
[16:37:05.968] INFO: Write out ROCDelayScan3_V0
[16:37:05.969] INFO: enter test to run
[16:37:14.698] INFO: test: PixelAlive no parameter change
[16:37:14.698] INFO: running: pixelalive
[16:37:14.702] INFO: ----------------------------------------------------------------------
[16:37:14.702] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[16:37:14.702] INFO: ----------------------------------------------------------------------
[16:37:15.023] INFO: Expecting 41600 events.
[16:37:19.343] INFO: 41600 events read in total (3604ms).
[16:37:19.344] INFO: Test took 4637ms.
[16:37:19.350] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:37:19.750] INFO: PixTestAlive::aliveTest() done
[16:37:19.750] INFO: number of dead pixels (per ROC): 0 0 0 1 0 0 1 0 0 3 0 0 3 0 0 0
[16:37:19.754] INFO: enter test to run
[16:38:15.618] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[16:38:15.618] INFO: running: highrate
[16:38:15.618] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[16:38:15.775] INFO: ----------------------------------------------------------------------
[16:38:15.775] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[16:38:15.775] INFO: ----------------------------------------------------------------------
[16:38:15.775] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[16:38:15.775] INFO: edge/corner pixel THR is adjusted
[16:38:15.775] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:38:16.732] INFO: Collecting data for 5 seconds...
[16:38:21.747] INFO: Done with hot pixel readout
[16:38:33.845] INFO: PixTest:: pg_setup set to default.

[16:38:33.845] INFO: 26 hot pixels found in step 0
[16:38:34.838] INFO: Collecting data for 5 seconds...
[16:38:39.853] INFO: Done with hot pixel readout
[16:38:51.935] INFO: PixTest:: pg_setup set to default.

[16:38:51.936] INFO: 36 hot pixels found in step 1
[16:38:52.929] INFO: Collecting data for 5 seconds...
[16:38:57.944] INFO: Done with hot pixel readout
[16:39:10.042] INFO: PixTest:: pg_setup set to default.
[16:39:10.043] INFO: 31 hot pixels found in step 2
[16:39:11.036] INFO: Collecting data for 5 seconds...
[16:39:16.052] INFO: Done with hot pixel readout
[16:39:28.169] INFO: PixTest:: pg_setup set to default.
[16:39:28.170] INFO: 36 hot pixels found in step 3
[16:39:29.163] INFO: Collecting data for 5 seconds...
[16:39:34.177] INFO: Done with hot pixel readout
[16:39:46.269] INFO: PixTest:: pg_setup set to default.


[16:39:46.269] INFO: 32 hot pixels found in step 4
[16:39:47.262] INFO: Collecting data for 5 seconds...
[16:39:52.277] INFO: Done with hot pixel readout
[16:40:04.362] INFO: PixTest:: pg_setup set to default.

[16:40:04.363] INFO: 27 hot pixels found in step 5
[16:40:05.355] INFO: Collecting data for 5 seconds...
[16:40:10.370] INFO: Done with hot pixel readout
[16:40:22.475] INFO: PixTest:: pg_setup set to default.





[16:40:22.476] INFO: 27 hot pixels found in step 6
[16:40:23.471] INFO: Collecting data for 5 seconds...
[16:40:28.487] INFO: Done with hot pixel readout
[16:40:40.575] INFO: PixTest:: pg_setup set to default.



[16:40:40.576] INFO: 19 hot pixels found in step 7
[16:40:41.569] INFO: Collecting data for 5 seconds...
[16:40:46.583] INFO: Done with hot pixel readout
[16:40:58.652] INFO: PixTest:: pg_setup set to default.






[16:40:58.653] INFO: 25 hot pixels found in step 8
[16:40:59.646] INFO: Collecting data for 5 seconds...
[16:41:04.661] INFO: Done with hot pixel readout
[16:41:16.760] INFO: PixTest:: pg_setup set to default.




[16:41:16.761] INFO: 11 hot pixels found in step 9
[16:41:17.755] INFO: Collecting data for 5 seconds...
[16:41:22.770] INFO: Done with hot pixel readout
[16:41:34.858] INFO: PixTest:: pg_setup set to default.




[16:41:34.859] INFO: 22 hot pixels found in step 10
[16:41:35.853] INFO: Collecting data for 5 seconds...
[16:41:40.868] INFO: Done with hot pixel readout
[16:41:52.964] INFO: PixTest:: pg_setup set to default.






[16:41:52.965] INFO: 22 hot pixels found in step 11
[16:41:53.958] INFO: Collecting data for 5 seconds...
[16:41:58.973] INFO: Done with hot pixel readout
[16:42:11.082] INFO: PixTest:: pg_setup set to default.






[16:42:11.083] INFO: 22 hot pixels found in step 12
[16:42:12.076] INFO: Collecting data for 5 seconds...
[16:42:17.091] INFO: Done with hot pixel readout
[16:42:29.177] INFO: PixTest:: pg_setup set to default.




[16:42:29.178] INFO: 18 hot pixels found in step 13
[16:42:30.171] INFO: Collecting data for 5 seconds...
[16:42:35.187] INFO: Done with hot pixel readout
[16:42:47.253] INFO: PixTest:: pg_setup set to default.



[16:42:47.254] INFO: 18 hot pixels found in step 14
[16:42:47.291] INFO: 18 hot pixels could not be trimmed and have been masked.
[16:42:47.294] INFO: PixTest::trimHotPixels() done
[16:42:47.295] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C0.dat
[16:42:47.300] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C1.dat
[16:42:47.306] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C2.dat
[16:42:47.312] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C3.dat
[16:42:47.318] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C4.dat
[16:42:47.323] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C5.dat
[16:42:47.328] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C6.dat
[16:42:47.333] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C7.dat
[16:42:47.339] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C8.dat
[16:42:47.344] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C9.dat
[16:42:47.349] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C10.dat
[16:42:47.354] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C11.dat
[16:42:47.360] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C12.dat
[16:42:47.365] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C13.dat
[16:42:47.370] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C14.dat
[16:42:47.375] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C15.dat
[16:42:47.381] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//defaultMaskFile.dat
[16:42:47.392] INFO: enter test to run
[16:44:51.743] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[16:44:51.743] INFO: running: highrate
[16:44:51.747] INFO: ----------------------------------------------------------------------
[16:44:51.747] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[16:44:51.747] INFO: ----------------------------------------------------------------------
[16:44:51.747] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[16:44:51.747] INFO: edge/corner pixel THR is adjusted
[16:44:51.747] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:44:52.705] INFO: Collecting data for 1 seconds...
[16:44:53.708] INFO: Done with hot pixel readout
[16:44:57.867] INFO: PixTest:: pg_setup set to default.
[16:44:57.868] INFO: 0 hot pixels found in step 0
[16:44:57.873] INFO: 0 hot pixels could not be trimmed and have been masked.
[16:44:57.961] INFO: PixTest::trimHotPixels() done
[16:44:57.961] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C0.dat
[16:44:57.971] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C1.dat
[16:44:57.976] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C2.dat
[16:44:57.981] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C3.dat
[16:44:57.986] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C4.dat
[16:44:57.991] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C5.dat
[16:44:57.997] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C6.dat
[16:44:57.002] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C7.dat
[16:44:58.007] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C8.dat
[16:44:58.012] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C9.dat
[16:44:58.017] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C10.dat
[16:44:58.023] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C11.dat
[16:44:58.028] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C12.dat
[16:44:58.033] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C13.dat
[16:44:58.038] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C14.dat
[16:44:58.043] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//trimParameters35_C15.dat
[16:44:58.048] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-O-1-07_FPIXTest-17C-FNAL-160526-1044_2016-05-26_10h44m_1464277493/000_FPIXTest_p17//defaultMaskFile.dat
[16:44:58.059] INFO: enter test to run
[16:46:33.502] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[16:46:33.502] INFO: running: xray
[16:46:33.503] INFO: ----------------------------------------------------------------------
[16:46:33.503] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:46:33.503] INFO: ----------------------------------------------------------------------
[16:46:34.466] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:46:45.553] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[16:47:14.954] INFO: Resuming triggers.
[16:47:26.043] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[16:47:55.350] INFO: Resuming triggers.
[16:48:06.441] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[16:48:35.931] INFO: Resuming triggers.
[16:48:47.025] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[16:49:16.329] INFO: Resuming triggers.
[16:49:27.422] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[16:49:56.850] INFO: Resuming triggers.
[16:50:07.945] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[16:50:37.376] INFO: Resuming triggers.
[16:50:48.470] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[16:51:17.815] INFO: Resuming triggers.
[16:51:28.910] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[16:51:58.320] INFO: Resuming triggers.
[16:52:09.417] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[16:52:38.899] INFO: Resuming triggers.
[16:52:39.368] INFO: data taking finished, elapsed time: 100 seconds.
[16:52:40.999] INFO: PixTest:: pg_setup set to default.
[16:52:40.002] INFO: PixTestXray::doPhRun() done
[16:52:41.143] INFO: enter test to run
[16:52:59.715] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[16:52:59.715] INFO: running: xray
[16:52:59.717] INFO: ----------------------------------------------------------------------
[16:52:59.717] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:52:59.717] INFO: ----------------------------------------------------------------------
[16:53:00.680] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:53:06.974] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[16:53:36.942] INFO: Resuming triggers.
[16:53:43.236] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[16:54:12.924] INFO: Resuming triggers.
[16:54:19.220] INFO: run duration 18 seconds, buffer almost full (81%), pausing triggers.
[16:54:49.213] INFO: Resuming triggers.
[16:54:55.506] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[16:55:25.411] INFO: Resuming triggers.
[16:55:31.705] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[16:56:01.682] INFO: Resuming triggers.
[16:56:07.976] INFO: run duration 37 seconds, buffer almost full (81%), pausing triggers.
[16:56:38.240] INFO: Resuming triggers.
[16:56:44.534] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[16:57:14.494] INFO: Resuming triggers.
[16:57:20.792] INFO: run duration 50 seconds, buffer almost full (81%), pausing triggers.
[16:57:50.667] INFO: Resuming triggers.
[16:57:56.964] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[16:58:26.964] INFO: Resuming triggers.
[16:58:33.264] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[16:59:03.195] INFO: Resuming triggers.
[16:59:09.498] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[16:59:39.362] INFO: Resuming triggers.
[16:59:45.664] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[17:00:15.633] INFO: Resuming triggers.
[17:00:21.935] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[17:00:51.861] INFO: Resuming triggers.
[17:00:58.161] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[17:01:28.063] INFO: Resuming triggers.
[17:01:34.364] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[17:02:04.201] INFO: Resuming triggers.
[17:02:10.038] INFO: data taking finished, elapsed time: 100 seconds.
[17:02:37.996] INFO: PixTest:: pg_setup set to default.
[17:02:37.999] INFO: PixTestXray::doPhRun() done
[17:02:38.147] INFO: enter test to run
[17:02:56.351] INFO: test: HighRate no parameter change
[17:02:56.351] INFO: running: highrate
[17:02:56.352] INFO: ----------------------------------------------------------------------
[17:02:56.353] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[17:02:56.353] INFO: ----------------------------------------------------------------------
[17:02:56.493] INFO: Expecting 768 events.
[17:02:57.627] INFO: 768 events read in total (418ms).
[17:02:57.627] INFO: Test took 1268ms.
[17:02:58.430] INFO: Expecting 41600 events.
[17:03:01.506] INFO: 41600 events read in total (2549ms).
[17:03:01.507] INFO: Test took 3873ms.
[17:03:01.542] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:03:02.270] INFO: Expecting 41600 events.
[17:03:05.480] INFO: 41600 events read in total (2683ms).
[17:03:05.481] INFO: Test took 3921ms.
[17:03:05.518] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:03:06.238] INFO: Expecting 41600 events.
[17:03:09.477] INFO: 41600 events read in total (2712ms).
[17:03:09.478] INFO: Test took 3941ms.
[17:03:09.514] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:03:10.233] INFO: Expecting 41600 events.
[17:03:13.484] INFO: 41600 events read in total (2724ms).
[17:03:13.485] INFO: Test took 3953ms.
[17:03:13.520] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:03:14.240] INFO: Expecting 41600 events.
[17:03:17.495] INFO: 41600 events read in total (2728ms).
[17:03:17.496] INFO: Test took 3956ms.
[17:03:17.531] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:03:18.254] INFO: Expecting 41600 events.
[17:03:21.493] INFO: 41600 events read in total (2712ms).
[17:03:21.494] INFO: Test took 3944ms.
[17:03:21.530] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:03:22.251] INFO: Expecting 41600 events.
[17:03:25.507] INFO: 41600 events read in total (2729ms).
[17:03:25.508] INFO: Test took 3958ms.
[17:03:25.544] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:03:26.262] INFO: Expecting 41600 events.
[17:03:29.516] INFO: 41600 events read in total (2727ms).
[17:03:29.517] INFO: Test took 3956ms.
[17:03:29.553] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:03:30.272] INFO: Expecting 41600 events.
[17:03:33.524] INFO: 41600 events read in total (2725ms).
[17:03:33.525] INFO: Test took 3953ms.
[17:03:33.560] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:03:34.280] INFO: Expecting 41600 events.
[17:03:37.532] INFO: 41600 events read in total (2725ms).
[17:03:37.533] INFO: Test took 3954ms.
[17:03:37.569] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:03:38.288] INFO: Expecting 41600 events.
[17:03:41.545] INFO: 41600 events read in total (2730ms).
[17:03:41.546] INFO: Test took 3959ms.
[17:03:41.582] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:03:42.304] INFO: Expecting 41600 events.
[17:03:45.559] INFO: 41600 events read in total (2729ms).
[17:03:45.560] INFO: Test took 3958ms.
[17:03:45.596] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:03:46.315] INFO: Expecting 41600 events.
[17:03:49.555] INFO: 41600 events read in total (2714ms).
[17:03:49.556] INFO: Test took 3941ms.
[17:03:49.592] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:03:50.311] INFO: Expecting 41600 events.
[17:03:53.567] INFO: 41600 events read in total (2730ms).
[17:03:53.568] INFO: Test took 3956ms.
[17:03:53.605] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:03:54.325] INFO: Expecting 41600 events.
[17:03:57.576] INFO: 41600 events read in total (2724ms).
[17:03:57.577] INFO: Test took 3952ms.
[17:03:57.613] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:03:58.335] INFO: Expecting 41600 events.
[17:04:01.581] INFO: 41600 events read in total (2719ms).
[17:04:01.582] INFO: Test took 3949ms.
[17:04:01.618] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:04:02.338] INFO: Expecting 41600 events.
[17:04:05.589] INFO: 41600 events read in total (2724ms).
[17:04:05.590] INFO: Test took 3953ms.
[17:04:05.626] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:04:06.346] INFO: Expecting 41600 events.
[17:04:09.608] INFO: 41600 events read in total (2735ms).
[17:04:09.609] INFO: Test took 3965ms.
[17:04:09.645] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:04:10.363] INFO: Expecting 41600 events.
[17:04:13.603] INFO: 41600 events read in total (2713ms).
[17:04:13.604] INFO: Test took 3939ms.
[17:04:13.641] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:04:14.358] INFO: Expecting 41600 events.
[17:04:17.490] INFO: 41600 events read in total (2605ms).
[17:04:17.491] INFO: Test took 3830ms.
[17:04:17.527] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:04:17.888] INFO: enter test to run
[17:04:49.614] INFO: test: HighRate no parameter change
[17:04:49.614] INFO: running: highrate
[17:04:49.615] INFO: ----------------------------------------------------------------------
[17:04:49.615] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[17:04:49.615] INFO: ----------------------------------------------------------------------
[17:04:50.234] INFO: Expecting 208000 events.
[17:05:02.167] INFO: 208000 events read in total (11407ms).
[17:05:02.170] INFO: Test took 12545ms.
[17:05:02.329] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:05:02.584] INFO: number of dead pixels (per ROC): 0 0 0 1 0 0 1 0 0 3 0 0 3 0 0 0
[17:05:02.584] INFO: number of red-efficiency pixels: 89 53 101 137 156 171 161 169 117 153 153 95 130 50 29 30
[17:05:02.584] INFO: number of X-ray hits detected: 63544 42520 68711 114785 123023 131374 135177 102061 94727 108608 104448 82218 82835 49518 23257 26436
[17:05:02.584] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[17:05:02.584] INFO: number of Vcal hits detected: 207909 207947 207895 207813 207840 207825 207786 207822 207881 207695 207843 207903 207718 207949 207971 207970
[17:05:02.584] INFO: Vcal hit fiducial efficiency (%): 100.0 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
[17:05:02.584] INFO: Vcal hit overall efficiency (%): 100.0 100.0 99.9 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
[17:05:02.584] INFO: X-ray hit rate [MHz/cm2]: 18.6 12.5 20.1 33.6 36.1 38.5 39.6 29.9 27.8 31.8 30.6 24.1 24.3 14.5 6.8 7.7
[17:05:02.584] INFO: PixTestHighRate::doXPixelAlive() done
[17:05:02.638] INFO: PixTest:: pg_setup set to default.
[17:05:02.652] INFO: enter test to run
[17:05:47.726] INFO: test: HighRate no parameter change
[17:05:47.726] INFO: running: highrate
[17:05:47.727] INFO: ----------------------------------------------------------------------
[17:05:47.727] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[17:05:47.727] INFO: ----------------------------------------------------------------------
[17:05:48.342] INFO: Expecting 208000 events.
[17:06:02.131] INFO: 208000 events read in total (13262ms).
[17:06:02.137] INFO: Test took 14400ms.
[17:06:02.453] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:06:02.759] INFO: number of dead pixels (per ROC): 0 0 0 1 0 0 1 0 0 3 0 0 3 0 0 0
[17:06:02.759] INFO: number of red-efficiency pixels: 168 112 284 376 596 521 552 504 335 508 467 297 297 153 53 67
[17:06:02.759] INFO: number of X-ray hits detected: 130442 86944 140659 235006 250482 269114 275807 208265 195034 222570 214558 168164 169349 100444 47636 55456
[17:06:02.759] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[17:06:02.759] INFO: number of Vcal hits detected: 207823 207887 207693 207544 207348 207415 207319 207425 207641 207303 207495 207689 207540 207837 207946 207933
[17:06:02.759] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.7 99.7 99.7 99.8 99.7 99.8 99.9 99.9 99.9 100.0 100.0
[17:06:02.759] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.7 99.7 99.7 99.8 99.7 99.8 99.9 99.8 99.9 100.0 100.0
[17:06:02.759] INFO: X-ray hit rate [MHz/cm2]: 38.2 25.5 41.2 68.9 73.4 78.9 80.8 61.0 57.2 65.2 62.9 49.3 49.6 29.4 14.0 16.3
[17:06:02.759] INFO: PixTestHighRate::doXPixelAlive() done
[17:06:02.811] INFO: PixTest:: pg_setup set to default.
[17:06:02.823] INFO: enter test to run
[17:06:35.325] INFO: test: HighRate no parameter change
[17:06:35.325] INFO: running: highrate
[17:06:35.326] INFO: ----------------------------------------------------------------------
[17:06:35.327] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[17:06:35.327] INFO: ----------------------------------------------------------------------
[17:06:35.944] INFO: Expecting 208000 events.
[17:06:51.925] INFO: 208000 events read in total (15454ms).
[17:06:51.933] INFO: Test took 16598ms.
[17:06:52.430] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:06:52.788] INFO: number of dead pixels (per ROC): 0 0 0 1 0 0 1 0 0 3 0 0 3 0 0 0
[17:06:52.788] INFO: number of red-efficiency pixels: 374 273 678 953 1473 1245 1347 1159 648 1215 1125 694 745 297 94 104
[17:06:52.788] INFO: number of X-ray hits detected: 200336 133489 216283 360899 382702 413112 424269 321561 299853 341875 328864 259330 260893 155276 73598 84528
[17:06:52.788] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[17:06:52.788] INFO: number of Vcal hits detected: 207584 207700 207082 206792 206024 206353 206106 206285 207242 206304 206627 207209 206994 207683 207900 207894
[17:06:52.788] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.6 99.5 99.1 99.3 99.2 99.3 99.7 99.3 99.4 99.7 99.6 99.9 100.0 99.9
[17:06:52.788] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.6 99.4 99.1 99.2 99.1 99.2 99.6 99.2 99.3 99.6 99.5 99.8 100.0 99.9
[17:06:52.788] INFO: X-ray hit rate [MHz/cm2]: 58.7 39.1 63.4 105.8 112.2 121.1 124.4 94.3 87.9 100.2 96.4 76.0 76.5 45.5 21.6 24.8
[17:06:52.788] INFO: PixTestHighRate::doXPixelAlive() done
[17:06:52.833] INFO: PixTest:: pg_setup set to default.
[17:06:52.847] INFO: enter test to run
[17:07:14.429] INFO: test: exit no parameter change
[17:07:14.798] QUIET: Connection to board 33 closed.
[17:07:14.800] INFO: pXar: this is the end, my friend