[08:34:54.746] <TB3> INFO: *** Welcome to pxar ***
[08:34:54.746] <TB3> INFO: *** Today: 2015/10/06
[08:34:55.045] <TB3> INFO: *** Version: 9da6
[08:34:55.045] <TB3> INFO: readRocDacs: /home/mameinha/data/R419_Fulltest_p17_2015-10-06_10h34m_1444120483//000_FulltestROC_p17//dacParameters_C0.dat .. /home/mameinha/data/R419_Fulltest_p17_2015-10-06_10h34m_1444120483//000_FulltestROC_p17//dacParameters_C0.dat
[08:34:55.045] <TB3> INFO: readTbmDacs: /home/mameinha/data/R419_Fulltest_p17_2015-10-06_10h34m_1444120483//000_FulltestROC_p17//tbmParameters_C0a.dat .. /home/mameinha/data/R419_Fulltest_p17_2015-10-06_10h34m_1444120483//000_FulltestROC_p17//tbmParameters_C4294967295b.dat
[08:34:55.045] <TB3> INFO: readMaskFile: /home/mameinha/data/R419_Fulltest_p17_2015-10-06_10h34m_1444120483//000_FulltestROC_p17//defaultMaskFile.dat
[08:34:55.046] <TB3> INFO: readTrimFile: /home/mameinha/data/R419_Fulltest_p17_2015-10-06_10h34m_1444120483//000_FulltestROC_p17//trimParameters_C0.dat .. /home/mameinha/data/R419_Fulltest_p17_2015-10-06_10h34m_1444120483//000_FulltestROC_p17//trimParameters_C0.dat
[08:34:55.053] <TB3> INFO: clk: 4
[08:34:55.053] <TB3> INFO: ctr: 4
[08:34:55.053] <TB3> INFO: sda: 19
[08:34:55.053] <TB3> INFO: tin: 9
[08:34:55.053] <TB3> INFO: level: 15
[08:34:55.053] <TB3> INFO: deser160phase: 4
[08:34:55.053] <TB3> QUIET: Instanciating API for pxar v2.6.0+20~g1a7f656
[08:34:55.053] <TB3> INFO: Log level: INFO
[08:34:55.075] <TB3> QUIET: Connection to board DTB_WRQ4OZ opened.
[08:34:55.078] <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:34:55.080] <TB3> INFO: RPC call hashes of host and DTB match: 398089610
[08:34:56.242] <TB3> INFO: DUT info:
[08:34:56.242] <TB3> INFO: The DUT currently contains the following objects:
[08:34:56.242] <TB3> INFO: 0 TBM Cores (0 ON)
[08:34:56.242] <TB3> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[08:34:56.242] <TB3> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[08:34:56.644] <TB3> INFO: enter 'restricted' command line mode
[08:34:56.644] <TB3> INFO: enter test to run
[08:34:56.644] <TB3> INFO: test: Setup no parameter change
[08:34:56.644] <TB3> INFO: running: setup
[08:34:56.648] <TB3> INFO: PixTestSetup::doTest() ntrig = 10

[08:34:56.649] <TB3> INFO: PixTestSetup:: pg set to RES|TOK
[08:34:56.649] <TB3> INFO: 0 1 2 3 4 5 6 7
[08:34:59.690] <TB3> INFO: 0: 000 000 004 07c 7f0 f00 000 000
[08:35:02.703] <TB3> INFO: 1: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[08:35:05.716] <TB3> INFO: 2: 000 000 004 07c <7f8>[*] f80 800 000
[08:35:08.728] <TB3> INFO: 3: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[08:35:11.742] <TB3> INFO: 4: 800 000 000 03c 3f8 f80 800 000
[08:35:14.755] <TB3> INFO: 5: 000 000 000 03c 3fc fc0 c00 000
[08:35:17.767] <TB3> INFO: 6: 000 000 000 03c 3fc fc0 c00 000
[08:35:20.780] <TB3> INFO: 7: c00 000 000 03c 3fc fc0 c00 000
[08:35:23.792] <TB3> INFO: 8: 000 000 000 03c 3fc fc0 c00 000
[08:35:26.804] <TB3> INFO: 9: 000 000 000 03c 3fc fc0 c00 000
[08:35:29.816] <TB3> INFO: 10: 000 000 000 01c 1fc fc0 c00 000
[08:35:32.828] <TB3> INFO: 11: 000 000 000 01c 1fc fe0 e00 000
[08:35:35.841] <TB3> INFO: 12: 000 000 000 01c 1fc fe0 e00 000
[08:35:38.853] <TB3> INFO: 13: e00 000 000 01c 1fc fe0 e00 000
[08:35:41.865] <TB3> INFO: 14: 000 000 000 00c 0fc fe0 e00 000
[08:35:44.878] <TB3> INFO: 15: 000 000 000 00c 0fc ff0 f00 000
[08:35:47.890] <TB3> INFO: 16: 000 000 000 00c 0fc ff0 f00 000
[08:35:50.903] <TB3> INFO: 17: 000 000 000 00c 0fc ff0 f00 000
[08:35:53.916] <TB3> INFO: 18: 000 000 000 00c 0fc ff0 f00 000
[08:35:56.929] <TB3> INFO: 19: 000 000 000 00c 0fc ff0 f00 000
[08:35:57.349] <TB3> INFO: Found good delays at CLK = 2, DESER160 = 4
[08:35:57.350] <TB3> INFO: PixTestSetup:: Write Tb parameters to file.
[08:35:57.355] <TB3> INFO: write dtb parameters into /home/mameinha/data/R419_Fulltest_p17_2015-10-06_10h34m_1444120483//000_FulltestROC_p17//tbParameters.dat
[08:35:57.357] <TB3> INFO: PixTestSetup::doTest() done for.
[08:35:57.382] <TB3> INFO: enter test to run
[08:35:57.382] <TB3> INFO: test: Pretest no parameter change
[08:35:57.382] <TB3> INFO: running: pretest
[08:35:57.384] <TB3> INFO: ----------------------------------------------------------------------
[08:35:57.384] <TB3> INFO: PixTestPretest::programROC()
[08:35:57.384] <TB3> INFO: ----------------------------------------------------------------------
[08:36:00.386] <TB3> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[08:36:00.386] <TB3> INFO: IA differences per ROC: 17.7
[08:36:00.390] <TB3> INFO: enter test to run
[08:36:00.390] <TB3> INFO: test: Pretest no parameter change
[08:36:00.390] <TB3> INFO: running: pretest
[08:36:00.391] <TB3> INFO: ----------------------------------------------------------------------
[08:36:00.391] <TB3> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[08:36:00.391] <TB3> INFO: ----------------------------------------------------------------------
[08:36:01.202] <TB3> INFO: PixTestPretest::setVana() done, Module Ia 23.3 mA = 23.3 mA/ROC
[08:36:01.202] <TB3> INFO: i(loss) [mA/ROC]: 18.5
[08:36:01.204] <TB3> INFO: enter test to run
[08:36:01.204] <TB3> INFO: test: Pretest no parameter change
[08:36:01.204] <TB3> INFO: running: pretest
[08:36:01.205] <TB3> INFO: ----------------------------------------------------------------------
[08:36:01.205] <TB3> INFO: PixTestPretest::findWorkingPixel()
[08:36:01.205] <TB3> INFO: ----------------------------------------------------------------------
[08:36:01.215] <TB3> INFO: Expecting 231680 events.
[08:36:03.427] <TB3> INFO: 231680 events read in total (1825ms).
[08:36:03.429] <TB3> INFO: Test took 2224ms.
[08:36:03.808] <TB3> INFO: Found working pixel in all ROCs: col/row = 12/22
[08:36:03.813] <TB3> INFO: enter test to run
[08:36:03.813] <TB3> INFO: test: Pretest no parameter change
[08:36:03.813] <TB3> INFO: running: pretest
[08:36:03.815] <TB3> INFO: ----------------------------------------------------------------------
[08:36:03.815] <TB3> INFO: PixTestPretest::setVthrCompCalDel()
[08:36:03.815] <TB3> INFO: ----------------------------------------------------------------------
[08:36:03.824] <TB3> INFO: Expecting 231680 events.
[08:36:06.023] <TB3> INFO: 231680 events read in total (1812ms).
[08:36:06.026] <TB3> INFO: Test took 2211ms.
[08:36:06.404] <TB3> INFO: PixTestPretest::setVthrCompCalDel() done
[08:36:06.405] <TB3> INFO: CalDel: 142
[08:36:06.405] <TB3> INFO: VthrComp: 51
[08:36:06.408] <TB3> INFO: enter test to run
[08:36:06.408] <TB3> INFO: test: Pretest no parameter change
[08:36:06.408] <TB3> INFO: running: pretest
[08:36:06.429] <TB3> INFO: write dac parameters into /home/mameinha/data/R419_Fulltest_p17_2015-10-06_10h34m_1444120483//000_FulltestROC_p17//dacParameters_C0.dat
[08:36:06.431] <TB3> INFO: enter test to run
[08:36:06.431] <TB3> INFO: test: PixelAlive no parameter change
[08:36:06.431] <TB3> INFO: running: pixelalive
[08:36:06.433] <TB3> INFO: ######################################################################
[08:36:06.433] <TB3> INFO: PixTestAlive::doTest()
[08:36:06.433] <TB3> INFO: ######################################################################
[08:36:06.434] <TB3> INFO: ----------------------------------------------------------------------
[08:36:06.434] <TB3> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[08:36:06.434] <TB3> INFO: ----------------------------------------------------------------------
[08:36:06.454] <TB3> INFO: Expecting 41600 events.
[08:36:07.250] <TB3> INFO: 41600 events read in total (409ms).
[08:36:07.251] <TB3> INFO: Test took 816ms.
[08:36:07.251] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:36:07.636] <TB3> INFO: PixTestAlive::aliveTest() done
[08:36:07.636] <TB3> INFO: number of dead pixels (per ROC): 0
[08:36:07.638] <TB3> INFO: ----------------------------------------------------------------------
[08:36:07.638] <TB3> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[08:36:07.638] <TB3> INFO: ----------------------------------------------------------------------
[08:36:07.657] <TB3> INFO: Expecting 41600 events.
[08:36:08.399] <TB3> INFO: 41600 events read in total (355ms).
[08:36:08.399] <TB3> INFO: Test took 761ms.
[08:36:08.399] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:36:08.399] <TB3> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[08:36:08.789] <TB3> INFO: PixTestAlive::maskTest() done
[08:36:08.789] <TB3> INFO: number of mask-defect pixels (per ROC): 0
[08:36:08.790] <TB3> INFO: ----------------------------------------------------------------------
[08:36:08.790] <TB3> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[08:36:08.790] <TB3> INFO: ----------------------------------------------------------------------
[08:36:08.809] <TB3> INFO: Expecting 41600 events.
[08:36:09.605] <TB3> INFO: 41600 events read in total (409ms).
[08:36:09.606] <TB3> INFO: Test took 816ms.
[08:36:09.606] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:36:09.992] <TB3> INFO: PixTestAlive::addressDecodingTest() done
[08:36:09.992] <TB3> INFO: number of address-decoding pixels (per ROC): 0
[08:36:09.992] <TB3> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[08:36:09.992] <TB3> INFO: enter test to run
[08:36:09.992] <TB3> INFO: test: Scurves no parameter change
[08:36:09.992] <TB3> INFO: running: scurves
[08:36:09.994] <TB3> INFO: ######################################################################
[08:36:09.994] <TB3> INFO: PixTestScurves::doTest() ntrig = 50
[08:36:09.994] <TB3> INFO: ######################################################################
[08:36:09.994] <TB3> INFO: ----------------------------------------------------------------------
[08:36:09.994] <TB3> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[08:36:09.994] <TB3> INFO: ----------------------------------------------------------------------
[08:36:09.994] <TB3> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[08:36:10.004] <TB3> INFO: dacScan split into 1 runs with ntrig = 50
[08:36:10.004] <TB3> INFO: run 1 of 1
[08:36:10.023] <TB3> INFO: Expecting 41808000 events.
[08:38:32.874] <TB3> INFO: 20518950 events read in total (142464ms).
[08:40:52.313] <TB3> INFO: 40795600 events read in total (281903ms).
[08:40:59.286] <TB3> INFO: 41808000 events read in total (288876ms).
[08:40:59.313] <TB3> INFO: Test took 289309ms.
[08:40:59.333] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:41:00.845] <TB3> INFO: PixTestScurves::scurves() done
[08:41:00.845] <TB3> INFO: Vcal mean: 91.25
[08:41:00.845] <TB3> INFO: Vcal RMS: 4.83
[08:41:00.849] <TB3> INFO: enter test to run
[08:41:00.850] <TB3> INFO: test: Trim no parameter change
[08:41:00.850] <TB3> INFO: running: trim
[08:41:00.852] <TB3> INFO: ######################################################################
[08:41:00.852] <TB3> INFO: PixTestTrim::doTest()
[08:41:00.852] <TB3> INFO: ######################################################################
[08:41:00.853] <TB3> INFO: ----------------------------------------------------------------------
[08:41:00.853] <TB3> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[08:41:00.853] <TB3> INFO: ----------------------------------------------------------------------
[08:41:00.859] <TB3> INFO: ---> VthrComp thr map (minimal VthrComp)
[08:41:00.859] <TB3> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[08:41:00.867] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:41:00.867] <TB3> INFO: run 1 of 1
[08:41:00.888] <TB3> INFO: Expecting 6281600 events.
[08:41:46.158] <TB3> INFO: 6281600 events read in total (44883ms).
[08:41:46.175] <TB3> INFO: Test took 45308ms.
[08:41:46.183] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:41:47.306] <TB3> INFO: ROC 0 VthrComp = 98
[08:41:47.306] <TB3> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[08:41:47.306] <TB3> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[08:41:47.314] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:41:47.314] <TB3> INFO: run 1 of 1
[08:41:47.333] <TB3> INFO: Expecting 6281600 events.
[08:42:36.102] <TB3> INFO: 6281600 events read in total (48382ms).
[08:42:36.142] <TB3> INFO: Test took 48828ms.
[08:42:36.162] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:42:37.418] <TB3> INFO: roc 0 with ID = 0 has maximal Vcal 56.2921 for pixel 47/79 mean/min/max = 44.043/31.6666/56.4195
[08:42:37.427] <TB3> INFO: Expecting 514560 events.
[08:42:41.387] <TB3> INFO: 514560 events read in total (3573ms).
[08:42:41.391] <TB3> INFO: Test took 3972ms.
[08:42:41.785] <TB3> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[08:42:41.792] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:42:41.792] <TB3> INFO: run 1 of 1
[08:42:41.811] <TB3> INFO: Expecting 6281600 events.
[08:43:30.629] <TB3> INFO: 6281600 events read in total (48431ms).
[08:43:30.670] <TB3> INFO: Test took 48878ms.
[08:43:30.690] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:43:31.905] <TB3> INFO: ---> TrimStepCorr4 extremal thresholds: 12.640092 .. 46.999843
[08:43:31.910] <TB3> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 2 .. 56 (-1/-1) hits flags = 528 (plus default)
[08:43:31.917] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:43:31.917] <TB3> INFO: run 1 of 1
[08:43:31.936] <TB3> INFO: Expecting 2288000 events.
[08:43:49.309] <TB3> INFO: 2288000 events read in total (16986ms).
[08:43:49.319] <TB3> INFO: Test took 17402ms.
[08:43:49.323] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:43:50.115] <TB3> INFO: ---> TrimStepCorr2 extremal thresholds: 20.472651 .. 41.333627
[08:43:50.119] <TB3> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 10 .. 51 (-1/-1) hits flags = 528 (plus default)
[08:43:50.127] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:43:50.127] <TB3> INFO: run 1 of 1
[08:43:50.146] <TB3> INFO: Expecting 1747200 events.
[08:44:03.596] <TB3> INFO: 1747200 events read in total (13063ms).
[08:44:03.603] <TB3> INFO: Test took 13476ms.
[08:44:03.607] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:44:04.363] <TB3> INFO: ---> TrimStepCorr1a extremal thresholds: 25.454434 .. 37.453143
[08:44:04.367] <TB3> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 15 .. 47 (-1/-1) hits flags = 528 (plus default)
[08:44:04.375] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:44:04.375] <TB3> INFO: run 1 of 1
[08:44:04.394] <TB3> INFO: Expecting 1372800 events.
[08:44:15.134] <TB3> INFO: 1372800 events read in total (10353ms).
[08:44:15.140] <TB3> INFO: Test took 10765ms.
[08:44:15.143] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:44:15.870] <TB3> INFO: ---> TrimStepCorr1b extremal thresholds: 26.562638 .. 36.821606
[08:44:15.875] <TB3> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 16 .. 46 (-1/-1) hits flags = 528 (plus default)
[08:44:15.882] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:44:15.882] <TB3> INFO: run 1 of 1
[08:44:15.902] <TB3> INFO: Expecting 1289600 events.
[08:44:26.025] <TB3> INFO: 1289600 events read in total (9736ms).
[08:44:26.031] <TB3> INFO: Test took 10149ms.
[08:44:26.034] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:44:26.744] <TB3> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[08:44:26.744] <TB3> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[08:44:26.751] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:44:26.751] <TB3> INFO: run 1 of 1
[08:44:26.771] <TB3> INFO: Expecting 1705600 events.
[08:44:40.097] <TB3> INFO: 1705600 events read in total (12940ms).
[08:44:40.106] <TB3> INFO: Test took 13355ms.
[08:44:40.110] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:44:40.899] <TB3> INFO: write dac parameters into /home/mameinha/data/R419_Fulltest_p17_2015-10-06_10h34m_1444120483//000_FulltestROC_p17//dacParameters35_C0.dat
[08:44:40.903] <TB3> INFO: write trim parameters into /home/mameinha/data/R419_Fulltest_p17_2015-10-06_10h34m_1444120483//000_FulltestROC_p17//trimParameters35_C0.dat
[08:44:40.914] <TB3> INFO: PixTestTrim::trimTest() done
[08:44:40.914] <TB3> INFO: vtrim: 88
[08:44:40.914] <TB3> INFO: vthrcomp: 98
[08:44:40.914] <TB3> INFO: vcal mean: 34.95
[08:44:40.914] <TB3> INFO: vcal RMS: 0.75
[08:44:40.914] <TB3> INFO: bits mean: 9.94
[08:44:40.914] <TB3> INFO: bits RMS: 2.69
[08:44:40.917] <TB3> INFO: ----------------------------------------------------------------------
[08:44:40.917] <TB3> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[08:44:40.917] <TB3> INFO: ----------------------------------------------------------------------
[08:44:40.918] <TB3> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[08:44:40.925] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:44:40.925] <TB3> INFO: run 1 of 1
[08:44:40.945] <TB3> INFO: Expecting 8320000 events.
[08:45:42.336] <TB3> INFO: 8320000 events read in total (61004ms).
[08:45:42.373] <TB3> INFO: Test took 61448ms.
[08:45:42.389] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:45:43.839] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 153 (-1/-1) hits flags = 528 (plus default)
[08:45:43.847] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:45:43.847] <TB3> INFO: run 1 of 1
[08:45:43.866] <TB3> INFO: Expecting 6406400 events.
[08:46:30.715] <TB3> INFO: 6406400 events read in total (46462ms).
[08:46:30.735] <TB3> INFO: Test took 46888ms.
[08:46:30.745] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:46:31.968] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 141 (-1/-1) hits flags = 528 (plus default)
[08:46:31.976] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:46:31.976] <TB3> INFO: run 1 of 1
[08:46:31.995] <TB3> INFO: Expecting 5907200 events.
[08:47:14.965] <TB3> INFO: 5907200 events read in total (42583ms).
[08:47:14.981] <TB3> INFO: Test took 43005ms.
[08:47:14.989] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:47:16.144] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 140 (-1/-1) hits flags = 528 (plus default)
[08:47:16.151] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:47:16.151] <TB3> INFO: run 1 of 1
[08:47:16.171] <TB3> INFO: Expecting 5865600 events.
[08:47:58.871] <TB3> INFO: 5865600 events read in total (42313ms).
[08:47:58.888] <TB3> INFO: Test took 42737ms.
[08:47:58.895] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:48:00.035] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 141 (-1/-1) hits flags = 528 (plus default)
[08:48:00.042] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[08:48:00.042] <TB3> INFO: run 1 of 1
[08:48:00.061] <TB3> INFO: Expecting 5907200 events.
[08:48:43.067] <TB3> INFO: 5907200 events read in total (42619ms).
[08:48:43.084] <TB3> INFO: Test took 43042ms.
[08:48:43.092] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:48:44.240] <TB3> INFO: PixTestTrim::trimBitTest() done
[08:48:44.242] <TB3> INFO: PixTestTrim::doTest() done, duration: 463 seconds
[08:48:44.283] <TB3> INFO: enter test to run
[08:48:44.283] <TB3> INFO: test: PhOptimization no parameter change
[08:48:44.283] <TB3> INFO: running: phoptimization
[08:48:44.283] <TB3> INFO: ######################################################################
[08:48:44.283] <TB3> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[08:48:44.283] <TB3> INFO: ######################################################################
[08:48:44.303] <TB3> INFO: Expecting 41600 events.
[08:48:45.098] <TB3> INFO: 41600 events read in total (408ms).
[08:48:45.099] <TB3> INFO: Test took 815ms.
[08:48:45.099] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:48:45.490] <TB3> INFO: Expecting 41600 events.
[08:48:46.286] <TB3> INFO: 41600 events read in total (409ms).
[08:48:46.287] <TB3> INFO: Test took 1187ms.
[08:48:46.287] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:48:46.676] <TB3> INFO: Expecting 41600 events.
[08:48:47.472] <TB3> INFO: 41600 events read in total (409ms).
[08:48:47.473] <TB3> INFO: Test took 1185ms.
[08:48:47.473] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[08:48:47.862] <TB3> INFO: Expecting 2560 events.
[08:48:48.280] <TB3> INFO: 2560 events read in total (31ms).
[08:48:48.280] <TB3> INFO: Test took 806ms.
[08:48:48.675] <TB3> INFO: Expecting 655360 events.
[08:48:53.909] <TB3> INFO: 655360 events read in total (4847ms).
[08:48:53.918] <TB3> INFO: Test took 5638ms.
[08:48:54.210] <TB3> INFO: Expecting 655360 events.
[08:48:59.446] <TB3> INFO: 655360 events read in total (4850ms).
[08:48:59.454] <TB3> INFO: Test took 5523ms.
[08:48:59.473] <TB3> INFO: safety margin for low PH: adding 0, margin is now 20
[08:48:59.491] <TB3> INFO: write dac parameters into /home/mameinha/data/R419_Fulltest_p17_2015-10-06_10h34m_1444120483//000_FulltestROC_p17//dacParameters35_C0.dat
[08:48:59.748] <TB3> INFO: Expecting 41600 events.
[08:49:00.510] <TB3> INFO: 41600 events read in total (375ms).
[08:49:00.510] <TB3> INFO: Test took 1016ms.
[08:49:00.900] <TB3> INFO: Expecting 41600 events.
[08:49:01.661] <TB3> INFO: 41600 events read in total (374ms).
[08:49:01.661] <TB3> INFO: Test took 1150ms.
[08:49:02.051] <TB3> INFO: Expecting 41600 events.
[08:49:02.812] <TB3> INFO: 41600 events read in total (375ms).
[08:49:02.812] <TB3> INFO: Test took 1150ms.
[08:49:03.202] <TB3> INFO: Expecting 2560 events.
[08:49:03.619] <TB3> INFO: 2560 events read in total (30ms).
[08:49:03.620] <TB3> INFO: Test took 807ms.
[08:49:04.015] <TB3> INFO: Expecting 2560 events.
[08:49:04.432] <TB3> INFO: 2560 events read in total (30ms).
[08:49:04.433] <TB3> INFO: Test took 813ms.
[08:49:04.840] <TB3> INFO: PixTestPhOptimization::doTest() done, duration: 20 seconds
[08:49:04.840] <TB3> INFO: PH scale (per ROC): 75
[08:49:04.840] <TB3> INFO: PH offset (per ROC): 190
[08:49:04.853] <TB3> INFO: enter test to run
[08:49:04.853] <TB3> INFO: test: GainPedestal no parameter change
[08:49:04.853] <TB3> INFO: running: gainpedestal
[08:49:04.854] <TB3> INFO: ######################################################################
[08:49:04.854] <TB3> INFO: PixTestGainPedestal::doTest() ntrig = 10
[08:49:04.854] <TB3> INFO: ######################################################################
[08:49:04.862] <TB3> INFO: scanning low vcal = 10
[08:49:04.881] <TB3> INFO: Expecting 41600 events.
[08:49:05.970] <TB3> INFO: 41600 events read in total (702ms).
[08:49:05.971] <TB3> INFO: Test took 1109ms.
[08:49:05.971] <TB3> INFO: scanning low vcal = 20
[08:49:06.365] <TB3> INFO: Expecting 41600 events.
[08:49:07.454] <TB3> INFO: 41600 events read in total (702ms).
[08:49:07.455] <TB3> INFO: Test took 1484ms.
[08:49:07.455] <TB3> INFO: scanning low vcal = 30
[08:49:07.850] <TB3> INFO: Expecting 41600 events.
[08:49:08.939] <TB3> INFO: 41600 events read in total (702ms).
[08:49:08.939] <TB3> INFO: Test took 1484ms.
[08:49:08.939] <TB3> INFO: scanning low vcal = 40
[08:49:09.334] <TB3> INFO: Expecting 41600 events.
[08:49:10.457] <TB3> INFO: 41600 events read in total (736ms).
[08:49:10.458] <TB3> INFO: Test took 1519ms.
[08:49:10.458] <TB3> INFO: scanning low vcal = 50
[08:49:10.847] <TB3> INFO: Expecting 41600 events.
[08:49:11.972] <TB3> INFO: 41600 events read in total (738ms).
[08:49:11.973] <TB3> INFO: Test took 1515ms.
[08:49:11.973] <TB3> INFO: scanning low vcal = 60
[08:49:12.362] <TB3> INFO: Expecting 41600 events.
[08:49:13.486] <TB3> INFO: 41600 events read in total (737ms).
[08:49:13.486] <TB3> INFO: Test took 1513ms.
[08:49:13.486] <TB3> INFO: scanning low vcal = 70
[08:49:13.875] <TB3> INFO: Expecting 41600 events.
[08:49:15.000] <TB3> INFO: 41600 events read in total (738ms).
[08:49:15.000] <TB3> INFO: Test took 1513ms.
[08:49:15.001] <TB3> INFO: scanning low vcal = 80
[08:49:15.389] <TB3> INFO: Expecting 41600 events.
[08:49:16.522] <TB3> INFO: 41600 events read in total (746ms).
[08:49:16.523] <TB3> INFO: Test took 1522ms.
[08:49:16.523] <TB3> INFO: scanning low vcal = 90
[08:49:16.912] <TB3> INFO: Expecting 41600 events.
[08:49:18.037] <TB3> INFO: 41600 events read in total (738ms).
[08:49:18.037] <TB3> INFO: Test took 1514ms.
[08:49:18.037] <TB3> INFO: scanning low vcal = 100
[08:49:18.426] <TB3> INFO: Expecting 41600 events.
[08:49:19.559] <TB3> INFO: 41600 events read in total (746ms).
[08:49:19.559] <TB3> INFO: Test took 1522ms.
[08:49:19.559] <TB3> INFO: scanning low vcal = 110
[08:49:19.948] <TB3> INFO: Expecting 41600 events.
[08:49:21.073] <TB3> INFO: 41600 events read in total (738ms).
[08:49:21.074] <TB3> INFO: Test took 1515ms.
[08:49:21.074] <TB3> INFO: scanning low vcal = 120
[08:49:21.463] <TB3> INFO: Expecting 41600 events.
[08:49:22.588] <TB3> INFO: 41600 events read in total (738ms).
[08:49:22.588] <TB3> INFO: Test took 1514ms.
[08:49:22.588] <TB3> INFO: scanning low vcal = 130
[08:49:22.977] <TB3> INFO: Expecting 41600 events.
[08:49:24.102] <TB3> INFO: 41600 events read in total (738ms).
[08:49:24.102] <TB3> INFO: Test took 1514ms.
[08:49:24.102] <TB3> INFO: scanning low vcal = 140
[08:49:24.491] <TB3> INFO: Expecting 41600 events.
[08:49:25.616] <TB3> INFO: 41600 events read in total (738ms).
[08:49:25.616] <TB3> INFO: Test took 1514ms.
[08:49:25.616] <TB3> INFO: scanning low vcal = 150
[08:49:26.005] <TB3> INFO: Expecting 41600 events.
[08:49:27.130] <TB3> INFO: 41600 events read in total (738ms).
[08:49:27.131] <TB3> INFO: Test took 1515ms.
[08:49:27.131] <TB3> INFO: scanning low vcal = 160
[08:49:27.519] <TB3> INFO: Expecting 41600 events.
[08:49:28.644] <TB3> INFO: 41600 events read in total (737ms).
[08:49:28.645] <TB3> INFO: Test took 1514ms.
[08:49:28.645] <TB3> INFO: scanning low vcal = 170
[08:49:29.034] <TB3> INFO: Expecting 41600 events.
[08:49:30.158] <TB3> INFO: 41600 events read in total (737ms).
[08:49:30.158] <TB3> INFO: Test took 1513ms.
[08:49:30.159] <TB3> INFO: scanning low vcal = 180
[08:49:30.547] <TB3> INFO: Expecting 41600 events.
[08:49:31.671] <TB3> INFO: 41600 events read in total (737ms).
[08:49:31.672] <TB3> INFO: Test took 1513ms.
[08:49:31.672] <TB3> INFO: scanning low vcal = 190
[08:49:32.061] <TB3> INFO: Expecting 41600 events.
[08:49:33.185] <TB3> INFO: 41600 events read in total (737ms).
[08:49:33.185] <TB3> INFO: Test took 1513ms.
[08:49:33.185] <TB3> INFO: scanning low vcal = 200
[08:49:33.574] <TB3> INFO: Expecting 41600 events.
[08:49:34.698] <TB3> INFO: 41600 events read in total (737ms).
[08:49:34.699] <TB3> INFO: Test took 1514ms.
[08:49:34.699] <TB3> INFO: scanning low vcal = 210
[08:49:35.088] <TB3> INFO: Expecting 41600 events.
[08:49:36.212] <TB3> INFO: 41600 events read in total (737ms).
[08:49:36.212] <TB3> INFO: Test took 1513ms.
[08:49:36.213] <TB3> INFO: scanning low vcal = 220
[08:49:36.601] <TB3> INFO: Expecting 41600 events.
[08:49:37.725] <TB3> INFO: 41600 events read in total (736ms).
[08:49:37.726] <TB3> INFO: Test took 1513ms.
[08:49:37.726] <TB3> INFO: scanning low vcal = 230
[08:49:38.115] <TB3> INFO: Expecting 41600 events.
[08:49:39.239] <TB3> INFO: 41600 events read in total (737ms).
[08:49:39.240] <TB3> INFO: Test took 1514ms.
[08:49:39.240] <TB3> INFO: scanning low vcal = 240
[08:49:39.628] <TB3> INFO: Expecting 41600 events.
[08:49:40.753] <TB3> INFO: 41600 events read in total (738ms).
[08:49:40.753] <TB3> INFO: Test took 1513ms.
[08:49:40.753] <TB3> INFO: scanning low vcal = 250
[08:49:41.142] <TB3> INFO: Expecting 41600 events.
[08:49:42.266] <TB3> INFO: 41600 events read in total (737ms).
[08:49:42.267] <TB3> INFO: Test took 1514ms.
[08:49:42.267] <TB3> INFO: scanning high vcal = 30 (= 210 in low range)
[08:49:42.656] <TB3> INFO: Expecting 41600 events.
[08:49:43.780] <TB3> INFO: 41600 events read in total (737ms).
[08:49:43.780] <TB3> INFO: Test took 1513ms.
[08:49:43.781] <TB3> INFO: scanning high vcal = 50 (= 350 in low range)
[08:49:44.169] <TB3> INFO: Expecting 41600 events.
[08:49:45.294] <TB3> INFO: 41600 events read in total (738ms).
[08:49:45.294] <TB3> INFO: Test took 1513ms.
[08:49:45.294] <TB3> INFO: scanning high vcal = 70 (= 490 in low range)
[08:49:45.683] <TB3> INFO: Expecting 41600 events.
[08:49:46.807] <TB3> INFO: 41600 events read in total (737ms).
[08:49:46.807] <TB3> INFO: Test took 1513ms.
[08:49:46.808] <TB3> INFO: scanning high vcal = 90 (= 630 in low range)
[08:49:47.196] <TB3> INFO: Expecting 41600 events.
[08:49:48.320] <TB3> INFO: 41600 events read in total (737ms).
[08:49:48.320] <TB3> INFO: Test took 1512ms.
[08:49:48.321] <TB3> INFO: scanning high vcal = 200 (= 1400 in low range)
[08:49:48.710] <TB3> INFO: Expecting 41600 events.
[08:49:49.834] <TB3> INFO: 41600 events read in total (737ms).
[08:49:49.834] <TB3> INFO: Test took 1513ms.
[08:49:50.218] <TB3> INFO: PixTestGainPedestal::measure() done
[08:49:52.162] <TB3> INFO: PixTestGainPedestal::fit() done
[08:49:52.162] <TB3> INFO: non-linearity mean: 0.955
[08:49:52.162] <TB3> INFO: non-linearity RMS: 0.007
[08:49:52.162] <TB3> INFO: write gain/ped parameters into /home/mameinha/data/R419_Fulltest_p17_2015-10-06_10h34m_1444120483//000_FulltestROC_p17//phCalibrationFitErr35_C0.dat
[08:49:52.201] <TB3> INFO: PixTestGainPedestal::doTest() done, duration: 47 seconds
[08:49:52.201] <TB3> INFO: enter test to run
[08:49:52.201] <TB3> INFO: test: Readback no parameter change
[08:49:52.201] <TB3> INFO: running: readback
[08:49:52.201] <TB3> INFO: readReadbackCal: /home/mameinha/data/R419_Fulltest_p17_2015-10-06_10h34m_1444120483//000_FulltestROC_p17//readbackCal_C0.dat .. /home/mameinha/data/R419_Fulltest_p17_2015-10-06_10h34m_1444120483//000_FulltestROC_p17//readbackCal_C0.dat
[08:49:52.202] <TB3> INFO: ######################################################################
[08:49:52.202] <TB3> INFO: PixTestReadback::doTest()
[08:49:52.202] <TB3> INFO: ######################################################################
[08:49:52.203] <TB3> INFO: PixTestReadback::RES sent once
[08:50:03.338] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R419_Fulltest_p17_2015-10-06_10h34m_1444120483//000_FulltestROC_p17//readbackCal_C0.dat
[08:50:03.344] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[08:50:03.344] <TB3> INFO: PixTestReadback::RES sent once
[08:50:14.442] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R419_Fulltest_p17_2015-10-06_10h34m_1444120483//000_FulltestROC_p17//readbackCal_C0.dat
[08:50:14.448] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[08:50:14.448] <TB3> INFO: PixTestReadback::RES sent once
[08:50:22.777] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[08:50:22.777] <TB3> INFO: Vbg will be calibrated using Vd calibration
[08:50:22.777] <TB3> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 153calibrated Vbg = 1.22924 :::*/*/*/*/
[08:50:23.154] <TB3> INFO: PixTestReadback::RES sent once
[08:50:31.993] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R419_Fulltest_p17_2015-10-06_10h34m_1444120483//000_FulltestROC_p17//readbackCal_C0.dat
[08:50:31.997] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[08:50:31.997] <TB3> INFO: PixTestReadback::doTest() done
[08:50:32.031] <TB3> INFO: enter test to run
[08:50:32.031] <TB3> INFO: test: no parameter change
[08:50:32.089] <TB3> QUIET: Connection to board 71 closed.
[08:50:32.169] <TB3> INFO: pXar: this is the end, my friend