[16:02:01.021] INFO: *** Welcome to pxar ***
[16:02:01.021] INFO: *** Today: 2016/12/01
[16:02:02.509] INFO: *** Version: v1.9.0-818-g96727
[16:02:02.509] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//dacParameters35_C15.dat
[16:02:02.871] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:02:02.871] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//defaultMaskFile.dat
[16:02:02.877] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C15.dat
[16:02:03.302] INFO: clk: 4
[16:02:03.302] INFO: ctr: 4
[16:02:03.302] INFO: sda: 19
[16:02:03.302] INFO: tin: 9
[16:02:03.302] INFO: level: 15
[16:02:03.302] INFO: triggerdelay: 0
[16:02:03.302] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[16:02:03.303] INFO: Log level: INFO
[16:02:03.349] QUIET: Connection to board DTB_WREHUL opened.
[16:02:03.352] 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:
------------------------------------------------------
[16:02:03.355] INFO: RPC call hashes of host and DTB match: 398089610
[16:02:04.907] INFO: DUT info:
[16:02:04.907] INFO: The DUT currently contains the following objects:
[16:02:04.907] INFO: 2 TBM Cores tbm08c (2 ON)
[16:02:04.907] INFO: TBM Core alpha (0): 7 registers set
[16:02:04.907] INFO: TBM Core beta (1): 7 registers set
[16:02:04.907] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[16:02:04.907] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[16:02:04.907] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[16:02:04.907] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[16:02:04.907] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[16:02:04.907] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[16:02:04.907] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[16:02:04.907] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[16:02:04.907] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[16:02:04.907] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[16:02:04.907] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[16:02:04.907] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[16:02:04.907] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[16:02:04.907] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[16:02:04.907] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[16:02:04.907] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[16:02:04.907] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[16:02:05.456] INFO: enter 'restricted' command line mode
[16:02:05.456] INFO: enter test to run
[16:03:00.158] INFO: test: PixelAlive no parameter change
[16:03:00.158] INFO: running: pixelalive
[16:03:00.184] INFO: ----------------------------------------------------------------------
[16:03:00.184] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[16:03:00.184] INFO: ----------------------------------------------------------------------
[16:03:00.504] INFO: Expecting 41600 events.
[16:03:04.725] INFO: 41600 events read in total (3503ms).
[16:03:04.896] INFO: Test took 4709ms.
[16:03:04.903] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:03:05.232] INFO: PixTestAlive::aliveTest() done
[16:03:05.232] INFO: number of dead pixels (per ROC): 2 0 1 0 0 4 1 0 1 0 1 2 0 0 47 0
[16:03:05.266] INFO: enter test to run
[16:03:08.813] INFO: test: timing no parameter change
[16:03:08.814] INFO: running: timing
[16:03:08.817] INFO: ######################################################################
[16:03:08.817] INFO: PixTestTiming::doTest()
[16:03:08.817] INFO: ######################################################################
[16:03:08.817] INFO: ----------------------------------------------------------------------
[16:03:08.817] INFO: PixTestTiming::TBMPhaseScan()
[16:03:08.817] INFO: ----------------------------------------------------------------------
[16:07:49.153] INFO: TBM Phase Settings: 224
[16:07:49.153] INFO: 400MHz Phase: 0
[16:07:49.153] INFO: 160MHz Phase: 7
[16:07:49.153] INFO: Functional Phase Area: 3
[16:07:49.156] INFO: Test took 280339 ms.
[16:07:49.156] INFO: PixTestTiming::TBMPhaseScan() done.
[16:07:49.156] INFO: ----------------------------------------------------------------------
[16:07:49.156] INFO: PixTestTiming::ROCDelayScan()
[16:07:49.156] INFO: ----------------------------------------------------------------------
[16:10:59.705] INFO: ROC Delay Settings: 228
[16:10:59.705] INFO: ROC Header-Trailer/Token Delay: 11
[16:10:59.706] INFO: ROC Port 0 Delay: 4
[16:10:59.706] INFO: ROC Port 1 Delay: 4
[16:10:59.706] INFO: Functional ROC Area: 5
[16:10:59.709] INFO: Test took 190553 ms.
[16:10:59.709] INFO: PixTestTiming::ROCDelayScan() done.
[16:10:59.709] INFO: ----------------------------------------------------------------------
[16:10:59.709] INFO: PixTestTiming::TimingTest()
[16:10:59.709] INFO: ----------------------------------------------------------------------
[16:11:15.999] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:11:31.133] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:11:46.272] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:12:01.373] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:12:16.569] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:12:31.733] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:12:46.869] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:13:02.035] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:13:17.219] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:13:32.267] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:13:32.648] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:13:32.666] INFO: ----------------------------------------------------------------------
[16:13:32.666] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[16:13:32.666] INFO: ----------------------------------------------------------------------
[16:13:32.666] INFO: ----------------------------------------------------------------------
[16:13:32.666] INFO: Read back bit status: 1
[16:13:32.666] INFO: ----------------------------------------------------------------------
[16:13:32.666] INFO: ----------------------------------------------------------------------
[16:13:32.666] INFO: Timings are good!
[16:13:32.666] INFO: ----------------------------------------------------------------------
[16:13:32.666] INFO: Test took 152957 ms.
[16:13:32.666] INFO: PixTestTiming::TimingTest() done.
[16:13:32.684] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//tbmParameters_C0a.dat
[16:13:32.684] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:13:32.684] INFO: PixTestTiming::doTest took 623870 ms.
[16:13:32.684] INFO: PixTestTiming::doTest() done
[16:13:32.684] INFO: Write out TBMPhaseScan_0_V0
[16:13:32.684] INFO: Write out TBMPhaseScan_1_V0
[16:13:32.684] INFO: Write out CombinedTBMPhaseScan_V0
[16:13:32.735] INFO: Write out ROCDelayScan3_V0
[16:13:32.736] INFO: enter test to run
[16:15:35.257] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[16:15:35.257] INFO: running: highrate
[16:15:35.284] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[16:15:35.591] INFO: ----------------------------------------------------------------------
[16:15:35.592] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[16:15:35.592] INFO: ----------------------------------------------------------------------
[16:15:35.592] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[16:15:35.592] INFO: edge/corner pixel THR is adjusted
[16:15:35.592] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:15:36.571] INFO: Collecting data for 5 seconds...
[16:15:41.589] INFO: Done with hot pixel readout
[16:15:52.734] INFO: PixTest:: pg_setup set to default.
[16:15:52.735] INFO: 11 hot pixels found in step 0
[16:15:53.723] INFO: Collecting data for 5 seconds...
[16:15:58.741] INFO: Done with hot pixel readout
[16:16:09.916] INFO: PixTest:: pg_setup set to default.
[16:16:09.916] INFO: 11 hot pixels found in step 1
[16:16:10.904] INFO: Collecting data for 5 seconds...
[16:16:15.921] INFO: Done with hot pixel readout
[16:16:27.016] INFO: PixTest:: pg_setup set to default.
[16:16:27.017] INFO: 9 hot pixels found in step 2
[16:16:27.005] INFO: Collecting data for 5 seconds...
[16:16:33.021] INFO: Done with hot pixel readout
[16:16:44.539] INFO: PixTest:: pg_setup set to default.
[16:16:44.540] INFO: 7 hot pixels found in step 3
[16:16:45.528] INFO: Collecting data for 5 seconds...
[16:16:50.547] INFO: Done with hot pixel readout
[16:17:01.688] INFO: PixTest:: pg_setup set to default.
[16:17:01.689] INFO: 5 hot pixels found in step 4
[16:17:02.676] INFO: Collecting data for 5 seconds...
[16:17:07.694] INFO: Done with hot pixel readout
[16:17:18.942] INFO: PixTest:: pg_setup set to default.
[16:17:18.943] INFO: 7 hot pixels found in step 5
[16:17:19.931] INFO: Collecting data for 5 seconds...
[16:17:24.949] INFO: Done with hot pixel readout
[16:17:35.817] INFO: PixTest:: pg_setup set to default.
[16:17:35.818] INFO: 2 hot pixels found in step 6
[16:17:36.809] INFO: Collecting data for 5 seconds...
[16:17:41.827] INFO: Done with hot pixel readout
[16:17:53.147] INFO: PixTest:: pg_setup set to default.
[16:17:53.148] INFO: 5 hot pixels found in step 7
[16:17:54.135] INFO: Collecting data for 5 seconds...
[16:17:59.153] INFO: Done with hot pixel readout
[16:18:10.271] INFO: PixTest:: pg_setup set to default.
[16:18:10.272] INFO: 4 hot pixels found in step 8
[16:18:11.260] INFO: Collecting data for 5 seconds...
[16:18:16.278] INFO: Done with hot pixel readout
[16:18:27.651] INFO: PixTest:: pg_setup set to default.
[16:18:27.652] INFO: 3 hot pixels found in step 9
[16:18:28.638] INFO: Collecting data for 5 seconds...
[16:18:33.657] INFO: Done with hot pixel readout
[16:18:44.861] INFO: PixTest:: pg_setup set to default.
[16:18:44.862] INFO: 0 hot pixels found in step 10
[16:18:44.895] INFO: 0 hot pixels could not be trimmed and have been masked.
[16:18:44.898] INFO: PixTest::trimHotPixels() done
[16:18:44.899] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C0.dat
[16:18:44.904] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C1.dat
[16:18:44.910] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C2.dat
[16:18:44.916] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C3.dat
[16:18:44.957] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C4.dat
[16:18:44.965] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C5.dat
[16:18:44.970] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C6.dat
[16:18:44.976] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C7.dat
[16:18:44.981] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C8.dat
[16:18:44.987] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C9.dat
[16:18:44.992] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C10.dat
[16:18:44.998] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C11.dat
[16:18:44.003] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C12.dat
[16:18:45.009] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C13.dat
[16:18:45.014] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C14.dat
[16:18:45.019] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C15.dat
[16:18:45.025] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//defaultMaskFile.dat
[16:18:45.035] INFO: enter test to run
[16:19:37.687] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[16:19:37.687] INFO: running: highrate
[16:19:37.692] INFO: ----------------------------------------------------------------------
[16:19:37.692] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[16:19:37.692] INFO: ----------------------------------------------------------------------
[16:19:37.692] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[16:19:37.692] INFO: edge/corner pixel THR is adjusted
[16:19:37.692] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:19:38.648] INFO: Collecting data for 1 seconds...
[16:19:39.652] INFO: Done with hot pixel readout
[16:19:43.302] INFO: PixTest:: pg_setup set to default.
[16:19:43.302] INFO: 0 hot pixels found in step 0
[16:19:43.310] INFO: 0 hot pixels could not be trimmed and have been masked.
[16:19:43.403] INFO: PixTest::trimHotPixels() done
[16:19:43.403] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C0.dat
[16:19:43.425] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C1.dat
[16:19:43.437] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C2.dat
[16:19:43.445] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C3.dat
[16:19:43.451] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C4.dat
[16:19:43.456] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C5.dat
[16:19:43.462] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C6.dat
[16:19:43.467] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C7.dat
[16:19:43.473] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C8.dat
[16:19:43.478] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C9.dat
[16:19:43.506] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C10.dat
[16:19:43.511] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C11.dat
[16:19:43.517] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C12.dat
[16:19:43.522] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C13.dat
[16:19:43.527] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C14.dat
[16:19:43.533] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C15.dat
[16:19:43.538] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-4-12_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//defaultMaskFile.dat
[16:19:43.547] INFO: enter test to run
[16:20:10.255] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[16:20:10.255] INFO: running: xray
[16:20:10.256] INFO: ----------------------------------------------------------------------
[16:20:10.256] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:20:10.256] INFO: ----------------------------------------------------------------------
[16:20:11.240] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:20:23.441] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[16:20:52.758] INFO: Resuming triggers.
[16:21:04.960] INFO: run duration 24 seconds, buffer almost full (81%), pausing triggers.
[16:21:34.088] INFO: Resuming triggers.
[16:21:46.287] INFO: run duration 36 seconds, buffer almost full (81%), pausing triggers.
[16:22:15.606] INFO: Resuming triggers.
[16:22:27.802] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[16:22:57.971] INFO: Resuming triggers.
[16:23:10.170] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[16:23:39.258] INFO: Resuming triggers.
[16:23:51.457] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[16:24:21.429] INFO: Resuming triggers.
[16:24:33.627] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[16:25:03.875] INFO: Resuming triggers.
[16:25:16.073] INFO: run duration 97 seconds, buffer almost full (81%), pausing triggers.
[16:25:46.107] INFO: Resuming triggers.
[16:25:48.885] INFO: data taking finished, elapsed time: 100 seconds.
[16:25:55.963] INFO: PixTest:: pg_setup set to default.
[16:25:55.967] INFO: PixTestXray::doPhRun() done
[16:25:56.663] INFO: enter test to run
[16:26:45.388] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[16:26:45.388] INFO: running: xray
[16:26:45.400] INFO: ----------------------------------------------------------------------
[16:26:45.400] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:26:45.400] INFO: ----------------------------------------------------------------------
[16:26:46.378] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:26:53.871] INFO: run duration 7 seconds, buffer almost full (81%), pausing triggers.
[16:27:23.851] INFO: Resuming triggers.
[16:27:31.353] INFO: run duration 14 seconds, buffer almost full (81%), pausing triggers.
[16:28:01.434] INFO: Resuming triggers.
[16:28:08.933] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[16:28:38.996] INFO: Resuming triggers.
[16:28:46.499] INFO: run duration 29 seconds, buffer almost full (81%), pausing triggers.
[16:29:16.719] INFO: Resuming triggers.
[16:29:24.216] INFO: run duration 37 seconds, buffer almost full (81%), pausing triggers.
[16:29:54.144] INFO: Resuming triggers.
[16:30:01.643] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[16:30:31.879] INFO: Resuming triggers.
[16:30:39.377] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[16:31:09.565] INFO: Resuming triggers.
[16:31:17.064] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[16:31:47.223] INFO: Resuming triggers.
[16:31:54.721] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[16:32:25.298] INFO: Resuming triggers.
[16:32:32.820] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[16:33:03.322] INFO: Resuming triggers.
[16:33:10.819] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[16:33:41.579] INFO: Resuming triggers.
[16:33:49.080] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[16:34:19.888] INFO: Resuming triggers.
[16:34:27.385] INFO: run duration 97 seconds, buffer almost full (81%), pausing triggers.
[16:34:57.772] INFO: Resuming triggers.
[16:35:00.635] INFO: data taking finished, elapsed time: 100 seconds.
[16:35:12.656] INFO: PixTest:: pg_setup set to default.
[16:35:12.659] INFO: PixTestXray::doPhRun() done
[16:35:12.843] INFO: enter test to run
[16:36:05.888] INFO: test: HighRate no parameter change
[16:36:05.888] INFO: running: highrate
[16:36:05.909] INFO: ----------------------------------------------------------------------
[16:36:05.909] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[16:36:05.909] INFO: ----------------------------------------------------------------------
[16:36:06.132] INFO: Expecting 768 events.
[16:36:07.286] INFO: 768 events read in total (438ms).
[16:36:07.287] INFO: Test took 1292ms.
[16:36:08.089] INFO: Expecting 41600 events.
[16:36:11.099] INFO: 41600 events read in total (2483ms).
[16:36:11.100] INFO: Test took 3727ms.
[16:36:11.130] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:11.867] INFO: Expecting 41600 events.
[16:36:15.022] INFO: 41600 events read in total (2628ms).
[16:36:15.023] INFO: Test took 3877ms.
[16:36:15.053] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:15.788] INFO: Expecting 41600 events.
[16:36:19.039] INFO: 41600 events read in total (2724ms).
[16:36:19.040] INFO: Test took 3970ms.
[16:36:19.070] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:19.799] INFO: Expecting 41600 events.
[16:36:23.047] INFO: 41600 events read in total (2721ms).
[16:36:23.048] INFO: Test took 3962ms.
[16:36:23.078] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:23.802] INFO: Expecting 41600 events.
[16:36:27.008] INFO: 41600 events read in total (2679ms).
[16:36:27.009] INFO: Test took 3915ms.
[16:36:27.041] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:27.769] INFO: Expecting 41600 events.
[16:36:30.984] INFO: 41600 events read in total (2688ms).
[16:36:30.985] INFO: Test took 3928ms.
[16:36:31.016] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:31.746] INFO: Expecting 41600 events.
[16:36:34.951] INFO: 41600 events read in total (2678ms).
[16:36:34.952] INFO: Test took 3920ms.
[16:36:34.981] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:35.709] INFO: Expecting 41600 events.
[16:36:38.807] INFO: 41600 events read in total (2571ms).
[16:36:38.808] INFO: Test took 3811ms.
[16:36:38.838] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:39.568] INFO: Expecting 41600 events.
[16:36:42.658] INFO: 41600 events read in total (2564ms).
[16:36:42.659] INFO: Test took 3804ms.
[16:36:42.689] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:43.422] INFO: Expecting 41600 events.
[16:36:46.655] INFO: 41600 events read in total (2706ms).
[16:36:46.655] INFO: Test took 3949ms.
[16:36:46.686] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:47.416] INFO: Expecting 41600 events.
[16:36:50.567] INFO: 41600 events read in total (2625ms).
[16:36:50.567] INFO: Test took 3865ms.
[16:36:50.598] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:51.326] INFO: Expecting 41600 events.
[16:36:54.521] INFO: 41600 events read in total (2669ms).
[16:36:54.522] INFO: Test took 3906ms.
[16:36:54.556] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:55.279] INFO: Expecting 41600 events.
[16:36:58.352] INFO: 41600 events read in total (2546ms).
[16:36:58.353] INFO: Test took 3780ms.
[16:36:58.384] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:59.108] INFO: Expecting 41600 events.
[16:37:02.285] INFO: 41600 events read in total (2650ms).
[16:37:02.286] INFO: Test took 3886ms.
[16:37:02.316] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:37:03.043] INFO: Expecting 41600 events.
[16:37:06.272] INFO: 41600 events read in total (2702ms).
[16:37:06.273] INFO: Test took 3941ms.
[16:37:06.303] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:37:07.032] INFO: Expecting 41600 events.
[16:37:10.197] INFO: 41600 events read in total (2638ms).
[16:37:10.198] INFO: Test took 3878ms.
[16:37:10.228] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:37:10.959] INFO: Expecting 41600 events.
[16:37:14.193] INFO: 41600 events read in total (2707ms).
[16:37:14.194] INFO: Test took 3948ms.
[16:37:14.224] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:37:14.954] INFO: Expecting 41600 events.
[16:37:18.187] INFO: 41600 events read in total (2706ms).
[16:37:18.188] INFO: Test took 3947ms.
[16:37:18.220] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:37:18.948] INFO: Expecting 41600 events.
[16:37:22.159] INFO: 41600 events read in total (2684ms).
[16:37:22.160] INFO: Test took 3922ms.
[16:37:22.190] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:37:22.918] INFO: Expecting 41600 events.
[16:37:26.045] INFO: 41600 events read in total (2600ms).
[16:37:26.046] INFO: Test took 3840ms.
[16:37:26.075] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:37:26.438] INFO: enter test to run
[16:38:06.152] INFO: test: HighRate no parameter change
[16:38:06.152] INFO: running: highrate
[16:38:06.153] INFO: ----------------------------------------------------------------------
[16:38:06.153] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:38:06.153] INFO: ----------------------------------------------------------------------
[16:38:06.771] INFO: Expecting 208000 events.
[16:38:18.689] INFO: 208000 events read in total (11391ms).
[16:38:18.691] INFO: Test took 12530ms.
[16:38:18.815] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:38:19.062] INFO: number of dead pixels (per ROC): 2 0 1 0 0 4 1 0 1 0 1 2 0 0 47 0
[16:38:19.074] INFO: number of red-efficiency pixels: 73 61 70 101 107 106 106 82 82 105 117 76 86 56 104 5
[16:38:19.074] INFO: number of X-ray hits detected: 60216 39069 58144 84967 90923 92386 97705 65352 62198 83085 83414 72620 74289 45637 18043 3447
[16:38:19.074] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:38:19.074] INFO: number of Vcal hits detected: 207828 207937 207881 207895 207890 207691 207843 207916 207869 207892 207831 207826 207913 207943 205562 207995
[16:38:19.075] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0
[16:38:19.075] INFO: Vcal hit overall efficiency (%): 99.9 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 99.9 100.0 100.0 98.8 100.0
[16:38:19.075] INFO: X-ray hit rate [MHz/cm2]: 17.6 11.5 17.0 24.9 26.7 27.1 28.6 19.2 18.2 24.4 24.4 21.3 21.8 13.4 5.3 1.0
[16:38:19.075] INFO: PixTestHighRate::doXPixelAlive() done
[16:38:19.121] INFO: PixTest:: pg_setup set to default.
[16:38:19.138] INFO: enter test to run
[16:39:00.911] INFO: test: HighRate no parameter change
[16:39:00.911] INFO: running: highrate
[16:39:00.912] INFO: ----------------------------------------------------------------------
[16:39:00.912] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:39:00.912] INFO: ----------------------------------------------------------------------
[16:39:01.535] INFO: Expecting 208000 events.
[16:39:14.805] INFO: 208000 events read in total (12743ms).
[16:39:14.810] INFO: Test took 13889ms.
[16:39:15.061] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:15.348] INFO: number of dead pixels (per ROC): 2 0 1 0 0 4 1 0 1 0 1 2 0 0 47 0
[16:39:15.348] INFO: number of red-efficiency pixels: 205 131 165 329 329 294 394 242 184 310 316 263 234 162 136 8
[16:39:15.348] INFO: number of X-ray hits detected: 124881 81017 118859 176939 187650 192253 201863 134905 129467 171634 172629 149022 155123 93940 37350 7324
[16:39:15.348] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:39:15.348] INFO: number of Vcal hits detected: 207685 207864 207776 207643 207648 207493 207526 207742 207754 207663 207618 207630 207760 207832 205525 207992
[16:39:15.348] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.9 99.8 99.9 99.9 99.9 99.8 99.9 99.9 99.9 100.0 100.0
[16:39:15.348] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.8 99.8 99.8 99.9 99.9 98.8 100.0
[16:39:15.348] INFO: X-ray hit rate [MHz/cm2]: 36.6 23.7 34.8 51.9 55.0 56.4 59.2 39.5 37.9 50.3 50.6 43.7 45.5 27.5 10.9 2.1
[16:39:15.348] INFO: PixTestHighRate::doXPixelAlive() done
[16:39:15.394] INFO: PixTest:: pg_setup set to default.
[16:39:15.405] INFO: enter test to run
[16:39:51.679] INFO: test: HighRate no parameter change
[16:39:51.679] INFO: running: highrate
[16:39:51.680] INFO: ----------------------------------------------------------------------
[16:39:51.680] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:39:51.680] INFO: ----------------------------------------------------------------------
[16:39:52.299] INFO: Expecting 208000 events.
[16:40:06.998] INFO: 208000 events read in total (14172ms).
[16:40:06.004] INFO: Test took 15315ms.
[16:40:07.368] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:07.694] INFO: number of dead pixels (per ROC): 2 0 1 0 0 4 1 0 1 0 1 2 0 0 47 0
[16:40:07.694] INFO: number of red-efficiency pixels: 448 185 376 680 751 575 940 485 393 630 713 556 541 327 175 11
[16:40:07.694] INFO: number of X-ray hits detected: 188455 122397 179976 266924 281930 289212 304567 204176 195474 258033 259676 225529 233787 141642 56100 10759
[16:40:07.694] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:40:07.694] INFO: number of Vcal hits detected: 207370 207800 207521 207205 207157 207132 206827 207402 207503 207281 207148 207286 207397 207632 205484 207989
[16:40:07.694] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.7 99.6 99.7 99.5 99.8 99.8 99.7 99.6 99.7 99.7 99.8 99.9 100.0
[16:40:07.694] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.8 99.6 99.6 99.6 99.4 99.7 99.8 99.7 99.6 99.7 99.7 99.8 98.8 100.0
[16:40:07.694] INFO: X-ray hit rate [MHz/cm2]: 55.2 35.9 52.8 78.2 82.6 84.8 89.3 59.8 57.3 75.6 76.1 66.1 68.5 41.5 16.4 3.2
[16:40:07.694] INFO: PixTestHighRate::doXPixelAlive() done
[16:40:07.740] INFO: PixTest:: pg_setup set to default.
[16:40:07.756] INFO: enter test to run
[16:40:28.918] INFO: test: exit no parameter change
[16:40:30.922] QUIET: Connection to board 30 closed.
[16:40:31.238] INFO: pXar: this is the end, my friend