igt@kms_flip@flip-vs-expired-vblank@d-dp2 on shard-bmg@IGT

Detail	Value
Duration	1.45 seconds
Hostname	shard-bmg-8
Igt-Version	IGT-Version: 2.4-ge68d82b44 (x86_64) (Linux: 7.1.0-rc3-lgci-xe-xe-5053-8fbb3d48e61c7e68c-debug+ x86_64)
Out	Starting dynamic subtest: D-DP2 1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 Stack trace: #0 ../lib/igt_core.c:2074 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest D-DP2: FAIL (1.446s)
Err	Starting dynamic subtest: D-DP2 [524.564255] (kms_flip:13051) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [524.564428] (kms_flip:13051) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest D-DP2 failed. ** DEBUG [523.157120] (kms_flip:13051) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000009, size=0) [523.157131] (kms_flip:13051) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) [523.157148] (kms_flip:13051) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) [523.157402] (kms_flip:13051) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680) [523.157404] (kms_flip:13051) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) [523.157429] (kms_flip:13051) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000009, size=0) [523.157437] (kms_flip:13051) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) [523.157452] (kms_flip:13051) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) [523.157673] (kms_flip:13051) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680) [523.157675] (kms_flip:13051) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) [523.160495] (kms_flip:13051) intel_allocator_simple-DEBUG: Using simple allocator [523.164263] (kms_flip:13051) intel_allocator_simple-DEBUG: <ial: 0x62884ac278d0, fd: 5> objects: 3, reserved_areas: 0 [523.164269] (kms_flip:13051) intel_allocator_simple-DEBUG: <ial: 0x62884ac278d0, fd: 5> objects: 3, reserved_areas: 0 [523.181618] (kms_flip:13051) intel_allocator_simple-DEBUG: Using simple allocator [523.182818] (kms_flip:13051) intel_allocator_simple-DEBUG: <ial: 0x62884ac275d0, fd: 5> objects: 3, reserved_areas: 0 [523.182820] (kms_flip:13051) intel_allocator_simple-DEBUG: <ial: 0x62884ac275d0, fd: 5> objects: 3, reserved_areas: 0 [523.185740] (kms_flip:13051) intel_allocator_simple-DEBUG: Using simple allocator [523.186855] (kms_flip:13051) intel_allocator_simple-DEBUG: <ial: 0x62884ac278d0, fd: 5> objects: 3, reserved_areas: 0 [523.186856] (kms_flip:13051) intel_allocator_simple-DEBUG: <ial: 0x62884ac278d0, fd: 5> objects: 3, reserved_areas: 0 [523.198749] (kms_flip:13051) intel_allocator_simple-DEBUG: Using simple allocator [523.199903] (kms_flip:13051) intel_allocator_simple-DEBUG: <ial: 0x62884ac275d0, fd: 5> objects: 3, reserved_areas: 0 [523.199904] (kms_flip:13051) intel_allocator_simple-DEBUG: <ial: 0x62884ac275d0, fd: 5> objects: 3, reserved_areas: 0 [523.200504] (kms_flip:13051) igt_kms-INFO: 1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 [523.220572] (kms_flip:13051) DEBUG: No stale events found [523.386680] (kms_flip:13051) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0 [523.387036] (kms_flip:13051) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0 [523.413545] (kms_flip:13051) DEBUG: name = flip last_ts = 0.000000 last_received_ts = 0.000000 last_seq = 0 current_ts = 525.034912 current_received_ts = 525.034607 current_seq = 1281 count = 0 seq_step = 1 [523.413597] (kms_flip:13051) DEBUG: Vblank took 40us [523.430278] (kms_flip:13051) DEBUG: name = flip last_ts = 525.034912 last_received_ts = 525.034607 last_seq = 1281 current_ts = 525.051575 current_received_ts = 525.051331 current_seq = 1282 count = 1 seq_step = 1 [523.430333] (kms_flip:13051) DEBUG: Vblank took 39us [523.446883] (kms_flip:13051) DEBUG: name = flip last_ts = 525.051575 last_received_ts = 525.051331 last_seq = 1282 current_ts = 525.068237 current_received_ts = 525.067932 current_seq = 1283 count = 2 seq_step = 1 [523.446921] (kms_flip:13051) DEBUG: Vblank took 28us [523.463554] (kms_flip:13051) DEBUG: name = flip last_ts = 525.068237 last_received_ts = 525.067932 last_seq = 1283 current_ts = 525.084900 current_received_ts = 525.084656 current_seq = 1284 count = 3 seq_step = 1 [523.463590] (kms_flip:13051) DEBUG: Vblank took 30us [523.480090] (kms_flip:13051) DEBUG: name = flip last_ts = 525.084900 last_received_ts = 525.084656 last_seq = 1284 current_ts = 525.101562 current_received_ts = 525.101196 current_seq = 1285 count = 4 seq_step = 1 [523.480120] (kms_flip:13051) DEBUG: Vblank took 25us [523.496806] (kms_flip:13051) DEBUG: name = flip last_ts = 525.101562 last_received_ts = 525.101196 last_seq = 1285 current_ts = 525.118225 current_received_ts = 525.117920 current_seq = 1286 count = 5 seq_step = 1 [523.496836] (kms_flip:13051) DEBUG: Vblank took 26us [523.513531] (kms_flip:13051) DEBUG: name = flip last_ts = 525.118225 last_received_ts = 525.117920 last_seq = 1286 current_ts = 525.134949 current_received_ts = 525.134583 current_seq = 1287 count = 6 seq_step = 1 [523.513582] (kms_flip:13051) DEBUG: Vblank took 38us [523.530219] (kms_flip:13051) DEBUG: name = flip last_ts = 525.134949 last_received_ts = 525.134583 last_seq = 1287 current_ts = 525.151611 current_received_ts = 525.151306 current_seq = 1288 count = 7 seq_step = 1 [523.530259] (kms_flip:13051) DEBUG: Vblank took 30us [523.546891] (kms_flip:13051) DEBUG: name = flip last_ts = 525.151611 last_received_ts = 525.151306 last_seq = 1288 current_ts = 525.168274 current_received_ts = 525.167969 current_seq = 1289 count = 8 seq_step = 1 [523.546964] (kms_flip:13051) DEBUG: Vblank took 30us [523.563495] (kms_flip:13051) DEBUG: name = flip last_ts = 525.168274 last_received_ts = 525.167969 last_seq = 1289 current_ts = 525.184937 current_received_ts = 525.184570 current_seq = 1290 count = 9 seq_step = 1 [523.563551] (kms_flip:13051) DEBUG: Vblank took 42us [523.580237] (kms_flip:13051) DEBUG: name = flip last_ts = 525.184937 last_received_ts = 525.184570 last_seq = 1290 current_ts = 525.201599 current_received_ts = 525.201355 current_seq = 1291 count = 10 seq_step = 1 [523.580277] (kms_flip:13051) DEBUG: Vblank took 32us [523.596815] (kms_flip:13051) DEBUG: name = flip last_ts = 525.201599 last_received_ts = 525.201355 last_seq = 1291 current_ts = 525.218262 current_received_ts = 525.217957 current_seq = 1292 count = 11 seq_step = 1 [523.596845] (kms_flip:13051) DEBUG: Vblank took 26us [523.613661] (kms_flip:13051) DEBUG: name = flip last_ts = 525.218262 last_received_ts = 525.217957 last_seq = 1292 current_ts = 525.234924 current_received_ts = 525.234741 current_seq = 1293 count = 12 seq_step = 1 [523.613712] (kms_flip:13051) DEBUG: Vblank took 38us [523.630278] (kms_flip:13051) DEBUG: name = flip last_ts = 525.234924 last_received_ts = 525.234741 last_seq = 1293 current_ts = 525.251648 current_received_ts = 525.251404 current_seq = 1294 count = 13 seq_step = 1 [523.630329] (kms_flip:13051) DEBUG: Vblank took 39us [523.646983] (kms_flip:13051) DEBUG: name = flip last_ts = 525.251648 last_received_ts = 525.251404 last_seq = 1294 current_ts = 525.268311 current_received_ts = 525.268066 current_seq = 1295 count = 14 seq_step = 1 [523.647044] (kms_flip:13051) DEBUG: Vblank took 45us [523.663613] (kms_flip:13051) DEBUG: name = flip last_ts = 525.268311 last_received_ts = 525.268066 last_seq = 1295 current_ts = 525.284973 current_received_ts = 525.284729 current_seq = 1296 count = 15 seq_step = 1 [523.663665] (kms_flip:13051) DEBUG: Vblank took 38us [523.680277] (kms_flip:13051) DEBUG: name = flip last_ts = 525.284973 last_received_ts = 525.284729 last_seq = 1296 current_ts = 525.301636 current_received_ts = 525.301392 current_seq = 1297 count = 16 seq_step = 1 [523.680327] (kms_flip:13051) DEBUG: Vblank took 38us [523.696964] (kms_flip:13051) DEBUG: name = flip last_ts = 525.301636 last_received_ts = 525.301392 last_seq = 1297 current_ts = 525.318298 current_received_ts = 525.318115 current_seq = 1298 count = 17 seq_step = 1 [523.697015] (kms_flip:13051) DEBUG: Vblank took 38us [523.713619] (kms_flip:13051) DEBUG: name = flip last_ts = 525.318298 last_received_ts = 525.318115 last_seq = 1298 current_ts = 525.334961 current_received_ts = 525.334778 current_seq = 1299 count = 18 seq_step = 1 [523.713669] (kms_flip:13051) DEBUG: Vblank took 38us [523.730321] (kms_flip:13051) DEBUG: name = flip last_ts = 525.334961 last_received_ts = 525.334778 last_seq = 1299 current_ts = 525.351624 current_received_ts = 525.351440 current_seq = 1300 count = 19 seq_step = 1 [523.730373] (kms_flip:13051) DEBUG: Vblank took 40us [523.746906] (kms_flip:13051) DEBUG: name = flip last_ts = 525.351624 last_received_ts = 525.351440 last_seq = 1300 current_ts = 525.368347 current_received_ts = 525.368042 current_seq = 1301 count = 20 seq_step = 1 [523.746945] (kms_flip:13051) DEBUG: Vblank took 31us [523.763549] (kms_flip:13051) DEBUG: name = flip last_ts = 525.368347 last_received_ts = 525.368042 last_seq = 1301 current_ts = 525.385010 current_received_ts = 525.384705 current_seq = 1302 count = 21 seq_step = 1 [523.763579] (kms_flip:13051) DEBUG: Vblank took 25us [523.780331] (kms_flip:13051) DEBUG: name = flip last_ts = 525.385010 last_received_ts = 525.384705 last_seq = 1302 current_ts = 525.401672 current_received_ts = 525.401489 current_seq = 1303 count = 22 seq_step = 1 [523.780382] (kms_flip:13051) DEBUG: Vblank took 38us [523.797007] (kms_flip:13051) DEBUG: name = flip last_ts = 525.401672 last_received_ts = 525.401489 last_seq = 1303 current_ts = 525.418335 current_received_ts = 525.418152 current_seq = 1304 count = 23 seq_step = 1 [523.797060] (kms_flip:13051) DEBUG: Vblank took 38us [523.813670] (kms_flip:13051) DEBUG: name = flip last_ts = 525.418335 last_received_ts = 525.418152 last_seq = 1304 current_ts = 525.434998 current_received_ts = 525.434814 current_seq = 1305 count = 24 seq_step = 1 [523.813722] (kms_flip:13051) DEBUG: Vblank took 40us [523.830340] (kms_flip:13051) DEBUG: name = flip last_ts = 525.434998 last_received_ts = 525.434814 last_seq = 1305 current_ts = 525.451660 current_received_ts = 525.451477 current_seq = 1306 count = 25 seq_step = 1 [523.830391] (kms_flip:13051) DEBUG: Vblank took 38us [523.846995] (kms_flip:13051) DEBUG: name = flip last_ts = 525.451660 last_received_ts = 525.451477 last_seq = 1306 current_ts = 525.468384 current_received_ts = 525.468140 current_seq = 1307 count = 26 seq_step = 1 [523.847048] (kms_flip:13051) DEBUG: Vblank took 39us [523.863626] (kms_flip:13051) DEBUG: name = flip last_ts = 525.468384 last_received_ts = 525.468140 last_seq = 1307 current_ts = 525.485046 current_received_ts = 525.484802 current_seq = 1308 count = 27 seq_step = 1 [523.863676] (kms_flip:13051) DEBUG: Vblank took 37us [523.880293] (kms_flip:13051) DEBUG: name = flip last_ts = 525.485046 last_received_ts = 525.484802 last_seq = 1308 current_ts = 525.501709 current_received_ts = 525.501465 current_seq = 1309 count = 28 seq_step = 1 [523.880343] (kms_flip:13051) DEBUG: Vblank took 37us [523.896961] (kms_flip:13051) DEBUG: name = flip last_ts = 525.501709 last_received_ts = 525.501465 last_seq = 1309 current_ts = 525.518372 current_received_ts = 525.518127 current_seq = 1310 count = 29 seq_step = 1 [523.897012] (kms_flip:13051) DEBUG: Vblank took 38us [523.913679] (kms_flip:13051) DEBUG: name = flip last_ts = 525.518372 last_received_ts = 525.518127 last_seq = 1310 current_ts = 525.535034 current_received_ts = 525.534851 current_seq = 1311 count = 30 seq_step = 1 [523.913731] (kms_flip:13051) DEBUG: Vblank took 39us [523.930341] (kms_flip:13051) DEBUG: name = flip last_ts = 525.535034 last_received_ts = 525.534851 last_seq = 1311 current_ts = 525.551697 current_received_ts = 525.551514 current_seq = 1312 count = 31 seq_step = 1 [523.930394] (kms_flip:13051) DEBUG: Vblank took 39us [523.947014] (kms_flip:13051) DEBUG: name = flip last_ts = 525.551697 last_received_ts = 525.551514 last_seq = 1312 current_ts = 525.568420 current_received_ts = 525.568237 current_seq = 1313 count = 32 seq_step = 1 [523.947065] (kms_flip:13051) DEBUG: Vblank took 38us [523.963679] (kms_flip:13051) DEBUG: name = flip last_ts = 525.568420 last_received_ts = 525.568237 last_seq = 1313 current_ts = 525.585083 current_received_ts = 525.584900 current_seq = 1314 count = 33 seq_step = 1 [523.963731] (kms_flip:13051) DEBUG: Vblank took 39us [523.980347] (kms_flip:13051) DEBUG: name = flip last_ts = 525.585083 last_received_ts = 525.584900 last_seq = 1314 current_ts = 525.601746 current_received_ts = 525.601562 current_seq = 1315 count = 34 seq_step = 1 [523.980399] (kms_flip:13051) DEBUG: Vblank took 39us [523.997006] (kms_flip:13051) DEBUG: name = flip last_ts = 525.601746 last_received_ts = 525.601562 last_seq = 1315 current_ts = 525.618408 current_received_ts = 525.618225 current_seq = 1316 count = 35 seq_step = 1 [523.997058] (kms_flip:13051) DEBUG: Vblank took 39us [524.013681] (kms_flip:13051) DEBUG: name = flip last_ts = 525.618408 last_received_ts = 525.618225 last_seq = 1316 current_ts = 525.635071 current_received_ts = 525.634888 current_seq = 1317 count = 36 seq_step = 1 [524.013734] (kms_flip:13051) DEBUG: Vblank took 40us [524.030350] (kms_flip:13051) DEBUG: name = flip last_ts = 525.635071 last_received_ts = 525.634888 last_seq = 1317 current_ts = 525.651733 current_received_ts = 525.651550 current_seq = 1318 count = 37 seq_step = 1 [524.030402] (kms_flip:13051) DEBUG: Vblank took 39us [524.046972] (kms_flip:13051) DEBUG: name = flip last_ts = 525.651733 last_received_ts = 525.651550 last_seq = 1318 current_ts = 525.668457 current_received_ts = 525.668213 current_seq = 1319 count = 38 seq_step = 1 [524.047023] (kms_flip:13051) DEBUG: Vblank took 38us [524.063689] (kms_flip:13051) DEBUG: name = flip last_ts = 525.668457 last_received_ts = 525.668213 last_seq = 1319 current_ts = 525.685120 current_received_ts = 525.684937 current_seq = 1320 count = 39 seq_step = 1 [524.063742] (kms_flip:13051) DEBUG: Vblank took 39us [524.080348] (kms_flip:13051) DEBUG: name = flip last_ts = 525.685120 last_received_ts = 525.684937 last_seq = 1320 current_ts = 525.701782 current_received_ts = 525.701599 current_seq = 1321 count = 40 seq_step = 1 [524.080400] (kms_flip:13051) DEBUG: Vblank took 40us [524.097020] (kms_flip:13051) DEBUG: name = flip last_ts = 525.701782 last_received_ts = 525.701599 last_seq = 1321 current_ts = 525.718445 current_received_ts = 525.718262 current_seq = 1322 count = 41 seq_step = 1 [524.097073] (kms_flip:13051) DEBUG: Vblank took 40us [524.113686] (kms_flip:13051) DEBUG: name = flip last_ts = 525.718445 last_received_ts = 525.718262 last_seq = 1322 current_ts = 525.735107 current_received_ts = 525.734924 current_seq = 1323 count = 42 seq_step = 1 [524.113781] (kms_flip:13051) DEBUG: Vblank took 38us [524.130358] (kms_flip:13051) DEBUG: name = flip last_ts = 525.735107 last_received_ts = 525.734924 last_seq = 1323 current_ts = 525.751770 current_received_ts = 525.751587 current_seq = 1324 count = 43 seq_step = 1 [524.130409] (kms_flip:13051) DEBUG: Vblank took 38us [524.147021] (kms_flip:13051) DEBUG: name = flip last_ts = 525.751770 last_received_ts = 525.751587 last_seq = 1324 current_ts = 525.768494 current_received_ts = 525.768250 current_seq = 1325 count = 44 seq_step = 1 [524.147076] (kms_flip:13051) DEBUG: Vblank took 40us [524.163688] (kms_flip:13051) DEBUG: name = flip last_ts = 525.768494 last_received_ts = 525.768250 last_seq = 1325 current_ts = 525.785156 current_received_ts = 525.784973 current_seq = 1326 count = 45 seq_step = 1 [524.163788] (kms_flip:13051) DEBUG: Vblank took 88us [524.180358] (kms_flip:13051) DEBUG: name = flip last_ts = 525.785156 last_received_ts = 525.784973 last_seq = 1326 current_ts = 525.801819 current_received_ts = 525.801636 current_seq = 1327 count = 46 seq_step = 1 [524.180410] (kms_flip:13051) DEBUG: Vblank took 39us [524.197030] (kms_flip:13051) DEBUG: name = flip last_ts = 525.801819 last_received_ts = 525.801636 last_seq = 1327 current_ts = 525.818481 current_received_ts = 525.818298 current_seq = 1328 count = 47 seq_step = 1 [524.197082] (kms_flip:13051) DEBUG: Vblank took 39us [524.213686] (kms_flip:13051) DEBUG: name = flip last_ts = 525.818481 last_received_ts = 525.818298 last_seq = 1328 current_ts = 525.835144 current_received_ts = 525.834961 current_seq = 1329 count = 48 seq_step = 1 [524.213790] (kms_flip:13051) DEBUG: Vblank took 89us [524.230307] (kms_flip:13051) DEBUG: name = flip last_ts = 525.835144 last_received_ts = 525.834961 last_seq = 1329 current_ts = 525.851807 current_received_ts = 525.851562 current_seq = 1330 count = 49 seq_step = 1 [524.230359] (kms_flip:13051) DEBUG: Vblank took 38us [524.246973] (kms_flip:13051) DEBUG: name = flip last_ts = 525.851807 last_received_ts = 525.851562 last_seq = 1330 current_ts = 525.868469 current_received_ts = 525.868225 current_seq = 1331 count = 50 seq_step = 1 [524.247024] (kms_flip:13051) DEBUG: Vblank took 38us [524.263603] (kms_flip:13051) DEBUG: name = flip last_ts = 525.868469 last_received_ts = 525.868225 last_seq = 1331 current_ts = 525.885193 current_received_ts = 525.884888 current_seq = 1332 count = 51 seq_step = 1 [524.263642] (kms_flip:13051) DEBUG: Vblank took 30us [524.280263] (kms_flip:13051) DEBUG: name = flip last_ts = 525.885193 last_received_ts = 525.884888 last_seq = 1332 current_ts = 525.901855 current_received_ts = 525.901550 current_seq = 1333 count = 52 seq_step = 1 [524.280300] (kms_flip:13051) DEBUG: Vblank took 30us [524.296924] (kms_flip:13051) DEBUG: name = flip last_ts = 525.901855 last_received_ts = 525.901550 last_seq = 1333 current_ts = 525.918518 current_received_ts = 525.918213 current_seq = 1334 count = 53 seq_step = 1 [524.296958] (kms_flip:13051) DEBUG: Vblank took 28us [524.313576] (kms_flip:13051) DEBUG: name = flip last_ts = 525.918518 last_received_ts = 525.918213 last_seq = 1334 current_ts = 525.935181 current_received_ts = 525.934875 current_seq = 1335 count = 54 seq_step = 1 [524.313606] (kms_flip:13051) DEBUG: Vblank took 26us [524.330256] (kms_flip:13051) DEBUG: name = flip last_ts = 525.935181 last_received_ts = 525.934875 last_seq = 1335 current_ts = 525.951843 current_received_ts = 525.951538 current_seq = 1336 count = 55 seq_step = 1 [524.330496] (kms_flip:13051) DEBUG: Vblank took 233us [524.346911] (kms_flip:13051) DEBUG: name = flip last_ts = 525.951843 last_received_ts = 525.951538 last_seq = 1336 current_ts = 525.968506 current_received_ts = 525.968201 current_seq = 1337 count = 56 seq_step = 1 [524.347152] (kms_flip:13051) DEBUG: Vblank took 234us [524.363572] (kms_flip:13051) DEBUG: name = flip last_ts = 525.968506 last_received_ts = 525.968201 last_seq = 1337 current_ts = 525.985168 current_received_ts = 525.984924 current_seq = 1338 count = 57 seq_step = 1 [524.363604] (kms_flip:13051) DEBUG: Vblank took 26us [524.380265] (kms_flip:13051) DEBUG: name = flip last_ts = 525.985168 last_received_ts = 525.984924 last_seq = 1338 current_ts = 526.001892 current_received_ts = 526.001587 current_seq = 1339 count = 58 seq_step = 1 [524.380301] (kms_flip:13051) DEBUG: Vblank took 30us [524.396925] (kms_flip:13051) DEBUG: name = flip last_ts = 526.001892 last_received_ts = 526.001587 last_seq = 1339 current_ts = 526.018555 current_received_ts = 526.018250 current_seq = 1340 count = 59 seq_step = 1 [524.397149] (kms_flip:13051) DEBUG: Vblank took 218us [524.413752] (kms_flip:13051) DEBUG: name = flip last_ts = 526.018555 last_received_ts = 526.018250 last_seq = 1340 current_ts = 526.035217 current_received_ts = 526.035095 current_seq = 1341 count = 60 seq_step = 1 [524.413805] (kms_flip:13051) DEBUG: Vblank took 38us [524.430364] (kms_flip:13051) DEBUG: name = flip last_ts = 526.035217 last_received_ts = 526.035095 last_seq = 1341 current_ts = 526.051880 current_received_ts = 526.051697 current_seq = 1342 count = 61 seq_step = 1 [524.430417] (kms_flip:13051) DEBUG: Vblank took 38us [524.447028] (kms_flip:13051) DEBUG: name = flip last_ts = 526.051880 last_received_ts = 526.051697 last_seq = 1342 current_ts = 526.068542 current_received_ts = 526.068359 current_seq = 1343 count = 62 seq_step = 1 [524.447080] (kms_flip:13051) DEBUG: Vblank took 39us [524.463743] (kms_flip:13051) DEBUG: name = flip last_ts = 526.068542 last_received_ts = 526.068359 last_seq = 1343 current_ts = 526.085205 current_received_ts = 526.085083 current_seq = 1344 count = 63 seq_step = 1 [524.463796] (kms_flip:13051) DEBUG: Vblank took 39us [524.480310] (kms_flip:13051) DEBUG: name = flip last_ts = 526.085205 last_received_ts = 526.085083 last_seq = 1344 current_ts = 526.101929 current_received_ts = 526.101624 current_seq = 1345 count = 64 seq_step = 1 [524.480362] (kms_flip:13051) DEBUG: Vblank took 37us [524.496942] (kms_flip:13051) DEBUG: name = flip last_ts = 526.101929 last_received_ts = 526.101624 last_seq = 1345 current_ts = 526.118591 current_received_ts = 526.118286 current_seq = 1346 count = 65 seq_step = 1 [524.496980] (kms_flip:13051) DEBUG: Vblank took 29us [524.513604] (kms_flip:13051) DEBUG: name = flip last_ts = 526.118591 last_received_ts = 526.118286 last_seq = 1346 current_ts = 526.135254 current_received_ts = 526.134949 current_seq = 1347 count = 66 seq_step = 1 [524.513675] (kms_flip:13051) DEBUG: Vblank took 64us [524.530266] (kms_flip:13051) DEBUG: name = flip last_ts = 526.135254 last_received_ts = 526.134949 last_seq = 1347 current_ts = 526.151917 current_received_ts = 526.151611 current_seq = 1348 count = 67 seq_step = 1 [524.530298] (kms_flip:13051) DEBUG: Vblank took 26us [524.546935] (kms_flip:13051) DEBUG: name = flip last_ts = 526.151917 last_received_ts = 526.151611 last_seq = 1348 current_ts = 526.168579 current_received_ts = 526.168335 current_seq = 1349 count = 68 seq_step = 1 [524.546969] (kms_flip:13051) DEBUG: Vblank took 28us [524.563598] (kms_flip:13051) DEBUG: name = flip last_ts = 526.168579 last_received_ts = 526.168335 last_seq = 1349 current_ts = 526.185242 current_received_ts = 526.184998 current_seq = 1350 count = 69 seq_step = 1 [524.564249] (kms_flip:13051) DEBUG: Vblank took 645us [524.564255] (kms_flip:13051) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [524.564428] (kms_flip:13051) CRITICAL: Failed assertion: end - start < 500 [524.579056] (kms_flip:13051) igt_core-INFO: Stack trace: [524.594537] (kms_flip:13051) igt_core-INFO: #0 ../lib/igt_core.c:2074 __igt_fail_assert() [524.595921] (kms_flip:13051) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [524.595993] (kms_flip:13051) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [524.596048] (kms_flip:13051) igt_core-INFO: #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() [524.596085] (kms_flip:13051) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [524.600391] (kms_flip:13051) igt_core-INFO: #5 [__libc_init_first+0x8a] [524.601270] (kms_flip:13051) igt_core-INFO: #6 [__libc_start_main+0x8b] [524.601460] (kms_flip:13051) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest D-DP2: FAIL (1.446s)
Dmesg	<6> [540.150767] [IGT] kms_flip: starting dynamic subtest D-DP2 <7> [540.151347] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:554] <7> [540.151611] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:559] <7> [540.214504] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [540.215389] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe C] <7> [540.215539] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe B] <7> [540.215663] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.enable (expected yes, found no) <7> [540.215924] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.active (expected yes, found no) <7> [540.216149] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in cpu_transcoder (expected 1, found -1) <7> [540.216353] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in lane_count (expected 4, found 0) <7> [540.216553] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in dp_m_n (expected tu 64 data 7208960/8388608 link 480597/524288, found tu 0, data 0/0 link 0/0) <7> [540.216755] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in output_types (expected 0x00000080, found 0x00000000) <7> [540.216959] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [540.217148] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [540.217331] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [540.217615] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [540.217787] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [540.217964] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [540.218128] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [540.218290] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [540.218450] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [540.218605] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0) <7> [540.218755] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0) <7> [540.218901] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [540.219070] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [540.219214] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [540.219357] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [540.219500] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [540.219641] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [540.219780] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [540.219918] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [540.220050] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [540.220179] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [540.220307] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0) <7> [540.220445] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0) <7> [540.220571] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [540.220697] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [540.220817] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [540.220943] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [540.221060] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0) <7> [540.221176] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in enhanced_framing (expected yes, found no) <7> [540.221294] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [540.221411] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [540.221523] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [540.221633] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in port_clock (expected 162000, found 0) <7> [540.221741] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in infoframes.enable (expected 0x00000002, found 0x00000000) <7> [540.221849] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:387:pipe B] fastset requirement not met, forcing full modeset <7> [540.221971] xe 0000:03:00.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:387:pipe B] releasing TC PLL 2 <7> [540.222111] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [540.222201] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:387:pipe B] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x2 -> 0x0 <7> [540.222307] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:381:cursor B] ddb (4037 - 4096) -> ( 0 - 0), size 59 -> 0 <7> [540.222394] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:387:pipe B] min cdclk: 192000 kHz -> 0 kHz <7> [540.222541] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:387:pipe B] enable: no [modeset] <7> [540.222655] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:271:plane 1B] fb: [NOFB], visible: no <7> [540.222759] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:301:plane 2B] fb: [NOFB], visible: no <7> [540.222862] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:331:plane 3B] fb: [NOFB], visible: no <7> [540.222973] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:361:plane 4B] fb: [NOFB], visible: no <7> [540.223074] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:371:plane 5B] fb: [NOFB], visible: no <7> [540.223174] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:381:cursor B] fb: [NOFB], visible: no <7> [540.223688] xe 0000:03:00.0: [drm:intel_audio_codec_disable [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G] Disable audio codec on [CRTC:387:pipe B] <7> [540.245433] xe 0000:03:00.0: [drm:intel_disable_transcoder [xe]] disabling pipe B <7> [540.263155] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2 <7> [540.266054] xe 0000:03:00.0: [drm:intel_dpll_disable [xe]] disable TC PLL 2 (active 0x2, on? 1) for [CRTC:387:pipe B] <7> [540.268523] xe 0000:03:00.0: [drm:intel_dpll_disable [xe]] disabling TC PLL 2 <7> [540.269349] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:507:DDI TC1/PHY F] <7> [540.269817] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:509:DP-MST A] <7> [540.270336] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:510:DP-MST B] <7> [540.270763] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:511:DP-MST C] <7> [540.271222] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:512:DP-MST D] <7> [540.271627] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:526:DDI TC2/PHY G] <7> [540.272232] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:528:DP-MST A] <7> [540.272572] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:529:DP-MST B] <7> [540.272892] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:530:DP-MST C] <7> [540.273268] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:531:DP-MST D] <7> [540.273586] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:538:DDI TC3/PHY H] <7> [540.273880] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:542:DDI TC4/PHY I] <7> [540.274208] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:544:DP-MST A] <7> [540.274490] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:545:DP-MST B] <7> [540.274757] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:546:DP-MST C] <7> [540.275049] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:547:DP-MST D] <7> [540.275300] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:527:DP-2] <7> [540.275787] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no) <7> [540.276239] xe 0000:03:00.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [540.276458] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [540.277024] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_B <7> [540.277502] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [540.277985] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_2 <7> [540.278440] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:387:pipe B] <7> [540.279050] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:505:pipe D] <7> [540.279643] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:505:pipe D] <7> [540.279679] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:527:DP-2] <7> [540.279784] xe 0000:03:00.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:527:DP-2] Limiting target display pipe bpp to 30 (EDID bpp 48, max requested bpp 30, max platform bpp 36) <7> [540.280007] xe 0000:03:00.0: [drm:intel_dp_compute_config_limits [xe]] [CONNECTOR:527:DP-2] Can't force 30 bpp for HDR (pipe bpp: 18-36 DSC-support: no) <7> [540.280188] xe 0000:03:00.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:526:DDI TC2/PHY G][CRTC:505:pipe D] DP link limits: pixel clock 148500 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [540.280359] xe 0000:03:00.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 162000 bpp input 30 compressed 0.0000 HDR yes link rate required 556875 available 648000 <7> [540.280533] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:505:pipe D] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [540.280706] xe 0000:03:00.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:526:DDI TC2/PHY G] [CRTC:505:pipe D] <7> [540.280880] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.enable (expected no, found yes) <7> [540.281060] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.active (expected no, found yes) <7> [540.281220] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in cpu_transcoder (expected -1, found 3) <7> [540.281377] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in lane_count (expected 0, found 4) <7> [540.281531] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 7208960/8388608 link 480597/524288) <7> [540.281679] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in output_types (expected 0x00000000, found 0x00000080) <7> [540.281818] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [540.281965] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [540.282097] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [540.282227] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [540.282357] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [540.282492] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [540.282612] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [540.282730] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [540.282844] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [540.282967] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084) <7> [540.283077] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089) <7> [540.283187] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [540.283296] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [540.283406] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [540.283506] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [540.283607] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [540.283709] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [540.283807] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [540.283906] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [540.284000] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [540.284093] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [540.284186] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084) <7> [540.284278] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089) <7> [540.284370] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [540.284464] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [540.284557] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [540.284651] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [540.284745] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [540.284839] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in enhanced_framing (expected no, found yes) <7> [540.284940] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [540.285034] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [540.285128] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [540.285222] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in port_clock (expected 0, found 162000) <7> [540.285316] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000002) <7> [540.285411] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:505:pipe D] fastset requirement not met, forcing full modeset <7> [540.285524] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0xf), mbus joined? no->no <7> [540.285605] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:505:pipe D] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x8 <7> [540.285702] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:389:plane 1D] ddb ( 0 - 0) -> ( 0 - 1989), size 0 -> 1989 <7> [540.285779] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:499:cursor D] ddb ( 0 - 0) -> (1989 - 2048), size 0 -> 59 <7> [540.285856] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:389:plane 1D] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [540.285940] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:389:plane 1D] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 4, 9, 9, 17, 17, 17, 17, 0, 15, 0 <7> [540.286014] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:389:plane 1D] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 62, 62, 139, 139, 261, 261, 261, 261, 137, 230, 244 <7> [540.286086] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:389:plane 1D] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 123, 123, 245, 245, 367, 367, 0, 0, 138, 306, 306 <7> [540.286167] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] [CRTC:505:pipe D] data rate 594000 num active planes 1 <7> [540.286274] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 33600 required 624 qgv_peak_bw: 48000 <7> [540.286379] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 53000 required 624 qgv_peak_bw: 48000 <7> [540.286480] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 48000 for required data rate: 624 <7> [540.286592] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:505:pipe D] min cdclk: 0 kHz -> 192000 kHz <7> [540.286718] xe 0000:03:00.0: [drm:intel_find_dpll [xe]] [CRTC:505:pipe D] allocated TC PLL 2 <7> [540.286815] xe 0000:03:00.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:505:pipe D] reserving TC PLL 2 <7> [540.286913] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:505:pipe D] enable: yes [modeset] <7> [540.287020] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: DP (0x80), output format: RGB, sink format: RGB <7> [540.287124] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: D, pipe bpp: 30, dithering: 0 <7> [540.287226] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [540.287327] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [540.287427] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [540.287527] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [540.287626] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 7208960, data_n: 8388608, link_m: 480597, link_n: 524288, tu: 64 <7> [540.287725] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [540.287824] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: enabled <7> [540.287928] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [540.288025] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] psr: disabled, selective update: disabled, panel replay: disabled, selective fetch: disabled <7> [540.288123] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [540.288221] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] audio: 1, infoframes: 0, infoframes enabled: 0x2 <7> [540.288319] xe 0000:03:00.0: HDMI infoframe: Dynamic Range and Mastering, version 1, length 26 <7> [540.288321] xe 0000:03:00.0: length: 26 <7> [540.288322] xe 0000:03:00.0: metadata type: 0 <7> [540.288323] xe 0000:03:00.0: eotf: 2 <7> [540.288325] xe 0000:03:00.0: x[0]: 35400 <7> [540.288326] xe 0000:03:00.0: y[0]: 14599 <7> [540.288327] xe 0000:03:00.0: x[1]: 8500 <7> [540.288329] xe 0000:03:00.0: y[1]: 39850 <7> [540.288330] xe 0000:03:00.0: x[2]: 6550 <7> [540.288331] xe 0000:03:00.0: y[2]: 2300 <7> [540.288332] xe 0000:03:00.0: white point x: 15634 <7> [540.288333] xe 0000:03:00.0: white point y: 16450 <7> [540.288335] xe 0000:03:00.0: max_display_mastering_luminance: 1000 <7> [540.288336] xe 0000:03:00.0: min_display_mastering_luminance: 500 <7> [540.288337] xe 0000:03:00.0: max_cll: 500 <7> [540.288338] xe 0000:03:00.0: max_fall: 1000 <7> [540.288339] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 10 00 09 00 68 36 00 01 00 00 00 00 00 00 00 00 <7> [540.288438] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 61 a4 9a 00 44 50 46 39 30 34 33 35 09 07 07 11 <7> [540.288535] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 17 50 51 07 00 00 00 00 <7> [540.288633] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [540.288730] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [540.288827] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1125, vmax: 1125, flipline: 1125, pipeline full: 0, guardband: 42 vsync start: 41, vsync end: 36 <7> [540.288932] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1083, vmax vblank: 1083, vmin vtotal: 1125, vmax vtotal: 1125 <7> [540.289029] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [540.289127] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 <7> [540.289225] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 <7> [540.289322] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [540.289420] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x40 0x5 <7> [540.289518] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [540.289623] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port clock: 162000, pixel rate 148500, min cdclk 192000, min voltage level 0 <7> [540.289723] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] linetime: 119, ips linetime: 0 <7> [540.289822] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [540.289926] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe src: 1920x1080+0+0 <7> [540.290024] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [540.290121] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [540.290217] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [540.290313] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no <7> [540.290408] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] c20pll_hw_state: <7> [540.290503] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] tx[0] = 0xbe88, tx[1] = 0x5800, tx[2] = 0x0000 <7> [540.290598] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [540.290693] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[0] = 0x50a8 <7> [540.290788] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[1] = 0x2120 <7> [540.290883] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[2] = 0xcd9a <7> [540.290990] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[3] = 0xbfc1 <7> [540.291085] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[4] = 0x5ab8 <7> [540.291179] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[5] = 0x4c34 <7> [540.291274] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[6] = 0x2000 <7> [540.291368] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[7] = 0x0001 <7> [540.291463] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[8] = 0x6000 <7> [540.291557] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[9] = 0x0000 <7> [540.291651] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[10] = 0x0000 <7> [540.291746] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vdr: custom width: 0x00, serdes rate: 0x40, hdmi rate: 0x00 <7> [540.291846] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [540.291949] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [540.292044] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [540.292140] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [540.292236] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [540.292332] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [540.292427] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [540.292522] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [540.292617] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [540.292711] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [540.292806] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [540.292904] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [540.293006] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:389:plane 1D] fb: [FB:554] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [540.293108] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [540.293206] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [540.293303] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:419:plane 2D] fb: [NOFB], visible: no <7> [540.293400] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:449:plane 3D] fb: [NOFB], visible: no <7> [540.293500] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:479:plane 4D] fb: [NOFB], visible: no <7> [540.293599] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:489:plane 5D] fb: [NOFB], visible: no <7> [540.293697] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:499:cursor D] fb: [NOFB], visible: no <7> [540.294310] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [540.294426] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_D <7> [540.294548] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x8 (CLKGATE_DIS_DSSDSC=0x2a000000) <7> [540.294658] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:507:DDI TC1/PHY F] <7> [540.294753] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:509:DP-MST A] <7> [540.294843] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:510:DP-MST B] <7> [540.294938] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:511:DP-MST C] <7> [540.295025] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:512:DP-MST D] <7> [540.295111] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:526:DDI TC2/PHY G] <7> [540.295196] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:528:DP-MST A] <7> [540.295281] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:529:DP-MST B] <7> [540.295367] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:530:DP-MST C] <7> [540.295454] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:531:DP-MST D] <7> [540.295541] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:538:DDI TC3/PHY H] <7> [540.295626] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:542:DDI TC4/PHY I] <7> [540.295709] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:544:DP-MST A] <7> [540.295792] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:545:DP-MST B] <7> [540.295874] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:546:DP-MST C] <7> [540.295966] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:547:DP-MST D] <7> [540.296058] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x3 <7> [540.296224] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no) <7> [540.296322] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enable TC PLL 2 (active 0x8, on? 0) for [CRTC:505:pipe D] <7> [540.296419] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enabling TC PLL 2 <7> [540.300292] xe 0000:03:00.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX USBC2/DDI TC2/PHY G: DPCD: 12 14 c4 01 01 15 01 81 00 01 04 01 0f 00 01 <7> [540.305035] xe 0000:03:00.0: [drm:intel_dp_init_lttpr_and_dprx_caps [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] LTTPR common capabilities: 00 00 00 00 00 00 00 00 <7> [540.306051] xe 0000:03:00.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX USBC2/DDI TC2/PHY G: DPCD: 12 14 c4 01 01 15 01 81 00 01 04 01 0f 00 01 <7> [540.306491] xe 0000:03:00.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using LINK_BW_SET value 06 <7> [540.307998] xe 0000:03:00.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [540.308553] xe 0000:03:00.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using DP training pattern TPS1 <7> [540.314797] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Clock recovery OK <7> [540.314926] xe 0000:03:00.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using DP training pattern TPS3 <7> [540.321779] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Channel EQ done. DP Training successful <7> [540.322005] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Link Training passed at link rate = 162000, lane count = 4 <7> [540.323298] xe 0000:03:00.0: [drm:intel_enable_transcoder [xe]] enabling pipe D <7> [540.357655] xe 0000:03:00.0: [drm:intel_audio_codec_enable [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G] Enable audio codec on [CRTC:505:pipe D], 40 bytes ELD <7> [540.374504] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:527:DP-2] <7> [540.375453] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:505:pipe D] <7> [540.429132] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2 <6> [541.597464] [IGT] kms_flip: finished subtest D-DP2, FAIL

Detail

Value

Duration

1.45 seconds

Hostname

shard-bmg-8

Igt-Version

IGT-Version: 2.4-ge68d82b44 (x86_64) (Linux: 7.1.0-rc3-lgci-xe-xe-5053-8fbb3d48e61c7e68c-debug+ x86_64)

Out

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

Err

Starting dynamic subtest: D-DP2
[524.564255] (kms_flip:13051) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[524.564428] (kms_flip:13051) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest D-DP2 failed.
**** DEBUG ****
[523.157120] (kms_flip:13051) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000009, size=0)
[523.157131] (kms_flip:13051) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
[523.157148] (kms_flip:13051) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
[523.157402] (kms_flip:13051) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
[523.157404] (kms_flip:13051) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
[523.157429] (kms_flip:13051) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000009, size=0)
[523.157437] (kms_flip:13051) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
[523.157452] (kms_flip:13051) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
[523.157673] (kms_flip:13051) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
[523.157675] (kms_flip:13051) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
[523.160495] (kms_flip:13051) intel_allocator_simple-DEBUG: Using simple allocator
[523.164263] (kms_flip:13051) intel_allocator_simple-DEBUG: <ial: 0x62884ac278d0, fd: 5> objects: 3, reserved_areas: 0
[523.164269] (kms_flip:13051) intel_allocator_simple-DEBUG: <ial: 0x62884ac278d0, fd: 5> objects: 3, reserved_areas: 0
[523.181618] (kms_flip:13051) intel_allocator_simple-DEBUG: Using simple allocator
[523.182818] (kms_flip:13051) intel_allocator_simple-DEBUG: <ial: 0x62884ac275d0, fd: 5> objects: 3, reserved_areas: 0
[523.182820] (kms_flip:13051) intel_allocator_simple-DEBUG: <ial: 0x62884ac275d0, fd: 5> objects: 3, reserved_areas: 0
[523.185740] (kms_flip:13051) intel_allocator_simple-DEBUG: Using simple allocator
[523.186855] (kms_flip:13051) intel_allocator_simple-DEBUG: <ial: 0x62884ac278d0, fd: 5> objects: 3, reserved_areas: 0
[523.186856] (kms_flip:13051) intel_allocator_simple-DEBUG: <ial: 0x62884ac278d0, fd: 5> objects: 3, reserved_areas: 0
[523.198749] (kms_flip:13051) intel_allocator_simple-DEBUG: Using simple allocator
[523.199903] (kms_flip:13051) intel_allocator_simple-DEBUG: <ial: 0x62884ac275d0, fd: 5> objects: 3, reserved_areas: 0
[523.199904] (kms_flip:13051) intel_allocator_simple-DEBUG: <ial: 0x62884ac275d0, fd: 5> objects: 3, reserved_areas: 0
[523.200504] (kms_flip:13051) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
[523.220572] (kms_flip:13051) DEBUG: No stale events found
[523.386680] (kms_flip:13051) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
[523.387036] (kms_flip:13051) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
[523.413545] (kms_flip:13051) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 525.034912
current_received_ts = 525.034607
current_seq = 1281
count = 0
seq_step = 1
[523.413597] (kms_flip:13051) DEBUG: Vblank took 40us
[523.430278] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.034912
last_received_ts = 525.034607
last_seq = 1281
current_ts = 525.051575
current_received_ts = 525.051331
current_seq = 1282
count = 1
seq_step = 1
[523.430333] (kms_flip:13051) DEBUG: Vblank took 39us
[523.446883] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.051575
last_received_ts = 525.051331
last_seq = 1282
current_ts = 525.068237
current_received_ts = 525.067932
current_seq = 1283
count = 2
seq_step = 1
[523.446921] (kms_flip:13051) DEBUG: Vblank took 28us
[523.463554] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.068237
last_received_ts = 525.067932
last_seq = 1283
current_ts = 525.084900
current_received_ts = 525.084656
current_seq = 1284
count = 3
seq_step = 1
[523.463590] (kms_flip:13051) DEBUG: Vblank took 30us
[523.480090] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.084900
last_received_ts = 525.084656
last_seq = 1284
current_ts = 525.101562
current_received_ts = 525.101196
current_seq = 1285
count = 4
seq_step = 1
[523.480120] (kms_flip:13051) DEBUG: Vblank took 25us
[523.496806] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.101562
last_received_ts = 525.101196
last_seq = 1285
current_ts = 525.118225
current_received_ts = 525.117920
current_seq = 1286
count = 5
seq_step = 1
[523.496836] (kms_flip:13051) DEBUG: Vblank took 26us
[523.513531] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.118225
last_received_ts = 525.117920
last_seq = 1286
current_ts = 525.134949
current_received_ts = 525.134583
current_seq = 1287
count = 6
seq_step = 1
[523.513582] (kms_flip:13051) DEBUG: Vblank took 38us
[523.530219] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.134949
last_received_ts = 525.134583
last_seq = 1287
current_ts = 525.151611
current_received_ts = 525.151306
current_seq = 1288
count = 7
seq_step = 1
[523.530259] (kms_flip:13051) DEBUG: Vblank took 30us
[523.546891] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.151611
last_received_ts = 525.151306
last_seq = 1288
current_ts = 525.168274
current_received_ts = 525.167969
current_seq = 1289
count = 8
seq_step = 1
[523.546964] (kms_flip:13051) DEBUG: Vblank took 30us
[523.563495] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.168274
last_received_ts = 525.167969
last_seq = 1289
current_ts = 525.184937
current_received_ts = 525.184570
current_seq = 1290
count = 9
seq_step = 1
[523.563551] (kms_flip:13051) DEBUG: Vblank took 42us
[523.580237] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.184937
last_received_ts = 525.184570
last_seq = 1290
current_ts = 525.201599
current_received_ts = 525.201355
current_seq = 1291
count = 10
seq_step = 1
[523.580277] (kms_flip:13051) DEBUG: Vblank took 32us
[523.596815] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.201599
last_received_ts = 525.201355
last_seq = 1291
current_ts = 525.218262
current_received_ts = 525.217957
current_seq = 1292
count = 11
seq_step = 1
[523.596845] (kms_flip:13051) DEBUG: Vblank took 26us
[523.613661] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.218262
last_received_ts = 525.217957
last_seq = 1292
current_ts = 525.234924
current_received_ts = 525.234741
current_seq = 1293
count = 12
seq_step = 1
[523.613712] (kms_flip:13051) DEBUG: Vblank took 38us
[523.630278] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.234924
last_received_ts = 525.234741
last_seq = 1293
current_ts = 525.251648
current_received_ts = 525.251404
current_seq = 1294
count = 13
seq_step = 1
[523.630329] (kms_flip:13051) DEBUG: Vblank took 39us
[523.646983] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.251648
last_received_ts = 525.251404
last_seq = 1294
current_ts = 525.268311
current_received_ts = 525.268066
current_seq = 1295
count = 14
seq_step = 1
[523.647044] (kms_flip:13051) DEBUG: Vblank took 45us
[523.663613] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.268311
last_received_ts = 525.268066
last_seq = 1295
current_ts = 525.284973
current_received_ts = 525.284729
current_seq = 1296
count = 15
seq_step = 1
[523.663665] (kms_flip:13051) DEBUG: Vblank took 38us
[523.680277] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.284973
last_received_ts = 525.284729
last_seq = 1296
current_ts = 525.301636
current_received_ts = 525.301392
current_seq = 1297
count = 16
seq_step = 1
[523.680327] (kms_flip:13051) DEBUG: Vblank took 38us
[523.696964] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.301636
last_received_ts = 525.301392
last_seq = 1297
current_ts = 525.318298
current_received_ts = 525.318115
current_seq = 1298
count = 17
seq_step = 1
[523.697015] (kms_flip:13051) DEBUG: Vblank took 38us
[523.713619] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.318298
last_received_ts = 525.318115
last_seq = 1298
current_ts = 525.334961
current_received_ts = 525.334778
current_seq = 1299
count = 18
seq_step = 1
[523.713669] (kms_flip:13051) DEBUG: Vblank took 38us
[523.730321] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.334961
last_received_ts = 525.334778
last_seq = 1299
current_ts = 525.351624
current_received_ts = 525.351440
current_seq = 1300
count = 19
seq_step = 1
[523.730373] (kms_flip:13051) DEBUG: Vblank took 40us
[523.746906] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.351624
last_received_ts = 525.351440
last_seq = 1300
current_ts = 525.368347
current_received_ts = 525.368042
current_seq = 1301
count = 20
seq_step = 1
[523.746945] (kms_flip:13051) DEBUG: Vblank took 31us
[523.763549] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.368347
last_received_ts = 525.368042
last_seq = 1301
current_ts = 525.385010
current_received_ts = 525.384705
current_seq = 1302
count = 21
seq_step = 1
[523.763579] (kms_flip:13051) DEBUG: Vblank took 25us
[523.780331] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.385010
last_received_ts = 525.384705
last_seq = 1302
current_ts = 525.401672
current_received_ts = 525.401489
current_seq = 1303
count = 22
seq_step = 1
[523.780382] (kms_flip:13051) DEBUG: Vblank took 38us
[523.797007] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.401672
last_received_ts = 525.401489
last_seq = 1303
current_ts = 525.418335
current_received_ts = 525.418152
current_seq = 1304
count = 23
seq_step = 1
[523.797060] (kms_flip:13051) DEBUG: Vblank took 38us
[523.813670] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.418335
last_received_ts = 525.418152
last_seq = 1304
current_ts = 525.434998
current_received_ts = 525.434814
current_seq = 1305
count = 24
seq_step = 1
[523.813722] (kms_flip:13051) DEBUG: Vblank took 40us
[523.830340] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.434998
last_received_ts = 525.434814
last_seq = 1305
current_ts = 525.451660
current_received_ts = 525.451477
current_seq = 1306
count = 25
seq_step = 1
[523.830391] (kms_flip:13051) DEBUG: Vblank took 38us
[523.846995] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.451660
last_received_ts = 525.451477
last_seq = 1306
current_ts = 525.468384
current_received_ts = 525.468140
current_seq = 1307
count = 26
seq_step = 1
[523.847048] (kms_flip:13051) DEBUG: Vblank took 39us
[523.863626] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.468384
last_received_ts = 525.468140
last_seq = 1307
current_ts = 525.485046
current_received_ts = 525.484802
current_seq = 1308
count = 27
seq_step = 1
[523.863676] (kms_flip:13051) DEBUG: Vblank took 37us
[523.880293] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.485046
last_received_ts = 525.484802
last_seq = 1308
current_ts = 525.501709
current_received_ts = 525.501465
current_seq = 1309
count = 28
seq_step = 1
[523.880343] (kms_flip:13051) DEBUG: Vblank took 37us
[523.896961] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.501709
last_received_ts = 525.501465
last_seq = 1309
current_ts = 525.518372
current_received_ts = 525.518127
current_seq = 1310
count = 29
seq_step = 1
[523.897012] (kms_flip:13051) DEBUG: Vblank took 38us
[523.913679] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.518372
last_received_ts = 525.518127
last_seq = 1310
current_ts = 525.535034
current_received_ts = 525.534851
current_seq = 1311
count = 30
seq_step = 1
[523.913731] (kms_flip:13051) DEBUG: Vblank took 39us
[523.930341] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.535034
last_received_ts = 525.534851
last_seq = 1311
current_ts = 525.551697
current_received_ts = 525.551514
current_seq = 1312
count = 31
seq_step = 1
[523.930394] (kms_flip:13051) DEBUG: Vblank took 39us
[523.947014] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.551697
last_received_ts = 525.551514
last_seq = 1312
current_ts = 525.568420
current_received_ts = 525.568237
current_seq = 1313
count = 32
seq_step = 1
[523.947065] (kms_flip:13051) DEBUG: Vblank took 38us
[523.963679] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.568420
last_received_ts = 525.568237
last_seq = 1313
current_ts = 525.585083
current_received_ts = 525.584900
current_seq = 1314
count = 33
seq_step = 1
[523.963731] (kms_flip:13051) DEBUG: Vblank took 39us
[523.980347] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.585083
last_received_ts = 525.584900
last_seq = 1314
current_ts = 525.601746
current_received_ts = 525.601562
current_seq = 1315
count = 34
seq_step = 1
[523.980399] (kms_flip:13051) DEBUG: Vblank took 39us
[523.997006] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.601746
last_received_ts = 525.601562
last_seq = 1315
current_ts = 525.618408
current_received_ts = 525.618225
current_seq = 1316
count = 35
seq_step = 1
[523.997058] (kms_flip:13051) DEBUG: Vblank took 39us
[524.013681] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.618408
last_received_ts = 525.618225
last_seq = 1316
current_ts = 525.635071
current_received_ts = 525.634888
current_seq = 1317
count = 36
seq_step = 1
[524.013734] (kms_flip:13051) DEBUG: Vblank took 40us
[524.030350] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.635071
last_received_ts = 525.634888
last_seq = 1317
current_ts = 525.651733
current_received_ts = 525.651550
current_seq = 1318
count = 37
seq_step = 1
[524.030402] (kms_flip:13051) DEBUG: Vblank took 39us
[524.046972] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.651733
last_received_ts = 525.651550
last_seq = 1318
current_ts = 525.668457
current_received_ts = 525.668213
current_seq = 1319
count = 38
seq_step = 1
[524.047023] (kms_flip:13051) DEBUG: Vblank took 38us
[524.063689] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.668457
last_received_ts = 525.668213
last_seq = 1319
current_ts = 525.685120
current_received_ts = 525.684937
current_seq = 1320
count = 39
seq_step = 1
[524.063742] (kms_flip:13051) DEBUG: Vblank took 39us
[524.080348] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.685120
last_received_ts = 525.684937
last_seq = 1320
current_ts = 525.701782
current_received_ts = 525.701599
current_seq = 1321
count = 40
seq_step = 1
[524.080400] (kms_flip:13051) DEBUG: Vblank took 40us
[524.097020] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.701782
last_received_ts = 525.701599
last_seq = 1321
current_ts = 525.718445
current_received_ts = 525.718262
current_seq = 1322
count = 41
seq_step = 1
[524.097073] (kms_flip:13051) DEBUG: Vblank took 40us
[524.113686] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.718445
last_received_ts = 525.718262
last_seq = 1322
current_ts = 525.735107
current_received_ts = 525.734924
current_seq = 1323
count = 42
seq_step = 1
[524.113781] (kms_flip:13051) DEBUG: Vblank took 38us
[524.130358] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.735107
last_received_ts = 525.734924
last_seq = 1323
current_ts = 525.751770
current_received_ts = 525.751587
current_seq = 1324
count = 43
seq_step = 1
[524.130409] (kms_flip:13051) DEBUG: Vblank took 38us
[524.147021] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.751770
last_received_ts = 525.751587
last_seq = 1324
current_ts = 525.768494
current_received_ts = 525.768250
current_seq = 1325
count = 44
seq_step = 1
[524.147076] (kms_flip:13051) DEBUG: Vblank took 40us
[524.163688] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.768494
last_received_ts = 525.768250
last_seq = 1325
current_ts = 525.785156
current_received_ts = 525.784973
current_seq = 1326
count = 45
seq_step = 1
[524.163788] (kms_flip:13051) DEBUG: Vblank took 88us
[524.180358] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.785156
last_received_ts = 525.784973
last_seq = 1326
current_ts = 525.801819
current_received_ts = 525.801636
current_seq = 1327
count = 46
seq_step = 1
[524.180410] (kms_flip:13051) DEBUG: Vblank took 39us
[524.197030] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.801819
last_received_ts = 525.801636
last_seq = 1327
current_ts = 525.818481
current_received_ts = 525.818298
current_seq = 1328
count = 47
seq_step = 1
[524.197082] (kms_flip:13051) DEBUG: Vblank took 39us
[524.213686] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.818481
last_received_ts = 525.818298
last_seq = 1328
current_ts = 525.835144
current_received_ts = 525.834961
current_seq = 1329
count = 48
seq_step = 1
[524.213790] (kms_flip:13051) DEBUG: Vblank took 89us
[524.230307] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.835144
last_received_ts = 525.834961
last_seq = 1329
current_ts = 525.851807
current_received_ts = 525.851562
current_seq = 1330
count = 49
seq_step = 1
[524.230359] (kms_flip:13051) DEBUG: Vblank took 38us
[524.246973] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.851807
last_received_ts = 525.851562
last_seq = 1330
current_ts = 525.868469
current_received_ts = 525.868225
current_seq = 1331
count = 50
seq_step = 1
[524.247024] (kms_flip:13051) DEBUG: Vblank took 38us
[524.263603] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.868469
last_received_ts = 525.868225
last_seq = 1331
current_ts = 525.885193
current_received_ts = 525.884888
current_seq = 1332
count = 51
seq_step = 1
[524.263642] (kms_flip:13051) DEBUG: Vblank took 30us
[524.280263] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.885193
last_received_ts = 525.884888
last_seq = 1332
current_ts = 525.901855
current_received_ts = 525.901550
current_seq = 1333
count = 52
seq_step = 1
[524.280300] (kms_flip:13051) DEBUG: Vblank took 30us
[524.296924] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.901855
last_received_ts = 525.901550
last_seq = 1333
current_ts = 525.918518
current_received_ts = 525.918213
current_seq = 1334
count = 53
seq_step = 1
[524.296958] (kms_flip:13051) DEBUG: Vblank took 28us
[524.313576] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.918518
last_received_ts = 525.918213
last_seq = 1334
current_ts = 525.935181
current_received_ts = 525.934875
current_seq = 1335
count = 54
seq_step = 1
[524.313606] (kms_flip:13051) DEBUG: Vblank took 26us
[524.330256] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.935181
last_received_ts = 525.934875
last_seq = 1335
current_ts = 525.951843
current_received_ts = 525.951538
current_seq = 1336
count = 55
seq_step = 1
[524.330496] (kms_flip:13051) DEBUG: Vblank took 233us
[524.346911] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.951843
last_received_ts = 525.951538
last_seq = 1336
current_ts = 525.968506
current_received_ts = 525.968201
current_seq = 1337
count = 56
seq_step = 1
[524.347152] (kms_flip:13051) DEBUG: Vblank took 234us
[524.363572] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.968506
last_received_ts = 525.968201
last_seq = 1337
current_ts = 525.985168
current_received_ts = 525.984924
current_seq = 1338
count = 57
seq_step = 1
[524.363604] (kms_flip:13051) DEBUG: Vblank took 26us
[524.380265] (kms_flip:13051) DEBUG: name = flip
last_ts = 525.985168
last_received_ts = 525.984924
last_seq = 1338
current_ts = 526.001892
current_received_ts = 526.001587
current_seq = 1339
count = 58
seq_step = 1
[524.380301] (kms_flip:13051) DEBUG: Vblank took 30us
[524.396925] (kms_flip:13051) DEBUG: name = flip
last_ts = 526.001892
last_received_ts = 526.001587
last_seq = 1339
current_ts = 526.018555
current_received_ts = 526.018250
current_seq = 1340
count = 59
seq_step = 1
[524.397149] (kms_flip:13051) DEBUG: Vblank took 218us
[524.413752] (kms_flip:13051) DEBUG: name = flip
last_ts = 526.018555
last_received_ts = 526.018250
last_seq = 1340
current_ts = 526.035217
current_received_ts = 526.035095
current_seq = 1341
count = 60
seq_step = 1
[524.413805] (kms_flip:13051) DEBUG: Vblank took 38us
[524.430364] (kms_flip:13051) DEBUG: name = flip
last_ts = 526.035217
last_received_ts = 526.035095
last_seq = 1341
current_ts = 526.051880
current_received_ts = 526.051697
current_seq = 1342
count = 61
seq_step = 1
[524.430417] (kms_flip:13051) DEBUG: Vblank took 38us
[524.447028] (kms_flip:13051) DEBUG: name = flip
last_ts = 526.051880
last_received_ts = 526.051697
last_seq = 1342
current_ts = 526.068542
current_received_ts = 526.068359
current_seq = 1343
count = 62
seq_step = 1
[524.447080] (kms_flip:13051) DEBUG: Vblank took 39us
[524.463743] (kms_flip:13051) DEBUG: name = flip
last_ts = 526.068542
last_received_ts = 526.068359
last_seq = 1343
current_ts = 526.085205
current_received_ts = 526.085083
current_seq = 1344
count = 63
seq_step = 1
[524.463796] (kms_flip:13051) DEBUG: Vblank took 39us
[524.480310] (kms_flip:13051) DEBUG: name = flip
last_ts = 526.085205
last_received_ts = 526.085083
last_seq = 1344
current_ts = 526.101929
current_received_ts = 526.101624
current_seq = 1345
count = 64
seq_step = 1
[524.480362] (kms_flip:13051) DEBUG: Vblank took 37us
[524.496942] (kms_flip:13051) DEBUG: name = flip
last_ts = 526.101929
last_received_ts = 526.101624
last_seq = 1345
current_ts = 526.118591
current_received_ts = 526.118286
current_seq = 1346
count = 65
seq_step = 1
[524.496980] (kms_flip:13051) DEBUG: Vblank took 29us
[524.513604] (kms_flip:13051) DEBUG: name = flip
last_ts = 526.118591
last_received_ts = 526.118286
last_seq = 1346
current_ts = 526.135254
current_received_ts = 526.134949
current_seq = 1347
count = 66
seq_step = 1
[524.513675] (kms_flip:13051) DEBUG: Vblank took 64us
[524.530266] (kms_flip:13051) DEBUG: name = flip
last_ts = 526.135254
last_received_ts = 526.134949
last_seq = 1347
current_ts = 526.151917
current_received_ts = 526.151611
current_seq = 1348
count = 67
seq_step = 1
[524.530298] (kms_flip:13051) DEBUG: Vblank took 26us
[524.546935] (kms_flip:13051) DEBUG: name = flip
last_ts = 526.151917
last_received_ts = 526.151611
last_seq = 1348
current_ts = 526.168579
current_received_ts = 526.168335
current_seq = 1349
count = 68
seq_step = 1
[524.546969] (kms_flip:13051) DEBUG: Vblank took 28us
[524.563598] (kms_flip:13051) DEBUG: name = flip
last_ts = 526.168579
last_received_ts = 526.168335
last_seq = 1349
current_ts = 526.185242
current_received_ts = 526.184998
current_seq = 1350
count = 69
seq_step = 1
[524.564249] (kms_flip:13051) DEBUG: Vblank took 645us
[524.564255] (kms_flip:13051) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[524.564428] (kms_flip:13051) CRITICAL: Failed assertion: end - start < 500
[524.579056] (kms_flip:13051) igt_core-INFO: Stack trace:
[524.594537] (kms_flip:13051) igt_core-INFO:   #0 ../lib/igt_core.c:2074 __igt_fail_assert()
[524.595921] (kms_flip:13051) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[524.595993] (kms_flip:13051) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[524.596048] (kms_flip:13051) igt_core-INFO:   #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
[524.596085] (kms_flip:13051) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[524.600391] (kms_flip:13051) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[524.601270] (kms_flip:13051) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[524.601460] (kms_flip:13051) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest D-DP2: FAIL (1.446s)

Dmesg

<6> [540.150767] [IGT] kms_flip: starting dynamic subtest D-DP2

<7> [540.151347] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:554]

<7> [540.151611] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:559]

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

<7> [540.215389] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe C]

<7> [540.215539] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe B]

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

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

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

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

<7> [540.216553] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in dp_m_n (expected tu 64 data 7208960/8388608 link 480597/524288, found tu 0, data 0/0 link 0/0)

<7> [540.216755] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in output_types (expected 0x00000080, found 0x00000000)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [540.221741] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in infoframes.enable (expected 0x00000002, found 0x00000000)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [540.278440] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:387:pipe B]

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

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

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

<7> [540.279784] xe 0000:03:00.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:527:DP-2] Limiting target display pipe bpp to 30 (EDID bpp 48, max requested bpp 30, max platform bpp 36)

<7> [540.280007] xe 0000:03:00.0: [drm:intel_dp_compute_config_limits [xe]] [CONNECTOR:527:DP-2] Can't force 30 bpp for HDR (pipe bpp: 18-36 DSC-support: no)

<7> [540.280188] xe 0000:03:00.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:526:DDI TC2/PHY G][CRTC:505:pipe D] DP link limits: pixel clock 148500 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000

<7> [540.280359] xe 0000:03:00.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 162000 bpp input 30 compressed 0.0000 HDR yes link rate required 556875 available 648000

<7> [540.280533] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:505:pipe D] hw max bpp: 30, pipe bpp: 30, dithering: 0

<7> [540.280706] xe 0000:03:00.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:526:DDI TC2/PHY G] [CRTC:505:pipe D]

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

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

<7> [540.281220] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in cpu_transcoder (expected -1, found 3)

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

<7> [540.281531] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 7208960/8388608 link 480597/524288)

<7> [540.281679] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in output_types (expected 0x00000000, found 0x00000080)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [540.284940] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in pipe_bpp (expected 0, found 30)

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

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

<7> [540.285222] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in port_clock (expected 0, found 162000)

<7> [540.285316] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:505:pipe D] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000002)

<7> [540.285411] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:505:pipe D] fastset requirement not met, forcing full modeset

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

<7> [540.285605] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:505:pipe D] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x8

<7> [540.285702] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:389:plane 1D] ddb ( 0 - 0) -> ( 0 - 1989), size 0 -> 1989

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

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

<7> [540.285940] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:389:plane 1D] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 4, 9, 9, 17, 17, 17, 17, 0, 15, 0

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

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

<7> [540.286167] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] [CRTC:505:pipe D] data rate 594000 num active planes 1

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

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

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

<7> [540.286592] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:505:pipe D] min cdclk: 0 kHz -> 192000 kHz

<7> [540.286718] xe 0000:03:00.0: [drm:intel_find_dpll [xe]] [CRTC:505:pipe D] allocated TC PLL 2

<7> [540.286815] xe 0000:03:00.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:505:pipe D] reserving TC PLL 2

<7> [540.286913] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:505:pipe D] enable: yes [modeset]

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

<7> [540.287124] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: D, pipe bpp: 30, dithering: 0

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

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

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

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

<7> [540.287626] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 7208960, data_n: 8388608, link_m: 480597, link_n: 524288, tu: 64

<7> [540.287725] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0

<7> [540.287824] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: enabled

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

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

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

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

<7> [540.288319] xe 0000:03:00.0: HDMI infoframe: Dynamic Range and Mastering, version 1, length 26

<7> [540.288321] xe 0000:03:00.0: length: 26

<7> [540.288322] xe 0000:03:00.0: metadata type: 0

<7> [540.288323] xe 0000:03:00.0: eotf: 2

<7> [540.288325] xe 0000:03:00.0: x[0]: 35400

<7> [540.288326] xe 0000:03:00.0: y[0]: 14599

<7> [540.288327] xe 0000:03:00.0: x[1]: 8500

<7> [540.288329] xe 0000:03:00.0: y[1]: 39850

<7> [540.288330] xe 0000:03:00.0: x[2]: 6550

<7> [540.288331] xe 0000:03:00.0: y[2]: 2300

<7> [540.288332] xe 0000:03:00.0: white point x: 15634

<7> [540.288333] xe 0000:03:00.0: white point y: 16450

<7> [540.288335] xe 0000:03:00.0: max_display_mastering_luminance: 1000

<7> [540.288336] xe 0000:03:00.0: min_display_mastering_luminance: 500

<7> [540.288337] xe 0000:03:00.0: max_cll: 500

<7> [540.288338] xe 0000:03:00.0: max_fall: 1000

<7> [540.288339] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 10 00 09 00 68 36 00 01 00 00 00 00 00 00 00 00

<7> [540.288438] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 61 a4 9a 00 44 50 46 39 30 34 33 35 09 07 07 11

<7> [540.288535] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 17 50 51 07 00 00 00 00

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

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

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

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

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

<7> [540.289127] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5

<7> [540.289225] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5

<7> [540.289322] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5

<7> [540.289420] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x40 0x5

<7> [540.289518] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5

<7> [540.289623] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port clock: 162000, pixel rate 148500, min cdclk 192000, min voltage level 0

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

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

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

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

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

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

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

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

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

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

<7> [540.290693] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[0] = 0x50a8

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [540.293303] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:419:plane 2D] fb: [NOFB], visible: no

<7> [540.293400] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:449:plane 3D] fb: [NOFB], visible: no

<7> [540.293500] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:479:plane 4D] fb: [NOFB], visible: no

<7> [540.293599] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:489:plane 5D] fb: [NOFB], visible: no

<7> [540.293697] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:499:cursor D] fb: [NOFB], visible: no

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

<7> [540.294426] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_D

<7> [540.294548] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x8 (CLKGATE_DIS_DSSDSC=0x2a000000)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [540.296322] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enable TC PLL 2 (active 0x8, on? 0) for [CRTC:505:pipe D]

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

<7> [540.300292] xe 0000:03:00.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX USBC2/DDI TC2/PHY G: DPCD: 12 14 c4 01 01 15 01 81 00 01 04 01 0f 00 01

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

<7> [540.306051] xe 0000:03:00.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX USBC2/DDI TC2/PHY G: DPCD: 12 14 c4 01 01 15 01 81 00 01 04 01 0f 00 01

<7> [540.306491] xe 0000:03:00.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using LINK_BW_SET value 06

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

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

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

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

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

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

<7> [540.323298] xe 0000:03:00.0: [drm:intel_enable_transcoder [xe]] enabling pipe D

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

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

<7> [540.375453] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:505:pipe D]

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

<6> [541.597464] [IGT] kms_flip: finished subtest D-DP2, FAIL

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