[15:28:29.617] <TB2> INFO: *** Welcome to pxar ***
[15:28:29.617] <TB2> INFO: *** Today: 2015/12/04
[15:28:29.945] <TB2> INFO: *** Version: 9da6
[15:28:29.945] <TB2> INFO: readRocDacs: /home/mameinha/data/R427_FulltestROC_m20_2015-12-04_16h24m_1449242642//000_FulltestROC_m20//dacParameters_C0.dat .. /home/mameinha/data/R427_FulltestROC_m20_2015-12-04_16h24m_1449242642//000_FulltestROC_m20//dacParameters_C0.dat
[15:28:29.949] <TB2> INFO: readTbmDacs: /home/mameinha/data/R427_FulltestROC_m20_2015-12-04_16h24m_1449242642//000_FulltestROC_m20//tbmParameters_C0a.dat .. /home/mameinha/data/R427_FulltestROC_m20_2015-12-04_16h24m_1449242642//000_FulltestROC_m20//tbmParameters_C4294967295b.dat
[15:28:29.949] <TB2> INFO: readMaskFile: /home/mameinha/data/R427_FulltestROC_m20_2015-12-04_16h24m_1449242642//000_FulltestROC_m20//defaultMaskFile.dat
[15:28:29.950] <TB2> INFO: readTrimFile: /home/mameinha/data/R427_FulltestROC_m20_2015-12-04_16h24m_1449242642//000_FulltestROC_m20//trimParameters_C0.dat .. /home/mameinha/data/R427_FulltestROC_m20_2015-12-04_16h24m_1449242642//000_FulltestROC_m20//trimParameters_C0.dat
[15:28:29.956] <TB2> INFO: clk: 4
[15:28:29.956] <TB2> INFO: ctr: 4
[15:28:29.956] <TB2> INFO: sda: 19
[15:28:29.956] <TB2> INFO: tin: 9
[15:28:29.956] <TB2> INFO: level: 15
[15:28:29.956] <TB2> INFO: deser160phase: 4
[15:28:29.956] <TB2> QUIET: Instanciating API for pxar v2.6.1+42~g55d8827
[15:28:29.956] <TB2> INFO: Log level: INFO
[15:28:29.962] <TB2> INFO: Found DTB DTB_WZ4BYI
[15:28:29.971] <TB2> QUIET: Connection to board DTB_WZ4BYI opened.
[15:28:29.974] <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:
------------------------------------------------------
[15:28:29.976] <TB2> INFO: RPC call hashes of host and DTB match: 398089610
[15:28:31.140] <TB2> INFO: DUT info:
[15:28:31.140] <TB2> INFO: The DUT currently contains the following objects:
[15:28:31.140] <TB2> INFO: 0 TBM Cores (0 ON)
[15:28:31.140] <TB2> INFO: 1 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[15:28:31.140] <TB2> INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:28:31.593] <TB2> INFO: enter 'restricted' command line mode
[15:28:31.593] <TB2> INFO: enter test to run
[15:28:31.593] <TB2> INFO: test: Setup no parameter change
[15:28:31.593] <TB2> INFO: running: setup
[15:28:31.597] <TB2> INFO: PixTestSetup::doTest() ntrig = 10

[15:28:31.598] <TB2> INFO: PixTestSetup:: pg set to RES|TOK
[15:28:31.598] <TB2> INFO: 0 1 2 3 4 5 6 7
[15:28:34.638] <TB2> INFO: 0: 000 000 004 07c 7f0 f00 000 000
[15:28:37.649] <TB2> INFO: 1: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[15:28:40.661] <TB2> INFO: 2: 800 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[15:28:43.673] <TB2> INFO: 3: 000 000 004 07c <7f8>[*] f80 800 000
[15:28:46.686] <TB2> INFO: 4: 000 000 004 07c <7f8>[*] f80 <7f8>[1] 000
[15:28:49.699] <TB2> INFO: 5: 000 000 000 03c 3fc fc0 c00 000
[15:28:52.711] <TB2> INFO: 6: 800 000 000 03c 3fc fc0 c00 000
[15:28:55.723] <TB2> INFO: 7: 000 000 000 03c 3fc fc0 c00 000
[15:28:58.734] <TB2> INFO: 8: 000 000 000 03c 3fc fc0 c00 000
[15:29:01.746] <TB2> INFO: 9: c00 000 000 03c 3fc fc0 c00 000
[15:29:04.758] <TB2> INFO: 10: 000 000 000 01c 1fc fc0 c00 000
[15:29:07.772] <TB2> INFO: 11: 000 000 000 01c 1fc fe0 e00 000
[15:29:10.785] <TB2> INFO: 12: 000 000 000 01c 1fc fe0 e00 000
[15:29:13.799] <TB2> INFO: 13: e00 000 000 01c 1fc fe0 e00 000
[15:29:16.812] <TB2> INFO: 14: 000 000 000 01c 1fc fe0 e00 000
[15:29:19.826] <TB2> INFO: 15: e00 000 000 00c 0fc fe0 f00 000
[15:29:22.839] <TB2> INFO: 16: e00 000 000 00c 0fc ff0 f00 000
[15:29:25.852] <TB2> INFO: 17: 000 000 000 00c 0fc ff0 f00 000
[15:29:28.865] <TB2> INFO: 18: f00 000 000 00c 0fc ff0 f00 000
[15:29:31.879] <TB2> INFO: 19: 000 000 000 00c 0fc ff0 f00 000
[15:29:32.290] <TB2> INFO: Found good delays at CLK = 2, DESER160 = 4
[15:29:32.291] <TB2> INFO: PixTestSetup:: Write Tb parameters to file.
[15:29:32.463] <TB2> INFO: write dtb parameters into /home/mameinha/data/R427_FulltestROC_m20_2015-12-04_16h24m_1449242642//000_FulltestROC_m20//tbParameters.dat
[15:29:32.483] <TB2> INFO: PixTestSetup::doTest() done for.
[15:29:32.520] <TB2> INFO: enter test to run
[15:29:32.520] <TB2> INFO: test: Pretest no parameter change
[15:29:32.520] <TB2> INFO: running: pretest
[15:29:32.522] <TB2> INFO: ----------------------------------------------------------------------
[15:29:32.522] <TB2> INFO: PixTestPretest::programROC()
[15:29:32.522] <TB2> INFO: ----------------------------------------------------------------------
[15:29:35.524] <TB2> INFO: PixTestPretest::programROC() done: ROCs are all programmable
[15:29:35.524] <TB2> INFO: IA differences per ROC: 22.5
[15:29:35.528] <TB2> INFO: enter test to run
[15:29:35.528] <TB2> INFO: test: Pretest no parameter change
[15:29:35.528] <TB2> INFO: running: pretest
[15:29:35.530] <TB2> INFO: ----------------------------------------------------------------------
[15:29:35.530] <TB2> INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[15:29:35.530] <TB2> INFO: ----------------------------------------------------------------------
[15:29:36.441] <TB2> INFO: PixTestPretest::setVana() done, Module Ia 24.1 mA = 24.1 mA/ROC
[15:29:36.441] <TB2> INFO: i(loss) [mA/ROC]: 18.5
[15:29:36.444] <TB2> INFO: enter test to run
[15:29:36.444] <TB2> INFO: test: Pretest no parameter change
[15:29:36.444] <TB2> INFO: running: pretest
[15:29:36.445] <TB2> INFO: ----------------------------------------------------------------------
[15:29:36.445] <TB2> INFO: PixTestPretest::findWorkingPixel()
[15:29:36.445] <TB2> INFO: ----------------------------------------------------------------------
[15:29:36.455] <TB2> INFO: Expecting 231680 events.
[15:29:38.717] <TB2> INFO: 231680 events read in total (1875ms).
[15:29:38.719] <TB2> INFO: Test took 2273ms.
[15:29:39.097] <TB2> INFO: Found working pixel in all ROCs: col/row = 12/22
[15:29:39.105] <TB2> INFO: enter test to run
[15:29:39.105] <TB2> INFO: test: Pretest no parameter change
[15:29:39.105] <TB2> INFO: running: pretest
[15:29:39.106] <TB2> INFO: ----------------------------------------------------------------------
[15:29:39.106] <TB2> INFO: PixTestPretest::setVthrCompCalDel()
[15:29:39.106] <TB2> INFO: ----------------------------------------------------------------------
[15:29:39.116] <TB2> INFO: Expecting 231680 events.
[15:29:41.353] <TB2> INFO: 231680 events read in total (1850ms).
[15:29:41.356] <TB2> INFO: Test took 2249ms.
[15:29:41.734] <TB2> INFO: PixTestPretest::setVthrCompCalDel() done
[15:29:41.734] <TB2> INFO: CalDel: 145
[15:29:41.734] <TB2> INFO: VthrComp: 51
[15:29:41.738] <TB2> INFO: enter test to run
[15:29:41.738] <TB2> INFO: test: Pretest no parameter change
[15:29:41.738] <TB2> INFO: running: pretest
[15:29:41.802] <TB2> INFO: write dac parameters into /home/mameinha/data/R427_FulltestROC_m20_2015-12-04_16h24m_1449242642//000_FulltestROC_m20//dacParameters_C0.dat
[15:29:41.845] <TB2> INFO: enter test to run
[15:29:41.845] <TB2> INFO: test: PixelAlive no parameter change
[15:29:41.845] <TB2> INFO: running: pixelalive
[15:29:41.846] <TB2> INFO: ######################################################################
[15:29:41.846] <TB2> INFO: PixTestAlive::doTest()
[15:29:41.846] <TB2> INFO: ######################################################################
[15:29:41.848] <TB2> INFO: ----------------------------------------------------------------------
[15:29:41.848] <TB2> INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[15:29:41.848] <TB2> INFO: ----------------------------------------------------------------------
[15:29:41.867] <TB2> INFO: Expecting 41600 events.
[15:29:42.697] <TB2> INFO: 41600 events read in total (443ms).
[15:29:42.698] <TB2> INFO: Test took 850ms.
[15:29:42.698] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:29:43.080] <TB2> INFO: PixTestAlive::aliveTest() done
[15:29:43.080] <TB2> INFO: number of dead pixels (per ROC): 0
[15:29:43.081] <TB2> INFO: ----------------------------------------------------------------------
[15:29:43.081] <TB2> INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[15:29:43.081] <TB2> INFO: ----------------------------------------------------------------------
[15:29:43.105] <TB2> INFO: Expecting 41600 events.
[15:29:43.852] <TB2> INFO: 41600 events read in total (360ms).
[15:29:43.852] <TB2> INFO: Test took 771ms.
[15:29:43.852] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:29:43.852] <TB2> INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C0_V0
[15:29:44.241] <TB2> INFO: PixTestAlive::maskTest() done
[15:29:44.241] <TB2> INFO: number of mask-defect pixels (per ROC): 0
[15:29:44.243] <TB2> INFO: ----------------------------------------------------------------------
[15:29:44.243] <TB2> INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0)
[15:29:44.243] <TB2> INFO: ----------------------------------------------------------------------
[15:29:44.266] <TB2> INFO: Expecting 41600 events.
[15:29:45.158] <TB2> INFO: 41600 events read in total (505ms).
[15:29:45.159] <TB2> INFO: Test took 916ms.
[15:29:45.160] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:29:45.541] <TB2> INFO: PixTestAlive::addressDecodingTest() done
[15:29:45.541] <TB2> INFO: number of address-decoding pixels (per ROC): 0
[15:29:45.541] <TB2> INFO: PixTestAlive::doTest() done, duration: 3 seconds
[15:29:45.542] <TB2> INFO: enter test to run
[15:29:45.542] <TB2> INFO: test: Scurves no parameter change
[15:29:45.542] <TB2> INFO: running: scurves
[15:29:45.544] <TB2> INFO: ######################################################################
[15:29:45.544] <TB2> INFO: PixTestScurves::doTest() ntrig = 50
[15:29:45.544] <TB2> INFO: ######################################################################
[15:29:45.544] <TB2> INFO: ----------------------------------------------------------------------
[15:29:45.544] <TB2> INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = -1
[15:29:45.544] <TB2> INFO: ----------------------------------------------------------------------
[15:29:45.544] <TB2> INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 200 (-1/-1) hits flags = 528 (plus default)
[15:29:45.555] <TB2> INFO: dacScan split into 1 runs with ntrig = 50
[15:29:45.555] <TB2> INFO: run 1 of 1
[15:29:45.574] <TB2> INFO: Expecting 41808000 events.
[15:31:58.350] <TB2> INFO: 17623550 events read in total (132389ms).
[15:34:11.840] <TB2> INFO: 34953400 events read in total (265879ms).
[15:35:04.516] <TB2> INFO: 41808000 events read in total (318555ms).
[15:35:04.563] <TB2> INFO: Test took 319008ms.
[15:35:04.587] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:35:04.597] <TB2> INFO: dumping ASCII scurve output file: SCurveData
[15:35:06.419] <TB2> INFO: PixTestScurves::scurves() done
[15:35:06.419] <TB2> INFO: Vcal mean: 55.74
[15:35:06.419] <TB2> INFO: Vcal RMS: 4.61
[15:35:06.424] <TB2> INFO: enter test to run
[15:35:06.424] <TB2> INFO: test: Trim no parameter change
[15:35:06.425] <TB2> INFO: running: trim
[15:35:06.426] <TB2> INFO: ######################################################################
[15:35:06.426] <TB2> INFO: PixTestTrim::doTest()
[15:35:06.426] <TB2> INFO: ######################################################################
[15:35:06.427] <TB2> INFO: ----------------------------------------------------------------------
[15:35:06.427] <TB2> INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[15:35:06.427] <TB2> INFO: ----------------------------------------------------------------------
[15:35:06.432] <TB2> INFO: ---> VthrComp thr map (minimal VthrComp)
[15:35:06.432] <TB2> INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[15:35:06.440] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:35:06.440] <TB2> INFO: run 1 of 1
[15:35:06.459] <TB2> INFO: Expecting 6281600 events.
[15:35:54.841] <TB2> INFO: 6281600 events read in total (47993ms).
[15:35:54.863] <TB2> INFO: Test took 48423ms.
[15:35:54.873] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:35:56.015] <TB2> INFO: ROC 0 VthrComp = 66
[15:35:56.016] <TB2> INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[15:35:56.016] <TB2> INFO: ---> dac: vcal name: TrimThr1 ntrig: 10 dacrange: 10 .. 160 (-1/-1) hits flags = 528 (plus default)
[15:35:56.023] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:35:56.023] <TB2> INFO: run 1 of 1
[15:35:56.042] <TB2> INFO: Expecting 6281600 events.
[15:36:48.302] <TB2> INFO: 6281600 events read in total (51873ms).
[15:36:48.355] <TB2> INFO: Test took 52332ms.
[15:36:48.375] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:49.708] <TB2> INFO: roc 0 with ID = 0 has maximal Vcal 55.7662 for pixel 10/3 mean/min/max = 44.2931/32.7735/55.8126
[15:36:49.717] <TB2> INFO: Expecting 514560 events.
[15:36:54.091] <TB2> INFO: 514560 events read in total (3987ms).
[15:36:54.096] <TB2> INFO: Test took 4388ms.
[15:36:54.493] <TB2> INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 150 (-1/-1) hits flags = 528 (plus default)
[15:36:54.501] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:36:54.501] <TB2> INFO: run 1 of 1
[15:36:54.520] <TB2> INFO: Expecting 6281600 events.
[15:37:46.397] <TB2> INFO: 6281600 events read in total (51490ms).
[15:37:46.448] <TB2> INFO: Test took 51947ms.
[15:37:46.468] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:37:47.631] <TB2> INFO: ---> TrimStepCorr4 extremal thresholds: 17.380782 .. 45.671483
[15:37:47.636] <TB2> INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 10 dacrange: 7 .. 55 (-1/-1) hits flags = 528 (plus default)
[15:37:47.643] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:37:47.643] <TB2> INFO: run 1 of 1
[15:37:47.662] <TB2> INFO: Expecting 2038400 events.
[15:38:04.205] <TB2> INFO: 2038400 events read in total (16156ms).
[15:38:04.214] <TB2> INFO: Test took 16571ms.
[15:38:04.218] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:05.036] <TB2> INFO: ---> TrimStepCorr2 extremal thresholds: 24.977050 .. 39.064619
[15:38:05.041] <TB2> INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 10 dacrange: 14 .. 49 (-1/-1) hits flags = 528 (plus default)
[15:38:05.049] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:38:05.049] <TB2> INFO: run 1 of 1
[15:38:05.068] <TB2> INFO: Expecting 1497600 events.
[15:38:17.606] <TB2> INFO: 1497600 events read in total (12151ms).
[15:38:17.612] <TB2> INFO: Test took 12563ms.
[15:38:17.615] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:18.495] <TB2> INFO: ---> TrimStepCorr1a extremal thresholds: 27.944055 .. 37.291616
[15:38:18.500] <TB2> INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 10 dacrange: 17 .. 47 (-1/-1) hits flags = 528 (plus default)
[15:38:18.508] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:38:18.508] <TB2> INFO: run 1 of 1
[15:38:18.527] <TB2> INFO: Expecting 1289600 events.
[15:38:29.371] <TB2> INFO: 1289600 events read in total (10457ms).
[15:38:29.377] <TB2> INFO: Test took 10869ms.
[15:38:29.380] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:30.168] <TB2> INFO: ---> TrimStepCorr1b extremal thresholds: 29.148929 .. 36.479986
[15:38:30.173] <TB2> INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 10 dacrange: 19 .. 46 (-1/-1) hits flags = 528 (plus default)
[15:38:30.181] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:38:30.181] <TB2> INFO: run 1 of 1
[15:38:30.201] <TB2> INFO: Expecting 1164800 events.
[15:38:39.914] <TB2> INFO: 1164800 events read in total (9327ms).
[15:38:39.920] <TB2> INFO: Test took 9739ms.
[15:38:39.922] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:40.663] <TB2> INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[15:38:40.663] <TB2> INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (-1/-1) hits flags = 528 (plus default)
[15:38:40.671] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:38:40.671] <TB2> INFO: run 1 of 1
[15:38:40.690] <TB2> INFO: Expecting 1705600 events.
[15:38:54.602] <TB2> INFO: 1705600 events read in total (13525ms).
[15:38:54.610] <TB2> INFO: Test took 13939ms.
[15:38:54.614] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:55.476] <TB2> INFO: write dac parameters into /home/mameinha/data/R427_FulltestROC_m20_2015-12-04_16h24m_1449242642//000_FulltestROC_m20//dacParameters35_C0.dat
[15:38:55.523] <TB2> INFO: write trim parameters into /home/mameinha/data/R427_FulltestROC_m20_2015-12-04_16h24m_1449242642//000_FulltestROC_m20//trimParameters35_C0.dat
[15:38:55.601] <TB2> INFO: PixTestTrim::trimTest() done
[15:38:55.601] <TB2> INFO: vtrim: 88
[15:38:55.601] <TB2> INFO: vthrcomp: 66
[15:38:55.601] <TB2> INFO: vcal mean: 34.93
[15:38:55.601] <TB2> INFO: vcal RMS: 0.66
[15:38:55.601] <TB2> INFO: bits mean: 9.80
[15:38:55.601] <TB2> INFO: bits RMS: 2.57
[15:38:55.604] <TB2> INFO: ----------------------------------------------------------------------
[15:38:55.604] <TB2> INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[15:38:55.604] <TB2> INFO: ----------------------------------------------------------------------
[15:38:55.605] <TB2> INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (-1/-1) hits flags = 528 (plus default)
[15:38:55.612] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:38:55.612] <TB2> INFO: run 1 of 1
[15:38:55.631] <TB2> INFO: Expecting 8320000 events.
[15:40:02.627] <TB2> INFO: 8320000 events read in total (66609ms).
[15:40:02.681] <TB2> INFO: Test took 67069ms.
[15:40:02.707] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:40:04.139] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 103 (-1/-1) hits flags = 528 (plus default)
[15:40:04.146] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:40:04.146] <TB2> INFO: run 1 of 1
[15:40:04.165] <TB2> INFO: Expecting 4326400 events.
[15:40:38.089] <TB2> INFO: 4326400 events read in total (33537ms).
[15:40:38.105] <TB2> INFO: Test took 33959ms.
[15:40:38.113] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:40:39.173] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 92 (-1/-1) hits flags = 528 (plus default)
[15:40:39.180] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:40:39.180] <TB2> INFO: run 1 of 1
[15:40:39.200] <TB2> INFO: Expecting 3868800 events.
[15:41:08.868] <TB2> INFO: 3868800 events read in total (29281ms).
[15:41:08.884] <TB2> INFO: Test took 29704ms.
[15:41:08.890] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:41:09.884] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 92 (-1/-1) hits flags = 528 (plus default)
[15:41:09.891] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:41:09.891] <TB2> INFO: run 1 of 1
[15:41:09.911] <TB2> INFO: Expecting 3868800 events.
[15:41:39.309] <TB2> INFO: 3868800 events read in total (29011ms).
[15:41:39.321] <TB2> INFO: Test took 29430ms.
[15:41:39.326] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:41:40.292] <TB2> INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 91 (-1/-1) hits flags = 528 (plus default)
[15:41:40.299] <TB2> INFO: dacScan split into 1 runs with ntrig = 10
[15:41:40.299] <TB2> INFO: run 1 of 1
[15:41:40.318] <TB2> INFO: Expecting 3827200 events.
[15:42:10.291] <TB2> INFO: 3827200 events read in total (29586ms).
[15:42:10.303] <TB2> INFO: Test took 30004ms.
[15:42:10.309] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:42:11.286] <TB2> INFO: PixTestTrim::trimBitTest() done
[15:42:11.287] <TB2> INFO: PixTestTrim::doTest() done, duration: 424 seconds
[15:42:11.329] <TB2> INFO: enter test to run
[15:42:11.329] <TB2> INFO: test: PhOptimization no parameter change
[15:42:11.329] <TB2> INFO: running: phoptimization
[15:42:11.329] <TB2> INFO: ######################################################################
[15:42:11.329] <TB2> INFO: PixTestPhOptimization::doTest() Ntrig = 10
[15:42:11.329] <TB2> INFO: ######################################################################
[15:42:11.350] <TB2> INFO: Expecting 41600 events.
[15:42:12.169] <TB2> INFO: 41600 events read in total (432ms).
[15:42:12.169] <TB2> INFO: Test took 838ms.
[15:42:12.169] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:42:12.560] <TB2> INFO: Expecting 41600 events.
[15:42:13.339] <TB2> INFO: 41600 events read in total (392ms).
[15:42:13.340] <TB2> INFO: Test took 1170ms.
[15:42:13.340] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:42:13.733] <TB2> INFO: Expecting 41600 events.
[15:42:14.579] <TB2> INFO: 41600 events read in total (459ms).
[15:42:14.580] <TB2> INFO: Test took 1239ms.
[15:42:14.580] <TB2> INFO: Fetched DAQ statistics. Counters are being reset now.
[15:42:14.969] <TB2> INFO: Expecting 2560 events.
[15:42:15.389] <TB2> INFO: 2560 events read in total (34ms).
[15:42:15.390] <TB2> INFO: Test took 809ms.
[15:42:15.784] <TB2> INFO: Expecting 655360 events.
[15:42:21.350] <TB2> INFO: 655360 events read in total (5179ms).
[15:42:21.361] <TB2> INFO: Test took 5971ms.
[15:42:21.630] <TB2> INFO: Expecting 655360 events.
[15:42:27.251] <TB2> INFO: 655360 events read in total (5234ms).
[15:42:27.259] <TB2> INFO: Test took 5878ms.
[15:42:27.279] <TB2> INFO: safety margin for low PH: adding 0, margin is now 20
[15:42:27.298] <TB2> INFO: write dac parameters into /home/mameinha/data/R427_FulltestROC_m20_2015-12-04_16h24m_1449242642//000_FulltestROC_m20//dacParameters35_C0.dat
[15:42:27.545] <TB2> INFO: Expecting 41600 events.
[15:42:28.289] <TB2> INFO: 41600 events read in total (357ms).
[15:42:28.290] <TB2> INFO: Test took 982ms.
[15:42:28.679] <TB2> INFO: Expecting 41600 events.
[15:42:29.477] <TB2> INFO: 41600 events read in total (411ms).
[15:42:29.477] <TB2> INFO: Test took 1186ms.
[15:42:29.859] <TB2> INFO: Expecting 41600 events.
[15:42:30.669] <TB2> INFO: 41600 events read in total (423ms).
[15:42:30.670] <TB2> INFO: Test took 1192ms.
[15:42:31.055] <TB2> INFO: Expecting 2560 events.
[15:42:31.475] <TB2> INFO: 2560 events read in total (33ms).
[15:42:31.476] <TB2> INFO: Test took 805ms.
[15:42:31.870] <TB2> INFO: Expecting 2560 events.
[15:42:32.289] <TB2> INFO: 2560 events read in total (32ms).
[15:42:32.289] <TB2> INFO: Test took 813ms.
[15:42:32.695] <TB2> INFO: PixTestPhOptimization::doTest() done, duration: 21 seconds
[15:42:32.695] <TB2> INFO: PH scale (per ROC): 73
[15:42:32.695] <TB2> INFO: PH offset (per ROC): 131
[15:42:32.710] <TB2> INFO: enter test to run
[15:42:32.710] <TB2> INFO: test: GainPedestal no parameter change
[15:42:32.710] <TB2> INFO: running: gainpedestal
[15:42:32.711] <TB2> INFO: ######################################################################
[15:42:32.711] <TB2> INFO: PixTestGainPedestal::doTest() ntrig = 10
[15:42:32.711] <TB2> INFO: ######################################################################
[15:42:32.719] <TB2> INFO: scanning low vcal = 10
[15:42:32.738] <TB2> INFO: Expecting 41600 events.
[15:42:33.834] <TB2> INFO: 41600 events read in total (709ms).
[15:42:33.835] <TB2> INFO: Test took 1116ms.
[15:42:33.836] <TB2> INFO: scanning low vcal = 20
[15:42:34.229] <TB2> INFO: Expecting 41600 events.
[15:42:35.326] <TB2> INFO: 41600 events read in total (710ms).
[15:42:35.326] <TB2> INFO: Test took 1490ms.
[15:42:35.326] <TB2> INFO: scanning low vcal = 30
[15:42:35.721] <TB2> INFO: Expecting 41600 events.
[15:42:36.810] <TB2> INFO: 41600 events read in total (702ms).
[15:42:36.811] <TB2> INFO: Test took 1484ms.
[15:42:36.811] <TB2> INFO: scanning low vcal = 40
[15:42:37.206] <TB2> INFO: Expecting 41600 events.
[15:42:38.343] <TB2> INFO: 41600 events read in total (750ms).
[15:42:38.344] <TB2> INFO: Test took 1533ms.
[15:42:38.344] <TB2> INFO: scanning low vcal = 50
[15:42:38.729] <TB2> INFO: Expecting 41600 events.
[15:42:39.854] <TB2> INFO: 41600 events read in total (738ms).
[15:42:39.855] <TB2> INFO: Test took 1511ms.
[15:42:39.855] <TB2> INFO: scanning low vcal = 60
[15:42:40.243] <TB2> INFO: Expecting 41600 events.
[15:42:41.389] <TB2> INFO: 41600 events read in total (759ms).
[15:42:41.390] <TB2> INFO: Test took 1535ms.
[15:42:41.390] <TB2> INFO: scanning low vcal = 70
[15:42:41.775] <TB2> INFO: Expecting 41600 events.
[15:42:42.937] <TB2> INFO: 41600 events read in total (775ms).
[15:42:42.938] <TB2> INFO: Test took 1548ms.
[15:42:42.938] <TB2> INFO: scanning low vcal = 80
[15:42:43.320] <TB2> INFO: Expecting 41600 events.
[15:42:44.489] <TB2> INFO: 41600 events read in total (782ms).
[15:42:44.489] <TB2> INFO: Test took 1551ms.
[15:42:44.489] <TB2> INFO: scanning low vcal = 90
[15:42:44.873] <TB2> INFO: Expecting 41600 events.
[15:42:46.017] <TB2> INFO: 41600 events read in total (757ms).
[15:42:46.018] <TB2> INFO: Test took 1529ms.
[15:42:46.018] <TB2> INFO: scanning low vcal = 100
[15:42:46.403] <TB2> INFO: Expecting 41600 events.
[15:42:47.580] <TB2> INFO: 41600 events read in total (790ms).
[15:42:47.580] <TB2> INFO: Test took 1562ms.
[15:42:47.581] <TB2> INFO: scanning low vcal = 110
[15:42:47.969] <TB2> INFO: Expecting 41600 events.
[15:42:49.113] <TB2> INFO: 41600 events read in total (757ms).
[15:42:49.113] <TB2> INFO: Test took 1532ms.
[15:42:49.114] <TB2> INFO: scanning low vcal = 120
[15:42:49.499] <TB2> INFO: Expecting 41600 events.
[15:42:50.688] <TB2> INFO: 41600 events read in total (802ms).
[15:42:50.688] <TB2> INFO: Test took 1574ms.
[15:42:50.689] <TB2> INFO: scanning low vcal = 130
[15:42:51.072] <TB2> INFO: Expecting 41600 events.
[15:42:52.226] <TB2> INFO: 41600 events read in total (767ms).
[15:42:52.227] <TB2> INFO: Test took 1538ms.
[15:42:52.227] <TB2> INFO: scanning low vcal = 140
[15:42:52.608] <TB2> INFO: Expecting 41600 events.
[15:42:53.764] <TB2> INFO: 41600 events read in total (769ms).
[15:42:53.764] <TB2> INFO: Test took 1537ms.
[15:42:53.765] <TB2> INFO: scanning low vcal = 150
[15:42:54.153] <TB2> INFO: Expecting 41600 events.
[15:42:55.294] <TB2> INFO: 41600 events read in total (754ms).
[15:42:55.294] <TB2> INFO: Test took 1529ms.
[15:42:55.295] <TB2> INFO: scanning low vcal = 160
[15:42:55.679] <TB2> INFO: Expecting 41600 events.
[15:42:56.832] <TB2> INFO: 41600 events read in total (766ms).
[15:42:56.832] <TB2> INFO: Test took 1537ms.
[15:42:56.833] <TB2> INFO: scanning low vcal = 170
[15:42:57.215] <TB2> INFO: Expecting 41600 events.
[15:42:58.412] <TB2> INFO: 41600 events read in total (810ms).
[15:42:58.413] <TB2> INFO: Test took 1580ms.
[15:42:58.413] <TB2> INFO: scanning low vcal = 180
[15:42:58.793] <TB2> INFO: Expecting 41600 events.
[15:42:59.971] <TB2> INFO: 41600 events read in total (791ms).
[15:42:59.971] <TB2> INFO: Test took 1558ms.
[15:42:59.971] <TB2> INFO: scanning low vcal = 190
[15:43:00.356] <TB2> INFO: Expecting 41600 events.
[15:43:01.518] <TB2> INFO: 41600 events read in total (775ms).
[15:43:01.519] <TB2> INFO: Test took 1548ms.
[15:43:01.519] <TB2> INFO: scanning low vcal = 200
[15:43:01.902] <TB2> INFO: Expecting 41600 events.
[15:43:03.071] <TB2> INFO: 41600 events read in total (783ms).
[15:43:03.073] <TB2> INFO: Test took 1554ms.
[15:43:03.073] <TB2> INFO: scanning low vcal = 210
[15:43:03.452] <TB2> INFO: Expecting 41600 events.
[15:43:04.623] <TB2> INFO: 41600 events read in total (784ms).
[15:43:04.623] <TB2> INFO: Test took 1550ms.
[15:43:04.623] <TB2> INFO: scanning low vcal = 220
[15:43:05.003] <TB2> INFO: Expecting 41600 events.
[15:43:06.197] <TB2> INFO: 41600 events read in total (807ms).
[15:43:06.197] <TB2> INFO: Test took 1573ms.
[15:43:06.197] <TB2> INFO: scanning low vcal = 230
[15:43:06.578] <TB2> INFO: Expecting 41600 events.
[15:43:07.739] <TB2> INFO: 41600 events read in total (774ms).
[15:43:07.740] <TB2> INFO: Test took 1543ms.
[15:43:07.740] <TB2> INFO: scanning low vcal = 240
[15:43:08.125] <TB2> INFO: Expecting 41600 events.
[15:43:09.288] <TB2> INFO: 41600 events read in total (776ms).
[15:43:09.289] <TB2> INFO: Test took 1549ms.
[15:43:09.289] <TB2> INFO: scanning low vcal = 250
[15:43:09.678] <TB2> INFO: Expecting 41600 events.
[15:43:10.846] <TB2> INFO: 41600 events read in total (781ms).
[15:43:10.847] <TB2> INFO: Test took 1558ms.
[15:43:10.848] <TB2> INFO: scanning high vcal = 30 (= 210 in low range)
[15:43:11.228] <TB2> INFO: Expecting 41600 events.
[15:43:12.390] <TB2> INFO: 41600 events read in total (775ms).
[15:43:12.390] <TB2> INFO: Test took 1542ms.
[15:43:12.390] <TB2> INFO: scanning high vcal = 50 (= 350 in low range)
[15:43:12.775] <TB2> INFO: Expecting 41600 events.
[15:43:13.926] <TB2> INFO: 41600 events read in total (764ms).
[15:43:13.926] <TB2> INFO: Test took 1536ms.
[15:43:13.926] <TB2> INFO: scanning high vcal = 70 (= 490 in low range)
[15:43:14.307] <TB2> INFO: Expecting 41600 events.
[15:43:15.456] <TB2> INFO: 41600 events read in total (762ms).
[15:43:15.457] <TB2> INFO: Test took 1530ms.
[15:43:15.457] <TB2> INFO: scanning high vcal = 90 (= 630 in low range)
[15:43:15.837] <TB2> INFO: Expecting 41600 events.
[15:43:16.968] <TB2> INFO: 41600 events read in total (744ms).
[15:43:16.968] <TB2> INFO: Test took 1511ms.
[15:43:16.968] <TB2> INFO: scanning high vcal = 200 (= 1400 in low range)
[15:43:17.357] <TB2> INFO: Expecting 41600 events.
[15:43:18.487] <TB2> INFO: 41600 events read in total (743ms).
[15:43:18.488] <TB2> INFO: Test took 1520ms.
[15:43:18.872] <TB2> INFO: PixTestGainPedestal::measure() done
[15:43:21.161] <TB2> INFO: PixTestGainPedestal::fit() done
[15:43:21.161] <TB2> INFO: non-linearity mean: 0.918
[15:43:21.161] <TB2> INFO: non-linearity RMS: 0.028
[15:43:21.161] <TB2> INFO: write gain/ped parameters into /home/mameinha/data/R427_FulltestROC_m20_2015-12-04_16h24m_1449242642//000_FulltestROC_m20//phCalibrationFitErr35_C0.dat
[15:43:21.308] <TB2> INFO: PixTestGainPedestal::doTest() done, duration: 48 seconds
[15:43:21.309] <TB2> INFO: enter test to run
[15:43:21.309] <TB2> INFO: test: Readback no parameter change
[15:43:21.309] <TB2> INFO: running: readback
[15:43:21.309] <TB2> INFO: readReadbackCal: /home/mameinha/data/R427_FulltestROC_m20_2015-12-04_16h24m_1449242642//000_FulltestROC_m20//readbackCal_C0.dat .. /home/mameinha/data/R427_FulltestROC_m20_2015-12-04_16h24m_1449242642//000_FulltestROC_m20//readbackCal_C0.dat
[15:43:21.311] <TB2> INFO: ######################################################################
[15:43:21.311] <TB2> INFO: PixTestReadback::doTest()
[15:43:21.311] <TB2> INFO: ######################################################################
[15:43:21.311] <TB2> INFO: ----------------------------------------------------------------------
[15:43:21.311] <TB2> INFO: PixTestReadback::CalibrateVd()
[15:43:21.311] <TB2> INFO: ----------------------------------------------------------------------
[15:43:32.490] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R427_FulltestROC_m20_2015-12-04_16h24m_1449242642//000_FulltestROC_m20//readbackCal_C0.dat
[15:43:32.500] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[15:43:32.500] <TB2> INFO: ----------------------------------------------------------------------
[15:43:32.500] <TB2> INFO: PixTestReadback::CalibrateVa()
[15:43:32.500] <TB2> INFO: ----------------------------------------------------------------------
[15:43:43.645] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R427_FulltestROC_m20_2015-12-04_16h24m_1449242642//000_FulltestROC_m20//readbackCal_C0.dat
[15:43:43.724] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[15:43:43.724] <TB2> INFO: ----------------------------------------------------------------------
[15:43:43.724] <TB2> INFO: PixTestReadback::readbackVbg()
[15:43:43.724] <TB2> INFO: ----------------------------------------------------------------------
[15:43:52.050] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[15:43:52.050] <TB2> INFO: ----------------------------------------------------------------------
[15:43:52.050] <TB2> INFO: PixTestReadback::getCalibratedVbg()
[15:43:52.050] <TB2> INFO: ----------------------------------------------------------------------
[15:43:52.050] <TB2> INFO: Vbg will be calibrated using Vd calibration
[15:43:52.050] <TB2> INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 122.6calibrated Vbg = 1.34246 :::*/*/*/*/
[15:43:52.426] <TB2> INFO: ----------------------------------------------------------------------
[15:43:52.427] <TB2> INFO: PixTestReadback::CalibrateIa()
[15:43:52.427] <TB2> INFO: ----------------------------------------------------------------------
[15:44:01.320] <TB2> INFO: write readback calibration parameters into /home/mameinha/data/R427_FulltestROC_m20_2015-12-04_16h24m_1449242642//000_FulltestROC_m20//readbackCal_C0.dat
[15:44:01.381] <TB2> INFO: PixTestPattern:: pg_setup set to default.
[15:44:01.381] <TB2> INFO: PixTestReadback::doTest() done
[15:44:01.420] <TB2> INFO: enter test to run
[15:44:01.420] <TB2> INFO: test: no parameter change
[15:44:01.590] <TB2> QUIET: Connection to board 169 closed.
[15:44:01.669] <TB2> INFO: pXar: this is the end, my friend