[11:42:32.024] INFO: *** Welcome to pxar ***
[11:42:32.024] INFO: *** Today: 2016/10/14
[11:42:32.040] INFO: *** Version: v1.9.0-818-g96727
[11:42:32.040] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//dacParameters35_C15.dat
[11:42:32.040] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:42:32.040] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//defaultMaskFile.dat
[11:42:32.040] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C15.dat
[11:42:32.118] INFO: clk: 4
[11:42:32.118] INFO: ctr: 4
[11:42:32.118] INFO: sda: 19
[11:42:32.118] INFO: tin: 9
[11:42:32.118] INFO: level: 15
[11:42:32.118] INFO: triggerdelay: 0
[11:42:32.118] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[11:42:32.118] INFO: Log level: INFO
[11:42:32.136] QUIET: Connection to board DTB_WREKRL opened.
[11:42:32.139] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 33
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREKRL
MAC address: 40D855118021
Hostname: pixelDTB033
Comment:
------------------------------------------------------
[11:42:32.142] INFO: RPC call hashes of host and DTB match: 398089610
[11:42:33.673] INFO: DUT info:
[11:42:33.673] INFO: The DUT currently contains the following objects:
[11:42:33.673] INFO: 2 TBM Cores tbm08c (2 ON)
[11:42:33.673] INFO: TBM Core alpha (0): 7 registers set
[11:42:33.673] INFO: TBM Core beta (1): 7 registers set
[11:42:33.673] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:42:33.673] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:33.673] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:33.673] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:33.673] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:33.673] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:33.673] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:33.673] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:33.673] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:33.673] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:33.673] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:33.674] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:33.674] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:33.674] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:33.674] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:33.674] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:33.674] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:34.077] INFO: enter 'restricted' command line mode
[11:42:34.077] INFO: enter test to run
[11:42:38.612] INFO: test: PixelAlive no parameter change
[11:42:38.612] INFO: running: pixelalive
[11:42:38.621] INFO: ----------------------------------------------------------------------
[11:42:38.621] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[11:42:38.621] INFO: ----------------------------------------------------------------------
[11:42:38.936] INFO: Expecting 41600 events.
[11:42:43.265] INFO: 41600 events read in total (3611ms).
[11:42:43.434] INFO: Test took 4811ms.
[11:42:43.445] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:43.707] INFO: PixTestAlive::aliveTest() done
[11:42:43.707] INFO: number of dead pixels (per ROC): 0 0 0 0 0 1 0 0 0 0 0 0 0 0 1 1
[11:42:43.738] INFO: enter test to run
[11:42:53.212] INFO: test: timing no parameter change
[11:42:53.212] INFO: running: timing
[11:42:53.215] INFO: ######################################################################
[11:42:53.215] INFO: PixTestTiming::doTest()
[11:42:53.215] INFO: ######################################################################
[11:42:53.215] INFO: ----------------------------------------------------------------------
[11:42:53.215] INFO: PixTestTiming::TBMPhaseScan()
[11:42:53.215] INFO: ----------------------------------------------------------------------
[11:47:19.857] INFO: TBM Phase Settings: 236
[11:47:19.857] INFO: 400MHz Phase: 3
[11:47:19.857] INFO: 160MHz Phase: 7
[11:47:19.857] INFO: Functional Phase Area: 3
[11:47:19.860] INFO: Test took 266645 ms.
[11:47:19.860] INFO: PixTestTiming::TBMPhaseScan() done.
[11:47:19.861] INFO: ----------------------------------------------------------------------
[11:47:19.861] INFO: PixTestTiming::ROCDelayScan()
[11:47:19.861] INFO: ----------------------------------------------------------------------
[11:49:20.478] INFO: ROC Delay Settings: 228
[11:49:20.478] INFO: ROC Header-Trailer/Token Delay: 11
[11:49:20.478] INFO: ROC Port 0 Delay: 4
[11:49:20.478] INFO: ROC Port 1 Delay: 4
[11:49:20.478] INFO: Functional ROC Area: 4
[11:49:20.481] INFO: Test took 120621 ms.
[11:49:20.481] INFO: PixTestTiming::ROCDelayScan() done.
[11:49:20.482] INFO: ----------------------------------------------------------------------
[11:49:20.482] INFO: PixTestTiming::TimingTest()
[11:49:20.482] INFO: ----------------------------------------------------------------------
[11:49:36.803] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:49:52.007] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:50:07.255] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:50:22.516] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:50:37.734] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:50:52.807] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:07.822] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:22.867] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:37.999] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:53.119] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:53.495] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:53.512] INFO: ----------------------------------------------------------------------
[11:51:53.512] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:51:53.512] INFO: ----------------------------------------------------------------------
[11:51:53.512] INFO: ----------------------------------------------------------------------
[11:51:53.512] INFO: Read back bit status: 1
[11:51:53.512] INFO: ----------------------------------------------------------------------
[11:51:53.512] INFO: ----------------------------------------------------------------------
[11:51:53.512] INFO: Timings are good!
[11:51:53.512] INFO: ----------------------------------------------------------------------
[11:51:53.512] INFO: Test took 153031 ms.
[11:51:53.512] INFO: PixTestTiming::TimingTest() done.
[11:51:53.513] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:51:53.513] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:51:53.513] INFO: PixTestTiming::doTest took 540301 ms.
[11:51:53.513] INFO: PixTestTiming::doTest() done
[11:51:53.513] INFO: Write out TBMPhaseScan_0_V0
[11:51:53.513] INFO: Write out TBMPhaseScan_1_V0
[11:51:53.513] INFO: Write out CombinedTBMPhaseScan_V0
[11:51:53.514] INFO: Write out ROCDelayScan3_V0
[11:51:53.515] INFO: enter test to run
[11:52:22.392] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:52:22.392] INFO: running: highrate
[11:52:22.392] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:52:24.481] INFO: ----------------------------------------------------------------------
[11:52:24.481] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:52:24.481] INFO: ----------------------------------------------------------------------
[11:52:24.481] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:52:24.481] INFO: edge/corner pixel THR is adjusted
[11:52:24.481] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:52:25.440] INFO: Collecting data for 5 seconds...
[11:52:30.458] INFO: Done with hot pixel readout
[11:52:42.404] INFO: PixTest:: pg_setup set to default.
[11:52:42.405] INFO: 19 hot pixels found in step 0
[11:52:43.397] INFO: Collecting data for 5 seconds...
[11:52:48.416] INFO: Done with hot pixel readout
[11:53:00.364] INFO: PixTest:: pg_setup set to default.
[11:53:00.365] INFO: 17 hot pixels found in step 1
[11:53:01.357] INFO: Collecting data for 5 seconds...
[11:53:06.375] INFO: Done with hot pixel readout
[11:53:18.471] INFO: PixTest:: pg_setup set to default.
[11:53:18.472] INFO: 17 hot pixels found in step 2
[11:53:19.465] INFO: Collecting data for 5 seconds...
[11:53:24.481] INFO: Done with hot pixel readout
[11:53:36.045] INFO: PixTest:: pg_setup set to default.
[11:53:36.046] INFO: 15 hot pixels found in step 3
[11:53:37.038] INFO: Collecting data for 5 seconds...
[11:53:42.055] INFO: Done with hot pixel readout
[11:53:53.689] INFO: PixTest:: pg_setup set to default.
[11:53:53.690] INFO: 13 hot pixels found in step 4
[11:53:54.682] INFO: Collecting data for 5 seconds...
[11:53:59.699] INFO: Done with hot pixel readout
[11:54:11.332] INFO: PixTest:: pg_setup set to default.
[11:54:11.333] INFO: 11 hot pixels found in step 5
[11:54:12.325] INFO: Collecting data for 5 seconds...
[11:54:17.341] INFO: Done with hot pixel readout
[11:54:28.905] INFO: PixTest:: pg_setup set to default.
[11:54:28.906] INFO: 6 hot pixels found in step 6
[11:54:29.899] INFO: Collecting data for 5 seconds...
[11:54:34.915] INFO: Done with hot pixel readout
[11:54:46.541] INFO: PixTest:: pg_setup set to default.
[11:54:46.542] INFO: 10 hot pixels found in step 7
[11:54:47.535] INFO: Collecting data for 5 seconds...
[11:54:52.551] INFO: Done with hot pixel readout
[11:55:04.111] INFO: PixTest:: pg_setup set to default.
[11:55:04.112] INFO: 3 hot pixels found in step 8
[11:55:05.105] INFO: Collecting data for 5 seconds...
[11:55:10.121] INFO: Done with hot pixel readout
[11:55:21.755] INFO: PixTest:: pg_setup set to default.

[11:55:21.755] INFO: 5 hot pixels found in step 9
[11:55:22.747] INFO: Collecting data for 5 seconds...
[11:55:27.764] INFO: Done with hot pixel readout
[11:55:39.256] INFO: PixTest:: pg_setup set to default.
[11:55:39.257] INFO: 1 hot pixels found in step 10
[11:55:40.249] INFO: Collecting data for 5 seconds...
[11:55:45.266] INFO: Done with hot pixel readout
[11:55:56.898] INFO: PixTest:: pg_setup set to default.
[11:55:56.899] INFO: 2 hot pixels found in step 11
[11:55:57.892] INFO: Collecting data for 5 seconds...
[11:56:02.909] INFO: Done with hot pixel readout
[11:56:14.519] INFO: PixTest:: pg_setup set to default.
[11:56:14.520] INFO: 1 hot pixels found in step 12
[11:56:15.512] INFO: Collecting data for 5 seconds...
[11:56:20.528] INFO: Done with hot pixel readout
[11:56:31.879] INFO: PixTest:: pg_setup set to default.
[11:56:31.880] INFO: 1 hot pixels found in step 13
[11:56:32.872] INFO: Collecting data for 5 seconds...
[11:56:37.889] INFO: Done with hot pixel readout
[11:56:49.532] INFO: PixTest:: pg_setup set to default.
[11:56:49.533] INFO: 4 hot pixels found in step 14
[11:56:49.569] INFO: 4 hot pixels could not be trimmed and have been masked.
[11:56:49.573] INFO: PixTest::trimHotPixels() done
[11:56:49.573] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C0.dat
[11:56:49.579] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C1.dat
[11:56:49.585] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C2.dat
[11:56:49.590] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C3.dat
[11:56:49.596] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C4.dat
[11:56:49.601] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C5.dat
[11:56:49.606] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C6.dat
[11:56:49.632] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C7.dat
[11:56:49.637] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C8.dat
[11:56:49.642] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C9.dat
[11:56:49.648] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C10.dat
[11:56:49.653] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C11.dat
[11:56:49.658] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C12.dat
[11:56:49.663] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C13.dat
[11:56:49.669] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C14.dat
[11:56:49.674] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C15.dat
[11:56:49.679] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//defaultMaskFile.dat
[11:56:49.693] INFO: enter test to run
[11:57:10.926] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[11:57:10.926] INFO: running: highrate
[11:57:10.931] INFO: ----------------------------------------------------------------------
[11:57:10.931] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[11:57:10.931] INFO: ----------------------------------------------------------------------
[11:57:10.931] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[11:57:10.931] INFO: edge/corner pixel THR is adjusted
[11:57:10.931] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:57:11.889] INFO: Collecting data for 1 seconds...
[11:57:12.893] INFO: Done with hot pixel readout
[11:57:16.859] INFO: PixTest:: pg_setup set to default.
[11:57:16.860] INFO: 0 hot pixels found in step 0
[11:57:16.865] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:57:16.957] INFO: PixTest::trimHotPixels() done
[11:57:16.957] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C0.dat
[11:57:16.969] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C1.dat
[11:57:16.975] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C2.dat
[11:57:16.980] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C3.dat
[11:57:16.986] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C4.dat
[11:57:16.991] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C5.dat
[11:57:16.996] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C6.dat
[11:57:16.001] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C7.dat
[11:57:17.007] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C8.dat
[11:57:17.012] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C9.dat
[11:57:17.017] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C10.dat
[11:57:17.022] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C11.dat
[11:57:17.028] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C12.dat
[11:57:17.033] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C13.dat
[11:57:17.038] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C14.dat
[11:57:17.043] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//trimParameters35_C15.dat
[11:57:17.048] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-3-34_FPIXTest-17C-FNAL-160929-0938-150V_2016-09-29_09h38m_1475159936/000_FPIXTest_p17//defaultMaskFile.dat
[11:57:17.058] INFO: enter test to run
[11:57:47.206] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:57:47.206] INFO: running: xray
[11:57:47.219] INFO: ----------------------------------------------------------------------
[11:57:47.219] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:57:47.219] INFO: ----------------------------------------------------------------------
[11:57:48.206] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:57:59.732] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[11:58:29.080] INFO: Resuming triggers.
[11:58:40.611] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[11:59:09.930] INFO: Resuming triggers.
[11:59:21.460] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[11:59:51.390] INFO: Resuming triggers.
[12:00:02.924] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[12:00:32.534] INFO: Resuming triggers.
[12:00:44.066] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[12:01:13.652] INFO: Resuming triggers.
[12:01:25.183] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[12:01:54.407] INFO: Resuming triggers.
[12:02:05.942] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[12:02:35.243] INFO: Resuming triggers.
[12:02:46.774] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[12:03:16.441] INFO: Resuming triggers.
[12:03:24.535] INFO: data taking finished, elapsed time: 100 seconds.
[12:03:45.239] INFO: PixTest:: pg_setup set to default.
[12:03:45.242] INFO: PixTestXray::doPhRun() done
[12:03:45.700] INFO: enter test to run
[12:04:08.027] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:04:08.027] INFO: running: xray
[12:04:08.028] INFO: ----------------------------------------------------------------------
[12:04:08.028] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:04:08.028] INFO: ----------------------------------------------------------------------
[12:04:08.001] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:04:15.804] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[12:04:46.508] INFO: Resuming triggers.
[12:04:53.316] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[12:05:24.898] INFO: Resuming triggers.
[12:05:31.703] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[12:06:02.377] INFO: Resuming triggers.
[12:06:09.181] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[12:06:40.172] INFO: Resuming triggers.
[12:06:46.979] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[12:07:18.418] INFO: Resuming triggers.
[12:07:25.225] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[12:07:56.257] INFO: Resuming triggers.
[12:08:03.062] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[12:08:33.522] INFO: Resuming triggers.
[12:08:40.328] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[12:09:10.452] INFO: Resuming triggers.
[12:09:17.256] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[12:09:47.514] INFO: Resuming triggers.
[12:09:54.319] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[12:10:24.405] INFO: Resuming triggers.
[12:10:31.217] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[12:11:01.304] INFO: Resuming triggers.
[12:11:08.116] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[12:11:38.252] INFO: Resuming triggers.
[12:11:45.060] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[12:12:15.167] INFO: Resuming triggers.
[12:12:21.976] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[12:12:52.276] INFO: Resuming triggers.
[12:12:57.327] INFO: data taking finished, elapsed time: 100 seconds.
[12:13:19.891] INFO: PixTest:: pg_setup set to default.
[12:13:19.895] INFO: PixTestXray::doPhRun() done
[12:13:20.068] INFO: enter test to run
[12:13:42.063] INFO: test: HighRate no parameter change
[12:13:42.063] INFO: running: highrate
[12:13:42.079] INFO: ----------------------------------------------------------------------
[12:13:42.080] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:13:42.080] INFO: ----------------------------------------------------------------------
[12:13:42.240] INFO: Expecting 768 events.
[12:13:43.374] INFO: 768 events read in total (419ms).
[12:13:43.374] INFO: Test took 1270ms.
[12:13:44.177] INFO: Expecting 41600 events.
[12:13:47.216] INFO: 41600 events read in total (2513ms).
[12:13:47.217] INFO: Test took 3781ms.
[12:13:47.248] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:47.982] INFO: Expecting 41600 events.
[12:13:51.131] INFO: 41600 events read in total (2622ms).
[12:13:51.132] INFO: Test took 3866ms.
[12:13:51.165] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:51.892] INFO: Expecting 41600 events.
[12:13:55.103] INFO: 41600 events read in total (2684ms).
[12:13:55.104] INFO: Test took 3923ms.
[12:13:55.137] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:55.863] INFO: Expecting 41600 events.
[12:13:59.074] INFO: 41600 events read in total (2684ms).
[12:13:59.075] INFO: Test took 3920ms.
[12:13:59.108] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:59.832] INFO: Expecting 41600 events.
[12:14:03.060] INFO: 41600 events read in total (2701ms).
[12:14:03.061] INFO: Test took 3936ms.
[12:14:03.094] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:03.821] INFO: Expecting 41600 events.
[12:14:06.980] INFO: 41600 events read in total (2632ms).
[12:14:06.981] INFO: Test took 3869ms.
[12:14:07.014] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:07.737] INFO: Expecting 41600 events.
[12:14:10.966] INFO: 41600 events read in total (2703ms).
[12:14:10.967] INFO: Test took 3934ms.
[12:14:10.999] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:11.723] INFO: Expecting 41600 events.
[12:14:14.960] INFO: 41600 events read in total (2710ms).
[12:14:14.961] INFO: Test took 3944ms.
[12:14:14.995] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:15.716] INFO: Expecting 41600 events.
[12:14:18.950] INFO: 41600 events read in total (2707ms).
[12:14:18.951] INFO: Test took 3937ms.
[12:14:18.985] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:19.711] INFO: Expecting 41600 events.
[12:14:22.952] INFO: 41600 events read in total (2714ms).
[12:14:22.953] INFO: Test took 3951ms.
[12:14:22.986] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:23.707] INFO: Expecting 41600 events.
[12:14:26.927] INFO: 41600 events read in total (2693ms).
[12:14:26.928] INFO: Test took 3923ms.
[12:14:26.963] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:27.684] INFO: Expecting 41600 events.
[12:14:30.912] INFO: 41600 events read in total (2702ms).
[12:14:30.912] INFO: Test took 3929ms.
[12:14:30.945] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:31.671] INFO: Expecting 41600 events.
[12:14:34.896] INFO: 41600 events read in total (2698ms).
[12:14:34.897] INFO: Test took 3934ms.
[12:14:34.930] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:35.658] INFO: Expecting 41600 events.
[12:14:38.892] INFO: 41600 events read in total (2707ms).
[12:14:38.893] INFO: Test took 3944ms.
[12:14:38.928] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:39.651] INFO: Expecting 41600 events.
[12:14:42.914] INFO: 41600 events read in total (2737ms).
[12:14:42.915] INFO: Test took 3970ms.
[12:14:42.949] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:43.673] INFO: Expecting 41600 events.
[12:14:46.929] INFO: 41600 events read in total (2729ms).
[12:14:46.930] INFO: Test took 3964ms.
[12:14:46.963] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:47.685] INFO: Expecting 41600 events.
[12:14:50.941] INFO: 41600 events read in total (2729ms).
[12:14:50.942] INFO: Test took 3961ms.
[12:14:50.975] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:51.700] INFO: Expecting 41600 events.
[12:14:54.994] INFO: 41600 events read in total (2767ms).
[12:14:54.995] INFO: Test took 4002ms.
[12:14:55.029] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:55.751] INFO: Expecting 41600 events.
[12:14:58.967] INFO: 41600 events read in total (2689ms).
[12:14:58.968] INFO: Test took 3921ms.
[12:14:58.001] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:59.725] INFO: Expecting 41600 events.
[12:15:02.849] INFO: 41600 events read in total (2597ms).
[12:15:02.850] INFO: Test took 3831ms.
[12:15:02.883] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:03.239] INFO: enter test to run
[12:15:07.142] INFO: test: HighRate no parameter change
[12:15:07.142] INFO: running: highrate
[12:15:07.144] INFO: ----------------------------------------------------------------------
[12:15:07.144] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:15:07.144] INFO: ----------------------------------------------------------------------
[12:15:07.758] INFO: Expecting 208000 events.
[12:15:19.859] INFO: 208000 events read in total (11575ms).
[12:15:19.862] INFO: Test took 12712ms.
[12:15:20.006] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:20.258] INFO: number of dead pixels (per ROC): 0 0 0 0 0 1 0 160 0 0 0 0 0 0 1 0
[12:15:20.271] INFO: number of red-efficiency pixels: 69 50 86 129 152 133 141 238 91 97 90 94 85 63 30 27
[12:15:20.271] INFO: number of X-ray hits detected: 61804 42028 63984 102907 108460 110281 109597 70490 70716 98632 97037 81419 83923 50955 21483 26549
[12:15:20.271] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:15:20.271] INFO: number of Vcal hits detected: 207931 207950 207914 207868 207845 207816 207853 199922 207909 207901 207904 207877 207911 207936 207921 207973
[12:15:20.271] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0 100.0 99.9 100.0 100.0 100.0 100.0
[12:15:20.271] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 96.1 100.0 100.0 100.0 99.9 100.0 100.0 100.0 100.0
[12:15:20.271] INFO: X-ray hit rate [MHz/cm2]: 18.1 12.3 18.8 30.2 31.8 32.3 32.1 20.7 20.7 28.9 28.4 23.9 24.6 14.9 6.3 7.8
[12:15:20.271] INFO: PixTestHighRate::doXPixelAlive() done
[12:15:20.318] INFO: PixTest:: pg_setup set to default.
[12:15:20.332] INFO: enter test to run
[12:15:41.358] INFO: test: HighRate no parameter change
[12:15:41.358] INFO: running: highrate
[12:15:41.360] INFO: ----------------------------------------------------------------------
[12:15:41.360] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:15:41.360] INFO: ----------------------------------------------------------------------
[12:15:41.983] INFO: Expecting 208000 events.
[12:15:55.709] INFO: 208000 events read in total (13199ms).
[12:15:55.714] INFO: Test took 14346ms.
[12:15:55.005] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:56.305] INFO: number of dead pixels (per ROC): 0 0 0 0 0 1 0 160 0 0 0 0 0 0 1 0
[12:15:56.305] INFO: number of red-efficiency pixels: 239 145 260 436 486 414 365 362 236 379 310 249 301 214 72 58
[12:15:56.305] INFO: number of X-ray hits detected: 128646 87553 133552 215103 225647 230378 227832 145715 148144 203834 201701 169388 175058 106312 44631 55461
[12:15:56.305] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:15:56.305] INFO: number of Vcal hits detected: 207743 207855 207720 207528 207482 207510 207611 199786 207748 207593 207673 207713 207691 207773 207876 207942
[12:15:56.305] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.8 99.9 99.9 99.9 99.9 100.0 100.0
[12:15:56.305] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 96.1 99.9 99.8 99.8 99.9 99.9 99.9 99.9 100.0
[12:15:56.305] INFO: X-ray hit rate [MHz/cm2]: 37.7 25.7 39.1 63.0 66.1 67.5 66.8 42.7 43.4 59.7 59.1 49.6 51.3 31.2 13.1 16.3
[12:15:56.305] INFO: PixTestHighRate::doXPixelAlive() done
[12:15:56.350] INFO: PixTest:: pg_setup set to default.
[12:15:56.359] INFO: enter test to run
[12:16:16.614] INFO: test: HighRate no parameter change
[12:16:16.614] INFO: running: highrate
[12:16:16.616] INFO: ----------------------------------------------------------------------
[12:16:16.616] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:16:16.616] INFO: ----------------------------------------------------------------------
[12:16:17.234] INFO: Expecting 208000 events.
[12:16:32.540] INFO: 208000 events read in total (14779ms).
[12:16:32.547] INFO: Test took 15923ms.
[12:16:32.997] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:16:33.344] INFO: number of dead pixels (per ROC): 0 0 0 0 0 1 0 160 0 0 0 0 0 0 1 0
[12:16:33.344] INFO: number of red-efficiency pixels: 479 263 544 1033 1132 849 780 615 569 853 710 494 543 453 99 111
[12:16:33.344] INFO: number of X-ray hits detected: 194840 132767 201495 325109 340796 346915 343640 222450 223183 307858 305962 255959 263958 161851 67690 84604
[12:16:33.344] 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:16:33.344] INFO: number of Vcal hits detected: 207404 207707 207328 206710 206591 206933 207048 199477 207361 206997 207183 207423 207389 207463 207849 207888
[12:16:33.344] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.4 99.4 99.6 99.6 99.8 99.7 99.6 99.6 99.7 99.7 99.8 100.0 99.9
[12:16:33.344] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.7 99.4 99.3 99.5 99.5 95.9 99.7 99.5 99.6 99.7 99.7 99.7 99.9 99.9
[12:16:33.344] INFO: X-ray hit rate [MHz/cm2]: 57.1 38.9 59.1 95.3 99.9 101.7 100.7 65.2 65.4 90.2 89.7 75.0 77.4 47.4 19.8 24.8
[12:16:33.344] INFO: PixTestHighRate::doXPixelAlive() done
[12:16:33.389] INFO: PixTest:: pg_setup set to default.
[12:16:33.403] INFO: enter test to run
[12:16:55.926] INFO: test: exit no parameter change
[12:16:57.106] QUIET: Connection to board 33 closed.
[12:16:57.400] INFO: pXar: this is the end, my friend