[16:17:37.943] <TB3> INFO: *** Welcome to pxar ***
[16:17:37.943] <TB3> INFO: *** Today: 2015/10/05
[16:17:38.246] <TB3> INFO: *** Version: 9da6
[16:17:38.246] <TB3> INFO: readRocDacs: /home/mameinha/data/R416_Fulltest_p17_2015-10-05_18h17m_1444061849//000_FulltestROC_p17//dacParameters_C0.dat .. /home/mameinha/data/R416_Fulltest_p17_2015-10-05_18h17m_1444061849//000_FulltestROC_p17//dacParameters_C0.dat
[16:17:38.247] <TB3> INFO: readTbmDacs: /home/mameinha/data/R416_Fulltest_p17_2015-10-05_18h17m_1444061849//000_FulltestROC_p17//tbmParameters_C0a.dat .. /home/mameinha/data/R416_Fulltest_p17_2015-10-05_18h17m_1444061849//000_FulltestROC_p17//tbmParameters_C4294967295b.dat
[16:17:38.247] <TB3> INFO: readMaskFile: /home/mameinha/data/R416_Fulltest_p17_2015-10-05_18h17m_1444061849//000_FulltestROC_p17//defaultMaskFile.dat
[16:17:38.247] <TB3> INFO: readTrimFile: /home/mameinha/data/R416_Fulltest_p17_2015-10-05_18h17m_1444061849//000_FulltestROC_p17//trimParameters_C0.dat .. /home/mameinha/data/R416_Fulltest_p17_2015-10-05_18h17m_1444061849//000_FulltestROC_p17//trimParameters_C0.dat
[16:17:38.255] <TB3> INFO: clk: 4
[16:17:38.255] <TB3> INFO: ctr: 4
[16:17:38.255] <TB3> INFO: sda: 19
[16:17:38.255] <TB3> INFO: tin: 9
[16:17:38.255] <TB3> INFO: level: 15
[16:17:38.255] <TB3> INFO: deser160phase: 4
[16:17:38.255] <TB3> QUIET: Instanciating API for pxar v2.6.0+20~g1a7f656
[16:17:38.255] <TB3> INFO: Log level: INFO
[16:17:38.278] <TB3> QUIET: Connection to board DTB_WRQ4OZ opened.
[16:17:38.282] <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:
------------------------------------------------------
[16:17:38.284] <TB3> INFO: RPC call hashes of host and DTB match: 398089610
[16:17:39.446] <TB3> INFO: DUT info:
[16:17:39.446] <TB3> INFO: The DUT currently contains the following objects:
[16:17:39.446] <TB3> INFO: 0 TBM Cores (0 ON)
[16:17:39.446] <TB3> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[16:17:39.446] <TB3> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[16:17:39.848] <TB3> INFO: enter 'restricted' command line mode
[16:17:39.848] <TB3> INFO: enter test to run
[16:17:39.848] <TB3> INFO: test: Setup no parameter change
[16:17:39.848] <TB3> INFO: running: setup
[16:17:39.852] <TB3> INFO: PixTestSetup::doTest() ntrig = 10

[16:17:39.852] <TB3> INFO: PixTestSetup:: pg set to RES|TOK
[16:17:39.852] <TB3> INFO: 0 1 2 3 4 5 6 7
[16:17:42.894] <TB3> INFO: 0: 000 000 004 07c 7f0 f00 000 000
[16:17:45.907] <TB3> INFO: 1: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[16:17:48.920] <TB3> INFO: 2: 800 000 004 07c <7f8>[*] f80 800 000
[16:17:51.934] <TB3> INFO: 3: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[16:17:54.947] <TB3> INFO: 4: 000 000 000 03c 3f8 f80 800 000
[16:17:57.959] <TB3> INFO: 5: 800 000 000 03c 3f8 f80 800 000
[16:18:00.972] <TB3> INFO: 6: 000 000 000 03c 3fc fc0 c00 000
[16:18:03.985] <TB3> INFO: 7: 000 000 000 03c 3fc fc0 c00 000
[16:18:06.999] <TB3> INFO: 8: 000 000 000 03c 3fc fc0 c00 000
[16:18:10.012] <TB3> INFO: 9: 000 000 000 03c 3fc fc0 c00 000
[16:18:13.025] <TB3> INFO: 10: 000 000 000 01c 1fc fc0 c00 000
[16:18:16.038] <TB3> INFO: 11: 000 000 000 01c 1fc fe0 e00 000
[16:18:19.051] <TB3> INFO: 12: 000 000 000 01c 1fc fe0 e00 000
[16:18:22.064] <TB3> INFO: 13: 000 000 000 01c 1fc fe0 e00 000
[16:18:25.077] <TB3> INFO: 14: e00 000 000 00c 0fc fe0 e00 000
[16:18:28.090] <TB3> INFO: 15: 000 000 000 00c 0fc fe0 e00 000
[16:18:31.103] <TB3> INFO: 16: 000 000 000 00c 0fc ff0 f00 000
[16:18:34.115] <TB3> INFO: 17: 000 000 000 00c 0fc ff0 f00 000
[16:18:37.128] <TB3> INFO: 18: f00 000 000 00c 0fc ff0 f00 000
[16:18:40.141] <TB3> INFO: 19: 000 000 000 00c 0fc ff0 f00 000
[16:18:40.547] <TB3> INFO: Found good delays at CLK = 2, DESER160 = 4
[16:18:40.549] <TB3> INFO: PixTestSetup:: Write Tb parameters to file.
[16:18:40.624] <TB3> INFO: write dtb parameters into /home/mameinha/data/R416_Fulltest_p17_2015-10-05_18h17m_1444061849//000_FulltestROC_p17//tbParameters.dat
[16:18:40.627] <TB3> INFO: PixTestSetup::doTest() done for.
[16:18:40.651] <TB3> INFO: enter test to run
[16:18:40.652] <TB3> INFO: test: Pretest no parameter change
[16:18:40.653] <TB3> INFO: running: pretest
[16:18:40.654] <TB3> INFO: ----------------------------------------------------------------------
[16:18:40.654] <TB3> INFO: PixTestPretest::programROC()
[16:18:40.654] <TB3> INFO: ----------------------------------------------------------------------
[16:18:43.656] <TB3> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[16:18:43.656] <TB3> INFO: IA differences per ROC: 19.3
[16:18:43.660] <TB3> INFO: enter test to run
[16:18:43.660] <TB3> INFO: test: Pretest no parameter change
[16:18:43.660] <TB3> INFO: running: pretest
[16:18:43.661] <TB3> INFO: ----------------------------------------------------------------------
[16:18:43.661] <TB3> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[16:18:43.661] <TB3> INFO: ----------------------------------------------------------------------
[16:18:44.674] <TB3> INFO: PixTestPretest::setVana() done, Module Ia 24.9 mA = 24.9 mA/ROC
[16:18:44.674] <TB3> INFO: i(loss) [mA/ROC]: 20.1
[16:18:44.676] <TB3> INFO: enter test to run
[16:18:44.676] <TB3> INFO: test: Pretest no parameter change
[16:18:44.676] <TB3> INFO: running: pretest
[16:18:44.677] <TB3> INFO: ----------------------------------------------------------------------
[16:18:44.677] <TB3> INFO: PixTestPretest::findWorkingPixel()
[16:18:44.677] <TB3> INFO: ----------------------------------------------------------------------
[16:18:44.687] <TB3> INFO: Expecting 231680 events.
[16:18:46.888] <TB3> INFO: 231680 events read in total (1814ms).
[16:18:46.890] <TB3> INFO: Test took 2212ms.
[16:18:47.268] <TB3> INFO: Found working pixel in all ROCs: col/row = 12/22
[16:18:47.273] <TB3> INFO: enter test to run
[16:18:47.273] <TB3> INFO: test: Pretest no parameter change
[16:18:47.273] <TB3> INFO: running: pretest
[16:18:47.275] <TB3> INFO: ----------------------------------------------------------------------
[16:18:47.275] <TB3> INFO: PixTestPretest::setVthrCompCalDel()
[16:18:47.275] <TB3> INFO: ----------------------------------------------------------------------
[16:18:47.284] <TB3> INFO: Expecting 231680 events.
[16:18:49.482] <TB3> INFO: 231680 events read in total (1811ms).
[16:18:49.485] <TB3> INFO: Test took 2210ms.
[16:18:49.864] <TB3> INFO: PixTestPretest::setVthrCompCalDel() done
[16:18:49.864] <TB3> INFO: CalDel: 148
[16:18:49.864] <TB3> INFO: VthrComp: 51
[16:18:49.868] <TB3> INFO: enter test to run
[16:18:49.868] <TB3> INFO: test: Pretest no parameter change
[16:18:49.868] <TB3> INFO: running: pretest
[16:18:49.872] <TB3> INFO: write dac parameters into /home/mameinha/data/R416_Fulltest_p17_2015-10-05_18h17m_1444061849//000_FulltestROC_p17//dacParameters_C0.dat
[16:18:49.874] <TB3> INFO: enter test to run
[16:18:49.874] <TB3> INFO: test: PixelAlive no parameter change
[16:18:49.874] <TB3> INFO: running: pixelalive
[16:18:49.876] <TB3> INFO: ######################################################################
[16:18:49.876] <TB3> INFO: PixTestAlive::doTest()
[16:18:49.876] <TB3> INFO: ######################################################################
[16:18:49.877] <TB3> INFO: ----------------------------------------------------------------------
[16:18:49.877] <TB3> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[16:18:49.877] <TB3> INFO: ----------------------------------------------------------------------
[16:18:49.897] <TB3> INFO: Expecting 41600 events.
[16:18:50.694] <TB3> INFO: 41600 events read in total (410ms).
[16:18:50.694] <TB3> INFO: Test took 817ms.
[16:18:50.694] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:18:51.080] <TB3> INFO: PixTestAlive::aliveTest() done
[16:18:51.080] <TB3> INFO: number of dead pixels (per ROC): 0
[16:18:51.081] <TB3> INFO: ----------------------------------------------------------------------
[16:18:51.081] <TB3> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[16:18:51.081] <TB3> INFO: ----------------------------------------------------------------------
[16:18:51.100] <TB3> INFO: Expecting 41600 events.
[16:18:51.843] <TB3> INFO: 41600 events read in total (356ms).
[16:18:51.843] <TB3> INFO: Test took 762ms.
[16:18:51.843] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:18:51.843] <TB3> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[16:18:52.233] <TB3> INFO: PixTestAlive::maskTest() done
[16:18:52.233] <TB3> INFO: number of mask-defect pixels (per ROC): 0
[16:18:52.234] <TB3> INFO: ----------------------------------------------------------------------
[16:18:52.234] <TB3> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[16:18:52.234] <TB3> INFO: ----------------------------------------------------------------------
[16:18:52.253] <TB3> INFO: Expecting 41600 events.
[16:18:53.050] <TB3> INFO: 41600 events read in total (410ms).
[16:18:53.051] <TB3> INFO: Test took 817ms.
[16:18:53.051] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:18:53.436] <TB3> INFO: PixTestAlive::addressDecodingTest() done
[16:18:53.436] <TB3> INFO: number of address-decoding pixels (per ROC): 0
[16:18:53.436] <TB3> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[16:18:53.436] <TB3> INFO: enter test to run
[16:18:53.436] <TB3> INFO: test: Scurves no parameter change
[16:18:53.436] <TB3> INFO: running: scurves
[16:18:53.438] <TB3> INFO: ######################################################################
[16:18:53.438] <TB3> INFO: PixTestScurves::doTest() ntrig = 50
[16:18:53.438] <TB3> INFO: ######################################################################
[16:18:53.438] <TB3> INFO: ----------------------------------------------------------------------
[16:18:53.438] <TB3> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[16:18:53.438] <TB3> INFO: ----------------------------------------------------------------------
[16:18:53.438] <TB3> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[16:18:53.448] <TB3> INFO: dacScan split into 1 runs with ntrig = 50
[16:18:53.448] <TB3> INFO: run 1 of 1
[16:18:53.467] <TB3> INFO: Expecting 41808000 events.
[16:21:15.614] <TB3> INFO: 20608900 events read in total (141760ms).
[16:23:34.999] <TB3> INFO: 40880900 events read in total (281145ms).
[16:23:41.398] <TB3> INFO: 41808000 events read in total (287544ms).
[16:23:41.425] <TB3> INFO: Test took 287977ms.
[16:23:41.449] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:23:42.970] <TB3> INFO: PixTestScurves::scurves() done
[16:23:42.970] <TB3> INFO: Vcal mean: 91.66
[16:23:42.970] <TB3> INFO: Vcal RMS: 5.11
[16:23:42.975] <TB3> INFO: enter test to run
[16:23:42.975] <TB3> INFO: test: Trim no parameter change
[16:23:42.975] <TB3> INFO: running: trim
[16:23:42.976] <TB3> INFO: ######################################################################
[16:23:42.976] <TB3> INFO: PixTestTrim::doTest()
[16:23:42.976] <TB3> INFO: ######################################################################
[16:23:42.977] <TB3> INFO: ----------------------------------------------------------------------
[16:23:42.977] <TB3> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[16:23:42.977] <TB3> INFO: ----------------------------------------------------------------------
[16:23:42.982] <TB3> INFO: ---> VthrComp thr map (minimal VthrComp)
[16:23:42.982] <TB3> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[16:23:42.990] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:23:42.990] <TB3> INFO: run 1 of 1
[16:23:43.009] <TB3> INFO: Expecting 6281600 events.
[16:24:28.384] <TB3> INFO: 6281600 events read in total (44984ms).
[16:24:28.400] <TB3> INFO: Test took 45410ms.
[16:24:28.409] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:24:29.492] <TB3> INFO: ROC 0 VthrComp = 93
[16:24:29.492] <TB3> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[16:24:29.492] <TB3> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[16:24:29.500] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:24:29.500] <TB3> INFO: run 1 of 1
[16:24:29.519] <TB3> INFO: Expecting 6281600 events.
[16:25:18.261] <TB3> INFO: 6281600 events read in total (48355ms).
[16:25:18.307] <TB3> INFO: Test took 48807ms.
[16:25:18.326] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:25:19.588] <TB3> INFO: roc 0 with ID = 0 has maximal Vcal 59.1274 for pixel 22/3 mean/min/max = 46.1033/33.0217/59.185
[16:25:19.597] <TB3> INFO: Expecting 514560 events.
[16:25:23.600] <TB3> INFO: 514560 events read in total (3616ms).
[16:25:23.605] <TB3> INFO: Test took 4017ms.
[16:25:23.997] <TB3> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[16:25:24.004] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:25:24.004] <TB3> INFO: run 1 of 1
[16:25:24.024] <TB3> INFO: Expecting 6281600 events.
[16:26:12.988] <TB3> INFO: 6281600 events read in total (48577ms).
[16:26:13.036] <TB3> INFO: Test took 49031ms.
[16:26:13.056] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:26:14.298] <TB3> INFO: ---> TrimStepCorr4 extremal thresholds: 14.096737 .. 49.010129
[16:26:14.302] <TB3> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 4 .. 59 (-1/-1) hits flags = 528 (plus default)
[16:26:14.310] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:26:14.310] <TB3> INFO: run 1 of 1
[16:26:14.329] <TB3> INFO: Expecting 2329600 events.
[16:26:32.124] <TB3> INFO: 2329600 events read in total (17408ms).
[16:26:32.134] <TB3> INFO: Test took 17824ms.
[16:26:32.139] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:26:32.940] <TB3> INFO: ---> TrimStepCorr2 extremal thresholds: 22.960649 .. 44.457942
[16:26:32.945] <TB3> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 12 .. 54 (-1/-1) hits flags = 528 (plus default)
[16:26:32.952] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:26:32.952] <TB3> INFO: run 1 of 1
[16:26:32.971] <TB3> INFO: Expecting 1788800 events.
[16:26:46.826] <TB3> INFO: 1788800 events read in total (13468ms).
[16:26:46.833] <TB3> INFO: Test took 13881ms.
[16:26:46.837] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:26:47.606] <TB3> INFO: ---> TrimStepCorr1a extremal thresholds: 27.309394 .. 39.903973
[16:26:47.611] <TB3> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 17 .. 49 (-1/-1) hits flags = 528 (plus default)
[16:26:47.619] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:26:47.619] <TB3> INFO: run 1 of 1
[16:26:47.638] <TB3> INFO: Expecting 1372800 events.
[16:26:58.466] <TB3> INFO: 1372800 events read in total (10441ms).
[16:26:58.473] <TB3> INFO: Test took 10854ms.
[16:26:58.476] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:26:59.212] <TB3> INFO: ---> TrimStepCorr1b extremal thresholds: 29.733503 .. 39.903973
[16:26:59.217] <TB3> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 19 .. 49 (-1/-1) hits flags = 528 (plus default)
[16:26:59.224] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:26:59.224] <TB3> INFO: run 1 of 1
[16:26:59.243] <TB3> INFO: Expecting 1289600 events.
[16:27:09.494] <TB3> INFO: 1289600 events read in total (9864ms).
[16:27:09.501] <TB3> INFO: Test took 10277ms.
[16:27:09.504] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:27:10.232] <TB3> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[16:27:10.232] <TB3> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[16:27:10.240] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:27:10.240] <TB3> INFO: run 1 of 1
[16:27:10.259] <TB3> INFO: Expecting 1705600 events.
[16:27:23.586] <TB3> INFO: 1705600 events read in total (12940ms).
[16:27:23.594] <TB3> INFO: Test took 13354ms.
[16:27:23.598] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:27:24.379] <TB3> INFO: write dac parameters into /home/mameinha/data/R416_Fulltest_p17_2015-10-05_18h17m_1444061849//000_FulltestROC_p17//dacParameters35_C0.dat
[16:27:24.385] <TB3> INFO: write trim parameters into /home/mameinha/data/R416_Fulltest_p17_2015-10-05_18h17m_1444061849//000_FulltestROC_p17//trimParameters35_C0.dat
[16:27:24.396] <TB3> INFO: PixTestTrim::trimTest() done
[16:27:24.396] <TB3> INFO: vtrim: 111
[16:27:24.396] <TB3> INFO: vthrcomp: 93
[16:27:24.396] <TB3> INFO: vcal mean: 35.02
[16:27:24.396] <TB3> INFO: vcal RMS: 0.74
[16:27:24.396] <TB3> INFO: bits mean: 9.29
[16:27:24.396] <TB3> INFO: bits RMS: 2.66
[16:27:24.400] <TB3> INFO: ----------------------------------------------------------------------
[16:27:24.400] <TB3> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[16:27:24.400] <TB3> INFO: ----------------------------------------------------------------------
[16:27:24.400] <TB3> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[16:27:24.408] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:27:24.408] <TB3> INFO: run 1 of 1
[16:27:24.427] <TB3> INFO: Expecting 8320000 events.
[16:28:25.845] <TB3> INFO: 8320000 events read in total (61031ms).
[16:28:25.875] <TB3> INFO: Test took 61467ms.
[16:28:25.891] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:28:27.363] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 152 (-1/-1) hits flags = 528 (plus default)
[16:28:27.371] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:28:27.371] <TB3> INFO: run 1 of 1
[16:28:27.390] <TB3> INFO: Expecting 6364800 events.
[16:29:13.845] <TB3> INFO: 6364800 events read in total (46069ms).
[16:29:13.863] <TB3> INFO: Test took 46492ms.
[16:29:13.872] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:29:15.084] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 142 (-1/-1) hits flags = 528 (plus default)
[16:29:15.091] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:29:15.091] <TB3> INFO: run 1 of 1
[16:29:15.110] <TB3> INFO: Expecting 5948800 events.
[16:29:58.370] <TB3> INFO: 5948800 events read in total (42873ms).
[16:29:58.386] <TB3> INFO: Test took 43295ms.
[16:29:58.394] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:29:59.533] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 142 (-1/-1) hits flags = 528 (plus default)
[16:29:59.541] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:29:59.541] <TB3> INFO: run 1 of 1
[16:29:59.560] <TB3> INFO: Expecting 5948800 events.
[16:30:42.779] <TB3> INFO: 5948800 events read in total (42832ms).
[16:30:42.795] <TB3> INFO: Test took 43254ms.
[16:30:42.803] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:30:43.962] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 143 (-1/-1) hits flags = 528 (plus default)
[16:30:43.970] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:30:43.970] <TB3> INFO: run 1 of 1
[16:30:43.989] <TB3> INFO: Expecting 5990400 events.
[16:31:27.525] <TB3> INFO: 5990400 events read in total (43149ms).
[16:31:27.542] <TB3> INFO: Test took 43572ms.
[16:31:27.549] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:31:28.699] <TB3> INFO: PixTestTrim::trimBitTest() done
[16:31:28.700] <TB3> INFO: PixTestTrim::doTest() done, duration: 465 seconds
[16:31:28.739] <TB3> INFO: enter test to run
[16:31:28.740] <TB3> INFO: test: PhOptimization no parameter change
[16:31:28.740] <TB3> INFO: running: phoptimization
[16:31:28.740] <TB3> INFO: ######################################################################
[16:31:28.740] <TB3> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[16:31:28.740] <TB3> INFO: ######################################################################
[16:31:28.761] <TB3> INFO: Expecting 41600 events.
[16:31:29.556] <TB3> INFO: 41600 events read in total (408ms).
[16:31:29.556] <TB3> INFO: Test took 814ms.
[16:31:29.556] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:31:29.948] <TB3> INFO: Expecting 41600 events.
[16:31:30.744] <TB3> INFO: 41600 events read in total (410ms).
[16:31:30.745] <TB3> INFO: Test took 1188ms.
[16:31:30.745] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:31:31.134] <TB3> INFO: Expecting 41600 events.
[16:31:31.931] <TB3> INFO: 41600 events read in total (410ms).
[16:31:31.931] <TB3> INFO: Test took 1185ms.
[16:31:31.932] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:31:32.321] <TB3> INFO: Expecting 2560 events.
[16:31:32.739] <TB3> INFO: 2560 events read in total (31ms).
[16:31:32.739] <TB3> INFO: Test took 807ms.
[16:31:33.134] <TB3> INFO: Expecting 655360 events.
[16:31:38.347] <TB3> INFO: 655360 events read in total (4826ms).
[16:31:38.356] <TB3> INFO: Test took 5617ms.
[16:31:38.647] <TB3> INFO: Expecting 655360 events.
[16:31:43.857] <TB3> INFO: 655360 events read in total (4823ms).
[16:31:43.865] <TB3> INFO: Test took 5496ms.
[16:31:43.885] <TB3> INFO: safety margin for low PH: adding 0, margin is now 20
[16:31:43.899] <TB3> INFO: write dac parameters into /home/mameinha/data/R416_Fulltest_p17_2015-10-05_18h17m_1444061849//000_FulltestROC_p17//dacParameters35_C0.dat
[16:31:44.162] <TB3> INFO: Expecting 41600 events.
[16:31:44.922] <TB3> INFO: 41600 events read in total (373ms).
[16:31:44.922] <TB3> INFO: Test took 1020ms.
[16:31:45.311] <TB3> INFO: Expecting 41600 events.
[16:31:46.071] <TB3> INFO: 41600 events read in total (373ms).
[16:31:46.072] <TB3> INFO: Test took 1149ms.
[16:31:46.461] <TB3> INFO: Expecting 41600 events.
[16:31:47.221] <TB3> INFO: 41600 events read in total (373ms).
[16:31:47.221] <TB3> INFO: Test took 1149ms.
[16:31:47.611] <TB3> INFO: Expecting 2560 events.
[16:31:48.028] <TB3> INFO: 2560 events read in total (30ms).
[16:31:48.028] <TB3> INFO: Test took 806ms.
[16:31:48.423] <TB3> INFO: Expecting 2560 events.
[16:31:48.841] <TB3> INFO: 2560 events read in total (31ms).
[16:31:48.841] <TB3> INFO: Test took 813ms.
[16:31:49.248] <TB3> INFO: PixTestPhOptimization::doTest() done, duration: 20 seconds
[16:31:49.248] <TB3> INFO: PH scale (per ROC): 76
[16:31:49.248] <TB3> INFO: PH offset (per ROC): 187
[16:31:49.261] <TB3> INFO: enter test to run
[16:31:49.261] <TB3> INFO: test: GainPedestal no parameter change
[16:31:49.261] <TB3> INFO: running: gainpedestal
[16:31:49.263] <TB3> INFO: ######################################################################
[16:31:49.263] <TB3> INFO: PixTestGainPedestal::doTest() ntrig = 10
[16:31:49.263] <TB3> INFO: ######################################################################
[16:31:49.270] <TB3> INFO: scanning low vcal = 10
[16:31:49.289] <TB3> INFO: Expecting 41600 events.
[16:31:50.378] <TB3> INFO: 41600 events read in total (702ms).
[16:31:50.378] <TB3> INFO: Test took 1108ms.
[16:31:50.378] <TB3> INFO: scanning low vcal = 20
[16:31:50.773] <TB3> INFO: Expecting 41600 events.
[16:31:51.861] <TB3> INFO: 41600 events read in total (701ms).
[16:31:51.861] <TB3> INFO: Test took 1483ms.
[16:31:51.861] <TB3> INFO: scanning low vcal = 30
[16:31:52.256] <TB3> INFO: Expecting 41600 events.
[16:31:53.345] <TB3> INFO: 41600 events read in total (702ms).
[16:31:53.346] <TB3> INFO: Test took 1485ms.
[16:31:53.346] <TB3> INFO: scanning low vcal = 40
[16:31:53.740] <TB3> INFO: Expecting 41600 events.
[16:31:54.862] <TB3> INFO: 41600 events read in total (735ms).
[16:31:54.863] <TB3> INFO: Test took 1517ms.
[16:31:54.863] <TB3> INFO: scanning low vcal = 50
[16:31:55.252] <TB3> INFO: Expecting 41600 events.
[16:31:56.376] <TB3> INFO: 41600 events read in total (737ms).
[16:31:56.376] <TB3> INFO: Test took 1513ms.
[16:31:56.376] <TB3> INFO: scanning low vcal = 60
[16:31:56.765] <TB3> INFO: Expecting 41600 events.
[16:31:57.889] <TB3> INFO: 41600 events read in total (737ms).
[16:31:57.889] <TB3> INFO: Test took 1512ms.
[16:31:57.890] <TB3> INFO: scanning low vcal = 70
[16:31:58.279] <TB3> INFO: Expecting 41600 events.
[16:31:59.402] <TB3> INFO: 41600 events read in total (736ms).
[16:31:59.403] <TB3> INFO: Test took 1513ms.
[16:31:59.403] <TB3> INFO: scanning low vcal = 80
[16:31:59.792] <TB3> INFO: Expecting 41600 events.
[16:32:00.924] <TB3> INFO: 41600 events read in total (745ms).
[16:32:00.924] <TB3> INFO: Test took 1521ms.
[16:32:00.924] <TB3> INFO: scanning low vcal = 90
[16:32:01.313] <TB3> INFO: Expecting 41600 events.
[16:32:02.437] <TB3> INFO: 41600 events read in total (737ms).
[16:32:02.437] <TB3> INFO: Test took 1513ms.
[16:32:02.438] <TB3> INFO: scanning low vcal = 100
[16:32:02.827] <TB3> INFO: Expecting 41600 events.
[16:32:03.959] <TB3> INFO: 41600 events read in total (745ms).
[16:32:03.959] <TB3> INFO: Test took 1521ms.
[16:32:03.959] <TB3> INFO: scanning low vcal = 110
[16:32:04.348] <TB3> INFO: Expecting 41600 events.
[16:32:05.472] <TB3> INFO: 41600 events read in total (737ms).
[16:32:05.473] <TB3> INFO: Test took 1514ms.
[16:32:05.473] <TB3> INFO: scanning low vcal = 120
[16:32:05.862] <TB3> INFO: Expecting 41600 events.
[16:32:06.985] <TB3> INFO: 41600 events read in total (736ms).
[16:32:06.986] <TB3> INFO: Test took 1513ms.
[16:32:06.986] <TB3> INFO: scanning low vcal = 130
[16:32:07.375] <TB3> INFO: Expecting 41600 events.
[16:32:08.498] <TB3> INFO: 41600 events read in total (736ms).
[16:32:08.499] <TB3> INFO: Test took 1513ms.
[16:32:08.499] <TB3> INFO: scanning low vcal = 140
[16:32:08.888] <TB3> INFO: Expecting 41600 events.
[16:32:10.012] <TB3> INFO: 41600 events read in total (737ms).
[16:32:10.012] <TB3> INFO: Test took 1513ms.
[16:32:10.012] <TB3> INFO: scanning low vcal = 150
[16:32:10.401] <TB3> INFO: Expecting 41600 events.
[16:32:11.525] <TB3> INFO: 41600 events read in total (737ms).
[16:32:11.525] <TB3> INFO: Test took 1513ms.
[16:32:11.526] <TB3> INFO: scanning low vcal = 160
[16:32:11.915] <TB3> INFO: Expecting 41600 events.
[16:32:13.038] <TB3> INFO: 41600 events read in total (736ms).
[16:32:13.039] <TB3> INFO: Test took 1513ms.
[16:32:13.039] <TB3> INFO: scanning low vcal = 170
[16:32:13.428] <TB3> INFO: Expecting 41600 events.
[16:32:14.552] <TB3> INFO: 41600 events read in total (737ms).
[16:32:14.553] <TB3> INFO: Test took 1514ms.
[16:32:14.553] <TB3> INFO: scanning low vcal = 180
[16:32:14.942] <TB3> INFO: Expecting 41600 events.
[16:32:16.065] <TB3> INFO: 41600 events read in total (736ms).
[16:32:16.066] <TB3> INFO: Test took 1513ms.
[16:32:16.066] <TB3> INFO: scanning low vcal = 190
[16:32:16.455] <TB3> INFO: Expecting 41600 events.
[16:32:17.578] <TB3> INFO: 41600 events read in total (736ms).
[16:32:17.579] <TB3> INFO: Test took 1513ms.
[16:32:17.579] <TB3> INFO: scanning low vcal = 200
[16:32:17.968] <TB3> INFO: Expecting 41600 events.
[16:32:19.091] <TB3> INFO: 41600 events read in total (736ms).
[16:32:19.092] <TB3> INFO: Test took 1513ms.
[16:32:19.092] <TB3> INFO: scanning low vcal = 210
[16:32:19.481] <TB3> INFO: Expecting 41600 events.
[16:32:20.605] <TB3> INFO: 41600 events read in total (737ms).
[16:32:20.605] <TB3> INFO: Test took 1513ms.
[16:32:20.605] <TB3> INFO: scanning low vcal = 220
[16:32:20.994] <TB3> INFO: Expecting 41600 events.
[16:32:22.118] <TB3> INFO: 41600 events read in total (737ms).
[16:32:22.118] <TB3> INFO: Test took 1513ms.
[16:32:22.118] <TB3> INFO: scanning low vcal = 230
[16:32:22.507] <TB3> INFO: Expecting 41600 events.
[16:32:23.631] <TB3> INFO: 41600 events read in total (736ms).
[16:32:23.632] <TB3> INFO: Test took 1514ms.
[16:32:23.632] <TB3> INFO: scanning low vcal = 240
[16:32:24.021] <TB3> INFO: Expecting 41600 events.
[16:32:25.145] <TB3> INFO: 41600 events read in total (737ms).
[16:32:25.145] <TB3> INFO: Test took 1513ms.
[16:32:25.146] <TB3> INFO: scanning low vcal = 250
[16:32:25.534] <TB3> INFO: Expecting 41600 events.
[16:32:26.658] <TB3> INFO: 41600 events read in total (737ms).
[16:32:26.659] <TB3> INFO: Test took 1513ms.
[16:32:26.659] <TB3> INFO: scanning high vcal = 30 (= 210 in low range)
[16:32:27.048] <TB3> INFO: Expecting 41600 events.
[16:32:28.171] <TB3> INFO: 41600 events read in total (736ms).
[16:32:28.172] <TB3> INFO: Test took 1513ms.
[16:32:28.172] <TB3> INFO: scanning high vcal = 50 (= 350 in low range)
[16:32:28.561] <TB3> INFO: Expecting 41600 events.
[16:32:29.684] <TB3> INFO: 41600 events read in total (736ms).
[16:32:29.685] <TB3> INFO: Test took 1513ms.
[16:32:29.685] <TB3> INFO: scanning high vcal = 70 (= 490 in low range)
[16:32:30.074] <TB3> INFO: Expecting 41600 events.
[16:32:31.198] <TB3> INFO: 41600 events read in total (737ms).
[16:32:31.198] <TB3> INFO: Test took 1513ms.
[16:32:31.199] <TB3> INFO: scanning high vcal = 90 (= 630 in low range)
[16:32:31.588] <TB3> INFO: Expecting 41600 events.
[16:32:32.711] <TB3> INFO: 41600 events read in total (737ms).
[16:32:32.712] <TB3> INFO: Test took 1513ms.
[16:32:32.712] <TB3> INFO: scanning high vcal = 200 (= 1400 in low range)
[16:32:33.101] <TB3> INFO: Expecting 41600 events.
[16:32:34.225] <TB3> INFO: 41600 events read in total (737ms).
[16:32:34.225] <TB3> INFO: Test took 1513ms.
[16:32:34.609] <TB3> INFO: PixTestGainPedestal::measure() done
[16:32:36.654] <TB3> INFO: PixTestGainPedestal::fit() done
[16:32:36.654] <TB3> INFO: non-linearity mean: 0.960
[16:32:36.654] <TB3> INFO: non-linearity RMS: 0.007
[16:32:36.654] <TB3> INFO: write gain/ped parameters into /home/mameinha/data/R416_Fulltest_p17_2015-10-05_18h17m_1444061849//000_FulltestROC_p17//phCalibrationFitErr35_C0.dat
[16:32:36.703] <TB3> INFO: PixTestGainPedestal::doTest() done, duration: 47 seconds
[16:32:36.703] <TB3> INFO: enter test to run
[16:32:36.703] <TB3> INFO: test: Readback no parameter change
[16:32:36.703] <TB3> INFO: running: readback
[16:32:36.703] <TB3> INFO: readReadbackCal: /home/mameinha/data/R416_Fulltest_p17_2015-10-05_18h17m_1444061849//000_FulltestROC_p17//readbackCal_C0.dat .. /home/mameinha/data/R416_Fulltest_p17_2015-10-05_18h17m_1444061849//000_FulltestROC_p17//readbackCal_C0.dat
[16:32:36.704] <TB3> INFO: ######################################################################
[16:32:36.704] <TB3> INFO: PixTestReadback::doTest()
[16:32:36.704] <TB3> INFO: ######################################################################
[16:32:36.705] <TB3> INFO: PixTestReadback::RES sent once
[16:32:47.833] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R416_Fulltest_p17_2015-10-05_18h17m_1444061849//000_FulltestROC_p17//readbackCal_C0.dat
[16:32:47.838] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[16:32:47.839] <TB3> INFO: PixTestReadback::RES sent once
[16:32:58.937] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R416_Fulltest_p17_2015-10-05_18h17m_1444061849//000_FulltestROC_p17//readbackCal_C0.dat
[16:32:58.943] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[16:32:58.943] <TB3> INFO: PixTestReadback::RES sent once
[16:33:07.272] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[16:33:07.272] <TB3> INFO: Vbg will be calibrated using Vd calibration
[16:33:07.272] <TB3> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 154.2calibrated Vbg = 1.22103 :::*/*/*/*/
[16:33:07.649] <TB3> INFO: PixTestReadback::RES sent once
[16:33:16.486] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R416_Fulltest_p17_2015-10-05_18h17m_1444061849//000_FulltestROC_p17//readbackCal_C0.dat
[16:33:16.491] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[16:33:16.491] <TB3> INFO: PixTestReadback::doTest() done
[16:33:16.524] <TB3> INFO: enter test to run
[16:33:16.524] <TB3> INFO: test: no parameter change
[16:33:16.555] <TB3> QUIET: Connection to board 71 closed.
[16:33:16.637] <TB3> INFO: pXar: this is the end, my friend