[13:12:44.319] <TB3> INFO: *** Welcome to pxar ***
[13:12:44.320] <TB3> INFO: *** Today: 2015/12/04
[13:12:44.803] <TB3> INFO: *** Version: 9da6
[13:12:44.804] <TB3> INFO: readRocDacs: /home/mameinha/data/R424_AnalysisROC_m20_2015-12-04_14h00m_1449234020//000_AnalysisROC_m20//dacParameters_C0.dat .. /home/mameinha/data/R424_AnalysisROC_m20_2015-12-04_14h00m_1449234020//000_AnalysisROC_m20//dacParameters_C0.dat
[13:12:44.822] <TB3> INFO: readTbmDacs: /home/mameinha/data/R424_AnalysisROC_m20_2015-12-04_14h00m_1449234020//000_AnalysisROC_m20//tbmParameters_C0a.dat .. /home/mameinha/data/R424_AnalysisROC_m20_2015-12-04_14h00m_1449234020//000_AnalysisROC_m20//tbmParameters_C4294967295b.dat
[13:12:44.822] <TB3> INFO: readMaskFile: /home/mameinha/data/R424_AnalysisROC_m20_2015-12-04_14h00m_1449234020//000_AnalysisROC_m20//defaultMaskFile.dat
[13:12:44.823] <TB3> INFO: readTrimFile: /home/mameinha/data/R424_AnalysisROC_m20_2015-12-04_14h00m_1449234020//000_AnalysisROC_m20//trimParameters_C0.dat .. /home/mameinha/data/R424_AnalysisROC_m20_2015-12-04_14h00m_1449234020//000_AnalysisROC_m20//trimParameters_C0.dat
[13:12:44.831] <TB3> INFO: clk: 4
[13:12:44.831] <TB3> INFO: ctr: 4
[13:12:44.831] <TB3> INFO: sda: 19
[13:12:44.831] <TB3> INFO: tin: 9
[13:12:44.831] <TB3> INFO: level: 15
[13:12:44.831] <TB3> INFO: deser160phase: 4
[13:12:44.831] <TB3> QUIET: Instanciating API for pxar v2.6.1+42~g55d8827
[13:12:44.831] <TB3> INFO: Log level: INFO
[13:12:44.836] <TB3> INFO: Found DTB DTB_WWXJGB
[13:12:44.845] <TB3> QUIET: Connection to board DTB_WWXJGB opened.
[13:12:44.849] <TB3> INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 137
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WWXJGB
MAC address: 40D855118089
Hostname: pixelDTB137
Comment:
------------------------------------------------------
[13:12:44.851] <TB3> INFO: RPC call hashes of host and DTB match: 398089610
[13:12:46.024] <TB3> INFO: DUT info:
[13:12:46.024] <TB3> INFO: The DUT currently contains the following objects:
[13:12:46.024] <TB3> INFO: 0 TBM Cores (0 ON)
[13:12:46.024] <TB3> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[13:12:46.024] <TB3> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[13:12:46.426] <TB3> INFO: enter 'restricted' command line mode
[13:12:46.426] <TB3> INFO: enter test to run
[13:12:46.426] <TB3> INFO: test: Setup no parameter change
[13:12:46.427] <TB3> INFO: running: setup
[13:12:46.438] <TB3> INFO: PixTestSetup::doTest() ntrig = 10

[13:12:46.438] <TB3> INFO: PixTestSetup:: pg set to RES|TOK
[13:12:46.438] <TB3> INFO: 0 1 2 3 4 5 6 7
[13:12:49.482] <TB3> INFO: 0: 000 008 084 87c 7f0 f00 000 000
[13:12:52.497] <TB3> INFO: 1: 000 008 084 87c <7f8>[*] f80 <7f8>[1] 000
[13:12:55.512] <TB3> INFO: 2: 000 008 084 87c <7f8>[*] f80 <7f8>[1] 000
[13:12:58.527] <TB3> INFO: 3: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[13:13:01.542] <TB3> INFO: 4: 800 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[13:13:04.557] <TB3> INFO: 5: 000 004 040 43c 3fc fc0 c00 000
[13:13:07.571] <TB3> INFO: 6: 000 004 040 43c 3fc fc0 c00 000
[13:13:10.587] <TB3> INFO: 7: 000 000 040 43c 3fc fc0 c00 000
[13:13:13.602] <TB3> INFO: 8: 000 000 000 03c 3fc fc0 c00 000
[13:13:16.617] <TB3> INFO: 9: 000 000 000 03c 3fc fc0 c00 000
[13:13:19.632] <TB3> INFO: 10: c00 000 000 01c 1fc fe0 c00 000
[13:13:22.647] <TB3> INFO: 11: 000 000 020 21c 1fc fe0 e00 000
[13:13:25.661] <TB3> INFO: 12: 000 000 020 21c 1fc fe0 e00 000
[13:13:28.676] <TB3> INFO: 13: 000 000 000 01c 1fc fe0 e00 000
[13:13:31.691] <TB3> INFO: 14: 000 000 000 01c 1fc fe0 e00 000
[13:13:34.705] <TB3> INFO: 15: 000 000 010 10c 0fc ff0 f00 000
[13:13:37.720] <TB3> INFO: 16: 000 000 010 10c 0fc ff0 f00 000
[13:13:40.735] <TB3> INFO: 17: 000 000 010 10c 0fc ff0 f00 000
[13:13:43.750] <TB3> INFO: 18: 000 000 000 00c 0fc ff0 f00 000
[13:13:46.765] <TB3> INFO: 19: 000 000 000 08c 0fc ff0 f00 000
[13:13:47.174] <TB3> INFO: Found good delays at CLK = 2, DESER160 = 4
[13:13:47.175] <TB3> INFO: PixTestSetup:: Write Tb parameters to file.
[13:13:47.203] <TB3> INFO: write dtb parameters into /home/mameinha/data/R424_AnalysisROC_m20_2015-12-04_14h00m_1449234020//000_AnalysisROC_m20//tbParameters.dat
[13:13:47.208] <TB3> INFO: PixTestSetup::doTest() done for.
[13:13:47.232] <TB3> INFO: enter test to run
[13:13:47.232] <TB3> INFO: test: Pretest no parameter change
[13:13:47.232] <TB3> INFO: running: pretest
[13:13:47.234] <TB3> INFO: ----------------------------------------------------------------------
[13:13:47.234] <TB3> INFO: PixTestPretest::programROC()
[13:13:47.234] <TB3> INFO: ----------------------------------------------------------------------
[13:13:50.236] <TB3> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[13:13:50.236] <TB3> INFO: IA differences per ROC: 19.3
[13:13:50.242] <TB3> INFO: enter test to run
[13:13:50.242] <TB3> INFO: test: Pretest no parameter change
[13:13:50.242] <TB3> INFO: running: pretest
[13:13:50.243] <TB3> INFO: ----------------------------------------------------------------------
[13:13:50.243] <TB3> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[13:13:50.243] <TB3> INFO: ----------------------------------------------------------------------
[13:13:50.955] <TB3> INFO: PixTestPretest::setVana() done, Module Ia 24.1 mA = 24.1 mA/ROC
[13:13:50.955] <TB3> INFO: i(loss) [mA/ROC]: 20.9
[13:13:50.959] <TB3> INFO: enter test to run
[13:13:50.959] <TB3> INFO: test: Pretest no parameter change
[13:13:50.959] <TB3> INFO: running: pretest
[13:13:50.961] <TB3> INFO: ----------------------------------------------------------------------
[13:13:50.961] <TB3> INFO: PixTestPretest::findWorkingPixel()
[13:13:50.961] <TB3> INFO: ----------------------------------------------------------------------
[13:13:50.971] <TB3> INFO: Expecting 231680 events.
[13:13:53.230] <TB3> INFO: 231680 events read in total (1871ms).
[13:13:53.232] <TB3> INFO: Test took 2271ms.
[13:13:53.603] <TB3> INFO: Found working pixel in all ROCs: col/row = 12/22
[13:13:53.610] <TB3> INFO: enter test to run
[13:13:53.610] <TB3> INFO: test: Pretest no parameter change
[13:13:53.610] <TB3> INFO: running: pretest
[13:13:53.612] <TB3> INFO: ----------------------------------------------------------------------
[13:13:53.612] <TB3> INFO: PixTestPretest::setVthrCompCalDel()
[13:13:53.612] <TB3> INFO: ----------------------------------------------------------------------
[13:13:53.621] <TB3> INFO: Expecting 231680 events.
[13:13:55.890] <TB3> INFO: 231680 events read in total (1882ms).
[13:13:55.897] <TB3> INFO: Test took 2285ms.
[13:13:56.265] <TB3> INFO: PixTestPretest::setVthrCompCalDel() done
[13:13:56.265] <TB3> INFO: CalDel: 137
[13:13:56.265] <TB3> INFO: VthrComp: 51
[13:13:56.273] <TB3> INFO: enter test to run
[13:13:56.273] <TB3> INFO: test: Pretest no parameter change
[13:13:56.273] <TB3> INFO: running: pretest
[13:13:56.302] <TB3> INFO: write dac parameters into /home/mameinha/data/R424_AnalysisROC_m20_2015-12-04_14h00m_1449234020//000_AnalysisROC_m20//dacParameters_C0.dat
[13:13:56.306] <TB3> INFO: enter test to run
[13:13:56.306] <TB3> INFO: test: PixelAlive no parameter change
[13:13:56.306] <TB3> INFO: running: pixelalive
[13:13:56.307] <TB3> INFO: ######################################################################
[13:13:56.307] <TB3> INFO: PixTestAlive::doTest()
[13:13:56.307] <TB3> INFO: ######################################################################
[13:13:56.309] <TB3> INFO: ----------------------------------------------------------------------
[13:13:56.309] <TB3> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[13:13:56.309] <TB3> INFO: ----------------------------------------------------------------------
[13:13:56.331] <TB3> INFO: Expecting 41600 events.
[13:13:57.137] <TB3> INFO: 41600 events read in total (419ms).
[13:13:57.137] <TB3> INFO: Test took 827ms.
[13:13:57.138] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:13:57.525] <TB3> INFO: PixTestAlive::aliveTest() done
[13:13:57.525] <TB3> INFO: number of dead pixels (per ROC): 0
[13:13:57.527] <TB3> INFO: ----------------------------------------------------------------------
[13:13:57.527] <TB3> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[13:13:57.527] <TB3> INFO: ----------------------------------------------------------------------
[13:13:57.554] <TB3> INFO: Expecting 41600 events.
[13:13:58.306] <TB3> INFO: 41600 events read in total (365ms).
[13:13:58.306] <TB3> INFO: Test took 779ms.
[13:13:58.306] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:13:58.306] <TB3> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[13:13:58.697] <TB3> INFO: PixTestAlive::maskTest() done
[13:13:58.697] <TB3> INFO: number of mask-defect pixels (per ROC): 0
[13:13:58.699] <TB3> INFO: ----------------------------------------------------------------------
[13:13:58.699] <TB3> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[13:13:58.699] <TB3> INFO: ----------------------------------------------------------------------
[13:13:58.722] <TB3> INFO: Expecting 41600 events.
[13:13:59.525] <TB3> INFO: 41600 events read in total (416ms).
[13:13:59.526] <TB3> INFO: Test took 827ms.
[13:13:59.526] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:13:59.912] <TB3> INFO: PixTestAlive::addressDecodingTest() done
[13:13:59.912] <TB3> INFO: number of address-decoding pixels (per ROC): 0
[13:13:59.912] <TB3> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[13:13:59.913] <TB3> INFO: enter test to run
[13:13:59.913] <TB3> INFO: test: Scurves no parameter change
[13:13:59.914] <TB3> INFO: running: scurves
[13:13:59.915] <TB3> INFO: ######################################################################
[13:13:59.915] <TB3> INFO: PixTestScurves::doTest() ntrig = 50
[13:13:59.915] <TB3> INFO: ######################################################################
[13:13:59.915] <TB3> INFO: ----------------------------------------------------------------------
[13:13:59.915] <TB3> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[13:13:59.915] <TB3> INFO: ----------------------------------------------------------------------
[13:13:59.916] <TB3> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[13:13:59.933] <TB3> INFO: dacScan split into 1 runs with ntrig = 50
[13:13:59.933] <TB3> INFO: run 1 of 1
[13:13:59.956] <TB3> INFO: Expecting 41808000 events.
[13:16:08.044] <TB3> INFO: 17470300 events read in total (127700ms).
[13:18:14.096] <TB3> INFO: 34720150 events read in total (253752ms).
[13:19:05.103] <TB3> INFO: 41808000 events read in total (304759ms).
[13:19:05.148] <TB3> INFO: Test took 305215ms.
[13:19:05.173] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:19:05.183] <TB3> INFO: dumping ASCII scurve output file: SCurveData
[13:19:06.659] <TB3> INFO: PixTestScurves::scurves() done
[13:19:06.659] <TB3> INFO: Vcal mean: 54.39
[13:19:06.659] <TB3> INFO: Vcal RMS: 3.90
[13:19:06.664] <TB3> INFO: enter test to run
[13:19:06.664] <TB3> INFO: test: Trim no parameter change
[13:19:06.664] <TB3> INFO: running: trim
[13:19:06.666] <TB3> INFO: ######################################################################
[13:19:06.666] <TB3> INFO: PixTestTrim::doTest()
[13:19:06.666] <TB3> INFO: ######################################################################
[13:19:06.667] <TB3> INFO: ----------------------------------------------------------------------
[13:19:06.667] <TB3> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[13:19:06.667] <TB3> INFO: ----------------------------------------------------------------------
[13:19:06.673] <TB3> INFO: ---> VthrComp thr map (minimal VthrComp)
[13:19:06.673] <TB3> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[13:19:06.680] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:19:06.680] <TB3> INFO: run 1 of 1
[13:19:06.700] <TB3> INFO: Expecting 6281600 events.
[13:19:53.587] <TB3> INFO: 6281600 events read in total (46500ms).
[13:19:53.608] <TB3> INFO: Test took 46928ms.
[13:19:53.618] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:19:54.761] <TB3> INFO: ROC 0 VthrComp = 67
[13:19:54.761] <TB3> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[13:19:54.761] <TB3> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[13:19:54.769] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:19:54.769] <TB3> INFO: run 1 of 1
[13:19:54.788] <TB3> INFO: Expecting 6281600 events.
[13:20:45.173] <TB3> INFO: 6281600 events read in total (49998ms).
[13:20:45.233] <TB3> INFO: Test took 50464ms.
[13:20:45.254] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:20:46.724] <TB3> INFO: roc 0 with ID = 0 has maximal Vcal 52.5422 for pixel 0/35 mean/min/max = 42.4368/32.0079/52.8658
[13:20:46.732] <TB3> INFO: Expecting 514560 events.
[13:20:50.809] <TB3> INFO: 514560 events read in total (3690ms).
[13:20:50.814] <TB3> INFO: Test took 4090ms.
[13:20:51.231] <TB3> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[13:20:51.238] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:20:51.238] <TB3> INFO: run 1 of 1
[13:20:51.257] <TB3> INFO: Expecting 6281600 events.
[13:21:42.107] <TB3> INFO: 6281600 events read in total (50463ms).
[13:21:42.158] <TB3> INFO: Test took 50920ms.
[13:21:42.180] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:21:43.372] <TB3> INFO: ---> TrimStepCorr4 extremal thresholds: 16.626900 .. 43.022410
[13:21:43.377] <TB3> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 6 .. 53 (-1/-1) hits flags = 528 (plus default)
[13:21:43.384] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:21:43.384] <TB3> INFO: run 1 of 1
[13:21:43.404] <TB3> INFO: Expecting 1996800 events.
[13:21:59.090] <TB3> INFO: 1996800 events read in total (15300ms).
[13:21:59.099] <TB3> INFO: Test took 15715ms.
[13:21:59.103] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:21:59.909] <TB3> INFO: ---> TrimStepCorr2 extremal thresholds: 21.874165 .. 38.592441
[13:21:59.914] <TB3> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 11 .. 48 (-1/-1) hits flags = 528 (plus default)
[13:21:59.921] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:21:59.921] <TB3> INFO: run 1 of 1
[13:21:59.941] <TB3> INFO: Expecting 1580800 events.
[13:22:12.433] <TB3> INFO: 1580800 events read in total (12105ms).
[13:22:12.440] <TB3> INFO: Test took 12519ms.
[13:22:12.443] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:22:13.203] <TB3> INFO: ---> TrimStepCorr1a extremal thresholds: 26.699021 .. 37.028411
[13:22:13.208] <TB3> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 16 .. 47 (-1/-1) hits flags = 528 (plus default)
[13:22:13.215] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:22:13.215] <TB3> INFO: run 1 of 1
[13:22:13.234] <TB3> INFO: Expecting 1331200 events.
[13:22:24.042] <TB3> INFO: 1331200 events read in total (10421ms).
[13:22:24.050] <TB3> INFO: Test took 10835ms.
[13:22:24.054] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:22:24.806] <TB3> INFO: ---> TrimStepCorr1b extremal thresholds: 27.804511 .. 36.430787
[13:22:24.811] <TB3> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 17 .. 46 (-1/-1) hits flags = 528 (plus default)
[13:22:24.818] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:22:24.818] <TB3> INFO: run 1 of 1
[13:22:24.837] <TB3> INFO: Expecting 1248000 events.
[13:22:34.947] <TB3> INFO: 1248000 events read in total (9723ms).
[13:22:34.953] <TB3> INFO: Test took 10135ms.
[13:22:34.956] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:22:35.788] <TB3> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[13:22:35.788] <TB3> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[13:22:35.797] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:22:35.797] <TB3> INFO: run 1 of 1
[13:22:35.820] <TB3> INFO: Expecting 1705600 events.
[13:22:49.534] <TB3> INFO: 1705600 events read in total (13327ms).
[13:22:49.544] <TB3> INFO: Test took 13747ms.
[13:22:49.548] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:22:50.380] <TB3> INFO: write dac parameters into /home/mameinha/data/R424_AnalysisROC_m20_2015-12-04_14h00m_1449234020//000_AnalysisROC_m20//dacParameters35_C0.dat
[13:22:50.384] <TB3> INFO: write trim parameters into /home/mameinha/data/R424_AnalysisROC_m20_2015-12-04_14h00m_1449234020//000_AnalysisROC_m20//trimParameters35_C0.dat
[13:22:50.396] <TB3> INFO: PixTestTrim::trimTest() done
[13:22:50.396] <TB3> INFO: vtrim: 86
[13:22:50.396] <TB3> INFO: vthrcomp: 67
[13:22:50.396] <TB3> INFO: vcal mean: 35.05
[13:22:50.396] <TB3> INFO: vcal RMS: 0.65
[13:22:50.396] <TB3> INFO: bits mean: 11.02
[13:22:50.396] <TB3> INFO: bits RMS: 2.18
[13:22:50.400] <TB3> INFO: ----------------------------------------------------------------------
[13:22:50.400] <TB3> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[13:22:50.400] <TB3> INFO: ----------------------------------------------------------------------
[13:22:50.400] <TB3> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[13:22:50.408] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:22:50.408] <TB3> INFO: run 1 of 1
[13:22:50.427] <TB3> INFO: Expecting 8320000 events.
[13:23:55.876] <TB3> INFO: 8320000 events read in total (65061ms).
[13:23:55.928] <TB3> INFO: Test took 65520ms.
[13:23:55.957] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:23:57.651] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 106 (-1/-1) hits flags = 528 (plus default)
[13:23:57.659] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:23:57.659] <TB3> INFO: run 1 of 1
[13:23:57.678] <TB3> INFO: Expecting 4451200 events.
[13:24:32.105] <TB3> INFO: 4451200 events read in total (34040ms).
[13:24:32.124] <TB3> INFO: Test took 34465ms.
[13:24:32.133] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:24:33.218] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 94 (-1/-1) hits flags = 528 (plus default)
[13:24:33.226] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:24:33.226] <TB3> INFO: run 1 of 1
[13:24:33.245] <TB3> INFO: Expecting 3952000 events.
[13:25:03.378] <TB3> INFO: 3952000 events read in total (29746ms).
[13:25:03.392] <TB3> INFO: Test took 30166ms.
[13:25:03.398] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:25:04.485] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 93 (-1/-1) hits flags = 528 (plus default)
[13:25:04.495] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:25:04.495] <TB3> INFO: run 1 of 1
[13:25:04.517] <TB3> INFO: Expecting 3910400 events.
[13:25:34.256] <TB3> INFO: 3910400 events read in total (29351ms).
[13:25:34.270] <TB3> INFO: Test took 29775ms.
[13:25:34.276] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:25:35.270] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 93 (-1/-1) hits flags = 528 (plus default)
[13:25:35.277] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:25:35.277] <TB3> INFO: run 1 of 1
[13:25:35.297] <TB3> INFO: Expecting 3910400 events.
[13:26:05.488] <TB3> INFO: 3910400 events read in total (29804ms).
[13:26:05.502] <TB3> INFO: Test took 30225ms.
[13:26:05.509] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:26:06.521] <TB3> INFO: PixTestTrim::trimBitTest() done
[13:26:06.713] <TB3> INFO: PixTestTrim::doTest() done, duration: 420 seconds
[13:26:06.761] <TB3> INFO: enter test to run
[13:26:06.761] <TB3> INFO: test: PhOptimization no parameter change
[13:26:06.761] <TB3> INFO: running: phoptimization
[13:26:06.761] <TB3> INFO: ######################################################################
[13:26:06.761] <TB3> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[13:26:06.761] <TB3> INFO: ######################################################################
[13:26:06.786] <TB3> INFO: Expecting 41600 events.
[13:26:07.629] <TB3> INFO: 41600 events read in total (456ms).
[13:26:07.629] <TB3> INFO: Test took 866ms.
[13:26:07.629] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:26:08.020] <TB3> INFO: Expecting 41600 events.
[13:26:08.818] <TB3> INFO: 41600 events read in total (411ms).
[13:26:08.818] <TB3> INFO: Test took 1187ms.
[13:26:08.818] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:26:09.210] <TB3> INFO: Expecting 41600 events.
[13:26:10.017] <TB3> INFO: 41600 events read in total (420ms).
[13:26:10.018] <TB3> INFO: Test took 1199ms.
[13:26:10.019] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:26:10.406] <TB3> INFO: Expecting 2560 events.
[13:26:10.824] <TB3> INFO: 2560 events read in total (31ms).
[13:26:10.824] <TB3> INFO: Test took 805ms.
[13:26:11.220] <TB3> INFO: Expecting 655360 events.
[13:26:16.044] <TB3> INFO: 655360 events read in total (4437ms).
[13:26:16.053] <TB3> INFO: Test took 5228ms.
[13:26:16.401] <TB3> INFO: Expecting 655360 events.
[13:26:21.806] <TB3> INFO: 655360 events read in total (5018ms).
[13:26:21.814] <TB3> INFO: Test took 5740ms.
[13:26:21.840] <TB3> INFO: safety margin for low PH: adding 0, margin is now 20
[13:26:21.878] <TB3> INFO: write dac parameters into /home/mameinha/data/R424_AnalysisROC_m20_2015-12-04_14h00m_1449234020//000_AnalysisROC_m20//dacParameters35_C0.dat
[13:26:22.098] <TB3> INFO: Expecting 41600 events.
[13:26:22.868] <TB3> INFO: 41600 events read in total (382ms).
[13:26:22.868] <TB3> INFO: Test took 987ms.
[13:26:23.254] <TB3> INFO: Expecting 41600 events.
[13:26:24.050] <TB3> INFO: 41600 events read in total (409ms).
[13:26:24.051] <TB3> INFO: Test took 1182ms.
[13:26:24.437] <TB3> INFO: Expecting 41600 events.
[13:26:25.219] <TB3> INFO: 41600 events read in total (395ms).
[13:26:25.219] <TB3> INFO: Test took 1168ms.
[13:26:25.602] <TB3> INFO: Expecting 2560 events.
[13:26:26.022] <TB3> INFO: 2560 events read in total (33ms).
[13:26:26.022] <TB3> INFO: Test took 801ms.
[13:26:26.417] <TB3> INFO: Expecting 2560 events.
[13:26:26.835] <TB3> INFO: 2560 events read in total (31ms).
[13:26:26.836] <TB3> INFO: Test took 813ms.
[13:26:27.245] <TB3> INFO: PixTestPhOptimization::doTest() done, duration: 20 seconds
[13:26:27.245] <TB3> INFO: PH scale (per ROC): 97
[13:26:27.245] <TB3> INFO: PH offset (per ROC): 139
[13:26:27.265] <TB3> INFO: enter test to run
[13:26:27.265] <TB3> INFO: test: GainPedestal no parameter change
[13:26:27.265] <TB3> INFO: running: gainpedestal
[13:26:27.266] <TB3> INFO: ######################################################################
[13:26:27.266] <TB3> INFO: PixTestGainPedestal::doTest() ntrig = 10
[13:26:27.266] <TB3> INFO: ######################################################################
[13:26:27.274] <TB3> INFO: scanning low vcal = 10
[13:26:27.294] <TB3> INFO: Expecting 41600 events.
[13:26:28.384] <TB3> INFO: 41600 events read in total (703ms).
[13:26:28.385] <TB3> INFO: Test took 1111ms.
[13:26:28.385] <TB3> INFO: scanning low vcal = 20
[13:26:28.780] <TB3> INFO: Expecting 41600 events.
[13:26:29.877] <TB3> INFO: 41600 events read in total (710ms).
[13:26:29.877] <TB3> INFO: Test took 1492ms.
[13:26:29.878] <TB3> INFO: scanning low vcal = 30
[13:26:30.272] <TB3> INFO: Expecting 41600 events.
[13:26:31.366] <TB3> INFO: 41600 events read in total (707ms).
[13:26:31.367] <TB3> INFO: Test took 1489ms.
[13:26:31.367] <TB3> INFO: scanning low vcal = 40
[13:26:31.762] <TB3> INFO: Expecting 41600 events.
[13:26:32.893] <TB3> INFO: 41600 events read in total (744ms).
[13:26:32.894] <TB3> INFO: Test took 1527ms.
[13:26:32.894] <TB3> INFO: scanning low vcal = 50
[13:26:33.281] <TB3> INFO: Expecting 41600 events.
[13:26:34.416] <TB3> INFO: 41600 events read in total (748ms).
[13:26:34.417] <TB3> INFO: Test took 1523ms.
[13:26:34.417] <TB3> INFO: scanning low vcal = 60
[13:26:34.802] <TB3> INFO: Expecting 41600 events.
[13:26:35.931] <TB3> INFO: 41600 events read in total (742ms).
[13:26:35.932] <TB3> INFO: Test took 1515ms.
[13:26:35.932] <TB3> INFO: scanning low vcal = 70
[13:26:36.321] <TB3> INFO: Expecting 41600 events.
[13:26:37.450] <TB3> INFO: 41600 events read in total (742ms).
[13:26:37.451] <TB3> INFO: Test took 1519ms.
[13:26:37.451] <TB3> INFO: scanning low vcal = 80
[13:26:37.839] <TB3> INFO: Expecting 41600 events.
[13:26:38.998] <TB3> INFO: 41600 events read in total (772ms).
[13:26:38.999] <TB3> INFO: Test took 1548ms.
[13:26:38.999] <TB3> INFO: scanning low vcal = 90
[13:26:39.382] <TB3> INFO: Expecting 41600 events.
[13:26:40.530] <TB3> INFO: 41600 events read in total (761ms).
[13:26:40.531] <TB3> INFO: Test took 1532ms.
[13:26:40.531] <TB3> INFO: scanning low vcal = 100
[13:26:40.916] <TB3> INFO: Expecting 41600 events.
[13:26:42.076] <TB3> INFO: 41600 events read in total (773ms).
[13:26:42.077] <TB3> INFO: Test took 1546ms.
[13:26:42.077] <TB3> INFO: scanning low vcal = 110
[13:26:42.458] <TB3> INFO: Expecting 41600 events.
[13:26:43.627] <TB3> INFO: 41600 events read in total (782ms).
[13:26:43.627] <TB3> INFO: Test took 1550ms.
[13:26:43.628] <TB3> INFO: scanning low vcal = 120
[13:26:44.008] <TB3> INFO: Expecting 41600 events.
[13:26:45.146] <TB3> INFO: 41600 events read in total (751ms).
[13:26:45.147] <TB3> INFO: Test took 1519ms.
[13:26:45.147] <TB3> INFO: scanning low vcal = 130
[13:26:45.533] <TB3> INFO: Expecting 41600 events.
[13:26:46.671] <TB3> INFO: 41600 events read in total (751ms).
[13:26:46.672] <TB3> INFO: Test took 1525ms.
[13:26:46.672] <TB3> INFO: scanning low vcal = 140
[13:26:47.057] <TB3> INFO: Expecting 41600 events.
[13:26:48.228] <TB3> INFO: 41600 events read in total (784ms).
[13:26:48.228] <TB3> INFO: Test took 1556ms.
[13:26:48.229] <TB3> INFO: scanning low vcal = 150
[13:26:48.609] <TB3> INFO: Expecting 41600 events.
[13:26:49.740] <TB3> INFO: 41600 events read in total (744ms).
[13:26:49.741] <TB3> INFO: Test took 1512ms.
[13:26:49.741] <TB3> INFO: scanning low vcal = 160
[13:26:50.127] <TB3> INFO: Expecting 41600 events.
[13:26:51.294] <TB3> INFO: 41600 events read in total (779ms).
[13:26:51.295] <TB3> INFO: Test took 1554ms.
[13:26:51.296] <TB3> INFO: scanning low vcal = 170
[13:26:51.678] <TB3> INFO: Expecting 41600 events.
[13:26:52.829] <TB3> INFO: 41600 events read in total (764ms).
[13:26:52.829] <TB3> INFO: Test took 1533ms.
[13:26:52.830] <TB3> INFO: scanning low vcal = 180
[13:26:53.211] <TB3> INFO: Expecting 41600 events.
[13:26:54.368] <TB3> INFO: 41600 events read in total (770ms).
[13:26:54.369] <TB3> INFO: Test took 1539ms.
[13:26:54.369] <TB3> INFO: scanning low vcal = 190
[13:26:54.752] <TB3> INFO: Expecting 41600 events.
[13:26:55.924] <TB3> INFO: 41600 events read in total (784ms).
[13:26:55.924] <TB3> INFO: Test took 1555ms.
[13:26:55.925] <TB3> INFO: scanning low vcal = 200
[13:26:56.306] <TB3> INFO: Expecting 41600 events.
[13:26:57.440] <TB3> INFO: 41600 events read in total (747ms).
[13:26:57.440] <TB3> INFO: Test took 1515ms.
[13:26:57.440] <TB3> INFO: scanning low vcal = 210
[13:26:57.827] <TB3> INFO: Expecting 41600 events.
[13:26:58.955] <TB3> INFO: 41600 events read in total (741ms).
[13:26:58.955] <TB3> INFO: Test took 1515ms.
[13:26:58.955] <TB3> INFO: scanning low vcal = 220
[13:26:59.344] <TB3> INFO: Expecting 41600 events.
[13:27:00.499] <TB3> INFO: 41600 events read in total (767ms).
[13:27:00.500] <TB3> INFO: Test took 1545ms.
[13:27:00.500] <TB3> INFO: scanning low vcal = 230
[13:27:00.881] <TB3> INFO: Expecting 41600 events.
[13:27:02.037] <TB3> INFO: 41600 events read in total (768ms).
[13:27:02.037] <TB3> INFO: Test took 1537ms.
[13:27:02.038] <TB3> INFO: scanning low vcal = 240
[13:27:02.418] <TB3> INFO: Expecting 41600 events.
[13:27:03.561] <TB3> INFO: 41600 events read in total (756ms).
[13:27:03.562] <TB3> INFO: Test took 1524ms.
[13:27:03.562] <TB3> INFO: scanning low vcal = 250
[13:27:03.948] <TB3> INFO: Expecting 41600 events.
[13:27:05.120] <TB3> INFO: 41600 events read in total (785ms).
[13:27:05.121] <TB3> INFO: Test took 1559ms.
[13:27:05.121] <TB3> INFO: scanning high vcal = 30 (= 210 in low range)
[13:27:05.500] <TB3> INFO: Expecting 41600 events.
[13:27:06.657] <TB3> INFO: 41600 events read in total (770ms).
[13:27:06.658] <TB3> INFO: Test took 1537ms.
[13:27:06.658] <TB3> INFO: scanning high vcal = 50 (= 350 in low range)
[13:27:07.040] <TB3> INFO: Expecting 41600 events.
[13:27:08.189] <TB3> INFO: 41600 events read in total (762ms).
[13:27:08.189] <TB3> INFO: Test took 1531ms.
[13:27:08.190] <TB3> INFO: scanning high vcal = 70 (= 490 in low range)
[13:27:08.573] <TB3> INFO: Expecting 41600 events.
[13:27:09.706] <TB3> INFO: 41600 events read in total (746ms).
[13:27:09.707] <TB3> INFO: Test took 1517ms.
[13:27:09.707] <TB3> INFO: scanning high vcal = 90 (= 630 in low range)
[13:27:10.091] <TB3> INFO: Expecting 41600 events.
[13:27:11.236] <TB3> INFO: 41600 events read in total (758ms).
[13:27:11.237] <TB3> INFO: Test took 1530ms.
[13:27:11.237] <TB3> INFO: scanning high vcal = 200 (= 1400 in low range)
[13:27:11.619] <TB3> INFO: Expecting 41600 events.
[13:27:12.729] <TB3> INFO: 41600 events read in total (723ms).
[13:27:12.730] <TB3> INFO: Test took 1493ms.
[13:27:13.117] <TB3> INFO: PixTestGainPedestal::measure() done
[13:27:15.001] <TB3> INFO: PixTestGainPedestal::fit() done
[13:27:15.001] <TB3> INFO: non-linearity mean: 0.942
[13:27:15.001] <TB3> INFO: non-linearity RMS: 0.009
[13:27:15.067] <TB3> INFO: write gain/ped parameters into /home/mameinha/data/R424_AnalysisROC_m20_2015-12-04_14h00m_1449234020//000_AnalysisROC_m20//phCalibrationFitErr35_C0.dat
[13:27:15.109] <TB3> INFO: PixTestGainPedestal::doTest() done, duration: 47 seconds
[13:27:15.110] <TB3> INFO: enter test to run
[13:27:15.110] <TB3> INFO: test: Readback no parameter change
[13:27:15.110] <TB3> INFO: running: readback
[13:27:15.110] <TB3> INFO: readReadbackCal: /home/mameinha/data/R424_AnalysisROC_m20_2015-12-04_14h00m_1449234020//000_AnalysisROC_m20//readbackCal_C0.dat .. /home/mameinha/data/R424_AnalysisROC_m20_2015-12-04_14h00m_1449234020//000_AnalysisROC_m20//readbackCal_C0.dat
[13:27:15.111] <TB3> INFO: ######################################################################
[13:27:15.111] <TB3> INFO: PixTestReadback::doTest()
[13:27:15.111] <TB3> INFO: ######################################################################
[13:27:15.111] <TB3> INFO: ----------------------------------------------------------------------
[13:27:15.111] <TB3> INFO: PixTestReadback::CalibrateVd()
[13:27:15.111] <TB3> INFO: ----------------------------------------------------------------------
[13:27:27.423] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R424_AnalysisROC_m20_2015-12-04_14h00m_1449234020//000_AnalysisROC_m20//readbackCal_C0.dat
[13:27:27.538] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[13:27:27.538] <TB3> INFO: ----------------------------------------------------------------------
[13:27:27.538] <TB3> INFO: PixTestReadback::CalibrateVa()
[13:27:27.538] <TB3> INFO: ----------------------------------------------------------------------
[13:27:38.650] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R424_AnalysisROC_m20_2015-12-04_14h00m_1449234020//000_AnalysisROC_m20//readbackCal_C0.dat
[13:27:38.659] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[13:27:38.659] <TB3> INFO: ----------------------------------------------------------------------
[13:27:38.659] <TB3> INFO: PixTestReadback::readbackVbg()
[13:27:38.659] <TB3> INFO: ----------------------------------------------------------------------
[13:27:46.996] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[13:27:46.996] <TB3> INFO: ----------------------------------------------------------------------
[13:27:46.996] <TB3> INFO: PixTestReadback::getCalibratedVbg()
[13:27:46.996] <TB3> INFO: ----------------------------------------------------------------------
[13:27:46.996] <TB3> INFO: Vbg will be calibrated using Vd calibration
[13:27:46.996] <TB3> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 127calibrated Vbg = 1.31217 :::*/*/*/*/
[13:27:47.372] <TB3> INFO: ----------------------------------------------------------------------
[13:27:47.372] <TB3> INFO: PixTestReadback::CalibrateIa()
[13:27:47.372] <TB3> INFO: ----------------------------------------------------------------------
[13:27:56.233] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R424_AnalysisROC_m20_2015-12-04_14h00m_1449234020//000_AnalysisROC_m20//readbackCal_C0.dat
[13:27:56.239] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[13:27:56.239] <TB3> INFO: PixTestReadback::doTest() done
[13:27:56.276] <TB3> INFO: enter test to run
[13:27:56.276] <TB3> INFO: test: no parameter change
[13:27:56.370] <TB3> QUIET: Connection to board 137 closed.
[13:27:56.450] <TB3> INFO: pXar: this is the end, my friend