[16:05:12.225] INFO: *** Welcome to pxar ***
[16:05:12.225] INFO: *** Today: 2016/09/15
[16:05:14.412] INFO: *** Version: v1.9.0-818-g96727
[16:05:14.412] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//dacParameters35_C15.dat
[16:05:14.498] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:05:14.498] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//defaultMaskFile.dat
[16:05:14.501] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C15.dat
[16:05:14.634] INFO: clk: 4
[16:05:14.634] INFO: ctr: 4
[16:05:14.634] INFO: sda: 19
[16:05:14.634] INFO: tin: 9
[16:05:14.634] INFO: level: 15
[16:05:14.634] INFO: triggerdelay: 0
[16:05:14.634] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[16:05:14.634] INFO: Log level: INFO
[16:05:14.678] QUIET: Connection to board DTB_WREKRL opened.
[16:05:14.681] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 33
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREKRL
MAC address: 40D855118021
Hostname: pixelDTB033
Comment:
------------------------------------------------------
[16:05:14.684] INFO: RPC call hashes of host and DTB match: 398089610
[16:05:16.236] INFO: DUT info:
[16:05:16.236] INFO: The DUT currently contains the following objects:
[16:05:16.237] INFO: 2 TBM Cores tbm08c (2 ON)
[16:05:16.237] INFO: TBM Core alpha (0): 7 registers set
[16:05:16.237] INFO: TBM Core beta (1): 7 registers set
[16:05:16.237] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[16:05:16.237] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[16:05:16.237] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[16:05:16.237] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[16:05:16.237] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[16:05:16.237] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[16:05:16.237] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[16:05:16.237] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[16:05:16.237] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[16:05:16.237] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[16:05:16.237] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[16:05:16.237] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[16:05:16.237] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[16:05:16.237] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[16:05:16.237] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[16:05:16.237] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[16:05:16.237] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[16:05:16.728] INFO: enter 'restricted' command line mode
[16:05:16.728] INFO: enter test to run
[16:05:20.830] INFO: test: PixelAlive no parameter change
[16:05:20.830] INFO: running: pixelalive
[16:05:20.915] INFO: ----------------------------------------------------------------------
[16:05:20.915] 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:05:20.915] INFO: ----------------------------------------------------------------------
[16:05:21.237] INFO: Expecting 41600 events.
[16:05:25.711] INFO: 41600 events read in total (3755ms).
[16:05:25.875] INFO: Test took 4956ms.
[16:05:25.888] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:05:26.699] INFO: PixTestAlive::aliveTest() done
[16:05:26.700] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 2 0 0 2 0 0 0 0 0 0
[16:05:26.948] INFO: enter test to run
[16:07:04.413] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[16:07:04.413] INFO: running: highrate
[16:07:04.476] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[16:07:04.933] INFO: ----------------------------------------------------------------------
[16:07:04.933] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[16:07:04.933] INFO: ----------------------------------------------------------------------
[16:07:04.933] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[16:07:04.933] INFO: edge/corner pixel THR is adjusted
[16:07:04.933] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:07:05.891] INFO: Collecting data for 5 seconds...
[16:07:10.911] INFO: Done with hot pixel readout
[16:07:23.057] INFO: PixTest:: pg_setup set to default.
[16:07:23.057] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[16:07:23.058] INFO: 17 hot pixels found in step 0
[16:07:24.052] INFO: Collecting data for 5 seconds...
[16:07:29.070] INFO: Done with hot pixel readout
[16:07:41.196] INFO: PixTest:: pg_setup set to default.
[16:07:41.197] INFO: 23 hot pixels found in step 1
[16:07:42.196] INFO: Collecting data for 5 seconds...
[16:07:47.214] INFO: Done with hot pixel readout
[16:07:59.435] INFO: PixTest:: pg_setup set to default.
[16:07:59.435] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[16:07:59.435] INFO: 17 hot pixels found in step 2
[16:08:00.430] INFO: Collecting data for 5 seconds...
[16:08:05.448] INFO: Done with hot pixel readout
[16:08:17.485] INFO: PixTest:: pg_setup set to default.
[16:08:17.486] INFO: 16 hot pixels found in step 3
[16:08:18.480] INFO: Collecting data for 5 seconds...
[16:08:23.498] INFO: Done with hot pixel readout
[16:08:35.899] INFO: PixTest:: pg_setup set to default.
[16:08:35.900] INFO: 16 hot pixels found in step 4
[16:08:36.895] INFO: Collecting data for 5 seconds...
[16:08:41.914] INFO: Done with hot pixel readout
[16:08:54.563] INFO: PixTest:: pg_setup set to default.
[16:08:54.564] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[16:08:54.564] INFO: 13 hot pixels found in step 5
[16:08:55.559] INFO: Collecting data for 5 seconds...
[16:09:00.578] INFO: Done with hot pixel readout
[16:09:13.124] INFO: PixTest:: pg_setup set to default.
[16:09:13.124] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[16:09:13.124] INFO: 20 hot pixels found in step 6
[16:09:14.119] INFO: Collecting data for 5 seconds...
[16:09:19.138] INFO: Done with hot pixel readout
[16:09:31.432] INFO: PixTest:: pg_setup set to default.
[16:09:31.433] INFO: 11 hot pixels found in step 7
[16:09:32.426] INFO: Collecting data for 5 seconds...
[16:09:37.443] INFO: Done with hot pixel readout
[16:09:49.505] INFO: PixTest:: pg_setup set to default.
[16:09:49.506] INFO: 14 hot pixels found in step 8
[16:09:50.500] INFO: Collecting data for 5 seconds...
[16:09:55.517] INFO: Done with hot pixel readout
[16:10:07.865] INFO: PixTest:: pg_setup set to default.
[16:10:07.865] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[16:10:07.866] INFO: 11 hot pixels found in step 9
[16:10:08.860] INFO: Collecting data for 5 seconds...
[16:10:13.880] INFO: Done with hot pixel readout
[16:10:26.335] INFO: PixTest:: pg_setup set to default.
[16:10:26.336] INFO: 10 hot pixels found in step 10
[16:10:27.331] INFO: Collecting data for 5 seconds...
[16:10:32.351] INFO: Done with hot pixel readout
[16:10:44.808] INFO: PixTest:: pg_setup set to default.
[16:10:44.808] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[16:10:44.808] INFO: 11 hot pixels found in step 11
[16:10:45.803] INFO: Collecting data for 5 seconds...
[16:10:50.823] INFO: Done with hot pixel readout
[16:11:03.083] INFO: PixTest:: pg_setup set to default.
[16:11:03.084] INFO: 12 hot pixels found in step 12
[16:11:04.080] INFO: Collecting data for 5 seconds...
[16:11:09.096] INFO: Done with hot pixel readout
[16:11:21.234] INFO: PixTest:: pg_setup set to default.
[16:11:21.234] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[16:11:21.235] INFO: 12 hot pixels found in step 13
[16:11:22.229] INFO: Collecting data for 5 seconds...
[16:11:27.245] INFO: Done with hot pixel readout
[16:11:39.378] INFO: PixTest:: pg_setup set to default.
[16:11:39.378] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[16:11:39.379] INFO: 15 hot pixels found in step 14
[16:11:39.417] INFO: 15 hot pixels could not be trimmed and have been masked.
[16:11:39.430] INFO: PixTest::trimHotPixels() done
[16:11:39.430] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C0.dat
[16:11:39.442] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C1.dat
[16:11:39.450] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C2.dat
[16:11:39.455] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C3.dat
[16:11:39.460] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C4.dat
[16:11:39.465] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C5.dat
[16:11:39.471] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C6.dat
[16:11:39.476] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C7.dat
[16:11:39.481] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C8.dat
[16:11:39.486] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C9.dat
[16:11:39.492] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C10.dat
[16:11:39.497] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C11.dat
[16:11:39.502] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C12.dat
[16:11:39.507] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C13.dat
[16:11:39.513] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C14.dat
[16:11:39.518] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C15.dat
[16:11:39.523] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//defaultMaskFile.dat
[16:11:39.533] INFO: enter test to run
[16:14:02.250] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[16:14:02.250] INFO: running: highrate
[16:14:02.255] INFO: ----------------------------------------------------------------------
[16:14:02.255] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[16:14:02.255] INFO: ----------------------------------------------------------------------
[16:14:02.255] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[16:14:02.255] INFO: edge/corner pixel THR is adjusted
[16:14:02.255] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:14:03.213] INFO: Collecting data for 1 seconds...
[16:14:04.217] INFO: Done with hot pixel readout
[16:14:08.358] INFO: PixTest:: pg_setup set to default.
[16:14:08.359] INFO: 0 hot pixels found in step 0
[16:14:08.364] INFO: 0 hot pixels could not be trimmed and have been masked.
[16:14:08.452] INFO: PixTest::trimHotPixels() done
[16:14:08.452] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C0.dat
[16:14:08.479] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C1.dat
[16:14:08.486] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C2.dat
[16:14:08.491] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C3.dat
[16:14:08.497] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C4.dat
[16:14:08.502] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C5.dat
[16:14:08.507] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C6.dat
[16:14:08.512] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C7.dat
[16:14:08.518] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C8.dat
[16:14:08.523] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C9.dat
[16:14:08.528] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C10.dat
[16:14:08.533] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C11.dat
[16:14:08.538] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C12.dat
[16:14:08.544] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C13.dat
[16:14:08.549] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C14.dat
[16:14:08.555] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C15.dat
[16:14:08.560] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-7-24_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//defaultMaskFile.dat
[16:14:08.569] INFO: enter test to run
[16:14:39.434] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[16:14:39.434] INFO: running: xray
[16:14:39.435] INFO: ----------------------------------------------------------------------
[16:14:39.435] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:14:39.435] INFO: ----------------------------------------------------------------------
[16:14:40.413] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:14:51.668] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[16:15:21.456] INFO: Resuming triggers.
[16:15:32.716] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[16:16:02.762] INFO: Resuming triggers.
[16:16:14.020] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[16:16:43.917] INFO: Resuming triggers.
[16:16:55.177] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[16:17:25.012] INFO: Resuming triggers.
[16:17:36.269] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[16:18:06.215] INFO: Resuming triggers.
[16:18:17.471] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[16:18:48.076] INFO: Resuming triggers.
[16:18:59.333] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[16:19:28.860] INFO: Resuming triggers.
[16:19:40.116] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[16:20:10.207] INFO: Resuming triggers.
[16:20:20.486] INFO: data taking finished, elapsed time: 100 seconds.
[16:20:48.410] INFO: PixTest:: pg_setup set to default.
[16:20:48.413] INFO: PixTestXray::doPhRun() done
[16:20:48.622] INFO: enter test to run
[16:21:49.687] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[16:21:49.688] INFO: running: xray
[16:21:49.689] INFO: ----------------------------------------------------------------------
[16:21:49.689] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:21:49.689] INFO: ----------------------------------------------------------------------
[16:21:50.652] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:21:57.131] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[16:22:29.085] INFO: Resuming triggers.
[16:22:35.559] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[16:23:07.521] INFO: Resuming triggers.
[16:23:13.997] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[16:23:45.925] INFO: Resuming triggers.
[16:23:52.402] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[16:24:23.119] INFO: Resuming triggers.
[16:24:29.596] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[16:25:00.361] INFO: Resuming triggers.
[16:25:06.846] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[16:25:37.631] INFO: Resuming triggers.
[16:25:44.111] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[16:26:14.824] INFO: Resuming triggers.
[16:26:21.307] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[16:26:52.361] INFO: Resuming triggers.
[16:26:58.846] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[16:27:29.534] INFO: Resuming triggers.
[16:27:36.016] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[16:28:06.736] INFO: Resuming triggers.
[16:28:13.215] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[16:28:44.191] INFO: Resuming triggers.
[16:28:50.674] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[16:29:21.422] INFO: Resuming triggers.
[16:29:27.900] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[16:29:58.552] INFO: Resuming triggers.
[16:30:05.029] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[16:30:35.767] INFO: Resuming triggers.
[16:30:42.242] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[16:31:13.018] INFO: Resuming triggers.
[16:31:16.170] INFO: data taking finished, elapsed time: 100 seconds.
[16:31:31.682] INFO: PixTest:: pg_setup set to default.
[16:31:31.685] INFO: PixTestXray::doPhRun() done
[16:31:31.837] INFO: enter test to run
[16:32:35.227] INFO: test: HighRate no parameter change
[16:32:35.227] INFO: running: highrate
[16:32:35.245] INFO: ----------------------------------------------------------------------
[16:32:35.245] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[16:32:35.245] INFO: ----------------------------------------------------------------------
[16:32:35.400] INFO: Expecting 768 events.
[16:32:36.572] INFO: 768 events read in total (457ms).
[16:32:36.572] INFO: Test took 1306ms.
[16:32:37.375] INFO: Expecting 41600 events.
[16:32:40.501] INFO: 41600 events read in total (2599ms).
[16:32:40.502] INFO: Test took 3908ms.
[16:32:40.539] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:32:41.264] INFO: Expecting 41600 events.
[16:32:44.482] INFO: 41600 events read in total (2691ms).
[16:32:44.483] INFO: Test took 3924ms.
[16:32:44.520] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:32:45.234] INFO: Expecting 41600 events.
[16:32:48.545] INFO: 41600 events read in total (2784ms).
[16:32:48.546] INFO: Test took 4008ms.
[16:32:48.584] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:32:49.283] INFO: Expecting 41600 events.
[16:32:52.604] INFO: 41600 events read in total (2794ms).
[16:32:52.605] INFO: Test took 4003ms.
[16:32:52.643] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:32:53.358] INFO: Expecting 41600 events.
[16:32:56.637] INFO: 41600 events read in total (2753ms).
[16:32:56.638] INFO: Test took 3977ms.
[16:32:56.675] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:32:57.382] INFO: Expecting 41600 events.
[16:33:00.718] INFO: 41600 events read in total (2809ms).
[16:33:00.719] INFO: Test took 4026ms.
[16:33:00.756] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:01.465] INFO: Expecting 41600 events.
[16:33:04.763] INFO: 41600 events read in total (2771ms).
[16:33:04.764] INFO: Test took 3989ms.
[16:33:04.807] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:05.515] INFO: Expecting 41600 events.
[16:33:08.853] INFO: 41600 events read in total (2811ms).
[16:33:08.854] INFO: Test took 4028ms.
[16:33:08.890] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:09.605] INFO: Expecting 41600 events.
[16:33:12.996] INFO: 41600 events read in total (2864ms).
[16:33:12.997] INFO: Test took 4088ms.
[16:33:13.034] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:13.751] INFO: Expecting 41600 events.
[16:33:17.071] INFO: 41600 events read in total (2793ms).
[16:33:17.072] INFO: Test took 4019ms.
[16:33:17.109] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:17.813] INFO: Expecting 41600 events.
[16:33:21.127] INFO: 41600 events read in total (2788ms).
[16:33:21.128] INFO: Test took 4000ms.
[16:33:21.166] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:21.870] INFO: Expecting 41600 events.
[16:33:25.191] INFO: 41600 events read in total (2794ms).
[16:33:25.192] INFO: Test took 4007ms.
[16:33:25.230] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:25.946] INFO: Expecting 41600 events.
[16:33:29.255] INFO: 41600 events read in total (2782ms).
[16:33:29.256] INFO: Test took 4008ms.
[16:33:29.292] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:29.005] INFO: Expecting 41600 events.
[16:33:33.312] INFO: 41600 events read in total (2780ms).
[16:33:33.313] INFO: Test took 4001ms.
[16:33:33.350] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:34.066] INFO: Expecting 41600 events.
[16:33:37.329] INFO: 41600 events read in total (2737ms).
[16:33:37.330] INFO: Test took 3961ms.
[16:33:37.367] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:38.077] INFO: Expecting 41600 events.
[16:33:41.404] INFO: 41600 events read in total (2800ms).
[16:33:41.405] INFO: Test took 4020ms.
[16:33:41.441] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:42.161] INFO: Expecting 41600 events.
[16:33:45.342] INFO: 41600 events read in total (2654ms).
[16:33:45.343] INFO: Test took 3883ms.
[16:33:45.382] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:46.090] INFO: Expecting 41600 events.
[16:33:49.314] INFO: 41600 events read in total (2697ms).
[16:33:49.315] INFO: Test took 3915ms.
[16:33:49.353] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:50.071] INFO: Expecting 41600 events.
[16:33:53.414] INFO: 41600 events read in total (2816ms).
[16:33:53.415] INFO: Test took 4044ms.
[16:33:53.451] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:54.169] INFO: Expecting 41600 events.
[16:33:57.383] INFO: 41600 events read in total (2687ms).
[16:33:57.384] INFO: Test took 3914ms.
[16:33:57.421] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:57.777] INFO: enter test to run
[16:34:06.906] INFO: test: HighRate no parameter change
[16:34:06.906] INFO: running: highrate
[16:34:06.907] INFO: ----------------------------------------------------------------------
[16:34:06.907] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:34:06.907] INFO: ----------------------------------------------------------------------
[16:34:07.524] INFO: Expecting 208000 events.
[16:34:19.650] INFO: 208000 events read in total (11599ms).
[16:34:19.653] INFO: Test took 12739ms.
[16:34:19.810] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:34:20.066] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 2 0 0 2 0 0 0 0 0 0
[16:34:20.066] INFO: number of red-efficiency pixels: 90 44 83 125 170 195 151 102 101 136 166 110 115 63 31 38
[16:34:20.066] INFO: number of X-ray hits detected: 69736 41785 67374 105434 113341 118733 113507 81938 83829 112838 117273 94432 98905 60695 24365 26776
[16:34:20.066] 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:34:20.066] INFO: number of Vcal hits detected: 207909 207956 207917 207873 207825 207801 207746 207897 207891 207762 207832 207887 207880 207936 207969 207962
[16:34:20.067] 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
[16:34:20.067] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 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
[16:34:20.067] INFO: X-ray hit rate [MHz/cm2]: 20.4 12.2 19.7 30.9 33.2 34.8 33.3 24.0 24.6 33.1 34.4 27.7 29.0 17.8 7.1 7.8
[16:34:20.067] INFO: PixTestHighRate::doXPixelAlive() done
[16:34:20.111] INFO: PixTest:: pg_setup set to default.
[16:34:20.128] INFO: enter test to run
[16:34:48.906] INFO: test: HighRate no parameter change
[16:34:48.906] INFO: running: highrate
[16:34:48.907] INFO: ----------------------------------------------------------------------
[16:34:48.907] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:34:48.907] INFO: ----------------------------------------------------------------------
[16:34:49.527] INFO: Expecting 208000 events.
[16:35:03.811] INFO: 208000 events read in total (13757ms).
[16:35:03.817] INFO: Test took 14901ms.
[16:35:04.137] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:35:04.449] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 2 0 0 2 0 0 0 0 0 0
[16:35:04.449] INFO: number of red-efficiency pixels: 259 114 267 446 561 627 540 308 362 410 615 398 332 186 57 59
[16:35:04.449] INFO: number of X-ray hits detected: 143435 86522 139273 216730 233187 245810 234719 169569 174120 231986 240805 194742 203010 125053 51084 56356
[16:35:04.449] 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:35:04.449] INFO: number of Vcal hits detected: 207722 207885 207707 207513 207392 207284 207304 207671 207617 207457 207304 207566 207643 207808 207940 207941
[16:35:04.449] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.7 99.7 99.9 99.8 99.8 99.7 99.8 99.8 99.9 100.0 100.0
[16:35:04.449] 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.7 99.8 99.8 99.9 100.0 100.0
[16:35:04.449] INFO: X-ray hit rate [MHz/cm2]: 42.0 25.4 40.8 63.5 68.3 72.0 68.8 49.7 51.0 68.0 70.6 57.1 59.5 36.7 15.0 16.5
[16:35:04.449] INFO: PixTestHighRate::doXPixelAlive() done
[16:35:04.495] INFO: PixTest:: pg_setup set to default.
[16:35:04.508] INFO: enter test to run
[16:35:59.089] INFO: test: HighRate no parameter change
[16:35:59.089] INFO: running: highrate
[16:35:59.090] INFO: ----------------------------------------------------------------------
[16:35:59.090] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:35:59.090] INFO: ----------------------------------------------------------------------
[16:35:59.711] INFO: Expecting 208000 events.
[16:36:16.278] INFO: 208000 events read in total (16040ms).
[16:36:16.286] INFO: Test took 17186ms.
[16:36:16.770] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:17.132] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 2 0 0 2 0 0 0 0 0 0
[16:36:17.132] INFO: number of red-efficiency pixels: 539 255 666 1015 1323 1410 1307 614 724 898 1447 942 784 455 85 133
[16:36:17.132] INFO: number of X-ray hits detected: 216465 130008 208719 324024 347859 369751 350915 253880 260275 348387 360426 293265 305505 187848 76357 84311
[16:36:17.132] 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:36:17.132] INFO: number of Vcal hits detected: 207328 207725 207103 206735 206314 206078 206191 207257 207122 206819 206040 206829 207067 207464 207913 207867
[16:36:17.132] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.6 99.5 99.3 99.2 99.3 99.7 99.6 99.5 99.1 99.5 99.6 99.8 100.0 99.9
[16:36:17.132] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.6 99.4 99.2 99.1 99.1 99.6 99.6 99.4 99.1 99.4 99.6 99.7 100.0 99.9
[16:36:17.132] INFO: X-ray hit rate [MHz/cm2]: 63.4 38.1 61.2 95.0 102.0 108.4 102.9 74.4 76.3 102.1 105.6 86.0 89.5 55.1 22.4 24.7
[16:36:17.132] INFO: PixTestHighRate::doXPixelAlive() done
[16:36:17.177] INFO: PixTest:: pg_setup set to default.
[16:36:17.191] INFO: enter test to run
[16:37:01.513] INFO: test: exit no parameter change
[16:37:01.874] QUIET: Connection to board 33 closed.
[16:37:01.906] INFO: pXar: this is the end, my friend