[13:48:02.669] <TB3> INFO: *** Welcome to pxar ***
[13:48:02.669] <TB3> INFO: *** Today: 2015/10/07
[13:48:02.736] <TB3> INFO: *** Version: 9da6
[13:48:02.737] <TB3> INFO: readRocDacs: /home/mameinha/data/R422_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//dacParameters_C0.dat .. /home/mameinha/data/R422_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//dacParameters_C0.dat
[13:48:02.737] <TB3> INFO: readTbmDacs: /home/mameinha/data/R422_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//tbmParameters_C0a.dat .. /home/mameinha/data/R422_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//tbmParameters_C4294967295b.dat
[13:48:02.737] <TB3> INFO: readMaskFile: /home/mameinha/data/R422_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//defaultMaskFile.dat
[13:48:02.738] <TB3> INFO: readTrimFile: /home/mameinha/data/R422_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//trimParameters_C0.dat .. /home/mameinha/data/R422_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//trimParameters_C0.dat
[13:48:02.747] <TB3> INFO: clk: 2
[13:48:02.747] <TB3> INFO: ctr: 2
[13:48:02.747] <TB3> INFO: sda: 17
[13:48:02.747] <TB3> INFO: tin: 7
[13:48:02.747] <TB3> INFO: level: 15
[13:48:02.747] <TB3> INFO: deser160phase: 4
[13:48:02.747] <TB3> QUIET: Instanciating API for pxar v2.6.0+20~g1a7f656
[13:48:02.747] <TB3> INFO: Log level: INFO
[13:48:02.753] <TB3> INFO: Found DTB DTB_WRQ4OZ
[13:48:02.763] <TB3> QUIET: Connection to board DTB_WRQ4OZ opened.
[13:48:02.767] <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:
------------------------------------------------------
[13:48:02.769] <TB3> INFO: RPC call hashes of host and DTB match: 398089610
[13:48:03.937] <TB3> INFO: DUT info:
[13:48:03.937] <TB3> INFO: The DUT currently contains the following objects:
[13:48:03.938] <TB3> INFO: 0 TBM Cores (0 ON)
[13:48:03.938] <TB3> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[13:48:03.938] <TB3> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[13:48:04.383] <TB3> INFO: enter 'restricted' command line mode
[13:48:04.383] <TB3> INFO: enter test to run
[13:48:04.385] <TB3> INFO: test: Setup no parameter change
[13:48:04.385] <TB3> INFO: running: setup
[13:48:04.389] <TB3> INFO: PixTestSetup::doTest() ntrig = 10

[13:48:04.389] <TB3> INFO: PixTestSetup:: pg set to RES|TOK
[13:48:04.389] <TB3> INFO: 0 1 2 3 4 5 6 7
[13:48:07.433] <TB3> INFO: 0: 000 000 004 07c 7f0 f00 000 000
[13:48:10.447] <TB3> INFO: 1: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[13:48:13.461] <TB3> INFO: 2: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[13:48:16.476] <TB3> INFO: 3: 000 000 004 07c <7f8>[*] f80 800 000
[13:48:19.490] <TB3> INFO: 4: 000 000 000 03c 3f8 f80 800 000
[13:48:22.504] <TB3> INFO: 5: 000 000 000 03c 3f8 f80 800 000
[13:48:25.519] <TB3> INFO: 6: 000 000 000 03c 3fc fc0 c00 000
[13:48:28.533] <TB3> INFO: 7: 000 000 000 03c 3fc fc0 c00 000
[13:48:31.548] <TB3> INFO: 8: 000 000 000 03c 3fc fc0 c00 000
[13:48:34.562] <TB3> INFO: 9: 000 000 000 03c 3fc fc0 c00 000
[13:48:37.577] <TB3> INFO: 10: 000 000 000 01c 1fc fc0 c00 000
[13:48:40.592] <TB3> INFO: 11: 000 000 000 01c 1fc fe0 e00 000
[13:48:43.606] <TB3> INFO: 12: 000 000 000 01c 1fc fe0 e00 000
[13:48:46.621] <TB3> INFO: 13: e00 000 000 01c 1fc fe0 e00 000
[13:48:49.635] <TB3> INFO: 14: 000 000 000 00c 0fc fe0 e00 000
[13:48:52.649] <TB3> INFO: 15: 000 000 000 00c 0fc fe0 e00 000
[13:48:55.664] <TB3> INFO: 16: 000 000 000 00c 0fc ff0 f00 000
[13:48:58.679] <TB3> INFO: 17: 000 000 000 00c 0fc ff0 f00 000
[13:49:01.693] <TB3> INFO: 18: 000 000 000 00c 0fc ff0 f00 000
[13:49:04.707] <TB3> INFO: 19: 000 000 000 00c 0fc ff0 f00 000
[13:49:05.137] <TB3> INFO: Found good delays at CLK = 2, DESER160 = 4
[13:49:05.138] <TB3> INFO: PixTestSetup:: Write Tb parameters to file.
[13:49:05.148] <TB3> INFO: write dtb parameters into /home/mameinha/data/R422_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//tbParameters.dat
[13:49:05.151] <TB3> INFO: PixTestSetup::doTest() done for.
[13:49:05.186] <TB3> INFO: enter test to run
[13:49:05.186] <TB3> INFO: test: Pretest no parameter change
[13:49:05.186] <TB3> INFO: running: pretest
[13:49:05.188] <TB3> INFO: ----------------------------------------------------------------------
[13:49:05.188] <TB3> INFO: PixTestPretest::programROC()
[13:49:05.188] <TB3> INFO: ----------------------------------------------------------------------
[13:49:08.191] <TB3> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[13:49:08.191] <TB3> INFO: IA differences per ROC: 18.5
[13:49:08.196] <TB3> INFO: enter test to run
[13:49:08.196] <TB3> INFO: test: Pretest no parameter change
[13:49:08.196] <TB3> INFO: running: pretest
[13:49:08.197] <TB3> INFO: ----------------------------------------------------------------------
[13:49:08.197] <TB3> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[13:49:08.197] <TB3> INFO: ----------------------------------------------------------------------
[13:49:08.708] <TB3> INFO: PixTestPretest::setVana() done, Module Ia 23.3 mA = 23.3 mA/ROC
[13:49:08.708] <TB3> INFO: i(loss) [mA/ROC]: 19.3
[13:49:08.711] <TB3> INFO: enter test to run
[13:49:08.711] <TB3> INFO: test: Pretest no parameter change
[13:49:08.711] <TB3> INFO: running: pretest
[13:49:08.713] <TB3> INFO: ----------------------------------------------------------------------
[13:49:08.713] <TB3> INFO: PixTestPretest::findWorkingPixel()
[13:49:08.713] <TB3> INFO: ----------------------------------------------------------------------
[13:49:08.723] <TB3> INFO: Expecting 231680 events.
[13:49:10.922] <TB3> INFO: 231680 events read in total (1812ms).
[13:49:10.924] <TB3> INFO: Test took 2211ms.
[13:49:11.303] <TB3> INFO: Found working pixel in all ROCs: col/row = 12/22
[13:49:11.310] <TB3> INFO: enter test to run
[13:49:11.310] <TB3> INFO: test: Pretest no parameter change
[13:49:11.310] <TB3> INFO: running: pretest
[13:49:11.311] <TB3> INFO: ----------------------------------------------------------------------
[13:49:11.311] <TB3> INFO: PixTestPretest::setVthrCompCalDel()
[13:49:11.311] <TB3> INFO: ----------------------------------------------------------------------
[13:49:11.320] <TB3> INFO: Expecting 231680 events.
[13:49:13.547] <TB3> INFO: 231680 events read in total (1840ms).
[13:49:13.551] <TB3> INFO: Test took 2239ms.
[13:49:13.925] <TB3> INFO: PixTestPretest::setVthrCompCalDel() done
[13:49:13.925] <TB3> INFO: CalDel: 145
[13:49:13.925] <TB3> INFO: VthrComp: 51
[13:49:13.930] <TB3> INFO: enter test to run
[13:49:13.930] <TB3> INFO: test: Pretest no parameter change
[13:49:13.930] <TB3> INFO: running: pretest
[13:49:13.934] <TB3> INFO: write dac parameters into /home/mameinha/data/R422_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//dacParameters_C0.dat
[13:49:13.938] <TB3> INFO: enter test to run
[13:49:13.938] <TB3> INFO: test: PixelAlive no parameter change
[13:49:13.938] <TB3> INFO: running: pixelalive
[13:49:13.940] <TB3> INFO: ######################################################################
[13:49:13.940] <TB3> INFO: PixTestAlive::doTest()
[13:49:13.940] <TB3> INFO: ######################################################################
[13:49:13.941] <TB3> INFO: ----------------------------------------------------------------------
[13:49:13.941] <TB3> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[13:49:13.941] <TB3> INFO: ----------------------------------------------------------------------
[13:49:13.962] <TB3> INFO: Expecting 41600 events.
[13:49:14.766] <TB3> INFO: 41600 events read in total (417ms).
[13:49:14.767] <TB3> INFO: Test took 825ms.
[13:49:14.767] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:15.153] <TB3> INFO: PixTestAlive::aliveTest() done
[13:49:15.153] <TB3> INFO: number of dead pixels (per ROC): 0
[13:49:15.154] <TB3> INFO: ----------------------------------------------------------------------
[13:49:15.154] <TB3> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[13:49:15.154] <TB3> INFO: ----------------------------------------------------------------------
[13:49:15.176] <TB3> INFO: Expecting 41600 events.
[13:49:15.924] <TB3> INFO: 41600 events read in total (361ms).
[13:49:15.924] <TB3> INFO: Test took 769ms.
[13:49:15.924] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:15.924] <TB3> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[13:49:16.314] <TB3> INFO: PixTestAlive::maskTest() done
[13:49:16.314] <TB3> INFO: number of mask-defect pixels (per ROC): 0
[13:49:16.316] <TB3> INFO: ----------------------------------------------------------------------
[13:49:16.316] <TB3> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[13:49:16.316] <TB3> INFO: ----------------------------------------------------------------------
[13:49:16.336] <TB3> INFO: Expecting 41600 events.
[13:49:17.139] <TB3> INFO: 41600 events read in total (416ms).
[13:49:17.140] <TB3> INFO: Test took 824ms.
[13:49:17.140] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:17.525] <TB3> INFO: PixTestAlive::addressDecodingTest() done
[13:49:17.525] <TB3> INFO: number of address-decoding pixels (per ROC): 0
[13:49:17.525] <TB3> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[13:49:17.526] <TB3> INFO: enter test to run
[13:49:17.527] <TB3> INFO: test: Scurves no parameter change
[13:49:17.527] <TB3> INFO: running: scurves
[13:49:17.529] <TB3> INFO: ######################################################################
[13:49:17.529] <TB3> INFO: PixTestScurves::doTest() ntrig = 50
[13:49:17.529] <TB3> INFO: ######################################################################
[13:49:17.529] <TB3> INFO: ----------------------------------------------------------------------
[13:49:17.529] <TB3> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[13:49:17.529] <TB3> INFO: ----------------------------------------------------------------------
[13:49:17.529] <TB3> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[13:49:17.540] <TB3> INFO: dacScan split into 1 runs with ntrig = 50
[13:49:17.540] <TB3> INFO: run 1 of 1
[13:49:17.560] <TB3> INFO: Expecting 41808000 events.
[13:51:46.251] <TB3> INFO: 20257800 events read in total (148304ms).
[13:54:12.817] <TB3> INFO: 40228700 events read in total (294870ms).
[13:54:24.453] <TB3> INFO: 41808000 events read in total (306506ms).
[13:54:24.490] <TB3> INFO: Test took 306950ms.
[13:54:24.519] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:54:26.255] <TB3> INFO: PixTestScurves::scurves() done
[13:54:26.255] <TB3> INFO: Vcal mean: 88.24
[13:54:26.255] <TB3> INFO: Vcal RMS: 5.30
[13:54:26.263] <TB3> INFO: enter test to run
[13:54:26.263] <TB3> INFO: test: Trim no parameter change
[13:54:26.263] <TB3> INFO: running: trim
[13:54:26.265] <TB3> INFO: ######################################################################
[13:54:26.265] <TB3> INFO: PixTestTrim::doTest()
[13:54:26.265] <TB3> INFO: ######################################################################
[13:54:26.267] <TB3> INFO: ----------------------------------------------------------------------
[13:54:26.267] <TB3> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[13:54:26.267] <TB3> INFO: ----------------------------------------------------------------------
[13:54:26.272] <TB3> INFO: ---> VthrComp thr map (minimal VthrComp)
[13:54:26.272] <TB3> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[13:54:26.280] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:54:26.280] <TB3> INFO: run 1 of 1
[13:54:26.299] <TB3> INFO: Expecting 6281600 events.
[13:55:13.224] <TB3> INFO: 6281600 events read in total (46504ms).
[13:55:13.242] <TB3> INFO: Test took 46962ms.
[13:55:13.250] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:55:14.415] <TB3> INFO: ROC 0 VthrComp = 89
[13:55:14.415] <TB3> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[13:55:14.415] <TB3> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[13:55:14.423] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:55:14.423] <TB3> INFO: run 1 of 1
[13:55:14.443] <TB3> INFO: Expecting 6281600 events.
[13:56:05.782] <TB3> INFO: 6281600 events read in total (50952ms).
[13:56:05.851] <TB3> INFO: Test took 51428ms.
[13:56:05.878] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:56:07.335] <TB3> INFO: roc 0 with ID = 0 has maximal Vcal 59.5602 for pixel 36/61 mean/min/max = 46.3978/33.2116/59.5841
[13:56:07.344] <TB3> INFO: Expecting 514560 events.
[13:56:11.473] <TB3> INFO: 514560 events read in total (3742ms).
[13:56:11.477] <TB3> INFO: Test took 4142ms.
[13:56:11.871] <TB3> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[13:56:11.878] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:56:11.878] <TB3> INFO: run 1 of 1
[13:56:11.898] <TB3> INFO: Expecting 6281600 events.
[13:57:03.251] <TB3> INFO: 6281600 events read in total (50966ms).
[13:57:03.310] <TB3> INFO: Test took 51432ms.
[13:57:03.338] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:57:04.946] <TB3> INFO: ---> TrimStepCorr4 extremal thresholds: 1.787414 .. 48.748348
[13:57:04.951] <TB3> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 1 .. 58 (-1/-1) hits flags = 528 (plus default)
[13:57:04.959] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:57:04.959] <TB3> INFO: run 1 of 1
[13:57:04.978] <TB3> INFO: Expecting 2412800 events.
[13:57:24.012] <TB3> INFO: 2412800 events read in total (18647ms).
[13:57:24.022] <TB3> INFO: Test took 19063ms.
[13:57:24.027] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:57:24.860] <TB3> INFO: ---> TrimStepCorr2 extremal thresholds: 21.366556 .. 44.181935
[13:57:24.864] <TB3> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 11 .. 54 (-1/-1) hits flags = 528 (plus default)
[13:57:24.872] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:57:24.872] <TB3> INFO: run 1 of 1
[13:57:24.891] <TB3> INFO: Expecting 1830400 events.
[13:57:39.655] <TB3> INFO: 1830400 events read in total (14376ms).
[13:57:39.663] <TB3> INFO: Test took 14791ms.
[13:57:39.667] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:57:40.474] <TB3> INFO: ---> TrimStepCorr1a extremal thresholds: 26.148696 .. 39.617614
[13:57:40.478] <TB3> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 16 .. 49 (-1/-1) hits flags = 528 (plus default)
[13:57:40.486] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:57:40.486] <TB3> INFO: run 1 of 1
[13:57:40.505] <TB3> INFO: Expecting 1414400 events.
[13:57:52.090] <TB3> INFO: 1414400 events read in total (11198ms).
[13:57:52.096] <TB3> INFO: Test took 11610ms.
[13:57:52.099] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:57:52.869] <TB3> INFO: ---> TrimStepCorr1b extremal thresholds: 28.845512 .. 39.617614
[13:57:52.874] <TB3> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 18 .. 49 (-1/-1) hits flags = 528 (plus default)
[13:57:52.882] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:57:52.882] <TB3> INFO: run 1 of 1
[13:57:52.901] <TB3> INFO: Expecting 1331200 events.
[13:58:03.804] <TB3> INFO: 1331200 events read in total (10516ms).
[13:58:03.810] <TB3> INFO: Test took 10928ms.
[13:58:03.813] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:58:04.580] <TB3> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[13:58:04.580] <TB3> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[13:58:04.588] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:58:04.588] <TB3> INFO: run 1 of 1
[13:58:04.608] <TB3> INFO: Expecting 1705600 events.
[13:58:18.565] <TB3> INFO: 1705600 events read in total (13570ms).
[13:58:18.574] <TB3> INFO: Test took 13986ms.
[13:58:18.578] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:58:19.407] <TB3> INFO: write dac parameters into /home/mameinha/data/R422_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//dacParameters35_C0.dat
[13:58:19.411] <TB3> INFO: write trim parameters into /home/mameinha/data/R422_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//trimParameters35_C0.dat
[13:58:19.423] <TB3> INFO: PixTestTrim::trimTest() done
[13:58:19.423] <TB3> INFO: vtrim: 96
[13:58:19.423] <TB3> INFO: vthrcomp: 89
[13:58:19.423] <TB3> INFO: vcal mean: 34.96
[13:58:19.423] <TB3> INFO: vcal RMS: 0.79
[13:58:19.423] <TB3> INFO: bits mean: 9.16
[13:58:19.423] <TB3> INFO: bits RMS: 2.70
[13:58:19.427] <TB3> INFO: ----------------------------------------------------------------------
[13:58:19.427] <TB3> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[13:58:19.427] <TB3> INFO: ----------------------------------------------------------------------
[13:58:19.427] <TB3> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[13:58:19.435] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:58:19.435] <TB3> INFO: run 1 of 1
[13:58:19.456] <TB3> INFO: Expecting 8320000 events.
[13:59:24.041] <TB3> INFO: 8320000 events read in total (64198ms).
[13:59:24.081] <TB3> INFO: Test took 64646ms.
[13:59:24.097] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:59:25.771] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 154 (-1/-1) hits flags = 528 (plus default)
[13:59:25.778] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[13:59:25.778] <TB3> INFO: run 1 of 1
[13:59:25.798] <TB3> INFO: Expecting 6448000 events.
[14:00:14.607] <TB3> INFO: 6448000 events read in total (48422ms).
[14:00:14.628] <TB3> INFO: Test took 48849ms.
[14:00:14.639] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:00:16.229] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 143 (-1/-1) hits flags = 528 (plus default)
[14:00:16.239] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[14:00:16.239] <TB3> INFO: run 1 of 1
[14:00:16.259] <TB3> INFO: Expecting 5990400 events.
[14:01:01.423] <TB3> INFO: 5990400 events read in total (44777ms).
[14:01:01.444] <TB3> INFO: Test took 45205ms.
[14:01:01.453] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:01:02.666] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 142 (-1/-1) hits flags = 528 (plus default)
[14:01:02.674] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[14:01:02.674] <TB3> INFO: run 1 of 1
[14:01:02.693] <TB3> INFO: Expecting 5948800 events.
[14:01:47.918] <TB3> INFO: 5948800 events read in total (44838ms).
[14:01:47.937] <TB3> INFO: Test took 45263ms.
[14:01:47.946] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:01:49.165] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 143 (-1/-1) hits flags = 528 (plus default)
[14:01:49.173] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[14:01:49.173] <TB3> INFO: run 1 of 1
[14:01:49.195] <TB3> INFO: Expecting 5990400 events.
[14:02:34.536] <TB3> INFO: 5990400 events read in total (44954ms).
[14:02:34.555] <TB3> INFO: Test took 45382ms.
[14:02:34.564] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:02:35.882] <TB3> INFO: PixTestTrim::trimBitTest() done
[14:02:35.884] <TB3> INFO: PixTestTrim::doTest() done, duration: 489 seconds
[14:02:35.936] <TB3> INFO: enter test to run
[14:02:35.936] <TB3> INFO: test: PhOptimization no parameter change
[14:02:35.936] <TB3> INFO: running: phoptimization
[14:02:35.936] <TB3> INFO: ######################################################################
[14:02:35.936] <TB3> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[14:02:35.936] <TB3> INFO: ######################################################################
[14:02:35.957] <TB3> INFO: Expecting 41600 events.
[14:02:36.807] <TB3> INFO: 41600 events read in total (463ms).
[14:02:36.807] <TB3> INFO: Test took 869ms.
[14:02:36.807] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:02:37.198] <TB3> INFO: Expecting 41600 events.
[14:02:38.025] <TB3> INFO: 41600 events read in total (440ms).
[14:02:38.025] <TB3> INFO: Test took 1216ms.
[14:02:38.025] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:02:38.414] <TB3> INFO: Expecting 41600 events.
[14:02:39.238] <TB3> INFO: 41600 events read in total (437ms).
[14:02:39.238] <TB3> INFO: Test took 1212ms.
[14:02:39.239] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:02:39.627] <TB3> INFO: Expecting 2560 events.
[14:02:40.049] <TB3> INFO: 2560 events read in total (35ms).
[14:02:40.049] <TB3> INFO: Test took 810ms.
[14:02:40.444] <TB3> INFO: Expecting 655360 events.
[14:02:45.945] <TB3> INFO: 655360 events read in total (5114ms).
[14:02:45.958] <TB3> INFO: Test took 5908ms.
[14:02:46.189] <TB3> INFO: Expecting 655360 events.
[14:02:51.668] <TB3> INFO: 655360 events read in total (5092ms).
[14:02:51.680] <TB3> INFO: Test took 5705ms.
[14:02:51.700] <TB3> INFO: safety margin for low PH: adding 0, margin is now 20
[14:02:51.718] <TB3> INFO: write dac parameters into /home/mameinha/data/R422_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//dacParameters35_C0.dat
[14:02:51.928] <TB3> INFO: Expecting 41600 events.
[14:02:52.730] <TB3> INFO: 41600 events read in total (415ms).
[14:02:52.731] <TB3> INFO: Test took 1010ms.
[14:02:53.116] <TB3> INFO: Expecting 41600 events.
[14:02:53.905] <TB3> INFO: 41600 events read in total (401ms).
[14:02:53.906] <TB3> INFO: Test took 1175ms.
[14:02:54.288] <TB3> INFO: Expecting 41600 events.
[14:02:55.076] <TB3> INFO: 41600 events read in total (400ms).
[14:02:55.077] <TB3> INFO: Test took 1170ms.
[14:02:55.461] <TB3> INFO: Expecting 2560 events.
[14:02:55.883] <TB3> INFO: 2560 events read in total (35ms).
[14:02:55.883] <TB3> INFO: Test took 805ms.
[14:02:56.277] <TB3> INFO: Expecting 2560 events.
[14:02:56.698] <TB3> INFO: 2560 events read in total (34ms).
[14:02:56.699] <TB3> INFO: Test took 816ms.
[14:02:57.107] <TB3> INFO: PixTestPhOptimization::doTest() done, duration: 21 seconds
[14:02:57.107] <TB3> INFO: PH scale (per ROC): 81
[14:02:57.107] <TB3> INFO: PH offset (per ROC): 169
[14:02:57.129] <TB3> INFO: enter test to run
[14:02:57.129] <TB3> INFO: test: GainPedestal no parameter change
[14:02:57.129] <TB3> INFO: running: gainpedestal
[14:02:57.131] <TB3> INFO: ######################################################################
[14:02:57.131] <TB3> INFO: PixTestGainPedestal::doTest() ntrig = 10
[14:02:57.131] <TB3> INFO: ######################################################################
[14:02:57.140] <TB3> INFO: scanning low vcal = 10
[14:02:57.159] <TB3> INFO: Expecting 41600 events.
[14:02:58.256] <TB3> INFO: 41600 events read in total (710ms).
[14:02:58.257] <TB3> INFO: Test took 1117ms.
[14:02:58.257] <TB3> INFO: scanning low vcal = 20
[14:02:58.651] <TB3> INFO: Expecting 41600 events.
[14:02:59.748] <TB3> INFO: 41600 events read in total (710ms).
[14:02:59.748] <TB3> INFO: Test took 1491ms.
[14:02:59.749] <TB3> INFO: scanning low vcal = 30
[14:03:00.143] <TB3> INFO: Expecting 41600 events.
[14:03:01.235] <TB3> INFO: 41600 events read in total (705ms).
[14:03:01.235] <TB3> INFO: Test took 1486ms.
[14:03:01.236] <TB3> INFO: scanning low vcal = 40
[14:03:01.630] <TB3> INFO: Expecting 41600 events.
[14:03:02.765] <TB3> INFO: 41600 events read in total (747ms).
[14:03:02.765] <TB3> INFO: Test took 1529ms.
[14:03:02.766] <TB3> INFO: scanning low vcal = 50
[14:03:03.150] <TB3> INFO: Expecting 41600 events.
[14:03:04.280] <TB3> INFO: 41600 events read in total (742ms).
[14:03:04.281] <TB3> INFO: Test took 1515ms.
[14:03:04.281] <TB3> INFO: scanning low vcal = 60
[14:03:04.669] <TB3> INFO: Expecting 41600 events.
[14:03:05.807] <TB3> INFO: 41600 events read in total (750ms).
[14:03:05.807] <TB3> INFO: Test took 1526ms.
[14:03:05.808] <TB3> INFO: scanning low vcal = 70
[14:03:06.196] <TB3> INFO: Expecting 41600 events.
[14:03:07.333] <TB3> INFO: 41600 events read in total (750ms).
[14:03:07.334] <TB3> INFO: Test took 1526ms.
[14:03:07.334] <TB3> INFO: scanning low vcal = 80
[14:03:07.723] <TB3> INFO: Expecting 41600 events.
[14:03:08.880] <TB3> INFO: 41600 events read in total (770ms).
[14:03:08.881] <TB3> INFO: Test took 1547ms.
[14:03:08.881] <TB3> INFO: scanning low vcal = 90
[14:03:09.265] <TB3> INFO: Expecting 41600 events.
[14:03:10.423] <TB3> INFO: 41600 events read in total (771ms).
[14:03:10.423] <TB3> INFO: Test took 1542ms.
[14:03:10.424] <TB3> INFO: scanning low vcal = 100
[14:03:10.809] <TB3> INFO: Expecting 41600 events.
[14:03:11.978] <TB3> INFO: 41600 events read in total (782ms).
[14:03:11.979] <TB3> INFO: Test took 1555ms.
[14:03:11.979] <TB3> INFO: scanning low vcal = 110
[14:03:12.364] <TB3> INFO: Expecting 41600 events.
[14:03:13.530] <TB3> INFO: 41600 events read in total (779ms).
[14:03:13.530] <TB3> INFO: Test took 1551ms.
[14:03:13.531] <TB3> INFO: scanning low vcal = 120
[14:03:13.916] <TB3> INFO: Expecting 41600 events.
[14:03:15.056] <TB3> INFO: 41600 events read in total (753ms).
[14:03:15.057] <TB3> INFO: Test took 1526ms.
[14:03:15.057] <TB3> INFO: scanning low vcal = 130
[14:03:15.442] <TB3> INFO: Expecting 41600 events.
[14:03:16.588] <TB3> INFO: 41600 events read in total (759ms).
[14:03:16.588] <TB3> INFO: Test took 1531ms.
[14:03:16.589] <TB3> INFO: scanning low vcal = 140
[14:03:16.974] <TB3> INFO: Expecting 41600 events.
[14:03:18.110] <TB3> INFO: 41600 events read in total (749ms).
[14:03:18.111] <TB3> INFO: Test took 1522ms.
[14:03:18.112] <TB3> INFO: scanning low vcal = 150
[14:03:18.496] <TB3> INFO: Expecting 41600 events.
[14:03:19.653] <TB3> INFO: 41600 events read in total (770ms).
[14:03:19.654] <TB3> INFO: Test took 1542ms.
[14:03:19.654] <TB3> INFO: scanning low vcal = 160
[14:03:20.039] <TB3> INFO: Expecting 41600 events.
[14:03:21.193] <TB3> INFO: 41600 events read in total (767ms).
[14:03:21.194] <TB3> INFO: Test took 1540ms.
[14:03:21.194] <TB3> INFO: scanning low vcal = 170
[14:03:21.575] <TB3> INFO: Expecting 41600 events.
[14:03:22.740] <TB3> INFO: 41600 events read in total (778ms).
[14:03:22.741] <TB3> INFO: Test took 1547ms.
[14:03:22.741] <TB3> INFO: scanning low vcal = 180
[14:03:23.126] <TB3> INFO: Expecting 41600 events.
[14:03:24.264] <TB3> INFO: 41600 events read in total (750ms).
[14:03:24.265] <TB3> INFO: Test took 1524ms.
[14:03:24.265] <TB3> INFO: scanning low vcal = 190
[14:03:24.654] <TB3> INFO: Expecting 41600 events.
[14:03:25.805] <TB3> INFO: 41600 events read in total (764ms).
[14:03:25.805] <TB3> INFO: Test took 1540ms.
[14:03:25.806] <TB3> INFO: scanning low vcal = 200
[14:03:26.189] <TB3> INFO: Expecting 41600 events.
[14:03:27.344] <TB3> INFO: 41600 events read in total (768ms).
[14:03:27.344] <TB3> INFO: Test took 1538ms.
[14:03:27.345] <TB3> INFO: scanning low vcal = 210
[14:03:27.726] <TB3> INFO: Expecting 41600 events.
[14:03:28.882] <TB3> INFO: 41600 events read in total (768ms).
[14:03:28.883] <TB3> INFO: Test took 1538ms.
[14:03:28.883] <TB3> INFO: scanning low vcal = 220
[14:03:29.270] <TB3> INFO: Expecting 41600 events.
[14:03:30.423] <TB3> INFO: 41600 events read in total (766ms).
[14:03:30.424] <TB3> INFO: Test took 1541ms.
[14:03:30.424] <TB3> INFO: scanning low vcal = 230
[14:03:30.804] <TB3> INFO: Expecting 41600 events.
[14:03:31.973] <TB3> INFO: 41600 events read in total (782ms).
[14:03:31.974] <TB3> INFO: Test took 1550ms.
[14:03:31.974] <TB3> INFO: scanning low vcal = 240
[14:03:32.356] <TB3> INFO: Expecting 41600 events.
[14:03:33.517] <TB3> INFO: 41600 events read in total (774ms).
[14:03:33.518] <TB3> INFO: Test took 1544ms.
[14:03:33.518] <TB3> INFO: scanning low vcal = 250
[14:03:33.904] <TB3> INFO: Expecting 41600 events.
[14:03:35.066] <TB3> INFO: 41600 events read in total (775ms).
[14:03:35.067] <TB3> INFO: Test took 1549ms.
[14:03:35.067] <TB3> INFO: scanning high vcal = 30 (= 210 in low range)
[14:03:35.451] <TB3> INFO: Expecting 41600 events.
[14:03:36.612] <TB3> INFO: 41600 events read in total (773ms).
[14:03:36.613] <TB3> INFO: Test took 1546ms.
[14:03:36.614] <TB3> INFO: scanning high vcal = 50 (= 350 in low range)
[14:03:37.000] <TB3> INFO: Expecting 41600 events.
[14:03:38.164] <TB3> INFO: 41600 events read in total (777ms).
[14:03:38.165] <TB3> INFO: Test took 1551ms.
[14:03:38.165] <TB3> INFO: scanning high vcal = 70 (= 490 in low range)
[14:03:38.551] <TB3> INFO: Expecting 41600 events.
[14:03:39.703] <TB3> INFO: 41600 events read in total (765ms).
[14:03:39.703] <TB3> INFO: Test took 1538ms.
[14:03:39.704] <TB3> INFO: scanning high vcal = 90 (= 630 in low range)
[14:03:40.084] <TB3> INFO: Expecting 41600 events.
[14:03:41.220] <TB3> INFO: 41600 events read in total (749ms).
[14:03:41.220] <TB3> INFO: Test took 1516ms.
[14:03:41.221] <TB3> INFO: scanning high vcal = 200 (= 1400 in low range)
[14:03:41.606] <TB3> INFO: Expecting 41600 events.
[14:03:42.778] <TB3> INFO: 41600 events read in total (785ms).
[14:03:42.779] <TB3> INFO: Test took 1558ms.
[14:03:43.162] <TB3> INFO: PixTestGainPedestal::measure() done
[14:03:45.270] <TB3> INFO: PixTestGainPedestal::fit() done
[14:03:45.270] <TB3> INFO: non-linearity mean: 0.962
[14:03:45.270] <TB3> INFO: non-linearity RMS: 0.005
[14:03:45.270] <TB3> INFO: write gain/ped parameters into /home/mameinha/data/R422_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//phCalibrationFitErr35_C0.dat
[14:03:45.317] <TB3> INFO: PixTestGainPedestal::doTest() done, duration: 48 seconds
[14:03:45.318] <TB3> INFO: enter test to run
[14:03:45.318] <TB3> INFO: test: Readback no parameter change
[14:03:45.318] <TB3> INFO: running: readback
[14:03:45.318] <TB3> INFO: readReadbackCal: /home/mameinha/data/R422_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//readbackCal_C0.dat .. /home/mameinha/data/R422_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//readbackCal_C0.dat
[14:03:45.319] <TB3> INFO: ######################################################################
[14:03:45.319] <TB3> INFO: PixTestReadback::doTest()
[14:03:45.319] <TB3> INFO: ######################################################################
[14:03:45.320] <TB3> INFO: PixTestReadback::RES sent once
[14:03:56.484] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R422_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//readbackCal_C0.dat
[14:03:56.622] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[14:03:56.622] <TB3> INFO: PixTestReadback::RES sent once
[14:04:07.768] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R422_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//readbackCal_C0.dat
[14:04:07.818] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[14:04:07.819] <TB3> INFO: PixTestReadback::RES sent once
[14:04:16.156] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[14:04:16.157] <TB3> INFO: Vbg will be calibrated using Vd calibration
[14:04:16.157] <TB3> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 155.1calibrated Vbg = 1.22237 :::*/*/*/*/
[14:04:16.533] <TB3> INFO: PixTestReadback::RES sent once
[14:04:25.404] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R422_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//readbackCal_C0.dat
[14:04:25.411] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[14:04:25.411] <TB3> INFO: PixTestReadback::doTest() done
[14:04:25.444] <TB3> INFO: enter test to run
[14:04:25.444] <TB3> INFO: test: no parameter change
[14:04:25.729] <TB3> QUIET: Connection to board 71 closed.
[14:04:25.809] <TB3> INFO: pXar: this is the end, my friend