[17:17:08.279] <TB3> INFO: *** Welcome to pxar ***
[17:17:08.279] <TB3> INFO: *** Today: 2015/12/02
[17:17:08.327] <TB3> INFO: *** Version: 9da6
[17:17:08.328] <TB3> INFO: readRocDacs: /home/mameinha/data/R417_FulltestROC_m20_2015-12-02_18h16m_1449076609//000_FulltestROC_m20//dacParameters_C0.dat .. /home/mameinha/data/R417_FulltestROC_m20_2015-12-02_18h16m_1449076609//000_FulltestROC_m20//dacParameters_C0.dat
[17:17:08.328] <TB3> INFO: readTbmDacs: /home/mameinha/data/R417_FulltestROC_m20_2015-12-02_18h16m_1449076609//000_FulltestROC_m20//tbmParameters_C0a.dat .. /home/mameinha/data/R417_FulltestROC_m20_2015-12-02_18h16m_1449076609//000_FulltestROC_m20//tbmParameters_C4294967295b.dat
[17:17:08.328] <TB3> INFO: readMaskFile: /home/mameinha/data/R417_FulltestROC_m20_2015-12-02_18h16m_1449076609//000_FulltestROC_m20//defaultMaskFile.dat
[17:17:08.329] <TB3> INFO: readTrimFile: /home/mameinha/data/R417_FulltestROC_m20_2015-12-02_18h16m_1449076609//000_FulltestROC_m20//trimParameters_C0.dat .. /home/mameinha/data/R417_FulltestROC_m20_2015-12-02_18h16m_1449076609//000_FulltestROC_m20//trimParameters_C0.dat
[17:17:08.337] <TB3> INFO: clk: 4
[17:17:08.337] <TB3> INFO: ctr: 4
[17:17:08.337] <TB3> INFO: sda: 19
[17:17:08.337] <TB3> INFO: tin: 9
[17:17:08.337] <TB3> INFO: level: 15
[17:17:08.337] <TB3> INFO: deser160phase: 4
[17:17:08.337] <TB3> QUIET: Instanciating API for pxar v2.6.1+42~g55d8827
[17:17:08.337] <TB3> INFO: Log level: INFO
[17:17:08.343] <TB3> INFO: Found DTB DTB_WWXJGB
[17:17:08.353] <TB3> QUIET: Connection to board DTB_WWXJGB opened.
[17:17:08.356] <TB3> 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:
------------------------------------------------------
[17:17:08.358] <TB3> INFO: RPC call hashes of host and DTB match: 398089610
[17:17:09.527] <TB3> INFO: DUT info:
[17:17:09.527] <TB3> INFO: The DUT currently contains the following objects:
[17:17:09.527] <TB3> INFO: 0 TBM Cores (0 ON)
[17:17:09.527] <TB3> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[17:17:09.527] <TB3> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[17:17:09.976] <TB3> INFO: enter 'restricted' command line mode
[17:17:09.976] <TB3> INFO: enter test to run
[17:17:09.976] <TB3> INFO: test: Setup no parameter change
[17:17:09.976] <TB3> INFO: running: setup
[17:17:09.984] <TB3> INFO: PixTestSetup::doTest() ntrig = 10

[17:17:09.984] <TB3> INFO: PixTestSetup:: pg set to RES|TOK
[17:17:09.984] <TB3> INFO: 0 1 2 3 4 5 6 7
[17:17:13.029] <TB3> INFO: 0: 000 008 084 87c 7f0 f00 000 000
[17:17:16.044] <TB3> INFO: 1: 000 008 084 87c <7f8>[*] f80 800 000
[17:17:19.058] <TB3> INFO: 2: 000 008 084 87c <7f8>[*] f80 <7f8>[1] 000
[17:17:22.073] <TB3> INFO: 3: 000 004 004 07c <7f8>[*] f80 <7f8>[1] 000
[17:17:25.087] <TB3> INFO: 4: 800 004 044 07c <7f8>[*] f80 800 000
[17:17:28.102] <TB3> INFO: 5: 800 004 040 43c 3fc fc0 c00 000
[17:17:31.116] <TB3> INFO: 6: 000 004 040 43c 3fc fc0 c00 000
[17:17:34.131] <TB3> INFO: 7: 000 004 040 43c 3fc fc0 c00 000
[17:17:37.146] <TB3> INFO: 8: c00 000 020 03c 3fc fc0 c00 000
[17:17:40.160] <TB3> INFO: 9: c00 000 000 23c 3fc fc0 c00 000
[17:17:43.175] <TB3> INFO: 10: 000 000 020 21c 1fc fc0 c00 000
[17:17:46.190] <TB3> INFO: 11: 000 000 020 21c 1fc fe0 e00 000
[17:17:49.206] <TB3> INFO: 12: 000 000 020 21c 1fc fe0 e00 000
[17:17:52.222] <TB3> INFO: 13: 000 000 000 01c 1fc fe0 e00 000
[17:17:55.237] <TB3> INFO: 14: 000 000 010 01c 1fc fe0 e00 000
[17:17:58.251] <TB3> INFO: 15: 000 000 010 10c 0fc ff0 f00 000
[17:18:01.266] <TB3> INFO: 16: f00 000 010 10c 0fc ff0 f00 000
[17:18:04.281] <TB3> INFO: 17: 000 000 018 10c 0fc ff0 f00 000
[17:18:07.295] <TB3> INFO: 18: f00 000 000 00c 8fc ff0 f00 000
[17:18:10.310] <TB3> INFO: 19: 000 000 008 08c 8fc ff0 f00 000
[17:18:10.731] <TB3> INFO: Found good delays at CLK = 2, DESER160 = 4
[17:18:10.732] <TB3> INFO: PixTestSetup:: Write Tb parameters to file.
[17:18:10.781] <TB3> INFO: write dtb parameters into /home/mameinha/data/R417_FulltestROC_m20_2015-12-02_18h16m_1449076609//000_FulltestROC_m20//tbParameters.dat
[17:18:10.825] <TB3> INFO: PixTestSetup::doTest() done for.
[17:18:10.849] <TB3> INFO: enter test to run
[17:18:10.849] <TB3> INFO: test: Pretest no parameter change
[17:18:10.849] <TB3> INFO: running: pretest
[17:18:10.851] <TB3> INFO: ----------------------------------------------------------------------
[17:18:10.851] <TB3> INFO: PixTestPretest::programROC()
[17:18:10.851] <TB3> INFO: ----------------------------------------------------------------------
[17:18:13.853] <TB3> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[17:18:13.853] <TB3> INFO: IA differences per ROC: 20.1
[17:18:13.858] <TB3> INFO: enter test to run
[17:18:13.858] <TB3> INFO: test: Pretest no parameter change
[17:18:13.858] <TB3> INFO: running: pretest
[17:18:13.859] <TB3> INFO: ----------------------------------------------------------------------
[17:18:13.859] <TB3> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[17:18:13.859] <TB3> INFO: ----------------------------------------------------------------------
[17:18:14.471] <TB3> INFO: PixTestPretest::setVana() done, Module Ia 24.1 mA = 24.1 mA/ROC
[17:18:14.471] <TB3> INFO: i(loss) [mA/ROC]: 19.3
[17:18:14.475] <TB3> INFO: enter test to run
[17:18:14.475] <TB3> INFO: test: Pretest no parameter change
[17:18:14.475] <TB3> INFO: running: pretest
[17:18:14.477] <TB3> INFO: ----------------------------------------------------------------------
[17:18:14.477] <TB3> INFO: PixTestPretest::findWorkingPixel()
[17:18:14.477] <TB3> INFO: ----------------------------------------------------------------------
[17:18:14.488] <TB3> INFO: Expecting 231680 events.
[17:18:16.748] <TB3> INFO: 231680 events read in total (1873ms).
[17:18:16.810] <TB3> INFO: Test took 2333ms.
[17:18:17.125] <TB3> INFO: Found working pixel in all ROCs: col/row = 12/22
[17:18:17.132] <TB3> INFO: enter test to run
[17:18:17.132] <TB3> INFO: test: Pretest no parameter change
[17:18:17.132] <TB3> INFO: running: pretest
[17:18:17.133] <TB3> INFO: ----------------------------------------------------------------------
[17:18:17.133] <TB3> INFO: PixTestPretest::setVthrCompCalDel()
[17:18:17.133] <TB3> INFO: ----------------------------------------------------------------------
[17:18:17.142] <TB3> INFO: Expecting 231680 events.
[17:18:19.395] <TB3> INFO: 231680 events read in total (1866ms).
[17:18:19.399] <TB3> INFO: Test took 2265ms.
[17:18:19.778] <TB3> INFO: PixTestPretest::setVthrCompCalDel() done
[17:18:19.778] <TB3> INFO: CalDel: 161
[17:18:19.778] <TB3> INFO: VthrComp: 51
[17:18:19.784] <TB3> INFO: enter test to run
[17:18:19.784] <TB3> INFO: test: Pretest no parameter change
[17:18:19.784] <TB3> INFO: running: pretest
[17:18:19.832] <TB3> INFO: write dac parameters into /home/mameinha/data/R417_FulltestROC_m20_2015-12-02_18h16m_1449076609//000_FulltestROC_m20//dacParameters_C0.dat
[17:18:19.883] <TB3> INFO: enter test to run
[17:18:19.883] <TB3> INFO: test: PixelAlive no parameter change
[17:18:19.883] <TB3> INFO: running: pixelalive
[17:18:19.884] <TB3> INFO: ######################################################################
[17:18:19.884] <TB3> INFO: PixTestAlive::doTest()
[17:18:19.884] <TB3> INFO: ######################################################################
[17:18:19.886] <TB3> INFO: ----------------------------------------------------------------------
[17:18:19.886] <TB3> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[17:18:19.886] <TB3> INFO: ----------------------------------------------------------------------
[17:18:19.907] <TB3> INFO: Expecting 41600 events.
[17:18:20.730] <TB3> INFO: 41600 events read in total (436ms).
[17:18:20.730] <TB3> INFO: Test took 844ms.
[17:18:20.731] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:18:21.115] <TB3> INFO: PixTestAlive::aliveTest() done
[17:18:21.115] <TB3> INFO: number of dead pixels (per ROC): 1
[17:18:21.117] <TB3> INFO: ----------------------------------------------------------------------
[17:18:21.117] <TB3> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[17:18:21.117] <TB3> INFO: ----------------------------------------------------------------------
[17:18:21.137] <TB3> INFO: Expecting 41600 events.
[17:18:21.893] <TB3> INFO: 41600 events read in total (369ms).
[17:18:21.893] <TB3> INFO: Test took 776ms.
[17:18:21.893] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:18:21.893] <TB3> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[17:18:22.284] <TB3> INFO: PixTestAlive::maskTest() done
[17:18:22.284] <TB3> INFO: number of mask-defect pixels (per ROC): 0
[17:18:22.285] <TB3> INFO: ----------------------------------------------------------------------
[17:18:22.286] <TB3> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[17:18:22.286] <TB3> INFO: ----------------------------------------------------------------------
[17:18:22.310] <TB3> INFO: Expecting 41600 events.
[17:18:23.162] <TB3> INFO: 41600 events read in total (464ms).
[17:18:23.164] <TB3> INFO: Test took 878ms.
[17:18:23.164] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:18:23.548] <TB3> INFO: PixTestAlive::addressDecodingTest() done
[17:18:23.548] <TB3> INFO: number of address-decoding pixels (per ROC): 0
[17:18:23.548] <TB3> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[17:18:23.549] <TB3> INFO: enter test to run
[17:18:23.549] <TB3> INFO: test: Scurves no parameter change
[17:18:23.549] <TB3> INFO: running: scurves
[17:18:23.551] <TB3> INFO: ######################################################################
[17:18:23.551] <TB3> INFO: PixTestScurves::doTest() ntrig = 50
[17:18:23.551] <TB3> INFO: ######################################################################
[17:18:23.551] <TB3> INFO: ----------------------------------------------------------------------
[17:18:23.551] <TB3> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[17:18:23.551] <TB3> INFO: ----------------------------------------------------------------------
[17:18:23.551] <TB3> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[17:18:23.564] <TB3> INFO: dacScan split into 1 runs with ntrig = 50
[17:18:23.564] <TB3> INFO: run 1 of 1
[17:18:23.583] <TB3> INFO: Expecting 41808000 events.
[17:20:47.768] <TB3> INFO: 18621100 events read in total (143798ms).
[17:23:03.278] <TB3> INFO: 36842000 events read in total (279308ms).
[17:23:39.627] <TB3> INFO: 41808000 events read in total (315657ms).
[17:23:39.663] <TB3> INFO: Test took 316099ms.
[17:23:39.686] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:23:39.695] <TB3> INFO: dumping ASCII scurve output file: SCurveData
[17:23:41.249] <TB3> INFO: PixTestScurves::scurves() done
[17:23:41.249] <TB3> INFO: Vcal mean: 68.36
[17:23:41.250] <TB3> INFO: Vcal RMS: 4.86
[17:23:41.257] <TB3> INFO: enter test to run
[17:23:41.257] <TB3> INFO: test: Trim no parameter change
[17:23:41.257] <TB3> INFO: running: trim
[17:23:41.258] <TB3> INFO: ######################################################################
[17:23:41.258] <TB3> INFO: PixTestTrim::doTest()
[17:23:41.258] <TB3> INFO: ######################################################################
[17:23:41.260] <TB3> INFO: ----------------------------------------------------------------------
[17:23:41.260] <TB3> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[17:23:41.260] <TB3> INFO: ----------------------------------------------------------------------
[17:23:41.265] <TB3> INFO: ---> VthrComp thr map (minimal VthrComp)
[17:23:41.265] <TB3> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[17:23:41.272] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[17:23:41.272] <TB3> INFO: run 1 of 1
[17:23:41.292] <TB3> INFO: Expecting 6281600 events.
[17:24:30.830] <TB3> INFO: 6281600 events read in total (49151ms).
[17:24:30.850] <TB3> INFO: Test took 49578ms.
[17:24:30.859] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:24:32.176] <TB3> INFO: ROC 0 VthrComp = 78
[17:24:32.176] <TB3> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[17:24:32.176] <TB3> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[17:24:32.184] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[17:24:32.184] <TB3> INFO: run 1 of 1
[17:24:32.203] <TB3> INFO: Expecting 6281600 events.
[17:25:23.768] <TB3> INFO: 6281600 events read in total (51177ms).
[17:25:23.815] <TB3> INFO: Test took 51631ms.
[17:25:23.841] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:25:25.104] <TB3> INFO: roc 0 with ID = 0 has maximal Vcal 57.3062 for pixel 9/14 mean/min/max = 45.4999/33.51/57.4898
[17:25:25.113] <TB3> INFO: Expecting 514560 events.
[17:25:29.338] <TB3> INFO: 514560 events read in total (3838ms).
[17:25:29.345] <TB3> INFO: Test took 4241ms.
[17:25:29.740] <TB3> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[17:25:29.748] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[17:25:29.748] <TB3> INFO: run 1 of 1
[17:25:29.767] <TB3> INFO: Expecting 6281600 events.
[17:26:20.844] <TB3> INFO: 6281600 events read in total (50690ms).
[17:26:20.883] <TB3> INFO: Test took 51135ms.
[17:26:20.903] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:26:22.087] <TB3> INFO: ---> TrimStepCorr4 extremal thresholds: 17.190435 .. 47.319463
[17:26:22.092] <TB3> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 7 .. 57 (-1/-1) hits flags = 528 (plus default)
[17:26:22.099] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[17:26:22.099] <TB3> INFO: run 1 of 1
[17:26:22.119] <TB3> INFO: Expecting 2121600 events.
[17:26:39.123] <TB3> INFO: 2121600 events read in total (16617ms).
[17:26:39.132] <TB3> INFO: Test took 17033ms.
[17:26:39.136] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:26:39.954] <TB3> INFO: ---> TrimStepCorr2 extremal thresholds: 23.966696 .. 40.727545
[17:26:39.959] <TB3> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 13 .. 50 (-1/-1) hits flags = 528 (plus default)
[17:26:39.966] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[17:26:39.966] <TB3> INFO: run 1 of 1
[17:26:39.985] <TB3> INFO: Expecting 1580800 events.
[17:26:53.213] <TB3> INFO: 1580800 events read in total (12841ms).
[17:26:53.220] <TB3> INFO: Test took 13254ms.
[17:26:53.223] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:26:54.035] <TB3> INFO: ---> TrimStepCorr1a extremal thresholds: 28.558842 .. 37.266101
[17:26:54.040] <TB3> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 18 .. 47 (-1/-1) hits flags = 528 (plus default)
[17:26:54.048] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[17:26:54.048] <TB3> INFO: run 1 of 1
[17:26:54.068] <TB3> INFO: Expecting 1248000 events.
[17:27:04.382] <TB3> INFO: 1248000 events read in total (9927ms).
[17:27:04.388] <TB3> INFO: Test took 10340ms.
[17:27:04.390] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:27:05.136] <TB3> INFO: ---> TrimStepCorr1b extremal thresholds: 30.246018 .. 36.812946
[17:27:05.141] <TB3> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 20 .. 46 (-1/-1) hits flags = 528 (plus default)
[17:27:05.148] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[17:27:05.148] <TB3> INFO: run 1 of 1
[17:27:05.168] <TB3> INFO: Expecting 1123200 events.
[17:27:14.781] <TB3> INFO: 1123200 events read in total (9226ms).
[17:27:14.787] <TB3> INFO: Test took 9639ms.
[17:27:14.789] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:27:15.522] <TB3> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[17:27:15.522] <TB3> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[17:27:15.529] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[17:27:15.529] <TB3> INFO: run 1 of 1
[17:27:15.548] <TB3> INFO: Expecting 1705600 events.
[17:27:29.824] <TB3> INFO: 1705600 events read in total (13889ms).
[17:27:29.833] <TB3> INFO: Test took 14304ms.
[17:27:29.837] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:27:30.681] <TB3> INFO: write dac parameters into /home/mameinha/data/R417_FulltestROC_m20_2015-12-02_18h16m_1449076609//000_FulltestROC_m20//dacParameters35_C0.dat
[17:27:30.695] <TB3> INFO: write trim parameters into /home/mameinha/data/R417_FulltestROC_m20_2015-12-02_18h16m_1449076609//000_FulltestROC_m20//trimParameters35_C0.dat
[17:27:30.710] <TB3> INFO: PixTestTrim::trimTest() done
[17:27:30.710] <TB3> INFO: vtrim: 104
[17:27:30.710] <TB3> INFO: vthrcomp: 78
[17:27:30.710] <TB3> INFO: vcal mean: 34.92
[17:27:30.710] <TB3> INFO: vcal RMS: 0.86
[17:27:30.710] <TB3> INFO: bits mean: 9.15
[17:27:30.710] <TB3> INFO: bits RMS: 2.63
[17:27:30.715] <TB3> INFO: ----------------------------------------------------------------------
[17:27:30.715] <TB3> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[17:27:30.715] <TB3> INFO: ----------------------------------------------------------------------
[17:27:30.715] <TB3> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[17:27:30.723] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[17:27:30.723] <TB3> INFO: run 1 of 1
[17:27:30.743] <TB3> INFO: Expecting 8320000 events.
[17:28:36.539] <TB3> INFO: 8320000 events read in total (65409ms).
[17:28:36.582] <TB3> INFO: Test took 65859ms.
[17:28:36.602] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:28:38.053] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 114 (-1/-1) hits flags = 528 (plus default)
[17:28:38.060] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[17:28:38.061] <TB3> INFO: run 1 of 1
[17:28:38.080] <TB3> INFO: Expecting 4784000 events.
[17:29:14.989] <TB3> INFO: 4784000 events read in total (36522ms).
[17:29:15.011] <TB3> INFO: Test took 36950ms.
[17:29:15.021] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:29:16.244] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 105 (-1/-1) hits flags = 528 (plus default)
[17:29:16.251] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[17:29:16.251] <TB3> INFO: run 1 of 1
[17:29:16.271] <TB3> INFO: Expecting 4409600 events.
[17:29:50.504] <TB3> INFO: 4409600 events read in total (33846ms).
[17:29:50.516] <TB3> INFO: Test took 34264ms.
[17:29:50.523] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:29:51.568] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 105 (-1/-1) hits flags = 528 (plus default)
[17:29:51.575] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[17:29:51.575] <TB3> INFO: run 1 of 1
[17:29:51.595] <TB3> INFO: Expecting 4409600 events.
[17:30:25.228] <TB3> INFO: 4409600 events read in total (33246ms).
[17:30:25.241] <TB3> INFO: Test took 33665ms.
[17:30:25.247] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:30:26.348] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 104 (-1/-1) hits flags = 528 (plus default)
[17:30:26.356] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[17:30:26.356] <TB3> INFO: run 1 of 1
[17:30:26.375] <TB3> INFO: Expecting 4368000 events.
[17:31:00.222] <TB3> INFO: 4368000 events read in total (33459ms).
[17:31:00.239] <TB3> INFO: Test took 33883ms.
[17:31:00.247] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:31:01.313] <TB3> INFO: PixTestTrim::trimBitTest() done
[17:31:01.315] <TB3> INFO: PixTestTrim::doTest() done, duration: 440 seconds
[17:31:01.355] <TB3> INFO: enter test to run
[17:31:01.355] <TB3> INFO: test: PhOptimization no parameter change
[17:31:01.355] <TB3> INFO: running: phoptimization
[17:31:01.355] <TB3> INFO: ######################################################################
[17:31:01.355] <TB3> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[17:31:01.355] <TB3> INFO: ######################################################################
[17:31:01.376] <TB3> INFO: Expecting 41600 events.
[17:31:02.206] <TB3> INFO: 41600 events read in total (443ms).
[17:31:02.207] <TB3> INFO: Test took 850ms.
[17:31:02.207] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:31:02.595] <TB3> INFO: Expecting 41600 events.
[17:31:03.413] <TB3> INFO: 41600 events read in total (430ms).
[17:31:03.414] <TB3> INFO: Test took 1206ms.
[17:31:03.414] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:31:03.803] <TB3> INFO: Expecting 41600 events.
[17:31:04.618] <TB3> INFO: 41600 events read in total (428ms).
[17:31:04.618] <TB3> INFO: Test took 1203ms.
[17:31:04.619] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[17:31:05.006] <TB3> INFO: Expecting 2560 events.
[17:31:05.426] <TB3> INFO: 2560 events read in total (33ms).
[17:31:05.426] <TB3> INFO: Test took 807ms.
[17:31:05.821] <TB3> INFO: Expecting 655360 events.
[17:31:11.279] <TB3> INFO: 655360 events read in total (5071ms).
[17:31:11.288] <TB3> INFO: Test took 5861ms.
[17:31:11.571] <TB3> INFO: Expecting 655360 events.
[17:31:17.038] <TB3> INFO: 655360 events read in total (5080ms).
[17:31:17.046] <TB3> INFO: Test took 5745ms.
[17:31:17.066] <TB3> INFO: safety margin for low PH: adding 0, margin is now 20
[17:31:17.161] <TB3> INFO: write dac parameters into /home/mameinha/data/R417_FulltestROC_m20_2015-12-02_18h16m_1449076609//000_FulltestROC_m20//dacParameters35_C0.dat
[17:31:17.337] <TB3> INFO: Expecting 41600 events.
[17:31:18.125] <TB3> INFO: 41600 events read in total (401ms).
[17:31:18.126] <TB3> INFO: Test took 945ms.
[17:31:18.506] <TB3> INFO: Expecting 41600 events.
[17:31:19.295] <TB3> INFO: 41600 events read in total (402ms).
[17:31:19.296] <TB3> INFO: Test took 1169ms.
[17:31:19.681] <TB3> INFO: Expecting 41600 events.
[17:31:20.442] <TB3> INFO: 41600 events read in total (374ms).
[17:31:20.443] <TB3> INFO: Test took 1146ms.
[17:31:20.832] <TB3> INFO: Expecting 2560 events.
[17:31:21.249] <TB3> INFO: 2560 events read in total (30ms).
[17:31:21.250] <TB3> INFO: Test took 806ms.
[17:31:21.645] <TB3> INFO: Expecting 2560 events.
[17:31:22.063] <TB3> INFO: 2560 events read in total (31ms).
[17:31:22.063] <TB3> INFO: Test took 813ms.
[17:31:22.473] <TB3> INFO: PixTestPhOptimization::doTest() done, duration: 21 seconds
[17:31:22.473] <TB3> INFO: PH scale (per ROC): 101
[17:31:22.473] <TB3> INFO: PH offset (per ROC): 149
[17:31:22.488] <TB3> INFO: enter test to run
[17:31:22.488] <TB3> INFO: test: GainPedestal no parameter change
[17:31:22.488] <TB3> INFO: running: gainpedestal
[17:31:22.490] <TB3> INFO: ######################################################################
[17:31:22.490] <TB3> INFO: PixTestGainPedestal::doTest() ntrig = 10
[17:31:22.490] <TB3> INFO: ######################################################################
[17:31:22.498] <TB3> INFO: scanning low vcal = 10
[17:31:22.518] <TB3> INFO: Expecting 41600 events.
[17:31:23.608] <TB3> INFO: 41600 events read in total (703ms).
[17:31:23.609] <TB3> INFO: Test took 1111ms.
[17:31:23.609] <TB3> INFO: scanning low vcal = 20
[17:31:24.003] <TB3> INFO: Expecting 41600 events.
[17:31:25.107] <TB3> INFO: 41600 events read in total (717ms).
[17:31:25.107] <TB3> INFO: Test took 1498ms.
[17:31:25.108] <TB3> INFO: scanning low vcal = 30
[17:31:25.503] <TB3> INFO: Expecting 41600 events.
[17:31:26.592] <TB3> INFO: 41600 events read in total (702ms).
[17:31:26.592] <TB3> INFO: Test took 1484ms.
[17:31:26.592] <TB3> INFO: scanning low vcal = 40
[17:31:26.987] <TB3> INFO: Expecting 41600 events.
[17:31:28.111] <TB3> INFO: 41600 events read in total (737ms).
[17:31:28.111] <TB3> INFO: Test took 1519ms.
[17:31:28.112] <TB3> INFO: scanning low vcal = 50
[17:31:28.500] <TB3> INFO: Expecting 41600 events.
[17:31:29.627] <TB3> INFO: 41600 events read in total (739ms).
[17:31:29.628] <TB3> INFO: Test took 1516ms.
[17:31:29.628] <TB3> INFO: scanning low vcal = 60
[17:31:30.017] <TB3> INFO: Expecting 41600 events.
[17:31:31.143] <TB3> INFO: 41600 events read in total (739ms).
[17:31:31.143] <TB3> INFO: Test took 1515ms.
[17:31:31.143] <TB3> INFO: scanning low vcal = 70
[17:31:31.532] <TB3> INFO: Expecting 41600 events.
[17:31:32.685] <TB3> INFO: 41600 events read in total (766ms).
[17:31:32.686] <TB3> INFO: Test took 1543ms.
[17:31:32.686] <TB3> INFO: scanning low vcal = 80
[17:31:33.070] <TB3> INFO: Expecting 41600 events.
[17:31:34.238] <TB3> INFO: 41600 events read in total (781ms).
[17:31:34.239] <TB3> INFO: Test took 1553ms.
[17:31:34.239] <TB3> INFO: scanning low vcal = 90
[17:31:34.622] <TB3> INFO: Expecting 41600 events.
[17:31:35.755] <TB3> INFO: 41600 events read in total (746ms).
[17:31:35.756] <TB3> INFO: Test took 1517ms.
[17:31:35.756] <TB3> INFO: scanning low vcal = 100
[17:31:36.144] <TB3> INFO: Expecting 41600 events.
[17:31:37.310] <TB3> INFO: 41600 events read in total (778ms).
[17:31:37.311] <TB3> INFO: Test took 1555ms.
[17:31:37.311] <TB3> INFO: scanning low vcal = 110
[17:31:37.699] <TB3> INFO: Expecting 41600 events.
[17:31:38.850] <TB3> INFO: 41600 events read in total (764ms).
[17:31:38.850] <TB3> INFO: Test took 1539ms.
[17:31:38.851] <TB3> INFO: scanning low vcal = 120
[17:31:39.240] <TB3> INFO: Expecting 41600 events.
[17:31:40.381] <TB3> INFO: 41600 events read in total (754ms).
[17:31:40.382] <TB3> INFO: Test took 1531ms.
[17:31:40.382] <TB3> INFO: scanning low vcal = 130
[17:31:40.771] <TB3> INFO: Expecting 41600 events.
[17:31:41.927] <TB3> INFO: 41600 events read in total (769ms).
[17:31:41.927] <TB3> INFO: Test took 1545ms.
[17:31:41.928] <TB3> INFO: scanning low vcal = 140
[17:31:42.313] <TB3> INFO: Expecting 41600 events.
[17:31:43.463] <TB3> INFO: 41600 events read in total (763ms).
[17:31:43.464] <TB3> INFO: Test took 1536ms.
[17:31:43.464] <TB3> INFO: scanning low vcal = 150
[17:31:43.851] <TB3> INFO: Expecting 41600 events.
[17:31:45.008] <TB3> INFO: 41600 events read in total (770ms).
[17:31:45.008] <TB3> INFO: Test took 1544ms.
[17:31:45.009] <TB3> INFO: scanning low vcal = 160
[17:31:45.394] <TB3> INFO: Expecting 41600 events.
[17:31:46.531] <TB3> INFO: 41600 events read in total (750ms).
[17:31:46.531] <TB3> INFO: Test took 1522ms.
[17:31:46.532] <TB3> INFO: scanning low vcal = 170
[17:31:46.920] <TB3> INFO: Expecting 41600 events.
[17:31:48.058] <TB3> INFO: 41600 events read in total (751ms).
[17:31:48.059] <TB3> INFO: Test took 1527ms.
[17:31:48.060] <TB3> INFO: scanning low vcal = 180
[17:31:48.444] <TB3> INFO: Expecting 41600 events.
[17:31:49.605] <TB3> INFO: 41600 events read in total (774ms).
[17:31:49.605] <TB3> INFO: Test took 1545ms.
[17:31:49.605] <TB3> INFO: scanning low vcal = 190
[17:31:49.994] <TB3> INFO: Expecting 41600 events.
[17:31:51.150] <TB3> INFO: 41600 events read in total (769ms).
[17:31:51.151] <TB3> INFO: Test took 1545ms.
[17:31:51.151] <TB3> INFO: scanning low vcal = 200
[17:31:51.532] <TB3> INFO: Expecting 41600 events.
[17:31:52.697] <TB3> INFO: 41600 events read in total (778ms).
[17:31:52.697] <TB3> INFO: Test took 1545ms.
[17:31:52.698] <TB3> INFO: scanning low vcal = 210
[17:31:53.084] <TB3> INFO: Expecting 41600 events.
[17:31:54.237] <TB3> INFO: 41600 events read in total (766ms).
[17:31:54.237] <TB3> INFO: Test took 1539ms.
[17:31:54.238] <TB3> INFO: scanning low vcal = 220
[17:31:54.624] <TB3> INFO: Expecting 41600 events.
[17:31:55.784] <TB3> INFO: 41600 events read in total (772ms).
[17:31:55.785] <TB3> INFO: Test took 1547ms.
[17:31:55.785] <TB3> INFO: scanning low vcal = 230
[17:31:56.170] <TB3> INFO: Expecting 41600 events.
[17:31:57.310] <TB3> INFO: 41600 events read in total (754ms).
[17:31:57.310] <TB3> INFO: Test took 1525ms.
[17:31:57.311] <TB3> INFO: scanning low vcal = 240
[17:31:57.699] <TB3> INFO: Expecting 41600 events.
[17:31:58.860] <TB3> INFO: 41600 events read in total (773ms).
[17:31:58.861] <TB3> INFO: Test took 1550ms.
[17:31:58.861] <TB3> INFO: scanning low vcal = 250
[17:31:59.246] <TB3> INFO: Expecting 41600 events.
[17:32:00.382] <TB3> INFO: 41600 events read in total (749ms).
[17:32:00.382] <TB3> INFO: Test took 1521ms.
[17:32:00.382] <TB3> INFO: scanning high vcal = 30 (= 210 in low range)
[17:32:00.771] <TB3> INFO: Expecting 41600 events.
[17:32:01.899] <TB3> INFO: 41600 events read in total (741ms).
[17:32:01.900] <TB3> INFO: Test took 1517ms.
[17:32:01.900] <TB3> INFO: scanning high vcal = 50 (= 350 in low range)
[17:32:02.288] <TB3> INFO: Expecting 41600 events.
[17:32:03.447] <TB3> INFO: 41600 events read in total (772ms).
[17:32:03.448] <TB3> INFO: Test took 1548ms.
[17:32:03.448] <TB3> INFO: scanning high vcal = 70 (= 490 in low range)
[17:32:03.835] <TB3> INFO: Expecting 41600 events.
[17:32:04.977] <TB3> INFO: 41600 events read in total (755ms).
[17:32:04.978] <TB3> INFO: Test took 1530ms.
[17:32:04.978] <TB3> INFO: scanning high vcal = 90 (= 630 in low range)
[17:32:05.366] <TB3> INFO: Expecting 41600 events.
[17:32:06.504] <TB3> INFO: 41600 events read in total (751ms).
[17:32:06.504] <TB3> INFO: Test took 1526ms.
[17:32:06.505] <TB3> INFO: scanning high vcal = 200 (= 1400 in low range)
[17:32:06.889] <TB3> INFO: Expecting 41600 events.
[17:32:08.050] <TB3> INFO: 41600 events read in total (773ms).
[17:32:08.051] <TB3> INFO: Test took 1546ms.
[17:32:08.428] <TB3> INFO: PixTestGainPedestal::measure() done
[17:32:10.488] <TB3> INFO: PixTestGainPedestal::fit() done
[17:32:10.488] <TB3> INFO: non-linearity mean: 0.958
[17:32:10.488] <TB3> INFO: non-linearity RMS: 0.007
[17:32:10.488] <TB3> INFO: write gain/ped parameters into /home/mameinha/data/R417_FulltestROC_m20_2015-12-02_18h16m_1449076609//000_FulltestROC_m20//phCalibrationFitErr35_C0.dat
[17:32:10.521] <TB3> INFO: PixTestGainPedestal::doTest() done, duration: 48 seconds
[17:32:10.521] <TB3> INFO: enter test to run
[17:32:10.521] <TB3> INFO: test: Readback no parameter change
[17:32:10.521] <TB3> INFO: running: readback
[17:32:10.521] <TB3> INFO: readReadbackCal: /home/mameinha/data/R417_FulltestROC_m20_2015-12-02_18h16m_1449076609//000_FulltestROC_m20//readbackCal_C0.dat .. /home/mameinha/data/R417_FulltestROC_m20_2015-12-02_18h16m_1449076609//000_FulltestROC_m20//readbackCal_C0.dat
[17:32:10.522] <TB3> INFO: ######################################################################
[17:32:10.522] <TB3> INFO: PixTestReadback::doTest()
[17:32:10.522] <TB3> INFO: ######################################################################
[17:32:10.522] <TB3> INFO: ----------------------------------------------------------------------
[17:32:10.522] <TB3> INFO: PixTestReadback::CalibrateVd()
[17:32:10.522] <TB3> INFO: ----------------------------------------------------------------------
[17:32:21.851] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R417_FulltestROC_m20_2015-12-02_18h16m_1449076609//000_FulltestROC_m20//readbackCal_C0.dat
[17:32:21.932] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[17:32:21.933] <TB3> INFO: ----------------------------------------------------------------------
[17:32:21.933] <TB3> INFO: PixTestReadback::CalibrateVa()
[17:32:21.933] <TB3> INFO: ----------------------------------------------------------------------
[17:32:33.517] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R417_FulltestROC_m20_2015-12-02_18h16m_1449076609//000_FulltestROC_m20//readbackCal_C0.dat
[17:32:33.633] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[17:32:33.633] <TB3> INFO: ----------------------------------------------------------------------
[17:32:33.633] <TB3> INFO: PixTestReadback::readbackVbg()
[17:32:33.633] <TB3> INFO: ----------------------------------------------------------------------
[17:32:41.967] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[17:32:41.967] <TB3> INFO: ----------------------------------------------------------------------
[17:32:41.967] <TB3> INFO: PixTestReadback::getCalibratedVbg()
[17:32:41.967] <TB3> INFO: ----------------------------------------------------------------------
[17:32:41.967] <TB3> INFO: Vbg will be calibrated using Vd calibration
[17:32:41.967] <TB3> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 137.1calibrated Vbg = 1.31648 :::*/*/*/*/
[17:32:42.343] <TB3> INFO: ----------------------------------------------------------------------
[17:32:42.343] <TB3> INFO: PixTestReadback::CalibrateIa()
[17:32:42.343] <TB3> INFO: ----------------------------------------------------------------------
[17:32:51.335] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R417_FulltestROC_m20_2015-12-02_18h16m_1449076609//000_FulltestROC_m20//readbackCal_C0.dat
[17:32:51.342] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[17:32:51.342] <TB3> INFO: PixTestReadback::doTest() done
[17:32:51.377] <TB3> INFO: enter test to run
[17:32:51.377] <TB3> INFO: test: no parameter change
[17:32:51.407] <TB3> QUIET: Connection to board 137 closed.
[17:32:51.486] <TB3> INFO: pXar: this is the end, my friend