Test Date: 2015-07-30 09:25
Analysis date: 2015-10-28 15:12
Logfile
LogfileView
[10:51:02.526] INFO: *** Welcome to pxar ***
[10:51:02.526] INFO: *** Today: 2015/07/31
[10:51:02.526] INFO: readRocDacs: /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters_C0.dat .. /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters_C15.dat
[10:51:02.527] INFO: readTbmDacs: /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//tbmParameters_C0a.dat .. /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//tbmParameters_C0b.dat
[10:51:02.527] INFO: readMaskFile: /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//defaultMaskFile.dat
[10:51:02.527] INFO: readTrimFile: /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//trimParameters_C0.dat .. /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//trimParameters_C15.dat
[10:51:02.587] INFO: clk: 4
[10:51:02.587] INFO: ctr: 4
[10:51:02.587] INFO: sda: 19
[10:51:02.587] INFO: tin: 9
[10:51:02.587] INFO: level: 15
[10:51:02.587] INFO: triggerdelay: 0
[10:51:02.587] QUIET: Instanciating API for pxar v2.2.5+67~g3b1c276
[10:51:02.587] INFO: Log level: DEBUG
[10:51:02.595] INFO: Found DTB DTB_WV5QFZ
[10:51:02.605] QUIET: Connection to board DTB_WV5QFZ opened.
[10:51:02.608] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 98
HW version: DTB1.2
FW version: 4.2
SW version: 4.2
USB id: DTB_WV5QFZ
MAC address: 40D855118062
Hostname: pixelDTB098
Comment: with CMOS buffer
------------------------------------------------------
[10:51:02.611] INFO: RPC call hashes of host and DTB match: 447413373
[10:51:04.205] INFO: DUT info:
[10:51:04.205] INFO: The DUT currently contains the following objects:
[10:51:04.205] INFO: 2 TBM Cores tbm08c (2 ON)
[10:51:04.205] INFO: TBM Core alpha (0): 7 registers set
[10:51:04.205] INFO: TBM Core beta (1): 7 registers set
[10:51:04.205] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[10:51:04.205] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:04.205] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:04.205] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:04.205] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:04.205] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:04.205] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:04.205] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:04.205] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:04.205] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:04.205] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:04.205] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:04.205] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:04.205] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:04.205] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:04.206] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:04.206] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->BB<-
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> dumpall: checkbox(0)
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> dumpproblematic: checkbox(0)
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 5
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> vcals: 250
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->BB2<-
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> vcals: 222
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> plwidth: 35
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> targetia: 24
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->BB3<-
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> dumpall: checkbox(0)
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> dumpproblematic: checkbox(0)
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 5
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> vcals: 250
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Cmd<-
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->DacDacScan<-
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> phmap: checkbox
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> dac1: caldel
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> dac1lo: 0
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> dac1hi: 255
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> dac2: vthrcomp
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> dac2lo: 0
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> dac2hi: 255
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->DacScan<-
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> phmap: checkbox(1)
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> allpixels: checkbox(0)
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> unmasked: checkbox(0)
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> dac: vcal
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> daclo: 0
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> dachi: 255
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->GainPedestal<-
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> showfits: checkbox(0)
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> extended: checkbox(0)
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> dumphists: checkbox(0)
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> vcalstep: 10
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> measure: button
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> fit: button
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> save: button
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->HighRate<-
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> maskhotpixels: button
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> savemaskfile: checkbox(0)
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> maskfilename: default
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> caldelscan: button
[10:51:04.206] DEBUG: <PixTestParameters.cc/dump:L107> xpixelalive: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 50
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> vcal: 200
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> xnoisemaps: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> daclo: 0
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> dachi: 100
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> dacs/step: 20
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> rundaq: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> trgfrequency(khz): 20
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> runseconds: 2
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> triggerdelay: 20
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> delaytbm: checkbox
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> filltree: checkbox
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->IV<-
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> port: /dev/FIXME
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> voltagestart: 0
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> voltagestop: 600
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> voltagestep: 5
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> delay: 1
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> compliance(ua): 100
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->PhOptimization<-
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> safetymarginlow: 20
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> saturationvcal: 100
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> quantilesaturation: 0.98
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->PixelAlive<-
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> vcal: 200
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> alivetest: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> masktest: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> addressdecodingtest: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Pretest<-
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> programroc: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> targetia: 24
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> setvana: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> iterations: 100
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> settimings: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> findworkingpixel: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> setvthrcompcaldel: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> pix: 11,20
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> vcal: 250
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> deltavthrcomp: 50
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> fraccaldel: 0.5
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 5
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> savedacs: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Readback<-
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> calibratevd: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> calibrateva: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> calibrateia: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> readbackvbg: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> getcalibratedvbg: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> usecalvd: checkbox(1)
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> usecalva: checkbox(0)
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> setvana: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Scurves<-
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> adjustvcal: checkbox(1)
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> dumpall: checkbox(0)
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> dumpproblematic: checkbox(0)
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> dumpoutputfile: checkbox(0)
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 50
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> dac: VthrComp
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> daclo: 0
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> dachi: 200
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> dacs/step: 10
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> scurves: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Timing<-
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> fastscan: checkbox(0)
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> targetclk: 4
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> clocksdascan: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> phasescan: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> levelscan: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> tbmphasescan: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> rocdelayscan: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> timingtest: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> saveparameters: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Trim<-
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> trim: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> ntrig: 10
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> vcal: 35
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> trimbits: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L104> PixTestParameters: ->Xray<-
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> maskhotpixels: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> savemaskfile: checkbox(0)
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> maskfilename: default
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> source: Ag
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> phrun: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> runseconds: 100
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> trgfrequency(khz): 100
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> ratescan: button
[10:51:04.207] DEBUG: <PixTestParameters.cc/dump:L107> vthrcompmin: 10
[10:51:04.208] DEBUG: <PixTestParameters.cc/dump:L107> vthrcompmax: 80
[10:51:04.208] DEBUG: <PixTestParameters.cc/dump:L107> stepseconds: 5
[10:51:04.208] DEBUG: <PixTestParameters.cc/dump:L107> delaytbm: checkbox
[10:51:04.208] DEBUG: <PixTestParameters.cc/dump:L107> filltree: checkbox
[10:51:04.208] DEBUG: <PixSetup.cc/init:L81> PixSetup init start; getCurrentRSS() = 30949376
[10:51:04.208] DEBUG: <PixSetup.cc/init:L87> fPixTestParameters = 0x1ef4be0
[10:51:04.208] DEBUG: <PixSetup.cc/init:L88> fConfigParameters = 0x1e199c0
[10:51:04.208] DEBUG: <PixSetup.cc/init:L89> fPxarMemory = 0x7f1a31d94010
[10:51:04.208] DEBUG: <PixSetup.cc/init:L90> fPxarMemHi = 0x7f1a37fff510
[10:51:04.208] DEBUG: <PixSetup.cc/init:L106> PixSetup init done; getCurrentRSS() = 31010816 fPxarMemory = 0x7f1a31d94010
[10:51:04.208] DEBUG: <PixTestFactory.cc/PixTestFactory:L52> PixTestFactory::PixTestFactory()
[10:51:04.608] INFO: enter 'restricted' command line mode
[10:51:04.608] INFO: enter test to run
[10:51:04.608] INFO: test: Pretest no parameter change
[10:51:04.609] INFO: running: pretest
[10:51:04.614] INFO: ######################################################################
[10:51:04.614] INFO: PixTestPretest::doTest()
[10:51:04.614] INFO: ######################################################################
[10:51:04.616] INFO: ----------------------------------------------------------------------
[10:51:04.616] INFO: PixTestPretest::programROC()
[10:51:04.616] INFO: ----------------------------------------------------------------------
[10:51:22.636] INFO: PixTestPretest::programROC() done: ROCs are all programmable
[10:51:22.636] INFO: IA differences per ROC: 17.7 16.1 18.5 16.9 15.3 20.1 19.3 18.5 17.7 20.1 17.7 20.1 16.9 18.5 19.3 19.3
[10:51:22.706] INFO: ----------------------------------------------------------------------
[10:51:22.706] INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[10:51:22.706] INFO: ----------------------------------------------------------------------
[10:51:22.809] DEBUG: <PixTestPretest.cc/setVana:L254> offset current from other 15 ROCs is 68.5312 mA
[10:51:22.910] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 0 iter 0 Vana 78 Ia 23.0687 mA
[10:51:23.011] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 0 iter 1 Vana 84 Ia 24.6688 mA
[10:51:23.111] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 0 iter 2 Vana 81 Ia 23.8687 mA
[10:51:23.213] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 1 iter 0 Vana 78 Ia 20.6688 mA
[10:51:23.314] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 1 iter 1 Vana 98 Ia 24.6688 mA
[10:51:23.415] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 1 iter 2 Vana 95 Ia 24.6688 mA
[10:51:23.516] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 1 iter 3 Vana 92 Ia 23.8687 mA
[10:51:23.617] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 2 iter 0 Vana 78 Ia 23.0687 mA
[10:51:23.718] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 2 iter 1 Vana 84 Ia 25.4688 mA
[10:51:23.819] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 2 iter 2 Vana 76 Ia 23.0687 mA
[10:51:23.919] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 2 iter 3 Vana 82 Ia 24.6688 mA
[10:51:24.019] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 2 iter 4 Vana 79 Ia 23.8687 mA
[10:51:24.121] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 3 iter 0 Vana 78 Ia 21.4688 mA
[10:51:24.221] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 3 iter 1 Vana 93 Ia 24.6688 mA
[10:51:24.322] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 3 iter 2 Vana 90 Ia 23.8687 mA
[10:51:24.424] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 4 iter 0 Vana 78 Ia 19.8688 mA
[10:51:24.525] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 4 iter 1 Vana 103 Ia 23.8687 mA
[10:51:24.626] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 5 iter 0 Vana 78 Ia 24.6688 mA
[10:51:24.727] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 5 iter 1 Vana 75 Ia 24.6688 mA
[10:51:24.828] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 5 iter 2 Vana 72 Ia 23.8687 mA
[10:51:24.930] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 6 iter 0 Vana 78 Ia 23.8687 mA
[10:51:25.031] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 7 iter 0 Vana 78 Ia 23.0687 mA
[10:51:25.132] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 7 iter 1 Vana 84 Ia 24.6688 mA
[10:51:25.233] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 7 iter 2 Vana 81 Ia 23.8687 mA
[10:51:25.334] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 8 iter 0 Vana 78 Ia 22.2688 mA
[10:51:25.435] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 8 iter 1 Vana 88 Ia 24.6688 mA
[10:51:25.535] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 8 iter 2 Vana 85 Ia 23.8687 mA
[10:51:25.637] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 9 iter 0 Vana 78 Ia 24.6688 mA
[10:51:25.737] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 9 iter 1 Vana 75 Ia 23.8687 mA
[10:51:25.839] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 10 iter 0 Vana 78 Ia 22.2688 mA
[10:51:25.940] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 10 iter 1 Vana 88 Ia 24.6688 mA
[10:51:26.041] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 10 iter 2 Vana 85 Ia 23.8687 mA
[10:51:26.143] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 11 iter 0 Vana 78 Ia 24.6688 mA
[10:51:26.243] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 11 iter 1 Vana 75 Ia 23.8687 mA
[10:51:26.345] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 12 iter 0 Vana 78 Ia 21.4688 mA
[10:51:26.445] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 12 iter 1 Vana 93 Ia 24.6688 mA
[10:51:26.546] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 12 iter 2 Vana 90 Ia 23.8687 mA
[10:51:26.647] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 13 iter 0 Vana 78 Ia 23.0687 mA
[10:51:26.747] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 13 iter 1 Vana 84 Ia 24.6688 mA
[10:51:26.848] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 13 iter 2 Vana 81 Ia 23.8687 mA
[10:51:26.950] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 14 iter 0 Vana 78 Ia 23.8687 mA
[10:51:27.051] DEBUG: <PixTestPretest.cc/setVana:L280> ROC 15 iter 0 Vana 78 Ia 23.0687 mA
[10:51:27.152] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 15 iter 1 Vana 84 Ia 25.4688 mA
[10:51:27.253] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 15 iter 2 Vana 76 Ia 23.0687 mA
[10:51:27.354] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 15 iter 3 Vana 82 Ia 24.6688 mA
[10:51:27.455] DEBUG: <PixTestPretest.cc/setVana:L312> ROC 15 iter 4 Vana 79 Ia 23.8687 mA
[10:51:27.499] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 0 Vana 81
[10:51:27.499] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 1 Vana 92
[10:51:27.499] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 2 Vana 79
[10:51:27.500] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 3 Vana 90
[10:51:27.500] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 4 Vana 103
[10:51:27.500] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 5 Vana 72
[10:51:27.500] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 6 Vana 78
[10:51:27.500] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 7 Vana 81
[10:51:27.500] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 8 Vana 85
[10:51:27.501] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 9 Vana 75
[10:51:27.501] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 10 Vana 85
[10:51:27.501] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 11 Vana 75
[10:51:27.501] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 12 Vana 90
[10:51:27.501] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 13 Vana 81
[10:51:27.501] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 14 Vana 78
[10:51:27.501] DEBUG: <PixTestPretest.cc/setVana:L343> ROC 15 Vana 79
[10:51:27.604] INFO: PixTestPretest::setVana() done, Module Ia 385.9 mA = 24.1188 mA/ROC
[10:51:27.606] INFO: ----------------------------------------------------------------------
[10:51:27.606] INFO: PixTestPreTest::setTimings()
[10:51:27.606] INFO: ----------------------------------------------------------------------
[10:51:27.606] DEBUG: <PixTestPretest.cc/setTimings:L392> Testing Timing: Attempt #1
[10:51:28.603] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:28.603] INFO: Decoding statistics:
[10:51:28.603] INFO: General information:
[10:51:28.603] INFO: 16bit words read: 120
[10:51:28.603] INFO: valid events total: 10
[10:51:28.603] INFO: empty events: 10
[10:51:28.603] INFO: valid events with pixels: 0
[10:51:28.603] INFO: valid pixel hits: 0
[10:51:28.603] INFO: Event errors: 0
[10:51:28.603] INFO: start marker: 0
[10:51:28.603] INFO: stop marker: 0
[10:51:28.603] INFO: overflow: 0
[10:51:28.603] INFO: invalid 5bit words: 0
[10:51:28.603] INFO: invalid XOR eye diagram: 0
[10:51:28.603] INFO: TBM errors: 0
[10:51:28.603] INFO: flawed TBM headers: 0
[10:51:28.603] INFO: flawed TBM trailers: 0
[10:51:28.603] INFO: event ID mismatches: 0
[10:51:28.603] INFO: ROC errors: 0
[10:51:28.603] INFO: missing ROC header(s): 0
[10:51:28.603] INFO: misplaced readback start: 0
[10:51:28.603] INFO: Pixel decoding errors: 0
[10:51:28.603] INFO: pixel data incomplete: 0
[10:51:28.603] INFO: pixel address: 0
[10:51:28.603] INFO: pulse height fill bit: 0
[10:51:28.603] INFO: buffer corruption: 0
[10:51:28.603] INFO: ----------------------------------------------------------------------
[10:51:28.603] INFO: Default timings are good. No timing scan needed.
[10:51:28.603] INFO: ----------------------------------------------------------------------
[10:51:28.603] INFO: Test took 997 ms.
[10:51:28.603] INFO: PixTestPretest::setTimings() done.
[10:51:28.863] INFO: ----------------------------------------------------------------------
[10:51:28.863] INFO: PixTestPretest::findWorkingPixel()
[10:51:28.863] INFO: ----------------------------------------------------------------------
[10:51:36.784] INFO: Test took 7919ms.
[10:51:37.079] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C0 OK, with vthrComp = 94 and Delta(CalDel) = 59
[10:51:37.082] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C1 OK, with vthrComp = 77 and Delta(CalDel) = 63
[10:51:37.084] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C2 OK, with vthrComp = 101 and Delta(CalDel) = 63
[10:51:37.086] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C3 OK, with vthrComp = 104 and Delta(CalDel) = 62
[10:51:37.089] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C4 OK, with vthrComp = 97 and Delta(CalDel) = 54
[10:51:37.091] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C5 OK, with vthrComp = 89 and Delta(CalDel) = 63
[10:51:37.093] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C6 OK, with vthrComp = 115 and Delta(CalDel) = 62
[10:51:37.095] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C7 OK, with vthrComp = 73 and Delta(CalDel) = 58
[10:51:37.098] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C8 OK, with vthrComp = 65 and Delta(CalDel) = 63
[10:51:37.100] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C9 OK, with vthrComp = 88 and Delta(CalDel) = 55
[10:51:37.102] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C10 OK, with vthrComp = 97 and Delta(CalDel) = 59
[10:51:37.105] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C11 OK, with vthrComp = 105 and Delta(CalDel) = 58
[10:51:37.107] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C12 OK, with vthrComp = 106 and Delta(CalDel) = 56
[10:51:37.109] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C13 OK, with vthrComp = 94 and Delta(CalDel) = 59
[10:51:37.112] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C14 OK, with vthrComp = 90 and Delta(CalDel) = 58
[10:51:37.114] DEBUG: <PixTestPretest.cc/findWorkingPixel:L1051> fwp_c12_r22_C15 OK, with vthrComp = 75 and Delta(CalDel) = 58
[10:51:37.138] INFO: Found working pixel in all ROCs: col/row = 12/22
[10:51:37.186] INFO: ----------------------------------------------------------------------
[10:51:37.186] INFO: PixTestPretest::setVthrCompCalDel()
[10:51:37.186] INFO: ----------------------------------------------------------------------
[10:51:45.266] INFO: Test took 8074ms.
[10:51:45.321] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 130 +/- 29.5
[10:51:45.564] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 135 +/- 31
[10:51:45.567] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 140 +/- 31.5
[10:51:45.569] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 135 +/- 29.5
[10:51:45.572] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 97 +/- 27
[10:51:45.574] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 138 +/- 30.5
[10:51:45.577] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 140 +/- 31
[10:51:45.579] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 127 +/- 29
[10:51:45.581] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 146 +/- 32
[10:51:45.584] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 114 +/- 28.5
[10:51:45.586] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 115 +/- 29.5
[10:51:45.589] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 120 +/- 28.5
[10:51:45.591] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 109 +/- 29
[10:51:45.594] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 109 +/- 29
[10:51:45.597] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 124 +/- 29.5
[10:51:45.599] DEBUG: <PixTestPretest.cc/setVthrCompCalDel:L580> CalDel: 129 +/- 28
[10:51:45.650] INFO: PixTestPretest::setVthrCompCalDel() done
[10:51:45.650] INFO: CalDel: 130 135 140 135 97 138 140 127 146 114 115 120 109 109 124 129
[10:51:45.650] INFO: VthrComp: 51 51 51 51 51 51 51 51 51 51 53 51 51 51 51 51
[10:51:45.654] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters_C0.dat
[10:51:45.654] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters_C1.dat
[10:51:45.654] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters_C2.dat
[10:51:45.654] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters_C3.dat
[10:51:45.654] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters_C4.dat
[10:51:45.655] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters_C5.dat
[10:51:45.655] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters_C6.dat
[10:51:45.655] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters_C7.dat
[10:51:45.655] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters_C8.dat
[10:51:45.655] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters_C9.dat
[10:51:45.655] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters_C10.dat
[10:51:45.655] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters_C11.dat
[10:51:45.655] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters_C12.dat
[10:51:45.655] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters_C13.dat
[10:51:45.656] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters_C14.dat
[10:51:45.656] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters_C15.dat
[10:51:45.656] INFO: PixTestPretest::doTest() done, duration: 41 seconds
[10:51:45.656] DEBUG: <PixTestPretest.cc/~PixTestPretest:L134> PixTestPretest dtor
[10:51:45.730] INFO: enter test to run
[10:51:45.730] INFO: test: Fulltest no parameter change
[10:51:45.730] INFO: running: fulltest
[10:51:45.730] DEBUG: <PixTestFullTest.cc/init:L49> PixTestFullTest::init()
[10:51:45.730] DEBUG: <PixTestFullTest.cc/PixTestFullTest:L20> PixTestFullTest ctor(PixSetup &a, string, TGTab *)
[10:51:45.730] INFO: ######################################################################
[10:51:45.730] INFO: PixTestFullTest::doTest()
[10:51:45.730] INFO: ######################################################################
[10:51:45.730] DEBUG: <PixTestAlive.cc/init:L77> PixTestAlive::init()
[10:51:45.730] DEBUG: <PixTestAlive.cc/PixTestAlive:L21> PixTestAlive ctor(PixSetup &a, string, TGTab *)
[10:51:45.732] INFO: ######################################################################
[10:51:45.732] INFO: PixTestAlive::doTest()
[10:51:45.732] INFO: ######################################################################
[10:51:45.733] INFO: ----------------------------------------------------------------------
[10:51:45.734] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[10:51:45.734] INFO: ----------------------------------------------------------------------
[10:51:45.736] DEBUG: <PixTest.cc/efficiencyMaps:L328> attempt #0
[10:51:49.676] INFO: Test took 3940ms.
[10:51:49.696] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:49.696] DEBUG: <PixTest.cc/efficiencyMaps:L339> eff result size = 66546
[10:51:49.696] DEBUG: <PixTest.cc/efficiencyMaps:L344> Create hists PixelAlive_C0 .. PixelAlive_C15
[10:51:50.004] INFO: PixTestAlive::aliveTest() done
[10:51:50.004] INFO: number of dead pixels (per ROC): 0 0 1 0 0 0 4 5 3 1 0 0 0 0 0 0
[10:51:50.004] DEBUG: <PixTestAlive.cc/aliveTest:L188> number of red-efficiency pixels: 0 0 1 0 0 0 4 5 3 1 0 0 0 0 0 0
[10:51:50.006] INFO: ----------------------------------------------------------------------
[10:51:50.006] INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[10:51:50.006] INFO: ----------------------------------------------------------------------
[10:51:50.008] DEBUG: <PixTest.cc/efficiencyMaps:L328> attempt #0
[10:51:52.919] INFO: Test took 2911ms.
[10:51:52.921] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:52.921] DEBUG: <PixTest.cc/efficiencyMaps:L339> eff result size = 0
[10:51:52.921] DEBUG: <PixTest.cc/efficiencyMaps:L344> Create hists MaskTest_C0 .. MaskTest_C15
[10:51:52.922] INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C15_V0
[10:51:53.229] INFO: PixTestAlive::maskTest() done
[10:51:53.229] INFO: number of mask-defect pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[10:51:53.230] INFO: ----------------------------------------------------------------------
[10:51:53.230] INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[10:51:53.230] INFO: ----------------------------------------------------------------------
[10:51:53.233] DEBUG: <PixTest.cc/efficiencyMaps:L328> attempt #0
[10:51:57.166] INFO: Test took 3933ms.
[10:51:57.179] ERROR: <api.cc/repackMapData:L1807> This pixel doesn't belong here: ROC 2 [3,7,1]. Expected [3,13,x]

[10:51:57.185] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:57.186] DEBUG: <PixTest.cc/efficiencyMaps:L339> eff result size = 66547
[10:51:57.186] DEBUG: <PixTest.cc/efficiencyMaps:L344> Create hists AddressDecodingTest_C0 .. AddressDecodingTest_C15
[10:51:57.494] INFO: PixTestAlive::addressDecodingTest() done
[10:51:57.494] INFO: number of address-decoding pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[10:51:57.494] INFO: PixTestAlive::doTest() done, duration: 11 seconds
[10:51:57.494] DEBUG: <PixTestAlive.cc/~PixTestAlive:L109> PixTestAlive dtor
[10:51:57.500] DEBUG: <PixTestBBMap.cc/init:L79> PixTestBBMap::init()
[10:51:57.500] DEBUG: <PixTestBBMap.cc/PixTestBBMap:L27> PixTestBBMap ctor(PixSetup &a, string, TGTab *)
[10:51:57.502] INFO: ######################################################################
[10:51:57.502] INFO: PixTestBBMap::doTest() Ntrig = 5, VcalS = 250 (high range)
[10:51:57.502] INFO: ######################################################################
[10:51:57.506] INFO: ---> dac: VthrComp name: calSMap ntrig: 5 dacrange: 0 .. 149 (30) hits flags = 2 (plus default)
[10:51:57.517] INFO: dacScan step from 0 .. 29
[10:51:57.518] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:52:15.870] WARNING: Channel 0 ROC 7: Readback start marker after 8 readouts!

[10:52:15.870] WARNING: Channel 0 ROC 7: Readback start marker after 8 readouts!

[10:52:17.562] INFO: Test took 20044ms.
[10:52:17.599] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:52:17.599] INFO: dacScan step from 30 .. 59
[10:52:17.599] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:52:33.621] WARNING: Channel 0 ROC 4: Readback start marker after 6 readouts!

[10:52:33.621] WARNING: Channel 0 ROC 4: Readback start marker after 10 readouts!

[10:52:35.260] WARNING: Channel 0 ROC 4: Readback start marker after 9 readouts!

[10:52:35.260] WARNING: Channel 0 ROC 4: Readback start marker after 7 readouts!

[10:52:40.808] INFO: Test took 23209ms.
[10:52:40.988] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:52:41.027] INFO: dacScan step from 60 .. 89
[10:52:41.027] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:53:07.831] INFO: Test took 26804ms.
[10:53:08.092] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:53:08.174] INFO: dacScan step from 90 .. 119
[10:53:08.174] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:53:34.806] INFO: Test took 26632ms.
[10:53:35.069] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:53:35.150] INFO: dacScan step from 120 .. 149
[10:53:35.150] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:53:58.798] INFO: Test took 23648ms.
[10:53:58.001] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:53:59.041] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[10:54:00.252] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[10:54:01.748] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[10:54:03.032] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[10:54:04.437] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[10:54:05.779] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[10:54:07.109] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[10:54:08.359] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[10:54:09.578] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[10:54:10.784] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[10:54:12.035] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[10:54:13.330] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[10:54:14.604] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[10:54:15.863] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[10:54:17.086] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[10:54:18.349] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[10:54:19.547] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 270233600
[10:54:19.594] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C0_V0
[10:54:19.595] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 73 (obtained for minval = 0) start: 73 .. 91 last peak: 41.1805 last sigma: 5.01817 lcuts[0] = 56.235 lcuts[1] = 91.3622
[10:54:19.595] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C1_V0
[10:54:19.595] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 81 (obtained for minval = 0) start: 76 .. 91 last peak: 48.0764 last sigma: 4.37624 lcuts[0] = 61.2051 lcuts[1] = 91.8389
[10:54:19.596] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C2_V0
[10:54:19.596] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 81 (obtained for minval = 0) start: 81 .. 99 last peak: 47.7972 last sigma: 5.19324 lcuts[0] = 63.3769 lcuts[1] = 99.7295
[10:54:19.596] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C3_V0
[10:54:19.597] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 76 (obtained for minval = 0) start: 76 .. 93 last peak: 45.1882 last sigma: 4.81424 lcuts[0] = 59.6309 lcuts[1] = 93.3306
[10:54:19.597] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C4_V0
[10:54:19.597] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 76 (obtained for minval = 0) start: 76 .. 93 last peak: 44.949 last sigma: 4.85162 lcuts[0] = 59.5038 lcuts[1] = 93.4652
[10:54:19.598] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C5_V0
[10:54:19.598] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 74 (obtained for minval = 0) start: 74 .. 92 last peak: 40.2191 last sigma: 5.20239 lcuts[0] = 55.8263 lcuts[1] = 92.243
[10:54:19.598] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C6_V0
[10:54:19.599] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 78 (obtained for minval = 0) start: 78 .. 96 last peak: 43.9064 last sigma: 5.26713 lcuts[0] = 59.7078 lcuts[1] = 96.5777
[10:54:19.599] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C7_V0
[10:54:19.599] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 73 (obtained for minval = 0) start: 73 .. 91 last peak: 41.7519 last sigma: 4.95076 lcuts[0] = 56.6042 lcuts[1] = 91.2596
[10:54:19.599] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C8_V0
[10:54:19.600] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 75 (obtained for minval = 0) start: 75 .. 94 last peak: 41.5896 last sigma: 5.25824 lcuts[0] = 57.3644 lcuts[1] = 94.1721
[10:54:19.600] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C9_V0
[10:54:19.600] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 85 (obtained for minval = 0) start: 84 .. 103 last peak: 49.019 last sigma: 5.47294 lcuts[0] = 65.4378 lcuts[1] = 103.748
[10:54:19.601] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C10_V0
[10:54:19.601] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 101 (obtained for minval = 0) start: 101 .. 124 last peak: 57.6563 last sigma: 6.68695 lcuts[0] = 77.7172 lcuts[1] = 124.526
[10:54:19.601] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C11_V0
[10:54:19.602] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 89 (obtained for minval = 0) start: 89 .. 110 last peak: 52.228 last sigma: 5.79375 lcuts[0] = 69.6093 lcuts[1] = 110.166
[10:54:19.602] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C12_V0
[10:54:19.602] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 80 (obtained for minval = 0) start: 80 .. 98 last peak: 48.0147 last sigma: 5.04194 lcuts[0] = 63.1405 lcuts[1] = 98.4341
[10:54:19.603] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C13_V0
[10:54:19.603] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 80 (obtained for minval = 0) start: 80 .. 101 last peak: 43.0127 last sigma: 5.80789 lcuts[0] = 60.4364 lcuts[1] = 101.092
[10:54:19.603] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C14_V0
[10:54:19.604] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 83 (obtained for minval = 0) start: 83 .. 102 last peak: 48.6834 last sigma: 5.34169 lcuts[0] = 64.7085 lcuts[1] = 102.1
[10:54:19.604] DEBUG: <PixTestBBMap.cc/doTest:L152> found 1 peaks in dist_thr_calSMap_VthrComp_C15_V0
[10:54:19.604] DEBUG: <PixTestBBMap.cc/fitPeaks:L259> cut for dead bump bonds: 84 (obtained for minval = 0) start: 76 .. 93 last peak: 44.394 last sigma: 4.95855 lcuts[0] = 59.2697 lcuts[1] = 93.9796
[10:54:19.606] INFO: PixTestBBMap::doTest() done, duration: 142 seconds
[10:54:19.606] INFO: number of dead bumps (per ROC): 1 0 0 0 0 3 1 2 2 1 0 0 0 2 0 1
[10:54:19.606] INFO: separation cut (per ROC): 74 82 82 77 77 75 79 74 76 86 102 90 81 81 84 85
[10:54:19.606] DEBUG: <PixTestBBMap.cc/~PixTestBBMap:L97> PixTestBBMap dtor
[10:54:19.678] DEBUG: <PixTestScurves.cc/setParameter:L92> set fOutputFilename =
[10:54:19.680] INFO: ######################################################################
[10:54:19.680] INFO: PixTestScurves::fullTest() ntrig = 50
[10:54:19.680] INFO: ######################################################################
[10:54:19.680] INFO: ----------------------------------------------------------------------
[10:54:19.680] INFO: PixTestScurves::scurves(Vcal), ntrig = 50
[10:54:19.680] INFO: ----------------------------------------------------------------------
[10:54:19.680] INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 149 (10) hits flags = 16 (plus default)
[10:54:19.690] INFO: dacScan step from 0 .. 9
[10:54:19.690] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:54:54.783] INFO: Test took 35093ms.
[10:54:54.851] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:54:54.851] INFO: dacScan step from 10 .. 19
[10:54:54.851] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:55:30.115] INFO: Test took 35264ms.
[10:55:30.181] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:55:30.181] INFO: dacScan step from 20 .. 29
[10:55:30.181] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:56:03.135] WARNING: Channel 0 ROC 7: Readback start marker after 1 readouts!

[10:56:03.135] WARNING: Channel 0 ROC 7: Readback start marker after 15 readouts!

[10:56:05.467] INFO: Test took 35286ms.
[10:56:05.532] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:56:05.532] INFO: dacScan step from 30 .. 39
[10:56:05.532] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:56:21.297] WARNING: Channel 0 ROC 5: Readback start marker after 7 readouts!

[10:56:21.297] WARNING: Channel 0 ROC 5: Readback start marker after 9 readouts!

[10:56:40.704] INFO: Test took 35172ms.
[10:56:40.770] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:56:40.770] INFO: dacScan step from 40 .. 49
[10:56:40.770] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:56:57.657] WARNING: Channel 0 ROC 3: Readback start marker after 7 readouts!

[10:56:57.657] WARNING: Channel 0 ROC 3: Readback start marker after 9 readouts!

[10:57:05.309] WARNING: Channel 0 ROC 6: Readback start marker after 6 readouts!

[10:57:05.309] WARNING: Channel 0 ROC 6: Readback start marker after 10 readouts!

[10:57:16.049] INFO: Test took 35279ms.
[10:57:16.116] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:57:16.116] INFO: dacScan step from 50 .. 59
[10:57:16.116] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:57:51.292] INFO: Test took 35176ms.
[10:57:51.356] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:57:51.356] INFO: dacScan step from 60 .. 69
[10:57:51.356] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:58:15.768] ERROR: <datapipe.cc/CheckEventID:L420> Channel 0 Event ID mismatch: local ID (93) != TBM ID (94)

[10:58:15.768] WARNING: Channel 0 ROC 0: Readback start marker after 15 readouts!

[10:58:15.768] WARNING: Channel 0 ROC 1: Readback start marker after 15 readouts!

[10:58:15.768] WARNING: Channel 0 ROC 2: Readback start marker after 15 readouts!

[10:58:15.768] WARNING: Channel 0 ROC 3: Readback start marker after 15 readouts!

[10:58:15.768] WARNING: Channel 0 ROC 4: Readback start marker after 15 readouts!

[10:58:15.768] WARNING: Channel 0 ROC 5: Readback start marker after 15 readouts!

[10:58:15.768] WARNING: Channel 0 ROC 6: Readback start marker after 15 readouts!

[10:58:15.768] WARNING: Channel 0 ROC 7: Readback start marker after 15 readouts!

[10:58:26.555] INFO: Test took 35199ms.
[10:58:26.622] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:58:26.623] INFO: dacScan step from 70 .. 79
[10:58:26.623] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:58:56.063] WARNING: Channel 0 ROC 7: Readback start marker after 11 readouts!

[10:58:56.063] WARNING: Channel 0 ROC 7: Readback start marker after 5 readouts!

[10:59:02.358] ERROR: <datapipe.cc/CheckEventID:L420> Channel 1 Event ID mismatch: local ID (188) != TBM ID (0)

[10:59:02.358] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (1) != Token Chain Length (8)

[10:59:02.358] ERROR: <datapipe.cc/CheckEventID:L420> Channel 1 Event ID mismatch: local ID (1) != TBM ID (189)

[10:59:02.358] WARNING: Channel 1 ROC 2: Readback start marker after 15 readouts!

[10:59:02.358] WARNING: Channel 1 ROC 3: Readback start marker after 15 readouts!

[10:59:02.358] WARNING: Channel 1 ROC 4: Readback start marker after 15 readouts!

[10:59:02.358] WARNING: Channel 1 ROC 5: Readback start marker after 15 readouts!

[10:59:02.358] WARNING: Channel 1 ROC 6: Readback start marker after 15 readouts!

[10:59:02.358] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!

[10:59:02.368] INFO: Test took 35745ms.
[10:59:02.473] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:59:02.474] INFO: dacScan step from 80 .. 89
[10:59:02.474] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:59:28.155] WARNING: Channel 0 ROC 0: Readback start marker after 3 readouts!

[10:59:28.155] WARNING: Channel 0 ROC 0: Readback start marker after 13 readouts!

[10:59:39.826] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (14) != Token Chain Length (8)

[10:59:39.826] ERROR: <datapipe.cc/CheckEventID:L420> Channel 1 Event ID mismatch: local ID (195) != TBM ID (196)

[10:59:39.826] WARNING: Channel 1 ROC 1: Readback start marker after 15 readouts!

[10:59:39.826] WARNING: Channel 1 ROC 2: Readback start marker after 15 readouts!

[10:59:39.826] WARNING: Channel 1 ROC 3: Readback start marker after 15 readouts!

[10:59:39.826] WARNING: Channel 1 ROC 4: Readback start marker after 15 readouts!

[10:59:39.826] WARNING: Channel 1 ROC 5: Readback start marker after 15 readouts!

[10:59:39.826] WARNING: Channel 1 ROC 6: Readback start marker after 15 readouts!

[10:59:39.826] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!

[10:59:41.806] INFO: Test took 39332ms.
[10:59:42.052] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:59:42.064] INFO: dacScan step from 90 .. 99
[10:59:42.064] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[10:59:55.749] WARNING: Channel 0 ROC 5: Readback start marker after 7 readouts!

[10:59:55.749] WARNING: Channel 0 ROC 5: Readback start marker after 9 readouts!

[11:00:01.472] WARNING: Channel 0 ROC 1: Readback start marker after 8 readouts!

[11:00:01.472] WARNING: Channel 0 ROC 1: Readback start marker after 8 readouts!

[11:00:18.295] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (14) != Token Chain Length (8)

[11:00:18.295] ERROR: <datapipe.cc/CheckEventID:L420> Channel 1 Event ID mismatch: local ID (16) != TBM ID (17)

[11:00:18.295] WARNING: Channel 1 ROC 1: Readback start marker after 15 readouts!

[11:00:18.295] WARNING: Channel 1 ROC 2: Readback start marker after 15 readouts!

[11:00:18.295] WARNING: Channel 1 ROC 3: Readback start marker after 15 readouts!

[11:00:18.295] WARNING: Channel 1 ROC 4: Readback start marker after 15 readouts!

[11:00:18.295] WARNING: Channel 1 ROC 5: Readback start marker after 15 readouts!

[11:00:18.295] WARNING: Channel 1 ROC 6: Readback start marker after 15 readouts!

[11:00:18.295] WARNING: Channel 1 ROC 7: Readback start marker after 31 readouts!

[11:00:28.998] WARNING: Channel 0 ROC 4: Readback start marker after 8 readouts!

[11:00:28.998] WARNING: Channel 0 ROC 4: Readback start marker after 8 readouts!

[11:00:29.394] INFO: Test took 47330ms.
[11:00:29.850] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:00:29.870] INFO: dacScan step from 100 .. 109
[11:00:29.870] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:01:02.468] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (14) != Token Chain Length (8)

[11:01:02.468] ERROR: <datapipe.cc/CheckEventID:L420> Channel 1 Event ID mismatch: local ID (27) != TBM ID (28)

[11:01:02.468] WARNING: Channel 1 ROC 1: Readback start marker after 15 readouts!

[11:01:02.468] WARNING: Channel 1 ROC 2: Readback start marker after 15 readouts!

[11:01:02.468] WARNING: Channel 1 ROC 3: Readback start marker after 15 readouts!

[11:01:02.468] WARNING: Channel 1 ROC 4: Readback start marker after 15 readouts!

[11:01:02.468] WARNING: Channel 1 ROC 5: Readback start marker after 15 readouts!

[11:01:02.468] WARNING: Channel 1 ROC 6: Readback start marker after 15 readouts!

[11:01:02.468] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!

[11:01:24.159] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (4) != Token Chain Length (8)

[11:01:24.159] WARNING: Channel 1 ROC 5: Readback start marker after 15 readouts!

[11:01:24.159] WARNING: Channel 1 ROC 6: Readback start marker after 15 readouts!

[11:01:24.159] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!

[11:01:24.976] INFO: Test took 55106ms.
[11:01:25.542] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:01:25.569] INFO: dacScan step from 110 .. 119
[11:01:25.569] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:01:44.083] WARNING: Channel 0 ROC 5: Readback start marker after 13 readouts!

[11:01:44.083] WARNING: Channel 0 ROC 5: Readback start marker after 3 readouts!

[11:01:56.755] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (4) != Token Chain Length (8)

[11:01:56.755] WARNING: Channel 1 ROC 5: Readback start marker after 15 readouts!

[11:01:56.755] WARNING: Channel 1 ROC 6: Readback start marker after 15 readouts!

[11:01:56.755] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!

[11:02:18.777] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (4) != Token Chain Length (8)

[11:02:18.777] WARNING: Channel 1 ROC 5: Readback start marker after 15 readouts!

[11:02:18.777] WARNING: Channel 1 ROC 6: Readback start marker after 15 readouts!

[11:02:18.777] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!

[11:02:23.124] INFO: Test took 57555ms.
[11:02:23.683] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:02:23.714] INFO: dacScan step from 120 .. 129
[11:02:23.715] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:02:54.590] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (6) != Token Chain Length (8)

[11:02:54.591] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!

[11:03:16.907] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (6) != Token Chain Length (8)

[11:03:16.910] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!

[11:03:22.355] INFO: Test took 58640ms.
[11:03:22.917] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:03:22.949] INFO: dacScan step from 130 .. 139
[11:03:22.949] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:03:54.141] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (14) != Token Chain Length (8)

[11:03:54.141] ERROR: <datapipe.cc/CheckEventID:L420> Channel 1 Event ID mismatch: local ID (74) != TBM ID (75)

[11:03:54.141] WARNING: Channel 1 ROC 1: Readback start marker after 15 readouts!

[11:03:54.141] WARNING: Channel 1 ROC 2: Readback start marker after 15 readouts!

[11:03:54.141] WARNING: Channel 1 ROC 3: Readback start marker after 15 readouts!

[11:03:54.141] WARNING: Channel 1 ROC 4: Readback start marker after 15 readouts!

[11:03:54.141] WARNING: Channel 1 ROC 5: Readback start marker after 15 readouts!

[11:03:54.141] WARNING: Channel 1 ROC 6: Readback start marker after 15 readouts!

[11:03:54.141] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!

[11:04:16.645] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (6) != Token Chain Length (8)

[11:04:16.645] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!

[11:04:22.483] INFO: Test took 59534ms.
[11:04:23.054] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:04:23.086] INFO: dacScan step from 140 .. 149
[11:04:23.086] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:04:53.787] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (4) != Token Chain Length (8)

[11:04:53.787] WARNING: Channel 1 ROC 5: Readback start marker after 15 readouts!

[11:04:53.787] WARNING: Channel 1 ROC 6: Readback start marker after 15 readouts!

[11:04:53.787] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!

[11:05:10.000] WARNING: Channel 0 ROC 5: Readback start marker after 5 readouts!

[11:05:10.000] WARNING: Channel 0 ROC 5: Readback start marker after 11 readouts!

[11:05:15.377] ERROR: <datapipe.cc/CheckEventValidity:L437> Channel 1 Number of ROCs (6) != Token Chain Length (8)

[11:05:15.377] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!

[11:05:20.612] INFO: Test took 57526ms.
[11:05:21.173] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:05:21.206] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[11:05:21.206] INFO: dumping ASCII scurve output file: SCurveData
[11:05:22.498] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[11:05:22.498] INFO: dumping ASCII scurve output file: SCurveData
[11:05:23.755] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[11:05:23.755] INFO: dumping ASCII scurve output file: SCurveData
[11:05:24.998] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[11:05:24.998] INFO: dumping ASCII scurve output file: SCurveData
[11:05:26.259] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[11:05:26.259] INFO: dumping ASCII scurve output file: SCurveData
[11:05:27.541] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[11:05:27.541] INFO: dumping ASCII scurve output file: SCurveData
[11:05:28.819] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[11:05:28.819] INFO: dumping ASCII scurve output file: SCurveData
[11:05:30.085] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[11:05:30.085] INFO: dumping ASCII scurve output file: SCurveData
[11:05:31.367] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[11:05:31.367] INFO: dumping ASCII scurve output file: SCurveData
[11:05:32.629] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[11:05:32.629] INFO: dumping ASCII scurve output file: SCurveData
[11:05:33.878] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[11:05:33.878] INFO: dumping ASCII scurve output file: SCurveData
[11:05:35.101] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[11:05:35.101] INFO: dumping ASCII scurve output file: SCurveData
[11:05:36.345] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[11:05:36.345] INFO: dumping ASCII scurve output file: SCurveData
[11:05:37.594] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[11:05:37.594] INFO: dumping ASCII scurve output file: SCurveData
[11:05:38.843] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[11:05:38.843] INFO: dumping ASCII scurve output file: SCurveData
[11:05:40.100] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[11:05:40.100] INFO: dumping ASCII scurve output file: SCurveData
[11:05:41.371] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 625446912
[11:05:41.418] INFO: PixTestScurves::scurves() done
[11:05:41.418] INFO: Vcal mean: 80.03 96.86 100.72 90.15 91.36 89.27 96.81 83.14 89.00 95.60 110.45 96.88 97.40 96.81 96.88 90.99
[11:05:41.418] INFO: Vcal RMS: 4.29 5.69 6.11 6.15 5.64 5.67 6.07 5.81 6.32 6.27 5.74 6.06 5.97 5.91 5.82 6.33
[11:05:41.418] INFO: PixTestScurves::fullTest() done, duration: 681 seconds
[11:05:41.418] DEBUG: <PixTestScurves.cc/~PixTestScurves:L141> PixTestScurves dtor
[11:05:41.481] INFO: ######################################################################
[11:05:41.481] INFO: PixTestTrim::doTest()
[11:05:41.481] INFO: ######################################################################
[11:05:41.482] INFO: ----------------------------------------------------------------------
[11:05:41.482] INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[11:05:41.482] INFO: ----------------------------------------------------------------------
[11:05:41.552] INFO: ---> VthrComp thr map (minimal VthrComp)
[11:05:41.552] INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 5 dacrange: 0 .. 159 (20) hits flags = 16 (plus default)
[11:05:41.561] INFO: dacScan step from 0 .. 19
[11:05:41.561] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:05:55.549] INFO: Test took 13988ms.
[11:05:55.572] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:05:55.572] INFO: dacScan step from 20 .. 39
[11:05:55.572] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:06:06.847] WARNING: Channel 0 ROC 6: Readback start marker after 6 readouts!

[11:06:06.847] WARNING: Channel 0 ROC 6: Readback start marker after 10 readouts!

[11:06:09.205] WARNING: Channel 0 ROC 3: Readback start marker after 1 readouts!

[11:06:09.205] WARNING: Channel 0 ROC 3: Readback start marker after 15 readouts!

[11:06:09.694] INFO: Test took 14122ms.
[11:06:09.718] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:06:09.718] INFO: dacScan step from 40 .. 59
[11:06:09.718] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:06:22.876] WARNING: Channel 0 ROC 7: Readback start marker after 8 readouts!

[11:06:22.876] WARNING: Channel 0 ROC 7: Readback start marker after 8 readouts!

[11:06:23.829] INFO: Test took 14111ms.
[11:06:23.852] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:06:23.852] INFO: dacScan step from 60 .. 79
[11:06:23.852] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:06:35.878] WARNING: Channel 0 ROC 7: Readback start marker after 9 readouts!

[11:06:35.878] WARNING: Channel 0 ROC 7: Readback start marker after 7 readouts!

[11:06:37.902] INFO: Test took 14050ms.
[11:06:37.924] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:06:37.924] INFO: dacScan step from 80 .. 99
[11:06:37.924] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:06:52.296] INFO: Test took 14372ms.
[11:06:52.343] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:06:52.348] INFO: dacScan step from 100 .. 119
[11:06:52.348] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:07:08.982] INFO: Test took 16634ms.
[11:07:09.133] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:07:09.165] INFO: dacScan step from 120 .. 139
[11:07:09.166] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:07:26.562] INFO: Test took 17396ms.
[11:07:26.712] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:07:26.743] INFO: dacScan step from 140 .. 159
[11:07:26.743] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:07:41.310] INFO: Test took 14567ms.
[11:07:41.374] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:07:41.382] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[11:07:42.491] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[11:07:43.620] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[11:07:44.775] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[11:07:45.904] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[11:07:47.007] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[11:07:48.143] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[11:07:49.315] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[11:07:50.451] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[11:07:51.563] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[11:07:52.728] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[11:07:53.901] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[11:07:55.085] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[11:07:56.280] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[11:07:57.422] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[11:07:58.614] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[11:07:59.735] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 625549312
[11:07:59.736] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 84.0627 minThrLimit = 83.9737 minThrNLimit = 105.471 -> result = 84.0627 -> 84
[11:07:59.737] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 96.1818 minThrLimit = 96.1678 minThrNLimit = 113.349 -> result = 96.1818 -> 96
[11:07:59.737] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 99.0343 minThrLimit = 99.022 minThrNLimit = 119.235 -> result = 99.0343 -> 99
[11:07:59.737] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 90.5421 minThrLimit = 90.5333 minThrNLimit = 109.388 -> result = 90.5421 -> 90
[11:07:59.738] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 89.2982 minThrLimit = 89.2374 minThrNLimit = 108.73 -> result = 89.2982 -> 89
[11:07:59.738] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 89.986 minThrLimit = 89.9264 minThrNLimit = 109.624 -> result = 89.986 -> 89
[11:07:59.738] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 99.8377 minThrLimit = 99.8065 minThrNLimit = 121.436 -> result = 99.8377 -> 99
[11:07:59.739] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 87.9239 minThrLimit = 87.7803 minThrNLimit = 111.463 -> result = 87.9239 -> 87
[11:07:59.739] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 88.9091 minThrLimit = 88.8166 minThrNLimit = 107.658 -> result = 88.9091 -> 88
[11:07:59.739] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 96.8621 minThrLimit = 96.8083 minThrNLimit = 118.878 -> result = 96.8621 -> 96
[11:07:59.740] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 104.73 minThrLimit = 104.727 minThrNLimit = 127.557 -> result = 104.73 -> 104
[11:07:59.740] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 99.5171 minThrLimit = 99.4976 minThrNLimit = 124.055 -> result = 99.5171 -> 99
[11:07:59.740] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 98.7151 minThrLimit = 98.713 minThrNLimit = 124.255 -> result = 98.7151 -> 98
[11:07:59.741] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 97.3516 minThrLimit = 97.3218 minThrNLimit = 116.993 -> result = 97.3516 -> 97
[11:07:59.741] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 99.9635 minThrLimit = 99.9482 minThrNLimit = 123.85 -> result = 99.9635 -> 99
[11:07:59.741] DEBUG: <PixTest.cc/getMinimumVthrComp:L1208> minThr = 90.7793 minThrLimit = 90.705 minThrNLimit = 110.936 -> result = 90.7793 -> 90
[11:07:59.741] INFO: ROC 0 VthrComp = 84
[11:07:59.741] INFO: ROC 1 VthrComp = 96
[11:07:59.742] INFO: ROC 2 VthrComp = 99
[11:07:59.742] INFO: ROC 3 VthrComp = 90
[11:07:59.742] INFO: ROC 4 VthrComp = 89
[11:07:59.742] INFO: ROC 5 VthrComp = 89
[11:07:59.742] INFO: ROC 6 VthrComp = 99
[11:07:59.742] INFO: ROC 7 VthrComp = 87
[11:07:59.742] INFO: ROC 8 VthrComp = 88
[11:07:59.743] INFO: ROC 9 VthrComp = 96
[11:07:59.743] INFO: ROC 10 VthrComp = 104
[11:07:59.743] INFO: ROC 11 VthrComp = 99
[11:07:59.743] INFO: ROC 12 VthrComp = 98
[11:07:59.743] INFO: ROC 13 VthrComp = 97
[11:07:59.744] INFO: ROC 14 VthrComp = 99
[11:07:59.744] INFO: ROC 15 VthrComp = 90
[11:07:59.744] INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[11:07:59.744] INFO: ---> dac: vcal name: TrimThr1 ntrig: 5 dacrange: 0 .. 159 (20) hits flags = 16 (plus default)
[11:07:59.754] INFO: dacScan step from 0 .. 19
[11:07:59.754] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:08:13.810] INFO: Test took 14056ms.
[11:08:13.833] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:08:13.833] INFO: dacScan step from 20 .. 39
[11:08:13.834] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:08:28.072] INFO: Test took 14238ms.
[11:08:28.107] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:08:28.109] INFO: dacScan step from 40 .. 59
[11:08:28.110] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:08:45.022] INFO: Test took 16912ms.
[11:08:45.172] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:08:45.208] INFO: dacScan step from 60 .. 79
[11:08:45.208] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:08:56.294] ERROR: <datapipe.cc/CheckEventID:L420> Channel 0 Event ID mismatch: local ID (72) != TBM ID (73)

[11:08:56.294] WARNING: Channel 0 ROC 0: Readback start marker after 15 readouts!

[11:08:56.294] WARNING: Channel 0 ROC 1: Readback start marker after 15 readouts!

[11:08:56.294] WARNING: Channel 0 ROC 2: Readback start marker after 15 readouts!

[11:08:56.294] WARNING: Channel 0 ROC 3: Readback start marker after 15 readouts!

[11:08:56.294] WARNING: Channel 0 ROC 4: Readback start marker after 15 readouts!

[11:08:56.294] WARNING: Channel 0 ROC 5: Readback start marker after 15 readouts!

[11:08:56.294] WARNING: Channel 0 ROC 6: Readback start marker after 15 readouts!

[11:08:56.294] WARNING: Channel 0 ROC 7: Readback start marker after 15 readouts!

[11:09:03.784] INFO: Test took 18576ms.
[11:09:03.954] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:09:04.009] INFO: dacScan step from 80 .. 99
[11:09:04.009] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:09:22.546] INFO: Test took 18537ms.
[11:09:22.711] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:09:22.766] INFO: dacScan step from 100 .. 119
[11:09:22.766] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:09:40.812] INFO: Test took 18046ms.
[11:09:40.973] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:09:41.028] INFO: dacScan step from 120 .. 139
[11:09:41.028] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:10:00.011] INFO: Test took 18983ms.
[11:10:00.174] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:10:00.228] INFO: dacScan step from 140 .. 159
[11:10:00.229] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:10:18.787] INFO: Test took 18558ms.
[11:10:18.951] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:10:19.006] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[11:10:20.366] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[11:10:21.755] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[11:10:23.155] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[11:10:24.541] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[11:10:25.917] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[11:10:27.305] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[11:10:28.698] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[11:10:30.073] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[11:10:31.460] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[11:10:32.818] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[11:10:34.215] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[11:10:35.583] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[11:10:36.943] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[11:10:38.316] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[11:10:39.686] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[11:10:41.060] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 625549312
[11:10:41.062] INFO: roc 0 with ID = 0 has maximal Vcal 57.612 for pixel 12/12 mean/min/max = 44.7576/31.7667/57.7485
[11:10:41.062] INFO: roc 1 with ID = 1 has maximal Vcal 59.3141 for pixel 20/9 mean/min/max = 45.6906/31.9777/59.4035
[11:10:41.063] INFO: roc 2 with ID = 2 has maximal Vcal 60.7299 for pixel 20/79 mean/min/max = 45.9762/30.9875/60.9648
[11:10:41.063] INFO: roc 3 with ID = 3 has maximal Vcal 61.9502 for pixel 0/18 mean/min/max = 47.3591/32.3336/62.3846
[11:10:41.063] INFO: roc 4 with ID = 4 has maximal Vcal 63.5833 for pixel 13/79 mean/min/max = 46.5578/29.4453/63.6703
[11:10:41.064] INFO: roc 5 with ID = 5 has maximal Vcal 62.4185 for pixel 2/20 mean/min/max = 47.8029/33.1726/62.4331
[11:10:41.064] INFO: roc 6 with ID = 6 has maximal Vcal 59.0226 for pixel 17/18 mean/min/max = 46.0653/33.0978/59.0327
[11:10:41.064] INFO: roc 7 with ID = 7 has maximal Vcal 59.3414 for pixel 3/0 mean/min/max = 45.8521/32.1793/59.5249
[11:10:41.064] INFO: roc 8 with ID = 8 has maximal Vcal 62.1043 for pixel 0/7 mean/min/max = 47.8178/33.244/62.3916
[11:10:41.065] INFO: roc 9 with ID = 9 has maximal Vcal 60.847 for pixel 0/72 mean/min/max = 46.1357/31.3557/60.9158
[11:10:41.065] INFO: roc 10 with ID = 10 has maximal Vcal 67.2213 for pixel 3/34 mean/min/max = 50.4817/33.6981/67.2654
[11:10:41.065] INFO: roc 11 with ID = 11 has maximal Vcal 60.5832 for pixel 14/7 mean/min/max = 46.1567/31.4541/60.8592
[11:10:41.065] INFO: roc 12 with ID = 12 has maximal Vcal 61.1225 for pixel 5/70 mean/min/max = 46.4401/31.7114/61.1688
[11:10:41.066] INFO: roc 13 with ID = 13 has maximal Vcal 59.9968 for pixel 19/8 mean/min/max = 45.8309/31.5272/60.1347
[11:10:41.066] INFO: roc 14 with ID = 14 has maximal Vcal 60.308 for pixel 32/70 mean/min/max = 46.2798/32.1158/60.4439
[11:10:41.066] INFO: roc 15 with ID = 15 has maximal Vcal 60.5008 for pixel 23/70 mean/min/max = 46.3749/32.1185/60.6314
[11:10:41.066] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:11:57.429] INFO: Test took 76363ms.
[11:11:58.273] DEBUG: <PixTestTrim.cc/trimTest:L309> vtrim: vcal = 35.8869 < 35 for itrim+1 = 111; old thr = 34.8629 ... break
[11:11:58.294] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.0524 < 35 for itrim = 109; old thr = 33.7107 ... break
[11:11:58.311] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.1262 < 35 for itrim = 99; old thr = 34.6354 ... break
[11:11:58.336] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.0539 < 35 for itrim = 102; old thr = 34.2769 ... break
[11:11:58.359] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.2557 < 35 for itrim = 116; old thr = 33.3129 ... break
[11:11:58.382] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.0957 < 35 for itrim = 113; old thr = 32.6886 ... break
[11:11:58.406] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.8349 < 35 for itrim = 109; old thr = 33.6381 ... break
[11:11:58.432] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.3431 < 35 for itrim = 102; old thr = 33.0477 ... break
[11:11:58.454] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.3043 < 35 for itrim = 106; old thr = 34.5756 ... break
[11:11:58.477] DEBUG: <PixTestTrim.cc/trimTest:L309> vtrim: vcal = 35.6128 < 35 for itrim+1 = 116; old thr = 34.4462 ... break
[11:11:58.501] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.4808 < 35 for itrim = 126; old thr = 34.0915 ... break
[11:11:58.532] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.1453 < 35 for itrim = 103; old thr = 34.7634 ... break
[11:11:58.562] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.6089 < 35 for itrim = 120; old thr = 34.2371 ... break
[11:11:58.587] DEBUG: <PixTestTrim.cc/trimTest:L309> vtrim: vcal = 36.4801 < 35 for itrim+1 = 99; old thr = 34.1154 ... break
[11:11:58.617] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.3971 < 35 for itrim = 106; old thr = 34.2014 ... break
[11:11:58.646] DEBUG: <PixTestTrim.cc/trimTest:L304> vtrim: vcal = 35.2941 < 35 for itrim = 111; old thr = 33.0375 ... break
[11:11:58.709] INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 199 (20) hits flags = 16 (plus default)
[11:11:58.718] INFO: dacScan step from 0 .. 19
[11:11:58.718] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:12:18.791] INFO: Test took 20073ms.
[11:12:18.844] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:12:18.846] INFO: dacScan step from 20 .. 39
[11:12:18.846] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:12:43.240] INFO: Test took 24394ms.
[11:12:43.471] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:12:43.508] INFO: dacScan step from 40 .. 59
[11:12:43.508] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:13:12.446] INFO: Test took 28938ms.
[11:13:12.726] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:12.781] INFO: dacScan step from 60 .. 79
[11:13:12.781] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:13:36.033] WARNING: Channel 0 ROC 5: Readback start marker after 11 readouts!

[11:13:36.033] WARNING: Channel 0 ROC 5: Readback start marker after 5 readouts!

[11:13:41.711] INFO: Test took 28930ms.
[11:13:41.990] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:42.044] INFO: dacScan step from 80 .. 99
[11:13:42.044] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:14:11.136] INFO: Test took 29092ms.
[11:14:11.416] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:11.481] INFO: dacScan step from 100 .. 119
[11:14:11.481] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:14:36.737] WARNING: Channel 0 ROC 5: Readback start marker after 3 readouts!

[11:14:36.737] WARNING: Channel 0 ROC 5: Readback start marker after 13 readouts!

[11:14:40.612] INFO: Test took 29131ms.
[11:14:40.888] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:40.941] INFO: dacScan step from 120 .. 139
[11:14:40.942] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:15:10.678] INFO: Test took 29736ms.
[11:15:10.960] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:11.015] INFO: dacScan step from 140 .. 159
[11:15:11.015] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:15:40.136] INFO: Test took 29121ms.
[11:15:40.414] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:40.469] INFO: dacScan step from 160 .. 179
[11:15:40.469] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:16:04.313] WARNING: Channel 0 ROC 6: Readback start marker after 7 readouts!

[11:16:04.313] WARNING: Channel 0 ROC 6: Readback start marker after 9 readouts!

[11:16:08.890] INFO: Test took 28421ms.
[11:16:09.165] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:16:09.219] INFO: dacScan step from 180 .. 199
[11:16:09.219] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:16:38.801] INFO: Test took 29582ms.
[11:16:39.079] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:16:39.134] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[11:16:40.533] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[11:16:41.971] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[11:16:43.405] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[11:16:44.834] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[11:16:46.243] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[11:16:47.640] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[11:16:49.049] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[11:16:50.427] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[11:16:51.818] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[11:16:53.195] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[11:16:54.598] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[11:16:55.960] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[11:16:57.334] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[11:16:58.727] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[11:17:00.099] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[11:17:01.484] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 625561600
[11:17:01.485] INFO: ---> TrimStepCorr4 extremal thresholds: 0.056126 .. 255.000000
[11:17:01.549] INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 4 dacrange: 0 .. 255 (20) hits flags = 16 (plus default)
[11:17:01.558] INFO: dacScan step from 0 .. 19
[11:17:01.558] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:17:14.447] INFO: Test took 12889ms.
[11:17:14.469] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:17:14.469] INFO: dacScan step from 20 .. 39
[11:17:14.469] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:17:28.294] INFO: Test took 13825ms.
[11:17:28.390] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:17:28.408] INFO: dacScan step from 40 .. 59
[11:17:28.408] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:17:44.755] INFO: Test took 16347ms.
[11:17:44.907] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:17:44.961] INFO: dacScan step from 60 .. 79
[11:17:44.962] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:18:01.399] INFO: Test took 16437ms.
[11:18:01.541] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:18:01.596] INFO: dacScan step from 80 .. 99
[11:18:01.596] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:18:18.038] INFO: Test took 16441ms.
[11:18:18.182] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:18:18.238] INFO: dacScan step from 100 .. 119
[11:18:18.238] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:18:34.871] INFO: Test took 16633ms.
[11:18:35.019] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:18:35.073] INFO: dacScan step from 120 .. 139
[11:18:35.073] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:18:50.834] WARNING: Channel 0 ROC 0: Readback start marker after 6 readouts!

[11:18:50.837] WARNING: Channel 0 ROC 0: Readback start marker after 10 readouts!

[11:18:52.249] INFO: Test took 17176ms.
[11:18:52.394] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:18:52.450] INFO: dacScan step from 140 .. 159
[11:18:52.450] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:19:09.083] INFO: Test took 16633ms.
[11:19:09.226] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:19:09.279] INFO: dacScan step from 160 .. 179
[11:19:09.279] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:19:25.485] INFO: Test took 16206ms.
[11:19:25.627] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:19:25.681] INFO: dacScan step from 180 .. 199
[11:19:25.681] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:19:42.317] INFO: Test took 16636ms.
[11:19:42.458] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:19:42.512] INFO: dacScan step from 200 .. 219
[11:19:42.512] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:19:58.835] INFO: Test took 16323ms.
[11:19:58.976] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:19:59.032] INFO: dacScan step from 220 .. 239
[11:19:59.033] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:20:15.483] INFO: Test took 16450ms.
[11:20:15.630] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:20:15.704] INFO: dacScan step from 240 .. 255
[11:20:15.704] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:20:29.086] INFO: Test took 13382ms.
[11:20:29.200] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:20:29.245] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[11:20:30.929] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[11:20:32.643] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[11:20:34.366] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[11:20:36.076] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[11:20:37.794] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[11:20:39.503] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[11:20:41.217] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[11:20:42.924] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[11:20:44.646] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[11:20:46.343] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[11:20:48.067] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[11:20:49.769] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[11:20:51.491] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[11:20:53.215] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[11:20:54.939] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[11:20:56.668] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 625582080
[11:20:56.734] INFO: ---> TrimStepCorr2 extremal thresholds: 4.414118 .. 60.213944
[11:20:56.798] INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 4 dacrange: 4 .. 70 (20) hits flags = 16 (plus default)
[11:20:56.807] INFO: dacScan step from 4 .. 23
[11:20:56.807] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:21:09.195] WARNING: Channel 0 ROC 5: Readback start marker after 1 readouts!

[11:21:09.195] WARNING: Channel 0 ROC 5: Readback start marker after 15 readouts!

[11:21:09.582] INFO: Test took 12775ms.
[11:21:09.604] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:21:09.605] INFO: dacScan step from 24 .. 43
[11:21:09.605] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:21:24.194] INFO: Test took 14588ms.
[11:21:24.304] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:21:24.333] INFO: dacScan step from 44 .. 63
[11:21:24.333] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:21:40.783] INFO: Test took 16450ms.
[11:21:40.928] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:21:40.985] INFO: dacScan step from 64 .. 70
[11:21:40.985] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:21:48.421] INFO: Test took 7436ms.
[11:21:48.472] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:21:48.493] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[11:21:49.457] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[11:21:50.431] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[11:21:51.409] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[11:21:52.377] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[11:21:53.352] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[11:21:54.333] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[11:21:55.309] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[11:21:56.288] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[11:21:57.270] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[11:21:58.251] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[11:21:59.235] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[11:22:00.273] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[11:22:01.239] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[11:22:02.213] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[11:22:03.182] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[11:22:04.153] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 625704960
[11:22:04.220] INFO: ---> TrimStepCorr1a extremal thresholds: 4.414118 .. 52.462440
[11:22:04.285] INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 4 dacrange: 4 .. 62 (20) hits flags = 16 (plus default)
[11:22:04.294] INFO: dacScan step from 4 .. 23
[11:22:04.294] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:22:17.003] INFO: Test took 12709ms.
[11:22:17.025] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:22:17.025] INFO: dacScan step from 24 .. 43
[11:22:17.025] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:22:27.739] WARNING: Channel 0 ROC 3: Readback start marker after 11 readouts!

[11:22:27.739] WARNING: Channel 0 ROC 3: Readback start marker after 5 readouts!

[11:22:31.460] INFO: Test took 14435ms.
[11:22:31.567] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:22:31.597] INFO: dacScan step from 44 .. 62
[11:22:31.598] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:22:47.336] INFO: Test took 15738ms.
[11:22:47.472] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:22:47.526] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[11:22:48.428] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[11:22:49.327] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[11:22:50.228] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[11:22:51.129] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[11:22:52.032] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[11:22:52.932] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[11:22:53.834] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[11:22:54.736] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[11:22:55.636] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[11:22:56.540] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[11:22:57.444] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[11:22:58.345] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[11:22:59.243] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[11:23:00.146] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[11:23:01.046] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[11:23:01.952] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 625704960
[11:23:02.019] INFO: ---> TrimStepCorr1b extremal thresholds: 0.338933 .. 39.217631
[11:23:02.082] INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 4 dacrange: 0 .. 49 (20) hits flags = 16 (plus default)
[11:23:02.090] INFO: dacScan step from 0 .. 19
[11:23:02.090] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:23:14.910] INFO: Test took 12820ms.
[11:23:14.931] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:23:14.931] INFO: dacScan step from 20 .. 39
[11:23:14.931] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:23:28.433] INFO: Test took 13502ms.
[11:23:28.506] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:23:28.524] INFO: dacScan step from 40 .. 49
[11:23:28.524] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:23:38.146] INFO: Test took 9622ms.
[11:23:38.223] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:23:38.252] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[11:23:39.041] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[11:23:39.830] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[11:23:40.618] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[11:23:41.406] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[11:23:42.199] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[11:23:42.986] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[11:23:43.772] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[11:23:44.560] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[11:23:45.346] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[11:23:46.136] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[11:23:46.925] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[11:23:47.715] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[11:23:48.501] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[11:23:49.291] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[11:23:50.079] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[11:23:50.871] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 625709056
[11:23:50.943] INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[11:23:50.943] INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (20) hits flags = 16 (plus default)
[11:23:50.952] INFO: dacScan step from 15 .. 34
[11:23:50.952] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:24:05.140] WARNING: Channel 0 ROC 5: Readback start marker after 6 readouts!

[11:24:05.140] WARNING: Channel 0 ROC 5: Readback start marker after 10 readouts!

[11:24:05.680] WARNING: Channel 0 ROC 6: Readback start marker after 8 readouts!

[11:24:05.680] WARNING: Channel 0 ROC 6: Readback start marker after 8 readouts!

[11:24:11.158] INFO: Test took 20206ms.
[11:24:11.231] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:24:11.243] INFO: dacScan step from 35 .. 54
[11:24:11.243] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:24:39.241] INFO: Test took 27998ms.
[11:24:39.538] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:24:39.593] INFO: dacScan step from 55 .. 55
[11:24:39.593] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:24:43.707] INFO: Test took 4114ms.
[11:24:43.723] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:24:43.727] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[11:24:44.478] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[11:24:45.222] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[11:24:45.969] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[11:24:46.721] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[11:24:47.470] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[11:24:48.223] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[11:24:48.969] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[11:24:49.709] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[11:24:50.436] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[11:24:51.167] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[11:24:51.895] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[11:24:52.627] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[11:24:53.359] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[11:24:54.088] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[11:24:54.821] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[11:24:55.554] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 625709056
[11:24:55.605] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C0.dat
[11:24:55.605] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C1.dat
[11:24:55.605] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C2.dat
[11:24:55.605] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C3.dat
[11:24:55.605] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C4.dat
[11:24:55.606] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C5.dat
[11:24:55.606] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C6.dat
[11:24:55.606] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C7.dat
[11:24:55.606] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C8.dat
[11:24:55.606] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C9.dat
[11:24:55.606] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C10.dat
[11:24:55.606] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C11.dat
[11:24:55.606] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C12.dat
[11:24:55.606] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C13.dat
[11:24:55.606] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C14.dat
[11:24:55.606] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C15.dat
[11:24:55.606] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//trimParameters35_C0.dat
[11:24:55.613] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//trimParameters35_C1.dat
[11:24:55.619] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//trimParameters35_C2.dat
[11:24:55.625] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//trimParameters35_C3.dat
[11:24:55.630] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//trimParameters35_C4.dat
[11:24:55.635] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//trimParameters35_C5.dat
[11:24:55.641] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//trimParameters35_C6.dat
[11:24:55.646] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//trimParameters35_C7.dat
[11:24:55.652] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//trimParameters35_C8.dat
[11:24:55.657] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//trimParameters35_C9.dat
[11:24:55.662] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//trimParameters35_C10.dat
[11:24:55.668] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//trimParameters35_C11.dat
[11:24:55.673] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//trimParameters35_C12.dat
[11:24:55.678] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//trimParameters35_C13.dat
[11:24:55.684] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//trimParameters35_C14.dat
[11:24:55.689] INFO: write trim parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//trimParameters35_C15.dat
[11:24:55.694] INFO: PixTestTrim::trimTest() done
[11:24:55.694] INFO: vtrim: 111 109 99 102 116 113 109 102 106 116 126 103 120 99 106 111
[11:24:55.694] INFO: vthrcomp: 84 96 99 90 89 89 99 87 88 96 104 99 98 97 99 90
[11:24:55.694] INFO: vcal mean: 35.02 35.10 35.02 35.06 35.10 35.07 35.06 35.02 35.05 35.04 35.10 35.02 35.04 35.03 35.06 35.07
[11:24:55.694] INFO: vcal RMS: 1.08 1.18 1.29 1.11 1.22 1.14 1.60 1.54 1.60 1.19 1.17 1.22 1.13 1.18 1.07 1.22
[11:24:55.694] INFO: bits mean: 10.30 10.14 9.90 8.79 10.01 9.73 9.95 9.97 9.21 10.17 8.84 9.82 9.70 9.89 9.42 9.92
[11:24:55.694] INFO: bits RMS: 2.41 2.45 2.59 2.89 2.36 2.31 2.36 2.41 2.52 2.37 2.42 2.62 2.59 2.56 2.70 2.45
[11:24:55.704] INFO: ----------------------------------------------------------------------
[11:24:55.704] INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[11:24:55.704] INFO: ----------------------------------------------------------------------
[11:24:55.708] DEBUG: <PixTestTrim.cc/trimBitTest:L518> trimBitTest determine threshold map without trims
[11:24:55.708] INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (20) hits flags = 16 (plus default)
[11:24:55.717] INFO: dacScan step from 0 .. 19
[11:24:55.717] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:25:14.405] WARNING: Channel 0 ROC 3: Readback start marker after 10 readouts!

[11:25:14.405] WARNING: Channel 0 ROC 3: Readback start marker after 6 readouts!

[11:25:15.650] INFO: Test took 19933ms.
[11:25:15.687] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:25:15.687] INFO: dacScan step from 20 .. 39
[11:25:15.688] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:25:30.927] WARNING: Channel 0 ROC 6: Readback start marker after 13 readouts!

[11:25:30.927] WARNING: Channel 0 ROC 6: Readback start marker after 3 readouts!

[11:25:35.697] INFO: Test took 20009ms.
[11:25:35.734] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:25:35.734] INFO: dacScan step from 40 .. 59
[11:25:35.734] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:25:55.767] INFO: Test took 20033ms.
[11:25:55.808] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:25:55.808] INFO: dacScan step from 60 .. 79
[11:25:55.808] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:26:15.822] INFO: Test took 20014ms.
[11:26:15.861] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:26:15.861] INFO: dacScan step from 80 .. 99
[11:26:15.861] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:26:31.451] WARNING: Channel 0 ROC 7: Readback start marker after 13 readouts!

[11:26:31.451] WARNING: Channel 0 ROC 7: Readback start marker after 3 readouts!

[11:26:32.538] WARNING: Channel 0 ROC 7: Readback start marker after 14 readouts!

[11:26:32.538] WARNING: Channel 0 ROC 7: Readback start marker after 2 readouts!

[11:26:35.887] INFO: Test took 20026ms.
[11:26:35.928] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:26:35.929] INFO: dacScan step from 100 .. 119
[11:26:35.929] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:26:55.022] WARNING: Channel 0 ROC 3: Readback start marker after 2 readouts!

[11:26:55.022] WARNING: Channel 0 ROC 3: Readback start marker after 14 readouts!

[11:26:57.149] INFO: Test took 21220ms.
[11:26:57.276] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:26:57.291] INFO: dacScan step from 120 .. 139
[11:26:57.292] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:27:24.718] INFO: Test took 27426ms.
[11:27:24.981] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:27:25.026] INFO: dacScan step from 140 .. 159
[11:27:25.026] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:27:41.422] WARNING: Channel 0 ROC 3: Readback start marker after 2 readouts!

[11:27:41.422] WARNING: Channel 0 ROC 3: Readback start marker after 14 readouts!

[11:27:54.133] INFO: Test took 29107ms.
[11:27:54.407] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:27:54.463] INFO: dacScan step from 160 .. 179
[11:27:54.464] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:28:18.062] WARNING: Channel 0 ROC 0: Readback start marker after 3 readouts!

[11:28:18.062] WARNING: Channel 0 ROC 0: Readback start marker after 13 readouts!

[11:28:23.434] INFO: Test took 28970ms.
[11:28:23.707] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:28:23.762] INFO: dacScan step from 180 .. 199
[11:28:23.762] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:28:53.262] INFO: Test took 29500ms.
[11:28:53.536] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:28:53.589] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[11:28:55.032] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[11:28:56.444] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[11:28:57.844] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[11:28:59.272] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[11:29:00.679] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[11:29:02.093] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[11:29:03.497] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[11:29:04.926] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[11:29:06.335] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[11:29:07.727] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[11:29:09.081] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[11:29:10.476] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[11:29:11.878] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[11:29:13.287] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[11:29:14.698] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[11:29:16.127] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 625725440
[11:29:16.127] DEBUG: <PixTestTrim.cc/trimBitTest:L533> trimBitTest initDUT with trim bits = 14
[11:29:16.192] DEBUG: <PixTestTrim.cc/trimBitTest:L539> trimBitTest threshold map with trim = 14
[11:29:16.192] INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 182 (20) hits flags = 16 (plus default)
[11:29:16.202] INFO: dacScan step from 0 .. 19
[11:29:16.202] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:29:36.080] INFO: Test took 19878ms.
[11:29:36.116] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:36.116] INFO: dacScan step from 20 .. 39
[11:29:36.116] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:29:56.067] INFO: Test took 19950ms.
[11:29:56.106] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:56.106] INFO: dacScan step from 40 .. 59
[11:29:56.106] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:30:16.055] INFO: Test took 19949ms.
[11:30:16.092] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:30:16.092] INFO: dacScan step from 60 .. 79
[11:30:16.092] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:30:35.810] INFO: Test took 19718ms.
[11:30:35.851] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:30:35.852] INFO: dacScan step from 80 .. 99
[11:30:35.853] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:30:49.622] WARNING: Channel 0 ROC 6: Readback start marker after 1 readouts!

[11:30:49.623] WARNING: Channel 0 ROC 6: Readback start marker after 15 readouts!

[11:30:53.103] WARNING: Channel 0 ROC 6: Readback start marker after 11 readouts!

[11:30:53.103] WARNING: Channel 0 ROC 6: Readback start marker after 5 readouts!

[11:30:56.142] INFO: Test took 20288ms.
[11:30:56.208] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:30:56.211] INFO: dacScan step from 100 .. 119
[11:30:56.212] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:31:20.462] INFO: Test took 24250ms.
[11:31:20.677] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:31:20.704] INFO: dacScan step from 120 .. 139
[11:31:20.704] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:31:49.983] INFO: Test took 29279ms.
[11:31:50.254] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:31:50.307] INFO: dacScan step from 140 .. 159
[11:31:50.307] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:32:19.792] INFO: Test took 29485ms.
[11:32:20.067] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:32:20.121] INFO: dacScan step from 160 .. 179
[11:32:20.121] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:32:48.678] INFO: Test took 28557ms.
[11:32:48.959] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:32:49.013] INFO: dacScan step from 180 .. 182
[11:32:49.013] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:32:55.807] INFO: Test took 6794ms.
[11:32:55.853] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:32:55.863] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[11:32:57.231] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[11:32:58.581] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[11:32:59.921] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[11:33:01.287] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[11:33:02.646] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[11:33:04.016] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[11:33:05.377] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[11:33:06.750] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[11:33:08.118] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[11:33:09.470] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[11:33:10.759] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[11:33:12.109] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[11:33:13.460] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[11:33:14.800] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[11:33:16.143] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[11:33:17.495] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 625725440
[11:33:17.496] DEBUG: <PixTestTrim.cc/trimBitTest:L533> trimBitTest initDUT with trim bits = 13
[11:33:17.558] DEBUG: <PixTestTrim.cc/trimBitTest:L539> trimBitTest threshold map with trim = 13
[11:33:17.559] INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 169 (20) hits flags = 16 (plus default)
[11:33:17.567] INFO: dacScan step from 0 .. 19
[11:33:17.568] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:33:37.475] INFO: Test took 19907ms.
[11:33:37.514] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:33:37.514] INFO: dacScan step from 20 .. 39
[11:33:37.514] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:33:54.119] WARNING: Channel 0 ROC 7: Readback start marker after 9 readouts!

[11:33:54.120] WARNING: Channel 0 ROC 7: Readback start marker after 7 readouts!

[11:33:57.053] INFO: Test took 19539ms.
[11:33:57.089] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:33:57.089] INFO: dacScan step from 40 .. 59
[11:33:57.089] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:34:17.147] INFO: Test took 20058ms.
[11:34:17.186] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:34:17.186] INFO: dacScan step from 60 .. 79
[11:34:17.186] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:34:36.849] WARNING: Channel 0 ROC 7: Readback start marker after 6 readouts!

[11:34:36.849] WARNING: Channel 0 ROC 7: Readback start marker after 10 readouts!

[11:34:37.269] INFO: Test took 20082ms.
[11:34:37.306] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:34:37.306] INFO: dacScan step from 80 .. 99
[11:34:37.306] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:34:53.213] WARNING: Channel 0 ROC 0: Readback start marker after 3 readouts!

[11:34:53.213] WARNING: Channel 0 ROC 0: Readback start marker after 13 readouts!

[11:34:57.774] INFO: Test took 20468ms.
[11:34:57.839] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:34:57.843] INFO: dacScan step from 100 .. 119
[11:34:57.843] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:35:22.014] INFO: Test took 24171ms.
[11:35:22.227] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:35:22.255] INFO: dacScan step from 120 .. 139
[11:35:22.255] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:35:51.586] INFO: Test took 29331ms.
[11:35:51.855] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:35:51.909] INFO: dacScan step from 140 .. 159
[11:35:51.909] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:36:21.290] INFO: Test took 29381ms.
[11:36:21.564] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:36:21.618] INFO: dacScan step from 160 .. 169
[11:36:21.618] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:36:37.469] INFO: Test took 15851ms.
[11:36:37.615] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:36:37.645] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[11:36:38.927] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[11:36:40.190] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[11:36:41.437] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[11:36:42.723] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[11:36:43.997] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[11:36:45.273] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[11:36:46.545] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[11:36:47.824] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[11:36:49.098] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[11:36:50.364] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[11:36:51.563] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[11:36:52.828] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[11:36:54.083] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[11:36:55.343] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[11:36:56.610] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[11:36:57.885] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 625725440
[11:36:57.886] DEBUG: <PixTestTrim.cc/trimBitTest:L533> trimBitTest initDUT with trim bits = 11
[11:36:57.948] DEBUG: <PixTestTrim.cc/trimBitTest:L539> trimBitTest threshold map with trim = 11
[11:36:57.948] INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 169 (20) hits flags = 16 (plus default)
[11:36:57.957] INFO: dacScan step from 0 .. 19
[11:36:57.957] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:37:12.435] WARNING: Channel 0 ROC 2: Readback start marker after 8 readouts!

[11:37:12.435] WARNING: Channel 0 ROC 2: Readback start marker after 8 readouts!

[11:37:17.511] INFO: Test took 19554ms.
[11:37:17.547] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:37:17.547] INFO: dacScan step from 20 .. 39
[11:37:17.548] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:37:35.596] WARNING: Channel 0 ROC 7: Readback start marker after 6 readouts!

[11:37:35.596] WARNING: Channel 0 ROC 7: Readback start marker after 10 readouts!

[11:37:37.477] INFO: Test took 19929ms.
[11:37:37.515] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:37:37.515] INFO: dacScan step from 40 .. 59
[11:37:37.515] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:37:57.445] INFO: Test took 19931ms.
[11:37:57.485] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:37:57.485] INFO: dacScan step from 60 .. 79
[11:37:57.485] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:38:17.498] INFO: Test took 20013ms.
[11:38:17.536] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:17.536] INFO: dacScan step from 80 .. 99
[11:38:17.536] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:38:37.857] INFO: Test took 20321ms.
[11:38:37.922] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:37.926] INFO: dacScan step from 100 .. 119
[11:38:37.926] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:38:55.942] WARNING: Channel 0 ROC 3: Readback start marker after 2 readouts!

[11:38:55.942] WARNING: Channel 0 ROC 3: Readback start marker after 14 readouts!

[11:39:02.128] INFO: Test took 24202ms.
[11:39:02.341] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:02.373] INFO: dacScan step from 120 .. 139
[11:39:02.373] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:39:31.744] INFO: Test took 29371ms.
[11:39:32.017] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:32.069] INFO: dacScan step from 140 .. 159
[11:39:32.069] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:40:01.399] INFO: Test took 29330ms.
[11:40:01.679] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:01.733] INFO: dacScan step from 160 .. 169
[11:40:01.734] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:40:15.146] WARNING: Channel 0 ROC 0: Readback start marker after 12 readouts!

[11:40:15.146] WARNING: Channel 0 ROC 0: Readback start marker after 4 readouts!

[11:40:17.523] INFO: Test took 15789ms.
[11:40:17.663] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:17.693] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[11:40:18.977] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[11:40:20.222] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[11:40:21.455] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[11:40:22.713] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[11:40:23.967] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[11:40:25.225] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[11:40:26.481] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[11:40:27.958] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[11:40:29.351] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[11:40:30.740] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[11:40:31.932] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[11:40:33.211] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[11:40:34.455] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[11:40:35.969] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[11:40:37.428] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[11:40:39.043] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 625725440
[11:40:39.044] DEBUG: <PixTestTrim.cc/trimBitTest:L533> trimBitTest initDUT with trim bits = 7
[11:40:39.107] DEBUG: <PixTestTrim.cc/trimBitTest:L539> trimBitTest threshold map with trim = 7
[11:40:39.108] INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 170 (20) hits flags = 16 (plus default)
[11:40:39.123] INFO: dacScan step from 0 .. 19
[11:40:39.124] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:40:59.167] INFO: Test took 20043ms.
[11:40:59.204] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:59.204] INFO: dacScan step from 20 .. 39
[11:40:59.205] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:41:19.332] INFO: Test took 20127ms.
[11:41:19.371] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:19.371] INFO: dacScan step from 40 .. 59
[11:41:19.371] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:41:39.490] INFO: Test took 20119ms.
[11:41:39.527] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:39.527] INFO: dacScan step from 60 .. 79
[11:41:39.527] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:41:53.853] WARNING: Channel 0 ROC 7: Readback start marker after 1 readouts!

[11:41:53.853] WARNING: Channel 0 ROC 7: Readback start marker after 15 readouts!

[11:41:59.549] INFO: Test took 20022ms.
[11:41:59.587] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:59.587] INFO: dacScan step from 80 .. 99
[11:41:59.587] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:42:19.823] INFO: Test took 20236ms.
[11:42:19.889] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:19.893] INFO: dacScan step from 100 .. 119
[11:42:19.893] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:42:44.235] INFO: Test took 24342ms.
[11:42:44.450] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:44.477] INFO: dacScan step from 120 .. 139
[11:42:44.477] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:43:01.346] WARNING: Channel 0 ROC 4: Readback start marker after 10 readouts!

[11:43:01.346] WARNING: Channel 0 ROC 4: Readback start marker after 6 readouts!

[11:43:13.793] INFO: Test took 29316ms.
[11:43:14.070] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:43:14.124] INFO: dacScan step from 140 .. 159
[11:43:14.124] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:43:43.308] INFO: Test took 29184ms.
[11:43:43.588] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:43:43.642] INFO: dacScan step from 160 .. 170
[11:43:43.642] DEBUG: <PixTest.cc/dacScan:L1518> attempt #0
[11:44:00.500] INFO: Test took 16858ms.
[11:44:00.649] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:44:00.682] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 0
[11:44:01.954] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 1
[11:44:03.209] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 2
[11:44:04.454] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 3
[11:44:05.722] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 4
[11:44:06.984] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 5
[11:44:08.698] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 6
[11:44:09.999] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 7
[11:44:11.269] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 8
[11:44:12.532] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 9
[11:44:13.785] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 10
[11:44:14.971] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 11
[11:44:16.227] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 12
[11:44:17.474] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 13
[11:44:18.726] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 14
[11:44:19.982] DEBUG: <PixTest.cc/scurveAna:L1579> analyzing ROC 15
[11:44:21.245] DEBUG: <PixTest.cc/scurveMaps:L251> PixTest::scurveMaps end: getCurrentRSS() = 625725440
[11:44:21.246] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 0 step 0: thr difference mean: 9.30269, thr difference RMS: 0.981983
[11:44:21.246] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 1 step 0: thr difference mean: 11.155, thr difference RMS: 1.64977
[11:44:21.246] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 2 step 0: thr difference mean: 11.9491, thr difference RMS: 1.27228
[11:44:21.247] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 3 step 0: thr difference mean: 8.93745, thr difference RMS: 1.72464
[11:44:21.247] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 4 step 0: thr difference mean: 9.17377, thr difference RMS: 1.4013
[11:44:21.247] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 5 step 0: thr difference mean: 9.57655, thr difference RMS: 1.33059
[11:44:21.247] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 6 step 0: thr difference mean: 10.0947, thr difference RMS: 1.42658
[11:44:21.247] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 7 step 0: thr difference mean: 10.2009, thr difference RMS: 1.35842
[11:44:21.247] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 8 step 0: thr difference mean: 9.65707, thr difference RMS: 1.40883
[11:44:21.248] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 9 step 0: thr difference mean: 9.88507, thr difference RMS: 1.52253
[11:44:21.248] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 10 step 0: thr difference mean: 11.0512, thr difference RMS: 1.39609
[11:44:21.248] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 11 step 0: thr difference mean: 10.4975, thr difference RMS: 1.55537
[11:44:21.248] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 12 step 0: thr difference mean: 9.60683, thr difference RMS: 1.26046
[11:44:21.248] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 13 step 0: thr difference mean: 10.363, thr difference RMS: 1.23078
[11:44:21.248] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 14 step 0: thr difference mean: 10.3598, thr difference RMS: 1.82033
[11:44:21.249] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 15 step 0: thr difference mean: 9.70291, thr difference RMS: 1.79617
[11:44:21.249] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 0 step 1: thr difference mean: 9.26341, thr difference RMS: 0.983757
[11:44:21.249] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 1 step 1: thr difference mean: 11.2135, thr difference RMS: 1.66873
[11:44:21.249] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 2 step 1: thr difference mean: 12.0694, thr difference RMS: 1.28823
[11:44:21.249] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 3 step 1: thr difference mean: 9.01019, thr difference RMS: 1.71196
[11:44:21.249] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 4 step 1: thr difference mean: 9.14465, thr difference RMS: 1.39823
[11:44:21.249] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 5 step 1: thr difference mean: 9.66598, thr difference RMS: 1.33272
[11:44:21.250] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 6 step 1: thr difference mean: 10.2167, thr difference RMS: 1.41892
[11:44:21.250] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 7 step 1: thr difference mean: 10.3932, thr difference RMS: 1.28378
[11:44:21.250] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 8 step 1: thr difference mean: 9.72413, thr difference RMS: 1.38029
[11:44:21.250] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 9 step 1: thr difference mean: 10.0371, thr difference RMS: 1.52244
[11:44:21.250] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 10 step 1: thr difference mean: 11.1751, thr difference RMS: 1.39271
[11:44:21.250] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 11 step 1: thr difference mean: 10.7229, thr difference RMS: 1.5509
[11:44:21.251] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 12 step 1: thr difference mean: 9.70968, thr difference RMS: 1.29034
[11:44:21.251] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 13 step 1: thr difference mean: 10.5674, thr difference RMS: 1.25697
[11:44:21.251] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 14 step 1: thr difference mean: 10.498, thr difference RMS: 1.84534
[11:44:21.251] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 15 step 1: thr difference mean: 10.1103, thr difference RMS: 1.73719
[11:44:21.251] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 0 step 2: thr difference mean: 9.29385, thr difference RMS: 0.962987
[11:44:21.251] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 1 step 2: thr difference mean: 11.3035, thr difference RMS: 1.67543
[11:44:21.252] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 2 step 2: thr difference mean: 12.2087, thr difference RMS: 1.31545
[11:44:21.252] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 3 step 2: thr difference mean: 9.25186, thr difference RMS: 1.71693
[11:44:21.252] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 4 step 2: thr difference mean: 9.17299, thr difference RMS: 1.40995
[11:44:21.252] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 5 step 2: thr difference mean: 9.95075, thr difference RMS: 1.31514
[11:44:21.252] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 6 step 2: thr difference mean: 10.3381, thr difference RMS: 1.433
[11:44:21.252] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 7 step 2: thr difference mean: 10.5436, thr difference RMS: 1.31907
[11:44:21.252] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 8 step 2: thr difference mean: 9.8487, thr difference RMS: 1.37453
[11:44:21.253] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 9 step 2: thr difference mean: 10.2583, thr difference RMS: 1.52875
[11:44:21.253] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 10 step 2: thr difference mean: 11.351, thr difference RMS: 1.83075
[11:44:21.253] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 11 step 2: thr difference mean: 11.0768, thr difference RMS: 1.57587
[11:44:21.253] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 12 step 2: thr difference mean: 9.71803, thr difference RMS: 1.27247
[11:44:21.253] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 13 step 2: thr difference mean: 10.8224, thr difference RMS: 1.24981
[11:44:21.253] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 14 step 2: thr difference mean: 10.625, thr difference RMS: 1.87242
[11:44:21.254] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 15 step 2: thr difference mean: 10.267, thr difference RMS: 1.75211
[11:44:21.254] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 0 step 3: thr difference mean: 9.26783, thr difference RMS: 0.975881
[11:44:21.254] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 1 step 3: thr difference mean: 11.4114, thr difference RMS: 1.68019
[11:44:21.254] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 2 step 3: thr difference mean: 12.4437, thr difference RMS: 1.31973
[11:44:21.254] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 3 step 3: thr difference mean: 9.46658, thr difference RMS: 1.70984
[11:44:21.254] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 4 step 3: thr difference mean: 9.2152, thr difference RMS: 1.3825
[11:44:21.254] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 5 step 3: thr difference mean: 10.1534, thr difference RMS: 1.303
[11:44:21.255] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 6 step 3: thr difference mean: 10.44, thr difference RMS: 1.4286
[11:44:21.255] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 7 step 3: thr difference mean: 10.8739, thr difference RMS: 1.30617
[11:44:21.255] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 8 step 3: thr difference mean: 9.82397, thr difference RMS: 1.38256
[11:44:21.255] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 9 step 3: thr difference mean: 10.3702, thr difference RMS: 1.54161
[11:44:21.255] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 10 step 3: thr difference mean: 11.5617, thr difference RMS: 1.38179
[11:44:21.255] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 11 step 3: thr difference mean: 11.3843, thr difference RMS: 1.57368
[11:44:21.256] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 12 step 3: thr difference mean: 9.75011, thr difference RMS: 1.31832
[11:44:21.256] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 13 step 3: thr difference mean: 10.9957, thr difference RMS: 1.26359
[11:44:21.256] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 14 step 3: thr difference mean: 10.7087, thr difference RMS: 1.86646
[11:44:21.256] DEBUG: <PixTestTrim.cc/trimBitTest:L559> ROC 15 step 3: thr difference mean: 10.3231, thr difference RMS: 1.71859
[11:44:21.369] INFO: PixTestTrim::trimBitTest() done
[11:44:21.371] INFO: PixTestTrim::doTest() done, duration: 2319 seconds
[11:44:21.371] DEBUG: <PixTestTrim.cc/~PixTestTrim:L104> PixTestTrim dtor
[11:44:21.947] DEBUG: <PixTest.cc/setTestParameter:L569> setting ntrig to new value 10
[11:44:21.948] DEBUG: <PixTestPhOptimization.cc/setParameter:L37> setting fParNtrig ->10<- from sval = 10
[11:44:21.948] DEBUG: <PixTestPhOptimization.cc/setParameter:L42> setting fSafetyMarginLow ->20<- from sval = 20
[11:44:21.948] DEBUG: <PixTestPhOptimization.cc/setParameter:L48> setting fVcalMax ->100<- from sval = 100
[11:44:21.948] DEBUG: <PixTestPhOptimization.cc/setParameter:L53> setting fQuantMax ->0.98<- from sval = 0.98
[11:44:21.948] INFO: ######################################################################
[11:44:21.948] INFO: PixTestPhOptimization::doTest() Ntrig = 10
[11:44:21.948] INFO: ######################################################################
[11:44:21.950] DEBUG: <PixTest.cc/efficiencyMaps:L328> attempt #0
[11:44:25.912] INFO: Test took 3962ms.
[11:44:25.934] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:44:25.934] DEBUG: <PixTest.cc/efficiencyMaps:L339> eff result size = 66543
[11:44:25.934] DEBUG: <PixTest.cc/efficiencyMaps:L344> Create hists PixelAlive_C0 .. PixelAlive_C15
[11:44:25.937] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [2, 40, 74] has eff 0/10
[11:44:25.937] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [2, 40, 74]
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [4, 49, 75] has eff 0/10
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [4, 49, 75]
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [6, 47, 77] has eff 0/10
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [6, 47, 77]
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [6, 48, 79] has eff 0/10
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [6, 48, 79]
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [6, 50, 79] has eff 0/10
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [6, 50, 79]
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [6, 51, 79] has eff 0/10
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [6, 51, 79]
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [7, 49, 0] has eff 0/10
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [7, 49, 0]
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [7, 50, 0] has eff 0/10
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [7, 50, 0]
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [7, 51, 0] has eff 0/10
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [7, 51, 0]
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [7, 51, 1] has eff 0/10
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [7, 51, 1]
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [8, 0, 0] has eff 0/10
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [8, 0, 0]
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [8, 1, 0] has eff 0/10
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [8, 1, 0]
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [8, 2, 0] has eff 0/10
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [8, 2, 0]
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [8, 44, 63] has eff 0/10
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [8, 44, 63]
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [8, 41, 76] has eff 0/10
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [8, 41, 76]
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [9, 50, 59] has eff 1/10
[11:44:25.938] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [9, 50, 59]
[11:44:25.939] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [11, 49, 66] has eff 0/10
[11:44:25.939] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [11, 49, 66]
[11:44:25.939] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [13, 37, 54] has eff 4/10
[11:44:25.939] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [13, 37, 54]
[11:44:25.939] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [15, 45, 26] has eff 2/10
[11:44:25.939] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [15, 45, 26]
[11:44:25.939] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L227> Pixel [15, 34, 40] has eff 0/10
[11:44:25.939] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L231> bad Pixel found and blacklisted: [15, 34, 40]
[11:44:25.943] DEBUG: <PixTestPhOptimization.cc/BlacklistPixels:L239> Number of bad pixels found: 20
[11:44:25.943] DEBUG: <PixTestPhOptimization.cc/doTest:L124> **********Ph range will be optimised on the whole ROC***********
[11:44:25.943] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L276> ROC type is newer than digv2
[11:44:25.943] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L277> ROC type is psi46digv21respin
[11:44:26.200] DEBUG: <PixTest.cc/phMaps:L264> attempt #0
[11:44:30.134] INFO: Test took 3934ms.
[11:44:30.199] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:44:30.199] DEBUG: <PixTest.cc/phMaps:L275> eff result size = 66543
[11:44:30.199] DEBUG: <PixTest.cc/phMaps:L282> Create hists maxphmap_C0 .. maxphmap_C15
[11:44:30.203] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 196.155
[11:44:30.203] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,5] phvalue 197
[11:44:30.203] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 219.938
[11:44:30.203] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,5] phvalue 220
[11:44:30.203] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 215.987
[11:44:30.203] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,6] phvalue 216
[11:44:30.203] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 216.615
[11:44:30.203] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,5] phvalue 216
[11:44:30.203] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 200.765
[11:44:30.203] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [4 ,17] phvalue 200
[11:44:30.203] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 219.488
[11:44:30.203] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [4 ,5] phvalue 220
[11:44:30.203] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 221.189
[11:44:30.204] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,5] phvalue 222
[11:44:30.204] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 209.164
[11:44:30.204] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,5] phvalue 209
[11:44:30.204] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 209.031
[11:44:30.204] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [4 ,6] phvalue 209
[11:44:30.204] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 212.277
[11:44:30.204] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,5] phvalue 213
[11:44:30.204] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 213.414
[11:44:30.204] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [4 ,5] phvalue 213
[11:44:30.204] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 202.644
[11:44:30.204] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,5] phvalue 202
[11:44:30.204] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 204.173
[11:44:30.204] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,5] phvalue 204
[11:44:30.204] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 207.057
[11:44:30.204] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [4 ,7] phvalue 208
[11:44:30.204] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 224.765
[11:44:30.204] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,6] phvalue 225
[11:44:30.205] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L347> maxph quantile 210.112
[11:44:30.205] DEBUG: <PixTestPhOptimization.cc/GetMaxPhPixel:L371> Max pixel is [3 ,5] phvalue 210
[11:44:30.205] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L427> ROC type is newer than digv2
[11:44:30.205] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L428> ROC type is psi46digv21respin
[11:44:30.205] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L450> init_phScale=150, flag_minPh = 0, minph = 0
[11:44:30.213] DEBUG: <PixTest.cc/phMaps:L264> attempt #0
[11:44:34.264] INFO: Test took 4051ms.
[11:44:34.329] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:44:34.329] DEBUG: <PixTest.cc/phMaps:L275> eff result size = 66542
[11:44:34.329] DEBUG: <PixTest.cc/phMaps:L282> Create hists minphmap_C0 .. minphmap_C15
[11:44:34.332] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L457> result size 0

[11:44:34.333] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L484> done. init_phScale=155, flag_minPh = 1, minph = 77minph_roc = 0
[11:44:34.333] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 82.5886
[11:44:34.333] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [6 ,62] phvalue 82
[11:44:34.333] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 84.4688
[11:44:34.333] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [4 ,50] phvalue 85
[11:44:34.333] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 98.3634
[11:44:34.333] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [4 ,60] phvalue 98
[11:44:34.333] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 107.413
[11:44:34.333] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [3 ,14] phvalue 108
[11:44:34.334] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 77.013
[11:44:34.334] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [3 ,66] phvalue 78
[11:44:34.334] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 102.244
[11:44:34.334] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [3 ,12] phvalue 102
[11:44:34.334] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 113.719
[11:44:34.334] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [6 ,44] phvalue 114
[11:44:34.334] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 99.0781
[11:44:34.334] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [3 ,12] phvalue 100
[11:44:34.334] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 98.2514
[11:44:34.334] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [3 ,67] phvalue 99
[11:44:34.334] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 96.0234
[11:44:34.334] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [4 ,60] phvalue 97
[11:44:34.334] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 86.6001
[11:44:34.334] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [3 ,44] phvalue 87
[11:44:34.334] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 95.7019
[11:44:34.334] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [6 ,14] phvalue 96
[11:44:34.335] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 89.3798
[11:44:34.335] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [4 ,14] phvalue 89
[11:44:34.335] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 96.8898
[11:44:34.335] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [14 ,8] phvalue 97
[11:44:34.335] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 110.789
[11:44:34.335] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [6 ,42] phvalue 111
[11:44:34.335] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L502> minph quantile 0.02 83.9048
[11:44:34.335] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L525> Min pixel is [3 ,67] phvalue 84
[11:44:34.337] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 6, 62, 0 0
[11:44:34.337] INFO: The DUT currently contains the following objects:
[11:44:34.337] INFO: 2 TBM Cores tbm08c (2 ON)
[11:44:34.337] INFO: TBM Core alpha (0): 7 registers set
[11:44:34.337] INFO: TBM Core beta (1): 7 registers set
[11:44:34.337] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[11:44:34.337] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:34.337] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:34.337] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:34.337] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:34.337] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:34.337] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:34.337] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:34.337] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:34.337] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:34.338] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:34.338] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:34.338] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:34.338] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:34.338] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:34.338] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:34.338] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:35.567] INFO: Test took 1229ms.
[11:44:35.568] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[11:44:35.568] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 4, 50, 1 1
[11:44:35.568] INFO: The DUT currently contains the following objects:
[11:44:35.569] INFO: 2 TBM Cores tbm08c (2 ON)
[11:44:35.569] INFO: TBM Core alpha (0): 7 registers set
[11:44:35.569] INFO: TBM Core beta (1): 7 registers set
[11:44:35.569] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[11:44:35.569] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:35.569] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:35.569] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:35.569] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:35.569] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:35.569] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:35.569] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:35.569] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:35.569] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:35.569] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:35.569] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:35.569] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:35.569] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:35.569] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:35.569] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:35.569] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:36.796] INFO: Test took 1227ms.
[11:44:36.797] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[11:44:36.797] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 4, 60, 2 2
[11:44:36.797] INFO: The DUT currently contains the following objects:
[11:44:36.797] INFO: 2 TBM Cores tbm08c (2 ON)
[11:44:36.797] INFO: TBM Core alpha (0): 7 registers set
[11:44:36.797] INFO: TBM Core beta (1): 7 registers set
[11:44:36.797] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[11:44:36.797] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:36.797] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:36.797] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:36.797] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:36.797] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:36.797] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:36.797] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:36.797] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:36.797] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:36.797] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:36.797] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:36.797] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:36.797] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:36.797] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:36.797] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:36.797] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:38.026] INFO: Test took 1229ms.
[11:44:38.027] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[11:44:38.027] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 3, 14, 3 3
[11:44:38.027] INFO: The DUT currently contains the following objects:
[11:44:38.027] INFO: 2 TBM Cores tbm08c (2 ON)
[11:44:38.027] INFO: TBM Core alpha (0): 7 registers set
[11:44:38.027] INFO: TBM Core beta (1): 7 registers set
[11:44:38.027] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[11:44:38.027] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:38.027] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:38.027] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:38.027] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:38.027] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:38.027] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:38.027] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:38.027] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:38.027] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:38.027] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:38.027] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:38.027] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:38.027] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:38.027] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:38.027] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:38.027] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:39.256] INFO: Test took 1229ms.
[11:44:39.257] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[11:44:39.257] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 3, 66, 4 4
[11:44:39.257] INFO: The DUT currently contains the following objects:
[11:44:39.257] INFO: 2 TBM Cores tbm08c (2 ON)
[11:44:39.257] INFO: TBM Core alpha (0): 7 registers set
[11:44:39.257] INFO: TBM Core beta (1): 7 registers set
[11:44:39.257] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[11:44:39.257] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:39.257] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:39.257] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:39.257] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:39.257] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:39.257] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:39.258] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:39.258] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:39.258] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:39.258] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:39.258] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:39.258] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:39.258] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:39.258] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:39.258] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:39.258] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:40.487] INFO: Test took 1229ms.
[11:44:40.488] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[11:44:40.488] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 3, 12, 5 5
[11:44:40.488] INFO: The DUT currently contains the following objects:
[11:44:40.488] INFO: 2 TBM Cores tbm08c (2 ON)
[11:44:40.488] INFO: TBM Core alpha (0): 7 registers set
[11:44:40.488] INFO: TBM Core beta (1): 7 registers set
[11:44:40.488] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[11:44:40.488] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:40.488] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:40.488] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:40.488] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:40.488] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:40.488] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:40.488] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:40.488] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:40.488] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:40.488] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:40.488] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:40.488] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:40.488] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:40.488] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:40.488] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:40.489] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:41.718] INFO: Test took 1229ms.
[11:44:41.719] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[11:44:41.719] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 6, 44, 6 6
[11:44:41.719] INFO: The DUT currently contains the following objects:
[11:44:41.719] INFO: 2 TBM Cores tbm08c (2 ON)
[11:44:41.719] INFO: TBM Core alpha (0): 7 registers set
[11:44:41.719] INFO: TBM Core beta (1): 7 registers set
[11:44:41.719] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[11:44:41.719] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:41.719] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:41.719] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:41.719] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:41.719] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:41.719] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:41.719] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:41.719] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:41.719] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:41.719] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:41.719] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:41.719] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:41.719] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:41.719] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:41.719] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:41.719] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:42.950] INFO: Test took 1231ms.
[11:44:42.951] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[11:44:42.951] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 3, 12, 7 7
[11:44:42.952] INFO: The DUT currently contains the following objects:
[11:44:42.952] INFO: 2 TBM Cores tbm08c (2 ON)
[11:44:42.952] INFO: TBM Core alpha (0): 7 registers set
[11:44:42.952] INFO: TBM Core beta (1): 7 registers set
[11:44:42.952] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[11:44:42.952] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:42.952] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:42.952] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:42.952] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:42.952] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:42.952] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:42.952] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:42.952] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:42.952] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:42.952] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:42.952] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:42.952] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:42.952] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:42.952] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:42.952] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:42.952] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:44.182] INFO: Test took 1230ms.
[11:44:44.183] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[11:44:44.183] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 3, 67, 8 8
[11:44:44.183] INFO: The DUT currently contains the following objects:
[11:44:44.183] INFO: 2 TBM Cores tbm08c (2 ON)
[11:44:44.183] INFO: TBM Core alpha (0): 7 registers set
[11:44:44.183] INFO: TBM Core beta (1): 7 registers set
[11:44:44.183] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[11:44:44.183] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:44.184] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:44.184] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:44.184] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:44.184] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:44.184] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:44.184] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:44.184] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:44.184] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:44.184] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:44.184] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:44.184] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:44.184] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:44.184] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:44.184] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:44.184] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:45.413] INFO: Test took 1229ms.
[11:44:45.414] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[11:44:45.414] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 4, 60, 9 9
[11:44:45.414] INFO: The DUT currently contains the following objects:
[11:44:45.414] INFO: 2 TBM Cores tbm08c (2 ON)
[11:44:45.414] INFO: TBM Core alpha (0): 7 registers set
[11:44:45.414] INFO: TBM Core beta (1): 7 registers set
[11:44:45.414] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[11:44:45.414] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:45.414] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:45.414] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:45.414] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:45.414] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:45.414] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:45.414] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:45.414] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:45.414] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:45.414] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:45.414] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:45.414] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:45.414] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:45.414] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:45.414] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:45.414] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:46.644] INFO: Test took 1230ms.
[11:44:46.644] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[11:44:46.645] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 3, 44, 10 10
[11:44:46.645] INFO: The DUT currently contains the following objects:
[11:44:46.645] INFO: 2 TBM Cores tbm08c (2 ON)
[11:44:46.645] INFO: TBM Core alpha (0): 7 registers set
[11:44:46.645] INFO: TBM Core beta (1): 7 registers set
[11:44:46.645] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[11:44:46.645] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:46.645] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:46.645] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:46.645] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:46.645] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:46.645] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:46.645] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:46.645] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:46.645] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:46.645] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:46.645] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:46.645] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:46.645] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:46.645] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:46.645] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:46.645] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:47.874] INFO: Test took 1229ms.
[11:44:47.875] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[11:44:47.875] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 6, 14, 11 11
[11:44:47.875] INFO: The DUT currently contains the following objects:
[11:44:47.875] INFO: 2 TBM Cores tbm08c (2 ON)
[11:44:47.875] INFO: TBM Core alpha (0): 7 registers set
[11:44:47.875] INFO: TBM Core beta (1): 7 registers set
[11:44:47.875] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[11:44:47.875] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:47.875] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:47.876] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:47.876] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:47.876] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:47.876] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:47.876] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:47.876] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:47.876] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:47.876] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:47.876] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:47.876] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:47.876] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:47.876] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:47.876] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:47.876] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:49.104] INFO: Test took 1228ms.
[11:44:49.105] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[11:44:49.105] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 4, 14, 12 12
[11:44:49.105] INFO: The DUT currently contains the following objects:
[11:44:49.105] INFO: 2 TBM Cores tbm08c (2 ON)
[11:44:49.105] INFO: TBM Core alpha (0): 7 registers set
[11:44:49.105] INFO: TBM Core beta (1): 7 registers set
[11:44:49.105] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[11:44:49.105] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:49.105] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:49.105] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:49.105] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:49.105] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:49.105] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:49.105] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:49.105] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:49.105] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:49.105] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:49.105] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:49.105] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:49.105] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:49.105] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:49.106] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:49.106] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:50.336] INFO: Test took 1230ms.
[11:44:50.337] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[11:44:50.337] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 14, 8, 13 13
[11:44:50.337] INFO: The DUT currently contains the following objects:
[11:44:50.337] INFO: 2 TBM Cores tbm08c (2 ON)
[11:44:50.337] INFO: TBM Core alpha (0): 7 registers set
[11:44:50.337] INFO: TBM Core beta (1): 7 registers set
[11:44:50.337] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[11:44:50.337] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:50.337] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:50.337] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:50.337] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:50.337] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:50.337] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:50.337] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:50.337] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:50.337] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:50.337] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:50.337] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:50.337] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:50.337] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:50.337] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:50.337] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:50.337] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:51.566] INFO: Test took 1229ms.
[11:44:51.567] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[11:44:51.567] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 6, 42, 14 14
[11:44:51.567] INFO: The DUT currently contains the following objects:
[11:44:51.567] INFO: 2 TBM Cores tbm08c (2 ON)
[11:44:51.567] INFO: TBM Core alpha (0): 7 registers set
[11:44:51.567] INFO: TBM Core beta (1): 7 registers set
[11:44:51.567] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[11:44:51.567] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:51.567] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:51.567] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:51.567] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:51.567] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:51.567] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:51.567] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:51.567] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:51.567] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:51.567] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:51.567] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:51.567] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:51.567] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:51.567] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:51.567] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:51.567] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:52.796] INFO: Test took 1229ms.
[11:44:52.797] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[11:44:52.797] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L591> enabling pixels 3, 67, 15 15
[11:44:52.797] INFO: The DUT currently contains the following objects:
[11:44:52.797] INFO: 2 TBM Cores tbm08c (2 ON)
[11:44:52.797] INFO: TBM Core alpha (0): 7 registers set
[11:44:52.797] INFO: TBM Core beta (1): 7 registers set
[11:44:52.797] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[11:44:52.797] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:52.797] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:52.797] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:52.797] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:52.797] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:52.797] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:52.797] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:52.797] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:52.797] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:52.797] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:52.797] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:52.797] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:52.797] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:52.797] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:52.797] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:52.797] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[11:44:54.026] INFO: Test took 1229ms.
[11:44:54.028] DEBUG: <PixTestPhOptimization.cc/GetMinPhPixel:L611> size of results 256
[11:44:54.028] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 33 on ROC0
[11:44:54.028] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 31 on ROC1
[11:44:54.028] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 34 on ROC2
[11:44:54.028] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 34 on ROC3
[11:44:54.028] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 30 on ROC4
[11:44:54.028] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 31 on ROC5
[11:44:54.028] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 28 on ROC6
[11:44:54.028] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 33 on ROC7
[11:44:54.028] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 32 on ROC8
[11:44:54.028] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 28 on ROC9
[11:44:54.028] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 29 on ROC10
[11:44:54.028] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 30 on ROC11
[11:44:54.028] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 31 on ROC12
[11:44:54.028] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 28 on ROC13
[11:44:54.028] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 32 on ROC14
[11:44:54.028] DEBUG: <PixTestPhOptimization.cc/doTest:L132> vcal min 32 on ROC15
[11:44:54.033] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:45:00.888] WARNING: Channel 0 ROC 4: Readback start marker after 13 readouts!

[11:45:00.888] WARNING: Channel 0 ROC 4: Readback start marker after 3 readouts!

[11:45:15.830] WARNING: Channel 0 ROC 4: Readback start marker after 3 readouts!

[11:45:15.830] WARNING: Channel 0 ROC 4: Readback start marker after 13 readouts!

[11:46:53.833] WARNING: Channel 0 ROC 4: Readback start marker after 8 readouts!

[11:46:53.833] WARNING: Channel 0 ROC 4: Readback start marker after 8 readouts!

[11:47:13.280] WARNING: Channel 0 ROC 5: Readback start marker after 7 readouts!

[11:47:13.280] WARNING: Channel 0 ROC 5: Readback start marker after 9 readouts!

[11:47:48.672] INFO: Test took 174639ms.
[11:47:50.211] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:47:56.053] WARNING: Channel 0 ROC 0: Readback start marker after 15 readouts!

[11:47:56.053] WARNING: Channel 0 ROC 0: Readback start marker after 1 readouts!

[11:48:20.435] WARNING: Channel 0 ROC 5: Readback start marker after 3 readouts!

[11:48:20.435] WARNING: Channel 0 ROC 5: Readback start marker after 13 readouts!

[11:49:05.364] WARNING: Channel 0 ROC 3: Readback start marker after 1 readouts!

[11:49:05.364] WARNING: Channel 0 ROC 3: Readback start marker after 15 readouts!

[11:49:33.596] WARNING: Channel 0 ROC 6: Readback start marker after 4 readouts!

[11:49:33.596] WARNING: Channel 0 ROC 6: Readback start marker after 12 readouts!

[11:50:43.544] INFO: Test took 173333ms.
[11:50:45.134] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[11:50:45.134] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip0
[11:50:45.134] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[11:50:45.135] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip1
[11:50:45.135] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[11:50:45.135] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip2
[11:50:45.135] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[11:50:45.135] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip3
[11:50:45.135] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[11:50:45.136] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip4
[11:50:45.136] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[11:50:45.136] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip5
[11:50:45.136] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[11:50:45.137] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip6
[11:50:45.137] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[11:50:45.137] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip7
[11:50:45.137] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[11:50:45.137] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip8
[11:50:45.137] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[11:50:45.138] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip9
[11:50:45.138] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[11:50:45.138] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip10
[11:50:45.138] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[11:50:45.138] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip11
[11:50:45.138] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[11:50:45.139] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip12
[11:50:45.139] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[11:50:45.139] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip13
[11:50:45.139] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[11:50:45.139] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip14
[11:50:45.139] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L927> before assigning th2_sol to vector component
[11:50:45.140] DEBUG: <PixTestPhOptimization.cc/optimiseOnMapsNew:L934> after assigning th2_sol to vector component, chip15
[11:50:45.140] INFO: safety margin for low PH: adding 0, margin is now 20
[11:50:45.145] INFO: safety margin for low PH: adding 0, margin is now 20
[11:50:45.151] INFO: safety margin for low PH: adding 0, margin is now 20
[11:50:45.156] INFO: safety margin for low PH: adding 0, margin is now 20
[11:50:45.162] INFO: safety margin for low PH: adding 0, margin is now 20
[11:50:45.167] INFO: safety margin for low PH: adding 1, margin is now 21
[11:50:45.173] INFO: safety margin for low PH: adding 0, margin is now 20
[11:50:45.178] INFO: safety margin for low PH: adding 1, margin is now 21
[11:50:45.184] INFO: safety margin for low PH: adding 2, margin is now 22
[11:50:45.189] INFO: safety margin for low PH: adding 0, margin is now 20
[11:50:45.195] INFO: safety margin for low PH: adding 0, margin is now 20
[11:50:45.200] INFO: safety margin for low PH: adding 0, margin is now 20
[11:50:45.206] INFO: safety margin for low PH: adding 0, margin is now 20
[11:50:45.211] INFO: safety margin for low PH: adding 0, margin is now 20
[11:50:45.217] INFO: safety margin for low PH: adding 0, margin is now 20
[11:50:45.223] INFO: safety margin for low PH: adding 1, margin is now 21
[11:50:45.228] INFO: safety margin for low PH: adding 0, margin is now 20
[11:50:45.234] INFO: safety margin for low PH: adding 0, margin is now 20
[11:50:45.239] INFO: safety margin for low PH: adding 0, margin is now 20
[11:50:45.245] INFO: safety margin for low PH: adding 1, margin is now 21
[11:50:45.250] INFO: safety margin for low PH: adding 2, margin is now 22
[11:50:45.256] INFO: safety margin for low PH: adding 3, margin is now 23
[11:50:45.261] INFO: safety margin for low PH: adding 4, margin is now 24
[11:50:45.267] INFO: safety margin for low PH: adding 5, margin is now 25
[11:50:45.272] INFO: safety margin for low PH: adding 0, margin is now 20
[11:50:45.278] DEBUG: <PixTestPhOptimization.cc/doTest:L172> optimisation done
[11:50:45.331] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C0.dat
[11:50:45.332] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C1.dat
[11:50:45.332] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C2.dat
[11:50:45.332] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C3.dat
[11:50:45.332] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C4.dat
[11:50:45.332] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C5.dat
[11:50:45.332] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C6.dat
[11:50:45.332] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C7.dat
[11:50:45.332] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C8.dat
[11:50:45.332] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C9.dat
[11:50:45.333] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C10.dat
[11:50:45.333] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C11.dat
[11:50:45.333] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C12.dat
[11:50:45.333] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C13.dat
[11:50:45.333] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C14.dat
[11:50:45.333] INFO: write dac parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//dacParameters35_C15.dat
[11:50:49.285] INFO: Test took 3946ms.
[11:50:53.556] INFO: Test took 3924ms.
[11:50:57.855] INFO: Test took 3949ms.
[11:50:58.204] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:50:59.177] INFO: Test took 973ms.
[11:50:59.181] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:00.411] INFO: Test took 1230ms.
[11:51:00.414] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:01.643] INFO: Test took 1229ms.
[11:51:01.646] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:02.876] INFO: Test took 1230ms.
[11:51:02.881] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:04.109] INFO: Test took 1228ms.
[11:51:04.112] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:05.341] INFO: Test took 1229ms.
[11:51:05.344] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:06.572] INFO: Test took 1228ms.
[11:51:06.575] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:07.805] INFO: Test took 1230ms.
[11:51:07.808] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:09.038] INFO: Test took 1230ms.
[11:51:09.041] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:10.271] INFO: Test took 1230ms.
[11:51:10.274] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:11.503] INFO: Test took 1229ms.
[11:51:11.506] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:12.736] INFO: Test took 1230ms.
[11:51:12.740] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:13.968] INFO: Test took 1229ms.
[11:51:13.972] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:15.200] INFO: Test took 1228ms.
[11:51:15.203] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:16.433] INFO: Test took 1230ms.
[11:51:16.436] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:17.664] INFO: Test took 1228ms.
[11:51:17.667] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:18.897] INFO: Test took 1230ms.
[11:51:18.901] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:20.130] INFO: Test took 1230ms.
[11:51:20.133] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:21.362] INFO: Test took 1229ms.
[11:51:21.366] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:22.594] INFO: Test took 1228ms.
[11:51:22.598] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:23.825] INFO: Test took 1227ms.
[11:51:23.828] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:25.055] INFO: Test took 1227ms.
[11:51:25.059] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:26.288] INFO: Test took 1229ms.
[11:51:26.291] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:27.520] INFO: Test took 1229ms.
[11:51:27.524] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:28.752] INFO: Test took 1228ms.
[11:51:28.755] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:29.984] INFO: Test took 1229ms.
[11:51:29.987] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:31.220] INFO: Test took 1233ms.
[11:51:31.223] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:32.450] INFO: Test took 1227ms.
[11:51:32.453] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:33.681] INFO: Test took 1228ms.
[11:51:33.684] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:34.911] INFO: Test took 1227ms.
[11:51:34.915] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:36.143] INFO: Test took 1229ms.
[11:51:36.146] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[11:51:37.373] INFO: Test took 1227ms.
[11:51:38.026] INFO: PixTestPhOptimization::doTest() done, duration: 436 seconds
[11:51:38.026] INFO: PH scale (per ROC): 78 89 79 71 80 80 80 78 74 80 77 71 79 76 81 80
[11:51:38.026] INFO: PH offset (per ROC): 166 160 156 154 172 153 142 151 156 156 165 161 164 156 144 165
[11:51:38.170] DEBUG: <PixTestGainPedestal.cc/setParameter:L83> PixTestGainPedestal::PixTest() fVcalStep = 10
[11:51:38.172] INFO: ######################################################################
[11:51:38.172] INFO: PixTestGainPedestal::fullTest() ntrig = 10
[11:51:38.172] INFO: ######################################################################
[11:51:38.172] DEBUG: <PixTestGainPedestal.cc/measure:L192> using FLAGS = 16
[11:51:38.183] INFO: scanning low vcal = 10
[11:51:41.802] INFO: Test took 3619ms.
[11:51:41.807] INFO: scanning low vcal = 20
[11:51:45.516] INFO: Test took 3709ms.
[11:51:45.520] INFO: scanning low vcal = 30
[11:51:49.234] INFO: Test took 3714ms.
[11:51:49.247] INFO: scanning low vcal = 40
[11:51:53.337] INFO: Test took 4090ms.
[11:51:53.399] INFO: scanning low vcal = 50
[11:51:57.550] INFO: Test took 4151ms.
[11:51:57.610] INFO: scanning low vcal = 60
[11:52:01.760] INFO: Test took 4150ms.
[11:52:01.818] INFO: scanning low vcal = 70
[11:52:05.977] INFO: Test took 4159ms.
[11:52:06.040] INFO: scanning low vcal = 80
[11:52:10.185] INFO: Test took 4145ms.
[11:52:10.247] INFO: scanning low vcal = 90
[11:52:14.404] INFO: Test took 4157ms.
[11:52:14.466] INFO: scanning low vcal = 100
[11:52:18.627] INFO: Test took 4161ms.
[11:52:18.685] INFO: scanning low vcal = 110
[11:52:22.841] INFO: Test took 4156ms.
[11:52:22.905] INFO: scanning low vcal = 120
[11:52:27.034] INFO: Test took 4129ms.
[11:52:27.094] INFO: scanning low vcal = 130
[11:52:31.255] INFO: Test took 4160ms.
[11:52:31.313] INFO: scanning low vcal = 140
[11:52:35.511] INFO: Test took 4198ms.
[11:52:35.569] INFO: scanning low vcal = 150
[11:52:39.716] INFO: Test took 4147ms.
[11:52:39.775] INFO: scanning low vcal = 160
[11:52:43.942] INFO: Test took 4167ms.
[11:52:44.004] INFO: scanning low vcal = 170
[11:52:48.158] INFO: Test took 4154ms.
[11:52:48.218] INFO: scanning low vcal = 180
[11:52:52.380] INFO: Test took 4162ms.
[11:52:52.442] INFO: scanning low vcal = 190
[11:52:56.596] INFO: Test took 4154ms.
[11:52:56.655] INFO: scanning low vcal = 200
[11:53:00.824] INFO: Test took 4169ms.
[11:53:00.883] INFO: scanning low vcal = 210
[11:53:05.028] INFO: Test took 4145ms.
[11:53:05.088] INFO: scanning low vcal = 220
[11:53:09.223] INFO: Test took 4134ms.
[11:53:09.285] INFO: scanning low vcal = 230
[11:53:13.432] INFO: Test took 4147ms.
[11:53:13.491] INFO: scanning low vcal = 240
[11:53:17.620] INFO: Test took 4129ms.
[11:53:17.678] INFO: scanning low vcal = 250
[11:53:21.787] INFO: Test took 4109ms.
[11:53:21.847] INFO: scanning high vcal = 30 (= 210 in low range)
[11:53:25.952] INFO: Test took 4105ms.
[11:53:26.009] INFO: scanning high vcal = 50 (= 350 in low range)
[11:53:30.115] INFO: Test took 4106ms.
[11:53:30.173] INFO: scanning high vcal = 70 (= 490 in low range)
[11:53:34.283] INFO: Test took 4110ms.
[11:53:34.341] INFO: scanning high vcal = 90 (= 630 in low range)
[11:53:38.447] INFO: Test took 4106ms.
[11:53:38.505] INFO: scanning high vcal = 200 (= 1400 in low range)
[11:53:42.613] INFO: Test took 4108ms.
[11:53:43.146] INFO: PixTestGainPedestal::measure() done
[11:53:43.148] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C0
[11:53:43.148] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C1
[11:53:43.148] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C2
[11:53:43.149] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C3
[11:53:43.149] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C4
[11:53:43.149] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C5
[11:53:43.149] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C6
[11:53:43.149] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C7
[11:53:43.149] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C8
[11:53:43.150] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C9
[11:53:43.150] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C10
[11:53:43.150] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C11
[11:53:43.150] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C12
[11:53:43.150] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C13
[11:53:43.150] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C14
[11:53:43.150] DEBUG: <PixTestGainPedestal.cc/fit:L380> Create hist gainPedestalP1_C15
[11:54:12.624] INFO: PixTestGainPedestal::fit() done
[11:54:12.624] INFO: non-linearity mean: 0.955 0.953 0.956 0.956 0.957 0.964 0.963 0.950 0.950 0.957 0.957 0.957 0.954 0.962 0.958 0.953
[11:54:12.624] INFO: non-linearity RMS: 0.006 0.008 0.006 0.007 0.005 0.004 0.005 0.007 0.006 0.005 0.006 0.007 0.005 0.005 0.004 0.006
[11:54:12.624] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//phCalibrationFitErr35_C0.dat
[11:54:12.641] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//phCalibrationFitErr35_C1.dat
[11:54:12.657] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//phCalibrationFitErr35_C2.dat
[11:54:12.673] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//phCalibrationFitErr35_C3.dat
[11:54:12.690] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//phCalibrationFitErr35_C4.dat
[11:54:12.706] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//phCalibrationFitErr35_C5.dat
[11:54:12.722] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//phCalibrationFitErr35_C6.dat
[11:54:12.739] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//phCalibrationFitErr35_C7.dat
[11:54:12.755] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//phCalibrationFitErr35_C8.dat
[11:54:12.772] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//phCalibrationFitErr35_C9.dat
[11:54:12.788] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//phCalibrationFitErr35_C10.dat
[11:54:12.804] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//phCalibrationFitErr35_C11.dat
[11:54:12.821] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//phCalibrationFitErr35_C12.dat
[11:54:12.837] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//phCalibrationFitErr35_C13.dat
[11:54:12.853] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//phCalibrationFitErr35_C14.dat
[11:54:12.870] INFO: write gain/ped parameters into /home/pixel_dev/elcomandante/trunk/DATA/ThermalCycling/M3022_FullQualification_2015-07-31_09h17m_1438327071//002_Fulltest_m20//phCalibrationFitErr35_C15.dat
[11:54:12.886] INFO: PixTestGainPedestal::doTest() done, duration: 154 seconds
[11:54:12.886] DEBUG: <PixTestGainPedestal.cc/~PixTestGainPedestal:L125> PixTestGainPedestal dtor
[11:54:12.892] DEBUG: <PixTestFullTest.cc/~PixTestFullTest:L78> PixTestFullTest dtor
[11:54:12.892] INFO: enter test to run
[11:54:12.892] INFO: test: q no parameter change
[11:54:12.892] DEBUG: <PixMonitor.cc/dumpSummaries:L34> PixMonitor::dumpSummaries
[11:54:13.022] QUIET: Connection to board 98 closed.
[11:54:13.023] INFO: pXar: this is the end, my friend
[11:54:13.023] DEBUG: <PixSetup.cc/~PixSetup:L68> PixSetup free fPxarMemory
MoReWeb-v0.6.7-17-g62372b6 on branch psi46master