[12:22:17.790] <TB2> INFO: *** Welcome to pxar ***
[12:22:17.790] <TB2> INFO: *** Today: 2015/10/06
[12:22:17.820] <TB2> INFO: *** Version: 9da6
[12:22:17.820] <TB2> INFO: readRocDacs: /home/mameinha/data/R414_Fulltest_m20_2015-10-06_14h22m_1444134127//000_FulltestROC_m20//dacParameters_C0.dat .. /home/mameinha/data/R414_Fulltest_m20_2015-10-06_14h22m_1444134127//000_FulltestROC_m20//dacParameters_C0.dat
[12:22:17.821] <TB2> INFO: readTbmDacs: /home/mameinha/data/R414_Fulltest_m20_2015-10-06_14h22m_1444134127//000_FulltestROC_m20//tbmParameters_C0a.dat .. /home/mameinha/data/R414_Fulltest_m20_2015-10-06_14h22m_1444134127//000_FulltestROC_m20//tbmParameters_C4294967295b.dat
[12:22:17.821] <TB2> INFO: readMaskFile: /home/mameinha/data/R414_Fulltest_m20_2015-10-06_14h22m_1444134127//000_FulltestROC_m20//defaultMaskFile.dat
[12:22:17.822] <TB2> INFO: readTrimFile: /home/mameinha/data/R414_Fulltest_m20_2015-10-06_14h22m_1444134127//000_FulltestROC_m20//trimParameters_C0.dat .. /home/mameinha/data/R414_Fulltest_m20_2015-10-06_14h22m_1444134127//000_FulltestROC_m20//trimParameters_C0.dat
[12:22:17.829] <TB2> INFO: clk: 2
[12:22:17.829] <TB2> INFO: ctr: 2
[12:22:17.829] <TB2> INFO: sda: 17
[12:22:17.829] <TB2> INFO: tin: 7
[12:22:17.829] <TB2> INFO: level: 15
[12:22:17.829] <TB2> INFO: deser160phase: 4
[12:22:17.829] <TB2> QUIET: Instanciating API for pxar v2.6.0+20~g1a7f656
[12:22:17.829] <TB2> INFO: Log level: INFO
[12:22:17.841] <TB2> QUIET: Connection to board DTB_WWXJGB opened.
[12:22:17.845] <TB2> 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:
------------------------------------------------------
[12:22:17.848] <TB2> INFO: RPC call hashes of host and DTB match: 398089610
[12:22:19.012] <TB2> INFO: DUT info:
[12:22:19.012] <TB2> INFO: The DUT currently contains the following objects:
[12:22:19.012] <TB2> INFO: 0 TBM Cores (0 ON)
[12:22:19.012] <TB2> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[12:22:19.012] <TB2> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[12:22:19.414] <TB2> INFO: enter 'restricted' command line mode
[12:22:19.414] <TB2> INFO: enter test to run
[12:22:19.414] <TB2> INFO: test: Setup no parameter change
[12:22:19.414] <TB2> INFO: running: setup
[12:22:19.418] <TB2> INFO: PixTestSetup::doTest() ntrig = 10

[12:22:19.418] <TB2> INFO: PixTestSetup:: pg set to RES|TOK
[12:22:19.418] <TB2> INFO: 0 1 2 3 4 5 6 7
[12:22:22.462] <TB2> INFO: 0: 000 008 084 07c 7f0 f00 000 000
[12:22:25.476] <TB2> INFO: 1: 000 008 084 87c <7f8>[*] f80 <7f8>[1] 000
[12:22:28.490] <TB2> INFO: 2: 000 008 084 87c <7f8>[*] f80 800 000
[12:22:31.505] <TB2> INFO: 3: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[12:22:34.519] <TB2> INFO: 4: 000 000 044 07c <7f8>[*] f80 <7f8>[1] 000
[12:22:37.533] <TB2> INFO: 5: 000 004 040 03c 3fc fc0 c00 000
[12:22:40.547] <TB2> INFO: 6: c00 004 040 43c 3fc fc0 c00 000
[12:22:43.562] <TB2> INFO: 7: c00 000 040 43c 3fc fc0 c00 000
[12:22:46.576] <TB2> INFO: 8: 000 000 000 03c 3fc fc0 c00 000
[12:22:49.590] <TB2> INFO: 9: 000 000 000 23c 3fc fc0 c00 000
[12:22:52.604] <TB2> INFO: 10: 000 000 000 21c 1fc fc0 c00 000
[12:22:55.618] <TB2> INFO: 11: 000 000 020 21c 1fc fe0 e00 000
[12:22:58.632] <TB2> INFO: 12: 000 000 020 21c 1fc fe0 e00 000
[12:23:01.646] <TB2> INFO: 13: 000 000 000 01c 1fc fe0 e00 000
[12:23:04.660] <TB2> INFO: 14: 000 000 000 11c 1fc fe0 e00 000
[12:23:07.674] <TB2> INFO: 15: 000 000 010 10c 0fc ff0 f00 000
[12:23:10.688] <TB2> INFO: 16: f00 000 010 10c 0fc ff0 f00 000
[12:23:13.702] <TB2> INFO: 17: 000 000 010 10c 0fc ff0 f00 000
[12:23:16.716] <TB2> INFO: 18: 000 000 000 00c 0fc ff0 f00 000
[12:23:19.731] <TB2> INFO: 19: 000 000 000 00c 0fc ff0 f00 000
[12:23:20.137] <TB2> INFO: Found good delays at CLK = 2, DESER160 = 4
[12:23:20.139] <TB2> INFO: PixTestSetup:: Write Tb parameters to file.
[12:23:20.142] <TB2> INFO: write dtb parameters into /home/mameinha/data/R414_Fulltest_m20_2015-10-06_14h22m_1444134127//000_FulltestROC_m20//tbParameters.dat
[12:23:20.145] <TB2> INFO: PixTestSetup::doTest() done for.
[12:23:20.170] <TB2> INFO: enter test to run
[12:23:20.170] <TB2> INFO: test: Pretest no parameter change
[12:23:20.170] <TB2> INFO: running: pretest
[12:23:20.171] <TB2> INFO: ----------------------------------------------------------------------
[12:23:20.171] <TB2> INFO: PixTestPretest::programROC()
[12:23:20.171] <TB2> INFO: ----------------------------------------------------------------------
[12:23:23.174] <TB2> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[12:23:23.174] <TB2> INFO: IA differences per ROC: 19.3
[12:23:23.178] <TB2> INFO: enter test to run
[12:23:23.179] <TB2> INFO: test: Pretest no parameter change
[12:23:23.179] <TB2> INFO: running: pretest
[12:23:23.180] <TB2> INFO: ----------------------------------------------------------------------
[12:23:23.180] <TB2> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[12:23:23.180] <TB2> INFO: ----------------------------------------------------------------------
[12:23:23.690] <TB2> INFO: PixTestPretest::setVana() done, Module Ia 24.1 mA = 24.1 mA/ROC
[12:23:23.690] <TB2> INFO: i(loss) [mA/ROC]: 19.3
[12:23:23.694] <TB2> INFO: enter test to run
[12:23:23.694] <TB2> INFO: test: Pretest no parameter change
[12:23:23.694] <TB2> INFO: running: pretest
[12:23:23.695] <TB2> INFO: ----------------------------------------------------------------------
[12:23:23.695] <TB2> INFO: PixTestPretest::findWorkingPixel()
[12:23:23.695] <TB2> INFO: ----------------------------------------------------------------------
[12:23:23.705] <TB2> INFO: Expecting 231680 events.
[12:23:25.908] <TB2> INFO: 231680 events read in total (1816ms).
[12:23:25.910] <TB2> INFO: Test took 2215ms.
[12:23:26.288] <TB2> INFO: Found working pixel in all ROCs: col/row = 12/22
[12:23:26.295] <TB2> INFO: enter test to run
[12:23:26.295] <TB2> INFO: test: Pretest no parameter change
[12:23:26.295] <TB2> INFO: running: pretest
[12:23:26.296] <TB2> INFO: ----------------------------------------------------------------------
[12:23:26.296] <TB2> INFO: PixTestPretest::setVthrCompCalDel()
[12:23:26.296] <TB2> INFO: ----------------------------------------------------------------------
[12:23:26.306] <TB2> INFO: Expecting 231680 events.
[12:23:28.500] <TB2> INFO: 231680 events read in total (1807ms).
[12:23:28.503] <TB2> INFO: Test took 2206ms.
[12:23:28.884] <TB2> INFO: PixTestPretest::setVthrCompCalDel() done
[12:23:28.884] <TB2> INFO: CalDel: 147
[12:23:28.884] <TB2> INFO: VthrComp: 51
[12:23:28.888] <TB2> INFO: enter test to run
[12:23:28.888] <TB2> INFO: test: Pretest no parameter change
[12:23:28.888] <TB2> INFO: running: pretest
[12:23:28.891] <TB2> INFO: write dac parameters into /home/mameinha/data/R414_Fulltest_m20_2015-10-06_14h22m_1444134127//000_FulltestROC_m20//dacParameters_C0.dat
[12:23:28.894] <TB2> INFO: enter test to run
[12:23:28.894] <TB2> INFO: test: PixelAlive no parameter change
[12:23:28.894] <TB2> INFO: running: pixelalive
[12:23:28.896] <TB2> INFO: ######################################################################
[12:23:28.896] <TB2> INFO: PixTestAlive::doTest()
[12:23:28.896] <TB2> INFO: ######################################################################
[12:23:28.897] <TB2> INFO: ----------------------------------------------------------------------
[12:23:28.897] <TB2> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[12:23:28.897] <TB2> INFO: ----------------------------------------------------------------------
[12:23:28.916] <TB2> INFO: Expecting 41600 events.
[12:23:29.718] <TB2> INFO: 41600 events read in total (414ms).
[12:23:29.719] <TB2> INFO: Test took 822ms.
[12:23:29.719] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:23:30.104] <TB2> INFO: PixTestAlive::aliveTest() done
[12:23:30.104] <TB2> INFO: number of dead pixels (per ROC): 0
[12:23:30.106] <TB2> INFO: ----------------------------------------------------------------------
[12:23:30.106] <TB2> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[12:23:30.106] <TB2> INFO: ----------------------------------------------------------------------
[12:23:30.125] <TB2> INFO: Expecting 41600 events.
[12:23:30.869] <TB2> INFO: 41600 events read in total (357ms).
[12:23:30.869] <TB2> INFO: Test took 763ms.
[12:23:30.869] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:23:30.869] <TB2> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[12:23:31.259] <TB2> INFO: PixTestAlive::maskTest() done
[12:23:31.259] <TB2> INFO: number of mask-defect pixels (per ROC): 0
[12:23:31.261] <TB2> INFO: ----------------------------------------------------------------------
[12:23:31.261] <TB2> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[12:23:31.261] <TB2> INFO: ----------------------------------------------------------------------
[12:23:31.280] <TB2> INFO: Expecting 41600 events.
[12:23:32.080] <TB2> INFO: 41600 events read in total (413ms).
[12:23:32.081] <TB2> INFO: Test took 820ms.
[12:23:32.081] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:23:32.467] <TB2> INFO: PixTestAlive::addressDecodingTest() done
[12:23:32.467] <TB2> INFO: number of address-decoding pixels (per ROC): 0
[12:23:32.467] <TB2> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[12:23:32.468] <TB2> INFO: enter test to run
[12:23:32.468] <TB2> INFO: test: Scurves no parameter change
[12:23:32.468] <TB2> INFO: running: scurves
[12:23:32.469] <TB2> INFO: ######################################################################
[12:23:32.469] <TB2> INFO: PixTestScurves::doTest() ntrig = 50
[12:23:32.469] <TB2> INFO: ######################################################################
[12:23:32.469] <TB2> INFO: ----------------------------------------------------------------------
[12:23:32.469] <TB2> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[12:23:32.469] <TB2> INFO: ----------------------------------------------------------------------
[12:23:32.469] <TB2> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[12:23:32.480] <TB2> INFO: dacScan split into 1 runs with ntrig = 50
[12:23:32.480] <TB2> INFO: run 1 of 1
[12:23:32.499] <TB2> INFO: Expecting 41808000 events.
[12:25:48.351] <TB2> INFO: 19068500 events read in total (135465ms).
[12:27:59.892] <TB2> INFO: 37734600 events read in total (267006ms).
[12:28:28.692] <TB2> INFO: 41808000 events read in total (295806ms).
[12:28:28.723] <TB2> INFO: Test took 296243ms.
[12:28:28.745] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:28:30.176] <TB2> INFO: PixTestScurves::scurves() done
[12:28:30.176] <TB2> INFO: Vcal mean: 73.88
[12:28:30.176] <TB2> INFO: Vcal RMS: 4.98
[12:28:30.181] <TB2> INFO: enter test to run
[12:28:30.181] <TB2> INFO: test: Trim no parameter change
[12:28:30.181] <TB2> INFO: running: trim
[12:28:30.182] <TB2> INFO: ######################################################################
[12:28:30.182] <TB2> INFO: PixTestTrim::doTest()
[12:28:30.182] <TB2> INFO: ######################################################################
[12:28:30.184] <TB2> INFO: ----------------------------------------------------------------------
[12:28:30.184] <TB2> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[12:28:30.184] <TB2> INFO: ----------------------------------------------------------------------
[12:28:30.189] <TB2> INFO: ---> VthrComp thr map (minimal VthrComp)
[12:28:30.189] <TB2> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[12:28:30.196] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:28:30.196] <TB2> INFO: run 1 of 1
[12:28:30.215] <TB2> INFO: Expecting 6281600 events.
[12:29:15.867] <TB2> INFO: 6281600 events read in total (45265ms).
[12:29:15.883] <TB2> INFO: Test took 45687ms.
[12:29:15.891] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:16.953] <TB2> INFO: ROC 0 VthrComp = 79
[12:29:16.953] <TB2> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[12:29:16.953] <TB2> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[12:29:16.960] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:29:16.960] <TB2> INFO: run 1 of 1
[12:29:16.980] <TB2> INFO: Expecting 6281600 events.
[12:30:06.084] <TB2> INFO: 6281600 events read in total (48717ms).
[12:30:06.120] <TB2> INFO: Test took 49160ms.
[12:30:06.140] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:30:07.392] <TB2> INFO: roc 0 with ID = 0 has maximal Vcal 59.6221 for pixel 18/75 mean/min/max = 46.9482/34.1419/59.7544
[12:30:07.401] <TB2> INFO: Expecting 514560 events.
[12:30:11.443] <TB2> INFO: 514560 events read in total (3655ms).
[12:30:11.448] <TB2> INFO: Test took 4056ms.
[12:30:11.843] <TB2> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[12:30:11.850] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:30:11.850] <TB2> INFO: run 1 of 1
[12:30:11.869] <TB2> INFO: Expecting 6281600 events.
[12:31:01.617] <TB2> INFO: 6281600 events read in total (49360ms).
[12:31:01.656] <TB2> INFO: Test took 49805ms.
[12:31:01.676] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:31:02.883] <TB2> INFO: ---> TrimStepCorr4 extremal thresholds: 8.774584 .. 47.992667
[12:31:02.888] <TB2> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 8 .. 57 (-1/-1) hits flags = 528 (plus default)
[12:31:02.895] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:31:02.895] <TB2> INFO: run 1 of 1
[12:31:02.914] <TB2> INFO: Expecting 2080000 events.
[12:31:18.938] <TB2> INFO: 2080000 events read in total (15636ms).
[12:31:18.947] <TB2> INFO: Test took 16052ms.
[12:31:18.951] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:31:19.742] <TB2> INFO: ---> TrimStepCorr2 extremal thresholds: 20.196224 .. 41.699053
[12:31:19.746] <TB2> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 10 .. 51 (-1/-1) hits flags = 528 (plus default)
[12:31:19.754] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:31:19.754] <TB2> INFO: run 1 of 1
[12:31:19.773] <TB2> INFO: Expecting 1747200 events.
[12:31:33.384] <TB2> INFO: 1747200 events read in total (13224ms).
[12:31:33.391] <TB2> INFO: Test took 13637ms.
[12:31:33.395] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:31:34.146] <TB2> INFO: ---> TrimStepCorr1a extremal thresholds: 25.165521 .. 37.657158
[12:31:34.151] <TB2> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 15 .. 47 (-1/-1) hits flags = 528 (plus default)
[12:31:34.158] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:31:34.158] <TB2> INFO: run 1 of 1
[12:31:34.177] <TB2> INFO: Expecting 1372800 events.
[12:31:45.050] <TB2> INFO: 1372800 events read in total (10486ms).
[12:31:45.056] <TB2> INFO: Test took 10898ms.
[12:31:45.059] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:31:45.773] <TB2> INFO: ---> TrimStepCorr1b extremal thresholds: 27.510146 .. 37.411795
[12:31:45.778] <TB2> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 17 .. 47 (-1/-1) hits flags = 528 (plus default)
[12:31:45.785] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:31:45.785] <TB2> INFO: run 1 of 1
[12:31:45.804] <TB2> INFO: Expecting 1289600 events.
[12:31:56.110] <TB2> INFO: 1289600 events read in total (9919ms).
[12:31:56.115] <TB2> INFO: Test took 10331ms.
[12:31:56.118] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:31:56.841] <TB2> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[12:31:56.841] <TB2> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[12:31:56.848] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:31:56.848] <TB2> INFO: run 1 of 1
[12:31:56.867] <TB2> INFO: Expecting 1705600 events.
[12:32:10.257] <TB2> INFO: 1705600 events read in total (13003ms).
[12:32:10.265] <TB2> INFO: Test took 13417ms.
[12:32:10.269] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:32:11.048] <TB2> INFO: write dac parameters into /home/mameinha/data/R414_Fulltest_m20_2015-10-06_14h22m_1444134127//000_FulltestROC_m20//dacParameters35_C0.dat
[12:32:11.063] <TB2> INFO: write trim parameters into /home/mameinha/data/R414_Fulltest_m20_2015-10-06_14h22m_1444134127//000_FulltestROC_m20//trimParameters35_C0.dat
[12:32:11.074] <TB2> INFO: PixTestTrim::trimTest() done
[12:32:11.074] <TB2> INFO: vtrim: 105
[12:32:11.074] <TB2> INFO: vthrcomp: 79
[12:32:11.074] <TB2> INFO: vcal mean: 34.98
[12:32:11.074] <TB2> INFO: vcal RMS: 0.77
[12:32:11.074] <TB2> INFO: bits mean: 8.90
[12:32:11.074] <TB2> INFO: bits RMS: 2.58
[12:32:11.078] <TB2> INFO: ----------------------------------------------------------------------
[12:32:11.078] <TB2> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[12:32:11.078] <TB2> INFO: ----------------------------------------------------------------------
[12:32:11.078] <TB2> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[12:32:11.085] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:32:11.085] <TB2> INFO: run 1 of 1
[12:32:11.104] <TB2> INFO: Expecting 8320000 events.
[12:33:13.834] <TB2> INFO: 8320000 events read in total (62343ms).
[12:33:13.871] <TB2> INFO: Test took 62786ms.
[12:33:13.890] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:33:15.368] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 132 (-1/-1) hits flags = 528 (plus default)
[12:33:15.376] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:33:15.376] <TB2> INFO: run 1 of 1
[12:33:15.395] <TB2> INFO: Expecting 5532800 events.
[12:33:56.533] <TB2> INFO: 5532800 events read in total (40751ms).
[12:33:56.552] <TB2> INFO: Test took 41176ms.
[12:33:56.561] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:33:57.752] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 123 (-1/-1) hits flags = 528 (plus default)
[12:33:57.760] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:33:57.760] <TB2> INFO: run 1 of 1
[12:33:57.779] <TB2> INFO: Expecting 5158400 events.
[12:34:35.908] <TB2> INFO: 5158400 events read in total (37742ms).
[12:34:35.924] <TB2> INFO: Test took 38164ms.
[12:34:35.932] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:34:37.069] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 123 (-1/-1) hits flags = 528 (plus default)
[12:34:37.076] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:34:37.076] <TB2> INFO: run 1 of 1
[12:34:37.096] <TB2> INFO: Expecting 5158400 events.
[12:35:15.343] <TB2> INFO: 5158400 events read in total (37860ms).
[12:35:15.358] <TB2> INFO: Test took 38282ms.
[12:35:15.366] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:35:16.475] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 122 (-1/-1) hits flags = 528 (plus default)
[12:35:16.482] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:35:16.482] <TB2> INFO: run 1 of 1
[12:35:16.501] <TB2> INFO: Expecting 5116800 events.
[12:35:54.404] <TB2> INFO: 5116800 events read in total (37516ms).
[12:35:54.419] <TB2> INFO: Test took 37937ms.
[12:35:54.427] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:35:55.534] <TB2> INFO: PixTestTrim::trimBitTest() done
[12:35:55.535] <TB2> INFO: PixTestTrim::doTest() done, duration: 445 seconds
[12:35:55.575] <TB2> INFO: enter test to run
[12:35:55.575] <TB2> INFO: test: PhOptimization no parameter change
[12:35:55.575] <TB2> INFO: running: phoptimization
[12:35:55.575] <TB2> INFO: ######################################################################
[12:35:55.575] <TB2> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[12:35:55.575] <TB2> INFO: ######################################################################
[12:35:55.596] <TB2> INFO: Expecting 41600 events.
[12:35:56.395] <TB2> INFO: 41600 events read in total (412ms).
[12:35:56.395] <TB2> INFO: Test took 818ms.
[12:35:56.395] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:35:56.787] <TB2> INFO: Expecting 41600 events.
[12:35:57.587] <TB2> INFO: 41600 events read in total (413ms).
[12:35:57.587] <TB2> INFO: Test took 1190ms.
[12:35:57.588] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:35:57.977] <TB2> INFO: Expecting 41600 events.
[12:35:58.777] <TB2> INFO: 41600 events read in total (413ms).
[12:35:58.777] <TB2> INFO: Test took 1188ms.
[12:35:58.778] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:35:59.167] <TB2> INFO: Expecting 2560 events.
[12:35:59.585] <TB2> INFO: 2560 events read in total (31ms).
[12:35:59.585] <TB2> INFO: Test took 807ms.
[12:35:59.981] <TB2> INFO: Expecting 655360 events.
[12:36:05.234] <TB2> INFO: 655360 events read in total (4866ms).
[12:36:05.243] <TB2> INFO: Test took 5657ms.
[12:36:05.536] <TB2> INFO: Expecting 655360 events.
[12:36:10.883] <TB2> INFO: 655360 events read in total (4959ms).
[12:36:10.891] <TB2> INFO: Test took 5634ms.
[12:36:10.911] <TB2> INFO: safety margin for low PH: adding 0, margin is now 20
[12:36:10.926] <TB2> INFO: write dac parameters into /home/mameinha/data/R414_Fulltest_m20_2015-10-06_14h22m_1444134127//000_FulltestROC_m20//dacParameters35_C0.dat
[12:36:11.187] <TB2> INFO: Expecting 41600 events.
[12:36:11.950] <TB2> INFO: 41600 events read in total (376ms).
[12:36:11.950] <TB2> INFO: Test took 1020ms.
[12:36:12.340] <TB2> INFO: Expecting 41600 events.
[12:36:13.102] <TB2> INFO: 41600 events read in total (375ms).
[12:36:13.102] <TB2> INFO: Test took 1151ms.
[12:36:13.492] <TB2> INFO: Expecting 41600 events.
[12:36:14.254] <TB2> INFO: 41600 events read in total (375ms).
[12:36:14.255] <TB2> INFO: Test took 1152ms.
[12:36:14.644] <TB2> INFO: Expecting 2560 events.
[12:36:15.061] <TB2> INFO: 2560 events read in total (30ms).
[12:36:15.062] <TB2> INFO: Test took 807ms.
[12:36:15.457] <TB2> INFO: Expecting 2560 events.
[12:36:15.875] <TB2> INFO: 2560 events read in total (31ms).
[12:36:15.875] <TB2> INFO: Test took 813ms.
[12:36:16.285] <TB2> INFO: PixTestPhOptimization::doTest() done, duration: 20 seconds
[12:36:16.285] <TB2> INFO: PH scale (per ROC): 82
[12:36:16.285] <TB2> INFO: PH offset (per ROC): 153
[12:36:16.298] <TB2> INFO: enter test to run
[12:36:16.298] <TB2> INFO: test: GainPedestal no parameter change
[12:36:16.298] <TB2> INFO: running: gainpedestal
[12:36:16.300] <TB2> INFO: ######################################################################
[12:36:16.300] <TB2> INFO: PixTestGainPedestal::doTest() ntrig = 10
[12:36:16.300] <TB2> INFO: ######################################################################
[12:36:16.308] <TB2> INFO: scanning low vcal = 10
[12:36:16.327] <TB2> INFO: Expecting 41600 events.
[12:36:17.431] <TB2> INFO: 41600 events read in total (717ms).
[12:36:17.431] <TB2> INFO: Test took 1123ms.
[12:36:17.432] <TB2> INFO: scanning low vcal = 20
[12:36:17.826] <TB2> INFO: Expecting 41600 events.
[12:36:18.915] <TB2> INFO: 41600 events read in total (702ms).
[12:36:18.915] <TB2> INFO: Test took 1483ms.
[12:36:18.916] <TB2> INFO: scanning low vcal = 30
[12:36:19.310] <TB2> INFO: Expecting 41600 events.
[12:36:20.400] <TB2> INFO: 41600 events read in total (702ms).
[12:36:20.401] <TB2> INFO: Test took 1485ms.
[12:36:20.401] <TB2> INFO: scanning low vcal = 40
[12:36:20.796] <TB2> INFO: Expecting 41600 events.
[12:36:21.934] <TB2> INFO: 41600 events read in total (751ms).
[12:36:21.935] <TB2> INFO: Test took 1534ms.
[12:36:21.935] <TB2> INFO: scanning low vcal = 50
[12:36:22.324] <TB2> INFO: Expecting 41600 events.
[12:36:23.450] <TB2> INFO: 41600 events read in total (739ms).
[12:36:23.450] <TB2> INFO: Test took 1515ms.
[12:36:23.451] <TB2> INFO: scanning low vcal = 60
[12:36:23.839] <TB2> INFO: Expecting 41600 events.
[12:36:24.980] <TB2> INFO: 41600 events read in total (754ms).
[12:36:24.981] <TB2> INFO: Test took 1530ms.
[12:36:24.981] <TB2> INFO: scanning low vcal = 70
[12:36:25.370] <TB2> INFO: Expecting 41600 events.
[12:36:26.496] <TB2> INFO: 41600 events read in total (739ms).
[12:36:26.496] <TB2> INFO: Test took 1515ms.
[12:36:26.497] <TB2> INFO: scanning low vcal = 80
[12:36:26.885] <TB2> INFO: Expecting 41600 events.
[12:36:28.020] <TB2> INFO: 41600 events read in total (748ms).
[12:36:28.020] <TB2> INFO: Test took 1523ms.
[12:36:28.021] <TB2> INFO: scanning low vcal = 90
[12:36:28.410] <TB2> INFO: Expecting 41600 events.
[12:36:29.549] <TB2> INFO: 41600 events read in total (752ms).
[12:36:29.550] <TB2> INFO: Test took 1529ms.
[12:36:29.550] <TB2> INFO: scanning low vcal = 100
[12:36:29.939] <TB2> INFO: Expecting 41600 events.
[12:36:31.073] <TB2> INFO: 41600 events read in total (747ms).
[12:36:31.074] <TB2> INFO: Test took 1524ms.
[12:36:31.074] <TB2> INFO: scanning low vcal = 110
[12:36:31.463] <TB2> INFO: Expecting 41600 events.
[12:36:32.617] <TB2> INFO: 41600 events read in total (767ms).
[12:36:32.618] <TB2> INFO: Test took 1544ms.
[12:36:32.618] <TB2> INFO: scanning low vcal = 120
[12:36:33.007] <TB2> INFO: Expecting 41600 events.
[12:36:34.133] <TB2> INFO: 41600 events read in total (739ms).
[12:36:34.133] <TB2> INFO: Test took 1515ms.
[12:36:34.134] <TB2> INFO: scanning low vcal = 130
[12:36:34.522] <TB2> INFO: Expecting 41600 events.
[12:36:35.648] <TB2> INFO: 41600 events read in total (738ms).
[12:36:35.649] <TB2> INFO: Test took 1515ms.
[12:36:35.650] <TB2> INFO: scanning low vcal = 140
[12:36:36.038] <TB2> INFO: Expecting 41600 events.
[12:36:37.179] <TB2> INFO: 41600 events read in total (754ms).
[12:36:37.180] <TB2> INFO: Test took 1530ms.
[12:36:37.180] <TB2> INFO: scanning low vcal = 150
[12:36:37.569] <TB2> INFO: Expecting 41600 events.
[12:36:38.695] <TB2> INFO: 41600 events read in total (739ms).
[12:36:38.695] <TB2> INFO: Test took 1515ms.
[12:36:38.696] <TB2> INFO: scanning low vcal = 160
[12:36:39.085] <TB2> INFO: Expecting 41600 events.
[12:36:40.210] <TB2> INFO: 41600 events read in total (738ms).
[12:36:40.211] <TB2> INFO: Test took 1515ms.
[12:36:40.211] <TB2> INFO: scanning low vcal = 170
[12:36:40.600] <TB2> INFO: Expecting 41600 events.
[12:36:41.740] <TB2> INFO: 41600 events read in total (753ms).
[12:36:41.740] <TB2> INFO: Test took 1529ms.
[12:36:41.740] <TB2> INFO: scanning low vcal = 180
[12:36:42.129] <TB2> INFO: Expecting 41600 events.
[12:36:43.254] <TB2> INFO: 41600 events read in total (738ms).
[12:36:43.255] <TB2> INFO: Test took 1515ms.
[12:36:43.255] <TB2> INFO: scanning low vcal = 190
[12:36:43.644] <TB2> INFO: Expecting 41600 events.
[12:36:44.770] <TB2> INFO: 41600 events read in total (739ms).
[12:36:44.771] <TB2> INFO: Test took 1516ms.
[12:36:44.771] <TB2> INFO: scanning low vcal = 200
[12:36:45.160] <TB2> INFO: Expecting 41600 events.
[12:36:46.300] <TB2> INFO: 41600 events read in total (753ms).
[12:36:46.301] <TB2> INFO: Test took 1530ms.
[12:36:46.301] <TB2> INFO: scanning low vcal = 210
[12:36:46.690] <TB2> INFO: Expecting 41600 events.
[12:36:47.816] <TB2> INFO: 41600 events read in total (739ms).
[12:36:47.817] <TB2> INFO: Test took 1516ms.
[12:36:47.817] <TB2> INFO: scanning low vcal = 220
[12:36:48.206] <TB2> INFO: Expecting 41600 events.
[12:36:49.331] <TB2> INFO: 41600 events read in total (738ms).
[12:36:49.332] <TB2> INFO: Test took 1515ms.
[12:36:49.332] <TB2> INFO: scanning low vcal = 230
[12:36:49.721] <TB2> INFO: Expecting 41600 events.
[12:36:50.847] <TB2> INFO: 41600 events read in total (739ms).
[12:36:50.848] <TB2> INFO: Test took 1516ms.
[12:36:50.848] <TB2> INFO: scanning low vcal = 240
[12:36:51.237] <TB2> INFO: Expecting 41600 events.
[12:36:52.363] <TB2> INFO: 41600 events read in total (739ms).
[12:36:52.364] <TB2> INFO: Test took 1516ms.
[12:36:52.364] <TB2> INFO: scanning low vcal = 250
[12:36:52.753] <TB2> INFO: Expecting 41600 events.
[12:36:53.879] <TB2> INFO: 41600 events read in total (739ms).
[12:36:53.880] <TB2> INFO: Test took 1516ms.
[12:36:53.881] <TB2> INFO: scanning high vcal = 30 (= 210 in low range)
[12:36:54.269] <TB2> INFO: Expecting 41600 events.
[12:36:55.396] <TB2> INFO: 41600 events read in total (740ms).
[12:36:55.396] <TB2> INFO: Test took 1515ms.
[12:36:55.396] <TB2> INFO: scanning high vcal = 50 (= 350 in low range)
[12:36:55.785] <TB2> INFO: Expecting 41600 events.
[12:36:56.912] <TB2> INFO: 41600 events read in total (740ms).
[12:36:56.912] <TB2> INFO: Test took 1516ms.
[12:36:56.912] <TB2> INFO: scanning high vcal = 70 (= 490 in low range)
[12:36:57.301] <TB2> INFO: Expecting 41600 events.
[12:36:58.427] <TB2> INFO: 41600 events read in total (739ms).
[12:36:58.427] <TB2> INFO: Test took 1515ms.
[12:36:58.428] <TB2> INFO: scanning high vcal = 90 (= 630 in low range)
[12:36:58.817] <TB2> INFO: Expecting 41600 events.
[12:36:59.943] <TB2> INFO: 41600 events read in total (739ms).
[12:36:59.943] <TB2> INFO: Test took 1515ms.
[12:36:59.943] <TB2> INFO: scanning high vcal = 200 (= 1400 in low range)
[12:37:00.332] <TB2> INFO: Expecting 41600 events.
[12:37:01.458] <TB2> INFO: 41600 events read in total (739ms).
[12:37:01.459] <TB2> INFO: Test took 1515ms.
[12:37:01.843] <TB2> INFO: PixTestGainPedestal::measure() done
[12:37:03.730] <TB2> INFO: PixTestGainPedestal::fit() done
[12:37:03.730] <TB2> INFO: non-linearity mean: 0.953
[12:37:03.730] <TB2> INFO: non-linearity RMS: 0.006
[12:37:03.735] <TB2> INFO: write gain/ped parameters into /home/mameinha/data/R414_Fulltest_m20_2015-10-06_14h22m_1444134127//000_FulltestROC_m20//phCalibrationFitErr35_C0.dat
[12:37:03.773] <TB2> INFO: PixTestGainPedestal::doTest() done, duration: 47 seconds
[12:37:03.773] <TB2> INFO: enter test to run
[12:37:03.773] <TB2> INFO: test: Readback no parameter change
[12:37:03.773] <TB2> INFO: running: readback
[12:37:03.773] <TB2> INFO: readReadbackCal: /home/mameinha/data/R414_Fulltest_m20_2015-10-06_14h22m_1444134127//000_FulltestROC_m20//readbackCal_C0.dat .. /home/mameinha/data/R414_Fulltest_m20_2015-10-06_14h22m_1444134127//000_FulltestROC_m20//readbackCal_C0.dat
[12:37:03.774] <TB2> INFO: ######################################################################
[12:37:03.774] <TB2> INFO: PixTestReadback::doTest()
[12:37:03.774] <TB2> INFO: ######################################################################
[12:37:03.775] <TB2> INFO: PixTestReadback::RES sent once
[12:37:14.989] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R414_Fulltest_m20_2015-10-06_14h22m_1444134127//000_FulltestROC_m20//readbackCal_C0.dat
[12:37:14.996] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[12:37:14.996] <TB2> INFO: PixTestReadback::RES sent once
[12:37:26.095] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R414_Fulltest_m20_2015-10-06_14h22m_1444134127//000_FulltestROC_m20//readbackCal_C0.dat
[12:37:26.102] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[12:37:26.102] <TB2> INFO: PixTestReadback::RES sent once
[12:37:34.433] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[12:37:34.433] <TB2> INFO: Vbg will be calibrated using Vd calibration
[12:37:34.433] <TB2> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 146.5calibrated Vbg = 1.22249 :::*/*/*/*/
[12:37:34.809] <TB2> INFO: PixTestReadback::RES sent once
[12:37:43.657] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R414_Fulltest_m20_2015-10-06_14h22m_1444134127//000_FulltestROC_m20//readbackCal_C0.dat
[12:37:43.662] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[12:37:43.662] <TB2> INFO: PixTestReadback::doTest() done
[12:37:43.735] <TB2> INFO: enter test to run
[12:37:43.735] <TB2> INFO: test: no parameter change
[12:37:43.765] <TB2> QUIET: Connection to board 137 closed.
[12:37:43.845] <TB2> INFO: pXar: this is the end, my friend