[09:20:14.063] INFO: *** Welcome to pxar ***
[09:20:14.063] INFO: *** Today: 2015/07/31
[09:20:14.063] INFO: readRocDacs: /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters_C0.dat .. /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters_C15.dat
[09:20:14.064] INFO: readTbmDacs: /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//tbmParameters_C0a.dat .. /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//tbmParameters_C0b.dat
[09:20:14.064] INFO: readMaskFile: /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//defaultMaskFile.dat
[09:20:14.064] INFO: readTrimFile: /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//trimParameters_C0.dat .. /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//trimParameters_C15.dat
[09:20:14.128] INFO: clk: 4
[09:20:14.128] INFO: ctr: 4
[09:20:14.128] INFO: sda: 19
[09:20:14.128] INFO: tin: 9
[09:20:14.128] INFO: level: 15
[09:20:14.128] INFO: triggerdelay: 0
[09:20:14.128] QUIET: Instanciating API for pxar v2.2.5+67~g3b1c276
[09:20:14.128] INFO: Log level: DEBUG
[09:20:14.136] INFO: Found DTB DTB_WV7UX2
[09:20:14.149] QUIET: Connection to board DTB_WV7UX2 opened.
[09:20:14.152] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 105
HW version: DTB1.2
FW version: 4.2
SW version: 4.2
USB id: DTB_WV7UX2
MAC address: 40D855118069
Hostname: pixelDTB105
Comment: with CMOS buffer
------------------------------------------------------
[09:20:14.155] INFO: RPC call hashes of host and DTB match: 447413373
[09:20:15.682] INFO: DUT info:
[09:20:15.683] INFO: The DUT currently contains the following objects:
[09:20:15.683] INFO: 2 TBM Cores tbm08c (2 ON)
[09:20:15.683] INFO: TBM Core alpha (0): 7 registers set
[09:20:15.683] INFO: TBM Core beta (1): 7 registers set
[09:20:15.683] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[09:20:15.683] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[09:20:15.683] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[09:20:15.683] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[09:20:15.683] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[09:20:15.683] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[09:20:15.683] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[09:20:15.683] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[09:20:15.683] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[09:20:15.683] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[09:20:15.683] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[09:20:15.683] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[09:20:15.683] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[09:20:15.683] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[09:20:15.683] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[09:20:15.683] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[09:20:15.683] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[09:20:15.683] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->BB<-
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> dumpall: checkbox(0)
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> dumpproblematic: checkbox(0)
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 5
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> vcals: 250
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->BB2<-
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> vcals: 222
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> plwidth: 35
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> targetia: 24
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->BB3<-
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> dumpall: checkbox(0)
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> dumpproblematic: checkbox(0)
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 5
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> vcals: 250
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Cmd<-
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->DacDacScan<-
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> phmap: checkbox
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> dac1: caldel
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> dac1lo: 0
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> dac1hi: 255
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> dac2: vthrcomp
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> dac2lo: 0
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> dac2hi: 255
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->DacScan<-
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> phmap: checkbox(1)
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> allpixels: checkbox(0)
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> unmasked: checkbox(0)
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> dac: vcal
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> daclo: 0
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> dachi: 255
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->GainPedestal<-
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> showfits: checkbox(0)
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> extended: checkbox(0)
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> dumphists: checkbox(0)
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> vcalstep: 10
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> measure: button
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> fit: button
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> save: button
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->HighRate<-
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> maskhotpixels: button
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> savemaskfile: checkbox(0)
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> maskfilename: default
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> caldelscan: button
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> xpixelalive: button
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 50
[09:20:15.684] DEBUG: <PixTestParameters.cc/dump:L107> vcal: 200
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> xnoisemaps: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> daclo: 0
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> dachi: 100
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> dacs/step: 20
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> rundaq: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> trgfrequency(khz): 20
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> runseconds: 2
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> triggerdelay: 20
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> delaytbm: checkbox
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> filltree: checkbox
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->IV<-
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> port: /dev/FIXME
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> voltagestart: 0
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> voltagestop: 600
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> voltagestep: 5
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> delay: 1
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> compliance(ua): 100
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->PhOptimization<-
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> safetymarginlow: 20
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> saturationvcal: 100
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> quantilesaturation: 0.98
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->PixelAlive<-
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> vcal: 200
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> alivetest: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> masktest: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> addressdecodingtest: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Pretest<-
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> programroc: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> targetia: 24
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> setvana: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> iterations: 100
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> settimings: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> findworkingpixel: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> setvthrcompcaldel: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> vcal: 250
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> deltavthrcomp: 50
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> fraccaldel: 0.5
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 5
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> savedacs: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Readback<-
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> calibratevd: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> calibrateva: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> calibrateia: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> readbackvbg: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> getcalibratedvbg: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> usecalvd: checkbox(1)
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> usecalva: checkbox(0)
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> setvana: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Scurves<-
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> adjustvcal: checkbox(1)
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> dumpall: checkbox(0)
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> dumpproblematic: checkbox(0)
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> dumpoutputfile: checkbox(0)
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 50
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> dac: VthrComp
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> daclo: 0
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> dachi: 200
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> dacs/step: 10
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> scurves: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Timing<-
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> fastscan: checkbox(0)
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> targetclk: 4
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> clocksdascan: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> phasescan: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> levelscan: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> tbmphasescan: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> rocdelayscan: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> timingtest: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> saveparameters: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Trim<-
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> trim: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> vcal: 35
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> trimbits: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Xray<-
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> maskhotpixels: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> savemaskfile: checkbox(0)
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> maskfilename: default
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> source: Ag
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> phrun: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> runseconds: 100
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> trgfrequency(khz): 100
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> ratescan: button
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> vthrcompmin: 10
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> vthrcompmax: 80
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> stepseconds: 5
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> delaytbm: checkbox
[09:20:15.685] DEBUG: <PixTestParameters.cc/dump:L107> filltree: checkbox
[09:20:15.685] DEBUG: <PixSetup.cc/init:L81> PixSetup init start; getCurrentRSS() = 31662080
[09:20:15.685] DEBUG: <PixSetup.cc/init:L87> fPixTestParameters = 0x1e62160
[09:20:15.685] DEBUG: <PixSetup.cc/init:L88> fConfigParameters = 0x1dc79c0
[09:20:15.685] DEBUG: <PixSetup.cc/init:L89> fPxarMemory = 0x7fb659d94010
[09:20:15.685] DEBUG: <PixSetup.cc/init:L90> fPxarMemHi = 0x7fb65ffff510
[09:20:15.685] DEBUG: <PixSetup.cc/init:L106> PixSetup init done; getCurrentRSS() = 31723520 fPxarMemory = 0x7fb659d94010
[09:20:15.685] DEBUG: <PixTestFactory.cc/PixTestFactory:L52> PixTestFactory::PixTestFactory()
[09:20:16.096] INFO: enter 'restricted' command line mode
[09:20:16.096] INFO: enter test to run
[09:20:16.096] INFO: test: Pretest no parameter change
[09:20:16.096] INFO: running: pretest
[09:20:16.101] INFO: ######################################################################
[09:20:16.101] INFO: PixTestPretest::doTest()
[09:20:16.101] INFO: ######################################################################
[09:20:16.103] INFO: ----------------------------------------------------------------------
[09:20:16.103] INFO: PixTestPretest::programROC()
[09:20:16.103] INFO: ----------------------------------------------------------------------
[09:20:34.124] INFO: PixTestPretest::programROC() done: ROCs are all programmable
[09:20:34.124] INFO: IA differences per ROC: 17.7 17.7 17.7 16.9 18.5 17.7 17.7 19.3 16.9 20.1 20.1 17.7 17.7 17.7 20.9 20.1
[09:20:34.194] INFO: ----------------------------------------------------------------------
[09:20:34.194] INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[09:20:34.194] INFO: ----------------------------------------------------------------------
[09:20:34.298] DEBUG: <PixTestPretest.cc/setVana:L254> offset current from other 15 ROCs is 70.0312 mA
[09:20:34.399] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 0 iter 0 Vana 78 Ia 23.1688 mA
[09:20:34.500] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 0 iter 1 Vana 83 Ia 24.7687 mA
[09:20:34.601] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 0 iter 2 Vana 79 Ia 21.5687 mA
[09:20:34.702] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 0 iter 3 Vana 94 Ia 26.3688 mA
[09:20:34.803] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 0 iter 4 Vana 81 Ia 22.3687 mA
[09:20:34.904] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 0 iter 5 Vana 91 Ia 25.5688 mA
[09:20:35.004] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 0 iter 6 Vana 83 Ia 24.7687 mA
[09:20:35.105] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 0 iter 7 Vana 79 Ia 22.3687 mA
[09:20:35.205] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 0 iter 8 Vana 89 Ia 26.3688 mA
[09:20:35.306] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 0 iter 9 Vana 76 Ia 22.3687 mA
[09:20:35.406] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 0 iter 10 Vana 86 Ia 26.3688 mA
[09:20:35.507] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 0 iter 11 Vana 73 Ia 21.5687 mA
[09:20:35.608] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 1 iter 0 Vana 78 Ia 23.9688 mA
[09:20:35.709] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 2 iter 0 Vana 78 Ia 22.3687 mA
[09:20:35.810] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 2 iter 1 Vana 88 Ia 25.5688 mA
[09:20:35.911] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 2 iter 2 Vana 80 Ia 23.9688 mA
[09:20:36.012] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 3 iter 0 Vana 78 Ia 22.3687 mA
[09:20:36.113] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 3 iter 1 Vana 88 Ia 22.3687 mA
[09:20:36.214] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 3 iter 2 Vana 98 Ia 25.5688 mA
[09:20:36.315] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 3 iter 3 Vana 90 Ia 24.7687 mA
[09:20:36.416] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 3 iter 4 Vana 86 Ia 23.9688 mA
[09:20:36.517] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 4 iter 0 Vana 78 Ia 24.7687 mA
[09:20:36.618] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 4 iter 1 Vana 74 Ia 22.3687 mA
[09:20:36.718] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 4 iter 2 Vana 84 Ia 25.5688 mA
[09:20:36.819] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 4 iter 3 Vana 76 Ia 23.1688 mA
[09:20:36.919] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 4 iter 4 Vana 81 Ia 25.5688 mA
[09:20:37.020] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 4 iter 5 Vana 73 Ia 23.1688 mA
[09:20:37.122] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 4 iter 6 Vana 78 Ia 23.9688 mA
[09:20:37.224] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 5 iter 0 Vana 78 Ia 21.5687 mA
[09:20:37.325] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 5 iter 1 Vana 93 Ia 26.3688 mA
[09:20:37.425] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 5 iter 2 Vana 80 Ia 23.1688 mA
[09:20:37.526] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 5 iter 3 Vana 85 Ia 24.7687 mA
[09:20:37.627] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 5 iter 4 Vana 81 Ia 23.1688 mA
[09:20:37.727] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 5 iter 5 Vana 86 Ia 23.1688 mA
[09:20:37.828] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 5 iter 6 Vana 91 Ia 23.9688 mA
[09:20:37.930] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 6 iter 0 Vana 78 Ia 23.1688 mA
[09:20:38.031] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 6 iter 1 Vana 83 Ia 23.9688 mA
[09:20:38.132] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 7 iter 0 Vana 78 Ia 23.1688 mA
[09:20:38.233] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 7 iter 1 Vana 83 Ia 24.7687 mA
[09:20:38.334] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 7 iter 2 Vana 79 Ia 23.1688 mA
[09:20:38.434] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 7 iter 3 Vana 84 Ia 25.5688 mA
[09:20:38.535] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 7 iter 4 Vana 76 Ia 23.1688 mA
[09:20:38.635] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 7 iter 5 Vana 81 Ia 24.7687 mA
[09:20:38.736] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 7 iter 6 Vana 77 Ia 23.1688 mA
[09:20:38.837] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 7 iter 7 Vana 82 Ia 25.5688 mA
[09:20:38.937] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 7 iter 8 Vana 74 Ia 22.3687 mA
[09:20:39.038] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 7 iter 9 Vana 84 Ia 25.5688 mA
[09:20:39.139] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 7 iter 10 Vana 76 Ia 23.1688 mA
[09:20:39.240] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 7 iter 11 Vana 81 Ia 24.7687 mA
[09:20:39.341] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 8 iter 0 Vana 78 Ia 21.5687 mA
[09:20:39.442] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 8 iter 1 Vana 93 Ia 25.5688 mA
[09:20:39.543] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 8 iter 2 Vana 85 Ia 23.9688 mA
[09:20:39.645] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 9 iter 0 Vana 78 Ia 24.7687 mA
[09:20:39.745] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 9 iter 1 Vana 74 Ia 23.9688 mA
[09:20:39.846] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 10 iter 0 Vana 78 Ia 24.7687 mA
[09:20:39.947] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 10 iter 1 Vana 74 Ia 23.9688 mA
[09:20:40.049] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 11 iter 0 Vana 78 Ia 21.5687 mA
[09:20:40.150] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 11 iter 1 Vana 93 Ia 24.7687 mA
[09:20:40.250] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 11 iter 2 Vana 89 Ia 23.9688 mA
[09:20:40.352] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 12 iter 0 Vana 78 Ia 22.3687 mA
[09:20:40.453] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 12 iter 1 Vana 88 Ia 24.7687 mA
[09:20:40.553] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 12 iter 2 Vana 84 Ia 23.9688 mA
[09:20:40.655] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 13 iter 0 Vana 78 Ia 23.1688 mA
[09:20:40.756] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 13 iter 1 Vana 83 Ia 23.9688 mA
[09:20:40.857] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 14 iter 0 Vana 78 Ia 23.9688 mA
[09:20:40.959] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 15 iter 0 Vana 78 Ia 23.1688 mA
[09:20:41.060] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 15 iter 1 Vana 83 Ia 24.7687 mA
[09:20:41.160] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 15 iter 2 Vana 79 Ia 23.1688 mA
[09:20:41.261] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 15 iter 3 Vana 84 Ia 24.7687 mA
[09:20:41.361] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 15 iter 4 Vana 80 Ia 23.1688 mA
[09:20:41.462] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 15 iter 5 Vana 85 Ia 24.7687 mA
[09:20:41.563] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 15 iter 6 Vana 81 Ia 23.9688 mA
[09:20:41.608] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 0 Vana 73
[09:20:41.608] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 1 Vana 78
[09:20:41.608] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 2 Vana 80
[09:20:41.608] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 3 Vana 86
[09:20:41.609] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 4 Vana 78
[09:20:41.609] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 5 Vana 91
[09:20:41.609] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 6 Vana 83
[09:20:41.609] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 7 Vana 81
[09:20:41.609] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 8 Vana 85
[09:20:41.609] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 9 Vana 74
[09:20:41.610] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 10 Vana 74
[09:20:41.610] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 11 Vana 89
[09:20:41.610] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 12 Vana 84
[09:20:41.610] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 13 Vana 83
[09:20:41.610] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 14 Vana 78
[09:20:41.610] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 15 Vana 81
[09:20:41.713] INFO: PixTestPretest::setVana() done, Module Ia 383.5 mA = 23.9688 mA/ROC
[09:20:41.714] INFO: ----------------------------------------------------------------------
[09:20:41.714] INFO: PixTestPreTest::setTimings()
[09:20:41.714] INFO: ----------------------------------------------------------------------
[09:20:41.714] DEBUG: <PixTestPretest.cc/setTimings:L392> Testing Timing: Attempt #1
[09:20:42.679] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:20:42.679] INFO: Decoding statistics:
[09:20:42.679] INFO: General information:
[09:20:42.680] INFO: 16bit words read: 120
[09:20:42.680] INFO: valid events total: 10
[09:20:42.680] INFO: empty events: 10
[09:20:42.680] INFO: valid events with pixels: 0
[09:20:42.680] INFO: valid pixel hits: 0
[09:20:42.680] INFO: Event errors: 0
[09:20:42.680] INFO: start marker: 0
[09:20:42.680] INFO: stop marker: 0
[09:20:42.680] INFO: overflow: 0
[09:20:42.680] INFO: invalid 5bit words: 0
[09:20:42.680] INFO: invalid XOR eye diagram: 0
[09:20:42.680] INFO: TBM errors: 0
[09:20:42.680] INFO: flawed TBM headers: 0
[09:20:42.680] INFO: flawed TBM trailers: 0
[09:20:42.680] INFO: event ID mismatches: 0
[09:20:42.680] INFO: ROC errors: 0
[09:20:42.680] INFO: missing ROC header(s): 0
[09:20:42.680] INFO: misplaced readback start: 0
[09:20:42.680] INFO: Pixel decoding errors: 0
[09:20:42.680] INFO: pixel data incomplete: 0
[09:20:42.680] INFO: pixel address: 0
[09:20:42.680] INFO: pulse height fill bit: 0
[09:20:42.680] INFO: buffer corruption: 0
[09:20:42.680] INFO: ----------------------------------------------------------------------
[09:20:42.680] INFO: Default timings are good. No timing scan needed.
[09:20:42.680] INFO: ----------------------------------------------------------------------
[09:20:42.680] INFO: Test took 966 ms.
[09:20:42.680] INFO: PixTestPretest::setTimings() done.
[09:20:42.872] INFO: ----------------------------------------------------------------------
[09:20:42.872] INFO: PixTestPretest::findWorkingPixel()
[09:20:42.872] INFO: ----------------------------------------------------------------------
[09:20:50.126] INFO: Test took 7251ms.
[09:20:50.362] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C0 OK, with vthrComp = 57 and Delta(CalDel) = 60
[09:20:50.365] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C1 OK, with vthrComp = 87 and Delta(CalDel) = 63
[09:20:50.367] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C2 OK, with vthrComp = 79 and Delta(CalDel) = 61
[09:20:50.369] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C3 OK, with vthrComp = 90 and Delta(CalDel) = 61
[09:20:50.371] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C4 OK, with vthrComp = 104 and Delta(CalDel) = 59
[09:20:50.377] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C5 OK, with vthrComp = 96 and Delta(CalDel) = 61
[09:20:50.380] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C6 OK, with vthrComp = 104 and Delta(CalDel) = 59
[09:20:50.383] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C7 OK, with vthrComp = 126 and Delta(CalDel) = 61
[09:20:50.386] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C8 OK, with vthrComp = 93 and Delta(CalDel) = 61
[09:20:50.388] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C9 OK, with vthrComp = 92 and Delta(CalDel) = 56
[09:20:50.391] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C10 OK, with vthrComp = 84 and Delta(CalDel) = 61
[09:20:50.393] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C11 OK, with vthrComp = 73 and Delta(CalDel) = 67
[09:20:50.397] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C12 OK, with vthrComp = 88 and Delta(CalDel) = 62
[09:20:50.399] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C13 OK, with vthrComp = 84 and Delta(CalDel) = 58
[09:20:50.402] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C14 OK, with vthrComp = 97 and Delta(CalDel) = 60
[09:20:50.404] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C15 OK, with vthrComp = 88 and Delta(CalDel) = 60
[09:20:50.430] INFO: Found working pixel in all ROCs: col/row = 12/22
[09:20:50.481] INFO: ----------------------------------------------------------------------
[09:20:50.481] INFO: PixTestPretest::setVthrCompCalDel()
[09:20:50.481] INFO: ----------------------------------------------------------------------
[09:20:57.722] INFO: Test took 7235ms.
[09:20:57.780] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 113 +/- 29.5
[09:20:57.953] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 137 +/- 32
[09:20:57.956] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 133 +/- 30.5
[09:20:57.958] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 123 +/- 30.5
[09:20:57.960] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 108 +/- 29
[09:20:57.962] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 105 +/- 28
[09:20:57.965] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 119 +/- 29.5
[09:20:57.967] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 114 +/- 30.5
[09:20:57.969] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 114 +/- 30
[09:20:57.971] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 101 +/- 26.5
[09:20:57.973] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 136 +/- 29.5
[09:20:57.976] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 155 +/- 32.5
[09:20:57.978] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 135 +/- 30
[09:20:57.980] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 118 +/- 28.5
[09:20:57.983] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 125 +/- 30.5
[09:20:57.985] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 132 +/- 30
[09:20:58.036] INFO: PixTestPretest::setVthrCompCalDel() done
[09:20:58.036] INFO: CalDel: 113 137 133 123 108 105 119 114 114 101 136 155 135 118 125 132
[09:20:58.036] INFO: VthrComp: 51 51 51 51 51 51 51 51 51 51 51 51 51 51 51 51
[09:20:58.039] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters_C0.dat
[09:20:58.039] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters_C1.dat
[09:20:58.039] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters_C2.dat
[09:20:58.040] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters_C3.dat
[09:20:58.040] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters_C4.dat
[09:20:58.040] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters_C5.dat
[09:20:58.040] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters_C6.dat
[09:20:58.040] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters_C7.dat
[09:20:58.040] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters_C8.dat
[09:20:58.040] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters_C9.dat
[09:20:58.040] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters_C10.dat
[09:20:58.040] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters_C11.dat
[09:20:58.041] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters_C12.dat
[09:20:58.041] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters_C13.dat
[09:20:58.041] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters_C14.dat
[09:20:58.041] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters_C15.dat
[09:20:58.041] INFO: PixTestPretest::doTest() done, duration: 41 seconds
[09:20:58.041] DEBUG: <PixTestPretest.cc/~PixTestPretest:L134> PixTestPretest dtor
[09:20:58.115] INFO: enter test to run
[09:20:58.115] INFO: test: Fulltest no parameter change
[09:20:58.115] INFO: running: fulltest
[09:20:58.115] DEBUG: <PixTestFullTest.cc/init:L49> PixTestFullTest::init()
[09:20:58.115] DEBUG: <PixTestFullTest.cc/PixTestFullTest:L20> PixTestFullTest ctor(PixSetup &a, string, TGTab *)
[09:20:58.115] INFO: ######################################################################
[09:20:58.115] INFO: PixTestFullTest::doTest()
[09:20:58.115] INFO: ######################################################################
[09:20:58.115] DEBUG: <PixTestAlive.cc/init:L77> PixTestAlive::init()
[09:20:58.115] DEBUG: <PixTestAlive.cc/PixTestAlive:L21> PixTestAlive ctor(PixSetup &a, string, TGTab *)
[09:20:58.117] INFO: ######################################################################
[09:20:58.117] INFO: PixTestAlive::doTest()
[09:20:58.117] INFO: ######################################################################
[09:20:58.119] INFO: ----------------------------------------------------------------------
[09:20:58.119] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[09:20:58.119] INFO: ----------------------------------------------------------------------
[09:20:58.121] DEBUG: <PixTest.cc/efficiencyMaps:L328> attempt #0
[09:21:01.841] INFO: Test took 3720ms.
[09:21:01.860] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:21:01.860] DEBUG: <PixTest.cc/efficiencyMaps:L339> eff result size = 66544
[09:21:01.860] DEBUG: <PixTest.cc/efficiencyMaps:L344> Create hists PixelAlive_C0 .. PixelAlive_C15
[09:21:02.100] INFO: PixTestAlive::aliveTest() done
[09:21:02.100] INFO: number of dead pixels (per ROC): 1 0 0 1 0 0 0 2 2 1 0 1 0 0 5 3
[09:21:02.100] DEBUG: <PixTestAlive.cc/aliveTest:L188> number of red-efficiency pixels: 1 0 0 1 0 0 0 2 2 1 0 1 0 0 5 3
[09:21:02.102] INFO: ----------------------------------------------------------------------
[09:21:02.102] INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[09:21:02.102] INFO: ----------------------------------------------------------------------
[09:21:02.104] DEBUG: <PixTest.cc/efficiencyMaps:L328> attempt #0
[09:21:04.768] INFO: Test took 2664ms.
[09:21:04.769] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:21:04.769] DEBUG: <PixTest.cc/efficiencyMaps:L339> eff result size = 0
[09:21:04.769] DEBUG: <PixTest.cc/efficiencyMaps:L344> Create hists MaskTest_C0 .. MaskTest_C15
[09:21:04.770] INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C15_V0
[09:21:05.010] INFO: PixTestAlive::maskTest() done
[09:21:05.010] INFO: number of mask-defect pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[09:21:05.012] INFO: ----------------------------------------------------------------------
[09:21:05.012] INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[09:21:05.012] INFO: ----------------------------------------------------------------------
[09:21:05.014] DEBUG: <PixTest.cc/efficiencyMaps:L328> attempt #0
[09:21:08.727] INFO: Test took 3713ms.
[09:21:08.748] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:21:08.748] DEBUG: <PixTest.cc/efficiencyMaps:L339> eff result size = 66544
[09:21:08.748] DEBUG: <PixTest.cc/efficiencyMaps:L344> Create hists AddressDecodingTest_C0 .. AddressDecodingTest_C15
[09:21:08.990] INFO: PixTestAlive::addressDecodingTest() done
[09:21:08.990] INFO: number of address-decoding pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[09:21:08.990] INFO: PixTestAlive::doTest() done, duration: 10 seconds
[09:21:08.990] DEBUG: <PixTestAlive.cc/~PixTestAlive:L109> PixTestAlive dtor
[09:21:08.995] DEBUG: <PixTestBBMap.cc/init:L79> PixTestBBMap::init()
[09:21:08.995] DEBUG: <PixTestBBMap.cc/PixTestBBMap:L27> PixTestBBMap ctor(PixSetup &a, string, TGTab *)
[09:21:08.997] INFO: ######################################################################
[09:21:08.997] INFO: PixTestBBMap::doTest() Ntrig = 5, VcalS = 250 (high range)
[09:21:08.997] INFO: ######################################################################
[09:21:08.001] INFO: ---> dac: VthrComp name: calSMap ntrig: 5 dacrange: 0 .. 149 (30) hits flags = 2 (plus default)
[09:21:09.013] INFO: dacScan step from 0 .. 29
[09:21:09.013] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:21:26.811] INFO: Test took 17798ms.
[09:21:26.845] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:21:26.845] INFO: dacScan step from 30 .. 59
[09:21:26.845] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:21:45.704] INFO: Test took 18859ms.
[09:21:45.802] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:21:45.816] INFO: dacScan step from 60 .. 89
[09:21:45.816] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:22:09.951] INFO: Test took 24135ms.
[09:22:10.215] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:22:10.292] INFO: dacScan step from 90 .. 119
[09:22:10.293] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:22:34.828] INFO: Test took 24535ms.
[09:22:35.084] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:22:35.169] INFO: dacScan step from 120 .. 149
[09:22:35.169] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:22:58.586] INFO: Test took 23417ms.
[09:22:58.792] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:22:58.830] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[09:23:00.020] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[09:23:01.225] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[09:23:02.418] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[09:23:03.636] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[09:23:04.930] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[09:23:06.218] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[09:23:07.512] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[09:23:08.819] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[09:23:10.013] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[09:23:11.281] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[09:23:12.517] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[09:23:13.708] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[09:23:14.951] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[09:23:16.215] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[09:23:17.752] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[09:23:19.315] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 257744896
[09:23:19.377] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C0_V0
[09:23:19.378] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 76 (obtained for minval = 0) start: 76 .. 90 last peak: 50.4073 last sigma: 4.04198 lcuts[0] = 62.5332 lcuts[1] = 90.8271
[09:23:19.379] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C1_V0
[09:23:19.379] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 87 (obtained for minval = 0) start: 87 .. 106 last peak: 53.1619 last sigma: 5.35183 lcuts[0] = 69.2174 lcuts[1] = 106.68
[09:23:19.380] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C2_V0
[09:23:19.380] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 87 (obtained for minval = 0) start: 87 .. 105 last peak: 54.9031 last sigma: 5.01163 lcuts[0] = 69.938 lcuts[1] = 105.019
[09:23:19.381] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C3_V0
[09:23:19.381] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 95 (obtained for minval = 0) start: 95 .. 114 last peak: 59.3703 last sigma: 5.5018 lcuts[0] = 75.8757 lcuts[1] = 114.388
[09:23:19.382] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C4_V0
[09:23:19.383] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 104 (obtained for minval = 0) start: 104 .. 126 last peak: 61.7417 last sigma: 6.50639 lcuts[0] = 81.2609 lcuts[1] = 126.806
[09:23:19.383] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C5_V0
[09:23:19.384] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 101 (obtained for minval = 0) start: 101 .. 124 last peak: 59.118 last sigma: 6.58531 lcuts[0] = 78.8739 lcuts[1] = 124.971
[09:23:19.384] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C6_V0
[09:23:19.385] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 105 (obtained for minval = 0) start: 105 .. 128 last peak: 61.1145 last sigma: 6.76816 lcuts[0] = 81.419 lcuts[1] = 128.796
[09:23:19.386] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C7_V0
[09:23:19.386] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 115 (obtained for minval = 0) start: 115 .. 141 last peak: 68.1379 last sigma: 7.31321 lcuts[0] = 90.0775 lcuts[1] = 141.27
[09:23:19.387] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C8_V0
[09:23:19.387] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 77 (obtained for minval = 0) start: 77 .. 92 last peak: 49.3575 last sigma: 4.36241 lcuts[0] = 62.4447 lcuts[1] = 92.9816
[09:23:19.388] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C9_V0
[09:23:19.389] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 96 (obtained for minval = 0) start: 96 .. 117 last peak: 58.0394 last sigma: 5.93056 lcuts[0] = 75.8311 lcuts[1] = 117.345
[09:23:19.390] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C10_V0
[09:23:19.391] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 93 (obtained for minval = 0) start: 93 .. 113 last peak: 57.0057 last sigma: 5.65933 lcuts[0] = 73.9837 lcuts[1] = 113.599
[09:23:19.392] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C11_V0
[09:23:19.392] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 88 (obtained for minval = 0) start: 88 .. 106 last peak: 53.961 last sigma: 5.24199 lcuts[0] = 69.6869 lcuts[1] = 106.381
[09:23:19.393] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C12_V0
[09:23:19.393] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 91 (obtained for minval = 0) start: 91 .. 110 last peak: 57.173 last sigma: 5.35675 lcuts[0] = 73.2432 lcuts[1] = 110.74
[09:23:19.394] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C13_V0
[09:23:19.395] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 98 (obtained for minval = 0) start: 98 .. 119 last peak: 59.8495 last sigma: 5.96816 lcuts[0] = 77.754 lcuts[1] = 119.531
[09:23:19.395] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C14_V0
[09:23:19.396] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 98 (obtained for minval = 0) start: 98 .. 120 last peak: 58.4726 last sigma: 6.15711 lcuts[0] = 76.9439 lcuts[1] = 120.044
[09:23:19.396] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C15_V0
[09:23:19.397] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 95 (obtained for minval = 0) start: 95 .. 115 last peak: 56.9669 last sigma: 5.85839 lcuts[0] = 74.5421 lcuts[1] = 115.551
[09:23:19.399] INFO: PixTestBBMap::doTest() done, duration: 130 seconds
[09:23:19.399] INFO: number of dead bumps (per ROC): 4 5 1 0 1 1 1 3 1 2 2 3 4 2 5 0
[09:23:19.399] INFO: separation cut (per ROC): 77 88 88 96 105 102 106 116 78 97 94 89 92 99 99 96
[09:23:19.400] DEBUG: <PixTestBBMap.cc/~PixTestBBMap:L97> PixTestBBMap dtor
[09:23:19.470] DEBUG: <PixTestScurves.cc/setParameter:L92> set fOutputFilename =
[09:23:19.472] INFO: ######################################################################
[09:23:19.473] INFO: PixTestScurves::fullTest() ntrig = 50
[09:23:19.473] INFO: ######################################################################
[09:23:19.474] INFO: ----------------------------------------------------------------------
[09:23:19.474] INFO: PixTestScurves::scurves(Vcal), ntrig = 50
[09:23:19.474] INFO: ----------------------------------------------------------------------
[09:23:19.474] INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 149 (10) hits flags = 16 (plus default)
[09:23:19.484] INFO: dacScan step from 0 .. 9
[09:23:19.485] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:23:53.699] INFO: Test took 34214ms.
[09:23:53.768] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:23:53.768] INFO: dacScan step from 10 .. 19
[09:23:53.768] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:24:28.153] INFO: Test took 34385ms.
[09:24:28.221] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:24:28.221] INFO: dacScan step from 20 .. 29
[09:24:28.221] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:25:02.740] INFO: Test took 34519ms.
[09:25:02.806] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:25:02.806] INFO: dacScan step from 30 .. 39
[09:25:02.806] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:25:37.188] INFO: Test took 34382ms.
[09:25:37.255] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:25:37.255] INFO: dacScan step from 40 .. 49
[09:25:37.255] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:26:11.734] INFO: Test took 34479ms.
[09:26:11.801] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:26:11.801] INFO: dacScan step from 50 .. 59
[09:26:11.801] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:26:46.271] INFO: Test took 34470ms.
[09:26:46.337] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:26:46.337] INFO: dacScan step from 60 .. 69
[09:26:46.338] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:27:20.935] INFO: Test took 34597ms.
[09:27:21.007] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:27:21.007] INFO: dacScan step from 70 .. 79
[09:27:21.007] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:27:55.449] INFO: Test took 34442ms.
[09:27:55.525] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:27:55.525] INFO: dacScan step from 80 .. 89
[09:27:55.526] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:28:30.907] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (14) != Token Chain Length (8)
[09:28:30.907] ERROR: <datapipe.cc/CheckEventID:L420> Channel 1 Event ID mismatch: local ID (74) != TBM ID (75)
[09:28:30.907] WARNING: Channel 1 ROC 1: Readback start marker after 15 readouts!
[09:28:30.907] WARNING: Channel 1 ROC 2: Readback start marker after 15 readouts!
[09:28:30.907] WARNING: Channel 1 ROC 3: Readback start marker after 15 readouts!
[09:28:30.907] WARNING: Channel 1 ROC 4: Readback start marker after 15 readouts!
[09:28:30.908] WARNING: Channel 1 ROC 5: Readback start marker after 15 readouts!
[09:28:30.908] WARNING: Channel 1 ROC 6: Readback start marker after 15 readouts!
[09:28:30.908] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!
[09:28:31.401] INFO: Test took 35875ms.
[09:28:31.556] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:28:31.560] INFO: dacScan step from 90 .. 99
[09:28:31.560] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:29:07.198] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (4) != Token Chain Length (8)
[09:29:07.201] WARNING: Channel 1 ROC 5: Readback start marker after 15 readouts!
[09:29:07.201] WARNING: Channel 1 ROC 6: Readback start marker after 15 readouts!
[09:29:07.201] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!
[09:29:11.493] INFO: Test took 39933ms.
[09:29:11.771] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:29:11.783] INFO: dacScan step from 100 .. 109
[09:29:11.783] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:29:46.115] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (14) != Token Chain Length (8)
[09:29:46.116] ERROR: <datapipe.cc/CheckEventID:L420> Channel 1 Event ID mismatch: local ID (29) != TBM ID (30)
[09:29:46.116] WARNING: Channel 1 ROC 1: Readback start marker after 15 readouts!
[09:29:46.116] WARNING: Channel 1 ROC 2: Readback start marker after 15 readouts!
[09:29:46.116] WARNING: Channel 1 ROC 3: Readback start marker after 15 readouts!
[09:29:46.116] WARNING: Channel 1 ROC 4: Readback start marker after 15 readouts!
[09:29:46.116] WARNING: Channel 1 ROC 5: Readback start marker after 15 readouts!
[09:29:46.116] WARNING: Channel 1 ROC 6: Readback start marker after 15 readouts!
[09:29:46.116] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!
[09:29:59.982] INFO: Test took 48199ms.
[09:30:00.476] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:30:00.504] INFO: dacScan step from 110 .. 119
[09:30:00.504] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:30:31.131] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (6) != Token Chain Length (8)
[09:30:31.131] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!
[09:30:52.817] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (4) != Token Chain Length (8)
[09:30:52.817] WARNING: Channel 1 ROC 5: Readback start marker after 15 readouts!
[09:30:52.817] WARNING: Channel 1 ROC 6: Readback start marker after 15 readouts!
[09:30:52.817] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!
[09:30:56.732] INFO: Test took 56228ms.
[09:30:57.323] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:30:57.354] INFO: dacScan step from 120 .. 129
[09:30:57.354] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:31:27.650] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (6) != Token Chain Length (8)
[09:31:27.650] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!
[09:31:49.915] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (4) != Token Chain Length (8)
[09:31:49.916] WARNING: Channel 1 ROC 5: Readback start marker after 15 readouts!
[09:31:49.916] WARNING: Channel 1 ROC 6: Readback start marker after 15 readouts!
[09:31:49.916] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!
[09:31:55.580] INFO: Test took 58226ms.
[09:31:56.152] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:31:56.181] INFO: dacScan step from 130 .. 139
[09:31:56.182] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:32:26.803] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (4) != Token Chain Length (8)
[09:32:26.804] WARNING: Channel 1 ROC 5: Readback start marker after 15 readouts!
[09:32:26.804] WARNING: Channel 1 ROC 6: Readback start marker after 15 readouts!
[09:32:26.804] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!
[09:32:48.572] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (4) != Token Chain Length (8)
[09:32:48.572] WARNING: Channel 1 ROC 5: Readback start marker after 31 readouts!
[09:32:48.572] WARNING: Channel 1 ROC 6: Readback start marker after 31 readouts!
[09:32:48.572] WARNING: Channel 1 ROC 7: Readback start marker after 31 readouts!
[09:32:54.374] INFO: Test took 58192ms.
[09:32:54.935] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:32:54.964] INFO: dacScan step from 140 .. 149
[09:32:54.964] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:33:24.865] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (14) != Token Chain Length (8)
[09:33:24.865] ERROR: <datapipe.cc/CheckEventID:L420> Channel 1 Event ID mismatch: local ID (155) != TBM ID (156)
[09:33:24.865] WARNING: Channel 1 ROC 1: Readback start marker after 15 readouts!
[09:33:24.865] WARNING: Channel 1 ROC 2: Readback start marker after 15 readouts!
[09:33:24.865] WARNING: Channel 1 ROC 3: Readback start marker after 15 readouts!
[09:33:24.865] WARNING: Channel 1 ROC 4: Readback start marker after 15 readouts!
[09:33:24.865] WARNING: Channel 1 ROC 5: Readback start marker after 15 readouts!
[09:33:24.865] WARNING: Channel 1 ROC 6: Readback start marker after 15 readouts!
[09:33:24.865] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!
[09:33:47.051] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (6) != Token Chain Length (8)
[09:33:47.051] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!
[09:33:52.894] INFO: Test took 57930ms.
[09:33:53.469] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:33:53.500] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[09:33:53.500] INFO: dumping ASCII scurve output file: SCurveData
[09:33:54.787] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[09:33:54.787] INFO: dumping ASCII scurve output file: SCurveData
[09:33:56.041] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[09:33:56.041] INFO: dumping ASCII scurve output file: SCurveData
[09:33:57.310] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[09:33:57.311] INFO: dumping ASCII scurve output file: SCurveData
[09:33:58.561] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[09:33:58.561] INFO: dumping ASCII scurve output file: SCurveData
[09:33:59.803] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[09:33:59.803] INFO: dumping ASCII scurve output file: SCurveData
[09:34:01.051] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[09:34:01.051] INFO: dumping ASCII scurve output file: SCurveData
[09:34:02.299] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[09:34:02.299] INFO: dumping ASCII scurve output file: SCurveData
[09:34:03.506] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[09:34:03.507] INFO: dumping ASCII scurve output file: SCurveData
[09:34:04.752] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[09:34:04.752] INFO: dumping ASCII scurve output file: SCurveData
[09:34:05.970] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[09:34:05.970] INFO: dumping ASCII scurve output file: SCurveData
[09:34:07.187] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[09:34:07.187] INFO: dumping ASCII scurve output file: SCurveData
[09:34:08.476] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[09:34:08.476] INFO: dumping ASCII scurve output file: SCurveData
[09:34:09.801] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[09:34:09.801] INFO: dumping ASCII scurve output file: SCurveData
[09:34:11.206] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[09:34:11.206] INFO: dumping ASCII scurve output file: SCurveData
[09:34:12.776] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[09:34:12.776] INFO: dumping ASCII scurve output file: SCurveData
[09:34:14.183] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 601391104
[09:34:14.238] INFO: PixTestScurves::scurves() done
[09:34:14.238] INFO: Vcal mean: 85.68 100.05 90.44 103.44 104.10 103.49 107.53 111.25 93.51 105.47 110.50 101.54 98.71 107.96 104.00 97.03
[09:34:14.239] INFO: Vcal RMS: 5.76 5.76 5.12 5.17 5.50 5.55 5.18 5.30 6.69 6.05 5.69 6.32 5.20 4.71 6.61 6.67
[09:34:14.240] INFO: PixTestScurves::fullTest() done, duration: 654 seconds
[09:34:14.240] DEBUG: <PixTestScurves.cc/~PixTestScurves:L141> PixTestScurves dtor
[09:34:14.326] INFO: ######################################################################
[09:34:14.326] INFO: PixTestTrim::doTest()
[09:34:14.327] INFO: ######################################################################
[09:34:14.329] INFO: ----------------------------------------------------------------------
[09:34:14.329] INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[09:34:14.329] INFO: ----------------------------------------------------------------------
[09:34:14.401] INFO: ---> VthrComp thr map (minimal VthrComp)
[09:34:14.401] INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 5 dacrange: 0 .. 159 (20) hits flags = 16 (plus default)
[09:34:14.415] INFO: dacScan step from 0 .. 19
[09:34:14.415] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:34:27.037] INFO: Test took 12622ms.
[09:34:27.059] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:34:27.059] INFO: dacScan step from 20 .. 39
[09:34:27.060] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:34:39.663] INFO: Test took 12603ms.
[09:34:39.688] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:34:39.688] INFO: dacScan step from 40 .. 59
[09:34:39.688] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:34:52.274] INFO: Test took 12586ms.
[09:34:52.298] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:34:52.298] INFO: dacScan step from 60 .. 79
[09:34:52.298] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:35:04.890] INFO: Test took 12592ms.
[09:35:04.916] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:35:04.916] INFO: dacScan step from 80 .. 99
[09:35:04.916] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:35:17.710] INFO: Test took 12794ms.
[09:35:17.753] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:35:17.755] INFO: dacScan step from 100 .. 119
[09:35:17.756] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:35:32.467] INFO: Test took 14711ms.
[09:35:32.599] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:35:32.622] INFO: dacScan step from 120 .. 139
[09:35:32.622] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:35:49.752] INFO: Test took 17130ms.
[09:35:49.903] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:35:49.932] INFO: dacScan step from 140 .. 159
[09:35:49.932] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:36:03.560] INFO: Test took 13628ms.
[09:36:03.639] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:36:03.648] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[09:36:04.745] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[09:36:05.897] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[09:36:07.042] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[09:36:08.198] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[09:36:09.462] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[09:36:10.712] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[09:36:11.966] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[09:36:13.224] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[09:36:14.383] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[09:36:15.641] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[09:36:16.807] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[09:36:17.944] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[09:36:19.124] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[09:36:20.334] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[09:36:21.551] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[09:36:22.749] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 601583616
[09:36:22.751] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 82.3115 minThrLimit = 82.3023 minThrNLimit = 100.004 -> result = 82.3115 -> 82
[09:36:22.751] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 93.6554 minThrLimit = 93.5874 minThrNLimit = 111.468 -> result = 93.6554 -> 93
[09:36:22.752] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 88.9123 minThrLimit = 88.8277 minThrNLimit = 108.405 -> result = 88.9123 -> 88
[09:36:22.752] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 98.6085 minThrLimit = 98.6007 minThrNLimit = 115.445 -> result = 98.6085 -> 98
[09:36:22.752] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 105.286 minThrLimit = 105.197 minThrNLimit = 132.678 -> result = 105.286 -> 105
[09:36:22.753] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 104.788 minThrLimit = 104.751 minThrNLimit = 130.528 -> result = 104.788 -> 104
[09:36:22.753] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 105.597 minThrLimit = 105.424 minThrNLimit = 130.938 -> result = 105.597 -> 105
[09:36:22.753] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 110.568 minThrLimit = 110.529 minThrNLimit = 137.558 -> result = 110.568 -> 110
[09:36:22.753] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 91.213 minThrLimit = 91.2071 minThrNLimit = 110.759 -> result = 91.213 -> 91
[09:36:22.754] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 100.915 minThrLimit = 100.874 minThrNLimit = 122.734 -> result = 100.915 -> 100
[09:36:22.754] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 94.9835 minThrLimit = 94.9689 minThrNLimit = 115.644 -> result = 94.9835 -> 94
[09:36:22.754] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 93.583 minThrLimit = 93.581 minThrNLimit = 110.065 -> result = 93.583 -> 93
[09:36:22.755] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 98.2376 minThrLimit = 98.2162 minThrNLimit = 117.989 -> result = 98.2376 -> 98
[09:36:22.755] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 102.926 minThrLimit = 102.914 minThrNLimit = 124.091 -> result = 102.926 -> 102
[09:36:22.755] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 101.712 minThrLimit = 101.655 minThrNLimit = 123.065 -> result = 101.712 -> 101
[09:36:22.756] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 97.1835 minThrLimit = 97.1542 minThrNLimit = 119.011 -> result = 97.1835 -> 97
[09:36:22.756] INFO: ROC 0 VthrComp = 82
[09:36:22.756] INFO: ROC 1 VthrComp = 93
[09:36:22.756] INFO: ROC 2 VthrComp = 88
[09:36:22.756] INFO: ROC 3 VthrComp = 98
[09:36:22.756] INFO: ROC 4 VthrComp = 105
[09:36:22.757] INFO: ROC 5 VthrComp = 104
[09:36:22.757] INFO: ROC 6 VthrComp = 105
[09:36:22.757] INFO: ROC 7 VthrComp = 110
[09:36:22.757] INFO: ROC 8 VthrComp = 91
[09:36:22.757] INFO: ROC 9 VthrComp = 100
[09:36:22.758] INFO: ROC 10 VthrComp = 94
[09:36:22.758] INFO: ROC 11 VthrComp = 93
[09:36:22.758] INFO: ROC 12 VthrComp = 98
[09:36:22.758] INFO: ROC 13 VthrComp = 102
[09:36:22.758] INFO: ROC 14 VthrComp = 101
[09:36:22.758] INFO: ROC 15 VthrComp = 97
[09:36:22.759] INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[09:36:22.759] INFO: ---> dac: vcal name: TrimThr1 ntrig: 5 dacrange: 0 .. 159 (20) hits flags = 16 (plus default)
[09:36:22.769] INFO: dacScan step from 0 .. 19
[09:36:22.770] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:36:35.123] INFO: Test took 12353ms.
[09:36:35.145] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:36:35.145] INFO: dacScan step from 20 .. 39
[09:36:35.146] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:36:47.567] INFO: Test took 12421ms.
[09:36:47.598] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:36:47.600] INFO: dacScan step from 40 .. 59
[09:36:47.601] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:37:02.792] INFO: Test took 15191ms.
[09:37:02.943] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:37:02.978] INFO: dacScan step from 60 .. 79
[09:37:02.978] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:37:19.996] INFO: Test took 17018ms.
[09:37:20.162] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:37:20.216] INFO: dacScan step from 80 .. 99
[09:37:20.216] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:37:37.278] INFO: Test took 17062ms.
[09:37:37.441] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:37:37.495] INFO: dacScan step from 100 .. 119
[09:37:37.496] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:37:54.529] INFO: Test took 17033ms.
[09:37:54.694] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:37:54.751] INFO: dacScan step from 120 .. 139
[09:37:54.751] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:38:13.368] INFO: Test took 18617ms.
[09:38:13.532] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:38:13.588] INFO: dacScan step from 140 .. 159
[09:38:13.588] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:38:30.748] INFO: Test took 17160ms.
[09:38:30.910] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:38:30.966] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[09:38:32.356] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[09:38:33.745] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[09:38:35.112] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[09:38:36.490] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[09:38:37.883] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[09:38:39.293] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[09:38:40.717] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[09:38:42.133] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[09:38:43.550] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[09:38:44.980] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[09:38:46.466] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[09:38:47.905] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[09:38:49.329] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[09:38:50.747] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[09:38:52.154] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[09:38:53.562] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 601583616
[09:38:53.564] INFO: roc 0 with ID = 0 has maximal Vcal 59.6796 for pixel 2/39 mean/min/max = 45.8125/31.8416/59.7835
[09:38:53.565] INFO: roc 1 with ID = 1 has maximal Vcal 63.3628 for pixel 24/79 mean/min/max = 48.3442/33.3159/63.3725
[09:38:53.565] INFO: roc 2 with ID = 2 has maximal Vcal 59.1559 for pixel 51/79 mean/min/max = 46.8594/34.4564/59.2624
[09:38:53.565] INFO: roc 3 with ID = 3 has maximal Vcal 57.8509 for pixel 25/4 mean/min/max = 45.1506/32.2438/58.0575
[09:38:53.565] INFO: roc 4 with ID = 4 has maximal Vcal 60.6232 for pixel 21/73 mean/min/max = 47.1647/33.6953/60.6341
[09:38:53.566] INFO: roc 5 with ID = 5 has maximal Vcal 61.7217 for pixel 24/67 mean/min/max = 47.8766/34.0195/61.7336
[09:38:53.566] INFO: roc 6 with ID = 6 has maximal Vcal 61.9161 for pixel 30/1 mean/min/max = 48.1125/34.2569/61.9682
[09:38:53.566] INFO: roc 7 with ID = 7 has maximal Vcal 60.6316 for pixel 51/1 mean/min/max = 47.7239/34.8078/60.6399
[09:38:53.567] INFO: roc 8 with ID = 8 has maximal Vcal 60.9647 for pixel 12/79 mean/min/max = 46.6719/32.2194/61.1245
[09:38:53.567] INFO: roc 9 with ID = 9 has maximal Vcal 62.7791 for pixel 0/12 mean/min/max = 47.6963/32.4132/62.9793
[09:38:53.567] INFO: roc 10 with ID = 10 has maximal Vcal 69.4391 for pixel 23/0 mean/min/max = 53.3691/37.264/69.4741
[09:38:53.567] INFO: roc 11 with ID = 11 has maximal Vcal 63.4214 for pixel 27/6 mean/min/max = 48.0293/32.6089/63.4497
[09:38:53.568] INFO: roc 12 with ID = 12 has maximal Vcal 56.8373 for pixel 11/21 mean/min/max = 44.661/31.8302/57.4918
[09:38:53.568] INFO: roc 13 with ID = 13 has maximal Vcal 58.9726 for pixel 25/1 mean/min/max = 46.2657/33.5065/59.0249
[09:38:53.568] INFO: roc 14 with ID = 14 has maximal Vcal 61.1262 for pixel 12/3 mean/min/max = 46.9287/32.3942/61.4632
[09:38:53.568] INFO: roc 15 with ID = 15 has maximal Vcal 60.3134 for pixel 15/78 mean/min/max = 45.5966/30.8623/60.3309
[09:38:53.569] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[09:40:08.697] INFO: Test took 75128ms.
[09:40:09.462] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.1538 < 35 for itrim = 91; old thr = 33.2399 ... break
[09:40:09.483] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.0944 < 35 for itrim = 117; old thr = 34.3446 ... break
[09:40:09.504] DEBUG: <PixTestTrim.cc/trimTest:L309> vtrim: vcal = 37.3309 < 35 for itrim+1 = 94; old thr = 34.5784 ... break
[09:40:09.526] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.4843 < 35 for itrim = 108; old thr = 33.7263 ... break
[09:40:09.561] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 36.2188 < 35 for itrim = 123; old thr = 33.6168 ... break
[09:40:09.592] DEBUG: <PixTestTrim.cc/trimTest:L309> vtrim: vcal = 35.6182 < 35 for itrim+1 = 126; old thr = 34.6018 ... break
[09:40:09.623] DEBUG: <PixTestTrim.cc/trimTest:L309> vtrim: vcal = 36.0179 < 35 for itrim+1 = 119; old thr = 34.3321 ... break
[09:40:09.644] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.2502 < 35 for itrim = 113; old thr = 33.6968 ... break
[09:40:09.668] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.7183 < 35 for itrim = 103; old thr = 34.0147 ... break
[09:40:09.690] DEBUG: <PixTestTrim.cc/trimTest:L309> vtrim: vcal = 35.3198 < 35 for itrim+1 = 112; old thr = 34.6927 ... break
[09:40:09.711] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.1608 < 35 for itrim = 127; old thr = 33.8912 ... break
[09:40:09.734] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.1158 < 35 for itrim = 114; old thr = 34.7033 ... break
[09:40:09.759] DEBUG: <PixTestTrim.cc/trimTest:L309> vtrim: vcal = 36.3533 < 35 for itrim+1 = 106; old thr = 33.7716 ... break
[09:40:09.785] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.3808 < 35 for itrim = 120; old thr = 31.1459 ... break
[09:40:09.815] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.8181 < 35 for itrim = 112; old thr = 33.0621 ... break
[09:40:09.844] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.7903 < 35 for itrim = 113; old thr = 32.7663 ... break
[09:40:09.908] INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 199 (20) hits flags = 16 (plus default)
[09:40:09.918] INFO: dacScan step from 0 .. 19
[09:40:09.918] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:40:28.557] INFO: Test took 18639ms.
[09:40:28.608] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:40:28.610] INFO: dacScan step from 20 .. 39
[09:40:28.610] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:40:51.143] INFO: Test took 22533ms.
[09:40:51.369] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:40:51.402] INFO: dacScan step from 40 .. 59
[09:40:51.402] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:41:18.988] INFO: Test took 27586ms.
[09:41:19.272] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:41:19.328] INFO: dacScan step from 60 .. 79
[09:41:19.328] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:41:46.975] INFO: Test took 27647ms.
[09:41:47.254] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:41:47.309] INFO: dacScan step from 80 .. 99
[09:41:47.309] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:42:15.043] INFO: Test took 27734ms.
[09:42:15.325] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:42:15.380] INFO: dacScan step from 100 .. 119
[09:42:15.380] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:42:43.178] INFO: Test took 27798ms.
[09:42:43.463] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:42:43.516] INFO: dacScan step from 120 .. 139
[09:42:43.516] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:43:12.705] INFO: Test took 29189ms.
[09:43:12.979] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:43:13.032] INFO: dacScan step from 140 .. 159
[09:43:13.033] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:43:40.833] INFO: Test took 27800ms.
[09:43:41.115] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:43:41.169] INFO: dacScan step from 160 .. 179
[09:43:41.169] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:44:08.898] INFO: Test took 27729ms.
[09:44:09.176] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:44:09.231] INFO: dacScan step from 180 .. 199
[09:44:09.231] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:44:37.535] INFO: Test took 28304ms.
[09:44:37.813] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:44:37.869] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[09:44:39.321] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[09:44:40.788] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[09:44:42.225] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[09:44:43.690] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[09:44:45.098] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[09:44:46.538] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[09:44:47.979] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[09:44:49.425] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[09:44:50.874] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[09:44:52.323] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[09:44:53.844] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[09:44:55.299] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[09:44:56.726] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[09:44:58.311] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[09:44:59.738] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[09:45:01.157] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 601612288
[09:45:01.159] INFO: ---> TrimStepCorr4 extremal thresholds: 0.004236 .. 255.000000
[09:45:01.222] INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 4 dacrange: 0 .. 255 (20) hits flags = 16 (plus default)
[09:45:01.231] INFO: dacScan step from 0 .. 19
[09:45:01.231] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:45:12.637] INFO: Test took 11406ms.
[09:45:12.661] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:45:12.661] INFO: dacScan step from 20 .. 39
[09:45:12.661] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:45:24.940] INFO: Test took 12279ms.
[09:45:25.021] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:45:25.037] INFO: dacScan step from 40 .. 59
[09:45:25.038] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:45:39.473] INFO: Test took 14435ms.
[09:45:39.622] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:45:39.675] INFO: dacScan step from 60 .. 79
[09:45:39.675] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:45:54.442] INFO: Test took 14767ms.
[09:45:54.585] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:45:54.640] INFO: dacScan step from 80 .. 99
[09:45:54.640] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:46:09.623] INFO: Test took 14983ms.
[09:46:09.769] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:46:09.826] INFO: dacScan step from 100 .. 119
[09:46:09.826] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:46:24.986] INFO: Test took 15160ms.
[09:46:25.131] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:46:25.185] INFO: dacScan step from 120 .. 139
[09:46:25.185] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:46:41.778] INFO: Test took 16593ms.
[09:46:41.919] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:46:41.975] INFO: dacScan step from 140 .. 159
[09:46:41.975] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:46:57.268] INFO: Test took 15293ms.
[09:46:57.416] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:46:57.471] INFO: dacScan step from 160 .. 179
[09:46:57.471] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:47:12.557] INFO: Test took 15086ms.
[09:47:12.702] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:12.758] INFO: dacScan step from 180 .. 199
[09:47:12.758] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:47:28.587] INFO: Test took 15829ms.
[09:47:28.730] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:28.787] INFO: dacScan step from 200 .. 219
[09:47:28.787] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:47:43.710] INFO: Test took 14923ms.
[09:47:43.855] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:43.912] INFO: dacScan step from 220 .. 239
[09:47:43.912] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:47:58.810] INFO: Test took 14898ms.
[09:47:58.957] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:59.014] INFO: dacScan step from 240 .. 255
[09:47:59.014] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:48:11.495] INFO: Test took 12481ms.
[09:48:11.612] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:48:11.658] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[09:48:13.385] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[09:48:15.114] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[09:48:16.831] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[09:48:18.572] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[09:48:20.315] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[09:48:22.052] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[09:48:23.804] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[09:48:25.542] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[09:48:27.288] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[09:48:29.019] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[09:48:30.807] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[09:48:32.555] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[09:48:34.274] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[09:48:36.002] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[09:48:37.738] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[09:48:39.468] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 601616384
[09:48:39.535] INFO: ---> TrimStepCorr2 extremal thresholds: 15.324542 .. 62.896009
[09:48:39.597] INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 4 dacrange: 5 .. 72 (20) hits flags = 16 (plus default)
[09:48:39.606] INFO: dacScan step from 5 .. 24
[09:48:39.606] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:48:51.033] INFO: Test took 11427ms.
[09:48:51.058] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:48:51.058] INFO: dacScan step from 25 .. 44
[09:48:51.058] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:49:04.105] INFO: Test took 13047ms.
[09:49:04.220] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:49:04.252] INFO: dacScan step from 45 .. 64
[09:49:04.253] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:49:19.131] INFO: Test took 14878ms.
[09:49:19.275] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:49:19.329] INFO: dacScan step from 65 .. 72
[09:49:19.329] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:49:26.703] INFO: Test took 7374ms.
[09:49:26.764] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:49:26.789] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[09:49:27.789] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[09:49:28.789] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[09:49:29.781] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[09:49:30.771] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[09:49:31.764] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[09:49:32.764] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[09:49:33.762] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[09:49:34.762] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[09:49:35.766] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[09:49:36.771] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[09:49:37.913] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[09:49:39.265] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[09:49:40.526] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[09:49:41.665] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[09:49:42.679] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[09:49:43.846] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 601739264
[09:49:43.916] INFO: ---> TrimStepCorr1a extremal thresholds: 1.942726 .. 43.883863
[09:49:43.980] INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 4 dacrange: 1 .. 53 (20) hits flags = 16 (plus default)
[09:49:43.989] INFO: dacScan step from 1 .. 20
[09:49:43.989] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:49:55.221] INFO: Test took 11232ms.
[09:49:55.245] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:49:55.245] INFO: dacScan step from 21 .. 40
[09:49:55.245] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:50:07.600] INFO: Test took 12355ms.
[09:50:07.682] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:50:07.704] INFO: dacScan step from 41 .. 53
[09:50:07.704] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:50:18.194] INFO: Test took 10490ms.
[09:50:18.291] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:50:18.331] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[09:50:19.170] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[09:50:20.003] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[09:50:20.841] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[09:50:21.676] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[09:50:22.514] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[09:50:23.347] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[09:50:24.182] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[09:50:25.015] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[09:50:25.854] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[09:50:26.691] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[09:50:27.526] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[09:50:28.363] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[09:50:29.196] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[09:50:30.037] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[09:50:30.868] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[09:50:31.708] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 601739264
[09:50:31.776] INFO: ---> TrimStepCorr1b extremal thresholds: 0.361900 .. 43.883863
[09:50:31.840] INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 4 dacrange: 0 .. 53 (20) hits flags = 16 (plus default)
[09:50:31.848] INFO: dacScan step from 0 .. 19
[09:50:31.849] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:50:43.228] INFO: Test took 11379ms.
[09:50:43.250] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:50:43.251] INFO: dacScan step from 20 .. 39
[09:50:43.252] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:50:55.368] INFO: Test took 12116ms.
[09:50:55.443] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:50:55.460] INFO: dacScan step from 40 .. 53
[09:50:55.461] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:51:06.709] INFO: Test took 11248ms.
[09:51:06.815] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:51:06.856] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[09:51:07.699] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[09:51:08.549] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[09:51:09.397] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[09:51:10.244] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[09:51:11.096] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[09:51:11.939] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[09:51:12.776] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[09:51:13.614] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[09:51:14.455] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[09:51:15.295] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[09:51:16.136] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[09:51:16.973] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[09:51:17.808] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[09:51:18.644] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[09:51:19.470] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[09:51:20.300] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 601743360
[09:51:20.370] INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[09:51:20.370] INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (20) hits flags = 16 (plus default)
[09:51:20.379] INFO: dacScan step from 15 .. 34
[09:51:20.379] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:51:38.815] INFO: Test took 18436ms.
[09:51:38.893] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:51:38.905] INFO: dacScan step from 35 .. 54
[09:51:38.906] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:52:05.465] INFO: Test took 26559ms.
[09:52:05.759] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:52:05.815] INFO: dacScan step from 55 .. 55
[09:52:05.815] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:52:09.570] INFO: Test took 3755ms.
[09:52:09.592] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:52:09.595] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[09:52:10.385] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[09:52:11.173] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[09:52:11.961] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[09:52:12.747] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[09:52:13.540] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[09:52:14.331] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[09:52:15.119] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[09:52:15.909] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[09:52:16.701] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[09:52:17.495] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[09:52:18.276] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[09:52:19.062] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[09:52:19.839] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[09:52:20.609] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[09:52:21.380] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[09:52:22.155] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 601743360
[09:52:22.209] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C0.dat
[09:52:22.210] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C1.dat
[09:52:22.210] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C2.dat
[09:52:22.210] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C3.dat
[09:52:22.210] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C4.dat
[09:52:22.210] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C5.dat
[09:52:22.210] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C6.dat
[09:52:22.210] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C7.dat
[09:52:22.210] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C8.dat
[09:52:22.210] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C9.dat
[09:52:22.210] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C10.dat
[09:52:22.210] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C11.dat
[09:52:22.211] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C12.dat
[09:52:22.211] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C13.dat
[09:52:22.211] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C14.dat
[09:52:22.211] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C15.dat
[09:52:22.211] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//trimParameters35_C0.dat
[09:52:22.217] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//trimParameters35_C1.dat
[09:52:22.224] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//trimParameters35_C2.dat
[09:52:22.229] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//trimParameters35_C3.dat
[09:52:22.234] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//trimParameters35_C4.dat
[09:52:22.240] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//trimParameters35_C5.dat
[09:52:22.245] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//trimParameters35_C6.dat
[09:52:22.250] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//trimParameters35_C7.dat
[09:52:22.256] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//trimParameters35_C8.dat
[09:52:22.261] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//trimParameters35_C9.dat
[09:52:22.267] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//trimParameters35_C10.dat
[09:52:22.272] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//trimParameters35_C11.dat
[09:52:22.277] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//trimParameters35_C12.dat
[09:52:22.283] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//trimParameters35_C13.dat
[09:52:22.288] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//trimParameters35_C14.dat
[09:52:22.293] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//trimParameters35_C15.dat
[09:52:22.299] INFO: PixTestTrim::trimTest() done
[09:52:22.299] INFO: vtrim: 91 117 94 108 123 126 119 113 103 112 127 114 106 120 112 113
[09:52:22.299] INFO: vthrcomp: 82 93 88 98 105 104 105 110 91 100 94 93 98 102 101 97
[09:52:22.299] INFO: vcal mean: 35.16 35.14 35.16 34.94 35.14 35.15 35.19 35.07 35.08 35.13 35.23 35.15 35.10 35.17 35.08 35.08
[09:52:22.299] INFO: vcal RMS: 1.23 1.22 1.01 1.50 1.03 1.07 1.10 1.33 1.34 1.23 1.59 1.63 1.16 1.14 1.65 1.52
[09:52:22.299] INFO: bits mean: 9.85 9.15 8.24 10.06 9.13 9.10 8.86 8.79 9.45 8.65 7.98 9.81 9.94 10.14 9.74 10.23
[09:52:22.299] INFO: bits RMS: 2.51 2.53 2.79 2.41 2.51 2.45 2.48 2.49 2.61 2.90 2.18 2.32 2.60 2.20 2.49 2.45
[09:52:22.308] INFO: ----------------------------------------------------------------------
[09:52:22.308] INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[09:52:22.308] INFO: ----------------------------------------------------------------------
[09:52:22.313] DEBUG: <PixTestTrim.cc/trimBitTest:L518> trimBitTest determine threshold map without trims
[09:52:22.313] INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (20) hits flags = 16 (plus default)
[09:52:22.322] INFO: dacScan step from 0 .. 19
[09:52:22.322] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:52:40.410] INFO: Test took 18088ms.
[09:52:40.449] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:52:40.450] INFO: dacScan step from 20 .. 39
[09:52:40.451] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:52:58.894] INFO: Test took 18443ms.
[09:52:58.931] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:52:58.931] INFO: dacScan step from 40 .. 59
[09:52:58.931] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:53:17.333] INFO: Test took 18402ms.
[09:53:17.370] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:53:17.370] INFO: dacScan step from 60 .. 79
[09:53:17.370] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:53:35.760] INFO: Test took 18390ms.
[09:53:35.799] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:53:35.799] INFO: dacScan step from 80 .. 99
[09:53:35.799] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:53:53.904] INFO: Test took 18105ms.
[09:53:53.943] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:53:53.943] INFO: dacScan step from 100 .. 119
[09:53:53.943] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:54:12.897] INFO: Test took 18954ms.
[09:54:12.965] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:54:12.970] INFO: dacScan step from 120 .. 139
[09:54:12.970] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:54:36.875] INFO: Test took 23905ms.
[09:54:37.087] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:54:37.116] INFO: dacScan step from 140 .. 159
[09:54:37.116] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:55:04.632] INFO: Test took 27516ms.
[09:55:04.911] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:55:04.965] INFO: dacScan step from 160 .. 179
[09:55:04.965] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:55:32.559] INFO: Test took 27594ms.
[09:55:32.840] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:55:32.896] INFO: dacScan step from 180 .. 199
[09:55:32.896] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:56:01.311] INFO: Test took 28415ms.
[09:56:01.582] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:56:01.639] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[09:56:03.071] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[09:56:04.462] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[09:56:05.880] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[09:56:07.259] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[09:56:08.648] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[09:56:10.040] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[09:56:11.424] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[09:56:12.797] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[09:56:14.211] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[09:56:15.609] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[09:56:16.992] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[09:56:18.366] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[09:56:19.761] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[09:56:21.137] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[09:56:22.508] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[09:56:23.913] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 601759744
[09:56:23.913] DEBUG: <PixTestTrim.cc/trimBitTest:L533> trimBitTest initDUT with trim bits = 14
[09:56:23.976] DEBUG: <PixTestTrim.cc/trimBitTest:L539> trimBitTest threshold map with trim = 14
[09:56:23.976] INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 193 (20) hits flags = 16 (plus default)
[09:56:23.985] INFO: dacScan step from 0 .. 19
[09:56:23.985] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:56:42.109] INFO: Test took 18124ms.
[09:56:42.145] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:56:42.145] INFO: dacScan step from 20 .. 39
[09:56:42.145] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:57:00.501] INFO: Test took 18356ms.
[09:57:00.537] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:57:00.538] INFO: dacScan step from 40 .. 59
[09:57:00.538] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:57:18.899] INFO: Test took 18361ms.
[09:57:18.936] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:57:18.936] INFO: dacScan step from 60 .. 79
[09:57:18.936] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:57:37.387] INFO: Test took 18452ms.
[09:57:37.424] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:57:37.424] INFO: dacScan step from 80 .. 99
[09:57:37.424] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:57:55.718] INFO: Test took 18294ms.
[09:57:55.762] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:57:55.763] INFO: dacScan step from 100 .. 119
[09:57:55.763] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:58:15.623] INFO: Test took 19860ms.
[09:58:15.756] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:15.772] INFO: dacScan step from 120 .. 139
[09:58:15.772] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:58:42.843] INFO: Test took 27071ms.
[09:58:43.118] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:43.163] INFO: dacScan step from 140 .. 159
[09:58:43.163] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:59:10.955] INFO: Test took 27792ms.
[09:59:11.232] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:59:11.289] INFO: dacScan step from 160 .. 179
[09:59:11.289] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[09:59:38.994] INFO: Test took 27705ms.
[09:59:39.271] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:59:39.326] INFO: dacScan step from 180 .. 193
[09:59:39.326] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:00:00.107] INFO: Test took 20781ms.
[10:00:00.297] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:00:00.338] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[10:00:01.728] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[10:00:03.091] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[10:00:04.472] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[10:00:05.819] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[10:00:07.167] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[10:00:08.520] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[10:00:09.860] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[10:00:11.188] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[10:00:12.564] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[10:00:13.909] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[10:00:15.244] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[10:00:16.601] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[10:00:17.967] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[10:00:19.302] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[10:00:20.655] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[10:00:22.026] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 601759744
[10:00:22.027] DEBUG: <PixTestTrim.cc/trimBitTest:L533> trimBitTest initDUT with trim bits = 13
[10:00:22.090] DEBUG: <PixTestTrim.cc/trimBitTest:L539> trimBitTest threshold map with trim = 13
[10:00:22.090] INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 179 (20) hits flags = 16 (plus default)
[10:00:22.099] INFO: dacScan step from 0 .. 19
[10:00:22.099] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:00:40.170] INFO: Test took 18070ms.
[10:00:40.207] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:00:40.207] INFO: dacScan step from 20 .. 39
[10:00:40.207] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:00:58.713] INFO: Test took 18506ms.
[10:00:58.750] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:00:58.750] INFO: dacScan step from 40 .. 59
[10:00:58.750] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:01:17.357] INFO: Test took 18607ms.
[10:01:17.396] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:01:17.396] INFO: dacScan step from 60 .. 79
[10:01:17.396] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:01:35.873] INFO: Test took 18477ms.
[10:01:35.910] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:01:35.910] INFO: dacScan step from 80 .. 99
[10:01:35.911] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:01:54.484] INFO: Test took 18573ms.
[10:01:54.529] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:01:54.529] INFO: dacScan step from 100 .. 119
[10:01:54.529] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:02:14.230] INFO: Test took 19701ms.
[10:02:14.360] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:02:14.376] INFO: dacScan step from 120 .. 139
[10:02:14.376] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:02:41.448] INFO: Test took 27072ms.
[10:02:41.730] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:02:41.777] INFO: dacScan step from 140 .. 159
[10:02:41.777] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:03:09.409] INFO: Test took 27632ms.
[10:03:09.682] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:03:09.738] INFO: dacScan step from 160 .. 179
[10:03:09.739] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:03:37.510] INFO: Test took 27771ms.
[10:03:37.791] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:03:37.844] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[10:03:39.207] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[10:03:40.524] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[10:03:41.862] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[10:03:43.158] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[10:03:44.464] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[10:03:45.772] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[10:03:47.065] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[10:03:48.343] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[10:03:49.670] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[10:03:50.968] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[10:03:52.255] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[10:03:53.565] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[10:03:54.894] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[10:03:56.185] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[10:03:57.494] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[10:03:58.831] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 601759744
[10:03:58.832] DEBUG: <PixTestTrim.cc/trimBitTest:L533> trimBitTest initDUT with trim bits = 11
[10:03:58.896] DEBUG: <PixTestTrim.cc/trimBitTest:L539> trimBitTest threshold map with trim = 11
[10:03:58.897] INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 175 (20) hits flags = 16 (plus default)
[10:03:58.905] INFO: dacScan step from 0 .. 19
[10:03:58.906] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:04:17.355] INFO: Test took 18449ms.
[10:04:17.395] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:04:17.395] INFO: dacScan step from 20 .. 39
[10:04:17.395] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:04:35.420] INFO: Test took 18025ms.
[10:04:35.457] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:04:35.458] INFO: dacScan step from 40 .. 59
[10:04:35.458] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:04:53.890] INFO: Test took 18432ms.
[10:04:53.927] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:04:53.927] INFO: dacScan step from 60 .. 79
[10:04:53.927] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:05:12.356] INFO: Test took 18429ms.
[10:05:12.394] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:05:12.394] INFO: dacScan step from 80 .. 99
[10:05:12.395] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:05:30.976] INFO: Test took 18581ms.
[10:05:31.020] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:05:31.021] INFO: dacScan step from 100 .. 119
[10:05:31.021] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:05:51.272] INFO: Test took 20251ms.
[10:05:51.405] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:05:51.420] INFO: dacScan step from 120 .. 139
[10:05:51.421] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:06:18.137] INFO: Test took 26716ms.
[10:06:18.412] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:06:18.456] INFO: dacScan step from 140 .. 159
[10:06:18.456] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:06:46.383] INFO: Test took 27927ms.
[10:06:46.663] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:06:46.718] INFO: dacScan step from 160 .. 175
[10:06:46.718] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:07:09.354] INFO: Test took 22636ms.
[10:07:09.578] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:07:09.623] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[10:07:10.957] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[10:07:12.247] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[10:07:13.558] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[10:07:14.828] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[10:07:16.108] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[10:07:17.390] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[10:07:18.641] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[10:07:19.866] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[10:07:21.144] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[10:07:22.415] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[10:07:23.659] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[10:07:24.938] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[10:07:26.235] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[10:07:27.485] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[10:07:28.749] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[10:07:30.043] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 601759744
[10:07:30.043] DEBUG: <PixTestTrim.cc/trimBitTest:L533> trimBitTest initDUT with trim bits = 7
[10:07:30.106] DEBUG: <PixTestTrim.cc/trimBitTest:L539> trimBitTest threshold map with trim = 7
[10:07:30.106] INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 176 (20) hits flags = 16 (plus default)
[10:07:30.115] INFO: dacScan step from 0 .. 19
[10:07:30.115] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:07:48.525] INFO: Test took 18410ms.
[10:07:48.564] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:07:48.564] INFO: dacScan step from 20 .. 39
[10:07:48.564] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:08:06.926] INFO: Test took 18362ms.
[10:08:06.963] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:08:06.963] INFO: dacScan step from 40 .. 59
[10:08:06.963] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:08:25.313] INFO: Test took 18350ms.
[10:08:25.350] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:08:25.350] INFO: dacScan step from 60 .. 79
[10:08:25.350] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:08:43.678] INFO: Test took 18328ms.
[10:08:43.715] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:08:43.715] INFO: dacScan step from 80 .. 99
[10:08:43.715] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:09:02.207] INFO: Test took 18492ms.
[10:09:02.259] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:09:02.259] INFO: dacScan step from 100 .. 119
[10:09:02.260] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:09:22.553] INFO: Test took 20293ms.
[10:09:22.691] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:09:22.704] INFO: dacScan step from 120 .. 139
[10:09:22.704] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:09:49.492] INFO: Test took 26788ms.
[10:09:49.762] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:09:49.809] INFO: dacScan step from 140 .. 159
[10:09:49.809] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:10:17.520] INFO: Test took 27711ms.
[10:10:17.793] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:10:17.848] INFO: dacScan step from 160 .. 176
[10:10:17.848] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:10:41.525] INFO: Test took 23677ms.
[10:10:41.762] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:10:41.811] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[10:10:43.141] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[10:10:44.441] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[10:10:45.745] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[10:10:47.009] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[10:10:48.277] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[10:10:49.552] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[10:10:50.814] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[10:10:52.060] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[10:10:53.358] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[10:10:54.615] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[10:10:55.864] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[10:10:57.149] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[10:10:58.426] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[10:10:59.669] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[10:11:00.933] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[10:11:02.217] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 601759744
[10:11:02.218] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 0 step 0: thr difference mean: 11.3217, thr difference RMS: 1.28914
[10:11:02.218] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 1 step 0: thr difference mean: 10.5792, thr difference RMS: 1.01141
[10:11:02.218] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 2 step 0: thr difference mean: 9.37975, thr difference RMS: 1.48982
[10:11:02.219] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 3 step 0: thr difference mean: 11.2918, thr difference RMS: 0.949012
[10:11:02.219] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 4 step 0: thr difference mean: 10.588, thr difference RMS: 1.02316
[10:11:02.219] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 5 step 0: thr difference mean: 9.65963, thr difference RMS: 1.04582
[10:11:02.219] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 6 step 0: thr difference mean: 10.5605, thr difference RMS: 0.984717
[10:11:02.219] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 7 step 0: thr difference mean: 11.2705, thr difference RMS: 1.39637
[10:11:02.220] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 8 step 0: thr difference mean: 10.1004, thr difference RMS: 1.53263
[10:11:02.220] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 9 step 0: thr difference mean: 10.4513, thr difference RMS: 1.09036
[10:11:02.220] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 10 step 0: thr difference mean: 11.481, thr difference RMS: 1.45628
[10:11:02.220] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 11 step 0: thr difference mean: 13.158, thr difference RMS: 1.32316
[10:11:02.220] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 12 step 0: thr difference mean: 10.7308, thr difference RMS: 1.17785
[10:11:02.221] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 13 step 0: thr difference mean: 12.1352, thr difference RMS: 1.16493
[10:11:02.221] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 14 step 0: thr difference mean: 11.9112, thr difference RMS: 1.09103
[10:11:02.221] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 15 step 0: thr difference mean: 10.6892, thr difference RMS: 1.46724
[10:11:02.221] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 0 step 1: thr difference mean: 10.9257, thr difference RMS: 1.29139
[10:11:02.221] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 1 step 1: thr difference mean: 10.2978, thr difference RMS: 0.995728
[10:11:02.222] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 2 step 1: thr difference mean: 9.04508, thr difference RMS: 1.46067
[10:11:02.222] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 3 step 1: thr difference mean: 10.8991, thr difference RMS: 0.929191
[10:11:02.222] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 4 step 1: thr difference mean: 10.4847, thr difference RMS: 1.01464
[10:11:02.222] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 5 step 1: thr difference mean: 9.44796, thr difference RMS: 1.05298
[10:11:02.222] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 6 step 1: thr difference mean: 10.3765, thr difference RMS: 0.987755
[10:11:02.222] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 7 step 1: thr difference mean: 11.1131, thr difference RMS: 1.38396
[10:11:02.223] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 8 step 1: thr difference mean: 10.1278, thr difference RMS: 1.50765
[10:11:02.223] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 9 step 1: thr difference mean: 10.1184, thr difference RMS: 1.09713
[10:11:02.223] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 10 step 1: thr difference mean: 11.067, thr difference RMS: 2.15088
[10:11:02.223] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 11 step 1: thr difference mean: 12.5533, thr difference RMS: 1.24852
[10:11:02.224] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 12 step 1: thr difference mean: 10.3651, thr difference RMS: 1.15311
[10:11:02.224] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 13 step 1: thr difference mean: 11.6051, thr difference RMS: 1.14556
[10:11:02.224] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 14 step 1: thr difference mean: 11.7645, thr difference RMS: 1.05843
[10:11:02.224] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 15 step 1: thr difference mean: 10.3625, thr difference RMS: 1.43766
[10:11:02.224] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 0 step 2: thr difference mean: 11.1816, thr difference RMS: 1.25907
[10:11:02.225] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 1 step 2: thr difference mean: 10.4914, thr difference RMS: 1.01052
[10:11:02.225] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 2 step 2: thr difference mean: 9.21888, thr difference RMS: 1.45619
[10:11:02.225] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 3 step 2: thr difference mean: 10.9517, thr difference RMS: 0.940326
[10:11:02.225] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 4 step 2: thr difference mean: 10.6075, thr difference RMS: 0.988235
[10:11:02.226] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 5 step 2: thr difference mean: 9.66054, thr difference RMS: 1.04145
[10:11:02.226] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 6 step 2: thr difference mean: 10.4553, thr difference RMS: 0.994944
[10:11:02.226] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 7 step 2: thr difference mean: 11.4104, thr difference RMS: 1.38241
[10:11:02.226] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 8 step 2: thr difference mean: 10.3216, thr difference RMS: 1.5223
[10:11:02.226] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 9 step 2: thr difference mean: 10.1515, thr difference RMS: 1.07908
[10:11:02.227] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 10 step 2: thr difference mean: 11.3779, thr difference RMS: 2.51818
[10:11:02.227] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 11 step 2: thr difference mean: 12.7286, thr difference RMS: 1.28413
[10:11:02.227] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 12 step 2: thr difference mean: 10.6122, thr difference RMS: 1.14878
[10:11:02.227] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 13 step 2: thr difference mean: 12.0997, thr difference RMS: 1.1064
[10:11:02.227] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 14 step 2: thr difference mean: 11.9648, thr difference RMS: 1.06594
[10:11:02.228] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 15 step 2: thr difference mean: 10.6425, thr difference RMS: 1.47839
[10:11:02.228] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 0 step 3: thr difference mean: 11.441, thr difference RMS: 1.25009
[10:11:02.228] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 1 step 3: thr difference mean: 10.7225, thr difference RMS: 0.981958
[10:11:02.228] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 2 step 3: thr difference mean: 9.37704, thr difference RMS: 1.45038
[10:11:02.228] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 3 step 3: thr difference mean: 11.0013, thr difference RMS: 0.919083
[10:11:02.228] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 4 step 3: thr difference mean: 10.9197, thr difference RMS: 1.00385
[10:11:02.229] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 5 step 3: thr difference mean: 9.84694, thr difference RMS: 1.01996
[10:11:02.229] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 6 step 3: thr difference mean: 10.6489, thr difference RMS: 0.978899
[10:11:02.229] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 7 step 3: thr difference mean: 11.7111, thr difference RMS: 1.35713
[10:11:02.229] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 8 step 3: thr difference mean: 10.5972, thr difference RMS: 1.51876
[10:11:02.229] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 9 step 3: thr difference mean: 10.3939, thr difference RMS: 1.08153
[10:11:02.230] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 10 step 3: thr difference mean: 11.443, thr difference RMS: 2.47106
[10:11:02.230] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 11 step 3: thr difference mean: 12.8904, thr difference RMS: 1.28789
[10:11:02.230] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 12 step 3: thr difference mean: 10.7962, thr difference RMS: 1.16664
[10:11:02.230] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 13 step 3: thr difference mean: 12.0621, thr difference RMS: 1.13857
[10:11:02.230] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 14 step 3: thr difference mean: 12.2314, thr difference RMS: 1.09003
[10:11:02.230] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 15 step 3: thr difference mean: 10.8762, thr difference RMS: 1.4899
[10:11:02.345] INFO: PixTestTrim::trimBitTest() done
[10:11:02.347] INFO: PixTestTrim::doTest() done, duration: 2208 seconds
[10:11:02.347] DEBUG: <PixTestTrim.cc/~PixTestTrim:L104> PixTestTrim dtor
[10:11:02.936] DEBUG: <PixTest.cc/setTestParameter:L569> setting ntrig to new value 10
[10:11:02.936] DEBUG: <PixTestPhOptimization.cc/setParameter:L37> setting fParNtrig ->10<- from sval = 10
[10:11:02.936] DEBUG: <PixTestPhOptimization.cc/setParameter:L42> setting fSafetyMarginLow ->20<- from sval = 20
[10:11:02.936] DEBUG: <PixTestPhOptimization.cc/setParameter:L48> setting fVcalMax ->100<- from sval = 100
[10:11:02.936] DEBUG: <PixTestPhOptimization.cc/setParameter:L53> setting fQuantMax ->0.98<- from sval = 0.98
[10:11:02.936] INFO: ######################################################################
[10:11:02.936] INFO: PixTestPhOptimization::doTest() Ntrig = 10
[10:11:02.936] INFO: ######################################################################
[10:11:02.938] DEBUG: <PixTest.cc/efficiencyMaps:L328> attempt #0
[10:11:06.648] INFO: Test took 3710ms.
[10:11:06.669] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:11:06.669] DEBUG: <PixTest.cc/efficiencyMaps:L339> eff result size = 66534
[10:11:06.669] DEBUG: <PixTest.cc/efficiencyMaps:L344> Create hists PixelAlive_C0 .. PixelAlive_C15
[10:11:06.672] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [0, 20, 20] has eff 0/10
[10:11:06.672] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [0, 20, 20]
[10:11:06.673] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [1, 33, 42] has eff 0/10
[10:11:06.673] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [1, 33, 42]
[10:11:06.673] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [3, 38, 32] has eff 0/10
[10:11:06.673] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [3, 38, 32]
[10:11:06.673] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [3, 25, 34] has eff 0/10
[10:11:06.673] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [3, 25, 34]
[10:11:06.673] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [3, 44, 56] has eff 0/10
[10:11:06.673] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [3, 44, 56]
[10:11:06.673] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [3, 5, 68] has eff 1/10
[10:11:06.673] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [3, 5, 68]
[10:11:06.673] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [7, 51, 60] has eff 0/10
[10:11:06.673] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [7, 51, 60]
[10:11:06.673] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [7, 51, 63] has eff 0/10
[10:11:06.673] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [7, 51, 63]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [8, 0, 75] has eff 0/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [8, 0, 75]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [8, 1, 79] has eff 0/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [8, 1, 79]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [9, 40, 79] has eff 0/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [9, 40, 79]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [10, 51, 4] has eff 5/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [10, 51, 4]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [10, 49, 6] has eff 9/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [10, 49, 6]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [10, 51, 6] has eff 9/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [10, 51, 6]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [10, 51, 8] has eff 8/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [10, 51, 8]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [10, 51, 9] has eff 0/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [10, 51, 9]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [10, 51, 10] has eff 9/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [10, 51, 10]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [10, 46, 17] has eff 9/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [10, 46, 17]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [10, 51, 22] has eff 9/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [10, 51, 22]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [10, 47, 28] has eff 0/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [10, 47, 28]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [10, 47, 29] has eff 1/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [10, 47, 29]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [10, 51, 29] has eff 9/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [10, 51, 29]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [10, 51, 37] has eff 1/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [10, 51, 37]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [10, 48, 38] has eff 0/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [10, 48, 38]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [11, 37, 22] has eff 0/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [11, 37, 22]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [11, 47, 48] has eff 0/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [11, 47, 48]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [11, 47, 64] has eff 0/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [11, 47, 64]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [11, 38, 77] has eff 2/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [11, 38, 77]
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [11, 8, 79] has eff 0/10
[10:11:06.674] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [11, 8, 79]
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [12, 42, 42] has eff 0/10
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [12, 42, 42]
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [14, 34, 0] has eff 0/10
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [14, 34, 0]
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [14, 37, 0] has eff 0/10
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [14, 37, 0]
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [14, 47, 0] has eff 0/10
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [14, 47, 0]
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [14, 51, 0] has eff 0/10
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [14, 51, 0]
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [14, 50, 1] has eff 0/10
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [14, 50, 1]
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [15, 9, 29] has eff 0/10
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [15, 9, 29]
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [15, 41, 30] has eff 4/10
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [15, 41, 30]
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [15, 49, 44] has eff 3/10
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [15, 49, 44]
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [15, 16, 55] has eff 0/10
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [15, 16, 55]
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [15, 17, 55] has eff 0/10
[10:11:06.675] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [15, 17, 55]
[10:11:06.679] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L239> Number of bad pixels found: 40
[10:11:06.679] DEBUG: <PixTestPhOptimization.cc/doTest:L124> **********Ph range will be optimised on the whole ROC***********
[10:11:06.679] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L276> ROC type is newer than digv2
[10:11:06.679] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L277> ROC type is psi46digv21respin
[10:11:06.869] DEBUG: <PixTest.cc/phMaps:L264> attempt #0
[10:11:10.617] INFO: Test took 3748ms.
[10:11:10.682] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:11:10.682] DEBUG: <PixTest.cc/phMaps:L275> eff result size = 66534
[10:11:10.682] DEBUG: <PixTest.cc/phMaps:L282> Create hists maxphmap_C0 .. maxphmap_C15
[10:11:10.686] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 176.906
[10:11:10.686] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,6] phvalue 176
[10:11:10.686] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 171.756
[10:11:10.686] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,6] phvalue 172
[10:11:10.686] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 178.286
[10:11:10.686] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [6 ,5] phvalue 178
[10:11:10.686] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 169.245
[10:11:10.686] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,5] phvalue 170
[10:11:10.686] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 170.452
[10:11:10.686] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [4 ,5] phvalue 170
[10:11:10.687] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 172.676
[10:11:10.687] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [6 ,15] phvalue 172
[10:11:10.687] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 175.034
[10:11:10.687] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [16 ,9] phvalue 176
[10:11:10.687] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 176.166
[10:11:10.687] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,5] phvalue 176
[10:11:10.687] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 177.589
[10:11:10.687] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,5] phvalue 178
[10:11:10.687] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 184.008
[10:11:10.687] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,15] phvalue 184
[10:11:10.687] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 176.161
[10:11:10.687] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,5] phvalue 176
[10:11:10.687] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 163.204
[10:11:10.687] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,5] phvalue 164
[10:11:10.687] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 183.549
[10:11:10.687] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [6 ,5] phvalue 184
[10:11:10.688] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 182.023
[10:11:10.688] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [4 ,6] phvalue 183
[10:11:10.688] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 172.452
[10:11:10.688] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [6 ,17] phvalue 173
[10:11:10.688] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 178.047
[10:11:10.688] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [6 ,5] phvalue 179
[10:11:10.688] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L427> ROC type is newer than digv2
[10:11:10.688] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L428> ROC type is psi46digv21respin
[10:11:10.688] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L450> init_phScale=150, flag_minPh = 0, minph = 0
[10:11:10.696] DEBUG: <PixTest.cc/phMaps:L264> attempt #0
[10:11:14.452] INFO: Test took 3756ms.
[10:11:14.514] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:11:14.514] DEBUG: <PixTest.cc/phMaps:L275> eff result size = 66534
[10:11:14.514] DEBUG: <PixTest.cc/phMaps:L282> Create hists minphmap_C0 .. minphmap_C15
[10:11:14.518] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L457> result size 0
[10:11:14.518] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L484> done. init_phScale=155, flag_minPh = 1, minph = 50minph_roc = 5
[10:11:14.518] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 77.6587
[10:11:14.518] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [4 ,12] phvalue 78
[10:11:14.518] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 69.9308
[10:11:14.518] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [6 ,13] phvalue 70
[10:11:14.519] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 68.3743
[10:11:14.519] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [3 ,12] phvalue 69
[10:11:14.519] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 62.4238
[10:11:14.519] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [6 ,13] phvalue 63
[10:11:14.519] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 73.9735
[10:11:14.519] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [3 ,14] phvalue 74
[10:11:14.519] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 55.323
[10:11:14.519] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [3 ,50] phvalue 55
[10:11:14.519] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 73.0911
[10:11:14.519] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [3 ,13] phvalue 74
[10:11:14.519] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 67.9757
[10:11:14.519] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [4 ,25] phvalue 68
[10:11:14.519] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 74.0005
[10:11:14.519] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [4 ,50] phvalue 75
[10:11:14.519] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 78.0653
[10:11:14.519] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [7 ,50] phvalue 79
[10:11:14.520] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 70.4513
[10:11:14.520] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [4 ,25] phvalue 70
[10:11:14.520] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 52.5131
[10:11:14.520] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [6 ,12] phvalue 53
[10:11:14.520] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 77.3428
[10:11:14.520] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [3 ,6] phvalue 77
[10:11:14.520] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 78.2719
[10:11:14.520] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [3 ,25] phvalue 79
[10:11:14.520] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 64.1152
[10:11:14.520] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [3 ,24] phvalue 65
[10:11:14.520] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 75.2675
[10:11:14.520] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [3 ,60] phvalue 76
[10:11:14.522] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 4, 12, 0 0
[10:11:14.522] INFO: The DUT currently contains the following objects:
[10:11:14.522] INFO: 2 TBM Cores tbm08c (2 ON)
[10:11:14.522] INFO: TBM Core alpha (0): 7 registers set
[10:11:14.522] INFO: TBM Core beta (1): 7 registers set
[10:11:14.522] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[10:11:14.522] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:14.522] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:14.522] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:14.523] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:14.523] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:14.523] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:14.523] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:14.523] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:14.523] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:14.523] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:14.523] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:14.523] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:14.523] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:14.523] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:14.523] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:14.523] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:15.616] INFO: Test took 1093ms.
[10:11:15.617] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[10:11:15.617] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 6, 13, 1 1
[10:11:15.617] INFO: The DUT currently contains the following objects:
[10:11:15.617] INFO: 2 TBM Cores tbm08c (2 ON)
[10:11:15.617] INFO: TBM Core alpha (0): 7 registers set
[10:11:15.617] INFO: TBM Core beta (1): 7 registers set
[10:11:15.617] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[10:11:15.617] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:15.617] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:15.617] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:15.617] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:15.617] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:15.617] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:15.617] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:15.617] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:15.617] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:15.617] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:15.617] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:15.617] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:15.618] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:15.618] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:15.618] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:15.618] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:16.710] INFO: Test took 1092ms.
[10:11:16.711] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[10:11:16.711] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 3, 12, 2 2
[10:11:16.711] INFO: The DUT currently contains the following objects:
[10:11:16.711] INFO: 2 TBM Cores tbm08c (2 ON)
[10:11:16.711] INFO: TBM Core alpha (0): 7 registers set
[10:11:16.711] INFO: TBM Core beta (1): 7 registers set
[10:11:16.711] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[10:11:16.711] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:16.711] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:16.711] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:16.712] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:16.712] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:16.712] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:16.712] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:16.712] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:16.712] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:16.712] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:16.712] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:16.712] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:16.712] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:16.712] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:16.712] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:16.712] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:17.804] INFO: Test took 1092ms.
[10:11:17.805] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[10:11:17.805] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 6, 13, 3 3
[10:11:17.805] INFO: The DUT currently contains the following objects:
[10:11:17.805] INFO: 2 TBM Cores tbm08c (2 ON)
[10:11:17.805] INFO: TBM Core alpha (0): 7 registers set
[10:11:17.805] INFO: TBM Core beta (1): 7 registers set
[10:11:17.805] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[10:11:17.805] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:17.805] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:17.806] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:17.806] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:17.806] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:17.806] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:17.806] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:17.806] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:17.806] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:17.806] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:17.806] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:17.806] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:17.806] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:17.806] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:17.806] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:17.806] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:18.898] INFO: Test took 1092ms.
[10:11:18.899] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[10:11:18.899] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 3, 14, 4 4
[10:11:18.899] INFO: The DUT currently contains the following objects:
[10:11:18.899] INFO: 2 TBM Cores tbm08c (2 ON)
[10:11:18.899] INFO: TBM Core alpha (0): 7 registers set
[10:11:18.899] INFO: TBM Core beta (1): 7 registers set
[10:11:18.899] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[10:11:18.899] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:18.899] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:18.899] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:18.899] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:18.899] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:18.899] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:18.899] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:18.899] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:18.899] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:18.899] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:18.899] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:18.899] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:18.899] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:18.899] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:18.899] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:18.899] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:19.992] INFO: Test took 1093ms.
[10:11:19.993] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[10:11:19.993] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 3, 50, 5 5
[10:11:19.993] INFO: The DUT currently contains the following objects:
[10:11:19.993] INFO: 2 TBM Cores tbm08c (2 ON)
[10:11:19.993] INFO: TBM Core alpha (0): 7 registers set
[10:11:19.993] INFO: TBM Core beta (1): 7 registers set
[10:11:19.993] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[10:11:19.993] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:19.993] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:19.993] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:19.993] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:19.993] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:19.993] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:19.993] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:19.993] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:19.993] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:19.993] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:19.993] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:19.993] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:19.993] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:19.993] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:19.993] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:19.993] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:21.085] INFO: Test took 1092ms.
[10:11:21.086] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[10:11:21.086] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 3, 13, 6 6
[10:11:21.086] INFO: The DUT currently contains the following objects:
[10:11:21.086] INFO: 2 TBM Cores tbm08c (2 ON)
[10:11:21.086] INFO: TBM Core alpha (0): 7 registers set
[10:11:21.086] INFO: TBM Core beta (1): 7 registers set
[10:11:21.086] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[10:11:21.086] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:21.087] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:21.087] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:21.087] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:21.087] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:21.087] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:21.087] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:21.087] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:21.087] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:21.087] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:21.087] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:21.087] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:21.087] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:21.087] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:21.087] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:21.087] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:22.179] INFO: Test took 1092ms.
[10:11:22.180] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[10:11:22.180] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 4, 25, 7 7
[10:11:22.180] INFO: The DUT currently contains the following objects:
[10:11:22.180] INFO: 2 TBM Cores tbm08c (2 ON)
[10:11:22.180] INFO: TBM Core alpha (0): 7 registers set
[10:11:22.180] INFO: TBM Core beta (1): 7 registers set
[10:11:22.180] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[10:11:22.181] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:22.181] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:22.181] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:22.181] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:22.181] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:22.181] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:22.181] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:22.181] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:22.181] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:22.181] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:22.181] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:22.181] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:22.181] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:22.181] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:22.181] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:22.181] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:23.272] INFO: Test took 1091ms.
[10:11:23.273] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[10:11:23.273] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 4, 50, 8 8
[10:11:23.273] INFO: The DUT currently contains the following objects:
[10:11:23.273] INFO: 2 TBM Cores tbm08c (2 ON)
[10:11:23.273] INFO: TBM Core alpha (0): 7 registers set
[10:11:23.273] INFO: TBM Core beta (1): 7 registers set
[10:11:23.273] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[10:11:23.273] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:23.273] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:23.273] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:23.273] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:23.273] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:23.273] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:23.273] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:23.273] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:23.273] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:23.273] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:23.273] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:23.273] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:23.273] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:23.273] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:23.273] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:23.273] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:24.366] INFO: Test took 1093ms.
[10:11:24.367] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[10:11:24.367] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 7, 50, 9 9
[10:11:24.367] INFO: The DUT currently contains the following objects:
[10:11:24.367] INFO: 2 TBM Cores tbm08c (2 ON)
[10:11:24.367] INFO: TBM Core alpha (0): 7 registers set
[10:11:24.367] INFO: TBM Core beta (1): 7 registers set
[10:11:24.368] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[10:11:24.368] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:24.368] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:24.368] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:24.368] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:24.368] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:24.368] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:24.368] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:24.368] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:24.368] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:24.368] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:24.368] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:24.368] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:24.368] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:24.368] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:24.368] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:24.368] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:25.462] INFO: Test took 1094ms.
[10:11:25.462] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[10:11:25.462] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 4, 25, 10 10
[10:11:25.462] INFO: The DUT currently contains the following objects:
[10:11:25.463] INFO: 2 TBM Cores tbm08c (2 ON)
[10:11:25.463] INFO: TBM Core alpha (0): 7 registers set
[10:11:25.463] INFO: TBM Core beta (1): 7 registers set
[10:11:25.463] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[10:11:25.463] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:25.463] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:25.463] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:25.463] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:25.463] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:25.463] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:25.463] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:25.463] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:25.463] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:25.463] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:25.463] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:25.463] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:25.463] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:25.463] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:25.463] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:25.463] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:26.557] INFO: Test took 1094ms.
[10:11:26.557] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[10:11:26.558] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 6, 12, 11 11
[10:11:26.558] INFO: The DUT currently contains the following objects:
[10:11:26.558] INFO: 2 TBM Cores tbm08c (2 ON)
[10:11:26.558] INFO: TBM Core alpha (0): 7 registers set
[10:11:26.558] INFO: TBM Core beta (1): 7 registers set
[10:11:26.558] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[10:11:26.558] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:26.558] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:26.558] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:26.558] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:26.558] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:26.558] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:26.558] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:26.558] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:26.558] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:26.558] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:26.558] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:26.558] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:26.558] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:26.558] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:26.558] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:26.558] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:27.652] INFO: Test took 1094ms.
[10:11:27.653] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[10:11:27.653] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 3, 6, 12 12
[10:11:27.653] INFO: The DUT currently contains the following objects:
[10:11:27.653] INFO: 2 TBM Cores tbm08c (2 ON)
[10:11:27.653] INFO: TBM Core alpha (0): 7 registers set
[10:11:27.653] INFO: TBM Core beta (1): 7 registers set
[10:11:27.653] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[10:11:27.653] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:27.653] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:27.654] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:27.654] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:27.654] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:27.654] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:27.654] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:27.654] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:27.654] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:27.654] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:27.654] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:27.654] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:27.654] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:27.654] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:27.654] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:27.654] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:28.748] INFO: Test took 1094ms.
[10:11:28.749] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[10:11:28.749] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 3, 25, 13 13
[10:11:28.749] INFO: The DUT currently contains the following objects:
[10:11:28.749] INFO: 2 TBM Cores tbm08c (2 ON)
[10:11:28.749] INFO: TBM Core alpha (0): 7 registers set
[10:11:28.749] INFO: TBM Core beta (1): 7 registers set
[10:11:28.749] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[10:11:28.749] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:28.749] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:28.749] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:28.749] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:28.749] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:28.749] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:28.749] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:28.749] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:28.749] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:28.749] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:28.749] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:28.749] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:28.749] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:28.749] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:28.749] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:28.749] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:29.843] INFO: Test took 1094ms.
[10:11:29.844] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[10:11:29.844] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 3, 24, 14 14
[10:11:29.844] INFO: The DUT currently contains the following objects:
[10:11:29.844] INFO: 2 TBM Cores tbm08c (2 ON)
[10:11:29.844] INFO: TBM Core alpha (0): 7 registers set
[10:11:29.844] INFO: TBM Core beta (1): 7 registers set
[10:11:29.844] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[10:11:29.844] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:29.844] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:29.844] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:29.844] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:29.844] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:29.844] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:29.844] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:29.844] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:29.844] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:29.844] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:29.845] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:29.845] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:29.845] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:29.845] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:29.845] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:29.845] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:30.938] INFO: Test took 1093ms.
[10:11:30.938] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[10:11:30.939] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 3, 60, 15 15
[10:11:30.939] INFO: The DUT currently contains the following objects:
[10:11:30.939] INFO: 2 TBM Cores tbm08c (2 ON)
[10:11:30.939] INFO: TBM Core alpha (0): 7 registers set
[10:11:30.939] INFO: TBM Core beta (1): 7 registers set
[10:11:30.939] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[10:11:30.939] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:30.939] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:30.939] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:30.939] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:30.939] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:30.939] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:30.939] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:30.939] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:30.939] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:30.939] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:30.939] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:30.939] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:30.939] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:30.939] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:30.939] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:30.939] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[10:11:32.032] INFO: Test took 1093ms.
[10:11:32.033] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[10:11:32.033] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 33 on ROC0
[10:11:32.033] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 32 on ROC1
[10:11:32.033] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 32 on ROC2
[10:11:32.033] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 30 on ROC3
[10:11:32.033] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 33 on ROC4
[10:11:32.033] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 31 on ROC5
[10:11:32.033] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 31 on ROC6
[10:11:32.033] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 33 on ROC7
[10:11:32.033] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 29 on ROC8
[10:11:32.033] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 31 on ROC9
[10:11:32.033] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 29 on ROC10
[10:11:32.033] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 31 on ROC11
[10:11:32.033] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 33 on ROC12
[10:11:32.033] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 27 on ROC13
[10:11:32.033] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 33 on ROC14
[10:11:32.033] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 33 on ROC15
[10:11:32.037] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:14:25.751] INFO: Test took 173714ms.
[10:14:27.316] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:20.939] INFO: Test took 173623ms.
[10:17:22.671] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[10:17:22.671] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip0
[10:17:22.671] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[10:17:22.671] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip1
[10:17:22.672] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[10:17:22.672] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip2
[10:17:22.672] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[10:17:22.672] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip3
[10:17:22.672] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[10:17:22.673] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip4
[10:17:22.673] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[10:17:22.673] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip5
[10:17:22.673] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[10:17:22.673] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip6
[10:17:22.673] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[10:17:22.674] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip7
[10:17:22.674] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[10:17:22.674] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip8
[10:17:22.674] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[10:17:22.674] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip9
[10:17:22.674] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[10:17:22.675] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip10
[10:17:22.675] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[10:17:22.675] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip11
[10:17:22.675] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[10:17:22.675] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip12
[10:17:22.675] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[10:17:22.676] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip13
[10:17:22.676] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[10:17:22.676] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip14
[10:17:22.676] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[10:17:22.676] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip15
[10:17:22.676] INFO: safety margin for low PH: adding 0, margin is now 20
[10:17:22.682] INFO: safety margin for low PH: adding 0, margin is now 20
[10:17:22.687] INFO: safety margin for low PH: adding 0, margin is now 20
[10:17:22.693] INFO: safety margin for low PH: adding 0, margin is now 20
[10:17:22.698] INFO: safety margin for low PH: adding 0, margin is now 20
[10:17:22.703] INFO: safety margin for low PH: adding 0, margin is now 20
[10:17:22.709] INFO: safety margin for low PH: adding 0, margin is now 20
[10:17:22.714] INFO: safety margin for low PH: adding 0, margin is now 20
[10:17:22.720] INFO: safety margin for low PH: adding 0, margin is now 20
[10:17:22.725] INFO: safety margin for low PH: adding 0, margin is now 20
[10:17:22.731] INFO: safety margin for low PH: adding 0, margin is now 20
[10:17:22.736] INFO: safety margin for low PH: adding 1, margin is now 21
[10:17:22.741] INFO: safety margin for low PH: adding 0, margin is now 20
[10:17:22.747] INFO: safety margin for low PH: adding 0, margin is now 20
[10:17:22.752] INFO: safety margin for low PH: adding 0, margin is now 20
[10:17:22.758] INFO: safety margin for low PH: adding 0, margin is now 20
[10:17:22.763] INFO: safety margin for low PH: adding 0, margin is now 20
[10:17:22.769] DEBUG: <PixTestPhOptimization.cc/doTest:L172> optimisation done
[10:17:22.819] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C0.dat
[10:17:22.819] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C1.dat
[10:17:22.819] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C2.dat
[10:17:22.819] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C3.dat
[10:17:22.829] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C4.dat
[10:17:22.830] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C5.dat
[10:17:22.830] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C6.dat
[10:17:22.830] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C7.dat
[10:17:22.830] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C8.dat
[10:17:22.830] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C9.dat
[10:17:22.830] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C10.dat
[10:17:22.830] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C11.dat
[10:17:22.830] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C12.dat
[10:17:22.830] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C13.dat
[10:17:22.831] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C14.dat
[10:17:22.831] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//dacParameters35_C15.dat
[10:17:26.579] INFO: Test took 3744ms.
[10:17:30.558] INFO: Test took 3699ms.
[10:17:34.575] INFO: Test took 3738ms.
[10:17:34.862] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:35.765] INFO: Test took 903ms.
[10:17:35.768] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:36.859] INFO: Test took 1091ms.
[10:17:36.862] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:37.954] INFO: Test took 1092ms.
[10:17:37.957] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:39.049] INFO: Test took 1092ms.
[10:17:39.052] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:40.143] INFO: Test took 1091ms.
[10:17:40.146] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:41.238] INFO: Test took 1092ms.
[10:17:41.242] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:42.331] INFO: Test took 1090ms.
[10:17:42.334] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:43.424] INFO: Test took 1090ms.
[10:17:43.427] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:44.518] INFO: Test took 1091ms.
[10:17:44.521] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:45.613] INFO: Test took 1092ms.
[10:17:45.616] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:46.709] INFO: Test took 1093ms.
[10:17:46.712] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:47.804] INFO: Test took 1092ms.
[10:17:47.808] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:48.899] INFO: Test took 1091ms.
[10:17:48.902] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:49.993] INFO: Test took 1091ms.
[10:17:49.997] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:51.088] INFO: Test took 1091ms.
[10:17:51.091] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:52.182] INFO: Test took 1091ms.
[10:17:52.186] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:53.278] INFO: Test took 1092ms.
[10:17:53.281] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:54.372] INFO: Test took 1091ms.
[10:17:54.376] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:55.466] INFO: Test took 1090ms.
[10:17:55.469] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:56.561] INFO: Test took 1092ms.
[10:17:56.565] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:57.655] INFO: Test took 1091ms.
[10:17:57.659] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:58.751] INFO: Test took 1092ms.
[10:17:58.754] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:17:59.849] INFO: Test took 1095ms.
[10:17:59.852] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:18:00.947] INFO: Test took 1095ms.
[10:18:00.950] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:18:02.043] INFO: Test took 1093ms.
[10:18:02.046] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:18:03.139] INFO: Test took 1093ms.
[10:18:03.143] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:18:04.234] INFO: Test took 1091ms.
[10:18:04.238] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:18:05.330] INFO: Test took 1092ms.
[10:18:05.333] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:18:06.423] INFO: Test took 1090ms.
[10:18:06.426] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:18:07.519] INFO: Test took 1094ms.
[10:18:07.523] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:18:08.614] INFO: Test took 1091ms.
[10:18:08.618] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[10:18:09.711] INFO: Test took 1093ms.
[10:18:10.325] INFO: PixTestPhOptimization::doTest() done, duration: 427 seconds
[10:18:10.325] INFO: PH scale (per ROC): 66 63 78 69 63 77 70 72 64 67 61 65 76 69 69 71
[10:18:10.325] INFO: PH offset (per ROC): 176 186 177 189 181 190 177 184 183 174 189 200 173 175 186 176
[10:18:10.483] DEBUG: <PixTestGainPedestal.cc/setParameter:L83> PixTestGainPedestal::PixTest() fVcalStep = 10
[10:18:10.485] INFO: ######################################################################
[10:18:10.485] INFO: PixTestGainPedestal::fullTest() ntrig = 10
[10:18:10.485] INFO: ######################################################################
[10:18:10.485] DEBUG: <PixTestGainPedestal.cc/measure:L192> using FLAGS = 16
[10:18:10.496] INFO: scanning low vcal = 10
[10:18:13.807] INFO: Test took 3311ms.
[10:18:13.812] INFO: scanning low vcal = 20
[10:18:17.137] INFO: Test took 3325ms.
[10:18:17.142] INFO: scanning low vcal = 30
[10:18:20.486] INFO: Test took 3344ms.
[10:18:20.496] INFO: scanning low vcal = 40
[10:18:24.232] INFO: Test took 3736ms.
[10:18:24.290] INFO: scanning low vcal = 50
[10:18:28.045] INFO: Test took 3754ms.
[10:18:28.103] INFO: scanning low vcal = 60
[10:18:31.833] INFO: Test took 3730ms.
[10:18:31.892] INFO: scanning low vcal = 70
[10:18:35.670] INFO: Test took 3778ms.
[10:18:35.732] INFO: scanning low vcal = 80
[10:18:39.506] INFO: Test took 3774ms.
[10:18:39.566] INFO: scanning low vcal = 90
[10:18:43.334] INFO: Test took 3768ms.
[10:18:43.394] INFO: scanning low vcal = 100
[10:18:47.162] INFO: Test took 3768ms.
[10:18:47.222] INFO: scanning low vcal = 110
[10:18:51.013] INFO: Test took 3791ms.
[10:18:51.075] INFO: scanning low vcal = 120
[10:18:54.846] INFO: Test took 3771ms.
[10:18:54.905] INFO: scanning low vcal = 130
[10:18:58.775] INFO: Test took 3870ms.
[10:18:58.837] INFO: scanning low vcal = 140
[10:19:02.732] INFO: Test took 3895ms.
[10:19:02.794] INFO: scanning low vcal = 150
[10:19:06.571] INFO: Test took 3777ms.
[10:19:06.631] INFO: scanning low vcal = 160
[10:19:10.402] INFO: Test took 3771ms.
[10:19:10.464] INFO: scanning low vcal = 170
[10:19:14.245] INFO: Test took 3781ms.
[10:19:14.309] INFO: scanning low vcal = 180
[10:19:18.086] INFO: Test took 3777ms.
[10:19:18.144] INFO: scanning low vcal = 190
[10:19:21.913] INFO: Test took 3769ms.
[10:19:21.973] INFO: scanning low vcal = 200
[10:19:25.749] INFO: Test took 3776ms.
[10:19:25.807] INFO: scanning low vcal = 210
[10:19:29.574] INFO: Test took 3767ms.
[10:19:29.635] INFO: scanning low vcal = 220
[10:19:33.402] INFO: Test took 3766ms.
[10:19:33.461] INFO: scanning low vcal = 230
[10:19:37.223] INFO: Test took 3762ms.
[10:19:37.286] INFO: scanning low vcal = 240
[10:19:41.052] INFO: Test took 3766ms.
[10:19:41.115] INFO: scanning low vcal = 250
[10:19:44.893] INFO: Test took 3778ms.
[10:19:44.957] INFO: scanning high vcal = 30 (= 210 in low range)
[10:19:48.717] INFO: Test took 3760ms.
[10:19:48.777] INFO: scanning high vcal = 50 (= 350 in low range)
[10:19:52.534] INFO: Test took 3756ms.
[10:19:52.593] INFO: scanning high vcal = 70 (= 490 in low range)
[10:19:56.377] INFO: Test took 3784ms.
[10:19:56.436] INFO: scanning high vcal = 90 (= 630 in low range)
[10:20:00.218] INFO: Test took 3782ms.
[10:20:00.277] INFO: scanning high vcal = 200 (= 1400 in low range)
[10:20:04.045] INFO: Test took 3768ms.
[10:20:04.584] INFO: PixTestGainPedestal::measure() done
[10:20:04.586] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C0
[10:20:04.586] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C1
[10:20:04.586] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C2
[10:20:04.586] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C3
[10:20:04.586] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C4
[10:20:04.587] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C5
[10:20:04.587] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C6
[10:20:04.587] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C7
[10:20:04.587] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C8
[10:20:04.587] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C9
[10:20:04.587] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C10
[10:20:04.587] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C11
[10:20:04.587] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C12
[10:20:04.588] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C13
[10:20:04.588] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C14
[10:20:04.588] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C15
[10:20:34.612] INFO: PixTestGainPedestal::fit() done
[10:20:34.612] INFO: non-linearity mean: 0.954 0.966 0.961 0.954 0.956 0.962 0.961 0.954 0.952 0.946 0.954 0.954 0.965 0.954 0.954 0.957
[10:20:34.612] INFO: non-linearity RMS: 0.007 0.006 0.007 0.007 0.006 0.006 0.006 0.007 0.007 0.009 0.010 0.009 0.007 0.007 0.007 0.006
[10:20:34.612] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//phCalibrationFitErr35_C0.dat
[10:20:34.631] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//phCalibrationFitErr35_C1.dat
[10:20:34.648] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//phCalibrationFitErr35_C2.dat
[10:20:34.665] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//phCalibrationFitErr35_C3.dat
[10:20:34.681] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//phCalibrationFitErr35_C4.dat
[10:20:34.698] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//phCalibrationFitErr35_C5.dat
[10:20:34.715] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//phCalibrationFitErr35_C6.dat
[10:20:34.732] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//phCalibrationFitErr35_C7.dat
[10:20:34.749] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//phCalibrationFitErr35_C8.dat
[10:20:34.765] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//phCalibrationFitErr35_C9.dat
[10:20:34.782] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//phCalibrationFitErr35_C10.dat
[10:20:34.799] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//phCalibrationFitErr35_C11.dat
[10:20:34.815] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//phCalibrationFitErr35_C12.dat
[10:20:34.832] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//phCalibrationFitErr35_C13.dat
[10:20:34.848] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//phCalibrationFitErr35_C14.dat
[10:20:34.865] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3019_FullQualification_2015-07-31_09h17m_1438327071//000_Fulltest_p17//phCalibrationFitErr35_C15.dat
[10:20:34.882] INFO: PixTestGainPedestal::doTest() done, duration: 144 seconds
[10:20:34.882] DEBUG: <PixTestGainPedestal.cc/~PixTestGainPedestal:L125> PixTestGainPedestal dtor
[10:20:34.888] DEBUG: <PixTestFullTest.cc/~PixTestFullTest:L78> PixTestFullTest dtor
[10:20:34.888] INFO: enter test to run
[10:20:34.888] INFO: test: q no parameter change
[10:20:34.888] DEBUG: <PixMonitor.cc/dumpSummaries:L34> PixMonitor::dumpSummaries
[10:20:35.030] QUIET: Connection to board 105 closed.
[10:20:35.031] INFO: pXar: this is the end, my friend
[10:20:35.031] DEBUG: <PixSetup.cc/~PixSetup:L68> PixSetup free fPxarMemory