[10:01:17.954] <TB2> INFO: *** Welcome to pxar ***
[10:01:17.954] <TB2> INFO: *** Today: 2015/12/02
[10:01:18.302] <TB2> INFO: *** Version: 9da6
[10:01:18.302] <TB2> INFO: readRocDacs: /home/mameinha/data/R414_FulltestROC_m20_2015-12-02_11h01m_1449050469//000_FulltestROC_m20//dacParameters_C0.dat .. /home/mameinha/data/R414_FulltestROC_m20_2015-12-02_11h01m_1449050469//000_FulltestROC_m20//dacParameters_C0.dat
[10:01:18.304] <TB2> INFO: readTbmDacs: /home/mameinha/data/R414_FulltestROC_m20_2015-12-02_11h01m_1449050469//000_FulltestROC_m20//tbmParameters_C0a.dat .. /home/mameinha/data/R414_FulltestROC_m20_2015-12-02_11h01m_1449050469//000_FulltestROC_m20//tbmParameters_C4294967295b.dat
[10:01:18.304] <TB2> INFO: readMaskFile: /home/mameinha/data/R414_FulltestROC_m20_2015-12-02_11h01m_1449050469//000_FulltestROC_m20//defaultMaskFile.dat
[10:01:18.305] <TB2> INFO: readTrimFile: /home/mameinha/data/R414_FulltestROC_m20_2015-12-02_11h01m_1449050469//000_FulltestROC_m20//trimParameters_C0.dat .. /home/mameinha/data/R414_FulltestROC_m20_2015-12-02_11h01m_1449050469//000_FulltestROC_m20//trimParameters_C0.dat
[10:01:18.332] <TB2> INFO: clk: 4
[10:01:18.332] <TB2> INFO: ctr: 4
[10:01:18.332] <TB2> INFO: sda: 19
[10:01:18.332] <TB2> INFO: tin: 9
[10:01:18.332] <TB2> INFO: level: 15
[10:01:18.332] <TB2> INFO: deser160phase: 4
[10:01:18.332] <TB2> QUIET: Instanciating API for pxar v2.6.1+42~g55d8827
[10:01:18.332] <TB2> INFO: Log level: INFO
[10:01:18.345] <TB2> QUIET: Connection to board DTB_WWXJGB opened.
[10:01:18.348] <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:
------------------------------------------------------
[10:01:18.350] <TB2> INFO: RPC call hashes of host and DTB match: 398089610
[10:01:19.515] <TB2> INFO: DUT info:
[10:01:19.515] <TB2> INFO: The DUT currently contains the following objects:
[10:01:19.515] <TB2> INFO: 0 TBM Cores (0 ON)
[10:01:19.515] <TB2> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[10:01:19.515] <TB2> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[10:01:20.079] <TB2> INFO: enter 'restricted' command line mode
[10:01:20.079] <TB2> INFO: enter test to run
[10:01:20.079] <TB2> INFO: test: Setup no parameter change
[10:01:20.079] <TB2> INFO: running: setup
[10:01:20.084] <TB2> INFO: PixTestSetup::doTest() ntrig = 10

[10:01:20.084] <TB2> INFO: PixTestSetup:: pg set to RES|TOK
[10:01:20.084] <TB2> INFO: 0 1 2 3 4 5 6 7
[10:01:23.124] <TB2> INFO: 0: 000 008 084 87c 7f0 f00 000 000
[10:01:26.136] <TB2> INFO: 1: 000 008 084 87c <7f8>[*] f80 800 000
[10:01:29.148] <TB2> INFO: 2: 000 008 084 87c <7f8>[*] f80 <7f8>[1] 000
[10:01:32.160] <TB2> INFO: 3: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[10:01:35.172] <TB2> INFO: 4: 800 000 044 47c <7f8>[*] f80 <7f8>[1] 000
[10:01:38.184] <TB2> INFO: 5: 800 004 040 43c 3fc fc0 c00 000
[10:01:41.196] <TB2> INFO: 6: 000 004 040 43c 3fc fc0 c00 000
[10:01:44.207] <TB2> INFO: 7: 000 004 040 43c 3fc fc0 c00 000
[10:01:47.219] <TB2> INFO: 8: c00 000 000 03c 3fc fc0 c00 000
[10:01:50.231] <TB2> INFO: 9: 000 000 000 23c 3fc fc0 c00 000
[10:01:53.243] <TB2> INFO: 10: 000 000 020 21c 1fc fc0 c00 000
[10:01:56.255] <TB2> INFO: 11: 000 000 020 21c 1fc fe0 e00 000
[10:01:59.267] <TB2> INFO: 12: 000 000 020 21c 1fc fe0 e00 000
[10:02:02.279] <TB2> INFO: 13: 000 000 000 01c 1fc fe0 e00 000
[10:02:05.291] <TB2> INFO: 14: 000 000 010 11c 1fc fe0 e00 000
[10:02:08.303] <TB2> INFO: 15: e00 000 010 00c 0fc ff0 f00 000
[10:02:11.314] <TB2> INFO: 16: 000 000 010 10c 0fc ff0 f00 000
[10:02:14.326] <TB2> INFO: 17: 000 000 010 10c 0fc ff0 f00 000
[10:02:17.338] <TB2> INFO: 18: 000 000 000 00c 0fc ff0 f00 000
[10:02:20.350] <TB2> INFO: 19: 000 000 000 08c 8fc ff0 f00 000
[10:02:20.757] <TB2> INFO: Found good delays at CLK = 2, DESER160 = 4
[10:02:20.759] <TB2> INFO: PixTestSetup:: Write Tb parameters to file.
[10:02:20.774] <TB2> INFO: write dtb parameters into /home/mameinha/data/R414_FulltestROC_m20_2015-12-02_11h01m_1449050469//000_FulltestROC_m20//tbParameters.dat
[10:02:20.779] <TB2> INFO: PixTestSetup::doTest() done for.
[10:02:20.803] <TB2> INFO: enter test to run
[10:02:20.803] <TB2> INFO: test: Pretest no parameter change
[10:02:20.803] <TB2> INFO: running: pretest
[10:02:20.804] <TB2> INFO: ----------------------------------------------------------------------
[10:02:20.804] <TB2> INFO: PixTestPretest::programROC()
[10:02:20.804] <TB2> INFO: ----------------------------------------------------------------------
[10:02:23.806] <TB2> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[10:02:23.806] <TB2> INFO: IA differences per ROC: 20.9
[10:02:23.810] <TB2> INFO: enter test to run
[10:02:23.810] <TB2> INFO: test: Pretest no parameter change
[10:02:23.810] <TB2> INFO: running: pretest
[10:02:23.811] <TB2> INFO: ----------------------------------------------------------------------
[10:02:23.811] <TB2> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[10:02:23.811] <TB2> INFO: ----------------------------------------------------------------------
[10:02:24.520] <TB2> INFO: PixTestPretest::setVana() done, Module Ia 24.1 mA = 24.1 mA/ROC
[10:02:24.520] <TB2> INFO: i(loss) [mA/ROC]: 19.3
[10:02:24.522] <TB2> INFO: enter test to run
[10:02:24.522] <TB2> INFO: test: Pretest no parameter change
[10:02:24.522] <TB2> INFO: running: pretest
[10:02:24.523] <TB2> INFO: ----------------------------------------------------------------------
[10:02:24.523] <TB2> INFO: PixTestPretest::findWorkingPixel()
[10:02:24.523] <TB2> INFO: ----------------------------------------------------------------------
[10:02:24.533] <TB2> INFO: Expecting 231680 events.
[10:02:26.814] <TB2> INFO: 231680 events read in total (1894ms).
[10:02:26.816] <TB2> INFO: Test took 2293ms.
[10:02:27.194] <TB2> INFO: Found working pixel in all ROCs: col/row = 12/22
[10:02:27.454] <TB2> INFO: enter test to run
[10:02:27.454] <TB2> INFO: test: Pretest no parameter change
[10:02:27.454] <TB2> INFO: running: pretest
[10:02:27.455] <TB2> INFO: ----------------------------------------------------------------------
[10:02:27.455] <TB2> INFO: PixTestPretest::setVthrCompCalDel()
[10:02:27.455] <TB2> INFO: ----------------------------------------------------------------------
[10:02:27.464] <TB2> INFO: Expecting 231680 events.
[10:02:29.722] <TB2> INFO: 231680 events read in total (1871ms).
[10:02:29.724] <TB2> INFO: Test took 2269ms.
[10:02:30.104] <TB2> INFO: PixTestPretest::setVthrCompCalDel() done
[10:02:30.104] <TB2> INFO: CalDel: 147
[10:02:30.104] <TB2> INFO: VthrComp: 51
[10:02:30.107] <TB2> INFO: enter test to run
[10:02:30.107] <TB2> INFO: test: Pretest no parameter change
[10:02:30.107] <TB2> INFO: running: pretest
[10:02:30.346] <TB2> INFO: write dac parameters into /home/mameinha/data/R414_FulltestROC_m20_2015-12-02_11h01m_1449050469//000_FulltestROC_m20//dacParameters_C0.dat
[10:02:30.357] <TB2> INFO: enter test to run
[10:02:30.357] <TB2> INFO: test: PixelAlive no parameter change
[10:02:30.357] <TB2> INFO: running: pixelalive
[10:02:30.359] <TB2> INFO: ######################################################################
[10:02:30.359] <TB2> INFO: PixTestAlive::doTest()
[10:02:30.359] <TB2> INFO: ######################################################################
[10:02:30.360] <TB2> INFO: ----------------------------------------------------------------------
[10:02:30.360] <TB2> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[10:02:30.360] <TB2> INFO: ----------------------------------------------------------------------
[10:02:30.380] <TB2> INFO: Expecting 41600 events.
[10:02:31.192] <TB2> INFO: 41600 events read in total (425ms).
[10:02:31.192] <TB2> INFO: Test took 832ms.
[10:02:31.192] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:02:31.578] <TB2> INFO: PixTestAlive::aliveTest() done
[10:02:31.578] <TB2> INFO: number of dead pixels (per ROC): 0
[10:02:31.579] <TB2> INFO: ----------------------------------------------------------------------
[10:02:31.579] <TB2> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[10:02:31.579] <TB2> INFO: ----------------------------------------------------------------------
[10:02:31.598] <TB2> INFO: Expecting 41600 events.
[10:02:32.340] <TB2> INFO: 41600 events read in total (355ms).
[10:02:32.340] <TB2> INFO: Test took 761ms.
[10:02:32.340] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:02:32.340] <TB2> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[10:02:32.730] <TB2> INFO: PixTestAlive::maskTest() done
[10:02:32.730] <TB2> INFO: number of mask-defect pixels (per ROC): 0
[10:02:32.731] <TB2> INFO: ----------------------------------------------------------------------
[10:02:32.731] <TB2> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[10:02:32.731] <TB2> INFO: ----------------------------------------------------------------------
[10:02:32.751] <TB2> INFO: Expecting 41600 events.
[10:02:33.562] <TB2> INFO: 41600 events read in total (424ms).
[10:02:33.562] <TB2> INFO: Test took 831ms.
[10:02:33.563] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:02:33.948] <TB2> INFO: PixTestAlive::addressDecodingTest() done
[10:02:33.948] <TB2> INFO: number of address-decoding pixels (per ROC): 0
[10:02:33.948] <TB2> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[10:02:33.948] <TB2> INFO: enter test to run
[10:02:33.948] <TB2> INFO: test: Scurves no parameter change
[10:02:33.948] <TB2> INFO: running: scurves
[10:02:33.949] <TB2> INFO: ######################################################################
[10:02:33.949] <TB2> INFO: PixTestScurves::doTest() ntrig = 50
[10:02:33.949] <TB2> INFO: ######################################################################
[10:02:33.949] <TB2> INFO: ----------------------------------------------------------------------
[10:02:33.949] <TB2> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[10:02:33.949] <TB2> INFO: ----------------------------------------------------------------------
[10:02:33.949] <TB2> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[10:02:34.093] <TB2> INFO: dacScan split into 1 runs with ntrig = 50
[10:02:34.093] <TB2> INFO: run 1 of 1
[10:02:34.112] <TB2> INFO: Expecting 41808000 events.
[10:04:52.444] <TB2> INFO: 17763700 events read in total (137945ms).
[10:07:01.109] <TB2> INFO: 35128100 events read in total (266610ms).
[10:07:49.681] <TB2> INFO: 41808000 events read in total (315182ms).
[10:07:49.728] <TB2> INFO: Test took 315635ms.
[10:07:49.753] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:07:49.762] <TB2> INFO: dumping ASCII scurve output file: SCurveData
[10:07:51.275] <TB2> INFO: PixTestScurves::scurves() done
[10:07:51.275] <TB2> INFO: Vcal mean: 56.68
[10:07:51.275] <TB2> INFO: Vcal RMS: 4.85
[10:07:51.279] <TB2> INFO: enter test to run
[10:07:51.279] <TB2> INFO: test: Trim no parameter change
[10:07:51.279] <TB2> INFO: running: trim
[10:07:51.281] <TB2> INFO: ######################################################################
[10:07:51.281] <TB2> INFO: PixTestTrim::doTest()
[10:07:51.281] <TB2> INFO: ######################################################################
[10:07:51.282] <TB2> INFO: ----------------------------------------------------------------------
[10:07:51.282] <TB2> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[10:07:51.282] <TB2> INFO: ----------------------------------------------------------------------
[10:07:51.287] <TB2> INFO: ---> VthrComp thr map (minimal VthrComp)
[10:07:51.287] <TB2> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[10:07:51.294] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[10:07:51.294] <TB2> INFO: run 1 of 1
[10:07:51.313] <TB2> INFO: Expecting 6281600 events.
[10:08:37.845] <TB2> INFO: 6281600 events read in total (46142ms).
[10:08:37.861] <TB2> INFO: Test took 46567ms.
[10:08:37.870] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:08:38.897] <TB2> INFO: ROC 0 VthrComp = 68
[10:08:38.897] <TB2> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[10:08:38.897] <TB2> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[10:08:38.904] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[10:08:38.904] <TB2> INFO: run 1 of 1
[10:08:38.923] <TB2> INFO: Expecting 6281600 events.
[10:09:29.623] <TB2> INFO: 6281600 events read in total (50313ms).
[10:09:29.673] <TB2> INFO: Test took 50769ms.
[10:09:29.693] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:09:30.903] <TB2> INFO: roc 0 with ID = 0 has maximal Vcal 54.7797 for pixel 15/74 mean/min/max = 43.5575/31.5825/55.5325
[10:09:30.912] <TB2> INFO: Expecting 514560 events.
[10:09:35.075] <TB2> INFO: 514560 events read in total (3776ms).
[10:09:35.080] <TB2> INFO: Test took 4176ms.
[10:09:35.481] <TB2> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[10:09:35.488] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[10:09:35.488] <TB2> INFO: run 1 of 1
[10:09:35.507] <TB2> INFO: Expecting 6281600 events.
[10:10:26.128] <TB2> INFO: 6281600 events read in total (50234ms).
[10:10:26.181] <TB2> INFO: Test took 50693ms.
[10:10:26.201] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:10:27.351] <TB2> INFO: ---> TrimStepCorr4 extremal thresholds: 13.197196 .. 45.310911
[10:10:27.355] <TB2> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 3 .. 55 (-1/-1) hits flags = 528 (plus default)
[10:10:27.363] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[10:10:27.363] <TB2> INFO: run 1 of 1
[10:10:27.382] <TB2> INFO: Expecting 2204800 events.
[10:10:44.793] <TB2> INFO: 2204800 events read in total (17024ms).
[10:10:44.802] <TB2> INFO: Test took 17439ms.
[10:10:44.806] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:10:45.590] <TB2> INFO: ---> TrimStepCorr2 extremal thresholds: 19.471739 .. 39.054700
[10:10:45.594] <TB2> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 9 .. 49 (-1/-1) hits flags = 528 (plus default)
[10:10:45.602] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[10:10:45.602] <TB2> INFO: run 1 of 1
[10:10:45.621] <TB2> INFO: Expecting 1705600 events.
[10:10:59.092] <TB2> INFO: 1705600 events read in total (13084ms).
[10:10:59.098] <TB2> INFO: Test took 13496ms.
[10:10:59.101] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:10:59.844] <TB2> INFO: ---> TrimStepCorr1a extremal thresholds: 23.890791 .. 37.409225
[10:10:59.848] <TB2> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 13 .. 47 (-1/-1) hits flags = 528 (plus default)
[10:10:59.855] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[10:10:59.856] <TB2> INFO: run 1 of 1
[10:10:59.874] <TB2> INFO: Expecting 1456000 events.
[10:11:11.565] <TB2> INFO: 1456000 events read in total (11304ms).
[10:11:11.571] <TB2> INFO: Test took 11715ms.
[10:11:11.573] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:11:12.293] <TB2> INFO: ---> TrimStepCorr1b extremal thresholds: 26.495942 .. 36.586040
[10:11:12.298] <TB2> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 16 .. 46 (-1/-1) hits flags = 528 (plus default)
[10:11:12.305] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[10:11:12.305] <TB2> INFO: run 1 of 1
[10:11:12.324] <TB2> INFO: Expecting 1289600 events.
[10:11:22.780] <TB2> INFO: 1289600 events read in total (10069ms).
[10:11:22.785] <TB2> INFO: Test took 10480ms.
[10:11:22.787] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:11:23.501] <TB2> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[10:11:23.501] <TB2> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[10:11:23.508] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[10:11:23.508] <TB2> INFO: run 1 of 1
[10:11:23.527] <TB2> INFO: Expecting 1705600 events.
[10:11:37.125] <TB2> INFO: 1705600 events read in total (13211ms).
[10:11:37.133] <TB2> INFO: Test took 13625ms.
[10:11:37.137] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:11:37.919] <TB2> INFO: write dac parameters into /home/mameinha/data/R414_FulltestROC_m20_2015-12-02_11h01m_1449050469//000_FulltestROC_m20//dacParameters35_C0.dat
[10:11:37.980] <TB2> INFO: write trim parameters into /home/mameinha/data/R414_FulltestROC_m20_2015-12-02_11h01m_1449050469//000_FulltestROC_m20//trimParameters35_C0.dat
[10:11:38.009] <TB2> INFO: PixTestTrim::trimTest() done
[10:11:38.009] <TB2> INFO: vtrim: 109
[10:11:38.009] <TB2> INFO: vthrcomp: 68
[10:11:38.009] <TB2> INFO: vcal mean: 34.88
[10:11:38.009] <TB2> INFO: vcal RMS: 0.75
[10:11:38.009] <TB2> INFO: bits mean: 10.60
[10:11:38.009] <TB2> INFO: bits RMS: 2.44
[10:11:38.013] <TB2> INFO: ----------------------------------------------------------------------
[10:11:38.013] <TB2> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[10:11:38.013] <TB2> INFO: ----------------------------------------------------------------------
[10:11:38.013] <TB2> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[10:11:38.020] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[10:11:38.020] <TB2> INFO: run 1 of 1
[10:11:38.039] <TB2> INFO: Expecting 8320000 events.
[10:12:42.857] <TB2> INFO: 8320000 events read in total (64431ms).
[10:12:42.908] <TB2> INFO: Test took 64888ms.
[10:12:42.930] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:12:44.298] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 107 (-1/-1) hits flags = 528 (plus default)
[10:12:44.305] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[10:12:44.305] <TB2> INFO: run 1 of 1
[10:12:44.324] <TB2> INFO: Expecting 4492800 events.
[10:13:18.779] <TB2> INFO: 4492800 events read in total (34068ms).
[10:13:18.794] <TB2> INFO: Test took 34489ms.
[10:13:18.802] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:13:19.840] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 100 (-1/-1) hits flags = 528 (plus default)
[10:13:19.847] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[10:13:19.847] <TB2> INFO: run 1 of 1
[10:13:19.866] <TB2> INFO: Expecting 4201600 events.
[10:13:51.721] <TB2> INFO: 4201600 events read in total (31468ms).
[10:13:51.734] <TB2> INFO: Test took 31887ms.
[10:13:51.741] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:13:52.741] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 100 (-1/-1) hits flags = 528 (plus default)
[10:13:52.748] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[10:13:52.748] <TB2> INFO: run 1 of 1
[10:13:52.767] <TB2> INFO: Expecting 4201600 events.
[10:14:24.930] <TB2> INFO: 4201600 events read in total (31776ms).
[10:14:24.944] <TB2> INFO: Test took 32196ms.
[10:14:24.950] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:14:25.949] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 100 (-1/-1) hits flags = 528 (plus default)
[10:14:25.956] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[10:14:25.956] <TB2> INFO: run 1 of 1
[10:14:25.975] <TB2> INFO: Expecting 4201600 events.
[10:14:58.244] <TB2> INFO: 4201600 events read in total (31882ms).
[10:14:58.258] <TB2> INFO: Test took 32302ms.
[10:14:58.265] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:14:59.262] <TB2> INFO: PixTestTrim::trimBitTest() done
[10:14:59.263] <TB2> INFO: PixTestTrim::doTest() done, duration: 427 seconds
[10:14:59.304] <TB2> INFO: enter test to run
[10:14:59.304] <TB2> INFO: test: PhOptimization no parameter change
[10:14:59.304] <TB2> INFO: running: phoptimization
[10:14:59.304] <TB2> INFO: ######################################################################
[10:14:59.304] <TB2> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[10:14:59.304] <TB2> INFO: ######################################################################
[10:14:59.325] <TB2> INFO: Expecting 41600 events.
[10:15:00.149] <TB2> INFO: 41600 events read in total (437ms).
[10:15:00.150] <TB2> INFO: Test took 844ms.
[10:15:00.150] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:15:00.541] <TB2> INFO: Expecting 41600 events.
[10:15:01.339] <TB2> INFO: 41600 events read in total (411ms).
[10:15:01.340] <TB2> INFO: Test took 1185ms.
[10:15:01.340] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:15:01.729] <TB2> INFO: Expecting 41600 events.
[10:15:02.541] <TB2> INFO: 41600 events read in total (425ms).
[10:15:02.542] <TB2> INFO: Test took 1201ms.
[10:15:02.542] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[10:15:02.931] <TB2> INFO: Expecting 2560 events.
[10:15:03.349] <TB2> INFO: 2560 events read in total (31ms).
[10:15:03.349] <TB2> INFO: Test took 807ms.
[10:15:03.744] <TB2> INFO: Expecting 655360 events.
[10:15:09.227] <TB2> INFO: 655360 events read in total (5096ms).
[10:15:09.236] <TB2> INFO: Test took 5886ms.
[10:15:09.529] <TB2> INFO: Expecting 655360 events.
[10:15:15.024] <TB2> INFO: 655360 events read in total (5108ms).
[10:15:15.032] <TB2> INFO: Test took 5783ms.
[10:15:15.051] <TB2> INFO: safety margin for low PH: adding 0, margin is now 20
[10:15:15.281] <TB2> INFO: write dac parameters into /home/mameinha/data/R414_FulltestROC_m20_2015-12-02_11h01m_1449050469//000_FulltestROC_m20//dacParameters35_C0.dat
[10:15:15.327] <TB2> INFO: Expecting 41600 events.
[10:15:16.101] <TB2> INFO: 41600 events read in total (387ms).
[10:15:16.101] <TB2> INFO: Test took 800ms.
[10:15:16.490] <TB2> INFO: Expecting 41600 events.
[10:15:17.279] <TB2> INFO: 41600 events read in total (402ms).
[10:15:17.279] <TB2> INFO: Test took 1177ms.
[10:15:17.668] <TB2> INFO: Expecting 41600 events.
[10:15:18.428] <TB2> INFO: 41600 events read in total (373ms).
[10:15:18.428] <TB2> INFO: Test took 1148ms.
[10:15:18.818] <TB2> INFO: Expecting 2560 events.
[10:15:19.235] <TB2> INFO: 2560 events read in total (31ms).
[10:15:19.235] <TB2> INFO: Test took 806ms.
[10:15:19.631] <TB2> INFO: Expecting 2560 events.
[10:15:20.049] <TB2> INFO: 2560 events read in total (31ms).
[10:15:20.049] <TB2> INFO: Test took 814ms.
[10:15:20.455] <TB2> INFO: PixTestPhOptimization::doTest() done, duration: 21 seconds
[10:15:20.455] <TB2> INFO: PH scale (per ROC): 98
[10:15:20.455] <TB2> INFO: PH offset (per ROC): 146
[10:15:20.468] <TB2> INFO: enter test to run
[10:15:20.468] <TB2> INFO: test: GainPedestal no parameter change
[10:15:20.468] <TB2> INFO: running: gainpedestal
[10:15:20.469] <TB2> INFO: ######################################################################
[10:15:20.469] <TB2> INFO: PixTestGainPedestal::doTest() ntrig = 10
[10:15:20.469] <TB2> INFO: ######################################################################
[10:15:20.477] <TB2> INFO: scanning low vcal = 10
[10:15:20.496] <TB2> INFO: Expecting 41600 events.
[10:15:21.585] <TB2> INFO: 41600 events read in total (702ms).
[10:15:21.585] <TB2> INFO: Test took 1108ms.
[10:15:21.585] <TB2> INFO: scanning low vcal = 20
[10:15:21.980] <TB2> INFO: Expecting 41600 events.
[10:15:23.068] <TB2> INFO: 41600 events read in total (701ms).
[10:15:23.069] <TB2> INFO: Test took 1484ms.
[10:15:23.069] <TB2> INFO: scanning low vcal = 30
[10:15:23.464] <TB2> INFO: Expecting 41600 events.
[10:15:24.552] <TB2> INFO: 41600 events read in total (701ms).
[10:15:24.552] <TB2> INFO: Test took 1483ms.
[10:15:24.552] <TB2> INFO: scanning low vcal = 40
[10:15:24.947] <TB2> INFO: Expecting 41600 events.
[10:15:26.098] <TB2> INFO: 41600 events read in total (764ms).
[10:15:26.099] <TB2> INFO: Test took 1547ms.
[10:15:26.099] <TB2> INFO: scanning low vcal = 50
[10:15:26.488] <TB2> INFO: Expecting 41600 events.
[10:15:27.626] <TB2> INFO: 41600 events read in total (751ms).
[10:15:27.626] <TB2> INFO: Test took 1527ms.
[10:15:27.626] <TB2> INFO: scanning low vcal = 60
[10:15:28.015] <TB2> INFO: Expecting 41600 events.
[10:15:29.139] <TB2> INFO: 41600 events read in total (737ms).
[10:15:29.139] <TB2> INFO: Test took 1513ms.
[10:15:29.139] <TB2> INFO: scanning low vcal = 70
[10:15:29.528] <TB2> INFO: Expecting 41600 events.
[10:15:30.665] <TB2> INFO: 41600 events read in total (750ms).
[10:15:30.666] <TB2> INFO: Test took 1527ms.
[10:15:30.666] <TB2> INFO: scanning low vcal = 80
[10:15:31.055] <TB2> INFO: Expecting 41600 events.
[10:15:32.215] <TB2> INFO: 41600 events read in total (773ms).
[10:15:32.450] <TB2> INFO: Test took 1784ms.
[10:15:32.450] <TB2> INFO: scanning low vcal = 90
[10:15:32.604] <TB2> INFO: Expecting 41600 events.
[10:15:33.757] <TB2> INFO: 41600 events read in total (766ms).
[10:15:33.757] <TB2> INFO: Test took 1307ms.
[10:15:33.758] <TB2> INFO: scanning low vcal = 100
[10:15:34.146] <TB2> INFO: Expecting 41600 events.
[10:15:35.278] <TB2> INFO: 41600 events read in total (745ms).
[10:15:35.279] <TB2> INFO: Test took 1521ms.
[10:15:35.279] <TB2> INFO: scanning low vcal = 110
[10:15:35.668] <TB2> INFO: Expecting 41600 events.
[10:15:36.806] <TB2> INFO: 41600 events read in total (751ms).
[10:15:36.807] <TB2> INFO: Test took 1528ms.
[10:15:36.807] <TB2> INFO: scanning low vcal = 120
[10:15:37.196] <TB2> INFO: Expecting 41600 events.
[10:15:38.320] <TB2> INFO: 41600 events read in total (737ms).
[10:15:38.321] <TB2> INFO: Test took 1514ms.
[10:15:38.321] <TB2> INFO: scanning low vcal = 130
[10:15:38.710] <TB2> INFO: Expecting 41600 events.
[10:15:39.848] <TB2> INFO: 41600 events read in total (751ms).
[10:15:39.848] <TB2> INFO: Test took 1527ms.
[10:15:39.849] <TB2> INFO: scanning low vcal = 140
[10:15:40.237] <TB2> INFO: Expecting 41600 events.
[10:15:41.375] <TB2> INFO: 41600 events read in total (751ms).
[10:15:41.376] <TB2> INFO: Test took 1527ms.
[10:15:41.376] <TB2> INFO: scanning low vcal = 150
[10:15:41.765] <TB2> INFO: Expecting 41600 events.
[10:15:42.902] <TB2> INFO: 41600 events read in total (750ms).
[10:15:42.903] <TB2> INFO: Test took 1527ms.
[10:15:42.903] <TB2> INFO: scanning low vcal = 160
[10:15:43.292] <TB2> INFO: Expecting 41600 events.
[10:15:44.444] <TB2> INFO: 41600 events read in total (765ms).
[10:15:44.445] <TB2> INFO: Test took 1542ms.
[10:15:44.445] <TB2> INFO: scanning low vcal = 170
[10:15:44.834] <TB2> INFO: Expecting 41600 events.
[10:15:45.973] <TB2> INFO: 41600 events read in total (752ms).
[10:15:45.974] <TB2> INFO: Test took 1529ms.
[10:15:45.974] <TB2> INFO: scanning low vcal = 180
[10:15:46.363] <TB2> INFO: Expecting 41600 events.
[10:15:47.486] <TB2> INFO: 41600 events read in total (736ms).
[10:15:47.487] <TB2> INFO: Test took 1513ms.
[10:15:47.487] <TB2> INFO: scanning low vcal = 190
[10:15:47.876] <TB2> INFO: Expecting 41600 events.
[10:15:48.000] <TB2> INFO: 41600 events read in total (737ms).
[10:15:49.000] <TB2> INFO: Test took 1513ms.
[10:15:49.000] <TB2> INFO: scanning low vcal = 200
[10:15:49.389] <TB2> INFO: Expecting 41600 events.
[10:15:50.540] <TB2> INFO: 41600 events read in total (764ms).
[10:15:50.540] <TB2> INFO: Test took 1540ms.
[10:15:50.541] <TB2> INFO: scanning low vcal = 210
[10:15:50.930] <TB2> INFO: Expecting 41600 events.
[10:15:52.052] <TB2> INFO: 41600 events read in total (735ms).
[10:15:52.053] <TB2> INFO: Test took 1512ms.
[10:15:52.053] <TB2> INFO: scanning low vcal = 220
[10:15:52.442] <TB2> INFO: Expecting 41600 events.
[10:15:53.578] <TB2> INFO: 41600 events read in total (749ms).
[10:15:53.579] <TB2> INFO: Test took 1526ms.
[10:15:53.579] <TB2> INFO: scanning low vcal = 230
[10:15:53.968] <TB2> INFO: Expecting 41600 events.
[10:15:55.105] <TB2> INFO: 41600 events read in total (750ms).
[10:15:55.105] <TB2> INFO: Test took 1526ms.
[10:15:55.105] <TB2> INFO: scanning low vcal = 240
[10:15:55.494] <TB2> INFO: Expecting 41600 events.
[10:15:56.631] <TB2> INFO: 41600 events read in total (750ms).
[10:15:56.631] <TB2> INFO: Test took 1526ms.
[10:15:56.632] <TB2> INFO: scanning low vcal = 250
[10:15:57.020] <TB2> INFO: Expecting 41600 events.
[10:15:58.142] <TB2> INFO: 41600 events read in total (735ms).
[10:15:58.143] <TB2> INFO: Test took 1511ms.
[10:15:58.143] <TB2> INFO: scanning high vcal = 30 (= 210 in low range)
[10:15:58.532] <TB2> INFO: Expecting 41600 events.
[10:15:59.683] <TB2> INFO: 41600 events read in total (764ms).
[10:15:59.684] <TB2> INFO: Test took 1541ms.
[10:15:59.684] <TB2> INFO: scanning high vcal = 50 (= 350 in low range)
[10:16:00.073] <TB2> INFO: Expecting 41600 events.
[10:16:01.195] <TB2> INFO: 41600 events read in total (735ms).
[10:16:01.196] <TB2> INFO: Test took 1512ms.
[10:16:01.196] <TB2> INFO: scanning high vcal = 70 (= 490 in low range)
[10:16:01.585] <TB2> INFO: Expecting 41600 events.
[10:16:02.722] <TB2> INFO: 41600 events read in total (750ms).
[10:16:02.723] <TB2> INFO: Test took 1527ms.
[10:16:02.723] <TB2> INFO: scanning high vcal = 90 (= 630 in low range)
[10:16:03.112] <TB2> INFO: Expecting 41600 events.
[10:16:04.248] <TB2> INFO: 41600 events read in total (749ms).
[10:16:04.248] <TB2> INFO: Test took 1525ms.
[10:16:04.249] <TB2> INFO: scanning high vcal = 200 (= 1400 in low range)
[10:16:04.637] <TB2> INFO: Expecting 41600 events.
[10:16:05.760] <TB2> INFO: 41600 events read in total (736ms).
[10:16:05.760] <TB2> INFO: Test took 1511ms.
[10:16:06.144] <TB2> INFO: PixTestGainPedestal::measure() done
[10:16:08.107] <TB2> INFO: PixTestGainPedestal::fit() done
[10:16:08.107] <TB2> INFO: non-linearity mean: 0.960
[10:16:08.107] <TB2> INFO: non-linearity RMS: 0.006
[10:16:08.107] <TB2> INFO: write gain/ped parameters into /home/mameinha/data/R414_FulltestROC_m20_2015-12-02_11h01m_1449050469//000_FulltestROC_m20//phCalibrationFitErr35_C0.dat
[10:16:08.470] <TB2> INFO: PixTestGainPedestal::doTest() done, duration: 48 seconds
[10:16:08.470] <TB2> INFO: enter test to run
[10:16:08.470] <TB2> INFO: test: Readback no parameter change
[10:16:08.470] <TB2> INFO: running: readback
[10:16:08.470] <TB2> INFO: readReadbackCal: /home/mameinha/data/R414_FulltestROC_m20_2015-12-02_11h01m_1449050469//000_FulltestROC_m20//readbackCal_C0.dat .. /home/mameinha/data/R414_FulltestROC_m20_2015-12-02_11h01m_1449050469//000_FulltestROC_m20//readbackCal_C0.dat
[10:16:08.651] <TB2> INFO: ######################################################################
[10:16:08.651] <TB2> INFO: PixTestReadback::doTest()
[10:16:08.651] <TB2> INFO: ######################################################################
[10:16:08.651] <TB2> INFO: ----------------------------------------------------------------------
[10:16:08.651] <TB2> INFO: PixTestReadback::CalibrateVd()
[10:16:08.651] <TB2> INFO: ----------------------------------------------------------------------
[10:16:19.860] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R414_FulltestROC_m20_2015-12-02_11h01m_1449050469//000_FulltestROC_m20//readbackCal_C0.dat
[10:16:19.867] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[10:16:19.867] <TB2> INFO: ----------------------------------------------------------------------
[10:16:19.867] <TB2> INFO: PixTestReadback::CalibrateVa()
[10:16:19.867] <TB2> INFO: ----------------------------------------------------------------------
[10:16:30.981] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R414_FulltestROC_m20_2015-12-02_11h01m_1449050469//000_FulltestROC_m20//readbackCal_C0.dat
[10:16:30.987] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[10:16:30.987] <TB2> INFO: ----------------------------------------------------------------------
[10:16:30.987] <TB2> INFO: PixTestReadback::readbackVbg()
[10:16:30.987] <TB2> INFO: ----------------------------------------------------------------------
[10:16:39.312] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[10:16:39.313] <TB2> INFO: ----------------------------------------------------------------------
[10:16:39.313] <TB2> INFO: PixTestReadback::getCalibratedVbg()
[10:16:39.313] <TB2> INFO: ----------------------------------------------------------------------
[10:16:39.313] <TB2> INFO: Vbg will be calibrated using Vd calibration
[10:16:39.313] <TB2> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 132.9calibrated Vbg = 1.28832 :::*/*/*/*/
[10:16:39.689] <TB2> INFO: ----------------------------------------------------------------------
[10:16:39.689] <TB2> INFO: PixTestReadback::CalibrateIa()
[10:16:39.689] <TB2> INFO: ----------------------------------------------------------------------
[10:16:48.656] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R414_FulltestROC_m20_2015-12-02_11h01m_1449050469//000_FulltestROC_m20//readbackCal_C0.dat
[10:16:48.661] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[10:16:48.661] <TB2> INFO: PixTestReadback::doTest() done
[10:16:48.698] <TB2> INFO: enter test to run
[10:16:48.698] <TB2> INFO: test: no parameter change
[10:16:48.713] <TB2> QUIET: Connection to board 137 closed.
[10:16:48.792] <TB2> INFO: pXar: this is the end, my friend