[13:47:52.729] <TB2> INFO: *** Welcome to pxar ***
[13:47:52.729] <TB2> INFO: *** Today: 2015/10/07
[13:47:53.042] <TB2> INFO: *** Version: 9da6
[13:47:53.042] <TB2> INFO: readRocDacs: /home/mameinha/data/R421_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//dacParameters_C0.dat .. /home/mameinha/data/R421_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//dacParameters_C0.dat
[13:47:53.043] <TB2> INFO: readTbmDacs: /home/mameinha/data/R421_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//tbmParameters_C0a.dat .. /home/mameinha/data/R421_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//tbmParameters_C4294967295b.dat
[13:47:53.043] <TB2> INFO: readMaskFile: /home/mameinha/data/R421_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//defaultMaskFile.dat
[13:47:53.044] <TB2> INFO: readTrimFile: /home/mameinha/data/R421_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//trimParameters_C0.dat .. /home/mameinha/data/R421_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//trimParameters_C0.dat
[13:47:53.055] <TB2> INFO: clk: 2
[13:47:53.055] <TB2> INFO: ctr: 2
[13:47:53.055] <TB2> INFO: sda: 17
[13:47:53.055] <TB2> INFO: tin: 7
[13:47:53.055] <TB2> INFO: level: 15
[13:47:53.055] <TB2> INFO: deser160phase: 4
[13:47:53.055] <TB2> QUIET: Instanciating API for pxar v2.6.0+20~g1a7f656
[13:47:53.055] <TB2> INFO: Log level: INFO
[13:47:53.061] <TB2> INFO: Found DTB DTB_WWXJGB
[13:47:53.069] <TB2> QUIET: Connection to board DTB_WWXJGB opened.
[13:47:53.073] <TB2> INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 137
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WWXJGB
MAC address: 40D855118089
Hostname: pixelDTB137
Comment:
------------------------------------------------------
[13:47:53.075] <TB2> INFO: RPC call hashes of host and DTB match: 398089610
[13:47:54.239] <TB2> INFO: DUT info:
[13:47:54.239] <TB2> INFO: The DUT currently contains the following objects:
[13:47:54.239] <TB2> INFO: 0 TBM Cores (0 ON)
[13:47:54.239] <TB2> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[13:47:54.239] <TB2> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[13:47:54.640] <TB2> INFO: enter 'restricted' command line mode
[13:47:54.640] <TB2> INFO: enter test to run
[13:47:54.640] <TB2> INFO: test: Setup no parameter change
[13:47:54.640] <TB2> INFO: running: setup
[13:47:54.645] <TB2> INFO: PixTestSetup::doTest() ntrig = 10
[13:47:54.645] <TB2> WARNING: Pattern generator does not contain a trigger signal. No data is expected from the DUT!
[13:47:54.645] <TB2> INFO: PixTestSetup:: pg set to RES|TOK
[13:47:54.645] <TB2> INFO: 0 1 2 3 4 5 6 7
[13:47:57.688] <TB2> INFO: 0: 000 008 08c 8fc ff0 f00 000 000
[13:48:00.701] <TB2> INFO: 1: 000 008 084 87c <7f8>[*] f80 800 000
[13:48:03.715] <TB2> INFO: 2: 000 008 0c4 87c <7f8>[*] f80 <7f8>[1] 000
[13:48:06.729] <TB2> INFO: 3: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[13:48:09.743] <TB2> INFO: 4: 000 004 004 07c <7f8>[*] f80 800 000
[13:48:12.757] <TB2> INFO: 5: 000 004 040 43c 3f8 f80 800 000
[13:48:15.771] <TB2> INFO: 6: 000 004 040 43c 3fc fc0 c00 000
[13:48:18.785] <TB2> INFO: 7: 000 004 040 43c 3fc fc0 c00 000
[13:48:21.799] <TB2> INFO: 8: 000 000 020 03c 3fc fc0 c00 000
[13:48:24.813] <TB2> INFO: 9: c00 000 020 23c 3fc fc0 c00 000
[13:48:27.827] <TB2> INFO: 10: c00 000 020 23c 1fc fc0 c00 000
[13:48:30.841] <TB2> INFO: 11: 000 000 020 21c 1fc fe0 e00 000
[13:48:33.855] <TB2> INFO: 12: 000 000 020 21c 1fc fe0 e00 000
[13:48:36.870] <TB2> INFO: 13: 000 000 000 01c 1fc fe0 e00 000
[13:48:39.883] <TB2> INFO: 14: e00 000 010 11c 1fc fe0 e00 000
[13:48:42.897] <TB2> INFO: 15: e00 000 010 10c 0fc ff0 e00 000
[13:48:45.911] <TB2> INFO: 16: 000 000 010 10c 0fc ff0 f00 000
[13:48:48.925] <TB2> INFO: 17: 000 000 010 10c 0fc ff0 f00 000
[13:48:51.939] <TB2> INFO: 18: 000 000 000 00c 0fc ff0 f00 000
[13:48:54.952] <TB2> INFO: 19: 000 000 008 08c 8fc ff0 f00 000
[13:48:55.363] <TB2> INFO: Found good delays at CLK = 2, DESER160 = 4
[13:48:55.365] <TB2> INFO: PixTestSetup:: Write Tb parameters to file.
[13:48:55.384] <TB2> INFO: write dtb parameters into /home/mameinha/data/R421_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//tbParameters.dat
[13:48:55.387] <TB2> INFO: PixTestSetup::doTest() done for.
[13:48:55.425] <TB2> INFO: enter test to run
[13:48:55.425] <TB2> INFO: test: Pretest no parameter change
[13:48:55.425] <TB2> INFO: running: pretest
[13:48:55.427] <TB2> INFO: ----------------------------------------------------------------------
[13:48:55.427] <TB2> INFO: PixTestPretest::programROC()
[13:48:55.427] <TB2> INFO: ----------------------------------------------------------------------
[13:48:58.429] <TB2> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[13:48:58.429] <TB2> INFO: IA differences per ROC: 15.2
[13:48:58.433] <TB2> INFO: enter test to run
[13:48:58.434] <TB2> INFO: test: Pretest no parameter change
[13:48:58.434] <TB2> INFO: running: pretest
[13:48:58.435] <TB2> INFO: ----------------------------------------------------------------------
[13:48:58.435] <TB2> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[13:48:58.435] <TB2> INFO: ----------------------------------------------------------------------
[13:48:59.147] <TB2> INFO: PixTestPretest::setVana() done, Module Ia 24.1 mA = 24.1 mA/ROC
[13:48:59.147] <TB2> INFO: i(loss) [mA/ROC]: 20.9
[13:48:59.151] <TB2> INFO: enter test to run
[13:48:59.151] <TB2> INFO: test: Pretest no parameter change
[13:48:59.151] <TB2> INFO: running: pretest
[13:48:59.153] <TB2> INFO: ----------------------------------------------------------------------
[13:48:59.153] <TB2> INFO: PixTestPretest::findWorkingPixel()
[13:48:59.153] <TB2> INFO: ----------------------------------------------------------------------
[13:48:59.163] <TB2> INFO: Expecting 231680 events.
[13:49:01.377] <TB2> INFO: 231680 events read in total (1827ms).
[13:49:01.379] <TB2> INFO: Test took 2226ms.
[13:49:01.760] <TB2> INFO: Found working pixel in all ROCs: col/row = 12/22
[13:49:01.770] <TB2> INFO: enter test to run
[13:49:01.770] <TB2> INFO: test: Pretest no parameter change
[13:49:01.770] <TB2> INFO: running: pretest
[13:49:01.772] <TB2> INFO: ----------------------------------------------------------------------
[13:49:01.772] <TB2> INFO: PixTestPretest::setVthrCompCalDel()
[13:49:01.772] <TB2> INFO: ----------------------------------------------------------------------
[13:49:01.781] <TB2> INFO: Expecting 231680 events.
[13:49:04.010] <TB2> INFO: 231680 events read in total (1842ms).
[13:49:04.014] <TB2> INFO: Test took 2242ms.
[13:49:04.388] <TB2> INFO: PixTestPretest::setVthrCompCalDel() done
[13:49:04.388] <TB2> INFO: CalDel: 136
[13:49:04.388] <TB2> INFO: VthrComp: 51
[13:49:04.392] <TB2> INFO: enter test to run
[13:49:04.392] <TB2> INFO: test: Pretest no parameter change
[13:49:04.392] <TB2> INFO: running: pretest
[13:49:04.397] <TB2> INFO: write dac parameters into /home/mameinha/data/R421_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//dacParameters_C0.dat
[13:49:04.400] <TB2> INFO: enter test to run
[13:49:04.400] <TB2> INFO: test: PixelAlive no parameter change
[13:49:04.400] <TB2> INFO: running: pixelalive
[13:49:04.402] <TB2> INFO: ######################################################################
[13:49:04.402] <TB2> INFO: PixTestAlive::doTest()
[13:49:04.402] <TB2> INFO: ######################################################################
[13:49:04.403] <TB2> INFO: ----------------------------------------------------------------------
[13:49:04.403] <TB2> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[13:49:04.403] <TB2> INFO: ----------------------------------------------------------------------
[13:49:04.425] <TB2> INFO: Expecting 41600 events.
[13:49:05.240] <TB2> INFO: 41600 events read in total (428ms).
[13:49:05.241] <TB2> INFO: Test took 837ms.
[13:49:05.241] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:05.627] <TB2> INFO: PixTestAlive::aliveTest() done
[13:49:05.627] <TB2> INFO: number of dead pixels (per ROC): 0
[13:49:05.629] <TB2> INFO: ----------------------------------------------------------------------
[13:49:05.629] <TB2> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[13:49:05.629] <TB2> INFO: ----------------------------------------------------------------------
[13:49:05.649] <TB2> INFO: Expecting 41600 events.
[13:49:06.393] <TB2> INFO: 41600 events read in total (357ms).
[13:49:06.393] <TB2> INFO: Test took 764ms.
[13:49:06.393] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:06.393] <TB2> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[13:49:06.783] <TB2> INFO: PixTestAlive::maskTest() done
[13:49:06.783] <TB2> INFO: number of mask-defect pixels (per ROC): 0
[13:49:06.785] <TB2> INFO: ----------------------------------------------------------------------
[13:49:06.785] <TB2> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[13:49:06.785] <TB2> INFO: ----------------------------------------------------------------------
[13:49:06.808] <TB2> INFO: Expecting 41600 events.
[13:49:07.628] <TB2> INFO: 41600 events read in total (433ms).
[13:49:07.628] <TB2> INFO: Test took 843ms.
[13:49:07.628] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:08.015] <TB2> INFO: PixTestAlive::addressDecodingTest() done
[13:49:08.015] <TB2> INFO: number of address-decoding pixels (per ROC): 0
[13:49:08.015] <TB2> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[13:49:08.015] <TB2> INFO: enter test to run
[13:49:08.016] <TB2> INFO: test: Scurves no parameter change
[13:49:08.016] <TB2> INFO: running: scurves
[13:49:08.017] <TB2> INFO: ######################################################################
[13:49:08.017] <TB2> INFO: PixTestScurves::doTest() ntrig = 50
[13:49:08.017] <TB2> INFO: ######################################################################
[13:49:08.017] <TB2> INFO: ----------------------------------------------------------------------
[13:49:08.017] <TB2> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[13:49:08.017] <TB2> INFO: ----------------------------------------------------------------------
[13:49:08.017] <TB2> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[13:49:08.030] <TB2> INFO: dacScan split into 1 runs with ntrig = 50
[13:49:08.030] <TB2> INFO: run 1 of 1
[13:49:08.049] <TB2> INFO: Expecting 41808000 events.
[13:51:39.257] <TB2> INFO: 20417400 events read in total (150821ms).
[13:54:08.028] <TB2> INFO: 40366150 events read in total (299592ms).
[13:54:19.458] <TB2> INFO: 41808000 events read in total (311022ms).
[13:54:19.490] <TB2> INFO: Test took 311460ms.
[13:54:19.510] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:54:21.053] <TB2> INFO: PixTestScurves::scurves() done
[13:54:21.053] <TB2> INFO: Vcal mean: 88.88
[13:54:21.053] <TB2> INFO: Vcal RMS: 5.69
[13:54:21.058] <TB2> INFO: enter test to run
[13:54:21.058] <TB2> INFO: test: Trim no parameter change
[13:54:21.058] <TB2> INFO: running: trim
[13:54:21.060] <TB2> INFO: ######################################################################
[13:54:21.060] <TB2> INFO: PixTestTrim::doTest()
[13:54:21.060] <TB2> INFO: ######################################################################
[13:54:21.062] <TB2> INFO: ----------------------------------------------------------------------
[13:54:21.062] <TB2> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[13:54:21.062] <TB2> INFO: ----------------------------------------------------------------------
[13:54:21.070] <TB2> INFO: ---> VthrComp thr map (minimal VthrComp)
[13:54:21.070] <TB2> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[13:54:21.081] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:54:21.081] <TB2> INFO: run 1 of 1
[13:54:21.103] <TB2> INFO: Expecting 6281600 events.
[13:55:08.485] <TB2> INFO: 6281600 events read in total (46995ms).
[13:55:08.502] <TB2> INFO: Test took 47421ms.
[13:55:08.510] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:55:09.633] <TB2> INFO: ROC 0 VthrComp = 91
[13:55:09.633] <TB2> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[13:55:09.633] <TB2> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[13:55:09.643] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:55:09.643] <TB2> INFO: run 1 of 1
[13:55:09.662] <TB2> INFO: Expecting 6281600 events.
[13:56:02.726] <TB2> INFO: 6281600 events read in total (52676ms).
[13:56:02.768] <TB2> INFO: Test took 53125ms.
[13:56:02.788] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:56:04.105] <TB2> INFO: roc 0 with ID = 0 has maximal Vcal 59.4755 for pixel 0/9 mean/min/max = 45.8271/32.1238/59.5305
[13:56:04.113] <TB2> INFO: Expecting 514560 events.
[13:56:08.237] <TB2> INFO: 514560 events read in total (3737ms).
[13:56:08.241] <TB2> INFO: Test took 4136ms.
[13:56:08.625] <TB2> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[13:56:08.633] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:56:08.633] <TB2> INFO: run 1 of 1
[13:56:08.652] <TB2> INFO: Expecting 6281600 events.
[13:57:00.306] <TB2> INFO: 6281600 events read in total (51267ms).
[13:57:00.351] <TB2> INFO: Test took 51718ms.
[13:57:00.372] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:57:01.664] <TB2> INFO: ---> TrimStepCorr4 extremal thresholds: 13.187156 .. 47.145518
[13:57:01.668] <TB2> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 3 .. 57 (-1/-1) hits flags = 528 (plus default)
[13:57:01.676] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:57:01.676] <TB2> INFO: run 1 of 1
[13:57:01.696] <TB2> INFO: Expecting 2288000 events.
[13:57:20.087] <TB2> INFO: 2288000 events read in total (18004ms).
[13:57:20.101] <TB2> INFO: Test took 18425ms.
[13:57:20.107] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:57:20.991] <TB2> INFO: ---> TrimStepCorr2 extremal thresholds: 21.446930 .. 41.033805
[13:57:20.996] <TB2> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 11 .. 51 (-1/-1) hits flags = 528 (plus default)
[13:57:21.004] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:57:21.004] <TB2> INFO: run 1 of 1
[13:57:21.023] <TB2> INFO: Expecting 1705600 events.
[13:57:35.224] <TB2> INFO: 1705600 events read in total (13814ms).
[13:57:35.231] <TB2> INFO: Test took 14227ms.
[13:57:35.235] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:57:36.032] <TB2> INFO: ---> TrimStepCorr1a extremal thresholds: 25.831485 .. 37.502341
[13:57:36.038] <TB2> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 15 .. 47 (-1/-1) hits flags = 528 (plus default)
[13:57:36.047] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:57:36.047] <TB2> INFO: run 1 of 1
[13:57:36.066] <TB2> INFO: Expecting 1372800 events.
[13:57:47.535] <TB2> INFO: 1372800 events read in total (11082ms).
[13:57:47.541] <TB2> INFO: Test took 11494ms.
[13:57:47.544] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:57:48.296] <TB2> INFO: ---> TrimStepCorr1b extremal thresholds: 27.396254 .. 37.110104
[13:57:48.301] <TB2> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 17 .. 47 (-1/-1) hits flags = 528 (plus default)
[13:57:48.309] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:57:48.309] <TB2> INFO: run 1 of 1
[13:57:48.328] <TB2> INFO: Expecting 1289600 events.
[13:57:59.755] <TB2> INFO: 1289600 events read in total (11040ms).
[13:57:59.763] <TB2> INFO: Test took 11454ms.
[13:57:59.767] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:58:00.651] <TB2> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[13:58:00.651] <TB2> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[13:58:00.661] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:58:00.662] <TB2> INFO: run 1 of 1
[13:58:00.685] <TB2> INFO: Expecting 1705600 events.
[13:58:15.254] <TB2> INFO: 1705600 events read in total (14182ms).
[13:58:15.262] <TB2> INFO: Test took 14600ms.
[13:58:15.267] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:58:16.375] <TB2> INFO: write dac parameters into /home/mameinha/data/R421_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//dacParameters35_C0.dat
[13:58:16.380] <TB2> INFO: write trim parameters into /home/mameinha/data/R421_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//trimParameters35_C0.dat
[13:58:16.404] <TB2> INFO: PixTestTrim::trimTest() done
[13:58:16.404] <TB2> INFO: vtrim: 94
[13:58:16.404] <TB2> INFO: vthrcomp: 91
[13:58:16.404] <TB2> INFO: vcal mean: 34.99
[13:58:16.404] <TB2> INFO: vcal RMS: 0.76
[13:58:16.404] <TB2> INFO: bits mean: 9.13
[13:58:16.404] <TB2> INFO: bits RMS: 2.84
[13:58:16.408] <TB2> INFO: ----------------------------------------------------------------------
[13:58:16.408] <TB2> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[13:58:16.408] <TB2> INFO: ----------------------------------------------------------------------
[13:58:16.408] <TB2> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[13:58:16.419] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:58:16.420] <TB2> INFO: run 1 of 1
[13:58:16.440] <TB2> INFO: Expecting 8320000 events.
[13:59:21.535] <TB2> INFO: 8320000 events read in total (64708ms).
[13:59:21.580] <TB2> INFO: Test took 65160ms.
[13:59:21.596] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[13:59:23.301] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 151 (-1/-1) hits flags = 528 (plus default)
[13:59:23.309] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[13:59:23.309] <TB2> INFO: run 1 of 1
[13:59:23.328] <TB2> INFO: Expecting 6323200 events.
[14:00:12.146] <TB2> INFO: 6323200 events read in total (48432ms).
[14:00:12.179] <TB2> INFO: Test took 48870ms.
[14:00:12.189] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:00:13.470] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 140 (-1/-1) hits flags = 528 (plus default)
[14:00:13.478] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:00:13.478] <TB2> INFO: run 1 of 1
[14:00:13.497] <TB2> INFO: Expecting 5865600 events.
[14:00:59.116] <TB2> INFO: 5865600 events read in total (45232ms).
[14:00:59.142] <TB2> INFO: Test took 45664ms.
[14:00:59.153] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:01:00.595] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 140 (-1/-1) hits flags = 528 (plus default)
[14:01:00.603] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:01:00.603] <TB2> INFO: run 1 of 1
[14:01:00.622] <TB2> INFO: Expecting 5865600 events.
[14:01:46.044] <TB2> INFO: 5865600 events read in total (45034ms).
[14:01:46.070] <TB2> INFO: Test took 45467ms.
[14:01:46.081] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:01:47.317] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 139 (-1/-1) hits flags = 528 (plus default)
[14:01:47.325] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[14:01:47.325] <TB2> INFO: run 1 of 1
[14:01:47.345] <TB2> INFO: Expecting 5824000 events.
[14:02:31.229] <TB2> INFO: 5824000 events read in total (43497ms).
[14:02:31.246] <TB2> INFO: Test took 43921ms.
[14:02:31.254] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:02:32.457] <TB2> INFO: PixTestTrim::trimBitTest() done
[14:02:32.458] <TB2> INFO: PixTestTrim::doTest() done, duration: 491 seconds
[14:02:32.501] <TB2> INFO: enter test to run
[14:02:32.501] <TB2> INFO: test: PhOptimization no parameter change
[14:02:32.501] <TB2> INFO: running: phoptimization
[14:02:32.501] <TB2> INFO: ######################################################################
[14:02:32.501] <TB2> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[14:02:32.501] <TB2> INFO: ######################################################################
[14:02:32.522] <TB2> INFO: Expecting 41600 events.
[14:02:33.329] <TB2> INFO: 41600 events read in total (420ms).
[14:02:33.330] <TB2> INFO: Test took 827ms.
[14:02:33.330] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:02:33.721] <TB2> INFO: Expecting 41600 events.
[14:02:34.525] <TB2> INFO: 41600 events read in total (417ms).
[14:02:34.526] <TB2> INFO: Test took 1194ms.
[14:02:34.526] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:02:34.915] <TB2> INFO: Expecting 41600 events.
[14:02:35.717] <TB2> INFO: 41600 events read in total (415ms).
[14:02:35.718] <TB2> INFO: Test took 1191ms.
[14:02:35.718] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[14:02:36.107] <TB2> INFO: Expecting 2560 events.
[14:02:36.527] <TB2> INFO: 2560 events read in total (33ms).
[14:02:36.527] <TB2> INFO: Test took 809ms.
[14:02:36.922] <TB2> INFO: Expecting 655360 events.
[14:02:42.678] <TB2> INFO: 655360 events read in total (5369ms).
[14:02:42.687] <TB2> INFO: Test took 6159ms.
[14:02:42.923] <TB2> INFO: Expecting 655360 events.
[14:02:48.513] <TB2> INFO: 655360 events read in total (5203ms).
[14:02:48.521] <TB2> INFO: Test took 5820ms.
[14:02:48.540] <TB2> INFO: safety margin for low PH: adding 0, margin is now 20
[14:02:48.554] <TB2> INFO: write dac parameters into /home/mameinha/data/R421_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//dacParameters35_C0.dat
[14:02:48.806] <TB2> INFO: Expecting 41600 events.
[14:02:49.595] <TB2> INFO: 41600 events read in total (402ms).
[14:02:49.595] <TB2> INFO: Test took 1037ms.
[14:02:49.978] <TB2> INFO: Expecting 41600 events.
[14:02:50.748] <TB2> INFO: 41600 events read in total (383ms).
[14:02:50.749] <TB2> INFO: Test took 1153ms.
[14:02:51.136] <TB2> INFO: Expecting 41600 events.
[14:02:51.918] <TB2> INFO: 41600 events read in total (395ms).
[14:02:51.919] <TB2> INFO: Test took 1169ms.
[14:02:52.305] <TB2> INFO: Expecting 2560 events.
[14:02:52.725] <TB2> INFO: 2560 events read in total (33ms).
[14:02:52.725] <TB2> INFO: Test took 805ms.
[14:02:53.120] <TB2> INFO: Expecting 2560 events.
[14:02:53.539] <TB2> INFO: 2560 events read in total (32ms).
[14:02:53.540] <TB2> INFO: Test took 815ms.
[14:02:53.950] <TB2> INFO: PixTestPhOptimization::doTest() done, duration: 21 seconds
[14:02:53.950] <TB2> INFO: PH scale (per ROC): 83
[14:02:53.950] <TB2> INFO: PH offset (per ROC): 157
[14:02:53.964] <TB2> INFO: enter test to run
[14:02:53.964] <TB2> INFO: test: GainPedestal no parameter change
[14:02:53.964] <TB2> INFO: running: gainpedestal
[14:02:53.966] <TB2> INFO: ######################################################################
[14:02:53.966] <TB2> INFO: PixTestGainPedestal::doTest() ntrig = 10
[14:02:53.966] <TB2> INFO: ######################################################################
[14:02:53.976] <TB2> INFO: scanning low vcal = 10
[14:02:53.997] <TB2> INFO: Expecting 41600 events.
[14:02:55.091] <TB2> INFO: 41600 events read in total (707ms).
[14:02:55.092] <TB2> INFO: Test took 1116ms.
[14:02:55.092] <TB2> INFO: scanning low vcal = 20
[14:02:55.487] <TB2> INFO: Expecting 41600 events.
[14:02:56.578] <TB2> INFO: 41600 events read in total (704ms).
[14:02:56.579] <TB2> INFO: Test took 1487ms.
[14:02:56.579] <TB2> INFO: scanning low vcal = 30
[14:02:56.974] <TB2> INFO: Expecting 41600 events.
[14:02:58.071] <TB2> INFO: 41600 events read in total (710ms).
[14:02:58.071] <TB2> INFO: Test took 1492ms.
[14:02:58.072] <TB2> INFO: scanning low vcal = 40
[14:02:58.466] <TB2> INFO: Expecting 41600 events.
[14:02:59.627] <TB2> INFO: 41600 events read in total (774ms).
[14:02:59.628] <TB2> INFO: Test took 1556ms.
[14:02:59.628] <TB2> INFO: scanning low vcal = 50
[14:03:00.014] <TB2> INFO: Expecting 41600 events.
[14:03:01.155] <TB2> INFO: 41600 events read in total (754ms).
[14:03:01.155] <TB2> INFO: Test took 1527ms.
[14:03:01.156] <TB2> INFO: scanning low vcal = 60
[14:03:01.540] <TB2> INFO: Expecting 41600 events.
[14:03:02.693] <TB2> INFO: 41600 events read in total (766ms).
[14:03:02.694] <TB2> INFO: Test took 1538ms.
[14:03:02.694] <TB2> INFO: scanning low vcal = 70
[14:03:03.075] <TB2> INFO: Expecting 41600 events.
[14:03:04.225] <TB2> INFO: 41600 events read in total (763ms).
[14:03:04.226] <TB2> INFO: Test took 1532ms.
[14:03:04.227] <TB2> INFO: scanning low vcal = 80
[14:03:04.610] <TB2> INFO: Expecting 41600 events.
[14:03:05.784] <TB2> INFO: 41600 events read in total (787ms).
[14:03:05.785] <TB2> INFO: Test took 1558ms.
[14:03:05.785] <TB2> INFO: scanning low vcal = 90
[14:03:06.167] <TB2> INFO: Expecting 41600 events.
[14:03:07.316] <TB2> INFO: 41600 events read in total (762ms).
[14:03:07.317] <TB2> INFO: Test took 1532ms.
[14:03:07.318] <TB2> INFO: scanning low vcal = 100
[14:03:07.703] <TB2> INFO: Expecting 41600 events.
[14:03:08.863] <TB2> INFO: 41600 events read in total (773ms).
[14:03:08.864] <TB2> INFO: Test took 1546ms.
[14:03:08.865] <TB2> INFO: scanning low vcal = 110
[14:03:09.246] <TB2> INFO: Expecting 41600 events.
[14:03:10.403] <TB2> INFO: 41600 events read in total (770ms).
[14:03:10.404] <TB2> INFO: Test took 1539ms.
[14:03:10.404] <TB2> INFO: scanning low vcal = 120
[14:03:10.784] <TB2> INFO: Expecting 41600 events.
[14:03:11.938] <TB2> INFO: 41600 events read in total (767ms).
[14:03:11.939] <TB2> INFO: Test took 1535ms.
[14:03:11.939] <TB2> INFO: scanning low vcal = 130
[14:03:12.321] <TB2> INFO: Expecting 41600 events.
[14:03:13.506] <TB2> INFO: 41600 events read in total (798ms).
[14:03:13.508] <TB2> INFO: Test took 1569ms.
[14:03:13.508] <TB2> INFO: scanning low vcal = 140
[14:03:13.887] <TB2> INFO: Expecting 41600 events.
[14:03:15.019] <TB2> INFO: 41600 events read in total (745ms).
[14:03:15.019] <TB2> INFO: Test took 1511ms.
[14:03:15.020] <TB2> INFO: scanning low vcal = 150
[14:03:15.406] <TB2> INFO: Expecting 41600 events.
[14:03:16.556] <TB2> INFO: 41600 events read in total (763ms).
[14:03:16.557] <TB2> INFO: Test took 1537ms.
[14:03:16.557] <TB2> INFO: scanning low vcal = 160
[14:03:16.941] <TB2> INFO: Expecting 41600 events.
[14:03:18.074] <TB2> INFO: 41600 events read in total (746ms).
[14:03:18.075] <TB2> INFO: Test took 1518ms.
[14:03:18.075] <TB2> INFO: scanning low vcal = 170
[14:03:18.463] <TB2> INFO: Expecting 41600 events.
[14:03:19.625] <TB2> INFO: 41600 events read in total (775ms).
[14:03:19.625] <TB2> INFO: Test took 1550ms.
[14:03:19.626] <TB2> INFO: scanning low vcal = 180
[14:03:20.014] <TB2> INFO: Expecting 41600 events.
[14:03:21.197] <TB2> INFO: 41600 events read in total (796ms).
[14:03:21.198] <TB2> INFO: Test took 1572ms.
[14:03:21.198] <TB2> INFO: scanning low vcal = 190
[14:03:21.581] <TB2> INFO: Expecting 41600 events.
[14:03:22.729] <TB2> INFO: 41600 events read in total (762ms).
[14:03:22.730] <TB2> INFO: Test took 1532ms.
[14:03:22.730] <TB2> INFO: scanning low vcal = 200
[14:03:23.116] <TB2> INFO: Expecting 41600 events.
[14:03:24.250] <TB2> INFO: 41600 events read in total (747ms).
[14:03:24.251] <TB2> INFO: Test took 1521ms.
[14:03:24.251] <TB2> INFO: scanning low vcal = 210
[14:03:24.640] <TB2> INFO: Expecting 41600 events.
[14:03:25.811] <TB2> INFO: 41600 events read in total (784ms).
[14:03:25.812] <TB2> INFO: Test took 1561ms.
[14:03:25.812] <TB2> INFO: scanning low vcal = 220
[14:03:26.196] <TB2> INFO: Expecting 41600 events.
[14:03:27.362] <TB2> INFO: 41600 events read in total (779ms).
[14:03:27.363] <TB2> INFO: Test took 1551ms.
[14:03:27.363] <TB2> INFO: scanning low vcal = 230
[14:03:27.752] <TB2> INFO: Expecting 41600 events.
[14:03:28.895] <TB2> INFO: 41600 events read in total (756ms).
[14:03:28.895] <TB2> INFO: Test took 1532ms.
[14:03:28.896] <TB2> INFO: scanning low vcal = 240
[14:03:29.284] <TB2> INFO: Expecting 41600 events.
[14:03:30.430] <TB2> INFO: 41600 events read in total (759ms).
[14:03:30.431] <TB2> INFO: Test took 1535ms.
[14:03:30.431] <TB2> INFO: scanning low vcal = 250
[14:03:30.820] <TB2> INFO: Expecting 41600 events.
[14:03:31.977] <TB2> INFO: 41600 events read in total (770ms).
[14:03:31.977] <TB2> INFO: Test took 1546ms.
[14:03:31.978] <TB2> INFO: scanning high vcal = 30 (= 210 in low range)
[14:03:32.358] <TB2> INFO: Expecting 41600 events.
[14:03:33.524] <TB2> INFO: 41600 events read in total (779ms).
[14:03:33.525] <TB2> INFO: Test took 1547ms.
[14:03:33.525] <TB2> INFO: scanning high vcal = 50 (= 350 in low range)
[14:03:33.913] <TB2> INFO: Expecting 41600 events.
[14:03:35.072] <TB2> INFO: 41600 events read in total (772ms).
[14:03:35.073] <TB2> INFO: Test took 1548ms.
[14:03:35.073] <TB2> INFO: scanning high vcal = 70 (= 490 in low range)
[14:03:35.457] <TB2> INFO: Expecting 41600 events.
[14:03:36.609] <TB2> INFO: 41600 events read in total (765ms).
[14:03:36.610] <TB2> INFO: Test took 1537ms.
[14:03:36.610] <TB2> INFO: scanning high vcal = 90 (= 630 in low range)
[14:03:36.993] <TB2> INFO: Expecting 41600 events.
[14:03:38.160] <TB2> INFO: 41600 events read in total (780ms).
[14:03:38.160] <TB2> INFO: Test took 1550ms.
[14:03:38.161] <TB2> INFO: scanning high vcal = 200 (= 1400 in low range)
[14:03:38.543] <TB2> INFO: Expecting 41600 events.
[14:03:39.713] <TB2> INFO: 41600 events read in total (783ms).
[14:03:39.713] <TB2> INFO: Test took 1552ms.
[14:03:40.094] <TB2> INFO: PixTestGainPedestal::measure() done
[14:03:42.437] <TB2> INFO: PixTestGainPedestal::fit() done
[14:03:42.437] <TB2> INFO: non-linearity mean: 0.957
[14:03:42.437] <TB2> INFO: non-linearity RMS: 0.006
[14:03:42.475] <TB2> INFO: write gain/ped parameters into /home/mameinha/data/R421_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//phCalibrationFitErr35_C0.dat
[14:03:42.822] <TB2> INFO: PixTestGainPedestal::doTest() done, duration: 48 seconds
[14:03:42.823] <TB2> INFO: enter test to run
[14:03:42.823] <TB2> INFO: test: Readback no parameter change
[14:03:42.823] <TB2> INFO: running: readback
[14:03:42.823] <TB2> INFO: readReadbackCal: /home/mameinha/data/R421_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//readbackCal_C0.dat .. /home/mameinha/data/R421_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//readbackCal_C0.dat
[14:03:42.824] <TB2> INFO: ######################################################################
[14:03:42.824] <TB2> INFO: PixTestReadback::doTest()
[14:03:42.824] <TB2> INFO: ######################################################################
[14:03:42.826] <TB2> INFO: PixTestReadback::RES sent once
[14:03:54.805] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R421_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//readbackCal_C0.dat
[14:03:54.814] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[14:03:54.814] <TB2> INFO: PixTestReadback::RES sent once
[14:04:05.923] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R421_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//readbackCal_C0.dat
[14:04:05.936] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[14:04:05.937] <TB2> INFO: PixTestReadback::RES sent once
[14:04:14.273] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[14:04:14.274] <TB2> INFO: Vbg will be calibrated using Vd calibration
[14:04:14.274] <TB2> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 163.1calibrated Vbg = 1.2281 :::*/*/*/*/
[14:04:14.650] <TB2> INFO: PixTestReadback::RES sent once
[14:04:15.066] <TB2> ERROR: <datapipe.cc/CheckEventValidity:L488> Channel 0 Number of ROCs (0) != Token Chain Length (1)
[14:04:15.858] <TB2> ERROR: <datapipe.cc/CheckEventValidity:L488> Channel 0 Number of ROCs (0) != Token Chain Length (1)
[14:04:24.321] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R421_Fulltest_m20_2015-10-07_15h47m_1444225659//000_FulltestROC_m20//readbackCal_C0.dat
[14:04:24.328] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[14:04:24.328] <TB2> INFO: PixTestReadback::doTest() done
[14:04:24.385] <TB2> INFO: enter test to run
[14:04:24.385] <TB2> INFO: test: no parameter change
[14:04:24.434] <TB2> QUIET: Connection to board 137 closed.
[14:04:24.529] <TB2> INFO: pXar: this is the end, my friend