[12:36:56.952] <TB2> INFO: *** Welcome to pxar ***
[12:36:56.952] <TB2> INFO: *** Today: 2015/12/04
[12:36:59.126] <TB2> INFO: *** Version: 9da6
[12:36:59.126] <TB2> INFO: readRocDacs: /home/mameinha/data/R418_AnalysisROC_m20_2015-12-04_13h24m_1449231870//000_AnalysisROC_m20//dacParameters_C0.dat .. /home/mameinha/data/R418_AnalysisROC_m20_2015-12-04_13h24m_1449231870//000_AnalysisROC_m20//dacParameters_C0.dat
[12:36:59.131] <TB2> INFO: readTbmDacs: /home/mameinha/data/R418_AnalysisROC_m20_2015-12-04_13h24m_1449231870//000_AnalysisROC_m20//tbmParameters_C0a.dat .. /home/mameinha/data/R418_AnalysisROC_m20_2015-12-04_13h24m_1449231870//000_AnalysisROC_m20//tbmParameters_C4294967295b.dat
[12:36:59.131] <TB2> INFO: readMaskFile: /home/mameinha/data/R418_AnalysisROC_m20_2015-12-04_13h24m_1449231870//000_AnalysisROC_m20//defaultMaskFile.dat
[12:36:59.132] <TB2> INFO: readTrimFile: /home/mameinha/data/R418_AnalysisROC_m20_2015-12-04_13h24m_1449231870//000_AnalysisROC_m20//trimParameters_C0.dat .. /home/mameinha/data/R418_AnalysisROC_m20_2015-12-04_13h24m_1449231870//000_AnalysisROC_m20//trimParameters_C0.dat
[12:36:59.145] <TB2> INFO: clk: 4
[12:36:59.145] <TB2> INFO: ctr: 4
[12:36:59.145] <TB2> INFO: sda: 19
[12:36:59.145] <TB2> INFO: tin: 9
[12:36:59.145] <TB2> INFO: level: 15
[12:36:59.145] <TB2> INFO: deser160phase: 4
[12:36:59.145] <TB2> QUIET: Instanciating API for pxar v2.6.1+42~g55d8827
[12:36:59.145] <TB2> INFO: Log level: INFO
[12:36:59.150] <TB2> INFO: Found DTB DTB_WZ4BYI
[12:36:59.159] <TB2> QUIET: Connection to board DTB_WZ4BYI opened.
[12:36:59.162] <TB2> INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 169
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WZ4BYI
MAC address: 40D8551180A9
Hostname: pixelDTB169
Comment:
------------------------------------------------------
[12:36:59.164] <TB2> INFO: RPC call hashes of host and DTB match: 398089610
[12:37:00.327] <TB2> INFO: DUT info:
[12:37:00.327] <TB2> INFO: The DUT currently contains the following objects:
[12:37:00.327] <TB2> INFO: 0 TBM Cores (0 ON)
[12:37:00.327] <TB2> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[12:37:00.327] <TB2> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[12:37:00.729] <TB2> INFO: enter 'restricted' command line mode
[12:37:00.729] <TB2> INFO: enter test to run
[12:37:00.729] <TB2> INFO: test: Setup no parameter change
[12:37:00.729] <TB2> INFO: running: setup
[12:37:00.733] <TB2> INFO: PixTestSetup::doTest() ntrig = 10

[12:37:00.733] <TB2> INFO: PixTestSetup:: pg set to RES|TOK
[12:37:00.733] <TB2> INFO: 0 1 2 3 4 5 6 7
[12:37:03.773] <TB2> INFO: 0: 000 000 004 07c 7f0 f00 000 000
[12:37:06.785] <TB2> INFO: 1: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[12:37:09.799] <TB2> INFO: 2: 000 000 004 07c <7f8>[*] f80 800 000
[12:37:12.811] <TB2> INFO: 3: 000 000 004 07c <7f8>[*] f80 800 000
[12:37:15.823] <TB2> INFO: 4: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[12:37:18.836] <TB2> INFO: 5: 000 000 000 03c 3f8 f80 800 000
[12:37:21.849] <TB2> INFO: 6: 000 000 000 03c 3fc fc0 c00 000
[12:37:24.862] <TB2> INFO: 7: 000 000 000 03c 3fc fc0 c00 000
[12:37:27.874] <TB2> INFO: 8: 000 000 000 03c 3fc fc0 c00 000
[12:37:30.887] <TB2> INFO: 9: 000 000 000 03c 3fc fc0 c00 000
[12:37:33.899] <TB2> INFO: 10: c00 000 000 01c 1fc fc0 c00 000
[12:37:36.911] <TB2> INFO: 11: 000 000 000 01c 1fc fe0 e00 000
[12:37:39.924] <TB2> INFO: 12: 000 000 000 01c 1fc fe0 e00 000
[12:37:42.936] <TB2> INFO: 13: 000 000 000 01c 1fc fe0 e00 000
[12:37:45.948] <TB2> INFO: 14: 000 000 000 01c 1fc fe0 e00 000
[12:37:48.959] <TB2> INFO: 15: 000 000 000 00c 0fc fe0 e00 000
[12:37:51.971] <TB2> INFO: 16: 000 000 000 00c 0fc ff0 f00 000
[12:37:54.983] <TB2> INFO: 17: 000 000 000 00c 0fc ff0 f00 000
[12:37:57.995] <TB2> INFO: 18: 000 000 000 00c 0fc ff0 f00 000
[12:38:01.007] <TB2> INFO: 19: f00 000 000 00c 0fc ff0 f00 000
[12:38:01.435] <TB2> INFO: Found good delays at CLK = 2, DESER160 = 4
[12:38:01.436] <TB2> INFO: PixTestSetup:: Write Tb parameters to file.
[12:38:01.464] <TB2> INFO: write dtb parameters into /home/mameinha/data/R418_AnalysisROC_m20_2015-12-04_13h24m_1449231870//000_AnalysisROC_m20//tbParameters.dat
[12:38:01.470] <TB2> INFO: PixTestSetup::doTest() done for.
[12:38:01.497] <TB2> INFO: enter test to run
[12:38:01.497] <TB2> INFO: test: Pretest no parameter change
[12:38:01.497] <TB2> INFO: running: pretest
[12:38:01.499] <TB2> INFO: ----------------------------------------------------------------------
[12:38:01.499] <TB2> INFO: PixTestPretest::programROC()
[12:38:01.499] <TB2> INFO: ----------------------------------------------------------------------
[12:38:04.501] <TB2> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[12:38:04.501] <TB2> INFO: IA differences per ROC: 20.1
[12:38:04.505] <TB2> INFO: enter test to run
[12:38:04.505] <TB2> INFO: test: Pretest no parameter change
[12:38:04.505] <TB2> INFO: running: pretest
[12:38:04.506] <TB2> INFO: ----------------------------------------------------------------------
[12:38:04.506] <TB2> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[12:38:04.506] <TB2> INFO: ----------------------------------------------------------------------
[12:38:06.123] <TB2> INFO: PixTestPretest::setVana() done, Module Ia 24.9 mA = 24.9 mA/ROC
[12:38:06.123] <TB2> INFO: i(loss) [mA/ROC]: 20.9
[12:38:06.125] <TB2> INFO: enter test to run
[12:38:06.125] <TB2> INFO: test: Pretest no parameter change
[12:38:06.125] <TB2> INFO: running: pretest
[12:38:06.127] <TB2> INFO: ----------------------------------------------------------------------
[12:38:06.127] <TB2> INFO: PixTestPretest::findWorkingPixel()
[12:38:06.127] <TB2> INFO: ----------------------------------------------------------------------
[12:38:06.137] <TB2> INFO: Expecting 231680 events.
[12:38:08.408] <TB2> INFO: 231680 events read in total (1884ms).
[12:38:08.410] <TB2> INFO: Test took 2283ms.
[12:38:08.783] <TB2> INFO: Found working pixel in all ROCs: col/row = 12/22
[12:38:08.788] <TB2> INFO: enter test to run
[12:38:08.788] <TB2> INFO: test: Pretest no parameter change
[12:38:08.788] <TB2> INFO: running: pretest
[12:38:08.790] <TB2> INFO: ----------------------------------------------------------------------
[12:38:08.790] <TB2> INFO: PixTestPretest::setVthrCompCalDel()
[12:38:08.790] <TB2> INFO: ----------------------------------------------------------------------
[12:38:08.799] <TB2> INFO: Expecting 231680 events.
[12:38:11.143] <TB2> INFO: 231680 events read in total (1958ms).
[12:38:11.146] <TB2> INFO: Test took 2356ms.
[12:38:11.520] <TB2> INFO: PixTestPretest::setVthrCompCalDel() done
[12:38:11.520] <TB2> INFO: CalDel: 138
[12:38:11.520] <TB2> INFO: VthrComp: 51
[12:38:11.528] <TB2> INFO: enter test to run
[12:38:11.528] <TB2> INFO: test: Pretest no parameter change
[12:38:11.528] <TB2> INFO: running: pretest
[12:38:11.538] <TB2> INFO: write dac parameters into /home/mameinha/data/R418_AnalysisROC_m20_2015-12-04_13h24m_1449231870//000_AnalysisROC_m20//dacParameters_C0.dat
[12:38:11.550] <TB2> INFO: enter test to run
[12:38:11.550] <TB2> INFO: test: PixelAlive no parameter change
[12:38:11.550] <TB2> INFO: running: pixelalive
[12:38:11.551] <TB2> INFO: ######################################################################
[12:38:11.551] <TB2> INFO: PixTestAlive::doTest()
[12:38:11.551] <TB2> INFO: ######################################################################
[12:38:11.553] <TB2> INFO: ----------------------------------------------------------------------
[12:38:11.553] <TB2> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[12:38:11.553] <TB2> INFO: ----------------------------------------------------------------------
[12:38:11.580] <TB2> INFO: Expecting 41600 events.
[12:38:12.470] <TB2> INFO: 41600 events read in total (504ms).
[12:38:12.471] <TB2> INFO: Test took 918ms.
[12:38:12.471] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:38:12.853] <TB2> INFO: PixTestAlive::aliveTest() done
[12:38:12.853] <TB2> INFO: number of dead pixels (per ROC): 0
[12:38:12.855] <TB2> INFO: ----------------------------------------------------------------------
[12:38:12.855] <TB2> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[12:38:12.855] <TB2> INFO: ----------------------------------------------------------------------
[12:38:12.875] <TB2> INFO: Expecting 41600 events.
[12:38:13.673] <TB2> INFO: 41600 events read in total (412ms).
[12:38:13.674] <TB2> INFO: Test took 819ms.
[12:38:13.674] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:38:13.674] <TB2> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[12:38:14.063] <TB2> INFO: PixTestAlive::maskTest() done
[12:38:14.063] <TB2> INFO: number of mask-defect pixels (per ROC): 0
[12:38:14.064] <TB2> INFO: ----------------------------------------------------------------------
[12:38:14.064] <TB2> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[12:38:14.064] <TB2> INFO: ----------------------------------------------------------------------
[12:38:14.087] <TB2> INFO: Expecting 41600 events.
[12:38:14.969] <TB2> INFO: 41600 events read in total (495ms).
[12:38:14.969] <TB2> INFO: Test took 904ms.
[12:38:14.969] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:38:15.355] <TB2> INFO: PixTestAlive::addressDecodingTest() done
[12:38:15.355] <TB2> INFO: number of address-decoding pixels (per ROC): 0
[12:38:15.355] <TB2> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[12:38:15.356] <TB2> INFO: enter test to run
[12:38:15.356] <TB2> INFO: test: Scurves no parameter change
[12:38:15.356] <TB2> INFO: running: scurves
[12:38:15.357] <TB2> INFO: ######################################################################
[12:38:15.357] <TB2> INFO: PixTestScurves::doTest() ntrig = 50
[12:38:15.357] <TB2> INFO: ######################################################################
[12:38:15.357] <TB2> INFO: ----------------------------------------------------------------------
[12:38:15.357] <TB2> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[12:38:15.357] <TB2> INFO: ----------------------------------------------------------------------
[12:38:15.357] <TB2> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[12:38:15.371] <TB2> INFO: dacScan split into 1 runs with ntrig = 50
[12:38:15.371] <TB2> INFO: run 1 of 1
[12:38:15.392] <TB2> INFO: Expecting 41808000 events.
[12:40:29.323] <TB2> INFO: 17776750 events read in total (133544ms).
[12:42:42.461] <TB2> INFO: 35331850 events read in total (266682ms).
[12:43:31.267] <TB2> INFO: 41808000 events read in total (315488ms).
[12:43:31.313] <TB2> INFO: Test took 315941ms.
[12:43:31.338] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:43:31.348] <TB2> INFO: dumping ASCII scurve output file: SCurveData
[12:43:33.157] <TB2> INFO: PixTestScurves::scurves() done
[12:43:33.157] <TB2> INFO: Vcal mean: 58.58
[12:43:33.157] <TB2> INFO: Vcal RMS: 3.82
[12:43:33.164] <TB2> INFO: enter test to run
[12:43:33.164] <TB2> INFO: test: Trim no parameter change
[12:43:33.164] <TB2> INFO: running: trim
[12:43:33.165] <TB2> INFO: ######################################################################
[12:43:33.165] <TB2> INFO: PixTestTrim::doTest()
[12:43:33.165] <TB2> INFO: ######################################################################
[12:43:33.167] <TB2> INFO: ----------------------------------------------------------------------
[12:43:33.167] <TB2> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[12:43:33.167] <TB2> INFO: ----------------------------------------------------------------------
[12:43:33.174] <TB2> INFO: ---> VthrComp thr map (minimal VthrComp)
[12:43:33.174] <TB2> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[12:43:33.184] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:43:33.184] <TB2> INFO: run 1 of 1
[12:43:33.205] <TB2> INFO: Expecting 6281600 events.
[12:44:21.791] <TB2> INFO: 6281600 events read in total (48194ms).
[12:44:21.818] <TB2> INFO: Test took 48634ms.
[12:44:21.829] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:44:23.073] <TB2> INFO: ROC 0 VthrComp = 74
[12:44:23.074] <TB2> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[12:44:23.074] <TB2> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[12:44:23.081] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:44:23.081] <TB2> INFO: run 1 of 1
[12:44:23.101] <TB2> INFO: Expecting 6281600 events.
[12:45:14.185] <TB2> INFO: 6281600 events read in total (50697ms).
[12:45:14.237] <TB2> INFO: Test took 51156ms.
[12:45:14.257] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:45:15.511] <TB2> INFO: roc 0 with ID = 0 has maximal Vcal 53.2339 for pixel 1/79 mean/min/max = 43.5105/33.502/53.5189
[12:45:15.520] <TB2> INFO: Expecting 514560 events.
[12:45:19.856] <TB2> INFO: 514560 events read in total (3949ms).
[12:45:19.861] <TB2> INFO: Test took 4350ms.
[12:45:20.271] <TB2> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[12:45:20.279] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:45:20.279] <TB2> INFO: run 1 of 1
[12:45:20.299] <TB2> INFO: Expecting 6281600 events.
[12:46:12.730] <TB2> INFO: 6281600 events read in total (52044ms).
[12:46:12.784] <TB2> INFO: Test took 52505ms.
[12:46:12.805] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:46:14.031] <TB2> INFO: ---> TrimStepCorr4 extremal thresholds: 19.542010 .. 44.498650
[12:46:14.036] <TB2> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 9 .. 54 (-1/-1) hits flags = 528 (plus default)
[12:46:14.043] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:46:14.043] <TB2> INFO: run 1 of 1
[12:46:14.063] <TB2> INFO: Expecting 1913600 events.
[12:46:29.620] <TB2> INFO: 1913600 events read in total (15170ms).
[12:46:29.628] <TB2> INFO: Test took 15585ms.
[12:46:29.632] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:46:30.440] <TB2> INFO: ---> TrimStepCorr2 extremal thresholds: 25.734125 .. 38.396007
[12:46:30.445] <TB2> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 15 .. 48 (-1/-1) hits flags = 528 (plus default)
[12:46:30.452] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:46:30.452] <TB2> INFO: run 1 of 1
[12:46:30.471] <TB2> INFO: Expecting 1414400 events.
[12:46:42.111] <TB2> INFO: 1414400 events read in total (11253ms).
[12:46:42.117] <TB2> INFO: Test took 11665ms.
[12:46:42.120] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:46:43.017] <TB2> INFO: ---> TrimStepCorr1a extremal thresholds: 28.658497 .. 37.018491
[12:46:43.022] <TB2> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 18 .. 47 (-1/-1) hits flags = 528 (plus default)
[12:46:43.029] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:46:43.029] <TB2> INFO: run 1 of 1
[12:46:43.049] <TB2> INFO: Expecting 1248000 events.
[12:46:53.455] <TB2> INFO: 1248000 events read in total (10019ms).
[12:46:53.461] <TB2> INFO: Test took 10431ms.
[12:46:53.464] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:46:54.231] <TB2> INFO: ---> TrimStepCorr1b extremal thresholds: 30.516416 .. 36.397100
[12:46:54.235] <TB2> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 20 .. 46 (-1/-1) hits flags = 528 (plus default)
[12:46:54.243] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:46:54.243] <TB2> INFO: run 1 of 1
[12:46:54.262] <TB2> INFO: Expecting 1123200 events.
[12:47:03.634] <TB2> INFO: 1123200 events read in total (8985ms).
[12:47:03.640] <TB2> INFO: Test took 9397ms.
[12:47:03.643] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:47:04.393] <TB2> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[12:47:04.393] <TB2> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[12:47:04.401] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:47:04.401] <TB2> INFO: run 1 of 1
[12:47:04.420] <TB2> INFO: Expecting 1705600 events.
[12:47:18.640] <TB2> INFO: 1705600 events read in total (13833ms).
[12:47:18.650] <TB2> INFO: Test took 14249ms.
[12:47:18.654] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:47:19.466] <TB2> INFO: write dac parameters into /home/mameinha/data/R418_AnalysisROC_m20_2015-12-04_13h24m_1449231870//000_AnalysisROC_m20//dacParameters35_C0.dat
[12:47:19.530] <TB2> INFO: write trim parameters into /home/mameinha/data/R418_AnalysisROC_m20_2015-12-04_13h24m_1449231870//000_AnalysisROC_m20//trimParameters35_C0.dat
[12:47:19.633] <TB2> INFO: PixTestTrim::trimTest() done
[12:47:19.633] <TB2> INFO: vtrim: 104
[12:47:19.633] <TB2> INFO: vthrcomp: 74
[12:47:19.633] <TB2> INFO: vcal mean: 35.01
[12:47:19.633] <TB2> INFO: vcal RMS: 0.59
[12:47:19.633] <TB2> INFO: bits mean: 10.01
[12:47:19.633] <TB2> INFO: bits RMS: 2.30
[12:47:19.637] <TB2> INFO: ----------------------------------------------------------------------
[12:47:19.638] <TB2> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[12:47:19.638] <TB2> INFO: ----------------------------------------------------------------------
[12:47:19.638] <TB2> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[12:47:19.648] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:47:19.648] <TB2> INFO: run 1 of 1
[12:47:19.669] <TB2> INFO: Expecting 8320000 events.
[12:48:27.033] <TB2> INFO: 8320000 events read in total (66977ms).
[12:48:27.085] <TB2> INFO: Test took 67437ms.
[12:48:27.114] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:48:28.589] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 104 (-1/-1) hits flags = 528 (plus default)
[12:48:28.597] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:48:28.597] <TB2> INFO: run 1 of 1
[12:48:28.616] <TB2> INFO: Expecting 4368000 events.
[12:49:03.169] <TB2> INFO: 4368000 events read in total (34166ms).
[12:49:03.186] <TB2> INFO: Test took 34589ms.
[12:49:03.193] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:49:04.337] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 95 (-1/-1) hits flags = 528 (plus default)
[12:49:04.344] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:49:04.344] <TB2> INFO: run 1 of 1
[12:49:04.363] <TB2> INFO: Expecting 3993600 events.
[12:49:35.641] <TB2> INFO: 3993600 events read in total (30891ms).
[12:49:35.653] <TB2> INFO: Test took 31309ms.
[12:49:35.659] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:49:36.656] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 95 (-1/-1) hits flags = 528 (plus default)
[12:49:36.663] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:49:36.663] <TB2> INFO: run 1 of 1
[12:49:36.682] <TB2> INFO: Expecting 3993600 events.
[12:50:07.336] <TB2> INFO: 3993600 events read in total (30267ms).
[12:50:07.352] <TB2> INFO: Test took 30690ms.
[12:50:07.361] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:08.406] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 95 (-1/-1) hits flags = 528 (plus default)
[12:50:08.414] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[12:50:08.414] <TB2> INFO: run 1 of 1
[12:50:08.433] <TB2> INFO: Expecting 3993600 events.
[12:50:39.149] <TB2> INFO: 3993600 events read in total (30329ms).
[12:50:39.162] <TB2> INFO: Test took 30748ms.
[12:50:39.168] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:40.190] <TB2> INFO: PixTestTrim::trimBitTest() done
[12:50:40.191] <TB2> INFO: PixTestTrim::doTest() done, duration: 427 seconds
[12:50:40.231] <TB2> INFO: enter test to run
[12:50:40.231] <TB2> INFO: test: PhOptimization no parameter change
[12:50:40.231] <TB2> INFO: running: phoptimization
[12:50:40.231] <TB2> INFO: ######################################################################
[12:50:40.231] <TB2> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[12:50:40.231] <TB2> INFO: ######################################################################
[12:50:40.255] <TB2> INFO: Expecting 41600 events.
[12:50:41.068] <TB2> INFO: 41600 events read in total (426ms).
[12:50:41.068] <TB2> INFO: Test took 835ms.
[12:50:41.068] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:41.459] <TB2> INFO: Expecting 41600 events.
[12:50:42.228] <TB2> INFO: 41600 events read in total (382ms).
[12:50:42.229] <TB2> INFO: Test took 1160ms.
[12:50:42.229] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:42.621] <TB2> INFO: Expecting 41600 events.
[12:50:43.461] <TB2> INFO: 41600 events read in total (453ms).
[12:50:43.461] <TB2> INFO: Test took 1232ms.
[12:50:43.462] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:43.850] <TB2> INFO: Expecting 2560 events.
[12:50:44.271] <TB2> INFO: 2560 events read in total (34ms).
[12:50:44.271] <TB2> INFO: Test took 809ms.
[12:50:44.666] <TB2> INFO: Expecting 655360 events.
[12:50:50.203] <TB2> INFO: 655360 events read in total (5150ms).
[12:50:50.212] <TB2> INFO: Test took 5940ms.
[12:50:50.497] <TB2> INFO: Expecting 655360 events.
[12:50:56.139] <TB2> INFO: 655360 events read in total (5255ms).
[12:50:56.148] <TB2> INFO: Test took 5922ms.
[12:50:56.167] <TB2> INFO: safety margin for low PH: adding 0, margin is now 20
[12:50:56.184] <TB2> INFO: write dac parameters into /home/mameinha/data/R418_AnalysisROC_m20_2015-12-04_13h24m_1449231870//000_AnalysisROC_m20//dacParameters35_C0.dat
[12:50:56.435] <TB2> INFO: Expecting 41600 events.
[12:50:57.240] <TB2> INFO: 41600 events read in total (418ms).
[12:50:57.240] <TB2> INFO: Test took 1053ms.
[12:50:57.629] <TB2> INFO: Expecting 41600 events.
[12:50:58.434] <TB2> INFO: 41600 events read in total (418ms).
[12:50:58.434] <TB2> INFO: Test took 1193ms.
[12:50:58.820] <TB2> INFO: Expecting 41600 events.
[12:50:59.594] <TB2> INFO: 41600 events read in total (387ms).
[12:50:59.594] <TB2> INFO: Test took 1159ms.
[12:50:59.983] <TB2> INFO: Expecting 2560 events.
[12:51:00.401] <TB2> INFO: 2560 events read in total (31ms).
[12:51:00.401] <TB2> INFO: Test took 806ms.
[12:51:00.796] <TB2> INFO: Expecting 2560 events.
[12:51:01.214] <TB2> INFO: 2560 events read in total (31ms).
[12:51:01.214] <TB2> INFO: Test took 813ms.
[12:51:01.621] <TB2> INFO: PixTestPhOptimization::doTest() done, duration: 21 seconds
[12:51:01.621] <TB2> INFO: PH scale (per ROC): 110
[12:51:01.621] <TB2> INFO: PH offset (per ROC): 151
[12:51:01.638] <TB2> INFO: enter test to run
[12:51:01.638] <TB2> INFO: test: GainPedestal no parameter change
[12:51:01.638] <TB2> INFO: running: gainpedestal
[12:51:01.639] <TB2> INFO: ######################################################################
[12:51:01.639] <TB2> INFO: PixTestGainPedestal::doTest() ntrig = 10
[12:51:01.639] <TB2> INFO: ######################################################################
[12:51:01.646] <TB2> INFO: scanning low vcal = 10
[12:51:01.666] <TB2> INFO: Expecting 41600 events.
[12:51:02.783] <TB2> INFO: 41600 events read in total (730ms).
[12:51:02.783] <TB2> INFO: Test took 1137ms.
[12:51:02.783] <TB2> INFO: scanning low vcal = 20
[12:51:03.178] <TB2> INFO: Expecting 41600 events.
[12:51:04.267] <TB2> INFO: 41600 events read in total (702ms).
[12:51:04.267] <TB2> INFO: Test took 1484ms.
[12:51:04.267] <TB2> INFO: scanning low vcal = 30
[12:51:04.662] <TB2> INFO: Expecting 41600 events.
[12:51:05.750] <TB2> INFO: 41600 events read in total (701ms).
[12:51:05.750] <TB2> INFO: Test took 1483ms.
[12:51:05.751] <TB2> INFO: scanning low vcal = 40
[12:51:06.146] <TB2> INFO: Expecting 41600 events.
[12:51:07.276] <TB2> INFO: 41600 events read in total (743ms).
[12:51:07.276] <TB2> INFO: Test took 1525ms.
[12:51:07.276] <TB2> INFO: scanning low vcal = 50
[12:51:07.661] <TB2> INFO: Expecting 41600 events.
[12:51:08.801] <TB2> INFO: 41600 events read in total (753ms).
[12:51:08.801] <TB2> INFO: Test took 1525ms.
[12:51:08.801] <TB2> INFO: scanning low vcal = 60
[12:51:09.190] <TB2> INFO: Expecting 41600 events.
[12:51:10.331] <TB2> INFO: 41600 events read in total (755ms).
[12:51:10.332] <TB2> INFO: Test took 1530ms.
[12:51:10.332] <TB2> INFO: scanning low vcal = 70
[12:51:10.717] <TB2> INFO: Expecting 41600 events.
[12:51:11.899] <TB2> INFO: 41600 events read in total (795ms).
[12:51:11.899] <TB2> INFO: Test took 1567ms.
[12:51:11.900] <TB2> INFO: scanning low vcal = 80
[12:51:12.288] <TB2> INFO: Expecting 41600 events.
[12:51:13.421] <TB2> INFO: 41600 events read in total (746ms).
[12:51:13.421] <TB2> INFO: Test took 1521ms.
[12:51:13.422] <TB2> INFO: scanning low vcal = 90
[12:51:13.810] <TB2> INFO: Expecting 41600 events.
[12:51:14.961] <TB2> INFO: 41600 events read in total (764ms).
[12:51:14.962] <TB2> INFO: Test took 1540ms.
[12:51:14.962] <TB2> INFO: scanning low vcal = 100
[12:51:15.347] <TB2> INFO: Expecting 41600 events.
[12:51:16.503] <TB2> INFO: 41600 events read in total (769ms).
[12:51:16.503] <TB2> INFO: Test took 1541ms.
[12:51:16.504] <TB2> INFO: scanning low vcal = 110
[12:51:16.891] <TB2> INFO: Expecting 41600 events.
[12:51:18.031] <TB2> INFO: 41600 events read in total (753ms).
[12:51:18.031] <TB2> INFO: Test took 1527ms.
[12:51:18.032] <TB2> INFO: scanning low vcal = 120
[12:51:18.420] <TB2> INFO: Expecting 41600 events.
[12:51:19.544] <TB2> INFO: 41600 events read in total (737ms).
[12:51:19.545] <TB2> INFO: Test took 1513ms.
[12:51:19.545] <TB2> INFO: scanning low vcal = 130
[12:51:19.934] <TB2> INFO: Expecting 41600 events.
[12:51:21.073] <TB2> INFO: 41600 events read in total (753ms).
[12:51:21.073] <TB2> INFO: Test took 1528ms.
[12:51:21.074] <TB2> INFO: scanning low vcal = 140
[12:51:21.462] <TB2> INFO: Expecting 41600 events.
[12:51:22.601] <TB2> INFO: 41600 events read in total (752ms).
[12:51:22.602] <TB2> INFO: Test took 1528ms.
[12:51:22.602] <TB2> INFO: scanning low vcal = 150
[12:51:22.990] <TB2> INFO: Expecting 41600 events.
[12:51:24.126] <TB2> INFO: 41600 events read in total (749ms).
[12:51:24.127] <TB2> INFO: Test took 1525ms.
[12:51:24.127] <TB2> INFO: scanning low vcal = 160
[12:51:24.512] <TB2> INFO: Expecting 41600 events.
[12:51:25.665] <TB2> INFO: 41600 events read in total (766ms).
[12:51:25.666] <TB2> INFO: Test took 1539ms.
[12:51:25.666] <TB2> INFO: scanning low vcal = 170
[12:51:26.055] <TB2> INFO: Expecting 41600 events.
[12:51:27.200] <TB2> INFO: 41600 events read in total (758ms).
[12:51:27.201] <TB2> INFO: Test took 1535ms.
[12:51:27.201] <TB2> INFO: scanning low vcal = 180
[12:51:27.590] <TB2> INFO: Expecting 41600 events.
[12:51:28.759] <TB2> INFO: 41600 events read in total (783ms).
[12:51:28.760] <TB2> INFO: Test took 1559ms.
[12:51:28.760] <TB2> INFO: scanning low vcal = 190
[12:51:29.143] <TB2> INFO: Expecting 41600 events.
[12:51:30.287] <TB2> INFO: 41600 events read in total (757ms).
[12:51:30.287] <TB2> INFO: Test took 1527ms.
[12:51:30.287] <TB2> INFO: scanning low vcal = 200
[12:51:30.676] <TB2> INFO: Expecting 41600 events.
[12:51:31.822] <TB2> INFO: 41600 events read in total (759ms).
[12:51:31.823] <TB2> INFO: Test took 1536ms.
[12:51:31.823] <TB2> INFO: scanning low vcal = 210
[12:51:32.208] <TB2> INFO: Expecting 41600 events.
[12:51:33.356] <TB2> INFO: 41600 events read in total (761ms).
[12:51:33.357] <TB2> INFO: Test took 1534ms.
[12:51:33.357] <TB2> INFO: scanning low vcal = 220
[12:51:33.743] <TB2> INFO: Expecting 41600 events.
[12:51:34.867] <TB2> INFO: 41600 events read in total (737ms).
[12:51:34.867] <TB2> INFO: Test took 1510ms.
[12:51:34.868] <TB2> INFO: scanning low vcal = 230
[12:51:35.257] <TB2> INFO: Expecting 41600 events.
[12:51:36.396] <TB2> INFO: 41600 events read in total (753ms).
[12:51:36.396] <TB2> INFO: Test took 1528ms.
[12:51:36.397] <TB2> INFO: scanning low vcal = 240
[12:51:36.785] <TB2> INFO: Expecting 41600 events.
[12:51:37.923] <TB2> INFO: 41600 events read in total (751ms).
[12:51:37.924] <TB2> INFO: Test took 1527ms.
[12:51:37.924] <TB2> INFO: scanning low vcal = 250
[12:51:38.313] <TB2> INFO: Expecting 41600 events.
[12:51:39.454] <TB2> INFO: 41600 events read in total (754ms).
[12:51:39.454] <TB2> INFO: Test took 1530ms.
[12:51:39.455] <TB2> INFO: scanning high vcal = 30 (= 210 in low range)
[12:51:39.839] <TB2> INFO: Expecting 41600 events.
[12:51:40.967] <TB2> INFO: 41600 events read in total (741ms).
[12:51:40.968] <TB2> INFO: Test took 1513ms.
[12:51:40.968] <TB2> INFO: scanning high vcal = 50 (= 350 in low range)
[12:51:41.357] <TB2> INFO: Expecting 41600 events.
[12:51:42.525] <TB2> INFO: 41600 events read in total (781ms).
[12:51:42.525] <TB2> INFO: Test took 1557ms.
[12:51:42.526] <TB2> INFO: scanning high vcal = 70 (= 490 in low range)
[12:51:42.910] <TB2> INFO: Expecting 41600 events.
[12:51:44.059] <TB2> INFO: 41600 events read in total (762ms).
[12:51:44.060] <TB2> INFO: Test took 1534ms.
[12:51:44.060] <TB2> INFO: scanning high vcal = 90 (= 630 in low range)
[12:51:44.446] <TB2> INFO: Expecting 41600 events.
[12:51:45.581] <TB2> INFO: 41600 events read in total (749ms).
[12:51:45.582] <TB2> INFO: Test took 1522ms.
[12:51:45.582] <TB2> INFO: scanning high vcal = 200 (= 1400 in low range)
[12:51:45.967] <TB2> INFO: Expecting 41600 events.
[12:51:47.073] <TB2> INFO: 41600 events read in total (719ms).
[12:51:47.073] <TB2> INFO: Test took 1491ms.
[12:51:47.461] <TB2> INFO: PixTestGainPedestal::measure() done
[12:51:49.454] <TB2> INFO: PixTestGainPedestal::fit() done
[12:51:49.454] <TB2> INFO: non-linearity mean: 0.952
[12:51:49.454] <TB2> INFO: non-linearity RMS: 0.007
[12:51:49.454] <TB2> INFO: write gain/ped parameters into /home/mameinha/data/R418_AnalysisROC_m20_2015-12-04_13h24m_1449231870//000_AnalysisROC_m20//phCalibrationFitErr35_C0.dat
[12:51:49.993] <TB2> INFO: PixTestGainPedestal::doTest() done, duration: 48 seconds
[12:51:49.995] <TB2> INFO: enter test to run
[12:51:49.995] <TB2> INFO: test: Readback no parameter change
[12:51:49.995] <TB2> INFO: running: readback
[12:51:49.995] <TB2> INFO: readReadbackCal: /home/mameinha/data/R418_AnalysisROC_m20_2015-12-04_13h24m_1449231870//000_AnalysisROC_m20//readbackCal_C0.dat .. /home/mameinha/data/R418_AnalysisROC_m20_2015-12-04_13h24m_1449231870//000_AnalysisROC_m20//readbackCal_C0.dat
[12:51:49.996] <TB2> INFO: ######################################################################
[12:51:49.996] <TB2> INFO: PixTestReadback::doTest()
[12:51:49.996] <TB2> INFO: ######################################################################
[12:51:49.996] <TB2> INFO: ----------------------------------------------------------------------
[12:51:49.996] <TB2> INFO: PixTestReadback::CalibrateVd()
[12:51:49.996] <TB2> INFO: ----------------------------------------------------------------------
[12:52:01.316] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R418_AnalysisROC_m20_2015-12-04_13h24m_1449231870//000_AnalysisROC_m20//readbackCal_C0.dat
[12:52:01.342] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[12:52:01.342] <TB2> INFO: ----------------------------------------------------------------------
[12:52:01.342] <TB2> INFO: PixTestReadback::CalibrateVa()
[12:52:01.342] <TB2> INFO: ----------------------------------------------------------------------
[12:52:12.449] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R418_AnalysisROC_m20_2015-12-04_13h24m_1449231870//000_AnalysisROC_m20//readbackCal_C0.dat
[12:52:12.463] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[12:52:12.463] <TB2> INFO: ----------------------------------------------------------------------
[12:52:12.463] <TB2> INFO: PixTestReadback::readbackVbg()
[12:52:12.463] <TB2> INFO: ----------------------------------------------------------------------
[12:52:20.791] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[12:52:20.791] <TB2> INFO: ----------------------------------------------------------------------
[12:52:20.791] <TB2> INFO: PixTestReadback::getCalibratedVbg()
[12:52:20.791] <TB2> INFO: ----------------------------------------------------------------------
[12:52:20.792] <TB2> INFO: Vbg will be calibrated using Vd calibration
[12:52:20.792] <TB2> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 123calibrated Vbg = 1.32227 :::*/*/*/*/
[12:52:21.167] <TB2> INFO: ----------------------------------------------------------------------
[12:52:21.168] <TB2> INFO: PixTestReadback::CalibrateIa()
[12:52:21.168] <TB2> INFO: ----------------------------------------------------------------------

[12:52:30.032] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R418_AnalysisROC_m20_2015-12-04_13h24m_1449231870//000_AnalysisROC_m20//readbackCal_C0.dat
[12:52:30.118] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[12:52:30.118] <TB2> INFO: PixTestReadback::doTest() done
[12:52:30.153] <TB2> INFO: enter test to run
[12:52:30.153] <TB2> INFO: test: no parameter change
[12:52:30.294] <TB2> QUIET: Connection to board 169 closed.
[12:52:30.373] <TB2> INFO: pXar: this is the end, my friend