[11:30:00.310] INFO: *** Welcome to pxar ***
[11:30:00.310] INFO: *** Today: 2017/02/22
[11:30:06.448] INFO: *** Version: v1.9.0-825-g6bc29
[11:30:06.448] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-5-26_FPIXTest-17C-FNAL-170201-1320-150V_2017-02-01_13h28m_1485977315/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-26_FPIXTest-17C-FNAL-170201-1320-150V_2017-02-01_13h28m_1485977315/000_FPIXTest_p17//dacParameters35_C15.dat
[11:30:06.929] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-5-26_FPIXTest-17C-FNAL-170201-1320-150V_2017-02-01_13h28m_1485977315/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-26_FPIXTest-17C-FNAL-170201-1320-150V_2017-02-01_13h28m_1485977315/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:30:06.985] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-5-26_FPIXTest-17C-FNAL-170201-1320-150V_2017-02-01_13h28m_1485977315/000_FPIXTest_p17//defaultMaskFile.dat
[11:30:07.009] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-5-26_FPIXTest-17C-FNAL-170201-1320-150V_2017-02-01_13h28m_1485977315/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-26_FPIXTest-17C-FNAL-170201-1320-150V_2017-02-01_13h28m_1485977315/000_FPIXTest_p17//trimParameters35_C15.dat
[11:30:08.067] INFO: clk: 4
[11:30:08.067] INFO: ctr: 4
[11:30:08.067] INFO: sda: 19
[11:30:08.067] INFO: tin: 9
[11:30:08.067] INFO: level: 15
[11:30:08.067] INFO: triggerdelay: 0
[11:30:08.067] QUIET: Instanciating API for pxar v1.9.0+825~g6bc290c
[11:30:08.067] INFO: Log level: DEBUG
[11:30:08.127] QUIET: Connection to board DTB_WREKRL opened.
[11:30:08.130] 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:
------------------------------------------------------
[11:30:08.133] INFO: RPC call hashes of host and DTB match: 398089610
[11:30:09.720] INFO: DUT info:
[11:30:09.720] INFO: The DUT currently contains the following objects:
[11:30:09.720] INFO: 2 TBM Cores tbm08c (2 ON)
[11:30:09.781] INFO: TBM Core alpha (0): 7 registers set
[11:30:09.781] INFO: TBM Core beta (1): 7 registers set
[11:30:09.781] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:30:09.781] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:09.781] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:09.781] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:09.781] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:09.781] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:09.781] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:09.781] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:09.781] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:09.781] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:09.781] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:09.781] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:09.782] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:09.782] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:09.782] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:09.782] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:09.782] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:09.849] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->BB<-
[11:30:09.849] DEBUG: <PixTestParameters.cc/dump:L107> dumpall: checkbox(0)
[11:30:09.849] DEBUG: <PixTestParameters.cc/dump:L107> dumpproblematic: checkbox(0)
[11:30:09.849] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 5
[11:30:09.849] DEBUG: <PixTestParameters.cc/dump:L107> vcals: 250
[11:30:09.849] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->BB2<-
[11:30:09.849] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[11:30:09.849] DEBUG: <PixTestParameters.cc/dump:L107> vcals: 222
[11:30:09.849] DEBUG: <PixTestParameters.cc/dump:L107> plwidth: 35
[11:30:09.849] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> targetia: 24
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->BB3<-
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dumpall: checkbox(0)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dumpproblematic: checkbox(0)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 5
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> vcals: 250
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->BB4<-
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> savecaldelscan: checkbox(0)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 100
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> cals: 1
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> caldello: 80
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> caldelhi: 200
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> caldelstep: 10
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> vthrcomplo: 70
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> vthrcomphi: 130
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> vthrcompstep: 5
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> noisypixels: 10
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> vcal: 255
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> cut: 0.5
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Cmd<-
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->DacDacScan<-
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> phmap: checkbox
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dac1: caldel
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dac1lo: 0
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dac1hi: 255
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dac2: vthrcomp
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dac2lo: 0
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dac2hi: 255
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->DacScan<-
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> phmap: checkbox(1)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> allpixels: checkbox(0)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> unmasked: checkbox(0)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dac: vcal
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> daclo: 0
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dachi: 255
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->GainPedestal<-
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> showfits: checkbox(0)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> extended: checkbox(0)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dumphists: checkbox(0)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> vcalstep: 10
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> measure: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> fit: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> save: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->HighRate<-
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> trimhotpixels: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> trimhotpixelthr: 200
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> runsecondshotpixels: 10
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> savetrimbits: checkbox(1)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> maskuntrimmable: checkbox(1)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> maskhotpixels: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> savemaskfile: checkbox(0)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> maskfilename: default
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> caldelscan: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> xpixelalive: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 50
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> vcal: 200
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> xnoisemaps: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> daclo: 0
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dachi: 100
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dacs/step: 20
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> rundaq: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> trgfrequency(khz): 20
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> runseconds: 2
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> triggerdelay: 20
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> delaytbm: checkbox
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> filltree: checkbox
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->IV<-
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> port: /dev/FIXME
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> voltagestart: 0
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> voltagestop: 600
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> voltagestep: 5
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> delay: 1
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> compliance(ua): 100
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->PhOptimization<-
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> safetymarginlow: 20
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> saturationvcal: 100
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> quantilesaturation: 0.98
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->PixelAlive<-
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> phmap: checkbox(0)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> vcal: 200
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> alivetest: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> masktest: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> addressdecodingtest: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Pretest<-
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> programroc: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> checkidig: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> targetia: 24
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> setvana: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> iterations: 100
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> settimings: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> findtiming: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> findworkingpixel: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> setvthrcompcaldel: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> vcal: 250
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> deltavthrcomp: 50
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> fraccaldel: 0.5
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 5
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> savedacs: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Readback<-
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> calibratevd: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> calibrateva: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> calibrateia: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> readbackvbg: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> getcalibratedvbg: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> usecalvd: checkbox(1)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> usecalva: checkbox(0)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> setvana: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Scurves<-
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> adjustvcal: checkbox(0)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dumpall: checkbox(0)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dumpproblematic: checkbox(0)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dumpoutputfile: checkbox(0)
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 50
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dac: Vcal
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> daclo: 0
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dachi: 200
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> dacs/step: -1
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> ntrig/step: -1
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> scurves: button
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Timing<-
[11:30:09.850] DEBUG: <PixTestParameters.cc/dump:L107> targetclk: 4
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10000
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> clocksdascan: button
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> notokenpass: checkbox(0)
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> ignorereadback: checkbox(0)
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> phasescan: button
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> levelscan: button
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> tbmphasescan: button
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> rocdelayscan: button
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> timingtest: button
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> saveparameters: button
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Trim<-
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> trim: button
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 8
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> vcal: 35
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> trimbits: button
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Xray<-
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> maskhotpixels: button
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> savemaskfile: checkbox(0)
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> maskfilename: default
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> source: Ag
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> phrun: button
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> runseconds: 100
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> trgfrequency(khz): 100
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> ratescan: button
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> vthrcompmin: 10
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> vthrcompmax: 80
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> stepseconds: 5
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> delaytbm: checkbox
[11:30:09.877] DEBUG: <PixTestParameters.cc/dump:L107> filltree: checkbox
[11:30:09.880] DEBUG: <PixSetup.cc/init:L81> PixSetup init start; getCurrentRSS() = 29052928
[11:30:09.880] DEBUG: <PixSetup.cc/init:L87> fPixTestParameters = 0x24da220
[11:30:09.880] DEBUG: <PixSetup.cc/init:L88> fConfigParameters = 0x2400310
[11:30:09.880] DEBUG: <PixSetup.cc/init:L89> fPxarMemory = 0x7f5825d94010
[11:30:09.880] DEBUG: <PixSetup.cc/init:L90> fPxarMemHi = 0x7f582bfff510
[11:30:09.880] DEBUG: <PixSetup.cc/init:L106> PixSetup init done; getCurrentRSS() = 29118464 fPxarMemory = 0x7f5825d94010
[11:30:09.881] DEBUG: <pXar.cc/main:L223> Initial Analog Current: 379.4mA
[11:30:09.882] DEBUG: <pXar.cc/main:L224> Initial Digital Current: 496mA
[11:30:09.882] DEBUG: <pXar.cc/main:L225> Initial Module Temperature: 0.9 C
[11:30:09.927] DEBUG: <PixTestFactory.cc/PixTestFactory:L53> PixTestFactory::PixTestFactory()
[11:30:10.344] INFO: enter 'restricted' command line mode
[11:30:10.344] INFO: enter test to run
[11:30:23.194] INFO: test: PixelAlive no parameter change
[11:30:23.194] INFO: running: pixelalive
[11:30:23.194] DEBUG: <PixTestAlive.cc/init:L83> PixTestAlive::init()
[11:30:23.245] DEBUG: <PixTestAlive.cc/PixTestAlive:L21> PixTestAlive ctor(PixSetup &a, string, TGTab *)
[11:30:23.245] DEBUG: <PixTestAlive.cc/runCommand:L62> running command: alivetest
[11:30:23.337] INFO: ----------------------------------------------------------------------
[11:30:23.337] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[11:30:23.337] INFO: ----------------------------------------------------------------------
[11:30:23.341] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[11:30:23.664] INFO: Expecting 41600 events.
[11:30:27.696] INFO: 41600 events read in total (3314ms).
[11:30:27.868] INFO: Test took 4527ms.
[11:30:27.875] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:30:27.875] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 66537
[11:30:27.875] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists PixelAlive_C0 .. PixelAlive_C15
[11:30:28.478] INFO: PixTestAlive::aliveTest() done
[11:30:28.478] INFO: number of dead pixels (per ROC): 0 0 0 0 0 2 0 0 0 13 0 0 0 0 8 0
[11:30:28.478] DEBUG: <PixTestAlive.cc/aliveTest:L199> number of red-efficiency pixels: 0 0 0 0 0 2 0 0 0 200 0 0 0 0 8 0
[11:30:28.478] DEBUG: <PixTestAlive.cc/~PixTestAlive:L115> PixTestAlive dtor
[11:30:28.953] INFO: enter test to run
[11:30:42.969] INFO: test: timing no parameter change
[11:30:42.970] INFO: running: timing
[11:30:42.970] DEBUG: <PixTestTiming.cc/setParameter:L59> PixTestTiming::PixTest() targetclk = 4
[11:30:42.970] DEBUG: <PixTestTiming.cc/setParameter:L63> PixTestTiming::PixTest() ntrig = 10000
[11:30:42.970] DEBUG: <PixTestTiming.cc/setParameter:L47> fNoTokenPass: 0
[11:30:42.970] DEBUG: <PixTestTiming.cc/setParameter:L54> fIgnoreReadBack: 0
[11:30:42.970] DEBUG: <PixTestTiming.cc/init:L73> PixTestTiming::init()
[11:30:42.973] INFO: ######################################################################
[11:30:42.973] INFO: PixTestTiming::doTest()
[11:30:42.973] INFO: ######################################################################
[11:30:42.973] INFO: ----------------------------------------------------------------------
[11:30:42.973] INFO: PixTestTiming::TBMPhaseScan()
[11:30:42.973] INFO: ----------------------------------------------------------------------
[11:30:42.973] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 0 400MHz Phase: 0 TBM Phase: 00000000
[11:30:44.985] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 0 400MHz Phase: 1 TBM Phase: 00000100
[11:30:47.373] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 0 400MHz Phase: 2 TBM Phase: 00001000
[11:30:49.761] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 0 400MHz Phase: 3 TBM Phase: 00001100
[11:30:52.144] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 0 400MHz Phase: 4 TBM Phase: 00010000
[11:30:54.533] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 0 400MHz Phase: 5 TBM Phase: 00010100
[11:30:56.923] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 0 400MHz Phase: 6 TBM Phase: 00011000
[11:30:59.314] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 0 400MHz Phase: 7 TBM Phase: 00011100
[11:31:01.699] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 1 400MHz Phase: 0 TBM Phase: 00100000
[11:31:04.090] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 1 400MHz Phase: 1 TBM Phase: 00100100
[11:31:06.483] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 1 400MHz Phase: 2 TBM Phase: 00101000
[11:31:08.875] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 1 400MHz Phase: 3 TBM Phase: 00101100
[11:31:11.264] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 1 400MHz Phase: 4 TBM Phase: 00110000
[11:31:13.654] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 1 400MHz Phase: 5 TBM Phase: 00110100
[11:31:16.045] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 1 400MHz Phase: 6 TBM Phase: 00111000
[11:31:18.438] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 1 400MHz Phase: 7 TBM Phase: 00111100
[11:31:20.828] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 2 400MHz Phase: 0 TBM Phase: 01000000
[11:31:22.407] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 2 400MHz Phase: 1 TBM Phase: 01000100
[11:31:23.929] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 2 400MHz Phase: 2 TBM Phase: 01001000
[11:31:25.453] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 2 400MHz Phase: 3 TBM Phase: 01001100
[11:31:26.976] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 2 400MHz Phase: 4 TBM Phase: 01010000
[11:31:28.500] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 2 400MHz Phase: 5 TBM Phase: 01010100
[11:31:30.023] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 2 400MHz Phase: 6 TBM Phase: 01011000
[11:31:31.544] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 2 400MHz Phase: 7 TBM Phase: 01011100
[11:31:33.069] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 3 400MHz Phase: 0 TBM Phase: 01100000
[11:31:34.592] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 3 400MHz Phase: 1 TBM Phase: 01100100
[11:31:36.116] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 3 400MHz Phase: 2 TBM Phase: 01101000
[11:31:37.641] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 3 400MHz Phase: 3 TBM Phase: 01101100
[11:31:39.167] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 3 400MHz Phase: 4 TBM Phase: 01110000
[11:31:40.689] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 3 400MHz Phase: 5 TBM Phase: 01110100
[11:31:42.211] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 3 400MHz Phase: 6 TBM Phase: 01111000
[11:31:43.735] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 3 400MHz Phase: 7 TBM Phase: 01111100
[11:31:45.259] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 4 400MHz Phase: 0 TBM Phase: 10000000
[11:31:46.781] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 4 400MHz Phase: 1 TBM Phase: 10000100
[11:31:48.303] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 4 400MHz Phase: 2 TBM Phase: 10001000
[11:31:49.827] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 4 400MHz Phase: 3 TBM Phase: 10001100
[11:31:51.350] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 4 400MHz Phase: 4 TBM Phase: 10010000
[11:31:52.871] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 4 400MHz Phase: 5 TBM Phase: 10010100
[11:31:54.396] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 4 400MHz Phase: 6 TBM Phase: 10011000
[11:31:55.919] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 4 400MHz Phase: 7 TBM Phase: 10011100
[11:31:57.440] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 5 400MHz Phase: 0 TBM Phase: 10100000
[11:31:59.836] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 5 400MHz Phase: 1 TBM Phase: 10100100
[11:32:02.236] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 5 400MHz Phase: 2 TBM Phase: 10101000
[11:32:04.638] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 5 400MHz Phase: 3 TBM Phase: 10101100
[11:32:07.041] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 5 400MHz Phase: 4 TBM Phase: 10110000
[11:32:09.444] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 5 400MHz Phase: 5 TBM Phase: 10110100
[11:32:10.969] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 5 400MHz Phase: 6 TBM Phase: 10111000
[11:32:13.371] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 5 400MHz Phase: 7 TBM Phase: 10111100
[11:32:15.771] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 6 400MHz Phase: 0 TBM Phase: 11000000
[11:32:18.164] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 6 400MHz Phase: 1 TBM Phase: 11000100
[11:32:20.551] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 6 400MHz Phase: 2 TBM Phase: 11001000
[11:32:22.945] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 6 400MHz Phase: 3 TBM Phase: 11001100
[11:32:25.335] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 6 400MHz Phase: 4 TBM Phase: 11010000
[11:32:27.729] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 6 400MHz Phase: 5 TBM Phase: 11010100
[11:32:30.123] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 6 400MHz Phase: 6 TBM Phase: 11011000
[11:32:32.516] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 6 400MHz Phase: 7 TBM Phase: 11011100
[11:32:34.907] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 7 400MHz Phase: 0 TBM Phase: 11100000
[11:32:37.302] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 7 400MHz Phase: 1 TBM Phase: 11100100
[11:32:39.694] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 7 400MHz Phase: 2 TBM Phase: 11101000
[11:32:42.087] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 7 400MHz Phase: 3 TBM Phase: 11101100
[11:32:44.477] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 7 400MHz Phase: 4 TBM Phase: 11110000
[11:32:46.869] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 7 400MHz Phase: 5 TBM Phase: 11110100
[11:32:49.262] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 7 400MHz Phase: 6 TBM Phase: 11111000
[11:32:51.653] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 7 400MHz Phase: 7 TBM Phase: 11111100
[11:32:54.036] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 0 400MHz Phase: 0 TBM Phase: 00000000
[11:32:56.423] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 0 400MHz Phase: 1 TBM Phase: 00000100
[11:32:58.808] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 0 400MHz Phase: 2 TBM Phase: 00001000
[11:33:01.202] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 0 400MHz Phase: 3 TBM Phase: 00001100
[11:33:03.590] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 0 400MHz Phase: 4 TBM Phase: 00010000
[11:33:05.978] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 0 400MHz Phase: 5 TBM Phase: 00010100
[11:33:08.362] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 0 400MHz Phase: 6 TBM Phase: 00011000
[11:33:10.750] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 0 400MHz Phase: 7 TBM Phase: 00011100
[11:33:13.138] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 1 400MHz Phase: 0 TBM Phase: 00100000
[11:33:14.660] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 1 400MHz Phase: 1 TBM Phase: 00100100
[11:33:16.181] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 1 400MHz Phase: 2 TBM Phase: 00101000
[11:33:17.703] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 1 400MHz Phase: 3 TBM Phase: 00101100
[11:33:19.223] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 1 400MHz Phase: 4 TBM Phase: 00110000
[11:33:20.745] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 1 400MHz Phase: 5 TBM Phase: 00110100
[11:33:22.265] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 1 400MHz Phase: 6 TBM Phase: 00111000
[11:33:23.786] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 1 400MHz Phase: 7 TBM Phase: 00111100
[11:33:25.307] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 2 400MHz Phase: 0 TBM Phase: 01000000
[11:33:30.216] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 2 400MHz Phase: 1 TBM Phase: 01000100
[11:33:35.123] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 2 400MHz Phase: 2 TBM Phase: 01001000
[11:33:40.032] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 2 400MHz Phase: 3 TBM Phase: 01001100
[11:33:44.941] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 2 400MHz Phase: 4 TBM Phase: 01010000
[11:33:49.850] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 2 400MHz Phase: 5 TBM Phase: 01010100
[11:33:54.760] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 2 400MHz Phase: 6 TBM Phase: 01011000
[11:33:59.668] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 2 400MHz Phase: 7 TBM Phase: 01011100
[11:34:04.577] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 3 400MHz Phase: 0 TBM Phase: 01100000
[11:34:06.101] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 3 400MHz Phase: 1 TBM Phase: 01100100
[11:34:07.623] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 3 400MHz Phase: 2 TBM Phase: 01101000
[11:34:09.146] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 3 400MHz Phase: 3 TBM Phase: 01101100
[11:34:10.670] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 3 400MHz Phase: 4 TBM Phase: 01110000
[11:34:12.193] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 3 400MHz Phase: 5 TBM Phase: 01110100
[11:34:13.716] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 3 400MHz Phase: 6 TBM Phase: 01111000
[11:34:15.239] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 3 400MHz Phase: 7 TBM Phase: 01111100
[11:34:16.760] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 4 400MHz Phase: 0 TBM Phase: 10000000
[11:34:18.283] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 4 400MHz Phase: 1 TBM Phase: 10000100
[11:34:19.807] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 4 400MHz Phase: 2 TBM Phase: 10001000
[11:34:21.330] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 4 400MHz Phase: 3 TBM Phase: 10001100
[11:34:22.852] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 4 400MHz Phase: 4 TBM Phase: 10010000
[11:34:24.375] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 4 400MHz Phase: 5 TBM Phase: 10010100
[11:34:25.898] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 4 400MHz Phase: 6 TBM Phase: 10011000
[11:34:27.421] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 4 400MHz Phase: 7 TBM Phase: 10011100
[11:34:28.944] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 5 400MHz Phase: 0 TBM Phase: 10100000
[11:34:31.341] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 5 400MHz Phase: 1 TBM Phase: 10100100
[11:34:33.751] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 5 400MHz Phase: 2 TBM Phase: 10101000
[11:34:36.149] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 5 400MHz Phase: 3 TBM Phase: 10101100
[11:34:38.551] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 5 400MHz Phase: 4 TBM Phase: 10110000
[11:34:40.947] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 5 400MHz Phase: 5 TBM Phase: 10110100
[11:34:43.349] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 5 400MHz Phase: 6 TBM Phase: 10111000
[11:34:45.745] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 5 400MHz Phase: 7 TBM Phase: 10111100
[11:34:48.137] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 6 400MHz Phase: 0 TBM Phase: 11000000
[11:34:50.533] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 6 400MHz Phase: 1 TBM Phase: 11000100
[11:34:52.928] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 6 400MHz Phase: 2 TBM Phase: 11001000
[11:34:55.324] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 6 400MHz Phase: 3 TBM Phase: 11001100
[11:34:57.722] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 6 400MHz Phase: 4 TBM Phase: 11010000
[11:35:00.116] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 6 400MHz Phase: 5 TBM Phase: 11010100
[11:35:02.512] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 6 400MHz Phase: 6 TBM Phase: 11011000
[11:35:04.909] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 6 400MHz Phase: 7 TBM Phase: 11011100
[11:35:07.308] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 7 400MHz Phase: 0 TBM Phase: 11100000
[11:35:09.702] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 7 400MHz Phase: 1 TBM Phase: 11100100
[11:35:12.098] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 7 400MHz Phase: 2 TBM Phase: 11101000
[11:35:14.495] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 7 400MHz Phase: 3 TBM Phase: 11101100
[11:35:16.895] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 7 400MHz Phase: 4 TBM Phase: 11110000
[11:35:19.291] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 7 400MHz Phase: 5 TBM Phase: 11110100
[11:35:21.685] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 7 400MHz Phase: 6 TBM Phase: 11111000
[11:35:24.082] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 7 400MHz Phase: 7 TBM Phase: 11111100
[11:35:26.957] INFO: TBM Phase Settings: 236
[11:35:26.957] INFO: 400MHz Phase: 3
[11:35:26.957] INFO: 160MHz Phase: 7
[11:35:26.957] INFO: Functional Phase Area: 3
[11:35:26.968] INFO: Test took 283995 ms.
[11:35:26.968] INFO: PixTestTiming::TBMPhaseScan() done.
[11:35:26.968] INFO: ----------------------------------------------------------------------
[11:35:26.968] INFO: PixTestTiming::ROCDelayScan()
[11:35:26.968] INFO: ----------------------------------------------------------------------
[11:35:26.972] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 0 ROC Port0: 0 ROCDelay Setting: 11000000
[11:35:31.505] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 0 ROC Port0: 1 ROCDelay Setting: 11000001
[11:35:36.416] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 0 ROC Port0: 2 ROCDelay Setting: 11000010
[11:35:37.938] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 0 ROC Port0: 3 ROCDelay Setting: 11000011
[11:35:39.462] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 0 ROC Port0: 4 ROCDelay Setting: 11000100
[11:35:40.984] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 0 ROC Port0: 5 ROCDelay Setting: 11000101
[11:35:42.505] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 0 ROC Port0: 6 ROCDelay Setting: 11000110
[11:35:44.029] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 0 ROC Port0: 7 ROCDelay Setting: 11000111
[11:35:46.304] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 1 ROC Port0: 0 ROCDelay Setting: 11001000
[11:35:51.214] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 1 ROC Port0: 1 ROCDelay Setting: 11001001
[11:35:56.121] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 1 ROC Port0: 2 ROCDelay Setting: 11001010
[11:35:57.644] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 1 ROC Port0: 3 ROCDelay Setting: 11001011
[11:35:59.167] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 1 ROC Port0: 4 ROCDelay Setting: 11001100
[11:36:00.692] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 1 ROC Port0: 5 ROCDelay Setting: 11001101
[11:36:02.215] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 1 ROC Port0: 6 ROCDelay Setting: 11001110
[11:36:03.738] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 1 ROC Port0: 7 ROCDelay Setting: 11001111
[11:36:05.637] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 2 ROC Port0: 0 ROCDelay Setting: 11010000
[11:36:10.547] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 2 ROC Port0: 1 ROCDelay Setting: 11010001
[11:36:15.454] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 2 ROC Port0: 2 ROCDelay Setting: 11010010
[11:36:16.977] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 2 ROC Port0: 3 ROCDelay Setting: 11010011
[11:36:18.499] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 2 ROC Port0: 4 ROCDelay Setting: 11010100
[11:36:20.022] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 2 ROC Port0: 5 ROCDelay Setting: 11010101
[11:36:21.544] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 2 ROC Port0: 6 ROCDelay Setting: 11010110
[11:36:23.066] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 2 ROC Port0: 7 ROCDelay Setting: 11010111
[11:36:25.152] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 3 ROC Port0: 0 ROCDelay Setting: 11011000
[11:36:30.062] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 3 ROC Port0: 1 ROCDelay Setting: 11011001
[11:36:34.969] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 3 ROC Port0: 2 ROCDelay Setting: 11011010
[11:36:36.493] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 3 ROC Port0: 3 ROCDelay Setting: 11011011
[11:36:38.921] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 3 ROC Port0: 4 ROCDelay Setting: 11011100
[11:36:41.343] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 3 ROC Port0: 5 ROCDelay Setting: 11011101
[11:36:43.774] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 3 ROC Port0: 6 ROCDelay Setting: 11011110
[11:36:46.199] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 3 ROC Port0: 7 ROCDelay Setting: 11011111
[11:36:48.662] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 4 ROC Port0: 0 ROCDelay Setting: 11100000
[11:36:53.571] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 4 ROC Port0: 1 ROCDelay Setting: 11100001
[11:36:58.481] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 4 ROC Port0: 2 ROCDelay Setting: 11100010
[11:36:59.002] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 4 ROC Port0: 3 ROCDelay Setting: 11100011
[11:37:02.426] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 4 ROC Port0: 4 ROCDelay Setting: 11100100
[11:37:04.850] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 4 ROC Port0: 5 ROCDelay Setting: 11100101
[11:37:07.277] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 4 ROC Port0: 6 ROCDelay Setting: 11100110
[11:37:09.699] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 4 ROC Port0: 7 ROCDelay Setting: 11100111
[11:37:12.352] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 5 ROC Port0: 0 ROCDelay Setting: 11101000
[11:37:17.260] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 5 ROC Port0: 1 ROCDelay Setting: 11101001
[11:37:22.169] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 5 ROC Port0: 2 ROCDelay Setting: 11101010
[11:37:23.691] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 5 ROC Port0: 3 ROCDelay Setting: 11101011
[11:37:26.113] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 5 ROC Port0: 4 ROCDelay Setting: 11101100
[11:37:28.541] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 5 ROC Port0: 5 ROCDelay Setting: 11101101
[11:37:30.965] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 5 ROC Port0: 6 ROCDelay Setting: 11101110
[11:37:33.388] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 5 ROC Port0: 7 ROCDelay Setting: 11101111
[11:37:34.911] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 6 ROC Port0: 0 ROCDelay Setting: 11110000
[11:37:39.820] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 6 ROC Port0: 1 ROCDelay Setting: 11110001
[11:37:44.729] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 6 ROC Port0: 2 ROCDelay Setting: 11110010
[11:37:46.252] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 6 ROC Port0: 3 ROCDelay Setting: 11110011
[11:37:48.674] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 6 ROC Port0: 4 ROCDelay Setting: 11110100
[11:37:51.099] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 6 ROC Port0: 5 ROCDelay Setting: 11110101
[11:37:53.524] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 6 ROC Port0: 6 ROCDelay Setting: 11110110
[11:37:55.947] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 6 ROC Port0: 7 ROCDelay Setting: 11110111
[11:37:57.657] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 7 ROC Port0: 0 ROCDelay Setting: 11111000
[11:38:02.566] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 7 ROC Port0: 1 ROCDelay Setting: 11111001
[11:38:07.476] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 7 ROC Port0: 2 ROCDelay Setting: 11111010
[11:38:08.999] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 7 ROC Port0: 3 ROCDelay Setting: 11111011
[11:38:10.522] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 7 ROC Port0: 4 ROCDelay Setting: 11111100
[11:38:12.045] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 7 ROC Port0: 5 ROCDelay Setting: 11111101
[11:38:13.568] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 7 ROC Port0: 6 ROCDelay Setting: 11111110
[11:38:15.093] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 7 ROC Port0: 7 ROCDelay Setting: 11111111
[11:38:17.184] INFO: ROC Delay Settings: 228
[11:38:17.184] INFO: ROC Header-Trailer/Token Delay: 11
[11:38:17.184] INFO: ROC Port 0 Delay: 4
[11:38:17.184] INFO: ROC Port 1 Delay: 4
[11:38:17.184] INFO: Functional ROC Area: 4
[11:38:17.187] INFO: Test took 170219 ms.
[11:38:17.187] INFO: PixTestTiming::ROCDelayScan() done.
[11:38:17.235] INFO: ----------------------------------------------------------------------
[11:38:17.235] INFO: PixTestTiming::TimingTest()
[11:38:17.235] INFO: ----------------------------------------------------------------------
[11:38:18.377] DEBUG: <PixTest.cc/getEvents:L2459> Event: ====== 0 ====== a001 8000 4838 4838 4838 4838 4838 4838 4838 4838 e062 c000 a101 80c0 4838 4838 4838 4838 4839 4839 4839 4839 e062 c000
[11:38:18.377] DEBUG: <PixTest.cc/getEvents:L2459> Event: ====== 0 ====== a002 8040 4838 4838 4838 4838 4838 4838 4838 4838 e022 c000 a102 8000 4838 4838 4839 4839 4838 4838 4839 4839 e022 c000
[11:38:18.377] DEBUG: <PixTest.cc/getEvents:L2459> Event: ====== 0 ====== a003 80b1 4838 4838 4838 4838 4838 4838 4838 4838 e022 c000 a103 8040 4838 4839 4838 4839 4838 4839 4838 4839 e022 c000
[11:38:18.377] DEBUG: <PixTest.cc/getEvents:L2463> Collecting 1000000/10000000 Triggers
[11:38:33.502] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:33.502] DEBUG: <PixTest.cc/getEvents:L2463> Collecting 2000000/10000000 Triggers
[11:38:48.494] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:48.494] DEBUG: <PixTest.cc/getEvents:L2463> Collecting 3000000/10000000 Triggers
[11:39:03.435] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:03.435] DEBUG: <PixTest.cc/getEvents:L2463> Collecting 4000000/10000000 Triggers
[11:39:18.486] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:18.486] DEBUG: <PixTest.cc/getEvents:L2463> Collecting 5000000/10000000 Triggers
[11:39:33.413] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:33.413] DEBUG: <PixTest.cc/getEvents:L2463> Collecting 6000000/10000000 Triggers
[11:39:48.396] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:48.396] DEBUG: <PixTest.cc/getEvents:L2463> Collecting 7000000/10000000 Triggers
[11:40:03.413] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:03.413] DEBUG: <PixTest.cc/getEvents:L2463> Collecting 8000000/10000000 Triggers
[11:40:18.450] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:18.450] DEBUG: <PixTest.cc/getEvents:L2463> Collecting 9000000/10000000 Triggers
[11:40:33.508] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:33.508] DEBUG: <PixTest.cc/getEvents:L2470> Collecting 10000000/10000000 Triggers
[11:40:48.617] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:48.998] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:49.033] INFO: Decoding statistics:
[11:40:49.034] INFO: General information:
[11:40:49.034] INFO: 16bit words read: 240000000
[11:40:49.034] INFO: valid events total: 20000000
[11:40:49.034] INFO: empty events: 20000000
[11:40:49.034] INFO: valid events with pixels: 0
[11:40:49.034] INFO: valid pixel hits: 0
[11:40:49.034] INFO: Event errors: 0
[11:40:49.034] INFO: start marker: 0
[11:40:49.034] INFO: stop marker: 0
[11:40:49.034] INFO: overflow: 0
[11:40:49.034] INFO: invalid 5bit words: 0
[11:40:49.034] INFO: invalid XOR eye diagram: 0
[11:40:49.034] INFO: TBM errors: 0
[11:40:49.034] INFO: flawed TBM headers: 0
[11:40:49.034] INFO: flawed TBM trailers: 0
[11:40:49.034] INFO: event ID mismatches: 0
[11:40:49.034] INFO: ROC errors: 0
[11:40:49.034] INFO: missing ROC header(s): 0
[11:40:49.034] INFO: misplaced readback start: 0
[11:40:49.034] INFO: Pixel decoding errors: 0
[11:40:49.034] INFO: pixel data incomplete: 0
[11:40:49.034] INFO: pixel address: 0
[11:40:49.034] INFO: pulse height fill bit: 0
[11:40:49.034] INFO: buffer corruption: 0
[11:40:49.034] INFO: ----------------------------------------------------------------------
[11:40:49.034] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:40:49.034] INFO: ----------------------------------------------------------------------
[11:40:49.034] INFO: ----------------------------------------------------------------------
[11:40:49.034] INFO: Read back bit status: 1
[11:40:49.034] INFO: ----------------------------------------------------------------------
[11:40:49.034] INFO: ----------------------------------------------------------------------
[11:40:49.034] INFO: Timings are good!
[11:40:49.034] INFO: ----------------------------------------------------------------------
[11:40:49.034] INFO: Test took 151799 ms.
[11:40:49.034] INFO: PixTestTiming::TimingTest() done.
[11:40:49.120] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-26_FPIXTest-17C-FNAL-170201-1320-150V_2017-02-01_13h28m_1485977315/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:40:49.167] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-26_FPIXTest-17C-FNAL-170201-1320-150V_2017-02-01_13h28m_1485977315/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:40:49.167] INFO: PixTestTiming::doTest took 606197 ms.
[11:40:49.167] INFO: PixTestTiming::doTest() done
[11:40:49.167] DEBUG: <PixTestTiming.cc/~PixTestTiming:L96> PixTestTiming dtor
[11:40:49.182] INFO: Write out TBMPhaseScan_0_V0
[11:40:49.299] INFO: Write out TBMPhaseScan_1_V0
[11:40:49.299] INFO: Write out CombinedTBMPhaseScan_V0
[11:40:49.683] INFO: Write out ROCDelayScan3_V0
[11:40:49.708] INFO: enter test to run
[11:42:13.557] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:42:13.558] DEBUG: <PixTestParameters.cc/setTestParameter:L119> PixTestParameters: ->Xray<-
[11:42:13.558] DEBUG: <PixTestParameters.cc/setTestParameter:L124> setting source to new value DCLowRate
[11:42:13.558] INFO: running: xray
[11:42:13.585] DEBUG: <PixTestXray.cc/init:L135> PixTestXray::init()
[11:42:13.586] DEBUG: <PixTestXray.cc/PixTestXray:L28> PixTestXray ctor(PixSetup &a, string, TGTab *)
[11:42:13.586] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-5-26_FPIXTest-17C-FNAL-170201-1320-150V_2017-02-01_13h28m_1485977315/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-26_FPIXTest-17C-FNAL-170201-1320-150V_2017-02-01_13h28m_1485977315/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:42:13.840] DEBUG: <PixTestXray.cc/runCommand:L109> running command: phrun
[11:42:13.840] INFO: ----------------------------------------------------------------------
[11:42:13.840] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:42:13.840] INFO: ----------------------------------------------------------------------
[11:42:14.840] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:42:26.385] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[11:42:26.389] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:42:52.114] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 1137533 events.
[11:42:55.658] DEBUG: <PixTestXray.cc/processData:L823> # events read: 1137533, pixels seen in all events: 6600471
[11:42:55.690] INFO: Resuming triggers.
[11:43:07.249] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[11:43:07.252] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:43:32.889] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 1138743 events.
[11:43:36.345] DEBUG: <PixTestXray.cc/processData:L823> # events read: 1138743, pixels seen in all events: 6586779
[11:43:36.423] INFO: Resuming triggers.
[11:43:47.975] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[11:43:47.978] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:44:13.567] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 1138035 events.
[11:44:17.097] DEBUG: <PixTestXray.cc/processData:L823> # events read: 1138035, pixels seen in all events: 6595244
[11:44:17.171] INFO: Resuming triggers.
[11:44:28.725] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[11:44:28.729] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:44:54.379] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 1138288 events.
[11:44:58.027] DEBUG: <PixTestXray.cc/processData:L823> # events read: 1138288, pixels seen in all events: 6592224
[11:44:58.148] INFO: Resuming triggers.
[11:45:09.708] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[11:45:09.711] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:45:35.308] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 1138862 events.
[11:45:39.137] DEBUG: <PixTestXray.cc/processData:L823> # events read: 1138862, pixels seen in all events: 6584854
[11:45:39.215] INFO: Resuming triggers.
[11:45:50.775] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[11:45:50.778] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:46:16.600] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 1138865 events.
[11:46:20.358] DEBUG: <PixTestXray.cc/processData:L823> # events read: 1138865, pixels seen in all events: 6584779
[11:46:20.435] INFO: Resuming triggers.
[11:46:31.990] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[11:46:31.994] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:46:58.019] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 1138426 events.
[11:47:01.902] DEBUG: <PixTestXray.cc/processData:L823> # events read: 1138426, pixels seen in all events: 6589961
[11:47:02.033] INFO: Resuming triggers.
[11:47:13.622] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[11:47:13.626] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:47:38.658] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 1141638 events.
[11:47:42.872] DEBUG: <PixTestXray.cc/processData:L823> # events read: 1141638, pixels seen in all events: 6551967
[11:47:42.904] INFO: Resuming triggers.
[11:47:50.774] INFO: data taking finished, elapsed time: 100 seconds.
[11:47:50.969] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:48:08.590] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 775295 events.
[11:48:11.230] DEBUG: <PixTestXray.cc/processData:L823> # events read: 775295, pixels seen in all events: 4443324
[11:48:11.310] INFO: PixTest:: pg_setup set to default.
[11:48:11.313] INFO: PixTestXray::doPhRun() done
[11:48:11.318] DEBUG: <PixTestXray.cc/~PixTestXray:L218> PixTestXray dtor
[11:48:11.473] INFO: enter test to run
[11:49:35.875] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[11:49:35.875] DEBUG: <PixTestParameters.cc/setTestParameter:L119> PixTestParameters: ->Xray<-
[11:49:35.875] DEBUG: <PixTestParameters.cc/setTestParameter:L124> setting source to new value DCHighRate
[11:49:35.875] INFO: running: xray
[11:49:35.875] DEBUG: <PixTestXray.cc/init:L135> PixTestXray::init()
[11:49:35.875] DEBUG: <PixTestXray.cc/PixTestXray:L28> PixTestXray ctor(PixSetup &a, string, TGTab *)
[11:49:35.876] DEBUG: <PixTestXray.cc/runCommand:L109> running command: phrun
[11:49:35.876] INFO: ----------------------------------------------------------------------
[11:49:35.876] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:49:35.876] INFO: ----------------------------------------------------------------------
[11:49:36.840] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:49:43.734] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[11:49:43.738] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:50:07.315] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 679273 events.
[11:50:14.033] DEBUG: <PixTestXray.cc/processData:L823> # events read: 679273, pixels seen in all events: 12100438
[11:50:14.111] INFO: Resuming triggers.
[11:50:21.008] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[11:50:21.012] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:50:44.705] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 679422 events.
[11:50:51.343] DEBUG: <PixTestXray.cc/processData:L823> # events read: 679422, pixels seen in all events: 12099754
[11:50:51.419] INFO: Resuming triggers.
[11:50:58.314] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[11:50:58.317] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:51:21.991] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 679203 events.
[11:51:28.938] DEBUG: <PixTestXray.cc/processData:L823> # events read: 679203, pixels seen in all events: 12102253
[11:51:29.015] INFO: Resuming triggers.
[11:51:35.909] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[11:51:35.912] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:51:59.645] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 679106 events.
[11:52:06.435] DEBUG: <PixTestXray.cc/processData:L823> # events read: 679106, pixels seen in all events: 12102653
[11:52:06.515] INFO: Resuming triggers.
[11:52:13.405] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[11:52:13.408] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:52:38.121] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 678790 events.
[11:52:44.970] DEBUG: <PixTestXray.cc/processData:L823> # events read: 678790, pixels seen in all events: 12106850
[11:52:45.052] INFO: Resuming triggers.
[11:52:51.945] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[11:52:51.948] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:53:16.485] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 679012 events.
[11:53:23.367] DEBUG: <PixTestXray.cc/processData:L823> # events read: 679012, pixels seen in all events: 12104428
[11:53:23.445] INFO: Resuming triggers.
[11:53:30.334] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[11:53:30.337] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:53:55.059] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 678636 events.
[11:54:01.781] DEBUG: <PixTestXray.cc/processData:L823> # events read: 678636, pixels seen in all events: 12109142
[11:54:01.860] INFO: Resuming triggers.
[11:54:08.742] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[11:54:08.746] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:54:33.436] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 677963 events.
[11:54:40.324] DEBUG: <PixTestXray.cc/processData:L823> # events read: 677963, pixels seen in all events: 12117056
[11:54:40.403] INFO: Resuming triggers.
[11:54:47.284] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[11:54:47.287] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:55:11.472] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 677840 events.
[11:55:18.107] DEBUG: <PixTestXray.cc/processData:L823> # events read: 677840, pixels seen in all events: 12118536
[11:55:18.189] INFO: Resuming triggers.
[11:55:25.076] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[11:55:25.080] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:55:49.211] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 678500 events.
[11:55:55.454] DEBUG: <PixTestXray.cc/processData:L823> # events read: 678500, pixels seen in all events: 12110362
[11:55:55.529] INFO: Resuming triggers.
[11:56:02.411] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[11:56:02.414] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:56:26.152] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 677940 events.
[11:56:32.634] DEBUG: <PixTestXray.cc/processData:L823> # events read: 677940, pixels seen in all events: 12116295
[11:56:32.708] INFO: Resuming triggers.
[11:56:39.596] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[11:56:39.599] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:57:03.375] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 678571 events.
[11:57:09.831] DEBUG: <PixTestXray.cc/processData:L823> # events read: 678571, pixels seen in all events: 12109491
[11:57:09.906] INFO: Resuming triggers.
[11:57:16.791] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[11:57:16.795] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:57:40.662] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 678322 events.
[11:57:47.127] DEBUG: <PixTestXray.cc/processData:L823> # events read: 678322, pixels seen in all events: 12111794
[11:57:47.204] INFO: Resuming triggers.
[11:57:54.092] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[11:57:54.095] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:58:17.980] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 678582 events.
[11:58:24.561] DEBUG: <PixTestXray.cc/processData:L823> # events read: 678582, pixels seen in all events: 12108583
[11:58:24.636] INFO: Resuming triggers.
[11:58:28.555] INFO: data taking finished, elapsed time: 100 seconds.
[11:58:28.751] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[11:58:42.247] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 386116 events.
[11:58:45.926] DEBUG: <PixTestXray.cc/processData:L823> # events read: 386116, pixels seen in all events: 6875391
[11:58:45.959] INFO: PixTest:: pg_setup set to default.
[11:58:45.963] INFO: PixTestXray::doPhRun() done
[11:58:45.963] DEBUG: <PixTestXray.cc/~PixTestXray:L218> PixTestXray dtor
[11:58:46.126] INFO: enter test to run
[12:00:13.342] INFO: test: HighRate no parameter change
[12:00:13.342] INFO: running: highrate
[12:00:13.372] DEBUG: <PixTestHighRate.cc/setParameter:L68> setting fParTriggerFrequency -> 20
[12:00:13.372] DEBUG: <PixTestHighRate.cc/init:L211> PixTestHighRate::init()
[12:00:13.372] DEBUG: <PixTestHighRate.cc/PixTestHighRate:L31> PixTestHighRate ctor(PixSetup &a, string, TGTab *)
[12:00:13.373] DEBUG: <PixTestHighRate.cc/runCommand:L165> running command: caldelscan
[12:00:13.377] INFO: ----------------------------------------------------------------------
[12:00:13.377] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:00:13.377] INFO: ----------------------------------------------------------------------
[12:00:13.525] INFO: Expecting 768 events.
[12:00:14.659] INFO: 768 events read in total (418ms).
[12:00:14.659] INFO: Test took 1268ms.
[12:00:14.695] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:00:15.462] INFO: Expecting 41600 events.
[12:00:18.586] INFO: 41600 events read in total (2597ms).
[12:00:18.587] INFO: Test took 3892ms.
[12:00:18.625] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:18.625] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 364711
[12:00:18.625] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step0_C0 .. HR_xeff_CalDelScan_step0_C15
[12:00:18.625] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:00:18.647] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:00:19.346] INFO: Expecting 41600 events.
[12:00:22.572] INFO: 41600 events read in total (2699ms).
[12:00:22.573] INFO: Test took 3926ms.
[12:00:22.612] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:22.612] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 372969
[12:00:22.612] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step1_C0 .. HR_xeff_CalDelScan_step1_C15
[12:00:22.612] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:00:22.631] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:00:23.328] INFO: Expecting 41600 events.
[12:00:26.617] INFO: 41600 events read in total (2762ms).
[12:00:26.618] INFO: Test took 3987ms.
[12:00:26.656] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:26.656] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 370723
[12:00:26.656] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step2_C0 .. HR_xeff_CalDelScan_step2_C15
[12:00:26.656] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:00:26.676] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:00:27.373] INFO: Expecting 41600 events.
[12:00:30.660] INFO: 41600 events read in total (2760ms).
[12:00:30.662] INFO: Test took 3986ms.
[12:00:30.700] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:30.700] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 372346
[12:00:30.700] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step3_C0 .. HR_xeff_CalDelScan_step3_C15
[12:00:30.700] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:00:30.721] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:00:31.414] INFO: Expecting 41600 events.
[12:00:34.610] INFO: 41600 events read in total (2669ms).
[12:00:34.612] INFO: Test took 3891ms.
[12:00:34.649] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:34.649] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 378540
[12:00:34.649] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step4_C0 .. HR_xeff_CalDelScan_step4_C15
[12:00:34.650] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:00:34.669] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:00:35.366] INFO: Expecting 41600 events.
[12:00:38.667] INFO: 41600 events read in total (2774ms).
[12:00:38.668] INFO: Test took 3999ms.
[12:00:38.706] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:38.706] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 378927
[12:00:38.706] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step5_C0 .. HR_xeff_CalDelScan_step5_C15
[12:00:38.707] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:00:38.727] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:00:39.422] INFO: Expecting 41600 events.
[12:00:42.720] INFO: 41600 events read in total (2771ms).
[12:00:42.721] INFO: Test took 3994ms.
[12:00:42.760] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:42.760] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 375131
[12:00:42.760] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step6_C0 .. HR_xeff_CalDelScan_step6_C15
[12:00:42.760] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:00:42.779] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:00:43.474] INFO: Expecting 41600 events.
[12:00:46.775] INFO: 41600 events read in total (2774ms).
[12:00:46.776] INFO: Test took 3997ms.
[12:00:46.814] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:46.814] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 377922
[12:00:46.814] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step7_C0 .. HR_xeff_CalDelScan_step7_C15
[12:00:46.815] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:00:46.834] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:00:47.526] INFO: Expecting 41600 events.
[12:00:50.832] INFO: 41600 events read in total (2779ms).
[12:00:50.833] INFO: Test took 3999ms.
[12:00:50.874] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:50.874] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 380657
[12:00:50.874] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step8_C0 .. HR_xeff_CalDelScan_step8_C15
[12:00:50.874] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:00:50.894] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:00:51.582] INFO: Expecting 41600 events.
[12:00:54.896] INFO: 41600 events read in total (2787ms).
[12:00:54.898] INFO: Test took 4004ms.
[12:00:54.943] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:54.943] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 379786
[12:00:54.943] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step9_C0 .. HR_xeff_CalDelScan_step9_C15
[12:00:54.943] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:00:54.964] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:00:55.643] INFO: Expecting 41600 events.
[12:00:58.956] INFO: 41600 events read in total (2786ms).
[12:00:58.957] INFO: Test took 3993ms.
[12:00:58.996] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:58.996] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 376364
[12:00:58.996] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step10_C0 .. HR_xeff_CalDelScan_step10_C15
[12:00:58.996] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:00:59.016] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:00:59.708] INFO: Expecting 41600 events.
[12:01:02.004] INFO: 41600 events read in total (2769ms).
[12:01:02.005] INFO: Test took 3989ms.
[12:01:03.044] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:03.044] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 378481
[12:01:03.044] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step11_C0 .. HR_xeff_CalDelScan_step11_C15
[12:01:03.044] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:01:03.065] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:01:03.759] INFO: Expecting 41600 events.
[12:01:07.059] INFO: 41600 events read in total (2773ms).
[12:01:07.060] INFO: Test took 3995ms.
[12:01:07.098] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:07.099] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 373319
[12:01:07.099] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step12_C0 .. HR_xeff_CalDelScan_step12_C15
[12:01:07.099] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:01:07.119] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:01:07.815] INFO: Expecting 41600 events.
[12:01:11.124] INFO: 41600 events read in total (2783ms).
[12:01:11.125] INFO: Test took 4006ms.
[12:01:11.165] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:11.165] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 376945
[12:01:11.165] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step13_C0 .. HR_xeff_CalDelScan_step13_C15
[12:01:11.165] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:01:11.187] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:01:11.877] INFO: Expecting 41600 events.
[12:01:15.083] INFO: 41600 events read in total (2679ms).
[12:01:15.084] INFO: Test took 3897ms.
[12:01:15.123] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:15.123] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 379818
[12:01:15.123] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step14_C0 .. HR_xeff_CalDelScan_step14_C15
[12:01:15.124] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:01:15.143] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:01:15.834] INFO: Expecting 41600 events.
[12:01:19.131] INFO: 41600 events read in total (2770ms).
[12:01:19.132] INFO: Test took 3989ms.
[12:01:19.171] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:19.171] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 373617
[12:01:19.171] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step15_C0 .. HR_xeff_CalDelScan_step15_C15
[12:01:19.171] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:01:19.191] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:01:19.887] INFO: Expecting 41600 events.
[12:01:23.183] INFO: 41600 events read in total (2769ms).
[12:01:23.184] INFO: Test took 3993ms.
[12:01:23.222] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:23.222] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 374733
[12:01:23.222] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step16_C0 .. HR_xeff_CalDelScan_step16_C15
[12:01:23.222] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:01:23.242] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:01:23.935] INFO: Expecting 41600 events.
[12:01:27.191] INFO: 41600 events read in total (2729ms).
[12:01:27.192] INFO: Test took 3950ms.
[12:01:27.230] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:27.230] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 374374
[12:01:27.231] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step17_C0 .. HR_xeff_CalDelScan_step17_C15
[12:01:27.231] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:01:27.251] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:01:27.944] INFO: Expecting 41600 events.
[12:01:29.510] ERROR: <datapipe.cc/CheckEventValidity:L480> Channel 1 has NoTokenPass but 2 ROCs were found
[12:01:29.510] ERROR: <datapipe.cc/CheckEventID:L463> Channel 1 Event ID mismatch: local ID (246) != TBM ID (241)
[12:01:29.510] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 1 Number of ROCs (5) != Token Chain Length (8)
[12:01:29.510] ERROR: <datapipe.cc/CheckEventID:L463> Channel 1 Event ID mismatch: local ID (242) != TBM ID (246)
[12:01:29.510] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[12:01:29.510] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1f9 80b1 4839 a1 22a0 4839 a1 2284 10a 244c 4838 a1 22a7 c8 2441 4838 a1 2286 4839 a1 228f 4839 89 2245 a1 22c1 4838 a1 228a 861 2a4d 4839 a1 228f e002 c000
[12:01:29.510] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1f4 8040 4838 a1 228f 4838 48 262e 8b 2467 d0 2269 148 2662 4838 a1 22a4 4838 a1 228d 4838 a1 22a2 202 2a2f 203 2241 4838 a1 22ab 4838 a1 2286 304 204f 4838 a1 228d e002 c000
[12:01:29.510] ERROR: <datapipe.cc/Read:L166> ====== 2 ====== a1f5 80b1 4839 a1 228e 4839 b 2444 8d 2488 84 2285 89 2a82 8b 226f 90 2264 91 226f 92 2a6f 99 226e a0 2a6f a1 22c8
[12:01:29.510] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1f1 8006 ea4 2406 e23 2506 da4 2306 cc3 2706 aa3 2706 a43 2786 a03 2306 8a3 2786 843 2606 823 2586 803 2106 6c3 2786 623 2406 603 2306 583 2786 543 2506 503 2706 4a3 2586 443 2306 2c3 2506 1c3 2506 103 2386 c3 2786 a3 2786 83 2286 43 2506 23 2286 33 2506 93 2606 b3 2706 113 2406 153 2486 194 2106 1d4 2406 212 2606 293 2386 2b3 2306 4d3 2286 553 2306 653 2286 813 2106 853 2486 893 2506 8b3 2586 953 2106 d33 2586 d53 2506 0 2008 552 250a e84 248a a44 210a b3 258a c53 2511 a3 2590 4a3 2610 53 2490 2d3 2610 5d3 2410 833 2110 913 2090 a32 2612 983 2292 943 2214 893 2419 33 2220 a93 2330 a02 4839 a1 22a5 21b 2a81 4839 a1 228a 4839 a1 228e 4839 a1 22af 4c9 2866 4839 a1 228a 4839 a1 228d e002 c002
[12:01:29.510] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1f6 80c0 4838 4838 4838 4839 4838 4838 4838 4838 e002 c001
[12:01:29.510] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1f7 8000 4839 4839 4839 4838 4838 4838 4839 4839 e002 c001
[12:01:29.510] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1f8 8040 4838 4838 4839 4838 4839 4839 4838 4838 e002 c000
[12:01:31.379] CRITICAL: <hal.cc/condenseTriggers:L1899> Data size does not correspond to 10 triggers! Aborting data processing!
[12:01:31.380] INFO: 0 events read in total (2909ms).
[12:01:31.381] CRITICAL: <hal.cc/MultiRocAllPixelsCalibrate:L783> Incomplete DAQ data readout! Missing 4160 Events.
[12:01:31.408] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #1
[12:01:32.009] INFO: Expecting 41600 events.
[12:01:35.315] INFO: 41600 events read in total (2779ms).
[12:01:35.316] INFO: Test took 3908ms.
[12:01:35.355] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:35.355] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 377034
[12:01:35.355] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step18_C0 .. HR_xeff_CalDelScan_step18_C15
[12:01:35.355] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:01:35.375] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:01:36.067] INFO: Expecting 41600 events.
[12:01:39.275] INFO: 41600 events read in total (2681ms).
[12:01:39.276] INFO: Test took 3901ms.
[12:01:39.314] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:39.314] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 367861
[12:01:39.314] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step19_C0 .. HR_xeff_CalDelScan_step19_C15
[12:01:39.315] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:01:39.643] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 0: caldel = 163 eff = 0.999832
[12:01:39.653] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 1: caldel = 163 eff = 0.99988
[12:01:39.654] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 2: caldel = 160 eff = 0.99976
[12:01:39.654] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 3: caldel = 167 eff = 0.999639
[12:01:39.655] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 4: caldel = 169 eff = 0.999639
[12:01:39.655] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 5: caldel = 167 eff = 0.999111
[12:01:39.655] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 6: caldel = 156 eff = 0.999543
[12:01:39.655] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 7: caldel = 162 eff = 0.999688
[12:01:39.656] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 8: caldel = 152 eff = 0.968606
[12:01:39.656] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 9: caldel = 167 eff = 0.798365
[12:01:39.656] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 10: caldel = 168 eff = 0.968558
[12:01:39.656] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 11: caldel = 187 eff = 0.968534
[12:01:39.657] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 12: caldel = 134 eff = 0.968702
[12:01:39.657] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 13: caldel = 137 eff = 0.968534
[12:01:39.657] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 14: caldel = 148 eff = 0.966851
[12:01:39.657] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 15: caldel = 154 eff = 0.968894
[12:01:39.661] DEBUG: <PixTestHighRate.cc/~PixTestHighRate:L258> PixTestHighRate dtor
[12:01:39.680] INFO: enter test to run
[12:03:18.213] INFO: test: HighRate no parameter change
[12:03:18.213] INFO: running: highrate
[12:03:18.213] DEBUG: <PixTestHighRate.cc/setParameter:L68> setting fParTriggerFrequency -> 20
[12:03:18.213] DEBUG: <PixTestHighRate.cc/init:L211> PixTestHighRate::init()
[12:03:18.213] DEBUG: <PixTestHighRate.cc/PixTestHighRate:L31> PixTestHighRate ctor(PixSetup &a, string, TGTab *)
[12:03:18.214] DEBUG: <PixTestHighRate.cc/runCommand:L165> running command: xpixelalive
[12:03:18.214] INFO: ----------------------------------------------------------------------
[12:03:18.214] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:03:18.214] INFO: ----------------------------------------------------------------------
[12:03:18.214] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: clk: 4
[12:03:18.214] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: ctr: 4
[12:03:18.214] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: sda: 19
[12:03:18.215] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: tin: 9
[12:03:18.215] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: level: 15
[12:03:18.215] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: triggerdelay: 0
[12:03:18.215] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: clk: 4
[12:03:18.215] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: ctr: 4
[12:03:18.215] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: sda: 19
[12:03:18.215] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: tin: 9
[12:03:18.215] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: level: 15
[12:03:18.215] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: triggerdelay: 20
[12:03:18.221] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:03:18.829] INFO: Expecting 208000 events.
[12:03:31.216] INFO: 208000 events read in total (11861ms).
[12:03:31.220] INFO: Test took 12999ms.
[12:03:31.397] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:03:31.397] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 1654113
[12:03:31.397] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists highRate_C0 .. highRate_C15
[12:03:31.397] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:03:31.665] INFO: number of dead pixels (per ROC): 0 0 0 0 0 2 0 0 0 13 0 0 0 0 9 0
[12:03:31.665] INFO: number of red-efficiency pixels: 54 50 49 106 112 107 113 74 1207 2842 1236 1210 1236 1201 1175 1173
[12:03:31.665] INFO: number of X-ray hits detected: 58321 36604 59035 89852 98249 101321 97667 69283 66119 592998 82675 70402 74792 47742 18323 24194
[12:03:31.665] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:03:31.665] INFO: number of Vcal hits detected: 207943 207949 207949 207893 207888 207793 207883 207925 206158 154234 206120 206145 206116 206164 205763 206203
[12:03:31.665] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 100.0 100.0 99.9 100.0 99.1 75.2 99.1 99.1 99.1 99.1 99.1 99.1
[12:03:31.665] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 99.1 74.2 99.1 99.1 99.1 99.1 98.9 99.1
[12:03:31.665] INFO: X-ray hit rate [MHz/cm2]: 17.1 10.7 17.3 26.3 28.8 29.7 28.6 20.3 19.4 173.8 24.2 20.6 21.9 14.0 5.4 7.1
[12:03:31.665] INFO: PixTestHighRate::doXPixelAlive() done
[12:03:31.712] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: clk: 4
[12:03:31.712] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: ctr: 4
[12:03:31.712] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: sda: 19
[12:03:31.712] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: tin: 9
[12:03:31.712] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: level: 15
[12:03:31.712] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: triggerdelay: 0
[12:03:31.712] INFO: PixTest:: pg_setup set to default.
[12:03:31.712] DEBUG: <PixTestHighRate.cc/~PixTestHighRate:L258> PixTestHighRate dtor
[12:03:31.727] INFO: enter test to run
[12:03:47.181] INFO: test: HighRate no parameter change
[12:03:47.181] INFO: running: highrate
[12:03:47.181] DEBUG: <PixTestHighRate.cc/setParameter:L68> setting fParTriggerFrequency -> 20
[12:03:47.181] DEBUG: <PixTestHighRate.cc/init:L211> PixTestHighRate::init()
[12:03:47.181] DEBUG: <PixTestHighRate.cc/PixTestHighRate:L31> PixTestHighRate ctor(PixSetup &a, string, TGTab *)
[12:03:47.182] DEBUG: <PixTestHighRate.cc/runCommand:L165> running command: xpixelalive
[12:03:47.182] INFO: ----------------------------------------------------------------------
[12:03:47.182] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:03:47.182] INFO: ----------------------------------------------------------------------
[12:03:47.182] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: clk: 4
[12:03:47.182] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: ctr: 4
[12:03:47.182] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: sda: 19
[12:03:47.182] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: tin: 9
[12:03:47.182] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: level: 15
[12:03:47.182] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: triggerdelay: 0
[12:03:47.182] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: clk: 4
[12:03:47.182] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: ctr: 4
[12:03:47.182] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: sda: 19
[12:03:47.182] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: tin: 9
[12:03:47.182] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: level: 15
[12:03:47.182] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: triggerdelay: 20
[12:03:47.190] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:03:47.796] INFO: Expecting 208000 events.
[12:04:01.796] INFO: 208000 events read in total (13473ms).
[12:04:01.802] INFO: Test took 14612ms.
[12:04:02.133] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:04:02.133] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 2894293
[12:04:02.133] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists highRate_C0 .. highRate_C15
[12:04:02.134] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:04:02.447] INFO: number of dead pixels (per ROC): 0 0 0 0 0 2 0 0 0 11 0 0 0 0 8 0
[12:04:02.447] INFO: number of red-efficiency pixels: 168 121 199 350 437 387 458 248 1116 2842 1202 1105 1196 1098 981 1002
[12:04:02.447] INFO: number of X-ray hits detected: 128660 81228 130319 199467 216129 222545 215835 153825 146489 626657 184122 156078 165648 106464 40255 54033
[12:04:02.447] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:04:02.447] INFO: number of Vcal hits detected: 207818 207878 207790 207628 207527 207483 207513 207719 206336 163204 206201 206349 206231 206352 206074 206487
[12:04:02.447] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.2 79.5 99.1 99.2 99.2 99.2 99.3 99.3
[12:04:02.447] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.2 78.5 99.1 99.2 99.1 99.2 99.1 99.3
[12:04:02.447] INFO: X-ray hit rate [MHz/cm2]: 37.7 23.8 38.2 58.5 63.3 65.2 63.3 45.1 42.9 183.7 54.0 45.7 48.6 31.2 11.8 15.8
[12:04:02.447] INFO: PixTestHighRate::doXPixelAlive() done
[12:04:02.493] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: clk: 4
[12:04:02.493] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: ctr: 4
[12:04:02.493] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: sda: 19
[12:04:02.493] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: tin: 9
[12:04:02.493] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: level: 15
[12:04:02.493] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: triggerdelay: 0
[12:04:02.493] INFO: PixTest:: pg_setup set to default.
[12:04:02.493] DEBUG: <PixTestHighRate.cc/~PixTestHighRate:L258> PixTestHighRate dtor
[12:04:02.515] INFO: enter test to run
[12:05:07.028] INFO: test: HighRate no parameter change
[12:05:07.028] INFO: running: highrate
[12:05:07.028] DEBUG: <PixTestHighRate.cc/setParameter:L68> setting fParTriggerFrequency -> 20
[12:05:07.028] DEBUG: <PixTestHighRate.cc/init:L211> PixTestHighRate::init()
[12:05:07.029] DEBUG: <PixTestHighRate.cc/PixTestHighRate:L31> PixTestHighRate ctor(PixSetup &a, string, TGTab *)
[12:05:07.030] DEBUG: <PixTestHighRate.cc/runCommand:L165> running command: xpixelalive
[12:05:07.030] INFO: ----------------------------------------------------------------------
[12:05:07.030] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:05:07.030] INFO: ----------------------------------------------------------------------
[12:05:07.030] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: clk: 4
[12:05:07.030] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: ctr: 4
[12:05:07.030] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: sda: 19
[12:05:07.030] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: tin: 9
[12:05:07.030] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: level: 15
[12:05:07.030] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: triggerdelay: 0
[12:05:07.030] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: clk: 4
[12:05:07.030] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: ctr: 4
[12:05:07.030] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: sda: 19
[12:05:07.030] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: tin: 9
[12:05:07.030] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: level: 15
[12:05:07.030] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: triggerdelay: 20
[12:05:07.037] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[12:05:07.641] INFO: Expecting 208000 events.
[12:05:23.464] INFO: 208000 events read in total (15296ms).
[12:05:23.472] INFO: Test took 16435ms.
[12:05:23.939] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:05:23.939] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 4041688
[12:05:23.939] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists highRate_C0 .. highRate_C15
[12:05:23.940] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[12:05:24.294] INFO: number of dead pixels (per ROC): 0 0 0 0 0 2 0 0 0 10 0 0 0 0 8 0
[12:05:24.294] INFO: number of red-efficiency pixels: 352 246 419 714 1017 760 1063 506 1133 2913 1359 1143 1270 1108 801 838
[12:05:24.294] INFO: number of X-ray hits detected: 192438 122288 197199 299903 326439 336423 326100 232920 222271 648114 277839 237152 251036 161107 61910 82009
[12:05:24.294] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:05:24.294] INFO: number of Vcal hits detected: 207607 207740 207503 207157 206751 207000 206646 207382 206435 174141 206113 206453 206241 206465 206465 206857
[12:05:24.294] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.6 99.5 99.6 99.4 99.7 99.3 84.8 99.1 99.3 99.2 99.3 99.5 99.4
[12:05:24.295] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.6 99.4 99.5 99.3 99.7 99.2 83.7 99.1 99.3 99.2 99.3 99.3 99.5
[12:05:24.295] INFO: X-ray hit rate [MHz/cm2]: 56.4 35.8 57.8 87.9 95.7 98.6 95.6 68.3 65.1 190.0 81.4 69.5 73.6 47.2 18.1 24.0
[12:05:24.295] INFO: PixTestHighRate::doXPixelAlive() done
[12:05:24.341] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: clk: 4
[12:05:24.341] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: ctr: 4
[12:05:24.341] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: sda: 19
[12:05:24.341] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: tin: 9
[12:05:24.341] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: level: 15
[12:05:24.341] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: triggerdelay: 0
[12:05:24.341] INFO: PixTest:: pg_setup set to default.
[12:05:24.341] DEBUG: <PixTestHighRate.cc/~PixTestHighRate:L258> PixTestHighRate dtor
[12:05:24.352] INFO: enter test to run
[12:06:50.947] INFO: test: exit no parameter change
[12:06:50.948] DEBUG: <pXar.cc/main:L340> Final Analog Current: 384.3mA
[12:06:50.949] DEBUG: <pXar.cc/main:L341> Final Digital Current: 496mA
[12:06:50.949] DEBUG: <pXar.cc/main:L342> Final Module Temperature: 17.5 C
[12:06:50.949] DEBUG: <PixMonitor.cc/dumpSummaries:L39> PixMonitor::dumpSummaries
[12:06:51.682] QUIET: Connection to board 33 closed.
[12:06:51.924] INFO: pXar: this is the end, my friend
[12:06:51.952] DEBUG: <PixSetup.cc/~PixSetup:L68> PixSetup free fPxarMemory