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

[14:45:54.240] <TB2> INFO: PixTestSetup:: pg set to RES|TOK
[14:45:54.240] <TB2> INFO: 0 1 2 3 4 5 6 7
[14:45:57.280] <TB2> INFO: 0: 000 000 004 07c 7f0 f00 000 000
[14:46:00.292] <TB2> INFO: 1: 000 000 004 07c <7f8>[*] f80 800 000
[14:46:03.304] <TB2> INFO: 2: 800 000 004 07c <7f8>[*] f80 800 000
[14:46:06.317] <TB2> INFO: 3: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[14:46:09.330] <TB2> INFO: 4: 000 000 004 07c <7f8>[*] f80 800 000
[14:46:12.343] <TB2> INFO: 5: 000 000 000 03c 3f8 fc0 c00 000
[14:46:15.356] <TB2> INFO: 6: 000 000 000 03c 3fc fc0 c00 000
[14:46:18.369] <TB2> INFO: 7: c00 000 000 03c 3fc fc0 c00 000
[14:46:21.382] <TB2> INFO: 8: 000 000 000 03c 3fc fc0 c00 000
[14:46:24.396] <TB2> INFO: 9: 000 000 000 03c 3fc fc0 c00 000
[14:46:27.409] <TB2> INFO: 10: c00 000 000 01c 1fc fc0 c00 000
[14:46:30.422] <TB2> INFO: 11: 000 000 000 01c 1fc fe0 e00 000
[14:46:33.435] <TB2> INFO: 12: 000 000 000 01c 1fc fe0 e00 000
[14:46:36.448] <TB2> INFO: 13: 000 000 000 01c 1fc fe0 e00 000
[14:46:39.461] <TB2> INFO: 14: 000 000 000 01c 1fc fe0 e00 000
[14:46:42.474] <TB2> INFO: 15: 000 000 000 00c 0fc ff0 f00 000
[14:46:45.486] <TB2> INFO: 16: 000 000 000 00c 0fc ff0 f00 000
[14:46:48.499] <TB2> INFO: 17: 000 000 000 00c 0fc ff0 f00 000
[14:46:51.511] <TB2> INFO: 18: 000 000 000 00c 0fc ff0 f00 000
[14:46:54.523] <TB2> INFO: 19: 000 000 000 00c 0fc ff0 f00 000
[14:46:54.944] <TB2> INFO: Found good delays at CLK = 2, DESER160 = 4
[14:46:54.945] <TB2> INFO: PixTestSetup:: Write Tb parameters to file.
[14:46:54.969] <TB2> INFO: write dtb parameters into /home/mameinha/data/R422_FulltestROC_m20_2015-12-04_15h33m_1449239629//000_FulltestROC_m20//tbParameters.dat
[14:46:54.989] <TB2> INFO: PixTestSetup::doTest() done for.
[14:46:55.018] <TB2> INFO: enter test to run
[14:46:55.018] <TB2> INFO: test: Pretest no parameter change
[14:46:55.018] <TB2> INFO: running: pretest
[14:46:55.020] <TB2> INFO: ----------------------------------------------------------------------
[14:46:55.020] <TB2> INFO: PixTestPretest::programROC()
[14:46:55.020] <TB2> INFO: ----------------------------------------------------------------------
[14:46:58.022] <TB2> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[14:46:58.022] <TB2> INFO: IA differences per ROC: 19.3
[14:46:58.026] <TB2> INFO: enter test to run
[14:46:58.026] <TB2> INFO: test: Pretest no parameter change
[14:46:58.027] <TB2> INFO: running: pretest
[14:46:58.028] <TB2> INFO: ----------------------------------------------------------------------
[14:46:58.028] <TB2> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[14:46:58.028] <TB2> INFO: ----------------------------------------------------------------------
[14:46:59.644] <TB2> INFO: PixTestPretest::setVana() done, Module Ia 24.9 mA = 24.9 mA/ROC
[14:46:59.644] <TB2> INFO: i(loss) [mA/ROC]: 21.7
[14:46:59.646] <TB2> INFO: enter test to run
[14:46:59.646] <TB2> INFO: test: Pretest no parameter change
[14:46:59.646] <TB2> INFO: running: pretest
[14:46:59.648] <TB2> INFO: ----------------------------------------------------------------------
[14:46:59.648] <TB2> INFO: PixTestPretest::findWorkingPixel()
[14:46:59.648] <TB2> INFO: ----------------------------------------------------------------------
[14:46:59.658] <TB2> INFO: Expecting 231680 events.
[14:47:01.944] <TB2> INFO: 231680 events read in total (1899ms).
[14:47:01.946] <TB2> INFO: Test took 2298ms.
[14:47:02.322] <TB2> INFO: Found working pixel in all ROCs: col/row = 12/22
[14:47:02.331] <TB2> INFO: enter test to run
[14:47:02.331] <TB2> INFO: test: Pretest no parameter change
[14:47:02.331] <TB2> INFO: running: pretest
[14:47:02.333] <TB2> INFO: ----------------------------------------------------------------------
[14:47:02.333] <TB2> INFO: PixTestPretest::setVthrCompCalDel()
[14:47:02.333] <TB2> INFO: ----------------------------------------------------------------------
[14:47:02.342] <TB2> INFO: Expecting 231680 events.
[14:47:04.600] <TB2> INFO: 231680 events read in total (1871ms).
[14:47:04.604] <TB2> INFO: Test took 2271ms.
[14:47:04.981] <TB2> INFO: PixTestPretest::setVthrCompCalDel() done
[14:47:04.981] <TB2> INFO: CalDel: 149
[14:47:04.981] <TB2> INFO: VthrComp: 51
[14:47:04.985] <TB2> INFO: enter test to run
[14:47:04.985] <TB2> INFO: test: Pretest no parameter change
[14:47:04.985] <TB2> INFO: running: pretest
[14:47:05.019] <TB2> INFO: write dac parameters into /home/mameinha/data/R422_FulltestROC_m20_2015-12-04_15h33m_1449239629//000_FulltestROC_m20//dacParameters_C0.dat
[14:47:05.037] <TB2> INFO: enter test to run
[14:47:05.037] <TB2> INFO: test: PixelAlive no parameter change
[14:47:05.037] <TB2> INFO: running: pixelalive
[14:47:05.039] <TB2> INFO: ######################################################################
[14:47:05.039] <TB2> INFO: PixTestAlive::doTest()
[14:47:05.039] <TB2> INFO: ######################################################################
[14:47:05.040] <TB2> INFO: ----------------------------------------------------------------------
[14:47:05.040] <TB2> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[14:47:05.040] <TB2> INFO: ----------------------------------------------------------------------
[14:47:05.059] <TB2> INFO: Expecting 41600 events.
[14:47:05.919] <TB2> INFO: 41600 events read in total (473ms).
[14:47:05.919] <TB2> INFO: Test took 879ms.
[14:47:05.919] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:47:06.305] <TB2> INFO: PixTestAlive::aliveTest() done
[14:47:06.305] <TB2> INFO: number of dead pixels (per ROC): 0
[14:47:06.306] <TB2> INFO: ----------------------------------------------------------------------
[14:47:06.306] <TB2> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[14:47:06.306] <TB2> INFO: ----------------------------------------------------------------------
[14:47:06.333] <TB2> INFO: Expecting 41600 events.
[14:47:07.120] <TB2> INFO: 41600 events read in total (400ms).
[14:47:07.120] <TB2> INFO: Test took 814ms.
[14:47:07.120] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:47:07.120] <TB2> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[14:47:07.510] <TB2> INFO: PixTestAlive::maskTest() done
[14:47:07.510] <TB2> INFO: number of mask-defect pixels (per ROC): 0
[14:47:07.511] <TB2> INFO: ----------------------------------------------------------------------
[14:47:07.511] <TB2> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[14:47:07.511] <TB2> INFO: ----------------------------------------------------------------------
[14:47:07.533] <TB2> INFO: Expecting 41600 events.
[14:47:08.353] <TB2> INFO: 41600 events read in total (433ms).
[14:47:08.353] <TB2> INFO: Test took 842ms.
[14:47:08.353] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:47:08.739] <TB2> INFO: PixTestAlive::addressDecodingTest() done
[14:47:08.739] <TB2> INFO: number of address-decoding pixels (per ROC): 0
[14:47:08.739] <TB2> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[14:47:08.740] <TB2> INFO: enter test to run
[14:47:08.740] <TB2> INFO: test: Scurves no parameter change
[14:47:08.740] <TB2> INFO: running: scurves
[14:47:08.742] <TB2> INFO: ######################################################################
[14:47:08.742] <TB2> INFO: PixTestScurves::doTest() ntrig = 50
[14:47:08.742] <TB2> INFO: ######################################################################
[14:47:08.742] <TB2> INFO: ----------------------------------------------------------------------
[14:47:08.742] <TB2> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[14:47:08.742] <TB2> INFO: ----------------------------------------------------------------------
[14:47:08.742] <TB2> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[14:47:08.760] <TB2> INFO: dacScan split into 1 runs with ntrig = 50
[14:47:08.760] <TB2> INFO: run 1 of 1
[14:47:08.779] <TB2> INFO: Expecting 41808000 events.
[14:49:31.664] <TB2> INFO: 18998750 events read in total (142498ms).
[14:51:52.558] <TB2> INFO: 37659200 events read in total (283392ms).
[14:52:23.263] <TB2> INFO: 41808000 events read in total (314097ms).
[14:52:23.296] <TB2> INFO: Test took 314536ms.
[14:52:23.319] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:52:23.328] <TB2> INFO: dumping ASCII scurve output file: SCurveData
[14:52:24.944] <TB2> INFO: PixTestScurves::scurves() done
[14:52:24.944] <TB2> INFO: Vcal mean: 73.60
[14:52:24.944] <TB2> INFO: Vcal RMS: 4.58
[14:52:24.949] <TB2> INFO: enter test to run
[14:52:24.949] <TB2> INFO: test: Trim no parameter change
[14:52:24.949] <TB2> INFO: running: trim
[14:52:24.950] <TB2> INFO: ######################################################################
[14:52:24.950] <TB2> INFO: PixTestTrim::doTest()
[14:52:24.950] <TB2> INFO: ######################################################################
[14:52:24.951] <TB2> INFO: ----------------------------------------------------------------------
[14:52:24.951] <TB2> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[14:52:24.951] <TB2> INFO: ----------------------------------------------------------------------
[14:52:24.956] <TB2> INFO: ---> VthrComp thr map (minimal VthrComp)
[14:52:24.956] <TB2> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[14:52:24.965] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:52:24.965] <TB2> INFO: run 1 of 1
[14:52:24.984] <TB2> INFO: Expecting 6281600 events.
[14:53:12.912] <TB2> INFO: 6281600 events read in total (47541ms).
[14:53:12.930] <TB2> INFO: Test took 47965ms.
[14:53:12.939] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:53:14.209] <TB2> INFO: ROC 0 VthrComp = 81
[14:53:14.209] <TB2> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[14:53:14.209] <TB2> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[14:53:14.216] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:53:14.216] <TB2> INFO: run 1 of 1
[14:53:14.235] <TB2> INFO: Expecting 6281600 events.
[14:54:05.822] <TB2> INFO: 6281600 events read in total (51200ms).
[14:54:05.861] <TB2> INFO: Test took 51645ms.
[14:54:05.882] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:54:07.264] <TB2> INFO: roc 0 with ID = 0 has maximal Vcal 56.0752 for pixel 10/76 mean/min/max = 44.7471/33.308/56.1862
[14:54:07.273] <TB2> INFO: Expecting 514560 events.
[14:54:11.536] <TB2> INFO: 514560 events read in total (3877ms).
[14:54:11.544] <TB2> INFO: Test took 4280ms.
[14:54:11.933] <TB2> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[14:54:11.941] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:54:11.941] <TB2> INFO: run 1 of 1
[14:54:11.960] <TB2> INFO: Expecting 6281600 events.
[14:55:04.152] <TB2> INFO: 6281600 events read in total (51805ms).
[14:55:04.192] <TB2> INFO: Test took 52251ms.
[14:55:04.213] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:55:05.409] <TB2> INFO: ---> TrimStepCorr4 extremal thresholds: 14.629275 .. 46.768462
[14:55:05.413] <TB2> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 4 .. 56 (-1/-1) hits flags = 528 (plus default)
[14:55:05.423] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:55:05.423] <TB2> INFO: run 1 of 1
[14:55:05.443] <TB2> INFO: Expecting 2204800 events.
[14:55:22.903] <TB2> INFO: 2204800 events read in total (17073ms).
[14:55:22.912] <TB2> INFO: Test took 17489ms.
[14:55:22.916] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:55:23.731] <TB2> INFO: ---> TrimStepCorr2 extremal thresholds: 21.569841 .. 40.931106
[14:55:23.736] <TB2> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 11 .. 50 (-1/-1) hits flags = 528 (plus default)
[14:55:23.743] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:55:23.743] <TB2> INFO: run 1 of 1
[14:55:23.763] <TB2> INFO: Expecting 1664000 events.
[14:55:37.228] <TB2> INFO: 1664000 events read in total (13079ms).
[14:55:37.236] <TB2> INFO: Test took 13493ms.
[14:55:37.240] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:55:38.155] <TB2> INFO: ---> TrimStepCorr1a extremal thresholds: 26.156338 .. 37.614988
[14:55:38.160] <TB2> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 16 .. 47 (-1/-1) hits flags = 528 (plus default)
[14:55:38.167] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:55:38.167] <TB2> INFO: run 1 of 1
[14:55:38.187] <TB2> INFO: Expecting 1331200 events.
[14:55:49.396] <TB2> INFO: 1331200 events read in total (10823ms).
[14:55:49.402] <TB2> INFO: Test took 11235ms.
[14:55:49.406] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:55:50.291] <TB2> INFO: ---> TrimStepCorr1b extremal thresholds: 27.457174 .. 36.540774
[14:55:50.296] <TB2> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 17 .. 46 (-1/-1) hits flags = 528 (plus default)
[14:55:50.303] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:55:50.303] <TB2> INFO: run 1 of 1
[14:55:50.325] <TB2> INFO: Expecting 1248000 events.
[14:56:00.895] <TB2> INFO: 1248000 events read in total (10183ms).
[14:56:00.901] <TB2> INFO: Test took 10598ms.
[14:56:00.903] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:56:01.729] <TB2> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[14:56:01.729] <TB2> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[14:56:01.736] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:56:01.736] <TB2> INFO: run 1 of 1
[14:56:01.756] <TB2> INFO: Expecting 1705600 events.
[14:56:16.199] <TB2> INFO: 1705600 events read in total (14056ms).
[14:56:16.207] <TB2> INFO: Test took 14471ms.
[14:56:16.211] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:56:17.022] <TB2> INFO: write dac parameters into /home/mameinha/data/R422_FulltestROC_m20_2015-12-04_15h33m_1449239629//000_FulltestROC_m20//dacParameters35_C0.dat
[14:56:17.028] <TB2> INFO: write trim parameters into /home/mameinha/data/R422_FulltestROC_m20_2015-12-04_15h33m_1449239629//000_FulltestROC_m20//trimParameters35_C0.dat
[14:56:17.047] <TB2> INFO: PixTestTrim::trimTest() done
[14:56:17.047] <TB2> INFO: vtrim: 103
[14:56:17.047] <TB2> INFO: vthrcomp: 81
[14:56:17.047] <TB2> INFO: vcal mean: 34.90
[14:56:17.047] <TB2> INFO: vcal RMS: 0.70
[14:56:17.047] <TB2> INFO: bits mean: 9.93
[14:56:17.047] <TB2> INFO: bits RMS: 2.56
[14:56:17.051] <TB2> INFO: ----------------------------------------------------------------------
[14:56:17.051] <TB2> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[14:56:17.051] <TB2> INFO: ----------------------------------------------------------------------
[14:56:17.051] <TB2> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[14:56:17.059] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:56:17.059] <TB2> INFO: run 1 of 1
[14:56:17.082] <TB2> INFO: Expecting 8320000 events.
[14:57:23.478] <TB2> INFO: 8320000 events read in total (66009ms).
[14:57:23.517] <TB2> INFO: Test took 66458ms.
[14:57:23.536] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:57:25.099] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 123 (-1/-1) hits flags = 528 (plus default)
[14:57:25.106] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:57:25.106] <TB2> INFO: run 1 of 1
[14:57:25.126] <TB2> INFO: Expecting 5158400 events.
[14:58:04.616] <TB2> INFO: 5158400 events read in total (39103ms).
[14:58:04.637] <TB2> INFO: Test took 39531ms.
[14:58:04.647] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:58:05.794] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 115 (-1/-1) hits flags = 528 (plus default)
[14:58:05.801] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:58:05.801] <TB2> INFO: run 1 of 1
[14:58:05.821] <TB2> INFO: Expecting 4825600 events.
[14:58:42.934] <TB2> INFO: 4825600 events read in total (36726ms).
[14:58:42.948] <TB2> INFO: Test took 37147ms.
[14:58:42.955] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:58:44.068] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 115 (-1/-1) hits flags = 528 (plus default)
[14:58:44.075] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:58:44.075] <TB2> INFO: run 1 of 1
[14:58:44.095] <TB2> INFO: Expecting 4825600 events.
[14:59:21.243] <TB2> INFO: 4825600 events read in total (36762ms).
[14:59:21.257] <TB2> INFO: Test took 37182ms.
[14:59:21.264] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:22.379] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 115 (-1/-1) hits flags = 528 (plus default)
[14:59:22.387] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:59:22.387] <TB2> INFO: run 1 of 1
[14:59:22.406] <TB2> INFO: Expecting 4825600 events.
[15:00:00.036] <TB2> INFO: 4825600 events read in total (37243ms).
[15:00:00.050] <TB2> INFO: Test took 37663ms.
[15:00:00.057] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:01.203] <TB2> INFO: PixTestTrim::trimBitTest() done
[15:00:01.204] <TB2> INFO: PixTestTrim::doTest() done, duration: 456 seconds
[15:00:01.250] <TB2> INFO: enter test to run
[15:00:01.250] <TB2> INFO: test: PhOptimization no parameter change
[15:00:01.250] <TB2> INFO: running: phoptimization
[15:00:01.250] <TB2> INFO: ######################################################################
[15:00:01.250] <TB2> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[15:00:01.250] <TB2> INFO: ######################################################################
[15:00:01.271] <TB2> INFO: Expecting 41600 events.
[15:00:02.071] <TB2> INFO: 41600 events read in total (413ms).
[15:00:02.071] <TB2> INFO: Test took 820ms.
[15:00:02.071] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:02.461] <TB2> INFO: Expecting 41600 events.
[15:00:03.226] <TB2> INFO: 41600 events read in total (378ms).
[15:00:03.226] <TB2> INFO: Test took 1154ms.
[15:00:03.226] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:03.619] <TB2> INFO: Expecting 41600 events.
[15:00:04.422] <TB2> INFO: 41600 events read in total (416ms).
[15:00:04.422] <TB2> INFO: Test took 1195ms.
[15:00:04.422] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:04.811] <TB2> INFO: Expecting 2560 events.
[15:00:05.229] <TB2> INFO: 2560 events read in total (31ms).
[15:00:05.229] <TB2> INFO: Test took 806ms.
[15:00:05.624] <TB2> INFO: Expecting 655360 events.
[15:00:11.326] <TB2> INFO: 655360 events read in total (5315ms).
[15:00:11.335] <TB2> INFO: Test took 6106ms.
[15:00:11.578] <TB2> INFO: Expecting 655360 events.
[15:00:17.090] <TB2> INFO: 655360 events read in total (5125ms).
[15:00:17.098] <TB2> INFO: Test took 5750ms.
[15:00:17.117] <TB2> INFO: safety margin for low PH: adding 0, margin is now 20
[15:00:17.323] <TB2> INFO: write dac parameters into /home/mameinha/data/R422_FulltestROC_m20_2015-12-04_15h33m_1449239629//000_FulltestROC_m20//dacParameters35_C0.dat
[15:00:17.693] <TB2> INFO: Expecting 41600 events.
[15:00:18.461] <TB2> INFO: 41600 events read in total (381ms).
[15:00:18.462] <TB2> INFO: Test took 788ms.
[15:00:18.851] <TB2> INFO: Expecting 41600 events.
[15:00:19.668] <TB2> INFO: 41600 events read in total (430ms).
[15:00:19.668] <TB2> INFO: Test took 1206ms.
[15:00:20.052] <TB2> INFO: Expecting 41600 events.
[15:00:20.861] <TB2> INFO: 41600 events read in total (422ms).
[15:00:20.861] <TB2> INFO: Test took 1192ms.
[15:00:21.240] <TB2> INFO: Expecting 2560 events.
[15:00:21.657] <TB2> INFO: 2560 events read in total (30ms).
[15:00:21.657] <TB2> INFO: Test took 795ms.
[15:00:22.052] <TB2> INFO: Expecting 2560 events.
[15:00:22.470] <TB2> INFO: 2560 events read in total (31ms).
[15:00:22.471] <TB2> INFO: Test took 814ms.
[15:00:22.880] <TB2> INFO: PixTestPhOptimization::doTest() done, duration: 21 seconds
[15:00:22.880] <TB2> INFO: PH scale (per ROC): 96
[15:00:22.880] <TB2> INFO: PH offset (per ROC): 155
[15:00:22.898] <TB2> INFO: enter test to run
[15:00:22.898] <TB2> INFO: test: GainPedestal no parameter change
[15:00:22.898] <TB2> INFO: running: gainpedestal
[15:00:22.899] <TB2> INFO: ######################################################################
[15:00:22.899] <TB2> INFO: PixTestGainPedestal::doTest() ntrig = 10
[15:00:22.899] <TB2> INFO: ######################################################################
[15:00:22.907] <TB2> INFO: scanning low vcal = 10
[15:00:22.926] <TB2> INFO: Expecting 41600 events.
[15:00:24.036] <TB2> INFO: 41600 events read in total (723ms).
[15:00:24.036] <TB2> INFO: Test took 1129ms.
[15:00:24.036] <TB2> INFO: scanning low vcal = 20
[15:00:24.431] <TB2> INFO: Expecting 41600 events.
[15:00:25.520] <TB2> INFO: 41600 events read in total (702ms).
[15:00:25.520] <TB2> INFO: Test took 1484ms.
[15:00:25.520] <TB2> INFO: scanning low vcal = 30
[15:00:25.915] <TB2> INFO: Expecting 41600 events.
[15:00:27.021] <TB2> INFO: 41600 events read in total (719ms).
[15:00:27.022] <TB2> INFO: Test took 1502ms.
[15:00:27.022] <TB2> INFO: scanning low vcal = 40
[15:00:27.416] <TB2> INFO: Expecting 41600 events.
[15:00:28.588] <TB2> INFO: 41600 events read in total (785ms).
[15:00:28.589] <TB2> INFO: Test took 1567ms.
[15:00:28.589] <TB2> INFO: scanning low vcal = 50
[15:00:28.977] <TB2> INFO: Expecting 41600 events.
[15:00:30.115] <TB2> INFO: 41600 events read in total (751ms).
[15:00:30.116] <TB2> INFO: Test took 1527ms.
[15:00:30.116] <TB2> INFO: scanning low vcal = 60
[15:00:30.501] <TB2> INFO: Expecting 41600 events.
[15:00:31.678] <TB2> INFO: 41600 events read in total (790ms).
[15:00:31.790] <TB2> INFO: Test took 1674ms.
[15:00:31.790] <TB2> INFO: scanning low vcal = 70
[15:00:32.061] <TB2> INFO: Expecting 41600 events.
[15:00:33.204] <TB2> INFO: 41600 events read in total (756ms).
[15:00:33.204] <TB2> INFO: Test took 1414ms.
[15:00:33.204] <TB2> INFO: scanning low vcal = 80
[15:00:33.593] <TB2> INFO: Expecting 41600 events.
[15:00:34.779] <TB2> INFO: 41600 events read in total (799ms).
[15:00:34.780] <TB2> INFO: Test took 1576ms.
[15:00:34.780] <TB2> INFO: scanning low vcal = 90
[15:00:35.164] <TB2> INFO: Expecting 41600 events.
[15:00:36.335] <TB2> INFO: 41600 events read in total (784ms).
[15:00:36.336] <TB2> INFO: Test took 1556ms.
[15:00:36.336] <TB2> INFO: scanning low vcal = 100
[15:00:36.720] <TB2> INFO: Expecting 41600 events.
[15:00:37.891] <TB2> INFO: 41600 events read in total (784ms).
[15:00:37.892] <TB2> INFO: Test took 1556ms.
[15:00:37.892] <TB2> INFO: scanning low vcal = 110
[15:00:38.271] <TB2> INFO: Expecting 41600 events.
[15:00:39.417] <TB2> INFO: 41600 events read in total (759ms).
[15:00:39.417] <TB2> INFO: Test took 1525ms.
[15:00:39.418] <TB2> INFO: scanning low vcal = 120
[15:00:39.804] <TB2> INFO: Expecting 41600 events.
[15:00:40.972] <TB2> INFO: 41600 events read in total (781ms).
[15:00:40.972] <TB2> INFO: Test took 1554ms.
[15:00:40.973] <TB2> INFO: scanning low vcal = 130
[15:00:41.353] <TB2> INFO: Expecting 41600 events.
[15:00:42.490] <TB2> INFO: 41600 events read in total (750ms).
[15:00:42.491] <TB2> INFO: Test took 1518ms.
[15:00:42.491] <TB2> INFO: scanning low vcal = 140
[15:00:42.876] <TB2> INFO: Expecting 41600 events.
[15:00:44.019] <TB2> INFO: 41600 events read in total (756ms).
[15:00:44.020] <TB2> INFO: Test took 1529ms.
[15:00:44.020] <TB2> INFO: scanning low vcal = 150
[15:00:44.409] <TB2> INFO: Expecting 41600 events.
[15:00:45.561] <TB2> INFO: 41600 events read in total (765ms).
[15:00:45.561] <TB2> INFO: Test took 1541ms.
[15:00:45.561] <TB2> INFO: scanning low vcal = 160
[15:00:45.950] <TB2> INFO: Expecting 41600 events.
[15:00:47.097] <TB2> INFO: 41600 events read in total (760ms).
[15:00:47.097] <TB2> INFO: Test took 1536ms.
[15:00:47.098] <TB2> INFO: scanning low vcal = 170
[15:00:47.484] <TB2> INFO: Expecting 41600 events.
[15:00:48.647] <TB2> INFO: 41600 events read in total (776ms).
[15:00:48.647] <TB2> INFO: Test took 1549ms.
[15:00:48.648] <TB2> INFO: scanning low vcal = 180
[15:00:49.029] <TB2> INFO: Expecting 41600 events.
[15:00:50.178] <TB2> INFO: 41600 events read in total (762ms).
[15:00:50.178] <TB2> INFO: Test took 1530ms.
[15:00:50.178] <TB2> INFO: scanning low vcal = 190
[15:00:50.561] <TB2> INFO: Expecting 41600 events.
[15:00:51.720] <TB2> INFO: 41600 events read in total (772ms).
[15:00:51.720] <TB2> INFO: Test took 1542ms.
[15:00:51.721] <TB2> INFO: scanning low vcal = 200
[15:00:52.106] <TB2> INFO: Expecting 41600 events.
[15:00:53.257] <TB2> INFO: 41600 events read in total (764ms).
[15:00:53.257] <TB2> INFO: Test took 1536ms.
[15:00:53.257] <TB2> INFO: scanning low vcal = 210
[15:00:53.637] <TB2> INFO: Expecting 41600 events.
[15:00:54.786] <TB2> INFO: 41600 events read in total (762ms).
[15:00:54.787] <TB2> INFO: Test took 1530ms.
[15:00:54.787] <TB2> INFO: scanning low vcal = 220
[15:00:55.168] <TB2> INFO: Expecting 41600 events.
[15:00:56.328] <TB2> INFO: 41600 events read in total (773ms).
[15:00:56.330] <TB2> INFO: Test took 1543ms.
[15:00:56.330] <TB2> INFO: scanning low vcal = 230
[15:00:56.713] <TB2> INFO: Expecting 41600 events.
[15:00:57.909] <TB2> INFO: 41600 events read in total (809ms).
[15:00:57.910] <TB2> INFO: Test took 1580ms.
[15:00:57.910] <TB2> INFO: scanning low vcal = 240
[15:00:58.292] <TB2> INFO: Expecting 41600 events.
[15:00:59.468] <TB2> INFO: 41600 events read in total (789ms).
[15:00:59.470] <TB2> INFO: Test took 1560ms.
[15:00:59.470] <TB2> INFO: scanning low vcal = 250
[15:00:59.857] <TB2> INFO: Expecting 41600 events.
[15:01:01.038] <TB2> INFO: 41600 events read in total (794ms).
[15:01:01.039] <TB2> INFO: Test took 1569ms.
[15:01:01.039] <TB2> INFO: scanning high vcal = 30 (= 210 in low range)
[15:01:01.421] <TB2> INFO: Expecting 41600 events.
[15:01:02.587] <TB2> INFO: 41600 events read in total (779ms).
[15:01:02.588] <TB2> INFO: Test took 1549ms.
[15:01:02.588] <TB2> INFO: scanning high vcal = 50 (= 350 in low range)
[15:01:02.969] <TB2> INFO: Expecting 41600 events.
[15:01:04.127] <TB2> INFO: 41600 events read in total (771ms).
[15:01:04.128] <TB2> INFO: Test took 1540ms.
[15:01:04.128] <TB2> INFO: scanning high vcal = 70 (= 490 in low range)
[15:01:04.515] <TB2> INFO: Expecting 41600 events.
[15:01:05.670] <TB2> INFO: 41600 events read in total (768ms).
[15:01:05.671] <TB2> INFO: Test took 1543ms.
[15:01:05.671] <TB2> INFO: scanning high vcal = 90 (= 630 in low range)
[15:01:06.055] <TB2> INFO: Expecting 41600 events.
[15:01:07.194] <TB2> INFO: 41600 events read in total (752ms).
[15:01:07.195] <TB2> INFO: Test took 1524ms.
[15:01:07.195] <TB2> INFO: scanning high vcal = 200 (= 1400 in low range)
[15:01:07.579] <TB2> INFO: Expecting 41600 events.
[15:01:08.716] <TB2> INFO: 41600 events read in total (750ms).
[15:01:08.717] <TB2> INFO: Test took 1522ms.
[15:01:09.097] <TB2> INFO: PixTestGainPedestal::measure() done
[15:01:11.127] <TB2> INFO: PixTestGainPedestal::fit() done
[15:01:11.128] <TB2> INFO: non-linearity mean: 0.959
[15:01:11.128] <TB2> INFO: non-linearity RMS: 0.006
[15:01:11.128] <TB2> INFO: write gain/ped parameters into /home/mameinha/data/R422_FulltestROC_m20_2015-12-04_15h33m_1449239629//000_FulltestROC_m20//phCalibrationFitErr35_C0.dat
[15:01:11.349] <TB2> INFO: PixTestGainPedestal::doTest() done, duration: 48 seconds
[15:01:11.350] <TB2> INFO: enter test to run
[15:01:11.350] <TB2> INFO: test: Readback no parameter change
[15:01:11.350] <TB2> INFO: running: readback
[15:01:11.350] <TB2> INFO: readReadbackCal: /home/mameinha/data/R422_FulltestROC_m20_2015-12-04_15h33m_1449239629//000_FulltestROC_m20//readbackCal_C0.dat .. /home/mameinha/data/R422_FulltestROC_m20_2015-12-04_15h33m_1449239629//000_FulltestROC_m20//readbackCal_C0.dat
[15:01:11.351] <TB2> INFO: ######################################################################
[15:01:11.351] <TB2> INFO: PixTestReadback::doTest()
[15:01:11.351] <TB2> INFO: ######################################################################
[15:01:11.351] <TB2> INFO: ----------------------------------------------------------------------
[15:01:11.351] <TB2> INFO: PixTestReadback::CalibrateVd()
[15:01:11.351] <TB2> INFO: ----------------------------------------------------------------------
[15:01:22.667] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R422_FulltestROC_m20_2015-12-04_15h33m_1449239629//000_FulltestROC_m20//readbackCal_C0.dat
[15:01:22.686] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[15:01:22.686] <TB2> INFO: ----------------------------------------------------------------------
[15:01:22.686] <TB2> INFO: PixTestReadback::CalibrateVa()
[15:01:22.686] <TB2> INFO: ----------------------------------------------------------------------
[15:01:34.011] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R422_FulltestROC_m20_2015-12-04_15h33m_1449239629//000_FulltestROC_m20//readbackCal_C0.dat
[15:01:34.034] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[15:01:34.034] <TB2> INFO: ----------------------------------------------------------------------
[15:01:34.034] <TB2> INFO: PixTestReadback::readbackVbg()
[15:01:34.034] <TB2> INFO: ----------------------------------------------------------------------
[15:01:42.363] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[15:01:42.363] <TB2> INFO: ----------------------------------------------------------------------
[15:01:42.363] <TB2> INFO: PixTestReadback::getCalibratedVbg()
[15:01:42.363] <TB2> INFO: ----------------------------------------------------------------------
[15:01:42.363] <TB2> INFO: Vbg will be calibrated using Vd calibration
[15:01:42.363] <TB2> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 146.7calibrated Vbg = 1.34601 :::*/*/*/*/
[15:01:42.740] <TB2> INFO: ----------------------------------------------------------------------
[15:01:42.740] <TB2> INFO: PixTestReadback::CalibrateIa()
[15:01:42.740] <TB2> INFO: ----------------------------------------------------------------------
[15:01:51.616] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R422_FulltestROC_m20_2015-12-04_15h33m_1449239629//000_FulltestROC_m20//readbackCal_C0.dat
[15:01:51.719] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[15:01:51.719] <TB2> INFO: PixTestReadback::doTest() done
[15:01:51.757] <TB2> INFO: enter test to run
[15:01:51.757] <TB2> INFO: test: no parameter change
[15:01:51.795] <TB2> QUIET: Connection to board 169 closed.
[15:01:51.875] <TB2> INFO: pXar: this is the end, my friend