[13:07:54.139] <TB2> INFO: *** Welcome to pxar ***
[13:07:54.139] <TB2> INFO: *** Today: 2015/10/07
[13:07:55.394] <TB2> INFO: *** Version: 9da6
[13:07:55.394] <TB2> INFO: readRocDacs: /home/mameinha/data/R416_Fulltest_m20_2015-10-07_15h07m_1444223258//000_FulltestROC_m20//dacParameters_C0.dat .. /home/mameinha/data/R416_Fulltest_m20_2015-10-07_15h07m_1444223258//000_FulltestROC_m20//dacParameters_C0.dat
[13:07:55.397] <TB2> INFO: readTbmDacs: /home/mameinha/data/R416_Fulltest_m20_2015-10-07_15h07m_1444223258//000_FulltestROC_m20//tbmParameters_C0a.dat .. /home/mameinha/data/R416_Fulltest_m20_2015-10-07_15h07m_1444223258//000_FulltestROC_m20//tbmParameters_C4294967295b.dat
[13:07:55.397] <TB2> INFO: readMaskFile: /home/mameinha/data/R416_Fulltest_m20_2015-10-07_15h07m_1444223258//000_FulltestROC_m20//defaultMaskFile.dat
[13:07:55.398] <TB2> INFO: readTrimFile: /home/mameinha/data/R416_Fulltest_m20_2015-10-07_15h07m_1444223258//000_FulltestROC_m20//trimParameters_C0.dat .. /home/mameinha/data/R416_Fulltest_m20_2015-10-07_15h07m_1444223258//000_FulltestROC_m20//trimParameters_C0.dat
[13:07:55.404] <TB2> INFO: clk: 2
[13:07:55.404] <TB2> INFO: ctr: 2
[13:07:55.404] <TB2> INFO: sda: 17
[13:07:55.404] <TB2> INFO: tin: 7
[13:07:55.404] <TB2> INFO: level: 15
[13:07:55.404] <TB2> INFO: deser160phase: 4
[13:07:55.404] <TB2> QUIET: Instanciating API for pxar v2.6.0+20~g1a7f656
[13:07:55.404] <TB2> INFO: Log level: INFO
[13:07:55.410] <TB2> INFO: Found DTB DTB_WWXJGB
[13:07:55.418] <TB2> QUIET: Connection to board DTB_WWXJGB opened.
[13:07:55.422] <TB2> INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 137
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WWXJGB
MAC address: 40D855118089
Hostname: pixelDTB137
Comment:
------------------------------------------------------
[13:07:55.425] <TB2> INFO: RPC call hashes of host and DTB match: 398089610
[13:07:56.589] <TB2> INFO: DUT info:
[13:07:56.589] <TB2> INFO: The DUT currently contains the following objects:
[13:07:56.589] <TB2> INFO: 0 TBM Cores (0 ON)
[13:07:56.589] <TB2> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[13:07:56.589] <TB2> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[13:07:56.990] <TB2> INFO: enter 'restricted' command line mode
[13:07:56.990] <TB2> INFO: enter test to run
[13:07:56.990] <TB2> INFO: test: Setup no parameter change
[13:07:56.990] <TB2> INFO: running: setup
[13:07:56.995] <TB2> INFO: PixTestSetup::doTest() ntrig = 10

[13:07:56.995] <TB2> INFO: PixTestSetup:: pg set to RES|TOK
[13:07:56.995] <TB2> INFO: 0 1 2 3 4 5 6 7
[13:08:00.039] <TB2> INFO: 0: 000 008 08c 07c 7f0 f00 000 000
[13:08:03.052] <TB2> INFO: 1: 000 008 084 87c <7f8>[*] f80 800 000
[13:08:06.067] <TB2> INFO: 2: 000 008 084 87c <7f8>[*] f80 <7f8>[1] 000
[13:08:09.082] <TB2> INFO: 3: 000 000 004 07c <7f8>[*] f80 800 000
[13:08:12.097] <TB2> INFO: 4: 000 004 044 07c <7f8>[*] f80 800 000
[13:08:15.111] <TB2> INFO: 5: 000 004 040 43c 3f8 f80 800 000
[13:08:18.126] <TB2> INFO: 6: 000 004 040 43c 3fc fc0 c00 000
[13:08:21.141] <TB2> INFO: 7: 000 004 040 43c 3fc fc0 c00 000
[13:08:24.155] <TB2> INFO: 8: 000 000 000 03c 3fc fc0 c00 000
[13:08:27.170] <TB2> INFO: 9: 000 000 000 03c 3fc fc0 c00 000
[13:08:30.185] <TB2> INFO: 10: c00 000 000 01c 1fc fc0 c00 000
[13:08:33.199] <TB2> INFO: 11: c00 000 020 21c 1fc fe0 e00 000
[13:08:36.214] <TB2> INFO: 12: 000 000 020 21c 1fc fe0 e00 000
[13:08:39.228] <TB2> INFO: 13: e00 000 000 01c 1fc fe0 e00 000
[13:08:42.243] <TB2> INFO: 14: e00 000 000 11c 1fc fe0 e00 000
[13:08:45.256] <TB2> INFO: 15: 000 000 010 00c 0fc ff0 f00 000
[13:08:48.271] <TB2> INFO: 16: 000 000 010 10c 0fc ff0 f00 000
[13:08:51.285] <TB2> INFO: 17: 000 000 010 10c 0fc ff0 f00 000
[13:08:54.299] <TB2> INFO: 18: f00 000 000 00c 0fc ff0 f00 000
[13:08:57.314] <TB2> INFO: 19: 000 000 000 00c 8fc ff0 f00 000
[13:08:57.932] <TB2> INFO: Found good delays at CLK = 2, DESER160 = 4
[13:08:57.934] <TB2> INFO: PixTestSetup:: Write Tb parameters to file.
[13:08:57.942] <TB2> INFO: write dtb parameters into /home/mameinha/data/R416_Fulltest_m20_2015-10-07_15h07m_1444223258//000_FulltestROC_m20//tbParameters.dat
[13:08:57.950] <TB2> INFO: PixTestSetup::doTest() done for.
[13:08:57.984] <TB2> INFO: enter test to run
[13:08:57.984] <TB2> INFO: test: Pretest no parameter change
[13:08:57.984] <TB2> INFO: running: pretest
[13:08:57.986] <TB2> INFO: ----------------------------------------------------------------------
[13:08:57.986] <TB2> INFO: PixTestPretest::programROC()
[13:08:57.986] <TB2> INFO: ----------------------------------------------------------------------
[13:09:00.988] <TB2> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[13:09:00.988] <TB2> INFO: IA differences per ROC: 18.5
[13:09:00.994] <TB2> INFO: enter test to run
[13:09:00.994] <TB2> INFO: test: Pretest no parameter change
[13:09:00.994] <TB2> INFO: running: pretest
[13:09:00.996] <TB2> INFO: ----------------------------------------------------------------------
[13:09:00.996] <TB2> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[13:09:00.996] <TB2> INFO: ----------------------------------------------------------------------
[13:09:01.708] <TB2> INFO: PixTestPretest::setVana() done, Module Ia 24.1 mA = 24.1 mA/ROC
[13:09:01.708] <TB2> INFO: i(loss) [mA/ROC]: 20.1
[13:09:01.712] <TB2> INFO: enter test to run
[13:09:01.712] <TB2> INFO: test: Pretest no parameter change
[13:09:01.712] <TB2> INFO: running: pretest
[13:09:01.714] <TB2> INFO: ----------------------------------------------------------------------
[13:09:01.714] <TB2> INFO: PixTestPretest::findWorkingPixel()
[13:09:01.714] <TB2> INFO: ----------------------------------------------------------------------
[13:09:01.724] <TB2> INFO: Expecting 231680 events.
[13:09:04.005] <TB2> INFO: 231680 events read in total (1894ms).
[13:09:04.952] <TB2> INFO: Test took 3238ms.
[13:09:04.976] <TB2> INFO: Found working pixel in all ROCs: col/row = 12/22
[13:09:04.985] <TB2> INFO: enter test to run
[13:09:04.985] <TB2> INFO: test: Pretest no parameter change
[13:09:04.985] <TB2> INFO: running: pretest
[13:09:04.986] <TB2> INFO: ----------------------------------------------------------------------
[13:09:04.986] <TB2> INFO: PixTestPretest::setVthrCompCalDel()
[13:09:04.986] <TB2> INFO: ----------------------------------------------------------------------
[13:09:04.996] <TB2> INFO: Expecting 231680 events.
[13:09:07.294] <TB2> INFO: 231680 events read in total (1911ms).
[13:09:07.298] <TB2> INFO: Test took 2311ms.
[13:09:07.671] <TB2> INFO: PixTestPretest::setVthrCompCalDel() done
[13:09:07.672] <TB2> INFO: CalDel: 156
[13:09:07.672] <TB2> INFO: VthrComp: 51
[13:09:07.676] <TB2> INFO: enter test to run
[13:09:07.676] <TB2> INFO: test: Pretest no parameter change
[13:09:07.676] <TB2> INFO: running: pretest
[13:09:07.733] <TB2> INFO: write dac parameters into /home/mameinha/data/R416_Fulltest_m20_2015-10-07_15h07m_1444223258//000_FulltestROC_m20//dacParameters_C0.dat
[13:09:07.809] <TB2> INFO: enter test to run
[13:09:07.809] <TB2> INFO: test: PixelAlive no parameter change
[13:09:07.809] <TB2> INFO: running: pixelalive
[13:09:07.811] <TB2> INFO: ######################################################################
[13:09:07.811] <TB2> INFO: PixTestAlive::doTest()
[13:09:07.811] <TB2> INFO: ######################################################################
[13:09:07.813] <TB2> INFO: ----------------------------------------------------------------------
[13:09:07.813] <TB2> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[13:09:07.813] <TB2> INFO: ----------------------------------------------------------------------
[13:09:07.838] <TB2> INFO: Expecting 41600 events.
[13:09:08.653] <TB2> INFO: 41600 events read in total (428ms).
[13:09:08.654] <TB2> INFO: Test took 841ms.
[13:09:08.654] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:09:09.039] <TB2> INFO: PixTestAlive::aliveTest() done
[13:09:09.039] <TB2> INFO: number of dead pixels (per ROC): 0
[13:09:09.040] <TB2> INFO: ----------------------------------------------------------------------
[13:09:09.040] <TB2> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[13:09:09.040] <TB2> INFO: ----------------------------------------------------------------------
[13:09:09.068] <TB2> INFO: Expecting 41600 events.
[13:09:09.838] <TB2> INFO: 41600 events read in total (383ms).
[13:09:09.838] <TB2> INFO: Test took 797ms.
[13:09:09.838] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:09:09.838] <TB2> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[13:09:10.228] <TB2> INFO: PixTestAlive::maskTest() done
[13:09:10.228] <TB2> INFO: number of mask-defect pixels (per ROC): 0
[13:09:10.230] <TB2> INFO: ----------------------------------------------------------------------
[13:09:10.230] <TB2> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[13:09:10.230] <TB2> INFO: ----------------------------------------------------------------------
[13:09:10.261] <TB2> INFO: Expecting 41600 events.
[13:09:11.118] <TB2> INFO: 41600 events read in total (470ms).
[13:09:11.119] <TB2> INFO: Test took 889ms.
[13:09:11.120] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:09:11.504] <TB2> INFO: PixTestAlive::addressDecodingTest() done
[13:09:11.504] <TB2> INFO: number of address-decoding pixels (per ROC): 0
[13:09:11.504] <TB2> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[13:09:11.505] <TB2> INFO: enter test to run
[13:09:11.505] <TB2> INFO: test: Scurves no parameter change
[13:09:11.505] <TB2> INFO: running: scurves
[13:09:11.507] <TB2> INFO: ######################################################################
[13:09:11.507] <TB2> INFO: PixTestScurves::doTest() ntrig = 50
[13:09:11.507] <TB2> INFO: ######################################################################
[13:09:11.507] <TB2> INFO: ----------------------------------------------------------------------
[13:09:11.507] <TB2> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[13:09:11.507] <TB2> INFO: ----------------------------------------------------------------------
[13:09:11.507] <TB2> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[13:09:11.527] <TB2> INFO: dacScan split into 1 runs with ntrig = 50
[13:09:11.527] <TB2> INFO: run 1 of 1
[13:09:11.546] <TB2> INFO: Expecting 41808000 events.
[13:11:47.449] <TB2> INFO: 20359550 events read in total (155515ms).
[13:14:16.612] <TB2> INFO: 40401650 events read in total (304678ms).
[13:14:26.782] <TB2> INFO: 41808000 events read in total (314848ms).
[13:14:26.809] <TB2> INFO: Test took 315282ms.
[13:14:26.835] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:14:28.370] <TB2> INFO: PixTestScurves::scurves() done
[13:14:28.370] <TB2> INFO: Vcal mean: 89.14
[13:14:28.370] <TB2> INFO: Vcal RMS: 5.49
[13:14:28.374] <TB2> INFO: enter test to run
[13:14:28.374] <TB2> INFO: test: Trim no parameter change
[13:14:28.374] <TB2> INFO: running: trim
[13:14:28.376] <TB2> INFO: ######################################################################
[13:14:28.376] <TB2> INFO: PixTestTrim::doTest()
[13:14:28.376] <TB2> INFO: ######################################################################
[13:14:28.378] <TB2> INFO: ----------------------------------------------------------------------
[13:14:28.378] <TB2> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[13:14:28.378] <TB2> INFO: ----------------------------------------------------------------------
[13:14:28.384] <TB2> INFO: ---> VthrComp thr map (minimal VthrComp)
[13:14:28.384] <TB2> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[13:14:28.391] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:14:28.391] <TB2> INFO: run 1 of 1
[13:14:28.411] <TB2> INFO: Expecting 6281600 events.
[13:15:17.208] <TB2> INFO: 6281600 events read in total (48408ms).
[13:15:17.224] <TB2> INFO: Test took 48833ms.
[13:15:17.232] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:15:18.464] <TB2> INFO: ROC 0 VthrComp = 91
[13:15:18.465] <TB2> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[13:15:18.465] <TB2> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[13:15:18.472] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:15:18.472] <TB2> INFO: run 1 of 1
[13:15:18.492] <TB2> INFO: Expecting 6281600 events.
[13:16:11.736] <TB2> INFO: 6281600 events read in total (52857ms).
[13:16:11.785] <TB2> INFO: Test took 53313ms.
[13:16:11.804] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:16:13.184] <TB2> INFO: roc 0 with ID = 0 has maximal Vcal 60.1276 for pixel 3/1 mean/min/max = 46.2016/32.2733/60.1299
[13:16:13.193] <TB2> INFO: Expecting 514560 events.
[13:16:17.402] <TB2> INFO: 514560 events read in total (3822ms).
[13:16:17.406] <TB2> INFO: Test took 4222ms.
[13:16:17.804] <TB2> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[13:16:17.812] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:16:17.812] <TB2> INFO: run 1 of 1
[13:16:17.831] <TB2> INFO: Expecting 6281600 events.
[13:17:10.315] <TB2> INFO: 6281600 events read in total (52097ms).
[13:17:10.371] <TB2> INFO: Test took 52559ms.
[13:17:10.392] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:11.686] <TB2> INFO: ---> TrimStepCorr4 extremal thresholds: 12.569360 .. 50.677863
[13:17:11.691] <TB2> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 2 .. 60 (-1/-1) hits flags = 528 (plus default)
[13:17:11.698] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:17:11.698] <TB2> INFO: run 1 of 1
[13:17:11.718] <TB2> INFO: Expecting 2454400 events.
[13:17:31.094] <TB2> INFO: 2454400 events read in total (18989ms).
[13:17:31.105] <TB2> INFO: Test took 19407ms.
[13:17:31.110] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:31.949] <TB2> INFO: ---> TrimStepCorr2 extremal thresholds: 22.396551 .. 45.100272
[13:17:31.954] <TB2> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 12 .. 55 (-1/-1) hits flags = 528 (plus default)
[13:17:31.962] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:17:31.962] <TB2> INFO: run 1 of 1
[13:17:31.981] <TB2> INFO: Expecting 1830400 events.
[13:17:47.316] <TB2> INFO: 1830400 events read in total (14948ms).
[13:17:47.326] <TB2> INFO: Test took 15364ms.
[13:17:47.331] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:48.164] <TB2> INFO: ---> TrimStepCorr1a extremal thresholds: 26.395602 .. 41.951289
[13:17:48.169] <TB2> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 16 .. 51 (-1/-1) hits flags = 528 (plus default)
[13:17:48.177] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:17:48.177] <TB2> INFO: run 1 of 1
[13:17:48.196] <TB2> INFO: Expecting 1497600 events.
[13:18:00.483] <TB2> INFO: 1497600 events read in total (11900ms).
[13:18:00.493] <TB2> INFO: Test took 12316ms.
[13:18:00.498] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:18:01.383] <TB2> INFO: ---> TrimStepCorr1b extremal thresholds: 28.290902 .. 41.316736
[13:18:01.390] <TB2> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 18 .. 51 (-1/-1) hits flags = 528 (plus default)
[13:18:01.401] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:18:01.401] <TB2> INFO: run 1 of 1
[13:18:01.424] <TB2> INFO: Expecting 1414400 events.
[13:18:13.066] <TB2> INFO: 1414400 events read in total (11255ms).
[13:18:13.077] <TB2> INFO: Test took 11676ms.
[13:18:13.084] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:18:13.914] <TB2> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[13:18:13.914] <TB2> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[13:18:13.922] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:18:13.922] <TB2> INFO: run 1 of 1
[13:18:13.942] <TB2> INFO: Expecting 1705600 events.
[13:18:27.672] <TB2> INFO: 1705600 events read in total (13343ms).
[13:18:27.680] <TB2> INFO: Test took 13758ms.
[13:18:27.685] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:18:28.507] <TB2> INFO: write dac parameters into /home/mameinha/data/R416_Fulltest_m20_2015-10-07_15h07m_1444223258//000_FulltestROC_m20//dacParameters35_C0.dat
[13:18:28.513] <TB2> INFO: write trim parameters into /home/mameinha/data/R416_Fulltest_m20_2015-10-07_15h07m_1444223258//000_FulltestROC_m20//trimParameters35_C0.dat
[13:18:28.525] <TB2> INFO: PixTestTrim::trimTest() done
[13:18:28.525] <TB2> INFO: vtrim: 109
[13:18:28.525] <TB2> INFO: vthrcomp: 91
[13:18:28.525] <TB2> INFO: vcal mean: 34.97
[13:18:28.525] <TB2> INFO: vcal RMS: 0.76
[13:18:28.525] <TB2> INFO: bits mean: 9.16
[13:18:28.525] <TB2> INFO: bits RMS: 2.76
[13:18:28.530] <TB2> INFO: ----------------------------------------------------------------------
[13:18:28.530] <TB2> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[13:18:28.530] <TB2> INFO: ----------------------------------------------------------------------
[13:18:28.530] <TB2> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[13:18:28.538] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:18:28.538] <TB2> INFO: run 1 of 1
[13:18:28.557] <TB2> INFO: Expecting 8320000 events.
[13:19:35.259] <TB2> INFO: 8320000 events read in total (66315ms).
[13:19:35.302] <TB2> INFO: Test took 66764ms.
[13:19:35.319] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:19:36.832] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 152 (-1/-1) hits flags = 528 (plus default)
[13:19:36.840] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:19:36.840] <TB2> INFO: run 1 of 1
[13:19:36.860] <TB2> INFO: Expecting 6364800 events.
[13:20:25.298] <TB2> INFO: 6364800 events read in total (48051ms).
[13:20:25.320] <TB2> INFO: Test took 48480ms.
[13:20:25.330] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:20:26.592] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 141 (-1/-1) hits flags = 528 (plus default)
[13:20:26.599] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:20:26.599] <TB2> INFO: run 1 of 1
[13:20:26.619] <TB2> INFO: Expecting 5907200 events.
[13:21:11.126] <TB2> INFO: 5907200 events read in total (44120ms).
[13:21:11.145] <TB2> INFO: Test took 44545ms.
[13:21:11.155] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:21:12.408] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 141 (-1/-1) hits flags = 528 (plus default)
[13:21:12.416] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:21:12.416] <TB2> INFO: run 1 of 1
[13:21:12.435] <TB2> INFO: Expecting 5907200 events.
[13:21:56.953] <TB2> INFO: 5907200 events read in total (44131ms).
[13:21:56.969] <TB2> INFO: Test took 44553ms.
[13:21:56.977] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:21:58.174] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 142 (-1/-1) hits flags = 528 (plus default)
[13:21:58.181] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:21:58.181] <TB2> INFO: run 1 of 1
[13:21:58.203] <TB2> INFO: Expecting 5948800 events.
[13:22:45.194] <TB2> INFO: 5948800 events read in total (46604ms).
[13:22:45.213] <TB2> INFO: Test took 47032ms.
[13:22:45.224] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:22:46.784] <TB2> INFO: PixTestTrim::trimBitTest() done
[13:22:46.786] <TB2> INFO: PixTestTrim::doTest() done, duration: 498 seconds
[13:22:46.847] <TB2> INFO: enter test to run
[13:22:46.847] <TB2> INFO: test: PhOptimization no parameter change
[13:22:46.847] <TB2> INFO: running: phoptimization
[13:22:46.847] <TB2> INFO: ######################################################################
[13:22:46.847] <TB2> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[13:22:46.847] <TB2> INFO: ######################################################################
[13:22:46.870] <TB2> INFO: Expecting 41600 events.
[13:22:47.703] <TB2> INFO: 41600 events read in total (446ms).
[13:22:47.703] <TB2> INFO: Test took 854ms.
[13:22:47.704] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:22:48.094] <TB2> INFO: Expecting 41600 events.
[13:22:48.931] <TB2> INFO: 41600 events read in total (450ms).
[13:22:48.931] <TB2> INFO: Test took 1226ms.
[13:22:48.932] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:22:49.319] <TB2> INFO: Expecting 41600 events.
[13:22:50.139] <TB2> INFO: 41600 events read in total (433ms).
[13:22:50.140] <TB2> INFO: Test took 1207ms.
[13:22:50.140] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:22:50.525] <TB2> INFO: Expecting 2560 events.
[13:22:50.944] <TB2> INFO: 2560 events read in total (32ms).
[13:22:50.945] <TB2> INFO: Test took 804ms.
[13:22:51.340] <TB2> INFO: Expecting 655360 events.
[13:22:56.741] <TB2> INFO: 655360 events read in total (5014ms).
[13:22:56.749] <TB2> INFO: Test took 5804ms.
[13:22:57.038] <TB2> INFO: Expecting 655360 events.
[13:23:02.771] <TB2> INFO: 655360 events read in total (5345ms).
[13:23:02.779] <TB2> INFO: Test took 6016ms.
[13:23:02.800] <TB2> INFO: safety margin for low PH: adding 0, margin is now 20
[13:23:02.852] <TB2> INFO: write dac parameters into /home/mameinha/data/R416_Fulltest_m20_2015-10-07_15h07m_1444223258//000_FulltestROC_m20//dacParameters35_C0.dat
[13:23:03.028] <TB2> INFO: Expecting 41600 events.
[13:23:03.814] <TB2> INFO: 41600 events read in total (399ms).
[13:23:03.815] <TB2> INFO: Test took 942ms.
[13:23:04.197] <TB2> INFO: Expecting 41600 events.
[13:23:05.006] <TB2> INFO: 41600 events read in total (422ms).
[13:23:05.006] <TB2> INFO: Test took 1190ms.
[13:23:05.391] <TB2> INFO: Expecting 41600 events.
[13:23:06.178] <TB2> INFO: 41600 events read in total (400ms).
[13:23:06.179] <TB2> INFO: Test took 1172ms.
[13:23:06.561] <TB2> INFO: Expecting 2560 events.
[13:23:06.983] <TB2> INFO: 2560 events read in total (35ms).
[13:23:06.983] <TB2> INFO: Test took 803ms.
[13:23:07.377] <TB2> INFO: Expecting 2560 events.
[13:23:07.798] <TB2> INFO: 2560 events read in total (34ms).
[13:23:07.799] <TB2> INFO: Test took 815ms.
[13:23:08.208] <TB2> INFO: PixTestPhOptimization::doTest() done, duration: 21 seconds
[13:23:08.208] <TB2> INFO: PH scale (per ROC): 84
[13:23:08.208] <TB2> INFO: PH offset (per ROC): 171
[13:23:08.229] <TB2> INFO: enter test to run
[13:23:08.229] <TB2> INFO: test: GainPedestal no parameter change
[13:23:08.229] <TB2> INFO: running: gainpedestal
[13:23:08.231] <TB2> INFO: ######################################################################
[13:23:08.231] <TB2> INFO: PixTestGainPedestal::doTest() ntrig = 10
[13:23:08.231] <TB2> INFO: ######################################################################
[13:23:08.238] <TB2> INFO: scanning low vcal = 10
[13:23:08.258] <TB2> INFO: Expecting 41600 events.
[13:23:09.357] <TB2> INFO: 41600 events read in total (712ms).
[13:23:09.357] <TB2> INFO: Test took 1119ms.
[13:23:09.358] <TB2> INFO: scanning low vcal = 20
[13:23:09.752] <TB2> INFO: Expecting 41600 events.
[13:23:10.847] <TB2> INFO: 41600 events read in total (708ms).
[13:23:10.847] <TB2> INFO: Test took 1489ms.
[13:23:10.848] <TB2> INFO: scanning low vcal = 30
[13:23:11.243] <TB2> INFO: Expecting 41600 events.
[13:23:12.342] <TB2> INFO: 41600 events read in total (712ms).
[13:23:12.342] <TB2> INFO: Test took 1494ms.
[13:23:12.342] <TB2> INFO: scanning low vcal = 40
[13:23:12.736] <TB2> INFO: Expecting 41600 events.
[13:23:13.904] <TB2> INFO: 41600 events read in total (781ms).
[13:23:13.904] <TB2> INFO: Test took 1562ms.
[13:23:13.905] <TB2> INFO: scanning low vcal = 50
[13:23:14.286] <TB2> INFO: Expecting 41600 events.
[13:23:15.454] <TB2> INFO: 41600 events read in total (781ms).
[13:23:15.455] <TB2> INFO: Test took 1550ms.
[13:23:15.455] <TB2> INFO: scanning low vcal = 60
[13:23:15.837] <TB2> INFO: Expecting 41600 events.
[13:23:16.970] <TB2> INFO: 41600 events read in total (746ms).
[13:23:16.971] <TB2> INFO: Test took 1516ms.
[13:23:16.971] <TB2> INFO: scanning low vcal = 70
[13:23:17.360] <TB2> INFO: Expecting 41600 events.
[13:23:18.516] <TB2> INFO: 41600 events read in total (769ms).
[13:23:18.516] <TB2> INFO: Test took 1545ms.
[13:23:18.517] <TB2> INFO: scanning low vcal = 80
[13:23:18.900] <TB2> INFO: Expecting 41600 events.
[13:23:20.076] <TB2> INFO: 41600 events read in total (789ms).
[13:23:20.076] <TB2> INFO: Test took 1559ms.
[13:23:20.077] <TB2> INFO: scanning low vcal = 90
[13:23:20.460] <TB2> INFO: Expecting 41600 events.
[13:23:21.621] <TB2> INFO: 41600 events read in total (774ms).
[13:23:21.622] <TB2> INFO: Test took 1545ms.
[13:23:21.622] <TB2> INFO: scanning low vcal = 100
[13:23:22.006] <TB2> INFO: Expecting 41600 events.
[13:23:23.170] <TB2> INFO: 41600 events read in total (776ms).
[13:23:23.171] <TB2> INFO: Test took 1549ms.
[13:23:23.171] <TB2> INFO: scanning low vcal = 110
[13:23:23.553] <TB2> INFO: Expecting 41600 events.
[13:23:24.720] <TB2> INFO: 41600 events read in total (780ms).
[13:23:24.721] <TB2> INFO: Test took 1550ms.
[13:23:24.721] <TB2> INFO: scanning low vcal = 120
[13:23:25.105] <TB2> INFO: Expecting 41600 events.
[13:23:26.282] <TB2> INFO: 41600 events read in total (790ms).
[13:23:26.282] <TB2> INFO: Test took 1561ms.
[13:23:26.283] <TB2> INFO: scanning low vcal = 130
[13:23:26.668] <TB2> INFO: Expecting 41600 events.
[13:23:27.830] <TB2> INFO: 41600 events read in total (775ms).
[13:23:27.831] <TB2> INFO: Test took 1548ms.
[13:23:27.831] <TB2> INFO: scanning low vcal = 140
[13:23:28.217] <TB2> INFO: Expecting 41600 events.
[13:23:29.369] <TB2> INFO: 41600 events read in total (765ms).
[13:23:29.370] <TB2> INFO: Test took 1539ms.
[13:23:29.370] <TB2> INFO: scanning low vcal = 150
[13:23:29.757] <TB2> INFO: Expecting 41600 events.
[13:23:30.898] <TB2> INFO: 41600 events read in total (754ms).
[13:23:30.898] <TB2> INFO: Test took 1528ms.
[13:23:30.899] <TB2> INFO: scanning low vcal = 160
[13:23:31.287] <TB2> INFO: Expecting 41600 events.
[13:23:32.429] <TB2> INFO: 41600 events read in total (755ms).
[13:23:32.429] <TB2> INFO: Test took 1530ms.
[13:23:32.430] <TB2> INFO: scanning low vcal = 170
[13:23:32.818] <TB2> INFO: Expecting 41600 events.
[13:23:33.970] <TB2> INFO: 41600 events read in total (764ms).
[13:23:33.971] <TB2> INFO: Test took 1541ms.
[13:23:33.971] <TB2> INFO: scanning low vcal = 180
[13:23:34.354] <TB2> INFO: Expecting 41600 events.
[13:23:35.485] <TB2> INFO: 41600 events read in total (744ms).
[13:23:35.485] <TB2> INFO: Test took 1514ms.
[13:23:35.486] <TB2> INFO: scanning low vcal = 190
[13:23:35.874] <TB2> INFO: Expecting 41600 events.
[13:23:37.004] <TB2> INFO: 41600 events read in total (743ms).
[13:23:37.005] <TB2> INFO: Test took 1519ms.
[13:23:37.005] <TB2> INFO: scanning low vcal = 200
[13:23:37.394] <TB2> INFO: Expecting 41600 events.
[13:23:38.547] <TB2> INFO: 41600 events read in total (766ms).
[13:23:38.548] <TB2> INFO: Test took 1543ms.
[13:23:38.548] <TB2> INFO: scanning low vcal = 210
[13:23:38.936] <TB2> INFO: Expecting 41600 events.
[13:23:40.090] <TB2> INFO: 41600 events read in total (767ms).
[13:23:40.091] <TB2> INFO: Test took 1543ms.
[13:23:40.091] <TB2> INFO: scanning low vcal = 220
[13:23:40.480] <TB2> INFO: Expecting 41600 events.
[13:23:41.624] <TB2> INFO: 41600 events read in total (757ms).
[13:23:41.624] <TB2> INFO: Test took 1533ms.
[13:23:41.625] <TB2> INFO: scanning low vcal = 230
[13:23:42.013] <TB2> INFO: Expecting 41600 events.
[13:23:43.165] <TB2> INFO: 41600 events read in total (765ms).
[13:23:43.166] <TB2> INFO: Test took 1541ms.
[13:23:43.166] <TB2> INFO: scanning low vcal = 240
[13:23:43.554] <TB2> INFO: Expecting 41600 events.
[13:23:44.690] <TB2> INFO: 41600 events read in total (749ms).
[13:23:44.691] <TB2> INFO: Test took 1525ms.
[13:23:44.691] <TB2> INFO: scanning low vcal = 250
[13:23:45.080] <TB2> INFO: Expecting 41600 events.
[13:23:46.225] <TB2> INFO: 41600 events read in total (758ms).
[13:23:46.225] <TB2> INFO: Test took 1534ms.
[13:23:46.226] <TB2> INFO: scanning high vcal = 30 (= 210 in low range)
[13:23:46.614] <TB2> INFO: Expecting 41600 events.
[13:23:47.747] <TB2> INFO: 41600 events read in total (746ms).
[13:23:47.748] <TB2> INFO: Test took 1522ms.
[13:23:47.748] <TB2> INFO: scanning high vcal = 50 (= 350 in low range)
[13:23:48.136] <TB2> INFO: Expecting 41600 events.
[13:23:49.270] <TB2> INFO: 41600 events read in total (747ms).
[13:23:49.271] <TB2> INFO: Test took 1523ms.
[13:23:49.271] <TB2> INFO: scanning high vcal = 70 (= 490 in low range)
[13:23:49.659] <TB2> INFO: Expecting 41600 events.
[13:23:50.817] <TB2> INFO: 41600 events read in total (771ms).
[13:23:50.818] <TB2> INFO: Test took 1547ms.
[13:23:50.818] <TB2> INFO: scanning high vcal = 90 (= 630 in low range)
[13:23:51.204] <TB2> INFO: Expecting 41600 events.
[13:23:52.354] <TB2> INFO: 41600 events read in total (763ms).
[13:23:52.355] <TB2> INFO: Test took 1537ms.
[13:23:52.355] <TB2> INFO: scanning high vcal = 200 (= 1400 in low range)
[13:23:52.739] <TB2> INFO: Expecting 41600 events.
[13:23:53.887] <TB2> INFO: 41600 events read in total (761ms).
[13:23:53.887] <TB2> INFO: Test took 1532ms.
[13:23:54.268] <TB2> INFO: PixTestGainPedestal::measure() done
[13:23:56.364] <TB2> INFO: PixTestGainPedestal::fit() done
[13:23:56.364] <TB2> INFO: non-linearity mean: 0.960
[13:23:56.364] <TB2> INFO: non-linearity RMS: 0.006
[13:23:56.365] <TB2> INFO: write gain/ped parameters into /home/mameinha/data/R416_Fulltest_m20_2015-10-07_15h07m_1444223258//000_FulltestROC_m20//phCalibrationFitErr35_C0.dat
[13:23:56.417] <TB2> INFO: PixTestGainPedestal::doTest() done, duration: 48 seconds
[13:23:56.417] <TB2> INFO: enter test to run
[13:23:56.417] <TB2> INFO: test: Readback no parameter change
[13:23:56.417] <TB2> INFO: running: readback
[13:23:56.418] <TB2> INFO: readReadbackCal: /home/mameinha/data/R416_Fulltest_m20_2015-10-07_15h07m_1444223258//000_FulltestROC_m20//readbackCal_C0.dat .. /home/mameinha/data/R416_Fulltest_m20_2015-10-07_15h07m_1444223258//000_FulltestROC_m20//readbackCal_C0.dat
[13:23:56.419] <TB2> INFO: ######################################################################
[13:23:56.419] <TB2> INFO: PixTestReadback::doTest()
[13:23:56.419] <TB2> INFO: ######################################################################
[13:23:56.420] <TB2> INFO: PixTestReadback::RES sent once
[13:24:07.581] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R416_Fulltest_m20_2015-10-07_15h07m_1444223258//000_FulltestROC_m20//readbackCal_C0.dat
[13:24:07.594] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[13:24:07.595] <TB2> INFO: PixTestReadback::RES sent once
[13:24:18.866] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R416_Fulltest_m20_2015-10-07_15h07m_1444223258//000_FulltestROC_m20//readbackCal_C0.dat
[13:24:18.911] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[13:24:18.912] <TB2> INFO: PixTestReadback::RES sent once
[13:24:27.247] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[13:24:27.247] <TB2> INFO: Vbg will be calibrated using Vd calibration
[13:24:27.247] <TB2> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 154calibrated Vbg = 1.22619 :::*/*/*/*/
[13:24:27.623] <TB2> INFO: PixTestReadback::RES sent once
[13:24:36.535] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R416_Fulltest_m20_2015-10-07_15h07m_1444223258//000_FulltestROC_m20//readbackCal_C0.dat
[13:24:36.558] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[13:24:36.558] <TB2> INFO: PixTestReadback::doTest() done
[13:24:36.607] <TB2> INFO: enter test to run
[13:24:36.607] <TB2> INFO: test: no parameter change
[13:24:37.040] <TB2> QUIET: Connection to board 137 closed.
[13:24:37.120] <TB2> INFO: pXar: this is the end, my friend