[13:03:55.036] INFO: *** Welcome to pxar ***
[13:03:55.036] INFO: *** Today: 2016/07/19
[13:03:55.054] INFO: *** Version: v1.9.0-814-g7497
[13:03:55.054] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//dacParameters35_C15.dat
[13:03:55.087] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:03:55.088] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//defaultMaskFile.dat
[13:03:55.093] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C15.dat
[13:03:55.182] INFO: clk: 4
[13:03:55.182] INFO: ctr: 4
[13:03:55.182] INFO: sda: 19
[13:03:55.182] INFO: tin: 9
[13:03:55.182] INFO: level: 15
[13:03:55.182] INFO: triggerdelay: 0
[13:03:55.182] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[13:03:55.182] INFO: Log level: INFO
[13:03:55.200] QUIET: Connection to board DTB_WREKRL opened.
[13:03:55.203] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 33
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREKRL
MAC address: 40D855118021
Hostname: pixelDTB033
Comment:
------------------------------------------------------
[13:03:55.206] INFO: RPC call hashes of host and DTB match: 398089610
[13:03:56.739] INFO: DUT info:
[13:03:56.739] INFO: The DUT currently contains the following objects:
[13:03:56.740] INFO: 2 TBM Cores tbm08c (2 ON)
[13:03:56.740] INFO: TBM Core alpha (0): 7 registers set
[13:03:56.740] INFO: TBM Core beta (1): 7 registers set
[13:03:56.740] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[13:03:56.740] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:56.740] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:56.740] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:56.740] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:56.740] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:56.740] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:56.740] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:56.740] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:56.741] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:56.741] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:56.741] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:56.741] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:56.741] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:56.741] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:56.741] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:56.741] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[13:03:57.144] INFO: enter 'restricted' command line mode
[13:03:57.144] INFO: enter test to run
[13:04:03.731] INFO: test: PixelAlive no parameter change
[13:04:03.731] INFO: running: pixelalive
[13:04:03.741] INFO: ----------------------------------------------------------------------
[13:04:03.741] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[13:04:03.741] INFO: ----------------------------------------------------------------------
[13:04:04.063] INFO: Expecting 41600 events.
[13:04:08.381] INFO: 41600 events read in total (3600ms).
[13:04:08.551] INFO: Test took 4807ms.
[13:04:08.561] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:04:08.823] INFO: PixTestAlive::aliveTest() done
[13:04:08.823] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[13:04:08.854] INFO: enter test to run
[13:04:48.163] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[13:04:48.163] INFO: running: highrate
[13:04:48.163] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[13:04:48.385] INFO: ----------------------------------------------------------------------
[13:04:48.385] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[13:04:48.385] INFO: ----------------------------------------------------------------------
[13:04:48.385] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[13:04:48.385] INFO: edge/corner pixel THR is adjusted
[13:04:48.386] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:04:49.345] INFO: Collecting data for 5 seconds...
[13:04:54.365] INFO: Done with hot pixel readout
[13:05:05.949] INFO: PixTest:: pg_setup set to default.
[13:05:05.950] INFO: 9 hot pixels found in step 0
[13:05:06.968] INFO: Collecting data for 5 seconds...
[13:05:11.984] INFO: Done with hot pixel readout
[13:05:12.214] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 0 Number of ROCs (6) != Token Chain Length (8)
[13:05:12.214] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 1 Number of ROCs (7) != Token Chain Length (8)
[13:05:12.214] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[13:05:12.214] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0f6 8000 43c8 43c8 43c8 849 262c 43c8 43c8 43c8 43c8 43c8 e000 c000
[13:05:12.214] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0f0 80b1 4388 4388 413 284a 4388 4388 4388 4388 4388 750 284c 4388 e000 c000
[13:05:12.214] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0f1 80c0 4388 114 244a 4388 4388 4388 71d 2a4e 81b 2a6f 851 264f 4389 4389 15 2045 510 2669 4389 4389 110 2445 e000 c000
[13:05:12.214] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0f2 8000 4388 4388 55b 2263 4389 2a1 2482 511 204b 4389 18 204e 4388 74a 2844 4388 4389 4389 e000 c000
[13:05:12.214] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0f3 8040 43c8 43c9 43c8 559 265b 681 43c8 84d 2245 43c9 43c8 415 2446 43c9 e000 c000
[13:05:12.214] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0f4 80b1 43c8 43c8 43c8 43c8 43c8 43c8 31c 2049 854 264f 43c8 208 2649 43c8 254 2445 e000 c000
[13:05:12.214] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0f5 80c0 43c8 43c8 1a 2a40 43c8 43c8 43c8 43c8 43c8 20c 264c 2c0 264c 43c8 e000 c000
[13:05:12.214] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[13:05:12.214] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1f6 8000 43c8 43c8 454 2024 43c8 43c8 43c8 43c8 43c8 43c8 e000 c000
[13:05:12.214] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1f0 80b1 4389 752 2244 4389 4389 4389 4389 108 2a2a 4389 4389 4389 e000 c000
[13:05:12.214] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1f1 80c0 4388 4388 4388 4388 4389 4389 4389 4389 e000 c000
[13:05:12.214] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1f2 8000 4388 742 2a40 4388 2c5 2481 6dc 2646 84b 2443 4389 34b 2848 4389 4388 4388 4389 4389 e000 c000
[13:05:12.214] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1f3 8040 43c8 849 224f 2b2 220a cca 299a 43c8 43c9 43c8 43c9 43c8 43c9 e000 c000
[13:05:12.214] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1f4 80b1 43c8 358 224f 43c8 303 2645 43c8 205 2a64 43c8 85c 264f 43c8 43c8 415 224a 43c8 43c8 e000 c000
[13:05:12.214] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1f5 80c0 43c8 43c8 43c8 43c8 43c8 53 244f 43c8 43c8 43c8 e000 c000
[13:05:23.458] INFO: PixTest:: pg_setup set to default.
[13:05:23.459] INFO: 8 hot pixels found in step 1
[13:05:24.447] INFO: Collecting data for 5 seconds...
[13:05:29.464] INFO: Done with hot pixel readout
[13:05:40.386] INFO: PixTest:: pg_setup set to default.
[13:05:40.387] INFO: 9 hot pixels found in step 2
[13:05:41.374] INFO: Collecting data for 5 seconds...
[13:05:46.392] INFO: Done with hot pixel readout
[13:05:57.964] INFO: PixTest:: pg_setup set to default.
[13:05:57.965] INFO: 8 hot pixels found in step 3
[13:05:58.951] INFO: Collecting data for 5 seconds...
[13:06:03.967] INFO: Done with hot pixel readout
[13:06:15.486] INFO: PixTest:: pg_setup set to default.
[13:06:15.487] INFO: 5 hot pixels found in step 4
[13:06:16.473] INFO: Collecting data for 5 seconds...
[13:06:21.490] INFO: Done with hot pixel readout
[13:06:32.729] INFO: PixTest:: pg_setup set to default.
[13:06:32.730] INFO: 3 hot pixels found in step 5
[13:06:33.717] INFO: Collecting data for 5 seconds...
[13:06:38.734] INFO: Done with hot pixel readout
[13:06:39.126] ERROR: <datapipe.cc/CheckEventValidity:L480> Channel 0 has NoTokenPass but 4 ROCs were found
[13:06:39.126] WARNING: Channel 1 ROC 4: Readback start marker after 7 readouts!
[13:06:39.127] ERROR: <datapipe.cc/CheckEventValidity:L480> Channel 1 has NoTokenPass but 5 ROCs were found
[13:06:39.127] ERROR: <datapipe.cc/CheckEventID:L463> Channel 0 Event ID mismatch: local ID (39) != TBM ID (26)
[13:06:39.127] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 0 Number of ROCs (1) != Token Chain Length (8)
[13:06:39.127] ERROR: <datapipe.cc/CheckEventID:L463> Channel 0 Event ID mismatch: local ID (27) != TBM ID (39)
[13:06:39.127] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[13:06:39.127] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a129 80c0 43c8 43c8 413 2462 43c8 43c8 48b 2068 43c8 43c8 43c8 759 262e 43c8 e000 c000
[13:06:39.127] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a123 8040 4388 744 284a 4389 4388 4389 4388 20b 2249 4389 4388 4389 51d 224a e000 c000
[13:06:39.127] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a124 80b1 4388 4388 55 2849 611 2249 4388 711 2862 4388 4388 650 2044 4388 4388 4388 e000 c000
[13:06:39.127] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a125 80c0 4388 4388 653 2062 4388 4388 4388 4388 4388 4388 e000 c000
[13:06:39.127] ERROR: <datapipe.cc/Read:L166> ====== 2 ====== a126 8000 4388 43c8 43c8 43c8 43cb 87 2c0f 1 2aa7 8a8 207c 0 21ff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff
[13:06:39.127] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a127 8040 43c8 43c8 51c 264f 68b 2a44 43c8 43c8 495 2a4d 43c8 43c8 43c8 43c8 e000 c000
[13:06:39.127] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a128 80b1 43c8 43c8 553 246a 43c8 43c8 43c8 43c8 43c8 43c8 e000 c000
[13:06:39.127] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[13:06:39.127] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a02a 8000 43c8 43c8 118 2a2f 43c8 43c8 43c8 109 202e 800 2a26 43c8 50 2047 43c8 43c8 e000 c000
[13:06:39.127] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a025 80c0 4388 4388 4388 4388 4388 4388 4388 4388 511 2440 e000 c000
[13:06:39.127] ERROR: <datapipe.cc/Read:L166> ====== 2 ====== a026 8000 4388 43c8 43c8 43c8 510 2f30 2a5 2eab 540
[13:06:39.127] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a01a 805a 43c8 e000 c000
[13:06:39.127] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a027 8040 43c8 745 202f 43c8 14 282d 43c8 43c8 43c8 43c8 159 2661 513 284f 43c8 43c8 e000 c000
[13:06:39.127] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a028 80b1 43c8 43c8 43c8 43c8 43c8 43c8 511 2265 708 2066 43c8 30b 2465 43c8 e000 c000
[13:06:39.127] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a029 80c0 43c8 43c8 43c8 43c8 262 2046 43c8 d1 202b 409 2649 43c8 43c8 4c5 2445 68c 2642 70b 2882 43c8 60d 2646 e000 c000
[13:06:50.439] INFO: PixTest:: pg_setup set to default.
[13:06:50.440] INFO: 5 hot pixels found in step 6
[13:06:51.427] INFO: Collecting data for 5 seconds...
[13:06:56.443] INFO: Done with hot pixel readout
[13:07:07.732] INFO: PixTest:: pg_setup set to default.
[13:07:07.733] INFO: 2 hot pixels found in step 7
[13:07:08.721] INFO: Collecting data for 5 seconds...
[13:07:13.737] INFO: Done with hot pixel readout
[13:07:25.090] INFO: PixTest:: pg_setup set to default.
[13:07:25.091] INFO: 3 hot pixels found in step 8
[13:07:26.078] INFO: Collecting data for 5 seconds...
[13:07:31.094] INFO: Done with hot pixel readout
[13:07:42.554] INFO: PixTest:: pg_setup set to default.
[13:07:42.554] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[13:07:42.555] INFO: 3 hot pixels found in step 9
[13:07:43.543] INFO: Collecting data for 5 seconds...
[13:07:48.559] INFO: Done with hot pixel readout
[13:07:58.916] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 0 Number of ROCs (6) != Token Chain Length (8)
[13:07:58.916] ERROR: <datapipe.cc/CheckEventValidity:L480> Channel 1 has NoTokenPass but 7 ROCs were found
[13:07:58.916] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[13:07:58.916] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0c3 8040 4388 155 2040 4389 d2 2841 4388 60d 2660 4389 4388 849 2846 4389 48c 2246 555 2868 4388 4389 e000 c000
[13:07:58.916] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0bd 80c0 43c8 70b 2685 43c8 43c8 43c8 43c8 43c8 43c8 43c8 e000 c000
[13:07:58.916] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0be 8000 43c8 43c8 43c8 43c8 d8 2264 43c8 59 2241 35c 2441 43c8 43c8 43c8 255 2244 e000 c000
[13:07:58.916] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0bf 8040 43ca 43ca 43ca 43ca 43ca 18 2628 43ca 43ca 6d0 204f 43ca 514 2a2a e000 c000
[13:07:58.916] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0c0 80b1 43c8 43c8 43c8 48a 2249 820 2240 43c8 54a 2646 4388 6cc 264f 711 2540 c0d 2540 510 2105 117 2838 35a 2640 860 2a45 4388 e000 c000
[13:07:58.916] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0c1 80c0 4388 4388 4388 4388 4389 852 262f 4389 4389 753 2462 744 2841 744 2449 4389 e000 c000
[13:07:58.916] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a0c2 8000 4388 84b 2668 4388 4389 4389 488 2a4f 4388 4388 4389 cc 264d e1 2264 4389 e000 c000
[13:07:58.917] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[13:07:58.917] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1c3 8040 4388 4389 4388 4389 4388 4389 4388 619 2642 4389 da 2a4f e000 c000
[13:07:58.917] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1bd 80c0 43c8 254 282c 2c0 2641 43c8 43c8 43c8 43c8 43c8 43c8 43c8 e000 c000
[13:07:58.917] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1be 8000 43c8 43c8 43c8 43c8 43c8 43c8 2cb 2482 43c8 43c8 e000 c000
[13:07:58.917] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1bf 8040 43ca 509 224f 43ca 43ca 43ca 43ca 43ca 43ca 43ca 6e1 2664 e000 c000
[13:07:58.917] ERROR: <datapipe.cc/Read:L166> ====== 2 ====== a1c0 80b1 43c9 492 2646 43c9 4c8 2240 43c9 43c9 43c9 4389 14d 2a4e 4389 74a 2828 bf2 2a99 49 2450 440 2cbf fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff 2fff fff
[13:07:58.917] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1c1 80c0 4388 4388 70d 2241 4388 4388 14c 2840 4389 15c 242c 4e0 2664 4389 4389 4389 e000 c000
[13:07:58.917] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a1c2 8000 4388 4388 4c9 2464 855 222d 4389 759 2a4f 4389 4388 85b 264c 4388 4389 4389 e000 c000
[13:07:59.946] INFO: PixTest:: pg_setup set to default.
[13:07:59.946] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[13:07:59.947] INFO: 1 hot pixels found in step 10
[13:07:59.978] INFO: 1 hot pixels could not be trimmed and have been masked.
[13:07:59.982] INFO: PixTest::trimHotPixels() done
[13:07:59.986] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C0.dat
[13:07:59.998] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C1.dat
[13:08:00.005] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C2.dat
[13:08:00.011] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C3.dat
[13:08:00.016] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C4.dat
[13:08:00.021] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C5.dat
[13:08:00.026] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C6.dat
[13:08:00.032] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C7.dat
[13:08:00.037] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C8.dat
[13:08:00.042] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C9.dat
[13:08:00.047] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C10.dat
[13:08:00.053] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C11.dat
[13:08:00.058] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C12.dat
[13:08:00.063] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C13.dat
[13:08:00.068] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C14.dat
[13:08:00.074] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C15.dat
[13:08:00.079] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//defaultMaskFile.dat
[13:08:00.089] INFO: enter test to run
[13:09:59.721] INFO: test: timing no parameter change
[13:09:59.721] INFO: running: timing
[13:09:59.724] INFO: ######################################################################
[13:09:59.724] INFO: PixTestTiming::doTest()
[13:09:59.724] INFO: ######################################################################
[13:09:59.724] INFO: ----------------------------------------------------------------------
[13:09:59.724] INFO: PixTestTiming::TBMPhaseScan()
[13:09:59.725] INFO: ----------------------------------------------------------------------
[13:16:14.465] INFO: TBM Phase Settings: 240
[13:16:14.465] INFO: 400MHz Phase: 4
[13:16:14.465] INFO: 160MHz Phase: 7
[13:16:14.465] INFO: Functional Phase Area: 5
[13:16:14.475] INFO: Test took 374751 ms.
[13:16:14.475] INFO: PixTestTiming::TBMPhaseScan() done.
[13:16:14.476] INFO: ----------------------------------------------------------------------
[13:16:14.476] INFO: PixTestTiming::ROCDelayScan()
[13:16:14.476] INFO: ----------------------------------------------------------------------
[13:18:59.069] INFO: ROC Delay Settings: 228
[13:18:59.069] INFO: ROC Header-Trailer/Token Delay: 11
[13:18:59.069] INFO: ROC Port 0 Delay: 4
[13:18:59.069] INFO: ROC Port 1 Delay: 4
[13:18:59.069] INFO: Functional ROC Area: 5
[13:18:59.073] INFO: Test took 164598 ms.
[13:18:59.073] INFO: PixTestTiming::ROCDelayScan() done.
[13:18:59.073] INFO: ----------------------------------------------------------------------
[13:18:59.073] INFO: PixTestTiming::TimingTest()
[13:18:59.073] INFO: ----------------------------------------------------------------------
[13:19:15.194] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:19:30.165] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:19:45.153] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:20:00.115] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:20:15.082] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:20:30.106] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:20:45.230] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:21:00.328] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:21:15.407] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:21:30.476] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:21:30.857] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:21:30.870] INFO: ----------------------------------------------------------------------
[13:21:30.870] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[13:21:30.870] INFO: ----------------------------------------------------------------------
[13:21:30.870] INFO: ----------------------------------------------------------------------
[13:21:30.870] INFO: Read back bit status: 1
[13:21:30.870] INFO: ----------------------------------------------------------------------
[13:21:30.870] INFO: ----------------------------------------------------------------------
[13:21:30.870] INFO: Timings are good!
[13:21:30.870] INFO: ----------------------------------------------------------------------
[13:21:30.870] INFO: Test took 151797 ms.
[13:21:30.870] INFO: PixTestTiming::TimingTest() done.
[13:21:30.870] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//tbmParameters_C0a.dat
[13:21:30.870] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:21:30.870] INFO: PixTestTiming::doTest took 691149 ms.
[13:21:30.870] INFO: PixTestTiming::doTest() done
[13:21:30.870] INFO: Write out TBMPhaseScan_0_V0
[13:21:30.870] INFO: Write out TBMPhaseScan_1_V0
[13:21:30.870] INFO: Write out CombinedTBMPhaseScan_V0
[13:21:30.871] INFO: Write out ROCDelayScan3_V0
[13:21:30.872] INFO: enter test to run
[13:22:01.300] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[13:22:01.300] INFO: running: highrate
[13:22:01.305] INFO: ----------------------------------------------------------------------
[13:22:01.306] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[13:22:01.306] INFO: ----------------------------------------------------------------------
[13:22:01.306] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[13:22:01.306] INFO: edge/corner pixel THR is adjusted
[13:22:01.306] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:22:02.263] INFO: Collecting data for 5 seconds...
[13:22:07.282] INFO: Done with hot pixel readout
[13:22:18.792] INFO: PixTest:: pg_setup set to default.
[13:22:18.793] INFO: 2 hot pixels found in step 0
[13:22:19.785] INFO: Collecting data for 5 seconds...
[13:22:24.803] INFO: Done with hot pixel readout
[13:22:36.447] INFO: PixTest:: pg_setup set to default.
[13:22:36.448] INFO: 1 hot pixels found in step 1
[13:22:37.439] INFO: Collecting data for 5 seconds...
[13:22:42.458] INFO: Done with hot pixel readout
[13:22:53.939] INFO: PixTest:: pg_setup set to default.
[13:22:53.940] INFO: 1 hot pixels found in step 2
[13:22:54.932] INFO: Collecting data for 5 seconds...
[13:22:59.949] INFO: Done with hot pixel readout
[13:23:11.691] INFO: PixTest:: pg_setup set to default.
[13:23:11.691] INFO: 0 hot pixels found in step 3
[13:23:11.728] INFO: 0 hot pixels could not be trimmed and have been masked.
[13:23:11.732] INFO: PixTest::trimHotPixels() done
[13:23:11.732] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C0.dat
[13:23:11.738] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C1.dat
[13:23:11.744] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C2.dat
[13:23:11.749] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C3.dat
[13:23:11.755] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C4.dat
[13:23:11.760] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C5.dat
[13:23:11.766] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C6.dat
[13:23:11.771] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C7.dat
[13:23:11.776] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C8.dat
[13:23:11.782] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C9.dat
[13:23:11.787] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C10.dat
[13:23:11.793] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C11.dat
[13:23:11.798] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C12.dat
[13:23:11.804] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C13.dat
[13:23:11.809] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C14.dat
[13:23:11.815] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C15.dat
[13:23:11.820] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//defaultMaskFile.dat
[13:23:11.830] INFO: enter test to run
[13:24:24.683] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[13:24:24.683] INFO: running: highrate
[13:24:24.689] INFO: ----------------------------------------------------------------------
[13:24:24.689] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[13:24:24.689] INFO: ----------------------------------------------------------------------
[13:24:24.689] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[13:24:24.689] INFO: edge/corner pixel THR is adjusted
[13:24:24.689] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:24:25.646] INFO: Collecting data for 1 seconds...
[13:24:26.650] INFO: Done with hot pixel readout
[13:24:30.671] INFO: PixTest:: pg_setup set to default.
[13:24:30.672] INFO: 0 hot pixels found in step 0
[13:24:30.677] INFO: 0 hot pixels could not be trimmed and have been masked.
[13:24:30.769] INFO: PixTest::trimHotPixels() done
[13:24:30.769] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C0.dat
[13:24:30.776] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C1.dat
[13:24:30.784] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C2.dat
[13:24:30.789] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C3.dat
[13:24:30.795] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C4.dat
[13:24:30.800] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C5.dat
[13:24:30.805] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C6.dat
[13:24:30.811] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C7.dat
[13:24:30.816] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C8.dat
[13:24:30.821] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C9.dat
[13:24:30.827] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C10.dat
[13:24:30.832] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C11.dat
[13:24:30.837] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C12.dat
[13:24:30.843] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C13.dat
[13:24:30.848] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C14.dat
[13:24:30.853] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//trimParameters35_C15.dat
[13:24:30.858] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-H-1-36_FPIXTest-17C-FNAL-160714-1154_2016-07-14_11h54m_1468515260/000_FPIXTest_p17//defaultMaskFile.dat
[13:24:30.868] INFO: enter test to run
[13:25:10.363] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[13:25:10.363] INFO: running: xray
[13:25:10.364] INFO: ----------------------------------------------------------------------
[13:25:10.364] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:25:10.364] INFO: ----------------------------------------------------------------------
[13:25:11.327] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:25:22.966] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[13:25:52.410] INFO: Resuming triggers.
[13:26:04.050] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[13:26:33.429] INFO: Resuming triggers.
[13:26:45.069] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[13:27:14.460] INFO: Resuming triggers.
[13:27:26.099] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[13:27:55.431] INFO: Resuming triggers.
[13:28:07.072] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[13:28:36.371] INFO: Resuming triggers.
[13:28:48.010] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[13:29:17.314] INFO: Resuming triggers.
[13:29:28.954] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[13:29:58.206] INFO: Resuming triggers.
[13:30:09.846] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[13:30:39.157] INFO: Resuming triggers.
[13:30:46.364] INFO: data taking finished, elapsed time: 100 seconds.
[13:31:04.690] INFO: PixTest:: pg_setup set to default.
[13:31:04.693] INFO: PixTestXray::doPhRun() done
[13:31:04.830] INFO: enter test to run
[13:32:12.488] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[13:32:12.488] INFO: running: xray
[13:32:12.489] INFO: ----------------------------------------------------------------------
[13:32:12.489] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:32:12.489] INFO: ----------------------------------------------------------------------
[13:32:13.464] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:32:20.405] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[13:32:51.319] INFO: Resuming triggers.
[13:32:58.259] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[13:33:29.455] INFO: Resuming triggers.
[13:33:36.402] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[13:34:07.197] INFO: Resuming triggers.
[13:34:14.143] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[13:34:44.680] INFO: Resuming triggers.
[13:34:51.625] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[13:35:23.091] INFO: Resuming triggers.
[13:35:30.039] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[13:36:01.438] INFO: Resuming triggers.
[13:36:08.381] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[13:36:39.005] INFO: Resuming triggers.
[13:36:45.951] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[13:37:16.149] INFO: Resuming triggers.
[13:37:23.094] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[13:37:53.390] INFO: Resuming triggers.
[13:38:00.339] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[13:38:30.673] INFO: Resuming triggers.
[13:38:37.621] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[13:39:07.869] INFO: Resuming triggers.
[13:39:14.813] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[13:39:45.018] INFO: Resuming triggers.
[13:39:51.959] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[13:40:22.262] INFO: Resuming triggers.
[13:40:29.204] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[13:40:59.414] INFO: Resuming triggers.
[13:41:02.536] INFO: data taking finished, elapsed time: 100 seconds.
[13:41:16.406] INFO: PixTest:: pg_setup set to default.
[13:41:16.409] INFO: PixTestXray::doPhRun() done
[13:41:16.557] INFO: enter test to run
[13:42:39.324] INFO: test: HighRate no parameter change
[13:42:39.324] INFO: running: highrate
[13:42:39.325] INFO: ----------------------------------------------------------------------
[13:42:39.325] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[13:42:39.325] INFO: ----------------------------------------------------------------------
[13:42:39.479] INFO: Expecting 768 events.
[13:42:40.613] INFO: 768 events read in total (419ms).
[13:42:40.613] INFO: Test took 1279ms.
[13:42:41.416] INFO: Expecting 41600 events.
[13:42:44.493] INFO: 41600 events read in total (2550ms).
[13:42:44.494] INFO: Test took 3875ms.
[13:42:44.526] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:42:45.256] INFO: Expecting 41600 events.
[13:42:48.440] INFO: 41600 events read in total (2657ms).
[13:42:48.441] INFO: Test took 3899ms.
[13:42:48.474] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:42:49.198] INFO: Expecting 41600 events.
[13:42:52.414] INFO: 41600 events read in total (2689ms).
[13:42:52.415] INFO: Test took 3923ms.
[13:42:52.447] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:42:53.172] INFO: Expecting 41600 events.
[13:42:56.385] INFO: 41600 events read in total (2686ms).
[13:42:56.386] INFO: Test took 3921ms.
[13:42:56.419] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:42:57.143] INFO: Expecting 41600 events.
[13:43:00.358] INFO: 41600 events read in total (2688ms).
[13:43:00.359] INFO: Test took 3922ms.
[13:43:00.392] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:01.119] INFO: Expecting 41600 events.
[13:43:04.353] INFO: 41600 events read in total (2707ms).
[13:43:04.354] INFO: Test took 3945ms.
[13:43:04.386] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:05.110] INFO: Expecting 41600 events.
[13:43:08.337] INFO: 41600 events read in total (2700ms).
[13:43:08.338] INFO: Test took 3934ms.
[13:43:08.371] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:09.093] INFO: Expecting 41600 events.
[13:43:12.323] INFO: 41600 events read in total (2703ms).
[13:43:12.324] INFO: Test took 3935ms.
[13:43:12.356] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:13.083] INFO: Expecting 41600 events.
[13:43:16.320] INFO: 41600 events read in total (2711ms).
[13:43:16.321] INFO: Test took 3947ms.
[13:43:16.354] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:17.079] INFO: Expecting 41600 events.
[13:43:20.318] INFO: 41600 events read in total (2712ms).
[13:43:20.319] INFO: Test took 3947ms.
[13:43:20.352] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:21.081] INFO: Expecting 41600 events.
[13:43:24.299] INFO: 41600 events read in total (2692ms).
[13:43:24.300] INFO: Test took 3930ms.
[13:43:24.333] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:25.059] INFO: Expecting 41600 events.
[13:43:28.283] INFO: 41600 events read in total (2697ms).
[13:43:28.284] INFO: Test took 3934ms.
[13:43:28.317] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:29.044] INFO: Expecting 41600 events.
[13:43:32.268] INFO: 41600 events read in total (2697ms).
[13:43:32.269] INFO: Test took 3934ms.
[13:43:32.302] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:33.029] INFO: Expecting 41600 events.
[13:43:36.250] INFO: 41600 events read in total (2694ms).
[13:43:36.251] INFO: Test took 3932ms.
[13:43:36.283] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:37.008] INFO: Expecting 41600 events.
[13:43:40.235] INFO: 41600 events read in total (2700ms).
[13:43:40.236] INFO: Test took 3934ms.
[13:43:40.270] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:40.996] INFO: Expecting 41600 events.
[13:43:44.230] INFO: 41600 events read in total (2707ms).
[13:43:44.231] INFO: Test took 3943ms.
[13:43:44.263] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:44.989] INFO: Expecting 41600 events.
[13:43:48.229] INFO: 41600 events read in total (2714ms).
[13:43:48.230] INFO: Test took 3949ms.
[13:43:48.263] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:48.990] INFO: Expecting 41600 events.
[13:43:52.221] INFO: 41600 events read in total (2704ms).
[13:43:52.222] INFO: Test took 3940ms.
[13:43:52.255] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:52.977] INFO: Expecting 41600 events.
[13:43:56.193] INFO: 41600 events read in total (2689ms).
[13:43:56.194] INFO: Test took 3921ms.
[13:43:56.227] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:56.951] INFO: Expecting 41600 events.
[13:44:00.008] INFO: 41600 events read in total (2530ms).
[13:44:00.009] INFO: Test took 3765ms.
[13:44:00.042] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:00.406] INFO: enter test to run
[13:44:33.883] INFO: test: HighRate no parameter change
[13:44:33.883] INFO: running: highrate
[13:44:33.901] INFO: ----------------------------------------------------------------------
[13:44:33.901] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:44:33.901] INFO: ----------------------------------------------------------------------
[13:44:34.523] INFO: Expecting 208000 events.
[13:44:46.443] INFO: 208000 events read in total (11393ms).
[13:44:46.446] INFO: Test took 12534ms.
[13:44:46.588] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:46.842] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[13:44:46.842] INFO: number of red-efficiency pixels: 75 39 86 129 134 122 139 72 96 157 129 129 105 53 16 26
[13:44:46.842] INFO: number of X-ray hits detected: 60369 39798 62649 97897 102683 107261 102912 67456 74626 103739 98823 87929 89793 53295 20132 24100
[13:44:46.842] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:44:46.842] INFO: number of Vcal hits detected: 207924 207961 207911 207866 207865 207877 207860 207928 207900 207840 207864 207866 207893 207947 207983 207974
[13:44:46.842] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 99.9 100.0 100.0 100.0 100.0
[13:44:46.842] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[13:44:46.842] INFO: X-ray hit rate [MHz/cm2]: 17.7 11.7 18.4 28.7 30.1 31.4 30.2 19.8 21.9 30.4 29.0 25.8 26.3 15.6 5.9 7.1
[13:44:46.842] INFO: PixTestHighRate::doXPixelAlive() done
[13:44:46.886] INFO: PixTest:: pg_setup set to default.
[13:44:46.901] INFO: enter test to run
[13:45:13.947] INFO: test: HighRate no parameter change
[13:45:13.947] INFO: running: highrate
[13:45:13.948] INFO: ----------------------------------------------------------------------
[13:45:13.948] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:45:13.948] INFO: ----------------------------------------------------------------------
[13:45:14.566] INFO: Expecting 208000 events.
[13:45:28.123] INFO: 208000 events read in total (13030ms).
[13:45:28.128] INFO: Test took 14170ms.
[13:45:28.416] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:45:28.716] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[13:45:28.716] INFO: number of red-efficiency pixels: 205 117 238 434 408 368 433 210 268 494 361 344 339 158 44 45
[13:45:28.716] INFO: number of X-ray hits detected: 122622 82506 127065 199263 209332 219714 209613 137671 153869 212043 203638 180628 183011 109609 41852 49826
[13:45:28.716] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:45:28.716] INFO: number of Vcal hits detected: 207775 207880 207745 207518 207543 207601 207524 207775 207715 207475 207608 207637 207642 207833 207956 207954
[13:45:28.716] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[13:45:28.716] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.7 99.8 99.8 99.8 99.9 100.0 100.0
[13:45:28.716] INFO: X-ray hit rate [MHz/cm2]: 35.9 24.2 37.2 58.4 61.4 64.4 61.4 40.4 45.1 62.2 59.7 52.9 53.6 32.1 12.3 14.6
[13:45:28.716] INFO: PixTestHighRate::doXPixelAlive() done
[13:45:28.762] INFO: PixTest:: pg_setup set to default.
[13:45:28.773] INFO: enter test to run
[13:46:03.506] INFO: test: HighRate no parameter change
[13:46:03.507] INFO: running: highrate
[13:46:03.508] INFO: ----------------------------------------------------------------------
[13:46:03.508] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:46:03.508] INFO: ----------------------------------------------------------------------
[13:46:04.129] INFO: Expecting 208000 events.
[13:46:19.309] INFO: 208000 events read in total (14653ms).
[13:46:19.316] INFO: Test took 15797ms.
[13:46:19.746] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:46:20.090] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[13:46:20.090] INFO: number of red-efficiency pixels: 444 218 553 940 1003 932 1025 428 588 1086 883 774 773 333 68 87
[13:46:20.090] INFO: number of X-ray hits detected: 183302 123169 191750 299269 314896 328524 313548 207051 229657 318152 304159 268538 273855 163979 63106 76157
[13:46:20.090] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:46:20.090] INFO: number of Vcal hits detected: 207475 207767 207316 206893 206781 206869 206739 207502 207333 206611 206944 207058 207079 207630 207930 207911
[13:46:20.090] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.5 99.5 99.5 99.5 99.8 99.7 99.4 99.5 99.6 99.6 99.8 100.0 100.0
[13:46:20.090] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.7 99.5 99.4 99.5 99.4 99.8 99.7 99.3 99.5 99.5 99.6 99.8 100.0 100.0
[13:46:20.090] INFO: X-ray hit rate [MHz/cm2]: 53.7 36.1 56.2 87.7 92.3 96.3 91.9 60.7 67.3 93.3 89.2 78.7 80.3 48.1 18.5 22.3
[13:46:20.090] INFO: PixTestHighRate::doXPixelAlive() done
[13:46:20.135] INFO: PixTest:: pg_setup set to default.
[13:46:20.154] INFO: enter test to run
[13:46:45.018] INFO: test: exit no parameter change
[13:46:45.366] QUIET: Connection to board 33 closed.
[13:46:45.374] INFO: pXar: this is the end, my friend