[14:10:36.029] INFO: *** Welcome to pxar ***
[14:10:36.029] INFO: *** Today: 2016/09/19
[14:10:36.749] INFO: *** Version: v1.9.0-818-g96727
[14:10:36.749] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//dacParameters35_C15.dat
[14:10:36.827] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:10:36.844] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//defaultMaskFile.dat
[14:10:36.863] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C15.dat
[14:10:37.020] INFO: clk: 4
[14:10:37.020] INFO: ctr: 4
[14:10:37.020] INFO: sda: 19
[14:10:37.020] INFO: tin: 9
[14:10:37.020] INFO: level: 15
[14:10:37.020] INFO: triggerdelay: 0
[14:10:37.048] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[14:10:37.048] INFO: Log level: INFO
[14:10:37.073] QUIET: Connection to board DTB_WREKRL opened.
[14:10:37.076] 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:
------------------------------------------------------
[14:10:37.079] INFO: RPC call hashes of host and DTB match: 398089610
[14:10:38.608] INFO: DUT info:
[14:10:38.608] INFO: The DUT currently contains the following objects:
[14:10:38.608] INFO: 2 TBM Cores tbm08c (2 ON)
[14:10:38.608] INFO: TBM Core alpha (0): 7 registers set
[14:10:38.608] INFO: TBM Core beta (1): 7 registers set
[14:10:38.608] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[14:10:38.608] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:38.608] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:38.608] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:38.608] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:38.608] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:38.609] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:38.609] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:38.609] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:38.609] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:38.609] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:38.609] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:38.609] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:38.609] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:38.609] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:38.609] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:38.609] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:39.048] INFO: enter 'restricted' command line mode
[14:10:39.048] INFO: enter test to run
[14:10:43.667] INFO: test: PixelAlive no parameter change
[14:10:43.667] INFO: running: pixelalive
[14:10:43.712] INFO: ----------------------------------------------------------------------
[14:10:43.712] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[14:10:43.712] INFO: ----------------------------------------------------------------------
[14:10:44.035] INFO: Expecting 41600 events.
[14:10:48.288] INFO: 41600 events read in total (3535ms).
[14:10:48.453] INFO: Test took 4737ms.
[14:10:48.467] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:10:48.795] INFO: PixTestAlive::aliveTest() done
[14:10:48.795] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 2 0 1 0
[14:10:48.852] INFO: enter test to run
[14:10:52.011] INFO: test: timing no parameter change
[14:10:52.011] INFO: running: timing
[14:10:52.014] INFO: ######################################################################
[14:10:52.014] INFO: PixTestTiming::doTest()
[14:10:52.014] INFO: ######################################################################
[14:10:52.014] INFO: ----------------------------------------------------------------------
[14:10:52.014] INFO: PixTestTiming::TBMPhaseScan()
[14:10:52.015] INFO: ----------------------------------------------------------------------
[14:19:57.193] INFO: TBM Phase Settings: 240
[14:19:57.193] INFO: 400MHz Phase: 4
[14:19:57.193] INFO: 160MHz Phase: 7
[14:19:57.193] INFO: Functional Phase Area: 5
[14:19:57.202] INFO: Test took 545188 ms.
[14:19:57.202] INFO: PixTestTiming::TBMPhaseScan() done.
[14:19:57.202] INFO: ----------------------------------------------------------------------
[14:19:57.202] INFO: PixTestTiming::ROCDelayScan()
[14:19:57.202] INFO: ----------------------------------------------------------------------
[14:21:52.695] INFO: ROC Delay Settings: 228
[14:21:52.695] INFO: ROC Header-Trailer/Token Delay: 11
[14:21:52.695] INFO: ROC Port 0 Delay: 4
[14:21:52.695] INFO: ROC Port 1 Delay: 4
[14:21:52.695] INFO: Functional ROC Area: 3
[14:21:52.698] INFO: Test took 115496 ms.
[14:21:52.698] INFO: PixTestTiming::ROCDelayScan() done.
[14:21:52.698] INFO: ----------------------------------------------------------------------
[14:21:52.698] INFO: PixTestTiming::TimingTest()
[14:21:52.698] INFO: ----------------------------------------------------------------------
[14:22:08.778] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:23.698] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:38.530] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:53.421] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:23:08.268] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:23:23.131] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:23:37.976] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:23:52.788] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:07.666] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:22.543] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:22.922] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:22.941] INFO: ----------------------------------------------------------------------
[14:24:22.942] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[14:24:22.942] INFO: ----------------------------------------------------------------------
[14:24:22.942] INFO: ----------------------------------------------------------------------
[14:24:22.942] INFO: Read back bit status: 1
[14:24:22.942] INFO: ----------------------------------------------------------------------
[14:24:22.942] INFO: ----------------------------------------------------------------------
[14:24:22.942] INFO: Timings are good!
[14:24:22.942] INFO: ----------------------------------------------------------------------
[14:24:22.942] INFO: Test took 150244 ms.
[14:24:22.942] INFO: PixTestTiming::TimingTest() done.
[14:24:22.957] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//tbmParameters_C0a.dat
[14:24:22.957] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:24:22.957] INFO: PixTestTiming::doTest took 810946 ms.
[14:24:22.957] INFO: PixTestTiming::doTest() done
[14:24:22.957] INFO: Write out TBMPhaseScan_0_V0
[14:24:22.958] INFO: Write out TBMPhaseScan_1_V0
[14:24:22.958] INFO: Write out CombinedTBMPhaseScan_V0
[14:24:22.994] INFO: Write out ROCDelayScan3_V0
[14:24:22.995] INFO: enter test to run
[14:25:02.597] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[14:25:02.597] INFO: running: highrate
[14:25:02.625] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[14:25:02.932] INFO: ----------------------------------------------------------------------
[14:25:02.933] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[14:25:02.933] INFO: ----------------------------------------------------------------------
[14:25:02.933] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[14:25:02.933] INFO: edge/corner pixel THR is adjusted
[14:25:02.933] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:25:03.903] INFO: Collecting data for 5 seconds...
[14:25:08.920] INFO: Done with hot pixel readout
[14:25:19.950] INFO: PixTest:: pg_setup set to default.
[14:25:19.951] INFO: 0 hot pixels found in step 0
[14:25:19.985] INFO: 0 hot pixels could not be trimmed and have been masked.
[14:25:19.988] INFO: PixTest::trimHotPixels() done
[14:25:19.988] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C0.dat
[14:25:19.993] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C1.dat
[14:25:19.000] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C2.dat
[14:25:20.007] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C3.dat
[14:25:20.019] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C4.dat
[14:25:20.031] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C5.dat
[14:25:20.043] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C6.dat
[14:25:20.050] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C7.dat
[14:25:20.058] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C8.dat
[14:25:20.065] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C9.dat
[14:25:20.070] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C10.dat
[14:25:20.075] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C11.dat
[14:25:20.081] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C12.dat
[14:25:20.086] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C13.dat
[14:25:20.091] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C14.dat
[14:25:20.096] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C15.dat
[14:25:20.102] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//defaultMaskFile.dat
[14:25:20.117] INFO: enter test to run
[14:25:50.797] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[14:25:50.797] INFO: running: highrate
[14:25:50.801] INFO: ----------------------------------------------------------------------
[14:25:50.801] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[14:25:50.802] INFO: ----------------------------------------------------------------------
[14:25:50.802] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[14:25:50.802] INFO: edge/corner pixel THR is adjusted
[14:25:50.802] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:25:51.759] INFO: Collecting data for 1 seconds...
[14:25:52.763] INFO: Done with hot pixel readout
[14:25:56.537] INFO: PixTest:: pg_setup set to default.
[14:25:56.538] INFO: 0 hot pixels found in step 0
[14:25:56.544] INFO: 0 hot pixels could not be trimmed and have been masked.
[14:25:56.635] INFO: PixTest::trimHotPixels() done
[14:25:56.636] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C0.dat
[14:25:56.645] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C1.dat
[14:25:56.651] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C2.dat
[14:25:56.656] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C3.dat
[14:25:56.661] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C4.dat
[14:25:56.667] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C5.dat
[14:25:56.672] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C6.dat
[14:25:56.677] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C7.dat
[14:25:56.682] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C8.dat
[14:25:56.688] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C9.dat
[14:25:56.693] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C10.dat
[14:25:56.698] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C11.dat
[14:25:56.704] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C12.dat
[14:25:56.709] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C13.dat
[14:25:56.714] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C14.dat
[14:25:56.719] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//trimParameters35_C15.dat
[14:25:56.724] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-6-22_FPIXTest-17C-FNAL-160908-0917-150V_2016-09-08_09h17m_1473344239/000_FPIXTest_p17//defaultMaskFile.dat
[14:25:56.734] INFO: enter test to run
[14:28:04.124] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[14:28:04.124] INFO: running: xray
[14:28:04.125] INFO: ----------------------------------------------------------------------
[14:28:04.125] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:28:04.125] INFO: ----------------------------------------------------------------------
[14:28:05.086] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:28:16.937] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[14:28:42.775] INFO: Resuming triggers.
[14:28:54.626] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[14:29:21.141] INFO: Resuming triggers.
[14:29:32.992] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[14:30:00.095] INFO: Resuming triggers.
[14:30:11.943] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[14:30:40.231] INFO: Resuming triggers.
[14:30:52.081] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[14:31:19.735] INFO: Resuming triggers.
[14:31:31.583] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[14:31:59.921] INFO: Resuming triggers.
[14:32:11.771] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[14:32:40.137] INFO: Resuming triggers.
[14:32:51.986] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[14:33:20.414] INFO: Resuming triggers.
[14:33:25.930] INFO: data taking finished, elapsed time: 100 seconds.
[14:33:39.432] INFO: PixTest:: pg_setup set to default.
[14:33:39.435] INFO: PixTestXray::doPhRun() done
[14:33:39.660] INFO: enter test to run
[14:34:53.529] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[14:34:53.529] INFO: running: xray
[14:34:53.530] INFO: ----------------------------------------------------------------------
[14:34:53.530] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:34:53.530] INFO: ----------------------------------------------------------------------
[14:34:54.492] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:35:01.570] INFO: run duration 7 seconds, buffer almost full (81%), pausing triggers.
[14:35:31.424] INFO: Resuming triggers.
[14:35:38.504] INFO: run duration 14 seconds, buffer almost full (81%), pausing triggers.
[14:36:08.145] INFO: Resuming triggers.
[14:36:15.225] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[14:36:44.973] INFO: Resuming triggers.
[14:36:52.053] INFO: run duration 28 seconds, buffer almost full (81%), pausing triggers.
[14:37:21.821] INFO: Resuming triggers.
[14:37:28.905] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[14:37:58.467] INFO: Resuming triggers.
[14:38:05.547] INFO: run duration 42 seconds, buffer almost full (81%), pausing triggers.
[14:38:35.367] INFO: Resuming triggers.
[14:38:42.451] INFO: run duration 49 seconds, buffer almost full (81%), pausing triggers.
[14:39:12.632] INFO: Resuming triggers.
[14:39:19.717] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[14:39:49.087] INFO: Resuming triggers.
[14:39:56.172] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[14:40:25.432] INFO: Resuming triggers.
[14:40:32.516] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[14:41:01.686] INFO: Resuming triggers.
[14:41:08.773] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[14:41:37.876] INFO: Resuming triggers.
[14:41:44.963] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[14:42:14.333] INFO: Resuming triggers.
[14:42:21.418] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[14:42:50.899] INFO: Resuming triggers.
[14:42:57.983] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[14:43:27.056] INFO: Resuming triggers.
[14:43:28.218] INFO: data taking finished, elapsed time: 100 seconds.
[14:43:33.528] INFO: PixTest:: pg_setup set to default.
[14:43:33.531] INFO: PixTestXray::doPhRun() done
[14:43:33.683] INFO: enter test to run
[14:43:57.661] INFO: test: HighRate no parameter change
[14:43:57.661] INFO: running: highrate
[14:43:57.787] INFO: ----------------------------------------------------------------------
[14:43:57.787] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[14:43:57.787] INFO: ----------------------------------------------------------------------
[14:43:57.990] INFO: Expecting 768 events.
[14:43:59.149] INFO: 768 events read in total (443ms).
[14:43:59.150] INFO: Test took 1294ms.
[14:43:59.952] INFO: Expecting 41600 events.
[14:44:03.037] INFO: 41600 events read in total (2558ms).
[14:44:03.038] INFO: Test took 3740ms.
[14:44:03.075] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:44:03.779] INFO: Expecting 41600 events.
[14:44:06.893] INFO: 41600 events read in total (2587ms).
[14:44:06.894] INFO: Test took 3801ms.
[14:44:06.926] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:44:07.654] INFO: Expecting 41600 events.
[14:44:10.806] INFO: 41600 events read in total (2625ms).
[14:44:10.807] INFO: Test took 3864ms.
[14:44:10.849] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:44:11.549] INFO: Expecting 41600 events.
[14:44:14.702] INFO: 41600 events read in total (2626ms).
[14:44:14.703] INFO: Test took 3836ms.
[14:44:14.736] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:44:15.456] INFO: Expecting 41600 events.
[14:44:18.611] INFO: 41600 events read in total (2628ms).
[14:44:18.612] INFO: Test took 3858ms.
[14:44:18.645] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:44:19.368] INFO: Expecting 41600 events.
[14:44:22.474] INFO: 41600 events read in total (2579ms).
[14:44:22.475] INFO: Test took 3812ms.
[14:44:22.508] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:44:23.235] INFO: Expecting 41600 events.
[14:44:26.379] INFO: 41600 events read in total (2617ms).
[14:44:26.380] INFO: Test took 3855ms.
[14:44:26.413] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:44:27.140] INFO: Expecting 41600 events.
[14:44:30.243] INFO: 41600 events read in total (2576ms).
[14:44:30.244] INFO: Test took 3813ms.
[14:44:30.280] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:44:30.005] INFO: Expecting 41600 events.
[14:44:34.164] INFO: 41600 events read in total (2632ms).
[14:44:34.165] INFO: Test took 3866ms.
[14:44:34.198] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:44:34.924] INFO: Expecting 41600 events.
[14:44:38.067] INFO: 41600 events read in total (2616ms).
[14:44:38.068] INFO: Test took 3852ms.
[14:44:38.100] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:44:38.825] INFO: Expecting 41600 events.
[14:44:41.993] INFO: 41600 events read in total (2641ms).
[14:44:41.994] INFO: Test took 3877ms.
[14:44:42.032] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:44:42.741] INFO: Expecting 41600 events.
[14:44:45.825] INFO: 41600 events read in total (2557ms).
[14:44:45.826] INFO: Test took 3769ms.
[14:44:45.858] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:44:46.583] INFO: Expecting 41600 events.
[14:44:49.689] INFO: 41600 events read in total (2580ms).
[14:44:49.690] INFO: Test took 3815ms.
[14:44:49.725] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:44:50.452] INFO: Expecting 41600 events.
[14:44:53.602] INFO: 41600 events read in total (2623ms).
[14:44:53.603] INFO: Test took 3862ms.
[14:44:53.635] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:44:54.363] INFO: Expecting 41600 events.
[14:44:57.512] INFO: 41600 events read in total (2622ms).
[14:44:57.513] INFO: Test took 3861ms.
[14:44:57.546] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:44:58.269] INFO: Expecting 41600 events.
[14:45:01.438] INFO: 41600 events read in total (2643ms).
[14:45:01.439] INFO: Test took 3876ms.
[14:45:01.472] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:45:02.195] INFO: Expecting 41600 events.
[14:45:05.338] INFO: 41600 events read in total (2617ms).
[14:45:05.339] INFO: Test took 3849ms.
[14:45:05.372] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:45:06.103] INFO: Expecting 41600 events.
[14:45:09.268] INFO: 41600 events read in total (2638ms).
[14:45:09.269] INFO: Test took 3879ms.
[14:45:09.301] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:45:10.026] INFO: Expecting 41600 events.
[14:45:13.174] INFO: 41600 events read in total (2622ms).
[14:45:13.175] INFO: Test took 3857ms.
[14:45:13.207] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:45:13.936] INFO: Expecting 41600 events.
[14:45:16.991] INFO: 41600 events read in total (2528ms).
[14:45:16.992] INFO: Test took 3767ms.
[14:45:17.023] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:45:17.389] INFO: enter test to run
[14:45:49.661] INFO: test: HighRate no parameter change
[14:45:49.661] INFO: running: highrate
[14:45:49.662] INFO: ----------------------------------------------------------------------
[14:45:49.662] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:45:49.662] INFO: ----------------------------------------------------------------------
[14:45:50.295] INFO: Expecting 208000 events.
[14:46:01.912] INFO: 208000 events read in total (11090ms).
[14:46:01.915] INFO: Test took 12229ms.
[14:46:02.050] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:46:02.300] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 2 0 1 0
[14:46:02.300] INFO: number of red-efficiency pixels: 70 58 75 111 112 118 107 89 87 128 87 78 93 54 18 41
[14:46:02.300] INFO: number of X-ray hits detected: 63803 41913 64339 96163 102884 105070 103083 72934 68827 89503 88291 77509 80759 52465 20211 24559
[14:46:02.300] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:46:02.300] INFO: number of Vcal hits detected: 207929 207942 207924 207887 207884 207879 207891 207909 207911 207871 207911 207921 207807 207944 207932 207955
[14:46:02.300] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 100.0 99.9 99.9 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0 100.0
[14:46:02.300] 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 100.0 100.0 99.9 100.0 100.0 100.0
[14:46:02.300] INFO: X-ray hit rate [MHz/cm2]: 18.7 12.3 18.9 28.2 30.2 30.8 30.2 21.4 20.2 26.2 25.9 22.7 23.7 15.4 5.9 7.2
[14:46:02.300] INFO: PixTestHighRate::doXPixelAlive() done
[14:46:02.346] INFO: PixTest:: pg_setup set to default.
[14:46:02.355] INFO: enter test to run
[14:46:38.164] INFO: test: HighRate no parameter change
[14:46:38.164] INFO: running: highrate
[14:46:38.165] INFO: ----------------------------------------------------------------------
[14:46:38.165] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:46:38.165] INFO: ----------------------------------------------------------------------
[14:46:38.779] INFO: Expecting 208000 events.
[14:46:51.945] INFO: 208000 events read in total (12639ms).
[14:46:51.951] INFO: Test took 13777ms.
[14:46:52.227] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:46:52.518] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 2 0 1 0
[14:46:52.518] INFO: number of red-efficiency pixels: 195 148 247 303 435 445 347 236 240 373 276 221 212 169 49 56
[14:46:52.518] INFO: number of X-ray hits detected: 130131 85275 132050 194425 210090 213320 209104 147985 139927 181762 180331 156428 164033 106935 41181 49986
[14:46:52.518] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:46:52.518] INFO: number of Vcal hits detected: 207787 207848 207725 207674 207536 207516 207621 207753 207751 207598 207711 207769 207675 207813 207899 207936
[14:46:52.518] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.9 99.8 99.8 99.8 99.9 99.9 99.8 99.9 99.9 99.9 99.9 100.0 100.0
[14:46:52.518] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.8 99.9 99.9 99.8 99.9 100.0 100.0
[14:46:52.518] INFO: X-ray hit rate [MHz/cm2]: 38.1 25.0 38.7 57.0 61.6 62.5 61.3 43.4 41.0 53.3 52.9 45.9 48.1 31.3 12.1 14.7
[14:46:52.518] INFO: PixTestHighRate::doXPixelAlive() done
[14:46:52.564] INFO: PixTest:: pg_setup set to default.
[14:46:52.577] INFO: enter test to run
[14:47:05.732] INFO: test: HighRate no parameter change
[14:47:05.732] INFO: running: highrate
[14:47:05.733] INFO: ----------------------------------------------------------------------
[14:47:05.733] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:47:05.733] INFO: ----------------------------------------------------------------------
[14:47:06.354] INFO: Expecting 208000 events.
[14:47:21.257] INFO: 208000 events read in total (14376ms).
[14:47:21.266] INFO: Test took 15522ms.
[14:47:21.684] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:47:22.019] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 2 0 1 0
[14:47:22.019] INFO: number of red-efficiency pixels: 454 266 580 680 1056 1053 754 452 466 837 614 477 488 345 80 99
[14:47:22.019] INFO: number of X-ray hits detected: 196616 128008 197571 293544 315109 320486 315157 222100 211509 275076 271111 235970 248039 160898 62156 75849
[14:47:22.019] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:47:22.019] INFO: number of Vcal hits detected: 207433 207707 207234 207241 206694 206689 207132 207482 207468 207029 207313 207468 207362 207604 207867 207890
[14:47:22.019] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.7 99.4 99.4 99.6 99.8 99.8 99.6 99.7 99.8 99.8 99.8 100.0 99.9
[14:47:22.019] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.6 99.6 99.4 99.4 99.6 99.8 99.7 99.5 99.7 99.7 99.7 99.8 99.9 99.9
[14:47:22.019] INFO: X-ray hit rate [MHz/cm2]: 57.6 37.5 57.9 86.0 92.4 93.9 92.4 65.1 62.0 80.6 79.5 69.2 72.7 47.2 18.2 22.2
[14:47:22.019] INFO: PixTestHighRate::doXPixelAlive() done
[14:47:22.072] INFO: PixTest:: pg_setup set to default.
[14:47:22.093] INFO: enter test to run
[14:47:46.572] INFO: test: exit no parameter change
[14:47:47.249] QUIET: Connection to board 33 closed.
[14:47:47.411] INFO: pXar: this is the end, my friend