[09:06:42.491] <TB3> INFO: *** Welcome to pxar ***
[09:06:42.491] <TB3> INFO: *** Today: 2015/10/07
[09:06:42.714] <TB3> INFO: *** Version: 9da6
[09:06:42.714] <TB3> INFO: readRocDacs: /home/mameinha/data/R419_Fulltest_m20_2015-10-07_11h06m_1444208776//000_FulltestROC_m20//dacParameters_C0.dat .. /home/mameinha/data/R419_Fulltest_m20_2015-10-07_11h06m_1444208776//000_FulltestROC_m20//dacParameters_C0.dat
[09:06:42.719] <TB3> INFO: readTbmDacs: /home/mameinha/data/R419_Fulltest_m20_2015-10-07_11h06m_1444208776//000_FulltestROC_m20//tbmParameters_C0a.dat .. /home/mameinha/data/R419_Fulltest_m20_2015-10-07_11h06m_1444208776//000_FulltestROC_m20//tbmParameters_C4294967295b.dat
[09:06:42.719] <TB3> INFO: readMaskFile: /home/mameinha/data/R419_Fulltest_m20_2015-10-07_11h06m_1444208776//000_FulltestROC_m20//defaultMaskFile.dat
[09:06:42.720] <TB3> INFO: readTrimFile: /home/mameinha/data/R419_Fulltest_m20_2015-10-07_11h06m_1444208776//000_FulltestROC_m20//trimParameters_C0.dat .. /home/mameinha/data/R419_Fulltest_m20_2015-10-07_11h06m_1444208776//000_FulltestROC_m20//trimParameters_C0.dat
[09:06:42.734] <TB3> INFO: clk: 2
[09:06:42.734] <TB3> INFO: ctr: 2
[09:06:42.734] <TB3> INFO: sda: 17
[09:06:42.734] <TB3> INFO: tin: 7
[09:06:42.734] <TB3> INFO: level: 15
[09:06:42.734] <TB3> INFO: deser160phase: 4
[09:06:42.734] <TB3> QUIET: Instanciating API for pxar v2.6.0+20~g1a7f656
[09:06:42.734] <TB3> INFO: Log level: INFO
[09:06:42.740] <TB3> INFO: Found DTB DTB_WRQ4OZ
[09:06:42.750] <TB3> QUIET: Connection to board DTB_WRQ4OZ opened.
[09:06:42.753] <TB3> INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 71
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WRQ4OZ
MAC address: 40D855118047
Hostname: pixelDTB071
Comment:
------------------------------------------------------
[09:06:42.756] <TB3> INFO: RPC call hashes of host and DTB match: 398089610
[09:06:43.928] <TB3> INFO: DUT info:
[09:06:43.928] <TB3> INFO: The DUT currently contains the following objects:
[09:06:43.928] <TB3> INFO: 0 TBM Cores (0 ON)
[09:06:43.928] <TB3> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[09:06:43.928] <TB3> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[09:06:44.330] <TB3> INFO: enter 'restricted' command line mode
[09:06:44.330] <TB3> INFO: enter test to run
[09:06:44.331] <TB3> INFO: test: Setup no parameter change
[09:06:44.331] <TB3> INFO: running: setup
[09:06:44.336] <TB3> INFO: PixTestSetup::doTest() ntrig = 10

[09:06:44.336] <TB3> INFO: PixTestSetup:: pg set to RES|TOK
[09:06:44.336] <TB3> INFO: 0 1 2 3 4 5 6 7
[09:06:47.381] <TB3> INFO: 0: 000 000 004 07c 7f0 f00 000 000
[09:06:50.396] <TB3> INFO: 1: 000 000 004 07c <7f8>[*] f80 800 000
[09:06:53.411] <TB3> INFO: 2: 800 000 004 07c <7f8>[*] f80 800 000
[09:06:56.426] <TB3> INFO: 3: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[09:06:59.442] <TB3> INFO: 4: 800 000 004 07c <7f8>[*] f80 800 000
[09:07:02.457] <TB3> INFO: 5: 000 000 000 03c 3f8 f80 800 000
[09:07:05.472] <TB3> INFO: 6: 000 000 000 03c 3fc fc0 c00 000
[09:07:08.487] <TB3> INFO: 7: 000 000 000 03c 3fc fc0 c00 000
[09:07:11.502] <TB3> INFO: 8: 000 000 000 03c 3fc fc0 c00 000
[09:07:14.517] <TB3> INFO: 9: 000 000 000 03c 3fc fc0 c00 000
[09:07:17.533] <TB3> INFO: 10: c00 000 000 01c 1fc fc0 c00 000
[09:07:20.548] <TB3> INFO: 11: 000 000 000 01c 1fc fe0 e00 000
[09:07:23.563] <TB3> INFO: 12: 000 000 000 01c 1fc fe0 e00 000
[09:07:26.578] <TB3> INFO: 13: 000 000 000 01c 1fc fe0 e00 000
[09:07:29.593] <TB3> INFO: 14: 000 000 000 00c 0fc fe0 e00 000
[09:07:32.608] <TB3> INFO: 15: 000 000 000 00c 0fc fe0 e00 000
[09:07:35.623] <TB3> INFO: 16: 000 000 000 00c 0fc ff0 f00 000
[09:07:38.639] <TB3> INFO: 17: 000 000 000 00c 0fc ff0 f00 000
[09:07:41.654] <TB3> INFO: 18: f00 000 000 00c 0fc ff0 f00 000
[09:07:44.669] <TB3> INFO: 19: 000 000 000 00c 0fc ff0 f00 000
[09:07:45.086] <TB3> INFO: Found good delays at CLK = 2, DESER160 = 4
[09:07:45.087] <TB3> INFO: PixTestSetup:: Write Tb parameters to file.
[09:07:45.093] <TB3> INFO: write dtb parameters into /home/mameinha/data/R419_Fulltest_m20_2015-10-07_11h06m_1444208776//000_FulltestROC_m20//tbParameters.dat
[09:07:45.095] <TB3> INFO: PixTestSetup::doTest() done for.
[09:07:45.121] <TB3> INFO: enter test to run
[09:07:45.121] <TB3> INFO: test: Pretest no parameter change
[09:07:45.121] <TB3> INFO: running: pretest
[09:07:45.123] <TB3> INFO: ----------------------------------------------------------------------
[09:07:45.123] <TB3> INFO: PixTestPretest::programROC()
[09:07:45.123] <TB3> INFO: ----------------------------------------------------------------------
[09:07:48.126] <TB3> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[09:07:48.126] <TB3> INFO: IA differences per ROC: 17.7
[09:07:48.131] <TB3> INFO: enter test to run
[09:07:48.131] <TB3> INFO: test: Pretest no parameter change
[09:07:48.131] <TB3> INFO: running: pretest
[09:07:48.133] <TB3> INFO: ----------------------------------------------------------------------
[09:07:48.133] <TB3> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[09:07:48.133] <TB3> INFO: ----------------------------------------------------------------------
[09:07:48.847] <TB3> INFO: PixTestPretest::setVana() done, Module Ia 24.1 mA = 24.1 mA/ROC
[09:07:48.847] <TB3> INFO: i(loss) [mA/ROC]: 19.3
[09:07:48.850] <TB3> INFO: enter test to run
[09:07:48.850] <TB3> INFO: test: Pretest no parameter change
[09:07:48.850] <TB3> INFO: running: pretest
[09:07:48.852] <TB3> INFO: ----------------------------------------------------------------------
[09:07:48.852] <TB3> INFO: PixTestPretest::findWorkingPixel()
[09:07:48.852] <TB3> INFO: ----------------------------------------------------------------------
[09:07:48.862] <TB3> INFO: Expecting 231680 events.
[09:07:51.080] <TB3> INFO: 231680 events read in total (1831ms).
[09:07:51.082] <TB3> INFO: Test took 2230ms.
[09:07:51.457] <TB3> INFO: Found working pixel in all ROCs: col/row = 12/22
[09:07:51.468] <TB3> INFO: enter test to run
[09:07:51.468] <TB3> INFO: test: Pretest no parameter change
[09:07:51.468] <TB3> INFO: running: pretest
[09:07:51.470] <TB3> INFO: ----------------------------------------------------------------------
[09:07:51.470] <TB3> INFO: PixTestPretest::setVthrCompCalDel()
[09:07:51.470] <TB3> INFO: ----------------------------------------------------------------------
[09:07:51.480] <TB3> INFO: Expecting 231680 events.
[09:07:53.757] <TB3> INFO: 231680 events read in total (1890ms).
[09:07:53.761] <TB3> INFO: Test took 2290ms.
[09:07:54.132] <TB3> INFO: PixTestPretest::setVthrCompCalDel() done
[09:07:54.132] <TB3> INFO: CalDel: 146
[09:07:54.132] <TB3> INFO: VthrComp: 51
[09:07:54.140] <TB3> INFO: enter test to run
[09:07:54.140] <TB3> INFO: test: Pretest no parameter change
[09:07:54.140] <TB3> INFO: running: pretest
[09:07:54.195] <TB3> INFO: write dac parameters into /home/mameinha/data/R419_Fulltest_m20_2015-10-07_11h06m_1444208776//000_FulltestROC_m20//dacParameters_C0.dat
[09:07:54.202] <TB3> INFO: enter test to run
[09:07:54.202] <TB3> INFO: test: PixelAlive no parameter change
[09:07:54.202] <TB3> INFO: running: pixelalive
[09:07:54.204] <TB3> INFO: ######################################################################
[09:07:54.204] <TB3> INFO: PixTestAlive::doTest()
[09:07:54.204] <TB3> INFO: ######################################################################
[09:07:54.205] <TB3> INFO: ----------------------------------------------------------------------
[09:07:54.205] <TB3> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[09:07:54.205] <TB3> INFO: ----------------------------------------------------------------------
[09:07:54.239] <TB3> INFO: Expecting 41600 events.
[09:07:55.118] <TB3> INFO: 41600 events read in total (492ms).
[09:07:55.119] <TB3> INFO: Test took 913ms.
[09:07:55.119] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:07:55.501] <TB3> INFO: PixTestAlive::aliveTest() done
[09:07:55.501] <TB3> INFO: number of dead pixels (per ROC): 0
[09:07:55.503] <TB3> INFO: ----------------------------------------------------------------------
[09:07:55.503] <TB3> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[09:07:55.503] <TB3> INFO: ----------------------------------------------------------------------
[09:07:55.530] <TB3> INFO: Expecting 41600 events.
[09:07:56.295] <TB3> INFO: 41600 events read in total (378ms).
[09:07:56.295] <TB3> INFO: Test took 792ms.
[09:07:56.295] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:07:56.296] <TB3> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[09:07:56.686] <TB3> INFO: PixTestAlive::maskTest() done
[09:07:56.686] <TB3> INFO: number of mask-defect pixels (per ROC): 0
[09:07:56.688] <TB3> INFO: ----------------------------------------------------------------------
[09:07:56.688] <TB3> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[09:07:56.688] <TB3> INFO: ----------------------------------------------------------------------
[09:07:56.712] <TB3> INFO: Expecting 41600 events.
[09:07:57.564] <TB3> INFO: 41600 events read in total (464ms).
[09:07:57.565] <TB3> INFO: Test took 877ms.
[09:07:57.566] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:07:57.952] <TB3> INFO: PixTestAlive::addressDecodingTest() done
[09:07:57.952] <TB3> INFO: number of address-decoding pixels (per ROC): 0
[09:07:57.952] <TB3> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[09:07:57.954] <TB3> INFO: enter test to run
[09:07:57.954] <TB3> INFO: test: Scurves no parameter change
[09:07:57.954] <TB3> INFO: running: scurves
[09:07:57.956] <TB3> INFO: ######################################################################
[09:07:57.956] <TB3> INFO: PixTestScurves::doTest() ntrig = 50
[09:07:57.956] <TB3> INFO: ######################################################################
[09:07:57.956] <TB3> INFO: ----------------------------------------------------------------------
[09:07:57.956] <TB3> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[09:07:57.956] <TB3> INFO: ----------------------------------------------------------------------
[09:07:57.956] <TB3> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[09:07:57.972] <TB3> INFO: dacScan split into 1 runs with ntrig = 50
[09:07:57.972] <TB3> INFO: run 1 of 1
[09:07:57.992] <TB3> INFO: Expecting 41808000 events.
[09:10:27.249] <TB3> INFO: 20006100 events read in total (148870ms).
[09:12:56.256] <TB3> INFO: 39807600 events read in total (297877ms).
[09:13:10.794] <TB3> INFO: 41808000 events read in total (312415ms).
[09:13:10.836] <TB3> INFO: Test took 312864ms.
[09:13:10.883] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:13:12.558] <TB3> INFO: PixTestScurves::scurves() done
[09:13:12.558] <TB3> INFO: Vcal mean: 86.06
[09:13:12.558] <TB3> INFO: Vcal RMS: 5.12
[09:13:12.563] <TB3> INFO: enter test to run
[09:13:12.563] <TB3> INFO: test: Trim no parameter change
[09:13:12.563] <TB3> INFO: running: trim
[09:13:12.565] <TB3> INFO: ######################################################################
[09:13:12.565] <TB3> INFO: PixTestTrim::doTest()
[09:13:12.565] <TB3> INFO: ######################################################################
[09:13:12.566] <TB3> INFO: ----------------------------------------------------------------------
[09:13:12.566] <TB3> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[09:13:12.566] <TB3> INFO: ----------------------------------------------------------------------
[09:13:12.571] <TB3> INFO: ---> VthrComp thr map (minimal VthrComp)
[09:13:12.571] <TB3> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[09:13:12.583] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:13:12.583] <TB3> INFO: run 1 of 1
[09:13:12.606] <TB3> INFO: Expecting 6281600 events.
[09:14:02.932] <TB3> INFO: 6281600 events read in total (49938ms).
[09:14:02.952] <TB3> INFO: Test took 50369ms.
[09:14:02.960] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:14:04.133] <TB3> INFO: ROC 0 VthrComp = 93
[09:14:04.133] <TB3> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[09:14:04.133] <TB3> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[09:14:04.141] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:14:04.141] <TB3> INFO: run 1 of 1
[09:14:04.161] <TB3> INFO: Expecting 6281600 events.
[09:14:56.062] <TB3> INFO: 6281600 events read in total (51514ms).
[09:14:56.115] <TB3> INFO: Test took 51974ms.
[09:14:56.137] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:14:57.462] <TB3> INFO: roc 0 with ID = 0 has maximal Vcal 57.6804 for pixel 11/10 mean/min/max = 45.0938/32.4046/57.7831
[09:14:57.471] <TB3> INFO: Expecting 514560 events.
[09:15:01.655] <TB3> INFO: 514560 events read in total (3797ms).
[09:15:01.661] <TB3> INFO: Test took 4199ms.
[09:15:02.032] <TB3> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[09:15:02.042] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:15:02.042] <TB3> INFO: run 1 of 1
[09:15:02.065] <TB3> INFO: Expecting 6281600 events.
[09:15:54.747] <TB3> INFO: 6281600 events read in total (52295ms).
[09:15:54.800] <TB3> INFO: Test took 52758ms.
[09:15:54.821] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:15:56.093] <TB3> INFO: ---> TrimStepCorr4 extremal thresholds: 13.110736 .. 47.980624
[09:15:56.098] <TB3> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 3 .. 57 (-1/-1) hits flags = 528 (plus default)
[09:15:56.105] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:15:56.105] <TB3> INFO: run 1 of 1
[09:15:56.124] <TB3> INFO: Expecting 2288000 events.
[09:16:13.931] <TB3> INFO: 2288000 events read in total (17419ms).
[09:16:13.944] <TB3> INFO: Test took 17839ms.
[09:16:13.949] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:16:14.811] <TB3> INFO: ---> TrimStepCorr2 extremal thresholds: 20.680842 .. 42.315224
[09:16:14.816] <TB3> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 10 .. 52 (-1/-1) hits flags = 528 (plus default)
[09:16:14.824] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:16:14.824] <TB3> INFO: run 1 of 1
[09:16:14.844] <TB3> INFO: Expecting 1788800 events.
[09:16:29.263] <TB3> INFO: 1788800 events read in total (14032ms).
[09:16:29.271] <TB3> INFO: Test took 14447ms.
[09:16:29.274] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:16:30.059] <TB3> INFO: ---> TrimStepCorr1a extremal thresholds: 25.396967 .. 39.023627
[09:16:30.064] <TB3> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 15 .. 49 (-1/-1) hits flags = 528 (plus default)
[09:16:30.071] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:16:30.071] <TB3> INFO: run 1 of 1
[09:16:30.091] <TB3> INFO: Expecting 1456000 events.
[09:16:41.725] <TB3> INFO: 1456000 events read in total (11247ms).
[09:16:41.732] <TB3> INFO: Test took 11661ms.
[09:16:41.735] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:16:42.495] <TB3> INFO: ---> TrimStepCorr1b extremal thresholds: 27.255636 .. 39.012146
[09:16:42.499] <TB3> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 17 .. 49 (-1/-1) hits flags = 528 (plus default)
[09:16:42.507] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:16:42.507] <TB3> INFO: run 1 of 1
[09:16:42.530] <TB3> INFO: Expecting 1372800 events.
[09:16:53.746] <TB3> INFO: 1372800 events read in total (10829ms).
[09:16:53.753] <TB3> INFO: Test took 11246ms.
[09:16:53.757] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:16:54.516] <TB3> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[09:16:54.516] <TB3> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[09:16:54.524] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:16:54.524] <TB3> INFO: run 1 of 1
[09:16:54.543] <TB3> INFO: Expecting 1705600 events.
[09:17:08.700] <TB3> INFO: 1705600 events read in total (13770ms).
[09:17:08.709] <TB3> INFO: Test took 14185ms.
[09:17:08.714] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:17:09.575] <TB3> INFO: write dac parameters into /home/mameinha/data/R419_Fulltest_m20_2015-10-07_11h06m_1444208776//000_FulltestROC_m20//dacParameters35_C0.dat
[09:17:09.584] <TB3> INFO: write trim parameters into /home/mameinha/data/R419_Fulltest_m20_2015-10-07_11h06m_1444208776//000_FulltestROC_m20//trimParameters35_C0.dat
[09:17:09.595] <TB3> INFO: PixTestTrim::trimTest() done
[09:17:09.595] <TB3> INFO: vtrim: 88
[09:17:09.595] <TB3> INFO: vthrcomp: 93
[09:17:09.595] <TB3> INFO: vcal mean: 34.98
[09:17:09.595] <TB3> INFO: vcal RMS: 0.74
[09:17:09.595] <TB3> INFO: bits mean: 9.47
[09:17:09.595] <TB3> INFO: bits RMS: 2.72
[09:17:09.599] <TB3> INFO: ----------------------------------------------------------------------
[09:17:09.599] <TB3> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[09:17:09.599] <TB3> INFO: ----------------------------------------------------------------------
[09:17:09.599] <TB3> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[09:17:09.607] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:17:09.607] <TB3> INFO: run 1 of 1
[09:17:09.630] <TB3> INFO: Expecting 8320000 events.
[09:18:14.122] <TB3> INFO: 8320000 events read in total (64105ms).
[09:18:14.179] <TB3> INFO: Test took 64572ms.
[09:18:14.199] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:18:15.893] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 149 (-1/-1) hits flags = 528 (plus default)
[09:18:15.902] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:18:15.902] <TB3> INFO: run 1 of 1
[09:18:15.921] <TB3> INFO: Expecting 6240000 events.
[09:19:04.705] <TB3> INFO: 6240000 events read in total (48397ms).
[09:19:04.733] <TB3> INFO: Test took 48831ms.
[09:19:04.746] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:19:06.067] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 135 (-1/-1) hits flags = 528 (plus default)
[09:19:06.075] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:19:06.075] <TB3> INFO: run 1 of 1
[09:19:06.094] <TB3> INFO: Expecting 5657600 events.
[09:19:49.172] <TB3> INFO: 5657600 events read in total (42691ms).
[09:19:49.193] <TB3> INFO: Test took 43118ms.
[09:19:49.203] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:19:50.371] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 135 (-1/-1) hits flags = 528 (plus default)
[09:19:50.378] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:19:50.378] <TB3> INFO: run 1 of 1
[09:19:50.398] <TB3> INFO: Expecting 5657600 events.
[09:20:32.764] <TB3> INFO: 5657600 events read in total (41979ms).
[09:20:32.785] <TB3> INFO: Test took 42407ms.
[09:20:32.795] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:20:33.971] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 134 (-1/-1) hits flags = 528 (plus default)
[09:20:33.979] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:20:33.979] <TB3> INFO: run 1 of 1
[09:20:33.999] <TB3> INFO: Expecting 5616000 events.
[09:21:17.044] <TB3> INFO: 5616000 events read in total (42658ms).
[09:21:17.062] <TB3> INFO: Test took 43083ms.
[09:21:17.072] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:21:18.248] <TB3> INFO: PixTestTrim::trimBitTest() done
[09:21:18.250] <TB3> INFO: PixTestTrim::doTest() done, duration: 485 seconds
[09:21:18.293] <TB3> INFO: enter test to run
[09:21:18.293] <TB3> INFO: test: PhOptimization no parameter change
[09:21:18.293] <TB3> INFO: running: phoptimization
[09:21:18.293] <TB3> INFO: ######################################################################
[09:21:18.293] <TB3> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[09:21:18.293] <TB3> INFO: ######################################################################
[09:21:18.314] <TB3> INFO: Expecting 41600 events.
[09:21:19.150] <TB3> INFO: 41600 events read in total (449ms).
[09:21:19.151] <TB3> INFO: Test took 857ms.
[09:21:19.151] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:21:19.540] <TB3> INFO: Expecting 41600 events.
[09:21:20.404] <TB3> INFO: 41600 events read in total (476ms).
[09:21:20.405] <TB3> INFO: Test took 1252ms.
[09:21:20.405] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:21:20.794] <TB3> INFO: Expecting 41600 events.
[09:21:21.645] <TB3> INFO: 41600 events read in total (464ms).
[09:21:21.645] <TB3> INFO: Test took 1239ms.
[09:21:21.646] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:21:22.033] <TB3> INFO: Expecting 2560 events.
[09:21:22.453] <TB3> INFO: 2560 events read in total (32ms).
[09:21:22.454] <TB3> INFO: Test took 808ms.
[09:21:22.849] <TB3> INFO: Expecting 655360 events.
[09:21:28.350] <TB3> INFO: 655360 events read in total (5114ms).
[09:21:28.359] <TB3> INFO: Test took 5905ms.
[09:21:28.638] <TB3> INFO: Expecting 655360 events.
[09:21:34.105] <TB3> INFO: 655360 events read in total (5080ms).
[09:21:34.113] <TB3> INFO: Test took 5733ms.
[09:21:34.133] <TB3> INFO: safety margin for low PH: adding 0, margin is now 20
[09:21:34.147] <TB3> INFO: write dac parameters into /home/mameinha/data/R419_Fulltest_m20_2015-10-07_11h06m_1444208776//000_FulltestROC_m20//dacParameters35_C0.dat
[09:21:34.401] <TB3> INFO: Expecting 41600 events.
[09:21:35.172] <TB3> INFO: 41600 events read in total (384ms).
[09:21:35.172] <TB3> INFO: Test took 1022ms.
[09:21:35.562] <TB3> INFO: Expecting 41600 events.
[09:21:36.349] <TB3> INFO: 41600 events read in total (400ms).
[09:21:36.350] <TB3> INFO: Test took 1177ms.
[09:21:36.735] <TB3> INFO: Expecting 41600 events.
[09:21:37.547] <TB3> INFO: 41600 events read in total (425ms).
[09:21:37.547] <TB3> INFO: Test took 1197ms.
[09:21:37.925] <TB3> INFO: Expecting 2560 events.
[09:21:38.347] <TB3> INFO: 2560 events read in total (34ms).
[09:21:38.347] <TB3> INFO: Test took 798ms.
[09:21:38.741] <TB3> INFO: Expecting 2560 events.
[09:21:39.163] <TB3> INFO: 2560 events read in total (34ms).
[09:21:39.163] <TB3> INFO: Test took 815ms.
[09:21:39.572] <TB3> INFO: PixTestPhOptimization::doTest() done, duration: 21 seconds
[09:21:39.572] <TB3> INFO: PH scale (per ROC): 80
[09:21:39.572] <TB3> INFO: PH offset (per ROC): 175
[09:21:39.592] <TB3> INFO: enter test to run
[09:21:39.592] <TB3> INFO: test: GainPedestal no parameter change
[09:21:39.592] <TB3> INFO: running: gainpedestal
[09:21:39.594] <TB3> INFO: ######################################################################
[09:21:39.594] <TB3> INFO: PixTestGainPedestal::doTest() ntrig = 10
[09:21:39.594] <TB3> INFO: ######################################################################
[09:21:39.602] <TB3> INFO: scanning low vcal = 10
[09:21:39.622] <TB3> INFO: Expecting 41600 events.
[09:21:40.719] <TB3> INFO: 41600 events read in total (710ms).
[09:21:40.720] <TB3> INFO: Test took 1118ms.
[09:21:40.720] <TB3> INFO: scanning low vcal = 20
[09:21:41.114] <TB3> INFO: Expecting 41600 events.
[09:21:42.208] <TB3> INFO: 41600 events read in total (707ms).
[09:21:42.208] <TB3> INFO: Test took 1488ms.
[09:21:42.209] <TB3> INFO: scanning low vcal = 30
[09:21:42.603] <TB3> INFO: Expecting 41600 events.
[09:21:43.701] <TB3> INFO: 41600 events read in total (710ms).
[09:21:43.702] <TB3> INFO: Test took 1493ms.
[09:21:43.702] <TB3> INFO: scanning low vcal = 40
[09:21:44.096] <TB3> INFO: Expecting 41600 events.
[09:21:45.237] <TB3> INFO: 41600 events read in total (754ms).
[09:21:45.238] <TB3> INFO: Test took 1536ms.
[09:21:45.238] <TB3> INFO: scanning low vcal = 50
[09:21:45.624] <TB3> INFO: Expecting 41600 events.
[09:21:46.807] <TB3> INFO: 41600 events read in total (796ms).
[09:21:46.807] <TB3> INFO: Test took 1569ms.
[09:21:46.808] <TB3> INFO: scanning low vcal = 60
[09:21:47.191] <TB3> INFO: Expecting 41600 events.
[09:21:48.360] <TB3> INFO: 41600 events read in total (782ms).
[09:21:48.361] <TB3> INFO: Test took 1553ms.
[09:21:48.361] <TB3> INFO: scanning low vcal = 70
[09:21:48.745] <TB3> INFO: Expecting 41600 events.
[09:21:49.896] <TB3> INFO: 41600 events read in total (764ms).
[09:21:49.896] <TB3> INFO: Test took 1535ms.
[09:21:49.897] <TB3> INFO: scanning low vcal = 80
[09:21:50.280] <TB3> INFO: Expecting 41600 events.
[09:21:51.458] <TB3> INFO: 41600 events read in total (791ms).
[09:21:51.460] <TB3> INFO: Test took 1563ms.
[09:21:51.461] <TB3> INFO: scanning low vcal = 90
[09:21:51.842] <TB3> INFO: Expecting 41600 events.
[09:21:52.994] <TB3> INFO: 41600 events read in total (765ms).
[09:21:52.995] <TB3> INFO: Test took 1534ms.
[09:21:52.996] <TB3> INFO: scanning low vcal = 100
[09:21:53.380] <TB3> INFO: Expecting 41600 events.
[09:21:54.554] <TB3> INFO: 41600 events read in total (787ms).
[09:21:54.555] <TB3> INFO: Test took 1559ms.
[09:21:54.555] <TB3> INFO: scanning low vcal = 110
[09:21:54.937] <TB3> INFO: Expecting 41600 events.
[09:21:56.084] <TB3> INFO: 41600 events read in total (760ms).
[09:21:56.084] <TB3> INFO: Test took 1529ms.
[09:21:56.085] <TB3> INFO: scanning low vcal = 120
[09:21:56.468] <TB3> INFO: Expecting 41600 events.
[09:21:57.623] <TB3> INFO: 41600 events read in total (768ms).
[09:21:57.624] <TB3> INFO: Test took 1539ms.
[09:21:57.624] <TB3> INFO: scanning low vcal = 130
[09:21:58.006] <TB3> INFO: Expecting 41600 events.
[09:21:59.155] <TB3> INFO: 41600 events read in total (762ms).
[09:21:59.155] <TB3> INFO: Test took 1531ms.
[09:21:59.156] <TB3> INFO: scanning low vcal = 140
[09:21:59.539] <TB3> INFO: Expecting 41600 events.
[09:22:00.686] <TB3> INFO: 41600 events read in total (760ms).
[09:22:00.687] <TB3> INFO: Test took 1531ms.
[09:22:00.688] <TB3> INFO: scanning low vcal = 150
[09:22:01.072] <TB3> INFO: Expecting 41600 events.
[09:22:02.235] <TB3> INFO: 41600 events read in total (775ms).
[09:22:02.236] <TB3> INFO: Test took 1548ms.
[09:22:02.236] <TB3> INFO: scanning low vcal = 160
[09:22:02.619] <TB3> INFO: Expecting 41600 events.
[09:22:03.767] <TB3> INFO: 41600 events read in total (761ms).
[09:22:03.768] <TB3> INFO: Test took 1532ms.
[09:22:03.768] <TB3> INFO: scanning low vcal = 170
[09:22:04.155] <TB3> INFO: Expecting 41600 events.
[09:22:05.304] <TB3> INFO: 41600 events read in total (762ms).
[09:22:05.305] <TB3> INFO: Test took 1537ms.
[09:22:05.305] <TB3> INFO: scanning low vcal = 180
[09:22:05.688] <TB3> INFO: Expecting 41600 events.
[09:22:06.836] <TB3> INFO: 41600 events read in total (761ms).
[09:22:06.836] <TB3> INFO: Test took 1531ms.
[09:22:06.837] <TB3> INFO: scanning low vcal = 190
[09:22:07.221] <TB3> INFO: Expecting 41600 events.
[09:22:08.373] <TB3> INFO: 41600 events read in total (765ms).
[09:22:08.373] <TB3> INFO: Test took 1536ms.
[09:22:08.374] <TB3> INFO: scanning low vcal = 200
[09:22:08.754] <TB3> INFO: Expecting 41600 events.
[09:22:09.904] <TB3> INFO: 41600 events read in total (762ms).
[09:22:09.905] <TB3> INFO: Test took 1531ms.
[09:22:09.905] <TB3> INFO: scanning low vcal = 210
[09:22:10.288] <TB3> INFO: Expecting 41600 events.
[09:22:11.438] <TB3> INFO: 41600 events read in total (763ms).
[09:22:11.438] <TB3> INFO: Test took 1533ms.
[09:22:11.439] <TB3> INFO: scanning low vcal = 220
[09:22:11.827] <TB3> INFO: Expecting 41600 events.
[09:22:12.975] <TB3> INFO: 41600 events read in total (761ms).
[09:22:12.976] <TB3> INFO: Test took 1537ms.
[09:22:12.977] <TB3> INFO: scanning low vcal = 230
[09:22:13.359] <TB3> INFO: Expecting 41600 events.
[09:22:14.527] <TB3> INFO: 41600 events read in total (780ms).
[09:22:14.528] <TB3> INFO: Test took 1551ms.
[09:22:14.528] <TB3> INFO: scanning low vcal = 240
[09:22:14.914] <TB3> INFO: Expecting 41600 events.
[09:22:16.085] <TB3> INFO: 41600 events read in total (784ms).
[09:22:16.085] <TB3> INFO: Test took 1557ms.
[09:22:16.085] <TB3> INFO: scanning low vcal = 250
[09:22:16.468] <TB3> INFO: Expecting 41600 events.
[09:22:17.630] <TB3> INFO: 41600 events read in total (775ms).
[09:22:17.630] <TB3> INFO: Test took 1545ms.
[09:22:17.631] <TB3> INFO: scanning high vcal = 30 (= 210 in low range)
[09:22:18.014] <TB3> INFO: Expecting 41600 events.
[09:22:19.151] <TB3> INFO: 41600 events read in total (750ms).
[09:22:19.151] <TB3> INFO: Test took 1520ms.
[09:22:19.152] <TB3> INFO: scanning high vcal = 50 (= 350 in low range)
[09:22:19.537] <TB3> INFO: Expecting 41600 events.
[09:22:20.666] <TB3> INFO: 41600 events read in total (742ms).
[09:22:20.667] <TB3> INFO: Test took 1515ms.
[09:22:20.667] <TB3> INFO: scanning high vcal = 70 (= 490 in low range)
[09:22:21.056] <TB3> INFO: Expecting 41600 events.
[09:22:22.217] <TB3> INFO: 41600 events read in total (774ms).
[09:22:22.217] <TB3> INFO: Test took 1550ms.
[09:22:22.217] <TB3> INFO: scanning high vcal = 90 (= 630 in low range)
[09:22:22.603] <TB3> INFO: Expecting 41600 events.
[09:22:23.754] <TB3> INFO: 41600 events read in total (764ms).
[09:22:23.754] <TB3> INFO: Test took 1537ms.
[09:22:23.755] <TB3> INFO: scanning high vcal = 200 (= 1400 in low range)
[09:22:24.137] <TB3> INFO: Expecting 41600 events.
[09:22:25.285] <TB3> INFO: 41600 events read in total (761ms).
[09:22:25.286] <TB3> INFO: Test took 1531ms.
[09:22:25.665] <TB3> INFO: PixTestGainPedestal::measure() done
[09:22:28.015] <TB3> INFO: PixTestGainPedestal::fit() done
[09:22:28.015] <TB3> INFO: non-linearity mean: 0.951
[09:22:28.015] <TB3> INFO: non-linearity RMS: 0.007
[09:22:28.018] <TB3> INFO: write gain/ped parameters into /home/mameinha/data/R419_Fulltest_m20_2015-10-07_11h06m_1444208776//000_FulltestROC_m20//phCalibrationFitErr35_C0.dat
[09:22:28.057] <TB3> INFO: PixTestGainPedestal::doTest() done, duration: 48 seconds
[09:22:28.058] <TB3> INFO: enter test to run
[09:22:28.058] <TB3> INFO: test: Readback no parameter change
[09:22:28.058] <TB3> INFO: running: readback
[09:22:28.058] <TB3> INFO: readReadbackCal: /home/mameinha/data/R419_Fulltest_m20_2015-10-07_11h06m_1444208776//000_FulltestROC_m20//readbackCal_C0.dat .. /home/mameinha/data/R419_Fulltest_m20_2015-10-07_11h06m_1444208776//000_FulltestROC_m20//readbackCal_C0.dat
[09:22:28.059] <TB3> INFO: ######################################################################
[09:22:28.059] <TB3> INFO: PixTestReadback::doTest()
[09:22:28.059] <TB3> INFO: ######################################################################
[09:22:28.060] <TB3> INFO: PixTestReadback::RES sent once
[09:22:39.210] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R419_Fulltest_m20_2015-10-07_11h06m_1444208776//000_FulltestROC_m20//readbackCal_C0.dat
[09:22:39.218] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[09:22:39.219] <TB3> INFO: PixTestReadback::RES sent once
[09:22:50.338] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R419_Fulltest_m20_2015-10-07_11h06m_1444208776//000_FulltestROC_m20//readbackCal_C0.dat
[09:22:50.346] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[09:22:50.347] <TB3> INFO: PixTestReadback::RES sent once
[09:22:58.684] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[09:22:58.684] <TB3> INFO: Vbg will be calibrated using Vd calibration
[09:22:58.684] <TB3> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 152.2calibrated Vbg = 1.22533 :::*/*/*/*/
[09:22:59.060] <TB3> INFO: PixTestReadback::RES sent once
[09:23:07.935] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R419_Fulltest_m20_2015-10-07_11h06m_1444208776//000_FulltestROC_m20//readbackCal_C0.dat
[09:23:07.940] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[09:23:07.940] <TB3> INFO: PixTestReadback::doTest() done
[09:23:07.973] <TB3> INFO: enter test to run
[09:23:07.973] <TB3> INFO: test: no parameter change
[09:23:08.303] <TB3> QUIET: Connection to board 71 closed.
[09:23:08.382] <TB3> INFO: pXar: this is the end, my friend