[08:17:35.829] <TB3> INFO: *** Welcome to pxar ***
[08:17:35.829] <TB3> INFO: *** Today: 2015/10/07
[08:17:36.143] <TB3> INFO: *** Version: 9da6
[08:17:36.143] <TB3> INFO: readRocDacs: /home/mameinha/data/R417_Fulltest_p17_2015-10-07_10h17m_1444205846//000_FulltestROC_p17//dacParameters_C0.dat .. /home/mameinha/data/R417_Fulltest_p17_2015-10-07_10h17m_1444205846//000_FulltestROC_p17//dacParameters_C0.dat
[08:17:36.146] <TB3> INFO: readTbmDacs: /home/mameinha/data/R417_Fulltest_p17_2015-10-07_10h17m_1444205846//000_FulltestROC_p17//tbmParameters_C0a.dat .. /home/mameinha/data/R417_Fulltest_p17_2015-10-07_10h17m_1444205846//000_FulltestROC_p17//tbmParameters_C4294967295b.dat
[08:17:36.146] <TB3> INFO: readMaskFile: /home/mameinha/data/R417_Fulltest_p17_2015-10-07_10h17m_1444205846//000_FulltestROC_p17//defaultMaskFile.dat
[08:17:36.147] <TB3> INFO: readTrimFile: /home/mameinha/data/R417_Fulltest_p17_2015-10-07_10h17m_1444205846//000_FulltestROC_p17//trimParameters_C0.dat .. /home/mameinha/data/R417_Fulltest_p17_2015-10-07_10h17m_1444205846//000_FulltestROC_p17//trimParameters_C0.dat
[08:17:36.155] <TB3> INFO: clk: 2
[08:17:36.155] <TB3> INFO: ctr: 2
[08:17:36.155] <TB3> INFO: sda: 17
[08:17:36.155] <TB3> INFO: tin: 7
[08:17:36.155] <TB3> INFO: level: 15
[08:17:36.155] <TB3> INFO: deser160phase: 4
[08:17:36.155] <TB3> QUIET: Instanciating API for pxar v2.6.0+20~g1a7f656
[08:17:36.155] <TB3> INFO: Log level: INFO
[08:17:36.161] <TB3> INFO: Found DTB DTB_WRQ4OZ
[08:17:36.171] <TB3> QUIET: Connection to board DTB_WRQ4OZ opened.
[08:17:36.174] <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:
------------------------------------------------------
[08:17:36.177] <TB3> INFO: RPC call hashes of host and DTB match: 398089610
[08:17:37.341] <TB3> INFO: DUT info:
[08:17:37.341] <TB3> INFO: The DUT currently contains the following objects:
[08:17:37.341] <TB3> INFO: 0 TBM Cores (0 ON)
[08:17:37.341] <TB3> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[08:17:37.341] <TB3> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[08:17:37.755] <TB3> INFO: enter 'restricted' command line mode
[08:17:37.755] <TB3> INFO: enter test to run
[08:17:37.755] <TB3> INFO: test: Setup no parameter change
[08:17:37.755] <TB3> INFO: running: setup
[08:17:37.759] <TB3> INFO: PixTestSetup::doTest() ntrig = 10

[08:17:37.759] <TB3> INFO: PixTestSetup:: pg set to RES|TOK
[08:17:37.759] <TB3> INFO: 0 1 2 3 4 5 6 7
[08:17:40.803] <TB3> INFO: 0: 000 000 004 07c 7f0 f00 000 000
[08:17:43.818] <TB3> INFO: 1: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[08:17:46.832] <TB3> INFO: 2: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[08:17:49.847] <TB3> INFO: 3: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[08:17:52.862] <TB3> INFO: 4: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[08:17:55.877] <TB3> INFO: 5: 000 000 000 03c 3f8 f80 800 000
[08:17:58.891] <TB3> INFO: 6: 000 000 000 03c 3fc fc0 c00 000
[08:18:01.906] <TB3> INFO: 7: c00 000 000 03c 3fc fc0 c00 000
[08:18:04.920] <TB3> INFO: 8: 000 000 000 03c 3fc fc0 c00 000
[08:18:07.934] <TB3> INFO: 9: 000 000 000 03c 3fc fc0 c00 000
[08:18:10.948] <TB3> INFO: 10: c00 000 000 01c 1fc fc0 c00 000
[08:18:13.962] <TB3> INFO: 11: 000 000 000 01c 1fc fe0 e00 000
[08:18:16.976] <TB3> INFO: 12: 000 000 000 01c 1fc fe0 e00 000
[08:18:19.990] <TB3> INFO: 13: 000 000 000 01c 1fc fe0 e00 000
[08:18:23.005] <TB3> INFO: 14: 000 000 000 01c 1fc fe0 e00 000
[08:18:26.019] <TB3> INFO: 15: e00 000 000 00c 0fc fe0 e00 000
[08:18:29.034] <TB3> INFO: 16: 000 000 000 00c 0fc ff0 f00 000
[08:18:32.048] <TB3> INFO: 17: 000 000 000 00c 0fc ff0 f00 000
[08:18:56.758] <TB3> INFO: 18: 000 000 000 00c 0fc ff0 f00 000
[08:18:59.772] <TB3> INFO: 19: 000 000 000 00c 0fc ff0 f00 000
[08:19:00.181] <TB3> INFO: Found good delays at CLK = 2, DESER160 = 4
[08:19:00.183] <TB3> INFO: PixTestSetup:: Write Tb parameters to file.
[08:19:00.249] <TB3> INFO: write dtb parameters into /home/mameinha/data/R417_Fulltest_p17_2015-10-07_10h17m_1444205846//000_FulltestROC_p17//tbParameters.dat
[08:19:00.333] <TB3> INFO: PixTestSetup::doTest() done for.
[08:19:00.360] <TB3> INFO: enter test to run
[08:19:00.361] <TB3> INFO: test: Pretest no parameter change
[08:19:00.361] <TB3> INFO: running: pretest
[08:19:00.363] <TB3> INFO: ----------------------------------------------------------------------
[08:19:00.363] <TB3> INFO: PixTestPretest::programROC()
[08:19:00.363] <TB3> INFO: ----------------------------------------------------------------------
[08:19:03.365] <TB3> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[08:19:03.365] <TB3> INFO: IA differences per ROC: 19.3
[08:19:03.370] <TB3> INFO: enter test to run
[08:19:03.370] <TB3> INFO: test: Pretest no parameter change
[08:19:03.370] <TB3> INFO: running: pretest
[08:19:03.372] <TB3> INFO: ----------------------------------------------------------------------
[08:19:03.372] <TB3> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[08:19:03.372] <TB3> INFO: ----------------------------------------------------------------------
[08:19:03.982] <TB3> INFO: PixTestPretest::setVana() done, Module Ia 24.1 mA = 24.1 mA/ROC
[08:19:03.982] <TB3> INFO: i(loss) [mA/ROC]: 18.5
[08:19:03.985] <TB3> INFO: enter test to run
[08:19:03.985] <TB3> INFO: test: Pretest no parameter change
[08:19:03.985] <TB3> INFO: running: pretest
[08:19:03.987] <TB3> INFO: ----------------------------------------------------------------------
[08:19:03.987] <TB3> INFO: PixTestPretest::findWorkingPixel()
[08:19:03.987] <TB3> INFO: ----------------------------------------------------------------------
[08:19:03.997] <TB3> INFO: Expecting 231680 events.
[08:19:06.215] <TB3> INFO: 231680 events read in total (1831ms).
[08:19:06.217] <TB3> INFO: Test took 2230ms.
[08:19:06.595] <TB3> INFO: Found working pixel in all ROCs: col/row = 12/22
[08:19:06.602] <TB3> INFO: enter test to run
[08:19:06.602] <TB3> INFO: test: Pretest no parameter change
[08:19:06.602] <TB3> INFO: running: pretest
[08:19:06.604] <TB3> INFO: ----------------------------------------------------------------------
[08:19:06.604] <TB3> INFO: PixTestPretest::setVthrCompCalDel()
[08:19:06.604] <TB3> INFO: ----------------------------------------------------------------------
[08:19:06.613] <TB3> INFO: Expecting 231680 events.
[08:19:08.826] <TB3> INFO: 231680 events read in total (1826ms).
[08:19:08.830] <TB3> INFO: Test took 2226ms.
[08:19:09.204] <TB3> INFO: PixTestPretest::setVthrCompCalDel() done
[08:19:09.204] <TB3> INFO: CalDel: 143
[08:19:09.204] <TB3> INFO: VthrComp: 52
[08:19:09.208] <TB3> INFO: enter test to run
[08:19:09.208] <TB3> INFO: test: Pretest no parameter change
[08:19:09.208] <TB3> INFO: running: pretest
[08:19:09.296] <TB3> INFO: write dac parameters into /home/mameinha/data/R417_Fulltest_p17_2015-10-07_10h17m_1444205846//000_FulltestROC_p17//dacParameters_C0.dat
[08:19:09.300] <TB3> INFO: enter test to run
[08:19:09.300] <TB3> INFO: test: PixelAlive no parameter change
[08:19:09.300] <TB3> INFO: running: pixelalive
[08:19:09.301] <TB3> INFO: ######################################################################
[08:19:09.301] <TB3> INFO: PixTestAlive::doTest()
[08:19:09.301] <TB3> INFO: ######################################################################
[08:19:09.303] <TB3> INFO: ----------------------------------------------------------------------
[08:19:09.303] <TB3> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[08:19:09.303] <TB3> INFO: ----------------------------------------------------------------------
[08:19:09.322] <TB3> INFO: Expecting 41600 events.
[08:19:10.127] <TB3> INFO: 41600 events read in total (418ms).
[08:19:10.127] <TB3> INFO: Test took 824ms.
[08:19:10.128] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:19:10.513] <TB3> INFO: PixTestAlive::aliveTest() done
[08:19:10.513] <TB3> INFO: number of dead pixels (per ROC): 1
[08:19:10.515] <TB3> INFO: ----------------------------------------------------------------------
[08:19:10.515] <TB3> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[08:19:10.515] <TB3> INFO: ----------------------------------------------------------------------
[08:19:10.535] <TB3> INFO: Expecting 41600 events.
[08:19:11.280] <TB3> INFO: 41600 events read in total (358ms).
[08:19:11.280] <TB3> INFO: Test took 765ms.
[08:19:11.280] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:19:11.280] <TB3> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[08:19:11.671] <TB3> INFO: PixTestAlive::maskTest() done
[08:19:11.671] <TB3> INFO: number of mask-defect pixels (per ROC): 0
[08:19:11.673] <TB3> INFO: ----------------------------------------------------------------------
[08:19:11.673] <TB3> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[08:19:11.673] <TB3> INFO: ----------------------------------------------------------------------
[08:19:11.692] <TB3> INFO: Expecting 41600 events.
[08:19:12.495] <TB3> INFO: 41600 events read in total (415ms).
[08:19:12.496] <TB3> INFO: Test took 823ms.
[08:19:12.496] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:19:12.882] <TB3> INFO: PixTestAlive::addressDecodingTest() done
[08:19:12.882] <TB3> INFO: number of address-decoding pixels (per ROC): 0
[08:19:12.882] <TB3> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[08:19:12.882] <TB3> INFO: enter test to run
[08:19:12.882] <TB3> INFO: test: Scurves no parameter change
[08:19:12.882] <TB3> INFO: running: scurves
[08:19:12.884] <TB3> INFO: ######################################################################
[08:19:12.884] <TB3> INFO: PixTestScurves::doTest() ntrig = 50
[08:19:12.884] <TB3> INFO: ######################################################################
[08:19:12.884] <TB3> INFO: ----------------------------------------------------------------------
[08:19:12.884] <TB3> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[08:19:12.884] <TB3> INFO: ----------------------------------------------------------------------
[08:19:12.884] <TB3> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[08:19:12.985] <TB3> INFO: dacScan split into 1 runs with ntrig = 50
[08:19:12.985] <TB3> INFO: run 1 of 1
[08:19:13.004] <TB3> INFO: Expecting 41808000 events.
[08:21:44.823] <TB3> INFO: 21857750 events read in total (151431ms).
[08:24:06.079] <TB3> INFO: 41808000 events read in total (292687ms).
[08:24:06.139] <TB3> INFO: Test took 293154ms.
[08:24:06.159] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:24:07.751] <TB3> INFO: PixTestScurves::scurves() done
[08:24:07.751] <TB3> INFO: Vcal mean: 101.93
[08:24:07.751] <TB3> INFO: Vcal RMS: 6.71
[08:24:07.755] <TB3> INFO: enter test to run
[08:24:07.756] <TB3> INFO: test: Trim no parameter change
[08:24:07.756] <TB3> INFO: running: trim
[08:24:07.757] <TB3> INFO: ######################################################################
[08:24:07.757] <TB3> INFO: PixTestTrim::doTest()
[08:24:07.758] <TB3> INFO: ######################################################################
[08:24:07.759] <TB3> INFO: ----------------------------------------------------------------------
[08:24:07.759] <TB3> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[08:24:07.759] <TB3> INFO: ----------------------------------------------------------------------
[08:24:07.764] <TB3> INFO: ---> VthrComp thr map (minimal VthrComp)
[08:24:07.764] <TB3> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[08:24:07.773] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:24:07.773] <TB3> INFO: run 1 of 1
[08:24:07.793] <TB3> INFO: Expecting 6281600 events.
[08:24:56.641] <TB3> INFO: 6281600 events read in total (48440ms).
[08:24:56.665] <TB3> INFO: Test took 48893ms.
[08:24:56.673] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:24:57.823] <TB3> INFO: ROC 0 VthrComp = 101
[08:24:57.823] <TB3> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[08:24:57.823] <TB3> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[08:24:57.831] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:24:57.832] <TB3> INFO: run 1 of 1
[08:24:57.851] <TB3> INFO: Expecting 6281600 events.
[08:25:47.380] <TB3> INFO: 6281600 events read in total (49142ms).
[08:25:47.426] <TB3> INFO: Test took 49594ms.
[08:25:47.445] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:25:48.733] <TB3> INFO: roc 0 with ID = 0 has maximal Vcal 64.4121 for pixel 0/58 mean/min/max = 47.9204/31.267/64.5738
[08:25:48.742] <TB3> INFO: Expecting 514560 events.
[08:25:52.743] <TB3> INFO: 514560 events read in total (3614ms).
[08:25:52.747] <TB3> INFO: Test took 4014ms.
[08:25:53.136] <TB3> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[08:25:53.144] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:25:53.144] <TB3> INFO: run 1 of 1
[08:25:53.163] <TB3> INFO: Expecting 6281600 events.
[08:26:42.903] <TB3> INFO: 6281600 events read in total (49353ms).
[08:26:42.953] <TB3> INFO: Test took 49809ms.
[08:26:42.974] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:26:44.243] <TB3> INFO: ---> TrimStepCorr4 extremal thresholds: 7.725097 .. 52.139082
[08:26:44.248] <TB3> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 7 .. 62 (-1/-1) hits flags = 528 (plus default)
[08:26:44.256] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:26:44.256] <TB3> INFO: run 1 of 1
[08:26:44.275] <TB3> INFO: Expecting 2329600 events.
[08:27:02.310] <TB3> INFO: 2329600 events read in total (17648ms).
[08:27:02.321] <TB3> INFO: Test took 18065ms.
[08:27:02.326] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:27:03.176] <TB3> INFO: ---> TrimStepCorr2 extremal thresholds: 17.444065 .. 46.188417
[08:27:03.181] <TB3> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 7 .. 56 (-1/-1) hits flags = 528 (plus default)
[08:27:03.188] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:27:03.188] <TB3> INFO: run 1 of 1
[08:27:03.208] <TB3> INFO: Expecting 2080000 events.
[08:27:19.317] <TB3> INFO: 2080000 events read in total (15722ms).
[08:27:19.326] <TB3> INFO: Test took 16138ms.
[08:27:19.331] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:27:20.126] <TB3> INFO: ---> TrimStepCorr1a extremal thresholds: 22.397259 .. 41.767913
[08:27:20.131] <TB3> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 12 .. 51 (-1/-1) hits flags = 528 (plus default)
[08:27:20.139] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:27:20.139] <TB3> INFO: run 1 of 1
[08:27:20.158] <TB3> INFO: Expecting 1664000 events.
[08:27:33.139] <TB3> INFO: 1664000 events read in total (12594ms).
[08:27:33.146] <TB3> INFO: Test took 13007ms.
[08:27:33.150] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:27:33.909] <TB3> INFO: ---> TrimStepCorr1b extremal thresholds: 24.440788 .. 41.767913
[08:27:33.913] <TB3> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 14 .. 51 (-1/-1) hits flags = 528 (plus default)
[08:27:33.921] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:27:33.921] <TB3> INFO: run 1 of 1
[08:27:33.940] <TB3> INFO: Expecting 1580800 events.
[08:27:46.382] <TB3> INFO: 1580800 events read in total (12054ms).
[08:27:46.389] <TB3> INFO: Test took 12468ms.
[08:27:46.393] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:27:47.157] <TB3> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[08:27:47.157] <TB3> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[08:27:47.165] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:27:47.165] <TB3> INFO: run 1 of 1
[08:27:47.184] <TB3> INFO: Expecting 1705600 events.
[08:28:00.612] <TB3> INFO: 1705600 events read in total (13041ms).
[08:28:00.620] <TB3> INFO: Test took 13455ms.
[08:28:00.624] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:28:01.414] <TB3> INFO: write dac parameters into /home/mameinha/data/R417_Fulltest_p17_2015-10-07_10h17m_1444205846//000_FulltestROC_p17//dacParameters35_C0.dat
[08:28:01.501] <TB3> INFO: write trim parameters into /home/mameinha/data/R417_Fulltest_p17_2015-10-07_10h17m_1444205846//000_FulltestROC_p17//trimParameters35_C0.dat
[08:28:01.577] <TB3> INFO: PixTestTrim::trimTest() done
[08:28:01.577] <TB3> INFO: vtrim: 106
[08:28:01.577] <TB3> INFO: vthrcomp: 101
[08:28:01.577] <TB3> INFO: vcal mean: 34.97
[08:28:01.577] <TB3> INFO: vcal RMS: 1.01
[08:28:01.577] <TB3> INFO: bits mean: 8.90
[08:28:01.577] <TB3> INFO: bits RMS: 2.82
[08:28:01.581] <TB3> INFO: ----------------------------------------------------------------------
[08:28:01.581] <TB3> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[08:28:01.581] <TB3> INFO: ----------------------------------------------------------------------
[08:28:01.581] <TB3> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[08:28:01.588] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:28:01.589] <TB3> INFO: run 1 of 1
[08:28:01.608] <TB3> INFO: Expecting 8320000 events.
[08:29:03.658] <TB3> INFO: 8320000 events read in total (61663ms).
[08:29:03.697] <TB3> INFO: Test took 62108ms.
[08:29:03.711] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:29:05.179] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 176 (-1/-1) hits flags = 528 (plus default)
[08:29:05.187] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:29:05.187] <TB3> INFO: run 1 of 1
[08:29:05.206] <TB3> INFO: Expecting 7363200 events.
[08:29:59.876] <TB3> INFO: 7363200 events read in total (54283ms).
[08:29:59.908] <TB3> INFO: Test took 54721ms.
[08:29:59.920] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:30:01.281] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 163 (-1/-1) hits flags = 528 (plus default)
[08:30:01.289] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:30:01.289] <TB3> INFO: run 1 of 1
[08:30:01.308] <TB3> INFO: Expecting 6822400 events.
[08:30:51.746] <TB3> INFO: 6822400 events read in total (50051ms).
[08:30:51.773] <TB3> INFO: Test took 50484ms.
[08:30:51.783] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:30:53.048] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 161 (-1/-1) hits flags = 528 (plus default)
[08:30:53.056] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:30:53.056] <TB3> INFO: run 1 of 1
[08:30:53.075] <TB3> INFO: Expecting 6739200 events.
[08:31:42.942] <TB3> INFO: 6739200 events read in total (49480ms).
[08:31:42.968] <TB3> INFO: Test took 49912ms.
[08:31:42.978] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:31:44.247] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 162 (-1/-1) hits flags = 528 (plus default)
[08:31:44.255] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:31:44.255] <TB3> INFO: run 1 of 1
[08:31:44.274] <TB3> INFO: Expecting 6780800 events.
[08:32:34.430] <TB3> INFO: 6780800 events read in total (49769ms).
[08:32:34.461] <TB3> INFO: Test took 50206ms.
[08:32:34.470] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:32:35.746] <TB3> INFO: PixTestTrim::trimBitTest() done
[08:32:35.747] <TB3> INFO: PixTestTrim::doTest() done, duration: 507 seconds
[08:32:35.788] <TB3> INFO: enter test to run
[08:32:35.788] <TB3> INFO: test: PhOptimization no parameter change
[08:32:35.788] <TB3> INFO: running: phoptimization
[08:32:35.789] <TB3> INFO: ######################################################################
[08:32:35.789] <TB3> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[08:32:35.789] <TB3> INFO: ######################################################################
[08:32:35.809] <TB3> INFO: Expecting 41600 events.
[08:32:36.606] <TB3> INFO: 41600 events read in total (410ms).
[08:32:36.607] <TB3> INFO: Test took 817ms.
[08:32:36.607] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:32:36.998] <TB3> INFO: Expecting 41600 events.
[08:32:37.797] <TB3> INFO: 41600 events read in total (412ms).
[08:32:37.798] <TB3> INFO: Test took 1189ms.
[08:32:37.798] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:32:38.187] <TB3> INFO: Expecting 41600 events.
[08:32:38.987] <TB3> INFO: 41600 events read in total (413ms).
[08:32:38.987] <TB3> INFO: Test took 1188ms.
[08:32:38.988] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:32:39.376] <TB3> INFO: Expecting 2560 events.
[08:32:39.795] <TB3> INFO: 2560 events read in total (31ms).
[08:32:39.795] <TB3> INFO: Test took 807ms.
[08:32:40.191] <TB3> INFO: Expecting 655360 events.
[08:32:45.454] <TB3> INFO: 655360 events read in total (4876ms).
[08:32:45.463] <TB3> INFO: Test took 5667ms.
[08:32:45.755] <TB3> INFO: Expecting 655360 events.
[08:32:51.049] <TB3> INFO: 655360 events read in total (4908ms).
[08:32:51.060] <TB3> INFO: Test took 5583ms.
[08:32:51.079] <TB3> INFO: safety margin for low PH: adding 0, margin is now 20
[08:32:51.206] <TB3> INFO: write dac parameters into /home/mameinha/data/R417_Fulltest_p17_2015-10-07_10h17m_1444205846//000_FulltestROC_p17//dacParameters35_C0.dat
[08:32:51.350] <TB3> INFO: Expecting 41600 events.
[08:32:52.127] <TB3> INFO: 41600 events read in total (389ms).
[08:32:52.127] <TB3> INFO: Test took 862ms.
[08:32:52.516] <TB3> INFO: Expecting 41600 events.
[08:32:53.278] <TB3> INFO: 41600 events read in total (375ms).
[08:32:53.278] <TB3> INFO: Test took 1150ms.
[08:32:53.667] <TB3> INFO: Expecting 41600 events.
[08:32:54.429] <TB3> INFO: 41600 events read in total (375ms).
[08:32:54.429] <TB3> INFO: Test took 1150ms.
[08:32:54.818] <TB3> INFO: Expecting 2560 events.
[08:32:55.237] <TB3> INFO: 2560 events read in total (31ms).
[08:32:55.237] <TB3> INFO: Test took 807ms.
[08:32:55.632] <TB3> INFO: Expecting 2560 events.
[08:32:56.050] <TB3> INFO: 2560 events read in total (31ms).
[08:32:56.050] <TB3> INFO: Test took 813ms.
[08:32:56.458] <TB3> INFO: PixTestPhOptimization::doTest() done, duration: 20 seconds
[08:32:56.458] <TB3> INFO: PH scale (per ROC): 80
[08:32:56.458] <TB3> INFO: PH offset (per ROC): 177
[08:32:56.471] <TB3> INFO: enter test to run
[08:32:56.471] <TB3> INFO: test: GainPedestal no parameter change
[08:32:56.471] <TB3> INFO: running: gainpedestal
[08:32:56.473] <TB3> INFO: ######################################################################
[08:32:56.473] <TB3> INFO: PixTestGainPedestal::doTest() ntrig = 10
[08:32:56.473] <TB3> INFO: ######################################################################
[08:32:56.481] <TB3> INFO: scanning low vcal = 10
[08:32:56.500] <TB3> INFO: Expecting 41600 events.
[08:32:57.589] <TB3> INFO: 41600 events read in total (702ms).
[08:32:57.589] <TB3> INFO: Test took 1108ms.
[08:32:57.589] <TB3> INFO: scanning low vcal = 20
[08:32:57.984] <TB3> INFO: Expecting 41600 events.
[08:32:59.073] <TB3> INFO: 41600 events read in total (702ms).
[08:32:59.073] <TB3> INFO: Test took 1484ms.
[08:32:59.074] <TB3> INFO: scanning low vcal = 30
[08:32:59.468] <TB3> INFO: Expecting 41600 events.
[08:33:00.558] <TB3> INFO: 41600 events read in total (702ms).
[08:33:00.558] <TB3> INFO: Test took 1484ms.
[08:33:00.559] <TB3> INFO: scanning low vcal = 40
[08:33:00.953] <TB3> INFO: Expecting 41600 events.
[08:33:02.077] <TB3> INFO: 41600 events read in total (736ms).
[08:33:02.077] <TB3> INFO: Test took 1518ms.
[08:33:02.078] <TB3> INFO: scanning low vcal = 50
[08:33:02.467] <TB3> INFO: Expecting 41600 events.
[08:33:03.593] <TB3> INFO: 41600 events read in total (739ms).
[08:33:03.593] <TB3> INFO: Test took 1515ms.
[08:33:03.593] <TB3> INFO: scanning low vcal = 60
[08:33:03.982] <TB3> INFO: Expecting 41600 events.
[08:33:05.108] <TB3> INFO: 41600 events read in total (739ms).
[08:33:05.108] <TB3> INFO: Test took 1515ms.
[08:33:05.109] <TB3> INFO: scanning low vcal = 70
[08:33:05.498] <TB3> INFO: Expecting 41600 events.
[08:33:06.623] <TB3> INFO: 41600 events read in total (738ms).
[08:33:06.624] <TB3> INFO: Test took 1515ms.
[08:33:06.624] <TB3> INFO: scanning low vcal = 80
[08:33:07.013] <TB3> INFO: Expecting 41600 events.
[08:33:08.147] <TB3> INFO: 41600 events read in total (747ms).
[08:33:08.147] <TB3> INFO: Test took 1523ms.
[08:33:08.148] <TB3> INFO: scanning low vcal = 90
[08:33:08.537] <TB3> INFO: Expecting 41600 events.
[08:33:09.662] <TB3> INFO: 41600 events read in total (738ms).
[08:33:09.662] <TB3> INFO: Test took 1514ms.
[08:33:09.663] <TB3> INFO: scanning low vcal = 100
[08:33:10.051] <TB3> INFO: Expecting 41600 events.
[08:33:11.185] <TB3> INFO: 41600 events read in total (747ms).
[08:33:11.186] <TB3> INFO: Test took 1523ms.
[08:33:11.186] <TB3> INFO: scanning low vcal = 110
[08:33:11.575] <TB3> INFO: Expecting 41600 events.
[08:33:12.701] <TB3> INFO: 41600 events read in total (739ms).
[08:33:12.701] <TB3> INFO: Test took 1515ms.
[08:33:12.702] <TB3> INFO: scanning low vcal = 120
[08:33:13.090] <TB3> INFO: Expecting 41600 events.
[08:33:14.216] <TB3> INFO: 41600 events read in total (738ms).
[08:33:14.216] <TB3> INFO: Test took 1514ms.
[08:33:14.217] <TB3> INFO: scanning low vcal = 130
[08:33:14.605] <TB3> INFO: Expecting 41600 events.
[08:33:15.730] <TB3> INFO: 41600 events read in total (737ms).
[08:33:15.731] <TB3> INFO: Test took 1514ms.
[08:33:15.731] <TB3> INFO: scanning low vcal = 140
[08:33:16.120] <TB3> INFO: Expecting 41600 events.
[08:33:17.245] <TB3> INFO: 41600 events read in total (738ms).
[08:33:17.246] <TB3> INFO: Test took 1515ms.
[08:33:17.246] <TB3> INFO: scanning low vcal = 150
[08:33:17.635] <TB3> INFO: Expecting 41600 events.
[08:33:18.761] <TB3> INFO: 41600 events read in total (739ms).
[08:33:18.762] <TB3> INFO: Test took 1516ms.
[08:33:18.762] <TB3> INFO: scanning low vcal = 160
[08:33:19.151] <TB3> INFO: Expecting 41600 events.
[08:33:20.276] <TB3> INFO: 41600 events read in total (738ms).
[08:33:20.277] <TB3> INFO: Test took 1515ms.
[08:33:20.277] <TB3> INFO: scanning low vcal = 170
[08:33:20.666] <TB3> INFO: Expecting 41600 events.
[08:33:21.792] <TB3> INFO: 41600 events read in total (739ms).
[08:33:21.792] <TB3> INFO: Test took 1515ms.
[08:33:21.793] <TB3> INFO: scanning low vcal = 180
[08:33:22.182] <TB3> INFO: Expecting 41600 events.
[08:33:23.307] <TB3> INFO: 41600 events read in total (738ms).
[08:33:23.308] <TB3> INFO: Test took 1515ms.
[08:33:23.308] <TB3> INFO: scanning low vcal = 190
[08:33:23.697] <TB3> INFO: Expecting 41600 events.
[08:33:24.837] <TB3> INFO: 41600 events read in total (753ms).
[08:33:24.837] <TB3> INFO: Test took 1529ms.
[08:33:24.838] <TB3> INFO: scanning low vcal = 200
[08:33:25.227] <TB3> INFO: Expecting 41600 events.
[08:33:26.352] <TB3> INFO: 41600 events read in total (738ms).
[08:33:26.353] <TB3> INFO: Test took 1515ms.
[08:33:26.353] <TB3> INFO: scanning low vcal = 210
[08:33:26.742] <TB3> INFO: Expecting 41600 events.
[08:33:27.881] <TB3> INFO: 41600 events read in total (752ms).
[08:33:27.882] <TB3> INFO: Test took 1529ms.
[08:33:27.882] <TB3> INFO: scanning low vcal = 220
[08:33:28.271] <TB3> INFO: Expecting 41600 events.
[08:33:29.396] <TB3> INFO: 41600 events read in total (738ms).
[08:33:29.397] <TB3> INFO: Test took 1515ms.
[08:33:29.397] <TB3> INFO: scanning low vcal = 230
[08:33:29.786] <TB3> INFO: Expecting 41600 events.
[08:33:30.912] <TB3> INFO: 41600 events read in total (739ms).
[08:33:30.912] <TB3> INFO: Test took 1515ms.
[08:33:30.913] <TB3> INFO: scanning low vcal = 240
[08:33:31.301] <TB3> INFO: Expecting 41600 events.
[08:33:32.427] <TB3> INFO: 41600 events read in total (738ms).
[08:33:32.428] <TB3> INFO: Test took 1515ms.
[08:33:32.428] <TB3> INFO: scanning low vcal = 250
[08:33:32.817] <TB3> INFO: Expecting 41600 events.
[08:33:33.943] <TB3> INFO: 41600 events read in total (739ms).
[08:33:33.943] <TB3> INFO: Test took 1515ms.
[08:33:33.944] <TB3> INFO: scanning high vcal = 30 (= 210 in low range)
[08:33:34.332] <TB3> INFO: Expecting 41600 events.
[08:33:35.458] <TB3> INFO: 41600 events read in total (739ms).
[08:33:35.458] <TB3> INFO: Test took 1514ms.
[08:33:35.459] <TB3> INFO: scanning high vcal = 50 (= 350 in low range)
[08:33:35.848] <TB3> INFO: Expecting 41600 events.
[08:33:36.974] <TB3> INFO: 41600 events read in total (739ms).
[08:33:36.974] <TB3> INFO: Test took 1515ms.
[08:33:36.975] <TB3> INFO: scanning high vcal = 70 (= 490 in low range)
[08:33:37.363] <TB3> INFO: Expecting 41600 events.
[08:33:38.490] <TB3> INFO: 41600 events read in total (739ms).
[08:33:38.490] <TB3> INFO: Test took 1515ms.
[08:33:38.491] <TB3> INFO: scanning high vcal = 90 (= 630 in low range)
[08:33:38.879] <TB3> INFO: Expecting 41600 events.
[08:33:40.019] <TB3> INFO: 41600 events read in total (752ms).
[08:33:40.019] <TB3> INFO: Test took 1528ms.
[08:33:40.020] <TB3> INFO: scanning high vcal = 200 (= 1400 in low range)
[08:33:40.408] <TB3> INFO: Expecting 41600 events.
[08:33:41.534] <TB3> INFO: 41600 events read in total (738ms).
[08:33:41.535] <TB3> INFO: Test took 1515ms.
[08:33:41.919] <TB3> INFO: PixTestGainPedestal::measure() done
[08:33:43.907] <TB3> INFO: PixTestGainPedestal::fit() done
[08:33:43.907] <TB3> INFO: non-linearity mean: 0.961
[08:33:43.907] <TB3> INFO: non-linearity RMS: 0.005
[08:33:43.907] <TB3> INFO: write gain/ped parameters into /home/mameinha/data/R417_Fulltest_p17_2015-10-07_10h17m_1444205846//000_FulltestROC_p17//phCalibrationFitErr35_C0.dat
[08:33:44.147] <TB3> INFO: PixTestGainPedestal::doTest() done, duration: 47 seconds
[08:33:44.148] <TB3> INFO: enter test to run
[08:33:44.148] <TB3> INFO: test: Readback no parameter change
[08:33:44.148] <TB3> INFO: running: readback
[08:33:44.148] <TB3> INFO: readReadbackCal: /home/mameinha/data/R417_Fulltest_p17_2015-10-07_10h17m_1444205846//000_FulltestROC_p17//readbackCal_C0.dat .. /home/mameinha/data/R417_Fulltest_p17_2015-10-07_10h17m_1444205846//000_FulltestROC_p17//readbackCal_C0.dat
[08:33:44.166] <TB3> INFO: ######################################################################
[08:33:44.166] <TB3> INFO: PixTestReadback::doTest()
[08:33:44.166] <TB3> INFO: ######################################################################
[08:33:44.167] <TB3> INFO: PixTestReadback::RES sent once
[08:33:56.786] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R417_Fulltest_p17_2015-10-07_10h17m_1444205846//000_FulltestROC_p17//readbackCal_C0.dat
[08:33:56.798] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[08:33:56.798] <TB3> INFO: PixTestReadback::RES sent once
[08:34:07.903] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R417_Fulltest_p17_2015-10-07_10h17m_1444205846//000_FulltestROC_p17//readbackCal_C0.dat
[08:34:07.913] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[08:34:07.913] <TB3> INFO: PixTestReadback::RES sent once
[08:34:16.248] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[08:34:16.249] <TB3> INFO: Vbg will be calibrated using Vd calibration
[08:34:16.249] <TB3> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 160.4calibrated Vbg = 1.21639 :::*/*/*/*/
[08:34:16.625] <TB3> INFO: PixTestReadback::RES sent once
[08:34:25.481] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R417_Fulltest_p17_2015-10-07_10h17m_1444205846//000_FulltestROC_p17//readbackCal_C0.dat
[08:34:25.489] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[08:34:25.490] <TB3> INFO: PixTestReadback::doTest() done
[08:34:25.523] <TB3> INFO: enter test to run
[08:34:25.523] <TB3> INFO: test: no parameter change
[08:34:25.564] <TB3> QUIET: Connection to board 71 closed.
[08:34:26.180] <TB3> INFO: pXar: this is the end, my friend