[17:10:28.802] INFO: *** Welcome to pxar ***
[17:10:28.802] INFO: *** Today: 2016/09/28
[17:10:28.840] INFO: *** Version: v1.9.0-818-g96727
[17:10:28.840] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//dacParameters35_C15.dat
[17:10:28.841] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//tbmParameters_C0b.dat
[17:10:28.841] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//defaultMaskFile.dat
[17:10:28.841] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C15.dat
[17:10:28.913] INFO: clk: 4
[17:10:28.913] INFO: ctr: 4
[17:10:28.913] INFO: sda: 19
[17:10:28.913] INFO: tin: 9
[17:10:28.913] INFO: level: 15
[17:10:28.913] INFO: triggerdelay: 0
[17:10:28.913] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[17:10:28.913] INFO: Log level: INFO
[17:10:28.932] QUIET: Connection to board DTB_WREHUL opened.
[17:10:28.935] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 30
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREHUL
MAC address: 40D85511801E
Hostname: pixelDTB030
Comment:
------------------------------------------------------
[17:10:28.938] INFO: RPC call hashes of host and DTB match: 398089610
[17:10:30.470] INFO: DUT info:
[17:10:30.471] INFO: The DUT currently contains the following objects:
[17:10:30.471] INFO: 2 TBM Cores tbm08c (2 ON)
[17:10:30.471] INFO: TBM Core alpha (0): 7 registers set
[17:10:30.471] INFO: TBM Core beta (1): 7 registers set
[17:10:30.471] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[17:10:30.471] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[17:10:30.471] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[17:10:30.471] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[17:10:30.471] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[17:10:30.471] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[17:10:30.471] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[17:10:30.471] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[17:10:30.471] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[17:10:30.471] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[17:10:30.471] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[17:10:30.471] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[17:10:30.471] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[17:10:30.471] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[17:10:30.471] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[17:10:30.471] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[17:10:30.471] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[17:10:30.875] INFO: enter 'restricted' command line mode
[17:10:30.875] INFO: enter test to run
[17:11:03.636] INFO: test: PixelAlive no parameter change
[17:11:03.636] INFO: running: pixelalive
[17:11:03.645] INFO: ----------------------------------------------------------------------
[17:11:03.645] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[17:11:03.645] INFO: ----------------------------------------------------------------------
[17:11:03.964] INFO: Expecting 41600 events.
[17:11:08.295] INFO: 41600 events read in total (3612ms).
[17:11:08.462] INFO: Test took 4815ms.
[17:11:08.475] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:11:08.756] INFO: PixTestAlive::aliveTest() done
[17:11:08.756] INFO: number of dead pixels (per ROC): 0 1 0 0 0 0 0 0 0 0 3 0 0 0 0 0
[17:11:08.792] INFO: enter test to run
[17:11:18.275] INFO: test: timing no parameter change
[17:11:18.276] INFO: running: timing
[17:11:18.279] INFO: ######################################################################
[17:11:18.279] INFO: PixTestTiming::doTest()
[17:11:18.279] INFO: ######################################################################
[17:11:18.279] INFO: ----------------------------------------------------------------------
[17:11:18.279] INFO: PixTestTiming::TBMPhaseScan()
[17:11:18.279] INFO: ----------------------------------------------------------------------
[17:16:16.768] INFO: TBM Phase Settings: 208
[17:16:16.768] INFO: 400MHz Phase: 4
[17:16:16.769] INFO: 160MHz Phase: 6
[17:16:16.769] INFO: Functional Phase Area: 4
[17:16:16.772] INFO: Test took 298493 ms.
[17:16:16.772] INFO: PixTestTiming::TBMPhaseScan() done.
[17:16:16.772] INFO: ----------------------------------------------------------------------
[17:16:16.772] INFO: PixTestTiming::ROCDelayScan()
[17:16:16.772] INFO: ----------------------------------------------------------------------
[17:19:08.325] INFO: ROC Delay Settings: 220
[17:19:08.325] INFO: ROC Header-Trailer/Token Delay: 11
[17:19:08.325] INFO: ROC Port 0 Delay: 4
[17:19:08.325] INFO: ROC Port 1 Delay: 3
[17:19:08.325] INFO: Functional ROC Area: 3
[17:19:08.328] INFO: Test took 171557 ms.
[17:19:08.329] INFO: PixTestTiming::ROCDelayScan() done.
[17:19:08.329] INFO: ----------------------------------------------------------------------
[17:19:08.329] INFO: PixTestTiming::TimingTest()
[17:19:08.329] INFO: ----------------------------------------------------------------------




[17:19:24.827] INFO: Fetched DAQ statistics. Counters are being reset now.







[17:19:40.305] INFO: Fetched DAQ statistics. Counters are being reset now.


[17:19:55.376] INFO: Fetched DAQ statistics. Counters are being reset now.


[17:20:10.708] INFO: Fetched DAQ statistics. Counters are being reset now.










[17:20:26.371] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:20:41.545] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:20:56.611] INFO: Fetched DAQ statistics. Counters are being reset now.

[17:21:11.530] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:21:26.458] INFO: Fetched DAQ statistics. Counters are being reset now.


[17:21:41.535] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:21:41.922] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:21:41.935] INFO: ----------------------------------------------------------------------
[17:21:41.935] INFO: The fraction of properly decoded events is 100.00%: 9999994/10000000
[17:21:41.935] INFO: ----------------------------------------------------------------------
[17:21:41.935] INFO: ----------------------------------------------------------------------
[17:21:41.935] INFO: Read back bit status: 0
[17:21:41.935] INFO: ----------------------------------------------------------------------



[17:21:41.935] INFO: Test took 153606 ms.
[17:21:41.935] INFO: PixTestTiming::TimingTest() done.
[17:21:41.935] INFO: Problem with TimingTest! Timings not saved!
[17:21:41.935] INFO: PixTestTiming::doTest took 623659 ms.
[17:21:41.935] INFO: PixTestTiming::doTest() done
[17:21:41.935] INFO: Write out TBMPhaseScan_0_V0
[17:21:41.935] INFO: Write out TBMPhaseScan_1_V0
[17:21:41.935] INFO: Write out CombinedTBMPhaseScan_V0
[17:21:41.963] INFO: Write out ROCDelayScan3_V0
[17:21:41.964] INFO: enter test to run
[17:21:46.063] INFO: test: exit no parameter change
[17:21:46.340] QUIET: Connection to board 30 closed.
[17:21:46.341] INFO: pXar: this is the end, my friend
[11:49:48.238] INFO: *** Welcome to pxar ***
[11:49:48.270] INFO: *** Today: 2016/10/21
[11:49:48.282] INFO: *** Version: v1.9.0-818-g96727
[11:49:48.283] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//dacParameters35_C15.dat
[11:49:48.283] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:49:48.283] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//defaultMaskFile.dat
[11:49:48.283] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C15.dat
[11:49:48.352] INFO: clk: 4
[11:49:48.352] INFO: ctr: 4
[11:49:48.352] INFO: sda: 19
[11:49:48.352] INFO: tin: 9
[11:49:48.352] INFO: level: 15
[11:49:48.352] INFO: triggerdelay: 0
[11:49:48.352] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[11:49:48.352] INFO: Log level: INFO
[11:49:48.366] QUIET: Connection to board DTB_WREKRL opened.
[11:49:48.370] 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:
------------------------------------------------------
[11:49:48.372] INFO: RPC call hashes of host and DTB match: 398089610
[11:49:49.910] INFO: DUT info:
[11:49:49.910] INFO: The DUT currently contains the following objects:
[11:49:49.910] INFO: 2 TBM Cores tbm08c (2 ON)
[11:49:49.910] INFO: TBM Core alpha (0): 7 registers set
[11:49:49.910] INFO: TBM Core beta (1): 7 registers set
[11:49:49.910] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:49:49.910] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:49:49.910] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:49:49.910] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:49:49.910] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:49:49.911] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:49:49.911] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:49:49.911] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:49:49.911] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:49:49.911] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:49:49.911] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:49:49.911] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:49:49.911] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:49:49.911] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:49:49.911] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:49:49.911] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:49:49.911] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:49:50.314] INFO: enter 'restricted' command line mode
[11:49:50.314] INFO: enter test to run
[11:50:02.427] INFO: test: PixelAlive no parameter change
[11:50:02.427] INFO: running: pixelalive
[11:50:02.436] INFO: ----------------------------------------------------------------------
[11:50:02.436] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[11:50:02.436] INFO: ----------------------------------------------------------------------
[11:50:02.761] INFO: Expecting 41600 events.
[11:50:07.049] INFO: 41600 events read in total (3570ms).
[11:50:07.214] INFO: Test took 4774ms.
[11:50:07.220] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:50:07.549] INFO: PixTestAlive::aliveTest() done
[11:50:07.549] INFO: number of dead pixels (per ROC): 0 1 0 0 0 0 0 0 0 0 3 0 0 0 0 0
[11:50:07.582] INFO: enter test to run
[11:50:21.779] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:50:21.779] INFO: running: highrate
[11:50:21.780] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:50:21.945] INFO: ----------------------------------------------------------------------
[11:50:21.945] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:50:21.945] INFO: ----------------------------------------------------------------------
[11:50:21.945] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:50:21.946] INFO: edge/corner pixel THR is adjusted
[11:50:21.946] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:50:22.905] INFO: Collecting data for 5 seconds...
[11:50:27.923] INFO: Done with hot pixel readout
[11:50:40.226] INFO: PixTest:: pg_setup set to default.

[11:50:40.228] INFO: 52 hot pixels found in step 0
[11:50:41.220] INFO: Collecting data for 5 seconds...
[11:50:46.238] INFO: Done with hot pixel readout
[11:50:58.525] INFO: PixTest:: pg_setup set to default.


[11:50:58.526] INFO: 51 hot pixels found in step 1
[11:50:59.525] INFO: Collecting data for 5 seconds...
[11:51:04.543] INFO: Done with hot pixel readout
[11:51:16.705] INFO: PixTest:: pg_setup set to default.





[11:51:16.706] INFO: 51 hot pixels found in step 2
[11:51:17.702] INFO: Collecting data for 5 seconds...
[11:51:22.720] INFO: Done with hot pixel readout
[11:51:34.826] INFO: PixTest:: pg_setup set to default.





[11:51:34.827] INFO: 51 hot pixels found in step 3
[11:51:35.823] INFO: Collecting data for 5 seconds...
[11:51:40.841] INFO: Done with hot pixel readout
[11:51:53.118] INFO: PixTest:: pg_setup set to default.




[11:51:53.119] INFO: 57 hot pixels found in step 4
[11:51:54.113] INFO: Collecting data for 5 seconds...
[11:51:59.132] INFO: Done with hot pixel readout
[11:52:11.263] INFO: PixTest:: pg_setup set to default.




[11:52:11.264] INFO: 44 hot pixels found in step 5
[11:52:12.259] INFO: Collecting data for 5 seconds...
[11:52:17.277] INFO: Done with hot pixel readout
[11:52:29.507] INFO: PixTest:: pg_setup set to default.




[11:52:29.508] INFO: 44 hot pixels found in step 6
[11:52:30.504] INFO: Collecting data for 5 seconds...
[11:52:35.523] INFO: Done with hot pixel readout
[11:52:47.761] INFO: PixTest:: pg_setup set to default.


[11:52:47.762] INFO: 44 hot pixels found in step 7
[11:52:48.757] INFO: Collecting data for 5 seconds...
[11:52:53.775] INFO: Done with hot pixel readout
[11:53:05.890] INFO: PixTest:: pg_setup set to default.





[11:53:05.891] INFO: 39 hot pixels found in step 8
[11:53:06.885] INFO: Collecting data for 5 seconds...
[11:53:11.903] INFO: Done with hot pixel readout
[11:53:24.080] INFO: PixTest:: pg_setup set to default.

[11:53:24.081] INFO: 44 hot pixels found in step 9
[11:53:25.075] INFO: Collecting data for 5 seconds...
[11:53:30.093] INFO: Done with hot pixel readout
[11:53:42.251] INFO: PixTest:: pg_setup set to default.






[11:53:42.253] INFO: 38 hot pixels found in step 10
[11:53:43.248] INFO: Collecting data for 5 seconds...
[11:53:48.265] INFO: Done with hot pixel readout
[11:54:00.651] INFO: PixTest:: pg_setup set to default.






[11:54:00.652] INFO: 33 hot pixels found in step 11
[11:54:01.646] INFO: Collecting data for 5 seconds...
[11:54:06.665] INFO: Done with hot pixel readout
[11:54:19.300] INFO: PixTest:: pg_setup set to default.








[11:54:19.301] INFO: 41 hot pixels found in step 12
[11:54:20.296] INFO: Collecting data for 5 seconds...
[11:54:25.318] INFO: Done with hot pixel readout
[11:54:37.789] INFO: PixTest:: pg_setup set to default.





[11:54:37.790] INFO: 34 hot pixels found in step 13
[11:54:38.785] INFO: Collecting data for 5 seconds...
[11:54:43.805] INFO: Done with hot pixel readout
[11:54:56.426] INFO: PixTest:: pg_setup set to default.



[11:54:56.427] INFO: 22 hot pixels found in step 14
[11:54:56.465] INFO: 22 hot pixels could not be trimmed and have been masked.
[11:54:56.469] INFO: PixTest::trimHotPixels() done
[11:54:56.481] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C0.dat
[11:54:56.489] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C1.dat
[11:54:56.499] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C2.dat
[11:54:56.504] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C3.dat
[11:54:56.510] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C4.dat
[11:54:56.515] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C5.dat
[11:54:56.520] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C6.dat
[11:54:56.546] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C7.dat
[11:54:56.552] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C8.dat
[11:54:56.557] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C9.dat
[11:54:56.563] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C10.dat
[11:54:56.568] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C11.dat
[11:54:56.573] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C12.dat
[11:54:56.579] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C13.dat
[11:54:56.584] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C14.dat
[11:54:56.590] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//trimParameters35_C15.dat
[11:54:56.595] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-P-6-29_FPIXTest-17C-FNAL-160913-1810-300V_2016-09-13_18h23m_1473808983/000_FPIXTest_p17//defaultMaskFile.dat
[11:54:56.610] INFO: enter test to run
[11:55:14.273] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:55:14.273] INFO: running: xray
[11:55:14.274] INFO: ----------------------------------------------------------------------
[11:55:14.274] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:55:14.274] INFO: ----------------------------------------------------------------------
[11:55:15.306] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:55:26.401] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[11:55:54.025] INFO: Resuming triggers.
[11:56:05.147] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[11:56:35.304] INFO: Resuming triggers.
[11:56:46.400] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[11:57:17.246] INFO: Resuming triggers.
[11:57:28.343] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[11:57:58.704] INFO: Resuming triggers.
[11:58:09.801] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[11:58:39.407] INFO: Resuming triggers.
[11:58:50.504] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[11:59:20.203] INFO: Resuming triggers.
[11:59:31.314] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[12:00:00.923] INFO: Resuming triggers.
[12:00:12.015] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[12:00:41.585] INFO: Resuming triggers.
[12:00:52.678] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[12:01:22.266] INFO: Resuming triggers.
[12:01:22.773] INFO: data taking finished, elapsed time: 100 seconds.
[12:01:24.566] INFO: PixTest:: pg_setup set to default.
[12:01:24.583] INFO: PixTestXray::doPhRun() done
[12:01:25.150] INFO: enter test to run
[12:01:49.366] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:01:49.381] INFO: running: xray
[12:01:49.407] INFO: ----------------------------------------------------------------------
[12:01:49.407] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:01:49.407] INFO: ----------------------------------------------------------------------
[12:01:50.384] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:01:56.807] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[12:02:27.093] INFO: Resuming triggers.
[12:02:33.516] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[12:03:03.820] INFO: Resuming triggers.
[12:03:10.245] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[12:03:40.520] INFO: Resuming triggers.
[12:03:46.944] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[12:04:17.932] INFO: Resuming triggers.
[12:04:24.354] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[12:04:55.087] INFO: Resuming triggers.
[12:05:01.513] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[12:05:31.964] INFO: Resuming triggers.
[12:05:38.390] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[12:06:09.329] INFO: Resuming triggers.
[12:06:15.752] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[12:06:46.720] INFO: Resuming triggers.
[12:06:53.144] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[12:07:23.898] INFO: Resuming triggers.
[12:07:30.328] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[12:08:01.296] INFO: Resuming triggers.
[12:08:07.722] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[12:08:38.844] INFO: Resuming triggers.
[12:08:45.272] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[12:09:16.514] INFO: Resuming triggers.
[12:09:22.939] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[12:09:54.758] INFO: Resuming triggers.
[12:10:01.185] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[12:10:32.484] INFO: Resuming triggers.
[12:10:38.912] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[12:11:10.163] INFO: Resuming triggers.
[12:11:14.151] INFO: data taking finished, elapsed time: 100 seconds.
[12:11:33.841] INFO: PixTest:: pg_setup set to default.
[12:11:33.845] INFO: PixTestXray::doPhRun() done
[12:11:34.483] INFO: enter test to run
[12:11:54.818] INFO: test: HighRate no parameter change
[12:11:54.818] INFO: running: highrate
[12:11:54.986] INFO: ----------------------------------------------------------------------
[12:11:54.986] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:11:54.986] INFO: ----------------------------------------------------------------------
[12:11:55.339] INFO: Expecting 768 events.
[12:11:56.500] INFO: 768 events read in total (445ms).
[12:11:56.500] INFO: Test took 1324ms.
[12:11:57.351] INFO: Expecting 41600 events.
[12:12:00.529] INFO: 41600 events read in total (2651ms).
[12:12:00.530] INFO: Test took 3791ms.
[12:12:00.566] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:01.289] INFO: Expecting 41600 events.
[12:12:04.610] INFO: 41600 events read in total (2794ms).
[12:12:04.611] INFO: Test took 3945ms.
[12:12:04.648] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:05.366] INFO: Expecting 41600 events.
[12:12:08.735] INFO: 41600 events read in total (2842ms).
[12:12:08.736] INFO: Test took 4068ms.
[12:12:08.779] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:09.485] INFO: Expecting 41600 events.
[12:12:12.808] INFO: 41600 events read in total (2796ms).
[12:12:12.809] INFO: Test took 4011ms.
[12:12:12.847] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:13.561] INFO: Expecting 41600 events.
[12:12:16.899] INFO: 41600 events read in total (2811ms).
[12:12:16.900] INFO: Test took 4034ms.
[12:12:16.943] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:17.649] INFO: Expecting 41600 events.
[12:12:20.929] INFO: 41600 events read in total (2753ms).
[12:12:20.930] INFO: Test took 3969ms.
[12:12:20.967] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:21.683] INFO: Expecting 41600 events.
[12:12:25.068] INFO: 41600 events read in total (2859ms).
[12:12:25.069] INFO: Test took 4083ms.
[12:12:25.107] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:25.821] INFO: Expecting 41600 events.
[12:12:29.136] INFO: 41600 events read in total (2788ms).
[12:12:29.137] INFO: Test took 4010ms.
[12:12:29.175] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:29.890] INFO: Expecting 41600 events.
[12:12:33.168] INFO: 41600 events read in total (2751ms).
[12:12:33.169] INFO: Test took 3976ms.
[12:12:33.206] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:33.922] INFO: Expecting 41600 events.
[12:12:37.180] INFO: 41600 events read in total (2732ms).
[12:12:37.182] INFO: Test took 3957ms.
[12:12:37.218] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:37.940] INFO: Expecting 41600 events.
[12:12:41.210] INFO: 41600 events read in total (2743ms).
[12:12:41.211] INFO: Test took 3973ms.
[12:12:41.247] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:41.966] INFO: Expecting 41600 events.
[12:12:45.231] INFO: 41600 events read in total (2738ms).
[12:12:45.232] INFO: Test took 3967ms.
[12:12:45.268] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:45.989] INFO: Expecting 41600 events.
[12:12:49.261] INFO: 41600 events read in total (2745ms).
[12:12:49.262] INFO: Test took 3975ms.
[12:12:49.298] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:50.018] INFO: Expecting 41600 events.
[12:12:53.271] INFO: 41600 events read in total (2726ms).
[12:12:53.272] INFO: Test took 3954ms.
[12:12:53.308] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:54.029] INFO: Expecting 41600 events.
[12:12:57.252] INFO: 41600 events read in total (2696ms).
[12:12:57.253] INFO: Test took 3926ms.
[12:12:57.289] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:57.005] INFO: Expecting 41600 events.
[12:13:01.261] INFO: 41600 events read in total (2729ms).
[12:13:01.262] INFO: Test took 3954ms.
[12:13:01.299] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:02.017] INFO: Expecting 41600 events.
[12:13:05.279] INFO: 41600 events read in total (2735ms).
[12:13:05.280] INFO: Test took 3961ms.
[12:13:05.317] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:06.033] INFO: Expecting 41600 events.
[12:13:09.300] INFO: 41600 events read in total (2740ms).
[12:13:09.301] INFO: Test took 3966ms.
[12:13:09.337] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:10.054] INFO: Expecting 41600 events.
[12:13:13.282] INFO: 41600 events read in total (2701ms).
[12:13:13.283] INFO: Test took 3926ms.
[12:13:13.319] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:14.037] INFO: Expecting 41600 events.
[12:13:17.122] INFO: 41600 events read in total (2558ms).
[12:13:17.123] INFO: Test took 3783ms.
[12:13:17.159] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:17.520] INFO: enter test to run
[12:13:33.033] INFO: test: HighRate no parameter change
[12:13:33.033] INFO: running: highrate
[12:13:33.034] INFO: ----------------------------------------------------------------------
[12:13:33.035] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:13:33.035] INFO: ----------------------------------------------------------------------
[12:13:33.657] INFO: Expecting 208000 events.
[12:13:45.634] INFO: 208000 events read in total (11450ms).
[12:13:45.640] INFO: Test took 12586ms.
[12:13:45.797] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:46.054] INFO: number of dead pixels (per ROC): 0 1 0 0 0 0 0 0 0 0 3 0 0 0 0 0
[12:13:46.067] INFO: number of red-efficiency pixels: 78 54 90 102 149 159 170 143 95 138 150 102 120 81 23 34
[12:13:46.067] INFO: number of X-ray hits detected: 62108 42724 72202 112411 122068 125578 125946 97637 89603 113084 104469 89694 91699 56317 22145 26286
[12:13:46.067] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:13:46.067] INFO: number of Vcal hits detected: 207921 207896 207909 207894 207850 207837 207828 207856 207905 207858 207698 207895 207878 207919 207976 207966
[12:13:46.067] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[12:13:46.067] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[12:13:46.067] INFO: X-ray hit rate [MHz/cm2]: 18.2 12.5 21.2 32.9 35.8 36.8 36.9 28.6 26.3 33.1 30.6 26.3 26.9 16.5 6.5 7.7
[12:13:46.067] INFO: PixTestHighRate::doXPixelAlive() done
[12:13:46.119] INFO: PixTest:: pg_setup set to default.
[12:13:46.133] INFO: enter test to run
[12:14:09.857] INFO: test: HighRate no parameter change
[12:14:09.857] INFO: running: highrate
[12:14:09.858] INFO: ----------------------------------------------------------------------
[12:14:09.858] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:14:09.858] INFO: ----------------------------------------------------------------------
[12:14:10.482] INFO: Expecting 208000 events.
[12:14:24.384] INFO: 208000 events read in total (13375ms).
[12:14:24.390] INFO: Test took 14522ms.
[12:14:24.722] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:25.031] INFO: number of dead pixels (per ROC): 0 1 0 0 0 0 0 0 0 0 3 0 0 0 0 0
[12:14:25.032] INFO: number of red-efficiency pixels: 224 136 303 429 471 534 594 480 345 556 481 333 370 244 42 53
[12:14:25.032] INFO: number of X-ray hits detected: 127865 87765 148151 233051 251020 259578 259337 201884 184078 234508 217474 184822 190116 116453 45610 54330
[12:14:25.032] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:14:25.032] INFO: number of Vcal hits detected: 207756 207808 207654 207538 207487 207397 207332 207467 207631 207383 207323 207639 207612 207738 207958 207946
[12:14:25.032] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.7 99.7 99.8 99.8 99.7 99.8 99.8 99.8 99.9 100.0 100.0
[12:14:25.032] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.8 99.8 99.7 99.7 99.7 99.8 99.7 99.7 99.8 99.8 99.9 100.0 100.0
[12:14:25.032] INFO: X-ray hit rate [MHz/cm2]: 37.5 25.7 43.4 68.3 73.6 76.1 76.0 59.2 54.0 68.7 63.7 54.2 55.7 34.1 13.4 15.9
[12:14:25.032] INFO: PixTestHighRate::doXPixelAlive() done
[12:14:25.081] INFO: PixTest:: pg_setup set to default.
[12:14:25.097] INFO: enter test to run
[12:14:42.713] INFO: test: HighRate no parameter change
[12:14:42.713] INFO: running: highrate
[12:14:42.714] INFO: ----------------------------------------------------------------------
[12:14:42.714] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:14:42.714] INFO: ----------------------------------------------------------------------
[12:14:43.328] INFO: Expecting 208000 events.
[12:14:59.340] INFO: 208000 events read in total (15485ms).
[12:14:59.348] INFO: Test took 16625ms.
[12:14:59.840] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:00.202] INFO: number of dead pixels (per ROC): 0 1 0 0 0 0 0 0 0 0 3 0 0 0 0 0
[12:15:00.202] INFO: number of red-efficiency pixels: 499 302 684 1010 1164 1325 1488 951 742 1402 1156 747 864 537 72 108
[12:15:00.202] INFO: number of X-ray hits detected: 193564 132864 224777 351943 381317 392241 392508 304849 280646 353743 328944 281330 287659 177265 68942 83158
[12:15:00.202] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:15:00.202] INFO: number of Vcal hits detected: 207377 207622 207072 206736 206562 206133 205846 206734 207112 206137 206384 207099 206976 207332 207927 207888
[12:15:00.202] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.6 99.5 99.4 99.2 99.1 99.5 99.6 99.2 99.4 99.6 99.6 99.7 100.0 99.9
[12:15:00.202] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.6 99.4 99.3 99.1 99.0 99.4 99.6 99.1 99.2 99.6 99.5 99.7 100.0 99.9
[12:15:00.202] INFO: X-ray hit rate [MHz/cm2]: 56.7 38.9 65.9 103.2 111.8 115.0 115.0 89.4 82.3 103.7 96.4 82.5 84.3 52.0 20.2 24.4
[12:15:00.202] INFO: PixTestHighRate::doXPixelAlive() done
[12:15:00.250] INFO: PixTest:: pg_setup set to default.
[12:15:00.269] INFO: enter test to run
[12:15:09.793] INFO: test: exit no parameter change
[12:15:10.352] QUIET: Connection to board 33 closed.
[12:15:10.544] INFO: pXar: this is the end, my friend