Machine description: shard-mtlp-1
Result:
integration-manifest git-log-oneline i915_display_info16 igt_runner16 run16 runtimes16 results16.json boot16 dmesg16
Detail | Value |
---|---|
Duration | 9.25 seconds |
Hostname |
shard-mtlp-1 |
Igt-Version |
IGT-Version: 1.29-NO-GIT (x86_64) (Linux: 6.12.0-rc2-CI_DRM_15491-gc2c031e80da1+ x86_64) |
Out |
Using IGT_SRANDOM=1728498520 for randomisation Opened device: /dev/dri/card0 Using monotonic timestamps Starting subtest: plain-flip-ts-check-interruptible Starting dynamic subtest: A-eDP1 2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa Expected frametime: 11111us; measured 11111.4us +- 2.680us accuracy 0.07% Stack trace: #0 ../lib/igt_core.c:2051 __igt_fail_assert() #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1845 run_test() #3 ../tests/kms_flip.c:2114 __igt_unique____real_main2001() #4 ../tests/kms_flip.c:2001 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest A-eDP1: FAIL (9.248s) |
Err |
Starting subtest: plain-flip-ts-check-interruptible Starting dynamic subtest: A-eDP1 (kms_flip:1318) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674: (kms_flip:1318) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon) (kms_flip:1318) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest A-eDP1 failed. **** DEBUG **** (kms_flip:1318) DEBUG: name = flip last_ts = 45.112427 last_received_ts = 45.112366 last_seq = 3001 current_ts = 45.123535 current_received_ts = 45.123569 current_seq = 3002 count = 318 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.112427/3001, current 45.123535/3002: elapsed=11109.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.123535 last_received_ts = 45.123569 last_seq = 3002 current_ts = 45.134647 current_received_ts = 45.134720 current_seq = 3003 count = 319 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.123535/3002, current 45.134647/3003: elapsed=11114.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.134647 last_received_ts = 45.134720 last_seq = 3003 current_ts = 45.145763 current_received_ts = 45.145855 current_seq = 3004 count = 320 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.134647/3003, current 45.145763/3004: elapsed=11113.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.145763 last_received_ts = 45.145855 last_seq = 3004 current_ts = 45.156872 current_received_ts = 45.156658 current_seq = 3005 count = 321 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.145763/3004, current 45.156872/3005: elapsed=11109.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.156872 last_received_ts = 45.156658 last_seq = 3005 current_ts = 45.167980 current_received_ts = 45.168152 current_seq = 3006 count = 322 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.156872/3005, current 45.167980/3006: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.167980 last_received_ts = 45.168152 last_seq = 3006 current_ts = 45.179096 current_received_ts = 45.179199 current_seq = 3007 count = 323 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.167980/3006, current 45.179096/3007: elapsed=11113.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.179096 last_received_ts = 45.179199 last_seq = 3007 current_ts = 45.190205 current_received_ts = 45.190102 current_seq = 3008 count = 324 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.179096/3007, current 45.190205/3008: elapsed=11110.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.190205 last_received_ts = 45.190102 last_seq = 3008 current_ts = 45.201313 current_received_ts = 45.201401 current_seq = 3009 count = 325 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.190205/3008, current 45.201313/3009: elapsed=11109.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.201313 last_received_ts = 45.201401 last_seq = 3009 current_ts = 45.212429 current_received_ts = 45.212566 current_seq = 3010 count = 326 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.201313/3009, current 45.212429/3010: elapsed=11114.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.212429 last_received_ts = 45.212566 last_seq = 3010 current_ts = 45.223534 current_received_ts = 45.223671 current_seq = 3011 count = 327 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.212429/3010, current 45.223534/3011: elapsed=11106.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.223534 last_received_ts = 45.223671 last_seq = 3011 current_ts = 45.234650 current_received_ts = 45.234749 current_seq = 3012 count = 328 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.223534/3011, current 45.234650/3012: elapsed=11115.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.234650 last_received_ts = 45.234749 last_seq = 3012 current_ts = 45.245762 current_received_ts = 45.245640 current_seq = 3013 count = 329 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.234650/3012, current 45.245762/3013: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.245762 last_received_ts = 45.245640 last_seq = 3013 current_ts = 45.256874 current_received_ts = 45.257076 current_seq = 3014 count = 330 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.245762/3013, current 45.256874/3014: elapsed=11113.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.256874 last_received_ts = 45.257076 last_seq = 3014 current_ts = 45.267979 current_received_ts = 45.268066 current_seq = 3015 count = 331 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.256874/3014, current 45.267979/3015: elapsed=11107.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.267979 last_received_ts = 45.268066 last_seq = 3015 current_ts = 45.279091 current_received_ts = 45.279186 current_seq = 3016 count = 332 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.267979/3015, current 45.279091/3016: elapsed=11110.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.279091 last_received_ts = 45.279186 last_seq = 3016 current_ts = 45.290199 current_received_ts = 45.290123 current_seq = 3017 count = 333 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.279091/3016, current 45.290199/3017: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.290199 last_received_ts = 45.290123 last_seq = 3017 current_ts = 45.301319 current_received_ts = 45.301395 current_seq = 3018 count = 334 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.290199/3017, current 45.301319/3018: elapsed=11117.0us expected=11111.4us +- 55.6us, error 0.1% (kms_flip:1318) DEBUG: name = flip last_ts = 45.301319 last_received_ts = 45.301395 last_seq = 3018 current_ts = 45.312424 current_received_ts = 45.312561 current_seq = 3019 count = 335 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.301319/3018, current 45.312424/3019: elapsed=11107.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.312424 last_received_ts = 45.312561 last_seq = 3019 current_ts = 45.323536 current_received_ts = 45.323372 current_seq = 3020 count = 336 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.312424/3019, current 45.323536/3020: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.323536 last_received_ts = 45.323372 last_seq = 3020 current_ts = 45.334644 current_received_ts = 45.334747 current_seq = 3021 count = 337 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.323536/3020, current 45.334644/3021: elapsed=11110.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.334644 last_received_ts = 45.334747 last_seq = 3021 current_ts = 45.345757 current_received_ts = 45.345837 current_seq = 3022 count = 338 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.334644/3021, current 45.345757/3022: elapsed=11112.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.345757 last_received_ts = 45.345837 last_seq = 3022 current_ts = 45.356869 current_received_ts = 45.356960 current_seq = 3023 count = 339 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.345757/3022, current 45.356869/3023: elapsed=11110.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.356869 last_received_ts = 45.356960 last_seq = 3023 current_ts = 45.367985 current_received_ts = 45.367714 current_seq = 3024 count = 340 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.356869/3023, current 45.367985/3024: elapsed=11116.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.367985 last_received_ts = 45.367714 last_seq = 3024 current_ts = 45.379093 current_received_ts = 45.378868 current_seq = 3025 count = 341 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.367985/3024, current 45.379093/3025: elapsed=11109.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.379093 last_received_ts = 45.378868 last_seq = 3025 current_ts = 45.390202 current_received_ts = 45.390041 current_seq = 3026 count = 342 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.379093/3025, current 45.390202/3026: elapsed=11108.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.390202 last_received_ts = 45.390041 last_seq = 3026 current_ts = 45.401318 current_received_ts = 45.401134 current_seq = 3027 count = 343 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.390202/3026, current 45.401318/3027: elapsed=11115.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.401318 last_received_ts = 45.401134 last_seq = 3027 current_ts = 45.412430 current_received_ts = 45.412537 current_seq = 3028 count = 344 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.401318/3027, current 45.412430/3028: elapsed=11112.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.412430 last_received_ts = 45.412537 last_seq = 3028 current_ts = 45.423538 current_received_ts = 45.423412 current_seq = 3029 count = 345 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.412430/3028, current 45.423538/3029: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.423538 last_received_ts = 45.423412 last_seq = 3029 current_ts = 45.434647 current_received_ts = 45.434769 current_seq = 3030 count = 346 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.423538/3029, current 45.434647/3030: elapsed=11109.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.434647 last_received_ts = 45.434769 last_seq = 3030 current_ts = 45.445759 current_received_ts = 45.445881 current_seq = 3031 count = 347 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.434647/3030, current 45.445759/3031: elapsed=11109.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.445759 last_received_ts = 45.445881 last_seq = 3031 current_ts = 45.456875 current_received_ts = 45.456963 current_seq = 3032 count = 348 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.445759/3031, current 45.456875/3032: elapsed=11116.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.456875 last_received_ts = 45.456963 last_seq = 3032 current_ts = 45.467979 current_received_ts = 45.467911 current_seq = 3033 count = 349 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.456875/3032, current 45.467979/3033: elapsed=11108.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.467979 last_received_ts = 45.467911 last_seq = 3033 current_ts = 45.479095 current_received_ts = 45.479176 current_seq = 3034 count = 350 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.467979/3033, current 45.479095/3034: elapsed=11114.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.479095 last_received_ts = 45.479176 last_seq = 3034 current_ts = 45.490204 current_received_ts = 45.490215 current_seq = 3035 count = 351 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.479095/3034, current 45.490204/3035: elapsed=11107.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.490204 last_received_ts = 45.490215 last_seq = 3035 current_ts = 45.501316 current_received_ts = 45.501247 current_seq = 3036 count = 352 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.490204/3035, current 45.501316/3036: elapsed=11114.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.501316 last_received_ts = 45.501247 last_seq = 3036 current_ts = 45.512424 current_received_ts = 45.512558 current_seq = 3037 count = 353 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.501316/3036, current 45.512424/3037: elapsed=11108.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.512424 last_received_ts = 45.512558 last_seq = 3037 current_ts = 45.523540 current_received_ts = 45.523651 current_seq = 3038 count = 354 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.512424/3037, current 45.523540/3038: elapsed=11115.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.523540 last_received_ts = 45.523651 last_seq = 3038 current_ts = 45.534649 current_received_ts = 45.534512 current_seq = 3039 count = 355 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.523540/3038, current 45.534649/3039: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.534649 last_received_ts = 45.534512 last_seq = 3039 current_ts = 45.545757 current_received_ts = 45.545948 current_seq = 3040 count = 356 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.534649/3039, current 45.545757/3040: elapsed=11109.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.545757 last_received_ts = 45.545948 last_seq = 3040 current_ts = 45.556870 current_received_ts = 45.557076 current_seq = 3041 count = 357 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.545757/3040, current 45.556870/3041: elapsed=11110.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.556870 last_received_ts = 45.557076 last_seq = 3041 current_ts = 45.567986 current_received_ts = 45.567677 current_seq = 3042 count = 358 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.556870/3041, current 45.567986/3042: elapsed=11115.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.567986 last_received_ts = 45.567677 last_seq = 3042 current_ts = 45.579094 current_received_ts = 45.578781 current_seq = 3043 count = 359 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.567986/3042, current 45.579094/3043: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.579094 last_received_ts = 45.578781 last_seq = 3043 current_ts = 45.590206 current_received_ts = 45.589890 current_seq = 3044 count = 360 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.579094/3043, current 45.590206/3044: elapsed=11112.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.590206 last_received_ts = 45.589890 last_seq = 3044 current_ts = 45.601315 current_received_ts = 45.601063 current_seq = 3045 count = 361 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.590206/3044, current 45.601315/3045: elapsed=11109.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.601315 last_received_ts = 45.601063 last_seq = 3045 current_ts = 45.612427 current_received_ts = 45.612133 current_seq = 3046 count = 362 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.601315/3045, current 45.612427/3046: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.612427 last_received_ts = 45.612133 last_seq = 3046 current_ts = 45.623535 current_received_ts = 45.623341 current_seq = 3047 count = 363 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.612427/3046, current 45.623535/3047: elapsed=11108.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.623535 last_received_ts = 45.623341 last_seq = 3047 current_ts = 45.634651 current_received_ts = 45.634491 current_seq = 3048 count = 364 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.623535/3047, current 45.634651/3048: elapsed=11116.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.634651 last_received_ts = 45.634491 last_seq = 3048 current_ts = 45.645763 current_received_ts = 45.645580 current_seq = 3049 count = 365 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.634651/3048, current 45.645763/3049: elapsed=11112.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.645763 last_received_ts = 45.645580 last_seq = 3049 current_ts = 45.656868 current_received_ts = 45.656704 current_seq = 3050 count = 366 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.645763/3049, current 45.656868/3050: elapsed=11106.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.656868 last_received_ts = 45.656704 last_seq = 3050 current_ts = 45.667984 current_received_ts = 45.667812 current_seq = 3051 count = 367 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.656868/3050, current 45.667984/3051: elapsed=11116.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.667984 last_received_ts = 45.667812 last_seq = 3051 current_ts = 45.679092 current_received_ts = 45.678898 current_seq = 3052 count = 368 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.667984/3051, current 45.679092/3052: elapsed=11107.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.679092 last_received_ts = 45.678898 last_seq = 3052 current_ts = 45.690205 current_received_ts = 45.690048 current_seq = 3053 count = 369 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.679092/3052, current 45.690205/3053: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.690205 last_received_ts = 45.690048 last_seq = 3053 current_ts = 45.701317 current_received_ts = 45.701157 current_seq = 3054 count = 370 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.690205/3053, current 45.701317/3054: elapsed=11112.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.701317 last_received_ts = 45.701157 last_seq = 3054 current_ts = 45.712425 current_received_ts = 45.712227 current_seq = 3055 count = 371 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.701317/3054, current 45.712425/3055: elapsed=11112.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.712425 last_received_ts = 45.712227 last_seq = 3055 current_ts = 45.723537 current_received_ts = 45.723389 current_seq = 3056 count = 372 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.712425/3055, current 45.723537/3056: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.723537 last_received_ts = 45.723389 last_seq = 3056 current_ts = 45.734650 current_received_ts = 45.734367 current_seq = 3057 count = 373 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.723537/3056, current 45.734650/3057: elapsed=11112.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.734650 last_received_ts = 45.734367 last_seq = 3057 current_ts = 45.745762 current_received_ts = 45.745468 current_seq = 3058 count = 374 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.734650/3057, current 45.745762/3058: elapsed=11110.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.745762 last_received_ts = 45.745468 last_seq = 3058 current_ts = 45.756874 current_received_ts = 45.756618 current_seq = 3059 count = 375 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.745762/3058, current 45.756874/3059: elapsed=11114.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.756874 last_received_ts = 45.756618 last_seq = 3059 current_ts = 45.767982 current_received_ts = 45.767689 current_seq = 3060 count = 376 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.756874/3059, current 45.767982/3060: elapsed=11110.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.767982 last_received_ts = 45.767689 last_seq = 3060 current_ts = 45.779091 current_received_ts = 45.778797 current_seq = 3061 count = 377 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.767982/3060, current 45.779091/3061: elapsed=11108.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.779091 last_received_ts = 45.778797 last_seq = 3061 current_ts = 45.790203 current_received_ts = 45.789928 current_seq = 3062 count = 378 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.779091/3061, current 45.790203/3062: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.790203 last_received_ts = 45.789928 last_seq = 3062 current_ts = 45.801315 current_received_ts = 45.801033 current_seq = 3063 count = 379 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.790203/3062, current 45.801315/3063: elapsed=11112.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.801315 last_received_ts = 45.801033 last_seq = 3063 current_ts = 45.812424 current_received_ts = 45.812160 current_seq = 3064 count = 380 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.801315/3063, current 45.812424/3064: elapsed=11110.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.812424 last_received_ts = 45.812160 last_seq = 3064 current_ts = 45.823540 current_received_ts = 45.823219 current_seq = 3065 count = 381 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.812424/3064, current 45.823540/3065: elapsed=11113.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.823540 last_received_ts = 45.823219 last_seq = 3065 current_ts = 45.834648 current_received_ts = 45.834328 current_seq = 3066 count = 382 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.823540/3065, current 45.834648/3066: elapsed=11110.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.834648 last_received_ts = 45.834328 last_seq = 3066 current_ts = 45.845760 current_received_ts = 45.845482 current_seq = 3067 count = 383 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.834648/3066, current 45.845760/3067: elapsed=11114.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.845760 last_received_ts = 45.845482 last_seq = 3067 current_ts = 45.856876 current_received_ts = 45.856590 current_seq = 3068 count = 384 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.845760/3067, current 45.856876/3068: elapsed=11113.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.856876 last_received_ts = 45.856590 last_seq = 3068 current_ts = 45.867981 current_received_ts = 45.867664 current_seq = 3069 count = 385 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.856876/3068, current 45.867981/3069: elapsed=11107.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.867981 last_received_ts = 45.867664 last_seq = 3069 current_ts = 45.879093 current_received_ts = 45.878819 current_seq = 3070 count = 386 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.867981/3069, current 45.879093/3070: elapsed=11113.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.879093 last_received_ts = 45.878819 last_seq = 3070 current_ts = 45.890209 current_received_ts = 45.889893 current_seq = 3071 count = 387 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.879093/3070, current 45.890209/3071: elapsed=11113.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.890209 last_received_ts = 45.889893 last_seq = 3071 current_ts = 45.901318 current_received_ts = 45.901031 current_seq = 3072 count = 388 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.890209/3071, current 45.901318/3072: elapsed=11109.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.901318 last_received_ts = 45.901031 last_seq = 3072 current_ts = 45.912426 current_received_ts = 45.912106 current_seq = 3073 count = 389 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.901318/3072, current 45.912426/3073: elapsed=11108.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.912426 last_received_ts = 45.912106 last_seq = 3073 current_ts = 45.923542 current_received_ts = 45.923214 current_seq = 3074 count = 390 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.912426/3073, current 45.923542/3074: elapsed=11116.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.923542 last_received_ts = 45.923214 last_seq = 3074 current_ts = 45.934650 current_received_ts = 45.934380 current_seq = 3075 count = 391 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.923542/3074, current 45.934650/3075: elapsed=11108.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.934650 last_received_ts = 45.934380 last_seq = 3075 current_ts = 45.945759 current_received_ts = 45.945454 current_seq = 3076 count = 392 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.934650/3075, current 45.945759/3076: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.945759 last_received_ts = 45.945454 last_seq = 3076 current_ts = 45.956875 current_received_ts = 45.956570 current_seq = 3077 count = 393 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.945759/3076, current 45.956875/3077: elapsed=11115.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.956875 last_received_ts = 45.956570 last_seq = 3077 current_ts = 45.967979 current_received_ts = 45.967670 current_seq = 3078 count = 394 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.956875/3077, current 45.967979/3078: elapsed=11106.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.967979 last_received_ts = 45.967670 last_seq = 3078 current_ts = 45.979095 current_received_ts = 45.978779 current_seq = 3079 count = 395 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.967979/3078, current 45.979095/3079: elapsed=11115.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.979095 last_received_ts = 45.978779 last_seq = 3079 current_ts = 45.990208 current_received_ts = 45.989937 current_seq = 3080 count = 396 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.979095/3079, current 45.990208/3080: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 45.990208 last_received_ts = 45.989937 last_seq = 3080 current_ts = 46.001320 current_received_ts = 46.001038 current_seq = 3081 count = 397 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 45.990208/3080, current 46.001320/3081: elapsed=11112.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.001320 last_received_ts = 46.001038 last_seq = 3081 current_ts = 46.012428 current_received_ts = 46.012119 current_seq = 3082 count = 398 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.001320/3081, current 46.012428/3082: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.012428 last_received_ts = 46.012119 last_seq = 3082 current_ts = 46.023540 current_received_ts = 46.023232 current_seq = 3083 count = 399 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.012428/3082, current 46.023540/3083: elapsed=11112.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.023540 last_received_ts = 46.023232 last_seq = 3083 current_ts = 46.034649 current_received_ts = 46.034336 current_seq = 3084 count = 400 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.023540/3083, current 46.034649/3084: elapsed=11107.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.034649 last_received_ts = 46.034336 last_seq = 3084 current_ts = 46.045757 current_received_ts = 46.045448 current_seq = 3085 count = 401 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.034649/3084, current 46.045757/3085: elapsed=11110.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.045757 last_received_ts = 46.045448 last_seq = 3085 current_ts = 46.056870 current_received_ts = 46.056553 current_seq = 3086 count = 402 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.045757/3085, current 46.056870/3086: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.056870 last_received_ts = 46.056553 last_seq = 3086 current_ts = 46.067982 current_received_ts = 46.067642 current_seq = 3087 count = 403 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.056870/3086, current 46.067982/3087: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.067982 last_received_ts = 46.067642 last_seq = 3087 current_ts = 46.079094 current_received_ts = 46.078773 current_seq = 3088 count = 404 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.067982/3087, current 46.079094/3088: elapsed=11114.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.079094 last_received_ts = 46.078773 last_seq = 3088 current_ts = 46.090210 current_received_ts = 46.089890 current_seq = 3089 count = 405 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.079094/3088, current 46.090210/3089: elapsed=11114.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.090210 last_received_ts = 46.089890 last_seq = 3089 current_ts = 46.101315 current_received_ts = 46.101044 current_seq = 3090 count = 406 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.090210/3089, current 46.101315/3090: elapsed=11107.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.101315 last_received_ts = 46.101044 last_seq = 3090 current_ts = 46.112427 current_received_ts = 46.112141 current_seq = 3091 count = 407 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.101315/3090, current 46.112427/3091: elapsed=11110.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.112427 last_received_ts = 46.112141 last_seq = 3091 current_ts = 46.123543 current_received_ts = 46.123222 current_seq = 3092 count = 408 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.112427/3091, current 46.123543/3092: elapsed=11115.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.123543 last_received_ts = 46.123222 last_seq = 3092 current_ts = 46.134651 current_received_ts = 46.134338 current_seq = 3093 count = 409 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.123543/3092, current 46.134651/3093: elapsed=11109.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.134651 last_received_ts = 46.134338 last_seq = 3093 current_ts = 46.145763 current_received_ts = 46.145451 current_seq = 3094 count = 410 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.134651/3093, current 46.145763/3094: elapsed=11113.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.145763 last_received_ts = 46.145451 last_seq = 3094 current_ts = 46.156872 current_received_ts = 46.156563 current_seq = 3095 count = 411 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.145763/3094, current 46.156872/3095: elapsed=11108.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.156872 last_received_ts = 46.156563 last_seq = 3095 current_ts = 46.167980 current_received_ts = 46.167679 current_seq = 3096 count = 412 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.156872/3095, current 46.167980/3096: elapsed=11110.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.167980 last_received_ts = 46.167679 last_seq = 3096 current_ts = 46.179092 current_received_ts = 46.178787 current_seq = 3097 count = 413 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.167980/3096, current 46.179092/3097: elapsed=11113.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.179092 last_received_ts = 46.178787 last_seq = 3097 current_ts = 46.190205 current_received_ts = 46.189884 current_seq = 3098 count = 414 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.179092/3097, current 46.190205/3098: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.190205 last_received_ts = 46.189884 last_seq = 3098 current_ts = 46.201321 current_received_ts = 46.201035 current_seq = 3099 count = 415 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.190205/3098, current 46.201321/3099: elapsed=11114.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.201321 last_received_ts = 46.201035 last_seq = 3099 current_ts = 46.212433 current_received_ts = 46.212112 current_seq = 3100 count = 416 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.201321/3099, current 46.212433/3100: elapsed=11112.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.212433 last_received_ts = 46.212112 last_seq = 3100 current_ts = 46.223537 current_received_ts = 46.223225 current_seq = 3101 count = 417 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.212433/3100, current 46.223537/3101: elapsed=11106.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.223537 last_received_ts = 46.223225 last_seq = 3101 current_ts = 46.234650 current_received_ts = 46.234333 current_seq = 3102 count = 418 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.223537/3101, current 46.234650/3102: elapsed=11112.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.234650 last_received_ts = 46.234333 last_seq = 3102 current_ts = 46.245766 current_received_ts = 46.245445 current_seq = 3103 count = 419 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.234650/3102, current 46.245766/3103: elapsed=11116.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.245766 last_received_ts = 46.245445 last_seq = 3103 current_ts = 46.256874 current_received_ts = 46.256557 current_seq = 3104 count = 420 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.245766/3103, current 46.256874/3104: elapsed=11109.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.256874 last_received_ts = 46.256557 last_seq = 3104 current_ts = 46.267986 current_received_ts = 46.267673 current_seq = 3105 count = 421 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.256874/3104, current 46.267986/3105: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.267986 last_received_ts = 46.267673 last_seq = 3105 current_ts = 46.279095 current_received_ts = 46.278801 current_seq = 3106 count = 422 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.267986/3105, current 46.279095/3106: elapsed=11110.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.279095 last_received_ts = 46.278801 last_seq = 3106 current_ts = 46.290207 current_received_ts = 46.289894 current_seq = 3107 count = 423 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.279095/3106, current 46.290207/3107: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.290207 last_received_ts = 46.289894 last_seq = 3107 current_ts = 46.301315 current_received_ts = 46.301025 current_seq = 3108 count = 424 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.290207/3107, current 46.301315/3108: elapsed=11109.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.301315 last_received_ts = 46.301025 last_seq = 3108 current_ts = 46.312428 current_received_ts = 46.312119 current_seq = 3109 count = 425 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.301315/3108, current 46.312428/3109: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.312428 last_received_ts = 46.312119 last_seq = 3109 current_ts = 46.323540 current_received_ts = 46.323238 current_seq = 3110 count = 426 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.312428/3109, current 46.323540/3110: elapsed=11113.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.323540 last_received_ts = 46.323238 last_seq = 3110 current_ts = 46.334652 current_received_ts = 46.334366 current_seq = 3111 count = 427 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.323540/3110, current 46.334652/3111: elapsed=11112.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.334652 last_received_ts = 46.334366 last_seq = 3111 current_ts = 46.345764 current_received_ts = 46.345451 current_seq = 3112 count = 428 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.334652/3111, current 46.345764/3112: elapsed=11112.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.345764 last_received_ts = 46.345451 last_seq = 3112 current_ts = 46.356876 current_received_ts = 46.356552 current_seq = 3113 count = 429 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.345764/3112, current 46.356876/3113: elapsed=11113.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.356876 last_received_ts = 46.356552 last_seq = 3113 current_ts = 46.367981 current_received_ts = 46.367672 current_seq = 3114 count = 430 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.356876/3113, current 46.367981/3114: elapsed=11106.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.367981 last_received_ts = 46.367672 last_seq = 3114 current_ts = 46.379093 current_received_ts = 46.378780 current_seq = 3115 count = 431 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.367981/3114, current 46.379093/3115: elapsed=11113.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.379093 last_received_ts = 46.378780 last_seq = 3115 current_ts = 46.390205 current_received_ts = 46.389885 current_seq = 3116 count = 432 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.379093/3115, current 46.390205/3116: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.390205 last_received_ts = 46.389885 last_seq = 3116 current_ts = 46.401318 current_received_ts = 46.401035 current_seq = 3117 count = 433 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.390205/3116, current 46.401318/3117: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.401318 last_received_ts = 46.401035 last_seq = 3117 current_ts = 46.412434 current_received_ts = 46.412125 current_seq = 3118 count = 434 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.401318/3117, current 46.412434/3118: elapsed=11118.0us expected=11111.4us +- 55.6us, error 0.1% (kms_flip:1318) DEBUG: name = flip last_ts = 46.412434 last_received_ts = 46.412125 last_seq = 3118 current_ts = 46.423542 current_received_ts = 46.423225 current_seq = 3119 count = 435 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.412434/3118, current 46.423542/3119: elapsed=11108.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.423542 last_received_ts = 46.423225 last_seq = 3119 current_ts = 46.434654 current_received_ts = 46.434338 current_seq = 3120 count = 436 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.423542/3119, current 46.434654/3120: elapsed=11111.0us expected=11111.4us +- 55.6us, error 0.0% (kms_flip:1318) DEBUG: name = flip last_ts = 46.434654 last_received_ts = 46.434338 last_seq = 3120 current_ts = 46.445919 current_received_ts = 46.445599 current_seq = 3121 count = 437 seq_step = 1 (kms_flip:1318) DEBUG: flip ts/seq: last 46.434654/3120, current 46.445919/3121: elapsed=11266.0us expected=11111.4us +- 55.6us, error 1.4% (kms_flip:1318) DEBUG: inconsistent flip ts/seq: last 46.434654/3120, current 46.445919/3121: elapsed=11266.0us expected=11111.4us (kms_flip:1318) DEBUG: expected 108, counted 437, encoder type 2 (kms_flip:1318) DEBUG: dropped frames, expected 108, counted 437, encoder type 2 (kms_flip:1318) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674: (kms_flip:1318) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon) (kms_flip:1318) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:1318) igt_core-INFO: Stack trace: (kms_flip:1318) igt_core-INFO: #0 ../lib/igt_core.c:2051 __igt_fail_assert() (kms_flip:1318) igt_core-INFO: #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0() (kms_flip:1318) igt_core-INFO: #2 ../tests/kms_flip.c:1845 run_test() (kms_flip:1318) igt_core-INFO: #3 ../tests/kms_flip.c:2114 __igt_unique____real_main2001() (kms_flip:1318) igt_core-INFO: #4 ../tests/kms_flip.c:2001 main() (kms_flip:1318) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:1318) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:1318) igt_core-INFO: #7 [_start+0x25] **** END **** Dynamic subtest A-eDP1: FAIL (9.248s) |
Dmesg |
<7> [40.112556] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off
<7> [40.112682] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6
<7> [40.112787] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02
<6> [40.124946] Console: switching to colour dummy device 80x25
<6> [40.124978] [IGT] kms_flip: executing
<7> [40.130176] i915 0000:00:02.0: [drm:i915_gem_open [i915]]
<7> [40.131092] i915 0000:00:02.0: [drm:i915_drop_caches_set [i915]] Dropping caches: 0x000001dc [0x000001dc]
<7> [40.149402] i915 0000:00:02.0: [drm:i915_gem_open [i915]]
<7> [40.155430] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:250:DP-1]
<7> [40.155448] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:250:DP-1]
<7> [40.160312] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:250:DP-1] disconnected
<7> [40.160632] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:262:HDMI-A-1]
<7> [40.160635] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:262:HDMI-A-1]
<7> [40.165321] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:262:HDMI-A-1] disconnected
<7> [40.165626] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:268:DP-2]
<7> [40.165629] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:268:DP-2]
<7> [40.165964] i915 0000:00:02.0: [drm:intel_tc_port_update_mode [i915]] Port D/TC#1: TC port mode reset (disconnected -> tbt-alt)
<7> [40.166141] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:268:DP-2] disconnected
<7> [40.166463] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:277:HDMI-A-2]
<7> [40.166466] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:277:HDMI-A-2]
<7> [40.169339] i915 0000:00:02.0: [drm:intel_tc_port_update_mode [i915]] Port E/TC#2: TC port mode reset (disconnected -> legacy)
<7> [40.174556] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:277:HDMI-A-2] disconnected
<7> [40.174902] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:281:DP-3]
<7> [40.174905] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:281:DP-3]
<7> [40.175163] i915 0000:00:02.0: [drm:intel_tc_port_update_mode [i915]] Port F/TC#3: TC port mode reset (disconnected -> tbt-alt)
<7> [40.175310] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:281:DP-3] disconnected
<7> [40.175611] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:290:DP-4]
<7> [40.175613] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:290:DP-4]
<7> [40.176485] i915 0000:00:02.0: [drm:intel_tc_port_update_mode [i915]] Port G/TC#4: TC port mode reset (disconnected -> tbt-alt)
<7> [40.176624] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:290:DP-4] disconnected
<7> [40.176998] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:241:eDP-1]
<7> [40.177000] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:241:eDP-1]
<7> [40.177141] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DC_off
<7> [40.177951] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 02 to 00
<7> [40.178319] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turning VDD on
<7> [40.178502] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006f
<7> [40.179429] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] DSC DPCD: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
<7> [40.180085] i915 0000:00:02.0: [drm:intel_dp_print_rates [i915]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000
<7> [40.180176] i915 0000:00:02.0: [drm:intel_dp_print_rates [i915]] sink rates: 162000, 216000, 243000, 270000, 324000, 378000, 432000, 540000
<7> [40.180260] i915 0000:00:02.0: [drm:intel_dp_print_rates [i915]] common rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000
<7> [40.180419] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:241:eDP-1] Assigning EDID-1.4 digital sink color depth as 10 bpc.
<7> [40.180423] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:241:eDP-1] ELD monitor
<7> [40.180424] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:241:eDP-1] ELD size 20, SAD count 0
<7> [40.180441] i915 0000:00:02.0: [drm:intel_dp_set_edid [i915]] [CONNECTOR:241:eDP-1] VRR capable: no
<7> [40.180527] i915 0000:00:02.0: [drm:intel_dp_set_edid [i915]] [CONNECTOR:241:eDP-1] DFP max bpc 0, max dotclock 0, TMDS clock 0-0, PCON Max FRL BW 0Gbps
<7> [40.181344] i915 0000:00:02.0: [drm:intel_dp_set_edid [i915]] PCON ENCODER DSC DPCD: 00 00 00 00 00 00 00 00 00 00 00 00 00
<7> [40.181433] i915 0000:00:02.0: [drm:intel_dp_set_edid [i915]] [CONNECTOR:241:eDP-1] RGB->YcbCr conversion? no, YCbCr 4:2:0 allowed? yes, YCbCr 4:4:4->4:2:0 conversion? no
<7> [40.182105] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:241:eDP-1] probed modes:
<7> [40.182112] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa
<7> [40.182125] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:250:DP-1]
<7> [40.182127] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:250:DP-1]
<7> [40.186383] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:250:DP-1] disconnected
<7> [40.186395] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:262:HDMI-A-1]
<7> [40.186398] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:262:HDMI-A-1]
<7> [40.191294] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:262:HDMI-A-1] disconnected
<7> [40.191305] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:268:DP-2]
<7> [40.191308] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:268:DP-2]
<7> [40.191471] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:268:DP-2] disconnected
<7> [40.191480] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:277:HDMI-A-2]
<7> [40.191482] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:277:HDMI-A-2]
<7> [40.196319] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:277:HDMI-A-2] disconnected
<7> [40.196330] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:281:DP-3]
<7> [40.196333] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:281:DP-3]
<7> [40.196495] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:281:DP-3] disconnected
<7> [40.196503] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:290:DP-4]
<7> [40.196505] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:290:DP-4]
<7> [40.196664] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:290:DP-4] disconnected
<6> [40.198781] [IGT] kms_flip: starting subtest plain-flip-ts-check-interruptible
<6> [40.201330] [IGT] kms_flip: starting dynamic subtest A-eDP1
<7> [40.201881] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:298]
<7> [40.201915] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:301]
<7> [40.204867] [drm:i915_gem_do_execbuffer [i915]] EINVAL at eb_validate_vma:509
<7> [40.205424] [drm:i915_gem_do_execbuffer [i915]] EINVAL at eb_validate_vma:509
<7> [40.245567] [drm:i915_gem_do_execbuffer [i915]] EINVAL at eb_validate_vma:509
<7> [40.245756] [drm:i915_gem_do_execbuffer [i915]] EINVAL at eb_validate_vma:509
<7> [40.254764] [drm:i915_gem_do_execbuffer [i915]] EINVAL at eb_validate_vma:509
<7> [40.254937] [drm:i915_gem_do_execbuffer [i915]] EINVAL at eb_validate_vma:509
<7> [40.271642] [drm:i915_gem_do_execbuffer [i915]] EINVAL at eb_validate_vma:509
<7> [40.271807] [drm:i915_gem_do_execbuffer [i915]] EINVAL at eb_validate_vma:509
<7> [40.278483] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:82:pipe A]
<7> [40.278651] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.enable (expected yes, found no)
<7> [40.278760] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.active (expected yes, found no)
<7> [40.278864] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1)
<7> [40.278965] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in lane_count (expected 4, found 0)
<7> [40.279063] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 7483046/8388608 link 498869/524288, found tu 0, data 0/0 link 0/0)
<7> [40.279161] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000)
<7> [40.279258] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [40.279365] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0)
<7> [40.279463] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0)
<7> [40.279559] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0)
<7> [40.279657] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0)
<7> [40.279751] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0)
<7> [40.279848] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0)
<7> [40.279944] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0)
<7> [40.280040] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0)
<7> [40.280135] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0)
<7> [40.280231] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0)
<7> [40.280337] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1878, found 0)
<7> [40.280433] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1878, found 0)
<7> [40.280527] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0)
<7> [40.280632] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0)
<7> [40.280727] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0)
<7> [40.280820] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0)
<7> [40.280913] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0)
<7> [40.281006] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0)
<7> [40.281103] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0)
<7> [40.281196] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0)
<7> [40.281297] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0)
<7> [40.281393] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0)
<7> [40.281488] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1878, found 0)
<7> [40.281603] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1878, found 0)
<7> [40.281696] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [40.281789] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)
<7> [40.281881] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)
<7> [40.281974] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in enhanced_framing (expected yes, found no)
<7> [40.282067] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0)
<7> [40.282160] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 513820, found 0)
<7> [40.282254] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 513820, found 0)
<7> [40.282368] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in port_clock (expected 540000, found 0)
<7> [40.282465] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:82:pipe A] fastset requirement not met, forcing full modeset
<7> [40.282584] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no
<7> [40.282675] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:82:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0
<7> [40.282783] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] ddb ( 0 - 4001) -> ( 0 - 0), size 4001 -> 0
<7> [40.282868] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:77:cursor A] ddb (4001 - 4096) -> ( 0 - 0), size 95 -> 0
<7> [40.282953] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] level *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm
<7> [40.283037] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] lines 2, 16, 16, 19, 19, 28, 0, 0, 0, 3, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [40.283121] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] blocks 49, 385, 385, 457, 457, 673, 0, 0, 63, 73, 87 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [40.283205] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] min_ddb 55, 425, 425, 504, 504, 742, 0, 0, 64, 82, 88 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [40.283296] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:82:pipe A] data rate 0 num active planes 0
<7> [40.283406] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 0 qgv_peak_bw: 51200
<7> [40.283513] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 0 qgv_peak_bw: 51200
<7> [40.283666] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 51200
<7> [40.283777] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 51200
<7> [40.283877] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 0
<7> [40.283978] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] Can change cdclk via squashing
<7> [40.284074] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz
<7> [40.284170] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [40.284301] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:82:pipe A] enable: no [modeset]
<7> [40.284403] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:32:plane 1A] fb: [NOFB], visible: no
<7> [40.284502] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:41:plane 2A] fb: [NOFB], visible: no
<7> [40.284601] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:50:plane 3A] fb: [NOFB], visible: no
<7> [40.284699] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:59:plane 4A] fb: [NOFB], visible: no
<7> [40.284796] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:68:plane 5A] fb: [NOFB], visible: no
<7> [40.284893] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:77:cursor A] fb: [NOFB], visible: no
<7> [40.285041] i915 0000:00:02.0: [drm:intel_psr_disable_locked [i915]] Disabling PSR2
<7> [40.286314] i915 0000:00:02.0: [drm:intel_edp_backlight_off [i915]]
<7> [40.488448] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:241:eDP-1] set backlight PWM = 0
<7> [40.489375] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A
<7> [40.499750] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x00000089, pins 0x00000010, long 0x00000000
<7> [40.500048] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turn panel power off
<7> [40.500175] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - short
<7> [40.500346] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power off time
<7> [40.500645] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060
<7> [40.552120] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] Wait complete
<7> [40.552694] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling AUX_A
<7> [40.552724] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010
<7> [40.553085] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - long
<7> [40.553436] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 10
<7> [40.555743] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring short hpd on eDP [ENCODER:240:DDI A/PHY A]
<7> [40.555877] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:240:DDI A/PHY A]
<7> [40.556024] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:240:DDI A/PHY A]
<7> [40.556102] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:249:DDI B/PHY B]
<7> [40.556292] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:251:DP-MST A]
<7> [40.556468] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:252:DP-MST B]
<7> [40.556642] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:253:DP-MST C]
<7> [40.556812] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:254:DP-MST D]
<7> [40.556983] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:267:DDI TC1/PHY TC1]
<7> [40.557152] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:269:DP-MST A]
<7> [40.557330] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:270:DP-MST B]
<7> [40.557441] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:271:DP-MST C]
<7> [40.557532] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:272:DP-MST D]
<7> [40.557652] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:276:DDI TC2/PHY TC2]
<7> [40.557775] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:280:DDI TC3/PHY TC3]
<7> [40.557881] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:282:DP-MST A]
<7> [40.558015] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:283:DP-MST B]
<7> [40.558162] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:284:DP-MST C]
<7> [40.558323] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:285:DP-MST D]
<7> [40.558425] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:289:DDI TC4/PHY TC4]
<7> [40.558541] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:291:DP-MST A]
<7> [40.558664] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:292:DP-MST B]
<7> [40.558755] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:293:DP-MST C]
<7> [40.558846] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:294:DP-MST D]
<7> [40.558935] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:241:eDP-1]
<7> [40.559068] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 2 (mbus joined: no)
<7> [40.559183] i915 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [i915]] Changing mbus joined: yes -> no (pipe: *)
<7> [40.559278] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Post changing CDCLK to 172800 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0
<7> [40.559499] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] aud_ts_cdclk set to M=60, N=432
<7> [40.559638] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1
<7> [40.559842] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_A
<7> [40.560106] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:82:pipe A]
<7> [40.560520] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:134:pipe B]
<7> [40.560667] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:186:pipe C]
<7> [40.560750] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:238:pipe D]
<7> [40.560833] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:82:pipe A]
<7> [40.560853] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:241:eDP-1]
<7> [40.560884] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:241:eDP-1] Limiting display bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36)
<7> [40.561000] i915 0000:00:02.0: [drm:intel_dp_compute_config_link_bpp_limits [i915]] [ENCODER:240:DDI A/PHY A][CRTC:82:pipe A] DP link limits: pixel clock 513820 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 30 max link_bpp 30.0000
<7> [40.561090] i915 0000:00:02.0: [drm:intel_dp_compute_link_config [i915]] DP lane count 4 clock 540000 bpp input 30 compressed 0.0000 link rate required 1926825 available 2160000
<7> [40.561181] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:82:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0
<7> [40.561280] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:240:DDI A/PHY A] [CRTC:82:pipe A]
<7> [40.561381] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.enable (expected no, found yes)
<7> [40.561479] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.active (expected no, found yes)
<7> [40.561577] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in cpu_transcoder (expected -1, found 0)
<7> [40.561675] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in lane_count (expected 0, found 4)
<7> [40.561773] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 7483046/8388608 link 498869/524288)
<7> [40.561869] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100)
<7> [40.561964] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [40.562060] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880)
<7> [40.562154] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040)
<7> [40.562249] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880)
<7> [40.562354] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040)
<7> [40.562472] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928)
<7> [40.562568] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960)
<7> [40.562663] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800)
<7> [40.562757] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800)
<7> [40.562852] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803)
<7> [40.562947] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809)
<7> [40.563041] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1878)
<7> [40.563135] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1878)
<7> [40.563228] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880)
<7> [40.563331] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040)
<7> [40.563425] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880)
<7> [40.563519] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040)
<7> [40.563613] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928)
<7> [40.563707] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960)
<7> [40.563798] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800)
<7> [40.563889] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800)
<7> [40.563981] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803)
<7> [40.564075] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809)
<7> [40.564166] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1878)
<7> [40.564256] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1878)
<7> [40.564358] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [40.564452] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)
<7> [40.564547] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)
<7> [40.564641] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in enhanced_framing (expected no, found yes)
<7> [40.564736] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in pipe_bpp (expected 0, found 30)
<7> [40.564829] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 513820)
<7> [40.564920] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 513820)
<7> [40.565013] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in port_clock (expected 0, found 540000)
<7> [40.565127] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:82:pipe A] fastset requirement not met, forcing full modeset
<7> [40.565242] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes
<7> [40.565341] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:82:pipe A] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x1
<7> [40.565445] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] ddb ( 0 - 0) -> ( 0 - 4001), size 0 -> 4001
<7> [40.565533] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:77:cursor A] ddb ( 0 - 0) -> (4001 - 4096), size 0 -> 95
<7> [40.565620] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm
<7> [40.565704] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 2, 16, 16, 19, 19, 28, 0, 0, 0, 3, 0
<7> [40.565790] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 49, 385, 385, 457, 457, 673, 0, 0, 63, 73, 87
<7> [40.565877] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 55, 425, 425, 504, 504, 742, 0, 0, 64, 82, 88
<7> [40.565960] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:82:pipe A] data rate 2055280 num active planes 1
<7> [40.566059] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 2159 qgv_peak_bw: 51200
<7> [40.566158] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [40.566255] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [40.566358] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [40.566455] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 2159
<7> [40.566551] i915 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [i915]] [PLANE:32:plane 1A] min cdclk (256910 kHz) > [CRTC:82:pipe A] min cdclk (0 kHz)
<7> [40.566649] i915 0000:00:02.0: [drm:intel_bw_calc_min_cdclk [i915]] new bandwidth min cdclk (40143 kHz) > old min cdclk (0 kHz)
<7> [40.566748] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] Can change cdclk via squashing
<7> [40.566847] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 307200 kHz, actual 307200 kHz
<7> [40.566941] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [40.567042] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:82:pipe A] enable: yes [modeset]
<7> [40.567139] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB
<7> [40.567236] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: A, pipe bpp: 30, dithering: 0
<7> [40.567340] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [40.567438] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [40.567534] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [40.567646] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [40.567756] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m_n: lanes: 4; data_m: 7483046, data_n: 8388608, link_m: 498869, link_n: 524288, tu: 64
<7> [40.567866] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0
<7> [40.567962] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fec: disabled, enhanced framing: enabled
<7> [40.568058] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sdp split: disabled
<7> [40.568154] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled
<7> [40.568247] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0
<7> [40.568349] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x4
<7> [40.568445] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] DP SDP: VSC, revision 4, length 14
<7> [40.568540] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pixelformat: RGB
<7> [40.568635] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] colorimetry: sRGB
<7> [40.568730] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] bpc: 0
<7> [40.568824] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dynamic range: VESA range
<7> [40.568916] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] content type: Not defined
<7> [40.569010] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, vmin: 0, vmax: 0, pipeline full: 0, guardband: 0 flipline: 0, vmin vblank: 1, vmax vblank: 0
<7> [40.569103] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa
<7> [40.569197] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa
<7> [40.569293] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1878 vs=1803-1809 vt=1878, flags=0xa
<7> [40.569387] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x40 0xa
<7> [40.569483] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1878 vs=1803-1809 vt=1878, flags=0xa
<7> [40.569580] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 540000, pipe src: 2880x1800+0+0, pixel rate 513820
<7> [40.569675] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 48, ips linetime: 0
<7> [40.569770] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0
<7> [40.569862] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [40.569959] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [40.570056] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x83d60, dpll_md: 0xf42110, fp0: 0xf8, fp1: 0x1000000
<7> [40.570151] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [40.570262] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [40.570367] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000
<7> [40.570461] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [40.570556] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [40.570651] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [40.570746] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000
<7> [40.570841] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [40.570932] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [40.571026] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [40.571119] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [40.571212] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000
<7> [40.571307] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:32:plane 1A] fb: [FB:298] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x0, visible: yes
<7> [40.571404] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [40.571501] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0
<7> [40.571596] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:41:plane 2A] fb: [NOFB], visible: no
<7> [40.571690] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:50:plane 3A] fb: [NOFB], visible: no
<7> [40.571783] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:59:plane 4A] fb: [NOFB], visible: no
<7> [40.571876] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:68:plane 5A] fb: [NOFB], visible: no
<7> [40.571969] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:77:cursor A] fb: [NOFB], visible: no
<7> [40.574394] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_A
<7> [40.574581] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 307200 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0
<7> [40.574723] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] aud_ts_cdclk set to M=60, N=768
<7> [40.574828] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:240:DDI A/PHY A]
<7> [40.574921] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:249:DDI B/PHY B]
<7> [40.575013] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:251:DP-MST A]
<7> [40.575104] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:252:DP-MST B]
<7> [40.575197] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:253:DP-MST C]
<7> [40.575294] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:254:DP-MST D]
<7> [40.575383] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:267:DDI TC1/PHY TC1]
<7> [40.575471] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:269:DP-MST A]
<7> [40.575558] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:270:DP-MST B]
<7> [40.575645] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:271:DP-MST C]
<7> [40.575733] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:272:DP-MST D]
<7> [40.575821] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:276:DDI TC2/PHY TC2]
<7> [40.575906] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:280:DDI TC3/PHY TC3]
<7> [40.575991] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:282:DP-MST A]
<7> [40.576077] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:283:DP-MST B]
<7> [40.576164] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:284:DP-MST C]
<7> [40.576250] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:285:DP-MST D]
<7> [40.576353] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:289:DDI TC4/PHY TC4]
<7> [40.576441] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:291:DP-MST A]
<7> [40.576528] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:292:DP-MST B]
<7> [40.576614] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:293:DP-MST C]
<7> [40.576701] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:294:DP-MST D]
<7> [40.576788] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0xf
<7> [40.576979] i915 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [i915]] Changing mbus joined: no -> yes (pipe: *)
<7> [40.577075] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 4 (mbus joined: yes)
<7> [40.577207] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling AUX_A
<7> [40.578402] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turn panel power on
<7> [40.578499] i915 0000:00:02.0: [drm:wait_panel_power_cycle [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power cycle
<7> [41.160825] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x00000000 PP_CONTROL: 0x00000060
<7> [41.161249] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] Wait complete
<7> [41.161815] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power on
<7> [41.162271] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063
<7> [41.193904] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010
<7> [41.194353] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - long
<7> [41.194785] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 20
<7> [41.195281] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:240:DDI A/PHY A]
<7> [41.224366] i915 0000:00:02.0: [drm:intel_tc_port_update_mode [i915]] Port G/TC#4: TC port mode reset (tbt-alt -> disconnected)
<7> [41.224473] i915 0000:00:02.0: [drm:intel_tc_port_update_mode [i915]] Port F/TC#3: TC port mode reset (tbt-alt -> disconnected)
<7> [41.224629] i915 0000:00:02.0: [drm:intel_tc_port_update_mode [i915]] Port E/TC#2: TC port mode reset (legacy -> disconnected)
<7> [41.224691] i915 0000:00:02.0: [drm:intel_tc_port_update_mode [i915]] Port D/TC#1: TC port mode reset (tbt-alt -> disconnected)
<7> [41.362479] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] Wait complete
<7> [41.364716] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turning VDD on
<7> [41.365097] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b
<7> [41.368823] i915 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 14 c4 41 00 00 01 c0 02 00 00 00 00 0b 80
<7> [41.369671] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Reloading eDP link rates
<7> [41.370575] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 07
<7> [41.371487] i915 0000:00:02.0: [drm:intel_dp_set_signal_levels [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0
<7> [41.372131] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Using DP training pattern TPS1
<7> [41.373274] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Clock recovery OK
<7> [41.373378] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Using DP training pattern TPS3
<7> [41.374906] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful
<7> [41.374996] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Link Training passed at link rate = 540000, lane count = 4
<7> [41.375577] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe A
<7> [41.375938] i915 0000:00:02.0: [drm:intel_edp_backlight_on [i915]]
<7> [41.376111] i915 0000:00:02.0: [drm:intel_backlight_enable [i915]] pipe A
<7> [41.376329] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:241:eDP-1] set backlight PWM = 13892
<7> [41.386977] i915 0000:00:02.0: [drm:intel_psr_post_plane_update [i915]] Enabling PSR2
<7> [41.388758] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:241:eDP-1]
<7> [41.388952] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:82:pipe A]
<7> [44.424564] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turning VDD off
<7> [44.425028] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067
<7> [46.470809] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off
<7> [46.471234] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6
<7> [46.471688] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02
<6> [49.451281] [IGT] kms_flip: finished subtest A-eDP1, FAIL
|