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

[15:56:14.606] <TB3> INFO: PixTestSetup:: pg set to RES|TOK
[15:56:14.606] <TB3> INFO: 0 1 2 3 4 5 6 7
[15:56:17.649] <TB3> INFO: 0: 000 000 004 07c 7f0 f00 000 000
[15:56:20.662] <TB3> INFO: 1: 000 000 004 07c <7f8>[*] f80 800 000
[15:56:23.676] <TB3> INFO: 2: 000 000 004 07c <7f8>[*] f80 800 000
[15:56:26.689] <TB3> INFO: 3: 000 000 004 07c <7f8>[*] f80 800 000
[15:56:29.703] <TB3> INFO: 4: 800 000 000 03c 3f8 f80 800 000
[15:56:32.716] <TB3> INFO: 5: 800 000 000 03c 3fc f80 c00 000
[15:56:35.729] <TB3> INFO: 6: 000 000 000 03c 3fc fc0 c00 000
[15:56:38.742] <TB3> INFO: 7: 000 000 000 03c 3fc fc0 c00 000
[15:56:41.755] <TB3> INFO: 8: c00 000 000 03c 3fc fc0 c00 000
[15:56:44.767] <TB3> INFO: 9: 000 000 000 01c 3fc fc0 c00 000
[15:56:47.780] <TB3> INFO: 10: 000 000 000 01c 1fc fc0 c00 000
[15:56:50.794] <TB3> INFO: 11: 000 000 000 01c 1fc fe0 e00 000
[15:56:53.807] <TB3> INFO: 12: 000 000 000 01c 1fc fe0 e00 000
[15:56:56.820] <TB3> INFO: 13: 000 000 000 01c 1fc fe0 e00 000
[15:56:59.832] <TB3> INFO: 14: e00 000 000 00c 0fc fe0 e00 000
[15:57:02.845] <TB3> INFO: 15: 000 000 000 00c 0fc ff0 f00 000
[15:57:05.858] <TB3> INFO: 16: 000 000 000 00c 0fc ff0 f00 000
[15:57:08.871] <TB3> INFO: 17: 000 000 000 00c 0fc ff0 f00 000
[15:57:11.883] <TB3> INFO: 18: 000 000 000 00c 0fc ff0 f00 000
[15:57:14.896] <TB3> INFO: 19: 000 000 000 004 0fc ff0 f00 000
[15:57:15.303] <TB3> INFO: Found good delays at CLK = 2, DESER160 = 4
[15:57:15.305] <TB3> INFO: PixTestSetup:: Write Tb parameters to file.
[15:57:15.308] <TB3> INFO: write dtb parameters into /home/mameinha/data/R414_Fulltest_p17_2015-10-05_17h56m_1444060561//000_FulltestROC_p17//tbParameters.dat
[15:57:15.311] <TB3> INFO: PixTestSetup::doTest() done for.
[15:57:15.335] <TB3> INFO: enter test to run
[15:57:15.335] <TB3> INFO: test: Pretest no parameter change
[15:57:15.335] <TB3> INFO: running: pretest
[15:57:15.336] <TB3> INFO: ----------------------------------------------------------------------
[15:57:15.336] <TB3> INFO: PixTestPretest::programROC()
[15:57:15.336] <TB3> INFO: ----------------------------------------------------------------------
[15:57:18.338] <TB3> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[15:57:18.338] <TB3> INFO: IA differences per ROC: 19.3
[15:57:18.343] <TB3> INFO: enter test to run
[15:57:18.343] <TB3> INFO: test: Pretest no parameter change
[15:57:18.343] <TB3> INFO: running: pretest
[15:57:18.344] <TB3> INFO: ----------------------------------------------------------------------
[15:57:18.344] <TB3> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[15:57:18.344] <TB3> INFO: ----------------------------------------------------------------------
[15:57:18.954] <TB3> INFO: PixTestPretest::setVana() done, Module Ia 24.1 mA = 24.1 mA/ROC
[15:57:18.954] <TB3> INFO: i(loss) [mA/ROC]: 18.5
[15:57:18.957] <TB3> INFO: enter test to run
[15:57:18.957] <TB3> INFO: test: Pretest no parameter change
[15:57:18.957] <TB3> INFO: running: pretest
[15:57:18.958] <TB3> INFO: ----------------------------------------------------------------------
[15:57:18.958] <TB3> INFO: PixTestPretest::findWorkingPixel()
[15:57:18.958] <TB3> INFO: ----------------------------------------------------------------------
[15:57:18.968] <TB3> INFO: Expecting 231680 events.
[15:57:21.164] <TB3> INFO: 231680 events read in total (1809ms).
[15:57:21.166] <TB3> INFO: Test took 2208ms.
[15:57:21.545] <TB3> INFO: Found working pixel in all ROCs: col/row = 12/22
[15:57:21.550] <TB3> INFO: enter test to run
[15:57:21.550] <TB3> INFO: test: Pretest no parameter change
[15:57:21.550] <TB3> INFO: running: pretest
[15:57:21.552] <TB3> INFO: ----------------------------------------------------------------------
[15:57:21.552] <TB3> INFO: PixTestPretest::setVthrCompCalDel()
[15:57:21.552] <TB3> INFO: ----------------------------------------------------------------------
[15:57:21.561] <TB3> INFO: Expecting 231680 events.
[15:57:23.750] <TB3> INFO: 231680 events read in total (1802ms).
[15:57:23.752] <TB3> INFO: Test took 2200ms.
[15:57:24.133] <TB3> INFO: PixTestPretest::setVthrCompCalDel() done
[15:57:24.133] <TB3> INFO: CalDel: 142
[15:57:24.133] <TB3> INFO: VthrComp: 51
[15:57:24.136] <TB3> INFO: enter test to run
[15:57:24.136] <TB3> INFO: test: Pretest no parameter change
[15:57:24.136] <TB3> INFO: running: pretest
[15:57:24.189] <TB3> INFO: write dac parameters into /home/mameinha/data/R414_Fulltest_p17_2015-10-05_17h56m_1444060561//000_FulltestROC_p17//dacParameters_C0.dat
[15:57:24.192] <TB3> INFO: enter test to run
[15:57:24.192] <TB3> INFO: test: PixelAlive no parameter change
[15:57:24.192] <TB3> INFO: running: pixelalive
[15:57:24.194] <TB3> INFO: ######################################################################
[15:57:24.194] <TB3> INFO: PixTestAlive::doTest()
[15:57:24.194] <TB3> INFO: ######################################################################
[15:57:24.195] <TB3> INFO: ----------------------------------------------------------------------
[15:57:24.195] <TB3> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[15:57:24.195] <TB3> INFO: ----------------------------------------------------------------------
[15:57:24.214] <TB3> INFO: Expecting 41600 events.
[15:57:25.011] <TB3> INFO: 41600 events read in total (410ms).
[15:57:25.012] <TB3> INFO: Test took 817ms.
[15:57:25.012] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:57:25.397] <TB3> INFO: PixTestAlive::aliveTest() done
[15:57:25.397] <TB3> INFO: number of dead pixels (per ROC): 0
[15:57:25.398] <TB3> INFO: ----------------------------------------------------------------------
[15:57:25.398] <TB3> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[15:57:25.398] <TB3> INFO: ----------------------------------------------------------------------
[15:57:25.417] <TB3> INFO: Expecting 41600 events.
[15:57:26.159] <TB3> INFO: 41600 events read in total (354ms).
[15:57:26.159] <TB3> INFO: Test took 760ms.
[15:57:26.160] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:57:26.160] <TB3> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[15:57:26.549] <TB3> INFO: PixTestAlive::maskTest() done
[15:57:26.549] <TB3> INFO: number of mask-defect pixels (per ROC): 0
[15:57:26.550] <TB3> INFO: ----------------------------------------------------------------------
[15:57:26.550] <TB3> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[15:57:26.550] <TB3> INFO: ----------------------------------------------------------------------
[15:57:26.569] <TB3> INFO: Expecting 41600 events.
[15:57:27.365] <TB3> INFO: 41600 events read in total (409ms).
[15:57:27.366] <TB3> INFO: Test took 815ms.
[15:57:27.366] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:57:27.751] <TB3> INFO: PixTestAlive::addressDecodingTest() done
[15:57:27.751] <TB3> INFO: number of address-decoding pixels (per ROC): 0
[15:57:27.751] <TB3> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[15:57:27.752] <TB3> INFO: enter test to run
[15:57:27.752] <TB3> INFO: test: Scurves no parameter change
[15:57:27.752] <TB3> INFO: running: scurves
[15:57:27.753] <TB3> INFO: ######################################################################
[15:57:27.753] <TB3> INFO: PixTestScurves::doTest() ntrig = 50
[15:57:27.753] <TB3> INFO: ######################################################################
[15:57:27.753] <TB3> INFO: ----------------------------------------------------------------------
[15:57:27.753] <TB3> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[15:57:27.753] <TB3> INFO: ----------------------------------------------------------------------
[15:57:27.753] <TB3> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[15:57:27.764] <TB3> INFO: dacScan split into 1 runs with ntrig = 50
[15:57:27.764] <TB3> INFO: run 1 of 1
[15:57:27.783] <TB3> INFO: Expecting 41808000 events.
[15:59:41.875] <TB3> INFO: 19223750 events read in total (133705ms).
[16:01:52.600] <TB3> INFO: 38008300 events read in total (264430ms).
[16:02:19.090] <TB3> INFO: 41808000 events read in total (290920ms).
[16:02:19.121] <TB3> INFO: Test took 291358ms.
[16:02:19.146] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:02:20.591] <TB3> INFO: PixTestScurves::scurves() done
[16:02:20.591] <TB3> INFO: Vcal mean: 75.51
[16:02:20.591] <TB3> INFO: Vcal RMS: 4.70
[16:02:20.596] <TB3> INFO: enter test to run
[16:02:20.597] <TB3> INFO: test: Trim no parameter change
[16:02:20.597] <TB3> INFO: running: trim
[16:02:20.598] <TB3> INFO: ######################################################################
[16:02:20.598] <TB3> INFO: PixTestTrim::doTest()
[16:02:20.598] <TB3> INFO: ######################################################################
[16:02:20.600] <TB3> INFO: ----------------------------------------------------------------------
[16:02:20.600] <TB3> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[16:02:20.600] <TB3> INFO: ----------------------------------------------------------------------
[16:02:20.604] <TB3> INFO: ---> VthrComp thr map (minimal VthrComp)
[16:02:20.604] <TB3> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[16:02:20.612] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:02:20.612] <TB3> INFO: run 1 of 1
[16:02:20.631] <TB3> INFO: Expecting 6281600 events.
[16:03:05.948] <TB3> INFO: 6281600 events read in total (44930ms).
[16:03:05.967] <TB3> INFO: Test took 45355ms.
[16:03:05.974] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:03:07.019] <TB3> INFO: ROC 0 VthrComp = 79
[16:03:07.019] <TB3> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[16:03:07.019] <TB3> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[16:03:07.027] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:03:07.027] <TB3> INFO: run 1 of 1
[16:03:07.046] <TB3> INFO: Expecting 6281600 events.
[16:03:55.706] <TB3> INFO: 6281600 events read in total (48273ms).
[16:03:55.751] <TB3> INFO: Test took 48724ms.
[16:03:55.771] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:03:57.027] <TB3> INFO: roc 0 with ID = 0 has maximal Vcal 59.2023 for pixel 3/79 mean/min/max = 47.0595/34.7981/59.3208
[16:03:57.036] <TB3> INFO: Expecting 514560 events.
[16:04:00.995] <TB3> INFO: 514560 events read in total (3572ms).
[16:04:00.999] <TB3> INFO: Test took 3972ms.
[16:04:01.389] <TB3> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[16:04:01.396] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:04:01.396] <TB3> INFO: run 1 of 1
[16:04:01.415] <TB3> INFO: Expecting 6281600 events.
[16:04:50.247] <TB3> INFO: 6281600 events read in total (48445ms).
[16:04:50.294] <TB3> INFO: Test took 48898ms.
[16:04:50.315] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:51.547] <TB3> INFO: ---> TrimStepCorr4 extremal thresholds: 12.674559 .. 47.910182
[16:04:51.551] <TB3> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 2 .. 57 (-1/-1) hits flags = 528 (plus default)
[16:04:51.559] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:04:51.559] <TB3> INFO: run 1 of 1
[16:04:51.578] <TB3> INFO: Expecting 2329600 events.
[16:05:09.279] <TB3> INFO: 2329600 events read in total (17314ms).
[16:05:09.288] <TB3> INFO: Test took 17729ms.
[16:05:09.293] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:05:10.105] <TB3> INFO: ---> TrimStepCorr2 extremal thresholds: 22.018618 .. 42.410754
[16:05:10.109] <TB3> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 12 .. 52 (-1/-1) hits flags = 528 (plus default)
[16:05:10.117] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:05:10.117] <TB3> INFO: run 1 of 1
[16:05:10.136] <TB3> INFO: Expecting 1705600 events.
[16:05:23.347] <TB3> INFO: 1705600 events read in total (12824ms).
[16:05:23.354] <TB3> INFO: Test took 13237ms.
[16:05:23.358] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:05:24.124] <TB3> INFO: ---> TrimStepCorr1a extremal thresholds: 26.679523 .. 38.056545
[16:05:24.129] <TB3> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 16 .. 48 (-1/-1) hits flags = 528 (plus default)
[16:05:24.136] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:05:24.136] <TB3> INFO: run 1 of 1
[16:05:24.155] <TB3> INFO: Expecting 1372800 events.
[16:05:34.927] <TB3> INFO: 1372800 events read in total (10385ms).
[16:05:34.933] <TB3> INFO: Test took 10797ms.
[16:05:34.936] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:05:35.675] <TB3> INFO: ---> TrimStepCorr1b extremal thresholds: 27.630582 .. 38.056545
[16:05:35.679] <TB3> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 17 .. 48 (-1/-1) hits flags = 528 (plus default)
[16:05:35.687] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:05:35.687] <TB3> INFO: run 1 of 1
[16:05:35.706] <TB3> INFO: Expecting 1331200 events.
[16:05:46.200] <TB3> INFO: 1331200 events read in total (10107ms).
[16:05:46.206] <TB3> INFO: Test took 10519ms.
[16:05:46.209] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:05:46.935] <TB3> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[16:05:46.935] <TB3> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[16:05:46.942] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:05:46.942] <TB3> INFO: run 1 of 1
[16:05:46.961] <TB3> INFO: Expecting 1705600 events.
[16:06:00.322] <TB3> INFO: 1705600 events read in total (12974ms).
[16:06:00.330] <TB3> INFO: Test took 13388ms.
[16:06:00.334] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:06:01.121] <TB3> INFO: write dac parameters into /home/mameinha/data/R414_Fulltest_p17_2015-10-05_17h56m_1444060561//000_FulltestROC_p17//dacParameters35_C0.dat
[16:06:01.126] <TB3> INFO: write trim parameters into /home/mameinha/data/R414_Fulltest_p17_2015-10-05_17h56m_1444060561//000_FulltestROC_p17//trimParameters35_C0.dat
[16:06:01.136] <TB3> INFO: PixTestTrim::trimTest() done
[16:06:01.136] <TB3> INFO: vtrim: 96
[16:06:01.136] <TB3> INFO: vthrcomp: 79
[16:06:01.136] <TB3> INFO: vcal mean: 35.02
[16:06:01.137] <TB3> INFO: vcal RMS: 0.75
[16:06:01.137] <TB3> INFO: bits mean: 8.56
[16:06:01.137] <TB3> INFO: bits RMS: 2.66
[16:06:01.140] <TB3> INFO: ----------------------------------------------------------------------
[16:06:01.140] <TB3> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[16:06:01.140] <TB3> INFO: ----------------------------------------------------------------------
[16:06:01.140] <TB3> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[16:06:01.148] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:06:01.148] <TB3> INFO: run 1 of 1
[16:06:01.167] <TB3> INFO: Expecting 8320000 events.
[16:07:03.070] <TB3> INFO: 8320000 events read in total (61516ms).
[16:07:03.105] <TB3> INFO: Test took 61958ms.
[16:07:03.131] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:07:04.580] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 135 (-1/-1) hits flags = 528 (plus default)
[16:07:04.588] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:07:04.588] <TB3> INFO: run 1 of 1
[16:07:04.607] <TB3> INFO: Expecting 5657600 events.
[16:07:46.239] <TB3> INFO: 5657600 events read in total (41245ms).
[16:07:46.259] <TB3> INFO: Test took 41671ms.
[16:07:46.270] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:07:47.432] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 125 (-1/-1) hits flags = 528 (plus default)
[16:07:47.440] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:07:47.440] <TB3> INFO: run 1 of 1
[16:07:47.459] <TB3> INFO: Expecting 5241600 events.
[16:08:25.854] <TB3> INFO: 5241600 events read in total (38008ms).
[16:08:25.870] <TB3> INFO: Test took 38430ms.
[16:08:25.878] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:08:26.976] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 126 (-1/-1) hits flags = 528 (plus default)
[16:08:26.984] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:08:26.984] <TB3> INFO: run 1 of 1
[16:08:27.003] <TB3> INFO: Expecting 5283200 events.
[16:09:05.736] <TB3> INFO: 5283200 events read in total (38346ms).
[16:09:05.752] <TB3> INFO: Test took 38768ms.
[16:09:05.761] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:09:06.855] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 125 (-1/-1) hits flags = 528 (plus default)
[16:09:06.863] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[16:09:06.863] <TB3> INFO: run 1 of 1
[16:09:06.882] <TB3> INFO: Expecting 5241600 events.
[16:09:45.253] <TB3> INFO: 5241600 events read in total (37984ms).
[16:09:45.269] <TB3> INFO: Test took 38406ms.
[16:09:45.278] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:09:46.370] <TB3> INFO: PixTestTrim::trimBitTest() done
[16:09:46.371] <TB3> INFO: PixTestTrim::doTest() done, duration: 445 seconds
[16:09:46.411] <TB3> INFO: enter test to run
[16:09:46.411] <TB3> INFO: test: PhOptimization no parameter change
[16:09:46.411] <TB3> INFO: running: phoptimization
[16:09:46.411] <TB3> INFO: ######################################################################
[16:09:46.411] <TB3> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[16:09:46.411] <TB3> INFO: ######################################################################
[16:09:46.432] <TB3> INFO: Expecting 41600 events.
[16:09:47.226] <TB3> INFO: 41600 events read in total (407ms).
[16:09:47.226] <TB3> INFO: Test took 813ms.
[16:09:47.226] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:09:47.617] <TB3> INFO: Expecting 41600 events.
[16:09:48.414] <TB3> INFO: 41600 events read in total (410ms).
[16:09:48.415] <TB3> INFO: Test took 1188ms.
[16:09:48.415] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:09:48.804] <TB3> INFO: Expecting 41600 events.
[16:09:49.601] <TB3> INFO: 41600 events read in total (410ms).
[16:09:49.602] <TB3> INFO: Test took 1186ms.
[16:09:49.602] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[16:09:49.991] <TB3> INFO: Expecting 2560 events.
[16:09:50.409] <TB3> INFO: 2560 events read in total (31ms).
[16:09:50.409] <TB3> INFO: Test took 807ms.
[16:09:50.804] <TB3> INFO: Expecting 655360 events.
[16:09:56.020] <TB3> INFO: 655360 events read in total (4829ms).
[16:09:56.029] <TB3> INFO: Test took 5620ms.
[16:09:56.321] <TB3> INFO: Expecting 655360 events.
[16:10:01.538] <TB3> INFO: 655360 events read in total (4830ms).
[16:10:01.547] <TB3> INFO: Test took 5505ms.
[16:10:01.566] <TB3> INFO: safety margin for low PH: adding 0, margin is now 20
[16:10:01.580] <TB3> INFO: write dac parameters into /home/mameinha/data/R414_Fulltest_p17_2015-10-05_17h56m_1444060561//000_FulltestROC_p17//dacParameters35_C0.dat
[16:10:01.837] <TB3> INFO: Expecting 41600 events.
[16:10:02.597] <TB3> INFO: 41600 events read in total (373ms).
[16:10:02.597] <TB3> INFO: Test took 1015ms.
[16:10:02.987] <TB3> INFO: Expecting 41600 events.
[16:10:03.747] <TB3> INFO: 41600 events read in total (373ms).
[16:10:03.747] <TB3> INFO: Test took 1149ms.
[16:10:04.136] <TB3> INFO: Expecting 41600 events.
[16:10:04.897] <TB3> INFO: 41600 events read in total (374ms).
[16:10:04.897] <TB3> INFO: Test took 1149ms.
[16:10:05.286] <TB3> INFO: Expecting 2560 events.
[16:10:05.704] <TB3> INFO: 2560 events read in total (31ms).
[16:10:05.704] <TB3> INFO: Test took 806ms.
[16:10:06.099] <TB3> INFO: Expecting 2560 events.
[16:10:06.517] <TB3> INFO: 2560 events read in total (31ms).
[16:10:06.517] <TB3> INFO: Test took 812ms.
[16:10:06.925] <TB3> INFO: PixTestPhOptimization::doTest() done, duration: 20 seconds
[16:10:06.925] <TB3> INFO: PH scale (per ROC): 75
[16:10:06.925] <TB3> INFO: PH offset (per ROC): 174
[16:10:06.938] <TB3> INFO: enter test to run
[16:10:06.938] <TB3> INFO: test: GainPedestal no parameter change
[16:10:06.938] <TB3> INFO: running: gainpedestal
[16:10:06.940] <TB3> INFO: ######################################################################
[16:10:06.940] <TB3> INFO: PixTestGainPedestal::doTest() ntrig = 10
[16:10:06.940] <TB3> INFO: ######################################################################
[16:10:06.947] <TB3> INFO: scanning low vcal = 10
[16:10:06.968] <TB3> INFO: Expecting 41600 events.
[16:10:08.056] <TB3> INFO: 41600 events read in total (701ms).
[16:10:08.056] <TB3> INFO: Test took 1109ms.
[16:10:08.057] <TB3> INFO: scanning low vcal = 20
[16:10:08.451] <TB3> INFO: Expecting 41600 events.
[16:10:09.540] <TB3> INFO: 41600 events read in total (702ms).
[16:10:09.540] <TB3> INFO: Test took 1483ms.
[16:10:09.540] <TB3> INFO: scanning low vcal = 30
[16:10:09.935] <TB3> INFO: Expecting 41600 events.
[16:10:11.024] <TB3> INFO: 41600 events read in total (702ms).
[16:10:11.024] <TB3> INFO: Test took 1484ms.
[16:10:11.024] <TB3> INFO: scanning low vcal = 40
[16:10:11.419] <TB3> INFO: Expecting 41600 events.
[16:10:12.542] <TB3> INFO: 41600 events read in total (736ms).
[16:10:12.542] <TB3> INFO: Test took 1518ms.
[16:10:12.542] <TB3> INFO: scanning low vcal = 50
[16:10:12.931] <TB3> INFO: Expecting 41600 events.
[16:10:14.056] <TB3> INFO: 41600 events read in total (738ms).
[16:10:14.056] <TB3> INFO: Test took 1514ms.
[16:10:14.056] <TB3> INFO: scanning low vcal = 60
[16:10:14.445] <TB3> INFO: Expecting 41600 events.
[16:10:15.569] <TB3> INFO: 41600 events read in total (737ms).
[16:10:15.569] <TB3> INFO: Test took 1513ms.
[16:10:15.570] <TB3> INFO: scanning low vcal = 70
[16:10:15.958] <TB3> INFO: Expecting 41600 events.
[16:10:17.082] <TB3> INFO: 41600 events read in total (737ms).
[16:10:17.083] <TB3> INFO: Test took 1513ms.
[16:10:17.083] <TB3> INFO: scanning low vcal = 80
[16:10:17.472] <TB3> INFO: Expecting 41600 events.
[16:10:18.605] <TB3> INFO: 41600 events read in total (746ms).
[16:10:18.605] <TB3> INFO: Test took 1522ms.
[16:10:18.606] <TB3> INFO: scanning low vcal = 90
[16:10:18.994] <TB3> INFO: Expecting 41600 events.
[16:10:20.118] <TB3> INFO: 41600 events read in total (737ms).
[16:10:20.119] <TB3> INFO: Test took 1513ms.
[16:10:20.119] <TB3> INFO: scanning low vcal = 100
[16:10:20.508] <TB3> INFO: Expecting 41600 events.
[16:10:21.641] <TB3> INFO: 41600 events read in total (746ms).
[16:10:21.641] <TB3> INFO: Test took 1522ms.
[16:10:21.641] <TB3> INFO: scanning low vcal = 110
[16:10:22.030] <TB3> INFO: Expecting 41600 events.
[16:10:23.155] <TB3> INFO: 41600 events read in total (738ms).
[16:10:23.155] <TB3> INFO: Test took 1514ms.
[16:10:23.155] <TB3> INFO: scanning low vcal = 120
[16:10:23.544] <TB3> INFO: Expecting 41600 events.
[16:10:24.668] <TB3> INFO: 41600 events read in total (737ms).
[16:10:24.669] <TB3> INFO: Test took 1514ms.
[16:10:24.669] <TB3> INFO: scanning low vcal = 130
[16:10:25.058] <TB3> INFO: Expecting 41600 events.
[16:10:26.182] <TB3> INFO: 41600 events read in total (737ms).
[16:10:26.183] <TB3> INFO: Test took 1514ms.
[16:10:26.183] <TB3> INFO: scanning low vcal = 140
[16:10:26.572] <TB3> INFO: Expecting 41600 events.
[16:10:27.696] <TB3> INFO: 41600 events read in total (737ms).
[16:10:27.697] <TB3> INFO: Test took 1514ms.
[16:10:27.697] <TB3> INFO: scanning low vcal = 150
[16:10:28.086] <TB3> INFO: Expecting 41600 events.
[16:10:29.210] <TB3> INFO: 41600 events read in total (737ms).
[16:10:29.211] <TB3> INFO: Test took 1514ms.
[16:10:29.211] <TB3> INFO: scanning low vcal = 160
[16:10:29.600] <TB3> INFO: Expecting 41600 events.
[16:10:30.724] <TB3> INFO: 41600 events read in total (737ms).
[16:10:30.724] <TB3> INFO: Test took 1513ms.
[16:10:30.724] <TB3> INFO: scanning low vcal = 170
[16:10:31.113] <TB3> INFO: Expecting 41600 events.
[16:10:32.237] <TB3> INFO: 41600 events read in total (737ms).
[16:10:32.238] <TB3> INFO: Test took 1514ms.
[16:10:32.238] <TB3> INFO: scanning low vcal = 180
[16:10:32.627] <TB3> INFO: Expecting 41600 events.
[16:10:33.751] <TB3> INFO: 41600 events read in total (737ms).
[16:10:33.751] <TB3> INFO: Test took 1513ms.
[16:10:33.752] <TB3> INFO: scanning low vcal = 190
[16:10:34.140] <TB3> INFO: Expecting 41600 events.
[16:10:35.265] <TB3> INFO: 41600 events read in total (738ms).
[16:10:35.265] <TB3> INFO: Test took 1513ms.
[16:10:35.265] <TB3> INFO: scanning low vcal = 200
[16:10:35.654] <TB3> INFO: Expecting 41600 events.
[16:10:36.779] <TB3> INFO: 41600 events read in total (738ms).
[16:10:36.780] <TB3> INFO: Test took 1515ms.
[16:10:36.780] <TB3> INFO: scanning low vcal = 210
[16:10:37.169] <TB3> INFO: Expecting 41600 events.
[16:10:38.293] <TB3> INFO: 41600 events read in total (737ms).
[16:10:38.294] <TB3> INFO: Test took 1514ms.
[16:10:38.294] <TB3> INFO: scanning low vcal = 220
[16:10:38.683] <TB3> INFO: Expecting 41600 events.
[16:10:39.807] <TB3> INFO: 41600 events read in total (737ms).
[16:10:39.807] <TB3> INFO: Test took 1513ms.
[16:10:39.808] <TB3> INFO: scanning low vcal = 230
[16:10:40.196] <TB3> INFO: Expecting 41600 events.
[16:10:41.320] <TB3> INFO: 41600 events read in total (737ms).
[16:10:41.321] <TB3> INFO: Test took 1513ms.
[16:10:41.321] <TB3> INFO: scanning low vcal = 240
[16:10:41.710] <TB3> INFO: Expecting 41600 events.
[16:10:42.833] <TB3> INFO: 41600 events read in total (736ms).
[16:10:42.834] <TB3> INFO: Test took 1513ms.
[16:10:42.834] <TB3> INFO: scanning low vcal = 250
[16:10:43.223] <TB3> INFO: Expecting 41600 events.
[16:10:44.347] <TB3> INFO: 41600 events read in total (737ms).
[16:10:44.348] <TB3> INFO: Test took 1514ms.
[16:10:44.348] <TB3> INFO: scanning high vcal = 30 (= 210 in low range)
[16:10:44.737] <TB3> INFO: Expecting 41600 events.
[16:10:45.862] <TB3> INFO: 41600 events read in total (738ms).
[16:10:45.862] <TB3> INFO: Test took 1514ms.
[16:10:45.862] <TB3> INFO: scanning high vcal = 50 (= 350 in low range)
[16:10:46.251] <TB3> INFO: Expecting 41600 events.
[16:10:47.375] <TB3> INFO: 41600 events read in total (737ms).
[16:10:47.376] <TB3> INFO: Test took 1514ms.
[16:10:47.376] <TB3> INFO: scanning high vcal = 70 (= 490 in low range)
[16:10:47.765] <TB3> INFO: Expecting 41600 events.
[16:10:48.889] <TB3> INFO: 41600 events read in total (737ms).
[16:10:48.890] <TB3> INFO: Test took 1514ms.
[16:10:48.890] <TB3> INFO: scanning high vcal = 90 (= 630 in low range)
[16:10:49.279] <TB3> INFO: Expecting 41600 events.
[16:10:50.403] <TB3> INFO: 41600 events read in total (737ms).
[16:10:50.403] <TB3> INFO: Test took 1513ms.
[16:10:50.404] <TB3> INFO: scanning high vcal = 200 (= 1400 in low range)
[16:10:50.792] <TB3> INFO: Expecting 41600 events.
[16:10:51.917] <TB3> INFO: 41600 events read in total (738ms).
[16:10:51.917] <TB3> INFO: Test took 1513ms.
[16:10:52.301] <TB3> INFO: PixTestGainPedestal::measure() done
[16:10:54.270] <TB3> INFO: PixTestGainPedestal::fit() done
[16:10:54.271] <TB3> INFO: non-linearity mean: 0.959
[16:10:54.271] <TB3> INFO: non-linearity RMS: 0.006
[16:10:54.271] <TB3> INFO: write gain/ped parameters into /home/mameinha/data/R414_Fulltest_p17_2015-10-05_17h56m_1444060561//000_FulltestROC_p17//phCalibrationFitErr35_C0.dat
[16:10:54.311] <TB3> INFO: PixTestGainPedestal::doTest() done, duration: 47 seconds
[16:10:54.311] <TB3> INFO: enter test to run
[16:10:54.311] <TB3> INFO: test: Readback no parameter change
[16:10:54.311] <TB3> INFO: running: readback
[16:10:54.312] <TB3> INFO: readReadbackCal: /home/mameinha/data/R414_Fulltest_p17_2015-10-05_17h56m_1444060561//000_FulltestROC_p17//readbackCal_C0.dat .. /home/mameinha/data/R414_Fulltest_p17_2015-10-05_17h56m_1444060561//000_FulltestROC_p17//readbackCal_C0.dat
[16:10:54.312] <TB3> INFO: ######################################################################
[16:10:54.312] <TB3> INFO: PixTestReadback::doTest()
[16:10:54.312] <TB3> INFO: ######################################################################
[16:10:54.313] <TB3> INFO: PixTestReadback::RES sent once
[16:11:05.436] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R414_Fulltest_p17_2015-10-05_17h56m_1444060561//000_FulltestROC_p17//readbackCal_C0.dat
[16:11:05.442] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[16:11:05.442] <TB3> INFO: PixTestReadback::RES sent once
[16:11:16.536] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R414_Fulltest_p17_2015-10-05_17h56m_1444060561//000_FulltestROC_p17//readbackCal_C0.dat
[16:11:16.542] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[16:11:16.542] <TB3> INFO: PixTestReadback::RES sent once
[16:11:24.868] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[16:11:24.869] <TB3> INFO: Vbg will be calibrated using Vd calibration
[16:11:24.869] <TB3> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 147.7calibrated Vbg = 1.23083 :::*/*/*/*/
[16:11:25.245] <TB3> INFO: PixTestReadback::RES sent once

[16:11:34.081] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R414_Fulltest_p17_2015-10-05_17h56m_1444060561//000_FulltestROC_p17//readbackCal_C0.dat
[16:11:34.086] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[16:11:34.086] <TB3> INFO: PixTestReadback::doTest() done
[16:11:34.121] <TB3> INFO: enter test to run
[16:11:34.121] <TB3> INFO: test: no parameter change
[16:11:34.149] <TB3> QUIET: Connection to board 71 closed.
[16:11:34.229] <TB3> INFO: pXar: this is the end, my friend