[13:51:38.757] INFO: *** Welcome to pxar ***
[13:51:38.757] INFO: *** Today: 2017/03/31
[13:51:38.772] INFO: *** Version: v1.9.0-825-g6bc29
[13:51:38.772] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-P-6-06_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-P-6-06_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//dacParameters35_C15.dat
[13:51:38.773] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-P-6-06_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-P-6-06_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:51:38.773] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-P-6-06_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//defaultMaskFile.dat
[13:51:38.773] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-P-6-06_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-P-6-06_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C15.dat
[13:51:38.854] INFO: clk: 4
[13:51:38.854] INFO: ctr: 4
[13:51:38.854] INFO: sda: 19
[13:51:38.854] INFO: tin: 9
[13:51:38.854] INFO: level: 15
[13:51:38.854] INFO: triggerdelay: 0
[13:51:38.854] QUIET: Instanciating API for pxar v1.9.0+825~g6bc290c
[13:51:38.854] INFO: Log level: DEBUG
[13:51:38.869] QUIET: Connection to board DTB_WREKRL opened.
[13:51:38.872] 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:
------------------------------------------------------
[13:51:38.875] INFO: RPC call hashes of host and DTB match: 398089610
[13:51:40.415] INFO: DUT info:
[13:51:40.415] INFO: The DUT currently contains the following objects:
[13:51:40.415] INFO: 2 TBM Cores tbm08c (2 ON)
[13:51:40.415] INFO: TBM Core alpha (0): 7 registers set
[13:51:40.415] INFO: TBM Core beta (1): 7 registers set
[13:51:40.415] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[13:51:40.415] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:40.415] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:40.415] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:40.415] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:40.415] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:40.415] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:40.415] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:40.415] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:40.415] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:40.415] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:40.415] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:40.415] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:40.415] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:40.415] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:40.415] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:40.415] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:40.415] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->BB<-
[13:51:40.415] DEBUG: <PixTestParameters.cc/dump:L107> dumpall: checkbox(0)
[13:51:40.415] DEBUG: <PixTestParameters.cc/dump:L107> dumpproblematic: checkbox(0)
[13:51:40.415] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 5
[13:51:40.415] DEBUG: <PixTestParameters.cc/dump:L107> vcals: 250
[13:51:40.415] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->BB2<-
[13:51:40.415] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[13:51:40.415] DEBUG: <PixTestParameters.cc/dump:L107> vcals: 222
[13:51:40.415] DEBUG: <PixTestParameters.cc/dump:L107> plwidth: 35
[13:51:40.415] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[13:51:40.415] DEBUG: <PixTestParameters.cc/dump:L107> targetia: 24
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->BB3<-
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> dumpall: checkbox(0)
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> dumpproblematic: checkbox(0)
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 5
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> vcals: 250
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->BB4<-
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> savecaldelscan: checkbox(0)
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 100
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> cals: 1
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> caldello: 80
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> caldelhi: 200
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> caldelstep: 10
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> vthrcomplo: 70
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> vthrcomphi: 130
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> vthrcompstep: 5
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> noisypixels: 10
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> vcal: 255
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> cut: 0.5
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Cmd<-
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->DacDacScan<-
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> phmap: checkbox
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> dac1: caldel
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> dac1lo: 0
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> dac1hi: 255
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> dac2: vthrcomp
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> dac2lo: 0
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> dac2hi: 255
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->DacScan<-
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> phmap: checkbox(1)
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> allpixels: checkbox(0)
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> unmasked: checkbox(0)
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> dac: vcal
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> daclo: 0
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> dachi: 255
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->GainPedestal<-
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> showfits: checkbox(0)
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> extended: checkbox(0)
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> dumphists: checkbox(0)
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> vcalstep: 10
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> measure: button
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> fit: button
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> save: button
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->HighRate<-
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> trimhotpixels: button
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> trimhotpixelthr: 200
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> runsecondshotpixels: 10
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> savetrimbits: checkbox(1)
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> maskuntrimmable: checkbox(1)
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> maskhotpixels: button
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> savemaskfile: checkbox(0)
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> maskfilename: default
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> caldelscan: button
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> xpixelalive: button
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 50
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> vcal: 200
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> xnoisemaps: button
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> daclo: 0
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> dachi: 100
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> dacs/step: 20
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> rundaq: button
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> trgfrequency(khz): 20
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> runseconds: 2
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> triggerdelay: 20
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> delaytbm: checkbox
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> filltree: checkbox
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->IV<-
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> port: /dev/FIXME
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> voltagestart: 0
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> voltagestop: 600
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> voltagestep: 5
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> delay: 1
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> compliance(ua): 100
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->PhOptimization<-
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> safetymarginlow: 20
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> saturationvcal: 100
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> quantilesaturation: 0.98
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->PixelAlive<-
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> phmap: checkbox(0)
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> vcal: 200
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> alivetest: button
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> masktest: button
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> addressdecodingtest: button
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Pretest<-
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> programroc: button
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> checkidig: button
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> targetia: 24
[13:51:40.416] DEBUG: <PixTestParameters.cc/dump:L107> setvana: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> iterations: 100
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> settimings: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> findtiming: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> findworkingpixel: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> setvthrcompcaldel: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> vcal: 250
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> deltavthrcomp: 50
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> fraccaldel: 0.5
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 5
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> savedacs: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Readback<-
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> calibratevd: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> calibrateva: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> calibrateia: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> readbackvbg: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> getcalibratedvbg: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> usecalvd: checkbox(1)
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> usecalva: checkbox(0)
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> setvana: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Scurves<-
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> adjustvcal: checkbox(0)
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> dumpall: checkbox(0)
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> dumpproblematic: checkbox(0)
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> dumpoutputfile: checkbox(0)
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 50
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> dac: Vcal
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> daclo: 0
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> dachi: 200
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> dacs/step: -1
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> ntrig/step: -1
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> scurves: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Timing<-
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> targetclk: 4
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10000
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> clocksdascan: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> notokenpass: checkbox(0)
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> ignorereadback: checkbox(0)
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> phasescan: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> levelscan: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> tbmphasescan: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> rocdelayscan: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> timingtest: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> saveparameters: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Trim<-
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> trim: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 8
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> vcal: 35
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> trimbits: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Xray<-
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> maskhotpixels: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> savemaskfile: checkbox(0)
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> maskfilename: default
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> source: Ag
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> phrun: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> runseconds: 100
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> trgfrequency(khz): 100
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> ratescan: button
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> vthrcompmin: 10
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> vthrcompmax: 80
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> stepseconds: 5
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> delaytbm: checkbox
[13:51:40.417] DEBUG: <PixTestParameters.cc/dump:L107> filltree: checkbox
[13:51:40.419] DEBUG: <PixSetup.cc/init:L81> PixSetup init start; getCurrentRSS() = 29061120
[13:51:40.419] DEBUG: <PixSetup.cc/init:L87> fPixTestParameters = 0xadd220
[13:51:40.419] DEBUG: <PixSetup.cc/init:L88> fConfigParameters = 0xa03310
[13:51:40.419] DEBUG: <PixSetup.cc/init:L89> fPxarMemory = 0x7f0cddd94010
[13:51:40.419] DEBUG: <PixSetup.cc/init:L90> fPxarMemHi = 0x7f0ce3fff510
[13:51:40.419] DEBUG: <PixSetup.cc/init:L106> PixSetup init done; getCurrentRSS() = 29126656 fPxarMemory = 0x7f0cddd94010
[13:51:40.429] DEBUG: <pXar.cc/main:L223> Initial Analog Current: 381.9mA
[13:51:40.430] DEBUG: <pXar.cc/main:L224> Initial Digital Current: 464.7mA
[13:51:40.430] DEBUG: <pXar.cc/main:L225> Initial Module Temperature: 1.3 C
[13:51:40.430] DEBUG: <PixTestFactory.cc/PixTestFactory:L53> PixTestFactory::PixTestFactory()
[13:51:40.831] INFO: enter 'restricted' command line mode
[13:51:40.831] INFO: enter test to run
[13:51:46.720] INFO: test: PixelAlive no parameter change
[13:51:46.721] INFO: running: pixelalive
[13:51:46.721] DEBUG: <PixTestAlive.cc/init:L83> PixTestAlive::init()
[13:51:46.725] DEBUG: <PixTestAlive.cc/PixTestAlive:L21> PixTestAlive ctor(PixSetup &a, string, TGTab *)
[13:51:46.726] DEBUG: <PixTestAlive.cc/runCommand:L62> running command: alivetest
[13:51:46.730] INFO: ----------------------------------------------------------------------
[13:51:46.730] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[13:51:46.730] INFO: ----------------------------------------------------------------------
[13:51:46.733] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[13:51:47.050] INFO: Expecting 41600 events.
[13:51:51.526] INFO: 41600 events read in total (3757ms).
[13:51:51.694] INFO: Test took 4961ms.
[13:51:51.708] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:51:51.708] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 66277
[13:51:51.708] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists PixelAlive_C0 .. PixelAlive_C15
[13:51:51.971] INFO: PixTestAlive::aliveTest() done
[13:51:51.971] INFO: number of dead pixels (per ROC): 0 0 1 0 18 72 104 87 1 0 0 0 0 0 0 0
[13:51:51.971] DEBUG: <PixTestAlive.cc/aliveTest:L199> number of red-efficiency pixels: 0 1 1 1 21 114 296 188 1 0 0 0 0 0 0 0
[13:51:51.971] DEBUG: <PixTestAlive.cc/~PixTestAlive:L115> PixTestAlive dtor
[13:51:52.010] INFO: enter test to run
[13:52:16.520] INFO: test: timing no parameter change
[13:52:16.520] INFO: running: timing
[13:52:16.520] DEBUG: <PixTestTiming.cc/setParameter:L59> PixTestTiming::PixTest() targetclk = 4
[13:52:16.521] DEBUG: <PixTestTiming.cc/setParameter:L63> PixTestTiming::PixTest() ntrig = 10000
[13:52:16.521] DEBUG: <PixTestTiming.cc/setParameter:L47> fNoTokenPass: 0
[13:52:16.521] DEBUG: <PixTestTiming.cc/setParameter:L54> fIgnoreReadBack: 0
[13:52:16.521] DEBUG: <PixTestTiming.cc/init:L73> PixTestTiming::init()
[13:52:16.524] INFO: ######################################################################
[13:52:16.524] INFO: PixTestTiming::doTest()
[13:52:16.524] INFO: ######################################################################
[13:52:16.525] INFO: ----------------------------------------------------------------------
[13:52:16.525] INFO: PixTestTiming::TBMPhaseScan()
[13:52:16.525] INFO: ----------------------------------------------------------------------
[13:52:16.525] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 0 400MHz Phase: 0 TBM Phase: 00000000
[13:52:19.672] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 0 400MHz Phase: 1 TBM Phase: 00000100
[13:52:22.073] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 0 400MHz Phase: 2 TBM Phase: 00001000
[13:52:24.468] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 0 400MHz Phase: 3 TBM Phase: 00001100
[13:52:26.859] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 0 400MHz Phase: 4 TBM Phase: 00010000
[13:52:29.261] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 0 400MHz Phase: 5 TBM Phase: 00010100
[13:52:31.655] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 0 400MHz Phase: 6 TBM Phase: 00011000
[13:52:34.046] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 0 400MHz Phase: 7 TBM Phase: 00011100
[13:52:36.439] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 1 400MHz Phase: 0 TBM Phase: 00100000
[13:52:38.834] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 1 400MHz Phase: 1 TBM Phase: 00100100
[13:52:41.226] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 1 400MHz Phase: 2 TBM Phase: 00101000
[13:52:43.620] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 1 400MHz Phase: 3 TBM Phase: 00101100
[13:52:46.012] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 1 400MHz Phase: 4 TBM Phase: 00110000
[13:52:48.403] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 1 400MHz Phase: 5 TBM Phase: 00110100
[13:52:50.798] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 1 400MHz Phase: 6 TBM Phase: 00111000
[13:52:53.194] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 1 400MHz Phase: 7 TBM Phase: 00111100
[13:52:55.584] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 2 400MHz Phase: 0 TBM Phase: 01000000
[13:52:57.107] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 2 400MHz Phase: 1 TBM Phase: 01000100
[13:52:58.630] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 2 400MHz Phase: 2 TBM Phase: 01001000
[13:53:00.154] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 2 400MHz Phase: 3 TBM Phase: 01001100
[13:53:01.675] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 2 400MHz Phase: 4 TBM Phase: 01010000
[13:53:03.198] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 2 400MHz Phase: 5 TBM Phase: 01010100
[13:53:04.722] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 2 400MHz Phase: 6 TBM Phase: 01011000
[13:53:06.244] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 2 400MHz Phase: 7 TBM Phase: 01011100
[13:53:07.768] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 3 400MHz Phase: 0 TBM Phase: 01100000
[13:53:09.291] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 3 400MHz Phase: 1 TBM Phase: 01100100
[13:53:10.814] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 3 400MHz Phase: 2 TBM Phase: 01101000
[13:53:12.340] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 3 400MHz Phase: 3 TBM Phase: 01101100
[13:53:13.863] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 3 400MHz Phase: 4 TBM Phase: 01110000
[13:53:15.387] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 3 400MHz Phase: 5 TBM Phase: 01110100
[13:53:16.911] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 3 400MHz Phase: 6 TBM Phase: 01111000
[13:53:18.437] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 3 400MHz Phase: 7 TBM Phase: 01111100
[13:53:19.961] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 4 400MHz Phase: 0 TBM Phase: 10000000
[13:53:21.484] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 4 400MHz Phase: 1 TBM Phase: 10000100
[13:53:23.007] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 4 400MHz Phase: 2 TBM Phase: 10001000
[13:53:24.529] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 4 400MHz Phase: 3 TBM Phase: 10001100
[13:53:26.053] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 4 400MHz Phase: 4 TBM Phase: 10010000
[13:53:27.576] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 4 400MHz Phase: 5 TBM Phase: 10010100
[13:53:29.099] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 4 400MHz Phase: 6 TBM Phase: 10011000
[13:53:30.620] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 4 400MHz Phase: 7 TBM Phase: 10011100
[13:53:32.145] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 5 400MHz Phase: 0 TBM Phase: 10100000
[13:53:35.858] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 5 400MHz Phase: 1 TBM Phase: 10100100
[13:53:37.382] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 5 400MHz Phase: 2 TBM Phase: 10101000
[13:53:38.904] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 5 400MHz Phase: 3 TBM Phase: 10101100
[13:53:40.428] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 5 400MHz Phase: 4 TBM Phase: 10110000
[13:53:42.871] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 5 400MHz Phase: 5 TBM Phase: 10110100
[13:53:45.313] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 5 400MHz Phase: 6 TBM Phase: 10111000
[13:53:46.838] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 5 400MHz Phase: 7 TBM Phase: 10111100
[13:53:48.360] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 6 400MHz Phase: 0 TBM Phase: 11000000
[13:53:50.751] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 6 400MHz Phase: 1 TBM Phase: 11000100
[13:53:53.144] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 6 400MHz Phase: 2 TBM Phase: 11001000
[13:53:55.538] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 6 400MHz Phase: 3 TBM Phase: 11001100
[13:53:57.931] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 6 400MHz Phase: 4 TBM Phase: 11010000
[13:54:00.322] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 6 400MHz Phase: 5 TBM Phase: 11010100
[13:54:02.714] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 6 400MHz Phase: 6 TBM Phase: 11011000
[13:54:05.107] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 6 400MHz Phase: 7 TBM Phase: 11011100
[13:54:07.498] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 7 400MHz Phase: 0 TBM Phase: 11100000
[13:54:09.892] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 7 400MHz Phase: 1 TBM Phase: 11100100
[13:54:12.283] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 7 400MHz Phase: 2 TBM Phase: 11101000
[13:54:14.677] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 7 400MHz Phase: 3 TBM Phase: 11101100
[13:54:17.070] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 7 400MHz Phase: 4 TBM Phase: 11110000
[13:54:19.462] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 7 400MHz Phase: 5 TBM Phase: 11110100
[13:54:21.854] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 7 400MHz Phase: 6 TBM Phase: 11111000
[13:54:24.246] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 0 160MHz Phase: 7 400MHz Phase: 7 TBM Phase: 11111100
[13:54:26.636] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 0 400MHz Phase: 0 TBM Phase: 00000000
[13:54:29.596] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 0 400MHz Phase: 1 TBM Phase: 00000100
[13:54:31.992] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 0 400MHz Phase: 2 TBM Phase: 00001000
[13:54:34.387] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 0 400MHz Phase: 3 TBM Phase: 00001100
[13:54:36.783] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 0 400MHz Phase: 4 TBM Phase: 00010000
[13:54:39.178] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 0 400MHz Phase: 5 TBM Phase: 00010100
[13:54:41.575] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 0 400MHz Phase: 6 TBM Phase: 00011000
[13:54:43.969] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 0 400MHz Phase: 7 TBM Phase: 00011100
[13:54:46.365] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 1 400MHz Phase: 0 TBM Phase: 00100000
[13:54:48.752] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 1 400MHz Phase: 1 TBM Phase: 00100100
[13:54:51.148] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 1 400MHz Phase: 2 TBM Phase: 00101000
[13:54:53.545] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 1 400MHz Phase: 3 TBM Phase: 00101100
[13:54:55.939] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 1 400MHz Phase: 4 TBM Phase: 00110000
[13:54:58.335] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 1 400MHz Phase: 5 TBM Phase: 00110100
[13:55:00.731] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 1 400MHz Phase: 6 TBM Phase: 00111000
[13:55:03.127] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 1 400MHz Phase: 7 TBM Phase: 00111100
[13:55:05.521] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 2 400MHz Phase: 0 TBM Phase: 01000000
[13:55:07.046] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 2 400MHz Phase: 1 TBM Phase: 01000100
[13:55:09.439] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 2 400MHz Phase: 2 TBM Phase: 01001000
[13:55:11.834] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 2 400MHz Phase: 3 TBM Phase: 01001100
[13:55:14.228] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 2 400MHz Phase: 4 TBM Phase: 01010000
[13:55:16.623] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 2 400MHz Phase: 5 TBM Phase: 01010100
[13:55:19.019] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 2 400MHz Phase: 6 TBM Phase: 01011000
[13:55:21.417] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 2 400MHz Phase: 7 TBM Phase: 01011100
[13:55:23.811] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 3 400MHz Phase: 0 TBM Phase: 01100000
[13:55:25.334] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 3 400MHz Phase: 1 TBM Phase: 01100100
[13:55:26.857] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 3 400MHz Phase: 2 TBM Phase: 01101000
[13:55:28.379] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 3 400MHz Phase: 3 TBM Phase: 01101100
[13:55:30.092] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 3 400MHz Phase: 4 TBM Phase: 01110000
[13:55:31.614] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 3 400MHz Phase: 5 TBM Phase: 01110100
[13:55:33.134] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 3 400MHz Phase: 6 TBM Phase: 01111000
[13:55:34.658] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 3 400MHz Phase: 7 TBM Phase: 01111100
[13:55:36.182] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 4 400MHz Phase: 0 TBM Phase: 10000000
[13:55:37.705] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 4 400MHz Phase: 1 TBM Phase: 10000100
[13:55:39.228] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 4 400MHz Phase: 2 TBM Phase: 10001000
[13:55:40.751] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 4 400MHz Phase: 3 TBM Phase: 10001100
[13:55:42.274] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 4 400MHz Phase: 4 TBM Phase: 10010000
[13:55:43.796] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 4 400MHz Phase: 5 TBM Phase: 10010100
[13:55:45.320] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 4 400MHz Phase: 6 TBM Phase: 10011000
[13:55:46.843] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 4 400MHz Phase: 7 TBM Phase: 10011100
[13:55:48.367] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 5 400MHz Phase: 0 TBM Phase: 10100000
[13:55:50.950] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 5 400MHz Phase: 1 TBM Phase: 10100100
[13:55:52.474] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 5 400MHz Phase: 2 TBM Phase: 10101000
[13:55:55.011] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 5 400MHz Phase: 3 TBM Phase: 10101100
[13:55:56.534] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 5 400MHz Phase: 4 TBM Phase: 10110000
[13:55:58.057] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 5 400MHz Phase: 5 TBM Phase: 10110100
[13:55:59.579] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 5 400MHz Phase: 6 TBM Phase: 10111000
[13:56:01.102] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 5 400MHz Phase: 7 TBM Phase: 10111100
[13:56:02.626] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 6 400MHz Phase: 0 TBM Phase: 11000000
[13:56:05.022] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 6 400MHz Phase: 1 TBM Phase: 11000100
[13:56:07.418] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 6 400MHz Phase: 2 TBM Phase: 11001000
[13:56:09.814] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 6 400MHz Phase: 3 TBM Phase: 11001100
[13:56:12.209] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 6 400MHz Phase: 4 TBM Phase: 11010000
[13:56:14.604] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 6 400MHz Phase: 5 TBM Phase: 11010100
[13:56:16.991] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 6 400MHz Phase: 6 TBM Phase: 11011000
[13:56:19.387] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 6 400MHz Phase: 7 TBM Phase: 11011100
[13:56:21.783] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 7 400MHz Phase: 0 TBM Phase: 11100000
[13:56:24.178] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 7 400MHz Phase: 1 TBM Phase: 11100100
[13:56:26.573] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 7 400MHz Phase: 2 TBM Phase: 11101000
[13:56:28.969] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 7 400MHz Phase: 3 TBM Phase: 11101100
[13:56:31.363] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 7 400MHz Phase: 4 TBM Phase: 11110000
[13:56:33.760] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 7 400MHz Phase: 5 TBM Phase: 11110100
[13:56:36.155] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 7 400MHz Phase: 6 TBM Phase: 11111000
[13:56:38.550] DEBUG: <PixTestTiming.cc/TBMPhaseScan:L435> TBM Core: 1 160MHz Phase: 7 400MHz Phase: 7 TBM Phase: 11111100
[13:56:41.328] INFO: TBM Phase Settings: 244
[13:56:41.328] INFO: 400MHz Phase: 5
[13:56:41.328] INFO: 160MHz Phase: 7
[13:56:41.328] INFO: Functional Phase Area: 4
[13:56:41.331] INFO: Test took 264807 ms.
[13:56:41.331] INFO: PixTestTiming::TBMPhaseScan() done.
[13:56:41.332] INFO: ----------------------------------------------------------------------
[13:56:41.332] INFO: PixTestTiming::ROCDelayScan()
[13:56:41.332] INFO: ----------------------------------------------------------------------
[13:56:41.332] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 0 ROC Port0: 0 ROCDelay Setting: 11000000
[13:56:45.863] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 0 ROC Port0: 1 ROCDelay Setting: 11000001
[13:56:47.387] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 0 ROC Port0: 2 ROCDelay Setting: 11000010
[13:56:48.912] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 0 ROC Port0: 3 ROCDelay Setting: 11000011
[13:56:50.436] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 0 ROC Port0: 4 ROCDelay Setting: 11000100
[13:56:51.960] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 0 ROC Port0: 5 ROCDelay Setting: 11000101
[13:56:53.484] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 0 ROC Port0: 6 ROCDelay Setting: 11000110
[13:56:55.006] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 0 ROC Port0: 7 ROCDelay Setting: 11000111
[13:57:01.232] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 1 ROC Port0: 0 ROCDelay Setting: 11001000
[13:57:06.142] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 1 ROC Port0: 1 ROCDelay Setting: 11001001
[13:57:07.665] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 1 ROC Port0: 2 ROCDelay Setting: 11001010
[13:57:09.188] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 1 ROC Port0: 3 ROCDelay Setting: 11001011
[13:57:10.711] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 1 ROC Port0: 4 ROCDelay Setting: 11001100
[13:57:12.234] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 1 ROC Port0: 5 ROCDelay Setting: 11001101
[13:57:13.756] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 1 ROC Port0: 6 ROCDelay Setting: 11001110
[13:57:15.281] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 1 ROC Port0: 7 ROCDelay Setting: 11001111
[13:57:21.319] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 2 ROC Port0: 0 ROCDelay Setting: 11010000
[13:57:26.229] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 2 ROC Port0: 1 ROCDelay Setting: 11010001
[13:57:28.653] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 2 ROC Port0: 2 ROCDelay Setting: 11010010
[13:57:31.076] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 2 ROC Port0: 3 ROCDelay Setting: 11010011
[13:57:33.499] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 2 ROC Port0: 4 ROCDelay Setting: 11010100
[13:57:35.923] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 2 ROC Port0: 5 ROCDelay Setting: 11010101
[13:57:38.347] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 2 ROC Port0: 6 ROCDelay Setting: 11010110
[13:57:40.771] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 2 ROC Port0: 7 ROCDelay Setting: 11010111
[13:57:46.808] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 3 ROC Port0: 0 ROCDelay Setting: 11011000
[13:57:51.719] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 3 ROC Port0: 1 ROCDelay Setting: 11011001
[13:57:54.143] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 3 ROC Port0: 2 ROCDelay Setting: 11011010
[13:57:56.566] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 3 ROC Port0: 3 ROCDelay Setting: 11011011
[13:57:58.991] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 3 ROC Port0: 4 ROCDelay Setting: 11011100
[13:58:01.414] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 3 ROC Port0: 5 ROCDelay Setting: 11011101
[13:58:03.839] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 3 ROC Port0: 6 ROCDelay Setting: 11011110
[13:58:06.264] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 3 ROC Port0: 7 ROCDelay Setting: 11011111
[13:58:12.303] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 4 ROC Port0: 0 ROCDelay Setting: 11100000
[13:58:17.211] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 4 ROC Port0: 1 ROCDelay Setting: 11100001
[13:58:19.634] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 4 ROC Port0: 2 ROCDelay Setting: 11100010
[13:58:22.060] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 4 ROC Port0: 3 ROCDelay Setting: 11100011
[13:58:24.482] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 4 ROC Port0: 4 ROCDelay Setting: 11100100
[13:58:26.907] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 4 ROC Port0: 5 ROCDelay Setting: 11100101
[13:58:29.329] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 4 ROC Port0: 6 ROCDelay Setting: 11100110
[13:58:31.754] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 4 ROC Port0: 7 ROCDelay Setting: 11100111
[13:58:37.979] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 5 ROC Port0: 0 ROCDelay Setting: 11101000
[13:58:42.888] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 5 ROC Port0: 1 ROCDelay Setting: 11101001
[13:58:45.312] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 5 ROC Port0: 2 ROCDelay Setting: 11101010
[13:58:47.737] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 5 ROC Port0: 3 ROCDelay Setting: 11101011
[13:58:50.160] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 5 ROC Port0: 4 ROCDelay Setting: 11101100
[13:58:52.587] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 5 ROC Port0: 5 ROCDelay Setting: 11101101
[13:58:55.012] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 5 ROC Port0: 6 ROCDelay Setting: 11101110
[13:58:57.435] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 5 ROC Port0: 7 ROCDelay Setting: 11101111
[13:59:03.662] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 6 ROC Port0: 0 ROCDelay Setting: 11110000
[13:59:08.571] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 6 ROC Port0: 1 ROCDelay Setting: 11110001
[13:59:10.997] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 6 ROC Port0: 2 ROCDelay Setting: 11110010
[13:59:13.421] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 6 ROC Port0: 3 ROCDelay Setting: 11110011
[13:59:15.845] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 6 ROC Port0: 4 ROCDelay Setting: 11110100
[13:59:18.270] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 6 ROC Port0: 5 ROCDelay Setting: 11110101
[13:59:20.694] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 6 ROC Port0: 6 ROCDelay Setting: 11110110
[13:59:23.119] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 6 ROC Port0: 7 ROCDelay Setting: 11110111
[13:59:29.156] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 7 ROC Port0: 0 ROCDelay Setting: 11111000
[13:59:34.065] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 7 ROC Port0: 1 ROCDelay Setting: 11111001
[13:59:35.589] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 7 ROC Port0: 2 ROCDelay Setting: 11111010
[13:59:37.112] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 7 ROC Port0: 3 ROCDelay Setting: 11111011
[13:59:38.635] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 7 ROC Port0: 4 ROCDelay Setting: 11111100
[13:59:40.159] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 7 ROC Port0: 5 ROCDelay Setting: 11111101
[13:59:41.681] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 7 ROC Port0: 6 ROCDelay Setting: 11111110
[13:59:43.206] DEBUG: <PixTestTiming.cc/ROCDelayScan:L546> Token Header/Trailer Delay: 11 ROC Port1: 7 ROC Port0: 7 ROCDelay Setting: 11111111
[13:59:49.626] INFO: ROC Delay Settings: 227
[13:59:49.626] INFO: ROC Header-Trailer/Token Delay: 11
[13:59:49.626] INFO: ROC Port 0 Delay: 3
[13:59:49.626] INFO: ROC Port 1 Delay: 4
[13:59:49.626] INFO: Functional ROC Area: 5
[13:59:49.629] INFO: Test took 188298 ms.
[13:59:49.629] INFO: PixTestTiming::ROCDelayScan() done.
[13:59:49.629] INFO: ----------------------------------------------------------------------
[13:59:49.629] INFO: PixTestTiming::TimingTest()
[13:59:49.629] INFO: ----------------------------------------------------------------------
[13:59:50.772] DEBUG: <PixTest.cc/getEvents:L2459> Event: ====== 0 ====== a001 80b1 4388 4388 4388 4388 4388 4388 438a 4388 e062 c000 a101 8000 4388 4388 4388 4388 4388 4388 4388 4388 e062 c000
[13:59:50.772] DEBUG: <PixTest.cc/getEvents:L2459> Event: ====== 0 ====== a002 80c0 4388 4388 4388 4388 4388 438a 4388 4388 e022 c000 a102 8040 4388 4388 4388 4388 4388 4388 4388 4388 e022 c000
[13:59:50.772] DEBUG: <PixTest.cc/getEvents:L2459> Event: ====== 0 ====== a003 8000 4388 4388 4388 4388 4388 4388 4389 4388 e022 c000 a103 80b1 4388 4388 4388 4388 4388 4388 4388 4388 e022 c000
[13:59:50.772] DEBUG: <PixTest.cc/getEvents:L2463> Collecting 1000000/10000000 Triggers
[14:00:05.745] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:00:05.745] DEBUG: <PixTest.cc/getEvents:L2463> Collecting 2000000/10000000 Triggers
[14:00:20.720] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:00:20.720] DEBUG: <PixTest.cc/getEvents:L2463> Collecting 3000000/10000000 Triggers
[14:00:26.396] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 0 Number of ROCs (6) != Token Chain Length (8)
[14:00:26.396] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 1 Number of ROCs (2) != Token Chain Length (8)
[14:00:35.643] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:00:35.643] DEBUG: <PixTest.cc/getEvents:L2463> Collecting 4000000/10000000 Triggers
[14:00:50.597] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:00:50.597] DEBUG: <PixTest.cc/getEvents:L2463> Collecting 5000000/10000000 Triggers
[14:01:05.571] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:01:05.571] DEBUG: <PixTest.cc/getEvents:L2463> Collecting 6000000/10000000 Triggers
[14:01:20.730] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:01:20.730] DEBUG: <PixTest.cc/getEvents:L2463> Collecting 7000000/10000000 Triggers
[14:01:35.861] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:01:35.861] DEBUG: <PixTest.cc/getEvents:L2463> Collecting 8000000/10000000 Triggers
[14:01:51.007] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:01:51.007] DEBUG: <PixTest.cc/getEvents:L2463> Collecting 9000000/10000000 Triggers
[14:01:56.682] ERROR: <datapipe.cc/CheckEventValidity:L480> Channel 0 has NoTokenPass but 8 ROCs were found
[14:01:56.683] ERROR: <datapipe.cc/CheckEventValidity:L480> Channel 1 has NoTokenPass but 8 ROCs were found
[14:02:06.053] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:02:06.053] DEBUG: <PixTest.cc/getEvents:L2470> Collecting 10000000/10000000 Triggers
[14:02:21.136] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:02:21.518] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:02:21.535] INFO: Decoding statistics:
[14:02:21.536] INFO: General information:
[14:02:21.536] INFO: 16bit words read: 240000112
[14:02:21.536] INFO: valid events total: 19999996
[14:02:21.536] INFO: empty events: 19999996
[14:02:21.536] INFO: valid events with pixels: 0
[14:02:21.536] INFO: valid pixel hits: 0
[14:02:21.536] INFO: Event errors: 6
[14:02:21.536] INFO: start marker: 0
[14:02:21.536] INFO: stop marker: 2
[14:02:21.536] INFO: overflow: 0
[14:02:21.536] INFO: invalid 5bit words: 4
[14:02:21.536] INFO: invalid XOR eye diagram: 0
[14:02:21.536] INFO: TBM errors: 2
[14:02:21.536] INFO: flawed TBM headers: 0
[14:02:21.536] INFO: flawed TBM trailers: 2
[14:02:21.536] INFO: event ID mismatches: 0
[14:02:21.536] INFO: ROC errors: 4
[14:02:21.536] INFO: missing ROC header(s): 4
[14:02:21.536] INFO: misplaced readback start: 0
[14:02:21.536] INFO: Pixel decoding errors: 61
[14:02:21.536] INFO: pixel data incomplete: 2
[14:02:21.536] INFO: pixel address: 2
[14:02:21.536] INFO: pulse height fill bit: 57
[14:02:21.536] INFO: buffer corruption: 0
[14:02:21.536] INFO: ----------------------------------------------------------------------
[14:02:21.536] INFO: The fraction of properly decoded events is 100.00%: 9999998/10000000
[14:02:21.536] INFO: ----------------------------------------------------------------------
[14:02:21.536] INFO: ----------------------------------------------------------------------
[14:02:21.536] INFO: Read back bit status: 1
[14:02:21.536] INFO: ----------------------------------------------------------------------
[14:02:21.536] ERROR: <PixTest.cc/banner:L1418> ----------------------------------------------------------------------
[14:02:21.536] ERROR: <PixTest.cc/banner:L1419> Timings are not good :(
[14:02:21.536] ERROR: <PixTest.cc/banner:L1420> ----------------------------------------------------------------------
[14:02:21.536] INFO: Test took 151907 ms.
[14:02:21.536] INFO: PixTestTiming::TimingTest() done.
[14:02:21.536] INFO: Problem with TimingTest! Timings not saved!
[14:02:21.536] INFO: PixTestTiming::doTest took 605015 ms.
[14:02:21.536] INFO: PixTestTiming::doTest() done
[14:02:21.536] DEBUG: <PixTestTiming.cc/~PixTestTiming:L96> PixTestTiming dtor
[14:02:21.536] INFO: Write out TBMPhaseScan_0_V0
[14:02:21.536] INFO: Write out TBMPhaseScan_1_V0
[14:02:21.536] INFO: Write out CombinedTBMPhaseScan_V0
[14:02:21.537] INFO: Write out ROCDelayScan3_V0
[14:02:21.538] INFO: enter test to run
[14:03:51.835] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[14:03:51.835] DEBUG: <PixTestParameters.cc/setTestParameter:L119> PixTestParameters: ->Xray<-
[14:03:51.835] DEBUG: <PixTestParameters.cc/setTestParameter:L124> setting source to new value DCLowRate
[14:03:51.835] INFO: running: xray
[14:03:51.836] DEBUG: <PixTestXray.cc/init:L135> PixTestXray::init()
[14:03:51.836] DEBUG: <PixTestXray.cc/PixTestXray:L28> PixTestXray ctor(PixSetup &a, string, TGTab *)
[14:03:51.836] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-P-6-06_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-P-6-06_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[14:03:51.988] DEBUG: <PixTestXray.cc/runCommand:L109> running command: phrun
[14:03:51.988] INFO: ----------------------------------------------------------------------
[14:03:51.988] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:03:51.988] INFO: ----------------------------------------------------------------------
[14:03:52.952] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:04:04.021] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[14:04:04.025] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:04:30.217] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 1090538 events.
[14:04:34.335] DEBUG: <PixTestXray.cc/processData:L823> # events read: 1090538, pixels seen in all events: 7165288
[14:04:34.422] INFO: Resuming triggers.
[14:04:45.492] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[14:04:45.495] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:05:11.906] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 1090602 events.
[14:05:16.053] DEBUG: <PixTestXray.cc/processData:L823> # events read: 1090602, pixels seen in all events: 7164129
[14:05:16.184] INFO: Resuming triggers.
[14:05:27.254] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[14:05:27.272] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:05:53.520] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 1090561 events.
[14:05:57.604] DEBUG: <PixTestXray.cc/processData:L823> # events read: 1090561, pixels seen in all events: 7164790
[14:05:57.736] INFO: Resuming triggers.
[14:06:08.803] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[14:06:08.823] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:06:34.847] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 1090320 events.
[14:06:38.707] DEBUG: <PixTestXray.cc/processData:L823> # events read: 1090320, pixels seen in all events: 7167879
[14:06:38.787] INFO: Resuming triggers.
[14:06:49.854] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[14:06:49.913] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:07:15.602] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 1090282 events.
[14:07:19.435] DEBUG: <PixTestXray.cc/processData:L823> # events read: 1090282, pixels seen in all events: 7167600
[14:07:19.520] INFO: Resuming triggers.
[14:07:30.581] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[14:07:30.585] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:07:56.272] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 1089705 events.
[14:08:00.045] DEBUG: <PixTestXray.cc/processData:L823> # events read: 1089705, pixels seen in all events: 7174493
[14:08:00.125] INFO: Resuming triggers.
[14:08:11.193] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[14:08:11.250] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:08:36.890] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 1090380 events.
[14:08:40.670] DEBUG: <PixTestXray.cc/processData:L823> # events read: 1090380, pixels seen in all events: 7166940
[14:08:40.798] INFO: Resuming triggers.
[14:08:51.868] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[14:08:51.872] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:09:17.500] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 1090614 events.
[14:09:21.255] DEBUG: <PixTestXray.cc/processData:L823> # events read: 1090614, pixels seen in all events: 7163814
[14:09:21.384] INFO: Resuming triggers.
[14:09:32.449] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[14:09:32.453] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:09:58.193] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 1090122 events.
[14:10:02.080] DEBUG: <PixTestXray.cc/processData:L823> # events read: 1090122, pixels seen in all events: 7169823
[14:10:02.163] INFO: Resuming triggers.
[14:10:02.907] INFO: data taking finished, elapsed time: 100 seconds.
[14:10:03.102] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:10:04.005] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 73256 events.
[14:10:05.263] DEBUG: <PixTestXray.cc/processData:L823> # events read: 73256, pixels seen in all events: 481942
[14:10:05.272] INFO: PixTest:: pg_setup set to default.
[14:10:05.275] INFO: PixTestXray::doPhRun() done
[14:10:05.275] DEBUG: <PixTestXray.cc/~PixTestXray:L218> PixTestXray dtor
[14:10:05.416] INFO: enter test to run
[14:10:44.672] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[14:10:44.672] DEBUG: <PixTestParameters.cc/setTestParameter:L119> PixTestParameters: ->Xray<-
[14:10:44.672] DEBUG: <PixTestParameters.cc/setTestParameter:L124> setting source to new value DCHighRate
[14:10:44.672] INFO: running: xray
[14:10:44.673] DEBUG: <PixTestXray.cc/init:L135> PixTestXray::init()
[14:10:44.673] DEBUG: <PixTestXray.cc/PixTestXray:L28> PixTestXray ctor(PixSetup &a, string, TGTab *)
[14:10:44.674] DEBUG: <PixTestXray.cc/runCommand:L109> running command: phrun
[14:10:44.674] INFO: ----------------------------------------------------------------------
[14:10:44.674] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:10:44.674] INFO: ----------------------------------------------------------------------
[14:10:45.646] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:10:52.305] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[14:10:52.308] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:11:16.065] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 656048 events.
[14:11:22.477] DEBUG: <PixTestXray.cc/processData:L823> # events read: 656048, pixels seen in all events: 12379640
[14:11:22.544] INFO: Resuming triggers.
[14:11:29.198] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[14:11:29.201] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:11:52.859] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 655540 events.
[14:11:59.386] DEBUG: <PixTestXray.cc/processData:L823> # events read: 655540, pixels seen in all events: 12385169
[14:11:59.451] INFO: Resuming triggers.
[14:12:06.104] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[14:12:06.107] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:12:29.766] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 655398 events.
[14:12:36.296] DEBUG: <PixTestXray.cc/processData:L823> # events read: 655398, pixels seen in all events: 12387465
[14:12:36.361] INFO: Resuming triggers.
[14:12:43.017] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[14:12:43.020] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:13:06.607] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 655637 events.
[14:13:13.099] DEBUG: <PixTestXray.cc/processData:L823> # events read: 655637, pixels seen in all events: 12385410
[14:13:13.164] INFO: Resuming triggers.
[14:13:19.814] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[14:13:19.817] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:13:43.530] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 655117 events.
[14:13:50.048] DEBUG: <PixTestXray.cc/processData:L823> # events read: 655117, pixels seen in all events: 12390726
[14:13:50.113] INFO: Resuming triggers.
[14:13:56.764] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[14:13:56.767] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:14:20.466] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 655184 events.
[14:14:26.944] DEBUG: <PixTestXray.cc/processData:L823> # events read: 655184, pixels seen in all events: 12390545
[14:14:27.009] INFO: Resuming triggers.
[14:14:33.657] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[14:14:33.660] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:14:58.050] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 654914 events.
[14:15:05.230] DEBUG: <PixTestXray.cc/processData:L823> # events read: 654914, pixels seen in all events: 12392651
[14:15:05.299] INFO: Resuming triggers.
[14:15:11.938] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[14:15:11.941] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:15:35.831] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 654050 events.
[14:15:43.131] DEBUG: <PixTestXray.cc/processData:L823> # events read: 654050, pixels seen in all events: 12403625
[14:15:43.198] INFO: Resuming triggers.
[14:15:49.844] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[14:15:49.847] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:16:13.511] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 654731 events.
[14:16:20.613] DEBUG: <PixTestXray.cc/processData:L823> # events read: 654731, pixels seen in all events: 12395467
[14:16:20.679] INFO: Resuming triggers.
[14:16:27.319] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[14:16:27.322] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:16:51.123] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 654118 events.
[14:16:58.197] DEBUG: <PixTestXray.cc/processData:L823> # events read: 654118, pixels seen in all events: 12403191
[14:16:58.263] INFO: Resuming triggers.
[14:17:04.902] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[14:17:04.905] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:17:28.847] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 653949 events.
[14:17:35.853] DEBUG: <PixTestXray.cc/processData:L823> # events read: 653949, pixels seen in all events: 12404919
[14:17:35.918] INFO: Resuming triggers.
[14:17:42.553] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[14:17:42.556] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:18:07.020] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 653618 events.
[14:18:13.959] DEBUG: <PixTestXray.cc/processData:L823> # events read: 653618, pixels seen in all events: 12408533
[14:18:14.025] INFO: Resuming triggers.
[14:18:20.664] INFO: run duration 86 seconds, buffer almost full (81%), pausing triggers.
[14:18:20.667] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:18:44.996] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 654041 events.
[14:18:52.022] DEBUG: <PixTestXray.cc/processData:L823> # events read: 654041, pixels seen in all events: 12403854
[14:18:52.091] INFO: Resuming triggers.
[14:18:58.727] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[14:18:58.730] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:19:23.509] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 653755 events.
[14:19:30.012] DEBUG: <PixTestXray.cc/processData:L823> # events read: 653755, pixels seen in all events: 12407308
[14:19:30.078] INFO: Resuming triggers.
[14:19:36.714] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[14:19:36.717] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:20:00.345] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 653703 events.
[14:20:06.856] DEBUG: <PixTestXray.cc/processData:L823> # events read: 653703, pixels seen in all events: 12407200
[14:20:06.920] INFO: Resuming triggers.
[14:20:07.587] INFO: data taking finished, elapsed time: 100 seconds.
[14:20:07.783] DEBUG: <PixTestXray.cc/processData:L754> Getting Event Buffer
[14:20:10.343] DEBUG: <PixTestXray.cc/processData:L772> Processing Data: 65642 events.
[14:20:11.007] DEBUG: <PixTestXray.cc/processData:L823> # events read: 65642, pixels seen in all events: 1247133
[14:20:11.013] INFO: PixTest:: pg_setup set to default.
[14:20:11.016] INFO: PixTestXray::doPhRun() done
[14:20:11.016] DEBUG: <PixTestXray.cc/~PixTestXray:L218> PixTestXray dtor
[14:20:11.165] INFO: enter test to run
[14:21:12.292] INFO: test: HighRate no parameter change
[14:21:12.292] INFO: running: highrate
[14:21:12.292] DEBUG: <PixTestHighRate.cc/setParameter:L68> setting fParTriggerFrequency -> 20
[14:21:12.292] DEBUG: <PixTestHighRate.cc/init:L211> PixTestHighRate::init()
[14:21:12.292] DEBUG: <PixTestHighRate.cc/PixTestHighRate:L31> PixTestHighRate ctor(PixSetup &a, string, TGTab *)
[14:21:12.339] DEBUG: <PixTestHighRate.cc/runCommand:L165> running command: caldelscan
[14:21:12.339] INFO: ----------------------------------------------------------------------
[14:21:12.339] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[14:21:12.339] INFO: ----------------------------------------------------------------------
[14:21:12.480] INFO: Expecting 768 events.
[14:21:13.614] INFO: 768 events read in total (418ms).
[14:21:13.614] INFO: Test took 1268ms.
[14:21:13.621] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:21:14.417] INFO: Expecting 41600 events.
[14:21:17.540] INFO: 41600 events read in total (2596ms).
[14:21:17.541] INFO: Test took 3920ms.
[14:21:17.580] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:17.580] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 364215
[14:21:17.580] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step0_C0 .. HR_xeff_CalDelScan_step0_C15
[14:21:17.580] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:21:17.598] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:21:18.298] INFO: Expecting 41600 events.
[14:21:19.894] ERROR: <datapipe.cc/CheckEventValidity:L480> Channel 0 has NoTokenPass but 7 ROCs were found
[14:21:19.894] WARNING: Channel 1 ROC 7: Readback start marker after 5 readouts!
[14:21:19.894] ERROR: <datapipe.cc/CheckEventValidity:L480> Channel 1 has NoTokenPass but 8 ROCs were found
[14:21:19.894] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[14:21:19.894] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a09f 80c0 43c8 db 20a8 43c8 43c8 43c8 db 20ac 43c8 db 20ac 2d3 2a4f 43cb db 20aa 43c8 db 210f 43c8 db 208f e002 c000
[14:21:19.894] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a099 8040 438b db 24ab 438b db 248f 438b db 248f 438b db 24ab 438a db 24a7 4389 4389 1b 290a 9 2b09 14 2702 db 254d c9 230d 15c 2509 14d 250f 151 2706 154 2700 15a 2b07 293 2926 31c 20ec 621 2907 438b db 24a9 e002 c000
[14:21:19.895] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a09a 80b1 4388 db 24ac 4388 db 248b 4388 db 24a2 4388 db 24c2 2d8 2844 619 244c 4388 db 24ad 610 2a41 4389 4389 db 252a 15b 210d 4388 e002 c000
[14:21:19.895] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a09b 80c0 4388 db 24af 4388 db 2489 4388 db 24a7 4388 db 24af 4389 db 24a7 4389 249 2641 80c 2441 4388 db 2523 d9 2b05 4389 80 262d db 24af 69a 2a40 e002 c000
[14:21:19.895] ERROR: <datapipe.cc/Read:L166> ====== 2 ====== a09c 8000 4388 db 20c0 4388 4389 db 20a5 4389 db 20a5 210 2040 4388 db 20a0 da 2a4f 4388 db 20a7 518 3242 43c8 da 2fd5 65f 27c1 fff 22ae 20 20ff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff
[14:21:19.895] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a09d 8040 43c8 db 20a4 43c9 43c8 43c9 db 20a9 43c8 db 20a7 43c9 43c9 db 2127 43c9 43 26a6 db 20a5 e002 c000
[14:21:19.895] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a09e 80b1 43c8 43c8 db 208f 43c8 43c8 db 20ac 119 244c 43c8 db 20ad 105 284a 44c 2449 43c8 db 20ad 43ca db 212c 43c8 db 20a2 e002 c000
[14:21:19.895] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[14:21:19.895] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a19f 8040 43c8 db 20a2 43c8 db 20ae 550 222f 43c8 db 20a7 43c8 db 20a9 43c8 db 20a5 43c8 db 208d 43c8 db 208f 43c8 db 20a1 e002 c000
[14:21:19.895] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a199 80c0 4388 db 24a3 4388 db 24a8 4388 db 284d db 24a6 70d 2245 4388 db 24a7 11b 264f 4389 db 24a5 4389 db 248f 4389 db 248f 4389 e002 c000
[14:21:19.895] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a19a 8000 4388 db 24a2 4388 db 24ac 295 204f 4389 db 248d 259 2a49 4389 db 24ad 411 2a6d 4388 db 24a9 11d 2049 4388 db 24a4 4389 db 248d 4389 db 24a2 e002 c000
[14:21:19.895] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a19b 8040 4388 db 24a8 4389 19 2868 db 24af 4388 db 24a9 4389 db 24af 4388 11 2041 db 24c0 75b 244c 4389 db 24a1 4388 db 248d 4389 db 248f e002 c000
[14:21:19.895] ERROR: <datapipe.cc/Read:L166> ====== 2 ====== a19c 80b1 4388 db 20a2 30a 2a4f 4388 db 20c1 4388 db 20a1 4388 db 20a6 4388 db 20ae 4388 db 208d 43c8 10db 208f 43cb f2a 280d 829 2eaa 1f 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff
[14:21:19.895] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a19d 80c0 43c8 db 20a1 43c8 43c8 db 20a5 43c8 db 20a5 43c8 db 20a9 43c8 db 208a 43c8 db 20a2 43c8 db 20a1 e002 c000
[14:21:19.895] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a19e 8000 43c8 db 20a5 43c8 db 20c3 43c8 db 20a4 509 2041 43c8 db 20a5 43c8 db 20a9 43c8 db 208f 43c8 db 208f 43c8 db 208d e002 c000
[14:21:21.538] INFO: 41600 events read in total (2713ms).
[14:21:21.539] INFO: Test took 3941ms.
[14:21:21.578] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:21.578] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 370054
[14:21:21.578] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step1_C0 .. HR_xeff_CalDelScan_step1_C15
[14:21:21.578] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:21:21.599] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:21:22.290] INFO: Expecting 41600 events.
[14:21:25.522] INFO: 41600 events read in total (2705ms).
[14:21:25.523] INFO: Test took 3923ms.
[14:21:25.564] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:25.564] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 374704
[14:21:25.564] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step2_C0 .. HR_xeff_CalDelScan_step2_C15
[14:21:25.564] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:21:25.585] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:21:26.273] INFO: Expecting 41600 events.
[14:21:29.557] INFO: 41600 events read in total (2757ms).
[14:21:29.558] INFO: Test took 3973ms.
[14:21:29.599] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:29.599] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 375084
[14:21:29.599] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step3_C0 .. HR_xeff_CalDelScan_step3_C15
[14:21:29.599] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:21:29.619] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:21:30.312] INFO: Expecting 41600 events.
[14:21:33.599] INFO: 41600 events read in total (2760ms).
[14:21:33.600] INFO: Test took 3981ms.
[14:21:33.641] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:33.641] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 374708
[14:21:33.641] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step4_C0 .. HR_xeff_CalDelScan_step4_C15
[14:21:33.641] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:21:33.660] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:21:34.351] INFO: Expecting 41600 events.
[14:21:37.647] INFO: 41600 events read in total (2769ms).
[14:21:37.648] INFO: Test took 3988ms.
[14:21:37.688] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:37.688] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 374897
[14:21:37.688] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step5_C0 .. HR_xeff_CalDelScan_step5_C15
[14:21:37.688] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:21:37.708] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:21:38.402] INFO: Expecting 41600 events.
[14:21:41.701] INFO: 41600 events read in total (2773ms).
[14:21:41.702] INFO: Test took 3994ms.
[14:21:41.742] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:41.742] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 373139
[14:21:41.742] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step6_C0 .. HR_xeff_CalDelScan_step6_C15
[14:21:41.742] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:21:41.763] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:21:42.456] INFO: Expecting 41600 events.
[14:21:45.757] INFO: 41600 events read in total (2774ms).
[14:21:45.759] INFO: Test took 3996ms.
[14:21:45.798] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:45.798] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 373935
[14:21:45.798] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step7_C0 .. HR_xeff_CalDelScan_step7_C15
[14:21:45.799] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:21:45.820] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:21:46.511] INFO: Expecting 41600 events.
[14:21:49.812] INFO: 41600 events read in total (2775ms).
[14:21:49.813] INFO: Test took 3993ms.
[14:21:49.852] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:49.852] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 374522
[14:21:49.852] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step8_C0 .. HR_xeff_CalDelScan_step8_C15
[14:21:49.852] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:21:49.874] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:21:50.566] INFO: Expecting 41600 events.
[14:21:53.869] INFO: 41600 events read in total (2776ms).
[14:21:53.870] INFO: Test took 3996ms.
[14:21:53.910] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:53.910] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 374489
[14:21:53.910] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step9_C0 .. HR_xeff_CalDelScan_step9_C15
[14:21:53.911] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:21:53.932] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:21:54.624] INFO: Expecting 41600 events.
[14:21:57.925] INFO: 41600 events read in total (2775ms).
[14:21:57.926] INFO: Test took 3994ms.
[14:21:57.966] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:57.966] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 374478
[14:21:57.966] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step10_C0 .. HR_xeff_CalDelScan_step10_C15
[14:21:57.966] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:21:57.985] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:21:58.680] INFO: Expecting 41600 events.
[14:22:01.984] INFO: 41600 events read in total (2777ms).
[14:22:01.985] INFO: Test took 4000ms.
[14:22:02.026] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:02.026] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 375008
[14:22:02.026] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step11_C0 .. HR_xeff_CalDelScan_step11_C15
[14:22:02.026] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:22:02.047] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:22:02.739] INFO: Expecting 41600 events.
[14:22:05.989] INFO: 41600 events read in total (2723ms).
[14:22:05.990] INFO: Test took 3943ms.
[14:22:06.029] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:06.029] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 374128
[14:22:06.029] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step12_C0 .. HR_xeff_CalDelScan_step12_C15
[14:22:06.030] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:22:06.050] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:22:06.743] INFO: Expecting 41600 events.
[14:22:08.341] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 0 Number of ROCs (6) != Token Chain Length (8)
[14:22:08.342] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 1 Number of ROCs (6) != Token Chain Length (8)
[14:22:08.344] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[14:22:08.345] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a096 80b1 43c9 10 2642 db 24aa 43c8 db 248a 43c9 db 248f 6c3 2a4f 845 2a44 43c9 db 24a9 43c9 db 24a9 43c8 db 24ad 43c8 1c 22ef db 2544 21a 2b00 4c8 26ed 821 26e9 43c9 db 24ad 31d 2a4c 6cc 2227 e002 c000
[14:22:08.345] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a090 8000 4388 db 28ad 4388 db 28a4 299 224f 4388 db 28a3 4388 db 28a7 519 2a4c 4388 db 288f 4388 db 28aa 4389 db 292d 4388 db 28a5 15d 2665 e002 c000
[14:22:08.345] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a091 8040 4388 db 28a5 4388 db 28a7 4388 db 28a2 4388 db 28a7 4388 db 28a9 d4 2262 4389 db 28ad 4389 db 2946 81d 22e5 84a 22e7 4388 db 28a5 e002 c000
[14:22:08.345] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a092 80b1 4389 db 24ad 45a 2049 4389 db 2487 4389 db 24a2 495 242d 4389 db 24ac 110 2643 2c4 2847 4389 db 24a5 10d 206b 4388 db 24c5 4388 db 252d 258 2701 4389 9c 2441 db 24c1 213 2888 21d 2684 69a 2a49 854 2221 e002 c000
[14:22:08.345] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a093 80c0 4388 db 24ad 4388 db 248f 4388 db 24a1 4388 db 24af 43c8 10db 24ab 549 270f ff9 20db 4c7 20ca 668 2562 64f 43c8 db 2525 43c8 62 206f db 24a8 855 262d e002 c000
[14:22:08.345] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a094 8000 43c8 db 24a9 43c8 8b 264b db 248d 43c8 db 24a1 43c8 db 24a9 21b 2a4f 651 2a47 43c8 db 24a5 6c2 262c 43c8 db 24c5 43c8 db 2529 43c8 db 24a5 e002 c000
[14:22:08.345] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a095 8040 43c9 db 24a9 43c9 db 2487 43c8 db 24a4 43c9 db 24c1 d9 2461 280 2445 43c8 db 24a7 712 284f 43c8 db 24ad 43c8 14 2301 1a 2305 53 210e db 2545 153 2b0d 2d5 2308 44a 2507 43c9 db 248f e002 c000
[14:22:08.345] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[14:22:08.345] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a196 8000 43c9 db 24a5 55c 2840 43c8 db 24ad 154 2a45 43c9 db 24a1 43c8 db 24c1 43c8 db 24ab 43c9 db 24a2 43c8 db 248f 43c8 db 24a1 e002 c000
[14:22:08.345] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a190 80b1 4389 db 28a2 4389 db 28ac 4389 db 288f 4389 db 28a7 4389 db 28a9 4389 db 288d 4389 db 28a1 4389 db 28a1 e002 c000
[14:22:08.345] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a191 80c0 4388 db 28a1 4388 c 2a44 db 28af 4388 db 28a1 4388 db 28a7 543 264f 4388 db 28a7 4388 db 288f 4388 db 28a3 4388 db 28a5 262 284f e002 c000
[14:22:08.345] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a192 8000 4388 db 24a4 4388 8 202d db 24ac 4388 db 24a5 4388 db 24a5 4389 db 24a9 4388 db 24a5 4388 db 248f 4388 db 24a5 e002 c000
[14:22:08.345] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a193 8040 4389 db 24a8 24a 2460 4388 db 24ab 4389 db 24a7 4389 db 34a9 43c8 db 2e00 72 21b6 21b0 1b6 43c9 db 24a1 e002 c000
[14:22:08.345] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a194 80b1 43c9 db 24a2 43c8 db 24af 43c8 4c 2440 db 248f 43c9 db 24a5 43c8 db 24a8 43c8 db 24a3 43c9 db 248d 43c8 db 248f e002 c000
[14:22:08.345] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a195 80c0 43c8 db 24a5 43c9 db 24ab 43c8 db 24a9 43c8 db 24a5 43c8 db 24ad 43c9 db 24a5 414 2a45 43c9 db 248d 43c9 db 248f e002 c000
[14:22:10.045] INFO: 41600 events read in total (2775ms).
[14:22:10.046] INFO: Test took 3996ms.
[14:22:10.085] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:10.085] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 373818
[14:22:10.085] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step13_C0 .. HR_xeff_CalDelScan_step13_C15
[14:22:10.085] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:22:10.106] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:22:10.800] INFO: Expecting 41600 events.
[14:22:14.099] INFO: 41600 events read in total (2772ms).
[14:22:14.101] INFO: Test took 3995ms.
[14:22:14.139] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:14.140] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 373264
[14:22:14.140] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step14_C0 .. HR_xeff_CalDelScan_step14_C15
[14:22:14.140] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:22:14.159] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:22:14.853] INFO: Expecting 41600 events.
[14:22:16.385] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 0 Number of ROCs (6) != Token Chain Length (8)
[14:22:16.385] ERROR: <datapipe.cc/CheckEventValidity:L480> Channel 1 has NoTokenPass but 6 ROCs were found
[14:22:16.385] ERROR: <datapipe.cc/CheckEventID:L463> Channel 1 Event ID mismatch: local ID (16) != TBM ID (203)
[14:22:16.385] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[14:22:16.385] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0cd 8040 43c8 a2 20ad 759 2649 43c9 a2 208f 43c8 a2 20a2 43c9 a2 208f 43c8 a2 208f 91 2044 43c9 a2 20a5 650 2248 43c8 55 2108 45 2700 a2 210d 69d 2702 43c9 a2 2085 855 262f e002 c000
[14:22:16.385] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0c7 80c0 4388 50 2829 a2 20ad 521 2485 4389 58 2842 a2 20a5 4389 a2 20a2 11b 2064 4388 a2 208d 280 2a42 4389 a2 208f 84a 2642 4388 a2 208c 4389 a2 210d 4388 a2 2067 e002 c000
[14:22:16.386] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0c8 8000 4389 a2 20ad 4389 a2 208f 4388 a2 208b e0 2445 4388 a2 20a1 111 2645 4389 a2 2089 4389 a2 208f 4388 a2 2107 4388 a2 206d 855 2a2c e002 c000
[14:22:16.386] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0c9 8040 438b a2 20cb 438b a2 208f 438b a2 208d 438b a2 2087 438b a2 2087 4388 a2 20a4 409 2664 660 2a65 4388 a2 2121 a0 2501 218 26ee 30c 2901 438a a2 2082 e002 c000
[14:22:16.386] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0ca 80b1 4388 a2 20c4 259 2269 4388 a2 20a3 4388 a2 208f 4388 a2 208f 4388 19 2840 a2 20a1 43c8 10a2 20a5 7ff 3fff cb9 2577 eaf 2ea5 4fc 20c3 fc 2808 a2 2085 112 284f e002 c000
[14:22:16.386] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0cb 80c0 43c8 a2 20af 43c8 a2 208f 43c8 a2 20a2 851 2062 43c8 a2 208d 43c9 a2 20a3 dc 2465 43c9 a2 208f 14a 204c 4e1 2466 713 2443 43c9 a2 210d 43c9 a2 2089 25a 266f 854 222f 859 222f e002 c000
[14:22:16.386] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0cc 8000 43c8 a2 20c5 43c8 a2 20a1 43c9 a2 20a5 43c9 a2 208f 40d 204d 74c 2a65 43c8 a2 208c 43c9 a2 20a5 43c9 a2 212d dd 2b08 29d 2503 2c2 2b20 31d 2509 311 2703 43c9 a2 206f e002 c000
[14:22:16.386] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[14:22:16.386] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1ce 8000 43c8 a2 2089 43c8 a2 20a7 43c8 a2 20a5 43c8 a2 208f 43c8 a2 20a5 d8 244f 43c8 a2 208d 43c8 a2 208a 43c8 a2 208f e002 c000
[14:22:16.386] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1c9 80c0 4388 a2 208f 4388 a2 20af 4388 a2 20af 4388 a2 2089 2d0 264f 4389 a2 208f 4389 a2 208d 4389 a2 208b 4389 a2 20a5 e002 c000
[14:22:16.386] ERROR: <datapipe.cc/Read:L166> ====== 2 ====== a1ca 8000 4388 a2 2085 4388 a2 20ad 349 2a67 4389 a2 20ab 4389 a2 208b 41a 204f 4388 a2 20a8 43c8 10a2 208d 7fd 3eaa fbf 2a84 9fa 29ea a01
[14:22:16.386] ERROR: <datapipe.cc/Read:L166> ====== 2 ====== a10f 8057 fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff
[14:22:16.386] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1cb 8040 43c8 a2 2089 43c9 a2 20c5 43c8 a2 20a5 750 2444 43c9 a2 208f 43c8 a2 20ad 43c9 a2 208d 43c8 a2 208a 43c9 a2 20a2 e002 c000
[14:22:16.386] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1cc 80b1 43c8 a2 2085 43c8 a2 20af 43c8 a2 20a3 43c8 a2 2088 43c8 a2 208f 350 2665 43c8 a2 208d 43c8 a2 208a 43c8 a2 208d 213 2a45 e002 c000
[14:22:16.386] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1cd 80c0 43c8 a2 2088 43c8 a2 20ad 43c8 a2 20a9 340 2422 68a 2641 43c8 a2 208a 4c3 2a65 43c8 a2 20a2 68b 2a4f 43c8 a2 208c 43c8 a2 208d 43c8 a2 208f e002 c000
[14:22:18.308] CRITICAL: <hal.cc/condenseTriggers:L1899> Data size does not correspond to 10 triggers! Aborting data processing!
[14:22:18.311] INFO: 0 events read in total (2931ms).
[14:22:18.311] CRITICAL: <hal.cc/MultiRocAllPixelsCalibrate:L783> Incomplete DAQ data readout! Missing 4160 Events.
[14:22:18.338] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #1
[14:22:18.942] INFO: Expecting 41600 events.
[14:22:22.236] INFO: 41600 events read in total (2767ms).
[14:22:22.237] INFO: Test took 3899ms.
[14:22:22.278] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:22.278] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 372988
[14:22:22.278] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step15_C0 .. HR_xeff_CalDelScan_step15_C15
[14:22:22.278] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:22:22.300] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:22:22.989] INFO: Expecting 41600 events.
[14:22:26.283] INFO: 41600 events read in total (2767ms).
[14:22:26.284] INFO: Test took 3984ms.
[14:22:26.324] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:26.324] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 371394
[14:22:26.324] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step16_C0 .. HR_xeff_CalDelScan_step16_C15
[14:22:26.324] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:22:26.345] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:22:27.040] INFO: Expecting 41600 events.
[14:22:28.527] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 0 Number of ROCs (6) != Token Chain Length (8)
[14:22:28.527] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 1 Number of ROCs (6) != Token Chain Length (8)
[14:22:28.527] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[14:22:28.527] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0e5 8040 43c8 4c 2482 43c9 4c 246f 43c9 4c 2467 855 2a4a 43c8 4c 2485 43c9 4c 248b 43c8 4c 24a1 43c8 12 2aec 4c 2541 43c8 4c 24af 49 2464 49 2080 48 248f e002 c000
[14:22:28.527] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0df 80c0 4388 4c 2486 4388 4c 2467 4388 4c 246c 4388 4c 2481 4388 4c 248b 438b 18 282b 4c 248f 4388 4c 2526 4388 4c 248c 152 2a6c e002 c000
[14:22:28.527] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0e0 8000 4388 4c 2489 4388 4c 2467 61a 244d 4388 22 244a 4c 246c 4388 4c 246f 142 2842 4388 4c 248a 4388 4c 24a1 4389 4c 2525 113 22ec 211 26eb 35a 28ed 4388 4c 248f e002 c000
[14:22:28.527] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0e1 8040 4388 4c 2482 d5 286d 4388 4c 2481 4388 4c 2469 54a 2841 4388 4c 246f 4388 4c 2489 4389 4c 2488 83 22a1 4389 4c 250f 4388 5b 2881 4c 24af 20c 2882 e002 c000
[14:22:28.527] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0e2 80b1 4389 4c 2482 4389 4c 2481 43c9 4c 246d 454 2f3a f11 2eff ff9 204c 484 20d1 64f 43c9 4c 2485 620 2048 43c8 4c 248d 43c8 4c 250f 43c9 4c 24ad 6dc 2042 e002 c000
[14:22:28.527] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0e3 80c0 43c8 4c 248d 43c8 4c 2482 43c8 4c 2467 2a0 2244 43c8 4c 2484 54a 2840 43c8 4c 2489 43c9 4c 248f 43c8 4c 252b 43c8 4c 248a e002 c000
[14:22:28.527] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0e4 8000 43c9 4c 2486 43c8 4c 246d 115 284e 43c8 4c 2482 43c9 4c 248a 43c8 4c 2487 43c8 4c 24a7 43c8 4c 2520 48 270d 705 28ec 43c9 4c 248f 24b 248d 69a 2a49 855 262d e002 c000
[14:22:28.527] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[14:22:28.527] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1e5 80c0 43c9 4c 2482 43c8 4c 246f 43c9 4c 2481 43c9 4c 248a 43c9 4c 246f 43c8 4c 2485 43c8 4c 246f 43c8 4c 2469 e002 c000
[14:22:28.527] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1df 8040 4388 4c 2482 4388 4c 246b 4388 4c 2481 4388 4c 248f 80a 2244 4388 4c 246f 4388 4c 2489 4388 4c 2469 4388 4c 2469 e002 c000
[14:22:28.528] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1e0 80b1 4389 4c 248c 4389 4c 2489 4389 4c 2486 95 2441 4389 4c 248f 4389 4c 246d 4389 4c 2483 4389 4c 246b 4389 4c 246d e002 c000
[14:22:28.528] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1e1 80c0 4388 4c 2485 219 242d 520 284a 4388 4c 246c cb 224f 2c9 224c 81b 266a 4388 4c 246d 99 2043 4388 4c 248f 58 2a45 4388 4c 246f 65c 204d 645 2062 4388 4c 2487 4388 4c 246d 4388 4c 246c e002 c000
[14:22:28.528] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1e2 8000 4389 4c 2482 4388 4c 2485 60b 224f 43c8 43 2267 27f 2768 72 2098 948 2840 2840 98 2900 196 24cc 802 43c9 4c 2489 43c9 4c 246b 43c9 4c 246d e002 c000
[14:22:28.528] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1e3 8040 43c8 4c 2488 43c9 4c 246f 43c9 4c 2482 43c8 4c 2489 84 2243 43c8 4c 2480 43c8 4c 2487 43c8 4c 246f 43c8 4c 246f e002 c000
[14:22:28.528] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1e4 80b1 43c8 4c 2485 43c8 4c 246c 43c9 4c 2469 482 2a42 4c2 2840 43c8 4c 24a4 745 2645 43c9 4c 2481 43c8 4c 2484 43c9 4c 2469 43c8 4c 2469 e002 c000
[14:22:30.361] INFO: 41600 events read in total (2794ms).
[14:22:30.362] INFO: Test took 4017ms.
[14:22:30.401] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:30.401] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 371315
[14:22:30.401] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step17_C0 .. HR_xeff_CalDelScan_step17_C15
[14:22:30.402] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:22:30.422] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:22:31.115] INFO: Expecting 41600 events.
[14:22:32.628] ERROR: <datapipe.cc/CheckEventValidity:L480> Channel 1 has NoTokenPass but 7 ROCs were found
[14:22:32.628] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[14:22:32.628] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a028 8000 43c8 51 268d 43c8 51 268f 43c9 51 266f 43c9 51 2685 43c8 51 26a4 43c9 5 2a41 51 26a9 64c 284f 713 2442 43c8 51 2748 560 2301 43c8 51 26ca e002 c000
[14:22:32.628] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a022 80b1 4389 51 268f 4389 51 2687 4389 51 2669 49a 224d 4389 51 2689 814 2847 4389 51 26a1 515 264f 4388 51 26a5 713 2445 4388 4389 51 26af e002 c000
[14:22:32.628] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a023 80c0 4388 51 26a2 4388 51 268b 4388 51 2669 4388 51 266f 4388 51 268f 690 282c 4389 51 26c1 4388 51 270f 313 2907 4388 51 26af 69a 2a44 e002 c000
[14:22:32.628] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a024 8000 4389 51 268f 4389 51 2685 4388 51 266a 85c 244d 4389 51 2689 50d 284f 4388 51 26a4 150 2640 4388 51 268d 6d8 2442 4388 8 2ae9 121 2b02 619 2701 4389 51 26cc e002 c000
[14:22:32.628] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a025 8040 4388 51 268f 4388 51 2688 4389 51 266c 4388 51 2683 488 2267 4389 51 26a3 4388 51 368f 43c8 51 3740 1545 2fdb 540 25ff 43c8 51 26cd e002 c000
[14:22:32.628] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a026 80b1 43c9 51 26a5 43c8 51 268d 290 2a49 43c9 51 266c 43c9 51 2682 43c9 51 268f 215 264f 35d 2484 413 2887 43c8 51 26a1 43c8 51 2741 31d 2b05 413 2907 495 2703 4a0 2705 43c9 51 26ad 9b 222f 295 262f e002 c000
[14:22:32.628] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a027 80c0 43c9 51 268f 43c8 51 2684 43c9 51 266a 43c8 51 266f 805 2a40 43c8 51 268f 43c8 51 26a1 43c9 51 272c 43c8 51 26aa 9b 224c e002 c000
[14:22:32.628] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[14:22:32.628] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a128 80b1 43c9 51 268e 43c9 51 2682 43c9 51 2688 115 264a 43c9 51 2689 43c9 51 266f 43c9 51 268f 20c 244f 43c9 51 266d 43c9 51 2681 e002 c000
[14:22:32.629] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a122 8000 4389 51 268d 4388 51 2689 313 2469 4389 51 2682 dd 244d 4389 51 26a2 4389 51 266f 4389 19 2840 51 268f 4389 51 266f 4389 51 2681 85c 282b e002 c000
[14:22:32.629] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a123 8040 4388 51 268f 4389 51 2689 4388 51 266f 80a 2a4d 4388 51 268f 4388 51 266f 4388 51 2689 4388 51 266f 4388 51 2682 715 2048 e002 c000
[14:22:32.629] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a124 80b1 4389 51 268c 4388 51 266f 4388 51 2688 159 2649 4389 51 2686 749 244f 4389 51 2668 540 2665 4388 51d 2845 4389 51 266f 615 2043 4388 51 2682 e002 c000
[14:22:32.629] ERROR: <datapipe.cc/Read:L166> ====== 2 ====== a125 80c0 4388 51 268f 4388 51 266b 4388 51 2681 4da 2a61 4388 51 2689 4389 51 266c 4389 51 368c 43c9 51 366f 1aa7 2ea5 980 2a00 40 21ff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff
[14:22:32.629] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a126 8000 43c9 51 268f 310 2262 854 2841 43c9 51 2685 43c9 51 2685 851 2049 43c8 51 2689 618 2647 61b 2a47 43c9 51 266d 43c9 51 268b d1 2447 43c8 51 266f 2c1 2063 43c8 51 2681 e002 c000
[14:22:32.629] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a127 8040 43ca 51 26a1 43cb 51 2669 43ca 51 268c 64b 2865 43ca 51 268a 43cb 51 266f 43ca 21c 2246 43ca 51 266f 43ca 51 266f e002 c000
[14:22:34.401] INFO: 41600 events read in total (2759ms).
[14:22:34.402] INFO: Test took 3980ms.
[14:22:34.442] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:34.442] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 371561
[14:22:34.442] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step18_C0 .. HR_xeff_CalDelScan_step18_C15
[14:22:34.442] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:22:34.462] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:22:35.150] INFO: Expecting 41600 events.
[14:22:38.280] INFO: 41600 events read in total (2603ms).
[14:22:38.282] INFO: Test took 3820ms.
[14:22:38.325] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:38.325] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 367071
[14:22:38.325] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists HR_xeff_CalDelScan_step19_C0 .. HR_xeff_CalDelScan_step19_C15
[14:22:38.325] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:22:38.648] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 0: caldel = 160 eff = 0.99887
[14:22:38.648] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 1: caldel = 142 eff = 0.99899
[14:22:38.649] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 2: caldel = 143 eff = 0.998582
[14:22:38.649] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 3: caldel = 155 eff = 0.99875
[14:22:38.649] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 4: caldel = 146 eff = 0.994014
[14:22:38.649] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 5: caldel = 168 eff = 0.981058
[14:22:38.650] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 6: caldel = 156 eff = 0.960817
[14:22:38.650] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 7: caldel = 163 eff = 0.972236
[14:22:38.650] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 8: caldel = 152 eff = 0.999615
[14:22:38.650] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 9: caldel = 144 eff = 0.999688
[14:22:38.651] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 10: caldel = 156 eff = 0.999591
[14:22:38.651] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 11: caldel = 162 eff = 0.999615
[14:22:38.651] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 12: caldel = 169 eff = 0.999519
[14:22:38.651] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 13: caldel = 148 eff = 0.99976
[14:22:38.652] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 14: caldel = 163 eff = 0.999952
[14:22:38.652] DEBUG: <PixTestHighRate.cc/doCalDelScan:L435> roc 15: caldel = 146 eff = 0.999904
[14:22:38.656] DEBUG: <PixTestHighRate.cc/~PixTestHighRate:L258> PixTestHighRate dtor
[14:22:38.680] INFO: enter test to run
[14:23:01.483] INFO: test: HighRate no parameter change
[14:23:01.483] INFO: running: highrate
[14:23:01.484] DEBUG: <PixTestHighRate.cc/setParameter:L68> setting fParTriggerFrequency -> 20
[14:23:01.484] DEBUG: <PixTestHighRate.cc/init:L211> PixTestHighRate::init()
[14:23:01.484] DEBUG: <PixTestHighRate.cc/PixTestHighRate:L31> PixTestHighRate ctor(PixSetup &a, string, TGTab *)
[14:23:01.485] DEBUG: <PixTestHighRate.cc/runCommand:L165> running command: xpixelalive
[14:23:01.485] INFO: ----------------------------------------------------------------------
[14:23:01.485] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:23:01.485] INFO: ----------------------------------------------------------------------
[14:23:01.485] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: clk: 4
[14:23:01.485] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: ctr: 4
[14:23:01.485] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: sda: 19
[14:23:01.485] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: tin: 9
[14:23:01.485] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: level: 15
[14:23:01.485] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: triggerdelay: 0
[14:23:01.485] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: clk: 4
[14:23:01.485] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: ctr: 4
[14:23:01.485] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: sda: 19
[14:23:01.485] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: tin: 9
[14:23:01.485] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: level: 15
[14:23:01.485] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: triggerdelay: 20
[14:23:01.492] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:23:02.095] INFO: Expecting 208000 events.
[14:23:14.286] INFO: 208000 events read in total (11664ms).
[14:23:14.289] INFO: Test took 12797ms.
[14:23:14.459] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:23:14.459] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 1569197
[14:23:14.459] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists highRate_C0 .. highRate_C15
[14:23:14.460] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:23:14.718] INFO: number of dead pixels (per ROC): 0 0 1 0 19 71 104 86 1 0 0 0 0 0 0 0
[14:23:14.718] INFO: number of red-efficiency pixels: 106 54 87 120 156 270 1660 475 77 127 101 96 106 63 24 39
[14:23:14.718] INFO: number of X-ray hits detected: 72040 45327 67623 104025 112096 131601 319147 126555 60950 94528 91284 83997 93012 53601 21870 25263
[14:23:14.718] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:23:14.718] INFO: number of Vcal hits detected: 207890 207946 207862 207878 206913 204171 200304 202645 207873 207870 207891 207903 207893 207936 207976 207959
[14:23:14.718] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 98.8 99.7 100.0 99.9 100.0 100.0 100.0 100.0 100.0 100.0
[14:23:14.718] INFO: Vcal hit overall efficiency (%): 99.9 100.0 99.9 99.9 99.5 98.2 96.3 97.4 99.9 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[14:23:14.719] INFO: X-ray hit rate [MHz/cm2]: 21.1 13.3 19.8 30.5 32.9 38.6 93.5 37.1 17.9 27.7 26.8 24.6 27.3 15.7 6.4 7.4
[14:23:14.719] INFO: PixTestHighRate::doXPixelAlive() done
[14:23:14.766] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: clk: 4
[14:23:14.766] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: ctr: 4
[14:23:14.766] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: sda: 19
[14:23:14.766] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: tin: 9
[14:23:14.766] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: level: 15
[14:23:14.766] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: triggerdelay: 0
[14:23:14.766] INFO: PixTest:: pg_setup set to default.
[14:23:14.766] DEBUG: <PixTestHighRate.cc/~PixTestHighRate:L258> PixTestHighRate dtor
[14:23:14.776] INFO: enter test to run
[14:23:40.522] INFO: test: HighRate no parameter change
[14:23:40.523] INFO: running: highrate
[14:23:40.523] DEBUG: <PixTestHighRate.cc/setParameter:L68> setting fParTriggerFrequency -> 20
[14:23:40.523] DEBUG: <PixTestHighRate.cc/init:L211> PixTestHighRate::init()
[14:23:40.523] DEBUG: <PixTestHighRate.cc/PixTestHighRate:L31> PixTestHighRate ctor(PixSetup &a, string, TGTab *)
[14:23:40.524] DEBUG: <PixTestHighRate.cc/runCommand:L165> running command: xpixelalive
[14:23:40.524] INFO: ----------------------------------------------------------------------
[14:23:40.524] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:23:40.524] INFO: ----------------------------------------------------------------------
[14:23:40.524] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: clk: 4
[14:23:40.524] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: ctr: 4
[14:23:40.524] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: sda: 19
[14:23:40.524] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: tin: 9
[14:23:40.524] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: level: 15
[14:23:40.524] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: triggerdelay: 0
[14:23:40.524] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: clk: 4
[14:23:40.524] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: ctr: 4
[14:23:40.524] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: sda: 19
[14:23:40.524] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: tin: 9
[14:23:40.524] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: level: 15
[14:23:40.524] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: triggerdelay: 20
[14:23:40.533] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:23:41.141] INFO: Expecting 208000 events.
[14:23:44.811] WARNING: Channel 0 ROC 6: Readback start marker after 13 readouts!
[14:23:44.811] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 1 Number of ROCs (7) != Token Chain Length (8)
[14:23:44.811] WARNING: Channel 0 ROC 6: Readback start marker after 3 readouts!
[14:23:44.811] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[14:23:44.811] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1de 8000 43c8 13 2aa4 43c8 13 2aa3 43c8 13 2a8e 4d0 222d 43c8 13 2a8d 43c8 13 2a8d 43c8 13 2a8d 43c8 13 2a8f 43c8 13 2aa1 e002 c000
[14:23:44.812] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1d8 80b1 4389 13 2a87 4389 13 2aa7 41c 2a49 50b 284f 61d 2268 4389 13 2aa5 8b 2667 154 224f 4389 13 2a8e 59 2268 151 2080 748 262f 810 2049 4389 13 2a8f e0 2668 501 2446 75b 2247 4389 13 2a8a 203 266d 4389 13 2a8f 304 2044 4389 13 2aa5 e002 c000
[14:23:44.812] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1d9 80c0 4388 13 2aa5 740 2646 4388 13 2a8d 4388 13 2aa2 149 264f 150 264d 6ca 2a43 851 2240 4388 13 2aa1 4389 13 2a8d 120 2441 4389 13 2a8d 4389 13 2a8d 4389 13 2aa9 e002 c000
[14:23:44.812] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1da 8000 4388 13 2aa2 4cc 2449 650 2662 4388 13 2aa5 4dd 244d 4389 13 2aa8 8a 244f 4389 13 2a87 294 2241 4388 13 2aa9 4388 13 2a89 4389 13 2aa0 4389 13 2aa3 e002 c000
[14:23:44.812] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1db 8040 4388 13 2a8f 4389 13 2aad 8b 2885 4388 13 2aaa 4389 13 2a8e 351 206b 43c8 1013 2aa5 320 2460 b2 43c9 13 2aa1 43c8 13 2aa3 43c9 13 2aa5 483 2047 e002 c000
[14:23:44.812] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1dc 80b1 43c8 13 2a8d 43c8 13 2aa1 14b 284d 20d 2649 615 2665 804 2824 43c8 13 2aa2 4db 2a4f 51d 2040 84d 284f 43c8 13 2a8a 43c8 13 2a8d 43c8 10 2829 13 2aa1 43c8 13 2aa1 49d 206f 43c8 13 2aa7 119 2847 819 224c e002 c000
[14:23:44.812] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1dd 80c0 43c8 13 2aa2 43c8 13 2a8d 43c8 13 2aa1 43c8 13 2a89 210 2a4d 409 206a 509 2049 43c8 13 2aa9 15 26a7 e2 2862 e2 2465 43c8 13 2aa5 43c8 13 2aa1 43c8 13 2aa4 422 284d e002 c000
[14:23:44.812] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[14:23:44.812] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0e1 8040 43c8 13 2aa4 43c8 13 2a87 293 2467 43c8 13 2a8d 43c8 20 2441 13 2aa5 43c8 13 2a89 50 2845 541 2849 703 2a82 43c9 13 2a8a 290 284f 81b 2a63 43c9 13 2b2f 43c8 13 2aaf e002 c000
[14:23:44.812] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0db 80c0 4388 13 2aac 71a 284d 4388 13 2a6d 4388 13 2aa8 4388 13 2a8f 4389 13 2a8d 1321 2849 43c8 43ca 284f 43c9 13 2b4d 45 2303 43c9 8 284f 13 2ac6 8b 284f e002 c000
[14:23:44.812] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0dc 8000 43c8 13 2aa8 661 286a 43c8 13 2a8a 4d5 206e 43c9 13 2aa9 dd 2842 43c9 13 2a8f 43c8 13 2a89 14 2649 43c9 13 2aa5 70c 2625 75d 244f 858 262d 43c8 13 2b2f 99 210d 95 20ef 20c 2ae9 43c9 1b 2865 13 2aaf 855 2a44 e002 c000
[14:23:44.812] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0dd 8040 43c8 13 2aac 43c9 13 2a88 43c8 13 2aa2 43c9 13 2a87 703 2842 852 2469 43c8 13 2a6d d8 2269 10c 2a4a 43c8 13 2aa9 30b 2466 43c8 13 2b25 43c9 13 2ac5 e002 c000
[14:23:44.812] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0de 80b1 43c8 13 2aa2 43c8 13 2a8d 43c8 13 2aa5 6c5 2865 43c8 13 2a8b 74d 204f 43c8 13 2a82 58 2849 43c8 13 2aa6 43ca 13 2b40 a0 250b 20d 2309 2d4 2b05 451 2509 44c 2104 69d 2900 851 2ae3 43c8 13 2aa9 e002 c000
[14:23:44.812] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0df 80c0 43c8 43c8 13 2a85 43c8 13 2ac1 43c8 13 2a8f 30c 2845 362 224d 43c8 13 2a6d 552 2a4d 619 244d 43ca 13 2aac 4c9 244f 818 284d 43c8 13 2b0d 210 2505 545 2705 55a 2b03 43c8 13 2ac1 258 2665 e002 c000
[14:23:44.812] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0e0 8000 43c8 13 2aa4 43c8 13 2a8b 43c8 13 2aad 43c8 13 2a8d 68b 2640 713 2684 43c8 13 2a83 94 2045 6ca 2a68 43c8 13 2aa1 43c9 13 2b26 54a 2b20 43c8 13 2aa4 85d 224f e002 c000
[14:23:55.053] INFO: 208000 events read in total (13385ms).
[14:23:55.058] INFO: Test took 14525ms.
[14:23:55.368] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:23:55.368] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 2838376
[14:23:55.368] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists highRate_C0 .. highRate_C15
[14:23:55.369] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:23:55.673] INFO: number of dead pixels (per ROC): 0 0 1 0 19 71 104 86 1 0 0 0 0 0 0 0
[14:23:55.673] INFO: number of red-efficiency pixels: 300 182 331 452 501 629 1783 631 198 360 325 286 334 215 51 64
[14:23:55.673] INFO: number of X-ray hits detected: 149765 94435 142233 217755 233211 247388 395411 192420 127312 197314 192609 176074 195560 111679 45922 53010
[14:23:55.673] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:23:55.673] INFO: number of Vcal hits detected: 207648 207802 207579 207504 206519 203776 200236 202637 207750 207610 207647 207700 207640 207770 207947 207936
[14:23:55.673] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.8 99.8 99.7 98.8 99.6 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[14:23:55.674] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.8 99.3 98.0 96.3 97.4 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[14:23:55.674] INFO: X-ray hit rate [MHz/cm2]: 43.9 27.7 41.7 63.8 68.4 72.5 115.9 56.4 37.3 57.8 56.5 51.6 57.3 32.7 13.5 15.5
[14:23:55.674] INFO: PixTestHighRate::doXPixelAlive() done
[14:23:55.724] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: clk: 4
[14:23:55.724] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: ctr: 4
[14:23:55.724] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: sda: 19
[14:23:55.724] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: tin: 9
[14:23:55.724] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: level: 15
[14:23:55.724] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: triggerdelay: 0
[14:23:55.724] INFO: PixTest:: pg_setup set to default.
[14:23:55.724] DEBUG: <PixTestHighRate.cc/~PixTestHighRate:L258> PixTestHighRate dtor
[14:23:55.741] INFO: enter test to run
[14:24:05.178] INFO: test: HighRate no parameter change
[14:24:05.178] INFO: running: highrate
[14:24:05.178] DEBUG: <PixTestHighRate.cc/setParameter:L68> setting fParTriggerFrequency -> 20
[14:24:05.179] DEBUG: <PixTestHighRate.cc/init:L211> PixTestHighRate::init()
[14:24:05.179] DEBUG: <PixTestHighRate.cc/PixTestHighRate:L31> PixTestHighRate ctor(PixSetup &a, string, TGTab *)
[14:24:05.180] DEBUG: <PixTestHighRate.cc/runCommand:L165> running command: xpixelalive
[14:24:05.180] INFO: ----------------------------------------------------------------------
[14:24:05.180] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:24:05.180] INFO: ----------------------------------------------------------------------
[14:24:05.180] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: clk: 4
[14:24:05.180] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: ctr: 4
[14:24:05.180] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: sda: 19
[14:24:05.180] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: tin: 9
[14:24:05.180] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: level: 15
[14:24:05.180] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L464> old set: triggerdelay: 0
[14:24:05.180] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: clk: 4
[14:24:05.180] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: ctr: 4
[14:24:05.180] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: sda: 19
[14:24:05.180] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: tin: 9
[14:24:05.180] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: level: 15
[14:24:05.180] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L480> setting: triggerdelay: 20
[14:24:05.186] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #0
[14:24:05.792] INFO: Expecting 208000 events.
[14:24:09.465] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 0 Number of ROCs (6) != Token Chain Length (8)
[14:24:09.465] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 1 Number of ROCs (6) != Token Chain Length (8)
[14:24:09.465] ERROR: <datapipe.cc/CheckEventID:L463> Channel 1 Event ID mismatch: local ID (199) != TBM ID (31)
[14:24:09.465] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 1 Number of ROCs (0) != Token Chain Length (8)
[14:24:09.465] ERROR: <datapipe.cc/CheckEventID:L463> Channel 1 Event ID mismatch: local ID (32) != TBM ID (199)
[14:24:09.465] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[14:24:09.465] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0c9 8040 43ca 1a 22a9 43ca 1a 2281 43ca 1a 228a 654 204e 43ca 1a 2289 43ca 1a 2287 840 264b 43c9 214 2642 43c8 1a 232b 43ca 1c 2880 1a 22a6 98 224f 312 204f e002 c000
[14:24:09.465] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0c3 80c0 4389 1a 22a6 4389 1b 2443 1a 228b 213 2847 4389 1a 228d 44d 2249 822 204f 4389 1a 2287 6d0 2440 860 2245 4389 22 284a 1a 2285 4389 4 202a 1a 22ac 442 206f 4388 1a 232f 61 2b21 460 210c 60c 2503 709 250c 754 2b02 852 2901 4389 1a 22af 119 2087 e002 c000
[14:24:09.465] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0c4 8000 4388 d 2664 1a 22ac 4388 1a 2287 299 224f 4388 1a 22a5 4388 1a 228d cd 204f 320 2047 6d4 2844 4388 1a 226c 852 264f 4388 458 286d 44d 286f 4388 1a 2328 2d1 2109 4388 1a 22a5 e002 c000
[14:24:09.465] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0c5 8040 4388 1a 22aa 4388 1a 2287 4388 1a 228f 4388 1a 2281 4388 1a 226c 105 2a65 4388 18 2262 1a 22a1 24c 244f 4388 1a 2342 4388 1a 22a5 112 2467 859 224b e002 c000
[14:24:09.465] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0c6 80b1 4389 1a 22a5 54 2465 dc 2461 661 266d 4389 1a 2282 458 264f 4389 1a 2289 44d 204f 510 2262 4389 4389 1a 226d cc 2644 6a7 2e1f 1df4 25f0 2aa 2e7f 62 201a 284 2290 86f 2758 462 43c8 1a 2324 121 2707 315 210e 605 2701 43c9 1a 22e1 e002 c000
[14:24:09.465] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0c7 80c0 43c8 1a 228d 71a 264f 43c8 1a 226f 62 284f 21b 2045 43c8 1a 2285 43c8 1a 22a9 43c8 1a 2285 149 2a6f 20b 286d 28b 2a4c 498 2884 688 2260 43c8 1a 228c 99 266f 6cc 2440 43c9 1a 232b a0 2309 43c8 1a 22a4 213 248d e002 c000
[14:24:09.465] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0c8 8000 43c8 1a 22a6 54 244f 293 2860 29d 2287 43c8 1a 226d 43c8 1a 22a6 6cd 264d 80c 2624 80c 2a45 43c8 1a 2285 43c8 d 2027 8 2827 1a 2284 43c9 1a 22a5 699 2440 43c9 1a 232f 28b 2305 80d 2505 43c8 1a 228f d9 2461 e002 c000
[14:24:09.465] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[14:24:09.465] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1ca 8000 43c8 1a 22a6 54c 262d 43c8 1a 2281 43c9 1a 228f 43c9 1a 2283 705 2661 43c8 1a 22a5 44c 2649 43c8 1a 228d 43c9 1a 2287 43c9 1a 22a5 e002 c000
[14:24:09.465] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1c5 80c0 4388 1a 228f 93 224d 4388 15 284f 1a 22a9 d9 2461 81d 2a46 4388 1a 22a1 661 228c 4388 1a 2289 59 2a47 4388 1a 22a8 154 2a4a 495 2061 804 2423 4388 1a 228d 4388 1a 2285 4388 1a 22a1 90 2645 e002 c000
[14:24:09.465] ERROR: <datapipe.cc/Read:L166> ====== 2 ====== a1c6 8000 4388 1a 22a6 349 264f 4388 1a 2289 609 2a65 4388 1a 22a6 4388 14 240f 1a 228f 151 2689 21b 2065 4388 1a 22aa 43c8 1a 22a9 e69 355a a07
[14:24:09.465] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a11f 80e0 68 e002 c000
[14:24:09.465] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1c7 8040 43ca 1a 228f 43ca 1a 228d 43ca d 2a42 1a 22a3 43ca 1a 228a 43ca 1a 22a9 68c 204f 43ca 9 262f 1a 22a9 4db 2464 43ca 1a 226d 43ca 1a 22a5 e002 c000
[14:24:09.466] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1c8 80b1 43c9 1a 228e 30a 286d 43c9 15 204c 1a 22a5 43c9 1a 22a2 311 204a 43c9 1a 228b 43c9 1a 22a3 43c9 1a 228f 43c9 1a 2289 43c9 1a 22a2 851 2a28 e002 c000
[14:24:09.466] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1c9 80c0 43c8 1a 22a1 43c8 c 202f 1a 22a6 689 2847 43c8 12 282f 1a 22a5 43c8 1a 22a3 a0 282c 50a 244a 43c9 1a 22a5 43c9 1a 228d 44c 2649 43c9 1a 2285 43c9 1a 228f e002 c000
[14:24:20.391] CRITICAL: <hal.cc/condenseTriggers:L1899> Data size does not correspond to 50 triggers! Aborting data processing!
[14:24:20.403] INFO: 0 events read in total (14084ms).
[14:24:20.403] CRITICAL: <hal.cc/MultiRocAllPixelsCalibrate:L783> Incomplete DAQ data readout! Missing 4160 Events.
[14:24:20.403] DEBUG: <PixTest.cc/efficiencyMaps:L396> attempt #1
[14:24:20.003] INFO: Expecting 208000 events.
[14:24:36.719] INFO: 208000 events read in total (15189ms).
[14:24:36.727] INFO: Test took 16324ms.
[14:24:37.174] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:37.174] DEBUG: <PixTest.cc/efficiencyMaps:L407> eff result size = 4081601
[14:24:37.174] DEBUG: <PixTest.cc/efficiencyMaps:L412> Create hists highRate_C0 .. highRate_C15
[14:24:37.174] DEBUG: <PixTest.cc/efficiencyMaps:L426> booking xray maps for unmasked detector
[14:24:37.525] INFO: number of dead pixels (per ROC): 0 0 1 0 19 71 104 87 1 0 0 0 0 0 0 0
[14:24:37.525] INFO: number of red-efficiency pixels: 686 338 725 1168 1108 1194 2267 915 440 782 707 631 757 528 94 95
[14:24:37.525] INFO: number of X-ray hits detected: 226172 143317 214677 328018 351278 356999 477188 255733 191832 298901 290554 266772 293433 169641 69714 81095
[14:24:37.525] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:24:37.525] INFO: number of Vcal hits detected: 206945 207602 206953 206507 205711 202967 199258 202312 207446 207111 207167 207294 207136 207330 207900 207902
[14:24:37.525] INFO: Vcal hit fiducial efficiency (%): 99.6 99.8 99.6 99.4 99.4 99.3 98.3 99.5 99.8 99.6 99.6 99.7 99.6 99.7 100.0 100.0
[14:24:37.525] INFO: Vcal hit overall efficiency (%): 99.5 99.8 99.5 99.3 98.9 97.6 95.8 97.3 99.7 99.6 99.6 99.7 99.6 99.7 100.0 100.0
[14:24:37.525] INFO: X-ray hit rate [MHz/cm2]: 66.3 42.0 62.9 96.1 103.0 104.6 139.9 75.0 56.2 87.6 85.2 78.2 86.0 49.7 20.4 23.8
[14:24:37.525] INFO: PixTestHighRate::doXPixelAlive() done
[14:24:37.573] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: clk: 4
[14:24:37.573] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: ctr: 4
[14:24:37.573] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: sda: 19
[14:24:37.573] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: tin: 9
[14:24:37.573] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: level: 15
[14:24:37.573] DEBUG: <PixTestHighRate.cc/doXPixelAlive:L599> resetting: triggerdelay: 0
[14:24:37.573] INFO: PixTest:: pg_setup set to default.
[14:24:37.573] DEBUG: <PixTestHighRate.cc/~PixTestHighRate:L258> PixTestHighRate dtor
[14:24:37.587] INFO: enter test to run
[14:24:41.922] INFO: test: exit no parameter change
[14:24:41.923] DEBUG: <pXar.cc/main:L340> Final Analog Current: 389.9mA
[14:24:41.924] DEBUG: <pXar.cc/main:L341> Final Digital Current: 465.5mA
[14:24:41.924] DEBUG: <pXar.cc/main:L342> Final Module Temperature: 18.3 C
[14:24:41.924] DEBUG: <PixMonitor.cc/dumpSummaries:L39> PixMonitor::dumpSummaries
[14:24:42.276] QUIET: Connection to board 33 closed.
[14:24:42.277] INFO: pXar: this is the end, my friend
[14:24:42.277] DEBUG: <PixSetup.cc/~PixSetup:L68> PixSetup free fPxarMemory