igt@kms_flip@flip-vs-expired-vblank-interruptible@c-dp2 on shard-bmg@xe-pw-164657v2 Test details

Detail	Value
Duration	3.62 seconds
Hostname	shard-bmg-3
Igt-Version	IGT-Version: 2.4-g93abaf017 (x86_64) (Linux: 7.0.0-lgci-xe-xe-pw-164657v2-debug+ x86_64)
Out	Starting dynamic subtest: C-DP2 1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest C-DP2: FAIL (3.620s)
Err	Starting dynamic subtest: C-DP2 (kms_flip:11462) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:11462) CRITICAL: Failed assertion: end - start < 500 (kms_flip:11462) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest C-DP2 failed. ** DEBUG (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.282532 last_received_ts = 628.282227 last_seq = 345 current_ts = 628.299194 current_received_ts = 628.298889 current_seq = 346 count = 44 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.299194 last_received_ts = 628.298889 last_seq = 346 current_ts = 628.315857 current_received_ts = 628.315491 current_seq = 347 count = 45 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.315857 last_received_ts = 628.315491 last_seq = 347 current_ts = 628.332520 current_received_ts = 628.332153 current_seq = 348 count = 46 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 628.332520 last_received_ts = 628.332153 last_seq = 348 current_ts = 628.349182 current_received_ts = 628.348816 current_seq = 349 count = 47 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 628.349182 last_received_ts = 628.348816 last_seq = 349 current_ts = 628.365906 current_received_ts = 628.365479 current_seq = 350 count = 48 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.365906 last_received_ts = 628.365479 last_seq = 350 current_ts = 628.382568 current_received_ts = 628.382141 current_seq = 351 count = 49 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 628.382568 last_received_ts = 628.382141 last_seq = 351 current_ts = 628.399231 current_received_ts = 628.398926 current_seq = 352 count = 50 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 27us (kms_flip:11462) DEBUG: name = flip last_ts = 628.399231 last_received_ts = 628.398926 last_seq = 352 current_ts = 628.415894 current_received_ts = 628.415527 current_seq = 353 count = 51 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.415894 last_received_ts = 628.415527 last_seq = 353 current_ts = 628.432556 current_received_ts = 628.432129 current_seq = 354 count = 52 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 628.432556 last_received_ts = 628.432129 last_seq = 354 current_ts = 628.449219 current_received_ts = 628.448853 current_seq = 355 count = 53 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 628.449219 last_received_ts = 628.448853 last_seq = 355 current_ts = 628.465881 current_received_ts = 628.465515 current_seq = 356 count = 54 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.465881 last_received_ts = 628.465515 last_seq = 356 current_ts = 628.482544 current_received_ts = 628.482178 current_seq = 357 count = 55 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 628.482544 last_received_ts = 628.482178 last_seq = 357 current_ts = 628.499207 current_received_ts = 628.498901 current_seq = 358 count = 56 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.499207 last_received_ts = 628.498901 last_seq = 358 current_ts = 628.515869 current_received_ts = 628.515503 current_seq = 359 count = 57 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 628.515869 last_received_ts = 628.515503 last_seq = 359 current_ts = 628.532593 current_received_ts = 628.532166 current_seq = 360 count = 58 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.532593 last_received_ts = 628.532166 last_seq = 360 current_ts = 628.549255 current_received_ts = 628.548828 current_seq = 361 count = 59 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.549255 last_received_ts = 628.548828 last_seq = 361 current_ts = 628.565918 current_received_ts = 628.565491 current_seq = 362 count = 60 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.565918 last_received_ts = 628.565491 last_seq = 362 current_ts = 628.582581 current_received_ts = 628.582153 current_seq = 363 count = 61 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.582581 last_received_ts = 628.582153 last_seq = 363 current_ts = 628.599243 current_received_ts = 628.598938 current_seq = 364 count = 62 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.599243 last_received_ts = 628.598938 last_seq = 364 current_ts = 628.615906 current_received_ts = 628.615540 current_seq = 365 count = 63 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 628.615906 last_received_ts = 628.615540 last_seq = 365 current_ts = 628.632568 current_received_ts = 628.632202 current_seq = 366 count = 64 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.632568 last_received_ts = 628.632202 last_seq = 366 current_ts = 628.649231 current_received_ts = 628.648865 current_seq = 367 count = 65 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.649231 last_received_ts = 628.648865 last_seq = 367 current_ts = 628.665894 current_received_ts = 628.665527 current_seq = 368 count = 66 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 628.665894 last_received_ts = 628.665527 last_seq = 368 current_ts = 628.682556 current_received_ts = 628.682190 current_seq = 369 count = 67 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 628.682556 last_received_ts = 628.682190 last_seq = 369 current_ts = 628.699219 current_received_ts = 628.698792 current_seq = 370 count = 68 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 628.699219 last_received_ts = 628.698792 last_seq = 370 current_ts = 628.715881 current_received_ts = 628.715576 current_seq = 371 count = 69 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.715881 last_received_ts = 628.715576 last_seq = 371 current_ts = 628.732544 current_received_ts = 628.732178 current_seq = 372 count = 70 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.732544 last_received_ts = 628.732178 last_seq = 372 current_ts = 628.749207 current_received_ts = 628.748901 current_seq = 373 count = 71 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.749207 last_received_ts = 628.748901 last_seq = 373 current_ts = 628.765930 current_received_ts = 628.765503 current_seq = 374 count = 72 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.765930 last_received_ts = 628.765503 last_seq = 374 current_ts = 628.782593 current_received_ts = 628.782166 current_seq = 375 count = 73 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 27us (kms_flip:11462) DEBUG: name = flip last_ts = 628.782593 last_received_ts = 628.782166 last_seq = 375 current_ts = 628.799255 current_received_ts = 628.798828 current_seq = 376 count = 74 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.799255 last_received_ts = 628.798828 last_seq = 376 current_ts = 628.815918 current_received_ts = 628.815613 current_seq = 377 count = 75 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.815918 last_received_ts = 628.815613 last_seq = 377 current_ts = 628.832581 current_received_ts = 628.832153 current_seq = 378 count = 76 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 628.832581 last_received_ts = 628.832153 last_seq = 378 current_ts = 628.849243 current_received_ts = 628.848816 current_seq = 379 count = 77 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.849243 last_received_ts = 628.848816 last_seq = 379 current_ts = 628.865906 current_received_ts = 628.865540 current_seq = 380 count = 78 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 628.865906 last_received_ts = 628.865540 last_seq = 380 current_ts = 628.882568 current_received_ts = 628.882202 current_seq = 381 count = 79 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.882568 last_received_ts = 628.882202 last_seq = 381 current_ts = 628.899231 current_received_ts = 628.898865 current_seq = 382 count = 80 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.899231 last_received_ts = 628.898865 last_seq = 382 current_ts = 628.915894 current_received_ts = 628.915527 current_seq = 383 count = 81 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 628.915894 last_received_ts = 628.915527 last_seq = 383 current_ts = 628.932556 current_received_ts = 628.932190 current_seq = 384 count = 82 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 628.932556 last_received_ts = 628.932190 last_seq = 384 current_ts = 628.949219 current_received_ts = 628.948853 current_seq = 385 count = 83 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.949219 last_received_ts = 628.948853 last_seq = 385 current_ts = 628.965881 current_received_ts = 628.965515 current_seq = 386 count = 84 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 628.965881 last_received_ts = 628.965515 last_seq = 386 current_ts = 628.982605 current_received_ts = 628.982300 current_seq = 387 count = 85 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 628.982605 last_received_ts = 628.982300 last_seq = 387 current_ts = 628.999268 current_received_ts = 628.998962 current_seq = 388 count = 86 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 628.999268 last_received_ts = 628.998962 last_seq = 388 current_ts = 629.015930 current_received_ts = 629.015564 current_seq = 389 count = 87 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.015930 last_received_ts = 629.015564 last_seq = 389 current_ts = 629.032593 current_received_ts = 629.032166 current_seq = 390 count = 88 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.032593 last_received_ts = 629.032166 last_seq = 390 current_ts = 629.049255 current_received_ts = 629.048889 current_seq = 391 count = 89 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.049255 last_received_ts = 629.048889 last_seq = 391 current_ts = 629.065918 current_received_ts = 629.065552 current_seq = 392 count = 90 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.065918 last_received_ts = 629.065552 last_seq = 392 current_ts = 629.082581 current_received_ts = 629.082214 current_seq = 393 count = 91 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 27us (kms_flip:11462) DEBUG: name = flip last_ts = 629.082581 last_received_ts = 629.082214 last_seq = 393 current_ts = 629.099243 current_received_ts = 629.098816 current_seq = 394 count = 92 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.099243 last_received_ts = 629.098816 last_seq = 394 current_ts = 629.115906 current_received_ts = 629.115601 current_seq = 395 count = 93 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.115906 last_received_ts = 629.115601 last_seq = 395 current_ts = 629.132568 current_received_ts = 629.132263 current_seq = 396 count = 94 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.132568 last_received_ts = 629.132263 last_seq = 396 current_ts = 629.149231 current_received_ts = 629.148926 current_seq = 397 count = 95 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.149231 last_received_ts = 629.148926 last_seq = 397 current_ts = 629.165894 current_received_ts = 629.165527 current_seq = 398 count = 96 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.165894 last_received_ts = 629.165527 last_seq = 398 current_ts = 629.182617 current_received_ts = 629.182190 current_seq = 399 count = 97 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.182617 last_received_ts = 629.182190 last_seq = 399 current_ts = 629.199280 current_received_ts = 629.198975 current_seq = 400 count = 98 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.199280 last_received_ts = 629.198975 last_seq = 400 current_ts = 629.215942 current_received_ts = 629.215515 current_seq = 401 count = 99 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.215942 last_received_ts = 629.215515 last_seq = 401 current_ts = 629.232605 current_received_ts = 629.232239 current_seq = 402 count = 100 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.232605 last_received_ts = 629.232239 last_seq = 402 current_ts = 629.249268 current_received_ts = 629.248901 current_seq = 403 count = 101 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.249268 last_received_ts = 629.248901 last_seq = 403 current_ts = 629.265930 current_received_ts = 629.265564 current_seq = 404 count = 102 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 24us (kms_flip:11462) DEBUG: name = flip last_ts = 629.265930 last_received_ts = 629.265564 last_seq = 404 current_ts = 629.282593 current_received_ts = 629.282227 current_seq = 405 count = 103 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.282593 last_received_ts = 629.282227 last_seq = 405 current_ts = 629.299255 current_received_ts = 629.298828 current_seq = 406 count = 104 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.299255 last_received_ts = 629.298828 last_seq = 406 current_ts = 629.315918 current_received_ts = 629.315613 current_seq = 407 count = 105 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.315918 last_received_ts = 629.315613 last_seq = 407 current_ts = 629.332581 current_received_ts = 629.332275 current_seq = 408 count = 106 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.332581 last_received_ts = 629.332275 last_seq = 408 current_ts = 629.349243 current_received_ts = 629.348938 current_seq = 409 count = 107 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.349243 last_received_ts = 629.348938 last_seq = 409 current_ts = 629.365906 current_received_ts = 629.365540 current_seq = 410 count = 108 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.365906 last_received_ts = 629.365540 last_seq = 410 current_ts = 629.382568 current_received_ts = 629.382202 current_seq = 411 count = 109 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.382568 last_received_ts = 629.382202 last_seq = 411 current_ts = 629.399292 current_received_ts = 629.398987 current_seq = 412 count = 110 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.399292 last_received_ts = 629.398987 last_seq = 412 current_ts = 629.415955 current_received_ts = 629.415588 current_seq = 413 count = 111 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.415955 last_received_ts = 629.415588 last_seq = 413 current_ts = 629.432617 current_received_ts = 629.432312 current_seq = 414 count = 112 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.432617 last_received_ts = 629.432312 last_seq = 414 current_ts = 629.449280 current_received_ts = 629.448975 current_seq = 415 count = 113 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.449280 last_received_ts = 629.448975 last_seq = 415 current_ts = 629.465942 current_received_ts = 629.465515 current_seq = 416 count = 114 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.465942 last_received_ts = 629.465515 last_seq = 416 current_ts = 629.482605 current_received_ts = 629.482239 current_seq = 417 count = 115 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.482605 last_received_ts = 629.482239 last_seq = 417 current_ts = 629.499268 current_received_ts = 629.498962 current_seq = 418 count = 116 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 57us (kms_flip:11462) DEBUG: name = flip last_ts = 629.499268 last_received_ts = 629.498962 last_seq = 418 current_ts = 629.515930 current_received_ts = 629.515564 current_seq = 419 count = 117 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.515930 last_received_ts = 629.515564 last_seq = 419 current_ts = 629.532593 current_received_ts = 629.532043 current_seq = 420 count = 118 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 38us (kms_flip:11462) DEBUG: name = flip last_ts = 629.532593 last_received_ts = 629.532043 last_seq = 420 current_ts = 629.549255 current_received_ts = 629.548950 current_seq = 421 count = 119 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 54us (kms_flip:11462) DEBUG: name = flip last_ts = 629.549255 last_received_ts = 629.548950 last_seq = 421 current_ts = 629.565918 current_received_ts = 629.565552 current_seq = 422 count = 120 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 28us (kms_flip:11462) DEBUG: name = flip last_ts = 629.565918 last_received_ts = 629.565552 last_seq = 422 current_ts = 629.582581 current_received_ts = 629.582214 current_seq = 423 count = 121 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.582581 last_received_ts = 629.582214 last_seq = 423 current_ts = 629.599243 current_received_ts = 629.598877 current_seq = 424 count = 122 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 28us (kms_flip:11462) DEBUG: name = flip last_ts = 629.599243 last_received_ts = 629.598877 last_seq = 424 current_ts = 629.615967 current_received_ts = 629.615601 current_seq = 425 count = 123 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.615967 last_received_ts = 629.615601 last_seq = 425 current_ts = 629.632629 current_received_ts = 629.632263 current_seq = 426 count = 124 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.632629 last_received_ts = 629.632263 last_seq = 426 current_ts = 629.649292 current_received_ts = 629.648926 current_seq = 427 count = 125 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.649292 last_received_ts = 629.648926 last_seq = 427 current_ts = 629.665955 current_received_ts = 629.665588 current_seq = 428 count = 126 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.665955 last_received_ts = 629.665588 last_seq = 428 current_ts = 629.682617 current_received_ts = 629.682312 current_seq = 429 count = 127 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.682617 last_received_ts = 629.682312 last_seq = 429 current_ts = 629.699280 current_received_ts = 629.698975 current_seq = 430 count = 128 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 60us (kms_flip:11462) DEBUG: name = flip last_ts = 629.699280 last_received_ts = 629.698975 last_seq = 430 current_ts = 629.715942 current_received_ts = 629.715637 current_seq = 431 count = 129 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.715942 last_received_ts = 629.715637 last_seq = 431 current_ts = 629.732605 current_received_ts = 629.732300 current_seq = 432 count = 130 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.732605 last_received_ts = 629.732300 last_seq = 432 current_ts = 629.749268 current_received_ts = 629.748962 current_seq = 433 count = 131 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 39us (kms_flip:11462) DEBUG: name = flip last_ts = 629.749268 last_received_ts = 629.748962 last_seq = 433 current_ts = 629.765930 current_received_ts = 629.765564 current_seq = 434 count = 132 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.765930 last_received_ts = 629.765564 last_seq = 434 current_ts = 629.782593 current_received_ts = 629.782227 current_seq = 435 count = 133 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.782593 last_received_ts = 629.782227 last_seq = 435 current_ts = 629.799255 current_received_ts = 629.799011 current_seq = 436 count = 134 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 49us (kms_flip:11462) DEBUG: name = flip last_ts = 629.799255 last_received_ts = 629.799011 last_seq = 436 current_ts = 629.815979 current_received_ts = 629.815552 current_seq = 437 count = 135 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.815979 last_received_ts = 629.815552 last_seq = 437 current_ts = 629.832642 current_received_ts = 629.832214 current_seq = 438 count = 136 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.832642 last_received_ts = 629.832214 last_seq = 438 current_ts = 629.849304 current_received_ts = 629.848938 current_seq = 439 count = 137 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.849304 last_received_ts = 629.848938 last_seq = 439 current_ts = 629.865967 current_received_ts = 629.865601 current_seq = 440 count = 138 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.865967 last_received_ts = 629.865601 last_seq = 440 current_ts = 629.882629 current_received_ts = 629.882263 current_seq = 441 count = 139 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.882629 last_received_ts = 629.882263 last_seq = 441 current_ts = 629.899292 current_received_ts = 629.898987 current_seq = 442 count = 140 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 41us (kms_flip:11462) DEBUG: name = flip last_ts = 629.899292 last_received_ts = 629.898987 last_seq = 442 current_ts = 629.915955 current_received_ts = 629.915649 current_seq = 443 count = 141 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.915955 last_received_ts = 629.915649 last_seq = 443 current_ts = 629.932617 current_received_ts = 629.932312 current_seq = 444 count = 142 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.932617 last_received_ts = 629.932312 last_seq = 444 current_ts = 629.949280 current_received_ts = 629.948975 current_seq = 445 count = 143 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 24us (kms_flip:11462) DEBUG: name = flip last_ts = 629.949280 last_received_ts = 629.948975 last_seq = 445 current_ts = 629.965942 current_received_ts = 629.965637 current_seq = 446 count = 144 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 629.965942 last_received_ts = 629.965637 last_seq = 446 current_ts = 629.982666 current_received_ts = 629.982361 current_seq = 447 count = 145 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 629.982666 last_received_ts = 629.982361 last_seq = 447 current_ts = 629.999268 current_received_ts = 629.999023 current_seq = 448 count = 146 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 24us (kms_flip:11462) DEBUG: name = flip last_ts = 629.999268 last_received_ts = 629.999023 last_seq = 448 current_ts = 630.015991 current_received_ts = 630.015686 current_seq = 449 count = 147 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 630.015991 last_received_ts = 630.015686 last_seq = 449 current_ts = 630.032654 current_received_ts = 630.032349 current_seq = 450 count = 148 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 630.032654 last_received_ts = 630.032349 last_seq = 450 current_ts = 630.049316 current_received_ts = 630.049011 current_seq = 451 count = 149 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 630.049316 last_received_ts = 630.049011 last_seq = 451 current_ts = 630.065979 current_received_ts = 630.065613 current_seq = 452 count = 150 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 630.065979 last_received_ts = 630.065613 last_seq = 452 current_ts = 630.082642 current_received_ts = 630.082275 current_seq = 453 count = 151 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 630.082642 last_received_ts = 630.082275 last_seq = 453 current_ts = 630.099304 current_received_ts = 630.098938 current_seq = 454 count = 152 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 630.099304 last_received_ts = 630.098938 last_seq = 454 current_ts = 630.115967 current_received_ts = 630.115601 current_seq = 455 count = 153 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 630.115967 last_received_ts = 630.115601 last_seq = 455 current_ts = 630.132629 current_received_ts = 630.132263 current_seq = 456 count = 154 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 24us (kms_flip:11462) DEBUG: name = flip last_ts = 630.132629 last_received_ts = 630.132263 last_seq = 456 current_ts = 630.149292 current_received_ts = 630.149048 current_seq = 457 count = 155 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 44us (kms_flip:11462) DEBUG: name = flip last_ts = 630.149292 last_received_ts = 630.149048 last_seq = 457 current_ts = 630.165955 current_received_ts = 630.165527 current_seq = 458 count = 156 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 630.165955 last_received_ts = 630.165527 last_seq = 458 current_ts = 630.182617 current_received_ts = 630.182251 current_seq = 459 count = 157 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 630.182617 last_received_ts = 630.182251 last_seq = 459 current_ts = 630.199280 current_received_ts = 630.198914 current_seq = 460 count = 158 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 630.199280 last_received_ts = 630.198914 last_seq = 460 current_ts = 630.216003 current_received_ts = 630.215576 current_seq = 461 count = 159 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 26us (kms_flip:11462) DEBUG: name = flip last_ts = 630.216003 last_received_ts = 630.215576 last_seq = 461 current_ts = 630.232666 current_received_ts = 630.232239 current_seq = 462 count = 160 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 25us (kms_flip:11462) DEBUG: name = flip last_ts = 630.232666 last_received_ts = 630.232239 last_seq = 462 current_ts = 630.249329 current_received_ts = 630.249084 current_seq = 463 count = 161 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 45us (kms_flip:11462) DEBUG: name = flip last_ts = 630.249329 last_received_ts = 630.249084 last_seq = 463 current_ts = 630.265991 current_received_ts = 630.265686 current_seq = 464 count = 162 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 36us (kms_flip:11462) DEBUG: name = flip last_ts = 630.265991 last_received_ts = 630.265686 last_seq = 464 current_ts = 630.282654 current_received_ts = 630.282349 current_seq = 465 count = 163 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 36us (kms_flip:11462) DEBUG: name = flip last_ts = 630.282654 last_received_ts = 630.282349 last_seq = 465 current_ts = 630.299316 current_received_ts = 630.299072 current_seq = 466 count = 164 seq_step = 1 (kms_flip:11462) DEBUG: Vblank took 1591us (kms_flip:11462) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:11462) CRITICAL: Failed assertion: end - start < 500 (kms_flip:11462) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:11462) igt_core-INFO: Stack trace: (kms_flip:11462) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:11462) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() (kms_flip:11462) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() (kms_flip:11462) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() (kms_flip:11462) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() (kms_flip:11462) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:11462) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:11462) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest C-DP2: FAIL (3.620s)
Dmesg	<6> [627.213773] [IGT] kms_flip: starting dynamic subtest C-DP2 <7> [627.216076] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:556] <7> [627.217284] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:558] <7> [627.261116] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [627.261232] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B] <7> [627.261297] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.enable (expected yes, found no) <7> [627.261422] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.active (expected yes, found no) <7> [627.261524] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in cpu_transcoder (expected 1, found -1) <7> [627.261637] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in lane_count (expected 4, found 0) <7> [627.261735] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] 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> [627.261833] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in output_types (expected 0x00000080, found 0x00000000) <7> [627.261937] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [627.262038] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [627.262138] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [627.262237] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [627.262334] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [627.262430] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [627.262527] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [627.262631] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [627.262727] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [627.262824] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0) <7> [627.262919] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0) <7> [627.263014] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [627.263109] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [627.263212] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [627.263313] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [627.263412] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [627.263510] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [627.263613] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [627.263710] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [627.263806] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [627.263900] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [627.263995] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0) <7> [627.264089] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0) <7> [627.264183] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [627.264277] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [627.264371] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [627.264465] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [627.264560] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0) <7> [627.264665] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in enhanced_framing (expected yes, found no) <7> [627.264761] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in pipe_bpp (expected 36, found 0) <7> [627.264855] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [627.264950] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [627.265044] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in port_clock (expected 270000, found 0) <7> [627.265140] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:269:pipe B] fastset requirement not met, forcing full modeset <7> [627.265235] xe 0000:03:00.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:269:pipe B] releasing TC PLL 2 <7> [627.265358] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [627.265442] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:269:pipe B] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x2 -> 0x0 <7> [627.265546] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:263:cursor B] ddb (4037 - 4096) -> ( 0 - 0), size 59 -> 0 <7> [627.265671] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:269:pipe B] min cdclk: 192000 kHz -> 0 kHz <7> [627.265805] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:269:pipe B] enable: no [modeset] <7> [627.265910] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:153:plane 1B] fb: [NOFB], visible: no <7> [627.266010] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:183:plane 2B] fb: [NOFB], visible: no <7> [627.266109] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:213:plane 3B] fb: [NOFB], visible: no <7> [627.266208] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:243:plane 4B] fb: [NOFB], visible: no <7> [627.266305] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:253:plane 5B] fb: [NOFB], visible: no <7> [627.266403] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:263:cursor B] fb: [NOFB], visible: no <7> [627.266811] xe 0000:03:00.0: [drm:intel_audio_codec_disable [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G] Disable audio codec on [CRTC:269:pipe B] <7> [627.291685] xe 0000:03:00.0: [drm:intel_disable_transcoder [xe]] disabling pipe B <7> [627.308835] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2 <7> [627.311735] xe 0000:03:00.0: [drm:intel_dpll_disable [xe]] disable TC PLL 2 (active 0x2, on? 1) for [CRTC:269:pipe B] <7> [627.314219] xe 0000:03:00.0: [drm:intel_dpll_disable [xe]] disabling TC PLL 2 <7> [627.315075] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:507:DDI TC1/PHY F] <7> [627.315508] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:509:DP-MST A] <7> [627.315975] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:510:DP-MST B] <7> [627.316357] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:511:DP-MST C] <7> [627.316744] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:512:DP-MST D] <7> [627.317128] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:526:DDI TC2/PHY G] <7> [627.317691] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:528:DP-MST A] <7> [627.318016] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:529:DP-MST B] <7> [627.318326] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:530:DP-MST C] <7> [627.318640] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:531:DP-MST D] <7> [627.318951] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:538:DDI TC3/PHY H] <7> [627.319223] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:542:DDI TC4/PHY I] <7> [627.319499] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:544:DP-MST A] <7> [627.319801] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:545:DP-MST B] <7> [627.320055] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:546:DP-MST C] <7> [627.320300] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:547:DP-MST D] <7> [627.320543] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:527:DP-2] <7> [627.321039] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no) <7> [627.321249] xe 0000:03:00.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [627.321676] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [627.322207] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_B <7> [627.322648] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [627.322886] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_2 <7> [627.323326] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:269:pipe B] <7> [627.323714] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C] <7> [627.324462] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:505:pipe D] <7> [627.324628] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C] <7> [627.324659] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:527:DP-2] <7> [627.324763] xe 0000:03:00.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:526:DDI TC2/PHY G][CRTC:387:pipe C] DP link limits: pixel clock 148500 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 36 min link_bpp 18.0000 max link_bpp 36.0000 <7> [627.324940] xe 0000:03:00.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 270000 bpp input 36 compressed 0.0000 HDR no link rate required 668250 available 1080000 <7> [627.325110] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:387:pipe C] hw max bpp: 36, pipe bpp: 36, dithering: 0 <7> [627.325287] xe 0000:03:00.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:526:DDI TC2/PHY G] [CRTC:387:pipe C] <7> [627.325447] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.enable (expected no, found yes) <7> [627.325608] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.active (expected no, found yes) <7> [627.325755] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2) <7> [627.325900] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in lane_count (expected 0, found 4) <7> [627.326044] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] 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> [627.326183] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in output_types (expected 0x00000000, found 0x00000080) <7> [627.326315] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [627.326446] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [627.326577] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [627.326699] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [627.326821] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [627.326946] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [627.327074] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [627.327193] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [627.327308] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [627.327419] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084) <7> [627.327530] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089) <7> [627.327645] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [627.327752] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [627.327860] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [627.327969] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [627.328067] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [627.328166] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [627.328262] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [627.328363] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [627.328462] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [627.328556] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [627.328665] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084) <7> [627.328759] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089) <7> [627.328855] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [627.328945] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [627.329032] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [627.329118] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [627.329204] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [627.329290] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in enhanced_framing (expected no, found yes) <7> [627.329376] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in dpll_hw_state <7> [627.329462] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] expected: <7> [627.329547] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no <7> [627.329646] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] c20pll_hw_state: <7> [627.329741] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] tx[0] = 0xbe88, tx[1] = 0x5800, tx[2] = 0x0000 <7> [627.329834] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [627.329920] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[0] = 0x40e8 <7> [627.330005] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[1] = 0x7d20 <7> [627.330090] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[2] = 0x0a06 <7> [627.330176] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[3] = 0x8f1c <7> [627.330261] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[4] = 0x0000 <7> [627.330346] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[5] = 0x0000 <7> [627.330432] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[6] = 0x2200 <7> [627.330518] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[7] = 0xffff <7> [627.330609] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[8] = 0x0400 <7> [627.330703] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[9] = 0x0000 <7> [627.330789] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[10] = 0x0001 <7> [627.330876] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] vdr: custom width: 0x00, serdes rate: 0x00, hdmi rate: 0x00 <7> [627.330963] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] found: <7> [627.331048] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no <7> [627.331132] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] c20pll_hw_state: <7> [627.331218] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] tx[0] = 0xbe88, tx[1] = 0x4800, tx[2] = 0x0000 <7> [627.331305] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [627.331394] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[0] = 0x308c <7> [627.331481] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[1] = 0x2110 <7> [627.331575] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[2] = 0xcc9c <7> [627.331672] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[3] = 0xbfc1 <7> [627.331765] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[4] = 0x4b9a <7> [627.331852] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[5] = 0x3f81 <7> [627.331940] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[6] = 0x2000 <7> [627.332027] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[7] = 0x0001 <7> [627.332113] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[8] = 0x5000 <7> [627.332199] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[9] = 0x0000 <7> [627.332285] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[10] = 0x0000 <7> [627.332370] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] vdr: custom width: 0x00, serdes rate: 0x42, hdmi rate: 0x00 <7> [627.332456] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 36) <7> [627.332539] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [627.332634] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [627.332728] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in port_clock (expected 0, found 270000) <7> [627.332821] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:387:pipe C] fastset requirement not met, forcing full modeset <7> [627.332924] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xd (total dbuf slices 0xf), mbus joined? no->no <7> [627.333001] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:387:pipe C] dbuf slices 0x0 -> 0xc, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4 <7> [627.333096] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:271:plane 1C] ddb ( 0 - 0) -> ( 0 - 1989), size 0 -> 1989 <7> [627.333171] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:381:cursor C] ddb ( 0 - 0) -> (1989 - 2048), size 0 -> 59 <7> [627.333245] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [627.333316] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 4, 9, 9, 17, 17, 17, 17, 0, 15, 0 <7> [627.333387] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 62, 62, 139, 139, 261, 261, 261, 261, 137, 230, 244 <7> [627.333456] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 123, 123, 245, 245, 367, 367, 0, 0, 138, 306, 306 <7> [627.333535] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] [CRTC:387:pipe C] data rate 594000 num active planes 1 <7> [627.333639] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 33600 required 624 qgv_peak_bw: 48000 <7> [627.333741] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 53000 required 624 qgv_peak_bw: 48000 <7> [627.333837] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 48000 for required data rate: 624 <7> [627.333935] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:387:pipe C] min cdclk: 0 kHz -> 192000 kHz <7> [627.334045] xe 0000:03:00.0: [drm:intel_find_dpll [xe]] [CRTC:387:pipe C] allocated TC PLL 2 <7> [627.334136] xe 0000:03:00.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:387:pipe C] reserving TC PLL 2 <7> [627.334224] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:387:pipe C] enable: yes [modeset] <7> [627.334317] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: DP (0x80), output format: RGB, sink format: RGB <7> [627.334409] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: C, pipe bpp: 36, dithering: 0 <7> [627.334499] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [627.334591] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [627.334688] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [627.334779] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [627.334868] 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> [627.334956] 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> [627.335042] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: enabled <7> [627.335129] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [627.335215] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] psr: disabled, selective update: disabled, panel replay: disabled, selective fetch: disabled <7> [627.335300] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [627.335386] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] audio: 1, infoframes: 0, infoframes enabled: 0x0 <7> [627.335477] 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> [627.335566] 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> [627.335701] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 17 50 51 07 00 00 00 00 <7> [627.335799] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [627.335894] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [627.335989] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1125, vmax: 1125, flipline: 1125, pipeline full: 0, guardband: 42 vsync start: 41, vsync end: 36 <7> [627.336085] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1083, vmax vblank: 1083, vmin vtotal: 1125, vmax vtotal: 1125 <7> [627.336180] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [627.336273] 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> [627.336369] 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> [627.336463] 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> [627.336557] 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> [627.336664] 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> [627.336758] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port clock: 270000, pixel rate 148500, min cdclk 192000, min voltage level 0 <7> [627.336852] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] linetime: 119, ips linetime: 0 <7> [627.336945] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [627.337039] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe src: 1920x1080+0+0 <7> [627.337135] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [627.337234] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [627.337334] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [627.337431] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no <7> [627.337527] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] c20pll_hw_state: <7> [627.337630] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] tx[0] = 0xbe88, tx[1] = 0x4800, tx[2] = 0x0000 <7> [627.337726] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [627.337821] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[0] = 0x308c <7> [627.337915] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[1] = 0x2110 <7> [627.338009] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[2] = 0xcc9c <7> [627.338102] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[3] = 0xbfc1 <7> [627.338196] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[4] = 0x4b9a <7> [627.338289] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[5] = 0x3f81 <7> [627.338382] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[6] = 0x2000 <7> [627.338475] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[7] = 0x0001 <7> [627.338566] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[8] = 0x5000 <7> [627.338671] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[9] = 0x0000 <7> [627.338764] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[10] = 0x0000 <7> [627.338858] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vdr: custom width: 0x00, serdes rate: 0x42, hdmi rate: 0x00 <7> [627.338951] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [627.339044] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [627.339139] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [627.339234] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [627.339334] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [627.339427] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [627.339528] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [627.339628] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [627.339721] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [627.339814] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [627.339907] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [627.340001] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [627.340095] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:271:plane 1C] fb: [FB:556] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [627.340190] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [627.340283] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [627.340376] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:301:plane 2C] fb: [NOFB], visible: no <7> [627.340471] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:331:plane 3C] fb: [NOFB], visible: no <7> [627.340568] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:361:plane 4C] fb: [NOFB], visible: no <7> [627.340678] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:371:plane 5C] fb: [NOFB], visible: no <7> [627.340773] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:381:cursor C] fb: [NOFB], visible: no <7> [627.341380] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [627.341493] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_C <7> [627.341618] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x4 (CLKGATE_DIS_DSSDSC=0x8a000000) <7> [627.341730] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:507:DDI TC1/PHY F] <7> [627.341823] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:509:DP-MST A] <7> [627.341914] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:510:DP-MST B] <7> [627.342004] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:511:DP-MST C] <7> [627.342095] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:512:DP-MST D] <7> [627.342184] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:526:DDI TC2/PHY G] <7> [627.342271] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:528:DP-MST A] <7> [627.342359] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:529:DP-MST B] <7> [627.342444] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:530:DP-MST C] <7> [627.342529] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:531:DP-MST D] <7> [627.342622] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:538:DDI TC3/PHY H] <7> [627.342708] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:542:DDI TC4/PHY I] <7> [627.342794] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:544:DP-MST A] <7> [627.342880] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:545:DP-MST B] <7> [627.342971] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:546:DP-MST C] <7> [627.343058] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:547:DP-MST D] <7> [627.343155] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xd <7> [627.343323] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no) <7> [627.343423] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enable TC PLL 2 (active 0x4, on? 0) for [CRTC:387:pipe C] <7> [627.343519] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enabling TC PLL 2 <7> [627.347525] 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> [627.352268] xe 0000:03:00.0: [drm:intel_dp_init_lttpr_and_dprx_caps [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] LTTPR common capabilities: 00 00 00 00 00 00 00 00 <7> [627.353287] 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> [627.353732] xe 0000:03:00.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using LINK_BW_SET value 0a <7> [627.355241] xe 0000:03:00.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [627.355802] xe 0000:03:00.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using DP training pattern TPS1 <7> [627.362471] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Clock recovery OK <7> [627.362591] xe 0000:03:00.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using DP training pattern TPS3 <7> [627.368520] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Channel EQ done. DP Training successful <7> [627.368660] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Link Training passed at link rate = 270000, lane count = 4 <7> [627.369905] xe 0000:03:00.0: [drm:intel_enable_transcoder [xe]] enabling pipe C <7> [627.387345] xe 0000:03:00.0: [drm:intel_audio_codec_enable [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G] Enable audio codec on [CRTC:387:pipe C], 40 bytes ELD <7> [627.404145] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:527:DP-2] <7> [627.405037] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:387:pipe C] <7> [627.472611] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2 <7> [629.400835] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2 <7> [629.504613] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2 <6> [630.851609] [IGT] kms_flip: finished subtest C-DP2, FAIL

Detail

Value

Duration

3.62 seconds

Hostname

shard-bmg-3

Igt-Version

IGT-Version: 2.4-g93abaf017 (x86_64) (Linux: 7.0.0-lgci-xe-xe-pw-164657v2-debug+ x86_64)

Out

Starting dynamic subtest: C-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-DP2: FAIL (3.620s)

Err

Starting dynamic subtest: C-DP2
(kms_flip:11462) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:11462) CRITICAL: Failed assertion: end - start < 500
(kms_flip:11462) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest C-DP2 failed.
**** DEBUG ****
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.282532
last_received_ts = 628.282227
last_seq = 345
current_ts = 628.299194
current_received_ts = 628.298889
current_seq = 346
count = 44
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.299194
last_received_ts = 628.298889
last_seq = 346
current_ts = 628.315857
current_received_ts = 628.315491
current_seq = 347
count = 45
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.315857
last_received_ts = 628.315491
last_seq = 347
current_ts = 628.332520
current_received_ts = 628.332153
current_seq = 348
count = 46
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.332520
last_received_ts = 628.332153
last_seq = 348
current_ts = 628.349182
current_received_ts = 628.348816
current_seq = 349
count = 47
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.349182
last_received_ts = 628.348816
last_seq = 349
current_ts = 628.365906
current_received_ts = 628.365479
current_seq = 350
count = 48
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.365906
last_received_ts = 628.365479
last_seq = 350
current_ts = 628.382568
current_received_ts = 628.382141
current_seq = 351
count = 49
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.382568
last_received_ts = 628.382141
last_seq = 351
current_ts = 628.399231
current_received_ts = 628.398926
current_seq = 352
count = 50
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 27us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.399231
last_received_ts = 628.398926
last_seq = 352
current_ts = 628.415894
current_received_ts = 628.415527
current_seq = 353
count = 51
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.415894
last_received_ts = 628.415527
last_seq = 353
current_ts = 628.432556
current_received_ts = 628.432129
current_seq = 354
count = 52
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.432556
last_received_ts = 628.432129
last_seq = 354
current_ts = 628.449219
current_received_ts = 628.448853
current_seq = 355
count = 53
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.449219
last_received_ts = 628.448853
last_seq = 355
current_ts = 628.465881
current_received_ts = 628.465515
current_seq = 356
count = 54
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.465881
last_received_ts = 628.465515
last_seq = 356
current_ts = 628.482544
current_received_ts = 628.482178
current_seq = 357
count = 55
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.482544
last_received_ts = 628.482178
last_seq = 357
current_ts = 628.499207
current_received_ts = 628.498901
current_seq = 358
count = 56
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.499207
last_received_ts = 628.498901
last_seq = 358
current_ts = 628.515869
current_received_ts = 628.515503
current_seq = 359
count = 57
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.515869
last_received_ts = 628.515503
last_seq = 359
current_ts = 628.532593
current_received_ts = 628.532166
current_seq = 360
count = 58
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.532593
last_received_ts = 628.532166
last_seq = 360
current_ts = 628.549255
current_received_ts = 628.548828
current_seq = 361
count = 59
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.549255
last_received_ts = 628.548828
last_seq = 361
current_ts = 628.565918
current_received_ts = 628.565491
current_seq = 362
count = 60
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.565918
last_received_ts = 628.565491
last_seq = 362
current_ts = 628.582581
current_received_ts = 628.582153
current_seq = 363
count = 61
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.582581
last_received_ts = 628.582153
last_seq = 363
current_ts = 628.599243
current_received_ts = 628.598938
current_seq = 364
count = 62
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.599243
last_received_ts = 628.598938
last_seq = 364
current_ts = 628.615906
current_received_ts = 628.615540
current_seq = 365
count = 63
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.615906
last_received_ts = 628.615540
last_seq = 365
current_ts = 628.632568
current_received_ts = 628.632202
current_seq = 366
count = 64
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.632568
last_received_ts = 628.632202
last_seq = 366
current_ts = 628.649231
current_received_ts = 628.648865
current_seq = 367
count = 65
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.649231
last_received_ts = 628.648865
last_seq = 367
current_ts = 628.665894
current_received_ts = 628.665527
current_seq = 368
count = 66
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.665894
last_received_ts = 628.665527
last_seq = 368
current_ts = 628.682556
current_received_ts = 628.682190
current_seq = 369
count = 67
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.682556
last_received_ts = 628.682190
last_seq = 369
current_ts = 628.699219
current_received_ts = 628.698792
current_seq = 370
count = 68
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.699219
last_received_ts = 628.698792
last_seq = 370
current_ts = 628.715881
current_received_ts = 628.715576
current_seq = 371
count = 69
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.715881
last_received_ts = 628.715576
last_seq = 371
current_ts = 628.732544
current_received_ts = 628.732178
current_seq = 372
count = 70
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.732544
last_received_ts = 628.732178
last_seq = 372
current_ts = 628.749207
current_received_ts = 628.748901
current_seq = 373
count = 71
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.749207
last_received_ts = 628.748901
last_seq = 373
current_ts = 628.765930
current_received_ts = 628.765503
current_seq = 374
count = 72
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.765930
last_received_ts = 628.765503
last_seq = 374
current_ts = 628.782593
current_received_ts = 628.782166
current_seq = 375
count = 73
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 27us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.782593
last_received_ts = 628.782166
last_seq = 375
current_ts = 628.799255
current_received_ts = 628.798828
current_seq = 376
count = 74
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.799255
last_received_ts = 628.798828
last_seq = 376
current_ts = 628.815918
current_received_ts = 628.815613
current_seq = 377
count = 75
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.815918
last_received_ts = 628.815613
last_seq = 377
current_ts = 628.832581
current_received_ts = 628.832153
current_seq = 378
count = 76
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.832581
last_received_ts = 628.832153
last_seq = 378
current_ts = 628.849243
current_received_ts = 628.848816
current_seq = 379
count = 77
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.849243
last_received_ts = 628.848816
last_seq = 379
current_ts = 628.865906
current_received_ts = 628.865540
current_seq = 380
count = 78
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.865906
last_received_ts = 628.865540
last_seq = 380
current_ts = 628.882568
current_received_ts = 628.882202
current_seq = 381
count = 79
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.882568
last_received_ts = 628.882202
last_seq = 381
current_ts = 628.899231
current_received_ts = 628.898865
current_seq = 382
count = 80
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.899231
last_received_ts = 628.898865
last_seq = 382
current_ts = 628.915894
current_received_ts = 628.915527
current_seq = 383
count = 81
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.915894
last_received_ts = 628.915527
last_seq = 383
current_ts = 628.932556
current_received_ts = 628.932190
current_seq = 384
count = 82
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.932556
last_received_ts = 628.932190
last_seq = 384
current_ts = 628.949219
current_received_ts = 628.948853
current_seq = 385
count = 83
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.949219
last_received_ts = 628.948853
last_seq = 385
current_ts = 628.965881
current_received_ts = 628.965515
current_seq = 386
count = 84
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.965881
last_received_ts = 628.965515
last_seq = 386
current_ts = 628.982605
current_received_ts = 628.982300
current_seq = 387
count = 85
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.982605
last_received_ts = 628.982300
last_seq = 387
current_ts = 628.999268
current_received_ts = 628.998962
current_seq = 388
count = 86
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 628.999268
last_received_ts = 628.998962
last_seq = 388
current_ts = 629.015930
current_received_ts = 629.015564
current_seq = 389
count = 87
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.015930
last_received_ts = 629.015564
last_seq = 389
current_ts = 629.032593
current_received_ts = 629.032166
current_seq = 390
count = 88
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.032593
last_received_ts = 629.032166
last_seq = 390
current_ts = 629.049255
current_received_ts = 629.048889
current_seq = 391
count = 89
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.049255
last_received_ts = 629.048889
last_seq = 391
current_ts = 629.065918
current_received_ts = 629.065552
current_seq = 392
count = 90
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.065918
last_received_ts = 629.065552
last_seq = 392
current_ts = 629.082581
current_received_ts = 629.082214
current_seq = 393
count = 91
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 27us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.082581
last_received_ts = 629.082214
last_seq = 393
current_ts = 629.099243
current_received_ts = 629.098816
current_seq = 394
count = 92
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.099243
last_received_ts = 629.098816
last_seq = 394
current_ts = 629.115906
current_received_ts = 629.115601
current_seq = 395
count = 93
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.115906
last_received_ts = 629.115601
last_seq = 395
current_ts = 629.132568
current_received_ts = 629.132263
current_seq = 396
count = 94
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.132568
last_received_ts = 629.132263
last_seq = 396
current_ts = 629.149231
current_received_ts = 629.148926
current_seq = 397
count = 95
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.149231
last_received_ts = 629.148926
last_seq = 397
current_ts = 629.165894
current_received_ts = 629.165527
current_seq = 398
count = 96
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.165894
last_received_ts = 629.165527
last_seq = 398
current_ts = 629.182617
current_received_ts = 629.182190
current_seq = 399
count = 97
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.182617
last_received_ts = 629.182190
last_seq = 399
current_ts = 629.199280
current_received_ts = 629.198975
current_seq = 400
count = 98
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.199280
last_received_ts = 629.198975
last_seq = 400
current_ts = 629.215942
current_received_ts = 629.215515
current_seq = 401
count = 99
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.215942
last_received_ts = 629.215515
last_seq = 401
current_ts = 629.232605
current_received_ts = 629.232239
current_seq = 402
count = 100
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.232605
last_received_ts = 629.232239
last_seq = 402
current_ts = 629.249268
current_received_ts = 629.248901
current_seq = 403
count = 101
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.249268
last_received_ts = 629.248901
last_seq = 403
current_ts = 629.265930
current_received_ts = 629.265564
current_seq = 404
count = 102
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 24us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.265930
last_received_ts = 629.265564
last_seq = 404
current_ts = 629.282593
current_received_ts = 629.282227
current_seq = 405
count = 103
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.282593
last_received_ts = 629.282227
last_seq = 405
current_ts = 629.299255
current_received_ts = 629.298828
current_seq = 406
count = 104
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.299255
last_received_ts = 629.298828
last_seq = 406
current_ts = 629.315918
current_received_ts = 629.315613
current_seq = 407
count = 105
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.315918
last_received_ts = 629.315613
last_seq = 407
current_ts = 629.332581
current_received_ts = 629.332275
current_seq = 408
count = 106
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.332581
last_received_ts = 629.332275
last_seq = 408
current_ts = 629.349243
current_received_ts = 629.348938
current_seq = 409
count = 107
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.349243
last_received_ts = 629.348938
last_seq = 409
current_ts = 629.365906
current_received_ts = 629.365540
current_seq = 410
count = 108
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.365906
last_received_ts = 629.365540
last_seq = 410
current_ts = 629.382568
current_received_ts = 629.382202
current_seq = 411
count = 109
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.382568
last_received_ts = 629.382202
last_seq = 411
current_ts = 629.399292
current_received_ts = 629.398987
current_seq = 412
count = 110
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.399292
last_received_ts = 629.398987
last_seq = 412
current_ts = 629.415955
current_received_ts = 629.415588
current_seq = 413
count = 111
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.415955
last_received_ts = 629.415588
last_seq = 413
current_ts = 629.432617
current_received_ts = 629.432312
current_seq = 414
count = 112
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.432617
last_received_ts = 629.432312
last_seq = 414
current_ts = 629.449280
current_received_ts = 629.448975
current_seq = 415
count = 113
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.449280
last_received_ts = 629.448975
last_seq = 415
current_ts = 629.465942
current_received_ts = 629.465515
current_seq = 416
count = 114
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.465942
last_received_ts = 629.465515
last_seq = 416
current_ts = 629.482605
current_received_ts = 629.482239
current_seq = 417
count = 115
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.482605
last_received_ts = 629.482239
last_seq = 417
current_ts = 629.499268
current_received_ts = 629.498962
current_seq = 418
count = 116
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 57us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.499268
last_received_ts = 629.498962
last_seq = 418
current_ts = 629.515930
current_received_ts = 629.515564
current_seq = 419
count = 117
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.515930
last_received_ts = 629.515564
last_seq = 419
current_ts = 629.532593
current_received_ts = 629.532043
current_seq = 420
count = 118
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 38us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.532593
last_received_ts = 629.532043
last_seq = 420
current_ts = 629.549255
current_received_ts = 629.548950
current_seq = 421
count = 119
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 54us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.549255
last_received_ts = 629.548950
last_seq = 421
current_ts = 629.565918
current_received_ts = 629.565552
current_seq = 422
count = 120
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 28us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.565918
last_received_ts = 629.565552
last_seq = 422
current_ts = 629.582581
current_received_ts = 629.582214
current_seq = 423
count = 121
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.582581
last_received_ts = 629.582214
last_seq = 423
current_ts = 629.599243
current_received_ts = 629.598877
current_seq = 424
count = 122
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 28us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.599243
last_received_ts = 629.598877
last_seq = 424
current_ts = 629.615967
current_received_ts = 629.615601
current_seq = 425
count = 123
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.615967
last_received_ts = 629.615601
last_seq = 425
current_ts = 629.632629
current_received_ts = 629.632263
current_seq = 426
count = 124
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.632629
last_received_ts = 629.632263
last_seq = 426
current_ts = 629.649292
current_received_ts = 629.648926
current_seq = 427
count = 125
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.649292
last_received_ts = 629.648926
last_seq = 427
current_ts = 629.665955
current_received_ts = 629.665588
current_seq = 428
count = 126
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.665955
last_received_ts = 629.665588
last_seq = 428
current_ts = 629.682617
current_received_ts = 629.682312
current_seq = 429
count = 127
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.682617
last_received_ts = 629.682312
last_seq = 429
current_ts = 629.699280
current_received_ts = 629.698975
current_seq = 430
count = 128
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 60us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.699280
last_received_ts = 629.698975
last_seq = 430
current_ts = 629.715942
current_received_ts = 629.715637
current_seq = 431
count = 129
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.715942
last_received_ts = 629.715637
last_seq = 431
current_ts = 629.732605
current_received_ts = 629.732300
current_seq = 432
count = 130
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.732605
last_received_ts = 629.732300
last_seq = 432
current_ts = 629.749268
current_received_ts = 629.748962
current_seq = 433
count = 131
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 39us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.749268
last_received_ts = 629.748962
last_seq = 433
current_ts = 629.765930
current_received_ts = 629.765564
current_seq = 434
count = 132
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.765930
last_received_ts = 629.765564
last_seq = 434
current_ts = 629.782593
current_received_ts = 629.782227
current_seq = 435
count = 133
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.782593
last_received_ts = 629.782227
last_seq = 435
current_ts = 629.799255
current_received_ts = 629.799011
current_seq = 436
count = 134
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 49us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.799255
last_received_ts = 629.799011
last_seq = 436
current_ts = 629.815979
current_received_ts = 629.815552
current_seq = 437
count = 135
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.815979
last_received_ts = 629.815552
last_seq = 437
current_ts = 629.832642
current_received_ts = 629.832214
current_seq = 438
count = 136
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.832642
last_received_ts = 629.832214
last_seq = 438
current_ts = 629.849304
current_received_ts = 629.848938
current_seq = 439
count = 137
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.849304
last_received_ts = 629.848938
last_seq = 439
current_ts = 629.865967
current_received_ts = 629.865601
current_seq = 440
count = 138
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.865967
last_received_ts = 629.865601
last_seq = 440
current_ts = 629.882629
current_received_ts = 629.882263
current_seq = 441
count = 139
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.882629
last_received_ts = 629.882263
last_seq = 441
current_ts = 629.899292
current_received_ts = 629.898987
current_seq = 442
count = 140
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 41us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.899292
last_received_ts = 629.898987
last_seq = 442
current_ts = 629.915955
current_received_ts = 629.915649
current_seq = 443
count = 141
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.915955
last_received_ts = 629.915649
last_seq = 443
current_ts = 629.932617
current_received_ts = 629.932312
current_seq = 444
count = 142
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.932617
last_received_ts = 629.932312
last_seq = 444
current_ts = 629.949280
current_received_ts = 629.948975
current_seq = 445
count = 143
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 24us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.949280
last_received_ts = 629.948975
last_seq = 445
current_ts = 629.965942
current_received_ts = 629.965637
current_seq = 446
count = 144
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.965942
last_received_ts = 629.965637
last_seq = 446
current_ts = 629.982666
current_received_ts = 629.982361
current_seq = 447
count = 145
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.982666
last_received_ts = 629.982361
last_seq = 447
current_ts = 629.999268
current_received_ts = 629.999023
current_seq = 448
count = 146
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 24us
(kms_flip:11462) DEBUG: name = flip
last_ts = 629.999268
last_received_ts = 629.999023
last_seq = 448
current_ts = 630.015991
current_received_ts = 630.015686
current_seq = 449
count = 147
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 630.015991
last_received_ts = 630.015686
last_seq = 449
current_ts = 630.032654
current_received_ts = 630.032349
current_seq = 450
count = 148
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 630.032654
last_received_ts = 630.032349
last_seq = 450
current_ts = 630.049316
current_received_ts = 630.049011
current_seq = 451
count = 149
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 630.049316
last_received_ts = 630.049011
last_seq = 451
current_ts = 630.065979
current_received_ts = 630.065613
current_seq = 452
count = 150
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 630.065979
last_received_ts = 630.065613
last_seq = 452
current_ts = 630.082642
current_received_ts = 630.082275
current_seq = 453
count = 151
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 630.082642
last_received_ts = 630.082275
last_seq = 453
current_ts = 630.099304
current_received_ts = 630.098938
current_seq = 454
count = 152
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 630.099304
last_received_ts = 630.098938
last_seq = 454
current_ts = 630.115967
current_received_ts = 630.115601
current_seq = 455
count = 153
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 630.115967
last_received_ts = 630.115601
last_seq = 455
current_ts = 630.132629
current_received_ts = 630.132263
current_seq = 456
count = 154
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 24us
(kms_flip:11462) DEBUG: name = flip
last_ts = 630.132629
last_received_ts = 630.132263
last_seq = 456
current_ts = 630.149292
current_received_ts = 630.149048
current_seq = 457
count = 155
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 44us
(kms_flip:11462) DEBUG: name = flip
last_ts = 630.149292
last_received_ts = 630.149048
last_seq = 457
current_ts = 630.165955
current_received_ts = 630.165527
current_seq = 458
count = 156
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 630.165955
last_received_ts = 630.165527
last_seq = 458
current_ts = 630.182617
current_received_ts = 630.182251
current_seq = 459
count = 157
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 630.182617
last_received_ts = 630.182251
last_seq = 459
current_ts = 630.199280
current_received_ts = 630.198914
current_seq = 460
count = 158
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 630.199280
last_received_ts = 630.198914
last_seq = 460
current_ts = 630.216003
current_received_ts = 630.215576
current_seq = 461
count = 159
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 26us
(kms_flip:11462) DEBUG: name = flip
last_ts = 630.216003
last_received_ts = 630.215576
last_seq = 461
current_ts = 630.232666
current_received_ts = 630.232239
current_seq = 462
count = 160
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 25us
(kms_flip:11462) DEBUG: name = flip
last_ts = 630.232666
last_received_ts = 630.232239
last_seq = 462
current_ts = 630.249329
current_received_ts = 630.249084
current_seq = 463
count = 161
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 45us
(kms_flip:11462) DEBUG: name = flip
last_ts = 630.249329
last_received_ts = 630.249084
last_seq = 463
current_ts = 630.265991
current_received_ts = 630.265686
current_seq = 464
count = 162
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 36us
(kms_flip:11462) DEBUG: name = flip
last_ts = 630.265991
last_received_ts = 630.265686
last_seq = 464
current_ts = 630.282654
current_received_ts = 630.282349
current_seq = 465
count = 163
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 36us
(kms_flip:11462) DEBUG: name = flip
last_ts = 630.282654
last_received_ts = 630.282349
last_seq = 465
current_ts = 630.299316
current_received_ts = 630.299072
current_seq = 466
count = 164
seq_step = 1
(kms_flip:11462) DEBUG: Vblank took 1591us
(kms_flip:11462) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:11462) CRITICAL: Failed assertion: end - start < 500
(kms_flip:11462) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:11462) igt_core-INFO: Stack trace:
(kms_flip:11462) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:11462) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
(kms_flip:11462) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
(kms_flip:11462) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
(kms_flip:11462) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
(kms_flip:11462) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:11462) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:11462) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-DP2: FAIL (3.620s)

Dmesg

<6> [627.213773] [IGT] kms_flip: starting dynamic subtest C-DP2

<7> [627.216076] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:556]

<7> [627.217284] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:558]

<7> [627.261116] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A]

<7> [627.261232] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B]

<7> [627.261297] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.enable (expected yes, found no)

<7> [627.261422] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.active (expected yes, found no)

<7> [627.261524] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in cpu_transcoder (expected 1, found -1)

<7> [627.261637] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in lane_count (expected 4, found 0)

<7> [627.261735] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] 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> [627.261833] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in output_types (expected 0x00000080, found 0x00000000)

<7> [627.261937] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0)

<7> [627.262038] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0)

<7> [627.262138] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0)

<7> [627.262237] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0)

<7> [627.262334] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0)

<7> [627.262430] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0)

<7> [627.262527] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0)

<7> [627.262631] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0)

<7> [627.262727] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0)

<7> [627.262824] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0)

<7> [627.262919] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0)

<7> [627.263014] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0)

<7> [627.263109] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0)

<7> [627.263212] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0)

<7> [627.263313] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0)

<7> [627.263412] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0)

<7> [627.263510] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0)

<7> [627.263613] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0)

<7> [627.263710] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0)

<7> [627.263806] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0)

<7> [627.263900] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0)

<7> [627.263995] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0)

<7> [627.264089] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0)

<7> [627.264183] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0)

<7> [627.264277] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0)

<7> [627.264371] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0)

<7> [627.264465] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0)

<7> [627.264560] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0)

<7> [627.264665] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in enhanced_framing (expected yes, found no)

<7> [627.264761] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in pipe_bpp (expected 36, found 0)

<7> [627.264855] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0)

<7> [627.264950] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0)

<7> [627.265044] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in port_clock (expected 270000, found 0)

<7> [627.265140] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:269:pipe B] fastset requirement not met, forcing full modeset

<7> [627.265235] xe 0000:03:00.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:269:pipe B] releasing TC PLL 2

<7> [627.265358] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no

<7> [627.265442] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:269:pipe B] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x2 -> 0x0

<7> [627.265546] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:263:cursor B] ddb (4037 - 4096) -> ( 0 - 0), size 59 -> 0

<7> [627.265671] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:269:pipe B] min cdclk: 192000 kHz -> 0 kHz

<7> [627.265805] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:269:pipe B] enable: no [modeset]

<7> [627.265910] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:153:plane 1B] fb: [NOFB], visible: no

<7> [627.266010] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:183:plane 2B] fb: [NOFB], visible: no

<7> [627.266109] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:213:plane 3B] fb: [NOFB], visible: no

<7> [627.266208] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:243:plane 4B] fb: [NOFB], visible: no

<7> [627.266305] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:253:plane 5B] fb: [NOFB], visible: no

<7> [627.266403] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:263:cursor B] fb: [NOFB], visible: no

<7> [627.266811] xe 0000:03:00.0: [drm:intel_audio_codec_disable [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G] Disable audio codec on [CRTC:269:pipe B]

<7> [627.291685] xe 0000:03:00.0: [drm:intel_disable_transcoder [xe]] disabling pipe B

<7> [627.308835] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2

<7> [627.311735] xe 0000:03:00.0: [drm:intel_dpll_disable [xe]] disable TC PLL 2 (active 0x2, on? 1) for [CRTC:269:pipe B]

<7> [627.314219] xe 0000:03:00.0: [drm:intel_dpll_disable [xe]] disabling TC PLL 2

<7> [627.315075] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:507:DDI TC1/PHY F]

<7> [627.315508] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:509:DP-MST A]

<7> [627.315975] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:510:DP-MST B]

<7> [627.316357] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:511:DP-MST C]

<7> [627.316744] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:512:DP-MST D]

<7> [627.317128] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:526:DDI TC2/PHY G]

<7> [627.317691] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:528:DP-MST A]

<7> [627.318016] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:529:DP-MST B]

<7> [627.318326] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:530:DP-MST C]

<7> [627.318640] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:531:DP-MST D]

<7> [627.318951] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:538:DDI TC3/PHY H]

<7> [627.319223] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:542:DDI TC4/PHY I]

<7> [627.319499] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:544:DP-MST A]

<7> [627.319801] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:545:DP-MST B]

<7> [627.320055] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:546:DP-MST C]

<7> [627.320300] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:547:DP-MST D]

<7> [627.320543] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:527:DP-2]

<7> [627.321039] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no)

<7> [627.321249] xe 0000:03:00.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: *)

<7> [627.321676] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1

<7> [627.322207] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_B

<7> [627.322648] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xaa000000)

<7> [627.322886] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_2

<7> [627.323326] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:269:pipe B]

<7> [627.323714] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C]

<7> [627.324462] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:505:pipe D]

<7> [627.324628] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C]

<7> [627.324659] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:527:DP-2]

<7> [627.324763] xe 0000:03:00.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:526:DDI TC2/PHY G][CRTC:387:pipe C] DP link limits: pixel clock 148500 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 36 min link_bpp 18.0000 max link_bpp 36.0000

<7> [627.324940] xe 0000:03:00.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 270000 bpp input 36 compressed 0.0000 HDR no link rate required 668250 available 1080000

<7> [627.325110] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:387:pipe C] hw max bpp: 36, pipe bpp: 36, dithering: 0

<7> [627.325287] xe 0000:03:00.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:526:DDI TC2/PHY G] [CRTC:387:pipe C]

<7> [627.325447] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.enable (expected no, found yes)

<7> [627.325608] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.active (expected no, found yes)

<7> [627.325755] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2)

<7> [627.325900] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in lane_count (expected 0, found 4)

<7> [627.326044] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] 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> [627.326183] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in output_types (expected 0x00000000, found 0x00000080)

<7> [627.326315] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in framestart_delay (expected 0, found 1)

<7> [627.326446] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920)

<7> [627.326577] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200)

<7> [627.326699] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920)

<7> [627.326821] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200)

<7> [627.326946] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008)

<7> [627.327074] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052)

<7> [627.327193] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080)

<7> [627.327308] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080)

<7> [627.327419] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084)

<7> [627.327530] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089)

<7> [627.327645] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125)

<7> [627.327752] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125)

<7> [627.327860] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920)

<7> [627.327969] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200)

<7> [627.328067] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920)

<7> [627.328166] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200)

<7> [627.328262] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008)

<7> [627.328363] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052)

<7> [627.328462] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080)

<7> [627.328556] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080)

<7> [627.328665] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084)

<7> [627.328759] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089)

<7> [627.328855] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125)

<7> [627.328945] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125)

<7> [627.329032] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in pixel_multiplier (expected 0, found 1)

<7> [627.329118] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1)

<7> [627.329204] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4)

<7> [627.329290] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in enhanced_framing (expected no, found yes)

<7> [627.329376] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in dpll_hw_state

<7> [627.329462] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] expected:

<7> [627.329547] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no

<7> [627.329646] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] c20pll_hw_state:

<7> [627.329741] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] tx[0] = 0xbe88, tx[1] = 0x5800, tx[2] = 0x0000

<7> [627.329834] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000

<7> [627.329920] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[0] = 0x40e8

<7> [627.330005] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[1] = 0x7d20

<7> [627.330090] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[2] = 0x0a06

<7> [627.330176] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[3] = 0x8f1c

<7> [627.330261] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[4] = 0x0000

<7> [627.330346] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[5] = 0x0000

<7> [627.330432] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[6] = 0x2200

<7> [627.330518] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[7] = 0xffff

<7> [627.330609] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[8] = 0x0400

<7> [627.330703] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[9] = 0x0000

<7> [627.330789] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[10] = 0x0001

<7> [627.330876] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] vdr: custom width: 0x00, serdes rate: 0x00, hdmi rate: 0x00

<7> [627.330963] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] found:

<7> [627.331048] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no

<7> [627.331132] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] c20pll_hw_state:

<7> [627.331218] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] tx[0] = 0xbe88, tx[1] = 0x4800, tx[2] = 0x0000

<7> [627.331305] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000

<7> [627.331394] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[0] = 0x308c

<7> [627.331481] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[1] = 0x2110

<7> [627.331575] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[2] = 0xcc9c

<7> [627.331672] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[3] = 0xbfc1

<7> [627.331765] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[4] = 0x4b9a

<7> [627.331852] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[5] = 0x3f81

<7> [627.331940] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[6] = 0x2000

<7> [627.332027] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[7] = 0x0001

<7> [627.332113] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[8] = 0x5000

<7> [627.332199] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[9] = 0x0000

<7> [627.332285] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[10] = 0x0000

<7> [627.332370] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] vdr: custom width: 0x00, serdes rate: 0x42, hdmi rate: 0x00

<7> [627.332456] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 36)

<7> [627.332539] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500)

<7> [627.332634] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500)

<7> [627.332728] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in port_clock (expected 0, found 270000)

<7> [627.332821] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:387:pipe C] fastset requirement not met, forcing full modeset

<7> [627.332924] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xd (total dbuf slices 0xf), mbus joined? no->no

<7> [627.333001] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:387:pipe C] dbuf slices 0x0 -> 0xc, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4

<7> [627.333096] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:271:plane 1C] ddb ( 0 - 0) -> ( 0 - 1989), size 0 -> 1989

<7> [627.333171] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:381:cursor C] ddb ( 0 - 0) -> (1989 - 2048), size 0 -> 59

<7> [627.333245] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm

<7> [627.333316] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 4, 9, 9, 17, 17, 17, 17, 0, 15, 0

<7> [627.333387] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 62, 62, 139, 139, 261, 261, 261, 261, 137, 230, 244

<7> [627.333456] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 123, 123, 245, 245, 367, 367, 0, 0, 138, 306, 306

<7> [627.333535] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] [CRTC:387:pipe C] data rate 594000 num active planes 1

<7> [627.333639] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 33600 required 624 qgv_peak_bw: 48000

<7> [627.333741] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 53000 required 624 qgv_peak_bw: 48000

<7> [627.333837] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 48000 for required data rate: 624

<7> [627.333935] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:387:pipe C] min cdclk: 0 kHz -> 192000 kHz

<7> [627.334045] xe 0000:03:00.0: [drm:intel_find_dpll [xe]] [CRTC:387:pipe C] allocated TC PLL 2

<7> [627.334136] xe 0000:03:00.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:387:pipe C] reserving TC PLL 2

<7> [627.334224] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:387:pipe C] enable: yes [modeset]

<7> [627.334317] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: DP (0x80), output format: RGB, sink format: RGB

<7> [627.334409] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: C, pipe bpp: 36, dithering: 0

<7> [627.334499] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid>

<7> [627.334591] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0

<7> [627.334688] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0

<7> [627.334779] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0

<7> [627.334868] 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> [627.334956] 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> [627.335042] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: enabled

<7> [627.335129] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled

<7> [627.335215] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] psr: disabled, selective update: disabled, panel replay: disabled, selective fetch: disabled

<7> [627.335300] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0

<7> [627.335386] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] audio: 1, infoframes: 0, infoframes enabled: 0x0

<7> [627.335477] 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> [627.335566] 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> [627.335701] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 17 50 51 07 00 00 00 00

<7> [627.335799] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1

<7> [627.335894] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0

<7> [627.335989] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1125, vmax: 1125, flipline: 1125, pipeline full: 0, guardband: 42 vsync start: 41, vsync end: 36

<7> [627.336085] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1083, vmax vblank: 1083, vmin vtotal: 1125, vmax vtotal: 1125

<7> [627.336180] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0

<7> [627.336273] 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> [627.336369] 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> [627.336463] 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> [627.336557] 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> [627.336664] 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> [627.336758] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port clock: 270000, pixel rate 148500, min cdclk 192000, min voltage level 0

<7> [627.336852] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] linetime: 119, ips linetime: 0

<7> [627.336945] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0

<7> [627.337039] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe src: 1920x1080+0+0

<7> [627.337135] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no

<7> [627.337234] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0

<7> [627.337334] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0

<7> [627.337431] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no

<7> [627.337527] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] c20pll_hw_state:

<7> [627.337630] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] tx[0] = 0xbe88, tx[1] = 0x4800, tx[2] = 0x0000

<7> [627.337726] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000

<7> [627.337821] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[0] = 0x308c

<7> [627.337915] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[1] = 0x2110

<7> [627.338009] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[2] = 0xcc9c

<7> [627.338102] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[3] = 0xbfc1

<7> [627.338196] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[4] = 0x4b9a

<7> [627.338289] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[5] = 0x3f81

<7> [627.338382] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[6] = 0x2000

<7> [627.338475] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[7] = 0x0001

<7> [627.338566] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[8] = 0x5000

<7> [627.338671] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[9] = 0x0000

<7> [627.338764] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[10] = 0x0000

<7> [627.338858] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vdr: custom width: 0x00, serdes rate: 0x42, hdmi rate: 0x00

<7> [627.338951] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0

<7> [627.339044] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries

<7> [627.339139] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000

<7> [627.339234] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000

<7> [627.339334] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000

<7> [627.339427] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000

<7> [627.339528] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000

<7> [627.339628] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000

<7> [627.339721] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [627.339814] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [627.339907] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [627.340001] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000

<7> [627.340095] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:271:plane 1C] fb: [FB:556] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes

<7> [627.340190] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0

<7> [627.340283] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0

<7> [627.340376] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:301:plane 2C] fb: [NOFB], visible: no

<7> [627.340471] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:331:plane 3C] fb: [NOFB], visible: no

<7> [627.340568] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:361:plane 4C] fb: [NOFB], visible: no

<7> [627.340678] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:371:plane 5C] fb: [NOFB], visible: no

<7> [627.340773] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:381:cursor C] fb: [NOFB], visible: no

<7> [627.341380] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_2

<7> [627.341493] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_C

<7> [627.341618] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x4 (CLKGATE_DIS_DSSDSC=0x8a000000)

<7> [627.341730] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:507:DDI TC1/PHY F]

<7> [627.341823] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:509:DP-MST A]

<7> [627.341914] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:510:DP-MST B]

<7> [627.342004] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:511:DP-MST C]

<7> [627.342095] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:512:DP-MST D]

<7> [627.342184] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:526:DDI TC2/PHY G]

<7> [627.342271] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:528:DP-MST A]

<7> [627.342359] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:529:DP-MST B]

<7> [627.342444] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:530:DP-MST C]

<7> [627.342529] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:531:DP-MST D]

<7> [627.342622] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:538:DDI TC3/PHY H]

<7> [627.342708] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:542:DDI TC4/PHY I]

<7> [627.342794] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:544:DP-MST A]

<7> [627.342880] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:545:DP-MST B]

<7> [627.342971] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:546:DP-MST C]

<7> [627.343058] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:547:DP-MST D]

<7> [627.343155] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xd

<7> [627.343323] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no)

<7> [627.343423] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enable TC PLL 2 (active 0x4, on? 0) for [CRTC:387:pipe C]

<7> [627.343519] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enabling TC PLL 2

<7> [627.347525] 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> [627.352268] xe 0000:03:00.0: [drm:intel_dp_init_lttpr_and_dprx_caps [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] LTTPR common capabilities: 00 00 00 00 00 00 00 00

<7> [627.353287] 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> [627.353732] xe 0000:03:00.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using LINK_BW_SET value 0a

<7> [627.355241] xe 0000:03:00.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0

<7> [627.355802] xe 0000:03:00.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using DP training pattern TPS1

<7> [627.362471] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Clock recovery OK

<7> [627.362591] xe 0000:03:00.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using DP training pattern TPS3

<7> [627.368520] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Channel EQ done. DP Training successful

<7> [627.368660] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Link Training passed at link rate = 270000, lane count = 4

<7> [627.369905] xe 0000:03:00.0: [drm:intel_enable_transcoder [xe]] enabling pipe C

<7> [627.387345] xe 0000:03:00.0: [drm:intel_audio_codec_enable [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G] Enable audio codec on [CRTC:387:pipe C], 40 bytes ELD

<7> [627.404145] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:527:DP-2]

<7> [627.405037] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:387:pipe C]

<7> [627.472611] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2

<7> [629.400835] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2

<7> [629.504613] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2

<6> [630.851609] [IGT] kms_flip: finished subtest C-DP2, FAIL

Results for igt@kms_flip@flip-vs-expired-vblank-interruptible@c-dp2