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

[15:45:34.969] <TB3> INFO: PixTestSetup:: pg set to RES|TOK
[15:45:34.969] <TB3> INFO: 0 1 2 3 4 5 6 7
[15:45:38.012] <TB3> INFO: 0: 000 008 00c 8fc ff0 f00 000 000
[15:45:41.027] <TB3> INFO: 1: 000 00c 084 87c <7f8>[*] f80 800 000
[15:45:44.041] <TB3> INFO: 2: 000 008 084 87c <7f8>[*] f80 <7f8>[1] 000
[15:45:47.057] <TB3> INFO: 3: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[15:45:50.072] <TB3> INFO: 4: 000 004 004 07c <7f8>[*] f80 <7f8>[1] 000
[15:45:53.086] <TB3> INFO: 5: 000 004 040 43c 3f8 f80 800 000
[15:45:56.102] <TB3> INFO: 6: 800 004 040 43c 3fc fc0 c00 000
[15:45:59.116] <TB3> INFO: 7: 000 004 040 43c 3fc fc0 c00 000
[15:46:02.131] <TB3> INFO: 8: 000 000 000 03c 3fc fc0 c00 000
[15:46:05.146] <TB3> INFO: 9: 000 000 000 03c 3fc fc0 c00 000
[15:46:08.161] <TB3> INFO: 10: c00 000 000 23c 3fc fc0 c00 000
[15:46:11.177] <TB3> INFO: 11: 000 000 020 21c 1fc fe0 e00 000
[15:46:14.191] <TB3> INFO: 12: 000 000 020 21c 1fc fe0 e00 000
[15:46:17.206] <TB3> INFO: 13: e00 000 000 01c 1fc fe0 e00 000
[15:46:20.221] <TB3> INFO: 14: 000 000 010 01c 1fc fe0 e00 000
[15:46:23.235] <TB3> INFO: 15: 000 000 010 10c 0fc fe0 e00 000
[15:46:26.249] <TB3> INFO: 16: 000 000 010 10c 0fc ff0 f00 000
[15:46:29.265] <TB3> INFO: 17: 000 000 010 10c 0fc ff0 f00 000
[15:46:32.279] <TB3> INFO: 18: 000 000 000 00c 0fc ff0 f00 000
[15:46:35.294] <TB3> INFO: 19: f00 000 008 00c 0fc ff0 f00 000
[15:46:35.705] <TB3> INFO: Found good delays at CLK = 2, DESER160 = 4
[15:46:35.707] <TB3> INFO: PixTestSetup:: Write Tb parameters to file.
[15:46:35.718] <TB3> INFO: write dtb parameters into /home/mameinha/data/R416_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//tbParameters.dat
[15:46:35.724] <TB3> INFO: PixTestSetup::doTest() done for.
[15:46:35.749] <TB3> INFO: enter test to run
[15:46:35.749] <TB3> INFO: test: Pretest no parameter change
[15:46:35.749] <TB3> INFO: running: pretest
[15:46:35.750] <TB3> INFO: ----------------------------------------------------------------------
[15:46:35.750] <TB3> INFO: PixTestPretest::programROC()
[15:46:35.750] <TB3> INFO: ----------------------------------------------------------------------
[15:46:38.753] <TB3> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[15:46:38.753] <TB3> INFO: IA differences per ROC: 19.3
[15:46:38.759] <TB3> INFO: enter test to run
[15:46:38.759] <TB3> INFO: test: Pretest no parameter change
[15:46:38.759] <TB3> INFO: running: pretest
[15:46:38.761] <TB3> INFO: ----------------------------------------------------------------------
[15:46:38.761] <TB3> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[15:46:38.761] <TB3> INFO: ----------------------------------------------------------------------
[15:46:39.373] <TB3> INFO: PixTestPretest::setVana() done, Module Ia 24.1 mA = 24.1 mA/ROC
[15:46:39.373] <TB3> INFO: i(loss) [mA/ROC]: 20.1
[15:46:39.376] <TB3> INFO: enter test to run
[15:46:39.376] <TB3> INFO: test: Pretest no parameter change
[15:46:39.376] <TB3> INFO: running: pretest
[15:46:39.378] <TB3> INFO: ----------------------------------------------------------------------
[15:46:39.378] <TB3> INFO: PixTestPretest::findWorkingPixel()
[15:46:39.378] <TB3> INFO: ----------------------------------------------------------------------
[15:46:39.388] <TB3> INFO: Expecting 231680 events.
[15:46:41.662] <TB3> INFO: 231680 events read in total (1886ms).
[15:46:41.664] <TB3> INFO: Test took 2286ms.
[15:46:42.035] <TB3> INFO: Found working pixel in all ROCs: col/row = 12/22
[15:46:42.048] <TB3> INFO: enter test to run
[15:46:42.048] <TB3> INFO: test: Pretest no parameter change
[15:46:42.048] <TB3> INFO: running: pretest
[15:46:42.050] <TB3> INFO: ----------------------------------------------------------------------
[15:46:42.050] <TB3> INFO: PixTestPretest::setVthrCompCalDel()
[15:46:42.050] <TB3> INFO: ----------------------------------------------------------------------
[15:46:42.059] <TB3> INFO: Expecting 231680 events.
[15:46:44.336] <TB3> INFO: 231680 events read in total (1890ms).
[15:46:44.340] <TB3> INFO: Test took 2290ms.
[15:46:44.714] <TB3> INFO: PixTestPretest::setVthrCompCalDel() done
[15:46:44.714] <TB3> INFO: CalDel: 170
[15:46:44.714] <TB3> INFO: VthrComp: 51
[15:46:44.723] <TB3> INFO: enter test to run
[15:46:44.723] <TB3> INFO: test: Pretest no parameter change
[15:46:44.723] <TB3> INFO: running: pretest
[15:46:44.736] <TB3> INFO: write dac parameters into /home/mameinha/data/R416_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//dacParameters_C0.dat
[15:46:44.744] <TB3> INFO: enter test to run
[15:46:44.744] <TB3> INFO: test: PixelAlive no parameter change
[15:46:44.744] <TB3> INFO: running: pixelalive
[15:46:44.746] <TB3> INFO: ######################################################################
[15:46:44.746] <TB3> INFO: PixTestAlive::doTest()
[15:46:44.746] <TB3> INFO: ######################################################################
[15:46:44.748] <TB3> INFO: ----------------------------------------------------------------------
[15:46:44.748] <TB3> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[15:46:44.748] <TB3> INFO: ----------------------------------------------------------------------
[15:46:44.773] <TB3> INFO: Expecting 41600 events.
[15:46:45.575] <TB3> INFO: 41600 events read in total (415ms).
[15:46:45.577] <TB3> INFO: Test took 829ms.
[15:46:45.577] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:45.963] <TB3> INFO: PixTestAlive::aliveTest() done
[15:46:45.963] <TB3> INFO: number of dead pixels (per ROC): 0
[15:46:45.965] <TB3> INFO: ----------------------------------------------------------------------
[15:46:45.965] <TB3> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[15:46:45.965] <TB3> INFO: ----------------------------------------------------------------------
[15:46:45.991] <TB3> INFO: Expecting 41600 events.
[15:46:46.740] <TB3> INFO: 41600 events read in total (362ms).
[15:46:46.740] <TB3> INFO: Test took 775ms.
[15:46:46.740] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:46.740] <TB3> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[15:46:47.130] <TB3> INFO: PixTestAlive::maskTest() done
[15:46:47.130] <TB3> INFO: number of mask-defect pixels (per ROC): 0
[15:46:47.132] <TB3> INFO: ----------------------------------------------------------------------
[15:46:47.132] <TB3> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[15:46:47.132] <TB3> INFO: ----------------------------------------------------------------------
[15:46:47.160] <TB3> INFO: Expecting 41600 events.
[15:46:47.972] <TB3> INFO: 41600 events read in total (425ms).
[15:46:47.973] <TB3> INFO: Test took 841ms.
[15:46:47.973] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:48.359] <TB3> INFO: PixTestAlive::addressDecodingTest() done
[15:46:48.359] <TB3> INFO: number of address-decoding pixels (per ROC): 0
[15:46:48.359] <TB3> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[15:46:48.360] <TB3> INFO: enter test to run
[15:46:48.360] <TB3> INFO: test: Scurves no parameter change
[15:46:48.360] <TB3> INFO: running: scurves
[15:46:48.362] <TB3> INFO: ######################################################################
[15:46:48.362] <TB3> INFO: PixTestScurves::doTest() ntrig = 50
[15:46:48.362] <TB3> INFO: ######################################################################
[15:46:48.362] <TB3> INFO: ----------------------------------------------------------------------
[15:46:48.362] <TB3> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[15:46:48.362] <TB3> INFO: ----------------------------------------------------------------------
[15:46:48.362] <TB3> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[15:46:48.380] <TB3> INFO: dacScan split into 1 runs with ntrig = 50
[15:46:48.380] <TB3> INFO: run 1 of 1
[15:46:48.403] <TB3> INFO: Expecting 41808000 events.
[15:49:09.763] <TB3> INFO: 18713350 events read in total (140973ms).
[15:51:25.496] <TB3> INFO: 37124350 events read in total (276706ms).
[15:51:59.160] <TB3> INFO: 41808000 events read in total (310370ms).
[15:51:59.235] <TB3> INFO: Test took 310855ms.
[15:51:59.278] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:51:59.465] <TB3> INFO: dumping ASCII scurve output file: SCurveData
[15:52:01.613] <TB3> INFO: PixTestScurves::scurves() done
[15:52:01.613] <TB3> INFO: Vcal mean: 70.28
[15:52:01.613] <TB3> INFO: Vcal RMS: 4.18
[15:52:01.618] <TB3> INFO: enter test to run
[15:52:01.618] <TB3> INFO: test: Trim no parameter change
[15:52:01.618] <TB3> INFO: running: trim
[15:52:01.620] <TB3> INFO: ######################################################################
[15:52:01.620] <TB3> INFO: PixTestTrim::doTest()
[15:52:01.620] <TB3> INFO: ######################################################################
[15:52:01.621] <TB3> INFO: ----------------------------------------------------------------------
[15:52:01.621] <TB3> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[15:52:01.621] <TB3> INFO: ----------------------------------------------------------------------
[15:52:01.627] <TB3> INFO: ---> VthrComp thr map (minimal VthrComp)
[15:52:01.627] <TB3> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[15:52:01.634] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[15:52:01.634] <TB3> INFO: run 1 of 1
[15:52:01.654] <TB3> INFO: Expecting 6281600 events.
[15:52:48.612] <TB3> INFO: 6281600 events read in total (46571ms).
[15:52:48.633] <TB3> INFO: Test took 46999ms.
[15:52:48.642] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:52:49.817] <TB3> INFO: ROC 0 VthrComp = 82
[15:52:49.817] <TB3> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[15:52:49.817] <TB3> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[15:52:49.826] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[15:52:49.826] <TB3> INFO: run 1 of 1
[15:52:49.849] <TB3> INFO: Expecting 6281600 events.
[15:53:40.300] <TB3> INFO: 6281600 events read in total (50064ms).
[15:53:40.351] <TB3> INFO: Test took 50525ms.
[15:53:40.371] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:53:41.637] <TB3> INFO: roc 0 with ID = 0 has maximal Vcal 54.7462 for pixel 0/7 mean/min/max = 43.7283/32.6914/54.7652
[15:53:41.646] <TB3> INFO: Expecting 514560 events.
[15:53:45.762] <TB3> INFO: 514560 events read in total (3729ms).
[15:53:45.768] <TB3> INFO: Test took 4131ms.
[15:53:46.164] <TB3> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[15:53:46.171] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[15:53:46.171] <TB3> INFO: run 1 of 1
[15:53:46.191] <TB3> INFO: Expecting 6281600 events.
[15:54:36.759] <TB3> INFO: 6281600 events read in total (50181ms).
[15:54:36.829] <TB3> INFO: Test took 50658ms.
[15:54:36.852] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:54:38.090] <TB3> INFO: ---> TrimStepCorr4 extremal thresholds: 15.560580 .. 47.018095
[15:54:38.095] <TB3> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 5 .. 57 (-1/-1) hits flags = 528 (plus default)
[15:54:38.102] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[15:54:38.102] <TB3> INFO: run 1 of 1
[15:54:38.122] <TB3> INFO: Expecting 2204800 events.
[15:54:55.525] <TB3> INFO: 2204800 events read in total (17016ms).
[15:54:55.534] <TB3> INFO: Test took 17432ms.
[15:54:55.539] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:54:56.402] <TB3> INFO: ---> TrimStepCorr2 extremal thresholds: 21.423557 .. 42.556542
[15:54:56.407] <TB3> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 11 .. 52 (-1/-1) hits flags = 528 (plus default)
[15:54:56.414] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[15:54:56.414] <TB3> INFO: run 1 of 1
[15:54:56.434] <TB3> INFO: Expecting 1747200 events.
[15:55:10.582] <TB3> INFO: 1747200 events read in total (13761ms).
[15:55:10.590] <TB3> INFO: Test took 14176ms.
[15:55:10.594] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:55:11.375] <TB3> INFO: ---> TrimStepCorr1a extremal thresholds: 25.857889 .. 39.162655
[15:55:11.380] <TB3> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 15 .. 49 (-1/-1) hits flags = 528 (plus default)
[15:55:11.387] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[15:55:11.387] <TB3> INFO: run 1 of 1
[15:55:11.407] <TB3> INFO: Expecting 1456000 events.
[15:55:23.033] <TB3> INFO: 1456000 events read in total (11239ms).
[15:55:23.039] <TB3> INFO: Test took 11652ms.
[15:55:23.043] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:55:23.806] <TB3> INFO: ---> TrimStepCorr1b extremal thresholds: 26.323197 .. 38.282173
[15:55:23.811] <TB3> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 16 .. 48 (-1/-1) hits flags = 528 (plus default)
[15:55:23.818] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[15:55:23.818] <TB3> INFO: run 1 of 1
[15:55:23.837] <TB3> INFO: Expecting 1372800 events.
[15:55:35.334] <TB3> INFO: 1372800 events read in total (11109ms).
[15:55:35.340] <TB3> INFO: Test took 11522ms.
[15:55:35.343] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:55:36.100] <TB3> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[15:55:36.100] <TB3> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[15:55:36.108] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[15:55:36.108] <TB3> INFO: run 1 of 1
[15:55:36.127] <TB3> INFO: Expecting 1705600 events.
[15:55:50.227] <TB3> INFO: 1705600 events read in total (13713ms).
[15:55:50.236] <TB3> INFO: Test took 14128ms.
[15:55:50.240] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:55:51.093] <TB3> INFO: write dac parameters into /home/mameinha/data/R416_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//dacParameters35_C0.dat
[15:55:51.114] <TB3> INFO: write trim parameters into /home/mameinha/data/R416_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//trimParameters35_C0.dat
[15:55:51.322] <TB3> INFO: PixTestTrim::trimTest() done
[15:55:51.322] <TB3> INFO: vtrim: 117
[15:55:51.322] <TB3> INFO: vthrcomp: 82
[15:55:51.322] <TB3> INFO: vcal mean: 34.87
[15:55:51.322] <TB3> INFO: vcal RMS: 0.67
[15:55:51.322] <TB3> INFO: bits mean: 9.94
[15:55:51.322] <TB3> INFO: bits RMS: 2.62
[15:55:51.327] <TB3> INFO: ----------------------------------------------------------------------
[15:55:51.327] <TB3> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[15:55:51.327] <TB3> INFO: ----------------------------------------------------------------------
[15:55:51.327] <TB3> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[15:55:51.335] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[15:55:51.335] <TB3> INFO: run 1 of 1
[15:55:51.355] <TB3> INFO: Expecting 8320000 events.
[15:56:55.212] <TB3> INFO: 8320000 events read in total (63470ms).
[15:56:55.261] <TB3> INFO: Test took 63926ms.
[15:56:55.281] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:56:56.734] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 117 (-1/-1) hits flags = 528 (plus default)
[15:56:56.742] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[15:56:56.742] <TB3> INFO: run 1 of 1
[15:56:56.761] <TB3> INFO: Expecting 4908800 events.
[15:57:34.331] <TB3> INFO: 4908800 events read in total (37183ms).
[15:57:34.347] <TB3> INFO: Test took 37605ms.
[15:57:34.357] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:57:35.500] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 109 (-1/-1) hits flags = 528 (plus default)
[15:57:35.508] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[15:57:35.508] <TB3> INFO: run 1 of 1
[15:57:35.530] <TB3> INFO: Expecting 4576000 events.
[15:58:09.832] <TB3> INFO: 4576000 events read in total (33915ms).
[15:58:09.849] <TB3> INFO: Test took 34341ms.
[15:58:09.858] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:58:10.924] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 109 (-1/-1) hits flags = 528 (plus default)
[15:58:10.931] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[15:58:10.931] <TB3> INFO: run 1 of 1
[15:58:10.950] <TB3> INFO: Expecting 4576000 events.
[15:58:44.991] <TB3> INFO: 4576000 events read in total (33654ms).
[15:58:45.005] <TB3> INFO: Test took 34074ms.
[15:58:45.012] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:58:46.100] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 109 (-1/-1) hits flags = 528 (plus default)
[15:58:46.107] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[15:58:46.107] <TB3> INFO: run 1 of 1
[15:58:46.127] <TB3> INFO: Expecting 4576000 events.
[15:59:21.123] <TB3> INFO: 4576000 events read in total (34610ms).
[15:59:21.136] <TB3> INFO: Test took 35029ms.
[15:59:21.143] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:22.215] <TB3> INFO: PixTestTrim::trimBitTest() done
[15:59:22.217] <TB3> INFO: PixTestTrim::doTest() done, duration: 440 seconds
[15:59:22.277] <TB3> INFO: enter test to run
[15:59:22.277] <TB3> INFO: test: PhOptimization no parameter change
[15:59:22.277] <TB3> INFO: running: phoptimization
[15:59:22.277] <TB3> INFO: ######################################################################
[15:59:22.277] <TB3> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[15:59:22.277] <TB3> INFO: ######################################################################
[15:59:22.302] <TB3> INFO: Expecting 41600 events.
[15:59:23.120] <TB3> INFO: 41600 events read in total (431ms).
[15:59:23.121] <TB3> INFO: Test took 842ms.
[15:59:23.121] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:23.512] <TB3> INFO: Expecting 41600 events.
[15:59:24.315] <TB3> INFO: 41600 events read in total (416ms).
[15:59:24.315] <TB3> INFO: Test took 1193ms.
[15:59:24.316] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:24.704] <TB3> INFO: Expecting 41600 events.
[15:59:25.519] <TB3> INFO: 41600 events read in total (428ms).
[15:59:25.519] <TB3> INFO: Test took 1202ms.
[15:59:25.519] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:25.908] <TB3> INFO: Expecting 2560 events.
[15:59:26.327] <TB3> INFO: 2560 events read in total (32ms).
[15:59:26.327] <TB3> INFO: Test took 807ms.
[15:59:26.722] <TB3> INFO: Expecting 655360 events.
[15:59:32.141] <TB3> INFO: 655360 events read in total (5032ms).
[15:59:32.150] <TB3> INFO: Test took 5822ms.
[15:59:32.444] <TB3> INFO: Expecting 655360 events.
[15:59:37.931] <TB3> INFO: 655360 events read in total (5100ms).
[15:59:37.940] <TB3> INFO: Test took 5776ms.
[15:59:37.960] <TB3> INFO: safety margin for low PH: adding 0, margin is now 20
[15:59:37.976] <TB3> INFO: write dac parameters into /home/mameinha/data/R416_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//dacParameters35_C0.dat
[15:59:38.218] <TB3> INFO: Expecting 41600 events.
[15:59:38.991] <TB3> INFO: 41600 events read in total (386ms).
[15:59:38.992] <TB3> INFO: Test took 1010ms.
[15:59:39.377] <TB3> INFO: Expecting 41600 events.
[15:59:40.140] <TB3> INFO: 41600 events read in total (376ms).
[15:59:40.140] <TB3> INFO: Test took 1147ms.
[15:59:40.529] <TB3> INFO: Expecting 41600 events.
[15:59:41.294] <TB3> INFO: 41600 events read in total (378ms).
[15:59:41.295] <TB3> INFO: Test took 1154ms.
[15:59:41.684] <TB3> INFO: Expecting 2560 events.
[15:59:42.104] <TB3> INFO: 2560 events read in total (33ms).
[15:59:42.104] <TB3> INFO: Test took 808ms.
[15:59:42.499] <TB3> INFO: Expecting 2560 events.
[15:59:42.918] <TB3> INFO: 2560 events read in total (32ms).
[15:59:42.918] <TB3> INFO: Test took 814ms.
[15:59:43.328] <TB3> INFO: PixTestPhOptimization::doTest() done, duration: 21 seconds
[15:59:43.328] <TB3> INFO: PH scale (per ROC): 95
[15:59:43.328] <TB3> INFO: PH offset (per ROC): 164
[15:59:43.346] <TB3> INFO: enter test to run
[15:59:43.346] <TB3> INFO: test: GainPedestal no parameter change
[15:59:43.346] <TB3> INFO: running: gainpedestal
[15:59:43.347] <TB3> INFO: ######################################################################
[15:59:43.347] <TB3> INFO: PixTestGainPedestal::doTest() ntrig = 10
[15:59:43.347] <TB3> INFO: ######################################################################
[15:59:43.355] <TB3> INFO: scanning low vcal = 10
[15:59:43.374] <TB3> INFO: Expecting 41600 events.
[15:59:44.472] <TB3> INFO: 41600 events read in total (710ms).
[15:59:44.473] <TB3> INFO: Test took 1118ms.
[15:59:44.473] <TB3> INFO: scanning low vcal = 20
[15:59:44.867] <TB3> INFO: Expecting 41600 events.
[15:59:45.957] <TB3> INFO: 41600 events read in total (703ms).
[15:59:45.957] <TB3> INFO: Test took 1484ms.
[15:59:45.957] <TB3> INFO: scanning low vcal = 30
[15:59:46.352] <TB3> INFO: Expecting 41600 events.
[15:59:47.442] <TB3> INFO: 41600 events read in total (703ms).
[15:59:47.442] <TB3> INFO: Test took 1485ms.
[15:59:47.442] <TB3> INFO: scanning low vcal = 40
[15:59:47.837] <TB3> INFO: Expecting 41600 events.
[15:59:48.965] <TB3> INFO: 41600 events read in total (741ms).
[15:59:48.966] <TB3> INFO: Test took 1524ms.
[15:59:48.966] <TB3> INFO: scanning low vcal = 50
[15:59:49.354] <TB3> INFO: Expecting 41600 events.
[15:59:50.506] <TB3> INFO: 41600 events read in total (765ms).
[15:59:50.507] <TB3> INFO: Test took 1541ms.
[15:59:50.507] <TB3> INFO: scanning low vcal = 60
[15:59:50.887] <TB3> INFO: Expecting 41600 events.
[15:59:52.038] <TB3> INFO: 41600 events read in total (764ms).
[15:59:52.039] <TB3> INFO: Test took 1532ms.
[15:59:52.039] <TB3> INFO: scanning low vcal = 70
[15:59:52.422] <TB3> INFO: Expecting 41600 events.
[15:59:53.587] <TB3> INFO: 41600 events read in total (778ms).
[15:59:53.588] <TB3> INFO: Test took 1549ms.
[15:59:53.588] <TB3> INFO: scanning low vcal = 80
[15:59:53.969] <TB3> INFO: Expecting 41600 events.
[15:59:55.127] <TB3> INFO: 41600 events read in total (771ms).
[15:59:55.129] <TB3> INFO: Test took 1541ms.
[15:59:55.129] <TB3> INFO: scanning low vcal = 90
[15:59:55.510] <TB3> INFO: Expecting 41600 events.
[15:59:56.685] <TB3> INFO: 41600 events read in total (788ms).
[15:59:56.686] <TB3> INFO: Test took 1557ms.
[15:59:56.686] <TB3> INFO: scanning low vcal = 100
[15:59:57.067] <TB3> INFO: Expecting 41600 events.
[15:59:58.226] <TB3> INFO: 41600 events read in total (772ms).
[15:59:58.227] <TB3> INFO: Test took 1541ms.
[15:59:58.227] <TB3> INFO: scanning low vcal = 110
[15:59:58.608] <TB3> INFO: Expecting 41600 events.
[15:59:59.758] <TB3> INFO: 41600 events read in total (763ms).
[15:59:59.758] <TB3> INFO: Test took 1531ms.
[15:59:59.759] <TB3> INFO: scanning low vcal = 120
[16:00:00.142] <TB3> INFO: Expecting 41600 events.
[16:00:01.297] <TB3> INFO: 41600 events read in total (768ms).
[16:00:01.298] <TB3> INFO: Test took 1539ms.
[16:00:01.299] <TB3> INFO: scanning low vcal = 130
[16:00:01.679] <TB3> INFO: Expecting 41600 events.
[16:00:02.829] <TB3> INFO: 41600 events read in total (763ms).
[16:00:02.829] <TB3> INFO: Test took 1530ms.
[16:00:02.829] <TB3> INFO: scanning low vcal = 140
[16:00:03.214] <TB3> INFO: Expecting 41600 events.
[16:00:04.360] <TB3> INFO: 41600 events read in total (759ms).
[16:00:04.361] <TB3> INFO: Test took 1532ms.
[16:00:04.361] <TB3> INFO: scanning low vcal = 150
[16:00:04.746] <TB3> INFO: Expecting 41600 events.
[16:00:05.874] <TB3> INFO: 41600 events read in total (741ms).
[16:00:05.874] <TB3> INFO: Test took 1513ms.
[16:00:05.875] <TB3> INFO: scanning low vcal = 160
[16:00:06.263] <TB3> INFO: Expecting 41600 events.
[16:00:07.410] <TB3> INFO: 41600 events read in total (760ms).
[16:00:07.410] <TB3> INFO: Test took 1535ms.
[16:00:07.411] <TB3> INFO: scanning low vcal = 170
[16:00:07.796] <TB3> INFO: Expecting 41600 events.
[16:00:08.976] <TB3> INFO: 41600 events read in total (793ms).
[16:00:08.977] <TB3> INFO: Test took 1566ms.
[16:00:08.977] <TB3> INFO: scanning low vcal = 180
[16:00:09.358] <TB3> INFO: Expecting 41600 events.
[16:00:10.508] <TB3> INFO: 41600 events read in total (763ms).
[16:00:10.508] <TB3> INFO: Test took 1531ms.
[16:00:10.509] <TB3> INFO: scanning low vcal = 190
[16:00:10.892] <TB3> INFO: Expecting 41600 events.
[16:00:12.039] <TB3> INFO: 41600 events read in total (760ms).
[16:00:12.040] <TB3> INFO: Test took 1531ms.
[16:00:12.040] <TB3> INFO: scanning low vcal = 200
[16:00:12.425] <TB3> INFO: Expecting 41600 events.
[16:00:13.588] <TB3> INFO: 41600 events read in total (776ms).
[16:00:13.589] <TB3> INFO: Test took 1549ms.
[16:00:13.589] <TB3> INFO: scanning low vcal = 210
[16:00:13.972] <TB3> INFO: Expecting 41600 events.
[16:00:15.127] <TB3> INFO: 41600 events read in total (768ms).
[16:00:15.128] <TB3> INFO: Test took 1539ms.
[16:00:15.128] <TB3> INFO: scanning low vcal = 220
[16:00:15.509] <TB3> INFO: Expecting 41600 events.
[16:00:16.638] <TB3> INFO: 41600 events read in total (741ms).
[16:00:16.639] <TB3> INFO: Test took 1511ms.
[16:00:16.640] <TB3> INFO: scanning low vcal = 230
[16:00:17.027] <TB3> INFO: Expecting 41600 events.
[16:00:18.177] <TB3> INFO: 41600 events read in total (763ms).
[16:00:18.178] <TB3> INFO: Test took 1538ms.
[16:00:18.179] <TB3> INFO: scanning low vcal = 240
[16:00:18.560] <TB3> INFO: Expecting 41600 events.
[16:00:19.710] <TB3> INFO: 41600 events read in total (763ms).
[16:00:19.711] <TB3> INFO: Test took 1532ms.
[16:00:19.712] <TB3> INFO: scanning low vcal = 250
[16:00:20.093] <TB3> INFO: Expecting 41600 events.
[16:00:21.240] <TB3> INFO: 41600 events read in total (761ms).
[16:00:21.240] <TB3> INFO: Test took 1528ms.
[16:00:21.241] <TB3> INFO: scanning high vcal = 30 (= 210 in low range)
[16:00:21.625] <TB3> INFO: Expecting 41600 events.
[16:00:22.779] <TB3> INFO: 41600 events read in total (766ms).
[16:00:22.779] <TB3> INFO: Test took 1538ms.
[16:00:22.780] <TB3> INFO: scanning high vcal = 50 (= 350 in low range)
[16:00:23.158] <TB3> INFO: Expecting 41600 events.
[16:00:24.308] <TB3> INFO: 41600 events read in total (762ms).
[16:00:24.308] <TB3> INFO: Test took 1528ms.
[16:00:24.309] <TB3> INFO: scanning high vcal = 70 (= 490 in low range)
[16:00:24.691] <TB3> INFO: Expecting 41600 events.
[16:00:25.839] <TB3> INFO: 41600 events read in total (761ms).
[16:00:25.840] <TB3> INFO: Test took 1531ms.
[16:00:25.840] <TB3> INFO: scanning high vcal = 90 (= 630 in low range)
[16:00:26.224] <TB3> INFO: Expecting 41600 events.
[16:00:27.377] <TB3> INFO: 41600 events read in total (766ms).
[16:00:27.378] <TB3> INFO: Test took 1538ms.
[16:00:27.378] <TB3> INFO: scanning high vcal = 200 (= 1400 in low range)
[16:00:27.759] <TB3> INFO: Expecting 41600 events.
[16:00:28.911] <TB3> INFO: 41600 events read in total (765ms).
[16:00:28.911] <TB3> INFO: Test took 1533ms.
[16:00:29.289] <TB3> INFO: PixTestGainPedestal::measure() done
[16:00:31.395] <TB3> INFO: PixTestGainPedestal::fit() done
[16:00:31.395] <TB3> INFO: non-linearity mean: 0.959
[16:00:31.395] <TB3> INFO: non-linearity RMS: 0.006
[16:00:31.396] <TB3> INFO: write gain/ped parameters into /home/mameinha/data/R416_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//phCalibrationFitErr35_C0.dat
[16:00:31.432] <TB3> INFO: PixTestGainPedestal::doTest() done, duration: 48 seconds
[16:00:31.432] <TB3> INFO: enter test to run
[16:00:31.432] <TB3> INFO: test: Readback no parameter change
[16:00:31.432] <TB3> INFO: running: readback
[16:00:31.432] <TB3> INFO: readReadbackCal: /home/mameinha/data/R416_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//readbackCal_C0.dat .. /home/mameinha/data/R416_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//readbackCal_C0.dat
[16:00:31.433] <TB3> INFO: ######################################################################
[16:00:31.433] <TB3> INFO: PixTestReadback::doTest()
[16:00:31.433] <TB3> INFO: ######################################################################
[16:00:31.433] <TB3> INFO: ----------------------------------------------------------------------
[16:00:31.433] <TB3> INFO: PixTestReadback::CalibrateVd()
[16:00:31.433] <TB3> INFO: ----------------------------------------------------------------------
[16:00:45.743] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R416_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//readbackCal_C0.dat
[16:00:45.752] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[16:00:45.752] <TB3> INFO: ----------------------------------------------------------------------
[16:00:45.752] <TB3> INFO: PixTestReadback::CalibrateVa()
[16:00:45.752] <TB3> INFO: ----------------------------------------------------------------------
[16:00:57.136] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R416_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//readbackCal_C0.dat
[16:00:57.173] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[16:00:57.173] <TB3> INFO: ----------------------------------------------------------------------
[16:00:57.173] <TB3> INFO: PixTestReadback::readbackVbg()
[16:00:57.173] <TB3> INFO: ----------------------------------------------------------------------
[16:01:05.507] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[16:01:05.507] <TB3> INFO: ----------------------------------------------------------------------
[16:01:05.507] <TB3> INFO: PixTestReadback::getCalibratedVbg()
[16:01:05.507] <TB3> INFO: ----------------------------------------------------------------------
[16:01:05.507] <TB3> INFO: Vbg will be calibrated using Vd calibration
[16:01:05.507] <TB3> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 147.1calibrated Vbg = 1.29216 :::*/*/*/*/
[16:01:05.883] <TB3> INFO: ----------------------------------------------------------------------
[16:01:05.883] <TB3> INFO: PixTestReadback::CalibrateIa()
[16:01:05.883] <TB3> INFO: ----------------------------------------------------------------------
[16:01:14.780] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R416_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//readbackCal_C0.dat
[16:01:14.786] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[16:01:14.786] <TB3> INFO: PixTestReadback::doTest() done
[16:01:14.850] <TB3> INFO: enter test to run
[16:01:14.850] <TB3> INFO: test: no parameter change
[16:01:14.880] <TB3> QUIET: Connection to board 137 closed.
[16:01:14.960] <TB3> INFO: pXar: this is the end, my friend