[13:30:13.661] <TB2> INFO: *** Welcome to pxar ***
[13:30:13.661] <TB2> INFO: *** Today: 2015/10/06
[13:30:13.952] <TB2> INFO: *** Version: 9da6
[13:30:13.952] <TB2> INFO: readRocDacs: /home/mameinha/data/R415_Fulltest_m20_2015-10-06_15h30m_1444138204//000_FulltestROC_m20//dacParameters_C0.dat .. /home/mameinha/data/R415_Fulltest_m20_2015-10-06_15h30m_1444138204//000_FulltestROC_m20//dacParameters_C0.dat
[13:30:13.953] <TB2> INFO: readTbmDacs: /home/mameinha/data/R415_Fulltest_m20_2015-10-06_15h30m_1444138204//000_FulltestROC_m20//tbmParameters_C0a.dat .. /home/mameinha/data/R415_Fulltest_m20_2015-10-06_15h30m_1444138204//000_FulltestROC_m20//tbmParameters_C4294967295b.dat
[13:30:13.953] <TB2> INFO: readMaskFile: /home/mameinha/data/R415_Fulltest_m20_2015-10-06_15h30m_1444138204//000_FulltestROC_m20//defaultMaskFile.dat
[13:30:13.954] <TB2> INFO: readTrimFile: /home/mameinha/data/R415_Fulltest_m20_2015-10-06_15h30m_1444138204//000_FulltestROC_m20//trimParameters_C0.dat .. /home/mameinha/data/R415_Fulltest_m20_2015-10-06_15h30m_1444138204//000_FulltestROC_m20//trimParameters_C0.dat
[13:30:13.961] <TB2> INFO: clk: 2
[13:30:13.961] <TB2> INFO: ctr: 2
[13:30:13.961] <TB2> INFO: sda: 17
[13:30:13.961] <TB2> INFO: tin: 7
[13:30:13.961] <TB2> INFO: level: 15
[13:30:13.961] <TB2> INFO: deser160phase: 4
[13:30:13.961] <TB2> QUIET: Instanciating API for pxar v2.6.0+20~g1a7f656
[13:30:13.961] <TB2> INFO: Log level: INFO
[13:30:13.974] <TB2> QUIET: Connection to board DTB_WWXJGB opened.
[13:30:13.977] <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:30:13.980] <TB2> INFO: RPC call hashes of host and DTB match: 398089610
[13:30:15.145] <TB2> INFO: DUT info:
[13:30:15.145] <TB2> INFO: The DUT currently contains the following objects:
[13:30:15.145] <TB2> INFO: 0 TBM Cores (0 ON)
[13:30:15.145] <TB2> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[13:30:15.145] <TB2> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[13:30:15.547] <TB2> INFO: enter 'restricted' command line mode
[13:30:15.547] <TB2> INFO: enter test to run
[13:30:15.547] <TB2> INFO: test: Setup no parameter change
[13:30:15.547] <TB2> INFO: running: setup
[13:30:15.551] <TB2> INFO: PixTestSetup::doTest() ntrig = 10

[13:30:15.551] <TB2> INFO: PixTestSetup:: pg set to RES|TOK
[13:30:15.551] <TB2> INFO: 0 1 2 3 4 5 6 7
[13:30:18.595] <TB2> INFO: 0: 000 000 00c 8fc ff0 f00 000 000
[13:30:21.609] <TB2> INFO: 1: 000 008 084 87c <7f8>[*] f80 800 000
[13:30:24.623] <TB2> INFO: 2: 000 008 084 87c <7f8>[*] f80 800 000
[13:30:27.637] <TB2> INFO: 3: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[13:30:30.651] <TB2> INFO: 4: 000 004 044 07c <7f8>[*] f80 800 000
[13:30:33.665] <TB2> INFO: 5: 000 004 040 43c 3fc f80 800 000
[13:30:36.679] <TB2> INFO: 6: 000 004 040 43c 3fc fc0 c00 000
[13:30:39.693] <TB2> INFO: 7: 000 004 040 43c 3fc fc0 c00 000
[13:30:42.707] <TB2> INFO: 8: c00 000 000 03c 3fc fc0 c00 000
[13:30:45.721] <TB2> INFO: 9: 000 000 020 03c 3fc fc0 c00 000
[13:30:48.735] <TB2> INFO: 10: 000 000 020 21c 1fc fc0 c00 000
[13:30:51.749] <TB2> INFO: 11: 000 000 020 21c 1fc fe0 e00 000
[13:30:54.763] <TB2> INFO: 12: 000 000 020 21c 1fc fe0 e00 000
[13:30:57.777] <TB2> INFO: 13: 000 000 000 01c 1fc fe0 e00 000
[13:31:00.791] <TB2> INFO: 14: e00 000 010 11c 1fc fe0 e00 000
[13:31:03.805] <TB2> INFO: 15: e00 000 010 10c 0fc fe0 e00 000
[13:31:06.819] <TB2> INFO: 16: 000 000 010 10c 0fc ff0 f00 000
[13:31:09.833] <TB2> INFO: 17: 000 000 010 10c 0fc ff0 f00 000
[13:31:12.847] <TB2> INFO: 18: 000 000 000 00c 0fc ff0 f00 000
[13:31:15.861] <TB2> INFO: 19: 000 000 008 00c 8fc ff0 f00 000
[13:31:16.265] <TB2> INFO: Found good delays at CLK = 2, DESER160 = 4
[13:31:16.266] <TB2> INFO: PixTestSetup:: Write Tb parameters to file.
[13:31:16.270] <TB2> INFO: write dtb parameters into /home/mameinha/data/R415_Fulltest_m20_2015-10-06_15h30m_1444138204//000_FulltestROC_m20//tbParameters.dat
[13:31:16.273] <TB2> INFO: PixTestSetup::doTest() done for.
[13:31:16.297] <TB2> INFO: enter test to run
[13:31:16.297] <TB2> INFO: test: Pretest no parameter change
[13:31:16.297] <TB2> INFO: running: pretest
[13:31:16.299] <TB2> INFO: ----------------------------------------------------------------------
[13:31:16.299] <TB2> INFO: PixTestPretest::programROC()
[13:31:16.299] <TB2> INFO: ----------------------------------------------------------------------
[13:31:19.301] <TB2> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[13:31:19.301] <TB2> INFO: IA differences per ROC: 18.5
[13:31:19.308] <TB2> INFO: enter test to run
[13:31:19.308] <TB2> INFO: test: Pretest no parameter change
[13:31:19.308] <TB2> INFO: running: pretest
[13:31:19.309] <TB2> INFO: ----------------------------------------------------------------------
[13:31:19.309] <TB2> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[13:31:19.309] <TB2> INFO: ----------------------------------------------------------------------
[13:31:20.020] <TB2> INFO: PixTestPretest::setVana() done, Module Ia 24.1 mA = 24.1 mA/ROC
[13:31:20.020] <TB2> INFO: i(loss) [mA/ROC]: 20.1
[13:31:20.023] <TB2> INFO: enter test to run
[13:31:20.023] <TB2> INFO: test: Pretest no parameter change
[13:31:20.023] <TB2> INFO: running: pretest
[13:31:20.024] <TB2> INFO: ----------------------------------------------------------------------
[13:31:20.024] <TB2> INFO: PixTestPretest::findWorkingPixel()
[13:31:20.024] <TB2> INFO: ----------------------------------------------------------------------
[13:31:20.034] <TB2> INFO: Expecting 231680 events.
[13:31:22.235] <TB2> INFO: 231680 events read in total (1813ms).
[13:31:22.237] <TB2> INFO: Test took 2212ms.
[13:31:22.616] <TB2> INFO: Found working pixel in all ROCs: col/row = 12/22
[13:31:22.622] <TB2> INFO: enter test to run
[13:31:22.622] <TB2> INFO: test: Pretest no parameter change
[13:31:22.622] <TB2> INFO: running: pretest
[13:31:22.623] <TB2> INFO: ----------------------------------------------------------------------
[13:31:22.623] <TB2> INFO: PixTestPretest::setVthrCompCalDel()
[13:31:22.623] <TB2> INFO: ----------------------------------------------------------------------
[13:31:22.633] <TB2> INFO: Expecting 231680 events.
[13:31:24.834] <TB2> INFO: 231680 events read in total (1814ms).
[13:31:24.837] <TB2> INFO: Test took 2213ms.
[13:31:25.218] <TB2> INFO: PixTestPretest::setVthrCompCalDel() done
[13:31:25.218] <TB2> INFO: CalDel: 150
[13:31:25.218] <TB2> INFO: VthrComp: 51
[13:31:25.222] <TB2> INFO: enter test to run
[13:31:25.222] <TB2> INFO: test: Pretest no parameter change
[13:31:25.222] <TB2> INFO: running: pretest
[13:31:25.226] <TB2> INFO: write dac parameters into /home/mameinha/data/R415_Fulltest_m20_2015-10-06_15h30m_1444138204//000_FulltestROC_m20//dacParameters_C0.dat
[13:31:25.229] <TB2> INFO: enter test to run
[13:31:25.229] <TB2> INFO: test: PixelAlive no parameter change
[13:31:25.229] <TB2> INFO: running: pixelalive
[13:31:25.230] <TB2> INFO: ######################################################################
[13:31:25.231] <TB2> INFO: PixTestAlive::doTest()
[13:31:25.231] <TB2> INFO: ######################################################################
[13:31:25.232] <TB2> INFO: ----------------------------------------------------------------------
[13:31:25.232] <TB2> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[13:31:25.232] <TB2> INFO: ----------------------------------------------------------------------
[13:31:25.251] <TB2> INFO: Expecting 41600 events.
[13:31:26.052] <TB2> INFO: 41600 events read in total (414ms).
[13:31:26.052] <TB2> INFO: Test took 820ms.
[13:31:26.053] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:31:26.439] <TB2> INFO: PixTestAlive::aliveTest() done
[13:31:26.439] <TB2> INFO: number of dead pixels (per ROC): 0
[13:31:26.441] <TB2> INFO: ----------------------------------------------------------------------
[13:31:26.441] <TB2> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[13:31:26.441] <TB2> INFO: ----------------------------------------------------------------------
[13:31:26.460] <TB2> INFO: Expecting 41600 events.
[13:31:27.204] <TB2> INFO: 41600 events read in total (357ms).
[13:31:27.204] <TB2> INFO: Test took 763ms.
[13:31:27.204] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:31:27.205] <TB2> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[13:31:27.596] <TB2> INFO: PixTestAlive::maskTest() done
[13:31:27.596] <TB2> INFO: number of mask-defect pixels (per ROC): 0
[13:31:27.597] <TB2> INFO: ----------------------------------------------------------------------
[13:31:27.597] <TB2> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[13:31:27.597] <TB2> INFO: ----------------------------------------------------------------------
[13:31:27.617] <TB2> INFO: Expecting 41600 events.
[13:31:28.416] <TB2> INFO: 41600 events read in total (412ms).
[13:31:28.417] <TB2> INFO: Test took 819ms.
[13:31:28.417] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:31:28.803] <TB2> INFO: PixTestAlive::addressDecodingTest() done
[13:31:28.803] <TB2> INFO: number of address-decoding pixels (per ROC): 0
[13:31:28.803] <TB2> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[13:31:28.804] <TB2> INFO: enter test to run
[13:31:28.804] <TB2> INFO: test: Scurves no parameter change
[13:31:28.804] <TB2> INFO: running: scurves
[13:31:28.805] <TB2> INFO: ######################################################################
[13:31:28.805] <TB2> INFO: PixTestScurves::doTest() ntrig = 50
[13:31:28.805] <TB2> INFO: ######################################################################
[13:31:28.805] <TB2> INFO: ----------------------------------------------------------------------
[13:31:28.805] <TB2> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[13:31:28.805] <TB2> INFO: ----------------------------------------------------------------------
[13:31:28.805] <TB2> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[13:31:28.816] <TB2> INFO: dacScan split into 1 runs with ntrig = 50
[13:31:28.816] <TB2> INFO: run 1 of 1
[13:31:28.835] <TB2> INFO: Expecting 41808000 events.
[13:33:55.719] <TB2> INFO: 20815500 events read in total (146497ms).
[13:36:18.271] <TB2> INFO: 40900200 events read in total (289049ms).
[13:36:24.698] <TB2> INFO: 41808000 events read in total (295476ms).
[13:36:24.726] <TB2> INFO: Test took 295910ms.
[13:36:24.751] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:36:26.283] <TB2> INFO: PixTestScurves::scurves() done
[13:36:26.283] <TB2> INFO: Vcal mean: 91.63
[13:36:26.283] <TB2> INFO: Vcal RMS: 6.66
[13:36:26.287] <TB2> INFO: enter test to run
[13:36:26.288] <TB2> INFO: test: Trim no parameter change
[13:36:26.288] <TB2> INFO: running: trim
[13:36:26.290] <TB2> INFO: ######################################################################
[13:36:26.290] <TB2> INFO: PixTestTrim::doTest()
[13:36:26.290] <TB2> INFO: ######################################################################
[13:36:26.291] <TB2> INFO: ----------------------------------------------------------------------
[13:36:26.291] <TB2> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[13:36:26.291] <TB2> INFO: ----------------------------------------------------------------------
[13:36:26.296] <TB2> INFO: ---> VthrComp thr map (minimal VthrComp)
[13:36:26.296] <TB2> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[13:36:26.304] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:36:26.304] <TB2> INFO: run 1 of 1
[13:36:26.323] <TB2> INFO: Expecting 6281600 events.
[13:37:12.414] <TB2> INFO: 6281600 events read in total (45700ms).
[13:37:12.429] <TB2> INFO: Test took 46125ms.
[13:37:12.440] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:13.566] <TB2> INFO: ROC 0 VthrComp = 91
[13:37:13.566] <TB2> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[13:37:13.566] <TB2> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[13:37:13.574] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:37:13.574] <TB2> INFO: run 1 of 1
[13:37:13.593] <TB2> INFO: Expecting 6281600 events.
[13:38:03.519] <TB2> INFO: 6281600 events read in total (49538ms).
[13:38:03.632] <TB2> INFO: Test took 50058ms.
[13:38:03.651] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:04.930] <TB2> INFO: roc 0 with ID = 0 has maximal Vcal 64.8478 for pixel 12/2 mean/min/max = 48.0674/31.2582/64.8767
[13:38:04.939] <TB2> INFO: Expecting 514560 events.
[13:38:09.000] <TB2> INFO: 514560 events read in total (3674ms).
[13:38:09.005] <TB2> INFO: Test took 4075ms.
[13:38:09.398] <TB2> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[13:38:09.406] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:38:09.406] <TB2> INFO: run 1 of 1
[13:38:09.425] <TB2> INFO: Expecting 6281600 events.
[13:38:59.477] <TB2> INFO: 6281600 events read in total (49665ms).
[13:38:59.527] <TB2> INFO: Test took 50121ms.
[13:38:59.547] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:00.791] <TB2> INFO: ---> TrimStepCorr4 extremal thresholds: 6.500000 .. 49.602181
[13:39:00.795] <TB2> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 6 .. 59 (-1/-1) hits flags = 528 (plus default)
[13:39:00.803] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:39:00.803] <TB2> INFO: run 1 of 1
[13:39:00.822] <TB2> INFO: Expecting 2246400 events.
[13:39:18.426] <TB2> INFO: 2246400 events read in total (17217ms).
[13:39:18.435] <TB2> INFO: Test took 17632ms.
[13:39:18.440] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:19.247] <TB2> INFO: ---> TrimStepCorr2 extremal thresholds: 16.479689 .. 42.862850
[13:39:19.251] <TB2> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 6 .. 52 (-1/-1) hits flags = 528 (plus default)
[13:39:19.259] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:39:19.259] <TB2> INFO: run 1 of 1
[13:39:19.278] <TB2> INFO: Expecting 1955200 events.
[13:39:34.444] <TB2> INFO: 1955200 events read in total (14779ms).
[13:39:34.451] <TB2> INFO: Test took 15192ms.
[13:39:34.455] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:35.213] <TB2> INFO: ---> TrimStepCorr1a extremal thresholds: 21.624045 .. 37.866412
[13:39:35.218] <TB2> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 11 .. 47 (-1/-1) hits flags = 528 (plus default)
[13:39:35.225] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:39:35.225] <TB2> INFO: run 1 of 1
[13:39:35.244] <TB2> INFO: Expecting 1539200 events.
[13:39:47.311] <TB2> INFO: 1539200 events read in total (11680ms).
[13:39:47.317] <TB2> INFO: Test took 12092ms.
[13:39:47.320] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:48.043] <TB2> INFO: ---> TrimStepCorr1b extremal thresholds: 25.378116 .. 37.784716
[13:39:48.048] <TB2> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 15 .. 47 (-1/-1) hits flags = 528 (plus default)
[13:39:48.056] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:39:48.056] <TB2> INFO: run 1 of 1
[13:39:48.075] <TB2> INFO: Expecting 1372800 events.
[13:39:58.983] <TB2> INFO: 1372800 events read in total (10521ms).
[13:39:58.988] <TB2> INFO: Test took 10932ms.
[13:39:58.991] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:59.708] <TB2> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[13:39:59.708] <TB2> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[13:39:59.716] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:39:59.716] <TB2> INFO: run 1 of 1
[13:39:59.735] <TB2> INFO: Expecting 1705600 events.
[13:40:13.309] <TB2> INFO: 1705600 events read in total (13187ms).
[13:40:13.318] <TB2> INFO: Test took 13602ms.
[13:40:13.322] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:40:14.127] <TB2> INFO: write dac parameters into /home/mameinha/data/R415_Fulltest_m20_2015-10-06_15h30m_1444138204//000_FulltestROC_m20//dacParameters35_C0.dat
[13:40:14.131] <TB2> INFO: write trim parameters into /home/mameinha/data/R415_Fulltest_m20_2015-10-06_15h30m_1444138204//000_FulltestROC_m20//trimParameters35_C0.dat
[13:40:14.142] <TB2> INFO: PixTestTrim::trimTest() done
[13:40:14.142] <TB2> INFO: vtrim: 129
[13:40:14.142] <TB2> INFO: vthrcomp: 91
[13:40:14.142] <TB2> INFO: vcal mean: 34.99
[13:40:14.142] <TB2> INFO: vcal RMS: 0.87
[13:40:14.142] <TB2> INFO: bits mean: 9.30
[13:40:14.142] <TB2> INFO: bits RMS: 2.70
[13:40:14.146] <TB2> INFO: ----------------------------------------------------------------------
[13:40:14.146] <TB2> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[13:40:14.146] <TB2> INFO: ----------------------------------------------------------------------
[13:40:14.146] <TB2> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[13:40:14.154] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:40:14.154] <TB2> INFO: run 1 of 1
[13:40:14.173] <TB2> INFO: Expecting 8320000 events.
[13:41:16.654] <TB2> INFO: 8320000 events read in total (62094ms).
[13:41:16.690] <TB2> INFO: Test took 62536ms.
[13:41:16.706] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:41:18.161] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 158 (-1/-1) hits flags = 528 (plus default)
[13:41:18.169] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:41:18.169] <TB2> INFO: run 1 of 1
[13:41:18.188] <TB2> INFO: Expecting 6614400 events.
[13:42:07.475] <TB2> INFO: 6614400 events read in total (48900ms).
[13:42:07.496] <TB2> INFO: Test took 49327ms.
[13:42:07.506] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:42:08.750] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 148 (-1/-1) hits flags = 528 (plus default)
[13:42:08.757] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:42:08.757] <TB2> INFO: run 1 of 1
[13:42:08.776] <TB2> INFO: Expecting 6198400 events.
[13:42:54.581] <TB2> INFO: 6198400 events read in total (45418ms).
[13:42:54.599] <TB2> INFO: Test took 45842ms.
[13:42:54.608] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:42:55.804] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 148 (-1/-1) hits flags = 528 (plus default)
[13:42:55.811] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:42:55.811] <TB2> INFO: run 1 of 1
[13:42:55.830] <TB2> INFO: Expecting 6198400 events.
[13:43:41.669] <TB2> INFO: 6198400 events read in total (45451ms).
[13:43:41.689] <TB2> INFO: Test took 45878ms.
[13:43:41.698] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:42.891] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 148 (-1/-1) hits flags = 528 (plus default)
[13:43:42.899] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:43:42.899] <TB2> INFO: run 1 of 1
[13:43:42.918] <TB2> INFO: Expecting 6198400 events.
[13:44:28.728] <TB2> INFO: 6198400 events read in total (45423ms).
[13:44:28.749] <TB2> INFO: Test took 45850ms.
[13:44:28.758] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:29.967] <TB2> INFO: PixTestTrim::trimBitTest() done
[13:44:29.969] <TB2> INFO: PixTestTrim::doTest() done, duration: 483 seconds
[13:44:30.009] <TB2> INFO: enter test to run
[13:44:30.009] <TB2> INFO: test: PhOptimization no parameter change
[13:44:30.009] <TB2> INFO: running: phoptimization
[13:44:30.009] <TB2> INFO: ######################################################################
[13:44:30.009] <TB2> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[13:44:30.009] <TB2> INFO: ######################################################################
[13:44:30.030] <TB2> INFO: Expecting 41600 events.
[13:44:30.829] <TB2> INFO: 41600 events read in total (412ms).
[13:44:30.829] <TB2> INFO: Test took 818ms.
[13:44:30.830] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:31.221] <TB2> INFO: Expecting 41600 events.
[13:44:32.036] <TB2> INFO: 41600 events read in total (428ms).
[13:44:32.037] <TB2> INFO: Test took 1206ms.
[13:44:32.037] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:32.426] <TB2> INFO: Expecting 41600 events.
[13:44:33.227] <TB2> INFO: 41600 events read in total (414ms).
[13:44:33.228] <TB2> INFO: Test took 1190ms.
[13:44:33.228] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:33.617] <TB2> INFO: Expecting 2560 events.
[13:44:34.035] <TB2> INFO: 2560 events read in total (31ms).
[13:44:34.035] <TB2> INFO: Test took 807ms.
[13:44:34.431] <TB2> INFO: Expecting 655360 events.
[13:44:39.709] <TB2> INFO: 655360 events read in total (4891ms).
[13:44:39.720] <TB2> INFO: Test took 5684ms.
[13:44:40.008] <TB2> INFO: Expecting 655360 events.
[13:44:45.376] <TB2> INFO: 655360 events read in total (4981ms).
[13:44:45.385] <TB2> INFO: Test took 5652ms.
[13:44:45.403] <TB2> INFO: safety margin for low PH: adding 0, margin is now 20
[13:44:45.423] <TB2> INFO: write dac parameters into /home/mameinha/data/R415_Fulltest_m20_2015-10-06_15h30m_1444138204//000_FulltestROC_m20//dacParameters35_C0.dat
[13:44:45.678] <TB2> INFO: Expecting 41600 events.
[13:44:46.453] <TB2> INFO: 41600 events read in total (388ms).
[13:44:46.454] <TB2> INFO: Test took 1028ms.
[13:44:46.843] <TB2> INFO: Expecting 41600 events.
[13:44:47.618] <TB2> INFO: 41600 events read in total (388ms).
[13:44:47.619] <TB2> INFO: Test took 1165ms.
[13:44:48.008] <TB2> INFO: Expecting 41600 events.
[13:44:48.770] <TB2> INFO: 41600 events read in total (375ms).
[13:44:48.770] <TB2> INFO: Test took 1151ms.
[13:44:49.159] <TB2> INFO: Expecting 2560 events.
[13:44:49.577] <TB2> INFO: 2560 events read in total (31ms).
[13:44:49.577] <TB2> INFO: Test took 806ms.
[13:44:49.972] <TB2> INFO: Expecting 2560 events.
[13:44:50.390] <TB2> INFO: 2560 events read in total (31ms).
[13:44:50.390] <TB2> INFO: Test took 813ms.
[13:44:50.799] <TB2> INFO: PixTestPhOptimization::doTest() done, duration: 20 seconds
[13:44:50.799] <TB2> INFO: PH scale (per ROC): 78
[13:44:50.799] <TB2> INFO: PH offset (per ROC): 177
[13:44:50.812] <TB2> INFO: enter test to run
[13:44:50.812] <TB2> INFO: test: GainPedestal no parameter change
[13:44:50.812] <TB2> INFO: running: gainpedestal
[13:44:50.813] <TB2> INFO: ######################################################################
[13:44:50.813] <TB2> INFO: PixTestGainPedestal::doTest() ntrig = 10
[13:44:50.813] <TB2> INFO: ######################################################################
[13:44:50.821] <TB2> INFO: scanning low vcal = 10
[13:44:50.840] <TB2> INFO: Expecting 41600 events.
[13:44:51.929] <TB2> INFO: 41600 events read in total (702ms).
[13:44:51.930] <TB2> INFO: Test took 1109ms.
[13:44:51.930] <TB2> INFO: scanning low vcal = 20
[13:44:52.325] <TB2> INFO: Expecting 41600 events.
[13:44:53.413] <TB2> INFO: 41600 events read in total (701ms).
[13:44:53.414] <TB2> INFO: Test took 1484ms.
[13:44:53.414] <TB2> INFO: scanning low vcal = 30
[13:44:53.809] <TB2> INFO: Expecting 41600 events.
[13:44:54.898] <TB2> INFO: 41600 events read in total (702ms).
[13:44:54.898] <TB2> INFO: Test took 1484ms.
[13:44:54.898] <TB2> INFO: scanning low vcal = 40
[13:44:55.293] <TB2> INFO: Expecting 41600 events.
[13:44:56.430] <TB2> INFO: 41600 events read in total (750ms).
[13:44:56.431] <TB2> INFO: Test took 1533ms.
[13:44:56.431] <TB2> INFO: scanning low vcal = 50
[13:44:56.820] <TB2> INFO: Expecting 41600 events.
[13:44:57.945] <TB2> INFO: 41600 events read in total (738ms).
[13:44:57.946] <TB2> INFO: Test took 1515ms.
[13:44:57.946] <TB2> INFO: scanning low vcal = 60
[13:44:58.334] <TB2> INFO: Expecting 41600 events.
[13:44:59.460] <TB2> INFO: 41600 events read in total (738ms).
[13:44:59.460] <TB2> INFO: Test took 1514ms.
[13:44:59.461] <TB2> INFO: scanning low vcal = 70
[13:44:59.849] <TB2> INFO: Expecting 41600 events.
[13:45:00.988] <TB2> INFO: 41600 events read in total (752ms).
[13:45:00.989] <TB2> INFO: Test took 1528ms.
[13:45:00.989] <TB2> INFO: scanning low vcal = 80
[13:45:01.378] <TB2> INFO: Expecting 41600 events.
[13:45:02.527] <TB2> INFO: 41600 events read in total (762ms).
[13:45:02.527] <TB2> INFO: Test took 1538ms.
[13:45:02.527] <TB2> INFO: scanning low vcal = 90
[13:45:02.916] <TB2> INFO: Expecting 41600 events.
[13:45:04.041] <TB2> INFO: 41600 events read in total (738ms).
[13:45:04.042] <TB2> INFO: Test took 1515ms.
[13:45:04.042] <TB2> INFO: scanning low vcal = 100
[13:45:04.431] <TB2> INFO: Expecting 41600 events.
[13:45:05.564] <TB2> INFO: 41600 events read in total (746ms).
[13:45:05.565] <TB2> INFO: Test took 1522ms.
[13:45:05.565] <TB2> INFO: scanning low vcal = 110
[13:45:05.954] <TB2> INFO: Expecting 41600 events.
[13:45:07.079] <TB2> INFO: 41600 events read in total (738ms).
[13:45:07.080] <TB2> INFO: Test took 1515ms.
[13:45:07.080] <TB2> INFO: scanning low vcal = 120
[13:45:07.469] <TB2> INFO: Expecting 41600 events.
[13:45:08.594] <TB2> INFO: 41600 events read in total (738ms).
[13:45:08.595] <TB2> INFO: Test took 1515ms.
[13:45:08.595] <TB2> INFO: scanning low vcal = 130
[13:45:08.984] <TB2> INFO: Expecting 41600 events.
[13:45:10.109] <TB2> INFO: 41600 events read in total (738ms).
[13:45:10.110] <TB2> INFO: Test took 1515ms.
[13:45:10.111] <TB2> INFO: scanning low vcal = 140
[13:45:10.499] <TB2> INFO: Expecting 41600 events.
[13:45:11.624] <TB2> INFO: 41600 events read in total (738ms).
[13:45:11.625] <TB2> INFO: Test took 1514ms.
[13:45:11.625] <TB2> INFO: scanning low vcal = 150
[13:45:12.014] <TB2> INFO: Expecting 41600 events.
[13:45:13.139] <TB2> INFO: 41600 events read in total (738ms).
[13:45:13.140] <TB2> INFO: Test took 1515ms.
[13:45:13.140] <TB2> INFO: scanning low vcal = 160
[13:45:13.529] <TB2> INFO: Expecting 41600 events.
[13:45:14.654] <TB2> INFO: 41600 events read in total (738ms).
[13:45:14.655] <TB2> INFO: Test took 1515ms.
[13:45:14.655] <TB2> INFO: scanning low vcal = 170
[13:45:15.044] <TB2> INFO: Expecting 41600 events.
[13:45:16.169] <TB2> INFO: 41600 events read in total (738ms).
[13:45:16.169] <TB2> INFO: Test took 1514ms.
[13:45:16.170] <TB2> INFO: scanning low vcal = 180
[13:45:16.558] <TB2> INFO: Expecting 41600 events.
[13:45:17.698] <TB2> INFO: 41600 events read in total (753ms).
[13:45:17.699] <TB2> INFO: Test took 1529ms.
[13:45:17.699] <TB2> INFO: scanning low vcal = 190
[13:45:18.088] <TB2> INFO: Expecting 41600 events.
[13:45:19.213] <TB2> INFO: 41600 events read in total (738ms).
[13:45:19.214] <TB2> INFO: Test took 1515ms.
[13:45:19.214] <TB2> INFO: scanning low vcal = 200
[13:45:19.603] <TB2> INFO: Expecting 41600 events.
[13:45:20.728] <TB2> INFO: 41600 events read in total (738ms).
[13:45:20.729] <TB2> INFO: Test took 1515ms.
[13:45:20.729] <TB2> INFO: scanning low vcal = 210
[13:45:21.118] <TB2> INFO: Expecting 41600 events.
[13:45:22.243] <TB2> INFO: 41600 events read in total (738ms).
[13:45:22.244] <TB2> INFO: Test took 1515ms.
[13:45:22.244] <TB2> INFO: scanning low vcal = 220
[13:45:22.632] <TB2> INFO: Expecting 41600 events.
[13:45:23.758] <TB2> INFO: 41600 events read in total (739ms).
[13:45:23.758] <TB2> INFO: Test took 1514ms.
[13:45:23.759] <TB2> INFO: scanning low vcal = 230
[13:45:24.147] <TB2> INFO: Expecting 41600 events.
[13:45:25.287] <TB2> INFO: 41600 events read in total (753ms).
[13:45:25.288] <TB2> INFO: Test took 1529ms.
[13:45:25.288] <TB2> INFO: scanning low vcal = 240
[13:45:25.677] <TB2> INFO: Expecting 41600 events.
[13:45:26.802] <TB2> INFO: 41600 events read in total (738ms).
[13:45:26.802] <TB2> INFO: Test took 1514ms.
[13:45:26.803] <TB2> INFO: scanning low vcal = 250
[13:45:27.191] <TB2> INFO: Expecting 41600 events.
[13:45:28.331] <TB2> INFO: 41600 events read in total (753ms).
[13:45:28.332] <TB2> INFO: Test took 1529ms.
[13:45:28.332] <TB2> INFO: scanning high vcal = 30 (= 210 in low range)
[13:45:28.721] <TB2> INFO: Expecting 41600 events.
[13:45:29.848] <TB2> INFO: 41600 events read in total (740ms).
[13:45:29.848] <TB2> INFO: Test took 1516ms.
[13:45:29.849] <TB2> INFO: scanning high vcal = 50 (= 350 in low range)
[13:45:30.237] <TB2> INFO: Expecting 41600 events.
[13:45:31.363] <TB2> INFO: 41600 events read in total (739ms).
[13:45:31.363] <TB2> INFO: Test took 1514ms.
[13:45:31.364] <TB2> INFO: scanning high vcal = 70 (= 490 in low range)
[13:45:31.752] <TB2> INFO: Expecting 41600 events.
[13:45:32.892] <TB2> INFO: 41600 events read in total (752ms).
[13:45:32.893] <TB2> INFO: Test took 1529ms.
[13:45:32.893] <TB2> INFO: scanning high vcal = 90 (= 630 in low range)
[13:45:33.282] <TB2> INFO: Expecting 41600 events.
[13:45:34.408] <TB2> INFO: 41600 events read in total (739ms).
[13:45:34.408] <TB2> INFO: Test took 1515ms.
[13:45:34.409] <TB2> INFO: scanning high vcal = 200 (= 1400 in low range)
[13:45:34.797] <TB2> INFO: Expecting 41600 events.
[13:45:35.924] <TB2> INFO: 41600 events read in total (740ms).
[13:45:35.924] <TB2> INFO: Test took 1515ms.
[13:45:36.309] <TB2> INFO: PixTestGainPedestal::measure() done
[13:45:38.189] <TB2> INFO: PixTestGainPedestal::fit() done
[13:45:38.189] <TB2> INFO: non-linearity mean: 0.954
[13:45:38.189] <TB2> INFO: non-linearity RMS: 0.007
[13:45:38.189] <TB2> INFO: write gain/ped parameters into /home/mameinha/data/R415_Fulltest_m20_2015-10-06_15h30m_1444138204//000_FulltestROC_m20//phCalibrationFitErr35_C0.dat
[13:45:38.241] <TB2> INFO: PixTestGainPedestal::doTest() done, duration: 47 seconds
[13:45:38.242] <TB2> INFO: enter test to run
[13:45:38.242] <TB2> INFO: test: Readback no parameter change
[13:45:38.242] <TB2> INFO: running: readback
[13:45:38.242] <TB2> INFO: readReadbackCal: /home/mameinha/data/R415_Fulltest_m20_2015-10-06_15h30m_1444138204//000_FulltestROC_m20//readbackCal_C0.dat .. /home/mameinha/data/R415_Fulltest_m20_2015-10-06_15h30m_1444138204//000_FulltestROC_m20//readbackCal_C0.dat
[13:45:38.243] <TB2> INFO: ######################################################################
[13:45:38.243] <TB2> INFO: PixTestReadback::doTest()
[13:45:38.243] <TB2> INFO: ######################################################################
[13:45:38.244] <TB2> INFO: PixTestReadback::RES sent once
[13:45:49.404] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R415_Fulltest_m20_2015-10-06_15h30m_1444138204//000_FulltestROC_m20//readbackCal_C0.dat
[13:45:49.413] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[13:45:49.414] <TB2> INFO: PixTestReadback::RES sent once
[13:46:00.517] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R415_Fulltest_m20_2015-10-06_15h30m_1444138204//000_FulltestROC_m20//readbackCal_C0.dat
[13:46:00.525] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[13:46:00.525] <TB2> INFO: PixTestReadback::RES sent once
[13:46:08.855] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[13:46:08.856] <TB2> INFO: Vbg will be calibrated using Vd calibration
[13:46:08.856] <TB2> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 153calibrated Vbg = 1.23115 :::*/*/*/*/
[13:46:09.232] <TB2> INFO: PixTestReadback::RES sent once
[13:46:18.074] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R415_Fulltest_m20_2015-10-06_15h30m_1444138204//000_FulltestROC_m20//readbackCal_C0.dat
[13:46:18.080] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[13:46:18.080] <TB2> INFO: PixTestReadback::doTest() done
[13:46:18.113] <TB2> INFO: enter test to run
[13:46:18.113] <TB2> INFO: test: no parameter change
[13:46:18.148] <TB2> QUIET: Connection to board 137 closed.
[13:46:18.229] <TB2> INFO: pXar: this is the end, my friend