[17:34:06.861] INFO: *** Welcome to pxar ***
[17:34:06.861] INFO: *** Today: 2016/05/30
[17:34:06.879] INFO: *** Version: v1.9.0-796-gef167-dirty
[17:34:06.879] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//dacParameters35_C15.dat
[17:34:06.880] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//tbmParameters_C0b.dat
[17:34:06.881] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//defaultMaskFile.dat
[17:34:06.881] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C15.dat
[17:34:06.956] INFO: clk: 4
[17:34:06.956] INFO: ctr: 4
[17:34:06.956] INFO: sda: 19
[17:34:06.956] INFO: tin: 9
[17:34:06.956] INFO: level: 15
[17:34:06.956] INFO: triggerdelay: 0
[17:34:06.956] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[17:34:06.956] INFO: Log level: INFO
[17:34:06.975] QUIET: Connection to board DTB_WREKRL opened.
[17:34:06.978] 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:
------------------------------------------------------
[17:34:06.981] INFO: RPC call hashes of host and DTB match: 398089610
[17:34:08.506] INFO: DUT info:
[17:34:08.506] INFO: The DUT currently contains the following objects:
[17:34:08.506] INFO: 2 TBM Cores tbm08c (2 ON)
[17:34:08.506] INFO: TBM Core alpha (0): 7 registers set
[17:34:08.506] INFO: TBM Core beta (1): 7 registers set
[17:34:08.506] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[17:34:08.506] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[17:34:08.506] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[17:34:08.506] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[17:34:08.506] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[17:34:08.506] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[17:34:08.507] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[17:34:08.507] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[17:34:08.507] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[17:34:08.507] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[17:34:08.507] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[17:34:08.507] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[17:34:08.507] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[17:34:08.507] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[17:34:08.507] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[17:34:08.507] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[17:34:08.507] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[17:34:08.910] INFO: enter 'restricted' command line mode
[17:34:08.910] INFO: enter test to run
[17:34:11.913] INFO: test: timing no parameter change
[17:34:11.913] INFO: running: timing
[17:34:11.922] INFO: ######################################################################
[17:34:11.922] INFO: PixTestTiming::doTest()
[17:34:11.922] INFO: ######################################################################
[17:34:11.922] INFO: ----------------------------------------------------------------------
[17:34:11.922] INFO: PixTestTiming::TBMPhaseScan()
[17:34:11.922] INFO: ----------------------------------------------------------------------
[17:38:24.097] INFO: TBM Phase Settings: 252
[17:38:24.097] INFO: 400MHz Phase: 7
[17:38:24.098] INFO: 160MHz Phase: 7
[17:38:24.098] INFO: Functional Phase Area: 3
[17:38:24.101] INFO: Test took 252179 ms.
[17:38:24.101] INFO: PixTestTiming::TBMPhaseScan() done.
[17:38:24.101] INFO: ----------------------------------------------------------------------
[17:38:24.101] INFO: PixTestTiming::ROCDelayScan()
[17:38:24.101] INFO: ----------------------------------------------------------------------
[17:40:22.999] INFO: ROC Delay Settings: 228
[17:40:22.999] INFO: ROC Header-Trailer/Token Delay: 11
[17:40:22.999] INFO: ROC Port 0 Delay: 4
[17:40:22.999] INFO: ROC Port 1 Delay: 4
[17:40:22.999] INFO: Functional ROC Area: 3
[17:40:22.003] INFO: Test took 118902 ms.
[17:40:22.003] INFO: PixTestTiming::ROCDelayScan() done.
[17:40:22.003] INFO: ----------------------------------------------------------------------
[17:40:22.003] INFO: PixTestTiming::TimingTest()
[17:40:22.003] INFO: ----------------------------------------------------------------------
[17:40:39.127] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:40:54.098] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:41:09.063] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:41:24.041] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:41:39.014] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:41:53.991] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:42:08.938] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:42:23.919] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:42:38.880] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:42:53.855] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:42:54.234] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:42:54.251] INFO: ----------------------------------------------------------------------
[17:42:54.251] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[17:42:54.251] INFO: ----------------------------------------------------------------------
[17:42:54.251] INFO: ----------------------------------------------------------------------
[17:42:54.251] INFO: Read back bit status: 1
[17:42:54.251] INFO: ----------------------------------------------------------------------
[17:42:54.251] INFO: ----------------------------------------------------------------------
[17:42:54.251] INFO: Timings are good!
[17:42:54.251] INFO: ----------------------------------------------------------------------
[17:42:54.251] INFO: Test took 151248 ms.
[17:42:54.251] INFO: PixTestTiming::TimingTest() done.
[17:42:54.251] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//tbmParameters_C0a.dat
[17:42:54.251] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//tbmParameters_C0b.dat
[17:42:54.252] INFO: PixTestTiming::doTest took 522335 ms.
[17:42:54.252] INFO: PixTestTiming::doTest() done
[17:42:54.252] INFO: Write out TBMPhaseScan_0_V0
[17:42:54.278] INFO: Write out TBMPhaseScan_1_V0
[17:42:54.278] INFO: Write out CombinedTBMPhaseScan_V0
[17:42:54.278] INFO: Write out ROCDelayScan3_V0
[17:42:54.279] INFO: enter test to run
[17:43:15.005] INFO: test: PixelAlive no parameter change
[17:43:15.005] INFO: running: pixelalive
[17:43:15.010] INFO: ----------------------------------------------------------------------
[17:43:15.010] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[17:43:15.010] INFO: ----------------------------------------------------------------------
[17:43:15.325] INFO: Expecting 41600 events.
[17:43:19.653] INFO: 41600 events read in total (3612ms).
[17:43:19.654] INFO: Test took 4642ms.
[17:43:19.660] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:43:20.062] INFO: PixTestAlive::aliveTest() done
[17:43:20.062] INFO: number of dead pixels (per ROC): 0 0 0 0 1 0 0 0 0 0 0 1 1 0 0 1
[17:43:20.066] INFO: enter test to run
[17:44:28.844] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[17:44:28.845] INFO: running: highrate
[17:44:28.845] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[17:44:29.006] INFO: ----------------------------------------------------------------------
[17:44:29.006] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[17:44:29.006] INFO: ----------------------------------------------------------------------
[17:44:29.006] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[17:44:29.006] INFO: edge/corner pixel THR is adjusted
[17:44:29.006] INFO: PixTestHighRate::trimHotPixels: step 0...
[17:44:29.963] INFO: Collecting data for 5 seconds...
[17:44:34.979] INFO: Done with hot pixel readout
[17:44:46.556] INFO: PixTest:: pg_setup set to default.
[17:44:46.557] INFO: 1 hot pixels found in step 0
[17:44:47.548] INFO: Collecting data for 5 seconds...
[17:44:52.563] INFO: Done with hot pixel readout
[17:45:04.116] INFO: PixTest:: pg_setup set to default.
[17:45:04.117] INFO: 0 hot pixels found in step 1
[17:45:04.152] INFO: 0 hot pixels could not be trimmed and have been masked.
[17:45:04.155] INFO: PixTest::trimHotPixels() done
[17:45:04.155] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C0.dat
[17:45:04.160] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C1.dat
[17:45:04.167] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C2.dat
[17:45:04.173] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C3.dat
[17:45:04.178] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C4.dat
[17:45:04.184] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C5.dat
[17:45:04.189] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C6.dat
[17:45:04.194] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C7.dat
[17:45:04.199] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C8.dat
[17:45:04.204] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C9.dat
[17:45:04.209] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C10.dat
[17:45:04.214] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C11.dat
[17:45:04.219] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C12.dat
[17:45:04.224] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C13.dat
[17:45:04.230] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C14.dat
[17:45:04.235] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C15.dat
[17:45:04.240] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//defaultMaskFile.dat
[17:45:04.250] INFO: enter test to run
[17:45:19.588] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[17:45:19.588] INFO: running: highrate
[17:45:19.592] INFO: ----------------------------------------------------------------------
[17:45:19.593] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[17:45:19.593] INFO: ----------------------------------------------------------------------
[17:45:19.593] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[17:45:19.593] INFO: edge/corner pixel THR is adjusted
[17:45:19.593] INFO: PixTestHighRate::trimHotPixels: step 0...
[17:45:20.551] INFO: Collecting data for 1 seconds...
[17:45:21.554] INFO: Done with hot pixel readout
[17:45:25.543] INFO: PixTest:: pg_setup set to default.
[17:45:25.544] INFO: 0 hot pixels found in step 0
[17:45:25.549] INFO: 0 hot pixels could not be trimmed and have been masked.
[17:45:25.637] INFO: PixTest::trimHotPixels() done
[17:45:25.637] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C0.dat
[17:45:25.645] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C1.dat
[17:45:25.650] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C2.dat
[17:45:25.655] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C3.dat
[17:45:25.660] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C4.dat
[17:45:25.666] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C5.dat
[17:45:25.671] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C6.dat
[17:45:25.676] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C7.dat
[17:45:25.681] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C8.dat
[17:45:25.686] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C9.dat
[17:45:25.692] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C10.dat
[17:45:25.697] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C11.dat
[17:45:25.702] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C12.dat
[17:45:25.707] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C13.dat
[17:45:25.712] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C14.dat
[17:45:25.718] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//trimParameters35_C15.dat
[17:45:25.723] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-O-1-23_FPIXTest-17C-FNAL-160525-1145_2016-05-25_11h45m_1464194732/000_FPIXTest_p17//defaultMaskFile.dat
[17:45:25.732] INFO: enter test to run
[17:45:44.764] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[17:45:44.764] INFO: running: xray
[17:45:44.765] INFO: ----------------------------------------------------------------------
[17:45:44.765] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[17:45:44.765] INFO: ----------------------------------------------------------------------
[17:45:45.728] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[17:45:57.113] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[17:46:26.332] INFO: Resuming triggers.
[17:46:37.716] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[17:47:07.046] INFO: Resuming triggers.
[17:47:18.430] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[17:47:47.711] INFO: Resuming triggers.
[17:47:59.094] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[17:48:28.385] INFO: Resuming triggers.
[17:48:39.771] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[17:49:09.064] INFO: Resuming triggers.
[17:49:20.450] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[17:49:49.687] INFO: Resuming triggers.
[17:50:01.074] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[17:50:30.316] INFO: Resuming triggers.
[17:50:41.706] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[17:51:10.992] INFO: Resuming triggers.
[17:51:20.212] INFO: data taking finished, elapsed time: 100 seconds.
[17:51:44.148] INFO: PixTest:: pg_setup set to default.
[17:51:44.151] INFO: PixTestXray::doPhRun() done
[17:51:44.287] INFO: enter test to run
[17:53:17.729] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[17:53:17.729] INFO: running: xray
[17:53:17.730] INFO: ----------------------------------------------------------------------
[17:53:17.730] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[17:53:17.730] INFO: ----------------------------------------------------------------------
[17:53:18.694] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[17:53:25.471] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[17:53:55.250] INFO: Resuming triggers.
[17:54:02.030] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[17:54:31.948] INFO: Resuming triggers.
[17:54:38.728] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[17:55:08.679] INFO: Resuming triggers.
[17:55:15.459] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[17:55:45.445] INFO: Resuming triggers.
[17:55:52.226] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[17:56:22.173] INFO: Resuming triggers.
[17:56:28.957] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[17:56:58.903] INFO: Resuming triggers.
[17:57:05.685] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[17:57:35.623] INFO: Resuming triggers.
[17:57:42.403] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[17:58:12.401] INFO: Resuming triggers.
[17:58:19.182] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[17:58:49.025] INFO: Resuming triggers.
[17:58:55.808] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[17:59:25.743] INFO: Resuming triggers.
[17:59:32.528] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[18:00:02.432] INFO: Resuming triggers.
[18:00:09.214] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[18:00:39.102] INFO: Resuming triggers.
[18:00:45.885] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[18:01:15.798] INFO: Resuming triggers.
[18:01:22.581] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[18:01:52.459] INFO: Resuming triggers.
[18:01:57.821] INFO: data taking finished, elapsed time: 100 seconds.
[18:02:21.707] INFO: PixTest:: pg_setup set to default.
[18:02:21.710] INFO: PixTestXray::doPhRun() done
[18:02:21.857] INFO: enter test to run
[18:02:41.965] INFO: test: HighRate no parameter change
[18:02:41.965] INFO: running: highrate
[18:02:41.966] INFO: ----------------------------------------------------------------------
[18:02:41.966] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[18:02:41.966] INFO: ----------------------------------------------------------------------
[18:02:42.108] INFO: Expecting 768 events.
[18:02:43.242] INFO: 768 events read in total (418ms).
[18:02:43.243] INFO: Test took 1269ms.
[18:02:44.046] INFO: Expecting 41600 events.
[18:02:47.150] INFO: 41600 events read in total (2577ms).
[18:02:47.151] INFO: Test took 3902ms.
[18:02:47.184] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:02:47.909] INFO: Expecting 41600 events.
[18:02:51.104] INFO: 41600 events read in total (2668ms).
[18:02:51.105] INFO: Test took 3904ms.
[18:02:51.139] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:02:51.864] INFO: Expecting 41600 events.
[18:02:55.090] INFO: 41600 events read in total (2699ms).
[18:02:55.091] INFO: Test took 3935ms.
[18:02:55.125] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:02:55.850] INFO: Expecting 41600 events.
[18:02:59.081] INFO: 41600 events read in total (2704ms).
[18:02:59.082] INFO: Test took 3938ms.
[18:02:59.115] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:02:59.836] INFO: Expecting 41600 events.
[18:03:03.066] INFO: 41600 events read in total (2703ms).
[18:03:03.067] INFO: Test took 3933ms.
[18:03:03.102] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:03:03.823] INFO: Expecting 41600 events.
[18:03:07.066] INFO: 41600 events read in total (2716ms).
[18:03:07.067] INFO: Test took 3947ms.
[18:03:07.101] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:03:07.826] INFO: Expecting 41600 events.
[18:03:11.062] INFO: 41600 events read in total (2709ms).
[18:03:11.064] INFO: Test took 3945ms.
[18:03:11.098] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:03:11.823] INFO: Expecting 41600 events.
[18:03:15.056] INFO: 41600 events read in total (2706ms).
[18:03:15.057] INFO: Test took 3941ms.
[18:03:15.091] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:03:15.814] INFO: Expecting 41600 events.
[18:03:19.053] INFO: 41600 events read in total (2712ms).
[18:03:19.054] INFO: Test took 3944ms.
[18:03:19.089] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:03:19.814] INFO: Expecting 41600 events.
[18:03:23.069] INFO: 41600 events read in total (2729ms).
[18:03:23.070] INFO: Test took 3962ms.
[18:03:23.104] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:03:23.824] INFO: Expecting 41600 events.
[18:03:27.065] INFO: 41600 events read in total (2715ms).
[18:03:27.066] INFO: Test took 3943ms.
[18:03:27.101] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:03:27.822] INFO: Expecting 41600 events.
[18:03:31.063] INFO: 41600 events read in total (2714ms).
[18:03:31.064] INFO: Test took 3944ms.
[18:03:31.098] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:03:31.820] INFO: Expecting 41600 events.
[18:03:35.047] INFO: 41600 events read in total (2700ms).
[18:03:35.048] INFO: Test took 3933ms.
[18:03:35.082] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:03:35.804] INFO: Expecting 41600 events.
[18:03:39.032] INFO: 41600 events read in total (2701ms).
[18:03:39.033] INFO: Test took 3934ms.
[18:03:39.068] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:03:39.792] INFO: Expecting 41600 events.
[18:03:43.040] INFO: 41600 events read in total (2721ms).
[18:03:43.041] INFO: Test took 3954ms.
[18:03:43.075] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:03:43.798] INFO: Expecting 41600 events.
[18:03:47.057] INFO: 41600 events read in total (2732ms).
[18:03:47.058] INFO: Test took 3964ms.
[18:03:47.093] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:03:47.813] INFO: Expecting 41600 events.
[18:03:51.042] INFO: 41600 events read in total (2702ms).
[18:03:51.043] INFO: Test took 3932ms.
[18:03:51.077] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:03:51.801] INFO: Expecting 41600 events.
[18:03:55.040] INFO: 41600 events read in total (2712ms).
[18:03:55.041] INFO: Test took 3945ms.
[18:03:55.076] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:03:55.799] INFO: Expecting 41600 events.
[18:03:59.014] INFO: 41600 events read in total (2688ms).
[18:03:59.015] INFO: Test took 3921ms.
[18:03:59.050] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:03:59.776] INFO: Expecting 41600 events.
[18:04:02.834] INFO: 41600 events read in total (2531ms).
[18:04:02.835] INFO: Test took 3767ms.
[18:04:02.868] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:04:03.232] INFO: enter test to run
[18:05:40.667] INFO: test: HighRate no parameter change
[18:05:40.667] INFO: running: highrate
[18:05:40.669] INFO: ----------------------------------------------------------------------
[18:05:40.669] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[18:05:40.669] INFO: ----------------------------------------------------------------------
[18:05:41.285] INFO: Expecting 208000 events.
[18:05:53.153] INFO: 208000 events read in total (11342ms).
[18:05:53.156] INFO: Test took 12479ms.
[18:05:53.303] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:05:53.556] INFO: number of dead pixels (per ROC): 0 0 0 0 1 0 0 0 0 0 0 1 1 0 0 1
[18:05:53.556] INFO: number of red-efficiency pixels: 92 53 78 147 171 153 126 102 97 106 102 81 110 84 24 26
[18:05:53.556] INFO: number of X-ray hits detected: 66349 46034 67776 104747 113694 116267 120623 86268 82330 98368 97557 86352 84216 51475 22405 25831
[18:05:53.556] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[18:05:53.556] INFO: number of Vcal hits detected: 207907 207946 207921 207849 207776 207842 207871 207896 207900 207893 207895 207869 207839 207909 207976 207925
[18:05:53.556] 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 100.0 100.0 99.9 100.0 100.0 100.0
[18:05:53.556] INFO: Vcal hit overall 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
[18:05:53.556] INFO: X-ray hit rate [MHz/cm2]: 19.4 13.5 19.9 30.7 33.3 34.1 35.4 25.3 24.1 28.8 28.6 25.3 24.7 15.1 6.6 7.6
[18:05:53.556] INFO: PixTestHighRate::doXPixelAlive() done
[18:05:53.607] INFO: PixTest:: pg_setup set to default.
[18:05:53.617] INFO: enter test to run
[18:09:03.226] INFO: test: HighRate no parameter change
[18:09:03.226] INFO: running: highrate
[18:09:03.227] INFO: ----------------------------------------------------------------------
[18:09:03.227] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[18:09:03.227] INFO: ----------------------------------------------------------------------
[18:09:03.842] INFO: Expecting 208000 events.
[18:09:17.478] INFO: 208000 events read in total (13109ms).
[18:09:17.483] INFO: Test took 14248ms.
[18:09:17.770] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:09:18.070] INFO: number of dead pixels (per ROC): 0 0 0 0 1 0 0 0 0 0 0 1 1 0 0 1
[18:09:18.070] INFO: number of red-efficiency pixels: 246 160 227 395 496 558 399 343 301 349 288 273 268 189 49 73
[18:09:18.070] INFO: number of X-ray hits detected: 134339 93578 137384 210671 229604 234524 242444 174709 167318 201769 198045 173618 170441 105673 45293 52251
[18:09:18.070] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[18:09:18.070] INFO: number of Vcal hits detected: 207734 207834 207755 207584 207408 207389 207566 207635 207682 207626 207701 207656 207672 207805 207950 207878
[18:09:18.070] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.7 99.8 99.8 99.9 99.8 99.9 99.9 99.9 99.9 100.0 100.0
[18:09:18.070] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.7 99.8 99.8 99.8 99.8 99.9 99.8 99.8 99.9 100.0 99.9
[18:09:18.070] INFO: X-ray hit rate [MHz/cm2]: 39.4 27.4 40.3 61.7 67.3 68.7 71.1 51.2 49.0 59.1 58.0 50.9 50.0 31.0 13.3 15.3
[18:09:18.070] INFO: PixTestHighRate::doXPixelAlive() done
[18:09:18.120] INFO: PixTest:: pg_setup set to default.
[18:09:18.134] INFO: enter test to run
[18:10:28.937] INFO: test: HighRate no parameter change
[18:10:28.937] INFO: running: highrate
[18:10:28.938] INFO: ----------------------------------------------------------------------
[18:10:28.938] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[18:10:28.938] INFO: ----------------------------------------------------------------------
[18:10:29.550] INFO: Expecting 208000 events.
[18:10:44.976] INFO: 208000 events read in total (14899ms).
[18:10:44.983] INFO: Test took 16035ms.
[18:10:45.415] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:10:45.768] INFO: number of dead pixels (per ROC): 0 0 0 0 1 0 0 0 0 0 0 1 1 0 0 1
[18:10:45.768] INFO: number of red-efficiency pixels: 495 317 481 1097 1217 1192 945 762 626 690 675 531 629 427 100 82
[18:10:45.768] INFO: number of X-ray hits detected: 201877 140179 204733 317214 345151 351330 364678 262275 252754 302578 297927 261057 257180 157969 68665 80235
[18:10:45.768] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[18:10:45.768] INFO: number of Vcal hits detected: 207423 207656 207427 206650 206444 206434 206847 207054 207299 207191 207241 207348 207247 207515 207896 207868
[18:10:45.768] INFO: Vcal hit fiducial efficiency (%): 99.7 99.8 99.8 99.4 99.3 99.3 99.5 99.6 99.7 99.6 99.7 99.7 99.7 99.8 99.9 100.0
[18:10:45.768] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.7 99.4 99.3 99.2 99.4 99.5 99.7 99.6 99.6 99.7 99.6 99.8 100.0 99.9
[18:10:45.768] INFO: X-ray hit rate [MHz/cm2]: 59.2 41.1 60.0 93.0 101.2 103.0 106.9 76.9 74.1 88.7 87.3 76.5 75.4 46.3 20.1 23.5
[18:10:45.768] INFO: PixTestHighRate::doXPixelAlive() done
[18:10:45.818] INFO: PixTest:: pg_setup set to default.
[18:10:45.831] INFO: enter test to run
[18:12:18.120] INFO: test: exit no parameter change
[18:12:18.479] QUIET: Connection to board 33 closed.
[18:12:18.480] INFO: pXar: this is the end, my friend