Results for igt@kms_flip@flip-vs-expired-vblank@d-dp2

Machine description: shard-bmg-2

Result: Fail

i915_display_info23 igt_runner23 results23.json results23-xe-load.json i915_display_info_post_exec23 boot23 dmesg23

DetailValue
Duration 3.92 seconds
Hostname 
shard-bmg-2
Igt-Version 
IGT-Version: 1.30-g40b32b434 (x86_64) (Linux: 6.14.0-rc5-xe+ x86_64)
Out 
Starting dynamic subtest: D-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __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 D-DP2: FAIL (3.917s)
Err 
Starting dynamic subtest: D-DP2
(kms_flip:3994) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:3994) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest D-DP2 failed.
**** DEBUG ****
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.576828
last_received_ts = 142.576248
last_seq = 377
current_ts = 142.593506
current_received_ts = 142.592911
current_seq = 378
count = 90
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 27us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.593506
last_received_ts = 142.592911
last_seq = 378
current_ts = 142.610168
current_received_ts = 142.609589
current_seq = 379
count = 91
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 25us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.610168
last_received_ts = 142.609589
last_seq = 379
current_ts = 142.626846
current_received_ts = 142.626251
current_seq = 380
count = 92
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 31us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.626846
last_received_ts = 142.626251
last_seq = 380
current_ts = 142.643509
current_received_ts = 142.642929
current_seq = 381
count = 93
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 28us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.643509
last_received_ts = 142.642929
last_seq = 381
current_ts = 142.660172
current_received_ts = 142.659592
current_seq = 382
count = 94
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 27us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.660172
last_received_ts = 142.659592
last_seq = 382
current_ts = 142.676849
current_received_ts = 142.676270
current_seq = 383
count = 95
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 27us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.676849
last_received_ts = 142.676270
last_seq = 383
current_ts = 142.693512
current_received_ts = 142.692932
current_seq = 384
count = 96
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 28us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.693512
last_received_ts = 142.692932
last_seq = 384
current_ts = 142.710190
current_received_ts = 142.709778
current_seq = 385
count = 97
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 47us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.710190
last_received_ts = 142.709778
last_seq = 385
current_ts = 142.726852
current_received_ts = 142.726273
current_seq = 386
count = 98
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 29us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.726852
last_received_ts = 142.726273
last_seq = 386
current_ts = 142.743530
current_received_ts = 142.742935
current_seq = 387
count = 99
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 27us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.743530
last_received_ts = 142.742935
last_seq = 387
current_ts = 142.760193
current_received_ts = 142.759613
current_seq = 388
count = 100
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 27us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.760193
last_received_ts = 142.759613
last_seq = 388
current_ts = 142.776871
current_received_ts = 142.776276
current_seq = 389
count = 101
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 28us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.776871
last_received_ts = 142.776276
last_seq = 389
current_ts = 142.793533
current_received_ts = 142.792953
current_seq = 390
count = 102
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 28us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.793533
last_received_ts = 142.792953
last_seq = 390
current_ts = 142.810211
current_received_ts = 142.809616
current_seq = 391
count = 103
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 28us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.810211
last_received_ts = 142.809616
last_seq = 391
current_ts = 142.826874
current_received_ts = 142.826294
current_seq = 392
count = 104
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 28us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.826874
last_received_ts = 142.826294
last_seq = 392
current_ts = 142.843552
current_received_ts = 142.842972
current_seq = 393
count = 105
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 69us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.843552
last_received_ts = 142.842972
last_seq = 393
current_ts = 142.860214
current_received_ts = 142.859634
current_seq = 394
count = 106
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 28us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.860214
last_received_ts = 142.859634
last_seq = 394
current_ts = 142.876892
current_received_ts = 142.876297
current_seq = 395
count = 107
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 28us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.876892
last_received_ts = 142.876297
last_seq = 395
current_ts = 142.893555
current_received_ts = 142.892975
current_seq = 396
count = 108
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 50us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.893555
last_received_ts = 142.892975
last_seq = 396
current_ts = 142.910233
current_received_ts = 142.909637
current_seq = 397
count = 109
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 28us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.910233
last_received_ts = 142.909637
last_seq = 397
current_ts = 142.926895
current_received_ts = 142.926453
current_seq = 398
count = 110
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 47us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.926895
last_received_ts = 142.926453
last_seq = 398
current_ts = 142.943558
current_received_ts = 142.943039
current_seq = 399
count = 111
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 37us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.943558
last_received_ts = 142.943039
last_seq = 399
current_ts = 142.960236
current_received_ts = 142.959656
current_seq = 400
count = 112
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 26us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.960236
last_received_ts = 142.959656
last_seq = 400
current_ts = 142.976898
current_received_ts = 142.976471
current_seq = 401
count = 113
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 46us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.976898
last_received_ts = 142.976471
last_seq = 401
current_ts = 142.993576
current_received_ts = 142.992996
current_seq = 402
count = 114
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 28us
(kms_flip:3994) DEBUG: name = flip
last_ts = 142.993576
last_received_ts = 142.992996
last_seq = 402
current_ts = 143.010239
current_received_ts = 143.009659
current_seq = 403
count = 115
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 28us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.010239
last_received_ts = 143.009659
last_seq = 403
current_ts = 143.026917
current_received_ts = 143.026321
current_seq = 404
count = 116
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 27us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.026917
last_received_ts = 143.026321
last_seq = 404
current_ts = 143.043579
current_received_ts = 143.042999
current_seq = 405
count = 117
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 27us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.043579
last_received_ts = 143.042999
last_seq = 405
current_ts = 143.060257
current_received_ts = 143.059662
current_seq = 406
count = 118
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 28us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.060257
last_received_ts = 143.059662
last_seq = 406
current_ts = 143.076920
current_received_ts = 143.076340
current_seq = 407
count = 119
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 27us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.076920
last_received_ts = 143.076340
last_seq = 407
current_ts = 143.093597
current_received_ts = 143.093063
current_seq = 408
count = 120
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 31us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.093597
last_received_ts = 143.093063
last_seq = 408
current_ts = 143.110260
current_received_ts = 143.109848
current_seq = 409
count = 121
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 47us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.110260
last_received_ts = 143.109848
last_seq = 409
current_ts = 143.126938
current_received_ts = 143.126404
current_seq = 410
count = 122
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 40us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.126938
last_received_ts = 143.126404
last_seq = 410
current_ts = 143.143600
current_received_ts = 143.143051
current_seq = 411
count = 123
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 32us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.143600
last_received_ts = 143.143051
last_seq = 411
current_ts = 143.160278
current_received_ts = 143.159698
current_seq = 412
count = 124
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 29us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.160278
last_received_ts = 143.159698
last_seq = 412
current_ts = 143.176941
current_received_ts = 143.176529
current_seq = 413
count = 125
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 47us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.176941
last_received_ts = 143.176529
last_seq = 413
current_ts = 143.193619
current_received_ts = 143.193054
current_seq = 414
count = 126
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 32us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.193619
last_received_ts = 143.193054
last_seq = 414
current_ts = 143.210281
current_received_ts = 143.209869
current_seq = 415
count = 127
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 46us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.210281
last_received_ts = 143.209869
last_seq = 415
current_ts = 143.226959
current_received_ts = 143.226395
current_seq = 416
count = 128
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 41us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.226959
last_received_ts = 143.226395
last_seq = 416
current_ts = 143.243622
current_received_ts = 143.243073
current_seq = 417
count = 129
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 31us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.243622
last_received_ts = 143.243073
last_seq = 417
current_ts = 143.260284
current_received_ts = 143.259872
current_seq = 418
count = 130
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 47us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.260284
last_received_ts = 143.259872
last_seq = 418
current_ts = 143.276962
current_received_ts = 143.276489
current_seq = 419
count = 131
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 40us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.276962
last_received_ts = 143.276489
last_seq = 419
current_ts = 143.293625
current_received_ts = 143.293167
current_seq = 420
count = 132
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 40us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.293625
last_received_ts = 143.293167
last_seq = 420
current_ts = 143.310303
current_received_ts = 143.309769
current_seq = 421
count = 133
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 40us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.310303
last_received_ts = 143.309769
last_seq = 421
current_ts = 143.326965
current_received_ts = 143.326401
current_seq = 422
count = 134
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 28us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.326965
last_received_ts = 143.326401
last_seq = 422
current_ts = 143.343643
current_received_ts = 143.343079
current_seq = 423
count = 135
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 31us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.343643
last_received_ts = 143.343079
last_seq = 423
current_ts = 143.360306
current_received_ts = 143.359726
current_seq = 424
count = 136
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 29us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.360306
last_received_ts = 143.359726
last_seq = 424
current_ts = 143.376984
current_received_ts = 143.376389
current_seq = 425
count = 137
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 25us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.376984
last_received_ts = 143.376389
last_seq = 425
current_ts = 143.393646
current_received_ts = 143.393082
current_seq = 426
count = 138
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 28us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.393646
last_received_ts = 143.393082
last_seq = 426
current_ts = 143.410324
current_received_ts = 143.409744
current_seq = 427
count = 139
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 28us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.410324
last_received_ts = 143.409744
last_seq = 427
current_ts = 143.426987
current_received_ts = 143.426407
current_seq = 428
count = 140
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 25us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.426987
last_received_ts = 143.426407
last_seq = 428
current_ts = 143.443665
current_received_ts = 143.443207
current_seq = 429
count = 141
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 46us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.443665
last_received_ts = 143.443207
last_seq = 429
current_ts = 143.460342
current_received_ts = 143.459961
current_seq = 430
count = 142
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 103us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.460342
last_received_ts = 143.459961
last_seq = 430
current_ts = 143.477005
current_received_ts = 143.476547
current_seq = 431
count = 143
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 36us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.477005
last_received_ts = 143.476547
last_seq = 431
current_ts = 143.493683
current_received_ts = 143.493393
current_seq = 432
count = 144
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 48us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.493683
last_received_ts = 143.493393
last_seq = 432
current_ts = 143.510345
current_received_ts = 143.509933
current_seq = 433
count = 145
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 87us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.510345
last_received_ts = 143.509933
last_seq = 433
current_ts = 143.527008
current_received_ts = 143.526672
current_seq = 434
count = 146
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 47us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.527008
last_received_ts = 143.526672
last_seq = 434
current_ts = 143.543671
current_received_ts = 143.543320
current_seq = 435
count = 147
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 43us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.543671
last_received_ts = 143.543320
last_seq = 435
current_ts = 143.560349
current_received_ts = 143.559830
current_seq = 436
count = 148
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 36us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.560349
last_received_ts = 143.559830
last_seq = 436
current_ts = 143.577026
current_received_ts = 143.576630
current_seq = 437
count = 149
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 47us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.577026
last_received_ts = 143.576630
last_seq = 437
current_ts = 143.593689
current_received_ts = 143.593216
current_seq = 438
count = 150
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 42us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.593689
last_received_ts = 143.593216
last_seq = 438
current_ts = 143.610352
current_received_ts = 143.609879
current_seq = 439
count = 151
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 41us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.610352
last_received_ts = 143.609879
last_seq = 439
current_ts = 143.627029
current_received_ts = 143.626556
current_seq = 440
count = 152
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 40us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.627029
last_received_ts = 143.626556
last_seq = 440
current_ts = 143.643692
current_received_ts = 143.643158
current_seq = 441
count = 153
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 40us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.643692
last_received_ts = 143.643158
last_seq = 441
current_ts = 143.660370
current_received_ts = 143.659790
current_seq = 442
count = 154
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 32us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.660370
last_received_ts = 143.659790
last_seq = 442
current_ts = 143.677032
current_received_ts = 143.676453
current_seq = 443
count = 155
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 32us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.677032
last_received_ts = 143.676453
last_seq = 443
current_ts = 143.693710
current_received_ts = 143.693130
current_seq = 444
count = 156
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 28us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.693710
last_received_ts = 143.693130
last_seq = 444
current_ts = 143.710373
current_received_ts = 143.709793
current_seq = 445
count = 157
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 29us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.710373
last_received_ts = 143.709793
last_seq = 445
current_ts = 143.727036
current_received_ts = 143.726456
current_seq = 446
count = 158
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 25us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.727036
last_received_ts = 143.726456
last_seq = 446
current_ts = 143.743713
current_received_ts = 143.743179
current_seq = 447
count = 159
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 40us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.743713
last_received_ts = 143.743179
last_seq = 447
current_ts = 143.760376
current_received_ts = 143.759964
current_seq = 448
count = 160
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 47us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.760376
last_received_ts = 143.759964
last_seq = 448
current_ts = 143.777054
current_received_ts = 143.776474
current_seq = 449
count = 161
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 34us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.777054
last_received_ts = 143.776474
last_seq = 449
current_ts = 143.793716
current_received_ts = 143.793152
current_seq = 450
count = 162
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 31us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.793716
last_received_ts = 143.793152
last_seq = 450
current_ts = 143.810394
current_received_ts = 143.809814
current_seq = 451
count = 163
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 29us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.810394
last_received_ts = 143.809814
last_seq = 451
current_ts = 143.827057
current_received_ts = 143.826645
current_seq = 452
count = 164
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 46us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.827057
last_received_ts = 143.826645
last_seq = 452
current_ts = 143.843735
current_received_ts = 143.843262
current_seq = 453
count = 165
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 40us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.843735
last_received_ts = 143.843262
last_seq = 453
current_ts = 143.860397
current_received_ts = 143.859924
current_seq = 454
count = 166
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 74us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.860397
last_received_ts = 143.859924
last_seq = 454
current_ts = 143.877075
current_received_ts = 143.876602
current_seq = 455
count = 167
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 40us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.877075
last_received_ts = 143.876602
last_seq = 455
current_ts = 143.893738
current_received_ts = 143.893204
current_seq = 456
count = 168
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 40us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.893738
last_received_ts = 143.893204
last_seq = 456
current_ts = 143.910416
current_received_ts = 143.909866
current_seq = 457
count = 169
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 40us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.910416
last_received_ts = 143.909866
last_seq = 457
current_ts = 143.927078
current_received_ts = 143.926514
current_seq = 458
count = 170
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 31us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.927078
last_received_ts = 143.926514
last_seq = 458
current_ts = 143.943756
current_received_ts = 143.943192
current_seq = 459
count = 171
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 27us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.943756
last_received_ts = 143.943192
last_seq = 459
current_ts = 143.960419
current_received_ts = 143.959991
current_seq = 460
count = 172
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 48us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.960419
last_received_ts = 143.959991
last_seq = 460
current_ts = 143.977097
current_received_ts = 143.976608
current_seq = 461
count = 173
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 41us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.977097
last_received_ts = 143.976608
last_seq = 461
current_ts = 143.993759
current_received_ts = 143.993240
current_seq = 462
count = 174
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 41us
(kms_flip:3994) DEBUG: name = flip
last_ts = 143.993759
last_received_ts = 143.993240
last_seq = 462
current_ts = 144.010422
current_received_ts = 144.009903
current_seq = 463
count = 175
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 39us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.010422
last_received_ts = 144.009903
last_seq = 463
current_ts = 144.027100
current_received_ts = 144.026535
current_seq = 464
count = 176
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 32us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.027100
last_received_ts = 144.026535
last_seq = 464
current_ts = 144.043762
current_received_ts = 144.043198
current_seq = 465
count = 177
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 30us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.043762
last_received_ts = 144.043198
last_seq = 465
current_ts = 144.060440
current_received_ts = 144.059860
current_seq = 466
count = 178
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 30us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.060440
last_received_ts = 144.059860
last_seq = 466
current_ts = 144.077103
current_received_ts = 144.076553
current_seq = 467
count = 179
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 31us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.077103
last_received_ts = 144.076553
last_seq = 467
current_ts = 144.093781
current_received_ts = 144.093353
current_seq = 468
count = 180
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 47us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.093781
last_received_ts = 144.093353
last_seq = 468
current_ts = 144.110443
current_received_ts = 144.109970
current_seq = 469
count = 181
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 46us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.110443
last_received_ts = 144.109970
last_seq = 469
current_ts = 144.127121
current_received_ts = 144.126648
current_seq = 470
count = 182
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 40us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.127121
last_received_ts = 144.126648
last_seq = 470
current_ts = 144.143784
current_received_ts = 144.143326
current_seq = 471
count = 183
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 41us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.143784
last_received_ts = 144.143326
last_seq = 471
current_ts = 144.160461
current_received_ts = 144.159927
current_seq = 472
count = 184
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 41us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.160461
last_received_ts = 144.159927
last_seq = 472
current_ts = 144.177124
current_received_ts = 144.176666
current_seq = 473
count = 185
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 48us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.177124
last_received_ts = 144.176666
last_seq = 473
current_ts = 144.193802
current_received_ts = 144.193329
current_seq = 474
count = 186
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 40us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.193802
last_received_ts = 144.193329
last_seq = 474
current_ts = 144.210464
current_received_ts = 144.209991
current_seq = 475
count = 187
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 42us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.210464
last_received_ts = 144.209991
last_seq = 475
current_ts = 144.227142
current_received_ts = 144.226669
current_seq = 476
count = 188
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 40us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.227142
last_received_ts = 144.226669
last_seq = 476
current_ts = 144.243805
current_received_ts = 144.243271
current_seq = 477
count = 189
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 40us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.243805
last_received_ts = 144.243271
last_seq = 477
current_ts = 144.260468
current_received_ts = 144.260040
current_seq = 478
count = 190
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 40us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.260468
last_received_ts = 144.260040
last_seq = 478
current_ts = 144.277145
current_received_ts = 144.276611
current_seq = 479
count = 191
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 41us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.277145
last_received_ts = 144.276611
last_seq = 479
current_ts = 144.293808
current_received_ts = 144.293274
current_seq = 480
count = 192
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 40us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.293808
last_received_ts = 144.293274
last_seq = 480
current_ts = 144.310486
current_received_ts = 144.309906
current_seq = 481
count = 193
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 32us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.310486
last_received_ts = 144.309906
last_seq = 481
current_ts = 144.327148
current_received_ts = 144.326599
current_seq = 482
count = 194
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 33us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.327148
last_received_ts = 144.326599
last_seq = 482
current_ts = 144.343826
current_received_ts = 144.343399
current_seq = 483
count = 195
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 47us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.343826
last_received_ts = 144.343399
last_seq = 483
current_ts = 144.360489
current_received_ts = 144.360077
current_seq = 484
count = 196
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 49us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.360489
last_received_ts = 144.360077
last_seq = 484
current_ts = 144.377167
current_received_ts = 144.376694
current_seq = 485
count = 197
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 41us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.377167
last_received_ts = 144.376694
last_seq = 485
current_ts = 144.393829
current_received_ts = 144.393372
current_seq = 486
count = 198
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 41us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.393829
last_received_ts = 144.393372
last_seq = 486
current_ts = 144.410507
current_received_ts = 144.409973
current_seq = 487
count = 199
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 48us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.410507
last_received_ts = 144.409973
last_seq = 487
current_ts = 144.427170
current_received_ts = 144.426605
current_seq = 488
count = 200
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 34us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.427170
last_received_ts = 144.426605
last_seq = 488
current_ts = 144.443832
current_received_ts = 144.443283
current_seq = 489
count = 201
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 33us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.443832
last_received_ts = 144.443283
last_seq = 489
current_ts = 144.460510
current_received_ts = 144.460129
current_seq = 490
count = 202
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 47us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.460510
last_received_ts = 144.460129
last_seq = 490
current_ts = 144.477173
current_received_ts = 144.476608
current_seq = 491
count = 203
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 27us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.477173
last_received_ts = 144.476608
last_seq = 491
current_ts = 144.493851
current_received_ts = 144.493423
current_seq = 492
count = 204
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 47us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.493851
last_received_ts = 144.493423
last_seq = 492
current_ts = 144.510513
current_received_ts = 144.510086
current_seq = 493
count = 205
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 40us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.510513
last_received_ts = 144.510086
last_seq = 493
current_ts = 144.527191
current_received_ts = 144.526703
current_seq = 494
count = 206
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 41us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.527191
last_received_ts = 144.526703
last_seq = 494
current_ts = 144.543854
current_received_ts = 144.543381
current_seq = 495
count = 207
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 41us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.543854
last_received_ts = 144.543381
last_seq = 495
current_ts = 144.560532
current_received_ts = 144.559998
current_seq = 496
count = 208
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 42us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.560532
last_received_ts = 144.559998
last_seq = 496
current_ts = 144.577194
current_received_ts = 144.576630
current_seq = 497
count = 209
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 32us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.577194
last_received_ts = 144.576630
last_seq = 497
current_ts = 144.593872
current_received_ts = 144.593292
current_seq = 498
count = 210
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 31us
(kms_flip:3994) DEBUG: name = flip
last_ts = 144.593872
last_received_ts = 144.593292
last_seq = 498
current_ts = 144.610535
current_received_ts = 144.610321
current_seq = 499
count = 211
seq_step = 1
(kms_flip:3994) DEBUG: Vblank took 854us
(kms_flip:3994) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:3994) CRITICAL: Failed assertion: end - start < 500
(kms_flip:3994) igt_core-INFO: Stack trace:
(kms_flip:3994) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3994) igt_core-INFO:   #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
(kms_flip:3994) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:3994) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:3994) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3994) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3994) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3994) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest D-DP2: FAIL (3.917s)
Dmesg
<6> [141.234348] [IGT] kms_flip: starting dynamic subtest D-DP2
<7> [141.235386] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:295]
<7> [141.236171] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:296]
<7> [141.313184] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:82:pipe A]
<7> [141.313843] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:134:pipe B]
<7> [141.314112] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:186:pipe C]
<7> [141.314277] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.enable (expected yes, found no)
<7> [141.314596] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.active (expected yes, found no)
<7> [141.314878] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in cpu_transcoder (expected 2, found -1)
<7> [141.315159] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in lane_count (expected 4, found 0)
<7> [141.315434] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in dp_m_n (expected tu 64 data 5190451/8388608 link 288358/524288, found tu 0, data 0/0 link 0/0)
<7> [141.315750] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in output_types (expected 0x00000080, found 0x00000000)
<7> [141.316006] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [141.316229] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0)
<7> [141.316448] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0)
<7> [141.316662] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0)
<7> [141.316867] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0)
<7> [141.317083] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0)
<7> [141.317286] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0)
<7> [141.317482] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0)
<7> [141.317683] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0)
<7> [141.317872] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0)
<7> [141.318072] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0)
<7> [141.318249] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0)
<7> [141.318424] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0)
<7> [141.318599] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0)
<7> [141.318771] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0)
<7> [141.318936] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0)
<7> [141.319127] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0)
<7> [141.319291] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0)
<7> [141.319444] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0)
<7> [141.319599] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0)
<7> [141.319754] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0)
<7> [141.319902] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0)
<7> [141.320071] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0)
<7> [141.320221] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0)
<7> [141.320366] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0)
<7> [141.320510] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [141.320651] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0)
<7> [141.320790] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0)
<7> [141.320925] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in enhanced_framing (expected yes, found no)
<7> [141.321075] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in pipe_bpp (expected 36, found 0)
<7> [141.321210] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0)
<7> [141.321338] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0)
<7> [141.321466] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:186:pipe C] fastset requirement not met in port_clock (expected 270000, found 0)
<7> [141.321592] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:186:pipe C] fastset requirement not met, forcing full modeset
<7> [141.321784] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xd -> 0x1 (total dbuf slices 0xf), mbus joined? no->no
<7> [141.321946] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:186:pipe C] dbuf slices 0xc -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x4 -> 0x0
<7> [141.322129] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [PLANE:181:cursor C] ddb (1989 - 2048) -> ( 0 - 0), size 59 -> 0
<7> [141.322251] xe 0000:03:00.0: [drm:intel_modeset_calc_cdclk [xe]] New cdclk calculated to be logical 652800 kHz, actual 652800 kHz
<7> [141.322374] xe 0000:03:00.0: [drm:intel_modeset_calc_cdclk [xe]] New voltage level calculated to be logical 3, actual 3
<7> [141.322510] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:186:pipe C] enable: no [modeset]
<7> [141.322630] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:136:plane 1C] fb: [NOFB], visible: no
<7> [141.322748] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:plane 2C] fb: [NOFB], visible: no
<7> [141.322856] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:154:plane 3C] fb: [NOFB], visible: no
<7> [141.322963] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:163:plane 4C] fb: [NOFB], visible: no
<7> [141.323093] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:172:plane 5C] fb: [NOFB], visible: no
<7> [141.323197] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:181:cursor C] fb: [NOFB], visible: no
<7> [141.323687] xe 0000:03:00.0: [drm:intel_audio_codec_disable [xe]] [CONNECTOR:260:DP-2][ENCODER:259:DDI TC2/PHY G] Disable audio codec on [CRTC:186:pipe C]
<7> [141.348665] xe 0000:03:00.0: [drm:intel_audio_component_get_eld [xe]] Not valid for port E
<7> [141.349265] xe 0000:03:00.0: [drm:intel_disable_transcoder [xe]] disabling pipe C
<7> [141.369437] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2
<7> [141.371781] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:240:DDI TC1/PHY F]
<7> [141.372266] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:242:DP-MST A]
<7> [141.372648] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:243:DP-MST B]
<7> [141.373051] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:244:DP-MST C]
<7> [141.373626] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:245:DP-MST D]
<7> [141.374217] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:259:DDI TC2/PHY G]
<7> [141.374832] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:261:DP-MST A]
<7> [141.375363] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:262:DP-MST B]
<7> [141.375753] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:263:DP-MST C]
<7> [141.376168] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:264:DP-MST D]
<7> [141.376514] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:271:DDI TC3/PHY H]
<7> [141.376851] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:275:DDI TC4/PHY I]
<7> [141.377219] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:277:DP-MST A]
<7> [141.377550] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:278:DP-MST B]
<7> [141.377870] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:279:DP-MST C]
<7> [141.378248] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:280:DP-MST D]
<7> [141.378579] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:260:DP-2]
<7> [141.378920] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no)
<7> [141.379305] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1
<7> [141.379743] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_C
<7> [141.380209] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_2
<7> [141.380613] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:186:pipe C]
<7> [141.381006] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:238:pipe D]
<7> [141.381654] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:238:pipe D]
<7> [141.381717] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:260:DP-2]
<7> [141.381903] xe 0000:03:00.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:259:DDI TC2/PHY G][CRTC:238:pipe D] DP link limits: pixel clock 148500 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 36 max link_bpp 36.0000
<7> [141.382209] xe 0000:03:00.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 270000 bpp input 36 compressed 0.0000 link rate required 668250 available 1080000
<7> [141.382480] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:238:pipe D] hw max bpp: 36, pipe bpp: 36, dithering: 0
<7> [141.382747] xe 0000:03:00.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:259:DDI TC2/PHY G] [CRTC:238:pipe D]
<7> [141.383027] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.enable (expected no, found yes)
<7> [141.383281] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.active (expected no, found yes)
<7> [141.383514] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in cpu_transcoder (expected -1, found 3)
<7> [141.383742] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in lane_count (expected 0, found 4)
<7> [141.383954] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 5190451/8388608 link 288358/524288)
<7> [141.384191] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in output_types (expected 0x00000000, found 0x00000080)
<7> [141.384390] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [141.384581] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920)
<7> [141.384768] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200)
<7> [141.384956] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920)
<7> [141.385169] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200)
<7> [141.385348] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008)
<7> [141.385523] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052)
<7> [141.385695] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080)
<7> [141.385851] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080)
<7> [141.386015] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084)
<7> [141.386179] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089)
<7> [141.386337] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125)
<7> [141.386492] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125)
<7> [141.386644] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920)
<7> [141.386798] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200)
<7> [141.386936] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920)
<7> [141.387110] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200)
<7> [141.387250] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008)
<7> [141.387382] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052)
<7> [141.387513] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080)
<7> [141.387643] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080)
<7> [141.387771] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084)
<7> [141.387889] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089)
<7> [141.388023] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125)
<7> [141.388143] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125)
<7> [141.388259] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [141.388372] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1)
<7> [141.388486] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4)
<7> [141.388599] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in enhanced_framing (expected no, found yes)
<7> [141.388712] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in dpll_hw_state.cx0pll C20
<7> [141.388817] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] expected:
<7> [141.388922] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] c20pll_hw_state:
<7> [141.389050] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] tx[0] = 0xbe88, tx[1] = 0x5800, tx[2] = 0x0000
<7> [141.389160] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000
<7> [141.389263] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[0] = 0x40e8
<7> [141.389363] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[1] = 0x7d20
<7> [141.389463] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[2] = 0x0a06
<7> [141.389563] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[3] = 0x8f1c
<7> [141.389659] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[4] = 0x0000
<7> [141.389748] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[5] = 0x0000
<7> [141.389838] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[6] = 0x2200
<7> [141.389926] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[7] = 0xffff
<7> [141.390020] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[8] = 0x0400
<7> [141.390107] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[9] = 0x0000
<7> [141.390189] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[10] = 0x0001
<7> [141.390273] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] found:
<7> [141.390362] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] c20pll_hw_state:
<7> [141.390443] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] tx[0] = 0xbe88, tx[1] = 0x4800, tx[2] = 0x0000
<7> [141.390523] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000
<7> [141.390602] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[0] = 0x308c
<7> [141.390680] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[1] = 0x2110
<7> [141.390758] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[2] = 0xcc9c
<7> [141.390835] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[3] = 0xbfc1
<7> [141.390909] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[4] = 0x4b9a
<7> [141.390990] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[5] = 0x3f81
<7> [141.391066] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[6] = 0x2000
<7> [141.391136] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[7] = 0x0001
<7> [141.391206] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[8] = 0x5000
<7> [141.391276] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[9] = 0x0000
<7> [141.391344] xe 0000:03:00.0: [drm:intel_cx0pll_dump_hw_state [xe]] mpllb[10] = 0x0000
<7> [141.391415] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in pipe_bpp (expected 0, found 36)
<7> [141.391493] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500)
<7> [141.391572] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500)
<7> [141.391649] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:238:pipe D] fastset requirement not met in port_clock (expected 0, found 270000)
<7> [141.391725] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:238:pipe D] fastset requirement not met, forcing full modeset
<7> [141.391843] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0xf), mbus joined? no->no
<7> [141.391978] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:238:pipe D] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x8
<7> [141.392095] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [PLANE:188:plane 1D] ddb ( 0 - 0) -> ( 0 - 1989), size 0 -> 1989
<7> [141.392163] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [PLANE:233:cursor D] ddb ( 0 - 0) -> (1989 - 2048), size 0 -> 59
<7> [141.392229] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [PLANE:188:plane 1D] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm
<7> [141.392293] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [PLANE:188:plane 1D] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 3, 7, 11, 17, 17, 17, 17, 0, 15, 0
<7> [141.392357] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [PLANE:188:plane 1D] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 49, 113, 177, 273, 273, 273, 273, 30, 241, 255
<7> [141.392420] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [PLANE:188:plane 1D] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 19, 55, 126, 196, 302, 302, 0, 0, 31, 267, 267
<7> [141.392484] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] [CRTC:238:pipe D] data rate 594000 num active planes 1
<7> [141.392564] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 33600 required 624 qgv_peak_bw: 48000
<7> [141.392640] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 53000 required 624 qgv_peak_bw: 48000
<7> [141.392716] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 48000 for required data rate: 624
<7> [141.392798] xe 0000:03:00.0: [drm:intel_plane_calc_min_cdclk [xe]] [PLANE:188:plane 1D] min cdclk (74250 kHz) > [CRTC:238:pipe D] min cdclk (0 kHz)
<7> [141.392878] xe 0000:03:00.0: [drm:intel_bw_calc_min_cdclk [xe]] new bandwidth min cdclk (11602 kHz) > old min cdclk (0 kHz)
<7> [141.392953] xe 0000:03:00.0: [drm:intel_modeset_calc_cdclk [xe]] New cdclk calculated to be logical 652800 kHz, actual 652800 kHz
<7> [141.393041] xe 0000:03:00.0: [drm:intel_modeset_calc_cdclk [xe]] New voltage level calculated to be logical 3, actual 3
<7> [141.393127] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:238:pipe D] enable: yes [modeset]
<7> [141.393204] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: DP (0x80), output format: RGB, sink format: RGB
<7> [141.393280] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: D, pipe bpp: 36, dithering: 0
<7> [141.393354] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid>
<7> [141.393427] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [141.393498] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0
<7> [141.393570] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0
<7> [141.393641] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 5190451, data_n: 8388608, link_m: 288358, link_n: 524288, tu: 64
<7> [141.393712] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0
<7> [141.393783] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: enabled
<7> [141.393853] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled
<7> [141.393922] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] psr: disabled, selective update: disabled, panel replay: disabled, selective fetch: disabled
<7> [141.394001] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0
<7> [141.394073] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] audio: 1, infoframes: 0, infoframes enabled: 0x0
<7> [141.394144] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 10 00 09 00 68 36 00 01 00 00 00 00 00 00 00 00
<7> [141.394215] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 61 a4 9a 00 44 50 46 39 30 34 33 35 09 07 07 11
<7> [141.394284] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 17 50 51 07 00 00 00 00
<7> [141.394354] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1
<7> [141.394423] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0
<7> [141.394492] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0
<7> [141.394562] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0
<7> [141.394631] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5
<7> [141.394701] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5
<7> [141.394771] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5
<7> [141.394842] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x40 0x5
<7> [141.394911] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5
<7> [141.394986] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port clock: 270000, pipe src: 1920x1080+0+0, pixel rate 148500
<7> [141.395058] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] linetime: 119, ips linetime: 0
<7> [141.395128] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0
<7> [141.395199] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [141.395270] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0
<7> [141.395339] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] dpll_hw_state: dpll: 0x41eb0, dpll_md: 0x4800be88, fp0: 0x5000000, fp1: 0x5
<7> [141.395409] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [141.395479] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [141.395549] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000
<7> [141.395619] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [141.395688] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [141.395757] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [141.395826] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000
<7> [141.395896] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [141.395971] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [141.396042] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [141.396111] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [141.396182] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000
<7> [141.396252] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:188:plane 1D] fb: [FB:295] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x0, visible: yes
<7> [141.396323] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [141.396393] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0
<7> [141.396463] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:197:plane 2D] fb: [NOFB], visible: no
<7> [141.396534] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:206:plane 3D] fb: [NOFB], visible: no
<7> [141.396604] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:215:plane 4D] fb: [NOFB], visible: no
<7> [141.396673] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:224:plane 5D] fb: [NOFB], visible: no
<7> [141.396743] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:233:cursor D] fb: [NOFB], visible: no
<7> [141.397224] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_2
<7> [141.397343] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_D
<7> [141.397469] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:240:DDI TC1/PHY F]
<7> [141.397542] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:242:DP-MST A]
<7> [141.397611] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:243:DP-MST B]
<7> [141.397679] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:244:DP-MST C]
<7> [141.397746] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:245:DP-MST D]
<7> [141.397811] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:259:DDI TC2/PHY G]
<7> [141.397876] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:261:DP-MST A]
<7> [141.397940] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:262:DP-MST B]
<7> [141.398013] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:263:DP-MST C]
<7> [141.398081] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:264:DP-MST D]
<7> [141.398147] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:271:DDI TC3/PHY H]
<7> [141.398212] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:275:DDI TC4/PHY I]
<7> [141.398275] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:277:DP-MST A]
<7> [141.398338] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:278:DP-MST B]
<7> [141.398400] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:279:DP-MST C]
<7> [141.398462] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:280:DP-MST D]
<7> [141.398526] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x3
<7> [141.398671] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no)
<7> [141.403283] xe 0000:03:00.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX USBC2/DDI TC2/PHY G: DPCD: 12 14 c4 01 01 15 01 81 00 01 04 01 0f 00 01
<7> [141.411314] xe 0000:03:00.0: [drm:intel_dp_init_lttpr_and_dprx_caps [xe]] [CONNECTOR:260:DP-2][ENCODER:259:DDI TC2/PHY G][DPRX] LTTPR common capabilities: 00 00 00 00 00 00 00 00
<7> [141.412445] xe 0000:03:00.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX USBC2/DDI TC2/PHY G: DPCD: 12 14 c4 01 01 15 01 81 00 01 04 01 0f 00 01
<7> [141.412814] xe 0000:03:00.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:260:DP-2][ENCODER:259:DDI TC2/PHY G][DPRX] Using LINK_BW_SET value 0a
<7> [141.414252] xe 0000:03:00.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:260:DP-2][ENCODER:259:DDI TC2/PHY G][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0
<7> [141.414539] xe 0000:03:00.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:260:DP-2][ENCODER:259:DDI TC2/PHY G][DPRX] Using DP training pattern TPS1
<7> [141.420991] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:260:DP-2][ENCODER:259:DDI TC2/PHY G][DPRX] Clock recovery OK
<7> [141.421083] xe 0000:03:00.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:260:DP-2][ENCODER:259:DDI TC2/PHY G][DPRX] Using DP training pattern TPS3
<7> [141.428001] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:260:DP-2][ENCODER:259:DDI TC2/PHY G][DPRX] Channel EQ done. DP Training successful
<7> [141.428129] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:260:DP-2][ENCODER:259:DDI TC2/PHY G][DPRX] Link Training passed at link rate = 270000, lane count = 4
<7> [141.428826] xe 0000:03:00.0: [drm:intel_enable_transcoder [xe]] enabling pipe D
<7> [141.446125] xe 0000:03:00.0: [drm:intel_audio_codec_enable [xe]] [CONNECTOR:260:DP-2][ENCODER:259:DDI TC2/PHY G] Enable audio codec on [CRTC:238:pipe D], 40 bytes ELD
<7> [141.462613] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:260:DP-2]
<7> [141.463221] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:238:pipe D]
<7> [141.532027] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2
<7> [143.490875] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2
<7> [143.594941] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2
<6> [145.152241] [IGT] kms_flip: finished subtest D-DP2, FAIL
Created at 2025-03-07 05:54:34