[09:39:43.389] <TB3> INFO: *** Welcome to pxar ***
[09:39:43.389] <TB3> INFO: *** Today: 2015/10/06
[09:39:44.037] <TB3> INFO: *** Version: 9da6
[09:39:44.037] <TB3> INFO: readRocDacs: /home/mameinha/data/R421_Fulltest_p17_2015-10-06_11h39m_1444124371//000_FulltestROC_p17//dacParameters_C0.dat .. /home/mameinha/data/R421_Fulltest_p17_2015-10-06_11h39m_1444124371//000_FulltestROC_p17//dacParameters_C0.dat
[09:39:44.038] <TB3> INFO: readTbmDacs: /home/mameinha/data/R421_Fulltest_p17_2015-10-06_11h39m_1444124371//000_FulltestROC_p17//tbmParameters_C0a.dat .. /home/mameinha/data/R421_Fulltest_p17_2015-10-06_11h39m_1444124371//000_FulltestROC_p17//tbmParameters_C4294967295b.dat
[09:39:44.038] <TB3> INFO: readMaskFile: /home/mameinha/data/R421_Fulltest_p17_2015-10-06_11h39m_1444124371//000_FulltestROC_p17//defaultMaskFile.dat
[09:39:44.039] <TB3> INFO: readTrimFile: /home/mameinha/data/R421_Fulltest_p17_2015-10-06_11h39m_1444124371//000_FulltestROC_p17//trimParameters_C0.dat .. /home/mameinha/data/R421_Fulltest_p17_2015-10-06_11h39m_1444124371//000_FulltestROC_p17//trimParameters_C0.dat
[09:39:44.046] <TB3> INFO: clk: 2
[09:39:44.046] <TB3> INFO: ctr: 2
[09:39:44.046] <TB3> INFO: sda: 17
[09:39:44.046] <TB3> INFO: tin: 7
[09:39:44.046] <TB3> INFO: level: 15
[09:39:44.046] <TB3> INFO: deser160phase: 4
[09:39:44.047] <TB3> QUIET: Instanciating API for pxar v2.6.0+20~g1a7f656
[09:39:44.047] <TB3> INFO: Log level: INFO
[09:39:44.068] <TB3> QUIET: Connection to board DTB_WRQ4OZ opened.
[09:39:44.071] <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:
------------------------------------------------------
[09:39:44.074] <TB3> INFO: RPC call hashes of host and DTB match: 398089610
[09:39:45.237] <TB3> INFO: DUT info:
[09:39:45.237] <TB3> INFO: The DUT currently contains the following objects:
[09:39:45.237] <TB3> INFO: 0 TBM Cores (0 ON)
[09:39:45.237] <TB3> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[09:39:45.237] <TB3> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[09:39:45.638] <TB3> INFO: enter 'restricted' command line mode
[09:39:45.638] <TB3> INFO: enter test to run
[09:39:45.638] <TB3> INFO: test: Setup no parameter change
[09:39:45.638] <TB3> INFO: running: setup
[09:39:45.643] <TB3> INFO: PixTestSetup::doTest() ntrig = 10

[09:39:45.643] <TB3> INFO: PixTestSetup:: pg set to RES|TOK
[09:39:45.643] <TB3> INFO: 0 1 2 3 4 5 6 7
[09:39:48.684] <TB3> INFO: 0: 000 000 004 07c 7f0 f00 000 000
[09:39:51.698] <TB3> INFO: 1: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[09:39:54.711] <TB3> INFO: 2: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[09:39:57.725] <TB3> INFO: 3: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[09:40:00.738] <TB3> INFO: 4: 000 000 000 03c 3f8 f80 800 000
[09:40:03.751] <TB3> INFO: 5: 000 000 000 03c 3f8 f80 800 000
[09:40:06.765] <TB3> INFO: 6: 000 000 000 03c 3fc fc0 c00 000
[09:40:09.778] <TB3> INFO: 7: 000 000 000 03c 3fc fc0 c00 000
[09:40:12.791] <TB3> INFO: 8: 000 000 000 03c 3fc fc0 c00 000
[09:40:15.803] <TB3> INFO: 9: c00 000 000 03c 3fc fc0 c00 000
[09:40:18.816] <TB3> INFO: 10: c00 000 000 01c 1fc fc0 c00 000
[09:40:21.829] <TB3> INFO: 11: 000 000 000 01c 1fc fe0 e00 000
[09:40:24.842] <TB3> INFO: 12: 000 000 000 01c 1fc fe0 e00 000
[09:40:27.855] <TB3> INFO: 13: e00 000 000 01c 1fc fe0 e00 000
[09:40:30.868] <TB3> INFO: 14: 000 000 000 00c 0fc fe0 e00 000
[09:40:33.880] <TB3> INFO: 15: 000 000 000 00c 0fc fe0 e00 000
[09:40:36.893] <TB3> INFO: 16: 000 000 000 00c 0fc ff0 f00 000
[09:40:39.906] <TB3> INFO: 17: 000 000 000 00c 0fc ff0 f00 000
[09:40:42.919] <TB3> INFO: 18: 000 000 000 00c 0fc ff0 f00 000
[09:40:45.932] <TB3> INFO: 19: 000 000 000 00c 0fc ff0 f00 000
[09:40:46.337] <TB3> INFO: Found good delays at CLK = 2, DESER160 = 4
[09:40:46.338] <TB3> INFO: PixTestSetup:: Write Tb parameters to file.
[09:40:46.343] <TB3> INFO: write dtb parameters into /home/mameinha/data/R421_Fulltest_p17_2015-10-06_11h39m_1444124371//000_FulltestROC_p17//tbParameters.dat
[09:40:46.345] <TB3> INFO: PixTestSetup::doTest() done for.
[09:40:46.369] <TB3> INFO: enter test to run
[09:40:46.369] <TB3> INFO: test: Pretest no parameter change
[09:40:46.369] <TB3> INFO: running: pretest
[09:40:46.370] <TB3> INFO: ----------------------------------------------------------------------
[09:40:46.370] <TB3> INFO: PixTestPretest::programROC()
[09:40:46.370] <TB3> INFO: ----------------------------------------------------------------------
[09:40:49.372] <TB3> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[09:40:49.372] <TB3> INFO: IA differences per ROC: 16.1
[09:40:49.376] <TB3> INFO: enter test to run
[09:40:49.377] <TB3> INFO: test: Pretest no parameter change
[09:40:49.377] <TB3> INFO: running: pretest
[09:40:49.378] <TB3> INFO: ----------------------------------------------------------------------
[09:40:49.378] <TB3> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[09:40:49.378] <TB3> INFO: ----------------------------------------------------------------------
[09:40:49.987] <TB3> INFO: PixTestPretest::setVana() done, Module Ia 24.1 mA = 24.1 mA/ROC
[09:40:49.987] <TB3> INFO: i(loss) [mA/ROC]: 20.9
[09:40:49.989] <TB3> INFO: enter test to run
[09:40:49.989] <TB3> INFO: test: Pretest no parameter change
[09:40:49.989] <TB3> INFO: running: pretest
[09:40:49.991] <TB3> INFO: ----------------------------------------------------------------------
[09:40:49.991] <TB3> INFO: PixTestPretest::findWorkingPixel()
[09:40:49.991] <TB3> INFO: ----------------------------------------------------------------------
[09:40:50.000] <TB3> INFO: Expecting 231680 events.
[09:40:52.195] <TB3> INFO: 231680 events read in total (1808ms).
[09:40:52.197] <TB3> INFO: Test took 2206ms.
[09:40:52.576] <TB3> INFO: Found working pixel in all ROCs: col/row = 12/22
[09:40:52.581] <TB3> INFO: enter test to run
[09:40:52.581] <TB3> INFO: test: Pretest no parameter change
[09:40:52.581] <TB3> INFO: running: pretest
[09:40:52.583] <TB3> INFO: ----------------------------------------------------------------------
[09:40:52.583] <TB3> INFO: PixTestPretest::setVthrCompCalDel()
[09:40:52.583] <TB3> INFO: ----------------------------------------------------------------------
[09:40:52.591] <TB3> INFO: Expecting 231680 events.
[09:40:54.785] <TB3> INFO: 231680 events read in total (1807ms).
[09:40:54.787] <TB3> INFO: Test took 2204ms.
[09:40:55.166] <TB3> INFO: PixTestPretest::setVthrCompCalDel() done
[09:40:55.166] <TB3> INFO: CalDel: 130
[09:40:55.166] <TB3> INFO: VthrComp: 51
[09:40:55.170] <TB3> INFO: enter test to run
[09:40:55.170] <TB3> INFO: test: Pretest no parameter change
[09:40:55.170] <TB3> INFO: running: pretest
[09:40:55.251] <TB3> INFO: write dac parameters into /home/mameinha/data/R421_Fulltest_p17_2015-10-06_11h39m_1444124371//000_FulltestROC_p17//dacParameters_C0.dat
[09:40:55.254] <TB3> INFO: enter test to run
[09:40:55.254] <TB3> INFO: test: PixelAlive no parameter change
[09:40:55.254] <TB3> INFO: running: pixelalive
[09:40:55.255] <TB3> INFO: ######################################################################
[09:40:55.255] <TB3> INFO: PixTestAlive::doTest()
[09:40:55.255] <TB3> INFO: ######################################################################
[09:40:55.257] <TB3> INFO: ----------------------------------------------------------------------
[09:40:55.257] <TB3> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[09:40:55.257] <TB3> INFO: ----------------------------------------------------------------------
[09:40:55.276] <TB3> INFO: Expecting 41600 events.
[09:40:56.076] <TB3> INFO: 41600 events read in total (413ms).
[09:40:56.077] <TB3> INFO: Test took 820ms.
[09:40:56.077] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:40:56.462] <TB3> INFO: PixTestAlive::aliveTest() done
[09:40:56.462] <TB3> INFO: number of dead pixels (per ROC): 0
[09:40:56.464] <TB3> INFO: ----------------------------------------------------------------------
[09:40:56.464] <TB3> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[09:40:56.464] <TB3> INFO: ----------------------------------------------------------------------
[09:40:56.483] <TB3> INFO: Expecting 41600 events.
[09:40:57.229] <TB3> INFO: 41600 events read in total (359ms).
[09:40:57.229] <TB3> INFO: Test took 765ms.
[09:40:57.229] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:40:57.230] <TB3> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[09:40:57.620] <TB3> INFO: PixTestAlive::maskTest() done
[09:40:57.620] <TB3> INFO: number of mask-defect pixels (per ROC): 0
[09:40:57.621] <TB3> INFO: ----------------------------------------------------------------------
[09:40:57.621] <TB3> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[09:40:57.621] <TB3> INFO: ----------------------------------------------------------------------
[09:40:57.640] <TB3> INFO: Expecting 41600 events.
[09:40:58.440] <TB3> INFO: 41600 events read in total (413ms).
[09:40:58.441] <TB3> INFO: Test took 820ms.
[09:40:58.441] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:40:58.826] <TB3> INFO: PixTestAlive::addressDecodingTest() done
[09:40:58.826] <TB3> INFO: number of address-decoding pixels (per ROC): 0
[09:40:58.826] <TB3> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[09:40:58.827] <TB3> INFO: enter test to run
[09:40:58.827] <TB3> INFO: test: Scurves no parameter change
[09:40:58.827] <TB3> INFO: running: scurves
[09:40:58.828] <TB3> INFO: ######################################################################
[09:40:58.828] <TB3> INFO: PixTestScurves::doTest() ntrig = 50
[09:40:58.828] <TB3> INFO: ######################################################################
[09:40:58.828] <TB3> INFO: ----------------------------------------------------------------------
[09:40:58.828] <TB3> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[09:40:58.828] <TB3> INFO: ----------------------------------------------------------------------
[09:40:58.828] <TB3> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[09:40:58.839] <TB3> INFO: dacScan split into 1 runs with ntrig = 50
[09:40:58.839] <TB3> INFO: run 1 of 1
[09:40:58.858] <TB3> INFO: Expecting 41808000 events.
[09:43:23.967] <TB3> INFO: 20644050 events read in total (144722ms).
[09:45:45.748] <TB3> INFO: 40758950 events read in total (286503ms).
[09:45:53.144] <TB3> INFO: 41808000 events read in total (293899ms).
[09:45:53.171] <TB3> INFO: Test took 294332ms.
[09:45:53.194] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:45:54.709] <TB3> INFO: PixTestScurves::scurves() done
[09:45:54.709] <TB3> INFO: Vcal mean: 90.94
[09:45:54.709] <TB3> INFO: Vcal RMS: 5.41
[09:45:54.713] <TB3> INFO: enter test to run
[09:45:54.713] <TB3> INFO: test: Trim no parameter change
[09:45:54.713] <TB3> INFO: running: trim
[09:45:54.715] <TB3> INFO: ######################################################################
[09:45:54.715] <TB3> INFO: PixTestTrim::doTest()
[09:45:54.715] <TB3> INFO: ######################################################################
[09:45:54.716] <TB3> INFO: ----------------------------------------------------------------------
[09:45:54.716] <TB3> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[09:45:54.716] <TB3> INFO: ----------------------------------------------------------------------
[09:45:54.721] <TB3> INFO: ---> VthrComp thr map (minimal VthrComp)
[09:45:54.721] <TB3> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[09:45:54.729] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:45:54.729] <TB3> INFO: run 1 of 1
[09:45:54.748] <TB3> INFO: Expecting 6281600 events.
[09:46:40.834] <TB3> INFO: 6281600 events read in total (45692ms).
[09:46:40.851] <TB3> INFO: Test took 46122ms.
[09:46:40.860] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:46:41.954] <TB3> INFO: ROC 0 VthrComp = 92
[09:46:41.955] <TB3> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[09:46:41.955] <TB3> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[09:46:41.962] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:46:41.962] <TB3> INFO: run 1 of 1
[09:46:41.981] <TB3> INFO: Expecting 6281600 events.
[09:47:31.369] <TB3> INFO: 6281600 events read in total (49001ms).
[09:47:31.417] <TB3> INFO: Test took 49455ms.
[09:47:31.438] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:32.711] <TB3> INFO: roc 0 with ID = 0 has maximal Vcal 59.1235 for pixel 0/3 mean/min/max = 46.1678/33.0817/59.2539
[09:47:32.720] <TB3> INFO: Expecting 514560 events.
[09:47:36.667] <TB3> INFO: 514560 events read in total (3560ms).
[09:47:36.671] <TB3> INFO: Test took 3959ms.
[09:47:37.064] <TB3> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[09:47:37.071] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:47:37.071] <TB3> INFO: run 1 of 1
[09:47:37.090] <TB3> INFO: Expecting 6281600 events.
[09:48:26.642] <TB3> INFO: 6281600 events read in total (49165ms).
[09:48:26.682] <TB3> INFO: Test took 49611ms.
[09:48:26.702] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:48:27.964] <TB3> INFO: ---> TrimStepCorr4 extremal thresholds: 15.109262 .. 47.684831
[09:48:27.969] <TB3> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 5 .. 57 (-1/-1) hits flags = 528 (plus default)
[09:48:27.977] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:48:27.977] <TB3> INFO: run 1 of 1
[09:48:27.996] <TB3> INFO: Expecting 2204800 events.
[09:48:45.170] <TB3> INFO: 2204800 events read in total (16787ms).
[09:48:45.179] <TB3> INFO: Test took 17202ms.
[09:48:45.184] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:48:45.977] <TB3> INFO: ---> TrimStepCorr2 extremal thresholds: 23.520189 .. 42.497300
[09:48:45.982] <TB3> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 13 .. 52 (-1/-1) hits flags = 528 (plus default)
[09:48:45.989] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:48:45.989] <TB3> INFO: run 1 of 1
[09:48:46.008] <TB3> INFO: Expecting 1664000 events.
[09:48:59.154] <TB3> INFO: 1664000 events read in total (12759ms).
[09:48:59.161] <TB3> INFO: Test took 13172ms.
[09:48:59.165] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:48:59.922] <TB3> INFO: ---> TrimStepCorr1a extremal thresholds: 27.355803 .. 38.198496
[09:48:59.927] <TB3> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 17 .. 48 (-1/-1) hits flags = 528 (plus default)
[09:48:59.934] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:48:59.934] <TB3> INFO: run 1 of 1
[09:48:59.953] <TB3> INFO: Expecting 1331200 events.
[09:49:10.627] <TB3> INFO: 1331200 events read in total (10287ms).
[09:49:10.633] <TB3> INFO: Test took 10699ms.
[09:49:10.636] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:49:11.371] <TB3> INFO: ---> TrimStepCorr1b extremal thresholds: 29.748636 .. 38.001693
[09:49:11.376] <TB3> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 19 .. 48 (-1/-1) hits flags = 528 (plus default)
[09:49:11.383] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:49:11.383] <TB3> INFO: run 1 of 1
[09:49:11.402] <TB3> INFO: Expecting 1248000 events.
[09:49:21.498] <TB3> INFO: 1248000 events read in total (9709ms).
[09:49:21.504] <TB3> INFO: Test took 10121ms.
[09:49:21.507] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:49:22.233] <TB3> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[09:49:22.233] <TB3> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[09:49:22.241] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:49:22.241] <TB3> INFO: run 1 of 1
[09:49:22.260] <TB3> INFO: Expecting 1705600 events.
[09:49:35.797] <TB3> INFO: 1705600 events read in total (13150ms).
[09:49:35.806] <TB3> INFO: Test took 13565ms.
[09:49:35.810] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:49:36.598] <TB3> INFO: write dac parameters into /home/mameinha/data/R421_Fulltest_p17_2015-10-06_11h39m_1444124371//000_FulltestROC_p17//dacParameters35_C0.dat
[09:49:36.602] <TB3> INFO: write trim parameters into /home/mameinha/data/R421_Fulltest_p17_2015-10-06_11h39m_1444124371//000_FulltestROC_p17//trimParameters35_C0.dat
[09:49:36.612] <TB3> INFO: PixTestTrim::trimTest() done
[09:49:36.612] <TB3> INFO: vtrim: 93
[09:49:36.612] <TB3> INFO: vthrcomp: 92
[09:49:36.612] <TB3> INFO: vcal mean: 35.00
[09:49:36.612] <TB3> INFO: vcal RMS: 0.72
[09:49:36.612] <TB3> INFO: bits mean: 8.77
[09:49:36.612] <TB3> INFO: bits RMS: 2.86
[09:49:36.616] <TB3> INFO: ----------------------------------------------------------------------
[09:49:36.616] <TB3> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[09:49:36.616] <TB3> INFO: ----------------------------------------------------------------------
[09:49:36.616] <TB3> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[09:49:36.624] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:49:36.624] <TB3> INFO: run 1 of 1
[09:49:36.643] <TB3> INFO: Expecting 8320000 events.
[09:50:38.868] <TB3> INFO: 8320000 events read in total (61838ms).
[09:50:38.898] <TB3> INFO: Test took 62274ms.
[09:50:38.914] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:50:40.371] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 153 (-1/-1) hits flags = 528 (plus default)
[09:50:40.378] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:50:40.378] <TB3> INFO: run 1 of 1
[09:50:40.397] <TB3> INFO: Expecting 6406400 events.
[09:51:27.926] <TB3> INFO: 6406400 events read in total (47142ms).
[09:51:27.945] <TB3> INFO: Test took 47567ms.
[09:51:27.954] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:51:29.180] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 141 (-1/-1) hits flags = 528 (plus default)
[09:51:29.188] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:51:29.188] <TB3> INFO: run 1 of 1
[09:51:29.207] <TB3> INFO: Expecting 5907200 events.
[09:52:12.830] <TB3> INFO: 5907200 events read in total (43236ms).
[09:52:12.845] <TB3> INFO: Test took 43657ms.
[09:52:12.853] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:52:13.995] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 142 (-1/-1) hits flags = 528 (plus default)
[09:52:14.002] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:52:14.002] <TB3> INFO: run 1 of 1
[09:52:14.021] <TB3> INFO: Expecting 5948800 events.
[09:52:58.001] <TB3> INFO: 5948800 events read in total (43593ms).
[09:52:58.017] <TB3> INFO: Test took 44015ms.
[09:52:58.025] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:52:59.176] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 141 (-1/-1) hits flags = 528 (plus default)
[09:52:59.184] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:52:59.184] <TB3> INFO: run 1 of 1
[09:52:59.204] <TB3> INFO: Expecting 5907200 events.
[09:53:42.832] <TB3> INFO: 5907200 events read in total (43241ms).
[09:53:42.847] <TB3> INFO: Test took 43663ms.
[09:53:42.855] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:53:44.025] <TB3> INFO: PixTestTrim::trimBitTest() done
[09:53:44.026] <TB3> INFO: PixTestTrim::doTest() done, duration: 469 seconds
[09:53:44.067] <TB3> INFO: enter test to run
[09:53:44.068] <TB3> INFO: test: PhOptimization no parameter change
[09:53:44.068] <TB3> INFO: running: phoptimization
[09:53:44.068] <TB3> INFO: ######################################################################
[09:53:44.068] <TB3> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[09:53:44.068] <TB3> INFO: ######################################################################
[09:53:44.088] <TB3> INFO: Expecting 41600 events.
[09:53:44.887] <TB3> INFO: 41600 events read in total (412ms).
[09:53:44.887] <TB3> INFO: Test took 819ms.
[09:53:44.888] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:53:45.279] <TB3> INFO: Expecting 41600 events.
[09:53:46.080] <TB3> INFO: 41600 events read in total (414ms).
[09:53:46.081] <TB3> INFO: Test took 1192ms.
[09:53:46.081] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:53:46.470] <TB3> INFO: Expecting 41600 events.
[09:53:47.273] <TB3> INFO: 41600 events read in total (416ms).
[09:53:47.273] <TB3> INFO: Test took 1191ms.
[09:53:47.274] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:53:47.663] <TB3> INFO: Expecting 2560 events.
[09:53:48.081] <TB3> INFO: 2560 events read in total (32ms).
[09:53:48.081] <TB3> INFO: Test took 807ms.
[09:53:48.476] <TB3> INFO: Expecting 655360 events.
[09:53:53.692] <TB3> INFO: 655360 events read in total (4829ms).
[09:53:53.700] <TB3> INFO: Test took 5619ms.
[09:53:53.994] <TB3> INFO: Expecting 655360 events.
[09:53:59.208] <TB3> INFO: 655360 events read in total (4827ms).
[09:53:59.216] <TB3> INFO: Test took 5503ms.
[09:53:59.235] <TB3> INFO: safety margin for low PH: adding 0, margin is now 20
[09:53:59.248] <TB3> INFO: write dac parameters into /home/mameinha/data/R421_Fulltest_p17_2015-10-06_11h39m_1444124371//000_FulltestROC_p17//dacParameters35_C0.dat
[09:53:59.512] <TB3> INFO: Expecting 41600 events.
[09:54:00.273] <TB3> INFO: 41600 events read in total (374ms).
[09:54:00.273] <TB3> INFO: Test took 1022ms.
[09:54:00.662] <TB3> INFO: Expecting 41600 events.
[09:54:01.422] <TB3> INFO: 41600 events read in total (373ms).
[09:54:01.423] <TB3> INFO: Test took 1149ms.
[09:54:01.812] <TB3> INFO: Expecting 41600 events.
[09:54:02.572] <TB3> INFO: 41600 events read in total (373ms).
[09:54:02.573] <TB3> INFO: Test took 1150ms.
[09:54:02.962] <TB3> INFO: Expecting 2560 events.
[09:54:03.379] <TB3> INFO: 2560 events read in total (30ms).
[09:54:03.379] <TB3> INFO: Test took 806ms.
[09:54:03.775] <TB3> INFO: Expecting 2560 events.
[09:54:04.192] <TB3> INFO: 2560 events read in total (30ms).
[09:54:04.192] <TB3> INFO: Test took 812ms.
[09:54:04.599] <TB3> INFO: PixTestPhOptimization::doTest() done, duration: 20 seconds
[09:54:04.599] <TB3> INFO: PH scale (per ROC): 73
[09:54:04.599] <TB3> INFO: PH offset (per ROC): 175
[09:54:04.612] <TB3> INFO: enter test to run
[09:54:04.612] <TB3> INFO: test: GainPedestal no parameter change
[09:54:04.612] <TB3> INFO: running: gainpedestal
[09:54:04.614] <TB3> INFO: ######################################################################
[09:54:04.614] <TB3> INFO: PixTestGainPedestal::doTest() ntrig = 10
[09:54:04.614] <TB3> INFO: ######################################################################
[09:54:04.621] <TB3> INFO: scanning low vcal = 10
[09:54:04.640] <TB3> INFO: Expecting 41600 events.
[09:54:05.729] <TB3> INFO: 41600 events read in total (702ms).
[09:54:05.730] <TB3> INFO: Test took 1109ms.
[09:54:05.730] <TB3> INFO: scanning low vcal = 20
[09:54:06.125] <TB3> INFO: Expecting 41600 events.
[09:54:07.213] <TB3> INFO: 41600 events read in total (701ms).
[09:54:07.213] <TB3> INFO: Test took 1483ms.
[09:54:07.213] <TB3> INFO: scanning low vcal = 30
[09:54:07.608] <TB3> INFO: Expecting 41600 events.
[09:54:08.697] <TB3> INFO: 41600 events read in total (702ms).
[09:54:08.698] <TB3> INFO: Test took 1485ms.
[09:54:08.698] <TB3> INFO: scanning low vcal = 40
[09:54:09.093] <TB3> INFO: Expecting 41600 events.
[09:54:10.215] <TB3> INFO: 41600 events read in total (735ms).
[09:54:10.216] <TB3> INFO: Test took 1518ms.
[09:54:10.216] <TB3> INFO: scanning low vcal = 50
[09:54:10.605] <TB3> INFO: Expecting 41600 events.
[09:54:11.729] <TB3> INFO: 41600 events read in total (737ms).
[09:54:11.730] <TB3> INFO: Test took 1514ms.
[09:54:11.730] <TB3> INFO: scanning low vcal = 60
[09:54:12.119] <TB3> INFO: Expecting 41600 events.
[09:54:13.243] <TB3> INFO: 41600 events read in total (737ms).
[09:54:13.244] <TB3> INFO: Test took 1514ms.
[09:54:13.244] <TB3> INFO: scanning low vcal = 70
[09:54:13.633] <TB3> INFO: Expecting 41600 events.
[09:54:14.757] <TB3> INFO: 41600 events read in total (737ms).
[09:54:14.757] <TB3> INFO: Test took 1514ms.
[09:54:14.758] <TB3> INFO: scanning low vcal = 80
[09:54:15.147] <TB3> INFO: Expecting 41600 events.
[09:54:16.279] <TB3> INFO: 41600 events read in total (745ms).
[09:54:16.280] <TB3> INFO: Test took 1522ms.
[09:54:16.280] <TB3> INFO: scanning low vcal = 90
[09:54:16.669] <TB3> INFO: Expecting 41600 events.
[09:54:17.793] <TB3> INFO: 41600 events read in total (737ms).
[09:54:17.794] <TB3> INFO: Test took 1514ms.
[09:54:17.794] <TB3> INFO: scanning low vcal = 100
[09:54:18.183] <TB3> INFO: Expecting 41600 events.
[09:54:19.315] <TB3> INFO: 41600 events read in total (745ms).
[09:54:19.316] <TB3> INFO: Test took 1522ms.
[09:54:19.316] <TB3> INFO: scanning low vcal = 110
[09:54:19.705] <TB3> INFO: Expecting 41600 events.
[09:54:20.829] <TB3> INFO: 41600 events read in total (737ms).
[09:54:20.830] <TB3> INFO: Test took 1514ms.
[09:54:20.830] <TB3> INFO: scanning low vcal = 120
[09:54:21.219] <TB3> INFO: Expecting 41600 events.
[09:54:22.343] <TB3> INFO: 41600 events read in total (737ms).
[09:54:22.343] <TB3> INFO: Test took 1513ms.
[09:54:22.343] <TB3> INFO: scanning low vcal = 130
[09:54:22.732] <TB3> INFO: Expecting 41600 events.
[09:54:23.856] <TB3> INFO: 41600 events read in total (737ms).
[09:54:23.856] <TB3> INFO: Test took 1513ms.
[09:54:23.856] <TB3> INFO: scanning low vcal = 140
[09:54:24.245] <TB3> INFO: Expecting 41600 events.
[09:54:25.369] <TB3> INFO: 41600 events read in total (737ms).
[09:54:25.369] <TB3> INFO: Test took 1513ms.
[09:54:25.369] <TB3> INFO: scanning low vcal = 150
[09:54:25.758] <TB3> INFO: Expecting 41600 events.
[09:54:26.882] <TB3> INFO: 41600 events read in total (737ms).
[09:54:26.882] <TB3> INFO: Test took 1513ms.
[09:54:26.883] <TB3> INFO: scanning low vcal = 160
[09:54:27.271] <TB3> INFO: Expecting 41600 events.
[09:54:28.395] <TB3> INFO: 41600 events read in total (737ms).
[09:54:28.395] <TB3> INFO: Test took 1512ms.
[09:54:28.396] <TB3> INFO: scanning low vcal = 170
[09:54:28.784] <TB3> INFO: Expecting 41600 events.
[09:54:29.908] <TB3> INFO: 41600 events read in total (737ms).
[09:54:29.909] <TB3> INFO: Test took 1513ms.
[09:54:29.909] <TB3> INFO: scanning low vcal = 180
[09:54:30.298] <TB3> INFO: Expecting 41600 events.
[09:54:31.421] <TB3> INFO: 41600 events read in total (736ms).
[09:54:31.422] <TB3> INFO: Test took 1513ms.
[09:54:31.422] <TB3> INFO: scanning low vcal = 190
[09:54:31.811] <TB3> INFO: Expecting 41600 events.
[09:54:32.935] <TB3> INFO: 41600 events read in total (737ms).
[09:54:32.935] <TB3> INFO: Test took 1513ms.
[09:54:32.935] <TB3> INFO: scanning low vcal = 200
[09:54:33.324] <TB3> INFO: Expecting 41600 events.
[09:54:34.448] <TB3> INFO: 41600 events read in total (737ms).
[09:54:34.448] <TB3> INFO: Test took 1513ms.
[09:54:34.449] <TB3> INFO: scanning low vcal = 210
[09:54:34.838] <TB3> INFO: Expecting 41600 events.
[09:54:35.962] <TB3> INFO: 41600 events read in total (737ms).
[09:54:35.962] <TB3> INFO: Test took 1513ms.
[09:54:35.962] <TB3> INFO: scanning low vcal = 220
[09:54:36.351] <TB3> INFO: Expecting 41600 events.
[09:54:37.475] <TB3> INFO: 41600 events read in total (737ms).
[09:54:37.475] <TB3> INFO: Test took 1513ms.
[09:54:37.476] <TB3> INFO: scanning low vcal = 230
[09:54:37.864] <TB3> INFO: Expecting 41600 events.
[09:54:38.988] <TB3> INFO: 41600 events read in total (737ms).
[09:54:38.989] <TB3> INFO: Test took 1513ms.
[09:54:38.990] <TB3> INFO: scanning low vcal = 240
[09:54:39.378] <TB3> INFO: Expecting 41600 events.
[09:54:40.502] <TB3> INFO: 41600 events read in total (737ms).
[09:54:40.502] <TB3> INFO: Test took 1512ms.
[09:54:40.503] <TB3> INFO: scanning low vcal = 250
[09:54:40.891] <TB3> INFO: Expecting 41600 events.
[09:54:42.015] <TB3> INFO: 41600 events read in total (737ms).
[09:54:42.016] <TB3> INFO: Test took 1513ms.
[09:54:42.016] <TB3> INFO: scanning high vcal = 30 (= 210 in low range)
[09:54:42.405] <TB3> INFO: Expecting 41600 events.
[09:54:43.529] <TB3> INFO: 41600 events read in total (737ms).
[09:54:43.529] <TB3> INFO: Test took 1513ms.
[09:54:43.530] <TB3> INFO: scanning high vcal = 50 (= 350 in low range)
[09:54:43.919] <TB3> INFO: Expecting 41600 events.
[09:54:45.043] <TB3> INFO: 41600 events read in total (737ms).
[09:54:45.043] <TB3> INFO: Test took 1513ms.
[09:54:45.044] <TB3> INFO: scanning high vcal = 70 (= 490 in low range)
[09:54:45.432] <TB3> INFO: Expecting 41600 events.
[09:54:46.556] <TB3> INFO: 41600 events read in total (737ms).
[09:54:46.557] <TB3> INFO: Test took 1513ms.
[09:54:46.557] <TB3> INFO: scanning high vcal = 90 (= 630 in low range)
[09:54:46.946] <TB3> INFO: Expecting 41600 events.
[09:54:48.070] <TB3> INFO: 41600 events read in total (737ms).
[09:54:48.070] <TB3> INFO: Test took 1513ms.
[09:54:48.070] <TB3> INFO: scanning high vcal = 200 (= 1400 in low range)
[09:54:48.459] <TB3> INFO: Expecting 41600 events.
[09:54:49.583] <TB3> INFO: 41600 events read in total (737ms).
[09:54:49.583] <TB3> INFO: Test took 1513ms.
[09:54:49.967] <TB3> INFO: PixTestGainPedestal::measure() done
[09:54:51.931] <TB3> INFO: PixTestGainPedestal::fit() done
[09:54:51.931] <TB3> INFO: non-linearity mean: 0.957
[09:54:51.931] <TB3> INFO: non-linearity RMS: 0.007
[09:54:51.932] <TB3> INFO: write gain/ped parameters into /home/mameinha/data/R421_Fulltest_p17_2015-10-06_11h39m_1444124371//000_FulltestROC_p17//phCalibrationFitErr35_C0.dat
[09:54:51.977] <TB3> INFO: PixTestGainPedestal::doTest() done, duration: 47 seconds
[09:54:51.978] <TB3> INFO: enter test to run
[09:54:51.978] <TB3> INFO: test: Readback no parameter change
[09:54:51.978] <TB3> INFO: running: readback
[09:54:51.978] <TB3> INFO: readReadbackCal: /home/mameinha/data/R421_Fulltest_p17_2015-10-06_11h39m_1444124371//000_FulltestROC_p17//readbackCal_C0.dat .. /home/mameinha/data/R421_Fulltest_p17_2015-10-06_11h39m_1444124371//000_FulltestROC_p17//readbackCal_C0.dat
[09:54:51.979] <TB3> INFO: ######################################################################
[09:54:51.979] <TB3> INFO: PixTestReadback::doTest()
[09:54:51.979] <TB3> INFO: ######################################################################
[09:54:51.980] <TB3> INFO: PixTestReadback::RES sent once
[09:55:03.112] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R421_Fulltest_p17_2015-10-06_11h39m_1444124371//000_FulltestROC_p17//readbackCal_C0.dat
[09:55:03.118] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[09:55:03.118] <TB3> INFO: PixTestReadback::RES sent once
[09:55:14.217] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R421_Fulltest_p17_2015-10-06_11h39m_1444124371//000_FulltestROC_p17//readbackCal_C0.dat
[09:55:14.223] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[09:55:14.223] <TB3> INFO: PixTestReadback::RES sent once
[09:55:22.552] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[09:55:22.552] <TB3> INFO: Vbg will be calibrated using Vd calibration
[09:55:22.552] <TB3> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 163.1calibrated Vbg = 1.22789 :::*/*/*/*/
[09:55:22.929] <TB3> INFO: PixTestReadback::RES sent once
[09:55:31.769] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R421_Fulltest_p17_2015-10-06_11h39m_1444124371//000_FulltestROC_p17//readbackCal_C0.dat
[09:55:31.774] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[09:55:31.774] <TB3> INFO: PixTestReadback::doTest() done
[09:55:31.807] <TB3> INFO: enter test to run
[09:55:31.807] <TB3> INFO: test: no parameter change
[09:55:31.837] <TB3> QUIET: Connection to board 71 closed.
[09:55:31.916] <TB3> INFO: pXar: this is the end, my friend