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

[15:45:25.480] <TB2> INFO: PixTestSetup:: pg set to RES|TOK
[15:45:25.480] <TB2> INFO: 0 1 2 3 4 5 6 7
[15:45:28.520] <TB2> INFO: 0: 000 000 00c 0fc ff0 f00 000 000
[15:45:31.532] <TB2> INFO: 1: 000 000 004 07c <7f8>[*] f80 800 000
[15:45:34.544] <TB2> INFO: 2: 000 000 004 07c <7f8>[*] f80 800 000
[15:45:37.557] <TB2> INFO: 3: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[15:45:40.569] <TB2> INFO: 4: 800 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[15:45:43.582] <TB2> INFO: 5: 800 000 000 03c 3f8 f80 800 000
[15:45:46.595] <TB2> INFO: 6: 000 000 000 03c 3fc fc0 c00 000
[15:45:49.608] <TB2> INFO: 7: c00 000 000 03c 3fc fc0 c00 000
[15:45:52.620] <TB2> INFO: 8: 000 000 000 03c 3fc fc0 c00 000
[15:45:55.632] <TB2> INFO: 9: 000 000 000 03c 3fc fc0 c00 000
[15:45:58.644] <TB2> INFO: 10: c00 000 000 03c 3fc fc0 c00 000
[15:46:01.657] <TB2> INFO: 11: 000 000 000 01c 1fc fe0 e00 000
[15:46:04.670] <TB2> INFO: 12: e00 000 000 01c 1fc fe0 e00 000
[15:46:07.682] <TB2> INFO: 13: e00 000 000 01c 1fc fe0 e00 000
[15:46:10.695] <TB2> INFO: 14: e00 000 000 01c 1fc fe0 e00 000
[15:46:13.708] <TB2> INFO: 15: e00 000 000 00c 0fc fe0 e00 000
[15:46:16.721] <TB2> INFO: 16: 000 000 000 00c 0fc ff0 f00 000
[15:46:19.733] <TB2> INFO: 17: 000 000 000 00c 0fc ff0 f00 000
[15:46:22.746] <TB2> INFO: 18: 000 000 000 00c 0fc ff0 f00 000
[15:46:25.758] <TB2> INFO: 19: 000 000 000 00c 0fc ff0 f00 000
[15:46:26.174] <TB2> INFO: Found good delays at CLK = 2, DESER160 = 4
[15:46:26.175] <TB2> INFO: PixTestSetup:: Write Tb parameters to file.
[15:46:26.206] <TB2> INFO: write dtb parameters into /home/mameinha/data/R415_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//tbParameters.dat
[15:46:26.211] <TB2> INFO: PixTestSetup::doTest() done for.
[15:46:26.238] <TB2> INFO: enter test to run
[15:46:26.238] <TB2> INFO: test: Pretest no parameter change
[15:46:26.238] <TB2> INFO: running: pretest
[15:46:26.240] <TB2> INFO: ----------------------------------------------------------------------
[15:46:26.240] <TB2> INFO: PixTestPretest::programROC()
[15:46:26.240] <TB2> INFO: ----------------------------------------------------------------------
[15:46:29.242] <TB2> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[15:46:29.242] <TB2> INFO: IA differences per ROC: 18.5
[15:46:29.246] <TB2> INFO: enter test to run
[15:46:29.246] <TB2> INFO: test: Pretest no parameter change
[15:46:29.246] <TB2> INFO: running: pretest
[15:46:29.247] <TB2> INFO: ----------------------------------------------------------------------
[15:46:29.247] <TB2> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[15:46:29.247] <TB2> INFO: ----------------------------------------------------------------------
[15:46:29.957] <TB2> INFO: PixTestPretest::setVana() done, Module Ia 23.3 mA = 23.3 mA/ROC
[15:46:29.957] <TB2> INFO: i(loss) [mA/ROC]: 20.1
[15:46:29.961] <TB2> INFO: enter test to run
[15:46:29.961] <TB2> INFO: test: Pretest no parameter change
[15:46:29.961] <TB2> INFO: running: pretest
[15:46:29.962] <TB2> INFO: ----------------------------------------------------------------------
[15:46:29.962] <TB2> INFO: PixTestPretest::findWorkingPixel()
[15:46:29.962] <TB2> INFO: ----------------------------------------------------------------------
[15:46:29.972] <TB2> INFO: Expecting 231680 events.
[15:46:32.253] <TB2> INFO: 231680 events read in total (1894ms).
[15:46:32.255] <TB2> INFO: Test took 2292ms.
[15:46:32.630] <TB2> INFO: Found working pixel in all ROCs: col/row = 12/22
[15:46:32.641] <TB2> INFO: enter test to run
[15:46:32.641] <TB2> INFO: test: Pretest no parameter change
[15:46:32.641] <TB2> INFO: running: pretest
[15:46:32.643] <TB2> INFO: ----------------------------------------------------------------------
[15:46:32.643] <TB2> INFO: PixTestPretest::setVthrCompCalDel()
[15:46:32.643] <TB2> INFO: ----------------------------------------------------------------------
[15:46:32.652] <TB2> INFO: Expecting 231680 events.
[15:46:34.920] <TB2> INFO: 231680 events read in total (1881ms).
[15:46:34.923] <TB2> INFO: Test took 2280ms.
[15:46:35.294] <TB2> INFO: PixTestPretest::setVthrCompCalDel() done
[15:46:35.295] <TB2> INFO: CalDel: 151
[15:46:35.295] <TB2> INFO: VthrComp: 51
[15:46:35.299] <TB2> INFO: enter test to run
[15:46:35.299] <TB2> INFO: test: Pretest no parameter change
[15:46:35.299] <TB2> INFO: running: pretest
[15:46:35.310] <TB2> INFO: write dac parameters into /home/mameinha/data/R415_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//dacParameters_C0.dat
[15:46:35.318] <TB2> INFO: enter test to run
[15:46:35.318] <TB2> INFO: test: PixelAlive no parameter change
[15:46:35.318] <TB2> INFO: running: pixelalive
[15:46:35.320] <TB2> INFO: ######################################################################
[15:46:35.320] <TB2> INFO: PixTestAlive::doTest()
[15:46:35.320] <TB2> INFO: ######################################################################
[15:46:35.321] <TB2> INFO: ----------------------------------------------------------------------
[15:46:35.321] <TB2> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[15:46:35.321] <TB2> INFO: ----------------------------------------------------------------------
[15:46:35.342] <TB2> INFO: Expecting 41600 events.
[15:46:36.163] <TB2> INFO: 41600 events read in total (435ms).
[15:46:36.164] <TB2> INFO: Test took 843ms.
[15:46:36.164] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:36.548] <TB2> INFO: PixTestAlive::aliveTest() done
[15:46:36.548] <TB2> INFO: number of dead pixels (per ROC): 0
[15:46:36.550] <TB2> INFO: ----------------------------------------------------------------------
[15:46:36.550] <TB2> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[15:46:36.550] <TB2> INFO: ----------------------------------------------------------------------
[15:46:36.569] <TB2> INFO: Expecting 41600 events.
[15:46:37.360] <TB2> INFO: 41600 events read in total (404ms).
[15:46:37.361] <TB2> INFO: Test took 811ms.
[15:46:37.361] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:37.361] <TB2> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[15:46:37.751] <TB2> INFO: PixTestAlive::maskTest() done
[15:46:37.751] <TB2> INFO: number of mask-defect pixels (per ROC): 0
[15:46:37.752] <TB2> INFO: ----------------------------------------------------------------------
[15:46:37.752] <TB2> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[15:46:37.752] <TB2> INFO: ----------------------------------------------------------------------
[15:46:37.773] <TB2> INFO: Expecting 41600 events.
[15:46:38.588] <TB2> INFO: 41600 events read in total (428ms).
[15:46:38.589] <TB2> INFO: Test took 837ms.
[15:46:38.589] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:38.974] <TB2> INFO: PixTestAlive::addressDecodingTest() done
[15:46:38.974] <TB2> INFO: number of address-decoding pixels (per ROC): 0
[15:46:38.974] <TB2> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[15:46:38.974] <TB2> INFO: enter test to run
[15:46:38.974] <TB2> INFO: test: Scurves no parameter change
[15:46:38.974] <TB2> INFO: running: scurves
[15:46:38.976] <TB2> INFO: ######################################################################
[15:46:38.976] <TB2> INFO: PixTestScurves::doTest() ntrig = 50
[15:46:38.976] <TB2> INFO: ######################################################################
[15:46:38.976] <TB2> INFO: ----------------------------------------------------------------------
[15:46:38.976] <TB2> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[15:46:38.976] <TB2> INFO: ----------------------------------------------------------------------
[15:46:38.976] <TB2> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[15:46:38.986] <TB2> INFO: dacScan split into 1 runs with ntrig = 50
[15:46:38.986] <TB2> INFO: run 1 of 1
[15:46:39.006] <TB2> INFO: Expecting 41808000 events.
[15:49:04.489] <TB2> INFO: 18412300 events read in total (145096ms).
[15:51:22.458] <TB2> INFO: 36348850 events read in total (283065ms).
[15:52:04.112] <TB2> INFO: 41808000 events read in total (324719ms).
[15:52:04.146] <TB2> INFO: Test took 325160ms.
[15:52:04.184] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:52:04.193] <TB2> INFO: dumping ASCII scurve output file: SCurveData
[15:52:05.750] <TB2> INFO: PixTestScurves::scurves() done
[15:52:05.750] <TB2> INFO: Vcal mean: 64.86
[15:52:05.750] <TB2> INFO: Vcal RMS: 4.87
[15:52:05.754] <TB2> INFO: enter test to run
[15:52:05.754] <TB2> INFO: test: Trim no parameter change
[15:52:05.754] <TB2> INFO: running: trim
[15:52:05.756] <TB2> INFO: ######################################################################
[15:52:05.756] <TB2> INFO: PixTestTrim::doTest()
[15:52:05.756] <TB2> INFO: ######################################################################
[15:52:05.757] <TB2> INFO: ----------------------------------------------------------------------
[15:52:05.757] <TB2> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[15:52:05.757] <TB2> INFO: ----------------------------------------------------------------------
[15:52:05.762] <TB2> INFO: ---> VthrComp thr map (minimal VthrComp)
[15:52:05.762] <TB2> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[15:52:05.770] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:52:05.770] <TB2> INFO: run 1 of 1
[15:52:05.789] <TB2> INFO: Expecting 6281600 events.
[15:52:53.384] <TB2> INFO: 6281600 events read in total (47207ms).
[15:52:53.405] <TB2> INFO: Test took 47635ms.
[15:52:53.414] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:52:54.518] <TB2> INFO: ROC 0 VthrComp = 73
[15:52:54.518] <TB2> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[15:52:54.518] <TB2> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[15:52:54.525] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:52:54.525] <TB2> INFO: run 1 of 1
[15:52:54.544] <TB2> INFO: Expecting 6281600 events.
[15:53:47.070] <TB2> INFO: 6281600 events read in total (52139ms).
[15:53:47.109] <TB2> INFO: Test took 52584ms.
[15:53:47.129] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:53:48.473] <TB2> INFO: roc 0 with ID = 0 has maximal Vcal 56.9229 for pixel 0/72 mean/min/max = 45.4562/33.9345/56.978
[15:53:48.482] <TB2> INFO: Expecting 514560 events.
[15:53:52.812] <TB2> INFO: 514560 events read in total (3943ms).
[15:53:52.817] <TB2> INFO: Test took 4344ms.
[15:53:53.252] <TB2> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[15:53:53.262] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:53:53.262] <TB2> INFO: run 1 of 1
[15:53:53.285] <TB2> INFO: Expecting 6281600 events.
[15:54:46.023] <TB2> INFO: 6281600 events read in total (52351ms).
[15:54:46.061] <TB2> INFO: Test took 52799ms.
[15:54:46.082] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:54:47.277] <TB2> INFO: ---> TrimStepCorr4 extremal thresholds: 16.859334 .. 47.313837
[15:54:47.282] <TB2> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 6 .. 57 (-1/-1) hits flags = 528 (plus default)
[15:54:47.289] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:54:47.289] <TB2> INFO: run 1 of 1
[15:54:47.309] <TB2> INFO: Expecting 2163200 events.
[15:55:04.671] <TB2> INFO: 2163200 events read in total (16975ms).
[15:55:04.681] <TB2> INFO: Test took 17392ms.
[15:55:04.685] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:55:05.511] <TB2> INFO: ---> TrimStepCorr2 extremal thresholds: 23.557034 .. 42.584853
[15:55:05.516] <TB2> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 13 .. 52 (-1/-1) hits flags = 528 (plus default)
[15:55:05.523] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:55:05.523] <TB2> INFO: run 1 of 1
[15:55:05.543] <TB2> INFO: Expecting 1664000 events.
[15:55:19.384] <TB2> INFO: 1664000 events read in total (13454ms).
[15:55:19.391] <TB2> INFO: Test took 13868ms.
[15:55:19.395] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:55:20.194] <TB2> INFO: ---> TrimStepCorr1a extremal thresholds: 27.550738 .. 39.727054
[15:55:20.198] <TB2> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 17 .. 49 (-1/-1) hits flags = 528 (plus default)
[15:55:20.206] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:55:20.206] <TB2> INFO: run 1 of 1
[15:55:20.225] <TB2> INFO: Expecting 1372800 events.
[15:55:31.581] <TB2> INFO: 1372800 events read in total (10969ms).
[15:55:31.587] <TB2> INFO: Test took 11381ms.
[15:55:31.591] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:55:32.390] <TB2> INFO: ---> TrimStepCorr1b extremal thresholds: 29.591486 .. 39.116244
[15:55:32.395] <TB2> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 19 .. 49 (-1/-1) hits flags = 528 (plus default)
[15:55:32.402] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:55:32.402] <TB2> INFO: run 1 of 1
[15:55:32.422] <TB2> INFO: Expecting 1289600 events.
[15:55:43.259] <TB2> INFO: 1289600 events read in total (10451ms).
[15:55:43.265] <TB2> INFO: Test took 10863ms.
[15:55:43.268] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:55:44.112] <TB2> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[15:55:44.113] <TB2> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[15:55:44.123] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:55:44.123] <TB2> INFO: run 1 of 1
[15:55:44.143] <TB2> INFO: Expecting 1705600 events.
[15:55:58.551] <TB2> INFO: 1705600 events read in total (14021ms).
[15:55:58.562] <TB2> INFO: Test took 14439ms.
[15:55:58.567] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:55:59.385] <TB2> INFO: write dac parameters into /home/mameinha/data/R415_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//dacParameters35_C0.dat
[15:55:59.391] <TB2> INFO: write trim parameters into /home/mameinha/data/R415_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//trimParameters35_C0.dat
[15:55:59.401] <TB2> INFO: PixTestTrim::trimTest() done
[15:55:59.401] <TB2> INFO: vtrim: 107
[15:55:59.401] <TB2> INFO: vthrcomp: 73
[15:55:59.401] <TB2> INFO: vcal mean: 34.90
[15:55:59.401] <TB2> INFO: vcal RMS: 0.64
[15:55:59.401] <TB2> INFO: bits mean: 8.77
[15:55:59.401] <TB2> INFO: bits RMS: 2.93
[15:55:59.405] <TB2> INFO: ----------------------------------------------------------------------
[15:55:59.405] <TB2> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[15:55:59.405] <TB2> INFO: ----------------------------------------------------------------------
[15:55:59.406] <TB2> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[15:55:59.415] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:55:59.415] <TB2> INFO: run 1 of 1
[15:55:59.438] <TB2> INFO: Expecting 8320000 events.
[15:57:06.212] <TB2> INFO: 8320000 events read in total (66387ms).
[15:57:06.252] <TB2> INFO: Test took 66837ms.
[15:57:06.273] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:57:07.749] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 112 (-1/-1) hits flags = 528 (plus default)
[15:57:07.757] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:57:07.757] <TB2> INFO: run 1 of 1
[15:57:07.776] <TB2> INFO: Expecting 4700800 events.
[15:57:44.401] <TB2> INFO: 4700800 events read in total (36238ms).
[15:57:44.417] <TB2> INFO: Test took 36660ms.
[15:57:44.425] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:57:45.526] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 103 (-1/-1) hits flags = 528 (plus default)
[15:57:45.533] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:57:45.533] <TB2> INFO: run 1 of 1
[15:57:45.552] <TB2> INFO: Expecting 4326400 events.
[15:58:19.227] <TB2> INFO: 4326400 events read in total (33288ms).
[15:58:19.240] <TB2> INFO: Test took 33707ms.
[15:58:19.246] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:58:20.283] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 103 (-1/-1) hits flags = 528 (plus default)
[15:58:20.291] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:58:20.291] <TB2> INFO: run 1 of 1
[15:58:20.310] <TB2> INFO: Expecting 4326400 events.
[15:58:53.618] <TB2> INFO: 4326400 events read in total (32921ms).
[15:58:53.630] <TB2> INFO: Test took 33339ms.
[15:58:53.637] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:58:54.690] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 103 (-1/-1) hits flags = 528 (plus default)
[15:58:54.697] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:58:54.697] <TB2> INFO: run 1 of 1
[15:58:54.717] <TB2> INFO: Expecting 4326400 events.
[15:59:28.692] <TB2> INFO: 4326400 events read in total (33588ms).
[15:59:28.705] <TB2> INFO: Test took 34008ms.
[15:59:28.711] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:29.874] <TB2> INFO: PixTestTrim::trimBitTest() done
[15:59:29.876] <TB2> INFO: PixTestTrim::doTest() done, duration: 444 seconds
[15:59:29.935] <TB2> INFO: enter test to run
[15:59:29.935] <TB2> INFO: test: PhOptimization no parameter change
[15:59:29.935] <TB2> INFO: running: phoptimization
[15:59:29.935] <TB2> INFO: ######################################################################
[15:59:29.935] <TB2> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[15:59:29.935] <TB2> INFO: ######################################################################
[15:59:29.956] <TB2> INFO: Expecting 41600 events.
[15:59:30.792] <TB2> INFO: 41600 events read in total (450ms).
[15:59:30.792] <TB2> INFO: Test took 856ms.
[15:59:30.792] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:31.183] <TB2> INFO: Expecting 41600 events.
[15:59:31.986] <TB2> INFO: 41600 events read in total (416ms).
[15:59:31.987] <TB2> INFO: Test took 1194ms.
[15:59:31.987] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:32.375] <TB2> INFO: Expecting 41600 events.
[15:59:33.197] <TB2> INFO: 41600 events read in total (435ms).
[15:59:33.198] <TB2> INFO: Test took 1211ms.
[15:59:33.198] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:33.587] <TB2> INFO: Expecting 2560 events.
[15:59:34.006] <TB2> INFO: 2560 events read in total (32ms).
[15:59:34.006] <TB2> INFO: Test took 807ms.
[15:59:34.402] <TB2> INFO: Expecting 655360 events.
[15:59:39.959] <TB2> INFO: 655360 events read in total (5170ms).
[15:59:39.967] <TB2> INFO: Test took 5960ms.
[15:59:40.255] <TB2> INFO: Expecting 655360 events.
[15:59:45.876] <TB2> INFO: 655360 events read in total (5234ms).
[15:59:45.888] <TB2> INFO: Test took 5908ms.
[15:59:45.917] <TB2> INFO: safety margin for low PH: adding 0, margin is now 20
[15:59:45.935] <TB2> INFO: write dac parameters into /home/mameinha/data/R415_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//dacParameters35_C0.dat
[15:59:46.140] <TB2> INFO: Expecting 41600 events.
[15:59:46.929] <TB2> INFO: 41600 events read in total (402ms).
[15:59:46.930] <TB2> INFO: Test took 988ms.
[15:59:47.315] <TB2> INFO: Expecting 41600 events.
[15:59:48.079] <TB2> INFO: 41600 events read in total (377ms).
[15:59:48.079] <TB2> INFO: Test took 1149ms.
[15:59:48.467] <TB2> INFO: Expecting 41600 events.
[15:59:49.241] <TB2> INFO: 41600 events read in total (387ms).
[15:59:49.241] <TB2> INFO: Test took 1161ms.
[15:59:49.630] <TB2> INFO: Expecting 2560 events.
[15:59:50.048] <TB2> INFO: 2560 events read in total (31ms).
[15:59:50.049] <TB2> INFO: Test took 807ms.
[15:59:50.443] <TB2> INFO: Expecting 2560 events.
[15:59:50.861] <TB2> INFO: 2560 events read in total (31ms).
[15:59:50.861] <TB2> INFO: Test took 812ms.
[15:59:51.268] <TB2> INFO: PixTestPhOptimization::doTest() done, duration: 21 seconds
[15:59:51.268] <TB2> INFO: PH scale (per ROC): 92
[15:59:51.268] <TB2> INFO: PH offset (per ROC): 175
[15:59:51.286] <TB2> INFO: enter test to run
[15:59:51.286] <TB2> INFO: test: GainPedestal no parameter change
[15:59:51.286] <TB2> INFO: running: gainpedestal
[15:59:51.287] <TB2> INFO: ######################################################################
[15:59:51.287] <TB2> INFO: PixTestGainPedestal::doTest() ntrig = 10
[15:59:51.287] <TB2> INFO: ######################################################################
[15:59:51.295] <TB2> INFO: scanning low vcal = 10
[15:59:51.315] <TB2> INFO: Expecting 41600 events.
[15:59:52.418] <TB2> INFO: 41600 events read in total (716ms).
[15:59:52.418] <TB2> INFO: Test took 1123ms.
[15:59:52.418] <TB2> INFO: scanning low vcal = 20
[15:59:52.813] <TB2> INFO: Expecting 41600 events.
[15:59:53.924] <TB2> INFO: 41600 events read in total (724ms).
[15:59:53.924] <TB2> INFO: Test took 1506ms.
[15:59:53.924] <TB2> INFO: scanning low vcal = 30
[15:59:54.319] <TB2> INFO: Expecting 41600 events.
[15:59:55.416] <TB2> INFO: 41600 events read in total (710ms).
[15:59:55.416] <TB2> INFO: Test took 1492ms.
[15:59:55.417] <TB2> INFO: scanning low vcal = 40
[15:59:55.811] <TB2> INFO: Expecting 41600 events.
[15:59:56.952] <TB2> INFO: 41600 events read in total (754ms).
[15:59:56.952] <TB2> INFO: Test took 1535ms.
[15:59:56.952] <TB2> INFO: scanning low vcal = 50
[15:59:57.341] <TB2> INFO: Expecting 41600 events.
[15:59:58.466] <TB2> INFO: 41600 events read in total (738ms).
[15:59:58.467] <TB2> INFO: Test took 1515ms.
[15:59:58.467] <TB2> INFO: scanning low vcal = 60
[15:59:58.856] <TB2> INFO: Expecting 41600 events.
[15:59:59.979] <TB2> INFO: 41600 events read in total (736ms).
[15:59:59.980] <TB2> INFO: Test took 1513ms.
[15:59:59.980] <TB2> INFO: scanning low vcal = 70
[16:00:00.369] <TB2> INFO: Expecting 41600 events.
[16:00:01.496] <TB2> INFO: 41600 events read in total (740ms).
[16:00:01.497] <TB2> INFO: Test took 1517ms.
[16:00:01.497] <TB2> INFO: scanning low vcal = 80
[16:00:01.885] <TB2> INFO: Expecting 41600 events.
[16:00:03.017] <TB2> INFO: 41600 events read in total (745ms).
[16:00:03.018] <TB2> INFO: Test took 1521ms.
[16:00:03.018] <TB2> INFO: scanning low vcal = 90
[16:00:03.407] <TB2> INFO: Expecting 41600 events.
[16:00:04.537] <TB2> INFO: 41600 events read in total (744ms).
[16:00:04.539] <TB2> INFO: Test took 1521ms.
[16:00:04.540] <TB2> INFO: scanning low vcal = 100
[16:00:04.924] <TB2> INFO: Expecting 41600 events.
[16:00:06.089] <TB2> INFO: 41600 events read in total (778ms).
[16:00:06.089] <TB2> INFO: Test took 1549ms.
[16:00:06.089] <TB2> INFO: scanning low vcal = 110
[16:00:06.473] <TB2> INFO: Expecting 41600 events.
[16:00:07.611] <TB2> INFO: 41600 events read in total (751ms).
[16:00:07.612] <TB2> INFO: Test took 1523ms.
[16:00:07.612] <TB2> INFO: scanning low vcal = 120
[16:00:08.001] <TB2> INFO: Expecting 41600 events.
[16:00:09.150] <TB2> INFO: 41600 events read in total (763ms).
[16:00:09.151] <TB2> INFO: Test took 1539ms.
[16:00:09.151] <TB2> INFO: scanning low vcal = 130
[16:00:09.538] <TB2> INFO: Expecting 41600 events.
[16:00:10.663] <TB2> INFO: 41600 events read in total (738ms).
[16:00:10.664] <TB2> INFO: Test took 1513ms.
[16:00:10.664] <TB2> INFO: scanning low vcal = 140
[16:00:11.053] <TB2> INFO: Expecting 41600 events.
[16:00:12.177] <TB2> INFO: 41600 events read in total (738ms).
[16:00:12.177] <TB2> INFO: Test took 1513ms.
[16:00:12.177] <TB2> INFO: scanning low vcal = 150
[16:00:12.566] <TB2> INFO: Expecting 41600 events.
[16:00:13.734] <TB2> INFO: 41600 events read in total (781ms).
[16:00:13.734] <TB2> INFO: Test took 1557ms.
[16:00:13.735] <TB2> INFO: scanning low vcal = 160
[16:00:14.123] <TB2> INFO: Expecting 41600 events.
[16:00:15.264] <TB2> INFO: 41600 events read in total (754ms).
[16:00:15.265] <TB2> INFO: Test took 1530ms.
[16:00:15.265] <TB2> INFO: scanning low vcal = 170
[16:00:15.654] <TB2> INFO: Expecting 41600 events.
[16:00:16.810] <TB2> INFO: 41600 events read in total (769ms).
[16:00:16.811] <TB2> INFO: Test took 1546ms.
[16:00:16.811] <TB2> INFO: scanning low vcal = 180
[16:00:17.198] <TB2> INFO: Expecting 41600 events.
[16:00:18.337] <TB2> INFO: 41600 events read in total (752ms).
[16:00:18.338] <TB2> INFO: Test took 1527ms.
[16:00:18.338] <TB2> INFO: scanning low vcal = 190
[16:00:18.727] <TB2> INFO: Expecting 41600 events.
[16:00:19.892] <TB2> INFO: 41600 events read in total (778ms).
[16:00:19.892] <TB2> INFO: Test took 1554ms.
[16:00:19.893] <TB2> INFO: scanning low vcal = 200
[16:00:20.278] <TB2> INFO: Expecting 41600 events.
[16:00:21.416] <TB2> INFO: 41600 events read in total (751ms).
[16:00:21.416] <TB2> INFO: Test took 1523ms.
[16:00:21.417] <TB2> INFO: scanning low vcal = 210
[16:00:21.805] <TB2> INFO: Expecting 41600 events.
[16:00:22.941] <TB2> INFO: 41600 events read in total (749ms).
[16:00:22.942] <TB2> INFO: Test took 1525ms.
[16:00:22.942] <TB2> INFO: scanning low vcal = 220
[16:00:23.327] <TB2> INFO: Expecting 41600 events.
[16:00:24.480] <TB2> INFO: 41600 events read in total (766ms).
[16:00:24.480] <TB2> INFO: Test took 1538ms.
[16:00:24.480] <TB2> INFO: scanning low vcal = 230
[16:00:24.869] <TB2> INFO: Expecting 41600 events.
[16:00:26.034] <TB2> INFO: 41600 events read in total (778ms).
[16:00:26.035] <TB2> INFO: Test took 1555ms.
[16:00:26.035] <TB2> INFO: scanning low vcal = 240
[16:00:26.421] <TB2> INFO: Expecting 41600 events.
[16:00:27.560] <TB2> INFO: 41600 events read in total (752ms).
[16:00:27.561] <TB2> INFO: Test took 1526ms.
[16:00:27.561] <TB2> INFO: scanning low vcal = 250
[16:00:27.949] <TB2> INFO: Expecting 41600 events.
[16:00:29.098] <TB2> INFO: 41600 events read in total (762ms).
[16:00:29.099] <TB2> INFO: Test took 1538ms.
[16:00:29.099] <TB2> INFO: scanning high vcal = 30 (= 210 in low range)
[16:00:29.486] <TB2> INFO: Expecting 41600 events.
[16:00:30.650] <TB2> INFO: 41600 events read in total (777ms).
[16:00:30.651] <TB2> INFO: Test took 1552ms.
[16:00:30.651] <TB2> INFO: scanning high vcal = 50 (= 350 in low range)
[16:00:31.037] <TB2> INFO: Expecting 41600 events.
[16:00:32.194] <TB2> INFO: 41600 events read in total (771ms).
[16:00:32.194] <TB2> INFO: Test took 1543ms.
[16:00:32.194] <TB2> INFO: scanning high vcal = 70 (= 490 in low range)
[16:00:32.580] <TB2> INFO: Expecting 41600 events.
[16:00:33.708] <TB2> INFO: 41600 events read in total (741ms).
[16:00:33.708] <TB2> INFO: Test took 1514ms.
[16:00:33.709] <TB2> INFO: scanning high vcal = 90 (= 630 in low range)
[16:00:34.097] <TB2> INFO: Expecting 41600 events.
[16:00:35.258] <TB2> INFO: 41600 events read in total (774ms).
[16:00:35.259] <TB2> INFO: Test took 1550ms.
[16:00:35.259] <TB2> INFO: scanning high vcal = 200 (= 1400 in low range)
[16:00:35.642] <TB2> INFO: Expecting 41600 events.
[16:00:36.789] <TB2> INFO: 41600 events read in total (760ms).
[16:00:36.789] <TB2> INFO: Test took 1530ms.
[16:00:37.167] <TB2> INFO: PixTestGainPedestal::measure() done
[16:00:39.203] <TB2> INFO: PixTestGainPedestal::fit() done
[16:00:39.203] <TB2> INFO: non-linearity mean: 0.956
[16:00:39.203] <TB2> INFO: non-linearity RMS: 0.007
[16:00:39.220] <TB2> INFO: write gain/ped parameters into /home/mameinha/data/R415_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//phCalibrationFitErr35_C0.dat
[16:00:39.374] <TB2> INFO: PixTestGainPedestal::doTest() done, duration: 48 seconds
[16:00:39.375] <TB2> INFO: enter test to run
[16:00:39.375] <TB2> INFO: test: Readback no parameter change
[16:00:39.375] <TB2> INFO: running: readback
[16:00:39.375] <TB2> INFO: readReadbackCal: /home/mameinha/data/R415_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//readbackCal_C0.dat .. /home/mameinha/data/R415_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//readbackCal_C0.dat
[16:00:39.376] <TB2> INFO: ######################################################################
[16:00:39.376] <TB2> INFO: PixTestReadback::doTest()
[16:00:39.376] <TB2> INFO: ######################################################################
[16:00:39.376] <TB2> INFO: ----------------------------------------------------------------------
[16:00:39.376] <TB2> INFO: PixTestReadback::CalibrateVd()
[16:00:39.376] <TB2> INFO: ----------------------------------------------------------------------
[16:00:51.372] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R415_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//readbackCal_C0.dat
[16:00:51.552] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[16:00:51.552] <TB2> INFO: ----------------------------------------------------------------------
[16:00:51.552] <TB2> INFO: PixTestReadback::CalibrateVa()
[16:00:51.552] <TB2> INFO: ----------------------------------------------------------------------
[16:01:02.650] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R415_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//readbackCal_C0.dat
[16:01:02.670] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[16:01:02.670] <TB2> INFO: ----------------------------------------------------------------------
[16:01:02.670] <TB2> INFO: PixTestReadback::readbackVbg()
[16:01:02.670] <TB2> INFO: ----------------------------------------------------------------------
[16:01:10.998] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[16:01:10.999] <TB2> INFO: ----------------------------------------------------------------------
[16:01:10.999] <TB2> INFO: PixTestReadback::getCalibratedVbg()
[16:01:10.999] <TB2> INFO: ----------------------------------------------------------------------
[16:01:10.999] <TB2> INFO: Vbg will be calibrated using Vd calibration
[16:01:10.999] <TB2> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 137calibrated Vbg = 1.30836 :::*/*/*/*/
[16:01:11.375] <TB2> INFO: ----------------------------------------------------------------------
[16:01:11.375] <TB2> INFO: PixTestReadback::CalibrateIa()
[16:01:11.375] <TB2> INFO: ----------------------------------------------------------------------
[16:01:20.211] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R415_FulltestROC_m20_2015-12-02_16h45m_1449071109//000_FulltestROC_m20//readbackCal_C0.dat
[16:01:20.220] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[16:01:20.220] <TB2> INFO: PixTestReadback::doTest() done
[16:01:20.254] <TB2> INFO: enter test to run
[16:01:20.254] <TB2> INFO: test: no parameter change
[16:01:20.346] <TB2> QUIET: Connection to board 169 closed.
[16:01:20.426] <TB2> INFO: pXar: this is the end, my friend