(11:04 AM) [gfx@gfx-desktop] [tests]$ : sudo -E ./perf --r oa-exponents --d
IGT-Version: 1.19-g490b386 (x86_64) (Linux: 4.13.0-drm-tip-ww36-commit-59fbfaa+ x86_64)
(perf:1455) igt-core-DEBUG: Test requirement passed: !igt_run_in_simulation()
(perf:1455) DEBUG: Test requirement passed: stat("/proc/sys/dev/i915/perf_stream_paranoid", &sb) == 0
(perf:1455) DEBUG: Test requirement passed: stat("/proc/sys/dev/i915/oa_max_sample_rate", &sb) == 0
(perf:1455) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'
(perf:1455) DEBUG: TestOa metric set UUID = baa3c7e4-52b6-4b85-801e-465a94b746dd
(perf:1455) DEBUG: Test requirement passed: init_sys_info()
(perf:1455) DEBUG: Test requirement passed: render_copy
(perf:1455) igt-core-DEBUG: Starting subtest: oa-exponents
(perf:1455) DEBUG: requesting pinned GT freq = 450mhz
(perf:1455) DEBUG: Testing OA timer exponents with requested GT frequency = 450mhz
(perf:1455) DEBUG: ITER 0: testing OA exponent 5 (period = 5333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b031d60, exponent mask=3f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b031da0, exponent mask=3f
(perf:1455) DEBUG: ITER 0: time delta = 5333(ns) clock delta = 2390 freq = 448(mhz)
(perf:1455) DEBUG: ITER 1: testing OA exponent 5 (period = 5333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b070160, exponent mask=3f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b0701a0, exponent mask=3f
(perf:1455) DEBUG: ITER 1: time delta = 5333(ns) clock delta = 2390 freq = 448(mhz)
(perf:1455) DEBUG: ITER 2: testing OA exponent 5 (period = 5333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b0914a0, exponent mask=3f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b0914e0, exponent mask=3f
(perf:1455) DEBUG: ITER 2: time delta = 5333(ns) clock delta = 2394 freq = 448(mhz)
(perf:1455) DEBUG: ITER 3: testing OA exponent 5 (period = 5333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b0c5aa0, exponent mask=3f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b0c5ae0, exponent mask=3f
(perf:1455) DEBUG: ITER 3: time delta = 5333(ns) clock delta = 2390 freq = 448(mhz)
(perf:1455) DEBUG: ITER 4: testing OA exponent 5 (period = 5333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b0f9160, exponent mask=3f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b0f91a0, exponent mask=3f
(perf:1455) DEBUG: ITER 4: time delta = 5333(ns) clock delta = 2394 freq = 448(mhz)
(perf:1455) DEBUG: ITER 5: testing OA exponent 5 (period = 5333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b131ce0, exponent mask=3f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b131d20, exponent mask=3f
(perf:1455) DEBUG: ITER 5: time delta = 5333(ns) clock delta = 2394 freq = 448(mhz)
(perf:1455) DEBUG: ITER 6: testing OA exponent 5 (period = 5333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b1680e0, exponent mask=3f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b168120, exponent mask=3f
(perf:1455) DEBUG: ITER 6: time delta = 5333(ns) clock delta = 2389 freq = 447(mhz)
(perf:1455) DEBUG: ITER 7: testing OA exponent 5 (period = 5333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b19fe60, exponent mask=3f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b19fea0, exponent mask=3f
(perf:1455) DEBUG: ITER 7: time delta = 5333(ns) clock delta = 2394 freq = 448(mhz)
(perf:1455) DEBUG: ITER 8: testing OA exponent 5 (period = 5333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b1e3a60, exponent mask=3f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b1e3aa0, exponent mask=3f
(perf:1455) DEBUG: ITER 8: time delta = 5333(ns) clock delta = 2399 freq = 449(mhz)
(perf:1455) DEBUG: ITER 9: testing OA exponent 5 (period = 5333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b21f0e0, exponent mask=3f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b21f120, exponent mask=3f
(perf:1455) DEBUG: ITER 9: time delta = 5333(ns) clock delta = 2390 freq = 448(mhz)
(perf:1455) DEBUG: number of iterations with expected clock frequency = 10
(perf:1455) DEBUG: ITER 0: testing OA exponent 6 (period = 10666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b25a8c0, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b25a940, exponent mask=7f
(perf:1455) DEBUG: ITER 0: time delta = 10666(ns) clock delta = 4792 freq = 449(mhz)
(perf:1455) DEBUG: ITER 1: testing OA exponent 6 (period = 10666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b28a2c0, exponent mask=7f
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b298fc0, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b299040, exponent mask=7f
(perf:1455) DEBUG: ITER 1: time delta = 10666(ns) clock delta = 4793 freq = 449(mhz)
(perf:1455) DEBUG: ITER 2: testing OA exponent 6 (period = 10666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b2da3c0, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b2da440, exponent mask=7f
(perf:1455) DEBUG: ITER 2: time delta = 10666(ns) clock delta = 4793 freq = 449(mhz)
(perf:1455) DEBUG: ITER 3: testing OA exponent 6 (period = 10666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b310840, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b3108c0, exponent mask=7f
(perf:1455) DEBUG: ITER 3: time delta = 10666(ns) clock delta = 4793 freq = 449(mhz)
(perf:1455) DEBUG: ITER 4: testing OA exponent 6 (period = 10666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b344f40, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b344fc0, exponent mask=7f
(perf:1455) DEBUG: ITER 4: time delta = 10666(ns) clock delta = 4784 freq = 448(mhz)
(perf:1455) DEBUG: ITER 5: testing OA exponent 6 (period = 10666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b3782c0, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b378340, exponent mask=7f
(perf:1455) DEBUG: ITER 5: time delta = 10666(ns) clock delta = 4797 freq = 449(mhz)
(perf:1455) DEBUG: ITER 6: testing OA exponent 6 (period = 10666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e881b, timestamp = 5b3b11c0, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b3b1240, exponent mask=7f
(perf:1455) DEBUG: ITER 6: time delta = 10666(ns) clock delta = 4788 freq = 448(mhz)
(perf:1455) DEBUG: ITER 7: testing OA exponent 6 (period = 10666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b3e4ac0, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b3e4b40, exponent mask=7f
(perf:1455) DEBUG: ITER 7: time delta = 10666(ns) clock delta = 4788 freq = 448(mhz)
(perf:1455) DEBUG: ITER 8: testing OA exponent 6 (period = 10666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b4182c0, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b418340, exponent mask=7f
(perf:1455) DEBUG: ITER 8: time delta = 10666(ns) clock delta = 4779 freq = 448(mhz)
(perf:1455) DEBUG: ITER 9: testing OA exponent 6 (period = 10666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b44c5c0, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b44c640, exponent mask=7f
(perf:1455) DEBUG: ITER 9: time delta = 10666(ns) clock delta = 4792 freq = 449(mhz)
(perf:1455) DEBUG: number of iterations with expected clock frequency = 10
(perf:1455) DEBUG: ITER 0: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b471680, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e881b, timestamp = 5b471780, exponent mask=ff
(perf:1455) DEBUG: ITER 0: time delta = 21333(ns) clock delta = 5359 freq = 251(mhz)
(perf:1455) DEBUG: ITER 1: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b4ed880, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b4ed980, exponent mask=ff
(perf:1455) DEBUG: ITER 1: time delta = 21333(ns) clock delta = 9572 freq = 448(mhz)
(perf:1455) DEBUG: ITER 2: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b522a80, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b522b80, exponent mask=ff
(perf:1455) DEBUG: ITER 2: time delta = 21333(ns) clock delta = 9580 freq = 449(mhz)
(perf:1455) DEBUG: ITER 3: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b568f80, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b569080, exponent mask=ff
(perf:1455) DEBUG: ITER 3: time delta = 21333(ns) clock delta = 9580 freq = 449(mhz)
(perf:1455) DEBUG: ITER 4: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b5c6280, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b5c6380, exponent mask=ff
(perf:1455) DEBUG: ITER 4: time delta = 21333(ns) clock delta = 9580 freq = 449(mhz)
(perf:1455) DEBUG: ITER 5: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b5f9580, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b5f9680, exponent mask=ff
(perf:1455) DEBUG: ITER 5: time delta = 21333(ns) clock delta = 9580 freq = 449(mhz)
(perf:1455) DEBUG: ITER 6: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b63a180, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b63a280, exponent mask=ff
(perf:1455) DEBUG: ITER 6: time delta = 21333(ns) clock delta = 9585 freq = 449(mhz)
(perf:1455) DEBUG: ITER 7: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b67b480, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b67b580, exponent mask=ff
(perf:1455) DEBUG: ITER 7: time delta = 21333(ns) clock delta = 9580 freq = 449(mhz)
(perf:1455) DEBUG: ITER 8: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b6d2280, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b6d2380, exponent mask=ff
(perf:1455) DEBUG: ITER 8: time delta = 21333(ns) clock delta = 9585 freq = 449(mhz)
(perf:1455) DEBUG: ITER 9: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b727a80, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b727b80, exponent mask=ff
(perf:1455) DEBUG: ITER 9: time delta = 21333(ns) clock delta = 9580 freq = 449(mhz)
(perf:1455) DEBUG: number of iterations with expected clock frequency = 9
(perf:1455) DEBUG: ITER 0: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b766700, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b766900, exponent mask=1ff
(perf:1455) DEBUG: ITER 0: time delta = 42666(ns) clock delta = 19148 freq = 448(mhz)
(perf:1455) DEBUG: ITER 1: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b7b9100, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b7b9300, exponent mask=1ff
(perf:1455) DEBUG: ITER 1: time delta = 42666(ns) clock delta = 15066 freq = 353(mhz)
(perf:1455) DEBUG: ITER 2: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b808d00, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b808f00, exponent mask=1ff
(perf:1455) DEBUG: ITER 2: time delta = 42666(ns) clock delta = 14994 freq = 351(mhz)
(perf:1455) DEBUG: ITER 3: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b848900, exponent mask=1ff
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b874b00, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b874d00, exponent mask=1ff
(perf:1455) DEBUG: ITER 3: time delta = 42666(ns) clock delta = 19161 freq = 449(mhz)
(perf:1455) DEBUG: ITER 4: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b8b6100, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b8b6300, exponent mask=1ff
(perf:1455) DEBUG: ITER 4: time delta = 42666(ns) clock delta = 19152 freq = 448(mhz)
(perf:1455) DEBUG: ITER 5: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b8f0900, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b8f0b00, exponent mask=1ff
(perf:1455) DEBUG: ITER 5: time delta = 42666(ns) clock delta = 19152 freq = 448(mhz)
(perf:1455) DEBUG: ITER 6: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b94df00, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b94e100, exponent mask=1ff
(perf:1455) DEBUG: ITER 6: time delta = 42666(ns) clock delta = 19152 freq = 448(mhz)
(perf:1455) DEBUG: ITER 7: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b97f100, exponent mask=1ff
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b98df00, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b98e100, exponent mask=1ff
(perf:1455) DEBUG: ITER 7: time delta = 42666(ns) clock delta = 19161 freq = 449(mhz)
(perf:1455) DEBUG: ITER 8: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b9bf500, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b9bf700, exponent mask=1ff
(perf:1455) DEBUG: ITER 8: time delta = 42666(ns) clock delta = 19152 freq = 448(mhz)
(perf:1455) DEBUG: ITER 9: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5ba09100, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5ba09300, exponent mask=1ff
(perf:1455) DEBUG: ITER 9: time delta = 42666(ns) clock delta = 19147 freq = 448(mhz)
(perf:1455) DEBUG: number of iterations with expected clock frequency = 8
(perf:1455) DEBUG: ITER 0: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5ba4f200, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5ba4f600, exponent mask=3ff
(perf:1455) DEBUG: ITER 0: time delta = 85333(ns) clock delta = 38318 freq = 449(mhz)
(perf:1455) DEBUG: ITER 1: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5ba9aa00, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5ba9ae00, exponent mask=3ff
(perf:1455) DEBUG: ITER 1: time delta = 85333(ns) clock delta = 38313 freq = 448(mhz)
(perf:1455) DEBUG: ITER 2: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5baf0200, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5baf0600, exponent mask=3ff
(perf:1455) DEBUG: ITER 2: time delta = 85333(ns) clock delta = 38313 freq = 448(mhz)
(perf:1455) DEBUG: ITER 3: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bb29a00, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bb29e00, exponent mask=3ff
(perf:1455) DEBUG: ITER 3: time delta = 85333(ns) clock delta = 34632 freq = 405(mhz)
(perf:1455) DEBUG: ITER 4: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bb6de00, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bb6e200, exponent mask=3ff
(perf:1455) DEBUG: ITER 4: time delta = 85333(ns) clock delta = 38304 freq = 448(mhz)
(perf:1455) DEBUG: ITER 5: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bbae600, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bbaea00, exponent mask=3ff
(perf:1455) DEBUG: ITER 5: time delta = 85333(ns) clock delta = 38304 freq = 448(mhz)
(perf:1455) DEBUG: ITER 6: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bbe7200, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bbe7600, exponent mask=3ff
(perf:1455) DEBUG: ITER 6: time delta = 85333(ns) clock delta = 34105 freq = 399(mhz)
(perf:1455) DEBUG: ITER 7: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bc1a600, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bc1aa00, exponent mask=3ff
(perf:1455) DEBUG: ITER 7: time delta = 85333(ns) clock delta = 38304 freq = 448(mhz)
(perf:1455) DEBUG: ITER 8: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bc4d200, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bc4d600, exponent mask=3ff
(perf:1455) DEBUG: ITER 8: time delta = 85333(ns) clock delta = 34123 freq = 399(mhz)
(perf:1455) DEBUG: ITER 9: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bc7fe00, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bc80200, exponent mask=3ff
(perf:1455) DEBUG: ITER 9: time delta = 85333(ns) clock delta = 38313 freq = 448(mhz)
(perf:1455) DEBUG: number of iterations with expected clock frequency = 7
(perf:1455) DEBUG: ITER 0: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bcaa400, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bcaac00, exponent mask=7ff
(perf:1455) DEBUG: ITER 0: time delta = 170666(ns) clock delta = 76631 freq = 449(mhz)
(perf:1455) DEBUG: ITER 1: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bcdd400, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bcddc00, exponent mask=7ff
(perf:1455) DEBUG: ITER 1: time delta = 170666(ns) clock delta = 76630 freq = 449(mhz)
(perf:1455) DEBUG: ITER 2: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bd20c00, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bd21400, exponent mask=7ff
(perf:1455) DEBUG: ITER 2: time delta = 170666(ns) clock delta = 76631 freq = 449(mhz)
(perf:1455) DEBUG: ITER 3: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bd6ac00, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bd6b400, exponent mask=7ff
(perf:1455) DEBUG: ITER 3: time delta = 170666(ns) clock delta = 76617 freq = 448(mhz)
(perf:1455) DEBUG: ITER 4: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bdb0400, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bdb0c00, exponent mask=7ff
(perf:1455) DEBUG: ITER 4: time delta = 170666(ns) clock delta = 76617 freq = 448(mhz)
(perf:1455) DEBUG: ITER 5: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bdf6400, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bdf6c00, exponent mask=7ff
(perf:1455) DEBUG: ITER 5: time delta = 170666(ns) clock delta = 76617 freq = 448(mhz)
(perf:1455) DEBUG: ITER 6: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5be3bc00, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5be3c400, exponent mask=7ff
(perf:1455) DEBUG: ITER 6: time delta = 170666(ns) clock delta = 76621 freq = 448(mhz)
(perf:1455) DEBUG: ITER 7: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5be80c00, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5be81400, exponent mask=7ff
(perf:1455) DEBUG: ITER 7: time delta = 170666(ns) clock delta = 76621 freq = 448(mhz)
(perf:1455) DEBUG: ITER 8: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bec6400, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bec6c00, exponent mask=7ff
(perf:1455) DEBUG: ITER 8: time delta = 170666(ns) clock delta = 76626 freq = 448(mhz)
(perf:1455) DEBUG: ITER 9: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bf10c55, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bf11400, exponent mask=7ff
(perf:1455) DEBUG: timestamp0 = 1542523989/0x5bf10c55
(perf:1455) DEBUG: timestamp1 = 1542525952/0x5bf11400
(perf:1455) CRITICAL: Test assertion failure function test_oa_exponents, file perf.c:1482:
(perf:1455) CRITICAL: Failed assertion: timestamp_delta == expected_timestamp_delta
(perf:1455) CRITICAL: error: 1963 != 2048
Stack trace:
  #0 [__igt_fail_assert+0x101]
  #1 [test_oa_exponents+0x35d]
  #2 [<unknown>+0x35d]
Subtest oa-exponents failed.
**** DEBUG ****
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b298fc0, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b299040, exponent mask=7f
(perf:1455) DEBUG: ITER 1: time delta = 10666(ns) clock delta = 4793 freq = 449(mhz)
(perf:1455) DEBUG: ITER 2: testing OA exponent 6 (period = 10666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b2da3c0, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b2da440, exponent mask=7f
(perf:1455) DEBUG: ITER 2: time delta = 10666(ns) clock delta = 4793 freq = 449(mhz)
(perf:1455) DEBUG: ITER 3: testing OA exponent 6 (period = 10666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b310840, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b3108c0, exponent mask=7f
(perf:1455) DEBUG: ITER 3: time delta = 10666(ns) clock delta = 4793 freq = 449(mhz)
(perf:1455) DEBUG: ITER 4: testing OA exponent 6 (period = 10666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b344f40, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b344fc0, exponent mask=7f
(perf:1455) DEBUG: ITER 4: time delta = 10666(ns) clock delta = 4784 freq = 448(mhz)
(perf:1455) DEBUG: ITER 5: testing OA exponent 6 (period = 10666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b3782c0, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b378340, exponent mask=7f
(perf:1455) DEBUG: ITER 5: time delta = 10666(ns) clock delta = 4797 freq = 449(mhz)
(perf:1455) DEBUG: ITER 6: testing OA exponent 6 (period = 10666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e881b, timestamp = 5b3b11c0, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b3b1240, exponent mask=7f
(perf:1455) DEBUG: ITER 6: time delta = 10666(ns) clock delta = 4788 freq = 448(mhz)
(perf:1455) DEBUG: ITER 7: testing OA exponent 6 (period = 10666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b3e4ac0, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b3e4b40, exponent mask=7f
(perf:1455) DEBUG: ITER 7: time delta = 10666(ns) clock delta = 4788 freq = 448(mhz)
(perf:1455) DEBUG: ITER 8: testing OA exponent 6 (period = 10666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b4182c0, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b418340, exponent mask=7f
(perf:1455) DEBUG: ITER 8: time delta = 10666(ns) clock delta = 4779 freq = 448(mhz)
(perf:1455) DEBUG: ITER 9: testing OA exponent 6 (period = 10666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b44c5c0, exponent mask=7f
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b44c640, exponent mask=7f
(perf:1455) DEBUG: ITER 9: time delta = 10666(ns) clock delta = 4792 freq = 449(mhz)
(perf:1455) DEBUG: number of iterations with expected clock frequency = 10
(perf:1455) DEBUG: ITER 0: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b471680, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e881b, timestamp = 5b471780, exponent mask=ff
(perf:1455) DEBUG: ITER 0: time delta = 21333(ns) clock delta = 5359 freq = 251(mhz)
(perf:1455) DEBUG: ITER 1: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b4ed880, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b4ed980, exponent mask=ff
(perf:1455) DEBUG: ITER 1: time delta = 21333(ns) clock delta = 9572 freq = 448(mhz)
(perf:1455) DEBUG: ITER 2: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b522a80, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b522b80, exponent mask=ff
(perf:1455) DEBUG: ITER 2: time delta = 21333(ns) clock delta = 9580 freq = 449(mhz)
(perf:1455) DEBUG: ITER 3: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b568f80, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b569080, exponent mask=ff
(perf:1455) DEBUG: ITER 3: time delta = 21333(ns) clock delta = 9580 freq = 449(mhz)
(perf:1455) DEBUG: ITER 4: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b5c6280, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b5c6380, exponent mask=ff
(perf:1455) DEBUG: ITER 4: time delta = 21333(ns) clock delta = 9580 freq = 449(mhz)
(perf:1455) DEBUG: ITER 5: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b5f9580, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b5f9680, exponent mask=ff
(perf:1455) DEBUG: ITER 5: time delta = 21333(ns) clock delta = 9580 freq = 449(mhz)
(perf:1455) DEBUG: ITER 6: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b63a180, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b63a280, exponent mask=ff
(perf:1455) DEBUG: ITER 6: time delta = 21333(ns) clock delta = 9585 freq = 449(mhz)
(perf:1455) DEBUG: ITER 7: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b67b480, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b67b580, exponent mask=ff
(perf:1455) DEBUG: ITER 7: time delta = 21333(ns) clock delta = 9580 freq = 449(mhz)
(perf:1455) DEBUG: ITER 8: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b6d2280, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b6d2380, exponent mask=ff
(perf:1455) DEBUG: ITER 8: time delta = 21333(ns) clock delta = 9585 freq = 449(mhz)
(perf:1455) DEBUG: ITER 9: testing OA exponent 7 (period = 21333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b727a80, exponent mask=ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b727b80, exponent mask=ff
(perf:1455) DEBUG: ITER 9: time delta = 21333(ns) clock delta = 9580 freq = 449(mhz)
(perf:1455) DEBUG: number of iterations with expected clock frequency = 9
(perf:1455) DEBUG: ITER 0: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b766700, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b766900, exponent mask=1ff
(perf:1455) DEBUG: ITER 0: time delta = 42666(ns) clock delta = 19148 freq = 448(mhz)
(perf:1455) DEBUG: ITER 1: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b7b9100, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b7b9300, exponent mask=1ff
(perf:1455) DEBUG: ITER 1: time delta = 42666(ns) clock delta = 15066 freq = 353(mhz)
(perf:1455) DEBUG: ITER 2: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b808d00, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b808f00, exponent mask=1ff
(perf:1455) DEBUG: ITER 2: time delta = 42666(ns) clock delta = 14994 freq = 351(mhz)
(perf:1455) DEBUG: ITER 3: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b848900, exponent mask=1ff
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b874b00, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b874d00, exponent mask=1ff
(perf:1455) DEBUG: ITER 3: time delta = 42666(ns) clock delta = 19161 freq = 449(mhz)
(perf:1455) DEBUG: ITER 4: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b8b6100, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b8b6300, exponent mask=1ff
(perf:1455) DEBUG: ITER 4: time delta = 42666(ns) clock delta = 19152 freq = 448(mhz)
(perf:1455) DEBUG: ITER 5: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b8f0900, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b8f0b00, exponent mask=1ff
(perf:1455) DEBUG: ITER 5: time delta = 42666(ns) clock delta = 19152 freq = 448(mhz)
(perf:1455) DEBUG: ITER 6: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b94df00, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b94e100, exponent mask=1ff
(perf:1455) DEBUG: ITER 6: time delta = 42666(ns) clock delta = 19152 freq = 448(mhz)
(perf:1455) DEBUG: ITER 7: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b97f100, exponent mask=1ff
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b98df00, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b98e100, exponent mask=1ff
(perf:1455) DEBUG: ITER 7: time delta = 42666(ns) clock delta = 19161 freq = 449(mhz)
(perf:1455) DEBUG: ITER 8: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b9bf500, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5b9bf700, exponent mask=1ff
(perf:1455) DEBUG: ITER 8: time delta = 42666(ns) clock delta = 19152 freq = 448(mhz)
(perf:1455) DEBUG: ITER 9: testing OA exponent 8 (period = 42666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5ba09100, exponent mask=1ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5ba09300, exponent mask=1ff
(perf:1455) DEBUG: ITER 9: time delta = 42666(ns) clock delta = 19147 freq = 448(mhz)
(perf:1455) DEBUG: number of iterations with expected clock frequency = 8
(perf:1455) DEBUG: ITER 0: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5ba4f200, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5ba4f600, exponent mask=3ff
(perf:1455) DEBUG: ITER 0: time delta = 85333(ns) clock delta = 38318 freq = 449(mhz)
(perf:1455) DEBUG: ITER 1: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5ba9aa00, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5ba9ae00, exponent mask=3ff
(perf:1455) DEBUG: ITER 1: time delta = 85333(ns) clock delta = 38313 freq = 448(mhz)
(perf:1455) DEBUG: ITER 2: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5baf0200, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5baf0600, exponent mask=3ff
(perf:1455) DEBUG: ITER 2: time delta = 85333(ns) clock delta = 38313 freq = 448(mhz)
(perf:1455) DEBUG: ITER 3: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bb29a00, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bb29e00, exponent mask=3ff
(perf:1455) DEBUG: ITER 3: time delta = 85333(ns) clock delta = 34632 freq = 405(mhz)
(perf:1455) DEBUG: ITER 4: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bb6de00, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bb6e200, exponent mask=3ff
(perf:1455) DEBUG: ITER 4: time delta = 85333(ns) clock delta = 38304 freq = 448(mhz)
(perf:1455) DEBUG: ITER 5: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bbae600, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bbaea00, exponent mask=3ff
(perf:1455) DEBUG: ITER 5: time delta = 85333(ns) clock delta = 38304 freq = 448(mhz)
(perf:1455) DEBUG: ITER 6: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bbe7200, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bbe7600, exponent mask=3ff
(perf:1455) DEBUG: ITER 6: time delta = 85333(ns) clock delta = 34105 freq = 399(mhz)
(perf:1455) DEBUG: ITER 7: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bc1a600, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bc1aa00, exponent mask=3ff
(perf:1455) DEBUG: ITER 7: time delta = 85333(ns) clock delta = 38304 freq = 448(mhz)
(perf:1455) DEBUG: ITER 8: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bc4d200, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bc4d600, exponent mask=3ff
(perf:1455) DEBUG: ITER 8: time delta = 85333(ns) clock delta = 34123 freq = 399(mhz)
(perf:1455) DEBUG: ITER 9: testing OA exponent 9 (period = 85333ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bc7fe00, exponent mask=3ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bc80200, exponent mask=3ff
(perf:1455) DEBUG: ITER 9: time delta = 85333(ns) clock delta = 38313 freq = 448(mhz)
(perf:1455) DEBUG: number of iterations with expected clock frequency = 7
(perf:1455) DEBUG: ITER 0: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bcaa400, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bcaac00, exponent mask=7ff
(perf:1455) DEBUG: ITER 0: time delta = 170666(ns) clock delta = 76631 freq = 449(mhz)
(perf:1455) DEBUG: ITER 1: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bcdd400, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bcddc00, exponent mask=7ff
(perf:1455) DEBUG: ITER 1: time delta = 170666(ns) clock delta = 76630 freq = 449(mhz)
(perf:1455) DEBUG: ITER 2: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read restart: OA trigger collision / report lost
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bd20c00, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bd21400, exponent mask=7ff
(perf:1455) DEBUG: ITER 2: time delta = 170666(ns) clock delta = 76631 freq = 449(mhz)
(perf:1455) DEBUG: ITER 3: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bd6ac00, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bd6b400, exponent mask=7ff
(perf:1455) DEBUG: ITER 3: time delta = 170666(ns) clock delta = 76617 freq = 448(mhz)
(perf:1455) DEBUG: ITER 4: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bdb0400, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bdb0c00, exponent mask=7ff
(perf:1455) DEBUG: ITER 4: time delta = 170666(ns) clock delta = 76617 freq = 448(mhz)
(perf:1455) DEBUG: ITER 5: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bdf6400, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bdf6c00, exponent mask=7ff
(perf:1455) DEBUG: ITER 5: time delta = 170666(ns) clock delta = 76617 freq = 448(mhz)
(perf:1455) DEBUG: ITER 6: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5be3bc00, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5be3c400, exponent mask=7ff
(perf:1455) DEBUG: ITER 6: time delta = 170666(ns) clock delta = 76621 freq = 448(mhz)
(perf:1455) DEBUG: ITER 7: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5be80c00, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5be81400, exponent mask=7ff
(perf:1455) DEBUG: ITER 7: time delta = 170666(ns) clock delta = 76621 freq = 448(mhz)
(perf:1455) DEBUG: ITER 8: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bec6400, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bec6c00, exponent mask=7ff
(perf:1455) DEBUG: ITER 8: time delta = 170666(ns) clock delta = 76626 freq = 448(mhz)
(perf:1455) DEBUG: ITER 9: testing OA exponent 10 (period = 170666ns) with sysfs GT freq = 450mhz +- 45
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bf10c55, exponent mask=7ff
(perf:1455) DEBUG: read report: reason = 360e801b, timestamp = 5bf11400, exponent mask=7ff
(perf:1455) DEBUG: timestamp0 = 1542523989/0x5bf10c55
(perf:1455) DEBUG: timestamp1 = 1542525952/0x5bf11400
(perf:1455) CRITICAL: Test assertion failure function test_oa_exponents, file perf.c:1482:
(perf:1455) CRITICAL: Failed assertion: timestamp_delta == expected_timestamp_delta
(perf:1455) CRITICAL: error: 1963 != 2048
(perf:1455) igt-core-INFO: Stack trace:
(perf:1455) igt-core-INFO:   #0 [__igt_fail_assert+0x101]
(perf:1455) igt-core-INFO:   #1 [test_oa_exponents+0x35d]
(perf:1455) igt-core-INFO:   #2 [<unknown>+0x35d]
****  END  ****
Subtest oa-exponents: FAIL (1.325s)
(perf:1455) DEBUG: restoring GT frequency range: min = 300mhz, max =1050mhz, current: min=450mhz, max=450mhz
(perf:1455) igt-core-DEBUG: Exiting with status code 99
(perf:1455) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'