[15:41:59.023] INFO: *** Welcome to pxar ***
[15:41:59.023] INFO: *** Today: 2016/11/17
[15:42:02.772] INFO: *** Version: v1.9.0-818-g96727
[15:42:02.773] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//dacParameters35_C15.dat
[15:42:03.054] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:42:03.055] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//defaultMaskFile.dat
[15:42:03.061] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C15.dat
[15:42:03.191] INFO: clk: 4
[15:42:03.191] INFO: ctr: 4
[15:42:03.191] INFO: sda: 19
[15:42:03.191] INFO: tin: 9
[15:42:03.191] INFO: level: 15
[15:42:03.191] INFO: triggerdelay: 0
[15:42:03.191] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[15:42:03.191] INFO: Log level: INFO
[15:42:03.236] QUIET: Connection to board DTB_WREHUL opened.
[15:42:03.239] 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:42:03.242] INFO: RPC call hashes of host and DTB match: 398089610
[15:42:04.812] INFO: DUT info:
[15:42:04.812] INFO: The DUT currently contains the following objects:
[15:42:04.812] INFO: 2 TBM Cores tbm08c (2 ON)
[15:42:04.812] INFO: TBM Core alpha (0): 7 registers set
[15:42:04.812] INFO: TBM Core beta (1): 7 registers set
[15:42:04.812] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:42:04.812] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:04.812] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:04.812] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:04.812] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:04.812] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:04.812] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:04.812] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:04.812] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:04.812] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:04.812] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:04.812] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:04.812] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:04.812] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:04.812] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:04.812] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:04.812] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:05.595] INFO: enter 'restricted' command line mode
[15:42:05.595] INFO: enter test to run
[15:42:10.106] INFO: test: PixelAlive no parameter change
[15:42:10.106] INFO: running: pixelalive
[15:42:10.240] INFO: ----------------------------------------------------------------------
[15:42:10.240] 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:42:10.240] INFO: ----------------------------------------------------------------------
[15:42:10.561] INFO: Expecting 41600 events.
[15:42:14.959] INFO: 41600 events read in total (3679ms).
[15:42:15.118] INFO: Test took 4875ms.
[15:42:15.129] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:42:16.103] INFO: PixTestAlive::aliveTest() done
[15:42:16.103] INFO: number of dead pixels (per ROC): 0 1 1 1 42 0 1 0 0 0 3 1 2 0 0 0
[15:42:16.407] INFO: enter test to run
[15:42:30.210] INFO: test: timing no parameter change
[15:42:30.210] INFO: running: timing
[15:42:30.213] INFO: ######################################################################
[15:42:30.213] INFO: PixTestTiming::doTest()
[15:42:30.213] INFO: ######################################################################
[15:42:30.213] INFO: ----------------------------------------------------------------------
[15:42:30.213] INFO: PixTestTiming::TBMPhaseScan()
[15:42:30.213] INFO: ----------------------------------------------------------------------
[15:46:59.351] INFO: TBM Phase Settings: 224
[15:46:59.351] INFO: 400MHz Phase: 0
[15:46:59.351] INFO: 160MHz Phase: 7
[15:46:59.351] INFO: Functional Phase Area: 3
[15:46:59.372] INFO: Test took 269159 ms.
[15:46:59.372] INFO: PixTestTiming::TBMPhaseScan() done.
[15:46:59.372] INFO: ----------------------------------------------------------------------
[15:46:59.372] INFO: PixTestTiming::ROCDelayScan()
[15:46:59.372] INFO: ----------------------------------------------------------------------
[15:49:03.525] INFO: ROC Delay Settings: 228
[15:49:03.525] INFO: ROC Header-Trailer/Token Delay: 11
[15:49:03.525] INFO: ROC Port 0 Delay: 4
[15:49:03.525] INFO: ROC Port 1 Delay: 4
[15:49:03.525] INFO: Functional ROC Area: 4
[15:49:03.529] INFO: Test took 124157 ms.
[15:49:03.529] INFO: PixTestTiming::ROCDelayScan() done.
[15:49:03.529] INFO: ----------------------------------------------------------------------
[15:49:03.529] INFO: PixTestTiming::TimingTest()
[15:49:03.529] INFO: ----------------------------------------------------------------------
[15:49:19.862] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:49:35.105] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:49:50.243] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:05.203] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:20.199] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:35.168] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:50.176] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:51:05.164] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:51:20.153] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:51:35.122] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:51:35.505] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:51:35.522] INFO: ----------------------------------------------------------------------
[15:51:35.522] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:51:35.522] INFO: ----------------------------------------------------------------------
[15:51:35.522] INFO: ----------------------------------------------------------------------
[15:51:35.523] INFO: Read back bit status: 1
[15:51:35.523] INFO: ----------------------------------------------------------------------
[15:51:35.523] INFO: ----------------------------------------------------------------------
[15:51:35.523] INFO: Timings are good!
[15:51:35.523] INFO: ----------------------------------------------------------------------
[15:51:35.523] INFO: Test took 151994 ms.
[15:51:35.523] INFO: PixTestTiming::TimingTest() done.
[15:51:35.523] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:51:35.523] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:51:35.523] INFO: PixTestTiming::doTest took 545313 ms.
[15:51:35.523] INFO: PixTestTiming::doTest() done
[15:51:35.523] INFO: Write out TBMPhaseScan_0_V0
[15:51:35.524] INFO: Write out TBMPhaseScan_1_V0
[15:51:35.524] INFO: Write out CombinedTBMPhaseScan_V0
[15:51:35.525] INFO: Write out ROCDelayScan3_V0
[15:51:35.526] INFO: enter test to run
[15:52:31.478] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:52:31.478] INFO: running: highrate
[15:52:31.494] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:52:31.813] INFO: ----------------------------------------------------------------------
[15:52:31.813] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:52:31.813] INFO: ----------------------------------------------------------------------
[15:52:31.813] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:52:31.813] INFO: edge/corner pixel THR is adjusted
[15:52:31.813] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:52:32.772] INFO: Collecting data for 5 seconds...
[15:52:37.789] INFO: Done with hot pixel readout
[15:52:49.427] INFO: PixTest:: pg_setup set to default.
[15:52:49.428] INFO: 4 hot pixels found in step 0
[15:52:50.419] INFO: Collecting data for 5 seconds...
[15:52:55.436] INFO: Done with hot pixel readout
[15:53:07.098] INFO: PixTest:: pg_setup set to default.
[15:53:07.099] INFO: 7 hot pixels found in step 1
[15:53:08.090] INFO: Collecting data for 5 seconds...
[15:53:13.106] INFO: Done with hot pixel readout
[15:53:24.787] INFO: PixTest:: pg_setup set to default.
[15:53:24.788] INFO: 9 hot pixels found in step 2
[15:53:25.779] INFO: Collecting data for 5 seconds...
[15:53:30.796] INFO: Done with hot pixel readout
[15:53:42.379] INFO: PixTest:: pg_setup set to default.
[15:53:42.379] INFO: 4 hot pixels found in step 3
[15:53:43.370] INFO: Collecting data for 5 seconds...
[15:53:48.386] INFO: Done with hot pixel readout
[15:54:00.030] INFO: PixTest:: pg_setup set to default.
[15:54:00.031] INFO: 7 hot pixels found in step 4
[15:54:01.023] INFO: Collecting data for 5 seconds...
[15:54:06.039] INFO: Done with hot pixel readout
[15:54:17.612] INFO: PixTest:: pg_setup set to default.
[15:54:17.613] INFO: 8 hot pixels found in step 5
[15:54:18.606] INFO: Collecting data for 5 seconds...
[15:54:23.622] INFO: Done with hot pixel readout
[15:54:35.270] INFO: PixTest:: pg_setup set to default.

[15:54:35.271] INFO: 6 hot pixels found in step 6
[15:54:36.262] INFO: Collecting data for 5 seconds...
[15:54:41.278] INFO: Done with hot pixel readout
[15:54:52.921] INFO: PixTest:: pg_setup set to default.
[15:54:52.922] INFO: 5 hot pixels found in step 7
[15:54:53.913] INFO: Collecting data for 5 seconds...
[15:54:58.930] INFO: Done with hot pixel readout
[15:55:10.579] INFO: PixTest:: pg_setup set to default.
[15:55:10.580] INFO: 2 hot pixels found in step 8
[15:55:11.572] INFO: Collecting data for 5 seconds...
[15:55:16.589] INFO: Done with hot pixel readout
[15:55:28.239] INFO: PixTest:: pg_setup set to default.
[15:55:28.240] INFO: 4 hot pixels found in step 9
[15:55:29.231] INFO: Collecting data for 5 seconds...
[15:55:34.249] INFO: Done with hot pixel readout
[15:55:45.912] INFO: PixTest:: pg_setup set to default.
[15:55:45.913] INFO: 10 hot pixels found in step 10
[15:55:46.904] INFO: Collecting data for 5 seconds...
[15:55:51.920] INFO: Done with hot pixel readout
[15:56:03.706] INFO: PixTest:: pg_setup set to default.
[15:56:03.707] INFO: 2 hot pixels found in step 11
[15:56:04.699] INFO: Collecting data for 5 seconds...
[15:56:09.717] INFO: Done with hot pixel readout
[15:56:21.523] INFO: PixTest:: pg_setup set to default.
[15:56:21.524] INFO: 3 hot pixels found in step 12
[15:56:22.516] INFO: Collecting data for 5 seconds...
[15:56:27.534] INFO: Done with hot pixel readout
[15:56:39.308] INFO: PixTest:: pg_setup set to default.
[15:56:39.309] INFO: 3 hot pixels found in step 13
[15:56:40.299] INFO: Collecting data for 5 seconds...
[15:56:45.317] INFO: Done with hot pixel readout
[15:56:57.060] INFO: PixTest:: pg_setup set to default.
[15:56:57.061] INFO: 4 hot pixels found in step 14
[15:56:57.097] INFO: 4 hot pixels could not be trimmed and have been masked.
[15:56:57.101] INFO: PixTest::trimHotPixels() done
[15:56:57.132] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C0.dat
[15:56:57.140] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C1.dat
[15:56:57.146] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C2.dat
[15:56:57.152] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C3.dat
[15:56:57.157] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C4.dat
[15:56:57.163] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C5.dat
[15:56:57.168] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C6.dat
[15:56:57.174] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C7.dat
[15:56:57.179] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C8.dat
[15:56:57.185] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C9.dat
[15:56:57.190] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C10.dat
[15:56:57.196] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C11.dat
[15:56:57.201] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C12.dat
[15:56:57.207] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C13.dat
[15:56:57.212] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C14.dat
[15:56:57.218] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C15.dat
[15:56:57.223] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//defaultMaskFile.dat
[15:56:57.241] INFO: enter test to run
[15:57:35.740] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:57:35.740] INFO: running: highrate
[15:57:35.744] INFO: ----------------------------------------------------------------------
[15:57:35.744] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[15:57:35.744] INFO: ----------------------------------------------------------------------
[15:57:35.744] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[15:57:35.744] INFO: edge/corner pixel THR is adjusted
[15:57:35.744] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:57:36.701] INFO: Collecting data for 1 seconds...
[15:57:37.706] INFO: Done with hot pixel readout
[15:57:41.695] INFO: PixTest:: pg_setup set to default.
[15:57:41.695] INFO: 0 hot pixels found in step 0
[15:57:41.702] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:57:41.789] INFO: PixTest::trimHotPixels() done
[15:57:41.789] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C0.dat
[15:57:41.823] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C1.dat
[15:57:41.829] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C2.dat
[15:57:41.840] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C3.dat
[15:57:41.846] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C4.dat
[15:57:41.851] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C5.dat
[15:57:41.857] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C6.dat
[15:57:41.863] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C7.dat
[15:57:41.869] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C8.dat
[15:57:41.875] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C9.dat
[15:57:41.880] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C10.dat
[15:57:41.886] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C11.dat
[15:57:41.891] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C12.dat
[15:57:41.897] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C13.dat
[15:57:41.902] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C14.dat
[15:57:41.908] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//trimParameters35_C15.dat
[15:57:41.913] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-13_FPIXTest-17C-FNAL-161115-1259-150V_2016-11-15_12h59m_1479236379/000_FPIXTest_p17//defaultMaskFile.dat
[15:57:41.923] INFO: enter test to run
[15:58:07.787] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[15:58:07.787] INFO: running: xray
[15:58:07.789] INFO: ----------------------------------------------------------------------
[15:58:07.789] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:58:07.789] INFO: ----------------------------------------------------------------------
[15:58:08.766] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:58:20.304] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[15:58:50.120] INFO: Resuming triggers.
[15:59:01.656] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[15:59:31.575] INFO: Resuming triggers.
[15:59:43.116] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[16:00:12.668] INFO: Resuming triggers.
[16:00:24.205] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[16:00:54.995] INFO: Resuming triggers.
[16:01:06.532] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[16:01:36.835] INFO: Resuming triggers.
[16:01:48.371] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[16:02:18.786] INFO: Resuming triggers.
[16:02:30.321] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[16:03:00.167] INFO: Resuming triggers.
[16:03:11.705] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[16:03:41.054] INFO: Resuming triggers.
[16:03:49.127] INFO: data taking finished, elapsed time: 100 seconds.
[16:04:09.858] INFO: PixTest:: pg_setup set to default.
[16:04:09.861] INFO: PixTestXray::doPhRun() done
[16:04:10.104] INFO: enter test to run
[16:04:44.801] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[16:04:44.801] INFO: running: xray
[16:04:44.802] INFO: ----------------------------------------------------------------------
[16:04:44.802] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:04:44.802] INFO: ----------------------------------------------------------------------
[16:04:45.766] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:04:52.485] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[16:05:22.758] INFO: Resuming triggers.
[16:05:29.482] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[16:05:59.781] INFO: Resuming triggers.
[16:06:06.503] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[16:06:36.775] INFO: Resuming triggers.
[16:06:43.496] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[16:07:13.860] INFO: Resuming triggers.
[16:07:20.586] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[16:07:50.836] INFO: Resuming triggers.
[16:07:57.558] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[16:08:27.878] INFO: Resuming triggers.
[16:08:34.601] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[16:09:04.870] INFO: Resuming triggers.
[16:09:11.596] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[16:09:41.860] INFO: Resuming triggers.
[16:09:48.585] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[16:10:19.338] INFO: Resuming triggers.
[16:10:26.065] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[16:10:56.944] INFO: Resuming triggers.
[16:11:03.673] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[16:11:34.340] INFO: Resuming triggers.
[16:11:41.069] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[16:12:11.949] INFO: Resuming triggers.
[16:12:18.677] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[16:12:49.799] INFO: Resuming triggers.
[16:12:56.524] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[16:13:27.430] INFO: Resuming triggers.
[16:13:33.630] INFO: data taking finished, elapsed time: 100 seconds.
[16:14:02.383] INFO: PixTest:: pg_setup set to default.
[16:14:02.386] INFO: PixTestXray::doPhRun() done
[16:14:02.541] INFO: enter test to run
[16:15:03.573] INFO: test: HighRate no parameter change
[16:15:03.573] INFO: running: highrate
[16:15:03.591] INFO: ----------------------------------------------------------------------
[16:15:03.591] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[16:15:03.591] INFO: ----------------------------------------------------------------------
[16:15:03.782] INFO: Expecting 768 events.
[16:15:04.934] INFO: 768 events read in total (436ms).
[16:15:04.935] INFO: Test took 1315ms.
[16:15:05.738] INFO: Expecting 41600 events.
[16:15:08.857] INFO: 41600 events read in total (2593ms).
[16:15:08.858] INFO: Test took 3916ms.
[16:15:08.891] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:09.620] INFO: Expecting 41600 events.
[16:15:13.008] INFO: 41600 events read in total (2861ms).
[16:15:13.009] INFO: Test took 4100ms.
[16:15:13.044] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:13.762] INFO: Expecting 41600 events.
[16:15:17.188] INFO: 41600 events read in total (2900ms).
[16:15:17.189] INFO: Test took 4128ms.
[16:15:17.233] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:17.926] INFO: Expecting 41600 events.
[16:15:21.204] INFO: 41600 events read in total (2751ms).
[16:15:21.205] INFO: Test took 3947ms.
[16:15:21.240] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:21.961] INFO: Expecting 41600 events.
[16:15:25.192] INFO: 41600 events read in total (2704ms).
[16:15:25.193] INFO: Test took 3933ms.
[16:15:25.228] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:25.951] INFO: Expecting 41600 events.
[16:15:29.238] INFO: 41600 events read in total (2760ms).
[16:15:29.239] INFO: Test took 3994ms.
[16:15:29.273] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:29.987] INFO: Expecting 41600 events.
[16:15:33.235] INFO: 41600 events read in total (2721ms).
[16:15:33.236] INFO: Test took 3945ms.
[16:15:33.272] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:33.984] INFO: Expecting 41600 events.
[16:15:37.210] INFO: 41600 events read in total (2699ms).
[16:15:37.211] INFO: Test took 3921ms.
[16:15:37.246] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:37.964] INFO: Expecting 41600 events.
[16:15:41.338] INFO: 41600 events read in total (2847ms).
[16:15:41.339] INFO: Test took 4075ms.
[16:15:41.373] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:42.092] INFO: Expecting 41600 events.
[16:15:45.427] INFO: 41600 events read in total (2808ms).
[16:15:45.428] INFO: Test took 4038ms.
[16:15:45.463] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:46.179] INFO: Expecting 41600 events.
[16:15:49.486] INFO: 41600 events read in total (2780ms).
[16:15:49.488] INFO: Test took 4007ms.
[16:15:49.522] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:50.231] INFO: Expecting 41600 events.
[16:15:53.495] INFO: 41600 events read in total (2737ms).
[16:15:53.496] INFO: Test took 3957ms.
[16:15:53.531] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:54.250] INFO: Expecting 41600 events.
[16:15:57.503] INFO: 41600 events read in total (2726ms).
[16:15:57.504] INFO: Test took 3955ms.
[16:15:57.539] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:58.258] INFO: Expecting 41600 events.
[16:16:01.559] INFO: 41600 events read in total (2775ms).
[16:16:01.560] INFO: Test took 4004ms.
[16:16:01.595] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:02.312] INFO: Expecting 41600 events.
[16:16:05.555] INFO: 41600 events read in total (2717ms).
[16:16:05.556] INFO: Test took 3943ms.
[16:16:05.591] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:06.311] INFO: Expecting 41600 events.
[16:16:09.565] INFO: 41600 events read in total (2727ms).
[16:16:09.566] INFO: Test took 3957ms.
[16:16:09.600] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:10.323] INFO: Expecting 41600 events.
[16:16:13.609] INFO: 41600 events read in total (2759ms).
[16:16:13.610] INFO: Test took 3992ms.
[16:16:13.646] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:14.367] INFO: Expecting 41600 events.
[16:16:17.666] INFO: 41600 events read in total (2773ms).
[16:16:17.667] INFO: Test took 4002ms.
[16:16:17.702] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:18.426] INFO: Expecting 41600 events.
[16:16:21.707] INFO: 41600 events read in total (2754ms).
[16:16:21.708] INFO: Test took 3988ms.
[16:16:21.742] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:22.462] INFO: Expecting 41600 events.
[16:16:25.568] INFO: 41600 events read in total (2580ms).
[16:16:25.569] INFO: Test took 3809ms.
[16:16:25.602] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:25.968] INFO: enter test to run
[16:16:30.932] INFO: test: HighRate no parameter change
[16:16:30.932] INFO: running: highrate
[16:16:30.933] INFO: ----------------------------------------------------------------------
[16:16:30.933] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:16:30.933] INFO: ----------------------------------------------------------------------
[16:16:31.542] INFO: Expecting 208000 events.
[16:16:43.331] INFO: 208000 events read in total (11262ms).
[16:16:43.334] INFO: Test took 12394ms.
[16:16:43.480] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:43.733] INFO: number of dead pixels (per ROC): 0 1 1 1 36 0 1 0 0 0 3 1 2 0 0 0
[16:16:43.733] INFO: number of red-efficiency pixels: 91 55 72 146 179 102 123 101 95 124 142 110 95 68 23 25
[16:16:43.733] INFO: number of X-ray hits detected: 69174 43464 64813 97274 101781 110231 112315 71497 71718 106077 109682 87231 91504 58242 21781 23557
[16:16:43.733] 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:16:43.734] INFO: number of Vcal hits detected: 207906 207895 207877 207800 205767 207895 207822 207895 207904 207873 207709 207837 207806 207930 207976 207975
[16:16:43.734] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 100.0 99.9 100.0 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[16:16:43.734] INFO: Vcal hit overall efficiency (%): 100.0 99.9 99.9 99.9 98.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[16:16:43.734] INFO: X-ray hit rate [MHz/cm2]: 20.3 12.7 19.0 28.5 29.8 32.3 32.9 21.0 21.0 31.1 32.1 25.6 26.8 17.1 6.4 6.9
[16:16:43.734] INFO: PixTestHighRate::doXPixelAlive() done
[16:16:43.782] INFO: PixTest:: pg_setup set to default.
[16:16:43.794] INFO: enter test to run
[16:17:29.484] INFO: test: HighRate no parameter change
[16:17:29.484] INFO: running: highrate
[16:17:29.485] INFO: ----------------------------------------------------------------------
[16:17:29.485] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:17:29.485] INFO: ----------------------------------------------------------------------
[16:17:30.097] INFO: Expecting 208000 events.
[16:17:43.565] INFO: 208000 events read in total (12941ms).
[16:17:43.570] INFO: Test took 14076ms.
[16:17:43.861] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:17:44.161] INFO: number of dead pixels (per ROC): 0 1 1 1 37 0 1 0 0 0 3 1 2 0 0 0
[16:17:44.161] INFO: number of red-efficiency pixels: 214 140 199 432 475 361 400 283 259 375 531 336 249 156 55 64
[16:17:44.161] INFO: number of X-ray hits detected: 142297 89156 134233 201689 210372 228892 230681 148430 148789 219425 226918 180942 190330 120182 45799 48935
[16:17:44.161] 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:17:44.161] INFO: number of Vcal hits detected: 207769 207799 207739 207486 205441 207616 207519 207691 207720 207599 207253 207584 207635 207833 207944 207935
[16:17:44.161] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.8 99.7 99.8 99.9 99.9 100.0 100.0
[16:17:44.162] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 98.8 99.8 99.8 99.9 99.9 99.8 99.6 99.8 99.8 99.9 100.0 100.0
[16:17:44.162] INFO: X-ray hit rate [MHz/cm2]: 41.7 26.1 39.3 59.1 61.7 67.1 67.6 43.5 43.6 64.3 66.5 53.0 55.8 35.2 13.4 14.3
[16:17:44.162] INFO: PixTestHighRate::doXPixelAlive() done
[16:17:44.209] INFO: PixTest:: pg_setup set to default.
[16:17:44.225] INFO: enter test to run
[16:18:05.971] INFO: test: HighRate no parameter change
[16:18:05.971] INFO: running: highrate
[16:18:05.973] INFO: ----------------------------------------------------------------------
[16:18:05.973] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:18:05.973] INFO: ----------------------------------------------------------------------
[16:18:06.592] INFO: Expecting 208000 events.
[16:18:22.019] INFO: 208000 events read in total (14900ms).
[16:18:22.026] INFO: Test took 16043ms.
[16:18:22.461] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:18:22.811] INFO: number of dead pixels (per ROC): 0 1 1 1 34 0 1 0 0 0 3 1 2 0 0 0
[16:18:22.811] INFO: number of red-efficiency pixels: 453 282 459 956 1062 814 902 595 514 838 1184 779 560 378 83 90
[16:18:22.811] INFO: number of X-ray hits detected: 215485 134664 202758 305519 318094 343228 351022 224292 224856 331540 342239 273267 287259 182072 69550 74205
[16:18:22.811] 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:18:22.811] INFO: number of Vcal hits detected: 207479 207642 207388 206800 204669 207058 206870 207240 207397 206999 206333 207013 207273 207565 207914 207909
[16:18:22.811] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.5 99.4 99.6 99.5 99.7 99.7 99.6 99.3 99.6 99.7 99.8 100.0 100.0
[16:18:22.811] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.7 99.4 98.4 99.5 99.5 99.6 99.7 99.5 99.2 99.5 99.7 99.8 100.0 100.0
[16:18:22.811] INFO: X-ray hit rate [MHz/cm2]: 63.2 39.5 59.4 89.5 93.2 100.6 102.9 65.7 65.9 97.2 100.3 80.1 84.2 53.4 20.4 21.8
[16:18:22.811] INFO: PixTestHighRate::doXPixelAlive() done
[16:18:22.858] INFO: PixTest:: pg_setup set to default.
[16:18:22.876] INFO: enter test to run
[16:18:56.779] INFO: test: exit no parameter change
[16:18:57.197] QUIET: Connection to board 30 closed.
[16:18:57.236] INFO: pXar: this is the end, my friend