[14:36:11.493] <TB3> INFO: *** Welcome to pxar ***
[14:36:11.493] <TB3> INFO: *** Today: 2015/10/06
[14:36:11.785] <TB3> INFO: *** Version: 9da6
[14:36:11.785] <TB3> INFO: readRocDacs: /home/mameinha/data/R426_Fulltest_p17_2015-10-06_16h35m_1444142157//000_FulltestROC_p17//dacParameters_C0.dat .. /home/mameinha/data/R426_Fulltest_p17_2015-10-06_16h35m_1444142157//000_FulltestROC_p17//dacParameters_C0.dat
[14:36:11.786] <TB3> INFO: readTbmDacs: /home/mameinha/data/R426_Fulltest_p17_2015-10-06_16h35m_1444142157//000_FulltestROC_p17//tbmParameters_C0a.dat .. /home/mameinha/data/R426_Fulltest_p17_2015-10-06_16h35m_1444142157//000_FulltestROC_p17//tbmParameters_C4294967295b.dat
[14:36:11.786] <TB3> INFO: readMaskFile: /home/mameinha/data/R426_Fulltest_p17_2015-10-06_16h35m_1444142157//000_FulltestROC_p17//defaultMaskFile.dat
[14:36:11.786] <TB3> INFO: readTrimFile: /home/mameinha/data/R426_Fulltest_p17_2015-10-06_16h35m_1444142157//000_FulltestROC_p17//trimParameters_C0.dat .. /home/mameinha/data/R426_Fulltest_p17_2015-10-06_16h35m_1444142157//000_FulltestROC_p17//trimParameters_C0.dat
[14:36:11.793] <TB3> INFO: clk: 2
[14:36:11.793] <TB3> INFO: ctr: 2
[14:36:11.793] <TB3> INFO: sda: 17
[14:36:11.793] <TB3> INFO: tin: 7
[14:36:11.793] <TB3> INFO: level: 15
[14:36:11.793] <TB3> INFO: deser160phase: 4
[14:36:11.793] <TB3> QUIET: Instanciating API for pxar v2.6.0+20~g1a7f656
[14:36:11.793] <TB3> INFO: Log level: INFO
[14:36:11.813] <TB3> QUIET: Connection to board DTB_WRQ4OZ opened.
[14:36:11.816] <TB3> INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 71
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WRQ4OZ
MAC address: 40D855118047
Hostname: pixelDTB071
Comment:
------------------------------------------------------
[14:36:11.818] <TB3> INFO: RPC call hashes of host and DTB match: 398089610
[14:36:12.980] <TB3> INFO: DUT info:
[14:36:12.980] <TB3> INFO: The DUT currently contains the following objects:
[14:36:12.980] <TB3> INFO: 0 TBM Cores (0 ON)
[14:36:12.980] <TB3> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[14:36:12.980] <TB3> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[14:36:13.382] <TB3> INFO: enter 'restricted' command line mode
[14:36:13.382] <TB3> INFO: enter test to run
[14:36:13.382] <TB3> INFO: test: Setup no parameter change
[14:36:13.382] <TB3> INFO: running: setup
[14:36:13.386] <TB3> INFO: PixTestSetup::doTest() ntrig = 10

[14:36:13.386] <TB3> INFO: PixTestSetup:: pg set to RES|TOK
[14:36:13.386] <TB3> INFO: 0 1 2 3 4 5 6 7
[14:36:16.427] <TB3> INFO: 0: 000 000 004 07c 7f0 f00 000 000
[14:36:19.439] <TB3> INFO: 1: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[14:36:22.451] <TB3> INFO: 2: 000 000 004 07c <7f8>[*] f80 800 000
[14:36:25.463] <TB3> INFO: 3: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[14:36:28.475] <TB3> INFO: 4: 000 000 000 03c 3f8 f80 800 000
[14:36:31.487] <TB3> INFO: 5: 000 000 000 03c 3fc fc0 c00 000
[14:36:34.499] <TB3> INFO: 6: 000 000 000 03c 3fc fc0 c00 000
[14:36:37.511] <TB3> INFO: 7: 000 000 000 03c 3fc fc0 c00 000
[14:36:40.523] <TB3> INFO: 8: 000 000 000 03c 3fc fc0 c00 000
[14:36:43.535] <TB3> INFO: 9: 000 000 000 03c 3fc fc0 c00 000
[14:36:46.548] <TB3> INFO: 10: 000 000 000 01c 1fc fc0 c00 000
[14:36:49.560] <TB3> INFO: 11: 000 000 000 01c 1fc fe0 e00 000
[14:36:52.572] <TB3> INFO: 12: 000 000 000 01c 1fc fe0 e00 000
[14:36:55.585] <TB3> INFO: 13: 000 000 000 01c 1fc fe0 e00 000
[14:36:58.597] <TB3> INFO: 14: 000 000 000 00c 0fc fe0 e00 000
[14:37:01.609] <TB3> INFO: 15: 000 000 000 00c 0fc ff0 f00 000
[14:37:04.621] <TB3> INFO: 16: f00 000 000 00c 0fc ff0 f00 000
[14:37:07.633] <TB3> INFO: 17: 000 000 000 00c 0fc ff0 f00 000
[14:37:10.645] <TB3> INFO: 18: f00 000 000 00c 0fc ff0 f00 000
[14:37:13.656] <TB3> INFO: 19: 000 000 000 00c 0fc ff0 f00 000
[14:37:14.063] <TB3> INFO: Found good delays at CLK = 2, DESER160 = 4
[14:37:14.065] <TB3> INFO: PixTestSetup:: Write Tb parameters to file.
[14:37:14.071] <TB3> INFO: write dtb parameters into /home/mameinha/data/R426_Fulltest_p17_2015-10-06_16h35m_1444142157//000_FulltestROC_p17//tbParameters.dat
[14:37:14.074] <TB3> INFO: PixTestSetup::doTest() done for.
[14:37:14.098] <TB3> INFO: enter test to run
[14:37:14.099] <TB3> INFO: test: Pretest no parameter change
[14:37:14.099] <TB3> INFO: running: pretest
[14:37:14.101] <TB3> INFO: ----------------------------------------------------------------------
[14:37:14.101] <TB3> INFO: PixTestPretest::programROC()
[14:37:14.101] <TB3> INFO: ----------------------------------------------------------------------
[14:37:17.103] <TB3> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[14:37:17.103] <TB3> INFO: IA differences per ROC: 16.9
[14:37:17.106] <TB3> INFO: enter test to run
[14:37:17.106] <TB3> INFO: test: Pretest no parameter change
[14:37:17.106] <TB3> INFO: running: pretest
[14:37:17.108] <TB3> INFO: ----------------------------------------------------------------------
[14:37:17.108] <TB3> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[14:37:17.108] <TB3> INFO: ----------------------------------------------------------------------
[14:37:17.819] <TB3> INFO: PixTestPretest::setVana() done, Module Ia 24.1 mA = 24.1 mA/ROC
[14:37:17.819] <TB3> INFO: i(loss) [mA/ROC]: 20.1
[14:37:17.821] <TB3> INFO: enter test to run
[14:37:17.821] <TB3> INFO: test: Pretest no parameter change
[14:37:17.821] <TB3> INFO: running: pretest
[14:37:17.822] <TB3> INFO: ----------------------------------------------------------------------
[14:37:17.822] <TB3> INFO: PixTestPretest::findWorkingPixel()
[14:37:17.822] <TB3> INFO: ----------------------------------------------------------------------
[14:37:17.832] <TB3> INFO: Expecting 231680 events.
[14:37:20.043] <TB3> INFO: 231680 events read in total (1824ms).
[14:37:20.045] <TB3> INFO: Test took 2223ms.
[14:37:20.423] <TB3> INFO: Found working pixel in all ROCs: col/row = 12/22
[14:37:20.429] <TB3> INFO: enter test to run
[14:37:20.429] <TB3> INFO: test: Pretest no parameter change
[14:37:20.429] <TB3> INFO: running: pretest
[14:37:20.430] <TB3> INFO: ----------------------------------------------------------------------
[14:37:20.430] <TB3> INFO: PixTestPretest::setVthrCompCalDel()
[14:37:20.430] <TB3> INFO: ----------------------------------------------------------------------
[14:37:20.439] <TB3> INFO: Expecting 231680 events.
[14:37:22.661] <TB3> INFO: 231680 events read in total (1835ms).
[14:37:22.663] <TB3> INFO: Test took 2233ms.
[14:37:23.043] <TB3> INFO: PixTestPretest::setVthrCompCalDel() done
[14:37:23.043] <TB3> INFO: CalDel: 154
[14:37:23.043] <TB3> INFO: VthrComp: 51
[14:37:23.046] <TB3> INFO: enter test to run
[14:37:23.046] <TB3> INFO: test: Pretest no parameter change
[14:37:23.046] <TB3> INFO: running: pretest
[14:37:23.049] <TB3> INFO: write dac parameters into /home/mameinha/data/R426_Fulltest_p17_2015-10-06_16h35m_1444142157//000_FulltestROC_p17//dacParameters_C0.dat
[14:37:23.051] <TB3> INFO: enter test to run
[14:37:23.051] <TB3> INFO: test: PixelAlive no parameter change
[14:37:23.051] <TB3> INFO: running: pixelalive
[14:37:23.053] <TB3> INFO: ######################################################################
[14:37:23.053] <TB3> INFO: PixTestAlive::doTest()
[14:37:23.053] <TB3> INFO: ######################################################################
[14:37:23.054] <TB3> INFO: ----------------------------------------------------------------------
[14:37:23.054] <TB3> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[14:37:23.054] <TB3> INFO: ----------------------------------------------------------------------
[14:37:23.073] <TB3> INFO: Expecting 41600 events.
[14:37:23.872] <TB3> INFO: 41600 events read in total (412ms).
[14:37:23.872] <TB3> INFO: Test took 818ms.
[14:37:23.872] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:37:24.258] <TB3> INFO: PixTestAlive::aliveTest() done
[14:37:24.258] <TB3> INFO: number of dead pixels (per ROC): 0
[14:37:24.259] <TB3> INFO: ----------------------------------------------------------------------
[14:37:24.259] <TB3> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[14:37:24.259] <TB3> INFO: ----------------------------------------------------------------------
[14:37:24.278] <TB3> INFO: Expecting 41600 events.
[14:37:25.022] <TB3> INFO: 41600 events read in total (357ms).
[14:37:25.022] <TB3> INFO: Test took 763ms.
[14:37:25.022] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:37:25.022] <TB3> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[14:37:25.412] <TB3> INFO: PixTestAlive::maskTest() done
[14:37:25.412] <TB3> INFO: number of mask-defect pixels (per ROC): 0
[14:37:25.413] <TB3> INFO: ----------------------------------------------------------------------
[14:37:25.413] <TB3> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[14:37:25.413] <TB3> INFO: ----------------------------------------------------------------------
[14:37:25.433] <TB3> INFO: Expecting 41600 events.
[14:37:26.230] <TB3> INFO: 41600 events read in total (411ms).
[14:37:26.231] <TB3> INFO: Test took 818ms.
[14:37:26.231] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:37:26.616] <TB3> INFO: PixTestAlive::addressDecodingTest() done
[14:37:26.617] <TB3> INFO: number of address-decoding pixels (per ROC): 0
[14:37:26.617] <TB3> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[14:37:26.617] <TB3> INFO: enter test to run
[14:37:26.617] <TB3> INFO: test: Scurves no parameter change
[14:37:26.617] <TB3> INFO: running: scurves
[14:37:26.619] <TB3> INFO: ######################################################################
[14:37:26.619] <TB3> INFO: PixTestScurves::doTest() ntrig = 50
[14:37:26.619] <TB3> INFO: ######################################################################
[14:37:26.619] <TB3> INFO: ----------------------------------------------------------------------
[14:37:26.619] <TB3> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[14:37:26.619] <TB3> INFO: ----------------------------------------------------------------------
[14:37:26.619] <TB3> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[14:37:26.629] <TB3> INFO: dacScan split into 1 runs with ntrig = 50
[14:37:26.629] <TB3> INFO: run 1 of 1
[14:37:26.648] <TB3> INFO: Expecting 41808000 events.
[14:39:51.710] <TB3> INFO: 20630350 events read in total (144675ms).
[14:42:13.150] <TB3> INFO: 40810100 events read in total (286115ms).
[14:42:20.239] <TB3> INFO: 41808000 events read in total (293204ms).
[14:42:20.266] <TB3> INFO: Test took 293637ms.
[14:42:20.291] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:42:21.879] <TB3> INFO: PixTestScurves::scurves() done
[14:42:21.879] <TB3> INFO: Vcal mean: 91.23
[14:42:21.879] <TB3> INFO: Vcal RMS: 5.12
[14:42:21.884] <TB3> INFO: enter test to run
[14:42:21.884] <TB3> INFO: test: Trim no parameter change
[14:42:21.884] <TB3> INFO: running: trim
[14:42:21.885] <TB3> INFO: ######################################################################
[14:42:21.885] <TB3> INFO: PixTestTrim::doTest()
[14:42:21.885] <TB3> INFO: ######################################################################
[14:42:21.887] <TB3> INFO: ----------------------------------------------------------------------
[14:42:21.887] <TB3> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[14:42:21.887] <TB3> INFO: ----------------------------------------------------------------------
[14:42:21.891] <TB3> INFO: ---> VthrComp thr map (minimal VthrComp)
[14:42:21.891] <TB3> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[14:42:21.899] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[14:42:21.899] <TB3> INFO: run 1 of 1
[14:42:21.918] <TB3> INFO: Expecting 6281600 events.
[14:43:07.752] <TB3> INFO: 6281600 events read in total (45441ms).
[14:43:07.768] <TB3> INFO: Test took 45869ms.
[14:43:07.779] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:43:08.886] <TB3> INFO: ROC 0 VthrComp = 93
[14:43:08.886] <TB3> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[14:43:08.886] <TB3> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[14:43:08.894] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[14:43:08.894] <TB3> INFO: run 1 of 1
[14:43:08.913] <TB3> INFO: Expecting 6281600 events.
[14:43:58.886] <TB3> INFO: 6281600 events read in total (49586ms).
[14:43:58.926] <TB3> INFO: Test took 50032ms.
[14:43:58.946] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:44:00.245] <TB3> INFO: roc 0 with ID = 0 has maximal Vcal 58.1385 for pixel 1/79 mean/min/max = 45.9313/33.7082/58.1543
[14:44:00.253] <TB3> INFO: Expecting 514560 events.
[14:44:04.285] <TB3> INFO: 514560 events read in total (3645ms).
[14:44:04.289] <TB3> INFO: Test took 4044ms.
[14:44:04.678] <TB3> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[14:44:04.686] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[14:44:04.686] <TB3> INFO: run 1 of 1
[14:44:04.705] <TB3> INFO: Expecting 6281600 events.
[14:44:54.188] <TB3> INFO: 6281600 events read in total (49096ms).
[14:44:54.230] <TB3> INFO: Test took 49544ms.
[14:44:54.250] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:44:55.536] <TB3> INFO: ---> TrimStepCorr4 extremal thresholds: 15.845673 .. 48.014223
[14:44:55.541] <TB3> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 5 .. 58 (-1/-1) hits flags = 528 (plus default)
[14:44:55.548] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[14:44:55.548] <TB3> INFO: run 1 of 1
[14:44:55.567] <TB3> INFO: Expecting 2246400 events.
[14:45:13.206] <TB3> INFO: 2246400 events read in total (17252ms).
[14:45:13.217] <TB3> INFO: Test took 17669ms.
[14:45:13.222] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:45:14.034] <TB3> INFO: ---> TrimStepCorr2 extremal thresholds: 23.143527 .. 43.302905
[14:45:14.039] <TB3> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 13 .. 53 (-1/-1) hits flags = 528 (plus default)
[14:45:14.046] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[14:45:14.046] <TB3> INFO: run 1 of 1
[14:45:14.065] <TB3> INFO: Expecting 1705600 events.
[14:45:27.646] <TB3> INFO: 1705600 events read in total (13194ms).
[14:45:27.654] <TB3> INFO: Test took 13608ms.
[14:45:27.658] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:45:28.433] <TB3> INFO: ---> TrimStepCorr1a extremal thresholds: 27.713717 .. 40.188757
[14:45:28.437] <TB3> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 17 .. 50 (-1/-1) hits flags = 528 (plus default)
[14:45:28.445] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[14:45:28.445] <TB3> INFO: run 1 of 1
[14:45:28.464] <TB3> INFO: Expecting 1414400 events.
[14:45:39.828] <TB3> INFO: 1414400 events read in total (10977ms).
[14:45:39.835] <TB3> INFO: Test took 11390ms.
[14:45:39.839] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:45:40.592] <TB3> INFO: ---> TrimStepCorr1b extremal thresholds: 29.046174 .. 40.188757
[14:45:40.597] <TB3> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 19 .. 50 (-1/-1) hits flags = 528 (plus default)
[14:45:40.604] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[14:45:40.604] <TB3> INFO: run 1 of 1
[14:45:40.624] <TB3> INFO: Expecting 1331200 events.
[14:45:51.439] <TB3> INFO: 1331200 events read in total (10428ms).
[14:45:51.446] <TB3> INFO: Test took 10842ms.
[14:45:51.450] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:45:52.205] <TB3> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[14:45:52.205] <TB3> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[14:45:52.213] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[14:45:52.213] <TB3> INFO: run 1 of 1
[14:45:52.232] <TB3> INFO: Expecting 1705600 events.
[14:46:05.927] <TB3> INFO: 1705600 events read in total (13308ms).
[14:46:05.935] <TB3> INFO: Test took 13722ms.
[14:46:05.939] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:46:06.735] <TB3> INFO: write dac parameters into /home/mameinha/data/R426_Fulltest_p17_2015-10-06_16h35m_1444142157//000_FulltestROC_p17//dacParameters35_C0.dat
[14:46:06.738] <TB3> INFO: write trim parameters into /home/mameinha/data/R426_Fulltest_p17_2015-10-06_16h35m_1444142157//000_FulltestROC_p17//trimParameters35_C0.dat
[14:46:06.766] <TB3> INFO: PixTestTrim::trimTest() done
[14:46:06.766] <TB3> INFO: vtrim: 104
[14:46:06.766] <TB3> INFO: vthrcomp: 93
[14:46:06.766] <TB3> INFO: vcal mean: 34.98
[14:46:06.766] <TB3> INFO: vcal RMS: 0.75
[14:46:06.766] <TB3> INFO: bits mean: 8.79
[14:46:06.766] <TB3> INFO: bits RMS: 2.74
[14:46:06.770] <TB3> INFO: ----------------------------------------------------------------------
[14:46:06.770] <TB3> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[14:46:06.770] <TB3> INFO: ----------------------------------------------------------------------
[14:46:06.770] <TB3> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[14:46:06.777] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[14:46:06.777] <TB3> INFO: run 1 of 1
[14:46:06.796] <TB3> INFO: Expecting 8320000 events.
[14:47:10.328] <TB3> INFO: 8320000 events read in total (63145ms).
[14:47:10.363] <TB3> INFO: Test took 63586ms.
[14:47:10.379] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:47:11.862] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 152 (-1/-1) hits flags = 528 (plus default)
[14:47:11.869] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[14:47:11.869] <TB3> INFO: run 1 of 1
[14:47:11.888] <TB3> INFO: Expecting 6364800 events.
[14:47:59.419] <TB3> INFO: 6364800 events read in total (47144ms).
[14:47:59.442] <TB3> INFO: Test took 47573ms.
[14:47:59.454] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:48:00.694] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 142 (-1/-1) hits flags = 528 (plus default)
[14:48:00.701] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[14:48:00.701] <TB3> INFO: run 1 of 1
[14:48:00.720] <TB3> INFO: Expecting 5948800 events.
[14:48:44.368] <TB3> INFO: 5948800 events read in total (43261ms).
[14:48:44.385] <TB3> INFO: Test took 43684ms.
[14:48:44.396] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:48:45.557] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 142 (-1/-1) hits flags = 528 (plus default)
[14:48:45.565] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[14:48:45.565] <TB3> INFO: run 1 of 1
[14:48:45.584] <TB3> INFO: Expecting 5948800 events.
[14:49:29.443] <TB3> INFO: 5948800 events read in total (43472ms).
[14:49:29.460] <TB3> INFO: Test took 43895ms.
[14:49:29.470] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:49:30.640] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 141 (-1/-1) hits flags = 528 (plus default)
[14:49:30.647] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[14:49:30.648] <TB3> INFO: run 1 of 1
[14:49:30.667] <TB3> INFO: Expecting 5907200 events.
[14:50:14.600] <TB3> INFO: 5907200 events read in total (43546ms).
[14:50:14.617] <TB3> INFO: Test took 43969ms.
[14:50:14.628] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:50:15.798] <TB3> INFO: PixTestTrim::trimBitTest() done
[14:50:15.799] <TB3> INFO: PixTestTrim::doTest() done, duration: 473 seconds
[14:50:15.840] <TB3> INFO: enter test to run
[14:50:15.840] <TB3> INFO: test: PhOptimization no parameter change
[14:50:15.840] <TB3> INFO: running: phoptimization
[14:50:15.840] <TB3> INFO: ######################################################################
[14:50:15.840] <TB3> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[14:50:15.840] <TB3> INFO: ######################################################################
[14:50:15.860] <TB3> INFO: Expecting 41600 events.
[14:50:16.657] <TB3> INFO: 41600 events read in total (410ms).
[14:50:16.657] <TB3> INFO: Test took 816ms.
[14:50:16.657] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:50:17.048] <TB3> INFO: Expecting 41600 events.
[14:50:17.862] <TB3> INFO: 41600 events read in total (427ms).
[14:50:17.862] <TB3> INFO: Test took 1204ms.
[14:50:17.862] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:50:18.251] <TB3> INFO: Expecting 41600 events.
[14:50:19.051] <TB3> INFO: 41600 events read in total (413ms).
[14:50:19.051] <TB3> INFO: Test took 1188ms.
[14:50:19.051] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:50:19.440] <TB3> INFO: Expecting 2560 events.
[14:50:19.858] <TB3> INFO: 2560 events read in total (31ms).
[14:50:19.858] <TB3> INFO: Test took 806ms.
[14:50:20.254] <TB3> INFO: Expecting 655360 events.
[14:50:25.534] <TB3> INFO: 655360 events read in total (4894ms).
[14:50:25.543] <TB3> INFO: Test took 5684ms.
[14:50:25.837] <TB3> INFO: Expecting 655360 events.
[14:50:31.165] <TB3> INFO: 655360 events read in total (4941ms).
[14:50:31.174] <TB3> INFO: Test took 5618ms.
[14:50:31.193] <TB3> INFO: safety margin for low PH: adding 0, margin is now 20
[14:50:31.205] <TB3> INFO: write dac parameters into /home/mameinha/data/R426_Fulltest_p17_2015-10-06_16h35m_1444142157//000_FulltestROC_p17//dacParameters35_C0.dat
[14:50:31.466] <TB3> INFO: Expecting 41600 events.
[14:50:32.226] <TB3> INFO: 41600 events read in total (373ms).
[14:50:32.227] <TB3> INFO: Test took 1018ms.
[14:50:32.615] <TB3> INFO: Expecting 41600 events.
[14:50:33.375] <TB3> INFO: 41600 events read in total (373ms).
[14:50:33.376] <TB3> INFO: Test took 1149ms.
[14:50:33.765] <TB3> INFO: Expecting 41600 events.
[14:50:34.525] <TB3> INFO: 41600 events read in total (373ms).
[14:50:34.525] <TB3> INFO: Test took 1149ms.
[14:50:34.914] <TB3> INFO: Expecting 2560 events.
[14:50:35.331] <TB3> INFO: 2560 events read in total (30ms).
[14:50:35.332] <TB3> INFO: Test took 806ms.
[14:50:35.727] <TB3> INFO: Expecting 2560 events.
[14:50:36.144] <TB3> INFO: 2560 events read in total (30ms).
[14:50:36.144] <TB3> INFO: Test took 812ms.
[14:50:36.550] <TB3> INFO: PixTestPhOptimization::doTest() done, duration: 20 seconds
[14:50:36.550] <TB3> INFO: PH scale (per ROC): 74
[14:50:36.550] <TB3> INFO: PH offset (per ROC): 191
[14:50:36.563] <TB3> INFO: enter test to run
[14:50:36.563] <TB3> INFO: test: GainPedestal no parameter change
[14:50:36.563] <TB3> INFO: running: gainpedestal
[14:50:36.565] <TB3> INFO: ######################################################################
[14:50:36.565] <TB3> INFO: PixTestGainPedestal::doTest() ntrig = 10
[14:50:36.565] <TB3> INFO: ######################################################################
[14:50:36.573] <TB3> INFO: scanning low vcal = 10
[14:50:36.592] <TB3> INFO: Expecting 41600 events.
[14:50:37.680] <TB3> INFO: 41600 events read in total (702ms).
[14:50:37.681] <TB3> INFO: Test took 1108ms.
[14:50:37.681] <TB3> INFO: scanning low vcal = 20
[14:50:38.075] <TB3> INFO: Expecting 41600 events.
[14:50:39.164] <TB3> INFO: 41600 events read in total (702ms).
[14:50:39.164] <TB3> INFO: Test took 1483ms.
[14:50:39.164] <TB3> INFO: scanning low vcal = 30
[14:50:39.559] <TB3> INFO: Expecting 41600 events.
[14:50:40.648] <TB3> INFO: 41600 events read in total (702ms).
[14:50:40.648] <TB3> INFO: Test took 1484ms.
[14:50:40.648] <TB3> INFO: scanning low vcal = 40
[14:50:41.043] <TB3> INFO: Expecting 41600 events.
[14:50:42.165] <TB3> INFO: 41600 events read in total (735ms).
[14:50:42.166] <TB3> INFO: Test took 1518ms.
[14:50:42.166] <TB3> INFO: scanning low vcal = 50
[14:50:42.554] <TB3> INFO: Expecting 41600 events.
[14:50:43.693] <TB3> INFO: 41600 events read in total (752ms).
[14:50:43.694] <TB3> INFO: Test took 1528ms.
[14:50:43.694] <TB3> INFO: scanning low vcal = 60
[14:50:44.083] <TB3> INFO: Expecting 41600 events.
[14:50:45.205] <TB3> INFO: 41600 events read in total (736ms).
[14:50:45.206] <TB3> INFO: Test took 1512ms.
[14:50:45.206] <TB3> INFO: scanning low vcal = 70
[14:50:45.595] <TB3> INFO: Expecting 41600 events.
[14:50:46.717] <TB3> INFO: 41600 events read in total (736ms).
[14:50:46.718] <TB3> INFO: Test took 1512ms.
[14:50:46.718] <TB3> INFO: scanning low vcal = 80
[14:50:47.107] <TB3> INFO: Expecting 41600 events.
[14:50:48.238] <TB3> INFO: 41600 events read in total (744ms).
[14:50:48.239] <TB3> INFO: Test took 1521ms.
[14:50:48.239] <TB3> INFO: scanning low vcal = 90
[14:50:48.628] <TB3> INFO: Expecting 41600 events.
[14:50:49.751] <TB3> INFO: 41600 events read in total (737ms).
[14:50:49.751] <TB3> INFO: Test took 1512ms.
[14:50:49.751] <TB3> INFO: scanning low vcal = 100
[14:50:50.140] <TB3> INFO: Expecting 41600 events.
[14:50:51.272] <TB3> INFO: 41600 events read in total (745ms).
[14:50:51.272] <TB3> INFO: Test took 1521ms.
[14:50:51.273] <TB3> INFO: scanning low vcal = 110
[14:50:51.661] <TB3> INFO: Expecting 41600 events.
[14:50:52.813] <TB3> INFO: 41600 events read in total (765ms).
[14:50:52.813] <TB3> INFO: Test took 1540ms.
[14:50:52.814] <TB3> INFO: scanning low vcal = 120
[14:50:53.202] <TB3> INFO: Expecting 41600 events.
[14:50:54.355] <TB3> INFO: 41600 events read in total (766ms).
[14:50:54.355] <TB3> INFO: Test took 1541ms.
[14:50:54.355] <TB3> INFO: scanning low vcal = 130
[14:50:54.744] <TB3> INFO: Expecting 41600 events.
[14:50:55.882] <TB3> INFO: 41600 events read in total (751ms).
[14:50:55.882] <TB3> INFO: Test took 1527ms.
[14:50:55.882] <TB3> INFO: scanning low vcal = 140
[14:50:56.271] <TB3> INFO: Expecting 41600 events.
[14:50:57.395] <TB3> INFO: 41600 events read in total (737ms).
[14:50:57.395] <TB3> INFO: Test took 1513ms.
[14:50:57.396] <TB3> INFO: scanning low vcal = 150
[14:50:57.784] <TB3> INFO: Expecting 41600 events.
[14:50:58.909] <TB3> INFO: 41600 events read in total (738ms).
[14:50:58.909] <TB3> INFO: Test took 1513ms.
[14:50:58.909] <TB3> INFO: scanning low vcal = 160
[14:50:59.298] <TB3> INFO: Expecting 41600 events.
[14:51:00.422] <TB3> INFO: 41600 events read in total (737ms).
[14:51:00.423] <TB3> INFO: Test took 1514ms.
[14:51:00.423] <TB3> INFO: scanning low vcal = 170
[14:51:00.811] <TB3> INFO: Expecting 41600 events.
[14:51:01.950] <TB3> INFO: 41600 events read in total (752ms).
[14:51:01.950] <TB3> INFO: Test took 1527ms.
[14:51:01.951] <TB3> INFO: scanning low vcal = 180
[14:51:02.339] <TB3> INFO: Expecting 41600 events.
[14:51:03.464] <TB3> INFO: 41600 events read in total (738ms).
[14:51:03.464] <TB3> INFO: Test took 1513ms.
[14:51:03.464] <TB3> INFO: scanning low vcal = 190
[14:51:03.853] <TB3> INFO: Expecting 41600 events.
[14:51:04.977] <TB3> INFO: 41600 events read in total (737ms).
[14:51:04.978] <TB3> INFO: Test took 1514ms.
[14:51:04.978] <TB3> INFO: scanning low vcal = 200
[14:51:05.367] <TB3> INFO: Expecting 41600 events.
[14:51:06.506] <TB3> INFO: 41600 events read in total (752ms).
[14:51:06.506] <TB3> INFO: Test took 1528ms.
[14:51:06.506] <TB3> INFO: scanning low vcal = 210
[14:51:06.895] <TB3> INFO: Expecting 41600 events.
[14:51:08.033] <TB3> INFO: 41600 events read in total (751ms).
[14:51:08.034] <TB3> INFO: Test took 1528ms.
[14:51:08.034] <TB3> INFO: scanning low vcal = 220
[14:51:08.423] <TB3> INFO: Expecting 41600 events.
[14:51:09.563] <TB3> INFO: 41600 events read in total (753ms).
[14:51:09.563] <TB3> INFO: Test took 1529ms.
[14:51:09.564] <TB3> INFO: scanning low vcal = 230
[14:51:09.952] <TB3> INFO: Expecting 41600 events.
[14:51:11.076] <TB3> INFO: 41600 events read in total (737ms).
[14:51:11.077] <TB3> INFO: Test took 1513ms.
[14:51:11.077] <TB3> INFO: scanning low vcal = 240
[14:51:11.466] <TB3> INFO: Expecting 41600 events.
[14:51:12.590] <TB3> INFO: 41600 events read in total (737ms).
[14:51:12.590] <TB3> INFO: Test took 1513ms.
[14:51:12.590] <TB3> INFO: scanning low vcal = 250
[14:51:12.979] <TB3> INFO: Expecting 41600 events.
[14:51:14.104] <TB3> INFO: 41600 events read in total (738ms).
[14:51:14.104] <TB3> INFO: Test took 1514ms.
[14:51:14.104] <TB3> INFO: scanning high vcal = 30 (= 210 in low range)
[14:51:14.493] <TB3> INFO: Expecting 41600 events.
[14:51:15.617] <TB3> INFO: 41600 events read in total (737ms).
[14:51:15.617] <TB3> INFO: Test took 1513ms.
[14:51:15.618] <TB3> INFO: scanning high vcal = 50 (= 350 in low range)
[14:51:16.006] <TB3> INFO: Expecting 41600 events.
[14:51:17.130] <TB3> INFO: 41600 events read in total (737ms).
[14:51:17.131] <TB3> INFO: Test took 1513ms.
[14:51:17.131] <TB3> INFO: scanning high vcal = 70 (= 490 in low range)
[14:51:17.519] <TB3> INFO: Expecting 41600 events.
[14:51:18.658] <TB3> INFO: 41600 events read in total (752ms).
[14:51:18.659] <TB3> INFO: Test took 1528ms.
[14:51:18.659] <TB3> INFO: scanning high vcal = 90 (= 630 in low range)
[14:51:19.047] <TB3> INFO: Expecting 41600 events.
[14:51:20.185] <TB3> INFO: 41600 events read in total (751ms).
[14:51:20.186] <TB3> INFO: Test took 1527ms.
[14:51:20.186] <TB3> INFO: scanning high vcal = 200 (= 1400 in low range)
[14:51:20.575] <TB3> INFO: Expecting 41600 events.
[14:51:21.713] <TB3> INFO: 41600 events read in total (751ms).
[14:51:21.713] <TB3> INFO: Test took 1527ms.
[14:51:22.097] <TB3> INFO: PixTestGainPedestal::measure() done
[14:51:23.992] <TB3> INFO: PixTestGainPedestal::fit() done
[14:51:23.992] <TB3> INFO: non-linearity mean: 0.951
[14:51:23.992] <TB3> INFO: non-linearity RMS: 0.007
[14:51:24.010] <TB3> INFO: write gain/ped parameters into /home/mameinha/data/R426_Fulltest_p17_2015-10-06_16h35m_1444142157//000_FulltestROC_p17//phCalibrationFitErr35_C0.dat
[14:51:24.118] <TB3> INFO: PixTestGainPedestal::doTest() done, duration: 47 seconds
[14:51:24.119] <TB3> INFO: enter test to run
[14:51:24.120] <TB3> INFO: test: Readback no parameter change
[14:51:24.120] <TB3> INFO: running: readback
[14:51:24.120] <TB3> INFO: readReadbackCal: /home/mameinha/data/R426_Fulltest_p17_2015-10-06_16h35m_1444142157//000_FulltestROC_p17//readbackCal_C0.dat .. /home/mameinha/data/R426_Fulltest_p17_2015-10-06_16h35m_1444142157//000_FulltestROC_p17//readbackCal_C0.dat
[14:51:24.121] <TB3> INFO: ######################################################################
[14:51:24.121] <TB3> INFO: PixTestReadback::doTest()
[14:51:24.121] <TB3> INFO: ######################################################################
[14:51:24.122] <TB3> INFO: PixTestReadback::RES sent once
[14:51:35.281] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R426_Fulltest_p17_2015-10-06_16h35m_1444142157//000_FulltestROC_p17//readbackCal_C0.dat
[14:51:35.305] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[14:51:35.306] <TB3> INFO: PixTestReadback::RES sent once
[14:51:46.723] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R426_Fulltest_p17_2015-10-06_16h35m_1444142157//000_FulltestROC_p17//readbackCal_C0.dat
[14:51:46.753] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[14:51:46.753] <TB3> INFO: PixTestReadback::RES sent once
[14:51:55.080] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[14:51:55.080] <TB3> INFO: Vbg will be calibrated using Vd calibration
[14:51:55.080] <TB3> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 157calibrated Vbg = 1.22544 :::*/*/*/*/
[14:51:55.457] <TB3> INFO: PixTestReadback::RES sent once












[14:52:07.665] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R426_Fulltest_p17_2015-10-06_16h35m_1444142157//000_FulltestROC_p17//readbackCal_C0.dat
[14:52:07.674] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[14:52:07.674] <TB3> INFO: PixTestReadback::doTest() done
[14:52:07.707] <TB3> INFO: enter test to run
[14:52:07.707] <TB3> INFO: test: no parameter change
[14:52:07.768] <TB3> QUIET: Connection to board 71 closed.
[14:52:07.848] <TB3> INFO: pXar: this is the end, my friend