[15:18:09.623] INFO: *** Welcome to pxar ***
[15:18:09.623] INFO: *** Today: 2016/12/01
[15:18:12.514] INFO: *** Version: v1.9.0-818-g96727
[15:18:12.514] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//dacParameters35_C15.dat
[15:18:12.621] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:18:12.621] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//defaultMaskFile.dat
[15:18:12.626] INFO: MASKED Roc 0 col/row: 0 6
[15:18:12.626] INFO: MASKED Roc 0 col/row: 1 5
[15:18:12.626] INFO: MASKED Roc 2 col/row: 50 48
[15:18:12.626] INFO: MASKED Roc 3 col/row: 12 50
[15:18:12.626] INFO: MASKED Roc 10 col/row: 4 52
[15:18:12.626] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C15.dat
[15:18:12.626] INFO: masking Roc 0 col/row: 0 6
[15:18:12.626] INFO: masking Roc 0 col/row: 1 5
[15:18:12.664] INFO: masking Roc 2 col/row: 50 48
[15:18:12.674] INFO: masking Roc 3 col/row: 12 50
[15:18:12.709] INFO: masking Roc 10 col/row: 4 52
[15:18:12.766] INFO: clk: 4
[15:18:12.767] INFO: ctr: 4
[15:18:12.767] INFO: sda: 19
[15:18:12.767] INFO: tin: 9
[15:18:12.767] INFO: level: 15
[15:18:12.767] INFO: triggerdelay: 0
[15:18:12.767] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[15:18:12.767] INFO: Log level: INFO
[15:18:12.783] QUIET: Connection to board DTB_WREHUL opened.
[15:18:12.787] 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:
------------------------------------------------------
[15:18:12.789] INFO: RPC call hashes of host and DTB match: 398089610
[15:18:14.335] INFO: DUT info:
[15:18:14.335] INFO: The DUT currently contains the following objects:
[15:18:14.335] INFO: 2 TBM Cores tbm08c (2 ON)
[15:18:14.335] INFO: TBM Core alpha (0): 7 registers set
[15:18:14.335] INFO: TBM Core beta (1): 7 registers set
[15:18:14.335] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:18:14.335] INFO: ROC 0: 19 DACs set, Pixels: 2 masked, 0 active.
[15:18:14.335] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:18:14.335] INFO: ROC 2: 19 DACs set, Pixels: 1 masked, 0 active.
[15:18:14.335] INFO: ROC 3: 19 DACs set, Pixels: 1 masked, 0 active.
[15:18:14.335] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:18:14.335] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:18:14.335] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:18:14.335] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:18:14.335] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:18:14.335] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:18:14.335] INFO: ROC 10: 19 DACs set, Pixels: 1 masked, 0 active.
[15:18:14.335] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:18:14.335] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:18:14.335] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:18:14.335] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:18:14.335] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:18:14.793] INFO: enter 'restricted' command line mode
[15:18:14.793] INFO: enter test to run
[15:18:21.423] INFO: test: PixelAlive no parameter change
[15:18:21.424] INFO: running: pixelalive
[15:18:21.480] INFO: ----------------------------------------------------------------------
[15:18:21.480] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[15:18:21.480] INFO: ----------------------------------------------------------------------
[15:18:21.484] INFO: ROC 0 masking pixel 0/6
[15:18:21.484] INFO: ROC 0 masking pixel 1/5
[15:18:21.484] INFO: ROC 2 masking pixel 50/48
[15:18:21.484] INFO: ROC 3 masking pixel 12/50
[15:18:21.485] INFO: ROC 10 masking pixel 4/52
[15:18:21.805] INFO: Expecting 41600 events.
[15:18:26.145] INFO: 41600 events read in total (3622ms).
[15:18:26.308] INFO: Test took 4823ms.
[15:18:26.321] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:18:26.993] INFO: PixTestAlive::aliveTest() done
[15:18:26.993] INFO: number of dead pixels (per ROC): 2 0 1 1 0 0 3 0 0 1 1 0 0 0 0 1
[15:18:26.993] INFO: ROC 0 masking pixel 0/6
[15:18:26.993] INFO: ROC 0 masking pixel 1/5
[15:18:26.993] INFO: ROC 2 masking pixel 50/48
[15:18:26.993] INFO: ROC 3 masking pixel 12/50
[15:18:26.993] INFO: ROC 10 masking pixel 4/52
[15:18:27.237] INFO: enter test to run
[15:18:42.536] INFO: test: timing no parameter change
[15:18:42.536] INFO: running: timing
[15:18:42.539] INFO: ######################################################################
[15:18:42.539] INFO: PixTestTiming::doTest()
[15:18:42.539] INFO: ######################################################################
[15:18:42.539] INFO: ----------------------------------------------------------------------
[15:18:42.539] INFO: PixTestTiming::TBMPhaseScan()
[15:18:42.540] INFO: ----------------------------------------------------------------------
[15:23:04.383] INFO: TBM Phase Settings: 244
[15:23:04.383] INFO: 400MHz Phase: 5
[15:23:04.383] INFO: 160MHz Phase: 7
[15:23:04.383] INFO: Functional Phase Area: 4
[15:23:04.403] INFO: Test took 261864 ms.
[15:23:04.403] INFO: PixTestTiming::TBMPhaseScan() done.
[15:23:04.403] INFO: ROC 0 masking pixel 0/6
[15:23:04.403] INFO: ROC 0 masking pixel 1/5
[15:23:04.403] INFO: ROC 2 masking pixel 50/48
[15:23:04.404] INFO: ROC 3 masking pixel 12/50
[15:23:04.404] INFO: ROC 10 masking pixel 4/52
[15:23:04.404] INFO: ----------------------------------------------------------------------
[15:23:04.404] INFO: PixTestTiming::ROCDelayScan()
[15:23:04.404] INFO: ----------------------------------------------------------------------
[15:25:12.324] INFO: ROC Delay Settings: 228
[15:25:12.325] INFO: ROC Header-Trailer/Token Delay: 11
[15:25:12.325] INFO: ROC Port 0 Delay: 4
[15:25:12.325] INFO: ROC Port 1 Delay: 4
[15:25:12.325] INFO: Functional ROC Area: 5
[15:25:12.328] INFO: Test took 127924 ms.
[15:25:12.328] INFO: PixTestTiming::ROCDelayScan() done.
[15:25:12.328] INFO: ROC 0 masking pixel 0/6
[15:25:12.328] INFO: ROC 0 masking pixel 1/5
[15:25:12.328] INFO: ROC 2 masking pixel 50/48
[15:25:12.328] INFO: ROC 3 masking pixel 12/50
[15:25:12.328] INFO: ROC 10 masking pixel 4/52
[15:25:12.328] INFO: ----------------------------------------------------------------------
[15:25:12.328] INFO: PixTestTiming::TimingTest()
[15:25:12.328] INFO: ----------------------------------------------------------------------
[15:25:28.487] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:25:43.445] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:25:58.424] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:13.396] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:28.337] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:43.314] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:58.264] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:27:13.233] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:27:28.229] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:27:43.173] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:27:43.555] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:27:43.572] INFO: ----------------------------------------------------------------------
[15:27:43.572] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:27:43.572] INFO: ----------------------------------------------------------------------
[15:27:43.572] INFO: ----------------------------------------------------------------------
[15:27:43.572] INFO: Read back bit status: 1
[15:27:43.572] INFO: ----------------------------------------------------------------------
[15:27:43.572] INFO: ----------------------------------------------------------------------
[15:27:43.572] INFO: Timings are good!
[15:27:43.572] INFO: ----------------------------------------------------------------------
[15:27:43.572] INFO: Test took 151244 ms.
[15:27:43.572] INFO: PixTestTiming::TimingTest() done.
[15:27:43.572] INFO: ROC 0 masking pixel 0/6
[15:27:43.572] INFO: ROC 0 masking pixel 1/5
[15:27:43.572] INFO: ROC 2 masking pixel 50/48
[15:27:43.572] INFO: ROC 3 masking pixel 12/50
[15:27:43.572] INFO: ROC 10 masking pixel 4/52
[15:27:43.591] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:27:43.591] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:27:43.591] INFO: PixTestTiming::doTest took 541055 ms.
[15:27:43.591] INFO: PixTestTiming::doTest() done
[15:27:43.591] INFO: ROC 0 masking pixel 0/6
[15:27:43.591] INFO: ROC 0 masking pixel 1/5
[15:27:43.591] INFO: ROC 2 masking pixel 50/48
[15:27:43.591] INFO: ROC 3 masking pixel 12/50
[15:27:43.591] INFO: ROC 10 masking pixel 4/52
[15:27:43.592] INFO: Write out TBMPhaseScan_0_V0
[15:27:43.592] INFO: Write out TBMPhaseScan_1_V0
[15:27:43.592] INFO: Write out CombinedTBMPhaseScan_V0
[15:27:43.617] INFO: Write out ROCDelayScan3_V0
[15:27:43.618] INFO: enter test to run
[15:29:03.971] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:29:03.972] INFO: running: highrate
[15:29:03.992] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:29:04.266] INFO: ----------------------------------------------------------------------
[15:29:04.266] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:29:04.266] INFO: ----------------------------------------------------------------------
[15:29:04.266] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:29:04.266] INFO: edge/corner pixel THR is adjusted
[15:29:04.266] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:29:05.245] INFO: Collecting data for 5 seconds...
[15:29:10.261] INFO: Done with hot pixel readout
[15:29:22.170] INFO: PixTest:: pg_setup set to default.
[15:29:22.171] INFO: 0 hot pixels found in step 0
[15:29:22.209] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:29:22.212] INFO: PixTest::trimHotPixels() done
[15:29:22.212] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C0.dat
[15:29:22.218] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C1.dat
[15:29:22.224] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C2.dat
[15:29:22.230] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C3.dat
[15:29:22.235] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C4.dat
[15:29:22.240] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C5.dat
[15:29:22.245] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C6.dat
[15:29:22.251] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C7.dat
[15:29:22.256] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C8.dat
[15:29:22.261] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C9.dat
[15:29:22.266] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C10.dat
[15:29:22.271] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C11.dat
[15:29:22.276] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C12.dat
[15:29:22.282] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C13.dat
[15:29:22.287] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C14.dat
[15:29:22.292] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C15.dat
[15:29:22.308] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//defaultMaskFile.dat
[15:29:22.324] INFO: enter test to run
[15:29:52.915] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:29:52.915] INFO: running: highrate
[15:29:52.919] INFO: ----------------------------------------------------------------------
[15:29:52.920] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[15:29:52.920] INFO: ----------------------------------------------------------------------
[15:29:52.920] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[15:29:52.920] INFO: edge/corner pixel THR is adjusted
[15:29:52.920] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:29:53.878] INFO: Collecting data for 1 seconds...
[15:29:54.881] INFO: Done with hot pixel readout
[15:29:58.976] INFO: PixTest:: pg_setup set to default.
[15:29:58.977] INFO: 0 hot pixels found in step 0
[15:29:58.982] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:29:59.069] INFO: PixTest::trimHotPixels() done
[15:29:59.069] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C0.dat
[15:29:59.079] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C1.dat
[15:29:59.084] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C2.dat
[15:29:59.090] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C3.dat
[15:29:59.095] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C4.dat
[15:29:59.100] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C5.dat
[15:29:59.105] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C6.dat
[15:29:59.110] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C7.dat
[15:29:59.116] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C8.dat
[15:29:59.121] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C9.dat
[15:29:59.126] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C10.dat
[15:29:59.131] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C11.dat
[15:29:59.137] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C12.dat
[15:29:59.142] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C13.dat
[15:29:59.147] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C14.dat
[15:29:59.152] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C15.dat
[15:29:59.157] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-23_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//defaultMaskFile.dat
[15:29:59.167] INFO: enter test to run
[15:30:22.051] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[15:30:22.051] INFO: running: xray
[15:30:22.052] INFO: ----------------------------------------------------------------------
[15:30:22.052] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:30:22.052] INFO: ----------------------------------------------------------------------
[15:30:22.056] INFO: ROC 0 masking hot pixel 0/6
[15:30:22.056] INFO: ROC 0 masking hot pixel 1/5
[15:30:22.056] INFO: ROC 2 masking hot pixel 50/48
[15:30:22.056] INFO: ROC 3 masking hot pixel 12/50
[15:30:22.056] INFO: ROC 10 masking hot pixel 4/52
[15:30:22.056] INFO: ROC 0 masking pixel 0/6
[15:30:22.056] INFO: ROC 0 masking pixel 1/5
[15:30:22.056] INFO: ROC 2 masking pixel 50/48
[15:30:22.056] INFO: ROC 3 masking pixel 12/50
[15:30:22.056] INFO: ROC 10 masking pixel 4/52
[15:30:23.026] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:30:34.372] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[15:31:03.887] INFO: Resuming triggers.
[15:31:15.235] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[15:31:45.481] INFO: Resuming triggers.
[15:31:56.825] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[15:32:26.928] INFO: Resuming triggers.
[15:32:38.273] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[15:33:07.622] INFO: Resuming triggers.
[15:33:18.965] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[15:33:48.905] INFO: Resuming triggers.
[15:34:00.251] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[15:34:30.079] INFO: Resuming triggers.
[15:34:41.424] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[15:35:11.404] INFO: Resuming triggers.
[15:35:22.747] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[15:35:52.898] INFO: Resuming triggers.
[15:36:02.494] INFO: data taking finished, elapsed time: 100 seconds.
[15:36:28.453] INFO: PixTest:: pg_setup set to default.
[15:36:28.456] INFO: PixTestXray::doPhRun() done
[15:36:28.755] INFO: enter test to run
[15:37:03.264] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[15:37:03.264] INFO: running: xray
[15:37:03.265] INFO: ----------------------------------------------------------------------
[15:37:03.265] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:37:03.265] INFO: ----------------------------------------------------------------------
[15:37:03.269] INFO: ROC 0 masking hot pixel 0/6
[15:37:03.269] INFO: ROC 0 masking hot pixel 1/5
[15:37:03.269] INFO: ROC 2 masking hot pixel 50/48
[15:37:03.269] INFO: ROC 3 masking hot pixel 12/50
[15:37:03.269] INFO: ROC 10 masking hot pixel 4/52
[15:37:03.269] INFO: ROC 0 masking pixel 0/6
[15:37:03.269] INFO: ROC 0 masking pixel 1/5
[15:37:03.270] INFO: ROC 2 masking pixel 50/48
[15:37:03.270] INFO: ROC 3 masking pixel 12/50
[15:37:03.270] INFO: ROC 10 masking pixel 4/52
[15:37:04.229] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:37:10.797] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[15:37:41.715] INFO: Resuming triggers.
[15:37:48.280] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[15:38:19.572] INFO: Resuming triggers.
[15:38:26.135] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[15:38:57.326] INFO: Resuming triggers.
[15:39:03.896] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[15:39:34.065] INFO: Resuming triggers.
[15:39:40.629] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[15:40:10.707] INFO: Resuming triggers.
[15:40:17.271] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[15:40:47.496] INFO: Resuming triggers.
[15:40:54.063] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[15:41:24.360] INFO: Resuming triggers.
[15:41:30.925] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[15:42:01.028] INFO: Resuming triggers.
[15:42:07.591] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[15:42:38.045] INFO: Resuming triggers.
[15:42:44.611] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[15:43:14.701] INFO: Resuming triggers.
[15:43:21.268] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[15:43:51.253] INFO: Resuming triggers.
[15:43:57.819] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[15:44:27.884] INFO: Resuming triggers.
[15:44:34.448] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[15:45:04.742] INFO: Resuming triggers.
[15:45:11.304] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[15:45:41.744] INFO: Resuming triggers.
[15:45:48.307] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[15:46:19.195] INFO: Resuming triggers.
[15:46:21.056] INFO: data taking finished, elapsed time: 100 seconds.
[15:46:30.101] INFO: PixTest:: pg_setup set to default.
[15:46:30.104] INFO: PixTestXray::doPhRun() done
[15:46:30.290] INFO: enter test to run
[15:47:26.348] INFO: test: HighRate no parameter change
[15:47:26.348] INFO: running: highrate
[15:47:26.368] INFO: ----------------------------------------------------------------------
[15:47:26.368] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[15:47:26.368] INFO: ----------------------------------------------------------------------
[15:47:26.600] INFO: Expecting 768 events.
[15:47:27.760] INFO: 768 events read in total (445ms).
[15:47:27.760] INFO: Test took 1330ms.
[15:47:27.805] INFO: ROC 0 masking pixel 0/6
[15:47:27.805] INFO: ROC 0 masking pixel 1/5
[15:47:27.805] INFO: ROC 2 masking pixel 50/48
[15:47:27.805] INFO: ROC 3 masking pixel 12/50
[15:47:27.805] INFO: ROC 10 masking pixel 4/52
[15:47:28.563] INFO: Expecting 41600 events.
[15:47:31.553] INFO: 41600 events read in total (2463ms).
[15:47:31.554] INFO: Test took 3721ms.
[15:47:31.588] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:32.308] INFO: Expecting 41600 events.
[15:47:35.475] INFO: 41600 events read in total (2640ms).
[15:47:35.476] INFO: Test took 3871ms.
[15:47:35.512] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:36.229] INFO: Expecting 41600 events.
[15:47:39.493] INFO: 41600 events read in total (2737ms).
[15:47:39.495] INFO: Test took 3966ms.
[15:47:39.530] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:40.249] INFO: Expecting 41600 events.
[15:47:43.481] INFO: 41600 events read in total (2705ms).
[15:47:43.481] INFO: Test took 3932ms.
[15:47:43.518] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:44.239] INFO: Expecting 41600 events.
[15:47:47.428] INFO: 41600 events read in total (2662ms).
[15:47:47.429] INFO: Test took 3893ms.
[15:47:47.465] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:48.183] INFO: Expecting 41600 events.
[15:47:51.457] INFO: 41600 events read in total (2747ms).
[15:47:51.458] INFO: Test took 3975ms.
[15:47:51.493] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:52.210] INFO: Expecting 41600 events.
[15:47:55.512] INFO: 41600 events read in total (2775ms).
[15:47:55.513] INFO: Test took 4000ms.
[15:47:55.548] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:56.258] INFO: Expecting 41600 events.
[15:47:59.474] INFO: 41600 events read in total (2689ms).
[15:47:59.475] INFO: Test took 3909ms.
[15:47:59.511] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:00.232] INFO: Expecting 41600 events.
[15:48:03.521] INFO: 41600 events read in total (2762ms).
[15:48:03.522] INFO: Test took 3992ms.
[15:48:03.558] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:04.279] INFO: Expecting 41600 events.
[15:48:07.523] INFO: 41600 events read in total (2718ms).
[15:48:07.524] INFO: Test took 3948ms.
[15:48:07.559] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:08.278] INFO: Expecting 41600 events.
[15:48:11.568] INFO: 41600 events read in total (2763ms).
[15:48:11.569] INFO: Test took 3992ms.
[15:48:11.605] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:12.324] INFO: Expecting 41600 events.
[15:48:15.540] INFO: 41600 events read in total (2689ms).
[15:48:15.541] INFO: Test took 3917ms.
[15:48:15.577] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:16.295] INFO: Expecting 41600 events.
[15:48:19.596] INFO: 41600 events read in total (2774ms).
[15:48:19.597] INFO: Test took 3999ms.
[15:48:19.633] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:20.351] INFO: Expecting 41600 events.
[15:48:23.605] INFO: 41600 events read in total (2727ms).
[15:48:23.606] INFO: Test took 3954ms.
[15:48:23.654] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:24.363] INFO: Expecting 41600 events.
[15:48:27.456] INFO: 41600 events read in total (2566ms).
[15:48:27.457] INFO: Test took 3784ms.
[15:48:27.492] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:28.213] INFO: Expecting 41600 events.
[15:48:31.468] INFO: 41600 events read in total (2728ms).
[15:48:31.469] INFO: Test took 3959ms.
[15:48:31.505] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:32.228] INFO: Expecting 41600 events.
[15:48:35.473] INFO: 41600 events read in total (2718ms).
[15:48:35.474] INFO: Test took 3951ms.
[15:48:35.509] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:36.231] INFO: Expecting 41600 events.
[15:48:39.563] INFO: 41600 events read in total (2805ms).
[15:48:39.564] INFO: Test took 4037ms.
[15:48:39.599] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:40.317] INFO: Expecting 41600 events.
[15:48:43.576] INFO: 41600 events read in total (2732ms).
[15:48:43.577] INFO: Test took 3960ms.
[15:48:43.612] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:44.334] INFO: Expecting 41600 events.
[15:48:47.435] INFO: 41600 events read in total (2574ms).
[15:48:47.436] INFO: Test took 3805ms.
[15:48:47.472] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:47.830] INFO: enter test to run
[15:49:03.587] INFO: test: HighRate no parameter change
[15:49:03.587] INFO: running: highrate
[15:49:03.588] INFO: ----------------------------------------------------------------------
[15:49:03.588] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:49:03.588] INFO: ----------------------------------------------------------------------
[15:49:03.596] INFO: ROC 0 masking pixel 0/6
[15:49:03.596] INFO: ROC 0 masking pixel 1/5
[15:49:03.596] INFO: ROC 2 masking pixel 50/48
[15:49:03.597] INFO: ROC 3 masking pixel 12/50
[15:49:03.597] INFO: ROC 10 masking pixel 4/52
[15:49:04.208] INFO: Expecting 208000 events.
[15:49:16.331] INFO: 208000 events read in total (11596ms).
[15:49:16.334] INFO: Test took 12737ms.
[15:49:16.484] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:49:16.740] INFO: number of dead pixels (per ROC): 2 0 1 1 0 0 3 0 0 1 1 0 0 0 0 1
[15:49:16.767] INFO: number of red-efficiency pixels: 65 46 80 136 162 140 124 92 103 143 136 112 119 65 10 25
[15:49:16.767] INFO: number of X-ray hits detected: 60792 38648 63386 103661 113250 113760 115311 75878 79296 111693 113706 93052 101615 60591 22898 24751
[15:49:16.767] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:49:16.767] INFO: number of Vcal hits detected: 207835 207954 207867 207813 207835 207857 207728 207906 207894 207805 207812 207886 207880 207935 207989 207926
[15:49:16.767] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[15:49:16.767] 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 99.9 100.0 100.0 100.0
[15:49:16.768] INFO: X-ray hit rate [MHz/cm2]: 17.8 11.3 18.6 30.4 33.2 33.3 33.8 22.2 23.2 32.7 33.3 27.3 29.8 17.8 6.7 7.3
[15:49:16.768] INFO: PixTestHighRate::doXPixelAlive() done
[15:49:16.813] INFO: PixTest:: pg_setup set to default.
[15:49:16.827] INFO: enter test to run
[15:49:59.139] INFO: test: HighRate no parameter change
[15:49:59.139] INFO: running: highrate
[15:49:59.140] INFO: ----------------------------------------------------------------------
[15:49:59.140] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:49:59.140] INFO: ----------------------------------------------------------------------
[15:49:59.148] INFO: ROC 0 masking pixel 0/6
[15:49:59.148] INFO: ROC 0 masking pixel 1/5
[15:49:59.148] INFO: ROC 2 masking pixel 50/48
[15:49:59.148] INFO: ROC 3 masking pixel 12/50
[15:49:59.148] INFO: ROC 10 masking pixel 4/52
[15:49:59.759] INFO: Expecting 208000 events.
[15:50:13.669] INFO: 208000 events read in total (13383ms).
[15:50:13.675] INFO: Test took 14526ms.
[15:50:13.984] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:14.291] INFO: number of dead pixels (per ROC): 2 0 1 1 0 0 3 0 0 1 1 0 0 0 0 1
[15:50:14.291] INFO: number of red-efficiency pixels: 194 103 207 419 517 510 392 306 312 499 391 361 458 185 64 46
[15:50:14.291] INFO: number of X-ray hits detected: 125821 81198 132122 214301 235323 235209 238994 157278 165314 233113 236271 193972 208887 126027 48103 51676
[15:50:14.291] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:50:14.291] INFO: number of Vcal hits detected: 207702 207889 207733 207495 207429 207447 207428 207667 207676 207419 207530 207605 207498 207801 207936 207905
[15:50:14.291] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[15:50:14.291] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.7 99.7 99.8 99.8 99.7 99.8 99.8 99.8 99.9 100.0 100.0
[15:50:14.291] INFO: X-ray hit rate [MHz/cm2]: 36.9 23.8 38.7 62.8 69.0 68.9 70.1 46.1 48.5 68.3 69.3 56.9 61.2 36.9 14.1 15.1
[15:50:14.291] INFO: PixTestHighRate::doXPixelAlive() done
[15:50:14.339] INFO: PixTest:: pg_setup set to default.
[15:50:14.350] INFO: enter test to run
[15:50:33.075] INFO: test: HighRate no parameter change
[15:50:33.075] INFO: running: highrate
[15:50:33.076] INFO: ----------------------------------------------------------------------
[15:50:33.076] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:50:33.076] INFO: ----------------------------------------------------------------------
[15:50:33.086] INFO: ROC 0 masking pixel 0/6
[15:50:33.086] INFO: ROC 0 masking pixel 1/5
[15:50:33.086] INFO: ROC 2 masking pixel 50/48
[15:50:33.086] INFO: ROC 3 masking pixel 12/50
[15:50:33.086] INFO: ROC 10 masking pixel 4/52
[15:50:33.705] INFO: Expecting 208000 events.
[15:50:49.536] INFO: 208000 events read in total (15304ms).
[15:50:49.544] INFO: Test took 16457ms.
[15:50:49.003] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:50.359] INFO: number of dead pixels (per ROC): 2 0 1 1 0 0 3 0 0 1 1 0 0 0 0 1
[15:50:50.359] INFO: number of red-efficiency pixels: 446 221 426 990 1261 1214 904 627 608 1212 868 866 989 389 95 85
[15:50:50.359] INFO: number of X-ray hits detected: 188534 121234 197974 321962 353463 352708 361095 236851 247591 349527 356371 290091 315779 190700 71793 78599
[15:50:50.359] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:50:50.359] INFO: number of Vcal hits detected: 207373 207759 207449 206734 206371 206412 206743 207208 207245 206340 206894 206919 206803 207552 207904 207862
[15:50:50.360] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.5 99.3 99.3 99.5 99.7 99.7 99.3 99.5 99.6 99.5 99.8 100.0 100.0
[15:50:50.360] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.7 99.4 99.2 99.2 99.4 99.6 99.6 99.2 99.5 99.5 99.4 99.8 100.0 99.9
[15:50:50.360] INFO: X-ray hit rate [MHz/cm2]: 55.3 35.5 58.0 94.4 103.6 103.4 105.8 69.4 72.6 102.4 104.5 85.0 92.6 55.9 21.0 23.0
[15:50:50.360] INFO: PixTestHighRate::doXPixelAlive() done
[15:50:50.404] INFO: PixTest:: pg_setup set to default.
[15:50:50.421] INFO: enter test to run
[15:51:17.306] INFO: test: exit no parameter change
[15:51:18.123] QUIET: Connection to board 30 closed.
[15:51:18.287] INFO: pXar: this is the end, my friend