[12:15:31.235] INFO: *** Welcome to pxar ***
[12:15:31.235] INFO: *** Today: 2016/09/23
[12:15:31.951] INFO: *** Version: v1.9.0-818-g96727
[12:15:31.951] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//dacParameters35_C15.dat
[12:15:32.027] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:15:32.044] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//defaultMaskFile.dat
[12:15:32.062] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C15.dat
[12:15:32.234] INFO: clk: 4
[12:15:32.234] INFO: ctr: 4
[12:15:32.234] INFO: sda: 19
[12:15:32.234] INFO: tin: 9
[12:15:32.234] INFO: level: 15
[12:15:32.234] INFO: triggerdelay: 0
[12:15:32.234] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[12:15:32.234] INFO: Log level: INFO
[12:15:32.255] QUIET: Connection to board DTB_WREKRL opened.
[12:15:32.258] 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:
------------------------------------------------------
[12:15:32.261] INFO: RPC call hashes of host and DTB match: 398089610
[12:15:33.792] INFO: DUT info:
[12:15:33.792] INFO: The DUT currently contains the following objects:
[12:15:33.792] INFO: 2 TBM Cores tbm08c (2 ON)
[12:15:33.792] INFO: TBM Core alpha (0): 7 registers set
[12:15:33.792] INFO: TBM Core beta (1): 7 registers set
[12:15:33.792] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[12:15:33.792] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[12:15:33.792] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[12:15:33.792] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[12:15:33.792] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[12:15:33.792] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[12:15:33.792] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[12:15:33.792] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[12:15:33.792] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[12:15:33.792] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[12:15:33.792] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[12:15:33.792] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[12:15:33.792] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[12:15:33.792] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[12:15:33.792] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[12:15:33.792] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[12:15:33.792] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[12:15:34.215] INFO: enter 'restricted' command line mode
[12:15:34.215] INFO: enter test to run
[12:15:54.866] INFO: test: PixelAlive no parameter change
[12:15:54.866] INFO: running: pixelalive
[12:15:54.905] INFO: ----------------------------------------------------------------------
[12:15:54.905] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[12:15:54.905] INFO: ----------------------------------------------------------------------
[12:15:55.227] INFO: Expecting 41600 events.
[12:15:59.514] INFO: 41600 events read in total (3568ms).
[12:15:59.685] INFO: Test took 4777ms.
[12:15:59.694] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:59.968] INFO: PixTestAlive::aliveTest() done
[12:15:59.968] INFO: number of dead pixels (per ROC): 0 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[12:16:00.223] INFO: enter test to run
[12:16:26.016] INFO: test: timing no parameter change
[12:16:26.016] INFO: running: timing
[12:16:26.036] INFO: ######################################################################
[12:16:26.036] INFO: PixTestTiming::doTest()
[12:16:26.036] INFO: ######################################################################
[12:16:26.036] INFO: ----------------------------------------------------------------------
[12:16:26.036] INFO: PixTestTiming::TBMPhaseScan()
[12:16:26.036] INFO: ----------------------------------------------------------------------
[12:22:24.861] INFO: TBM Phase Settings: 240
[12:22:24.861] INFO: 400MHz Phase: 4
[12:22:24.861] INFO: 160MHz Phase: 7
[12:22:24.861] INFO: Functional Phase Area: 5
[12:22:24.864] INFO: Test took 358828 ms.
[12:22:24.864] INFO: PixTestTiming::TBMPhaseScan() done.
[12:22:24.865] INFO: ----------------------------------------------------------------------
[12:22:24.865] INFO: PixTestTiming::ROCDelayScan()
[12:22:24.865] INFO: ----------------------------------------------------------------------
[12:24:22.427] INFO: ROC Delay Settings: 220
[12:24:22.427] INFO: ROC Header-Trailer/Token Delay: 11
[12:24:22.427] INFO: ROC Port 0 Delay: 4
[12:24:22.427] INFO: ROC Port 1 Delay: 3
[12:24:22.427] INFO: Functional ROC Area: 4
[12:24:22.430] INFO: Test took 117566 ms.
[12:24:22.430] INFO: PixTestTiming::ROCDelayScan() done.
[12:24:22.431] INFO: ----------------------------------------------------------------------
[12:24:22.431] INFO: PixTestTiming::TimingTest()
[12:24:22.431] INFO: ----------------------------------------------------------------------
[12:24:38.833] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:24:54.091] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:25:09.214] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:25:24.428] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:25:39.654] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:25:54.919] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:10.030] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:25.024] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:39.980] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:54.940] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:55.318] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:55.334] INFO: ----------------------------------------------------------------------
[12:26:55.334] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[12:26:55.334] INFO: ----------------------------------------------------------------------
[12:26:55.334] INFO: ----------------------------------------------------------------------
[12:26:55.334] INFO: Read back bit status: 1
[12:26:55.334] INFO: ----------------------------------------------------------------------
[12:26:55.335] INFO: ----------------------------------------------------------------------
[12:26:55.335] INFO: Timings are good!
[12:26:55.335] INFO: ----------------------------------------------------------------------
[12:26:55.335] INFO: Test took 152904 ms.
[12:26:55.335] INFO: PixTestTiming::TimingTest() done.
[12:26:55.335] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//tbmParameters_C0a.dat
[12:26:55.335] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:26:55.335] INFO: PixTestTiming::doTest took 629303 ms.
[12:26:55.335] INFO: PixTestTiming::doTest() done
[12:26:55.335] INFO: Write out TBMPhaseScan_0_V0
[12:26:55.335] INFO: Write out TBMPhaseScan_1_V0
[12:26:55.335] INFO: Write out CombinedTBMPhaseScan_V0
[12:26:55.336] INFO: Write out ROCDelayScan3_V0
[12:26:55.336] INFO: enter test to run
[12:28:45.475] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[12:28:45.475] INFO: running: highrate
[12:28:45.475] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[12:28:45.681] INFO: ----------------------------------------------------------------------
[12:28:45.681] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[12:28:45.681] INFO: ----------------------------------------------------------------------
[12:28:45.681] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[12:28:45.681] INFO: edge/corner pixel THR is adjusted
[12:28:45.681] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:28:46.640] INFO: Collecting data for 5 seconds...
[12:28:51.656] INFO: Done with hot pixel readout
[12:29:03.500] INFO: PixTest:: pg_setup set to default.
[12:29:03.501] INFO: 6 hot pixels found in step 0
[12:29:04.494] INFO: Collecting data for 5 seconds...
[12:29:09.510] INFO: Done with hot pixel readout
[12:29:21.348] INFO: PixTest:: pg_setup set to default.
[12:29:21.348] INFO: 4 hot pixels found in step 1
[12:29:22.343] INFO: Collecting data for 5 seconds...
[12:29:27.359] INFO: Done with hot pixel readout
[12:29:39.168] INFO: PixTest:: pg_setup set to default.
[12:29:39.169] INFO: 8 hot pixels found in step 2
[12:29:40.163] INFO: Collecting data for 5 seconds...
[12:29:45.179] INFO: Done with hot pixel readout
[12:29:57.013] INFO: PixTest:: pg_setup set to default.

[12:29:57.014] INFO: 13 hot pixels found in step 3
[12:29:58.007] INFO: Collecting data for 5 seconds...
[12:30:03.023] INFO: Done with hot pixel readout
[12:30:14.854] INFO: PixTest:: pg_setup set to default.
[12:30:14.855] INFO: 14 hot pixels found in step 4
[12:30:15.848] INFO: Collecting data for 5 seconds...
[12:30:20.863] INFO: Done with hot pixel readout
[12:30:32.722] INFO: PixTest:: pg_setup set to default.
[12:30:32.723] INFO: 9 hot pixels found in step 5
[12:30:33.716] INFO: Collecting data for 5 seconds...
[12:30:38.733] INFO: Done with hot pixel readout
[12:30:50.559] INFO: PixTest:: pg_setup set to default.
[12:30:50.560] INFO: 8 hot pixels found in step 6
[12:30:51.553] INFO: Collecting data for 5 seconds...
[12:30:56.569] INFO: Done with hot pixel readout
[12:31:08.409] INFO: PixTest:: pg_setup set to default.
[12:31:08.410] INFO: 14 hot pixels found in step 7
[12:31:09.403] INFO: Collecting data for 5 seconds...
[12:31:14.420] INFO: Done with hot pixel readout
[12:31:26.244] INFO: PixTest:: pg_setup set to default.

[12:31:26.244] INFO: 11 hot pixels found in step 8
[12:31:27.237] INFO: Collecting data for 5 seconds...
[12:31:32.253] INFO: Done with hot pixel readout
[12:31:44.041] INFO: PixTest:: pg_setup set to default.
[12:31:44.041] INFO: 7 hot pixels found in step 9
[12:31:45.034] INFO: Collecting data for 5 seconds...
[12:31:50.051] INFO: Done with hot pixel readout
[12:32:01.909] INFO: PixTest:: pg_setup set to default.
[12:32:01.910] INFO: 6 hot pixels found in step 10
[12:32:02.903] INFO: Collecting data for 5 seconds...
[12:32:07.920] INFO: Done with hot pixel readout
[12:32:19.726] INFO: PixTest:: pg_setup set to default.
[12:32:19.727] INFO: 11 hot pixels found in step 11
[12:32:20.721] INFO: Collecting data for 5 seconds...
[12:32:25.737] INFO: Done with hot pixel readout
[12:32:37.608] INFO: PixTest:: pg_setup set to default.
[12:32:37.609] INFO: 11 hot pixels found in step 12
[12:32:38.602] INFO: Collecting data for 5 seconds...
[12:32:43.618] INFO: Done with hot pixel readout
[12:32:55.465] INFO: PixTest:: pg_setup set to default.
[12:32:55.466] INFO: 10 hot pixels found in step 13
[12:32:56.459] INFO: Collecting data for 5 seconds...
[12:33:01.476] INFO: Done with hot pixel readout
[12:33:13.307] INFO: PixTest:: pg_setup set to default.
[12:33:13.308] INFO: 4 hot pixels found in step 14
[12:33:13.345] INFO: 4 hot pixels could not be trimmed and have been masked.
[12:33:13.349] INFO: PixTest::trimHotPixels() done
[12:33:13.349] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C0.dat
[12:33:13.365] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C1.dat
[12:33:13.371] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C2.dat
[12:33:13.376] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C3.dat
[12:33:13.381] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C4.dat
[12:33:13.386] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C5.dat
[12:33:13.391] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C6.dat
[12:33:13.397] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C7.dat
[12:33:13.402] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C8.dat
[12:33:13.408] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C9.dat
[12:33:13.413] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C10.dat
[12:33:13.418] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C11.dat
[12:33:13.423] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C12.dat
[12:33:13.429] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C13.dat
[12:33:13.434] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C14.dat
[12:33:13.439] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C15.dat
[12:33:13.444] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//defaultMaskFile.dat
[12:33:13.454] INFO: enter test to run
[12:33:38.905] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[12:33:38.905] INFO: running: highrate
[12:33:38.910] INFO: ----------------------------------------------------------------------
[12:33:38.910] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[12:33:38.910] INFO: ----------------------------------------------------------------------
[12:33:38.910] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[12:33:38.910] INFO: edge/corner pixel THR is adjusted
[12:33:38.910] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:33:39.867] INFO: Collecting data for 1 seconds...
[12:33:40.871] INFO: Done with hot pixel readout
[12:33:44.860] INFO: PixTest:: pg_setup set to default.
[12:33:44.861] INFO: 0 hot pixels found in step 0
[12:33:44.867] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:33:44.953] INFO: PixTest::trimHotPixels() done
[12:33:44.953] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C0.dat
[12:33:44.964] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C1.dat
[12:33:44.971] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C2.dat
[12:33:44.976] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C3.dat
[12:33:44.981] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C4.dat
[12:33:44.987] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C5.dat
[12:33:44.992] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C6.dat
[12:33:44.997] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C7.dat
[12:33:44.003] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C8.dat
[12:33:45.008] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C9.dat
[12:33:45.013] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C10.dat
[12:33:45.019] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C11.dat
[12:33:45.024] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C12.dat
[12:33:45.029] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C13.dat
[12:33:45.034] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C14.dat
[12:33:45.040] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//trimParameters35_C15.dat
[12:33:45.045] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-3-22_FPIXTest-17C-FNAL-160920-1235-150V_2016-09-20_12h37m_1474393026/000_FPIXTest_p17//defaultMaskFile.dat
[12:33:45.062] INFO: enter test to run
[12:34:03.129] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[12:34:03.129] INFO: running: xray
[12:34:03.130] INFO: ----------------------------------------------------------------------
[12:34:03.130] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:34:03.130] INFO: ----------------------------------------------------------------------
[12:34:04.093] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:34:15.599] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[12:34:45.442] INFO: Resuming triggers.
[12:34:56.943] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[12:35:26.702] INFO: Resuming triggers.
[12:35:38.204] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[12:36:07.594] INFO: Resuming triggers.
[12:36:19.099] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[12:36:48.902] INFO: Resuming triggers.
[12:37:00.408] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[12:37:31.076] INFO: Resuming triggers.
[12:37:42.587] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[12:38:12.861] INFO: Resuming triggers.
[12:38:24.372] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[12:38:54.155] INFO: Resuming triggers.
[12:39:05.659] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[12:39:34.906] INFO: Resuming triggers.
[12:39:43.224] INFO: data taking finished, elapsed time: 100 seconds.
[12:40:04.752] INFO: PixTest:: pg_setup set to default.
[12:40:04.755] INFO: PixTestXray::doPhRun() done
[12:40:04.910] INFO: enter test to run
[12:43:22.933] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:43:22.933] INFO: running: xray
[12:43:22.934] INFO: ----------------------------------------------------------------------
[12:43:22.934] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:43:22.934] INFO: ----------------------------------------------------------------------
[12:43:23.899] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:43:30.616] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[12:44:00.656] INFO: Resuming triggers.
[12:44:07.372] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[12:44:37.383] INFO: Resuming triggers.
[12:44:44.099] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[12:45:14.447] INFO: Resuming triggers.
[12:45:21.163] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[12:45:51.347] INFO: Resuming triggers.
[12:45:58.065] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[12:46:28.262] INFO: Resuming triggers.
[12:46:34.979] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[12:47:05.005] INFO: Resuming triggers.
[12:47:12.720] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[12:47:43.768] INFO: Resuming triggers.
[12:47:50.484] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[12:48:20.222] INFO: Resuming triggers.
[12:48:26.940] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[12:48:55.012] INFO: Resuming triggers.
[12:49:01.731] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[12:49:31.244] INFO: Resuming triggers.
[12:49:37.962] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[12:50:08.498] INFO: Resuming triggers.
[12:50:15.218] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[12:50:46.104] INFO: Resuming triggers.
[12:50:52.823] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[12:51:24.186] INFO: Resuming triggers.
[12:51:30.908] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[12:52:02.423] INFO: Resuming triggers.
[12:52:08.705] INFO: data taking finished, elapsed time: 100 seconds.
[12:52:38.052] INFO: PixTest:: pg_setup set to default.
[12:52:38.055] INFO: PixTestXray::doPhRun() done
[12:52:38.226] INFO: enter test to run
[12:53:06.833] INFO: test: HighRate no parameter change
[12:53:06.833] INFO: running: highrate
[12:53:06.854] INFO: ----------------------------------------------------------------------
[12:53:06.854] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:53:06.854] INFO: ----------------------------------------------------------------------
[12:53:07.037] INFO: Expecting 768 events.
[12:53:08.189] INFO: 768 events read in total (436ms).
[12:53:08.190] INFO: Test took 1299ms.
[12:53:08.992] INFO: Expecting 41600 events.
[12:53:12.235] INFO: 41600 events read in total (2716ms).
[12:53:12.236] INFO: Test took 4040ms.
[12:53:12.272] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:12.986] INFO: Expecting 41600 events.
[12:53:16.352] INFO: 41600 events read in total (2839ms).
[12:53:16.353] INFO: Test took 4064ms.
[12:53:16.391] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:17.102] INFO: Expecting 41600 events.
[12:53:20.411] INFO: 41600 events read in total (2782ms).
[12:53:20.412] INFO: Test took 4001ms.
[12:53:20.451] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:21.157] INFO: Expecting 41600 events.
[12:53:24.412] INFO: 41600 events read in total (2728ms).
[12:53:24.413] INFO: Test took 3943ms.
[12:53:24.449] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:25.171] INFO: Expecting 41600 events.
[12:53:28.569] INFO: 41600 events read in total (2871ms).
[12:53:28.570] INFO: Test took 4104ms.
[12:53:28.608] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:29.324] INFO: Expecting 41600 events.
[12:53:32.601] INFO: 41600 events read in total (2750ms).
[12:53:32.602] INFO: Test took 3971ms.
[12:53:32.641] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:33.353] INFO: Expecting 41600 events.
[12:53:36.755] INFO: 41600 events read in total (2875ms).
[12:53:36.785] INFO: Test took 4126ms.
[12:53:36.820] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:37.508] INFO: Expecting 41600 events.
[12:53:40.807] INFO: 41600 events read in total (2772ms).
[12:53:40.808] INFO: Test took 3971ms.
[12:53:40.845] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:41.559] INFO: Expecting 41600 events.
[12:53:44.845] INFO: 41600 events read in total (2759ms).
[12:53:44.846] INFO: Test took 3981ms.
[12:53:44.881] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:45.601] INFO: Expecting 41600 events.
[12:53:48.912] INFO: 41600 events read in total (2784ms).
[12:53:48.913] INFO: Test took 4015ms.
[12:53:48.948] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:49.669] INFO: Expecting 41600 events.
[12:53:52.921] INFO: 41600 events read in total (2726ms).
[12:53:52.922] INFO: Test took 3956ms.
[12:53:52.957] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:53.679] INFO: Expecting 41600 events.
[12:53:56.965] INFO: 41600 events read in total (2759ms).
[12:53:56.966] INFO: Test took 3991ms.
[12:53:56.000] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:57.723] INFO: Expecting 41600 events.
[12:54:00.983] INFO: 41600 events read in total (2734ms).
[12:54:00.984] INFO: Test took 3965ms.
[12:54:01.017] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:54:01.740] INFO: Expecting 41600 events.
[12:54:04.980] INFO: 41600 events read in total (2713ms).
[12:54:04.981] INFO: Test took 3946ms.
[12:54:05.015] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:54:05.738] INFO: Expecting 41600 events.
[12:54:08.938] INFO: 41600 events read in total (2673ms).
[12:54:08.939] INFO: Test took 3907ms.
[12:54:08.974] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:54:09.695] INFO: Expecting 41600 events.
[12:54:12.912] INFO: 41600 events read in total (2690ms).
[12:54:12.913] INFO: Test took 3921ms.
[12:54:12.946] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:54:13.671] INFO: Expecting 41600 events.
[12:54:16.898] INFO: 41600 events read in total (2700ms).
[12:54:16.899] INFO: Test took 3935ms.
[12:54:16.933] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:54:17.658] INFO: Expecting 41600 events.
[12:54:20.916] INFO: 41600 events read in total (2732ms).
[12:54:20.917] INFO: Test took 3967ms.
[12:54:20.951] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:54:21.673] INFO: Expecting 41600 events.
[12:54:24.902] INFO: 41600 events read in total (2702ms).
[12:54:24.903] INFO: Test took 3933ms.
[12:54:24.937] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:54:25.660] INFO: Expecting 41600 events.
[12:54:28.681] INFO: 41600 events read in total (2494ms).
[12:54:28.682] INFO: Test took 3725ms.
[12:54:28.716] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:54:29.077] INFO: enter test to run
[12:54:35.616] INFO: test: HighRate no parameter change
[12:54:35.616] INFO: running: highrate
[12:54:35.617] INFO: ----------------------------------------------------------------------
[12:54:35.617] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:54:35.617] INFO: ----------------------------------------------------------------------
[12:54:36.233] INFO: Expecting 208000 events.
[12:54:47.998] INFO: 208000 events read in total (11238ms).
[12:54:47.001] INFO: Test took 12377ms.
[12:54:48.152] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:54:48.406] INFO: number of dead pixels (per ROC): 0 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[12:54:48.406] INFO: number of red-efficiency pixels: 80 52 80 112 133 194 160 86 91 135 145 89 91 74 12 19
[12:54:48.406] INFO: number of X-ray hits detected: 66311 44055 68832 107640 111138 121951 115439 80183 71788 99711 96460 80257 82426 51403 22213 26465
[12:54:48.406] 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:54:48.406] INFO: number of Vcal hits detected: 207920 207896 207919 207886 207865 207799 207830 207913 207908 207862 207855 207910 207883 207924 207988 207981
[12:54:48.407] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[12:54:48.407] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[12:54:48.407] INFO: X-ray hit rate [MHz/cm2]: 19.4 12.9 20.2 31.6 32.6 35.7 33.8 23.5 21.0 29.2 28.3 23.5 24.2 15.1 6.5 7.8
[12:54:48.407] INFO: PixTestHighRate::doXPixelAlive() done
[12:54:48.453] INFO: PixTest:: pg_setup set to default.
[12:54:48.463] INFO: enter test to run
[12:55:37.832] INFO: test: HighRate no parameter change
[12:55:37.832] INFO: running: highrate
[12:55:37.833] INFO: ----------------------------------------------------------------------
[12:55:37.833] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:55:37.833] INFO: ----------------------------------------------------------------------
[12:55:38.443] INFO: Expecting 208000 events.
[12:55:51.937] INFO: 208000 events read in total (12967ms).
[12:55:51.942] INFO: Test took 14101ms.
[12:55:52.234] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:55:52.538] INFO: number of dead pixels (per ROC): 0 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[12:55:52.538] INFO: number of red-efficiency pixels: 259 137 313 384 487 661 474 273 259 373 442 289 252 219 58 70
[12:55:52.538] INFO: number of X-ray hits detected: 136746 90081 141978 222756 228978 250037 239025 165851 147822 204851 199284 164870 170824 106377 46193 54994
[12:55:52.538] 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:55:52.538] INFO: number of Vcal hits detected: 207724 207811 207640 207588 207473 207241 207491 207711 207731 207609 207521 207696 207718 207766 207941 207930
[12:55:52.538] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.8 99.8 99.7 99.8 99.9 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[12:55:52.538] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.8 99.7 99.6 99.8 99.9 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[12:55:52.538] INFO: X-ray hit rate [MHz/cm2]: 40.1 26.4 41.6 65.3 67.1 73.3 70.1 48.6 43.3 60.0 58.4 48.3 50.1 31.2 13.5 16.1
[12:55:52.538] INFO: PixTestHighRate::doXPixelAlive() done
[12:55:52.584] INFO: PixTest:: pg_setup set to default.
[12:55:52.601] INFO: enter test to run
[12:56:13.560] INFO: test: HighRate no parameter change
[12:56:13.560] INFO: running: highrate
[12:56:13.561] INFO: ----------------------------------------------------------------------
[12:56:13.561] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:56:13.561] INFO: ----------------------------------------------------------------------
[12:56:14.181] INFO: Expecting 208000 events.
[12:56:29.664] INFO: 208000 events read in total (14956ms).
[12:56:29.672] INFO: Test took 16102ms.
[12:56:30.111] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:56:30.458] INFO: number of dead pixels (per ROC): 0 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[12:56:30.458] INFO: number of red-efficiency pixels: 554 292 733 931 1015 1575 1046 641 537 790 960 675 538 429 108 103
[12:56:30.458] INFO: number of X-ray hits detected: 206796 136898 213680 335503 344486 378618 362334 250445 223575 310034 301049 249015 257497 160332 70297 83099
[12:56:30.458] 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:56:30.458] INFO: number of Vcal hits detected: 207339 207620 206992 206890 206732 205797 206714 207225 207396 207089 206825 207215 207375 207507 207888 207893
[12:56:30.458] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.6 99.5 99.5 99.0 99.4 99.7 99.7 99.6 99.5 99.7 99.7 99.8 100.0 99.9
[12:56:30.458] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.5 99.5 99.4 98.9 99.4 99.6 99.7 99.6 99.4 99.6 99.7 99.8 99.9 99.9
[12:56:30.458] INFO: X-ray hit rate [MHz/cm2]: 60.6 40.1 62.6 98.3 101.0 111.0 106.2 73.4 65.5 90.9 88.2 73.0 75.5 47.0 20.6 24.4
[12:56:30.458] INFO: PixTestHighRate::doXPixelAlive() done
[12:56:30.509] INFO: PixTest:: pg_setup set to default.
[12:56:30.530] INFO: enter test to run
[12:56:34.655] INFO: test: exit no parameter change
[12:56:35.360] QUIET: Connection to board 33 closed.
[12:56:35.400] INFO: pXar: this is the end, my friend