Results for igt@kms_flip@plain-flip-ts-check-interruptible@a-edp1

Machine description: shard-mtlp-1

Result: Fail

integration-manifest git-log-oneline i915_display_info16 igt_runner16 run16 runtimes16 results16.json boot16 dmesg16

DetailValue
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
Created at 2024-10-09 19:16:07