[11:04:47.080] INFO: *** Welcome to pxar ***
[11:04:47.081] INFO: *** Today: 2016/04/29
[11:04:47.100] INFO: *** Version: v1.9.0-796-gef167-dirty
[11:04:47.100] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//dacParameters35_C15.dat
[11:04:47.101] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:04:47.101] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//defaultMaskFile.dat
[11:04:47.101] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C15.dat
[11:04:47.176] INFO: clk: 4
[11:04:47.176] INFO: ctr: 4
[11:04:47.176] INFO: sda: 19
[11:04:47.176] INFO: tin: 9
[11:04:47.176] INFO: level: 15
[11:04:47.177] INFO: triggerdelay: 0
[11:04:47.177] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[11:04:47.177] INFO: Log level: INFO
[11:04:47.195] QUIET: Connection to board DTB_WREKRL opened.
[11:04:47.198] 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:04:47.201] INFO: RPC call hashes of host and DTB match: 398089610
[11:04:48.734] INFO: DUT info:
[11:04:48.734] INFO: The DUT currently contains the following objects:
[11:04:48.734] INFO: 2 TBM Cores tbm08c (2 ON)
[11:04:48.734] INFO: TBM Core alpha (0): 7 registers set
[11:04:48.734] INFO: TBM Core beta (1): 7 registers set
[11:04:48.734] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:04:48.734] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:48.734] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:48.734] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:48.734] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:48.734] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:48.734] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:48.734] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:48.735] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:48.735] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:48.735] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:48.735] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:48.735] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:48.735] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:48.735] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:48.735] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:48.735] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:49.138] INFO: enter 'restricted' command line mode
[11:04:49.138] INFO: enter test to run
[11:04:50.784] INFO: test: timing no parameter change
[11:04:50.784] INFO: running: timing
[11:04:50.794] INFO: ######################################################################
[11:04:50.794] INFO: PixTestTiming::doTest()
[11:04:50.794] INFO: ######################################################################
[11:04:50.794] INFO: ----------------------------------------------------------------------
[11:04:50.794] INFO: PixTestTiming::TBMPhaseScan()
[11:04:50.794] INFO: ----------------------------------------------------------------------
[11:09:16.830] INFO: TBM Phase Settings: 248
[11:09:16.830] INFO: 400MHz Phase: 6
[11:09:16.830] INFO: 160MHz Phase: 7
[11:09:16.830] INFO: Functional Phase Area: 4
[11:09:16.833] INFO: Test took 266039 ms.
[11:09:16.833] INFO: PixTestTiming::TBMPhaseScan() done.
[11:09:16.833] INFO: ----------------------------------------------------------------------
[11:09:16.833] INFO: PixTestTiming::ROCDelayScan()
[11:09:16.833] INFO: ----------------------------------------------------------------------
[11:11:24.755] INFO: ROC Delay Settings: 228
[11:11:24.755] INFO: ROC Header-Trailer/Token Delay: 11
[11:11:24.755] INFO: ROC Port 0 Delay: 4
[11:11:24.755] INFO: ROC Port 1 Delay: 4
[11:11:24.755] INFO: Functional ROC Area: 5
[11:11:24.758] INFO: Test took 127925 ms.
[11:11:24.758] INFO: PixTestTiming::ROCDelayScan() done.
[11:11:24.758] INFO: ----------------------------------------------------------------------
[11:11:24.758] INFO: PixTestTiming::TimingTest()
[11:11:24.758] INFO: ----------------------------------------------------------------------
[11:11:40.915] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:11:55.920] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:12:10.907] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:12:25.884] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:12:40.886] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:12:55.874] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:10.868] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:25.849] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:40.835] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:55.820] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:56.198] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:56.215] INFO: ----------------------------------------------------------------------
[11:13:56.215] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:13:56.215] INFO: ----------------------------------------------------------------------
[11:13:56.215] INFO: ----------------------------------------------------------------------
[11:13:56.215] INFO: Read back bit status: 1
[11:13:56.215] INFO: ----------------------------------------------------------------------
[11:13:56.215] INFO: ----------------------------------------------------------------------
[11:13:56.215] INFO: Timings are good!
[11:13:56.215] INFO: ----------------------------------------------------------------------
[11:13:56.215] INFO: Test took 151457 ms.
[11:13:56.215] INFO: PixTestTiming::TimingTest() done.
[11:13:56.215] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:13:56.215] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:13:56.215] INFO: PixTestTiming::doTest took 545426 ms.
[11:13:56.215] INFO: PixTestTiming::doTest() done
[11:13:56.215] INFO: Write out TBMPhaseScan_0_V0
[11:13:56.241] INFO: Write out TBMPhaseScan_1_V0
[11:13:56.241] INFO: Write out CombinedTBMPhaseScan_V0
[11:13:56.242] INFO: Write out ROCDelayScan3_V0
[11:13:56.243] INFO: enter test to run
[11:14:17.020] INFO: test: PixelAlive no parameter change
[11:14:17.021] INFO: running: pixelalive
[11:14:17.025] INFO: ----------------------------------------------------------------------
[11:14:17.025] 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:14:17.025] INFO: ----------------------------------------------------------------------
[11:14:17.347] INFO: Expecting 41600 events.
[11:14:21.666] INFO: 41600 events read in total (3603ms).
[11:14:21.667] INFO: Test took 4640ms.
[11:14:21.673] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:22.070] INFO: PixTestAlive::aliveTest() done
[11:14:22.070] INFO: number of dead pixels (per ROC): 0 0 0 0 0 3 2 2 0 0 1 0 0 0 2 0
[11:14:22.074] INFO: enter test to run
[11:15:12.044] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:15:12.044] INFO: running: highrate
[11:15:12.045] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:15:12.196] INFO: ----------------------------------------------------------------------
[11:15:12.196] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:15:12.196] INFO: ----------------------------------------------------------------------
[11:15:12.196] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:15:12.196] INFO: edge/corner pixel THR is adjusted
[11:15:12.196] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:15:13.154] INFO: Collecting data for 5 seconds...
[11:15:18.170] INFO: Done with hot pixel readout
[11:15:30.861] INFO: PixTest:: pg_setup set to default.
[11:15:30.863] INFO: 180 hot pixels found in step 0
[11:15:31.860] INFO: Collecting data for 5 seconds...
[11:15:36.876] INFO: Done with hot pixel readout
[11:15:46.434] INFO: PixTest:: pg_setup set to default.
[11:15:46.435] INFO: 157 hot pixels found in step 1
[11:15:47.432] INFO: Collecting data for 5 seconds...
[11:15:52.443] INFO: Done with hot pixel readout
[11:16:04.664] INFO: PixTest:: pg_setup set to default.

[11:16:04.665] INFO: 167 hot pixels found in step 2
[11:16:05.663] INFO: Collecting data for 5 seconds...
[11:16:10.680] INFO: Done with hot pixel readout
[11:16:23.422] INFO: PixTest:: pg_setup set to default.




[11:16:23.423] INFO: 148 hot pixels found in step 3
[11:16:24.420] INFO: Collecting data for 5 seconds...
[11:16:29.436] INFO: Done with hot pixel readout
[11:16:42.139] INFO: PixTest:: pg_setup set to default.



[11:16:42.141] INFO: 142 hot pixels found in step 4
[11:16:43.138] INFO: Collecting data for 5 seconds...
[11:16:48.155] INFO: Done with hot pixel readout
[11:17:00.857] INFO: PixTest:: pg_setup set to default.






[11:17:00.858] INFO: 145 hot pixels found in step 5
[11:17:01.855] INFO: Collecting data for 5 seconds...
[11:17:06.871] INFO: Done with hot pixel readout
[11:17:19.602] INFO: PixTest:: pg_setup set to default.



[11:17:19.603] INFO: 134 hot pixels found in step 6
[11:17:20.602] INFO: Collecting data for 5 seconds...
[11:17:25.618] INFO: Done with hot pixel readout
[11:17:38.334] INFO: PixTest:: pg_setup set to default.












[11:17:38.335] INFO: 118 hot pixels found in step 7
[11:17:39.333] INFO: Collecting data for 5 seconds...
[11:17:44.349] INFO: Done with hot pixel readout
[11:17:57.020] INFO: PixTest:: pg_setup set to default.







[11:17:57.021] INFO: 104 hot pixels found in step 8
[11:17:58.019] INFO: Collecting data for 5 seconds...
[11:18:03.034] INFO: Done with hot pixel readout
[11:18:15.770] INFO: PixTest:: pg_setup set to default.








[11:18:15.772] INFO: 120 hot pixels found in step 9
[11:18:16.769] INFO: Collecting data for 5 seconds...
[11:18:21.785] INFO: Done with hot pixel readout
[11:18:34.525] INFO: PixTest:: pg_setup set to default.










[11:18:34.526] INFO: 94 hot pixels found in step 10
[11:18:35.523] INFO: Collecting data for 5 seconds...
[11:18:40.540] INFO: Done with hot pixel readout
[11:18:53.274] INFO: PixTest:: pg_setup set to default.











[11:18:53.275] INFO: 101 hot pixels found in step 11
[11:18:54.273] INFO: Collecting data for 5 seconds...
[11:18:59.290] INFO: Done with hot pixel readout
[11:19:12.030] INFO: PixTest:: pg_setup set to default.









[11:19:12.031] INFO: 93 hot pixels found in step 12
[11:19:13.029] INFO: Collecting data for 5 seconds...
[11:19:18.046] INFO: Done with hot pixel readout
[11:19:30.764] INFO: PixTest:: pg_setup set to default.












[11:19:30.765] INFO: 86 hot pixels found in step 13
[11:19:31.763] INFO: Collecting data for 5 seconds...
[11:19:36.779] INFO: Done with hot pixel readout
[11:19:49.506] INFO: PixTest:: pg_setup set to default.












[11:19:49.507] INFO: 80 hot pixels found in step 14
[11:19:49.549] INFO: 80 hot pixels could not be trimmed and have been masked.
[11:19:49.552] INFO: PixTest::trimHotPixels() done
[11:19:49.553] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C0.dat
[11:19:49.564] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C1.dat
[11:19:49.570] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C2.dat
[11:19:49.576] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C3.dat
[11:19:49.581] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C4.dat
[11:19:49.586] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C5.dat
[11:19:49.591] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C6.dat
[11:19:49.597] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C7.dat
[11:19:49.602] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C8.dat
[11:19:49.607] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C9.dat
[11:19:49.612] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C10.dat
[11:19:49.618] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C11.dat
[11:19:49.623] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C12.dat
[11:19:49.628] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C13.dat
[11:19:49.633] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C14.dat
[11:19:49.639] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C15.dat
[11:19:49.644] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//defaultMaskFile.dat
[11:19:49.660] INFO: enter test to run
[11:20:08.898] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[11:20:08.898] INFO: running: highrate
[11:20:08.903] INFO: ----------------------------------------------------------------------
[11:20:08.903] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[11:20:08.903] INFO: ----------------------------------------------------------------------
[11:20:08.903] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[11:20:08.903] INFO: edge/corner pixel THR is adjusted
[11:20:08.903] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:20:09.861] INFO: Collecting data for 1 seconds...
[11:20:10.865] INFO: Done with hot pixel readout
[11:20:15.382] INFO: PixTest:: pg_setup set to default.
[11:20:15.383] INFO: 0 hot pixels found in step 0
[11:20:15.388] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:20:15.456] INFO: PixTest::trimHotPixels() done
[11:20:15.456] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C0.dat
[11:20:15.468] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C1.dat
[11:20:15.477] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C2.dat
[11:20:15.482] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C3.dat
[11:20:15.488] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C4.dat
[11:20:15.493] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C5.dat
[11:20:15.498] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C6.dat
[11:20:15.503] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C7.dat
[11:20:15.529] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C8.dat
[11:20:15.541] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C9.dat
[11:20:15.549] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C10.dat
[11:20:15.554] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C11.dat
[11:20:15.560] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C12.dat
[11:20:15.565] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C13.dat
[11:20:15.570] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C14.dat
[11:20:15.576] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//trimParameters35_C15.dat
[11:20:15.581] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-J-NW_FPIXTest-17C-FNAL-160425-1325_2016-04-25_13h25m_1461608735/000_FPIXTest_p17//defaultMaskFile.dat
[11:20:15.591] INFO: enter test to run
[11:20:54.458] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:20:54.458] INFO: running: xray
[11:20:54.459] INFO: ----------------------------------------------------------------------
[11:20:54.459] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:20:54.459] INFO: ----------------------------------------------------------------------
[11:20:55.422] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:21:05.866] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[11:21:35.285] INFO: Resuming triggers.
[11:21:45.737] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[11:22:15.195] INFO: Resuming triggers.
[11:22:25.639] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[11:22:55.172] INFO: Resuming triggers.
[11:23:05.623] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[11:23:35.138] INFO: Resuming triggers.
[11:23:45.586] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[11:24:15.067] INFO: Resuming triggers.
[11:24:25.519] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[11:24:55.076] INFO: Resuming triggers.
[11:25:05.526] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[11:25:35.049] INFO: Resuming triggers.
[11:25:45.498] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[11:26:09.262] INFO: Resuming triggers.
[11:26:19.714] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[11:26:49.216] INFO: Resuming triggers.
[11:26:55.496] INFO: data taking finished, elapsed time: 100 seconds.
[11:27:13.564] INFO: PixTest:: pg_setup set to default.
[11:27:13.567] INFO: PixTestXray::doPhRun() done
[11:27:13.706] INFO: enter test to run
[11:27:56.086] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[11:27:56.086] INFO: running: xray
[11:27:56.088] INFO: ----------------------------------------------------------------------
[11:27:56.088] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:27:56.088] INFO: ----------------------------------------------------------------------
[11:27:57.059] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:28:02.832] INFO: run duration 5 seconds, buffer almost full (81%), pausing triggers.
[11:28:33.281] INFO: Resuming triggers.
[11:28:39.056] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[11:29:08.926] INFO: Resuming triggers.
[11:29:14.697] INFO: run duration 17 seconds, buffer almost full (81%), pausing triggers.
[11:29:45.067] INFO: Resuming triggers.
[11:29:50.842] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[11:30:19.533] INFO: Resuming triggers.
[11:30:25.305] INFO: run duration 28 seconds, buffer almost full (81%), pausing triggers.
[11:30:57.208] INFO: Resuming triggers.
[11:31:02.980] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[11:31:31.477] INFO: Resuming triggers.
[11:31:37.250] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[11:32:07.231] INFO: Resuming triggers.
[11:32:13.006] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[11:32:43.219] INFO: Resuming triggers.
[11:32:48.994] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[11:33:19.132] INFO: Resuming triggers.
[11:33:24.906] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[11:33:55.088] INFO: Resuming triggers.
[11:34:00.863] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[11:34:30.000] INFO: Resuming triggers.
[11:34:36.773] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[11:35:06.870] INFO: Resuming triggers.
[11:35:12.646] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[11:35:42.787] INFO: Resuming triggers.
[11:35:48.562] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[11:36:17.115] INFO: Resuming triggers.
[11:36:22.889] INFO: run duration 86 seconds, buffer almost full (81%), pausing triggers.
[11:36:50.602] INFO: Resuming triggers.
[11:36:56.376] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[11:37:26.447] INFO: Resuming triggers.
[11:37:32.221] INFO: run duration 97 seconds, buffer almost full (81%), pausing triggers.
[11:38:02.346] INFO: Resuming triggers.
[11:38:04.511] INFO: data taking finished, elapsed time: 100 seconds.
[11:38:16.071] INFO: PixTest:: pg_setup set to default.
[11:38:16.075] INFO: PixTestXray::doPhRun() done
[11:38:16.225] INFO: enter test to run
[11:41:22.272] INFO: test: HighRate no parameter change
[11:41:22.273] INFO: running: highrate
[11:41:22.291] INFO: ----------------------------------------------------------------------
[11:41:22.314] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[11:41:22.314] INFO: ----------------------------------------------------------------------
[11:41:22.492] INFO: Expecting 768 events.
[11:41:23.633] INFO: 768 events read in total (419ms).
[11:41:23.633] INFO: Test took 1296ms.
[11:41:24.436] INFO: Expecting 41600 events.
[11:41:27.619] INFO: 41600 events read in total (2656ms).
[11:41:27.621] INFO: Test took 3965ms.
[11:41:27.662] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:28.376] INFO: Expecting 41600 events.
[11:41:31.654] INFO: 41600 events read in total (2751ms).
[11:41:31.656] INFO: Test took 3974ms.
[11:41:31.698] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:32.409] INFO: Expecting 41600 events.
[11:41:35.723] INFO: 41600 events read in total (2788ms).
[11:41:35.724] INFO: Test took 4005ms.
[11:41:35.766] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:36.476] INFO: Expecting 41600 events.
[11:41:39.822] INFO: 41600 events read in total (2819ms).
[11:41:39.823] INFO: Test took 4035ms.
[11:41:39.865] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:40.567] INFO: Expecting 41600 events.
[11:41:43.906] INFO: 41600 events read in total (2812ms).
[11:41:43.907] INFO: Test took 4020ms.
[11:41:43.950] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:44.657] INFO: Expecting 41600 events.
[11:41:47.996] INFO: 41600 events read in total (2812ms).
[11:41:47.997] INFO: Test took 4028ms.
[11:41:48.039] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:48.745] INFO: Expecting 41600 events.
[11:41:52.080] INFO: 41600 events read in total (2808ms).
[11:41:52.081] INFO: Test took 4021ms.
[11:41:52.124] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:52.832] INFO: Expecting 41600 events.
[11:41:56.171] INFO: 41600 events read in total (2812ms).
[11:41:56.172] INFO: Test took 4028ms.
[11:41:56.214] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:56.923] INFO: Expecting 41600 events.
[11:42:00.249] INFO: 41600 events read in total (2799ms).
[11:42:00.250] INFO: Test took 4014ms.
[11:42:00.291] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:00.998] INFO: Expecting 41600 events.
[11:42:04.342] INFO: 41600 events read in total (2817ms).
[11:42:04.343] INFO: Test took 4032ms.
[11:42:04.384] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:05.091] INFO: Expecting 41600 events.
[11:42:08.426] INFO: 41600 events read in total (2808ms).
[11:42:08.427] INFO: Test took 4021ms.
[11:42:08.469] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:09.179] INFO: Expecting 41600 events.
[11:42:12.514] INFO: 41600 events read in total (2808ms).
[11:42:12.515] INFO: Test took 4025ms.
[11:42:12.558] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:13.265] INFO: Expecting 41600 events.
[11:42:16.594] INFO: 41600 events read in total (2802ms).
[11:42:16.595] INFO: Test took 4016ms.
[11:42:16.637] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:17.344] INFO: Expecting 41600 events.
[11:42:20.687] INFO: 41600 events read in total (2816ms).
[11:42:20.688] INFO: Test took 4030ms.
[11:42:20.731] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:21.438] INFO: Expecting 41600 events.
[11:42:24.789] INFO: 41600 events read in total (2824ms).
[11:42:24.790] INFO: Test took 4038ms.
[11:42:24.831] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:25.539] INFO: Expecting 41600 events.
[11:42:28.884] INFO: 41600 events read in total (2818ms).
[11:42:28.886] INFO: Test took 4035ms.
[11:42:28.928] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:29.632] INFO: Expecting 41600 events.
[11:42:32.963] INFO: 41600 events read in total (2804ms).
[11:42:32.964] INFO: Test took 4014ms.
[11:42:33.007] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:33.717] INFO: Expecting 41600 events.
[11:42:37.055] INFO: 41600 events read in total (2811ms).
[11:42:37.056] INFO: Test took 4027ms.
[11:42:37.098] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:37.807] INFO: Expecting 41600 events.
[11:42:41.122] INFO: 41600 events read in total (2788ms).
[11:42:41.123] INFO: Test took 4003ms.
[11:42:41.165] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:41.874] INFO: Expecting 41600 events.
[11:42:45.029] INFO: 41600 events read in total (2628ms).
[11:42:45.030] INFO: Test took 3844ms.
[11:42:45.071] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:45.421] INFO: enter test to run
[11:43:21.672] INFO: test: HighRate no parameter change
[11:43:21.672] INFO: running: highrate
[11:43:21.673] INFO: ----------------------------------------------------------------------
[11:43:21.673] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:43:21.673] INFO: ----------------------------------------------------------------------
[11:43:22.287] INFO: Expecting 208000 events.
[11:43:34.624] INFO: 208000 events read in total (11811ms).
[11:43:34.627] INFO: Test took 12944ms.
[11:43:34.813] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:43:35.077] INFO: number of dead pixels (per ROC): 0 0 0 0 0 2 2 2 0 0 1 0 0 0 2 0
[11:43:35.077] INFO: number of red-efficiency pixels: 92 64 115 207 190 224 245 134 91 165 179 143 171 74 28 30
[11:43:35.077] INFO: number of X-ray hits detected: 79181 58275 84241 139680 151717 157131 159758 105607 100136 119470 121780 105775 110658 66749 28714 34617
[11:43:35.077] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:43:35.077] INFO: number of Vcal hits detected: 207905 207936 207880 207787 207802 207667 207630 207767 207907 207831 207767 207855 207826 207926 207873 207970
[11:43:35.077] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 99.9 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
[11:43:35.077] INFO: Vcal hit overall efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.8 99.8 99.9 100.0 99.9 99.9 99.9 99.9 100.0 99.9 100.0
[11:43:35.077] INFO: X-ray hit rate [MHz/cm2]: 23.2 17.1 24.7 40.9 44.5 46.1 46.8 31.0 29.4 35.0 35.7 31.0 32.4 19.6 8.4 10.1
[11:43:35.077] INFO: PixTestHighRate::doXPixelAlive() done
[11:43:35.128] INFO: PixTest:: pg_setup set to default.
[11:43:35.143] INFO: enter test to run
[11:43:52.743] INFO: test: HighRate no parameter change
[11:43:52.744] INFO: running: highrate
[11:43:52.745] INFO: ----------------------------------------------------------------------
[11:43:52.745] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:43:52.745] INFO: ----------------------------------------------------------------------
[11:43:53.363] INFO: Expecting 208000 events.
[11:44:07.954] INFO: 208000 events read in total (14064ms).
[11:44:07.960] INFO: Test took 15206ms.
[11:44:08.336] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:44:08.660] INFO: number of dead pixels (per ROC): 0 0 0 0 0 2 2 2 0 0 1 0 0 0 2 0
[11:44:08.660] INFO: number of red-efficiency pixels: 239 145 411 834 709 794 897 395 305 558 607 466 520 225 91 97
[11:44:08.660] INFO: number of X-ray hits detected: 158253 116202 169282 279753 302496 315094 321224 212308 202252 239908 247180 213004 222611 134173 58004 70503
[11:44:08.660] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:44:08.660] INFO: number of Vcal hits detected: 207750 207845 207533 207041 207181 206990 206809 207466 207672 207388 207282 207489 207437 207760 207808 207900
[11:44:08.660] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.6 99.6 99.6 99.5 99.8 99.9 99.7 99.7 99.8 99.8 99.9 100.0 100.0
[11:44:08.660] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.5 99.6 99.5 99.4 99.7 99.8 99.7 99.7 99.8 99.7 99.9 99.9 100.0
[11:44:08.660] INFO: X-ray hit rate [MHz/cm2]: 46.4 34.1 49.6 82.0 88.7 92.4 94.2 62.2 59.3 70.3 72.5 62.4 65.2 39.3 17.0 20.7
[11:44:08.660] INFO: PixTestHighRate::doXPixelAlive() done
[11:44:08.712] INFO: PixTest:: pg_setup set to default.
[11:44:08.724] INFO: enter test to run
[11:44:18.831] INFO: test: HighRate no parameter change
[11:44:18.831] INFO: running: highrate
[11:44:18.832] INFO: ----------------------------------------------------------------------
[11:44:18.832] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:44:18.832] INFO: ----------------------------------------------------------------------
[11:44:19.442] INFO: Expecting 208000 events.
[11:44:36.447] INFO: 208000 events read in total (16478ms).
[11:44:36.456] INFO: Test took 17617ms.
[11:44:37.029] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:44:37.412] INFO: number of dead pixels (per ROC): 0 0 0 0 0 2 2 2 0 0 1 0 0 0 2 0
[11:44:37.412] INFO: number of red-efficiency pixels: 453 316 901 1768 1648 1767 2037 820 641 1362 1344 1013 1116 473 134 144
[11:44:37.412] INFO: number of X-ray hits detected: 236828 173474 253681 418065 450189 469283 476324 315467 301845 358595 366252 318362 330218 199754 86862 104530
[11:44:37.412] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:44:37.412] INFO: number of Vcal hits detected: 207489 207653 206637 205383 205616 205306 204710 206839 207252 206184 206196 206756 206590 207441 207758 207847
[11:44:37.412] INFO: Vcal hit fiducial efficiency (%): 99.8 99.8 99.4 98.9 99.0 98.9 98.6 99.5 99.7 99.2 99.2 99.5 99.4 99.8 99.9 99.9
[11:44:37.412] INFO: Vcal hit overall efficiency (%): 99.8 99.8 99.3 98.7 98.9 98.7 98.4 99.4 99.6 99.1 99.1 99.4 99.3 99.7 99.9 99.9
[11:44:37.412] INFO: X-ray hit rate [MHz/cm2]: 69.4 50.8 74.4 122.5 132.0 137.6 139.6 92.5 88.5 105.1 107.4 93.3 96.8 58.5 25.5 30.6
[11:44:37.412] INFO: PixTestHighRate::doXPixelAlive() done
[11:44:37.459] INFO: PixTest:: pg_setup set to default.
[11:44:37.475] INFO: enter test to run
[11:45:02.631] INFO: test: exit no parameter change
[11:45:03.084] QUIET: Connection to board 33 closed.
[11:45:03.095] INFO: pXar: this is the end, my friend