[14:10:57.299] <TB2> INFO: *** Welcome to pxar ***
[14:10:57.299] <TB2> INFO: *** Today: 2015/12/04
[14:10:57.870] <TB2> INFO: *** Version: 9da6
[14:10:57.870] <TB2> INFO: readRocDacs: /home/mameinha/data/R420_FulltestROC_m20_2015-12-04_15h06m_1449237996//000_FulltestROC_m20//dacParameters_C0.dat .. /home/mameinha/data/R420_FulltestROC_m20_2015-12-04_15h06m_1449237996//000_FulltestROC_m20//dacParameters_C0.dat
[14:10:57.871] <TB2> INFO: readTbmDacs: /home/mameinha/data/R420_FulltestROC_m20_2015-12-04_15h06m_1449237996//000_FulltestROC_m20//tbmParameters_C0a.dat .. /home/mameinha/data/R420_FulltestROC_m20_2015-12-04_15h06m_1449237996//000_FulltestROC_m20//tbmParameters_C4294967295b.dat
[14:10:57.871] <TB2> INFO: readMaskFile: /home/mameinha/data/R420_FulltestROC_m20_2015-12-04_15h06m_1449237996//000_FulltestROC_m20//defaultMaskFile.dat
[14:10:57.872] <TB2> INFO: readTrimFile: /home/mameinha/data/R420_FulltestROC_m20_2015-12-04_15h06m_1449237996//000_FulltestROC_m20//trimParameters_C0.dat .. /home/mameinha/data/R420_FulltestROC_m20_2015-12-04_15h06m_1449237996//000_FulltestROC_m20//trimParameters_C0.dat
[14:10:57.882] <TB2> INFO: clk: 4
[14:10:57.882] <TB2> INFO: ctr: 4
[14:10:57.882] <TB2> INFO: sda: 19
[14:10:57.882] <TB2> INFO: tin: 9
[14:10:57.882] <TB2> INFO: level: 15
[14:10:57.882] <TB2> INFO: deser160phase: 4
[14:10:57.882] <TB2> QUIET: Instanciating API for pxar v2.6.1+42~g55d8827
[14:10:57.882] <TB2> INFO: Log level: INFO
[14:10:57.887] <TB2> INFO: Found DTB DTB_WZ4BYI
[14:10:57.896] <TB2> QUIET: Connection to board DTB_WZ4BYI opened.
[14:10:57.899] <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:
------------------------------------------------------
[14:10:57.901] <TB2> INFO: RPC call hashes of host and DTB match: 398089610
[14:10:59.064] <TB2> INFO: DUT info:
[14:10:59.064] <TB2> INFO: The DUT currently contains the following objects:
[14:10:59.064] <TB2> INFO: 0 TBM Cores (0 ON)
[14:10:59.064] <TB2> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[14:10:59.064] <TB2> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:59.470] <TB2> INFO: enter 'restricted' command line mode
[14:10:59.470] <TB2> INFO: enter test to run
[14:10:59.470] <TB2> INFO: test: Setup no parameter change
[14:10:59.471] <TB2> INFO: running: setup
[14:10:59.475] <TB2> INFO: PixTestSetup::doTest() ntrig = 10

[14:10:59.475] <TB2> INFO: PixTestSetup:: pg set to RES|TOK
[14:10:59.475] <TB2> INFO: 0 1 2 3 4 5 6 7
[14:11:02.515] <TB2> INFO: 0: 000 000 004 07c 7f0 f00 000 000
[14:11:05.526] <TB2> INFO: 1: 000 000 004 07c <7f8>[*] f80 800 000
[14:11:08.539] <TB2> INFO: 2: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[14:11:11.551] <TB2> INFO: 3: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[14:11:14.564] <TB2> INFO: 4: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[14:11:17.575] <TB2> INFO: 5: 000 000 000 03c 3fc fc0 c00 000
[14:11:20.587] <TB2> INFO: 6: c00 000 000 03c 3fc fc0 c00 000
[14:11:23.599] <TB2> INFO: 7: 000 000 000 03c 3fc fc0 c00 000
[14:11:26.612] <TB2> INFO: 8: c00 000 000 03c 3fc fc0 c00 000
[14:11:29.625] <TB2> INFO: 9: c00 000 000 03c 3fc fc0 c00 000
[14:11:32.637] <TB2> INFO: 10: 000 000 000 01c 1fc fc0 c00 000
[14:11:35.649] <TB2> INFO: 11: 000 000 000 01c 1fc fe0 e00 000
[14:11:38.661] <TB2> INFO: 12: 000 000 000 01c 1fc fe0 e00 000
[14:11:41.672] <TB2> INFO: 13: e00 000 000 01c 1fc fe0 e00 000
[14:11:44.684] <TB2> INFO: 14: 000 000 000 01c 1fc fe0 e00 000
[14:11:47.696] <TB2> INFO: 15: 000 000 000 00c 0fc ff0 f00 000
[14:11:50.709] <TB2> INFO: 16: 000 000 000 00c 0fc ff0 f00 000
[14:11:53.721] <TB2> INFO: 17: 000 000 000 00c 0fc ff0 f00 000
[14:11:56.734] <TB2> INFO: 18: 000 000 000 00c 0fc ff0 f00 000
[14:11:59.746] <TB2> INFO: 19: 000 000 000 00c 0fc ff0 f00 000
[14:12:00.162] <TB2> INFO: Found good delays at CLK = 2, DESER160 = 4
[14:12:00.163] <TB2> INFO: PixTestSetup:: Write Tb parameters to file.
[14:12:00.193] <TB2> INFO: write dtb parameters into /home/mameinha/data/R420_FulltestROC_m20_2015-12-04_15h06m_1449237996//000_FulltestROC_m20//tbParameters.dat
[14:12:00.244] <TB2> INFO: PixTestSetup::doTest() done for.
[14:12:00.282] <TB2> INFO: enter test to run
[14:12:00.282] <TB2> INFO: test: Pretest no parameter change
[14:12:00.282] <TB2> INFO: running: pretest
[14:12:00.283] <TB2> INFO: ----------------------------------------------------------------------
[14:12:00.283] <TB2> INFO: PixTestPretest::programROC()
[14:12:00.283] <TB2> INFO: ----------------------------------------------------------------------
[14:12:03.285] <TB2> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[14:12:03.285] <TB2> INFO: IA differences per ROC: 20.9
[14:12:03.290] <TB2> INFO: enter test to run
[14:12:03.294] <TB2> INFO: test: Pretest no parameter change
[14:12:03.294] <TB2> INFO: running: pretest
[14:12:03.295] <TB2> INFO: ----------------------------------------------------------------------
[14:12:03.295] <TB2> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[14:12:03.295] <TB2> INFO: ----------------------------------------------------------------------
[14:12:04.207] <TB2> INFO: PixTestPretest::setVana() done, Module Ia 24.1 mA = 24.1 mA/ROC
[14:12:04.207] <TB2> INFO: i(loss) [mA/ROC]: 19.3
[14:12:04.208] <TB2> INFO: enter test to run
[14:12:04.208] <TB2> INFO: test: Pretest no parameter change
[14:12:04.208] <TB2> INFO: running: pretest
[14:12:04.210] <TB2> INFO: ----------------------------------------------------------------------
[14:12:04.210] <TB2> INFO: PixTestPretest::findWorkingPixel()
[14:12:04.210] <TB2> INFO: ----------------------------------------------------------------------
[14:12:04.220] <TB2> INFO: Expecting 231680 events.
[14:12:06.510] <TB2> INFO: 231680 events read in total (1903ms).
[14:12:06.512] <TB2> INFO: Test took 2302ms.
[14:12:06.886] <TB2> INFO: Found working pixel in all ROCs: col/row = 12/22
[14:12:06.894] <TB2> INFO: enter test to run
[14:12:06.894] <TB2> INFO: test: Pretest no parameter change
[14:12:06.895] <TB2> INFO: running: pretest
[14:12:06.896] <TB2> INFO: ----------------------------------------------------------------------
[14:12:06.896] <TB2> INFO: PixTestPretest::setVthrCompCalDel()
[14:12:06.896] <TB2> INFO: ----------------------------------------------------------------------
[14:12:06.905] <TB2> INFO: Expecting 231680 events.
[14:12:09.104] <TB2> INFO: 231680 events read in total (1812ms).
[14:12:09.107] <TB2> INFO: Test took 2212ms.
[14:12:09.486] <TB2> INFO: PixTestPretest::setVthrCompCalDel() done
[14:12:09.486] <TB2> INFO: CalDel: 168
[14:12:09.486] <TB2> INFO: VthrComp: 51
[14:12:09.496] <TB2> INFO: enter test to run
[14:12:09.497] <TB2> INFO: test: Pretest no parameter change
[14:12:09.497] <TB2> INFO: running: pretest
[14:12:09.502] <TB2> INFO: write dac parameters into /home/mameinha/data/R420_FulltestROC_m20_2015-12-04_15h06m_1449237996//000_FulltestROC_m20//dacParameters_C0.dat
[14:12:09.508] <TB2> INFO: enter test to run
[14:12:09.508] <TB2> INFO: test: PixelAlive no parameter change
[14:12:09.508] <TB2> INFO: running: pixelalive
[14:12:09.509] <TB2> INFO: ######################################################################
[14:12:09.509] <TB2> INFO: PixTestAlive::doTest()
[14:12:09.509] <TB2> INFO: ######################################################################
[14:12:09.511] <TB2> INFO: ----------------------------------------------------------------------
[14:12:09.511] <TB2> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[14:12:09.511] <TB2> INFO: ----------------------------------------------------------------------
[14:12:09.535] <TB2> INFO: Expecting 41600 events.
[14:12:10.413] <TB2> INFO: 41600 events read in total (491ms).
[14:12:10.413] <TB2> INFO: Test took 902ms.
[14:12:10.413] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:12:10.796] <TB2> INFO: PixTestAlive::aliveTest() done
[14:12:10.796] <TB2> INFO: number of dead pixels (per ROC): 0
[14:12:10.797] <TB2> INFO: ----------------------------------------------------------------------
[14:12:10.798] <TB2> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[14:12:10.798] <TB2> INFO: ----------------------------------------------------------------------
[14:12:10.817] <TB2> INFO: Expecting 41600 events.
[14:12:11.579] <TB2> INFO: 41600 events read in total (375ms).
[14:12:11.579] <TB2> INFO: Test took 781ms.
[14:12:11.579] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:12:11.579] <TB2> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[14:12:11.969] <TB2> INFO: PixTestAlive::maskTest() done
[14:12:11.969] <TB2> INFO: number of mask-defect pixels (per ROC): 0
[14:12:11.971] <TB2> INFO: ----------------------------------------------------------------------
[14:12:11.971] <TB2> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[14:12:11.971] <TB2> INFO: ----------------------------------------------------------------------
[14:12:11.997] <TB2> INFO: Expecting 41600 events.
[14:12:12.860] <TB2> INFO: 41600 events read in total (476ms).
[14:12:12.861] <TB2> INFO: Test took 890ms.
[14:12:12.861] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:12:13.243] <TB2> INFO: PixTestAlive::addressDecodingTest() done
[14:12:13.243] <TB2> INFO: number of address-decoding pixels (per ROC): 0
[14:12:13.243] <TB2> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[14:12:13.244] <TB2> INFO: enter test to run
[14:12:13.244] <TB2> INFO: test: Scurves no parameter change
[14:12:13.244] <TB2> INFO: running: scurves
[14:12:13.246] <TB2> INFO: ######################################################################
[14:12:13.246] <TB2> INFO: PixTestScurves::doTest() ntrig = 50
[14:12:13.246] <TB2> INFO: ######################################################################
[14:12:13.246] <TB2> INFO: ----------------------------------------------------------------------
[14:12:13.246] <TB2> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[14:12:13.246] <TB2> INFO: ----------------------------------------------------------------------
[14:12:13.246] <TB2> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[14:12:13.262] <TB2> INFO: dacScan split into 1 runs with ntrig = 50
[14:12:13.262] <TB2> INFO: run 1 of 1
[14:12:13.281] <TB2> INFO: Expecting 41808000 events.
[14:14:26.932] <TB2> INFO: 17422300 events read in total (133264ms).
[14:16:39.680] <TB2> INFO: 34676500 events read in total (266012ms).
[14:17:34.049] <TB2> INFO: 41808000 events read in total (320381ms).
[14:17:34.114] <TB2> INFO: Test took 320852ms.
[14:17:34.139] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:17:34.149] <TB2> INFO: dumping ASCII scurve output file: SCurveData
[14:17:35.768] <TB2> INFO: PixTestScurves::scurves() done
[14:17:35.768] <TB2> INFO: Vcal mean: 54.09
[14:17:35.768] <TB2> INFO: Vcal RMS: 3.84
[14:17:35.773] <TB2> INFO: enter test to run
[14:17:35.773] <TB2> INFO: test: Trim no parameter change
[14:17:35.773] <TB2> INFO: running: trim
[14:17:35.775] <TB2> INFO: ######################################################################
[14:17:35.775] <TB2> INFO: PixTestTrim::doTest()
[14:17:35.775] <TB2> INFO: ######################################################################
[14:17:35.776] <TB2> INFO: ----------------------------------------------------------------------
[14:17:35.776] <TB2> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[14:17:35.776] <TB2> INFO: ----------------------------------------------------------------------
[14:17:35.784] <TB2> INFO: ---> VthrComp thr map (minimal VthrComp)
[14:17:35.784] <TB2> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[14:17:35.793] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:17:35.793] <TB2> INFO: run 1 of 1
[14:17:35.812] <TB2> INFO: Expecting 6281600 events.
[14:18:24.706] <TB2> INFO: 6281600 events read in total (48504ms).
[14:18:24.727] <TB2> INFO: Test took 48935ms.
[14:18:24.737] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:18:25.837] <TB2> INFO: ROC 0 VthrComp = 67
[14:18:25.837] <TB2> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[14:18:25.837] <TB2> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[14:18:25.845] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:18:25.845] <TB2> INFO: run 1 of 1
[14:18:25.864] <TB2> INFO: Expecting 6281600 events.
[14:19:19.813] <TB2> INFO: 6281600 events read in total (53562ms).
[14:19:19.864] <TB2> INFO: Test took 54019ms.
[14:19:19.884] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:19:21.142] <TB2> INFO: roc 0 with ID = 0 has maximal Vcal 52.1713 for pixel 8/71 mean/min/max = 41.8421/31.4611/52.2232
[14:19:21.151] <TB2> INFO: Expecting 514560 events.
[14:19:25.426] <TB2> INFO: 514560 events read in total (3888ms).
[14:19:25.433] <TB2> INFO: Test took 4291ms.
[14:19:25.826] <TB2> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[14:19:25.834] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:19:25.834] <TB2> INFO: run 1 of 1
[14:19:25.853] <TB2> INFO: Expecting 6281600 events.
[14:20:19.953] <TB2> INFO: 6281600 events read in total (53713ms).
[14:20:20.007] <TB2> INFO: Test took 54173ms.
[14:20:20.028] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:21.291] <TB2> INFO: ---> TrimStepCorr4 extremal thresholds: 16.059577 .. 44.980900
[14:20:21.296] <TB2> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 6 .. 54 (-1/-1) hits flags = 528 (plus default)
[14:20:21.303] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:20:21.303] <TB2> INFO: run 1 of 1
[14:20:21.323] <TB2> INFO: Expecting 2038400 events.
[14:20:38.038] <TB2> INFO: 2038400 events read in total (16328ms).
[14:20:38.047] <TB2> INFO: Test took 16744ms.
[14:20:38.051] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:38.867] <TB2> INFO: ---> TrimStepCorr2 extremal thresholds: 21.693831 .. 38.171849
[14:20:38.872] <TB2> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 11 .. 48 (-1/-1) hits flags = 528 (plus default)
[14:20:38.879] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:20:38.879] <TB2> INFO: run 1 of 1
[14:20:38.898] <TB2> INFO: Expecting 1580800 events.
[14:20:52.524] <TB2> INFO: 1580800 events read in total (13239ms).
[14:20:52.990] <TB2> INFO: Test took 14111ms.
[14:20:52.994] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:53.778] <TB2> INFO: ---> TrimStepCorr1a extremal thresholds: 25.788596 .. 37.048640
[14:20:53.782] <TB2> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 15 .. 47 (-1/-1) hits flags = 528 (plus default)
[14:20:53.790] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:20:53.790] <TB2> INFO: run 1 of 1
[14:20:53.809] <TB2> INFO: Expecting 1372800 events.
[14:21:05.353] <TB2> INFO: 1372800 events read in total (11157ms).
[14:21:05.359] <TB2> INFO: Test took 11569ms.
[14:21:05.362] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:06.164] <TB2> INFO: ---> TrimStepCorr1b extremal thresholds: 27.417921 .. 36.295860
[14:21:06.169] <TB2> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 17 .. 46 (-1/-1) hits flags = 528 (plus default)
[14:21:06.176] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:21:06.176] <TB2> INFO: run 1 of 1
[14:21:06.195] <TB2> INFO: Expecting 1248000 events.
[14:21:17.073] <TB2> INFO: 1248000 events read in total (10491ms).
[14:21:17.082] <TB2> INFO: Test took 10906ms.
[14:21:17.086] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:17.995] <TB2> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[14:21:17.995] <TB2> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[14:21:18.004] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:21:18.004] <TB2> INFO: run 1 of 1
[14:21:18.027] <TB2> INFO: Expecting 1705600 events.
[14:21:32.824] <TB2> INFO: 1705600 events read in total (14411ms).
[14:21:32.834] <TB2> INFO: Test took 14830ms.
[14:21:32.838] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:33.947] <TB2> INFO: write dac parameters into /home/mameinha/data/R420_FulltestROC_m20_2015-12-04_15h06m_1449237996//000_FulltestROC_m20//dacParameters35_C0.dat
[14:21:33.954] <TB2> INFO: write trim parameters into /home/mameinha/data/R420_FulltestROC_m20_2015-12-04_15h06m_1449237996//000_FulltestROC_m20//trimParameters35_C0.dat
[14:21:33.963] <TB2> INFO: PixTestTrim::trimTest() done
[14:21:33.963] <TB2> INFO: vtrim: 90
[14:21:33.964] <TB2> INFO: vthrcomp: 67
[14:21:33.964] <TB2> INFO: vcal mean: 34.89
[14:21:33.964] <TB2> INFO: vcal RMS: 0.65
[14:21:33.964] <TB2> INFO: bits mean: 11.04
[14:21:33.964] <TB2> INFO: bits RMS: 2.21
[14:21:33.967] <TB2> INFO: ----------------------------------------------------------------------
[14:21:33.967] <TB2> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[14:21:33.967] <TB2> INFO: ----------------------------------------------------------------------
[14:21:33.968] <TB2> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[14:21:33.975] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:21:33.975] <TB2> INFO: run 1 of 1
[14:21:33.994] <TB2> INFO: Expecting 8320000 events.
[14:22:43.148] <TB2> INFO: 8320000 events read in total (68768ms).
[14:22:43.203] <TB2> INFO: Test took 69228ms.
[14:22:43.232] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:44.727] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 103 (-1/-1) hits flags = 528 (plus default)
[14:22:44.734] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:22:44.734] <TB2> INFO: run 1 of 1
[14:22:44.753] <TB2> INFO: Expecting 4326400 events.
[14:23:19.972] <TB2> INFO: 4326400 events read in total (34832ms).
[14:23:19.991] <TB2> INFO: Test took 35257ms.
[14:23:20.000] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:23:21.054] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 94 (-1/-1) hits flags = 528 (plus default)
[14:23:21.061] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:23:21.061] <TB2> INFO: run 1 of 1
[14:23:21.080] <TB2> INFO: Expecting 3952000 events.
[14:23:51.982] <TB2> INFO: 3952000 events read in total (30515ms).
[14:23:51.997] <TB2> INFO: Test took 30936ms.
[14:23:52.003] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:23:53.022] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 94 (-1/-1) hits flags = 528 (plus default)
[14:23:53.029] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:23:53.029] <TB2> INFO: run 1 of 1
[14:23:53.048] <TB2> INFO: Expecting 3952000 events.
[14:24:23.931] <TB2> INFO: 3952000 events read in total (30496ms).
[14:24:23.946] <TB2> INFO: Test took 30917ms.
[14:24:23.952] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:24.962] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 94 (-1/-1) hits flags = 528 (plus default)
[14:24:24.969] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:24:24.969] <TB2> INFO: run 1 of 1
[14:24:24.988] <TB2> INFO: Expecting 3952000 events.
[14:24:56.574] <TB2> INFO: 3952000 events read in total (31199ms).
[14:24:56.592] <TB2> INFO: Test took 31623ms.
[14:24:56.599] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:57.822] <TB2> INFO: PixTestTrim::trimBitTest() done
[14:24:57.823] <TB2> INFO: PixTestTrim::doTest() done, duration: 442 seconds
[14:24:57.881] <TB2> INFO: enter test to run
[14:24:57.881] <TB2> INFO: test: PhOptimization no parameter change
[14:24:57.881] <TB2> INFO: running: phoptimization
[14:24:57.881] <TB2> INFO: ######################################################################
[14:24:57.881] <TB2> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[14:24:57.881] <TB2> INFO: ######################################################################
[14:24:57.905] <TB2> INFO: Expecting 41600 events.
[14:24:58.716] <TB2> INFO: 41600 events read in total (424ms).
[14:24:58.716] <TB2> INFO: Test took 834ms.
[14:24:58.717] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:59.108] <TB2> INFO: Expecting 41600 events.
[14:24:59.876] <TB2> INFO: 41600 events read in total (381ms).
[14:24:59.876] <TB2> INFO: Test took 1158ms.
[14:24:59.876] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:25:00.269] <TB2> INFO: Expecting 41600 events.
[14:25:01.111] <TB2> INFO: 41600 events read in total (455ms).
[14:25:01.111] <TB2> INFO: Test took 1234ms.
[14:25:01.111] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:25:01.500] <TB2> INFO: Expecting 2560 events.
[14:25:01.921] <TB2> INFO: 2560 events read in total (35ms).
[14:25:01.921] <TB2> INFO: Test took 809ms.
[14:25:02.316] <TB2> INFO: Expecting 655360 events.
[14:25:07.229] <TB2> INFO: 655360 events read in total (4526ms).
[14:25:07.238] <TB2> INFO: Test took 5316ms.
[14:25:07.589] <TB2> INFO: Expecting 655360 events.
[14:25:13.160] <TB2> INFO: 655360 events read in total (5184ms).
[14:25:13.173] <TB2> INFO: Test took 5922ms.
[14:25:13.202] <TB2> INFO: safety margin for low PH: adding 0, margin is now 20
[14:25:13.638] <TB2> INFO: write dac parameters into /home/mameinha/data/R420_FulltestROC_m20_2015-12-04_15h06m_1449237996//000_FulltestROC_m20//dacParameters35_C0.dat
[14:25:13.697] <TB2> INFO: Expecting 41600 events.
[14:25:14.462] <TB2> INFO: 41600 events read in total (378ms).
[14:25:14.463] <TB2> INFO: Test took 786ms.
[14:25:14.851] <TB2> INFO: Expecting 41600 events.
[14:25:15.671] <TB2> INFO: 41600 events read in total (432ms).
[14:25:15.671] <TB2> INFO: Test took 1207ms.
[14:25:16.050] <TB2> INFO: Expecting 41600 events.
[14:25:16.837] <TB2> INFO: 41600 events read in total (400ms).
[14:25:16.837] <TB2> INFO: Test took 1165ms.
[14:25:17.219] <TB2> INFO: Expecting 2560 events.
[14:25:17.637] <TB2> INFO: 2560 events read in total (31ms).
[14:25:17.637] <TB2> INFO: Test took 799ms.
[14:25:18.032] <TB2> INFO: Expecting 2560 events.
[14:25:18.449] <TB2> INFO: 2560 events read in total (30ms).
[14:25:18.449] <TB2> INFO: Test took 812ms.
[14:25:18.856] <TB2> INFO: PixTestPhOptimization::doTest() done, duration: 20 seconds
[14:25:18.856] <TB2> INFO: PH scale (per ROC): 106
[14:25:18.856] <TB2> INFO: PH offset (per ROC): 131
[14:25:18.870] <TB2> INFO: enter test to run
[14:25:18.870] <TB2> INFO: test: GainPedestal no parameter change
[14:25:18.870] <TB2> INFO: running: gainpedestal
[14:25:18.872] <TB2> INFO: ######################################################################
[14:25:18.872] <TB2> INFO: PixTestGainPedestal::doTest() ntrig = 10
[14:25:18.872] <TB2> INFO: ######################################################################
[14:25:18.879] <TB2> INFO: scanning low vcal = 10
[14:25:18.899] <TB2> INFO: Expecting 41600 events.
[14:25:19.992] <TB2> INFO: 41600 events read in total (706ms).
[14:25:19.992] <TB2> INFO: Test took 1113ms.
[14:25:19.992] <TB2> INFO: scanning low vcal = 20
[14:25:20.387] <TB2> INFO: Expecting 41600 events.
[14:25:21.497] <TB2> INFO: 41600 events read in total (724ms).
[14:25:21.497] <TB2> INFO: Test took 1505ms.
[14:25:21.497] <TB2> INFO: scanning low vcal = 30
[14:25:21.891] <TB2> INFO: Expecting 41600 events.
[14:25:23.009] <TB2> INFO: 41600 events read in total (731ms).
[14:25:23.010] <TB2> INFO: Test took 1512ms.
[14:25:23.010] <TB2> INFO: scanning low vcal = 40
[14:25:23.404] <TB2> INFO: Expecting 41600 events.
[14:25:24.532] <TB2> INFO: 41600 events read in total (741ms).
[14:25:24.533] <TB2> INFO: Test took 1523ms.
[14:25:24.533] <TB2> INFO: scanning low vcal = 50
[14:25:24.921] <TB2> INFO: Expecting 41600 events.
[14:25:26.069] <TB2> INFO: 41600 events read in total (761ms).
[14:25:26.069] <TB2> INFO: Test took 1536ms.
[14:25:26.069] <TB2> INFO: scanning low vcal = 60
[14:25:26.458] <TB2> INFO: Expecting 41600 events.
[14:25:27.583] <TB2> INFO: 41600 events read in total (739ms).
[14:25:27.584] <TB2> INFO: Test took 1515ms.
[14:25:27.584] <TB2> INFO: scanning low vcal = 70
[14:25:27.972] <TB2> INFO: Expecting 41600 events.
[14:25:29.149] <TB2> INFO: 41600 events read in total (790ms).
[14:25:29.149] <TB2> INFO: Test took 1565ms.
[14:25:29.150] <TB2> INFO: scanning low vcal = 80
[14:25:29.536] <TB2> INFO: Expecting 41600 events.
[14:25:30.687] <TB2> INFO: 41600 events read in total (764ms).
[14:25:30.687] <TB2> INFO: Test took 1537ms.
[14:25:30.688] <TB2> INFO: scanning low vcal = 90
[14:25:31.075] <TB2> INFO: Expecting 41600 events.
[14:25:32.219] <TB2> INFO: 41600 events read in total (757ms).
[14:25:32.219] <TB2> INFO: Test took 1531ms.
[14:25:32.220] <TB2> INFO: scanning low vcal = 100
[14:25:32.604] <TB2> INFO: Expecting 41600 events.
[14:25:33.753] <TB2> INFO: 41600 events read in total (763ms).
[14:25:33.754] <TB2> INFO: Test took 1534ms.
[14:25:33.754] <TB2> INFO: scanning low vcal = 110
[14:25:34.142] <TB2> INFO: Expecting 41600 events.
[14:25:35.268] <TB2> INFO: 41600 events read in total (739ms).
[14:25:35.268] <TB2> INFO: Test took 1514ms.
[14:25:35.269] <TB2> INFO: scanning low vcal = 120
[14:25:35.657] <TB2> INFO: Expecting 41600 events.
[14:25:36.812] <TB2> INFO: 41600 events read in total (768ms).
[14:25:36.812] <TB2> INFO: Test took 1543ms.
[14:25:36.812] <TB2> INFO: scanning low vcal = 130
[14:25:37.200] <TB2> INFO: Expecting 41600 events.
[14:25:38.357] <TB2> INFO: 41600 events read in total (770ms).
[14:25:38.357] <TB2> INFO: Test took 1545ms.
[14:25:38.358] <TB2> INFO: scanning low vcal = 140
[14:25:38.744] <TB2> INFO: Expecting 41600 events.
[14:25:39.920] <TB2> INFO: 41600 events read in total (789ms).
[14:25:39.920] <TB2> INFO: Test took 1562ms.
[14:25:39.921] <TB2> INFO: scanning low vcal = 150
[14:25:40.303] <TB2> INFO: Expecting 41600 events.
[14:25:41.469] <TB2> INFO: 41600 events read in total (779ms).
[14:25:41.470] <TB2> INFO: Test took 1549ms.
[14:25:41.471] <TB2> INFO: scanning low vcal = 160
[14:25:41.855] <TB2> INFO: Expecting 41600 events.
[14:25:42.992] <TB2> INFO: 41600 events read in total (750ms).
[14:25:42.992] <TB2> INFO: Test took 1521ms.
[14:25:42.993] <TB2> INFO: scanning low vcal = 170
[14:25:43.378] <TB2> INFO: Expecting 41600 events.
[14:25:44.505] <TB2> INFO: 41600 events read in total (740ms).
[14:25:44.505] <TB2> INFO: Test took 1512ms.
[14:25:44.505] <TB2> INFO: scanning low vcal = 180
[14:25:44.894] <TB2> INFO: Expecting 41600 events.
[14:25:46.043] <TB2> INFO: 41600 events read in total (762ms).
[14:25:46.044] <TB2> INFO: Test took 1539ms.
[14:25:46.044] <TB2> INFO: scanning low vcal = 190
[14:25:46.431] <TB2> INFO: Expecting 41600 events.
[14:25:47.559] <TB2> INFO: 41600 events read in total (741ms).
[14:25:47.560] <TB2> INFO: Test took 1516ms.
[14:25:47.560] <TB2> INFO: scanning low vcal = 200
[14:25:47.948] <TB2> INFO: Expecting 41600 events.
[14:25:49.096] <TB2> INFO: 41600 events read in total (761ms).
[14:25:49.096] <TB2> INFO: Test took 1536ms.
[14:25:49.097] <TB2> INFO: scanning low vcal = 210
[14:25:49.484] <TB2> INFO: Expecting 41600 events.
[14:25:50.650] <TB2> INFO: 41600 events read in total (779ms).
[14:25:50.650] <TB2> INFO: Test took 1553ms.
[14:25:50.650] <TB2> INFO: scanning low vcal = 220
[14:25:51.035] <TB2> INFO: Expecting 41600 events.
[14:25:52.200] <TB2> INFO: 41600 events read in total (778ms).
[14:25:52.200] <TB2> INFO: Test took 1549ms.
[14:25:52.200] <TB2> INFO: scanning low vcal = 230
[14:25:52.585] <TB2> INFO: Expecting 41600 events.
[14:25:53.753] <TB2> INFO: 41600 events read in total (781ms).
[14:25:53.754] <TB2> INFO: Test took 1554ms.
[14:25:53.755] <TB2> INFO: scanning low vcal = 240
[14:25:54.138] <TB2> INFO: Expecting 41600 events.
[14:25:55.321] <TB2> INFO: 41600 events read in total (796ms).
[14:25:55.321] <TB2> INFO: Test took 1566ms.
[14:25:55.322] <TB2> INFO: scanning low vcal = 250
[14:25:55.709] <TB2> INFO: Expecting 41600 events.
[14:25:56.866] <TB2> INFO: 41600 events read in total (770ms).
[14:25:56.866] <TB2> INFO: Test took 1544ms.
[14:25:56.867] <TB2> INFO: scanning high vcal = 30 (= 210 in low range)
[14:25:57.245] <TB2> INFO: Expecting 41600 events.
[14:25:58.393] <TB2> INFO: 41600 events read in total (761ms).
[14:25:58.394] <TB2> INFO: Test took 1527ms.
[14:25:58.394] <TB2> INFO: scanning high vcal = 50 (= 350 in low range)
[14:25:58.782] <TB2> INFO: Expecting 41600 events.
[14:25:59.929] <TB2> INFO: 41600 events read in total (760ms).
[14:25:59.930] <TB2> INFO: Test took 1536ms.
[14:25:59.930] <TB2> INFO: scanning high vcal = 70 (= 490 in low range)
[14:26:00.315] <TB2> INFO: Expecting 41600 events.
[14:26:01.466] <TB2> INFO: 41600 events read in total (765ms).
[14:26:01.466] <TB2> INFO: Test took 1536ms.
[14:26:01.467] <TB2> INFO: scanning high vcal = 90 (= 630 in low range)
[14:26:01.847] <TB2> INFO: Expecting 41600 events.
[14:26:02.993] <TB2> INFO: 41600 events read in total (759ms).
[14:26:02.994] <TB2> INFO: Test took 1527ms.
[14:26:02.994] <TB2> INFO: scanning high vcal = 200 (= 1400 in low range)
[14:26:03.377] <TB2> INFO: Expecting 41600 events.
[14:26:04.500] <TB2> INFO: 41600 events read in total (736ms).
[14:26:04.501] <TB2> INFO: Test took 1507ms.
[14:26:04.885] <TB2> INFO: PixTestGainPedestal::measure() done
[14:26:06.729] <TB2> INFO: PixTestGainPedestal::fit() done
[14:26:06.729] <TB2> INFO: non-linearity mean: 0.945
[14:26:06.729] <TB2> INFO: non-linearity RMS: 0.010
[14:26:06.730] <TB2> INFO: write gain/ped parameters into /home/mameinha/data/R420_FulltestROC_m20_2015-12-04_15h06m_1449237996//000_FulltestROC_m20//phCalibrationFitErr35_C0.dat
[14:26:06.770] <TB2> INFO: PixTestGainPedestal::doTest() done, duration: 47 seconds
[14:26:06.770] <TB2> INFO: enter test to run
[14:26:06.770] <TB2> INFO: test: Readback no parameter change
[14:26:06.770] <TB2> INFO: running: readback
[14:26:06.770] <TB2> INFO: readReadbackCal: /home/mameinha/data/R420_FulltestROC_m20_2015-12-04_15h06m_1449237996//000_FulltestROC_m20//readbackCal_C0.dat .. /home/mameinha/data/R420_FulltestROC_m20_2015-12-04_15h06m_1449237996//000_FulltestROC_m20//readbackCal_C0.dat
[14:26:06.771] <TB2> INFO: ######################################################################
[14:26:06.771] <TB2> INFO: PixTestReadback::doTest()
[14:26:06.771] <TB2> INFO: ######################################################################
[14:26:06.771] <TB2> INFO: ----------------------------------------------------------------------
[14:26:06.771] <TB2> INFO: PixTestReadback::CalibrateVd()
[14:26:06.771] <TB2> INFO: ----------------------------------------------------------------------
[14:26:18.096] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R420_FulltestROC_m20_2015-12-04_15h06m_1449237996//000_FulltestROC_m20//readbackCal_C0.dat
[14:26:18.120] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[14:26:18.120] <TB2> INFO: ----------------------------------------------------------------------
[14:26:18.120] <TB2> INFO: PixTestReadback::CalibrateVa()
[14:26:18.120] <TB2> INFO: ----------------------------------------------------------------------
[14:26:29.320] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R420_FulltestROC_m20_2015-12-04_15h06m_1449237996//000_FulltestROC_m20//readbackCal_C0.dat
[14:26:29.330] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[14:26:29.330] <TB2> INFO: ----------------------------------------------------------------------
[14:26:29.330] <TB2> INFO: PixTestReadback::readbackVbg()
[14:26:29.330] <TB2> INFO: ----------------------------------------------------------------------
[14:26:37.656] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[14:26:37.656] <TB2> INFO: ----------------------------------------------------------------------
[14:26:37.656] <TB2> INFO: PixTestReadback::getCalibratedVbg()
[14:26:37.656] <TB2> INFO: ----------------------------------------------------------------------
[14:26:37.656] <TB2> INFO: Vbg will be calibrated using Vd calibration
[14:26:37.656] <TB2> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 119.3calibrated Vbg = 1.34268 :::*/*/*/*/
[14:26:38.033] <TB2> INFO: ----------------------------------------------------------------------
[14:26:38.033] <TB2> INFO: PixTestReadback::CalibrateIa()
[14:26:38.033] <TB2> INFO: ----------------------------------------------------------------------
[14:26:46.911] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R420_FulltestROC_m20_2015-12-04_15h06m_1449237996//000_FulltestROC_m20//readbackCal_C0.dat
[14:26:46.989] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[14:26:46.989] <TB2> INFO: PixTestReadback::doTest() done
[14:26:47.028] <TB2> INFO: enter test to run
[14:26:47.028] <TB2> INFO: test: no parameter change
[14:26:47.249] <TB2> QUIET: Connection to board 169 closed.
[14:26:47.328] <TB2> INFO: pXar: this is the end, my friend