[10:15:52.591] INFO: *** Welcome to pxar ***
[10:15:52.591] INFO: *** Today: 2016/11/16
[10:15:55.125] INFO: *** Version: v1.9.0-818-g96727
[10:15:55.125] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//dacParameters35_C15.dat
[10:15:55.490] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:15:55.490] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//defaultMaskFile.dat
[10:15:55.495] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C15.dat
[10:15:55.781] INFO: clk: 4
[10:15:55.781] INFO: ctr: 4
[10:15:55.781] INFO: sda: 19
[10:15:55.781] INFO: tin: 9
[10:15:55.781] INFO: level: 15
[10:15:55.781] INFO: triggerdelay: 0
[10:15:55.785] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[10:15:55.785] INFO: Log level: INFO
[10:15:55.806] QUIET: Connection to board DTB_WREHUL opened.
[10:15:55.809] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 30
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREHUL
MAC address: 40D85511801E
Hostname: pixelDTB030
Comment:
------------------------------------------------------
[10:15:55.812] INFO: RPC call hashes of host and DTB match: 398089610
[10:15:57.343] INFO: DUT info:
[10:15:57.343] INFO: The DUT currently contains the following objects:
[10:15:57.343] INFO: 2 TBM Cores tbm08c (2 ON)
[10:15:57.343] INFO: TBM Core alpha (0): 7 registers set
[10:15:57.343] INFO: TBM Core beta (1): 7 registers set
[10:15:57.344] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[10:15:57.344] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:57.344] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:57.344] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:57.344] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:57.344] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:57.344] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:57.344] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:57.344] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:57.344] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:57.344] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:57.344] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:57.344] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:57.344] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:57.344] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:57.344] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:57.344] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:57.851] INFO: enter 'restricted' command line mode
[10:15:57.851] INFO: enter test to run
[10:16:01.338] INFO: test: PixelAlive no parameter change
[10:16:01.338] INFO: running: pixelalive
[10:16:01.406] INFO: ----------------------------------------------------------------------
[10:16:01.406] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[10:16:01.406] INFO: ----------------------------------------------------------------------
[10:16:01.734] INFO: Expecting 41600 events.
[10:16:06.065] INFO: 41600 events read in total (3613ms).
[10:16:06.236] INFO: Test took 4827ms.
[10:16:06.247] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:16:07.024] INFO: PixTestAlive::aliveTest() done
[10:16:07.024] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 5 0
[10:16:07.249] INFO: enter test to run
[10:16:10.553] INFO: test: timing no parameter change
[10:16:10.553] INFO: running: timing
[10:16:10.557] INFO: ######################################################################
[10:16:10.557] INFO: PixTestTiming::doTest()
[10:16:10.557] INFO: ######################################################################
[10:16:10.557] INFO: ----------------------------------------------------------------------
[10:16:10.557] INFO: PixTestTiming::TBMPhaseScan()
[10:16:10.557] INFO: ----------------------------------------------------------------------
[10:21:12.849] INFO: TBM Phase Settings: 232
[10:21:12.849] INFO: 400MHz Phase: 2
[10:21:12.849] INFO: 160MHz Phase: 7
[10:21:12.849] INFO: Functional Phase Area: 3
[10:21:12.876] INFO: Test took 302319 ms.
[10:21:12.877] INFO: PixTestTiming::TBMPhaseScan() done.
[10:21:12.877] INFO: ----------------------------------------------------------------------
[10:21:12.877] INFO: PixTestTiming::ROCDelayScan()
[10:21:12.877] INFO: ----------------------------------------------------------------------
[10:23:15.341] INFO: ROC Delay Settings: 228
[10:23:15.341] INFO: ROC Header-Trailer/Token Delay: 11
[10:23:15.341] INFO: ROC Port 0 Delay: 4
[10:23:15.341] INFO: ROC Port 1 Delay: 4
[10:23:15.341] INFO: Functional ROC Area: 4
[10:23:15.344] INFO: Test took 122467 ms.
[10:23:15.344] INFO: PixTestTiming::ROCDelayScan() done.
[10:23:15.344] INFO: ----------------------------------------------------------------------
[10:23:15.344] INFO: PixTestTiming::TimingTest()
[10:23:15.344] INFO: ----------------------------------------------------------------------
[10:23:31.466] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:23:46.438] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:24:01.411] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:24:16.379] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:24:31.355] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:24:46.326] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:25:01.279] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:25:16.233] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:25:31.205] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:25:46.168] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:25:46.546] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:25:46.563] INFO: ----------------------------------------------------------------------
[10:25:46.563] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[10:25:46.563] INFO: ----------------------------------------------------------------------
[10:25:46.563] INFO: ----------------------------------------------------------------------
[10:25:46.564] INFO: Read back bit status: 1
[10:25:46.564] INFO: ----------------------------------------------------------------------
[10:25:46.564] INFO: ----------------------------------------------------------------------
[10:25:46.564] INFO: Timings are good!
[10:25:46.564] INFO: ----------------------------------------------------------------------
[10:25:46.564] INFO: Test took 151220 ms.
[10:25:46.564] INFO: PixTestTiming::TimingTest() done.
[10:25:46.573] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//tbmParameters_C0a.dat
[10:25:46.592] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:25:46.592] INFO: PixTestTiming::doTest took 576038 ms.
[10:25:46.592] INFO: PixTestTiming::doTest() done
[10:25:46.592] INFO: Write out TBMPhaseScan_0_V0
[10:25:46.592] INFO: Write out TBMPhaseScan_1_V0
[10:25:46.592] INFO: Write out CombinedTBMPhaseScan_V0
[10:25:46.624] INFO: Write out ROCDelayScan3_V0
[10:25:46.624] INFO: enter test to run
[10:27:01.941] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[10:27:01.941] INFO: running: highrate
[10:27:01.949] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[10:27:02.229] INFO: ----------------------------------------------------------------------
[10:27:02.229] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[10:27:02.229] INFO: ----------------------------------------------------------------------
[10:27:02.229] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[10:27:02.229] INFO: edge/corner pixel THR is adjusted
[10:27:02.229] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:27:03.203] INFO: Collecting data for 5 seconds...
[10:27:08.221] INFO: Done with hot pixel readout
[10:27:19.538] INFO: PixTest:: pg_setup set to default.
[10:27:19.539] INFO: 9 hot pixels found in step 0
[10:27:20.528] INFO: Collecting data for 5 seconds...
[10:27:25.544] INFO: Done with hot pixel readout
[10:27:36.614] INFO: PixTest:: pg_setup set to default.
[10:27:36.615] INFO: 7 hot pixels found in step 1
[10:27:37.604] INFO: Collecting data for 5 seconds...
[10:27:42.621] INFO: Done with hot pixel readout
[10:27:53.871] INFO: PixTest:: pg_setup set to default.
[10:27:53.872] INFO: 9 hot pixels found in step 2
[10:27:54.863] INFO: Collecting data for 5 seconds...
[10:27:59.879] INFO: Done with hot pixel readout
[10:28:11.300] INFO: PixTest:: pg_setup set to default.
[10:28:11.301] INFO: 11 hot pixels found in step 3
[10:28:12.291] INFO: Collecting data for 5 seconds...
[10:28:17.309] INFO: Done with hot pixel readout
[10:28:28.666] INFO: PixTest:: pg_setup set to default.


[10:28:28.667] INFO: 7 hot pixels found in step 4
[10:28:29.656] INFO: Collecting data for 5 seconds...
[10:28:34.674] INFO: Done with hot pixel readout
[10:28:45.657] INFO: PixTest:: pg_setup set to default.

[10:28:45.658] INFO: 8 hot pixels found in step 5
[10:28:46.649] INFO: Collecting data for 5 seconds...
[10:28:51.666] INFO: Done with hot pixel readout
[10:29:02.900] INFO: PixTest:: pg_setup set to default.



[10:29:02.901] INFO: 11 hot pixels found in step 6
[10:29:03.891] INFO: Collecting data for 5 seconds...
[10:29:08.908] INFO: Done with hot pixel readout
[10:29:20.043] INFO: PixTest:: pg_setup set to default.




[10:29:20.044] INFO: 7 hot pixels found in step 7
[10:29:21.036] INFO: Collecting data for 5 seconds...
[10:29:26.054] INFO: Done with hot pixel readout
[10:29:37.205] INFO: PixTest:: pg_setup set to default.





[10:29:37.206] INFO: 7 hot pixels found in step 8
[10:29:38.197] INFO: Collecting data for 5 seconds...
[10:29:43.215] INFO: Done with hot pixel readout
[10:29:54.615] INFO: PixTest:: pg_setup set to default.



[10:29:54.616] INFO: 5 hot pixels found in step 9
[10:29:55.605] INFO: Collecting data for 5 seconds...
[10:30:00.624] INFO: Done with hot pixel readout
[10:30:11.982] INFO: PixTest:: pg_setup set to default.




[10:30:11.983] INFO: 4 hot pixels found in step 10
[10:30:12.017] INFO: 4 hot pixels could not be trimmed and have been masked.
[10:30:12.020] INFO: PixTest::trimHotPixels() done
[10:30:12.021] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C0.dat
[10:30:12.040] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C1.dat
[10:30:12.047] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C2.dat
[10:30:12.053] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C3.dat
[10:30:12.059] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C4.dat
[10:30:12.064] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C5.dat
[10:30:12.070] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C6.dat
[10:30:12.075] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C7.dat
[10:30:12.080] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C8.dat
[10:30:12.086] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C9.dat
[10:30:12.091] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C10.dat
[10:30:12.097] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C11.dat
[10:30:12.102] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C12.dat
[10:30:12.107] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C13.dat
[10:30:12.113] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C14.dat
[10:30:12.118] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C15.dat
[10:30:12.124] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//defaultMaskFile.dat
[10:30:12.134] INFO: enter test to run
[10:30:39.172] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[10:30:39.172] INFO: running: highrate
[10:30:39.176] INFO: ----------------------------------------------------------------------
[10:30:39.176] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[10:30:39.176] INFO: ----------------------------------------------------------------------
[10:30:39.176] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[10:30:39.176] INFO: edge/corner pixel THR is adjusted
[10:30:39.176] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:30:40.133] INFO: Collecting data for 1 seconds...
[10:30:41.137] INFO: Done with hot pixel readout
[10:30:44.363] INFO: PixTest:: pg_setup set to default.
[10:30:44.364] INFO: 0 hot pixels found in step 0
[10:30:44.370] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:30:44.466] INFO: PixTest::trimHotPixels() done
[10:30:44.466] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C0.dat
[10:30:44.474] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C1.dat
[10:30:44.482] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C2.dat
[10:30:44.489] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C3.dat
[10:30:44.495] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C4.dat
[10:30:44.500] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C5.dat
[10:30:44.505] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C6.dat
[10:30:44.511] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C7.dat
[10:30:44.516] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C8.dat
[10:30:44.521] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C9.dat
[10:30:44.527] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C10.dat
[10:30:44.532] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C11.dat
[10:30:44.538] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C12.dat
[10:30:44.543] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C13.dat
[10:30:44.548] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C14.dat
[10:30:44.554] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C15.dat
[10:30:44.559] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-5-01_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//defaultMaskFile.dat
[10:30:44.568] INFO: enter test to run
[10:31:24.107] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[10:31:24.108] INFO: running: xray
[10:31:24.109] INFO: ----------------------------------------------------------------------
[10:31:24.109] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:31:24.109] INFO: ----------------------------------------------------------------------
[10:31:25.088] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:31:37.151] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[10:32:07.170] INFO: Resuming triggers.
[10:32:19.232] INFO: run duration 24 seconds, buffer almost full (81%), pausing triggers.
[10:32:49.113] INFO: Resuming triggers.
[10:33:01.172] INFO: run duration 36 seconds, buffer almost full (81%), pausing triggers.
[10:33:31.517] INFO: Resuming triggers.
[10:33:43.575] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[10:34:13.849] INFO: Resuming triggers.
[10:34:25.914] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[10:34:55.652] INFO: Resuming triggers.
[10:35:07.713] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[10:35:37.022] INFO: Resuming triggers.
[10:35:49.089] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[10:36:18.366] INFO: Resuming triggers.
[10:36:30.429] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[10:36:59.908] INFO: Resuming triggers.
[10:37:03.766] INFO: data taking finished, elapsed time: 100 seconds.
[10:37:13.417] INFO: PixTest:: pg_setup set to default.
[10:37:13.420] INFO: PixTestXray::doPhRun() done
[10:37:13.618] INFO: enter test to run
[10:38:02.665] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[10:38:02.665] INFO: running: xray
[10:38:02.666] INFO: ----------------------------------------------------------------------
[10:38:02.666] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:38:02.666] INFO: ----------------------------------------------------------------------
[10:38:03.630] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:38:10.944] INFO: run duration 7 seconds, buffer almost full (81%), pausing triggers.
[10:38:41.241] INFO: Resuming triggers.
[10:38:48.554] INFO: run duration 14 seconds, buffer almost full (81%), pausing triggers.
[10:39:19.165] INFO: Resuming triggers.
[10:39:26.477] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[10:39:56.816] INFO: Resuming triggers.
[10:40:04.130] INFO: run duration 29 seconds, buffer almost full (81%), pausing triggers.
[10:40:34.411] INFO: Resuming triggers.
[10:40:41.729] INFO: run duration 36 seconds, buffer almost full (81%), pausing triggers.
[10:41:11.955] INFO: Resuming triggers.
[10:41:19.269] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[10:41:50.175] INFO: Resuming triggers.
[10:41:57.490] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[10:42:28.708] INFO: Resuming triggers.
[10:42:36.018] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[10:43:06.810] INFO: Resuming triggers.
[10:43:14.121] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[10:43:45.488] INFO: Resuming triggers.
[10:43:52.802] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[10:44:23.833] INFO: Resuming triggers.
[10:44:31.146] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[10:45:01.882] INFO: Resuming triggers.
[10:45:09.195] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[10:45:40.857] INFO: Resuming triggers.
[10:45:48.168] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[10:46:19.596] INFO: Resuming triggers.
[10:46:24.875] INFO: data taking finished, elapsed time: 100 seconds.
[10:46:47.650] INFO: PixTest:: pg_setup set to default.
[10:46:47.653] INFO: PixTestXray::doPhRun() done
[10:46:47.805] INFO: enter test to run
[10:47:29.157] INFO: test: HighRate no parameter change
[10:47:29.157] INFO: running: highrate
[10:47:29.172] INFO: ----------------------------------------------------------------------
[10:47:29.172] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[10:47:29.172] INFO: ----------------------------------------------------------------------
[10:47:29.329] INFO: Expecting 768 events.
[10:47:30.463] INFO: 768 events read in total (418ms).
[10:47:30.464] INFO: Test took 1268ms.
[10:47:31.266] INFO: Expecting 41600 events.
[10:47:34.375] INFO: 41600 events read in total (2582ms).
[10:47:34.376] INFO: Test took 3772ms.
[10:47:34.414] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:47:35.125] INFO: Expecting 41600 events.
[10:47:38.278] INFO: 41600 events read in total (2626ms).
[10:47:38.279] INFO: Test took 3847ms.
[10:47:38.310] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:47:39.042] INFO: Expecting 41600 events.
[10:47:42.360] INFO: 41600 events read in total (2791ms).
[10:47:42.361] INFO: Test took 4035ms.
[10:47:42.391] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:47:43.124] INFO: Expecting 41600 events.
[10:47:46.332] INFO: 41600 events read in total (2682ms).
[10:47:46.333] INFO: Test took 3925ms.
[10:47:46.363] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:47:47.093] INFO: Expecting 41600 events.
[10:47:50.325] INFO: 41600 events read in total (2705ms).
[10:47:50.326] INFO: Test took 3947ms.
[10:47:50.358] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:47:51.085] INFO: Expecting 41600 events.
[10:47:54.428] INFO: 41600 events read in total (2817ms).
[10:47:54.429] INFO: Test took 4054ms.
[10:47:54.467] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:47:55.176] INFO: Expecting 41600 events.
[10:47:58.390] INFO: 41600 events read in total (2687ms).
[10:47:58.391] INFO: Test took 3908ms.
[10:47:58.421] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:47:59.151] INFO: Expecting 41600 events.
[10:48:02.348] INFO: 41600 events read in total (2670ms).
[10:48:02.349] INFO: Test took 3912ms.
[10:48:02.379] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:48:03.108] INFO: Expecting 41600 events.
[10:48:06.308] INFO: 41600 events read in total (2673ms).
[10:48:06.309] INFO: Test took 3913ms.
[10:48:06.340] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:48:07.070] INFO: Expecting 41600 events.
[10:48:10.273] INFO: 41600 events read in total (2676ms).
[10:48:10.274] INFO: Test took 3917ms.
[10:48:10.304] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:48:11.037] INFO: Expecting 41600 events.
[10:48:14.242] INFO: 41600 events read in total (2679ms).
[10:48:14.243] INFO: Test took 3921ms.
[10:48:14.273] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:48:14.005] INFO: Expecting 41600 events.
[10:48:18.225] INFO: 41600 events read in total (2693ms).
[10:48:18.226] INFO: Test took 3935ms.
[10:48:18.256] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:48:18.987] INFO: Expecting 41600 events.
[10:48:22.197] INFO: 41600 events read in total (2683ms).
[10:48:22.198] INFO: Test took 3924ms.
[10:48:22.228] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:48:22.958] INFO: Expecting 41600 events.
[10:48:26.156] INFO: 41600 events read in total (2671ms).
[10:48:26.156] INFO: Test took 3910ms.
[10:48:26.186] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:48:26.916] INFO: Expecting 41600 events.
[10:48:30.116] INFO: 41600 events read in total (2673ms).
[10:48:30.117] INFO: Test took 3914ms.
[10:48:30.147] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:48:30.875] INFO: Expecting 41600 events.
[10:48:34.076] INFO: 41600 events read in total (2674ms).
[10:48:34.077] INFO: Test took 3914ms.
[10:48:34.108] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:48:34.836] INFO: Expecting 41600 events.
[10:48:38.028] INFO: 41600 events read in total (2665ms).
[10:48:38.029] INFO: Test took 3904ms.
[10:48:38.059] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:48:38.793] INFO: Expecting 41600 events.
[10:48:41.998] INFO: 41600 events read in total (2678ms).
[10:48:41.999] INFO: Test took 3921ms.
[10:48:42.030] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:48:42.763] INFO: Expecting 41600 events.
[10:48:45.967] INFO: 41600 events read in total (2677ms).
[10:48:45.968] INFO: Test took 3921ms.
[10:48:45.999] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:48:46.728] INFO: Expecting 41600 events.
[10:48:49.820] INFO: 41600 events read in total (2565ms).
[10:48:49.821] INFO: Test took 3804ms.
[10:48:49.851] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:48:50.228] INFO: enter test to run
[10:49:00.436] INFO: test: HighRate no parameter change
[10:49:00.436] INFO: running: highrate
[10:49:00.437] INFO: ----------------------------------------------------------------------
[10:49:00.437] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:49:00.437] INFO: ----------------------------------------------------------------------
[10:49:01.051] INFO: Expecting 208000 events.
[10:49:12.724] INFO: 208000 events read in total (11146ms).
[10:49:12.726] INFO: Test took 12282ms.
[10:49:12.853] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:49:13.100] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 4 0
[10:49:13.100] INFO: number of red-efficiency pixels: 72 42 74 102 101 109 118 79 72 116 92 91 81 50 28 19
[10:49:13.100] INFO: number of X-ray hits detected: 61088 36467 55841 83001 90670 98992 97228 67754 67349 90624 89602 74601 76926 45843 18321 21512
[10:49:13.100] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:49:13.100] INFO: number of Vcal hits detected: 207926 207956 207926 207896 207898 207888 207880 207917 207926 207879 207908 207908 207918 207950 207728 207980
[10:49:13.100] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 100.0 99.9 99.9 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0 100.0
[10:49:13.100] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 100.0 100.0 99.9 99.9 100.0 100.0 99.9 100.0 100.0 100.0 100.0 99.9 100.0
[10:49:13.100] INFO: X-ray hit rate [MHz/cm2]: 17.9 10.7 16.4 24.3 26.6 29.0 28.5 19.9 19.7 26.6 26.3 21.9 22.5 13.4 5.4 6.3
[10:49:13.100] INFO: PixTestHighRate::doXPixelAlive() done
[10:49:13.153] INFO: PixTest:: pg_setup set to default.
[10:49:13.168] INFO: enter test to run
[10:49:36.916] INFO: test: HighRate no parameter change
[10:49:36.916] INFO: running: highrate
[10:49:36.917] INFO: ----------------------------------------------------------------------
[10:49:36.917] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:49:36.917] INFO: ----------------------------------------------------------------------
[10:49:37.534] INFO: Expecting 208000 events.
[10:49:50.656] INFO: 208000 events read in total (12595ms).
[10:49:50.660] INFO: Test took 13734ms.
[10:49:50.911] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:49:51.198] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 4 0
[10:49:51.198] INFO: number of red-efficiency pixels: 210 138 194 337 286 359 427 240 192 308 281 210 225 143 56 46
[10:49:51.198] INFO: number of X-ray hits detected: 126315 75820 116938 173937 188830 205918 202392 139970 140038 189337 185706 154249 160742 94740 37693 44588
[10:49:51.198] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:49:51.198] INFO: number of Vcal hits detected: 207781 207856 207789 207642 207698 207589 207539 207754 207801 207662 207708 207782 207771 207844 207700 207953
[10:49:51.198] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.9 99.8 99.8 99.9 99.9 99.8 99.9 99.9 99.9 99.9 100.0 100.0
[10:49:51.198] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.9 99.8 99.8 99.9 99.9 99.8 99.9 99.9 99.9 99.9 99.9 100.0
[10:49:51.198] INFO: X-ray hit rate [MHz/cm2]: 37.0 22.2 34.3 51.0 55.3 60.4 59.3 41.0 41.0 55.5 54.4 45.2 47.1 27.8 11.0 13.1
[10:49:51.198] INFO: PixTestHighRate::doXPixelAlive() done
[10:49:51.245] INFO: PixTest:: pg_setup set to default.
[10:49:51.258] INFO: enter test to run
[10:50:21.196] INFO: test: HighRate no parameter change
[10:50:21.196] INFO: running: highrate
[10:50:21.197] INFO: ----------------------------------------------------------------------
[10:50:21.197] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:50:21.197] INFO: ----------------------------------------------------------------------
[10:50:21.812] INFO: Expecting 208000 events.
[10:50:36.568] INFO: 208000 events read in total (14230ms).
[10:50:36.575] INFO: Test took 15368ms.
[10:50:36.960] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:50:37.289] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 4 0
[10:50:37.289] INFO: number of red-efficiency pixels: 370 230 470 707 560 683 964 506 442 626 613 409 422 331 73 86
[10:50:37.289] INFO: number of X-ray hits detected: 189977 113773 175411 259794 282767 309323 303574 212027 210996 283653 281076 231049 239507 143272 56462 67262
[10:50:37.289] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:50:37.289] INFO: number of Vcal hits detected: 207579 207757 207431 207201 207373 207173 206841 207405 207509 207276 207319 207559 207534 207635 207679 207913
[10:50:37.289] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.7 99.7 99.6 99.5 99.7 99.8 99.7 99.7 99.8 99.8 99.8 100.0 100.0
[10:50:37.289] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.6 99.7 99.6 99.4 99.7 99.8 99.7 99.7 99.8 99.8 99.8 99.8 100.0
[10:50:37.289] INFO: X-ray hit rate [MHz/cm2]: 55.7 33.3 51.4 76.1 82.9 90.7 89.0 62.1 61.8 83.1 82.4 67.7 70.2 42.0 16.5 19.7
[10:50:37.289] INFO: PixTestHighRate::doXPixelAlive() done
[10:50:37.341] INFO: PixTest:: pg_setup set to default.
[10:50:37.353] INFO: enter test to run
[10:51:10.395] INFO: test: exit no parameter change
[10:51:10.895] QUIET: Connection to board 30 closed.
[10:51:11.033] INFO: pXar: this is the end, my friend