[20:49:13.663] INFO: *** Welcome to pxar ***
[20:49:13.663] INFO: *** Today: 2015/08/10
[20:49:13.663] INFO: readRocDacs: /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters_C0.dat .. /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters_C15.dat
[20:49:13.665] INFO: readTbmDacs: /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/tbmParameters_C0a.dat .. /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/tbmParameters_C0b.dat
[20:49:13.665] INFO: readMaskFile: /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/defaultMaskFile.dat
[20:49:13.665] INFO: readTrimFile: /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/trimParameters_C0.dat .. /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/trimParameters_C15.dat
[20:49:13.770] INFO: clk: 4
[20:49:13.770] INFO: ctr: 4
[20:49:13.770] INFO: sda: 19
[20:49:13.770] INFO: tin: 9
[20:49:13.770] INFO: level: 15
[20:49:13.770] INFO: triggerdelay: 0
[20:49:13.770] QUIET: Instanciating API for pxar prod-01+36~geb5ac3f
[20:49:13.770] INFO: Log level: INFO
[20:49:13.785] INFO: Found DTB DTB_WZ4Y8V
[20:49:13.800] QUIET: Connection to board DTB_WZ4Y8V opened.
[20:49:13.803] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 176
HW version: DTB1.2
FW version: 4.0
SW version: 4.0
USB id: DTB_WZ4Y8V
MAC address: 40D8551180B0
Hostname: pixelDTB176
Comment:
------------------------------------------------------
[20:49:13.806] INFO: RPC call hashes of host and DTB match: 447413373
[20:49:15.544] INFO: DUT info:
[20:49:15.544] INFO: The DUT currently contains the following objects:
[20:49:15.544] INFO: 2 TBM Cores tbm08c (2 ON)
[20:49:15.544] INFO: TBM Core alpha (0): 7 registers set
[20:49:15.544] INFO: TBM Core beta (1): 7 registers set
[20:49:15.544] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[20:49:15.544] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[20:49:15.544] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[20:49:15.544] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[20:49:15.544] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[20:49:15.544] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[20:49:15.544] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[20:49:15.544] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[20:49:15.544] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[20:49:15.544] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[20:49:15.544] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[20:49:15.544] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[20:49:15.544] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[20:49:15.544] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[20:49:15.544] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[20:49:15.544] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[20:49:15.544] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[20:49:15.945] INFO: enter 'restricted' command line mode
[20:49:15.945] INFO: enter test to run
[20:49:15.945] INFO: test: pretest no parameter change
[20:49:15.945] INFO: running: pretest
[20:49:15.953] INFO: ######################################################################
[20:49:15.953] INFO: PixTestPretest::doTest()
[20:49:15.953] INFO: ######################################################################
[20:49:15.954] INFO: ----------------------------------------------------------------------
[20:49:15.955] INFO: PixTestPretest::programROC()
[20:49:15.955] INFO: ----------------------------------------------------------------------
[20:49:33.973] INFO: PixTestPretest::programROC() done: ROCs are all programmable
[20:49:33.974] INFO: IA differences per ROC: 18.5 20.9 19.3 18.5 18.5 19.3 20.1 20.1 18.5 20.1 18.5 16.1 20.1 20.1 17.7 20.1
[20:49:34.050] INFO: ----------------------------------------------------------------------
[20:49:34.050] INFO: PixTestPretest::setVana() target Ia = 24 mA/ROC
[20:49:34.050] INFO: ----------------------------------------------------------------------
[20:49:38.149] INFO: PixTestPretest::setVana() done, Module Ia 383.5 mA = 23.9688 mA/ROC
[20:49:38.152] INFO: ----------------------------------------------------------------------
[20:49:38.152] INFO: PixTestPretest::findWorkingPixel()
[20:49:38.152] INFO: ----------------------------------------------------------------------
[20:49:45.767] INFO: Test took 7606ms.
[20:49:46.090] INFO: Found working pixel in all ROCs: col/row = 12/22
[20:49:46.142] INFO: ----------------------------------------------------------------------
[20:49:46.142] INFO: PixTestPretest::setVthrCompCalDel()
[20:49:46.142] INFO: ----------------------------------------------------------------------
[20:49:53.725] INFO: Test took 7574ms.
[20:49:54.081] INFO: PixTestPretest::setVthrCompCalDel() done
[20:49:54.081] INFO: CalDel: 112 109 112 107 120 135 129 132 116 109 97 115 130 123 99 127
[20:49:54.081] INFO: VthrComp: 51 51 51 53 51 51 51 51 51 51 51 51 51 51 51 51
[20:49:54.087] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters_C0.dat
[20:49:54.088] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters_C1.dat
[20:49:54.088] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters_C2.dat
[20:49:54.088] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters_C3.dat
[20:49:54.089] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters_C4.dat
[20:49:54.089] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters_C5.dat
[20:49:54.089] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters_C6.dat
[20:49:54.089] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters_C7.dat
[20:49:54.089] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters_C8.dat
[20:49:54.090] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters_C9.dat
[20:49:54.090] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters_C10.dat
[20:49:54.090] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters_C11.dat
[20:49:54.090] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters_C12.dat
[20:49:54.090] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters_C13.dat
[20:49:54.091] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters_C14.dat
[20:49:54.091] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters_C15.dat
[20:49:54.091] INFO: PixTestPretest::doTest() done, duration: 38 seconds
[20:49:54.176] INFO: enter test to run
[20:49:54.176] INFO: test: fulltest no parameter change
[20:49:54.176] INFO: running: fulltest
[20:49:54.176] INFO: ######################################################################
[20:49:54.176] INFO: PixTestFullTest::doTest()
[20:49:54.176] INFO: ######################################################################
[20:49:54.178] INFO: ######################################################################
[20:49:54.178] INFO: PixTestAlive::doTest()
[20:49:54.178] INFO: ######################################################################
[20:49:54.179] INFO: ----------------------------------------------------------------------
[20:49:54.179] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[20:49:54.179] INFO: ----------------------------------------------------------------------
[20:49:57.800] INFO: Test took 3619ms.
[20:49:57.835] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:49:58.072] INFO: PixTestAlive::aliveTest() done
[20:49:58.072] INFO: number of dead pixels (per ROC): 2 0 0 0 1 0 0 0 1 1 0 0 0 0 0 0
[20:49:58.074] INFO: ----------------------------------------------------------------------
[20:49:58.074] INFO: PixTestAlive::maskTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[20:49:58.074] INFO: ----------------------------------------------------------------------
[20:50:00.872] INFO: Test took 2796ms.
[20:50:00.879] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:50:00.880] INFO: mask vs. old pixelAlive PixelAlive_C0_V0 .. PixelAlive_C15_V0
[20:50:01.119] INFO: PixTestAlive::maskTest() done
[20:50:01.119] INFO: number of mask-defect pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[20:50:01.121] INFO: ----------------------------------------------------------------------
[20:50:01.121] INFO: PixTestAlive::addressDecodingTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[20:50:01.121] INFO: ----------------------------------------------------------------------
[20:50:04.736] INFO: Test took 3613ms.
[20:50:04.771] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:50:05.017] INFO: PixTestAlive::addressDecodingTest() done
[20:50:05.017] INFO: number of address-decoding pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[20:50:05.018] INFO: PixTestAlive::doTest() done, duration: 10 seconds
[20:50:05.028] INFO: ######################################################################
[20:50:05.028] INFO: PixTestBBMap::doTest() Ntrig = 5, VcalS = 250 (high range)
[20:50:05.028] INFO: ######################################################################
[20:50:05.031] INFO: ---> dac: VthrComp name: calSMap ntrig: 5 dacrange: 0 .. 149 (30/5) hits flags = 2 (plus default)
[20:50:05.056] INFO: dacScan step from 0 .. 29
[20:50:05.056] INFO: dacScan split into 1 runs with ntrig = 5
[20:50:05.056] INFO: run 1 of 1
[20:50:24.923] INFO: Test took 19867ms.
[20:50:24.980] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:50:24.980] INFO: dacScan step from 30 .. 59
[20:50:24.980] INFO: dacScan split into 1 runs with ntrig = 5
[20:50:24.980] INFO: run 1 of 1
[20:50:44.780] INFO: Test took 19800ms.
[20:50:44.849] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:50:44.850] INFO: dacScan step from 60 .. 89
[20:50:44.850] INFO: dacScan split into 1 runs with ntrig = 5
[20:50:44.850] INFO: run 1 of 1
[20:51:09.363] INFO: Test took 24512ms.
[20:51:09.689] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:51:09.759] INFO: dacScan step from 90 .. 119
[20:51:09.759] INFO: dacScan split into 1 runs with ntrig = 5
[20:51:09.759] INFO: run 1 of 1
[20:51:37.384] INFO: Test took 27625ms.
[20:51:37.788] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:51:37.902] INFO: dacScan step from 120 .. 149
[20:51:37.902] INFO: dacScan split into 1 runs with ntrig = 5
[20:51:37.902] INFO: run 1 of 1
[20:51:57.003] ERROR: <datapipe.cc/CheckEventValidity:L463> Channel 0 Number of ROCs (6) != Token Chain Length (8)
[20:51:57.003] WARNING: Channel 1 ROC 6: Readback start marker after 8 readouts!
[20:51:57.003] ERROR: <datapipe.cc/CheckEventValidity:L463> Channel 1 Number of ROCs (7) != Token Chain Length (8)
[20:51:58.003] ERROR: <datapipe.cc/CheckEventID:L446> Channel 0 Event ID mismatch: local ID (56) != TBM ID (192)
[20:51:58.003] ERROR: <datapipe.cc/CheckEventValidity:L463> Channel 0 Number of ROCs (0) != Token Chain Length (8)
[20:51:58.003] ERROR: <datapipe.cc/CheckEventID:L446> Channel 0 Event ID mismatch: local ID (193) != TBM ID (56)
[20:51:58.003] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!
[20:51:58.003] WARNING: Channel 0 ROC 7: Readback start marker after 15 readouts!
[20:51:59.054] ERROR: <datapipe.cc/CheckEventID:L446> Channel 1 Event ID mismatch: local ID (103) != TBM ID (104)
[20:51:59.054] ERROR: <datapipe.cc/CheckEventID:L446> Channel 0 Event ID mismatch: local ID (103) != TBM ID (104)
[20:51:59.054] WARNING: Channel 1 ROC 0: Readback start marker after 15 readouts!
[20:51:59.054] WARNING: Channel 1 ROC 1: Readback start marker after 15 readouts!
[20:51:59.054] WARNING: Channel 1 ROC 2: Readback start marker after 15 readouts!
[20:51:59.054] WARNING: Channel 1 ROC 3: Readback start marker after 15 readouts!
[20:51:59.054] WARNING: Channel 1 ROC 4: Readback start marker after 15 readouts!
[20:51:59.054] WARNING: Channel 1 ROC 5: Readback start marker after 15 readouts!
[20:51:59.054] WARNING: Channel 1 ROC 6: Readback start marker after 15 readouts!
[20:51:59.054] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!
[20:51:59.054] WARNING: Channel 0 ROC 0: Readback start marker after 15 readouts!
[20:51:59.054] WARNING: Channel 0 ROC 1: Readback start marker after 15 readouts!
[20:51:59.054] WARNING: Channel 0 ROC 2: Readback start marker after 15 readouts!
[20:51:59.054] WARNING: Channel 0 ROC 3: Readback start marker after 15 readouts!
[20:51:59.054] WARNING: Channel 0 ROC 4: Readback start marker after 15 readouts!
[20:51:59.054] WARNING: Channel 0 ROC 5: Readback start marker after 15 readouts!
[20:51:59.054] WARNING: Channel 0 ROC 6: Readback start marker after 15 readouts!
[20:51:59.054] WARNING: Channel 0 ROC 7: Readback start marker after 15 readouts!
[20:52:02.440] INFO: Test took 24537ms.
[20:52:02.763] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:52:34.284] INFO: PixTestBBMap::doTest() done with 30 decoding errors: , duration: 149 seconds
[20:52:34.284] INFO: number of dead bumps (per ROC): 0 0 0 0 0 0 0 1 0 0 0 0 0 0 0 0
[20:52:34.284] INFO: separation cut (per ROC): 116 118 109 112 104 112 111 103 105 111 103 99 108 112 111 94
[20:52:34.374] INFO: ######################################################################
[20:52:34.374] INFO: PixTestScurves::fullTest() ntrig = 50, dacs/step = -1, ntrig/step = 1
[20:52:34.374] INFO: ######################################################################
[20:52:34.374] INFO: ----------------------------------------------------------------------
[20:52:34.374] INFO: PixTestScurves::scurves(Vcal), ntrig = 50, dacs/step = -1, ntrig/step = 1
[20:52:34.374] INFO: ----------------------------------------------------------------------
[20:52:34.374] INFO: ---> dac: Vcal name: scurveVcal ntrig: 50 dacrange: 0 .. 149 (-1/1) hits flags = 16 (plus default)
[20:52:34.389] INFO: dacScan split into 50 runs with ntrig = 1
[20:52:34.389] INFO: run 1 of 50
[20:53:24.152] INFO: Test took 49762ms.
[20:53:24.476] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:53:24.642] INFO: run 2 of 50
[20:54:14.484] INFO: Test took 49842ms.
[20:54:14.837] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:54:15.008] INFO: run 3 of 50
[20:55:04.790] INFO: Test took 49782ms.
[20:55:05.117] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:55:05.277] INFO: run 4 of 50
[20:55:55.074] INFO: Test took 49797ms.
[20:55:55.396] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:55:55.548] INFO: run 5 of 50
[20:56:45.265] INFO: Test took 49716ms.
[20:56:45.601] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:56:45.761] INFO: run 6 of 50
[20:57:35.588] INFO: Test took 49827ms.
[20:57:35.920] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:57:36.072] INFO: run 7 of 50
[20:58:25.948] INFO: Test took 49876ms.
[20:58:26.264] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:58:26.418] INFO: run 8 of 50
[20:59:16.277] INFO: Test took 49859ms.
[20:59:16.597] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:59:16.752] INFO: run 9 of 50
[21:00:06.662] INFO: Test took 49910ms.
[21:00:06.981] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:00:07.134] INFO: run 10 of 50
[21:00:56.994] INFO: Test took 49860ms.
[21:00:57.313] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:00:57.463] INFO: run 11 of 50
[21:01:47.291] INFO: Test took 49827ms.
[21:01:47.617] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:01:47.771] INFO: run 12 of 50
[21:02:37.683] INFO: Test took 49912ms.
[21:02:38.008] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:02:38.161] INFO: run 13 of 50
[21:03:27.923] INFO: Test took 49762ms.
[21:03:28.240] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:03:28.396] INFO: run 14 of 50
[21:04:18.293] INFO: Test took 49897ms.
[21:04:18.615] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:04:18.802] INFO: run 15 of 50
[21:05:08.749] INFO: Test took 49947ms.
[21:05:09.076] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:05:09.231] INFO: run 16 of 50
[21:05:59.120] INFO: Test took 49889ms.
[21:05:59.437] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:05:59.588] INFO: run 17 of 50
[21:06:49.575] INFO: Test took 49987ms.
[21:06:49.885] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:06:50.039] INFO: run 18 of 50
[21:07:39.872] INFO: Test took 49833ms.
[21:07:40.187] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:07:40.345] INFO: run 19 of 50
[21:08:30.174] INFO: Test took 49828ms.
[21:08:30.487] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:08:30.640] INFO: run 20 of 50
[21:09:20.395] INFO: Test took 49755ms.
[21:09:20.711] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:09:20.872] INFO: run 21 of 50
[21:10:10.714] INFO: Test took 49842ms.
[21:10:11.031] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:10:11.182] INFO: run 22 of 50
[21:11:01.126] INFO: Test took 49944ms.
[21:11:01.443] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:11:01.594] INFO: run 23 of 50
[21:11:51.500] INFO: Test took 49905ms.
[21:11:51.808] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:11:51.961] INFO: run 24 of 50
[21:12:41.791] INFO: Test took 49830ms.
[21:12:42.105] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:12:42.257] INFO: run 25 of 50
[21:13:32.178] INFO: Test took 49921ms.
[21:13:32.490] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:13:32.642] INFO: run 26 of 50
[21:14:22.516] INFO: Test took 49874ms.
[21:14:22.829] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:14:22.984] INFO: run 27 of 50
[21:15:12.825] INFO: Test took 49841ms.
[21:15:13.135] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:15:13.298] INFO: run 28 of 50
[21:16:03.178] INFO: Test took 49880ms.
[21:16:03.494] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:16:03.644] INFO: run 29 of 50
[21:16:53.439] INFO: Test took 49795ms.
[21:16:53.750] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:16:53.900] INFO: run 30 of 50
[21:17:43.775] INFO: Test took 49875ms.
[21:17:44.093] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:17:44.245] INFO: run 31 of 50
[21:18:34.082] INFO: Test took 49837ms.
[21:18:34.405] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:18:34.558] INFO: run 32 of 50
[21:19:24.396] INFO: Test took 49838ms.
[21:19:24.711] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:19:24.872] INFO: run 33 of 50
[21:20:14.661] INFO: Test took 49789ms.
[21:20:14.987] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:20:15.141] INFO: run 34 of 50
[21:21:04.894] INFO: Test took 49753ms.
[21:21:05.214] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:21:05.366] INFO: run 35 of 50
[21:21:54.927] INFO: Test took 49561ms.
[21:21:55.245] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:21:55.417] INFO: run 36 of 50
[21:22:45.127] INFO: Test took 49710ms.
[21:22:45.447] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:22:45.598] INFO: run 37 of 50
[21:23:35.367] INFO: Test took 49768ms.
[21:23:35.687] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:23:35.843] INFO: run 38 of 50
[21:24:25.613] INFO: Test took 49770ms.
[21:24:25.933] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:24:26.088] INFO: run 39 of 50
[21:25:15.929] INFO: Test took 49841ms.
[21:25:16.236] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:25:16.395] INFO: run 40 of 50
[21:26:06.037] INFO: Test took 49642ms.
[21:26:06.357] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:26:06.508] INFO: run 41 of 50
[21:26:56.265] INFO: Test took 49757ms.
[21:26:56.587] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:26:56.742] INFO: run 42 of 50
[21:27:46.503] INFO: Test took 49761ms.
[21:27:46.817] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:27:46.980] INFO: run 43 of 50
[21:28:36.777] INFO: Test took 49797ms.
[21:28:37.095] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:28:37.246] INFO: run 44 of 50
[21:29:27.007] INFO: Test took 49761ms.
[21:29:27.420] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:29:27.570] INFO: run 45 of 50
[21:30:17.401] INFO: Test took 49830ms.
[21:30:17.716] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:30:17.868] INFO: run 46 of 50
[21:31:07.694] INFO: Test took 49826ms.
[21:31:08.019] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:31:08.183] INFO: run 47 of 50
[21:31:58.004] INFO: Test took 49821ms.
[21:31:58.326] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:31:58.486] INFO: run 48 of 50
[21:32:48.132] INFO: Test took 49646ms.
[21:32:48.450] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:32:48.603] INFO: run 49 of 50
[21:33:38.273] INFO: Test took 49670ms.
[21:33:38.594] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:33:38.750] INFO: run 50 of 50
[21:34:28.294] INFO: Test took 49544ms.
[21:34:28.619] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:34:28.782] INFO: dumping ASCII scurve output file: SCurveData
[21:34:30.924] INFO: dumping ASCII scurve output file: SCurveData
[21:34:33.364] INFO: dumping ASCII scurve output file: SCurveData
[21:34:35.395] INFO: dumping ASCII scurve output file: SCurveData
[21:34:37.362] INFO: dumping ASCII scurve output file: SCurveData
[21:34:39.457] INFO: dumping ASCII scurve output file: SCurveData
[21:34:41.530] INFO: dumping ASCII scurve output file: SCurveData
[21:34:43.775] INFO: dumping ASCII scurve output file: SCurveData
[21:34:46.077] INFO: dumping ASCII scurve output file: SCurveData
[21:34:48.652] INFO: dumping ASCII scurve output file: SCurveData
[21:34:50.968] INFO: dumping ASCII scurve output file: SCurveData
[21:34:53.422] INFO: dumping ASCII scurve output file: SCurveData
[21:34:55.793] INFO: dumping ASCII scurve output file: SCurveData
[21:34:58.219] INFO: dumping ASCII scurve output file: SCurveData
[21:35:00.580] INFO: dumping ASCII scurve output file: SCurveData
[21:35:02.892] INFO: dumping ASCII scurve output file: SCurveData
[21:35:05.375] INFO: PixTestScurves::scurves() done
[21:35:05.375] INFO: Vcal mean: 111.53 108.80 98.34 111.34 100.41 112.64 97.06 101.87 105.98 92.50 94.96 103.30 103.00 106.88 105.55 83.34
[21:35:05.375] INFO: Vcal RMS: 5.55 5.61 5.42 5.02 6.29 5.73 5.33 6.06 5.40 5.61 5.19 5.56 5.93 5.36 5.16 4.89
[21:35:05.375] INFO: PixTestScurves::fullTest() done, duration: 2551 seconds
[21:35:05.489] INFO: ######################################################################
[21:35:05.489] INFO: PixTestTrim::doTest()
[21:35:05.489] INFO: ######################################################################
[21:35:05.491] INFO: ----------------------------------------------------------------------
[21:35:05.491] INFO: PixTestTrim::trimTest() ntrig = 10, vcal = 35
[21:35:05.491] INFO: ----------------------------------------------------------------------
[21:35:05.634] INFO: ---> VthrComp thr map (minimal VthrComp)
[21:35:05.634] INFO: ---> dac: vthrcomp name: TrimThr0 ntrig: 5 dacrange: 0 .. 159 (20/-1) hits flags = 16 (plus default)
[21:35:05.649] INFO: dacScan step from 0 .. 19
[21:35:05.649] INFO: dacScan split into 1 runs with ntrig = 5
[21:35:05.649] INFO: run 1 of 1
[21:35:19.589] INFO: Test took 13940ms.
[21:35:19.639] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:35:19.639] INFO: dacScan step from 20 .. 39
[21:35:19.639] INFO: dacScan split into 1 runs with ntrig = 5
[21:35:19.639] INFO: run 1 of 1
[21:35:33.774] INFO: Test took 14135ms.
[21:35:33.812] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:35:33.812] INFO: dacScan step from 40 .. 59
[21:35:33.812] INFO: dacScan split into 1 runs with ntrig = 5
[21:35:33.812] INFO: run 1 of 1
[21:35:47.922] INFO: Test took 14110ms.
[21:35:47.957] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:35:47.957] INFO: dacScan step from 60 .. 79
[21:35:47.957] INFO: dacScan split into 1 runs with ntrig = 5
[21:35:47.957] INFO: run 1 of 1
[21:36:02.197] INFO: Test took 14239ms.
[21:36:02.236] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:36:02.236] INFO: dacScan step from 80 .. 99
[21:36:02.236] INFO: dacScan split into 1 runs with ntrig = 5
[21:36:02.236] INFO: run 1 of 1
[21:36:16.639] INFO: Test took 14403ms.
[21:36:16.699] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:36:16.707] INFO: dacScan step from 100 .. 119
[21:36:16.707] INFO: dacScan split into 1 runs with ntrig = 5
[21:36:16.707] INFO: run 1 of 1
[21:36:33.383] INFO: Test took 16676ms.
[21:36:33.573] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:36:33.615] INFO: dacScan step from 120 .. 139
[21:36:33.615] INFO: dacScan split into 1 runs with ntrig = 5
[21:36:33.615] INFO: run 1 of 1
[21:36:47.557] ERROR: <datapipe.cc/CheckEventValidity:L463> Channel 1 Number of ROCs (7) != Token Chain Length (8)
[21:36:48.118] ERROR: <datapipe.cc/CheckEventValidity:L463> Channel 0 Number of ROCs (6) != Token Chain Length (8)
[21:36:48.118] WARNING: Channel 0 ROC 7: Readback start marker after 15 readouts!
[21:36:48.934] ERROR: <datapipe.cc/CheckEventValidity:L463> Channel 0 Number of ROCs (6) != Token Chain Length (8)
[21:36:48.934] WARNING: Channel 1 ROC 6: Readback start marker after 9 readouts!
[21:36:48.934] ERROR: <datapipe.cc/CheckEventValidity:L463> Channel 1 Number of ROCs (7) != Token Chain Length (8)
[21:36:48.934] WARNING: Channel 0 ROC 7: Readback start marker after 15 readouts!
[21:36:48.934] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!
[21:36:50.006] ERROR: <datapipe.cc/CheckEventValidity:L463> Channel 0 Number of ROCs (7) != Token Chain Length (8)
[21:36:50.814] ERROR: <datapipe.cc/CheckEventID:L446> Channel 0 Event ID mismatch: local ID (33) != TBM ID (34)
[21:36:50.814] ERROR: <datapipe.cc/CheckEventID:L446> Channel 1 Event ID mismatch: local ID (33) != TBM ID (34)
[21:36:50.815] WARNING: Channel 0 ROC 0: Readback start marker after 15 readouts!
[21:36:50.815] WARNING: Channel 0 ROC 1: Readback start marker after 15 readouts!
[21:36:50.815] WARNING: Channel 0 ROC 2: Readback start marker after 15 readouts!
[21:36:50.815] WARNING: Channel 0 ROC 3: Readback start marker after 15 readouts!
[21:36:50.815] WARNING: Channel 0 ROC 4: Readback start marker after 15 readouts!
[21:36:50.815] WARNING: Channel 0 ROC 5: Readback start marker after 15 readouts!
[21:36:50.815] WARNING: Channel 0 ROC 6: Readback start marker after 15 readouts!
[21:36:50.815] WARNING: Channel 0 ROC 7: Readback start marker after 15 readouts!
[21:36:50.815] WARNING: Channel 1 ROC 0: Readback start marker after 15 readouts!
[21:36:50.815] WARNING: Channel 1 ROC 1: Readback start marker after 15 readouts!
[21:36:50.815] WARNING: Channel 1 ROC 2: Readback start marker after 15 readouts!
[21:36:50.815] WARNING: Channel 1 ROC 3: Readback start marker after 15 readouts!
[21:36:50.815] WARNING: Channel 1 ROC 4: Readback start marker after 15 readouts!
[21:36:50.815] WARNING: Channel 1 ROC 5: Readback start marker after 15 readouts!
[21:36:50.815] WARNING: Channel 1 ROC 6: Readback start marker after 15 readouts!
[21:36:50.815] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!
[21:36:51.606] CRITICAL: <hal.cc/MultiRocAllPixelsDacScan:L1040> Incomplete DAQ data readout! Missing 1 Events.
[21:37:04.611] ERROR: <datapipe.cc/CheckEventValidity:L463> Channel 0 Number of ROCs (2) != Token Chain Length (8)
[21:37:04.611] ERROR: <datapipe.cc/CheckEventValidity:L463> Channel 1 Number of ROCs (6) != Token Chain Length (8)
[21:37:04.611] WARNING: Channel 0 ROC 3: Readback start marker after 15 readouts!
[21:37:04.611] WARNING: Channel 0 ROC 4: Readback start marker after 15 readouts!
[21:37:04.611] WARNING: Channel 0 ROC 5: Readback start marker after 15 readouts!
[21:37:04.611] WARNING: Channel 0 ROC 6: Readback start marker after 15 readouts!
[21:37:04.611] WARNING: Channel 0 ROC 7: Readback start marker after 15 readouts!
[21:37:04.611] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!
[21:37:05.085] ERROR: <datapipe.cc/CheckEventValidity:L463> Channel 0 Number of ROCs (6) != Token Chain Length (8)
[21:37:05.085] ERROR: <datapipe.cc/CheckEventValidity:L463> Channel 1 Number of ROCs (6) != Token Chain Length (8)
[21:37:05.088] WARNING: Channel 0 ROC 7: Readback start marker after 31 readouts!
[21:37:05.088] WARNING: Channel 1 ROC 7: Readback start marker after 31 readouts!
[21:37:06.096] ERROR: <datapipe.cc/CheckEventValidity:L463> Channel 0 Number of ROCs (6) != Token Chain Length (8)
[21:37:06.096] ERROR: <datapipe.cc/CheckEventValidity:L463> Channel 1 Number of ROCs (6) != Token Chain Length (8)
[21:37:06.096] WARNING: Channel 0 ROC 7: Readback start marker after 15 readouts!
[21:37:06.096] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!
[21:37:06.452] ERROR: <datapipe.cc/CheckEventValidity:L463> Channel 0 Number of ROCs (6) != Token Chain Length (8)
[21:37:06.452] ERROR: <datapipe.cc/CheckEventValidity:L463> Channel 1 Number of ROCs (6) != Token Chain Length (8)
[21:37:06.452] WARNING: Channel 0 ROC 7: Readback start marker after 15 readouts!
[21:37:06.452] WARNING: Channel 1 ROC 7: Readback start marker after 15 readouts!
[21:37:09.518] INFO: Test took 17831ms.
[21:37:09.781] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:37:09.845] INFO: dacScan step from 140 .. 159
[21:37:09.845] INFO: dacScan split into 1 runs with ntrig = 5
[21:37:09.845] INFO: run 1 of 1
[21:37:25.128] INFO: Test took 15283ms.
[21:37:25.264] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:37:59.420] INFO: ROC 0 VthrComp = 107
[21:37:59.420] INFO: ROC 1 VthrComp = 107
[21:37:59.420] INFO: ROC 2 VthrComp = 98
[21:37:59.420] INFO: ROC 3 VthrComp = 108
[21:37:59.420] INFO: ROC 4 VthrComp = 98
[21:37:59.421] INFO: ROC 5 VthrComp = 105
[21:37:59.421] INFO: ROC 6 VthrComp = 97
[21:37:59.421] INFO: ROC 7 VthrComp = 99
[21:37:59.421] INFO: ROC 8 VthrComp = 101
[21:37:59.421] INFO: ROC 9 VthrComp = 95
[21:37:59.421] INFO: ROC 10 VthrComp = 94
[21:37:59.421] INFO: ROC 11 VthrComp = 96
[21:37:59.421] INFO: ROC 12 VthrComp = 97
[21:37:59.422] INFO: ROC 13 VthrComp = 103
[21:37:59.422] INFO: ROC 14 VthrComp = 102
[21:37:59.422] INFO: ROC 15 VthrComp = 82
[21:37:59.422] INFO: ---> Vcal thr map (pixel with maximum Vcal thr)
[21:37:59.422] INFO: ---> dac: vcal name: TrimThr1 ntrig: 5 dacrange: 0 .. 159 (20/-1) hits flags = 16 (plus default)
[21:37:59.438] INFO: dacScan step from 0 .. 19
[21:37:59.438] INFO: dacScan split into 1 runs with ntrig = 5
[21:37:59.438] INFO: run 1 of 1
[21:38:13.581] INFO: Test took 14143ms.
[21:38:13.623] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:38:13.623] INFO: dacScan step from 20 .. 39
[21:38:13.623] INFO: dacScan split into 1 runs with ntrig = 5
[21:38:13.623] INFO: run 1 of 1
[21:38:28.065] INFO: Test took 14442ms.
[21:38:28.122] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:38:28.128] INFO: dacScan step from 40 .. 59
[21:38:28.128] INFO: dacScan split into 1 runs with ntrig = 5
[21:38:28.128] INFO: run 1 of 1
[21:38:45.617] INFO: Test took 17489ms.
[21:38:45.857] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:38:45.914] INFO: dacScan step from 60 .. 79
[21:38:45.914] INFO: dacScan split into 1 runs with ntrig = 5
[21:38:45.914] INFO: run 1 of 1
[21:39:05.283] INFO: Test took 19369ms.
[21:39:05.590] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:39:05.661] INFO: dacScan step from 80 .. 99
[21:39:05.661] INFO: dacScan split into 1 runs with ntrig = 5
[21:39:05.661] INFO: run 1 of 1
[21:39:25.039] INFO: Test took 19378ms.
[21:39:25.298] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:39:25.368] INFO: dacScan step from 100 .. 119
[21:39:25.368] INFO: dacScan split into 1 runs with ntrig = 5
[21:39:25.368] INFO: run 1 of 1
[21:39:44.681] INFO: Test took 19313ms.
[21:39:44.965] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:39:45.033] INFO: dacScan step from 120 .. 139
[21:39:45.033] INFO: dacScan split into 1 runs with ntrig = 5
[21:39:45.033] INFO: run 1 of 1
[21:40:04.300] INFO: Test took 19267ms.
[21:40:04.597] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:40:04.671] INFO: dacScan step from 140 .. 159
[21:40:04.671] INFO: dacScan split into 1 runs with ntrig = 5
[21:40:04.671] INFO: run 1 of 1
[21:40:24.168] INFO: Test took 19496ms.
[21:40:24.495] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:41:08.164] INFO: roc 0 with ID = 0 has maximal Vcal 60.9337 for pixel 20/4 mean/min/max = 48.012/35.0538/60.9701
[21:41:08.165] INFO: roc 1 with ID = 1 has maximal Vcal 61.1989 for pixel 23/72 mean/min/max = 47.5856/33.9661/61.205
[21:41:08.165] INFO: roc 2 with ID = 2 has maximal Vcal 58.3894 for pixel 8/11 mean/min/max = 45.4618/32.4244/58.4993
[21:41:08.165] INFO: roc 3 with ID = 3 has maximal Vcal 62.3587 for pixel 7/4 mean/min/max = 48.7115/34.8566/62.5664
[21:41:08.166] INFO: roc 4 with ID = 4 has maximal Vcal 59.3957 for pixel 3/45 mean/min/max = 45.4448/31.3326/59.557
[21:41:08.166] INFO: roc 5 with ID = 5 has maximal Vcal 64.7222 for pixel 0/11 mean/min/max = 49.2412/33.7519/64.7305
[21:41:08.166] INFO: roc 6 with ID = 6 has maximal Vcal 57.0952 for pixel 24/0 mean/min/max = 44.5082/31.847/57.1694
[21:41:08.167] INFO: roc 7 with ID = 7 has maximal Vcal 58.6301 for pixel 0/17 mean/min/max = 45.4906/32.3345/58.6467
[21:41:08.167] INFO: roc 8 with ID = 8 has maximal Vcal 59.0714 for pixel 22/15 mean/min/max = 46.0677/32.9971/59.1382
[21:41:08.168] INFO: roc 9 with ID = 9 has maximal Vcal 57.6842 for pixel 20/0 mean/min/max = 45.055/32.2756/57.8343
[21:41:08.168] INFO: roc 10 with ID = 10 has maximal Vcal 58.1845 for pixel 3/67 mean/min/max = 45.4659/32.7332/58.1987
[21:41:08.169] INFO: roc 11 with ID = 11 has maximal Vcal 60.8646 for pixel 0/21 mean/min/max = 46.775/32.5722/60.9778
[21:41:08.169] INFO: roc 12 with ID = 12 has maximal Vcal 62.5488 for pixel 41/8 mean/min/max = 47.0429/31.5081/62.5777
[21:41:08.170] INFO: roc 13 with ID = 13 has maximal Vcal 59.1269 for pixel 13/78 mean/min/max = 46.0077/32.8622/59.1532
[21:41:08.170] INFO: roc 14 with ID = 14 has maximal Vcal 57.69 for pixel 23/13 mean/min/max = 45.0839/32.2421/57.9258
[21:41:08.171] INFO: roc 15 with ID = 15 has maximal Vcal 57.3456 for pixel 20/6 mean/min/max = 45.2946/33.2217/57.3675
[21:41:08.171] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[21:42:27.791] INFO: Test took 79620ms.
[21:42:29.848] INFO: ---> dac: vcal name: TrimThr2 ntrig: 10 dacrange: 0 .. 199 (20/5) hits flags = 16 (plus default)
[21:42:29.867] INFO: dacScan step from 0 .. 19
[21:42:29.867] INFO: dacScan split into 2 runs with ntrig = 5
[21:42:29.867] INFO: run 1 of 2
[21:42:44.179] INFO: Test took 14312ms.
[21:42:44.228] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:42:44.233] INFO: run 2 of 2
[21:42:58.421] INFO: Test took 14188ms.
[21:42:58.469] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:42:58.471] INFO: dacScan step from 20 .. 39
[21:42:58.471] INFO: dacScan split into 2 runs with ntrig = 5
[21:42:58.472] INFO: run 1 of 2
[21:43:15.145] INFO: Test took 16673ms.
[21:43:15.362] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:43:15.411] INFO: run 2 of 2
[21:43:31.972] INFO: Test took 16561ms.
[21:43:32.192] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:43:32.247] INFO: dacScan step from 40 .. 59
[21:43:32.247] INFO: dacScan split into 2 runs with ntrig = 5
[21:43:32.247] INFO: run 1 of 2
[21:43:51.397] INFO: Test took 19150ms.
[21:43:51.701] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:43:51.777] INFO: run 2 of 2
[21:44:10.954] INFO: Test took 19177ms.
[21:44:11.278] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:44:11.362] INFO: dacScan step from 60 .. 79
[21:44:11.362] INFO: dacScan split into 2 runs with ntrig = 5
[21:44:11.362] INFO: run 1 of 2
[21:44:30.770] INFO: Test took 19408ms.
[21:44:31.061] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:44:31.135] INFO: run 2 of 2
[21:44:50.556] INFO: Test took 19420ms.
[21:44:50.853] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:44:50.927] INFO: dacScan step from 80 .. 99
[21:44:50.927] INFO: dacScan split into 2 runs with ntrig = 5
[21:44:50.927] INFO: run 1 of 2
[21:45:10.233] INFO: Test took 19306ms.
[21:45:10.523] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:45:10.598] INFO: run 2 of 2
[21:45:30.029] INFO: Test took 19431ms.
[21:45:30.312] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:45:30.387] INFO: dacScan step from 100 .. 119
[21:45:30.387] INFO: dacScan split into 2 runs with ntrig = 5
[21:45:30.387] INFO: run 1 of 2
[21:45:49.917] INFO: Test took 19529ms.
[21:45:50.208] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:45:50.275] INFO: run 2 of 2
[21:46:09.547] INFO: Test took 19272ms.
[21:46:09.828] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:46:09.899] INFO: dacScan step from 120 .. 139
[21:46:09.899] INFO: dacScan split into 2 runs with ntrig = 5
[21:46:09.899] INFO: run 1 of 2
[21:46:29.359] INFO: Test took 19460ms.
[21:46:29.649] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:46:29.719] INFO: run 2 of 2
[21:46:49.152] INFO: Test took 19432ms.
[21:46:49.417] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:46:49.486] INFO: dacScan step from 140 .. 159
[21:46:49.486] INFO: dacScan split into 2 runs with ntrig = 5
[21:46:49.486] INFO: run 1 of 2
[21:47:08.918] INFO: Test took 19432ms.
[21:47:09.205] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:47:09.278] INFO: run 2 of 2
[21:47:28.633] INFO: Test took 19355ms.
[21:47:28.904] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:47:28.976] INFO: dacScan step from 160 .. 179
[21:47:28.976] INFO: dacScan split into 2 runs with ntrig = 5
[21:47:28.976] INFO: run 1 of 2
[21:47:48.482] INFO: Test took 19506ms.
[21:47:48.789] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:47:48.857] INFO: run 2 of 2
[21:48:08.410] INFO: Test took 19552ms.
[21:48:08.676] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:48:08.748] INFO: dacScan step from 180 .. 199
[21:48:08.748] INFO: dacScan split into 2 runs with ntrig = 5
[21:48:08.748] INFO: run 1 of 2
[21:48:29.138] INFO: Test took 20390ms.
[21:48:29.442] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:48:29.517] INFO: run 2 of 2
[21:48:49.644] INFO: Test took 20127ms.
[21:48:49.983] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:49:34.631] INFO: ---> TrimStepCorr4 extremal thresholds: 0.020533 .. 255.000000
[21:49:34.766] INFO: ---> dac: vcal name: trimStepCorr4 ntrig: 4 dacrange: 0 .. 255 (20/-1) hits flags = 16 (plus default)
[21:49:34.781] INFO: dacScan step from 0 .. 19
[21:49:34.781] INFO: dacScan split into 1 runs with ntrig = 4
[21:49:34.781] INFO: run 1 of 1
[21:49:47.667] INFO: Test took 12885ms.
[21:49:47.703] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:49:47.703] INFO: dacScan step from 20 .. 39
[21:49:47.703] INFO: dacScan split into 1 runs with ntrig = 4
[21:49:47.703] INFO: run 1 of 1
[21:50:01.720] INFO: Test took 14016ms.
[21:50:01.839] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:50:01.869] INFO: dacScan step from 40 .. 59
[21:50:01.869] INFO: dacScan split into 1 runs with ntrig = 4
[21:50:01.869] INFO: run 1 of 1
[21:50:18.919] INFO: Test took 17050ms.
[21:50:19.173] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:50:19.250] INFO: dacScan step from 60 .. 79
[21:50:19.250] INFO: dacScan split into 1 runs with ntrig = 4
[21:50:19.250] INFO: run 1 of 1
[21:50:36.423] INFO: Test took 17172ms.
[21:50:36.652] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:50:36.719] INFO: dacScan step from 80 .. 99
[21:50:36.719] INFO: dacScan split into 1 runs with ntrig = 4
[21:50:36.719] INFO: run 1 of 1
[21:50:54.015] INFO: Test took 17295ms.
[21:50:54.258] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:50:54.336] INFO: dacScan step from 100 .. 119
[21:50:54.336] INFO: dacScan split into 1 runs with ntrig = 4
[21:50:54.336] INFO: run 1 of 1
[21:51:11.755] INFO: Test took 17419ms.
[21:51:11.985] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:51:12.053] INFO: dacScan step from 120 .. 139
[21:51:12.053] INFO: dacScan split into 1 runs with ntrig = 4
[21:51:12.053] INFO: run 1 of 1
[21:51:29.162] INFO: Test took 17109ms.
[21:51:29.425] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:51:29.509] INFO: dacScan step from 140 .. 159
[21:51:29.509] INFO: dacScan split into 1 runs with ntrig = 4
[21:51:29.510] INFO: run 1 of 1
[21:51:46.888] INFO: Test took 17378ms.
[21:51:47.114] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:51:47.182] INFO: dacScan step from 160 .. 179
[21:51:47.182] INFO: dacScan split into 1 runs with ntrig = 4
[21:51:47.182] INFO: run 1 of 1
[21:52:04.576] INFO: Test took 17394ms.
[21:52:04.804] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:52:04.873] INFO: dacScan step from 180 .. 199
[21:52:04.873] INFO: dacScan split into 1 runs with ntrig = 4
[21:52:04.873] INFO: run 1 of 1
[21:52:22.814] INFO: Test took 17941ms.
[21:52:23.061] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:52:23.176] INFO: dacScan step from 200 .. 219
[21:52:23.176] INFO: dacScan split into 1 runs with ntrig = 4
[21:52:23.176] INFO: run 1 of 1
[21:52:40.440] INFO: Test took 17264ms.
[21:52:40.685] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:52:40.759] INFO: dacScan step from 220 .. 239
[21:52:40.759] INFO: dacScan split into 1 runs with ntrig = 4
[21:52:40.759] INFO: run 1 of 1
[21:52:57.965] INFO: Test took 17206ms.
[21:52:58.237] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:52:58.316] INFO: dacScan step from 240 .. 255
[21:52:58.316] INFO: dacScan split into 1 runs with ntrig = 4
[21:52:58.316] INFO: run 1 of 1
[21:53:12.567] INFO: Test took 14251ms.
[21:53:12.839] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:54:06.699] INFO: ---> TrimStepCorr2 extremal thresholds: 14.600828 .. 57.305640
[21:54:06.836] INFO: ---> dac: vcal name: trimStepCorr2 ntrig: 4 dacrange: 4 .. 67 (20/-1) hits flags = 16 (plus default)
[21:54:06.851] INFO: dacScan step from 4 .. 23
[21:54:06.851] INFO: dacScan split into 1 runs with ntrig = 4
[21:54:06.851] INFO: run 1 of 1
[21:54:19.819] INFO: Test took 12968ms.
[21:54:19.850] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:54:19.850] INFO: dacScan step from 24 .. 43
[21:54:19.850] INFO: dacScan split into 1 runs with ntrig = 4
[21:54:19.850] INFO: run 1 of 1
[21:54:34.437] INFO: Test took 14586ms.
[21:54:34.610] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:54:34.664] INFO: dacScan step from 44 .. 63
[21:54:34.664] INFO: dacScan split into 1 runs with ntrig = 4
[21:54:34.664] INFO: run 1 of 1
[21:54:51.754] INFO: Test took 17090ms.
[21:54:52.044] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:54:52.123] INFO: dacScan step from 64 .. 67
[21:54:52.123] INFO: dacScan split into 1 runs with ntrig = 4
[21:54:52.123] INFO: run 1 of 1
[21:54:58.130] INFO: Test took 6007ms.
[21:54:58.180] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:55:24.601] INFO: ---> TrimStepCorr1a extremal thresholds: 0.338878 .. 57.305640
[21:55:24.738] INFO: ---> dac: vcal name: trimStepCorr1a ntrig: 4 dacrange: 0 .. 67 (20/-1) hits flags = 16 (plus default)
[21:55:24.753] INFO: dacScan step from 0 .. 19
[21:55:24.753] INFO: dacScan split into 1 runs with ntrig = 4
[21:55:24.753] INFO: run 1 of 1
[21:55:37.790] INFO: Test took 13037ms.
[21:55:37.833] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:55:37.833] INFO: dacScan step from 20 .. 39
[21:55:37.833] INFO: dacScan split into 1 runs with ntrig = 4
[21:55:37.833] INFO: run 1 of 1
[21:55:51.694] INFO: Test took 13861ms.
[21:55:51.822] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:55:51.866] INFO: dacScan step from 40 .. 59
[21:55:51.866] INFO: dacScan split into 1 runs with ntrig = 4
[21:55:51.866] INFO: run 1 of 1
[21:56:09.329] INFO: Test took 17463ms.
[21:56:09.619] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:56:09.698] INFO: dacScan step from 60 .. 67
[21:56:09.698] INFO: dacScan split into 1 runs with ntrig = 4
[21:56:09.699] INFO: run 1 of 1
[21:56:18.554] INFO: Test took 8855ms.
[21:56:18.656] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:56:45.567] INFO: ---> TrimStepCorr1b extremal thresholds: 1.074114 .. 48.071942
[21:56:45.722] INFO: ---> dac: vcal name: trimStepCorr1b ntrig: 4 dacrange: 1 .. 58 (20/-1) hits flags = 16 (plus default)
[21:56:45.737] INFO: dacScan step from 1 .. 20
[21:56:45.737] INFO: dacScan split into 1 runs with ntrig = 4
[21:56:45.737] INFO: run 1 of 1
[21:56:58.658] INFO: Test took 12921ms.
[21:56:58.699] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:56:58.699] INFO: dacScan step from 21 .. 40
[21:56:58.699] INFO: dacScan split into 1 runs with ntrig = 4
[21:56:58.699] INFO: run 1 of 1
[21:57:12.720] INFO: Test took 14021ms.
[21:57:12.865] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:57:12.903] INFO: dacScan step from 41 .. 58
[21:57:12.903] INFO: dacScan split into 1 runs with ntrig = 4
[21:57:12.903] INFO: run 1 of 1
[21:57:28.841] INFO: Test took 15938ms.
[21:57:29.106] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:57:54.508] INFO: ---> TrimThrFinal extremal thresholds: 15 .. 55
[21:57:54.508] INFO: ---> dac: vcal name: TrimThrFinal ntrig: 10 dacrange: 15 .. 55 (20/5) hits flags = 16 (plus default)
[21:57:54.523] INFO: dacScan step from 15 .. 34
[21:57:54.523] INFO: dacScan split into 2 runs with ntrig = 5
[21:57:54.523] INFO: run 1 of 2
[21:58:09.009] INFO: Test took 14486ms.
[21:58:09.084] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:58:09.098] INFO: run 2 of 2
[21:58:23.449] INFO: Test took 14351ms.
[21:58:23.530] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:58:23.545] INFO: dacScan step from 35 .. 54
[21:58:23.545] INFO: dacScan split into 2 runs with ntrig = 5
[21:58:23.545] INFO: run 1 of 2
[21:58:42.412] INFO: Test took 18867ms.
[21:58:42.743] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:58:42.823] INFO: run 2 of 2
[21:59:02.022] INFO: Test took 19199ms.
[21:59:02.305] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:59:02.379] INFO: dacScan step from 55 .. 55
[21:59:02.379] INFO: dacScan split into 2 runs with ntrig = 5
[21:59:02.379] INFO: run 1 of 2
[21:59:06.393] INFO: Test took 4014ms.
[21:59:06.412] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:59:06.421] INFO: run 2 of 2
[21:59:10.406] INFO: Test took 3985ms.
[21:59:10.425] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:59:29.787] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C0.dat
[21:59:29.788] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C1.dat
[21:59:29.788] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C2.dat
[21:59:29.788] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C3.dat
[21:59:29.789] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C4.dat
[21:59:29.789] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C5.dat
[21:59:29.789] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C6.dat
[21:59:29.789] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C7.dat
[21:59:29.790] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C8.dat
[21:59:29.790] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C9.dat
[21:59:29.790] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C10.dat
[21:59:29.791] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C11.dat
[21:59:29.791] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C12.dat
[21:59:29.791] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C13.dat
[21:59:29.791] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C14.dat
[21:59:29.792] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C15.dat
[21:59:29.792] INFO: write trim parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/trimParameters35_C0.dat
[21:59:29.805] INFO: write trim parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/trimParameters35_C1.dat
[21:59:29.815] INFO: write trim parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/trimParameters35_C2.dat
[21:59:29.826] INFO: write trim parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/trimParameters35_C3.dat
[21:59:29.838] INFO: write trim parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/trimParameters35_C4.dat
[21:59:29.848] INFO: write trim parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/trimParameters35_C5.dat
[21:59:29.860] INFO: write trim parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/trimParameters35_C6.dat
[21:59:29.872] INFO: write trim parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/trimParameters35_C7.dat
[21:59:29.884] INFO: write trim parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/trimParameters35_C8.dat
[21:59:29.895] INFO: write trim parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/trimParameters35_C9.dat
[21:59:29.907] INFO: write trim parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/trimParameters35_C10.dat
[21:59:29.920] INFO: write trim parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/trimParameters35_C11.dat
[21:59:29.931] INFO: write trim parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/trimParameters35_C12.dat
[21:59:29.943] INFO: write trim parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/trimParameters35_C13.dat
[21:59:29.955] INFO: write trim parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/trimParameters35_C14.dat
[21:59:29.965] INFO: write trim parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/trimParameters35_C15.dat
[21:59:29.978] INFO: PixTestTrim::trimTest() done
[21:59:29.978] INFO: vtrim: 117 119 98 129 108 125 95 102 119 96 100 107 121 105 109 101
[21:59:29.978] INFO: vthrcomp: 107 107 98 108 98 105 97 99 101 95 94 96 97 103 102 82
[21:59:29.978] INFO: vcal mean: 35.09 35.12 35.12 35.15 35.07 35.14 35.11 35.12 35.03 35.10 35.10 35.10 35.12 35.13 35.11 35.01
[21:59:29.978] INFO: vcal RMS: 1.37 1.12 1.17 1.32 1.48 1.27 1.16 1.14 1.34 1.19 1.09 1.23 1.37 1.24 1.15 1.07
[21:59:29.978] INFO: bits mean: 9.10 9.38 9.92 9.19 10.21 8.91 10.46 9.90 9.82 9.76 9.60 9.31 10.16 9.95 10.20 9.91
[21:59:29.978] INFO: bits RMS: 2.31 2.37 2.47 2.29 2.55 2.46 2.37 2.52 2.44 2.57 2.61 2.61 2.37 2.39 2.41 2.37
[21:59:29.987] INFO: ----------------------------------------------------------------------
[21:59:29.987] INFO: PixTestTrim::trimBitTest() ntrig = 10, vtrims = 254 126 63 32
[21:59:29.987] INFO: ----------------------------------------------------------------------
[21:59:29.991] INFO: ---> dac: Vcal name: TrimBitsThr0 ntrig: 10 dacrange: 0 .. 199 (20/5) hits flags = 16 (plus default)
[21:59:30.008] INFO: dacScan step from 0 .. 19
[21:59:30.008] INFO: dacScan split into 2 runs with ntrig = 5
[21:59:30.008] INFO: run 1 of 2
[21:59:43.002] INFO: Test took 13994ms.
[21:59:44.042] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:59:44.042] INFO: run 2 of 2
[21:59:58.081] INFO: Test took 14039ms.
[21:59:58.121] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:59:58.121] INFO: dacScan step from 20 .. 39
[21:59:58.121] INFO: dacScan split into 2 runs with ntrig = 5
[21:59:58.121] INFO: run 1 of 2
[22:00:12.215] INFO: Test took 14093ms.
[22:00:12.258] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:00:12.258] INFO: run 2 of 2
[22:00:26.327] INFO: Test took 14069ms.
[22:00:26.371] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:00:26.371] INFO: dacScan step from 40 .. 59
[22:00:26.371] INFO: dacScan split into 2 runs with ntrig = 5
[22:00:26.371] INFO: run 1 of 2
[22:00:40.518] INFO: Test took 14147ms.
[22:00:40.559] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:00:40.559] INFO: run 2 of 2
[22:00:54.739] INFO: Test took 14179ms.
[22:00:54.780] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:00:54.780] INFO: dacScan step from 60 .. 79
[22:00:54.780] INFO: dacScan split into 2 runs with ntrig = 5
[22:00:54.780] INFO: run 1 of 2
[22:01:08.910] INFO: Test took 14129ms.
[22:01:08.948] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:01:08.948] INFO: run 2 of 2
[22:01:23.021] INFO: Test took 14073ms.
[22:01:23.058] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:01:23.058] INFO: dacScan step from 80 .. 99
[22:01:23.058] INFO: dacScan split into 2 runs with ntrig = 5
[22:01:23.058] INFO: run 1 of 2
[22:01:37.210] INFO: Test took 14152ms.
[22:01:37.266] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:01:37.266] INFO: run 2 of 2
[22:01:51.423] INFO: Test took 14156ms.
[22:01:51.463] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:01:51.463] INFO: dacScan step from 100 .. 119
[22:01:51.463] INFO: dacScan split into 2 runs with ntrig = 5
[22:01:51.463] INFO: run 1 of 2
[22:02:05.887] INFO: Test took 14424ms.
[22:02:05.958] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:02:05.963] INFO: run 2 of 2
[22:02:20.306] INFO: Test took 14343ms.
[22:02:20.378] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:02:20.382] INFO: dacScan step from 120 .. 139
[22:02:20.382] INFO: dacScan split into 2 runs with ntrig = 5
[22:02:20.382] INFO: run 1 of 2
[22:02:36.585] INFO: Test took 16202ms.
[22:02:36.768] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:02:36.809] INFO: run 2 of 2
[22:02:53.213] INFO: Test took 16404ms.
[22:02:53.408] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:02:53.447] INFO: dacScan step from 140 .. 159
[22:02:53.447] INFO: dacScan split into 2 runs with ntrig = 5
[22:02:53.447] INFO: run 1 of 2
[22:03:12.632] INFO: Test took 19185ms.
[22:03:12.915] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:03:12.983] INFO: run 2 of 2
[22:03:32.043] INFO: Test took 19060ms.
[22:03:32.355] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:03:32.427] INFO: dacScan step from 160 .. 179
[22:03:32.427] INFO: dacScan split into 2 runs with ntrig = 5
[22:03:32.427] INFO: run 1 of 2
[22:03:52.082] INFO: Test took 19654ms.
[22:03:52.398] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:03:52.476] INFO: run 2 of 2
[22:04:12.064] INFO: Test took 19588ms.
[22:04:12.391] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:04:12.471] INFO: dacScan step from 180 .. 199
[22:04:12.471] INFO: dacScan split into 2 runs with ntrig = 5
[22:04:12.471] INFO: run 1 of 2
[22:04:32.584] INFO: Test took 20113ms.
[22:04:32.927] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:04:33.022] INFO: run 2 of 2
[22:04:53.133] INFO: Test took 20110ms.
[22:04:53.547] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:05:37.307] INFO: ---> dac: Vcal name: TrimThr_trim14 ntrig: 10 dacrange: 0 .. 185 (20/5) hits flags = 16 (plus default)
[22:05:37.324] INFO: dacScan step from 0 .. 19
[22:05:37.325] INFO: dacScan split into 2 runs with ntrig = 5
[22:05:37.325] INFO: run 1 of 2
[22:05:51.302] INFO: Test took 13977ms.
[22:05:51.347] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:05:51.347] INFO: run 2 of 2
[22:06:05.314] INFO: Test took 13967ms.
[22:06:05.359] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:06:05.359] INFO: dacScan step from 20 .. 39
[22:06:05.359] INFO: dacScan split into 2 runs with ntrig = 5
[22:06:05.359] INFO: run 1 of 2
[22:06:19.380] INFO: Test took 14021ms.
[22:06:19.427] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:06:19.427] INFO: run 2 of 2
[22:06:33.466] INFO: Test took 14039ms.
[22:06:33.513] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:06:33.513] INFO: dacScan step from 40 .. 59
[22:06:33.513] INFO: dacScan split into 2 runs with ntrig = 5
[22:06:33.513] INFO: run 1 of 2
[22:06:47.638] INFO: Test took 14125ms.
[22:06:47.684] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:06:47.685] INFO: run 2 of 2
[22:07:01.588] INFO: Test took 13903ms.
[22:07:01.633] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:07:01.633] INFO: dacScan step from 60 .. 79
[22:07:01.633] INFO: dacScan split into 2 runs with ntrig = 5
[22:07:01.633] INFO: run 1 of 2
[22:07:15.593] INFO: Test took 13960ms.
[22:07:15.633] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:07:15.633] INFO: run 2 of 2
[22:07:29.840] INFO: Test took 14207ms.
[22:07:29.883] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:07:29.883] INFO: dacScan step from 80 .. 99
[22:07:29.884] INFO: dacScan split into 2 runs with ntrig = 5
[22:07:29.884] INFO: run 1 of 2
[22:07:44.189] INFO: Test took 14305ms.
[22:07:44.234] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:07:44.235] INFO: run 2 of 2
[22:07:58.433] INFO: Test took 14198ms.
[22:07:58.479] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:07:58.481] INFO: dacScan step from 100 .. 119
[22:07:58.481] INFO: dacScan split into 2 runs with ntrig = 5
[22:07:58.481] INFO: run 1 of 2
[22:08:13.603] INFO: Test took 15122ms.
[22:08:13.722] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:08:13.745] INFO: run 2 of 2
[22:08:28.866] INFO: Test took 15121ms.
[22:08:28.991] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:08:29.013] INFO: dacScan step from 120 .. 139
[22:08:29.013] INFO: dacScan split into 2 runs with ntrig = 5
[22:08:29.013] INFO: run 1 of 2
[22:08:47.123] INFO: Test took 18110ms.
[22:08:47.397] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:08:47.464] INFO: run 2 of 2
[22:09:05.653] INFO: Test took 18189ms.
[22:09:05.902] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:09:05.971] INFO: dacScan step from 140 .. 159
[22:09:05.971] INFO: dacScan split into 2 runs with ntrig = 5
[22:09:05.971] INFO: run 1 of 2
[22:09:25.438] INFO: Test took 19467ms.
[22:09:25.732] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:09:25.808] INFO: run 2 of 2
[22:09:45.247] INFO: Test took 19439ms.
[22:09:45.579] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:09:45.659] INFO: dacScan step from 160 .. 179
[22:09:45.659] INFO: dacScan split into 2 runs with ntrig = 5
[22:09:45.659] INFO: run 1 of 2
[22:10:05.294] INFO: Test took 19634ms.
[22:10:05.639] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:10:05.717] INFO: run 2 of 2
[22:10:25.470] INFO: Test took 19753ms.
[22:10:25.759] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:10:25.830] INFO: dacScan step from 180 .. 185
[22:10:25.830] INFO: dacScan split into 2 runs with ntrig = 5
[22:10:25.830] INFO: run 1 of 2
[22:10:33.826] INFO: Test took 7996ms.
[22:10:33.923] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:10:33.951] INFO: run 2 of 2
[22:10:42.049] INFO: Test took 8098ms.
[22:10:42.142] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:11:21.686] INFO: ---> dac: Vcal name: TrimThr_trim13 ntrig: 10 dacrange: 0 .. 172 (20/5) hits flags = 16 (plus default)
[22:11:21.705] INFO: dacScan step from 0 .. 19
[22:11:21.705] INFO: dacScan split into 2 runs with ntrig = 5
[22:11:21.705] INFO: run 1 of 2
[22:11:35.795] INFO: Test took 14090ms.
[22:11:35.835] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:11:35.835] INFO: run 2 of 2
[22:11:49.978] INFO: Test took 14142ms.
[22:11:50.024] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:11:50.024] INFO: dacScan step from 20 .. 39
[22:11:50.024] INFO: dacScan split into 2 runs with ntrig = 5
[22:11:50.024] INFO: run 1 of 2
[22:12:04.139] INFO: Test took 14115ms.
[22:12:04.184] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:12:04.184] INFO: run 2 of 2
[22:12:18.211] INFO: Test took 14027ms.
[22:12:18.256] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:12:18.256] INFO: dacScan step from 40 .. 59
[22:12:18.256] INFO: dacScan split into 2 runs with ntrig = 5
[22:12:18.256] INFO: run 1 of 2
[22:12:32.314] INFO: Test took 14058ms.
[22:12:32.355] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:12:32.355] INFO: run 2 of 2
[22:12:46.408] INFO: Test took 14052ms.
[22:12:46.445] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:12:46.445] INFO: dacScan step from 60 .. 79
[22:12:46.445] INFO: dacScan split into 2 runs with ntrig = 5
[22:12:46.445] INFO: run 1 of 2
[22:13:00.396] INFO: Test took 13950ms.
[22:13:00.440] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:13:00.440] INFO: run 2 of 2
[22:13:14.382] INFO: Test took 13942ms.
[22:13:14.422] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:13:14.422] INFO: dacScan step from 80 .. 99
[22:13:14.422] INFO: dacScan split into 2 runs with ntrig = 5
[22:13:14.422] INFO: run 1 of 2
[22:13:28.579] INFO: Test took 14156ms.
[22:13:28.622] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:13:28.623] INFO: run 2 of 2
[22:13:42.720] INFO: Test took 14097ms.
[22:13:42.768] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:13:42.769] INFO: dacScan step from 100 .. 119
[22:13:42.769] INFO: dacScan split into 2 runs with ntrig = 5
[22:13:42.769] INFO: run 1 of 2
[22:13:57.910] INFO: Test took 15140ms.
[22:13:58.035] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:13:58.054] INFO: run 2 of 2
[22:14:13.216] INFO: Test took 15162ms.
[22:14:13.346] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:14:13.367] INFO: dacScan step from 120 .. 139
[22:14:13.367] INFO: dacScan split into 2 runs with ntrig = 5
[22:14:13.367] INFO: run 1 of 2
[22:14:31.584] INFO: Test took 18217ms.
[22:14:31.874] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:14:31.944] INFO: run 2 of 2
[22:14:49.923] INFO: Test took 17978ms.
[22:14:50.284] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:14:50.369] INFO: dacScan step from 140 .. 159
[22:14:50.369] INFO: dacScan split into 2 runs with ntrig = 5
[22:14:50.369] INFO: run 1 of 2
[22:15:09.756] INFO: Test took 19387ms.
[22:15:10.101] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:15:10.183] INFO: run 2 of 2
[22:15:29.664] INFO: Test took 19481ms.
[22:15:29.979] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:15:30.061] INFO: dacScan step from 160 .. 172
[22:15:30.061] INFO: dacScan split into 2 runs with ntrig = 5
[22:15:30.062] INFO: run 1 of 2
[22:15:44.012] INFO: Test took 13950ms.
[22:15:44.207] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:15:44.260] INFO: run 2 of 2
[22:15:58.255] INFO: Test took 13995ms.
[22:15:58.457] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:16:35.747] INFO: ---> dac: Vcal name: TrimThr_trim11 ntrig: 10 dacrange: 0 .. 172 (20/5) hits flags = 16 (plus default)
[22:16:35.764] INFO: dacScan step from 0 .. 19
[22:16:35.764] INFO: dacScan split into 2 runs with ntrig = 5
[22:16:35.764] INFO: run 1 of 2
[22:16:50.188] INFO: Test took 14424ms.
[22:16:50.228] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:16:50.228] INFO: run 2 of 2
[22:17:04.391] INFO: Test took 14163ms.
[22:17:04.432] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:17:04.432] INFO: dacScan step from 20 .. 39
[22:17:04.432] INFO: dacScan split into 2 runs with ntrig = 5
[22:17:04.432] INFO: run 1 of 2
[22:17:18.624] INFO: Test took 14191ms.
[22:17:18.667] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:17:18.667] INFO: run 2 of 2
[22:17:32.941] INFO: Test took 14274ms.
[22:17:32.987] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:17:32.987] INFO: dacScan step from 40 .. 59
[22:17:32.987] INFO: dacScan split into 2 runs with ntrig = 5
[22:17:32.988] INFO: run 1 of 2
[22:17:47.373] INFO: Test took 14385ms.
[22:17:47.422] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:17:47.422] INFO: run 2 of 2
[22:18:01.732] INFO: Test took 14309ms.
[22:18:01.775] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:18:01.775] INFO: dacScan step from 60 .. 79
[22:18:01.775] INFO: dacScan split into 2 runs with ntrig = 5
[22:18:01.775] INFO: run 1 of 2
[22:18:16.070] INFO: Test took 14295ms.
[22:18:16.111] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:18:16.111] INFO: run 2 of 2
[22:18:30.317] INFO: Test took 14206ms.
[22:18:30.362] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:18:30.362] INFO: dacScan step from 80 .. 99
[22:18:30.362] INFO: dacScan split into 2 runs with ntrig = 5
[22:18:30.362] INFO: run 1 of 2
[22:18:44.605] INFO: Test took 14243ms.
[22:18:44.649] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:18:44.650] INFO: run 2 of 2
[22:18:58.789] INFO: Test took 14139ms.
[22:18:58.835] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:18:58.836] INFO: dacScan step from 100 .. 119
[22:18:58.836] INFO: dacScan split into 2 runs with ntrig = 5
[22:18:58.836] INFO: run 1 of 2
[22:19:13.922] INFO: Test took 15085ms.
[22:19:14.046] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:19:14.066] INFO: run 2 of 2
[22:19:29.254] INFO: Test took 15188ms.
[22:19:29.377] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:19:29.395] INFO: dacScan step from 120 .. 139
[22:19:29.395] INFO: dacScan split into 2 runs with ntrig = 5
[22:19:29.395] INFO: run 1 of 2
[22:19:47.544] INFO: Test took 18149ms.
[22:19:47.786] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:19:47.850] INFO: run 2 of 2
[22:20:05.896] INFO: Test took 18046ms.
[22:20:06.193] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:20:06.264] INFO: dacScan step from 140 .. 159
[22:20:06.264] INFO: dacScan split into 2 runs with ntrig = 5
[22:20:06.264] INFO: run 1 of 2
[22:20:25.495] INFO: Test took 19231ms.
[22:20:25.837] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:20:25.923] INFO: run 2 of 2
[22:20:45.342] INFO: Test took 19419ms.
[22:20:45.669] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:20:45.747] INFO: dacScan step from 160 .. 172
[22:20:45.747] INFO: dacScan split into 2 runs with ntrig = 5
[22:20:45.747] INFO: run 1 of 2
[22:20:59.640] INFO: Test took 13893ms.
[22:20:59.837] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:20:59.888] INFO: run 2 of 2
[22:21:13.741] INFO: Test took 13853ms.
[22:21:13.925] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:21:51.601] INFO: ---> dac: Vcal name: TrimThr_trim7 ntrig: 10 dacrange: 0 .. 172 (20/5) hits flags = 16 (plus default)
[22:21:51.617] INFO: dacScan step from 0 .. 19
[22:21:51.617] INFO: dacScan split into 2 runs with ntrig = 5
[22:21:51.617] INFO: run 1 of 2
[22:22:05.561] INFO: Test took 13944ms.
[22:22:05.606] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:22:05.606] INFO: run 2 of 2
[22:22:19.626] INFO: Test took 14020ms.
[22:22:19.674] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:22:19.674] INFO: dacScan step from 20 .. 39
[22:22:19.674] INFO: dacScan split into 2 runs with ntrig = 5
[22:22:19.674] INFO: run 1 of 2
[22:22:33.630] INFO: Test took 13956ms.
[22:22:33.674] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:22:33.674] INFO: run 2 of 2
[22:22:47.644] INFO: Test took 13970ms.
[22:22:47.690] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:22:47.690] INFO: dacScan step from 40 .. 59
[22:22:47.690] INFO: dacScan split into 2 runs with ntrig = 5
[22:22:47.690] INFO: run 1 of 2
[22:23:01.802] INFO: Test took 14111ms.
[22:23:01.847] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:23:01.847] INFO: run 2 of 2
[22:23:15.847] INFO: Test took 14000ms.
[22:23:15.890] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:23:15.890] INFO: dacScan step from 60 .. 79
[22:23:15.890] INFO: dacScan split into 2 runs with ntrig = 5
[22:23:15.890] INFO: run 1 of 2
[22:23:29.901] INFO: Test took 14011ms.
[22:23:29.947] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:23:29.947] INFO: run 2 of 2
[22:23:44.035] INFO: Test took 14088ms.
[22:23:44.085] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:23:44.085] INFO: dacScan step from 80 .. 99
[22:23:44.085] INFO: dacScan split into 2 runs with ntrig = 5
[22:23:44.085] INFO: run 1 of 2
[22:23:58.339] INFO: Test took 14254ms.
[22:23:58.387] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:23:58.387] INFO: run 2 of 2
[22:24:12.531] INFO: Test took 14143ms.
[22:24:12.579] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:24:12.580] INFO: dacScan step from 100 .. 119
[22:24:12.580] INFO: dacScan split into 2 runs with ntrig = 5
[22:24:12.580] INFO: run 1 of 2
[22:24:27.887] INFO: Test took 15306ms.
[22:24:28.010] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:24:28.030] INFO: run 2 of 2
[22:24:43.303] INFO: Test took 15272ms.
[22:24:43.424] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:24:43.443] INFO: dacScan step from 120 .. 139
[22:24:43.443] INFO: dacScan split into 2 runs with ntrig = 5
[22:24:43.443] INFO: run 1 of 2
[22:25:01.726] INFO: Test took 18282ms.
[22:25:01.988] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:25:02.053] INFO: run 2 of 2
[22:25:19.975] INFO: Test took 17922ms.
[22:25:20.305] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:25:20.376] INFO: dacScan step from 140 .. 159
[22:25:20.376] INFO: dacScan split into 2 runs with ntrig = 5
[22:25:20.376] INFO: run 1 of 2
[22:25:39.786] INFO: Test took 19410ms.
[22:25:40.112] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:25:40.193] INFO: run 2 of 2
[22:25:59.749] INFO: Test took 19556ms.
[22:26:00.029] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:26:00.099] INFO: dacScan step from 160 .. 172
[22:26:00.099] INFO: dacScan split into 2 runs with ntrig = 5
[22:26:00.099] INFO: run 1 of 2
[22:26:14.020] INFO: Test took 13921ms.
[22:26:14.209] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:26:14.257] INFO: run 2 of 2
[22:26:27.002] INFO: Test took 13745ms.
[22:26:28.187] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:27:07.396] INFO: PixTestTrim::trimBitTest() done
[22:27:07.397] INFO: PixTestTrim::doTest() done, duration: 3121 seconds
[22:27:08.370] INFO: ######################################################################
[22:27:08.370] INFO: PixTestPhOptimization::doTest() Ntrig = 10
[22:27:08.370] INFO: ######################################################################
[22:27:12.060] INFO: Test took 3689ms.
[22:27:12.097] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:27:15.997] INFO: Test took 3699ms.
[22:27:16.137] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:27:19.842] INFO: Test took 3688ms.
[22:27:19.991] INFO: Fetched DAQ statistics. Counters are being reset now.
[22:27:19.002] INFO: The DUT currently contains the following objects:
[22:27:19.002] INFO: 2 TBM Cores tbm08c (2 ON)
[22:27:19.002] INFO: TBM Core alpha (0): 7 registers set
[22:27:19.002] INFO: TBM Core beta (1): 7 registers set
[22:27:19.002] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[22:27:19.002] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:19.002] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:19.002] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:19.002] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:19.002] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:19.002] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:19.002] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:19.002] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:19.002] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:19.002] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:19.002] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:19.002] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:19.002] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:19.002] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:19.002] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:19.002] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:21.102] INFO: Test took 1100ms.
[22:27:21.103] INFO: The DUT currently contains the following objects:
[22:27:21.103] INFO: 2 TBM Cores tbm08c (2 ON)
[22:27:21.103] INFO: TBM Core alpha (0): 7 registers set
[22:27:21.103] INFO: TBM Core beta (1): 7 registers set
[22:27:21.103] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[22:27:21.103] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:21.103] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:21.103] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:21.103] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:21.103] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:21.103] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:21.103] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:21.103] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:21.103] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:21.103] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:21.104] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:21.104] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:21.104] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:21.104] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:21.104] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:21.104] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:22.225] INFO: Test took 1121ms.
[22:27:22.227] INFO: The DUT currently contains the following objects:
[22:27:22.227] INFO: 2 TBM Cores tbm08c (2 ON)
[22:27:22.227] INFO: TBM Core alpha (0): 7 registers set
[22:27:22.227] INFO: TBM Core beta (1): 7 registers set
[22:27:22.227] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[22:27:22.227] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:22.227] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:22.227] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:22.227] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:22.227] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:22.227] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:22.227] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:22.227] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:22.227] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:22.227] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:22.227] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:22.227] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:22.227] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:22.227] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:22.227] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:22.227] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:23.347] INFO: Test took 1120ms.
[22:27:23.348] INFO: The DUT currently contains the following objects:
[22:27:23.348] INFO: 2 TBM Cores tbm08c (2 ON)
[22:27:23.348] INFO: TBM Core alpha (0): 7 registers set
[22:27:23.348] INFO: TBM Core beta (1): 7 registers set
[22:27:23.348] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[22:27:23.348] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:23.348] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:23.348] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:23.348] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:23.348] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:23.348] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:23.348] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:23.348] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:23.348] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:23.349] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:23.349] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:23.349] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:23.349] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:23.349] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:23.349] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:23.349] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:24.470] INFO: Test took 1121ms.
[22:27:24.472] INFO: The DUT currently contains the following objects:
[22:27:24.472] INFO: 2 TBM Cores tbm08c (2 ON)
[22:27:24.472] INFO: TBM Core alpha (0): 7 registers set
[22:27:24.472] INFO: TBM Core beta (1): 7 registers set
[22:27:24.472] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[22:27:24.472] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:24.472] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:24.472] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:24.472] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:24.472] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:24.472] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:24.472] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:24.472] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:24.472] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:24.472] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:24.472] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:24.472] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:24.472] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:24.472] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:24.472] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:24.472] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:25.593] INFO: Test took 1121ms.
[22:27:25.594] INFO: The DUT currently contains the following objects:
[22:27:25.594] INFO: 2 TBM Cores tbm08c (2 ON)
[22:27:25.594] INFO: TBM Core alpha (0): 7 registers set
[22:27:25.594] INFO: TBM Core beta (1): 7 registers set
[22:27:25.594] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[22:27:25.594] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:25.594] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:25.594] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:25.594] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:25.595] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:25.595] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:25.595] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:25.595] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:25.595] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:25.595] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:25.595] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:25.595] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:25.595] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:25.595] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:25.595] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:25.595] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:26.692] INFO: Test took 1097ms.
[22:27:26.694] INFO: The DUT currently contains the following objects:
[22:27:26.694] INFO: 2 TBM Cores tbm08c (2 ON)
[22:27:26.694] INFO: TBM Core alpha (0): 7 registers set
[22:27:26.694] INFO: TBM Core beta (1): 7 registers set
[22:27:26.694] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[22:27:26.694] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:26.694] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:26.694] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:26.694] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:26.694] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:26.694] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:26.694] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:26.694] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:26.694] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:26.694] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:26.694] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:26.694] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:26.694] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:26.695] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:26.695] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:26.695] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:27.808] INFO: Test took 1113ms.
[22:27:27.809] INFO: The DUT currently contains the following objects:
[22:27:27.809] INFO: 2 TBM Cores tbm08c (2 ON)
[22:27:27.809] INFO: TBM Core alpha (0): 7 registers set
[22:27:27.809] INFO: TBM Core beta (1): 7 registers set
[22:27:27.809] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[22:27:27.809] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:27.809] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:27.809] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:27.809] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:27.809] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:27.809] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:27.810] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:27.810] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:27.810] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:27.810] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:27.810] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:27.810] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:27.810] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:27.810] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:27.810] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:27.810] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:28.906] INFO: Test took 1096ms.
[22:27:28.908] INFO: The DUT currently contains the following objects:
[22:27:28.908] INFO: 2 TBM Cores tbm08c (2 ON)
[22:27:28.908] INFO: TBM Core alpha (0): 7 registers set
[22:27:28.908] INFO: TBM Core beta (1): 7 registers set
[22:27:28.908] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[22:27:28.908] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:28.908] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:28.908] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:28.908] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:28.908] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:28.908] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:28.908] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:28.908] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:28.908] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:28.908] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:28.908] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:28.909] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:28.909] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:28.909] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:28.909] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:28.909] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:30.026] INFO: Test took 1117ms.
[22:27:30.028] INFO: The DUT currently contains the following objects:
[22:27:30.028] INFO: 2 TBM Cores tbm08c (2 ON)
[22:27:30.028] INFO: TBM Core alpha (0): 7 registers set
[22:27:30.028] INFO: TBM Core beta (1): 7 registers set
[22:27:30.028] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[22:27:30.028] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:30.028] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:30.028] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:30.028] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:30.028] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:30.028] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:30.028] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:30.028] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:30.028] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:30.028] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:30.028] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:30.028] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:30.028] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:30.028] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:30.028] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:30.028] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:31.127] INFO: Test took 1099ms.
[22:27:31.129] INFO: The DUT currently contains the following objects:
[22:27:31.129] INFO: 2 TBM Cores tbm08c (2 ON)
[22:27:31.129] INFO: TBM Core alpha (0): 7 registers set
[22:27:31.129] INFO: TBM Core beta (1): 7 registers set
[22:27:31.129] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[22:27:31.129] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:31.129] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:31.129] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:31.130] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:31.130] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:31.130] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:31.130] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:31.130] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:31.130] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:31.130] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:31.130] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:31.130] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:31.130] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:31.130] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:31.130] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:31.130] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:32.248] INFO: Test took 1118ms.
[22:27:32.249] INFO: The DUT currently contains the following objects:
[22:27:32.249] INFO: 2 TBM Cores tbm08c (2 ON)
[22:27:32.249] INFO: TBM Core alpha (0): 7 registers set
[22:27:32.249] INFO: TBM Core beta (1): 7 registers set
[22:27:32.249] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[22:27:32.249] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:32.249] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:32.249] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:32.249] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:32.249] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:32.249] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:32.249] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:32.249] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:32.249] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:32.249] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:32.249] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:32.249] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:32.249] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:32.249] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:32.249] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:32.249] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:33.363] INFO: Test took 1114ms.
[22:27:33.364] INFO: The DUT currently contains the following objects:
[22:27:33.364] INFO: 2 TBM Cores tbm08c (2 ON)
[22:27:33.364] INFO: TBM Core alpha (0): 7 registers set
[22:27:33.364] INFO: TBM Core beta (1): 7 registers set
[22:27:33.364] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[22:27:33.364] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:33.364] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:33.364] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:33.364] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:33.364] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:33.364] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:33.364] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:33.364] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:33.364] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:33.364] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:33.364] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:33.365] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:33.365] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:33.365] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:33.365] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:33.365] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:34.464] INFO: Test took 1099ms.
[22:27:34.466] INFO: The DUT currently contains the following objects:
[22:27:34.466] INFO: 2 TBM Cores tbm08c (2 ON)
[22:27:34.466] INFO: TBM Core alpha (0): 7 registers set
[22:27:34.466] INFO: TBM Core beta (1): 7 registers set
[22:27:34.466] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[22:27:34.466] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:34.466] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:34.466] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:34.466] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:34.466] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:34.466] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:34.466] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:34.466] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:34.466] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:34.466] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:34.467] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:34.467] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:34.467] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:34.467] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:34.467] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:34.467] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:35.565] INFO: Test took 1098ms.
[22:27:35.566] INFO: The DUT currently contains the following objects:
[22:27:35.566] INFO: 2 TBM Cores tbm08c (2 ON)
[22:27:35.566] INFO: TBM Core alpha (0): 7 registers set
[22:27:35.566] INFO: TBM Core beta (1): 7 registers set
[22:27:35.566] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[22:27:35.566] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:35.566] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:35.566] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:35.566] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:35.566] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:35.566] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:35.566] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:35.566] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:35.567] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:35.567] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:35.567] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:35.567] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:35.567] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:35.567] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:35.567] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:35.567] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:36.685] INFO: Test took 1118ms.
[22:27:36.687] INFO: The DUT currently contains the following objects:
[22:27:36.687] INFO: 2 TBM Cores tbm08c (2 ON)
[22:27:36.687] INFO: TBM Core alpha (0): 7 registers set
[22:27:36.687] INFO: TBM Core beta (1): 7 registers set
[22:27:36.687] INFO: 16 ROCs psi46digv21respin (1 ON) with 4160 pixelConfigs
[22:27:36.687] INFO: ROC 0: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:36.687] INFO: ROC 1: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:36.687] INFO: ROC 2: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:36.687] INFO: ROC 3: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:36.687] INFO: ROC 4: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:36.687] INFO: ROC 5: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:36.687] INFO: ROC 6: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:36.687] INFO: ROC 7: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:36.687] INFO: ROC 8: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:36.687] INFO: ROC 9: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:36.687] INFO: ROC 10: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:36.688] INFO: ROC 11: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:36.688] INFO: ROC 12: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:36.688] INFO: ROC 13: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:36.688] INFO: ROC 14: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:36.688] INFO: ROC 15: 19 DACs set, Pixels: 4159 masked, 1 active.
[22:27:37.786] INFO: Test took 1098ms.
[22:27:37.793] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:30:46.394] INFO: Test took 188601ms.
[22:30:49.291] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:33:56.607] INFO: Test took 187316ms.
[22:33:59.532] INFO: safety margin for low PH: adding 0, margin is now 20
[22:33:59.542] INFO: safety margin for low PH: adding 0, margin is now 20
[22:33:59.552] INFO: safety margin for low PH: adding 0, margin is now 20
[22:33:59.562] INFO: safety margin for low PH: adding 1, margin is now 21
[22:33:59.572] INFO: safety margin for low PH: adding 2, margin is now 22
[22:33:59.582] INFO: safety margin for low PH: adding 3, margin is now 23
[22:33:59.592] INFO: safety margin for low PH: adding 0, margin is now 20
[22:33:59.602] INFO: safety margin for low PH: adding 0, margin is now 20
[22:33:59.612] INFO: safety margin for low PH: adding 1, margin is now 21
[22:33:59.622] INFO: safety margin for low PH: adding 2, margin is now 22
[22:33:59.633] INFO: safety margin for low PH: adding 3, margin is now 23
[22:33:59.642] INFO: safety margin for low PH: adding 4, margin is now 24
[22:33:59.652] INFO: safety margin for low PH: adding 5, margin is now 25
[22:33:59.662] INFO: safety margin for low PH: adding 6, margin is now 26
[22:33:59.673] INFO: safety margin for low PH: adding 7, margin is now 27
[22:33:59.682] INFO: safety margin for low PH: adding 0, margin is now 20
[22:33:59.692] INFO: safety margin for low PH: adding 0, margin is now 20
[22:33:59.702] INFO: safety margin for low PH: adding 0, margin is now 20
[22:33:59.712] INFO: safety margin for low PH: adding 0, margin is now 20
[22:33:59.722] INFO: safety margin for low PH: adding 0, margin is now 20
[22:33:59.732] INFO: safety margin for low PH: adding 0, margin is now 20
[22:33:59.742] INFO: safety margin for low PH: adding 0, margin is now 20
[22:33:59.752] INFO: safety margin for low PH: adding 0, margin is now 20
[22:33:59.761] INFO: safety margin for low PH: adding 0, margin is now 20
[22:33:59.772] INFO: safety margin for low PH: adding 0, margin is now 20
[22:33:59.782] INFO: safety margin for low PH: adding 0, margin is now 20
[22:33:59.830] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C0.dat
[22:33:59.830] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C1.dat
[22:33:59.831] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C2.dat
[22:33:59.831] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C3.dat
[22:33:59.831] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C4.dat
[22:33:59.831] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C5.dat
[22:33:59.832] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C6.dat
[22:33:59.832] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C7.dat
[22:33:59.832] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C8.dat
[22:33:59.832] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C9.dat
[22:33:59.833] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C10.dat
[22:33:59.833] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C11.dat
[22:33:59.833] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C12.dat
[22:33:59.833] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C13.dat
[22:33:59.833] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C14.dat
[22:33:59.834] INFO: write dac parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/dacParameters35_C15.dat
[22:34:03.546] INFO: Test took 3709ms.
[22:34:07.549] INFO: Test took 3652ms.
[22:34:11.612] INFO: Test took 3721ms.
[22:34:11.982] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:12.893] INFO: Test took 911ms.
[22:34:12.898] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:13.998] INFO: Test took 1100ms.
[22:34:13.003] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:15.101] INFO: Test took 1099ms.
[22:34:15.106] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:16.204] INFO: Test took 1098ms.
[22:34:16.210] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:17.304] INFO: Test took 1095ms.
[22:34:17.307] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:18.407] INFO: Test took 1100ms.
[22:34:18.412] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:19.536] INFO: Test took 1124ms.
[22:34:19.540] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:20.664] INFO: Test took 1124ms.
[22:34:20.668] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:21.761] INFO: Test took 1093ms.
[22:34:21.764] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:22.860] INFO: Test took 1096ms.
[22:34:22.864] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:23.961] INFO: Test took 1097ms.
[22:34:23.966] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:25.061] INFO: Test took 1095ms.
[22:34:25.064] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:26.157] INFO: Test took 1093ms.
[22:34:26.161] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:27.257] INFO: Test took 1096ms.
[22:34:27.261] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:28.360] INFO: Test took 1099ms.
[22:34:28.366] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:29.462] INFO: Test took 1097ms.
[22:34:29.466] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:30.586] INFO: Test took 1120ms.
[22:34:30.590] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:31.709] INFO: Test took 1119ms.
[22:34:31.715] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:32.813] INFO: Test took 1098ms.
[22:34:32.819] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:33.940] INFO: Test took 1122ms.
[22:34:33.945] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:35.063] INFO: Test took 1119ms.
[22:34:35.067] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:36.164] INFO: Test took 1097ms.
[22:34:36.170] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:37.265] INFO: Test took 1096ms.
[22:34:37.271] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:38.390] INFO: Test took 1120ms.
[22:34:38.394] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:39.494] INFO: Test took 1101ms.
[22:34:39.497] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:40.618] INFO: Test took 1121ms.
[22:34:40.622] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:41.742] INFO: Test took 1120ms.
[22:34:41.746] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:42.842] INFO: Test took 1096ms.
[22:34:42.847] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:43.945] INFO: Test took 1098ms.
[22:34:43.948] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:45.047] INFO: Test took 1099ms.
[22:34:45.053] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:46.169] INFO: Test took 1117ms.
[22:34:46.175] INFO: Not all ROCs have their pixels configured the same way. Running in FLAG_FORCE_SERIAL mode.
[22:34:47.295] INFO: Test took 1121ms.
[22:34:47.850] INFO: PixTestPhOptimization::doTest() done, duration: 459 seconds
[22:34:47.850] INFO: PH scale (per ROC): 63 73 70 68 69 69 72 73 66 67 72 58 67 68 70 76
[22:34:47.850] INFO: PH offset (per ROC): 175 188 176 186 176 187 171 173 176 178 183 183 187 179 161 174
[22:34:48.085] INFO: ######################################################################
[22:34:48.085] INFO: PixTestGainPedestal::fullTest() ntrig = 10
[22:34:48.085] INFO: ######################################################################
[22:34:48.102] INFO: scanning low vcal = 10
[22:34:52.199] INFO: Test took 4097ms.
[22:34:52.206] INFO: scanning low vcal = 20
[22:34:56.301] INFO: Test took 4095ms.
[22:34:56.311] INFO: scanning low vcal = 30
[22:35:00.400] INFO: Test took 4089ms.
[22:35:00.421] INFO: scanning low vcal = 40
[22:35:05.089] INFO: Test took 4668ms.
[22:35:05.224] INFO: scanning low vcal = 50
[22:35:09.831] INFO: Test took 4607ms.
[22:35:09.971] INFO: scanning low vcal = 60
[22:35:14.598] INFO: Test took 4627ms.
[22:35:14.735] INFO: scanning low vcal = 70
[22:35:19.290] INFO: Test took 4555ms.
[22:35:19.426] INFO: scanning low vcal = 80
[22:35:24.036] INFO: Test took 4610ms.
[22:35:24.174] INFO: scanning low vcal = 90
[22:35:28.777] INFO: Test took 4603ms.
[22:35:28.913] INFO: scanning low vcal = 100
[22:35:33.478] INFO: Test took 4565ms.
[22:35:33.609] INFO: scanning low vcal = 110
[22:35:38.242] INFO: Test took 4633ms.
[22:35:38.373] INFO: scanning low vcal = 120
[22:35:42.964] INFO: Test took 4591ms.
[22:35:43.103] INFO: scanning low vcal = 130
[22:35:47.696] INFO: Test took 4593ms.
[22:35:47.838] INFO: scanning low vcal = 140
[22:35:52.437] INFO: Test took 4599ms.
[22:35:52.575] INFO: scanning low vcal = 150
[22:35:57.229] INFO: Test took 4654ms.
[22:35:57.372] INFO: scanning low vcal = 160
[22:36:01.998] INFO: Test took 4626ms.
[22:36:02.140] INFO: scanning low vcal = 170
[22:36:06.790] INFO: Test took 4650ms.
[22:36:06.930] INFO: scanning low vcal = 180
[22:36:11.559] INFO: Test took 4629ms.
[22:36:11.695] INFO: scanning low vcal = 190
[22:36:16.432] INFO: Test took 4737ms.
[22:36:16.581] INFO: scanning low vcal = 200
[22:36:21.154] INFO: Test took 4573ms.
[22:36:21.301] INFO: scanning low vcal = 210
[22:36:25.935] INFO: Test took 4634ms.
[22:36:26.075] INFO: scanning low vcal = 220
[22:36:30.649] INFO: Test took 4574ms.
[22:36:30.792] INFO: scanning low vcal = 230
[22:36:35.425] INFO: Test took 4633ms.
[22:36:35.569] INFO: scanning low vcal = 240
[22:36:40.334] INFO: Test took 4765ms.
[22:36:40.472] INFO: scanning low vcal = 250
[22:36:45.066] INFO: Test took 4594ms.
[22:36:45.196] INFO: scanning high vcal = 30 (= 210 in low range)
[22:36:49.795] INFO: Test took 4599ms.
[22:36:49.937] INFO: scanning high vcal = 50 (= 350 in low range)
[22:36:54.542] INFO: Test took 4605ms.
[22:36:54.670] INFO: scanning high vcal = 70 (= 490 in low range)
[22:36:59.237] INFO: Test took 4567ms.
[22:36:59.367] INFO: scanning high vcal = 90 (= 630 in low range)
[22:37:04.022] INFO: Test took 4655ms.
[22:37:04.158] INFO: scanning high vcal = 200 (= 1400 in low range)
[22:37:08.778] INFO: Test took 4620ms.
[22:37:09.579] INFO: PixTestGainPedestal::measure() done
[22:38:02.497] INFO: PixTestGainPedestal::fit() done
[22:38:02.497] INFO: non-linearity mean: 0.952 0.954 0.958 0.959 0.958 0.959 0.955 0.958 0.958 0.953 0.954 0.958 0.953 0.956 0.954 0.949
[22:38:02.497] INFO: non-linearity RMS: 0.008 0.007 0.006 0.007 0.004 0.007 0.007 0.008 0.008 0.006 0.007 0.008 0.007 0.006 0.007 0.007
[22:38:02.497] INFO: write gain/ped parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/phCalibrationFitErr35_C0.dat
[22:38:02.523] INFO: write gain/ped parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/phCalibrationFitErr35_C1.dat
[22:38:02.548] INFO: write gain/ped parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/phCalibrationFitErr35_C2.dat
[22:38:02.573] INFO: write gain/ped parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/phCalibrationFitErr35_C3.dat
[22:38:02.599] INFO: write gain/ped parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/phCalibrationFitErr35_C4.dat
[22:38:02.624] INFO: write gain/ped parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/phCalibrationFitErr35_C5.dat
[22:38:02.649] INFO: write gain/ped parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/phCalibrationFitErr35_C6.dat
[22:38:02.676] INFO: write gain/ped parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/phCalibrationFitErr35_C7.dat
[22:38:02.701] INFO: write gain/ped parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/phCalibrationFitErr35_C8.dat
[22:38:02.727] INFO: write gain/ped parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/phCalibrationFitErr35_C9.dat
[22:38:02.752] INFO: write gain/ped parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/phCalibrationFitErr35_C10.dat
[22:38:02.778] INFO: write gain/ped parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/phCalibrationFitErr35_C11.dat
[22:38:02.804] INFO: write gain/ped parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/phCalibrationFitErr35_C12.dat
[22:38:02.831] INFO: write gain/ped parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/phCalibrationFitErr35_C13.dat
[22:38:02.856] INFO: write gain/ped parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/phCalibrationFitErr35_C14.dat
[22:38:02.882] INFO: write gain/ped parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/phCalibrationFitErr35_C15.dat
[22:38:02.907] INFO: PixTestGainPedestal::doTest() done, duration: 194 seconds
[22:38:02.916] INFO: readReadbackCal: /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C0.dat .. /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C15.dat
[22:38:02.918] INFO: PixTestReadback::doTest() start.
[22:38:02.919] INFO: PixTestReadback::RES sent once
[22:38:19.590] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C0.dat
[22:38:19.591] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C1.dat
[22:38:19.591] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C2.dat
[22:38:19.591] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C3.dat
[22:38:19.591] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C4.dat
[22:38:19.591] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C5.dat
[22:38:19.591] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C6.dat
[22:38:19.592] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C7.dat
[22:38:19.592] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C8.dat
[22:38:19.592] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C9.dat
[22:38:19.592] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C10.dat
[22:38:19.592] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C11.dat
[22:38:19.592] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C12.dat
[22:38:19.592] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C13.dat
[22:38:19.593] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C14.dat
[22:38:19.593] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C15.dat
[22:38:19.628] INFO: PixTestPattern:: pg_setup set to default.
[22:38:19.628] INFO: PixTestReadback::RES sent once
[22:38:36.254] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C0.dat
[22:38:36.254] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C1.dat
[22:38:36.254] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C2.dat
[22:38:36.255] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C3.dat
[22:38:36.255] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C4.dat
[22:38:36.255] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C5.dat
[22:38:36.255] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C6.dat
[22:38:36.255] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C7.dat
[22:38:36.255] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C8.dat
[22:38:36.256] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C9.dat
[22:38:36.256] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C10.dat
[22:38:36.256] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C11.dat
[22:38:36.256] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C12.dat
[22:38:36.256] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C13.dat
[22:38:36.257] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C14.dat
[22:38:36.257] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C15.dat
[22:38:36.299] INFO: PixTestPattern:: pg_setup set to default.
[22:38:36.300] INFO: PixTestReadback::RES sent once
[22:38:49.174] INFO: PixTestPattern:: pg_setup set to default.
[22:38:49.174] INFO: Vbg will be calibrated using Vd calibration
[22:38:49.174] INFO: /*/*/*/*::: ROC 0: uncalibrated Vbg = 148.8calibrated Vbg = 1.24974 :::*/*/*/*/
[22:38:49.174] INFO: /*/*/*/*::: ROC 1: uncalibrated Vbg = 153.1calibrated Vbg = 1.25614 :::*/*/*/*/
[22:38:49.174] INFO: /*/*/*/*::: ROC 2: uncalibrated Vbg = 147.5calibrated Vbg = 1.25375 :::*/*/*/*/
[22:38:49.174] INFO: /*/*/*/*::: ROC 3: uncalibrated Vbg = 156.2calibrated Vbg = 1.26506 :::*/*/*/*/
[22:38:49.174] INFO: /*/*/*/*::: ROC 4: uncalibrated Vbg = 155.4calibrated Vbg = 1.26603 :::*/*/*/*/
[22:38:49.174] INFO: /*/*/*/*::: ROC 5: uncalibrated Vbg = 158.9calibrated Vbg = 1.26955 :::*/*/*/*/
[22:38:49.174] INFO: /*/*/*/*::: ROC 6: uncalibrated Vbg = 148.4calibrated Vbg = 1.26731 :::*/*/*/*/
[22:38:49.174] INFO: /*/*/*/*::: ROC 7: uncalibrated Vbg = 149.5calibrated Vbg = 1.2673 :::*/*/*/*/
[22:38:49.174] INFO: /*/*/*/*::: ROC 8: uncalibrated Vbg = 158calibrated Vbg = 1.2681 :::*/*/*/*/
[22:38:49.174] INFO: /*/*/*/*::: ROC 9: uncalibrated Vbg = 156.1calibrated Vbg = 1.26552 :::*/*/*/*/
[22:38:49.174] INFO: /*/*/*/*::: ROC 10: uncalibrated Vbg = 153.7calibrated Vbg = 1.26903 :::*/*/*/*/
[22:38:49.174] INFO: /*/*/*/*::: ROC 11: uncalibrated Vbg = 153.4calibrated Vbg = 1.26025 :::*/*/*/*/
[22:38:49.174] INFO: /*/*/*/*::: ROC 12: uncalibrated Vbg = 154.1calibrated Vbg = 1.25672 :::*/*/*/*/
[22:38:49.174] INFO: /*/*/*/*::: ROC 13: uncalibrated Vbg = 155.1calibrated Vbg = 1.25847 :::*/*/*/*/
[22:38:49.174] INFO: /*/*/*/*::: ROC 14: uncalibrated Vbg = 161.7calibrated Vbg = 1.25262 :::*/*/*/*/
[22:38:49.174] INFO: /*/*/*/*::: ROC 15: uncalibrated Vbg = 157.3calibrated Vbg = 1.2583 :::*/*/*/*/
[22:38:49.179] INFO: PixTestReadback::RES sent once
[22:42:44.098] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C0.dat
[22:42:44.098] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C1.dat
[22:42:44.098] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C2.dat
[22:42:44.098] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C3.dat
[22:42:44.098] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C4.dat
[22:42:44.098] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C5.dat
[22:42:44.098] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C6.dat
[22:42:44.099] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C7.dat
[22:42:44.099] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C8.dat
[22:42:44.099] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C9.dat
[22:42:44.099] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C10.dat
[22:42:44.099] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C11.dat
[22:42:44.099] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C12.dat
[22:42:44.099] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C13.dat
[22:42:44.099] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C14.dat
[22:42:44.099] INFO: write readback calibration parameters into /home/l_tester/ColdBox/ModuleTests/M4570_FullQualification_2015-08-10_12h35m_1439206531/004_Fulltest_p17/readbackCal_C15.dat
[22:42:44.134] INFO: PixTestPattern:: pg_setup set to default.
[22:42:44.138] INFO: PixTestReadback::doTest() done
[22:42:44.154] INFO: enter test to run
[22:42:44.154] INFO: test: q no parameter change
[22:42:44.315] QUIET: Connection to board 176 closed.
[22:42:44.318] INFO: pXar: this is the end, my friend