[18:38:13.300] INFO: *** Welcome to pxar ***
[18:38:13.300] INFO: *** Today: 2016/06/20
[18:38:13.315] INFO: *** Version: v1.9.0-814-g7497
[18:38:13.315] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//dacParameters35_C15.dat
[18:38:13.316] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//tbmParameters_C0b.dat
[18:38:13.317] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//defaultMaskFile.dat
[18:38:13.317] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C15.dat
[18:38:13.392] INFO: clk: 4
[18:38:13.392] INFO: ctr: 4
[18:38:13.392] INFO: sda: 19
[18:38:13.392] INFO: tin: 9
[18:38:13.392] INFO: level: 15
[18:38:13.392] INFO: triggerdelay: 0
[18:38:13.392] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[18:38:13.392] INFO: Log level: INFO
[18:38:13.410] QUIET: Connection to board DTB_WREK4U opened.
[18:38:13.413] 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:
------------------------------------------------------
[18:38:13.416] INFO: RPC call hashes of host and DTB match: 398089610
[18:38:14.952] INFO: DUT info:
[18:38:14.952] INFO: The DUT currently contains the following objects:
[18:38:14.952] INFO: 2 TBM Cores tbm08c (2 ON)
[18:38:14.952] INFO: TBM Core alpha (0): 7 registers set
[18:38:14.952] INFO: TBM Core beta (1): 7 registers set
[18:38:14.952] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[18:38:14.952] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[18:38:14.952] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[18:38:14.953] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[18:38:14.953] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[18:38:14.953] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[18:38:14.953] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[18:38:14.953] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[18:38:14.953] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[18:38:14.953] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[18:38:14.953] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[18:38:14.953] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[18:38:14.953] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[18:38:14.953] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[18:38:14.953] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[18:38:14.953] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[18:38:14.953] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[18:38:15.356] INFO: enter 'restricted' command line mode
[18:38:15.356] INFO: enter test to run
[18:38:17.865] INFO: test: timing no parameter change
[18:38:17.865] INFO: running: timing
[18:38:17.874] INFO: ######################################################################
[18:38:17.874] INFO: PixTestTiming::doTest()
[18:38:17.874] INFO: ######################################################################
[18:38:17.874] INFO: ----------------------------------------------------------------------
[18:38:17.874] INFO: PixTestTiming::TBMPhaseScan()
[18:38:17.874] INFO: ----------------------------------------------------------------------
[18:43:39.523] INFO: TBM Phase Settings: 200
[18:43:39.523] INFO: 400MHz Phase: 2
[18:43:39.523] INFO: 160MHz Phase: 6
[18:43:39.523] INFO: Functional Phase Area: 3
[18:43:39.526] INFO: Test took 321652 ms.
[18:43:39.526] INFO: PixTestTiming::TBMPhaseScan() done.
[18:43:39.526] INFO: ----------------------------------------------------------------------
[18:43:39.526] INFO: PixTestTiming::ROCDelayScan()
[18:43:39.526] INFO: ----------------------------------------------------------------------
[18:46:39.741] INFO: ROC Delay Settings: 219
[18:46:39.741] INFO: ROC Header-Trailer/Token Delay: 11
[18:46:39.741] INFO: ROC Port 0 Delay: 3
[18:46:39.741] INFO: ROC Port 1 Delay: 3
[18:46:39.741] INFO: Functional ROC Area: 4
[18:46:39.744] INFO: Test took 180218 ms.
[18:46:39.744] INFO: PixTestTiming::ROCDelayScan() done.
[18:46:39.744] INFO: ----------------------------------------------------------------------
[18:46:39.745] INFO: PixTestTiming::TimingTest()
[18:46:39.745] INFO: ----------------------------------------------------------------------
[18:46:55.816] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:47:10.733] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:47:25.651] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:47:40.553] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:47:55.468] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:48:10.420] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:48:25.353] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:48:40.276] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:48:55.206] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:49:09.837] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:49:10.217] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:49:10.236] INFO: ----------------------------------------------------------------------
[18:49:10.236] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[18:49:10.236] INFO: ----------------------------------------------------------------------
[18:49:10.236] INFO: ----------------------------------------------------------------------
[18:49:10.236] INFO: Read back bit status: 1
[18:49:10.236] INFO: ----------------------------------------------------------------------
[18:49:10.236] INFO: ----------------------------------------------------------------------
[18:49:10.236] INFO: Timings are good!
[18:49:10.236] INFO: ----------------------------------------------------------------------
[18:49:10.236] INFO: Test took 150492 ms.
[18:49:10.236] INFO: PixTestTiming::TimingTest() done.
[18:49:10.236] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//tbmParameters_C0a.dat
[18:49:10.236] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//tbmParameters_C0b.dat
[18:49:10.236] INFO: PixTestTiming::doTest took 652367 ms.
[18:49:10.236] INFO: PixTestTiming::doTest() done
[18:49:10.236] INFO: Write out TBMPhaseScan_0_V0
[18:49:10.263] INFO: Write out TBMPhaseScan_1_V0
[18:49:10.263] INFO: Write out CombinedTBMPhaseScan_V0
[18:49:10.264] INFO: Write out ROCDelayScan3_V0
[18:49:10.264] INFO: enter test to run
[18:49:25.077] INFO: test: PixelAlive no parameter change
[18:49:25.077] INFO: running: pixelalive
[18:49:25.081] INFO: ----------------------------------------------------------------------
[18:49:25.081] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[18:49:25.081] INFO: ----------------------------------------------------------------------
[18:49:25.398] INFO: Expecting 41600 events.
[18:49:29.713] INFO: 41600 events read in total (3599ms).
[18:49:29.714] INFO: Test took 4629ms.
[18:49:29.720] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:49:30.116] INFO: PixTestAlive::aliveTest() done
[18:49:30.116] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[18:49:30.117] INFO: enter test to run
[18:53:40.619] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[18:53:40.619] INFO: running: highrate
[18:53:40.620] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[18:53:40.778] INFO: ----------------------------------------------------------------------
[18:53:40.778] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[18:53:40.778] INFO: ----------------------------------------------------------------------
[18:53:40.778] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[18:53:40.778] INFO: edge/corner pixel THR is adjusted
[18:53:40.778] INFO: PixTestHighRate::trimHotPixels: step 0...
[18:53:41.735] INFO: Collecting data for 5 seconds...
[18:53:46.753] INFO: Done with hot pixel readout
[18:53:58.637] INFO: PixTest:: pg_setup set to default.

[18:53:58.638] INFO: 25 hot pixels found in step 0
[18:53:59.632] INFO: Collecting data for 5 seconds...
[18:54:04.649] INFO: Done with hot pixel readout
[18:54:16.492] INFO: PixTest:: pg_setup set to default.
[18:54:16.493] INFO: 21 hot pixels found in step 1
[18:54:17.487] INFO: Collecting data for 5 seconds...
[18:54:22.503] INFO: Done with hot pixel readout
[18:54:34.378] INFO: PixTest:: pg_setup set to default.

[18:54:34.379] INFO: 15 hot pixels found in step 2
[18:54:35.373] INFO: Collecting data for 5 seconds...
[18:54:40.389] INFO: Done with hot pixel readout
[18:54:52.274] INFO: PixTest:: pg_setup set to default.
[18:54:52.275] INFO: 21 hot pixels found in step 3
[18:54:53.270] INFO: Collecting data for 5 seconds...
[18:54:58.286] INFO: Done with hot pixel readout
[18:55:10.130] INFO: PixTest:: pg_setup set to default.


[18:55:10.131] INFO: 18 hot pixels found in step 4
[18:55:11.124] INFO: Collecting data for 5 seconds...
[18:55:16.141] INFO: Done with hot pixel readout
[18:55:28.011] INFO: PixTest:: pg_setup set to default.


[18:55:28.012] INFO: 12 hot pixels found in step 5
[18:55:29.005] INFO: Collecting data for 5 seconds...
[18:55:34.022] INFO: Done with hot pixel readout
[18:55:45.887] INFO: PixTest:: pg_setup set to default.


[18:55:45.888] INFO: 15 hot pixels found in step 6
[18:55:46.882] INFO: Collecting data for 5 seconds...
[18:55:51.898] INFO: Done with hot pixel readout
[18:56:03.759] INFO: PixTest:: pg_setup set to default.



[18:56:03.760] INFO: 16 hot pixels found in step 7
[18:56:04.754] INFO: Collecting data for 5 seconds...
[18:56:09.771] INFO: Done with hot pixel readout
[18:56:21.637] INFO: PixTest:: pg_setup set to default.




[18:56:21.638] INFO: 13 hot pixels found in step 8
[18:56:22.631] INFO: Collecting data for 5 seconds...
[18:56:27.648] INFO: Done with hot pixel readout
[18:56:39.514] INFO: PixTest:: pg_setup set to default.

[18:56:39.515] INFO: 8 hot pixels found in step 9
[18:56:40.509] INFO: Collecting data for 5 seconds...
[18:56:45.526] INFO: Done with hot pixel readout
[18:56:57.397] INFO: PixTest:: pg_setup set to default.




[18:56:57.398] INFO: 10 hot pixels found in step 10
[18:56:58.391] INFO: Collecting data for 5 seconds...
[18:57:03.407] INFO: Done with hot pixel readout
[18:57:15.230] INFO: PixTest:: pg_setup set to default.




[18:57:15.231] INFO: 12 hot pixels found in step 11
[18:57:16.224] INFO: Collecting data for 5 seconds...
[18:57:21.241] INFO: Done with hot pixel readout
[18:57:33.119] INFO: PixTest:: pg_setup set to default.





[18:57:33.120] INFO: 12 hot pixels found in step 12
[18:57:34.113] INFO: Collecting data for 5 seconds...
[18:57:39.130] INFO: Done with hot pixel readout
[18:57:50.991] INFO: PixTest:: pg_setup set to default.




[18:57:50.992] INFO: 14 hot pixels found in step 13
[18:57:51.985] INFO: Collecting data for 5 seconds...
[18:57:57.002] INFO: Done with hot pixel readout
[18:58:08.847] INFO: PixTest:: pg_setup set to default.





[18:58:08.848] INFO: 14 hot pixels found in step 14
[18:58:08.886] INFO: 14 hot pixels could not be trimmed and have been masked.
[18:58:08.889] INFO: PixTest::trimHotPixels() done
[18:58:08.889] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C0.dat
[18:58:08.894] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C1.dat
[18:58:08.901] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C2.dat
[18:58:08.907] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C3.dat
[18:58:08.913] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C4.dat
[18:58:08.918] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C5.dat
[18:58:08.923] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C6.dat
[18:58:08.928] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C7.dat
[18:58:08.933] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C8.dat
[18:58:08.939] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C9.dat
[18:58:08.945] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C10.dat
[18:58:08.950] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C11.dat
[18:58:08.955] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C12.dat
[18:58:08.960] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C13.dat
[18:58:08.965] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C14.dat
[18:58:08.972] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C15.dat
[18:58:08.977] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//defaultMaskFile.dat
[18:58:08.987] INFO: enter test to run
[18:58:33.329] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[18:58:33.329] INFO: running: highrate
[18:58:33.334] INFO: ----------------------------------------------------------------------
[18:58:33.334] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[18:58:33.334] INFO: ----------------------------------------------------------------------
[18:58:33.334] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[18:58:33.334] INFO: edge/corner pixel THR is adjusted
[18:58:33.334] INFO: PixTestHighRate::trimHotPixels: step 0...
[18:58:34.292] INFO: Collecting data for 1 seconds...
[18:58:35.296] INFO: Done with hot pixel readout
[18:58:39.316] INFO: PixTest:: pg_setup set to default.
[18:58:39.317] INFO: 0 hot pixels found in step 0
[18:58:39.322] INFO: 0 hot pixels could not be trimmed and have been masked.
[18:58:39.413] INFO: PixTest::trimHotPixels() done
[18:58:39.413] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C0.dat
[18:58:39.424] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C1.dat
[18:58:39.429] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C2.dat
[18:58:39.434] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C3.dat
[18:58:39.440] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C4.dat
[18:58:39.445] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C5.dat
[18:58:39.450] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C6.dat
[18:58:39.455] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C7.dat
[18:58:39.461] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C8.dat
[18:58:39.466] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C9.dat
[18:58:39.471] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C10.dat
[18:58:39.476] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C11.dat
[18:58:39.482] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C12.dat
[18:58:39.487] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C13.dat
[18:58:39.492] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C14.dat
[18:58:39.497] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C15.dat
[18:58:39.503] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-O-1-10_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//defaultMaskFile.dat
[18:58:39.513] INFO: enter test to run
[18:58:57.721] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[18:58:57.721] INFO: running: xray
[18:58:57.722] INFO: ----------------------------------------------------------------------
[18:58:57.722] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[18:58:57.722] INFO: ----------------------------------------------------------------------
[18:58:58.685] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[18:59:10.036] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[18:59:39.496] INFO: Resuming triggers.
[18:59:50.845] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[19:00:20.140] INFO: Resuming triggers.
[19:00:31.489] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[19:01:01.005] INFO: Resuming triggers.
[19:01:12.352] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[19:01:41.746] INFO: Resuming triggers.
[19:01:53.092] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[19:02:22.828] INFO: Resuming triggers.
[19:02:34.173] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[19:03:03.809] INFO: Resuming triggers.
[19:03:15.157] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[19:03:44.577] INFO: Resuming triggers.
[19:03:55.922] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[19:04:26.070] INFO: Resuming triggers.
[19:04:35.641] INFO: data taking finished, elapsed time: 100 seconds.
[19:05:00.919] INFO: PixTest:: pg_setup set to default.
[19:05:00.922] INFO: PixTestXray::doPhRun() done
[19:05:01.080] INFO: enter test to run
[19:06:58.166] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[19:06:58.166] INFO: running: xray
[19:06:58.167] INFO: ----------------------------------------------------------------------
[19:06:58.167] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[19:06:58.167] INFO: ----------------------------------------------------------------------
[19:06:59.138] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[19:07:05.789] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[19:07:35.870] INFO: Resuming triggers.
[19:07:42.521] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[19:08:12.632] INFO: Resuming triggers.
[19:08:19.285] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[19:08:49.398] INFO: Resuming triggers.
[19:08:56.053] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[19:09:26.103] INFO: Resuming triggers.
[19:09:32.758] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[19:10:02.000] INFO: Resuming triggers.
[19:10:09.650] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[19:10:39.645] INFO: Resuming triggers.
[19:10:46.293] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[19:11:16.365] INFO: Resuming triggers.
[19:11:23.014] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[19:11:53.116] INFO: Resuming triggers.
[19:11:59.765] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[19:12:29.915] INFO: Resuming triggers.
[19:12:36.563] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[19:13:06.560] INFO: Resuming triggers.
[19:13:13.208] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[19:13:43.301] INFO: Resuming triggers.
[19:13:49.952] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[19:14:20.466] INFO: Resuming triggers.
[19:14:27.111] INFO: run duration 86 seconds, buffer almost full (81%), pausing triggers.
[19:14:57.707] INFO: Resuming triggers.
[19:15:04.355] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[19:15:35.699] INFO: Resuming triggers.
[19:15:42.347] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[19:16:13.787] INFO: Resuming triggers.
[19:16:14.377] INFO: data taking finished, elapsed time: 100 seconds.
[19:16:17.526] INFO: PixTest:: pg_setup set to default.
[19:16:17.529] INFO: PixTestXray::doPhRun() done
[19:16:17.681] INFO: enter test to run
[19:19:25.081] INFO: test: HighRate no parameter change
[19:19:25.081] INFO: running: highrate
[19:19:25.099] INFO: ----------------------------------------------------------------------
[19:19:25.099] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[19:19:25.099] INFO: ----------------------------------------------------------------------
[19:19:25.255] INFO: Expecting 768 events.
[19:19:26.388] INFO: 768 events read in total (418ms).
[19:19:26.389] INFO: Test took 1268ms.
[19:19:27.192] INFO: Expecting 41600 events.
[19:19:30.298] INFO: 41600 events read in total (2579ms).
[19:19:30.299] INFO: Test took 3903ms.
[19:19:30.342] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:19:31.058] INFO: Expecting 41600 events.
[19:19:34.283] INFO: 41600 events read in total (2699ms).
[19:19:34.284] INFO: Test took 3923ms.
[19:19:34.320] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:19:35.039] INFO: Expecting 41600 events.
[19:19:38.292] INFO: 41600 events read in total (2726ms).
[19:19:38.293] INFO: Test took 3956ms.
[19:19:38.328] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:19:39.048] INFO: Expecting 41600 events.
[19:19:42.288] INFO: 41600 events read in total (2713ms).
[19:19:42.289] INFO: Test took 3944ms.
[19:19:42.324] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:19:43.042] INFO: Expecting 41600 events.
[19:19:46.271] INFO: 41600 events read in total (2702ms).
[19:19:46.272] INFO: Test took 3929ms.
[19:19:46.307] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:19:47.027] INFO: Expecting 41600 events.
[19:19:50.269] INFO: 41600 events read in total (2715ms).
[19:19:50.270] INFO: Test took 3944ms.
[19:19:50.305] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:19:51.027] INFO: Expecting 41600 events.
[19:19:54.269] INFO: 41600 events read in total (2715ms).
[19:19:54.270] INFO: Test took 3946ms.
[19:19:54.304] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:19:55.028] INFO: Expecting 41600 events.
[19:19:58.274] INFO: 41600 events read in total (2719ms).
[19:19:58.275] INFO: Test took 3952ms.
[19:19:58.310] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:19:59.032] INFO: Expecting 41600 events.
[19:20:02.246] INFO: 41600 events read in total (2687ms).
[19:20:02.247] INFO: Test took 3919ms.
[19:20:02.283] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:20:03.005] INFO: Expecting 41600 events.
[19:20:06.251] INFO: 41600 events read in total (2719ms).
[19:20:06.252] INFO: Test took 3950ms.
[19:20:06.287] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:20:07.007] INFO: Expecting 41600 events.
[19:20:10.260] INFO: 41600 events read in total (2726ms).
[19:20:10.261] INFO: Test took 3954ms.
[19:20:10.297] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:20:11.016] INFO: Expecting 41600 events.
[19:20:14.279] INFO: 41600 events read in total (2736ms).
[19:20:14.280] INFO: Test took 3964ms.
[19:20:14.316] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:20:15.034] INFO: Expecting 41600 events.
[19:20:18.290] INFO: 41600 events read in total (2729ms).
[19:20:18.291] INFO: Test took 3956ms.
[19:20:18.326] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:20:19.050] INFO: Expecting 41600 events.
[19:20:22.286] INFO: 41600 events read in total (2709ms).
[19:20:22.287] INFO: Test took 3942ms.
[19:20:22.324] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:20:23.045] INFO: Expecting 41600 events.
[19:20:26.292] INFO: 41600 events read in total (2721ms).
[19:20:26.293] INFO: Test took 3950ms.
[19:20:26.329] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:20:27.046] INFO: Expecting 41600 events.
[19:20:30.268] INFO: 41600 events read in total (2695ms).
[19:20:30.269] INFO: Test took 3921ms.
[19:20:30.304] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:20:31.027] INFO: Expecting 41600 events.
[19:20:34.288] INFO: 41600 events read in total (2734ms).
[19:20:34.289] INFO: Test took 3967ms.
[19:20:34.324] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:20:35.046] INFO: Expecting 41600 events.
[19:20:38.294] INFO: 41600 events read in total (2721ms).
[19:20:38.295] INFO: Test took 3951ms.
[19:20:38.330] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:20:39.051] INFO: Expecting 41600 events.
[19:20:42.289] INFO: 41600 events read in total (2711ms).
[19:20:42.290] INFO: Test took 3941ms.
[19:20:42.325] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:20:43.047] INFO: Expecting 41600 events.
[19:20:46.125] INFO: 41600 events read in total (2551ms).
[19:20:46.126] INFO: Test took 3782ms.
[19:20:46.160] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:20:46.522] INFO: enter test to run
[19:21:26.768] INFO: test: HighRate no parameter change
[19:21:26.768] INFO: running: highrate
[19:21:26.769] INFO: ----------------------------------------------------------------------
[19:21:26.769] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[19:21:26.769] INFO: ----------------------------------------------------------------------
[19:21:27.389] INFO: Expecting 208000 events.
[19:21:39.277] INFO: 208000 events read in total (11361ms).
[19:21:39.280] INFO: Test took 12502ms.
[19:21:39.430] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:21:39.685] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[19:21:39.685] INFO: number of red-efficiency pixels: 85 47 89 153 155 152 175 118 112 116 96 84 91 42 21 28
[19:21:39.685] INFO: number of X-ray hits detected: 64286 42829 72001 113899 123686 120014 124972 93677 95034 98513 93555 82368 84631 49547 22047 25958
[19:21:39.685] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[19:21:39.685] INFO: number of Vcal hits detected: 207914 207953 207907 207846 207841 207844 207820 207880 207886 207881 207903 207913 207908 207957 207979 207972
[19:21:39.685] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 100.0 100.0 100.0 100.0 100.0 100.0
[19:21:39.685] 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 100.0 100.0 100.0 100.0 100.0 100.0
[19:21:39.685] INFO: X-ray hit rate [MHz/cm2]: 18.8 12.6 21.1 33.4 36.3 35.2 36.6 27.5 27.9 28.9 27.4 24.1 24.8 14.5 6.5 7.6
[19:21:39.685] INFO: PixTestHighRate::doXPixelAlive() done
[19:21:39.735] INFO: PixTest:: pg_setup set to default.
[19:21:39.748] INFO: enter test to run
[19:21:57.312] INFO: test: HighRate no parameter change
[19:21:57.312] INFO: running: highrate
[19:21:57.313] INFO: ----------------------------------------------------------------------
[19:21:57.313] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[19:21:57.313] INFO: ----------------------------------------------------------------------
[19:21:57.930] INFO: Expecting 208000 events.
[19:22:11.620] INFO: 208000 events read in total (13164ms).
[19:22:11.625] INFO: Test took 14303ms.
[19:22:11.924] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:22:12.230] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[19:22:12.230] INFO: number of red-efficiency pixels: 212 122 219 392 494 404 603 296 289 388 294 241 231 147 54 39
[19:22:12.230] INFO: number of X-ray hits detected: 129162 85319 144663 229063 247219 240168 250167 189070 192504 197064 189194 166385 170019 98206 44674 51690
[19:22:12.230] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[19:22:12.230] INFO: number of Vcal hits detected: 207773 207874 207768 207584 207456 207557 207322 207678 207703 207585 207691 207748 207759 207848 207946 207960
[19:22:12.230] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.7 99.9 99.9 99.8 99.9 99.9 99.9 99.9 100.0 100.0
[19:22:12.230] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.8 99.7 99.8 99.9 99.8 99.9 99.9 99.9 99.9 100.0 100.0
[19:22:12.230] INFO: X-ray hit rate [MHz/cm2]: 37.9 25.0 42.4 67.1 72.5 70.4 73.3 55.4 56.4 57.8 55.5 48.8 49.8 28.8 13.1 15.2
[19:22:12.230] INFO: PixTestHighRate::doXPixelAlive() done
[19:22:12.279] INFO: PixTest:: pg_setup set to default.
[19:22:12.298] INFO: enter test to run
[19:22:25.791] INFO: test: HighRate no parameter change
[19:22:25.791] INFO: running: highrate
[19:22:25.793] INFO: ----------------------------------------------------------------------
[19:22:25.793] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[19:22:25.793] INFO: ----------------------------------------------------------------------
[19:22:26.405] INFO: Expecting 208000 events.
[19:22:41.933] INFO: 208000 events read in total (15001ms).
[19:22:41.940] INFO: Test took 16137ms.
[19:22:42.394] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:22:42.745] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[19:22:42.745] INFO: number of red-efficiency pixels: 453 256 502 881 1174 940 1426 662 632 918 598 494 483 249 92 79
[19:22:42.745] INFO: number of X-ray hits detected: 193876 127866 216832 343799 371479 360114 376464 283138 288032 296504 281912 248306 255657 148338 66654 78903
[19:22:42.745] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[19:22:42.745] INFO: number of Vcal hits detected: 207476 207727 207380 206956 206540 206851 206032 207218 207286 206859 207338 207445 207475 207738 207902 207920
[19:22:42.745] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.5 99.4 99.5 99.1 99.7 99.7 99.5 99.7 99.8 99.8 99.9 100.0 100.0
[19:22:42.745] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.7 99.5 99.3 99.4 99.1 99.6 99.7 99.5 99.7 99.7 99.7 99.9 100.0 100.0
[19:22:42.745] INFO: X-ray hit rate [MHz/cm2]: 56.8 37.5 63.6 100.8 108.9 105.6 110.3 83.0 84.4 86.9 82.6 72.8 74.9 43.5 19.5 23.1
[19:22:42.745] INFO: PixTestHighRate::doXPixelAlive() done
[19:22:42.793] INFO: PixTest:: pg_setup set to default.
[19:22:42.810] INFO: enter test to run
[19:22:46.407] INFO: test: exit no parameter change
[19:22:46.755] QUIET: Connection to board 32 closed.
[19:22:46.771] INFO: pXar: this is the end, my friend