[14:18:54.596] INFO: *** Welcome to pxar ***
[14:18:54.596] INFO: *** Today: 2016/05/18
[14:18:54.618] INFO: *** Version: v1.9.0-796-gef167-dirty
[14:18:54.618] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//dacParameters35_C15.dat
[14:18:54.619] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:18:54.619] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//defaultMaskFile.dat
[14:18:54.619] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C15.dat
[14:18:54.688] INFO: clk: 4
[14:18:54.688] INFO: ctr: 4
[14:18:54.688] INFO: sda: 19
[14:18:54.688] INFO: tin: 9
[14:18:54.688] INFO: level: 15
[14:18:54.688] INFO: triggerdelay: 0
[14:18:54.688] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[14:18:54.688] INFO: Log level: INFO
[14:18:54.705] QUIET: Connection to board DTB_WREK4U opened.
[14:18:54.708] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 32
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREK4U
MAC address: 40D855118020
Hostname: pixelDTB032
Comment:
------------------------------------------------------
[14:18:54.711] INFO: RPC call hashes of host and DTB match: 398089610
[14:18:56.242] INFO: DUT info:
[14:18:56.242] INFO: The DUT currently contains the following objects:
[14:18:56.242] INFO: 2 TBM Cores tbm08c (2 ON)
[14:18:56.242] INFO: TBM Core alpha (0): 7 registers set
[14:18:56.242] INFO: TBM Core beta (1): 7 registers set
[14:18:56.242] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[14:18:56.242] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[14:18:56.243] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[14:18:56.243] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[14:18:56.243] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[14:18:56.243] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[14:18:56.243] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[14:18:56.243] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[14:18:56.243] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[14:18:56.243] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[14:18:56.243] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[14:18:56.243] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[14:18:56.243] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[14:18:56.243] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[14:18:56.243] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[14:18:56.243] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[14:18:56.243] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[14:18:56.646] INFO: enter 'restricted' command line mode
[14:18:56.647] INFO: enter test to run
[14:19:09.806] INFO: test: timing no parameter change
[14:19:09.806] INFO: running: timing
[14:19:09.815] INFO: ######################################################################
[14:19:09.815] INFO: PixTestTiming::doTest()
[14:19:09.815] INFO: ######################################################################
[14:19:09.815] INFO: ----------------------------------------------------------------------
[14:19:09.815] INFO: PixTestTiming::TBMPhaseScan()
[14:19:09.815] INFO: ----------------------------------------------------------------------
[14:25:35.840] INFO: TBM Phase Settings: 16
[14:25:35.840] INFO: 400MHz Phase: 4
[14:25:35.840] INFO: 160MHz Phase: 0
[14:25:35.840] INFO: Functional Phase Area: 2
[14:25:35.843] INFO: Test took 386028 ms.
[14:25:35.843] INFO: PixTestTiming::TBMPhaseScan() done.
[14:25:35.843] INFO: ----------------------------------------------------------------------
[14:25:35.843] INFO: PixTestTiming::ROCDelayScan()
[14:25:35.843] INFO: ----------------------------------------------------------------------
[14:27:44.623] INFO: ROC Delay Settings: 228
[14:27:44.623] INFO: ROC Header-Trailer/Token Delay: 11
[14:27:44.623] INFO: ROC Port 0 Delay: 4
[14:27:44.623] INFO: ROC Port 1 Delay: 4
[14:27:44.623] INFO: Functional ROC Area: 5
[14:27:44.627] INFO: Test took 128784 ms.
[14:27:44.627] INFO: PixTestTiming::ROCDelayScan() done.
[14:27:44.627] INFO: ----------------------------------------------------------------------
[14:27:44.627] INFO: PixTestTiming::TimingTest()
[14:27:44.627] INFO: ----------------------------------------------------------------------
[14:28:00.677] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:28:15.617] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:28:30.557] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:28:45.447] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:29:00.405] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:29:15.231] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:29:30.186] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:29:45.079] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:29:59.944] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:30:14.908] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:30:15.291] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:30:15.308] INFO: ----------------------------------------------------------------------
[14:30:15.308] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[14:30:15.308] INFO: ----------------------------------------------------------------------
[14:30:15.308] INFO: ----------------------------------------------------------------------
[14:30:15.308] INFO: Read back bit status: 1
[14:30:15.308] INFO: ----------------------------------------------------------------------
[14:30:15.308] INFO: ----------------------------------------------------------------------
[14:30:15.308] INFO: Timings are good!
[14:30:15.308] INFO: ----------------------------------------------------------------------
[14:30:15.308] INFO: Test took 150681 ms.
[14:30:15.308] INFO: PixTestTiming::TimingTest() done.
[14:30:15.308] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//tbmParameters_C0a.dat
[14:30:15.308] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:30:15.308] INFO: PixTestTiming::doTest took 665498 ms.
[14:30:15.308] INFO: PixTestTiming::doTest() done
[14:30:15.308] INFO: Write out TBMPhaseScan_0_V0
[14:30:15.334] INFO: Write out TBMPhaseScan_1_V0
[14:30:15.334] INFO: Write out CombinedTBMPhaseScan_V0
[14:30:15.335] INFO: Write out ROCDelayScan3_V0
[14:30:15.335] INFO: enter test to run
[14:30:22.801] INFO: test: PixelAlive no parameter change
[14:30:22.801] INFO: running: pixelalive
[14:30:22.805] INFO: ----------------------------------------------------------------------
[14:30:22.805] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[14:30:22.806] INFO: ----------------------------------------------------------------------
[14:30:23.129] INFO: Expecting 41600 events.
[14:30:27.436] INFO: 41600 events read in total (3591ms).
[14:30:27.437] INFO: Test took 4629ms.
[14:30:27.443] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:30:27.842] INFO: PixTestAlive::aliveTest() done
[14:30:27.843] INFO: number of dead pixels (per ROC): 138 58 56 56 55 57 57 135 135 94 56 58 56 60 58 135
[14:30:27.846] INFO: enter test to run
[14:30:55.409] INFO: test: timing no parameter change
[14:30:55.409] INFO: running: timing
[14:30:55.413] INFO: ######################################################################
[14:30:55.413] INFO: PixTestTiming::doTest()
[14:30:55.413] INFO: ######################################################################
[14:30:55.413] INFO: ----------------------------------------------------------------------
[14:30:55.413] INFO: PixTestTiming::TBMPhaseScan()
[14:30:55.413] INFO: ----------------------------------------------------------------------
[14:35:13.068] INFO: TBM Phase Settings: 252
[14:35:13.068] INFO: 400MHz Phase: 7
[14:35:13.068] INFO: 160MHz Phase: 7
[14:35:13.068] INFO: Functional Phase Area: 3
[14:35:13.071] INFO: Test took 257658 ms.
[14:35:13.071] INFO: PixTestTiming::TBMPhaseScan() done.
[14:35:13.071] INFO: ----------------------------------------------------------------------
[14:35:13.071] INFO: PixTestTiming::ROCDelayScan()
[14:35:13.071] INFO: ----------------------------------------------------------------------
[14:37:21.842] INFO: ROC Delay Settings: 228
[14:37:21.842] INFO: ROC Header-Trailer/Token Delay: 11
[14:37:21.842] INFO: ROC Port 0 Delay: 4
[14:37:21.842] INFO: ROC Port 1 Delay: 4
[14:37:21.842] INFO: Functional ROC Area: 5
[14:37:21.845] INFO: Test took 128774 ms.
[14:37:21.845] INFO: PixTestTiming::ROCDelayScan() done.
[14:37:21.845] INFO: ----------------------------------------------------------------------
[14:37:21.845] INFO: PixTestTiming::TimingTest()
[14:37:21.845] INFO: ----------------------------------------------------------------------
[14:37:37.936] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:37:52.924] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:38:07.888] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:38:22.677] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:38:37.629] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:38:52.606] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:39:07.462] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:39:22.398] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:39:37.275] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:39:52.193] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:39:52.582] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:39:52.596] INFO: ----------------------------------------------------------------------
[14:39:52.596] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[14:39:52.597] INFO: ----------------------------------------------------------------------
[14:39:52.597] INFO: ----------------------------------------------------------------------
[14:39:52.597] INFO: Read back bit status: 1
[14:39:52.597] INFO: ----------------------------------------------------------------------
[14:39:52.597] INFO: ----------------------------------------------------------------------
[14:39:52.597] INFO: Timings are good!
[14:39:52.597] INFO: ----------------------------------------------------------------------
[14:39:52.597] INFO: Test took 150752 ms.
[14:39:52.597] INFO: PixTestTiming::TimingTest() done.
[14:39:52.597] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//tbmParameters_C0a.dat
[14:39:52.597] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:39:52.597] INFO: PixTestTiming::doTest took 537188 ms.
[14:39:52.597] INFO: PixTestTiming::doTest() done
[14:39:52.597] INFO: Write out TBMPhaseScan_0_V1
[14:39:52.597] INFO: Write out TBMPhaseScan_1_V1
[14:39:52.597] INFO: Write out CombinedTBMPhaseScan_V1
[14:39:52.597] INFO: Write out ROCDelayScan3_V1
[14:39:52.598] INFO: enter test to run
[14:47:54.041] INFO: test: PixelAlive no parameter change
[14:47:54.041] INFO: running: pixelalive
[14:47:54.045] INFO: ----------------------------------------------------------------------
[14:47:54.045] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[14:47:54.045] INFO: ----------------------------------------------------------------------
[14:47:54.363] INFO: Expecting 41600 events.
[14:47:58.651] INFO: 41600 events read in total (3573ms).
[14:47:58.652] INFO: Test took 4604ms.
[14:47:58.658] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:47:59.060] INFO: PixTestAlive::aliveTest() done
[14:47:59.060] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[14:47:59.063] INFO: enter test to run
[14:52:56.735] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[14:52:56.735] INFO: running: highrate
[14:52:56.736] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[14:52:56.890] INFO: ----------------------------------------------------------------------
[14:52:56.891] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[14:52:56.891] INFO: ----------------------------------------------------------------------
[14:52:56.891] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[14:52:56.891] INFO: edge/corner pixel THR is adjusted
[14:52:56.891] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:52:57.848] INFO: Collecting data for 5 seconds...
[14:53:02.863] INFO: Done with hot pixel readout
[14:53:14.592] INFO: PixTest:: pg_setup set to default.

[14:53:14.593] INFO: 4 hot pixels found in step 0
[14:53:15.586] INFO: Collecting data for 5 seconds...
[14:53:20.602] INFO: Done with hot pixel readout
[14:53:32.061] INFO: PixTest:: pg_setup set to default.



[14:53:32.062] INFO: 4 hot pixels found in step 1
[14:53:33.057] INFO: Collecting data for 5 seconds...
[14:53:38.074] INFO: Done with hot pixel readout
[14:53:49.880] INFO: PixTest:: pg_setup set to default.

[14:53:49.881] INFO: 2 hot pixels found in step 2
[14:53:50.877] INFO: Collecting data for 5 seconds...
[14:53:55.893] INFO: Done with hot pixel readout
[14:54:07.278] INFO: PixTest:: pg_setup set to default.

[14:54:07.279] INFO: 4 hot pixels found in step 3
[14:54:08.274] INFO: Collecting data for 5 seconds...
[14:54:13.291] INFO: Done with hot pixel readout
[14:54:24.787] INFO: PixTest:: pg_setup set to default.


[14:54:24.788] INFO: 2 hot pixels found in step 4
[14:54:24.825] INFO: 2 hot pixels could not be trimmed and have been masked.
[14:54:24.829] INFO: PixTest::trimHotPixels() done
[14:54:24.829] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C0.dat
[14:54:24.835] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C1.dat
[14:54:24.842] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C2.dat
[14:54:24.847] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C3.dat
[14:54:24.852] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C4.dat
[14:54:24.859] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C5.dat
[14:54:24.864] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C6.dat
[14:54:24.870] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C7.dat
[14:54:24.875] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C8.dat
[14:54:24.880] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C9.dat
[14:54:24.886] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C10.dat
[14:54:24.891] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C11.dat
[14:54:24.896] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C12.dat
[14:54:24.901] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C13.dat
[14:54:24.907] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C14.dat
[14:54:24.912] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C15.dat
[14:54:24.917] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//defaultMaskFile.dat
[14:54:24.928] INFO: enter test to run
[14:55:26.710] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[14:55:26.710] INFO: running: highrate
[14:55:26.715] INFO: ----------------------------------------------------------------------
[14:55:26.715] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[14:55:26.715] INFO: ----------------------------------------------------------------------
[14:55:26.715] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[14:55:26.715] INFO: edge/corner pixel THR is adjusted
[14:55:26.715] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:55:27.672] INFO: Collecting data for 1 seconds...
[14:55:28.676] INFO: Done with hot pixel readout
[14:55:32.736] INFO: PixTest:: pg_setup set to default.
[14:55:32.737] INFO: 0 hot pixels found in step 0
[14:55:32.742] INFO: 0 hot pixels could not be trimmed and have been masked.
[14:55:32.824] INFO: PixTest::trimHotPixels() done
[14:55:32.824] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C0.dat
[14:55:32.836] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C1.dat
[14:55:32.842] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C2.dat
[14:55:32.847] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C3.dat
[14:55:32.853] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C4.dat
[14:55:32.858] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C5.dat
[14:55:32.863] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C6.dat
[14:55:32.869] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C7.dat
[14:55:32.874] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C8.dat
[14:55:32.880] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C9.dat
[14:55:32.885] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C10.dat
[14:55:32.891] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C11.dat
[14:55:32.896] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C12.dat
[14:55:32.901] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C13.dat
[14:55:32.907] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C14.dat
[14:55:32.912] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//trimParameters35_C15.dat
[14:55:32.917] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-B-2-03_FPIXTest-17C-FNAL-160516-0905_2016-05-16_09h05m_1463407515/000_FPIXTest_p17//defaultMaskFile.dat
[14:55:32.928] INFO: enter test to run
[14:55:46.662] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[14:55:46.662] INFO: running: xray
[14:55:46.663] INFO: ----------------------------------------------------------------------
[14:55:46.663] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:55:46.663] INFO: ----------------------------------------------------------------------
[14:55:47.626] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:55:58.754] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[14:56:27.152] INFO: Resuming triggers.
[14:56:38.286] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[14:57:07.060] INFO: Resuming triggers.
[14:57:18.190] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[14:57:46.951] INFO: Resuming triggers.
[14:57:58.082] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[14:58:26.925] INFO: Resuming triggers.
[14:58:38.059] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[14:59:07.048] INFO: Resuming triggers.
[14:59:18.180] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[14:59:46.834] INFO: Resuming triggers.
[14:59:57.969] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[15:00:26.496] INFO: Resuming triggers.
[15:00:37.630] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[15:01:06.396] INFO: Resuming triggers.
[15:01:17.530] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[15:01:45.895] INFO: Resuming triggers.
[15:01:46.038] INFO: data taking finished, elapsed time: 100 seconds.
[15:01:46.935] INFO: PixTest:: pg_setup set to default.
[15:01:46.938] INFO: PixTestXray::doPhRun() done
[15:01:47.078] INFO: enter test to run
[15:02:19.267] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[15:02:19.267] INFO: running: xray
[15:02:19.268] INFO: ----------------------------------------------------------------------
[15:02:19.268] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:02:19.268] INFO: ----------------------------------------------------------------------
[15:02:20.241] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:02:26.646] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[15:02:56.223] INFO: Resuming triggers.
[15:03:02.633] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[15:03:32.175] INFO: Resuming triggers.
[15:03:38.586] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[15:04:08.329] INFO: Resuming triggers.
[15:04:14.739] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[15:04:44.235] INFO: Resuming triggers.
[15:04:50.648] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[15:05:19.692] INFO: Resuming triggers.
[15:05:26.099] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[15:05:55.763] INFO: Resuming triggers.
[15:06:02.170] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[15:06:31.951] INFO: Resuming triggers.
[15:06:38.357] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[15:07:07.949] INFO: Resuming triggers.
[15:07:14.354] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[15:07:44.090] INFO: Resuming triggers.
[15:07:50.495] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[15:08:20.395] INFO: Resuming triggers.
[15:08:26.802] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[15:08:56.826] INFO: Resuming triggers.
[15:09:03.230] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[15:09:32.553] INFO: Resuming triggers.
[15:09:38.954] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[15:10:08.500] INFO: Resuming triggers.
[15:10:14.906] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[15:10:44.855] INFO: Resuming triggers.
[15:10:51.258] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[15:11:21.238] INFO: Resuming triggers.
[15:11:25.469] INFO: data taking finished, elapsed time: 100 seconds.
[15:11:45.508] INFO: PixTest:: pg_setup set to default.
[15:11:45.512] INFO: PixTestXray::doPhRun() done
[15:11:45.683] INFO: enter test to run
[15:13:20.366] INFO: test: HighRate no parameter change
[15:13:20.366] INFO: running: highrate
[15:13:20.383] INFO: ----------------------------------------------------------------------
[15:13:20.383] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[15:13:20.383] INFO: ----------------------------------------------------------------------
[15:13:20.539] INFO: Expecting 768 events.
[15:13:21.673] INFO: 768 events read in total (419ms).
[15:13:21.673] INFO: Test took 1268ms.
[15:13:22.477] INFO: Expecting 41600 events.
[15:13:25.608] INFO: 41600 events read in total (2605ms).
[15:13:25.609] INFO: Test took 3929ms.
[15:13:25.645] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:13:26.367] INFO: Expecting 41600 events.
[15:13:29.595] INFO: 41600 events read in total (2701ms).
[15:13:29.597] INFO: Test took 3933ms.
[15:13:29.639] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:13:30.353] INFO: Expecting 41600 events.
[15:13:33.616] INFO: 41600 events read in total (2736ms).
[15:13:33.617] INFO: Test took 3957ms.
[15:13:33.654] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:13:34.374] INFO: Expecting 41600 events.
[15:13:37.645] INFO: 41600 events read in total (2744ms).
[15:13:37.646] INFO: Test took 3974ms.
[15:13:37.683] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:13:38.399] INFO: Expecting 41600 events.
[15:13:41.680] INFO: 41600 events read in total (2754ms).
[15:13:41.681] INFO: Test took 3978ms.
[15:13:41.718] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:13:42.437] INFO: Expecting 41600 events.
[15:13:45.711] INFO: 41600 events read in total (2747ms).
[15:13:45.712] INFO: Test took 3974ms.
[15:13:45.750] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:13:46.467] INFO: Expecting 41600 events.
[15:13:49.746] INFO: 41600 events read in total (2753ms).
[15:13:49.747] INFO: Test took 3977ms.
[15:13:49.783] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:13:50.503] INFO: Expecting 41600 events.
[15:13:53.777] INFO: 41600 events read in total (2747ms).
[15:13:53.778] INFO: Test took 3975ms.
[15:13:53.815] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:13:54.536] INFO: Expecting 41600 events.
[15:13:57.808] INFO: 41600 events read in total (2745ms).
[15:13:57.809] INFO: Test took 3975ms.
[15:13:57.846] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:13:58.565] INFO: Expecting 41600 events.
[15:14:01.839] INFO: 41600 events read in total (2747ms).
[15:14:01.840] INFO: Test took 3976ms.
[15:14:01.876] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:14:02.595] INFO: Expecting 41600 events.
[15:14:05.870] INFO: 41600 events read in total (2748ms).
[15:14:05.871] INFO: Test took 3974ms.
[15:14:05.908] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:14:06.624] INFO: Expecting 41600 events.
[15:14:09.891] INFO: 41600 events read in total (2740ms).
[15:14:09.892] INFO: Test took 3964ms.
[15:14:09.929] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:14:10.648] INFO: Expecting 41600 events.
[15:14:13.910] INFO: 41600 events read in total (2735ms).
[15:14:13.911] INFO: Test took 3962ms.
[15:14:13.949] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:14:14.666] INFO: Expecting 41600 events.
[15:14:17.933] INFO: 41600 events read in total (2741ms).
[15:14:17.935] INFO: Test took 3967ms.
[15:14:17.971] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:14:18.692] INFO: Expecting 41600 events.
[15:14:21.961] INFO: 41600 events read in total (2742ms).
[15:14:21.962] INFO: Test took 3972ms.
[15:14:21.999] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:14:22.715] INFO: Expecting 41600 events.
[15:14:25.982] INFO: 41600 events read in total (2740ms).
[15:14:25.983] INFO: Test took 3966ms.
[15:14:26.021] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:14:26.739] INFO: Expecting 41600 events.
[15:14:29.001] INFO: 41600 events read in total (2735ms).
[15:14:29.002] INFO: Test took 3963ms.
[15:14:30.039] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:14:30.756] INFO: Expecting 41600 events.
[15:14:34.024] INFO: 41600 events read in total (2742ms).
[15:14:34.025] INFO: Test took 3967ms.
[15:14:34.063] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:14:34.783] INFO: Expecting 41600 events.
[15:14:38.027] INFO: 41600 events read in total (2717ms).
[15:14:38.028] INFO: Test took 3946ms.
[15:14:38.065] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:14:38.783] INFO: Expecting 41600 events.
[15:14:41.915] INFO: 41600 events read in total (2606ms).
[15:14:41.916] INFO: Test took 3831ms.
[15:14:41.952] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:14:42.309] INFO: enter test to run
[15:15:01.453] INFO: test: HighRate no parameter change
[15:15:01.453] INFO: running: highrate
[15:15:01.455] INFO: ----------------------------------------------------------------------
[15:15:01.455] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:15:01.455] INFO: ----------------------------------------------------------------------
[15:15:02.071] INFO: Expecting 208000 events.
[15:15:14.148] INFO: 208000 events read in total (11550ms).
[15:15:14.151] INFO: Test took 12688ms.
[15:15:14.315] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:15:14.572] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:15:14.572] INFO: number of red-efficiency pixels: 93 43 96 146 178 180 177 125 111 150 139 116 110 93 20 38
[15:15:14.572] INFO: number of X-ray hits detected: 76257 48033 73035 116202 124146 134651 126785 93913 93257 111465 105557 95275 96190 58439 22173 24805
[15:15:14.572] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:15:14.572] INFO: number of Vcal hits detected: 207905 207956 207904 207845 207817 207817 207816 207872 207886 207849 207860 207883 207888 207904 207980 207961
[15:15:14.572] 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 99.9 100.0 100.0 100.0 100.0
[15:15:14.572] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[15:15:14.572] INFO: X-ray hit rate [MHz/cm2]: 22.4 14.1 21.4 34.1 36.4 39.5 37.2 27.5 27.3 32.7 30.9 27.9 28.2 17.1 6.5 7.3
[15:15:14.572] INFO: PixTestHighRate::doXPixelAlive() done
[15:15:14.617] INFO: PixTest:: pg_setup set to default.
[15:15:14.632] INFO: enter test to run
[15:16:47.925] INFO: test: HighRate no parameter change
[15:16:47.925] INFO: running: highrate
[15:16:47.926] INFO: ----------------------------------------------------------------------
[15:16:47.926] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:16:47.926] INFO: ----------------------------------------------------------------------
[15:16:48.547] INFO: Expecting 208000 events.
[15:17:02.506] INFO: 208000 events read in total (13432ms).
[15:17:02.511] INFO: Test took 14575ms.
[15:17:02.829] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:17:03.144] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:17:03.144] INFO: number of red-efficiency pixels: 279 183 237 541 651 506 633 430 342 460 334 423 342 242 56 57
[15:17:03.144] INFO: number of X-ray hits detected: 153111 96660 146755 233075 249775 269170 253550 189089 187100 223009 211144 192332 192864 117380 44917 50201
[15:17:03.144] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:17:03.144] INFO: number of Vcal hits detected: 207690 207806 207750 207414 207275 207434 207293 207520 207634 207500 207643 207544 207634 207740 207944 207941
[15:17:03.144] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.7 99.7 99.8 99.7 99.8 99.8 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[15:17:03.144] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.7 99.7 99.7 99.7 99.8 99.8 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[15:17:03.144] INFO: X-ray hit rate [MHz/cm2]: 44.9 28.3 43.0 68.3 73.2 78.9 74.3 55.4 54.8 65.4 61.9 56.4 56.5 34.4 13.2 14.7
[15:17:03.144] INFO: PixTestHighRate::doXPixelAlive() done
[15:17:03.196] INFO: PixTest:: pg_setup set to default.
[15:17:03.216] INFO: enter test to run
[15:17:47.796] INFO: test: HighRate no parameter change
[15:17:47.796] INFO: running: highrate
[15:17:47.798] INFO: ----------------------------------------------------------------------
[15:17:47.798] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:17:47.798] INFO: ----------------------------------------------------------------------
[15:17:48.420] INFO: Expecting 208000 events.
[15:18:04.754] INFO: 208000 events read in total (15807ms).
[15:18:04.762] INFO: Test took 16956ms.
[15:18:05.249] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:18:05.617] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:18:05.617] INFO: number of red-efficiency pixels: 640 309 552 1296 1434 1213 1473 937 794 1135 814 909 836 592 103 105
[15:18:05.617] INFO: number of X-ray hits detected: 231480 145616 223259 352217 376749 406297 382580 285044 284611 338683 318849 288986 291957 177311 67598 75369
[15:18:05.618] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:18:05.618] INFO: number of Vcal hits detected: 207138 207663 207323 206343 206059 206434 206028 206815 207098 206631 207065 206871 207021 207273 207894 207894
[15:18:05.618] INFO: Vcal hit fiducial efficiency (%): 99.7 99.8 99.7 99.3 99.2 99.3 99.1 99.5 99.6 99.4 99.6 99.5 99.6 99.7 100.0 100.0
[15:18:05.618] INFO: Vcal hit overall efficiency (%): 99.6 99.8 99.7 99.2 99.1 99.2 99.1 99.4 99.6 99.3 99.6 99.5 99.5 99.7 99.9 99.9
[15:18:05.618] INFO: X-ray hit rate [MHz/cm2]: 67.8 42.7 65.4 103.2 110.4 119.1 112.1 83.5 83.4 99.3 93.5 84.7 85.6 52.0 19.8 22.1
[15:18:05.618] INFO: PixTestHighRate::doXPixelAlive() done
[15:18:05.665] INFO: PixTest:: pg_setup set to default.
[15:18:05.681] INFO: enter test to run
[15:18:37.852] INFO: test: exit no parameter change
[15:18:38.335] QUIET: Connection to board 32 closed.
[15:18:38.335] INFO: pXar: this is the end, my friend