[12:40:18.597] <TB3> INFO: *** Welcome to pxar ***
[12:40:18.597] <TB3> INFO: *** Today: 2015/10/06
[12:40:18.900] <TB3> INFO: *** Version: 9da6
[12:40:18.900] <TB3> INFO: readRocDacs: /home/mameinha/data/R422_Fulltest_p17_2015-10-06_14h40m_1444135207//000_FulltestROC_p17//dacParameters_C0.dat .. /home/mameinha/data/R422_Fulltest_p17_2015-10-06_14h40m_1444135207//000_FulltestROC_p17//dacParameters_C0.dat
[12:40:18.901] <TB3> INFO: readTbmDacs: /home/mameinha/data/R422_Fulltest_p17_2015-10-06_14h40m_1444135207//000_FulltestROC_p17//tbmParameters_C0a.dat .. /home/mameinha/data/R422_Fulltest_p17_2015-10-06_14h40m_1444135207//000_FulltestROC_p17//tbmParameters_C4294967295b.dat
[12:40:18.901] <TB3> INFO: readMaskFile: /home/mameinha/data/R422_Fulltest_p17_2015-10-06_14h40m_1444135207//000_FulltestROC_p17//defaultMaskFile.dat
[12:40:18.902] <TB3> INFO: readTrimFile: /home/mameinha/data/R422_Fulltest_p17_2015-10-06_14h40m_1444135207//000_FulltestROC_p17//trimParameters_C0.dat .. /home/mameinha/data/R422_Fulltest_p17_2015-10-06_14h40m_1444135207//000_FulltestROC_p17//trimParameters_C0.dat
[12:40:18.909] <TB3> INFO: clk: 2
[12:40:18.909] <TB3> INFO: ctr: 2
[12:40:18.909] <TB3> INFO: sda: 17
[12:40:18.909] <TB3> INFO: tin: 7
[12:40:18.909] <TB3> INFO: level: 15
[12:40:18.909] <TB3> INFO: deser160phase: 4
[12:40:18.909] <TB3> QUIET: Instanciating API for pxar v2.6.0+20~g1a7f656
[12:40:18.909] <TB3> INFO: Log level: INFO
[12:40:18.929] <TB3> QUIET: Connection to board DTB_WRQ4OZ opened.
[12:40:18.932] <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:
------------------------------------------------------
[12:40:18.934] <TB3> INFO: RPC call hashes of host and DTB match: 398089610
[12:40:20.096] <TB3> INFO: DUT info:
[12:40:20.096] <TB3> INFO: The DUT currently contains the following objects:
[12:40:20.096] <TB3> INFO: 0 TBM Cores (0 ON)
[12:40:20.096] <TB3> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[12:40:20.096] <TB3> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[12:40:20.498] <TB3> INFO: enter 'restricted' command line mode
[12:40:20.498] <TB3> INFO: enter test to run
[12:40:20.498] <TB3> INFO: test: Setup no parameter change
[12:40:20.498] <TB3> INFO: running: setup
[12:40:20.502] <TB3> INFO: PixTestSetup::doTest() ntrig = 10

[12:40:20.502] <TB3> INFO: PixTestSetup:: pg set to RES|TOK
[12:40:20.502] <TB3> INFO: 0 1 2 3 4 5 6 7
[12:40:23.543] <TB3> INFO: 0: 000 000 004 07c 7f0 f00 000 000
[12:40:26.555] <TB3> INFO: 1: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[12:40:29.567] <TB3> INFO: 2: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[12:40:32.579] <TB3> INFO: 3: 800 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[12:40:35.592] <TB3> INFO: 4: 800 000 000 03c 3f8 f80 800 000
[12:40:38.604] <TB3> INFO: 5: 000 000 000 03c 3fc fc0 c00 000
[12:40:41.616] <TB3> INFO: 6: 000 000 000 03c 3fc fc0 c00 000
[12:40:44.629] <TB3> INFO: 7: c00 000 000 03c 3fc fc0 c00 000
[12:40:47.641] <TB3> INFO: 8: 000 000 000 03c 3fc fc0 c00 000
[12:40:50.653] <TB3> INFO: 9: 000 000 000 01c 1fc fc0 c00 000
[12:40:53.666] <TB3> INFO: 10: 000 000 000 01c 1fc fc0 c00 000
[12:40:56.678] <TB3> INFO: 11: 000 000 000 01c 1fc fe0 e00 000
[12:40:59.690] <TB3> INFO: 12: 000 000 000 01c 1fc fe0 e00 000
[12:41:02.702] <TB3> INFO: 13: 000 000 000 01c 1fc fe0 e00 000
[12:41:05.714] <TB3> INFO: 14: e00 000 000 00c 0fc fe0 e00 000
[12:41:08.727] <TB3> INFO: 15: 000 000 000 00c 0fc ff0 f00 000
[12:41:11.739] <TB3> INFO: 16: f00 000 000 00c 0fc ff0 f00 000
[12:41:14.752] <TB3> INFO: 17: f00 000 000 00c 0fc ff0 f00 000
[12:41:17.764] <TB3> INFO: 18: 000 000 000 00c 0fc ff0 f00 000
[12:41:20.776] <TB3> INFO: 19: 000 000 000 004 07c ff0 f00 000
[12:41:21.182] <TB3> INFO: Found good delays at CLK = 2, DESER160 = 4
[12:41:21.183] <TB3> INFO: PixTestSetup:: Write Tb parameters to file.
[12:41:21.188] <TB3> INFO: write dtb parameters into /home/mameinha/data/R422_Fulltest_p17_2015-10-06_14h40m_1444135207//000_FulltestROC_p17//tbParameters.dat
[12:41:21.190] <TB3> INFO: PixTestSetup::doTest() done for.
[12:41:21.214] <TB3> INFO: enter test to run
[12:41:21.214] <TB3> INFO: test: Pretest no parameter change
[12:41:21.214] <TB3> INFO: running: pretest
[12:41:21.216] <TB3> INFO: ----------------------------------------------------------------------
[12:41:21.216] <TB3> INFO: PixTestPretest::programROC()
[12:41:21.216] <TB3> INFO: ----------------------------------------------------------------------
[12:41:24.218] <TB3> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[12:41:24.218] <TB3> INFO: IA differences per ROC: 19.3
[12:41:24.221] <TB3> INFO: enter test to run
[12:41:24.221] <TB3> INFO: test: Pretest no parameter change
[12:41:24.221] <TB3> INFO: running: pretest
[12:41:24.223] <TB3> INFO: ----------------------------------------------------------------------
[12:41:24.223] <TB3> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[12:41:24.223] <TB3> INFO: ----------------------------------------------------------------------
[12:41:25.738] <TB3> INFO: PixTestPretest::setVana() done, Module Ia 23.3 mA = 23.3 mA/ROC
[12:41:25.738] <TB3> INFO: i(loss) [mA/ROC]: 18.5
[12:41:25.740] <TB3> INFO: enter test to run
[12:41:25.740] <TB3> INFO: test: Pretest no parameter change
[12:41:25.740] <TB3> INFO: running: pretest
[12:41:25.742] <TB3> INFO: ----------------------------------------------------------------------
[12:41:25.742] <TB3> INFO: PixTestPretest::findWorkingPixel()
[12:41:25.742] <TB3> INFO: ----------------------------------------------------------------------
[12:41:25.751] <TB3> INFO: Expecting 231680 events.
[12:41:27.946] <TB3> INFO: 231680 events read in total (1808ms).
[12:41:27.948] <TB3> INFO: Test took 2206ms.
[12:41:28.327] <TB3> INFO: Found working pixel in all ROCs: col/row = 12/22
[12:41:28.332] <TB3> INFO: enter test to run
[12:41:28.332] <TB3> INFO: test: Pretest no parameter change
[12:41:28.332] <TB3> INFO: running: pretest
[12:41:28.333] <TB3> INFO: ----------------------------------------------------------------------
[12:41:28.333] <TB3> INFO: PixTestPretest::setVthrCompCalDel()
[12:41:28.333] <TB3> INFO: ----------------------------------------------------------------------
[12:41:28.342] <TB3> INFO: Expecting 231680 events.
[12:41:30.548] <TB3> INFO: 231680 events read in total (1819ms).
[12:41:30.551] <TB3> INFO: Test took 2218ms.
[12:41:30.930] <TB3> INFO: PixTestPretest::setVthrCompCalDel() done
[12:41:30.930] <TB3> INFO: CalDel: 142
[12:41:30.930] <TB3> INFO: VthrComp: 51
[12:41:30.934] <TB3> INFO: enter test to run
[12:41:30.934] <TB3> INFO: test: Pretest no parameter change
[12:41:30.934] <TB3> INFO: running: pretest
[12:41:30.938] <TB3> INFO: write dac parameters into /home/mameinha/data/R422_Fulltest_p17_2015-10-06_14h40m_1444135207//000_FulltestROC_p17//dacParameters_C0.dat
[12:41:30.940] <TB3> INFO: enter test to run
[12:41:30.940] <TB3> INFO: test: PixelAlive no parameter change
[12:41:30.940] <TB3> INFO: running: pixelalive
[12:41:30.942] <TB3> INFO: ######################################################################
[12:41:30.942] <TB3> INFO: PixTestAlive::doTest()
[12:41:30.942] <TB3> INFO: ######################################################################
[12:41:30.943] <TB3> INFO: ----------------------------------------------------------------------
[12:41:30.943] <TB3> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[12:41:30.943] <TB3> INFO: ----------------------------------------------------------------------
[12:41:30.962] <TB3> INFO: Expecting 41600 events.
[12:41:31.761] <TB3> INFO: 41600 events read in total (412ms).
[12:41:31.761] <TB3> INFO: Test took 818ms.
[12:41:31.761] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:41:32.147] <TB3> INFO: PixTestAlive::aliveTest() done
[12:41:32.147] <TB3> INFO: number of dead pixels (per ROC): 0
[12:41:32.148] <TB3> INFO: ----------------------------------------------------------------------
[12:41:32.148] <TB3> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[12:41:32.148] <TB3> INFO: ----------------------------------------------------------------------
[12:41:32.167] <TB3> INFO: Expecting 41600 events.
[12:41:32.910] <TB3> INFO: 41600 events read in total (356ms).
[12:41:32.910] <TB3> INFO: Test took 762ms.
[12:41:32.910] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:41:32.910] <TB3> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[12:41:33.299] <TB3> INFO: PixTestAlive::maskTest() done
[12:41:33.299] <TB3> INFO: number of mask-defect pixels (per ROC): 0
[12:41:33.301] <TB3> INFO: ----------------------------------------------------------------------
[12:41:33.301] <TB3> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[12:41:33.301] <TB3> INFO: ----------------------------------------------------------------------
[12:41:33.320] <TB3> INFO: Expecting 41600 events.
[12:41:34.117] <TB3> INFO: 41600 events read in total (410ms).
[12:41:34.118] <TB3> INFO: Test took 817ms.
[12:41:34.118] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:41:34.503] <TB3> INFO: PixTestAlive::addressDecodingTest() done
[12:41:34.503] <TB3> INFO: number of address-decoding pixels (per ROC): 0
[12:41:34.503] <TB3> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[12:41:34.504] <TB3> INFO: enter test to run
[12:41:34.504] <TB3> INFO: test: Scurves no parameter change
[12:41:34.504] <TB3> INFO: running: scurves
[12:41:34.505] <TB3> INFO: ######################################################################
[12:41:34.505] <TB3> INFO: PixTestScurves::doTest() ntrig = 50
[12:41:34.505] <TB3> INFO: ######################################################################
[12:41:34.505] <TB3> INFO: ----------------------------------------------------------------------
[12:41:34.505] <TB3> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[12:41:34.505] <TB3> INFO: ----------------------------------------------------------------------
[12:41:34.505] <TB3> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[12:41:34.516] <TB3> INFO: dacScan split into 1 runs with ntrig = 50
[12:41:34.516] <TB3> INFO: run 1 of 1
[12:41:34.535] <TB3> INFO: Expecting 41808000 events.
[12:44:00.625] <TB3> INFO: 20629300 events read in total (145704ms).
[12:46:23.716] <TB3> INFO: 40938750 events read in total (288795ms).
[12:46:29.795] <TB3> INFO: 41808000 events read in total (294874ms).
[12:46:29.821] <TB3> INFO: Test took 295305ms.
[12:46:29.841] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:46:31.396] <TB3> INFO: PixTestScurves::scurves() done
[12:46:31.396] <TB3> INFO: Vcal mean: 91.95
[12:46:31.396] <TB3> INFO: Vcal RMS: 4.95
[12:46:31.400] <TB3> INFO: enter test to run
[12:46:31.400] <TB3> INFO: test: Trim no parameter change
[12:46:31.400] <TB3> INFO: running: trim
[12:46:31.402] <TB3> INFO: ######################################################################
[12:46:31.402] <TB3> INFO: PixTestTrim::doTest()
[12:46:31.402] <TB3> INFO: ######################################################################
[12:46:31.403] <TB3> INFO: ----------------------------------------------------------------------
[12:46:31.403] <TB3> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[12:46:31.403] <TB3> INFO: ----------------------------------------------------------------------
[12:46:31.408] <TB3> INFO: ---> VthrComp thr map (minimal VthrComp)
[12:46:31.408] <TB3> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[12:46:31.415] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[12:46:31.415] <TB3> INFO: run 1 of 1
[12:46:31.434] <TB3> INFO: Expecting 6281600 events.
[12:47:17.022] <TB3> INFO: 6281600 events read in total (45201ms).
[12:47:17.039] <TB3> INFO: Test took 45624ms.
[12:47:17.047] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:47:18.121] <TB3> INFO: ROC 0 VthrComp = 92
[12:47:18.121] <TB3> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[12:47:18.121] <TB3> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[12:47:18.128] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[12:47:18.129] <TB3> INFO: run 1 of 1
[12:47:18.147] <TB3> INFO: Expecting 6281600 events.
[12:48:07.665] <TB3> INFO: 6281600 events read in total (49131ms).
[12:48:07.713] <TB3> INFO: Test took 49584ms.
[12:48:07.732] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:48:09.025] <TB3> INFO: roc 0 with ID = 0 has maximal Vcal 58.3645 for pixel 7/64 mean/min/max = 46.1443/33.9039/58.3848
[12:48:09.034] <TB3> INFO: Expecting 514560 events.
[12:48:13.064] <TB3> INFO: 514560 events read in total (3643ms).
[12:48:13.068] <TB3> INFO: Test took 4042ms.
[12:48:13.461] <TB3> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[12:48:13.469] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[12:48:13.469] <TB3> INFO: run 1 of 1
[12:48:13.488] <TB3> INFO: Expecting 6281600 events.
[12:49:03.946] <TB3> INFO: 6281600 events read in total (50071ms).
[12:49:03.995] <TB3> INFO: Test took 50526ms.
[12:49:04.016] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:49:05.285] <TB3> INFO: ---> TrimStepCorr4 extremal thresholds: 1.972804 .. 47.861647
[12:49:05.290] <TB3> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 1 .. 57 (-1/-1) hits flags = 528 (plus default)
[12:49:05.297] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[12:49:05.297] <TB3> INFO: run 1 of 1
[12:49:05.316] <TB3> INFO: Expecting 2371200 events.
[12:49:23.444] <TB3> INFO: 2371200 events read in total (17741ms).
[12:49:23.453] <TB3> INFO: Test took 18156ms.
[12:49:23.457] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:49:24.263] <TB3> INFO: ---> TrimStepCorr2 extremal thresholds: 21.798000 .. 43.112430
[12:49:24.268] <TB3> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 11 .. 53 (-1/-1) hits flags = 528 (plus default)
[12:49:24.275] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[12:49:24.275] <TB3> INFO: run 1 of 1
[12:49:24.294] <TB3> INFO: Expecting 1788800 events.
[12:49:38.244] <TB3> INFO: 1788800 events read in total (13563ms).
[12:49:38.251] <TB3> INFO: Test took 13976ms.
[12:49:38.254] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:49:39.017] <TB3> INFO: ---> TrimStepCorr1a extremal thresholds: 27.552706 .. 37.922078
[12:49:39.022] <TB3> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 17 .. 47 (-1/-1) hits flags = 528 (plus default)
[12:49:39.029] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[12:49:39.029] <TB3> INFO: run 1 of 1
[12:49:39.048] <TB3> INFO: Expecting 1289600 events.
[12:49:49.276] <TB3> INFO: 1289600 events read in total (9841ms).
[12:49:49.282] <TB3> INFO: Test took 10253ms.
[12:49:49.284] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:49:50.008] <TB3> INFO: ---> TrimStepCorr1b extremal thresholds: 29.270762 .. 37.922078
[12:49:50.012] <TB3> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 19 .. 47 (-1/-1) hits flags = 528 (plus default)
[12:49:50.020] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[12:49:50.020] <TB3> INFO: run 1 of 1
[12:49:50.038] <TB3> INFO: Expecting 1206400 events.
[12:49:59.746] <TB3> INFO: 1206400 events read in total (9321ms).
[12:49:59.751] <TB3> INFO: Test took 9731ms.
[12:49:59.754] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:00.466] <TB3> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[12:50:00.466] <TB3> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[12:50:00.473] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[12:50:00.473] <TB3> INFO: run 1 of 1
[12:50:00.492] <TB3> INFO: Expecting 1705600 events.
[12:50:13.970] <TB3> INFO: 1705600 events read in total (13091ms).
[12:50:13.978] <TB3> INFO: Test took 13505ms.
[12:50:13.982] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:14.767] <TB3> INFO: write dac parameters into /home/mameinha/data/R422_Fulltest_p17_2015-10-06_14h40m_1444135207//000_FulltestROC_p17//dacParameters35_C0.dat
[12:50:14.845] <TB3> INFO: write trim parameters into /home/mameinha/data/R422_Fulltest_p17_2015-10-06_14h40m_1444135207//000_FulltestROC_p17//trimParameters35_C0.dat
[12:50:14.856] <TB3> INFO: PixTestTrim::trimTest() done
[12:50:14.856] <TB3> INFO: vtrim: 97
[12:50:14.856] <TB3> INFO: vthrcomp: 92
[12:50:14.856] <TB3> INFO: vcal mean: 35.00
[12:50:14.856] <TB3> INFO: vcal RMS: 0.76
[12:50:14.856] <TB3> INFO: bits mean: 9.34
[12:50:14.856] <TB3> INFO: bits RMS: 2.58
[12:50:14.859] <TB3> INFO: ----------------------------------------------------------------------
[12:50:14.859] <TB3> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[12:50:14.859] <TB3> INFO: ----------------------------------------------------------------------
[12:50:14.860] <TB3> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[12:50:14.867] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[12:50:14.867] <TB3> INFO: run 1 of 1
[12:50:14.887] <TB3> INFO: Expecting 8320000 events.
[12:51:17.434] <TB3> INFO: 8320000 events read in total (62161ms).
[12:51:17.469] <TB3> INFO: Test took 62602ms.
[12:51:17.485] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:51:18.977] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 156 (-1/-1) hits flags = 528 (plus default)
[12:51:18.985] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[12:51:18.985] <TB3> INFO: run 1 of 1
[12:51:19.004] <TB3> INFO: Expecting 6531200 events.
[12:52:07.549] <TB3> INFO: 6531200 events read in total (48158ms).
[12:52:07.569] <TB3> INFO: Test took 48584ms.
[12:52:07.579] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:52:08.849] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 147 (-1/-1) hits flags = 528 (plus default)
[12:52:08.856] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[12:52:08.856] <TB3> INFO: run 1 of 1
[12:52:08.875] <TB3> INFO: Expecting 6156800 events.
[12:52:54.193] <TB3> INFO: 6156800 events read in total (44931ms).
[12:52:54.211] <TB3> INFO: Test took 45355ms.
[12:52:54.221] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:52:55.408] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 146 (-1/-1) hits flags = 528 (plus default)
[12:52:55.415] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[12:52:55.415] <TB3> INFO: run 1 of 1
[12:52:55.434] <TB3> INFO: Expecting 6115200 events.
[12:53:40.205] <TB3> INFO: 6115200 events read in total (44384ms).
[12:53:40.222] <TB3> INFO: Test took 44807ms.
[12:53:40.230] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:41.408] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 147 (-1/-1) hits flags = 528 (plus default)
[12:53:41.415] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[12:53:41.415] <TB3> INFO: run 1 of 1
[12:53:41.434] <TB3> INFO: Expecting 6156800 events.
[12:54:26.530] <TB3> INFO: 6156800 events read in total (44709ms).
[12:54:26.549] <TB3> INFO: Test took 45134ms.
[12:54:26.557] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:54:27.774] <TB3> INFO: PixTestTrim::trimBitTest() done
[12:54:27.776] <TB3> INFO: PixTestTrim::doTest() done, duration: 476 seconds
[12:54:27.817] <TB3> INFO: enter test to run
[12:54:27.817] <TB3> INFO: test: PhOptimization no parameter change
[12:54:27.817] <TB3> INFO: running: phoptimization
[12:54:27.817] <TB3> INFO: ######################################################################
[12:54:27.817] <TB3> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[12:54:27.817] <TB3> INFO: ######################################################################
[12:54:27.837] <TB3> INFO: Expecting 41600 events.
[12:54:28.648] <TB3> INFO: 41600 events read in total (424ms).
[12:54:28.649] <TB3> INFO: Test took 831ms.
[12:54:28.649] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:54:29.040] <TB3> INFO: Expecting 41600 events.
[12:54:29.840] <TB3> INFO: 41600 events read in total (413ms).
[12:54:29.840] <TB3> INFO: Test took 1190ms.
[12:54:29.840] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:54:30.229] <TB3> INFO: Expecting 41600 events.
[12:54:31.030] <TB3> INFO: 41600 events read in total (414ms).
[12:54:31.030] <TB3> INFO: Test took 1189ms.
[12:54:31.031] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:54:31.419] <TB3> INFO: Expecting 2560 events.
[12:54:31.837] <TB3> INFO: 2560 events read in total (31ms).
[12:54:31.838] <TB3> INFO: Test took 807ms.
[12:54:32.233] <TB3> INFO: Expecting 655360 events.
[12:54:37.607] <TB3> INFO: 655360 events read in total (4987ms).
[12:54:37.615] <TB3> INFO: Test took 5777ms.
[12:54:37.909] <TB3> INFO: Expecting 655360 events.
[12:54:43.152] <TB3> INFO: 655360 events read in total (4856ms).
[12:54:43.161] <TB3> INFO: Test took 5532ms.
[12:54:43.180] <TB3> INFO: safety margin for low PH: adding 0, margin is now 20
[12:54:43.217] <TB3> INFO: write dac parameters into /home/mameinha/data/R422_Fulltest_p17_2015-10-06_14h40m_1444135207//000_FulltestROC_p17//dacParameters35_C0.dat
[12:54:43.447] <TB3> INFO: Expecting 41600 events.
[12:54:44.208] <TB3> INFO: 41600 events read in total (374ms).
[12:54:44.208] <TB3> INFO: Test took 979ms.
[12:54:44.597] <TB3> INFO: Expecting 41600 events.
[12:54:45.358] <TB3> INFO: 41600 events read in total (374ms).
[12:54:45.358] <TB3> INFO: Test took 1149ms.
[12:54:45.747] <TB3> INFO: Expecting 41600 events.
[12:54:46.508] <TB3> INFO: 41600 events read in total (374ms).
[12:54:46.508] <TB3> INFO: Test took 1149ms.
[12:54:46.897] <TB3> INFO: Expecting 2560 events.
[12:54:47.314] <TB3> INFO: 2560 events read in total (30ms).
[12:54:47.315] <TB3> INFO: Test took 806ms.
[12:54:47.710] <TB3> INFO: Expecting 2560 events.
[12:54:48.127] <TB3> INFO: 2560 events read in total (30ms).
[12:54:48.127] <TB3> INFO: Test took 812ms.
[12:54:48.534] <TB3> INFO: PixTestPhOptimization::doTest() done, duration: 20 seconds
[12:54:48.534] <TB3> INFO: PH scale (per ROC): 75
[12:54:48.534] <TB3> INFO: PH offset (per ROC): 181
[12:54:48.550] <TB3> INFO: enter test to run
[12:54:48.550] <TB3> INFO: test: GainPedestal no parameter change
[12:54:48.550] <TB3> INFO: running: gainpedestal
[12:54:48.551] <TB3> INFO: ######################################################################
[12:54:48.551] <TB3> INFO: PixTestGainPedestal::doTest() ntrig = 10
[12:54:48.551] <TB3> INFO: ######################################################################
[12:54:48.559] <TB3> INFO: scanning low vcal = 10
[12:54:48.578] <TB3> INFO: Expecting 41600 events.
[12:54:49.680] <TB3> INFO: 41600 events read in total (715ms).
[12:54:49.680] <TB3> INFO: Test took 1121ms.
[12:54:49.680] <TB3> INFO: scanning low vcal = 20
[12:54:50.075] <TB3> INFO: Expecting 41600 events.
[12:54:51.164] <TB3> INFO: 41600 events read in total (702ms).
[12:54:51.164] <TB3> INFO: Test took 1484ms.
[12:54:51.164] <TB3> INFO: scanning low vcal = 30
[12:54:51.559] <TB3> INFO: Expecting 41600 events.
[12:54:52.648] <TB3> INFO: 41600 events read in total (702ms).
[12:54:52.648] <TB3> INFO: Test took 1484ms.
[12:54:52.649] <TB3> INFO: scanning low vcal = 40
[12:54:53.043] <TB3> INFO: Expecting 41600 events.
[12:54:54.180] <TB3> INFO: 41600 events read in total (750ms).
[12:54:54.180] <TB3> INFO: Test took 1531ms.
[12:54:54.181] <TB3> INFO: scanning low vcal = 50
[12:54:54.570] <TB3> INFO: Expecting 41600 events.
[12:54:55.708] <TB3> INFO: 41600 events read in total (751ms).
[12:54:55.708] <TB3> INFO: Test took 1527ms.
[12:54:55.709] <TB3> INFO: scanning low vcal = 60
[12:54:56.098] <TB3> INFO: Expecting 41600 events.
[12:54:57.221] <TB3> INFO: 41600 events read in total (736ms).
[12:54:57.222] <TB3> INFO: Test took 1513ms.
[12:54:57.222] <TB3> INFO: scanning low vcal = 70
[12:54:57.611] <TB3> INFO: Expecting 41600 events.
[12:54:58.748] <TB3> INFO: 41600 events read in total (750ms).
[12:54:58.748] <TB3> INFO: Test took 1526ms.
[12:54:58.749] <TB3> INFO: scanning low vcal = 80
[12:54:59.138] <TB3> INFO: Expecting 41600 events.
[12:55:00.297] <TB3> INFO: 41600 events read in total (773ms).
[12:55:00.297] <TB3> INFO: Test took 1548ms.
[12:55:00.298] <TB3> INFO: scanning low vcal = 90
[12:55:00.686] <TB3> INFO: Expecting 41600 events.
[12:55:01.839] <TB3> INFO: 41600 events read in total (766ms).
[12:55:01.839] <TB3> INFO: Test took 1541ms.
[12:55:01.840] <TB3> INFO: scanning low vcal = 100
[12:55:02.228] <TB3> INFO: Expecting 41600 events.
[12:55:03.360] <TB3> INFO: 41600 events read in total (745ms).
[12:55:03.361] <TB3> INFO: Test took 1521ms.
[12:55:03.361] <TB3> INFO: scanning low vcal = 110
[12:55:03.750] <TB3> INFO: Expecting 41600 events.
[12:55:04.874] <TB3> INFO: 41600 events read in total (737ms).
[12:55:04.874] <TB3> INFO: Test took 1513ms.
[12:55:04.874] <TB3> INFO: scanning low vcal = 120
[12:55:05.263] <TB3> INFO: Expecting 41600 events.
[12:55:06.387] <TB3> INFO: 41600 events read in total (737ms).
[12:55:06.388] <TB3> INFO: Test took 1514ms.
[12:55:06.388] <TB3> INFO: scanning low vcal = 130
[12:55:06.777] <TB3> INFO: Expecting 41600 events.
[12:55:07.900] <TB3> INFO: 41600 events read in total (736ms).
[12:55:07.900] <TB3> INFO: Test took 1512ms.
[12:55:07.900] <TB3> INFO: scanning low vcal = 140
[12:55:08.289] <TB3> INFO: Expecting 41600 events.
[12:55:09.426] <TB3> INFO: 41600 events read in total (750ms).
[12:55:09.426] <TB3> INFO: Test took 1526ms.
[12:55:09.427] <TB3> INFO: scanning low vcal = 150
[12:55:09.816] <TB3> INFO: Expecting 41600 events.
[12:55:10.938] <TB3> INFO: 41600 events read in total (736ms).
[12:55:10.938] <TB3> INFO: Test took 1511ms.
[12:55:10.939] <TB3> INFO: scanning low vcal = 160
[12:55:11.328] <TB3> INFO: Expecting 41600 events.
[12:55:12.450] <TB3> INFO: 41600 events read in total (735ms).
[12:55:12.450] <TB3> INFO: Test took 1511ms.
[12:55:12.451] <TB3> INFO: scanning low vcal = 170
[12:55:12.840] <TB3> INFO: Expecting 41600 events.
[12:55:13.962] <TB3> INFO: 41600 events read in total (736ms).
[12:55:13.962] <TB3> INFO: Test took 1511ms.
[12:55:13.963] <TB3> INFO: scanning low vcal = 180
[12:55:14.352] <TB3> INFO: Expecting 41600 events.
[12:55:15.474] <TB3> INFO: 41600 events read in total (736ms).
[12:55:15.474] <TB3> INFO: Test took 1511ms.
[12:55:15.475] <TB3> INFO: scanning low vcal = 190
[12:55:15.864] <TB3> INFO: Expecting 41600 events.
[12:55:16.986] <TB3> INFO: 41600 events read in total (736ms).
[12:55:16.987] <TB3> INFO: Test took 1512ms.
[12:55:16.987] <TB3> INFO: scanning low vcal = 200
[12:55:17.376] <TB3> INFO: Expecting 41600 events.
[12:55:18.499] <TB3> INFO: 41600 events read in total (736ms).
[12:55:18.499] <TB3> INFO: Test took 1512ms.
[12:55:18.500] <TB3> INFO: scanning low vcal = 210
[12:55:18.889] <TB3> INFO: Expecting 41600 events.
[12:55:20.035] <TB3> INFO: 41600 events read in total (760ms).
[12:55:20.035] <TB3> INFO: Test took 1535ms.
[12:55:20.036] <TB3> INFO: scanning low vcal = 220
[12:55:20.421] <TB3> INFO: Expecting 41600 events.
[12:55:21.545] <TB3> INFO: 41600 events read in total (737ms).
[12:55:21.545] <TB3> INFO: Test took 1509ms.
[12:55:21.546] <TB3> INFO: scanning low vcal = 230
[12:55:21.934] <TB3> INFO: Expecting 41600 events.
[12:55:23.073] <TB3> INFO: 41600 events read in total (752ms).
[12:55:23.073] <TB3> INFO: Test took 1527ms.
[12:55:23.073] <TB3> INFO: scanning low vcal = 240
[12:55:23.462] <TB3> INFO: Expecting 41600 events.
[12:55:24.600] <TB3> INFO: 41600 events read in total (751ms).
[12:55:24.600] <TB3> INFO: Test took 1527ms.
[12:55:24.600] <TB3> INFO: scanning low vcal = 250
[12:55:24.989] <TB3> INFO: Expecting 41600 events.
[12:55:26.113] <TB3> INFO: 41600 events read in total (737ms).
[12:55:26.113] <TB3> INFO: Test took 1513ms.
[12:55:26.114] <TB3> INFO: scanning high vcal = 30 (= 210 in low range)
[12:55:26.503] <TB3> INFO: Expecting 41600 events.
[12:55:27.640] <TB3> INFO: 41600 events read in total (751ms).
[12:55:27.640] <TB3> INFO: Test took 1526ms.
[12:55:27.641] <TB3> INFO: scanning high vcal = 50 (= 350 in low range)
[12:55:28.029] <TB3> INFO: Expecting 41600 events.
[12:55:29.153] <TB3> INFO: 41600 events read in total (737ms).
[12:55:29.153] <TB3> INFO: Test took 1512ms.
[12:55:29.153] <TB3> INFO: scanning high vcal = 70 (= 490 in low range)
[12:55:29.542] <TB3> INFO: Expecting 41600 events.
[12:55:30.694] <TB3> INFO: 41600 events read in total (765ms).
[12:55:30.694] <TB3> INFO: Test took 1541ms.
[12:55:30.695] <TB3> INFO: scanning high vcal = 90 (= 630 in low range)
[12:55:31.084] <TB3> INFO: Expecting 41600 events.
[12:55:32.207] <TB3> INFO: 41600 events read in total (736ms).
[12:55:32.208] <TB3> INFO: Test took 1513ms.
[12:55:32.208] <TB3> INFO: scanning high vcal = 200 (= 1400 in low range)
[12:55:32.597] <TB3> INFO: Expecting 41600 events.
[12:55:33.720] <TB3> INFO: 41600 events read in total (736ms).
[12:55:33.721] <TB3> INFO: Test took 1513ms.
[12:55:34.104] <TB3> INFO: PixTestGainPedestal::measure() done
[12:55:36.123] <TB3> INFO: PixTestGainPedestal::fit() done
[12:55:36.123] <TB3> INFO: non-linearity mean: 0.963
[12:55:36.123] <TB3> INFO: non-linearity RMS: 0.005
[12:55:36.123] <TB3> INFO: write gain/ped parameters into /home/mameinha/data/R422_Fulltest_p17_2015-10-06_14h40m_1444135207//000_FulltestROC_p17//phCalibrationFitErr35_C0.dat
[12:55:36.163] <TB3> INFO: PixTestGainPedestal::doTest() done, duration: 47 seconds
[12:55:36.164] <TB3> INFO: enter test to run
[12:55:36.164] <TB3> INFO: test: Readback no parameter change
[12:55:36.164] <TB3> INFO: running: readback
[12:55:36.164] <TB3> INFO: readReadbackCal: /home/mameinha/data/R422_Fulltest_p17_2015-10-06_14h40m_1444135207//000_FulltestROC_p17//readbackCal_C0.dat .. /home/mameinha/data/R422_Fulltest_p17_2015-10-06_14h40m_1444135207//000_FulltestROC_p17//readbackCal_C0.dat
[12:55:36.165] <TB3> INFO: ######################################################################
[12:55:36.165] <TB3> INFO: PixTestReadback::doTest()
[12:55:36.165] <TB3> INFO: ######################################################################
[12:55:36.165] <TB3> INFO: PixTestReadback::RES sent once
[12:55:47.297] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R422_Fulltest_p17_2015-10-06_14h40m_1444135207//000_FulltestROC_p17//readbackCal_C0.dat
[12:55:47.302] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[12:55:47.303] <TB3> INFO: PixTestReadback::RES sent once
[12:55:58.396] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R422_Fulltest_p17_2015-10-06_14h40m_1444135207//000_FulltestROC_p17//readbackCal_C0.dat
[12:55:58.402] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[12:55:58.402] <TB3> INFO: PixTestReadback::RES sent once
[12:56:06.729] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[12:56:06.729] <TB3> INFO: Vbg will be calibrated using Vd calibration
[12:56:06.729] <TB3> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 155.2calibrated Vbg = 1.23019 :::*/*/*/*/
[12:56:07.106] <TB3> INFO: PixTestReadback::RES sent once
[12:56:15.940] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R422_Fulltest_p17_2015-10-06_14h40m_1444135207//000_FulltestROC_p17//readbackCal_C0.dat
[12:56:15.945] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[12:56:15.945] <TB3> INFO: PixTestReadback::doTest() done
[12:56:15.979] <TB3> INFO: enter test to run
[12:56:15.979] <TB3> INFO: test: no parameter change
[12:56:16.022] <TB3> QUIET: Connection to board 71 closed.
[12:56:16.102] <TB3> INFO: pXar: this is the end, my friend