[16:13:02.789] INFO: *** Welcome to pxar ***
[16:13:02.789] INFO: *** Today: 2016/11/18
[16:13:03.642] INFO: *** Version: v1.9.0-818-g96727
[16:13:03.642] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//dacParameters35_C15.dat
[16:13:03.665] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:13:03.665] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//defaultMaskFile.dat
[16:13:03.675] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C15.dat
[16:13:03.883] INFO: clk: 4
[16:13:03.883] INFO: ctr: 4
[16:13:03.884] INFO: sda: 19
[16:13:03.884] INFO: tin: 9
[16:13:03.884] INFO: level: 15
[16:13:03.884] INFO: triggerdelay: 0
[16:13:03.884] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[16:13:03.884] INFO: Log level: INFO
[16:13:03.918] QUIET: Connection to board DTB_WREHUL opened.
[16:13:03.922] 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:13:03.924] INFO: RPC call hashes of host and DTB match: 398089610
[16:13:05.464] INFO: DUT info:
[16:13:05.464] INFO: The DUT currently contains the following objects:
[16:13:05.464] INFO: 2 TBM Cores tbm08c (2 ON)
[16:13:05.464] INFO: TBM Core alpha (0): 7 registers set
[16:13:05.464] INFO: TBM Core beta (1): 7 registers set
[16:13:05.464] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[16:13:05.464] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[16:13:05.464] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[16:13:05.464] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[16:13:05.464] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[16:13:05.464] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[16:13:05.464] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[16:13:05.464] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[16:13:05.464] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[16:13:05.465] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[16:13:05.465] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[16:13:05.465] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[16:13:05.465] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[16:13:05.465] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[16:13:05.465] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[16:13:05.465] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[16:13:05.465] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[16:13:05.919] INFO: enter 'restricted' command line mode
[16:13:05.919] INFO: enter test to run
[16:13:09.417] INFO: test: PixelAlive no parameter change
[16:13:09.417] INFO: running: pixelalive
[16:13:09.450] INFO: ----------------------------------------------------------------------
[16:13:09.450] 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:13:09.450] INFO: ----------------------------------------------------------------------
[16:13:09.777] INFO: Expecting 41600 events.
[16:13:14.101] INFO: 41600 events read in total (3606ms).
[16:13:14.267] INFO: Test took 4815ms.
[16:13:14.277] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:13:14.615] INFO: PixTestAlive::aliveTest() done
[16:13:14.615] INFO: number of dead pixels (per ROC): 1 0 0 0 0 3 8 0 1 1 0 0 0 0 6 0
[16:13:14.650] INFO: enter test to run
[16:14:01.889] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[16:14:01.889] INFO: running: highrate
[16:14:01.889] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[16:14:02.160] INFO: ----------------------------------------------------------------------
[16:14:02.160] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[16:14:02.160] INFO: ----------------------------------------------------------------------
[16:14:02.160] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[16:14:02.160] INFO: edge/corner pixel THR is adjusted
[16:14:02.160] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:14:03.146] INFO: Collecting data for 5 seconds...
[16:14:08.164] INFO: Done with hot pixel readout
[16:14:19.881] INFO: PixTest:: pg_setup set to default.
[16:14:19.882] INFO: 8 hot pixels found in step 0
[16:14:20.870] INFO: Collecting data for 5 seconds...
[16:14:25.889] INFO: Done with hot pixel readout
[16:14:37.423] INFO: PixTest:: pg_setup set to default.
[16:14:37.423] INFO: 6 hot pixels found in step 1
[16:14:38.417] INFO: Collecting data for 5 seconds...
[16:14:43.436] INFO: Done with hot pixel readout
[16:14:55.136] INFO: PixTest:: pg_setup set to default.
[16:14:55.137] INFO: 2 hot pixels found in step 2
[16:14:56.128] INFO: Collecting data for 5 seconds...
[16:15:01.147] INFO: Done with hot pixel readout
[16:15:12.905] INFO: PixTest:: pg_setup set to default.
[16:15:12.906] INFO: 1 hot pixels found in step 3
[16:15:13.898] INFO: Collecting data for 5 seconds...
[16:15:18.916] INFO: Done with hot pixel readout
[16:15:30.321] INFO: PixTest:: pg_setup set to default.
[16:15:30.322] INFO: 1 hot pixels found in step 4
[16:15:31.314] INFO: Collecting data for 5 seconds...
[16:15:36.333] INFO: Done with hot pixel readout
[16:15:47.476] INFO: PixTest:: pg_setup set to default.
[16:15:47.477] INFO: 1 hot pixels found in step 5
[16:15:48.469] INFO: Collecting data for 5 seconds...
[16:15:53.488] INFO: Done with hot pixel readout
[16:16:04.952] INFO: PixTest:: pg_setup set to default.
[16:16:04.953] INFO: 2 hot pixels found in step 6
[16:16:05.945] INFO: Collecting data for 5 seconds...
[16:16:10.964] INFO: Done with hot pixel readout
[16:16:22.579] INFO: PixTest:: pg_setup set to default.
[16:16:22.580] INFO: 0 hot pixels found in step 7
[16:16:22.617] INFO: 0 hot pixels could not be trimmed and have been masked.
[16:16:22.620] INFO: PixTest::trimHotPixels() done
[16:16:22.620] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C0.dat
[16:16:22.635] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C1.dat
[16:16:22.644] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C2.dat
[16:16:22.651] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C3.dat
[16:16:22.656] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C4.dat
[16:16:22.661] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C5.dat
[16:16:22.667] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C6.dat
[16:16:22.672] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C7.dat
[16:16:22.678] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C8.dat
[16:16:22.683] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C9.dat
[16:16:22.689] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C10.dat
[16:16:22.694] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C11.dat
[16:16:22.700] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C12.dat
[16:16:22.705] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C13.dat
[16:16:22.711] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C14.dat
[16:16:22.716] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C15.dat
[16:16:22.721] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//defaultMaskFile.dat
[16:16:22.732] INFO: enter test to run
[16:16:45.592] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[16:16:45.592] INFO: running: highrate
[16:16:45.596] INFO: ----------------------------------------------------------------------
[16:16:45.596] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[16:16:45.596] INFO: ----------------------------------------------------------------------
[16:16:45.596] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[16:16:45.596] INFO: edge/corner pixel THR is adjusted
[16:16:45.596] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:16:46.554] INFO: Collecting data for 1 seconds...
[16:16:47.558] INFO: Done with hot pixel readout
[16:16:51.589] INFO: PixTest:: pg_setup set to default.
[16:16:51.590] INFO: 0 hot pixels found in step 0
[16:16:51.596] INFO: 0 hot pixels could not be trimmed and have been masked.
[16:16:51.685] INFO: PixTest::trimHotPixels() done
[16:16:51.685] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C0.dat
[16:16:51.697] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C1.dat
[16:16:51.704] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C2.dat
[16:16:51.709] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C3.dat
[16:16:51.715] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C4.dat
[16:16:51.720] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C5.dat
[16:16:51.726] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C6.dat
[16:16:51.731] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C7.dat
[16:16:51.737] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C8.dat
[16:16:51.742] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C9.dat
[16:16:51.747] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C10.dat
[16:16:51.753] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C11.dat
[16:16:51.759] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C12.dat
[16:16:51.764] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C13.dat
[16:16:51.769] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C14.dat
[16:16:51.775] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//trimParameters35_C15.dat
[16:16:51.780] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//defaultMaskFile.dat
[16:16:51.811] INFO: enter test to run
[16:17:15.559] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[16:17:15.559] INFO: running: xray
[16:17:15.561] INFO: ----------------------------------------------------------------------
[16:17:15.561] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:17:15.561] INFO: ----------------------------------------------------------------------
[16:17:16.523] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:17:28.179] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[16:17:33.810] ERROR: <datapipe.cc/CheckEventValidity:L480> Channel 0 has NoTokenPass but 7 ROCs were found
[16:17:33.810] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 1 Number of ROCs (7) != Token Chain Length (8)
[16:17:33.810] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[16:17:33.810] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a04a 8000 43c8 43c8 43c8 43c8 43c8 43c8 c5 2a47 43c8 dd 2a4f 43c8 449 2a4d e000 c000
[16:17:33.810] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a044 80b1 47c8 47c8 408 2047 47c8 47c8 47c8 4e0 2465 503 2267 47c8 5d 2864 2d0 266d 47c8 47c8 e000 c000
[16:17:33.811] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a045 80c0 47c8 47c8 47c8 619 2841 47c8 47c8 47c8 47c8 9a 242d 47c8 24a 2445 24a 2a49 e000 c000
[16:17:33.811] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a046 8000 47c8 47c8 47c8 842 284a 47c8 47c8 47c8 47c8 47c8 e000 c000
[16:17:33.811] ERROR: <datapipe.cc/Read:L166> ====== 2 ====== a047 8040 47c8 47c8 47c8 47c8 47c8 47c8 a 284d 47c8 111 264f 689 2644 596 2ffe 0 20ff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff
[16:17:33.811] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a048 80b1 43c8 43c8 43c8 43c8 a 284d 300 2422 43c8 6c3 2a4c 43c8 712 2080 711 284c 43c8 208 262f 43c8 e000 c000
[16:17:33.811] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a049 80c0 43c8 43c8 43c8 43c8 43c8 43c8 43c8 492 2247 43c8 e000 c000
[16:17:33.811] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[16:17:33.811] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a14a 8000 43c8 4cc 224e 43c8 613 204f 43c8 29c 2a4c 6ca 2867 43c8 43c8 43c8 220 264f 43c8 55c 2046 43c8 e000 c000
[16:17:33.811] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a144 80b1 47c8 47c8 cc 2445 47c8 47c8 74d 2644 47c8 47c8 47c8 819 264d 47c8 e000 c000
[16:17:33.811] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a145 80c0 47c8 47c8 47c8 443 204f 47c8 47c8 84b 2249 47c8 47c8 47c8 e000 c000
[16:17:33.811] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a146 8000 47c8 47c8 47c8 47c8 40d 2045 47c8 47c8 47c8 47c8 e000 c000
[16:17:33.811] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a147 8040 47c8 47c8 19 2847 10a 2a4f 47c8 553 284f 54d 264b 43c8 6d4 2a04 70 22a7 43c8 43c8 43c8 e000 c000
[16:17:33.811] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a148 80b1 43c8 43c8 81c 2625 43c8 342 2629 4d1 2249 50a 2045 43c8 43c8 43c8 43c8 43c8 e000 c000
[16:17:33.811] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a149 80c0 43c8 43c8 6cd 2245 43c8 43c8 43c8 212 222f 28b 264c 43c8 43c8 43c8 e000 c000
[16:17:36.150] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 0 Number of ROCs (6) != Token Chain Length (8)
[16:17:36.151] ERROR: <datapipe.cc/CheckEventValidity:L480> Channel 1 has NoTokenPass but 7 ROCs were found
[16:17:36.151] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[16:17:36.151] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0d6 8000 43c8 43c8 114 282f 14b 2445 558 204c 43c8 43c8 43c8 53 206d 30d 244d 43c8 70b 2445 43c8 2cb 2a49 43c8 450 2445 e000 c000
[16:17:36.151] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0d0 80b1 47c8 47c8 47c8 644 2a2f 47c8 118 2627 47c8 47c8 81 284c 47c8 47c8 e000 c000
[16:17:36.151] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0d1 80c0 47c8 422 2242 47c8 47c8 47c8 420 2841 47c9 47c9 15b 2465 47c9 47c9 243 2269 e000 c000
[16:17:36.151] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0d2 8000 47c8 10 240d 47c8 dd 244c 47c9 47c9 47c8 89 2448 113 2863 4cd 2461 80a 2247 47c8 47c9 47c9 e000 c000
[16:17:36.151] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0d3 8040 47c8 47c9 412 2a45 47c8 47c9 47c8 50d 2444 43c9 1055 2579 616 e01f c0e5
[16:17:36.151] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0d4 80b1 43c8 43c8 43c8 9d 2a41 43c8 43c8 43c8 30d 224f 43c8 43c8 e000 c000
[16:17:36.151] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0d5 80c0 43c8 43c8 862 2a49 43c8 418 2645 43c8 43c8 43c8 43c8 15 244d d 2461 43c8 e000 c000
[16:17:36.151] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[16:17:36.151] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1d6 8000 43c8 43c8 48b 264d 50c 2426 43c8 c8 2445 811 2a62 43c8 43c8 309 2644 43c8 415 2449 43c8 43c8 e000 c000
[16:17:36.151] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1d0 80b1 47c9 47c9 240 2a2d 47c9 47c9 410 262f 47c9 47c9 47c9 47c9 e000 c000
[16:17:36.151] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1d1 80c0 47c8 47c8 142 2a62 75c 2044 47c8 854 2649 47c8 47c9 47c9 47c9 47c9 e000 c000
[16:17:36.151] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1d2 8000 47c8 47c8 47c9 47c9 47c8 47c8 47c9 47c9 e000 c000
[16:17:36.151] ERROR: <datapipe.cc/Read:L166> ====== 2 ====== a1d3 8040 47c8 47c9 119 2265 47c8 47c9 43c8 43c9 43c8 802 3643 a9f 29ea b60 201c 0 21ff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff
[16:17:36.151] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1d4 80b1 43c8 43c8 41c 242d 43c8 349 2a2d 43c8 43c8 43c8 43c8 262 2a2f 43c8 860 264f e000 c000
[16:17:36.151] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1d5 80c0 43c8 43c8 43c8 43c8 43c8 6c4 2241 43c8 415 204e 43c8 43c8 e000 c000
[16:17:39.705] ERROR: <datapipe.cc/CheckEventValidity:L480> Channel 0 has NoTokenPass but 4 ROCs were found
[16:17:39.705] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 1 Number of ROCs (7) != Token Chain Length (8)
[16:17:39.705] ERROR: <datapipe.cc/CheckEventID:L463> Channel 0 Event ID mismatch: local ID (38) != TBM ID (63)
[16:17:39.705] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 0 Number of ROCs (0) != Token Chain Length (8)
[16:17:39.706] ERROR: <datapipe.cc/CheckEventID:L463> Channel 0 Event ID mismatch: local ID (64) != TBM ID (38)
[16:17:39.706] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[16:17:39.706] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a128 80b1 43c8 43c8 248 2a45 43c8 43c8 721 224d 43c8 43c8 43c8 43c8 e000 c000
[16:17:39.706] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a122 8000 47c8 47c8 47c9 c9 204c 47c9 47c8 47c8 47c9 47c9 e000 c000
[16:17:39.706] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a123 8040 47c8 47c9 47c8 47c9 809 2a4d 47c8 47c9 34c 2669 35d 2665 47c8 47c9 e000 c000
[16:17:39.706] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a124 80b1 47c8 47c8 47c8 47c8 47c8 47c8 47c8 47c8 41b 2a4d e000 c000
[16:17:39.706] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a125 80c0 47c8 47c8 43c8 43c8 51 2041 43c8 43c8 43c8 e000 c000
[16:17:39.706] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a126 8000 43c8 281 262f 43c8 65d 224f 6cc 2243 43c8 458 2047 43c8 43c8 43c8 43c8 43c8 e000 c000
[16:17:39.706] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a127 8040 43c8 43c8 50 2445 43c8 43c8 6d3 2245 43c8 4d 2841 43c8 43c8 43c8 e000 c000
[16:17:39.706] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[16:17:39.706] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a029 80c0 43c8 43c8 43c8 43c8 29b 264d 43c8 43c8 43c8 319 204d 43c8 e000 c000
[16:17:39.706] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a024 80b1 47c8 47c8 220 2045 47c8 47c8 47c8 818 2a40 47c8 70a 204d 47c8 71b 204f 47c8 e000 c000
[16:17:39.706] ERROR: <datapipe.cc/Read:L166> ====== 2 ====== a025 80c0 47c8 47c8 47c8 43c8 43c8 4cc
[16:17:39.706] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a03f 80c3 60d 43c8 e000 c000
[16:17:39.706] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a026 8000 43c8 43c8 43c8 43c8 418 2a4f 43c8 4d5 224d 43c8 43c8 43c8 e000 c000
[16:17:39.706] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a027 8040 43c8 43c8 43c8 45b 284d 43c8 699 2a47 43c8 43c8 c 2629 43c8 43c8 e000 c000
[16:17:39.706] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a028 80b1 43c8 710 2844 43c8 43c8 43c8 d4 2a42 65d 2245 688 2646 43c8 43c8 43c8 31b 2268 43c8 114 2a45 644 2841 e000 c000
[16:17:41.023] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 1 Number of ROCs (7) != Token Chain Length (8)
[16:17:41.023] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 0 Number of ROCs (6) != Token Chain Length (8)
[16:17:41.023] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[16:17:41.023] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1ee 8000 43c8 449 2468 43c8 4c1 222c 43c8 43c8 613 2461 640 242b 43c8 10 202f da 2042 dd 224c 293 2245 43c8 44c 242f 441 2a44 43c8 43c8 e000 c000
[16:17:41.023] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1e8 80b1 47c8 47c8 47c8 47c8 47c8 95 2847 44c 262f 47c8 47c8 47c8 e000 c000
[16:17:41.023] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1e9 80c0 47c8 47c8 47c8 81b 204f 47c8 47c8 47c8 47c8 47c8 e000 c000
[16:17:41.023] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1ea 8000 47c8 4cb 2269 47c8 47c8 47c8 47c8 80d 2641 47c8 24a 206d 47c8 47c8 e000 c000
[16:17:41.023] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1eb 8040 47c8 43c8 43c8 61d 2a2f 43c8 43c8 43c8 43c8 e000 c000
[16:17:41.023] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1ec 80b1 43c8 11d 262e 43c8 35a 2045 35a 224c 43c8 40c 224c 43c8 43c8 611 2026 43c8 43c8 43c8 310 282c e000 c000
[16:17:41.023] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1ed 80c0 43c8 43c8 43c8 451 204d 489 2069 43c8 43c8 15d 2a69 43c8 303 2a4e 43c8 43c8 e000 c000
[16:17:41.023] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[16:17:41.023] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0ee 8000 43c8 43c8 43c8 43c8 43c8 610 2241 43c8 43c8 43c8 e000 c000
[16:17:41.023] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0e8 80b1 47c8 47c8 52 2462 47c8 47c8 47c8 47c8 458 264c 4cb 224f 47c8 94 242d 6c4 2829 47c8 e000 c000
[16:17:41.023] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0e9 80c0 47c8 47c8 47c8 47c8 47c8 47c8 47c8 47c8 e000 c000
[16:17:41.023] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0ea 8000 47c8 47c8 47c8 482 204f 47c8 47c8 6d1 2849 47c8 47c8 47c8 2a2 2061 e000 c000
[16:17:41.024] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0eb 8040 47c8 25b 2247 43c8 43c8 554 2489 a49 43c8 75a 2066 43c8 43c8 43c8 e000 c000
[16:17:41.024] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0ec 80b1 43c8 43c8 43c8 43c8 75a 2045 43c8 43c8 244 222d 43c8 842 2a2b 43c8 e000 c000
[16:17:41.024] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0ed 80c0 43c8 155 2647 43c8 43c8 43c8 43c8 43c8 4ca 2067 43c8 24c 284f 85a 2242 43c8 e000 c000
[16:17:42.195] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 1 Number of ROCs (6) != Token Chain Length (8)
[16:17:42.196] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 0 Number of ROCs (6) != Token Chain Length (8)
[16:17:42.196] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[16:17:42.196] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1b4 80b1 47c8 612 264f 47c8 47c8 47c8 450 2041 47c8 47c8 47c8 47c8 e000 c000
[16:17:42.196] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1ae 8000 43c8 4c8 2a68 43c8 43c8 20c 202d 43c8 43c8 559 206d 43c8 43c8 43c8 e000 c000
[16:17:42.196] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1af 8040 43ca 745 222a 43ca 43ca 43ca 43ca 711 242d 43ca 43ca 43ca e000 c000
[16:17:42.196] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1b0 80b1 43c9 515 2464 43c9 43c9 14c 222f 43c9 43c9 41b 284d 651 2444 641 2649 43c9 43c9 43c9 e000 c000
[16:17:42.196] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1b1 80c0 47c8 57c8 47c8 312 29c0 704 47c9 47c9 47c9 47c9 e000 c000
[16:17:42.196] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1b2 8000 47c8 492 262d 47c8 49c 2a4c 47c9 47c9 47c8 47c8 47c9 47c9 e000 c000
[16:17:42.196] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1b3 8040 47c8 47c9 47c8 47c9 47c8 47c9 4d5 2445 47c8 47c9 e000 c000
[16:17:42.196] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[16:17:42.196] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0b4 80b1 47c8 47c8 47c8 47c8 244 2029 47c8 150 2648 688 2049 47c8 299 2649 47c8 47c8 e000 c000
[16:17:42.196] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0ae 8000 43c8 43c8 285 202c 43c8 43c8 43c8 43c8 65a 2245 43c8 43c8 30b 204f e000 c000
[16:17:42.196] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0af 8040 43ca 43ca 43ca 43ca 685 2863 43ca 43ca 43ca 4d8 2a60 718 204a 43ca e000 c000
[16:17:42.196] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0b0 80b1 43c8 43c8 43c8 513 2464 43c8 310 282c 691 2240 43c8 43c8 43c8 43c8 e000 c000
[16:17:42.196] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0b1 80c0 47c8 57c8 47c8 47c8 d00 2f09 47c9 81d 2a49 47c9 e000 c000
[16:17:42.196] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0b2 8000 47c8 47c8 47c9 47c9 47c8 47c8 47c9 47c9 e000 c000
[16:17:42.196] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0b3 8040 47c8 47c9 47c8 47c9 47c8 47c9 47c8 47c9 e000 c000
[16:17:43.349] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 1 Number of ROCs (6) != Token Chain Length (8)
[16:17:43.349] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 0 Number of ROCs (6) != Token Chain Length (8)
[16:17:43.349] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[16:17:43.349] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a17a 8000 47c8 47c8 47c8 47c8 813 2461 47c8 47c8 47c8 47c8 840 2642 e000 c000
[16:17:43.349] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a174 80b1 43c8 43c8 43c8 845 2a4d 43c8 43c8 43c8 43c8 43c8 e000 c000
[16:17:43.349] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a175 80c0 43c8 43c8 43c8 43c8 43c8 43c8 43c8 43c8 e000 c000
[16:17:43.349] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a176 8000 43c8 43c8 249 2842 43c8 43c8 43c8 43c8 43c8 43c8 e000 c000
[16:17:43.349] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a177 8040 47c8 47c8 47ca 54 2384 d20 47c8 47c8 47c8 47c8 e000 c000
[16:17:43.350] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a178 80b1 47c8 47c8 d 2449 47c8 47c8 47c8 47c8 47c8 47c8 e000 c000
[16:17:43.350] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a179 80c0 47c8 709 2242 748 2443 47c8 2c1 2245 47c8 262 2485 47c8 553 284d 47c8 47c8 82 2629 47c8 47c8 25d 2a4c e000 c000
[16:17:43.350] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[16:17:43.350] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a07a 8000 47c8 65b 2646 47c8 47c8 47c8 47c8 47c8 47c8 47c8 8b 2669 e000 c000
[16:17:43.350] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a074 80b1 43c8 43c8 5a 204f 43c8 43c8 43c8 43c8 43c8 43c8 e000 c000
[16:17:43.350] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a075 80c0 43c8 43c8 43c8 21c 2061 70d 2840 43c8 752 2442 43c8 861 284f 43c8 43c8 43c8 658 2441 e000 c000
[16:17:43.350] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a076 8000 43c8 43c8 43c8 43c8 43c8 43c8 43c8 43c8 a 2225 e000 c000
[16:17:43.350] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a077 8040 47c8 47c8 7f1 25f8 55 204c 848 222d 47c8 47c8 47c8 47c8 e000 c000
[16:17:43.350] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a078 80b1 47c8 47c8 47c8 47c8 47c8 454 204c 47c8 47c8 47c8 e000 c000
[16:17:43.350] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a079 80c0 47c8 655 246a 47c8 47c8 47c8 31b 2647 47c8 47c8 47c8 6cd 2644 47c8 419 2461 e000 c000
[16:17:59.096] INFO: Resuming triggers.
[16:18:10.752] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[16:18:40.872] INFO: Resuming triggers.
[16:18:52.525] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[16:19:22.062] INFO: Resuming triggers.
[16:19:33.718] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[16:20:03.309] INFO: Resuming triggers.
[16:20:14.966] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[16:20:44.529] INFO: Resuming triggers.
[16:20:56.188] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[16:21:25.669] INFO: Resuming triggers.
[16:21:37.326] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[16:22:06.866] INFO: Resuming triggers.
[16:22:18.525] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[16:22:48.084] INFO: Resuming triggers.
[16:22:55.184] INFO: data taking finished, elapsed time: 100 seconds.
[16:23:13.423] INFO: PixTest:: pg_setup set to default.
[16:23:13.426] INFO: PixTestXray::doPhRun() done
[16:23:13.653] INFO: enter test to run
[16:23:58.125] INFO: test: timing no parameter change
[16:23:58.125] INFO: running: timing
[16:23:58.148] INFO: ######################################################################
[16:23:58.148] INFO: PixTestTiming::doTest()
[16:23:58.148] INFO: ######################################################################
[16:23:58.149] INFO: ----------------------------------------------------------------------
[16:23:58.149] INFO: PixTestTiming::TBMPhaseScan()
[16:23:58.149] INFO: ----------------------------------------------------------------------
[16:34:32.036] INFO: TBM Phase Settings: 16
[16:34:32.036] INFO: 400MHz Phase: 4
[16:34:32.036] INFO: 160MHz Phase: 0
[16:34:32.036] INFO: Functional Phase Area: 3
[16:34:32.046] INFO: Test took 633898 ms.
[16:34:32.046] INFO: PixTestTiming::TBMPhaseScan() done.
[16:34:32.047] INFO: ----------------------------------------------------------------------
[16:34:32.047] INFO: PixTestTiming::ROCDelayScan()
[16:34:32.047] INFO: ----------------------------------------------------------------------
[16:36:39.211] INFO: ROC Delay Settings: 228
[16:36:39.211] INFO: ROC Header-Trailer/Token Delay: 11
[16:36:39.211] INFO: ROC Port 0 Delay: 4
[16:36:39.211] INFO: ROC Port 1 Delay: 4
[16:36:39.211] INFO: Functional ROC Area: 5
[16:36:39.214] INFO: Test took 127167 ms.
[16:36:39.214] INFO: PixTestTiming::ROCDelayScan() done.
[16:36:39.215] INFO: ----------------------------------------------------------------------
[16:36:39.215] INFO: PixTestTiming::TimingTest()
[16:36:39.215] INFO: ----------------------------------------------------------------------
[16:36:55.337] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:37:10.310] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:37:25.242] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:37:40.205] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:37:55.156] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:38:10.146] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:38:25.111] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:38:40.099] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:38:55.067] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:10.052] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:10.433] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:10.447] INFO: ----------------------------------------------------------------------
[16:39:10.447] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[16:39:10.447] INFO: ----------------------------------------------------------------------
[16:39:10.447] INFO: ----------------------------------------------------------------------
[16:39:10.447] INFO: Read back bit status: 1
[16:39:10.447] INFO: ----------------------------------------------------------------------
[16:39:10.447] INFO: ----------------------------------------------------------------------
[16:39:10.447] INFO: Timings are good!
[16:39:10.447] INFO: ----------------------------------------------------------------------
[16:39:10.447] INFO: Test took 151232 ms.
[16:39:10.447] INFO: PixTestTiming::TimingTest() done.
[16:39:10.459] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//tbmParameters_C0a.dat
[16:39:10.459] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-49_FPIXTest-17C-FNAL-161115-1301-150V_2016-11-15_13h01m_1479236478/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:39:10.459] INFO: PixTestTiming::doTest took 912314 ms.
[16:39:10.459] INFO: PixTestTiming::doTest() done
[16:39:10.460] INFO: Write out TBMPhaseScan_0_V0
[16:39:10.460] INFO: Write out TBMPhaseScan_1_V0
[16:39:10.460] INFO: Write out CombinedTBMPhaseScan_V0
[16:39:10.485] INFO: Write out ROCDelayScan3_V0
[16:39:10.486] INFO: enter test to run
[16:39:55.198] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[16:39:55.198] INFO: running: xray
[16:39:55.200] INFO: ----------------------------------------------------------------------
[16:39:55.200] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:39:55.200] INFO: ----------------------------------------------------------------------
[16:39:56.173] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:40:07.836] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[16:40:37.852] INFO: Resuming triggers.
[16:40:49.509] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[16:41:19.050] INFO: Resuming triggers.
[16:41:30.707] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[16:42:00.593] INFO: Resuming triggers.
[16:42:12.249] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[16:42:41.791] INFO: Resuming triggers.
[16:42:53.447] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[16:43:23.377] INFO: Resuming triggers.
[16:43:35.037] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[16:44:05.273] INFO: Resuming triggers.
[16:44:16.933] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[16:44:47.023] INFO: Resuming triggers.
[16:44:58.681] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[16:45:28.289] INFO: Resuming triggers.
[16:45:35.396] INFO: data taking finished, elapsed time: 100 seconds.
[16:45:53.582] INFO: PixTest:: pg_setup set to default.
[16:45:53.586] INFO: PixTestXray::doPhRun() done
[16:45:53.751] INFO: enter test to run
[16:47:20.491] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[16:47:20.491] INFO: running: xray
[16:47:20.492] INFO: ----------------------------------------------------------------------
[16:47:20.492] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:47:20.492] INFO: ----------------------------------------------------------------------
[16:47:21.459] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:47:28.316] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[16:47:58.827] INFO: Resuming triggers.
[16:48:05.689] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[16:48:36.125] INFO: Resuming triggers.
[16:48:42.987] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[16:49:13.366] INFO: Resuming triggers.
[16:49:20.223] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[16:49:50.556] INFO: Resuming triggers.
[16:49:57.412] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[16:50:27.762] INFO: Resuming triggers.
[16:50:34.620] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[16:51:04.966] INFO: Resuming triggers.
[16:51:11.826] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[16:51:42.198] INFO: Resuming triggers.
[16:51:49.057] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[16:52:19.436] INFO: Resuming triggers.
[16:52:26.295] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[16:52:57.695] INFO: Resuming triggers.
[16:53:04.550] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[16:53:35.741] INFO: Resuming triggers.
[16:53:42.602] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[16:54:13.852] INFO: Resuming triggers.
[16:54:20.710] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[16:54:51.896] INFO: Resuming triggers.
[16:54:58.758] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[16:55:29.397] INFO: Resuming triggers.
[16:55:36.257] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[16:56:07.953] INFO: Resuming triggers.
[16:56:12.283] INFO: data taking finished, elapsed time: 100 seconds.
[16:56:32.515] INFO: PixTest:: pg_setup set to default.
[16:56:32.518] INFO: PixTestXray::doPhRun() done
[16:56:32.666] INFO: enter test to run
[16:57:26.343] INFO: test: HighRate no parameter change
[16:57:26.343] INFO: running: highrate
[16:57:26.407] INFO: ----------------------------------------------------------------------
[16:57:26.407] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[16:57:26.407] INFO: ----------------------------------------------------------------------
[16:57:26.577] INFO: Expecting 768 events.
[16:57:27.731] INFO: 768 events read in total (431ms).
[16:57:27.732] INFO: Test took 1288ms.
[16:57:28.534] INFO: Expecting 41600 events.
[16:57:31.701] INFO: 41600 events read in total (2640ms).
[16:57:31.702] INFO: Test took 3901ms.
[16:57:31.739] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:57:32.449] INFO: Expecting 41600 events.
[16:57:35.712] INFO: 41600 events read in total (2736ms).
[16:57:35.713] INFO: Test took 3939ms.
[16:57:35.747] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:57:36.472] INFO: Expecting 41600 events.
[16:57:39.756] INFO: 41600 events read in total (2757ms).
[16:57:39.757] INFO: Test took 3993ms.
[16:57:39.790] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:57:40.514] INFO: Expecting 41600 events.
[16:57:43.832] INFO: 41600 events read in total (2791ms).
[16:57:43.833] INFO: Test took 4026ms.
[16:57:43.867] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:57:44.586] INFO: Expecting 41600 events.
[16:57:47.835] INFO: 41600 events read in total (2722ms).
[16:57:47.836] INFO: Test took 3952ms.
[16:57:47.870] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:57:48.595] INFO: Expecting 41600 events.
[16:57:51.874] INFO: 41600 events read in total (2752ms).
[16:57:51.875] INFO: Test took 3988ms.
[16:57:51.908] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:57:52.631] INFO: Expecting 41600 events.
[16:57:55.980] INFO: 41600 events read in total (2822ms).
[16:57:55.981] INFO: Test took 4056ms.
[16:57:56.015] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:57:56.737] INFO: Expecting 41600 events.
[16:57:59.991] INFO: 41600 events read in total (2727ms).
[16:57:59.992] INFO: Test took 3960ms.
[16:58:00.025] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:00.739] INFO: Expecting 41600 events.
[16:58:03.987] INFO: 41600 events read in total (2721ms).
[16:58:03.988] INFO: Test took 3945ms.
[16:58:04.022] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:04.745] INFO: Expecting 41600 events.
[16:58:08.074] INFO: 41600 events read in total (2802ms).
[16:58:08.075] INFO: Test took 4036ms.
[16:58:08.108] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:08.830] INFO: Expecting 41600 events.
[16:58:12.131] INFO: 41600 events read in total (2774ms).
[16:58:12.132] INFO: Test took 4007ms.
[16:58:12.165] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:12.892] INFO: Expecting 41600 events.
[16:58:16.118] INFO: 41600 events read in total (2700ms).
[16:58:16.118] INFO: Test took 3935ms.
[16:58:16.151] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:16.881] INFO: Expecting 41600 events.
[16:58:20.107] INFO: 41600 events read in total (2699ms).
[16:58:20.108] INFO: Test took 3940ms.
[16:58:20.141] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:20.864] INFO: Expecting 41600 events.
[16:58:24.094] INFO: 41600 events read in total (2703ms).
[16:58:24.095] INFO: Test took 3935ms.
[16:58:24.127] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:24.855] INFO: Expecting 41600 events.
[16:58:28.090] INFO: 41600 events read in total (2708ms).
[16:58:28.091] INFO: Test took 3946ms.
[16:58:28.123] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:28.850] INFO: Expecting 41600 events.
[16:58:32.075] INFO: 41600 events read in total (2698ms).
[16:58:32.076] INFO: Test took 3935ms.
[16:58:32.109] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:32.837] INFO: Expecting 41600 events.
[16:58:36.049] INFO: 41600 events read in total (2686ms).
[16:58:36.050] INFO: Test took 3922ms.
[16:58:36.082] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:36.811] INFO: Expecting 41600 events.
[16:58:40.041] INFO: 41600 events read in total (2703ms).
[16:58:40.042] INFO: Test took 3943ms.
[16:58:40.075] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:40.798] INFO: Expecting 41600 events.
[16:58:43.003] INFO: 41600 events read in total (2678ms).
[16:58:43.004] INFO: Test took 3912ms.
[16:58:44.036] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:44.764] INFO: Expecting 41600 events.
[16:58:47.803] INFO: 41600 events read in total (2512ms).
[16:58:47.803] INFO: Test took 3749ms.
[16:58:47.836] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:58:48.205] INFO: enter test to run
[16:59:18.510] INFO: test: HighRate no parameter change
[16:59:18.511] INFO: running: highrate
[16:59:18.512] INFO: ----------------------------------------------------------------------
[16:59:18.512] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:59:18.512] INFO: ----------------------------------------------------------------------
[16:59:19.126] INFO: Expecting 208000 events.
[16:59:30.901] INFO: 208000 events read in total (11248ms).
[16:59:30.904] INFO: Test took 12381ms.
[16:59:31.043] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:59:31.293] INFO: number of dead pixels (per ROC): 1 0 0 0 0 3 8 0 1 1 0 0 0 0 6 0
[16:59:31.311] INFO: number of red-efficiency pixels: 77 48 81 105 112 137 157 90 77 126 123 99 99 52 27 32
[16:59:31.311] INFO: number of X-ray hits detected: 65809 43786 61268 93863 97093 103939 104284 71997 67121 96373 97968 82672 85522 54170 20533 24582
[16:59:31.311] 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:59:31.311] INFO: number of Vcal hits detected: 207873 207952 207918 207891 207888 207714 207447 207906 207872 207822 207876 207901 207900 207948 207679 207968
[16:59:31.311] 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 100.0 100.0 100.0 100.0 100.0
[16:59:31.312] INFO: Vcal hit overall efficiency (%): 99.9 100.0 100.0 99.9 99.9 99.9 99.7 100.0 99.9 99.9 99.9 100.0 100.0 100.0 99.8 100.0
[16:59:31.312] INFO: X-ray hit rate [MHz/cm2]: 19.3 12.8 18.0 27.5 28.5 30.5 30.6 21.1 19.7 28.2 28.7 24.2 25.1 15.9 6.0 7.2
[16:59:31.312] INFO: PixTestHighRate::doXPixelAlive() done
[16:59:31.360] INFO: PixTest:: pg_setup set to default.
[16:59:31.377] INFO: enter test to run
[16:59:52.438] INFO: test: HighRate no parameter change
[16:59:52.438] INFO: running: highrate
[16:59:52.439] INFO: ----------------------------------------------------------------------
[16:59:52.439] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:59:52.439] INFO: ----------------------------------------------------------------------
[16:59:53.059] INFO: Expecting 208000 events.
[17:00:06.482] INFO: 208000 events read in total (12897ms).
[17:00:06.488] INFO: Test took 14036ms.
[17:00:06.778] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:00:07.078] INFO: number of dead pixels (per ROC): 1 0 0 0 0 3 8 0 1 1 0 0 0 0 6 0
[17:00:07.078] INFO: number of red-efficiency pixels: 249 115 252 393 316 388 502 316 257 369 448 317 261 171 53 71
[17:00:07.078] INFO: number of X-ray hits detected: 140092 93588 131152 199800 206985 221103 221366 153418 142545 204168 207468 175160 183080 115469 44416 51466
[17:00:07.078] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[17:00:07.078] INFO: number of Vcal hits detected: 207674 207875 207735 207582 207663 207430 207062 207661 207675 207549 207524 207663 207732 207824 207650 207926
[17:00:07.078] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.9 99.8 99.8 99.8 99.9 99.8 99.8 99.8 99.9 99.9 100.0 100.0
[17:00:07.078] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.9 99.8 99.8 99.7 99.5 99.8 99.8 99.8 99.8 99.8 99.9 99.9 99.8 100.0
[17:00:07.078] INFO: X-ray hit rate [MHz/cm2]: 41.1 27.4 38.4 58.6 60.7 64.8 64.9 45.0 41.8 59.8 60.8 51.3 53.7 33.8 13.0 15.1
[17:00:07.078] INFO: PixTestHighRate::doXPixelAlive() done
[17:00:07.127] INFO: PixTest:: pg_setup set to default.
[17:00:07.144] INFO: enter test to run
[17:00:31.273] INFO: test: HighRate no parameter change
[17:00:31.273] INFO: running: highrate
[17:00:31.274] INFO: ----------------------------------------------------------------------
[17:00:31.274] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[17:00:31.274] INFO: ----------------------------------------------------------------------
[17:00:31.893] INFO: Expecting 208000 events.
[17:00:47.143] INFO: 208000 events read in total (14723ms).
[17:00:47.150] INFO: Test took 15864ms.
[17:00:47.581] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:00:47.928] INFO: number of dead pixels (per ROC): 1 0 0 0 0 3 8 0 1 1 0 0 0 0 6 0
[17:00:47.928] INFO: number of red-efficiency pixels: 496 293 551 904 791 812 1146 664 551 948 974 717 557 352 75 105
[17:00:47.928] INFO: number of X-ray hits detected: 209844 139960 196701 300452 309742 331733 332907 229600 214363 307106 312548 263706 274497 173294 66528 77906
[17:00:47.928] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[17:00:47.928] INFO: number of Vcal hits detected: 207362 207680 207326 206913 207083 206886 206131 207201 207304 206801 206810 207148 207362 207610 207630 207893
[17:00:47.928] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.5 99.6 99.6 99.4 99.7 99.7 99.5 99.5 99.6 99.7 99.8 100.0 100.0
[17:00:47.928] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.7 99.5 99.6 99.5 99.1 99.6 99.7 99.4 99.4 99.6 99.7 99.8 99.8 99.9
[17:00:47.928] INFO: X-ray hit rate [MHz/cm2]: 61.5 41.0 57.7 88.1 90.8 97.2 97.6 67.3 62.8 90.0 91.6 77.3 80.5 50.8 19.5 22.8
[17:00:47.928] INFO: PixTestHighRate::doXPixelAlive() done
[17:00:47.977] INFO: PixTest:: pg_setup set to default.
[17:00:47.994] INFO: enter test to run
[17:01:09.462] INFO: test: exit no parameter change
[17:01:10.162] QUIET: Connection to board 30 closed.
[17:01:10.240] INFO: pXar: this is the end, my friend