[08:59:26.541] <TB3> INFO: *** Welcome to pxar ***
[08:59:26.541] <TB3> INFO: *** Today: 2015/10/06
[08:59:26.834] <TB3> INFO: *** Version: 9da6
[08:59:26.834] <TB3> INFO: readRocDacs: /home/mameinha/data/R420_Fulltest_p17_2015-10-06_10h59m_1444121955//000_FulltestROC_p17//dacParameters_C0.dat .. /home/mameinha/data/R420_Fulltest_p17_2015-10-06_10h59m_1444121955//000_FulltestROC_p17//dacParameters_C0.dat
[08:59:26.835] <TB3> INFO: readTbmDacs: /home/mameinha/data/R420_Fulltest_p17_2015-10-06_10h59m_1444121955//000_FulltestROC_p17//tbmParameters_C0a.dat .. /home/mameinha/data/R420_Fulltest_p17_2015-10-06_10h59m_1444121955//000_FulltestROC_p17//tbmParameters_C4294967295b.dat
[08:59:26.835] <TB3> INFO: readMaskFile: /home/mameinha/data/R420_Fulltest_p17_2015-10-06_10h59m_1444121955//000_FulltestROC_p17//defaultMaskFile.dat
[08:59:26.836] <TB3> INFO: readTrimFile: /home/mameinha/data/R420_Fulltest_p17_2015-10-06_10h59m_1444121955//000_FulltestROC_p17//trimParameters_C0.dat .. /home/mameinha/data/R420_Fulltest_p17_2015-10-06_10h59m_1444121955//000_FulltestROC_p17//trimParameters_C0.dat
[08:59:26.842] <TB3> INFO: clk: 4
[08:59:26.842] <TB3> INFO: ctr: 4
[08:59:26.842] <TB3> INFO: sda: 19
[08:59:26.842] <TB3> INFO: tin: 9
[08:59:26.842] <TB3> INFO: level: 15
[08:59:26.842] <TB3> INFO: deser160phase: 4
[08:59:26.842] <TB3> QUIET: Instanciating API for pxar v2.6.0+20~g1a7f656
[08:59:26.842] <TB3> INFO: Log level: INFO
[08:59:26.862] <TB3> QUIET: Connection to board DTB_WRQ4OZ opened.
[08:59:26.865] <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:
------------------------------------------------------
[08:59:26.868] <TB3> INFO: RPC call hashes of host and DTB match: 398089610
[08:59:28.031] <TB3> INFO: DUT info:
[08:59:28.031] <TB3> INFO: The DUT currently contains the following objects:
[08:59:28.031] <TB3> INFO: 0 TBM Cores (0 ON)
[08:59:28.031] <TB3> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[08:59:28.031] <TB3> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[08:59:28.432] <TB3> INFO: enter 'restricted' command line mode
[08:59:28.433] <TB3> INFO: enter test to run
[08:59:28.433] <TB3> INFO: test: Setup no parameter change
[08:59:28.433] <TB3> INFO: running: setup
[08:59:28.437] <TB3> INFO: PixTestSetup::doTest() ntrig = 10

[08:59:28.437] <TB3> INFO: PixTestSetup:: pg set to RES|TOK
[08:59:28.437] <TB3> INFO: 0 1 2 3 4 5 6 7
[08:59:31.479] <TB3> INFO: 0: 000 000 004 07c 7f0 f00 000 000
[08:59:34.492] <TB3> INFO: 1: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[08:59:37.506] <TB3> INFO: 2: 000 000 004 07c <7f8>[*] f80 800 000
[08:59:40.519] <TB3> INFO: 3: 000 000 004 07c <7f8>[*] f80 800 000
[08:59:43.532] <TB3> INFO: 4: 000 000 000 03c 3f8 f80 800 000
[08:59:46.545] <TB3> INFO: 5: 800 000 000 03c 3fc fc0 c00 000
[08:59:49.558] <TB3> INFO: 6: 000 000 000 03c 3fc fc0 c00 000
[08:59:52.570] <TB3> INFO: 7: 000 000 000 03c 3fc fc0 c00 000
[08:59:55.583] <TB3> INFO: 8: c00 000 000 03c 3fc fc0 c00 000
[08:59:58.596] <TB3> INFO: 9: 000 000 000 03c 3fc fc0 c00 000
[09:00:01.610] <TB3> INFO: 10: c00 000 000 01c 1fc fc0 c00 000
[09:00:04.623] <TB3> INFO: 11: 000 000 000 01c 1fc fe0 e00 000
[09:00:07.636] <TB3> INFO: 12: 000 000 000 01c 1fc fe0 e00 000
[09:00:10.650] <TB3> INFO: 13: 000 000 000 01c 1fc fe0 e00 000
[09:00:13.663] <TB3> INFO: 14: 000 000 000 00c 0fc fe0 e00 000
[09:00:16.676] <TB3> INFO: 15: 000 000 000 00c 0fc ff0 f00 000
[09:00:19.689] <TB3> INFO: 16: 000 000 000 00c 0fc ff0 f00 000
[09:00:22.701] <TB3> INFO: 17: 000 000 000 00c 0fc ff0 f00 000
[09:00:25.714] <TB3> INFO: 18: 000 000 000 00c 0fc ff0 f00 000
[09:00:28.727] <TB3> INFO: 19: 000 000 000 00c 0fc ff0 f00 000
[09:00:29.131] <TB3> INFO: Found good delays at CLK = 2, DESER160 = 4
[09:00:29.133] <TB3> INFO: PixTestSetup:: Write Tb parameters to file.
[09:00:29.136] <TB3> INFO: write dtb parameters into /home/mameinha/data/R420_Fulltest_p17_2015-10-06_10h59m_1444121955//000_FulltestROC_p17//tbParameters.dat
[09:00:29.139] <TB3> INFO: PixTestSetup::doTest() done for.
[09:00:29.163] <TB3> INFO: enter test to run
[09:00:29.164] <TB3> INFO: test: Pretest no parameter change
[09:00:29.164] <TB3> INFO: running: pretest
[09:00:29.165] <TB3> INFO: ----------------------------------------------------------------------
[09:00:29.165] <TB3> INFO: PixTestPretest::programROC()
[09:00:29.165] <TB3> INFO: ----------------------------------------------------------------------
[09:00:32.167] <TB3> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[09:00:32.167] <TB3> INFO: IA differences per ROC: 20.1
[09:00:32.171] <TB3> INFO: enter test to run
[09:00:32.171] <TB3> INFO: test: Pretest no parameter change
[09:00:32.171] <TB3> INFO: running: pretest
[09:00:32.173] <TB3> INFO: ----------------------------------------------------------------------
[09:00:32.173] <TB3> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[09:00:32.173] <TB3> INFO: ----------------------------------------------------------------------
[09:00:32.782] <TB3> INFO: PixTestPretest::setVana() done, Module Ia 24.1 mA = 24.1 mA/ROC
[09:00:32.782] <TB3> INFO: i(loss) [mA/ROC]: 18.5
[09:00:32.785] <TB3> INFO: enter test to run
[09:00:32.785] <TB3> INFO: test: Pretest no parameter change
[09:00:32.785] <TB3> INFO: running: pretest
[09:00:32.786] <TB3> INFO: ----------------------------------------------------------------------
[09:00:32.786] <TB3> INFO: PixTestPretest::findWorkingPixel()
[09:00:32.786] <TB3> INFO: ----------------------------------------------------------------------
[09:00:32.796] <TB3> INFO: Expecting 231680 events.
[09:00:34.991] <TB3> INFO: 231680 events read in total (1808ms).
[09:00:34.993] <TB3> INFO: Test took 2207ms.
[09:00:35.372] <TB3> INFO: Found working pixel in all ROCs: col/row = 12/22
[09:00:35.377] <TB3> INFO: enter test to run
[09:00:35.377] <TB3> INFO: test: Pretest no parameter change
[09:00:35.377] <TB3> INFO: running: pretest
[09:00:35.379] <TB3> INFO: ----------------------------------------------------------------------
[09:00:35.379] <TB3> INFO: PixTestPretest::setVthrCompCalDel()
[09:00:35.379] <TB3> INFO: ----------------------------------------------------------------------
[09:00:35.388] <TB3> INFO: Expecting 231680 events.
[09:00:37.583] <TB3> INFO: 231680 events read in total (1808ms).
[09:00:37.586] <TB3> INFO: Test took 2207ms.
[09:00:37.965] <TB3> INFO: PixTestPretest::setVthrCompCalDel() done
[09:00:37.965] <TB3> INFO: CalDel: 155
[09:00:37.965] <TB3> INFO: VthrComp: 51
[09:00:37.968] <TB3> INFO: enter test to run
[09:00:37.968] <TB3> INFO: test: Pretest no parameter change
[09:00:37.968] <TB3> INFO: running: pretest
[09:00:37.970] <TB3> INFO: write dac parameters into /home/mameinha/data/R420_Fulltest_p17_2015-10-06_10h59m_1444121955//000_FulltestROC_p17//dacParameters_C0.dat
[09:00:37.973] <TB3> INFO: enter test to run
[09:00:37.973] <TB3> INFO: test: PixelAlive no parameter change
[09:00:37.973] <TB3> INFO: running: pixelalive
[09:00:37.974] <TB3> INFO: ######################################################################
[09:00:37.975] <TB3> INFO: PixTestAlive::doTest()
[09:00:37.975] <TB3> INFO: ######################################################################
[09:00:37.976] <TB3> INFO: ----------------------------------------------------------------------
[09:00:37.976] <TB3> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[09:00:37.976] <TB3> INFO: ----------------------------------------------------------------------
[09:00:37.995] <TB3> INFO: Expecting 41600 events.
[09:00:38.792] <TB3> INFO: 41600 events read in total (410ms).
[09:00:38.792] <TB3> INFO: Test took 816ms.
[09:00:38.793] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:00:39.178] <TB3> INFO: PixTestAlive::aliveTest() done
[09:00:39.178] <TB3> INFO: number of dead pixels (per ROC): 0
[09:00:39.180] <TB3> INFO: ----------------------------------------------------------------------
[09:00:39.180] <TB3> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[09:00:39.180] <TB3> INFO: ----------------------------------------------------------------------
[09:00:39.199] <TB3> INFO: Expecting 41600 events.
[09:00:39.942] <TB3> INFO: 41600 events read in total (356ms).
[09:00:39.942] <TB3> INFO: Test took 762ms.
[09:00:39.942] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:00:39.943] <TB3> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[09:00:40.332] <TB3> INFO: PixTestAlive::maskTest() done
[09:00:40.332] <TB3> INFO: number of mask-defect pixels (per ROC): 0
[09:00:40.334] <TB3> INFO: ----------------------------------------------------------------------
[09:00:40.334] <TB3> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[09:00:40.334] <TB3> INFO: ----------------------------------------------------------------------
[09:00:40.353] <TB3> INFO: Expecting 41600 events.
[09:00:41.150] <TB3> INFO: 41600 events read in total (410ms).
[09:00:41.150] <TB3> INFO: Test took 816ms.
[09:00:41.150] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:00:41.536] <TB3> INFO: PixTestAlive::addressDecodingTest() done
[09:00:41.536] <TB3> INFO: number of address-decoding pixels (per ROC): 0
[09:00:41.536] <TB3> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[09:00:41.537] <TB3> INFO: enter test to run
[09:00:41.537] <TB3> INFO: test: Scurves no parameter change
[09:00:41.537] <TB3> INFO: running: scurves
[09:00:41.538] <TB3> INFO: ######################################################################
[09:00:41.538] <TB3> INFO: PixTestScurves::doTest() ntrig = 50
[09:00:41.538] <TB3> INFO: ######################################################################
[09:00:41.538] <TB3> INFO: ----------------------------------------------------------------------
[09:00:41.538] <TB3> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[09:00:41.538] <TB3> INFO: ----------------------------------------------------------------------
[09:00:41.538] <TB3> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[09:00:41.549] <TB3> INFO: dacScan split into 1 runs with ntrig = 50
[09:00:41.549] <TB3> INFO: run 1 of 1
[09:00:41.568] <TB3> INFO: Expecting 41808000 events.
[09:03:01.670] <TB3> INFO: 20043650 events read in total (139715ms).
[09:05:20.111] <TB3> INFO: 39897600 events read in total (278156ms).
[09:05:33.313] <TB3> INFO: 41808000 events read in total (291358ms).
[09:05:33.358] <TB3> INFO: Test took 291809ms.
[09:05:33.392] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:05:35.080] <TB3> INFO: PixTestScurves::scurves() done
[09:05:35.080] <TB3> INFO: Vcal mean: 86.57
[09:05:35.080] <TB3> INFO: Vcal RMS: 4.89
[09:05:35.085] <TB3> INFO: enter test to run
[09:05:35.085] <TB3> INFO: test: Trim no parameter change
[09:05:35.085] <TB3> INFO: running: trim
[09:05:35.086] <TB3> INFO: ######################################################################
[09:05:35.086] <TB3> INFO: PixTestTrim::doTest()
[09:05:35.086] <TB3> INFO: ######################################################################
[09:05:35.087] <TB3> INFO: ----------------------------------------------------------------------
[09:05:35.087] <TB3> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[09:05:35.087] <TB3> INFO: ----------------------------------------------------------------------
[09:05:35.092] <TB3> INFO: ---> VthrComp thr map (minimal VthrComp)
[09:05:35.092] <TB3> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[09:05:35.100] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:05:35.100] <TB3> INFO: run 1 of 1
[09:05:35.118] <TB3> INFO: Expecting 6281600 events.
[09:06:20.753] <TB3> INFO: 6281600 events read in total (45242ms).
[09:06:20.775] <TB3> INFO: Test took 45675ms.
[09:06:20.786] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:06:21.854] <TB3> INFO: ROC 0 VthrComp = 90
[09:06:21.854] <TB3> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[09:06:21.854] <TB3> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[09:06:21.862] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:06:21.862] <TB3> INFO: run 1 of 1
[09:06:21.881] <TB3> INFO: Expecting 6281600 events.
[09:07:10.907] <TB3> INFO: 6281600 events read in total (48640ms).
[09:07:10.976] <TB3> INFO: Test took 49114ms.
[09:07:11.003] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:07:12.258] <TB3> INFO: roc 0 with ID = 0 has maximal Vcal 56.7419 for pixel 20/7 mean/min/max = 45.4527/34.0546/56.8507
[09:07:12.267] <TB3> INFO: Expecting 514560 events.
[09:07:16.251] <TB3> INFO: 514560 events read in total (3597ms).
[09:07:16.255] <TB3> INFO: Test took 3996ms.
[09:07:16.651] <TB3> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[09:07:16.658] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:07:16.658] <TB3> INFO: run 1 of 1
[09:07:16.677] <TB3> INFO: Expecting 6281600 events.
[09:08:05.870] <TB3> INFO: 6281600 events read in total (48806ms).
[09:08:05.918] <TB3> INFO: Test took 49260ms.
[09:08:05.938] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:08:07.194] <TB3> INFO: ---> TrimStepCorr4 extremal thresholds: 15.088063 .. 48.640707
[09:08:07.199] <TB3> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 5 .. 58 (-1/-1) hits flags = 528 (plus default)
[09:08:07.207] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:08:07.207] <TB3> INFO: run 1 of 1
[09:08:07.226] <TB3> INFO: Expecting 2246400 events.
[09:08:24.493] <TB3> INFO: 2246400 events read in total (16880ms).
[09:08:24.506] <TB3> INFO: Test took 17299ms.
[09:08:24.513] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:08:25.453] <TB3> INFO: ---> TrimStepCorr2 extremal thresholds: 23.682218 .. 43.524939
[09:08:25.457] <TB3> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 13 .. 53 (-1/-1) hits flags = 528 (plus default)
[09:08:25.465] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:08:25.465] <TB3> INFO: run 1 of 1
[09:08:25.484] <TB3> INFO: Expecting 1705600 events.
[09:08:38.804] <TB3> INFO: 1705600 events read in total (12933ms).
[09:08:38.811] <TB3> INFO: Test took 13346ms.
[09:08:38.815] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:08:39.584] <TB3> INFO: ---> TrimStepCorr1a extremal thresholds: 27.226683 .. 41.196115
[09:08:39.588] <TB3> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 17 .. 51 (-1/-1) hits flags = 528 (plus default)
[09:08:39.596] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:08:39.596] <TB3> INFO: run 1 of 1
[09:08:39.614] <TB3> INFO: Expecting 1456000 events.
[09:08:51.165] <TB3> INFO: 1456000 events read in total (11163ms).
[09:08:51.172] <TB3> INFO: Test took 11576ms.
[09:08:51.175] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:08:51.930] <TB3> INFO: ---> TrimStepCorr1b extremal thresholds: 28.809726 .. 40.935994
[09:08:51.934] <TB3> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 18 .. 50 (-1/-1) hits flags = 528 (plus default)
[09:08:51.941] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:08:51.941] <TB3> INFO: run 1 of 1
[09:08:51.960] <TB3> INFO: Expecting 1372800 events.
[09:09:02.885] <TB3> INFO: 1372800 events read in total (10538ms).
[09:09:02.891] <TB3> INFO: Test took 10950ms.
[09:09:02.895] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:09:03.641] <TB3> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[09:09:03.641] <TB3> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[09:09:03.648] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:09:03.648] <TB3> INFO: run 1 of 1
[09:09:03.667] <TB3> INFO: Expecting 1705600 events.
[09:09:17.092] <TB3> INFO: 1705600 events read in total (13038ms).
[09:09:17.100] <TB3> INFO: Test took 13452ms.
[09:09:17.105] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:09:17.896] <TB3> INFO: write dac parameters into /home/mameinha/data/R420_Fulltest_p17_2015-10-06_10h59m_1444121955//000_FulltestROC_p17//dacParameters35_C0.dat
[09:09:17.900] <TB3> INFO: write trim parameters into /home/mameinha/data/R420_Fulltest_p17_2015-10-06_10h59m_1444121955//000_FulltestROC_p17//trimParameters35_C0.dat
[09:09:17.910] <TB3> INFO: PixTestTrim::trimTest() done
[09:09:17.910] <TB3> INFO: vtrim: 95
[09:09:17.910] <TB3> INFO: vthrcomp: 90
[09:09:17.910] <TB3> INFO: vcal mean: 35.00
[09:09:17.910] <TB3> INFO: vcal RMS: 0.71
[09:09:17.910] <TB3> INFO: bits mean: 9.23
[09:09:17.910] <TB3> INFO: bits RMS: 2.59
[09:09:17.914] <TB3> INFO: ----------------------------------------------------------------------
[09:09:17.914] <TB3> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[09:09:17.914] <TB3> INFO: ----------------------------------------------------------------------
[09:09:17.914] <TB3> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[09:09:17.922] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:09:17.922] <TB3> INFO: run 1 of 1
[09:09:17.942] <TB3> INFO: Expecting 8320000 events.
[09:10:19.825] <TB3> INFO: 8320000 events read in total (61496ms).
[09:10:19.862] <TB3> INFO: Test took 61940ms.
[09:10:19.879] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:10:21.324] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 152 (-1/-1) hits flags = 528 (plus default)
[09:10:21.332] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:10:21.332] <TB3> INFO: run 1 of 1
[09:10:21.351] <TB3> INFO: Expecting 6364800 events.
[09:11:08.298] <TB3> INFO: 6364800 events read in total (46560ms).
[09:11:08.319] <TB3> INFO: Test took 46987ms.
[09:11:08.329] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:11:09.564] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 142 (-1/-1) hits flags = 528 (plus default)
[09:11:09.571] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:11:09.571] <TB3> INFO: run 1 of 1
[09:11:09.590] <TB3> INFO: Expecting 5948800 events.
[09:11:53.259] <TB3> INFO: 5948800 events read in total (43282ms).
[09:11:53.276] <TB3> INFO: Test took 43705ms.
[09:11:53.285] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:11:54.451] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 142 (-1/-1) hits flags = 528 (plus default)
[09:11:54.459] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:11:54.459] <TB3> INFO: run 1 of 1
[09:11:54.478] <TB3> INFO: Expecting 5948800 events.
[09:12:38.168] <TB3> INFO: 5948800 events read in total (43303ms).
[09:12:38.185] <TB3> INFO: Test took 43726ms.
[09:12:38.194] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:12:39.355] <TB3> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 143 (-1/-1) hits flags = 528 (plus default)
[09:12:39.362] <TB3> INFO: dacScan split into 1 runs with ntrig = 10
[09:12:39.362] <TB3> INFO: run 1 of 1
[09:12:39.381] <TB3> INFO: Expecting 5990400 events.
[09:13:23.405] <TB3> INFO: 5990400 events read in total (43637ms).
[09:13:23.422] <TB3> INFO: Test took 44060ms.
[09:13:23.431] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:13:24.601] <TB3> INFO: PixTestTrim::trimBitTest() done
[09:13:24.602] <TB3> INFO: PixTestTrim::doTest() done, duration: 469 seconds
[09:13:24.641] <TB3> INFO: enter test to run
[09:13:24.642] <TB3> INFO: test: PhOptimization no parameter change
[09:13:24.642] <TB3> INFO: running: phoptimization
[09:13:24.642] <TB3> INFO: ######################################################################
[09:13:24.642] <TB3> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[09:13:24.642] <TB3> INFO: ######################################################################
[09:13:24.662] <TB3> INFO: Expecting 41600 events.
[09:13:25.459] <TB3> INFO: 41600 events read in total (410ms).
[09:13:25.459] <TB3> INFO: Test took 816ms.
[09:13:25.459] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:13:25.850] <TB3> INFO: Expecting 41600 events.
[09:13:26.649] <TB3> INFO: 41600 events read in total (412ms).
[09:13:26.650] <TB3> INFO: Test took 1190ms.
[09:13:26.650] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:13:27.039] <TB3> INFO: Expecting 41600 events.
[09:13:27.837] <TB3> INFO: 41600 events read in total (411ms).
[09:13:27.837] <TB3> INFO: Test took 1186ms.
[09:13:27.837] <TB3> INFO: Fetched DAQ statistics. Counters are being reset now.
[09:13:28.226] <TB3> INFO: Expecting 2560 events.
[09:13:28.644] <TB3> INFO: 2560 events read in total (31ms).
[09:13:28.644] <TB3> INFO: Test took 806ms.
[09:13:29.040] <TB3> INFO: Expecting 655360 events.
[09:13:34.258] <TB3> INFO: 655360 events read in total (4831ms).
[09:13:34.266] <TB3> INFO: Test took 5621ms.
[09:13:34.562] <TB3> INFO: Expecting 655360 events.
[09:13:39.778] <TB3> INFO: 655360 events read in total (4829ms).
[09:13:39.786] <TB3> INFO: Test took 5507ms.
[09:13:39.805] <TB3> INFO: safety margin for low PH: adding 0, margin is now 20
[09:13:39.838] <TB3> INFO: write dac parameters into /home/mameinha/data/R420_Fulltest_p17_2015-10-06_10h59m_1444121955//000_FulltestROC_p17//dacParameters35_C0.dat
[09:13:40.081] <TB3> INFO: Expecting 41600 events.
[09:13:40.842] <TB3> INFO: 41600 events read in total (374ms).
[09:13:40.842] <TB3> INFO: Test took 1002ms.
[09:13:41.231] <TB3> INFO: Expecting 41600 events.
[09:13:41.992] <TB3> INFO: 41600 events read in total (374ms).
[09:13:41.992] <TB3> INFO: Test took 1149ms.
[09:13:42.381] <TB3> INFO: Expecting 41600 events.
[09:13:43.142] <TB3> INFO: 41600 events read in total (374ms).
[09:13:43.142] <TB3> INFO: Test took 1149ms.
[09:13:43.531] <TB3> INFO: Expecting 2560 events.
[09:13:43.949] <TB3> INFO: 2560 events read in total (31ms).
[09:13:43.949] <TB3> INFO: Test took 806ms.
[09:13:44.344] <TB3> INFO: Expecting 2560 events.
[09:13:44.762] <TB3> INFO: 2560 events read in total (31ms).
[09:13:44.762] <TB3> INFO: Test took 812ms.
[09:13:45.171] <TB3> INFO: PixTestPhOptimization::doTest() done, duration: 20 seconds
[09:13:45.171] <TB3> INFO: PH scale (per ROC): 80
[09:13:45.171] <TB3> INFO: PH offset (per ROC): 162
[09:13:45.184] <TB3> INFO: enter test to run
[09:13:45.184] <TB3> INFO: test: GainPedestal no parameter change
[09:13:45.184] <TB3> INFO: running: gainpedestal
[09:13:45.186] <TB3> INFO: ######################################################################
[09:13:45.186] <TB3> INFO: PixTestGainPedestal::doTest() ntrig = 10
[09:13:45.186] <TB3> INFO: ######################################################################
[09:13:45.194] <TB3> INFO: scanning low vcal = 10
[09:13:45.213] <TB3> INFO: Expecting 41600 events.
[09:13:46.302] <TB3> INFO: 41600 events read in total (702ms).
[09:13:46.302] <TB3> INFO: Test took 1108ms.
[09:13:46.302] <TB3> INFO: scanning low vcal = 20
[09:13:46.697] <TB3> INFO: Expecting 41600 events.
[09:13:47.786] <TB3> INFO: 41600 events read in total (702ms).
[09:13:47.786] <TB3> INFO: Test took 1484ms.
[09:13:47.786] <TB3> INFO: scanning low vcal = 30
[09:13:48.181] <TB3> INFO: Expecting 41600 events.
[09:13:49.270] <TB3> INFO: 41600 events read in total (702ms).
[09:13:49.271] <TB3> INFO: Test took 1485ms.
[09:13:49.271] <TB3> INFO: scanning low vcal = 40
[09:13:49.665] <TB3> INFO: Expecting 41600 events.
[09:13:50.788] <TB3> INFO: 41600 events read in total (736ms).
[09:13:50.789] <TB3> INFO: Test took 1518ms.
[09:13:50.789] <TB3> INFO: scanning low vcal = 50
[09:13:51.178] <TB3> INFO: Expecting 41600 events.
[09:13:52.302] <TB3> INFO: 41600 events read in total (737ms).
[09:13:52.302] <TB3> INFO: Test took 1513ms.
[09:13:52.303] <TB3> INFO: scanning low vcal = 60
[09:13:52.691] <TB3> INFO: Expecting 41600 events.
[09:13:53.815] <TB3> INFO: 41600 events read in total (737ms).
[09:13:53.816] <TB3> INFO: Test took 1513ms.
[09:13:53.816] <TB3> INFO: scanning low vcal = 70
[09:13:54.205] <TB3> INFO: Expecting 41600 events.
[09:13:55.329] <TB3> INFO: 41600 events read in total (737ms).
[09:13:55.329] <TB3> INFO: Test took 1513ms.
[09:13:55.330] <TB3> INFO: scanning low vcal = 80
[09:13:55.719] <TB3> INFO: Expecting 41600 events.
[09:13:56.851] <TB3> INFO: 41600 events read in total (745ms).
[09:13:56.852] <TB3> INFO: Test took 1522ms.
[09:13:56.852] <TB3> INFO: scanning low vcal = 90
[09:13:57.241] <TB3> INFO: Expecting 41600 events.
[09:13:58.372] <TB3> INFO: 41600 events read in total (737ms).
[09:13:58.373] <TB3> INFO: Test took 1521ms.
[09:13:58.373] <TB3> INFO: scanning low vcal = 100
[09:13:58.762] <TB3> INFO: Expecting 41600 events.
[09:13:59.894] <TB3> INFO: 41600 events read in total (745ms).
[09:13:59.895] <TB3> INFO: Test took 1522ms.
[09:13:59.896] <TB3> INFO: scanning low vcal = 110
[09:14:00.284] <TB3> INFO: Expecting 41600 events.
[09:14:01.409] <TB3> INFO: 41600 events read in total (738ms).
[09:14:01.410] <TB3> INFO: Test took 1514ms.
[09:14:01.410] <TB3> INFO: scanning low vcal = 120
[09:14:01.799] <TB3> INFO: Expecting 41600 events.
[09:14:02.923] <TB3> INFO: 41600 events read in total (737ms).
[09:14:02.923] <TB3> INFO: Test took 1513ms.
[09:14:02.924] <TB3> INFO: scanning low vcal = 130
[09:14:03.312] <TB3> INFO: Expecting 41600 events.
[09:14:04.437] <TB3> INFO: 41600 events read in total (738ms).
[09:14:04.437] <TB3> INFO: Test took 1513ms.
[09:14:04.438] <TB3> INFO: scanning low vcal = 140
[09:14:04.826] <TB3> INFO: Expecting 41600 events.
[09:14:05.951] <TB3> INFO: 41600 events read in total (738ms).
[09:14:05.951] <TB3> INFO: Test took 1513ms.
[09:14:05.951] <TB3> INFO: scanning low vcal = 150
[09:14:06.340] <TB3> INFO: Expecting 41600 events.
[09:14:07.465] <TB3> INFO: 41600 events read in total (737ms).
[09:14:07.466] <TB3> INFO: Test took 1515ms.
[09:14:07.466] <TB3> INFO: scanning low vcal = 160
[09:14:07.855] <TB3> INFO: Expecting 41600 events.
[09:14:08.979] <TB3> INFO: 41600 events read in total (737ms).
[09:14:08.980] <TB3> INFO: Test took 1514ms.
[09:14:08.980] <TB3> INFO: scanning low vcal = 170
[09:14:09.369] <TB3> INFO: Expecting 41600 events.
[09:14:10.493] <TB3> INFO: 41600 events read in total (737ms).
[09:14:10.494] <TB3> INFO: Test took 1514ms.
[09:14:10.494] <TB3> INFO: scanning low vcal = 180
[09:14:10.883] <TB3> INFO: Expecting 41600 events.
[09:14:12.007] <TB3> INFO: 41600 events read in total (737ms).
[09:14:12.007] <TB3> INFO: Test took 1513ms.
[09:14:12.008] <TB3> INFO: scanning low vcal = 190
[09:14:12.396] <TB3> INFO: Expecting 41600 events.
[09:14:13.521] <TB3> INFO: 41600 events read in total (737ms).
[09:14:13.522] <TB3> INFO: Test took 1514ms.
[09:14:13.522] <TB3> INFO: scanning low vcal = 200
[09:14:13.911] <TB3> INFO: Expecting 41600 events.
[09:14:15.036] <TB3> INFO: 41600 events read in total (738ms).
[09:14:15.036] <TB3> INFO: Test took 1514ms.
[09:14:15.036] <TB3> INFO: scanning low vcal = 210
[09:14:15.425] <TB3> INFO: Expecting 41600 events.
[09:14:16.550] <TB3> INFO: 41600 events read in total (738ms).
[09:14:16.550] <TB3> INFO: Test took 1514ms.
[09:14:16.551] <TB3> INFO: scanning low vcal = 220
[09:14:16.939] <TB3> INFO: Expecting 41600 events.
[09:14:18.064] <TB3> INFO: 41600 events read in total (738ms).
[09:14:18.064] <TB3> INFO: Test took 1513ms.
[09:14:18.065] <TB3> INFO: scanning low vcal = 230
[09:14:18.454] <TB3> INFO: Expecting 41600 events.
[09:14:19.580] <TB3> INFO: 41600 events read in total (739ms).
[09:14:19.580] <TB3> INFO: Test took 1515ms.
[09:14:19.581] <TB3> INFO: scanning low vcal = 240
[09:14:19.968] <TB3> INFO: Expecting 41600 events.
[09:14:21.092] <TB3> INFO: 41600 events read in total (737ms).
[09:14:21.093] <TB3> INFO: Test took 1512ms.
[09:14:21.093] <TB3> INFO: scanning low vcal = 250
[09:14:21.482] <TB3> INFO: Expecting 41600 events.
[09:14:22.606] <TB3> INFO: 41600 events read in total (737ms).
[09:14:22.606] <TB3> INFO: Test took 1513ms.
[09:14:22.607] <TB3> INFO: scanning high vcal = 30 (= 210 in low range)
[09:14:22.996] <TB3> INFO: Expecting 41600 events.
[09:14:24.120] <TB3> INFO: 41600 events read in total (737ms).
[09:14:24.120] <TB3> INFO: Test took 1513ms.
[09:14:24.120] <TB3> INFO: scanning high vcal = 50 (= 350 in low range)
[09:14:24.509] <TB3> INFO: Expecting 41600 events.
[09:14:25.634] <TB3> INFO: 41600 events read in total (738ms).
[09:14:25.634] <TB3> INFO: Test took 1514ms.
[09:14:25.634] <TB3> INFO: scanning high vcal = 70 (= 490 in low range)
[09:14:26.023] <TB3> INFO: Expecting 41600 events.
[09:14:27.148] <TB3> INFO: 41600 events read in total (738ms).
[09:14:27.148] <TB3> INFO: Test took 1514ms.
[09:14:27.148] <TB3> INFO: scanning high vcal = 90 (= 630 in low range)
[09:14:27.537] <TB3> INFO: Expecting 41600 events.
[09:14:28.662] <TB3> INFO: 41600 events read in total (738ms).
[09:14:28.662] <TB3> INFO: Test took 1514ms.
[09:14:28.662] <TB3> INFO: scanning high vcal = 200 (= 1400 in low range)
[09:14:29.051] <TB3> INFO: Expecting 41600 events.
[09:14:30.176] <TB3> INFO: 41600 events read in total (738ms).
[09:14:30.176] <TB3> INFO: Test took 1513ms.
[09:14:30.560] <TB3> INFO: PixTestGainPedestal::measure() done
[09:14:32.500] <TB3> INFO: PixTestGainPedestal::fit() done
[09:14:32.501] <TB3> INFO: non-linearity mean: 0.960
[09:14:32.501] <TB3> INFO: non-linearity RMS: 0.006
[09:14:32.501] <TB3> INFO: write gain/ped parameters into /home/mameinha/data/R420_Fulltest_p17_2015-10-06_10h59m_1444121955//000_FulltestROC_p17//phCalibrationFitErr35_C0.dat
[09:14:32.546] <TB3> INFO: PixTestGainPedestal::doTest() done, duration: 47 seconds
[09:14:32.547] <TB3> INFO: enter test to run
[09:14:32.547] <TB3> INFO: test: Readback no parameter change
[09:14:32.547] <TB3> INFO: running: readback
[09:14:32.547] <TB3> INFO: readReadbackCal: /home/mameinha/data/R420_Fulltest_p17_2015-10-06_10h59m_1444121955//000_FulltestROC_p17//readbackCal_C0.dat .. /home/mameinha/data/R420_Fulltest_p17_2015-10-06_10h59m_1444121955//000_FulltestROC_p17//readbackCal_C0.dat
[09:14:32.560] <TB3> INFO: ######################################################################
[09:14:32.560] <TB3> INFO: PixTestReadback::doTest()
[09:14:32.560] <TB3> INFO: ######################################################################
[09:14:32.561] <TB3> INFO: PixTestReadback::RES sent once
[09:14:43.698] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R420_Fulltest_p17_2015-10-06_10h59m_1444121955//000_FulltestROC_p17//readbackCal_C0.dat
[09:14:43.704] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[09:14:43.705] <TB3> INFO: PixTestReadback::RES sent once
[09:14:54.820] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R420_Fulltest_p17_2015-10-06_10h59m_1444121955//000_FulltestROC_p17//readbackCal_C0.dat
[09:14:54.838] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[09:14:54.838] <TB3> INFO: PixTestReadback::RES sent once
[09:15:03.168] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[09:15:03.169] <TB3> INFO: Vbg will be calibrated using Vd calibration
[09:15:03.169] <TB3> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 159.7calibrated Vbg = 1.2248 :::*/*/*/*/
[09:15:03.545] <TB3> INFO: PixTestReadback::RES sent once
[09:15:12.388] <TB3> INFO: write readback calibration parameters into /home/mameinha/data/R420_Fulltest_p17_2015-10-06_10h59m_1444121955//000_FulltestROC_p17//readbackCal_C0.dat
[09:15:12.393] <TB3> INFO: PixTestPattern:: pg_setup set to default.
[09:15:12.393] <TB3> INFO: PixTestReadback::doTest() done
[09:15:12.425] <TB3> INFO: enter test to run
[09:15:12.425] <TB3> INFO: test: no parameter change
[09:15:12.481] <TB3> QUIET: Connection to board 71 closed.
[09:15:12.560] <TB3> INFO: pXar: this is the end, my friend