igt@kms_flip@flip-vs-expired-vblank-interruptible@b-edp1 on shard-lnl@xe-3969-71929a54e8bb5da291d41a931d80c6c9160073dd Test details

Detail	Value
Duration	11.17 seconds
Hostname	shard-lnl-2
Igt-Version	IGT-Version: 2.2-g026eddf6f (x86_64) (Linux: 6.18.0-rc2-lgci-xe-xe-3969-71929a54e8bb5da29+ x86_64)
Out	Starting dynamic subtest: B-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1889 run_test() #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045() #4 ../tests/kms_flip.c:2045 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (11.168s)
Err	Starting dynamic subtest: B-eDP1 (kms_flip:5249) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:5249) CRITICAL: Failed assertion: end - start < 500 (kms_flip:5249) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-eDP1 failed. ** DEBUG (kms_flip:5249) DEBUG: Vblank took 57us (kms_flip:5249) DEBUG: name = flip last_ts = 381.096130 last_received_ts = 381.095459 last_seq = 1146 current_ts = 381.112793 current_received_ts = 381.112122 current_seq = 1147 count = 475 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 58us (kms_flip:5249) DEBUG: name = flip last_ts = 381.112793 last_received_ts = 381.112122 last_seq = 1147 current_ts = 381.129456 current_received_ts = 381.128815 current_seq = 1148 count = 476 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 46us (kms_flip:5249) DEBUG: name = flip last_ts = 381.129456 last_received_ts = 381.128815 last_seq = 1148 current_ts = 381.146118 current_received_ts = 381.145447 current_seq = 1149 count = 477 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 58us (kms_flip:5249) DEBUG: name = flip last_ts = 381.146118 last_received_ts = 381.145447 last_seq = 1149 current_ts = 381.162811 current_received_ts = 381.162079 current_seq = 1150 count = 478 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 53us (kms_flip:5249) DEBUG: name = flip last_ts = 381.162811 last_received_ts = 381.162079 last_seq = 1150 current_ts = 381.179474 current_received_ts = 381.178772 current_seq = 1151 count = 479 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 51us (kms_flip:5249) DEBUG: name = flip last_ts = 381.179474 last_received_ts = 381.178772 last_seq = 1151 current_ts = 381.196136 current_received_ts = 381.195435 current_seq = 1152 count = 480 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 42us (kms_flip:5249) DEBUG: name = flip last_ts = 381.196136 last_received_ts = 381.195435 last_seq = 1152 current_ts = 381.212799 current_received_ts = 381.212097 current_seq = 1153 count = 481 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 55us (kms_flip:5249) DEBUG: name = flip last_ts = 381.212799 last_received_ts = 381.212097 last_seq = 1153 current_ts = 381.229462 current_received_ts = 381.228760 current_seq = 1154 count = 482 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 54us (kms_flip:5249) DEBUG: name = flip last_ts = 381.229462 last_received_ts = 381.228760 last_seq = 1154 current_ts = 381.246124 current_received_ts = 381.245453 current_seq = 1155 count = 483 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 53us (kms_flip:5249) DEBUG: name = flip last_ts = 381.246124 last_received_ts = 381.245453 last_seq = 1155 current_ts = 381.262787 current_received_ts = 381.262085 current_seq = 1156 count = 484 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 56us (kms_flip:5249) DEBUG: name = flip last_ts = 381.262787 last_received_ts = 381.262085 last_seq = 1156 current_ts = 381.279449 current_received_ts = 381.278778 current_seq = 1157 count = 485 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 59us (kms_flip:5249) DEBUG: name = flip last_ts = 381.279449 last_received_ts = 381.278778 last_seq = 1157 current_ts = 381.296112 current_received_ts = 381.295441 current_seq = 1158 count = 486 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 51us (kms_flip:5249) DEBUG: name = flip last_ts = 381.296112 last_received_ts = 381.295441 last_seq = 1158 current_ts = 381.312775 current_received_ts = 381.312073 current_seq = 1159 count = 487 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 56us (kms_flip:5249) DEBUG: name = flip last_ts = 381.312775 last_received_ts = 381.312073 last_seq = 1159 current_ts = 381.329437 current_received_ts = 381.328766 current_seq = 1160 count = 488 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 61us (kms_flip:5249) DEBUG: name = flip last_ts = 381.329437 last_received_ts = 381.328766 last_seq = 1160 current_ts = 381.346130 current_received_ts = 381.345428 current_seq = 1161 count = 489 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 56us (kms_flip:5249) DEBUG: name = flip last_ts = 381.346130 last_received_ts = 381.345428 last_seq = 1161 current_ts = 381.362793 current_received_ts = 381.362091 current_seq = 1162 count = 490 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 62us (kms_flip:5249) DEBUG: name = flip last_ts = 381.362793 last_received_ts = 381.362091 last_seq = 1162 current_ts = 381.379456 current_received_ts = 381.378754 current_seq = 1163 count = 491 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 50us (kms_flip:5249) DEBUG: name = flip last_ts = 381.379456 last_received_ts = 381.378754 last_seq = 1163 current_ts = 381.396118 current_received_ts = 381.395416 current_seq = 1164 count = 492 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 51us (kms_flip:5249) DEBUG: name = flip last_ts = 381.396118 last_received_ts = 381.395416 last_seq = 1164 current_ts = 381.412781 current_received_ts = 381.412079 current_seq = 1165 count = 493 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 54us (kms_flip:5249) DEBUG: name = flip last_ts = 381.412781 last_received_ts = 381.412079 last_seq = 1165 current_ts = 381.429443 current_received_ts = 381.428741 current_seq = 1166 count = 494 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 53us (kms_flip:5249) DEBUG: name = flip last_ts = 381.429443 last_received_ts = 381.428741 last_seq = 1166 current_ts = 381.446106 current_received_ts = 381.445435 current_seq = 1167 count = 495 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 42us (kms_flip:5249) DEBUG: name = flip last_ts = 381.446106 last_received_ts = 381.445435 last_seq = 1167 current_ts = 381.462769 current_received_ts = 381.462097 current_seq = 1168 count = 496 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 51us (kms_flip:5249) DEBUG: name = flip last_ts = 381.462769 last_received_ts = 381.462097 last_seq = 1168 current_ts = 381.479431 current_received_ts = 381.478760 current_seq = 1169 count = 497 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 54us (kms_flip:5249) DEBUG: name = flip last_ts = 381.479431 last_received_ts = 381.478760 last_seq = 1169 current_ts = 381.496124 current_received_ts = 381.495422 current_seq = 1170 count = 498 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 52us (kms_flip:5249) DEBUG: name = flip last_ts = 381.496124 last_received_ts = 381.495422 last_seq = 1170 current_ts = 381.512787 current_received_ts = 381.512238 current_seq = 1171 count = 499 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 59us (kms_flip:5249) DEBUG: name = flip last_ts = 381.512787 last_received_ts = 381.512238 last_seq = 1171 current_ts = 381.529449 current_received_ts = 381.528778 current_seq = 1172 count = 500 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 140us (kms_flip:5249) DEBUG: name = flip last_ts = 381.529449 last_received_ts = 381.528778 last_seq = 1172 current_ts = 381.546112 current_received_ts = 381.545410 current_seq = 1173 count = 501 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 71us (kms_flip:5249) DEBUG: name = flip last_ts = 381.546112 last_received_ts = 381.545410 last_seq = 1173 current_ts = 381.562775 current_received_ts = 381.562073 current_seq = 1174 count = 502 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 44us (kms_flip:5249) DEBUG: name = flip last_ts = 381.562775 last_received_ts = 381.562073 last_seq = 1174 current_ts = 381.579437 current_received_ts = 381.578766 current_seq = 1175 count = 503 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 64us (kms_flip:5249) DEBUG: name = flip last_ts = 381.579437 last_received_ts = 381.578766 last_seq = 1175 current_ts = 381.596100 current_received_ts = 381.595428 current_seq = 1176 count = 504 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 54us (kms_flip:5249) DEBUG: name = flip last_ts = 381.596100 last_received_ts = 381.595428 last_seq = 1176 current_ts = 381.612762 current_received_ts = 381.612061 current_seq = 1177 count = 505 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 55us (kms_flip:5249) DEBUG: name = flip last_ts = 381.612762 last_received_ts = 381.612061 last_seq = 1177 current_ts = 381.629425 current_received_ts = 381.628784 current_seq = 1178 count = 506 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 59us (kms_flip:5249) DEBUG: name = flip last_ts = 381.629425 last_received_ts = 381.628784 last_seq = 1178 current_ts = 381.646088 current_received_ts = 381.645416 current_seq = 1179 count = 507 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 52us (kms_flip:5249) DEBUG: name = flip last_ts = 381.646088 last_received_ts = 381.645416 last_seq = 1179 current_ts = 381.662750 current_received_ts = 381.662079 current_seq = 1180 count = 508 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 45us (kms_flip:5249) DEBUG: name = flip last_ts = 381.662750 last_received_ts = 381.662079 last_seq = 1180 current_ts = 381.679413 current_received_ts = 381.678741 current_seq = 1181 count = 509 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 92us (kms_flip:5249) DEBUG: name = flip last_ts = 381.679413 last_received_ts = 381.678741 last_seq = 1181 current_ts = 381.696106 current_received_ts = 381.695404 current_seq = 1182 count = 510 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 53us (kms_flip:5249) DEBUG: name = flip last_ts = 381.696106 last_received_ts = 381.695404 last_seq = 1182 current_ts = 381.712769 current_received_ts = 381.712067 current_seq = 1183 count = 511 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 41us (kms_flip:5249) DEBUG: name = flip last_ts = 381.712769 last_received_ts = 381.712067 last_seq = 1183 current_ts = 381.729431 current_received_ts = 381.728760 current_seq = 1184 count = 512 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 57us (kms_flip:5249) DEBUG: name = flip last_ts = 381.729431 last_received_ts = 381.728760 last_seq = 1184 current_ts = 381.746094 current_received_ts = 381.745392 current_seq = 1185 count = 513 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 51us (kms_flip:5249) DEBUG: name = flip last_ts = 381.746094 last_received_ts = 381.745392 last_seq = 1185 current_ts = 381.762756 current_received_ts = 381.762085 current_seq = 1186 count = 514 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 44us (kms_flip:5249) DEBUG: name = flip last_ts = 381.762756 last_received_ts = 381.762085 last_seq = 1186 current_ts = 381.779419 current_received_ts = 381.778748 current_seq = 1187 count = 515 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 56us (kms_flip:5249) DEBUG: name = flip last_ts = 381.779419 last_received_ts = 381.778748 last_seq = 1187 current_ts = 381.796082 current_received_ts = 381.795410 current_seq = 1188 count = 516 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 103us (kms_flip:5249) DEBUG: name = flip last_ts = 381.796082 last_received_ts = 381.795410 last_seq = 1188 current_ts = 381.812744 current_received_ts = 381.812073 current_seq = 1189 count = 517 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 53us (kms_flip:5249) DEBUG: name = flip last_ts = 381.812744 last_received_ts = 381.812073 last_seq = 1189 current_ts = 381.829407 current_received_ts = 381.828735 current_seq = 1190 count = 518 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 53us (kms_flip:5249) DEBUG: name = flip last_ts = 381.829407 last_received_ts = 381.828735 last_seq = 1190 current_ts = 381.846069 current_received_ts = 381.845398 current_seq = 1191 count = 519 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 44us (kms_flip:5249) DEBUG: name = flip last_ts = 381.846069 last_received_ts = 381.845398 last_seq = 1191 current_ts = 381.862762 current_received_ts = 381.862061 current_seq = 1192 count = 520 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 64us (kms_flip:5249) DEBUG: name = flip last_ts = 381.862762 last_received_ts = 381.862061 last_seq = 1192 current_ts = 381.879425 current_received_ts = 381.878754 current_seq = 1193 count = 521 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 112us (kms_flip:5249) DEBUG: name = flip last_ts = 381.879425 last_received_ts = 381.878754 last_seq = 1193 current_ts = 381.896088 current_received_ts = 381.895416 current_seq = 1194 count = 522 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 76us (kms_flip:5249) DEBUG: name = flip last_ts = 381.896088 last_received_ts = 381.895416 last_seq = 1194 current_ts = 381.912750 current_received_ts = 381.912079 current_seq = 1195 count = 523 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 52us (kms_flip:5249) DEBUG: name = flip last_ts = 381.912750 last_received_ts = 381.912079 last_seq = 1195 current_ts = 381.929413 current_received_ts = 381.928741 current_seq = 1196 count = 524 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 95us (kms_flip:5249) DEBUG: name = flip last_ts = 381.929413 last_received_ts = 381.928741 last_seq = 1196 current_ts = 381.946075 current_received_ts = 381.945404 current_seq = 1197 count = 525 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 71us (kms_flip:5249) DEBUG: name = flip last_ts = 381.946075 last_received_ts = 381.945404 last_seq = 1197 current_ts = 381.962738 current_received_ts = 381.962067 current_seq = 1198 count = 526 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 70us (kms_flip:5249) DEBUG: name = flip last_ts = 381.962738 last_received_ts = 381.962067 last_seq = 1198 current_ts = 381.979401 current_received_ts = 381.978729 current_seq = 1199 count = 527 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 67us (kms_flip:5249) DEBUG: name = flip last_ts = 381.979401 last_received_ts = 381.978729 last_seq = 1199 current_ts = 381.996063 current_received_ts = 381.995422 current_seq = 1200 count = 528 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 63us (kms_flip:5249) DEBUG: name = flip last_ts = 381.996063 last_received_ts = 381.995422 last_seq = 1200 current_ts = 382.012726 current_received_ts = 382.012054 current_seq = 1201 count = 529 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 67us (kms_flip:5249) DEBUG: name = flip last_ts = 382.012726 last_received_ts = 382.012054 last_seq = 1201 current_ts = 382.029388 current_received_ts = 382.028748 current_seq = 1202 count = 530 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 58us (kms_flip:5249) DEBUG: name = flip last_ts = 382.029388 last_received_ts = 382.028748 last_seq = 1202 current_ts = 382.046082 current_received_ts = 382.045380 current_seq = 1203 count = 531 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 61us (kms_flip:5249) DEBUG: name = flip last_ts = 382.046082 last_received_ts = 382.045380 last_seq = 1203 current_ts = 382.062744 current_received_ts = 382.062042 current_seq = 1204 count = 532 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 80us (kms_flip:5249) DEBUG: name = flip last_ts = 382.062744 last_received_ts = 382.062042 last_seq = 1204 current_ts = 382.079407 current_received_ts = 382.078705 current_seq = 1205 count = 533 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 54us (kms_flip:5249) DEBUG: name = flip last_ts = 382.079407 last_received_ts = 382.078705 last_seq = 1205 current_ts = 382.096069 current_received_ts = 382.095367 current_seq = 1206 count = 534 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 52us (kms_flip:5249) DEBUG: name = flip last_ts = 382.096069 last_received_ts = 382.095367 last_seq = 1206 current_ts = 382.112732 current_received_ts = 382.112091 current_seq = 1207 count = 535 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 55us (kms_flip:5249) DEBUG: name = flip last_ts = 382.112732 last_received_ts = 382.112091 last_seq = 1207 current_ts = 382.129395 current_received_ts = 382.128723 current_seq = 1208 count = 536 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 62us (kms_flip:5249) DEBUG: name = flip last_ts = 382.129395 last_received_ts = 382.128723 last_seq = 1208 current_ts = 382.146057 current_received_ts = 382.145386 current_seq = 1209 count = 537 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 56us (kms_flip:5249) DEBUG: name = flip last_ts = 382.146057 last_received_ts = 382.145386 last_seq = 1209 current_ts = 382.162720 current_received_ts = 382.162048 current_seq = 1210 count = 538 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 46us (kms_flip:5249) DEBUG: name = flip last_ts = 382.162720 last_received_ts = 382.162048 last_seq = 1210 current_ts = 382.179382 current_received_ts = 382.178711 current_seq = 1211 count = 539 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 78us (kms_flip:5249) DEBUG: name = flip last_ts = 382.179382 last_received_ts = 382.178711 last_seq = 1211 current_ts = 382.196045 current_received_ts = 382.195374 current_seq = 1212 count = 540 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 51us (kms_flip:5249) DEBUG: name = flip last_ts = 382.196045 last_received_ts = 382.195374 last_seq = 1212 current_ts = 382.212708 current_received_ts = 382.212067 current_seq = 1213 count = 541 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 55us (kms_flip:5249) DEBUG: name = flip last_ts = 382.212708 last_received_ts = 382.212067 last_seq = 1213 current_ts = 382.229401 current_received_ts = 382.228729 current_seq = 1214 count = 542 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 57us (kms_flip:5249) DEBUG: name = flip last_ts = 382.229401 last_received_ts = 382.228729 last_seq = 1214 current_ts = 382.246063 current_received_ts = 382.245392 current_seq = 1215 count = 543 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 59us (kms_flip:5249) DEBUG: name = flip last_ts = 382.246063 last_received_ts = 382.245392 last_seq = 1215 current_ts = 382.262726 current_received_ts = 382.262054 current_seq = 1216 count = 544 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 63us (kms_flip:5249) DEBUG: name = flip last_ts = 382.262726 last_received_ts = 382.262054 last_seq = 1216 current_ts = 382.279388 current_received_ts = 382.278687 current_seq = 1217 count = 545 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 56us (kms_flip:5249) DEBUG: name = flip last_ts = 382.279388 last_received_ts = 382.278687 last_seq = 1217 current_ts = 382.296051 current_received_ts = 382.295380 current_seq = 1218 count = 546 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 48us (kms_flip:5249) DEBUG: name = flip last_ts = 382.296051 last_received_ts = 382.295380 last_seq = 1218 current_ts = 382.312714 current_received_ts = 382.312042 current_seq = 1219 count = 547 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 58us (kms_flip:5249) DEBUG: name = flip last_ts = 382.312714 last_received_ts = 382.312042 last_seq = 1219 current_ts = 382.329376 current_received_ts = 382.328674 current_seq = 1220 count = 548 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 54us (kms_flip:5249) DEBUG: name = flip last_ts = 382.329376 last_received_ts = 382.328674 last_seq = 1220 current_ts = 382.346039 current_received_ts = 382.345367 current_seq = 1221 count = 549 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 56us (kms_flip:5249) DEBUG: name = flip last_ts = 382.346039 last_received_ts = 382.345367 last_seq = 1221 current_ts = 382.362701 current_received_ts = 382.362030 current_seq = 1222 count = 550 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 56us (kms_flip:5249) DEBUG: name = flip last_ts = 382.362701 last_received_ts = 382.362030 last_seq = 1222 current_ts = 382.379395 current_received_ts = 382.378723 current_seq = 1223 count = 551 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 61us (kms_flip:5249) DEBUG: name = flip last_ts = 382.379395 last_received_ts = 382.378723 last_seq = 1223 current_ts = 382.396057 current_received_ts = 382.395355 current_seq = 1224 count = 552 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 44us (kms_flip:5249) DEBUG: name = flip last_ts = 382.396057 last_received_ts = 382.395355 last_seq = 1224 current_ts = 382.412720 current_received_ts = 382.412079 current_seq = 1225 count = 553 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 56us (kms_flip:5249) DEBUG: name = flip last_ts = 382.412720 last_received_ts = 382.412079 last_seq = 1225 current_ts = 382.429382 current_received_ts = 382.428711 current_seq = 1226 count = 554 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 57us (kms_flip:5249) DEBUG: name = flip last_ts = 382.429382 last_received_ts = 382.428711 last_seq = 1226 current_ts = 382.446045 current_received_ts = 382.445343 current_seq = 1227 count = 555 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 56us (kms_flip:5249) DEBUG: name = flip last_ts = 382.446045 last_received_ts = 382.445343 last_seq = 1227 current_ts = 382.462708 current_received_ts = 382.462067 current_seq = 1228 count = 556 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 62us (kms_flip:5249) DEBUG: name = flip last_ts = 382.462708 last_received_ts = 382.462067 last_seq = 1228 current_ts = 382.479370 current_received_ts = 382.478668 current_seq = 1229 count = 557 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 37us (kms_flip:5249) DEBUG: name = flip last_ts = 382.479370 last_received_ts = 382.478668 last_seq = 1229 current_ts = 382.496033 current_received_ts = 382.495361 current_seq = 1230 count = 558 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 44us (kms_flip:5249) DEBUG: name = flip last_ts = 382.496033 last_received_ts = 382.495361 last_seq = 1230 current_ts = 382.512695 current_received_ts = 382.512054 current_seq = 1231 count = 559 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 57us (kms_flip:5249) DEBUG: name = flip last_ts = 382.512695 last_received_ts = 382.512054 last_seq = 1231 current_ts = 382.529358 current_received_ts = 382.528687 current_seq = 1232 count = 560 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 54us (kms_flip:5249) DEBUG: name = flip last_ts = 382.529358 last_received_ts = 382.528687 last_seq = 1232 current_ts = 382.546021 current_received_ts = 382.545380 current_seq = 1233 count = 561 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 58us (kms_flip:5249) DEBUG: name = flip last_ts = 382.546021 last_received_ts = 382.545380 last_seq = 1233 current_ts = 382.562683 current_received_ts = 382.562042 current_seq = 1234 count = 562 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 41us (kms_flip:5249) DEBUG: name = flip last_ts = 382.562683 last_received_ts = 382.562042 last_seq = 1234 current_ts = 382.579376 current_received_ts = 382.578705 current_seq = 1235 count = 563 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 60us (kms_flip:5249) DEBUG: name = flip last_ts = 382.579376 last_received_ts = 382.578705 last_seq = 1235 current_ts = 382.596039 current_received_ts = 382.595337 current_seq = 1236 count = 564 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 43us (kms_flip:5249) DEBUG: name = flip last_ts = 382.596039 last_received_ts = 382.595337 last_seq = 1236 current_ts = 382.612701 current_received_ts = 382.612030 current_seq = 1237 count = 565 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 41us (kms_flip:5249) DEBUG: name = flip last_ts = 382.612701 last_received_ts = 382.612030 last_seq = 1237 current_ts = 382.629364 current_received_ts = 382.628662 current_seq = 1238 count = 566 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 54us (kms_flip:5249) DEBUG: name = flip last_ts = 382.629364 last_received_ts = 382.628662 last_seq = 1238 current_ts = 382.646027 current_received_ts = 382.645355 current_seq = 1239 count = 567 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 57us (kms_flip:5249) DEBUG: name = flip last_ts = 382.646027 last_received_ts = 382.645355 last_seq = 1239 current_ts = 382.662689 current_received_ts = 382.662018 current_seq = 1240 count = 568 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 58us (kms_flip:5249) DEBUG: name = flip last_ts = 382.662689 last_received_ts = 382.662018 last_seq = 1240 current_ts = 382.679352 current_received_ts = 382.678680 current_seq = 1241 count = 569 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 55us (kms_flip:5249) DEBUG: name = flip last_ts = 382.679352 last_received_ts = 382.678680 last_seq = 1241 current_ts = 382.696014 current_received_ts = 382.695526 current_seq = 1242 count = 570 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 68us (kms_flip:5249) DEBUG: name = flip last_ts = 382.696014 last_received_ts = 382.695526 last_seq = 1242 current_ts = 382.712677 current_received_ts = 382.712036 current_seq = 1243 count = 571 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 66us (kms_flip:5249) DEBUG: name = flip last_ts = 382.712677 last_received_ts = 382.712036 last_seq = 1243 current_ts = 382.729340 current_received_ts = 382.728668 current_seq = 1244 count = 572 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 54us (kms_flip:5249) DEBUG: name = flip last_ts = 382.729340 last_received_ts = 382.728668 last_seq = 1244 current_ts = 382.746033 current_received_ts = 382.745331 current_seq = 1245 count = 573 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 94us (kms_flip:5249) DEBUG: name = flip last_ts = 382.746033 last_received_ts = 382.745331 last_seq = 1245 current_ts = 382.762695 current_received_ts = 382.762024 current_seq = 1246 count = 574 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 42us (kms_flip:5249) DEBUG: name = flip last_ts = 382.762695 last_received_ts = 382.762024 last_seq = 1246 current_ts = 382.779358 current_received_ts = 382.778656 current_seq = 1247 count = 575 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 60us (kms_flip:5249) DEBUG: name = flip last_ts = 382.779358 last_received_ts = 382.778656 last_seq = 1247 current_ts = 382.796021 current_received_ts = 382.795319 current_seq = 1248 count = 576 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 57us (kms_flip:5249) DEBUG: name = flip last_ts = 382.796021 last_received_ts = 382.795319 last_seq = 1248 current_ts = 382.812683 current_received_ts = 382.811981 current_seq = 1249 count = 577 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 42us (kms_flip:5249) DEBUG: name = flip last_ts = 382.812683 last_received_ts = 382.811981 last_seq = 1249 current_ts = 382.829346 current_received_ts = 382.828674 current_seq = 1250 count = 578 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 53us (kms_flip:5249) DEBUG: name = flip last_ts = 382.829346 last_received_ts = 382.828674 last_seq = 1250 current_ts = 382.846008 current_received_ts = 382.845306 current_seq = 1251 count = 579 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 50us (kms_flip:5249) DEBUG: name = flip last_ts = 382.846008 last_received_ts = 382.845306 last_seq = 1251 current_ts = 382.862671 current_received_ts = 382.862000 current_seq = 1252 count = 580 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 47us (kms_flip:5249) DEBUG: name = flip last_ts = 382.862671 last_received_ts = 382.862000 last_seq = 1252 current_ts = 382.879333 current_received_ts = 382.878662 current_seq = 1253 count = 581 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 66us (kms_flip:5249) DEBUG: name = flip last_ts = 382.879333 last_received_ts = 382.878662 last_seq = 1253 current_ts = 382.895996 current_received_ts = 382.895355 current_seq = 1254 count = 582 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 55us (kms_flip:5249) DEBUG: name = flip last_ts = 382.895996 last_received_ts = 382.895355 last_seq = 1254 current_ts = 382.912689 current_received_ts = 382.912079 current_seq = 1255 count = 583 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 136us (kms_flip:5249) DEBUG: name = flip last_ts = 382.912689 last_received_ts = 382.912079 last_seq = 1255 current_ts = 382.929352 current_received_ts = 382.928650 current_seq = 1256 count = 584 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 57us (kms_flip:5249) DEBUG: name = flip last_ts = 382.929352 last_received_ts = 382.928650 last_seq = 1256 current_ts = 382.946014 current_received_ts = 382.945312 current_seq = 1257 count = 585 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 115us (kms_flip:5249) DEBUG: name = flip last_ts = 382.946014 last_received_ts = 382.945312 last_seq = 1257 current_ts = 382.962677 current_received_ts = 382.961975 current_seq = 1258 count = 586 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 69us (kms_flip:5249) DEBUG: name = flip last_ts = 382.962677 last_received_ts = 382.961975 last_seq = 1258 current_ts = 382.979340 current_received_ts = 382.978668 current_seq = 1259 count = 587 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 119us (kms_flip:5249) DEBUG: name = flip last_ts = 382.979340 last_received_ts = 382.978668 last_seq = 1259 current_ts = 382.996002 current_received_ts = 382.995300 current_seq = 1260 count = 588 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 62us (kms_flip:5249) DEBUG: name = flip last_ts = 382.996002 last_received_ts = 382.995300 last_seq = 1260 current_ts = 383.012665 current_received_ts = 383.012024 current_seq = 1261 count = 589 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 90us (kms_flip:5249) DEBUG: name = flip last_ts = 383.012665 last_received_ts = 383.012024 last_seq = 1261 current_ts = 383.029327 current_received_ts = 383.028656 current_seq = 1262 count = 590 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 64us (kms_flip:5249) DEBUG: name = flip last_ts = 383.029327 last_received_ts = 383.028656 last_seq = 1262 current_ts = 383.045990 current_received_ts = 383.045319 current_seq = 1263 count = 591 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 62us (kms_flip:5249) DEBUG: name = flip last_ts = 383.045990 last_received_ts = 383.045319 last_seq = 1263 current_ts = 383.062653 current_received_ts = 383.061981 current_seq = 1264 count = 592 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 53us (kms_flip:5249) DEBUG: name = flip last_ts = 383.062653 last_received_ts = 383.061981 last_seq = 1264 current_ts = 383.079315 current_received_ts = 383.078644 current_seq = 1265 count = 593 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 60us (kms_flip:5249) DEBUG: name = flip last_ts = 383.079315 last_received_ts = 383.078644 last_seq = 1265 current_ts = 383.095978 current_received_ts = 383.095337 current_seq = 1266 count = 594 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 57us (kms_flip:5249) DEBUG: name = flip last_ts = 383.095978 last_received_ts = 383.095337 last_seq = 1266 current_ts = 383.112671 current_received_ts = 383.111969 current_seq = 1267 count = 595 seq_step = 1 (kms_flip:5249) DEBUG: Vblank took 625us (kms_flip:5249) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928: (kms_flip:5249) CRITICAL: Failed assertion: end - start < 500 (kms_flip:5249) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:5249) igt_core-INFO: Stack trace: (kms_flip:5249) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:5249) igt_core-INFO: #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0() (kms_flip:5249) igt_core-INFO: #2 ../tests/kms_flip.c:1889 run_test() (kms_flip:5249) igt_core-INFO: #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045() (kms_flip:5249) igt_core-INFO: #4 ../tests/kms_flip.c:2045 main() (kms_flip:5249) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:5249) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:5249) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (11.168s)
Dmesg	<6> [416.734937] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [416.774643] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [416.774813] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [416.774928] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [416.775095] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:242] <7> [416.776054] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:244] <7> [416.843791] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:88:pipe A] <7> [416.843924] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [416.844096] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [416.844235] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [416.844477] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [416.844599] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0) <7> [416.844722] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [416.844845] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [416.844969] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [416.845097] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [416.845222] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [416.845354] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [416.845465] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [416.845574] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [416.845676] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [416.845777] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [416.845880] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [416.845980] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [416.846083] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [416.846196] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [416.846321] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [416.846433] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [416.846535] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [416.846637] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [416.846747] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [416.846856] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [416.846957] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [416.847059] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [416.847158] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [416.847257] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [416.847370] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [416.847475] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [416.847579] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [416.847683] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [416.847791] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [416.847906] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [416.848013] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [416.848118] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [416.848220] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [416.848334] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:88:pipe A] fastset requirement not met, forcing full modeset <7> [416.848495] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [416.848587] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:88:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [416.848705] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:83:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [416.848830] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:88:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [416.848965] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [416.849087] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [416.849204] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [416.849370] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:88:pipe A] enable: no [modeset] <7> [416.849481] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:33:plane 1A] fb: [NOFB], visible: no <7> [416.849587] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:43:plane 2A] fb: [NOFB], visible: no <7> [416.849692] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:53:plane 3A] fb: [NOFB], visible: no <7> [416.849798] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:63:plane 4A] fb: [NOFB], visible: no <7> [416.849904] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:73:plane 5A] fb: [NOFB], visible: no <7> [416.850012] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:83:cursor A] fb: [NOFB], visible: no <7> [416.850182] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [416.850314] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [416.850566] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [416.850684] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [417.053374] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:205:eDP-1] set backlight PWM = 0 <7> [417.053985] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [417.064712] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turn panel power off <7> [417.065079] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power off time <7> [417.065465] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [417.117856] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [417.118400] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:204:DDI A/PHY A] - short <7> [417.126092] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [417.126555] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:204:DDI A/PHY A] <7> [417.126624] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [417.127128] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:204:DDI A/PHY A] <7> [417.127500] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:213:DDI TC1/PHY TC1] <7> [417.127824] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:215:DP-MST A] <7> [417.128139] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:216:DP-MST B] <7> [417.128483] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:217:DP-MST C] <7> [417.128802] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:225:DDI TC2/PHY TC2] <7> [417.129113] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:227:DP-MST A] <7> [417.129448] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:228:DP-MST B] <7> [417.129761] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:229:DP-MST C] <7> [417.130067] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:233:DDI TC3/PHY TC3] <7> [417.130397] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:235:DP-MST A] <7> [417.130718] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:236:DP-MST B] <7> [417.131034] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:237:DP-MST C] <7> [417.131368] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:205:eDP-1] <7> [417.131745] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [417.132054] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [417.132372] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [417.132870] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [417.133397] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:88:pipe A] <7> [417.133787] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Post changing CDCLK to 153600 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [417.134254] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [417.134612] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [417.135704] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:145:pipe B] <7> [417.136334] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:202:pipe C] <7> [417.136794] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:145:pipe B] <7> [417.136901] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:205:eDP-1] <7> [417.137171] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CONNECTOR:205:eDP-1] Limiting display bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [417.137715] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:204:DDI A/PHY A][CRTC:145:pipe B] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 max link_bpp 30.0000 <7> [417.138115] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 link rate required 1303913 available 1728000 <7> [417.138559] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:145:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [417.138981] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:204:DDI A/PHY A] [CRTC:145:pipe B] <7> [417.139388] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [417.139768] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [417.140132] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [417.140503] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [417.140824] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [417.141133] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [417.141445] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [417.141728] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [417.142001] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [417.142258] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [417.142526] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [417.142765] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [417.143002] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [417.143230] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [417.143462] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [417.143679] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [417.143885] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [417.144084] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [417.144288] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [417.144482] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [417.144672] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [417.144856] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [417.145034] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [417.145201] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [417.145489] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [417.145665] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [417.145820] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [417.145973] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [417.146119] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [417.146262] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [417.146417] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [417.146562] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [417.146698] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [417.146834] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [417.146973] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [417.147106] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [417.147231] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [417.147362] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in port_clock (expected 0, found 432000) <7> [417.147490] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:145:pipe B] fastset requirement not met, forcing full modeset <7> [417.147727] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [417.147845] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:145:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [417.147990] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:90:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [417.148092] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:140:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [417.148172] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [417.148250] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [417.148342] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [417.148428] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [417.148532] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:145:pipe B] data rate 1390840 num active planes 1 <7> [417.148662] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [417.148777] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [417.148897] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [417.149009] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [417.149117] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [417.149226] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:145:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [417.149388] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [417.149524] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [417.149634] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [417.149794] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:145:pipe B] enable: yes [modeset] <7> [417.149929] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [417.150040] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [417.150147] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [417.150250] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [417.150372] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [417.150486] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [417.150594] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 6329869, data_n: 8388608, link_m: 421991, link_n: 524288, tu: 64 <7> [417.150705] xe 0000:00:02.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> [417.150816] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [417.150920] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [417.151024] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [417.151129] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0 <7> [417.151235] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [417.151355] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [417.151468] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [417.151577] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [417.151689] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [417.151791] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [417.151895] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [417.151998] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [417.152103] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0 set context latency: 0 <7> [417.152209] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 37 vsync start: 103, vsync end: 97 <7> [417.152331] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1869, vmax vblank: 1869, vmin vtotal: 1906, vmax vtotal: 1906 <7> [417.152467] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [417.152577] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [417.152679] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [417.152784] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa <7> [417.152887] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [417.152990] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pipe src: 2880x1800+0+0, pixel rate 347710, min cdclk 173855 <7> [417.153096] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [417.153201] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [417.153327] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [417.153443] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [417.153547] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dpll_hw_state: dpll: 0x69780, dpll_md: 0x42110, fp0: 0x1a2, fp1: 0x1000000 <7> [417.153651] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [417.153754] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [417.153857] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [417.153962] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [417.154066] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [417.154171] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [417.154293] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [417.154309] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [417.154419] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [417.154473] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [417.154528] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [417.154598] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [417.154634] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [417.154741] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [417.154744] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling always-on <7> [417.154849] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [417.154964] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:90:plane 1B] fb: [FB:242] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [417.155070] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [417.155173] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [417.155282] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:100:plane 2B] fb: [NOFB], visible: no <7> [417.155259] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [417.155400] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:110:plane 3B] fb: [NOFB], visible: no <7> [417.155419] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:204:DDI A/PHY A] - long <7> [417.155508] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:120:plane 4B] fb: [NOFB], visible: no <7> [417.155530] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [417.155615] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:130:plane 5B] fb: [NOFB], visible: no <7> [417.155650] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:204:DDI A/PHY A] <7> [417.155723] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:140:cursor B] fb: [NOFB], visible: no <7> [417.156315] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling always-on <7> [417.156446] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [417.156708] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [417.156887] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [417.157046] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [417.157237] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 192000 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [417.157398] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [417.157520] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [417.157636] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:204:DDI A/PHY A] <7> [417.157724] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:213:DDI TC1/PHY TC1] <7> [417.157810] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:215:DP-MST A] <7> [417.157894] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:216:DP-MST B] <7> [417.157977] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:217:DP-MST C] <7> [417.158060] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:225:DDI TC2/PHY TC2] <7> [417.158142] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:227:DP-MST A] <7> [417.158224] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:228:DP-MST B] <7> [417.158318] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:229:DP-MST C] <7> [417.158406] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:233:DDI TC3/PHY TC3] <7> [417.158497] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:235:DP-MST A] <7> [417.158580] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:236:DP-MST B] <7> [417.158663] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:237:DP-MST C] <7> [417.158747] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [417.158933] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *) <7> [417.159029] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [417.159163] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [417.160295] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turn panel power on <7> [417.160403] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power cycle (467 ms remaining) <7> [417.629348] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [417.639282] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [417.639581] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power on <7> [417.639881] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [417.675651] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [417.676074] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:204:DDI A/PHY A] - long <7> [417.676481] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [417.676935] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:204:DDI A/PHY A] <7> [417.850191] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [417.852402] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turning VDD on <7> [417.852749] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [417.855071] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e 44 c1 00 00 01 c0 02 00 02 00 00 0b 80 <7> [417.856382] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [417.857259] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [417.858438] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [417.859571] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [417.860611] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Clock recovery OK <7> [417.860941] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [417.862367] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [417.862699] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [417.863551] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [417.864032] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [417.864387] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [417.864795] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:205:eDP-1] set backlight PWM = 4518 <7> [417.880982] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [417.882924] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:205:eDP-1] <7> [417.883408] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:145:pipe B] <7> [420.405072] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turning VDD off <7> [420.405618] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [427.846547] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [427.847266] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [427.847980] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [427.904548] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

11.17 seconds

Hostname

shard-lnl-2

Igt-Version

IGT-Version: 2.2-g026eddf6f (x86_64) (Linux: 6.18.0-rc2-lgci-xe-xe-3969-71929a54e8bb5da29+ x86_64)

Out

Starting dynamic subtest: B-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1889 run_test()
  #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045()
  #4 ../tests/kms_flip.c:2045 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (11.168s)

Err

Starting dynamic subtest: B-eDP1
(kms_flip:5249) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:5249) CRITICAL: Failed assertion: end - start < 500
(kms_flip:5249) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:5249) DEBUG: Vblank took 57us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.096130
last_received_ts = 381.095459
last_seq = 1146
current_ts = 381.112793
current_received_ts = 381.112122
current_seq = 1147
count = 475
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 58us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.112793
last_received_ts = 381.112122
last_seq = 1147
current_ts = 381.129456
current_received_ts = 381.128815
current_seq = 1148
count = 476
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 46us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.129456
last_received_ts = 381.128815
last_seq = 1148
current_ts = 381.146118
current_received_ts = 381.145447
current_seq = 1149
count = 477
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 58us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.146118
last_received_ts = 381.145447
last_seq = 1149
current_ts = 381.162811
current_received_ts = 381.162079
current_seq = 1150
count = 478
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 53us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.162811
last_received_ts = 381.162079
last_seq = 1150
current_ts = 381.179474
current_received_ts = 381.178772
current_seq = 1151
count = 479
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 51us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.179474
last_received_ts = 381.178772
last_seq = 1151
current_ts = 381.196136
current_received_ts = 381.195435
current_seq = 1152
count = 480
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 42us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.196136
last_received_ts = 381.195435
last_seq = 1152
current_ts = 381.212799
current_received_ts = 381.212097
current_seq = 1153
count = 481
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 55us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.212799
last_received_ts = 381.212097
last_seq = 1153
current_ts = 381.229462
current_received_ts = 381.228760
current_seq = 1154
count = 482
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 54us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.229462
last_received_ts = 381.228760
last_seq = 1154
current_ts = 381.246124
current_received_ts = 381.245453
current_seq = 1155
count = 483
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 53us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.246124
last_received_ts = 381.245453
last_seq = 1155
current_ts = 381.262787
current_received_ts = 381.262085
current_seq = 1156
count = 484
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 56us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.262787
last_received_ts = 381.262085
last_seq = 1156
current_ts = 381.279449
current_received_ts = 381.278778
current_seq = 1157
count = 485
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 59us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.279449
last_received_ts = 381.278778
last_seq = 1157
current_ts = 381.296112
current_received_ts = 381.295441
current_seq = 1158
count = 486
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 51us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.296112
last_received_ts = 381.295441
last_seq = 1158
current_ts = 381.312775
current_received_ts = 381.312073
current_seq = 1159
count = 487
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 56us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.312775
last_received_ts = 381.312073
last_seq = 1159
current_ts = 381.329437
current_received_ts = 381.328766
current_seq = 1160
count = 488
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 61us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.329437
last_received_ts = 381.328766
last_seq = 1160
current_ts = 381.346130
current_received_ts = 381.345428
current_seq = 1161
count = 489
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 56us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.346130
last_received_ts = 381.345428
last_seq = 1161
current_ts = 381.362793
current_received_ts = 381.362091
current_seq = 1162
count = 490
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 62us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.362793
last_received_ts = 381.362091
last_seq = 1162
current_ts = 381.379456
current_received_ts = 381.378754
current_seq = 1163
count = 491
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 50us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.379456
last_received_ts = 381.378754
last_seq = 1163
current_ts = 381.396118
current_received_ts = 381.395416
current_seq = 1164
count = 492
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 51us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.396118
last_received_ts = 381.395416
last_seq = 1164
current_ts = 381.412781
current_received_ts = 381.412079
current_seq = 1165
count = 493
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 54us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.412781
last_received_ts = 381.412079
last_seq = 1165
current_ts = 381.429443
current_received_ts = 381.428741
current_seq = 1166
count = 494
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 53us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.429443
last_received_ts = 381.428741
last_seq = 1166
current_ts = 381.446106
current_received_ts = 381.445435
current_seq = 1167
count = 495
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 42us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.446106
last_received_ts = 381.445435
last_seq = 1167
current_ts = 381.462769
current_received_ts = 381.462097
current_seq = 1168
count = 496
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 51us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.462769
last_received_ts = 381.462097
last_seq = 1168
current_ts = 381.479431
current_received_ts = 381.478760
current_seq = 1169
count = 497
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 54us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.479431
last_received_ts = 381.478760
last_seq = 1169
current_ts = 381.496124
current_received_ts = 381.495422
current_seq = 1170
count = 498
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 52us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.496124
last_received_ts = 381.495422
last_seq = 1170
current_ts = 381.512787
current_received_ts = 381.512238
current_seq = 1171
count = 499
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 59us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.512787
last_received_ts = 381.512238
last_seq = 1171
current_ts = 381.529449
current_received_ts = 381.528778
current_seq = 1172
count = 500
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 140us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.529449
last_received_ts = 381.528778
last_seq = 1172
current_ts = 381.546112
current_received_ts = 381.545410
current_seq = 1173
count = 501
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 71us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.546112
last_received_ts = 381.545410
last_seq = 1173
current_ts = 381.562775
current_received_ts = 381.562073
current_seq = 1174
count = 502
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 44us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.562775
last_received_ts = 381.562073
last_seq = 1174
current_ts = 381.579437
current_received_ts = 381.578766
current_seq = 1175
count = 503
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 64us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.579437
last_received_ts = 381.578766
last_seq = 1175
current_ts = 381.596100
current_received_ts = 381.595428
current_seq = 1176
count = 504
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 54us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.596100
last_received_ts = 381.595428
last_seq = 1176
current_ts = 381.612762
current_received_ts = 381.612061
current_seq = 1177
count = 505
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 55us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.612762
last_received_ts = 381.612061
last_seq = 1177
current_ts = 381.629425
current_received_ts = 381.628784
current_seq = 1178
count = 506
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 59us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.629425
last_received_ts = 381.628784
last_seq = 1178
current_ts = 381.646088
current_received_ts = 381.645416
current_seq = 1179
count = 507
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 52us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.646088
last_received_ts = 381.645416
last_seq = 1179
current_ts = 381.662750
current_received_ts = 381.662079
current_seq = 1180
count = 508
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 45us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.662750
last_received_ts = 381.662079
last_seq = 1180
current_ts = 381.679413
current_received_ts = 381.678741
current_seq = 1181
count = 509
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 92us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.679413
last_received_ts = 381.678741
last_seq = 1181
current_ts = 381.696106
current_received_ts = 381.695404
current_seq = 1182
count = 510
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 53us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.696106
last_received_ts = 381.695404
last_seq = 1182
current_ts = 381.712769
current_received_ts = 381.712067
current_seq = 1183
count = 511
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 41us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.712769
last_received_ts = 381.712067
last_seq = 1183
current_ts = 381.729431
current_received_ts = 381.728760
current_seq = 1184
count = 512
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 57us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.729431
last_received_ts = 381.728760
last_seq = 1184
current_ts = 381.746094
current_received_ts = 381.745392
current_seq = 1185
count = 513
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 51us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.746094
last_received_ts = 381.745392
last_seq = 1185
current_ts = 381.762756
current_received_ts = 381.762085
current_seq = 1186
count = 514
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 44us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.762756
last_received_ts = 381.762085
last_seq = 1186
current_ts = 381.779419
current_received_ts = 381.778748
current_seq = 1187
count = 515
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 56us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.779419
last_received_ts = 381.778748
last_seq = 1187
current_ts = 381.796082
current_received_ts = 381.795410
current_seq = 1188
count = 516
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 103us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.796082
last_received_ts = 381.795410
last_seq = 1188
current_ts = 381.812744
current_received_ts = 381.812073
current_seq = 1189
count = 517
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 53us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.812744
last_received_ts = 381.812073
last_seq = 1189
current_ts = 381.829407
current_received_ts = 381.828735
current_seq = 1190
count = 518
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 53us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.829407
last_received_ts = 381.828735
last_seq = 1190
current_ts = 381.846069
current_received_ts = 381.845398
current_seq = 1191
count = 519
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 44us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.846069
last_received_ts = 381.845398
last_seq = 1191
current_ts = 381.862762
current_received_ts = 381.862061
current_seq = 1192
count = 520
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 64us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.862762
last_received_ts = 381.862061
last_seq = 1192
current_ts = 381.879425
current_received_ts = 381.878754
current_seq = 1193
count = 521
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 112us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.879425
last_received_ts = 381.878754
last_seq = 1193
current_ts = 381.896088
current_received_ts = 381.895416
current_seq = 1194
count = 522
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 76us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.896088
last_received_ts = 381.895416
last_seq = 1194
current_ts = 381.912750
current_received_ts = 381.912079
current_seq = 1195
count = 523
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 52us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.912750
last_received_ts = 381.912079
last_seq = 1195
current_ts = 381.929413
current_received_ts = 381.928741
current_seq = 1196
count = 524
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 95us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.929413
last_received_ts = 381.928741
last_seq = 1196
current_ts = 381.946075
current_received_ts = 381.945404
current_seq = 1197
count = 525
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 71us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.946075
last_received_ts = 381.945404
last_seq = 1197
current_ts = 381.962738
current_received_ts = 381.962067
current_seq = 1198
count = 526
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 70us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.962738
last_received_ts = 381.962067
last_seq = 1198
current_ts = 381.979401
current_received_ts = 381.978729
current_seq = 1199
count = 527
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 67us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.979401
last_received_ts = 381.978729
last_seq = 1199
current_ts = 381.996063
current_received_ts = 381.995422
current_seq = 1200
count = 528
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 63us
(kms_flip:5249) DEBUG: name = flip
last_ts = 381.996063
last_received_ts = 381.995422
last_seq = 1200
current_ts = 382.012726
current_received_ts = 382.012054
current_seq = 1201
count = 529
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 67us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.012726
last_received_ts = 382.012054
last_seq = 1201
current_ts = 382.029388
current_received_ts = 382.028748
current_seq = 1202
count = 530
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 58us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.029388
last_received_ts = 382.028748
last_seq = 1202
current_ts = 382.046082
current_received_ts = 382.045380
current_seq = 1203
count = 531
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 61us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.046082
last_received_ts = 382.045380
last_seq = 1203
current_ts = 382.062744
current_received_ts = 382.062042
current_seq = 1204
count = 532
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 80us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.062744
last_received_ts = 382.062042
last_seq = 1204
current_ts = 382.079407
current_received_ts = 382.078705
current_seq = 1205
count = 533
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 54us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.079407
last_received_ts = 382.078705
last_seq = 1205
current_ts = 382.096069
current_received_ts = 382.095367
current_seq = 1206
count = 534
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 52us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.096069
last_received_ts = 382.095367
last_seq = 1206
current_ts = 382.112732
current_received_ts = 382.112091
current_seq = 1207
count = 535
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 55us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.112732
last_received_ts = 382.112091
last_seq = 1207
current_ts = 382.129395
current_received_ts = 382.128723
current_seq = 1208
count = 536
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 62us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.129395
last_received_ts = 382.128723
last_seq = 1208
current_ts = 382.146057
current_received_ts = 382.145386
current_seq = 1209
count = 537
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 56us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.146057
last_received_ts = 382.145386
last_seq = 1209
current_ts = 382.162720
current_received_ts = 382.162048
current_seq = 1210
count = 538
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 46us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.162720
last_received_ts = 382.162048
last_seq = 1210
current_ts = 382.179382
current_received_ts = 382.178711
current_seq = 1211
count = 539
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 78us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.179382
last_received_ts = 382.178711
last_seq = 1211
current_ts = 382.196045
current_received_ts = 382.195374
current_seq = 1212
count = 540
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 51us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.196045
last_received_ts = 382.195374
last_seq = 1212
current_ts = 382.212708
current_received_ts = 382.212067
current_seq = 1213
count = 541
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 55us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.212708
last_received_ts = 382.212067
last_seq = 1213
current_ts = 382.229401
current_received_ts = 382.228729
current_seq = 1214
count = 542
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 57us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.229401
last_received_ts = 382.228729
last_seq = 1214
current_ts = 382.246063
current_received_ts = 382.245392
current_seq = 1215
count = 543
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 59us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.246063
last_received_ts = 382.245392
last_seq = 1215
current_ts = 382.262726
current_received_ts = 382.262054
current_seq = 1216
count = 544
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 63us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.262726
last_received_ts = 382.262054
last_seq = 1216
current_ts = 382.279388
current_received_ts = 382.278687
current_seq = 1217
count = 545
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 56us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.279388
last_received_ts = 382.278687
last_seq = 1217
current_ts = 382.296051
current_received_ts = 382.295380
current_seq = 1218
count = 546
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 48us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.296051
last_received_ts = 382.295380
last_seq = 1218
current_ts = 382.312714
current_received_ts = 382.312042
current_seq = 1219
count = 547
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 58us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.312714
last_received_ts = 382.312042
last_seq = 1219
current_ts = 382.329376
current_received_ts = 382.328674
current_seq = 1220
count = 548
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 54us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.329376
last_received_ts = 382.328674
last_seq = 1220
current_ts = 382.346039
current_received_ts = 382.345367
current_seq = 1221
count = 549
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 56us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.346039
last_received_ts = 382.345367
last_seq = 1221
current_ts = 382.362701
current_received_ts = 382.362030
current_seq = 1222
count = 550
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 56us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.362701
last_received_ts = 382.362030
last_seq = 1222
current_ts = 382.379395
current_received_ts = 382.378723
current_seq = 1223
count = 551
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 61us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.379395
last_received_ts = 382.378723
last_seq = 1223
current_ts = 382.396057
current_received_ts = 382.395355
current_seq = 1224
count = 552
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 44us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.396057
last_received_ts = 382.395355
last_seq = 1224
current_ts = 382.412720
current_received_ts = 382.412079
current_seq = 1225
count = 553
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 56us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.412720
last_received_ts = 382.412079
last_seq = 1225
current_ts = 382.429382
current_received_ts = 382.428711
current_seq = 1226
count = 554
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 57us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.429382
last_received_ts = 382.428711
last_seq = 1226
current_ts = 382.446045
current_received_ts = 382.445343
current_seq = 1227
count = 555
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 56us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.446045
last_received_ts = 382.445343
last_seq = 1227
current_ts = 382.462708
current_received_ts = 382.462067
current_seq = 1228
count = 556
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 62us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.462708
last_received_ts = 382.462067
last_seq = 1228
current_ts = 382.479370
current_received_ts = 382.478668
current_seq = 1229
count = 557
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 37us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.479370
last_received_ts = 382.478668
last_seq = 1229
current_ts = 382.496033
current_received_ts = 382.495361
current_seq = 1230
count = 558
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 44us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.496033
last_received_ts = 382.495361
last_seq = 1230
current_ts = 382.512695
current_received_ts = 382.512054
current_seq = 1231
count = 559
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 57us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.512695
last_received_ts = 382.512054
last_seq = 1231
current_ts = 382.529358
current_received_ts = 382.528687
current_seq = 1232
count = 560
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 54us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.529358
last_received_ts = 382.528687
last_seq = 1232
current_ts = 382.546021
current_received_ts = 382.545380
current_seq = 1233
count = 561
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 58us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.546021
last_received_ts = 382.545380
last_seq = 1233
current_ts = 382.562683
current_received_ts = 382.562042
current_seq = 1234
count = 562
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 41us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.562683
last_received_ts = 382.562042
last_seq = 1234
current_ts = 382.579376
current_received_ts = 382.578705
current_seq = 1235
count = 563
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 60us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.579376
last_received_ts = 382.578705
last_seq = 1235
current_ts = 382.596039
current_received_ts = 382.595337
current_seq = 1236
count = 564
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 43us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.596039
last_received_ts = 382.595337
last_seq = 1236
current_ts = 382.612701
current_received_ts = 382.612030
current_seq = 1237
count = 565
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 41us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.612701
last_received_ts = 382.612030
last_seq = 1237
current_ts = 382.629364
current_received_ts = 382.628662
current_seq = 1238
count = 566
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 54us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.629364
last_received_ts = 382.628662
last_seq = 1238
current_ts = 382.646027
current_received_ts = 382.645355
current_seq = 1239
count = 567
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 57us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.646027
last_received_ts = 382.645355
last_seq = 1239
current_ts = 382.662689
current_received_ts = 382.662018
current_seq = 1240
count = 568
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 58us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.662689
last_received_ts = 382.662018
last_seq = 1240
current_ts = 382.679352
current_received_ts = 382.678680
current_seq = 1241
count = 569
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 55us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.679352
last_received_ts = 382.678680
last_seq = 1241
current_ts = 382.696014
current_received_ts = 382.695526
current_seq = 1242
count = 570
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 68us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.696014
last_received_ts = 382.695526
last_seq = 1242
current_ts = 382.712677
current_received_ts = 382.712036
current_seq = 1243
count = 571
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 66us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.712677
last_received_ts = 382.712036
last_seq = 1243
current_ts = 382.729340
current_received_ts = 382.728668
current_seq = 1244
count = 572
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 54us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.729340
last_received_ts = 382.728668
last_seq = 1244
current_ts = 382.746033
current_received_ts = 382.745331
current_seq = 1245
count = 573
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 94us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.746033
last_received_ts = 382.745331
last_seq = 1245
current_ts = 382.762695
current_received_ts = 382.762024
current_seq = 1246
count = 574
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 42us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.762695
last_received_ts = 382.762024
last_seq = 1246
current_ts = 382.779358
current_received_ts = 382.778656
current_seq = 1247
count = 575
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 60us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.779358
last_received_ts = 382.778656
last_seq = 1247
current_ts = 382.796021
current_received_ts = 382.795319
current_seq = 1248
count = 576
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 57us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.796021
last_received_ts = 382.795319
last_seq = 1248
current_ts = 382.812683
current_received_ts = 382.811981
current_seq = 1249
count = 577
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 42us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.812683
last_received_ts = 382.811981
last_seq = 1249
current_ts = 382.829346
current_received_ts = 382.828674
current_seq = 1250
count = 578
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 53us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.829346
last_received_ts = 382.828674
last_seq = 1250
current_ts = 382.846008
current_received_ts = 382.845306
current_seq = 1251
count = 579
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 50us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.846008
last_received_ts = 382.845306
last_seq = 1251
current_ts = 382.862671
current_received_ts = 382.862000
current_seq = 1252
count = 580
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 47us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.862671
last_received_ts = 382.862000
last_seq = 1252
current_ts = 382.879333
current_received_ts = 382.878662
current_seq = 1253
count = 581
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 66us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.879333
last_received_ts = 382.878662
last_seq = 1253
current_ts = 382.895996
current_received_ts = 382.895355
current_seq = 1254
count = 582
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 55us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.895996
last_received_ts = 382.895355
last_seq = 1254
current_ts = 382.912689
current_received_ts = 382.912079
current_seq = 1255
count = 583
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 136us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.912689
last_received_ts = 382.912079
last_seq = 1255
current_ts = 382.929352
current_received_ts = 382.928650
current_seq = 1256
count = 584
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 57us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.929352
last_received_ts = 382.928650
last_seq = 1256
current_ts = 382.946014
current_received_ts = 382.945312
current_seq = 1257
count = 585
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 115us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.946014
last_received_ts = 382.945312
last_seq = 1257
current_ts = 382.962677
current_received_ts = 382.961975
current_seq = 1258
count = 586
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 69us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.962677
last_received_ts = 382.961975
last_seq = 1258
current_ts = 382.979340
current_received_ts = 382.978668
current_seq = 1259
count = 587
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 119us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.979340
last_received_ts = 382.978668
last_seq = 1259
current_ts = 382.996002
current_received_ts = 382.995300
current_seq = 1260
count = 588
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 62us
(kms_flip:5249) DEBUG: name = flip
last_ts = 382.996002
last_received_ts = 382.995300
last_seq = 1260
current_ts = 383.012665
current_received_ts = 383.012024
current_seq = 1261
count = 589
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 90us
(kms_flip:5249) DEBUG: name = flip
last_ts = 383.012665
last_received_ts = 383.012024
last_seq = 1261
current_ts = 383.029327
current_received_ts = 383.028656
current_seq = 1262
count = 590
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 64us
(kms_flip:5249) DEBUG: name = flip
last_ts = 383.029327
last_received_ts = 383.028656
last_seq = 1262
current_ts = 383.045990
current_received_ts = 383.045319
current_seq = 1263
count = 591
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 62us
(kms_flip:5249) DEBUG: name = flip
last_ts = 383.045990
last_received_ts = 383.045319
last_seq = 1263
current_ts = 383.062653
current_received_ts = 383.061981
current_seq = 1264
count = 592
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 53us
(kms_flip:5249) DEBUG: name = flip
last_ts = 383.062653
last_received_ts = 383.061981
last_seq = 1264
current_ts = 383.079315
current_received_ts = 383.078644
current_seq = 1265
count = 593
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 60us
(kms_flip:5249) DEBUG: name = flip
last_ts = 383.079315
last_received_ts = 383.078644
last_seq = 1265
current_ts = 383.095978
current_received_ts = 383.095337
current_seq = 1266
count = 594
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 57us
(kms_flip:5249) DEBUG: name = flip
last_ts = 383.095978
last_received_ts = 383.095337
last_seq = 1266
current_ts = 383.112671
current_received_ts = 383.111969
current_seq = 1267
count = 595
seq_step = 1
(kms_flip:5249) DEBUG: Vblank took 625us
(kms_flip:5249) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:5249) CRITICAL: Failed assertion: end - start < 500
(kms_flip:5249) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:5249) igt_core-INFO: Stack trace:
(kms_flip:5249) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:5249) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:5249) igt_core-INFO:   #2 ../tests/kms_flip.c:1889 run_test()
(kms_flip:5249) igt_core-INFO:   #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045()
(kms_flip:5249) igt_core-INFO:   #4 ../tests/kms_flip.c:2045 main()
(kms_flip:5249) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:5249) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:5249) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (11.168s)

Dmesg

<6> [416.734937] [IGT] kms_flip: starting dynamic subtest B-eDP1

<7> [416.774643] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off

<7> [416.774813] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6

<7> [416.774928] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02

<7> [416.775095] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:242]

<7> [416.776054] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:244]

<7> [416.843791] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:88:pipe A]

<7> [416.843924] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.enable (expected yes, found no)

<7> [416.844096] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.active (expected yes, found no)

<7> [416.844235] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1)

<7> [416.844477] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in lane_count (expected 4, found 0)

<7> [416.844599] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0)

<7> [416.844722] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000)

<7> [416.844845] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0)

<7> [416.844969] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0)

<7> [416.845097] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0)

<7> [416.845222] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0)

<7> [416.845354] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0)

<7> [416.845465] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0)

<7> [416.845574] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0)

<7> [416.845676] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0)

<7> [416.845777] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0)

<7> [416.845880] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0)

<7> [416.845980] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0)

<7> [416.846083] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0)

<7> [416.846196] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0)

<7> [416.846321] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0)

<7> [416.846433] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0)

<7> [416.846535] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0)

<7> [416.846637] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0)

<7> [416.846747] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0)

<7> [416.846856] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0)

<7> [416.846957] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0)

<7> [416.847059] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0)

<7> [416.847158] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0)

<7> [416.847257] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0)

<7> [416.847370] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0)

<7> [416.847475] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0)

<7> [416.847579] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0)

<7> [416.847683] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)

<7> [416.847791] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)

<7> [416.847906] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0)

<7> [416.848013] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0)

<7> [416.848118] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0)

<7> [416.848220] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:88:pipe A] fastset requirement not met in port_clock (expected 432000, found 0)

<7> [416.848334] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:88:pipe A] fastset requirement not met, forcing full modeset

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

<7> [416.848587] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:88:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0

<7> [416.848705] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:83:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0

<7> [416.848830] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:88:pipe A] min cdclk: 173855 kHz -> 0 kHz

<7> [416.848965] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing

<7> [416.849087] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz

<7> [416.849204] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0

<7> [416.849370] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:88:pipe A] enable: no [modeset]

<7> [416.849481] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:33:plane 1A] fb: [NOFB], visible: no

<7> [416.849587] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:43:plane 2A] fb: [NOFB], visible: no

<7> [416.849692] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:53:plane 3A] fb: [NOFB], visible: no

<7> [416.849798] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:63:plane 4A] fb: [NOFB], visible: no

<7> [416.849904] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:73:plane 5A] fb: [NOFB], visible: no

<7> [416.850012] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:83:cursor A] fb: [NOFB], visible: no

<7> [416.850182] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off

<7> [416.850314] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00

<7> [416.850566] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM

<7> [416.850684] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]]

<7> [417.053374] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:205:eDP-1] set backlight PWM = 0

<7> [417.053985] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A

<7> [417.064712] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turn panel power off

<7> [417.065079] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power off time

<7> [417.065465] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060

<7> [417.117856] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000

<7> [417.118400] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:204:DDI A/PHY A] - short

<7> [417.126092] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

<7> [417.126555] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:204:DDI A/PHY A]

<7> [417.126624] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A

<7> [417.127128] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:204:DDI A/PHY A]

<7> [417.127500] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:213:DDI TC1/PHY TC1]

<7> [417.127824] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:215:DP-MST A]

<7> [417.128139] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:216:DP-MST B]

<7> [417.128483] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:217:DP-MST C]

<7> [417.128802] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:225:DDI TC2/PHY TC2]

<7> [417.129113] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:227:DP-MST A]

<7> [417.129448] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:228:DP-MST B]

<7> [417.129761] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:229:DP-MST C]

<7> [417.130067] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:233:DDI TC3/PHY TC3]

<7> [417.130397] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:235:DP-MST A]

<7> [417.130718] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:236:DP-MST B]

<7> [417.131034] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:237:DP-MST C]

<7> [417.131368] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:205:eDP-1]

<7> [417.131745] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

<7> [417.132054] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: *)

<7> [417.132372] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1

<7> [417.132870] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A

<7> [417.133397] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:88:pipe A]

<7> [417.133787] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Post changing CDCLK to 153600 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0

<7> [417.134254] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

<7> [417.134612] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384

<7> [417.135704] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:145:pipe B]

<7> [417.136334] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:202:pipe C]

<7> [417.136794] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:145:pipe B]

<7> [417.136901] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:205:eDP-1]

<7> [417.137171] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CONNECTOR:205:eDP-1] Limiting display bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36)

<7> [417.137715] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:204:DDI A/PHY A][CRTC:145:pipe B] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 max link_bpp 30.0000

<7> [417.138115] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 link rate required 1303913 available 1728000

<7> [417.138559] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:145:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0

<7> [417.138981] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:204:DDI A/PHY A] [CRTC:145:pipe B]

<7> [417.139388] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.enable (expected no, found yes)

<7> [417.139768] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.active (expected no, found yes)

<7> [417.140132] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)

<7> [417.140503] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in lane_count (expected 0, found 4)

<7> [417.140824] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288)

<7> [417.141133] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100)

<7> [417.141445] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)

<7> [417.141728] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880)

<7> [417.142001] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040)

<7> [417.142258] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880)

<7> [417.142526] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040)

<7> [417.142765] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928)

<7> [417.143002] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960)

<7> [417.143230] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800)

<7> [417.143462] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800)

<7> [417.143679] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803)

<7> [417.143885] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809)

<7> [417.144084] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906)

<7> [417.144288] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906)

<7> [417.144482] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880)

<7> [417.144672] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040)

<7> [417.144856] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880)

<7> [417.145034] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040)

<7> [417.145201] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928)

<7> [417.145489] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960)

<7> [417.145665] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800)

<7> [417.145820] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800)

<7> [417.145973] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803)

<7> [417.146119] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809)

<7> [417.146262] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906)

<7> [417.146417] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906)

<7> [417.146562] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)

<7> [417.146698] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)

<7> [417.146834] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)

<7> [417.146973] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30)

<7> [417.147106] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710)

<7> [417.147231] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710)

<7> [417.147362] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:145:pipe B] fastset requirement not met in port_clock (expected 0, found 432000)

<7> [417.147490] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:145:pipe B] fastset requirement not met, forcing full modeset

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

<7> [417.147845] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:145:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2

<7> [417.147990] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:90:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051

<7> [417.148092] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:140:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45

<7> [417.148172] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm

<7> [417.148250] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0

<7> [417.148342] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197

<7> [417.148428] xe 0000:00:02.0: [drm:skl_print_plane_changes [xe]] [PLANE:90:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198

<7> [417.148532] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:145:pipe B] data rate 1390840 num active planes 1

<7> [417.148662] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400

<7> [417.148777] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400

<7> [417.148897] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400

<7> [417.149009] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400

<7> [417.149117] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461

<7> [417.149226] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:145:pipe B] min cdclk: 0 kHz -> 173855 kHz

<7> [417.149388] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing

<7> [417.149524] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz

<7> [417.149634] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0

<7> [417.149794] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:145:pipe B] enable: yes [modeset]

<7> [417.149929] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB

<7> [417.150040] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0

<7> [417.150147] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid>

<7> [417.150250] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0

<7> [417.150372] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0

<7> [417.150486] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0

<7> [417.150594] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 6329869, data_n: 8388608, link_m: 421991, link_n: 524288, tu: 64

<7> [417.150705] xe 0000:00:02.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> [417.150816] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

<7> [417.150920] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled

<7> [417.151024] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled

<7> [417.151129] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0

<7> [417.151235] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4

<7> [417.151355] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14

<7> [417.151468] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB

<7> [417.151577] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB

<7> [417.151689] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0

<7> [417.151791] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range

<7> [417.151895] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined

<7> [417.151998] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1

<7> [417.152103] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0 set context latency: 0

<7> [417.152209] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 37 vsync start: 103, vsync end: 97

<7> [417.152331] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1869, vmax vblank: 1869, vmin vtotal: 1906, vmax vtotal: 1906

<7> [417.152467] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa

<7> [417.152577] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa

<7> [417.152679] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa

<7> [417.152784] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa

<7> [417.152887] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa

<7> [417.152990] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pipe src: 2880x1800+0+0, pixel rate 347710, min cdclk 173855

<7> [417.153096] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0

<7> [417.153201] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0

<7> [417.153327] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no

<7> [417.153443] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0

<7> [417.153547] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dpll_hw_state: dpll: 0x69780, dpll_md: 0x42110, fp0: 0x1a2, fp1: 0x1000000

<7> [417.153651] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0

<7> [417.153754] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries

<7> [417.153857] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000

<7> [417.153962] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000

<7> [417.154066] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000

<7> [417.154171] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000

<7> [417.154293] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000

<7> [417.154309] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off

<7> [417.154419] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000

<7> [417.154473] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6

<7> [417.154528] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [417.154598] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02

<7> [417.154634] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [417.154741] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [417.154744] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling always-on

<7> [417.154849] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000

<7> [417.154964] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:90:plane 1B] fb: [FB:242] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes

<7> [417.155070] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0

<7> [417.155173] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0

<7> [417.155282] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:100:plane 2B] fb: [NOFB], visible: no

<7> [417.155259] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010

<7> [417.155400] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:110:plane 3B] fb: [NOFB], visible: no

<7> [417.155419] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:204:DDI A/PHY A] - long

<7> [417.155508] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:120:plane 4B] fb: [NOFB], visible: no

<7> [417.155530] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10

<7> [417.155615] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:130:plane 5B] fb: [NOFB], visible: no

<7> [417.155650] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:204:DDI A/PHY A]

<7> [417.155723] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:140:cursor B] fb: [NOFB], visible: no

<7> [417.156315] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling always-on

<7> [417.156446] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off

<7> [417.156708] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00

<7> [417.156887] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2

<7> [417.157046] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B

<7> [417.157237] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 192000 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0

<7> [417.157398] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

<7> [417.157520] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480

<7> [417.157636] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:204:DDI A/PHY A]

<7> [417.157724] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:213:DDI TC1/PHY TC1]

<7> [417.157810] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:215:DP-MST A]

<7> [417.157894] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:216:DP-MST B]

<7> [417.157977] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:217:DP-MST C]

<7> [417.158060] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:225:DDI TC2/PHY TC2]

<7> [417.158142] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:227:DP-MST A]

<7> [417.158224] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:228:DP-MST B]

<7> [417.158318] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:229:DP-MST C]

<7> [417.158406] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:233:DDI TC3/PHY TC3]

<7> [417.158497] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:235:DP-MST A]

<7> [417.158580] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:236:DP-MST B]

<7> [417.158663] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:237:DP-MST C]

<7> [417.158747] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf

<7> [417.158933] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *)

<7> [417.159029] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes)

<7> [417.159163] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A

<7> [417.160295] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turn panel power on

<7> [417.160403] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power cycle (467 ms remaining)

<7> [417.629348] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060

<7> [417.639282] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

<7> [417.639581] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 wait for panel power on

<7> [417.639881] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063

<7> [417.675651] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010

<7> [417.676074] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:204:DDI A/PHY A] - long

<7> [417.676481] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20

<7> [417.676935] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:204:DDI A/PHY A]

<7> [417.850191] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

<7> [417.852402] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turning VDD on

<7> [417.852749] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b

<7> [417.855071] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e 44 c1 00 00 01 c0 02 00 02 00 00 0b 80

<7> [417.856382] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Reloading eDP link rates

<7> [417.857259] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05

<7> [417.858438] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0

<7> [417.859571] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using DP training pattern TPS1

<7> [417.860611] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Clock recovery OK

<7> [417.860941] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Using DP training pattern TPS4

<7> [417.862367] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful

<7> [417.862699] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:205:eDP-1][ENCODER:204:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4

<7> [417.863551] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B

<7> [417.864032] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]]

<7> [417.864387] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B

<7> [417.864795] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:205:eDP-1] set backlight PWM = 4518

<7> [417.880982] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2

<7> [417.882924] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:205:eDP-1]

<7> [417.883408] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:145:pipe B]

<7> [420.405072] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 turning VDD off

<7> [420.405618] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:204:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067

<7> [427.846547] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off

<7> [427.847266] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6

<7> [427.847980] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02

<6> [427.904548] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Results for igt@kms_flip@flip-vs-expired-vblank-interruptible@b-edp1