igt@kms_flip@flip-vs-expired-vblank@b-edp1 on shard-lnl@IGTPW

Detail	Value
Duration	2.65 seconds
Hostname	shard-lnl-7
Igt-Version	IGT-Version: 2.4-g3c74f6044 (x86_64) (Linux: 7.1.0-rc5-lgci-xe-xe-5127-6b6931ea69504481e-debug+ x86_64)
Out	Starting dynamic subtest: B-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2106 __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 B-eDP1: FAIL (2.655s)
Err	Starting dynamic subtest: B-eDP1 [375.674201] (kms_flip:7115) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [375.674298] (kms_flip:7115) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest B-eDP1 failed. ** DEBUG [373.034310] (kms_flip:7115) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x100000000000009, size=0) [373.034320] (kms_flip:7115) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) [373.034334] (kms_flip:7115) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) [373.034840] (kms_flip:7115) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=11520) [373.034842] (kms_flip:7115) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) [373.034879] (kms_flip:7115) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x100000000000009, size=0) [373.034886] (kms_flip:7115) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) [373.034899] (kms_flip:7115) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) [373.038302] (kms_flip:7115) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=4, pitch=11520) [373.038305] (kms_flip:7115) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) [373.044230] (kms_flip:7115) intel_allocator_simple-DEBUG: Using simple allocator [373.048520] (kms_flip:7115) intel_allocator_simple-DEBUG: <ial: 0x61df3a655040, fd: 5> objects: 3, reserved_areas: 0 [373.048522] (kms_flip:7115) intel_allocator_simple-DEBUG: <ial: 0x61df3a655040, fd: 5> objects: 3, reserved_areas: 0 [373.065924] (kms_flip:7115) intel_allocator_simple-DEBUG: Using simple allocator [373.069808] (kms_flip:7115) intel_allocator_simple-DEBUG: <ial: 0x61df3a655040, fd: 5> objects: 3, reserved_areas: 0 [373.069809] (kms_flip:7115) intel_allocator_simple-DEBUG: <ial: 0x61df3a655040, fd: 5> objects: 3, reserved_areas: 0 [373.074683] (kms_flip:7115) intel_allocator_simple-DEBUG: Using simple allocator [373.079052] (kms_flip:7115) intel_allocator_simple-DEBUG: <ial: 0x61df3a6dd610, fd: 5> objects: 3, reserved_areas: 0 [373.079057] (kms_flip:7115) intel_allocator_simple-DEBUG: <ial: 0x61df3a6dd610, fd: 5> objects: 3, reserved_areas: 0 [373.094648] (kms_flip:7115) intel_allocator_simple-DEBUG: Using simple allocator [373.098542] (kms_flip:7115) intel_allocator_simple-DEBUG: <ial: 0x61df3a655040, fd: 5> objects: 3, reserved_areas: 0 [373.098544] (kms_flip:7115) intel_allocator_simple-DEBUG: <ial: 0x61df3a655040, fd: 5> objects: 3, reserved_areas: 0 [373.100192] (kms_flip:7115) igt_kms-INFO: 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa [373.120316] (kms_flip:7115) DEBUG: No stale events found [374.245101] (kms_flip:7115) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0 [374.245296] (kms_flip:7115) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0 [374.273270] (kms_flip:7115) DEBUG: name = flip last_ts = 0.000000 last_received_ts = 0.000000 last_seq = 0 current_ts = 375.789032 current_received_ts = 375.788361 current_seq = 5 count = 0 seq_step = 1 [374.273359] (kms_flip:7115) DEBUG: Vblank took 78us [374.290041] (kms_flip:7115) DEBUG: name = flip last_ts = 375.789032 last_received_ts = 375.788361 last_seq = 5 current_ts = 375.805695 current_received_ts = 375.805145 current_seq = 6 count = 1 seq_step = 1 [374.290117] (kms_flip:7115) DEBUG: Vblank took 68us [374.306669] (kms_flip:7115) DEBUG: name = flip last_ts = 375.805695 last_received_ts = 375.805145 last_seq = 6 current_ts = 375.822357 current_received_ts = 375.821777 current_seq = 7 count = 2 seq_step = 1 [374.306741] (kms_flip:7115) DEBUG: Vblank took 64us [374.323331] (kms_flip:7115) DEBUG: name = flip last_ts = 375.822357 last_received_ts = 375.821777 last_seq = 7 current_ts = 375.839020 current_received_ts = 375.838440 current_seq = 8 count = 3 seq_step = 1 [374.323469] (kms_flip:7115) DEBUG: Vblank took 131us [374.340011] (kms_flip:7115) DEBUG: name = flip last_ts = 375.839020 last_received_ts = 375.838440 last_seq = 8 current_ts = 375.855682 current_received_ts = 375.855103 current_seq = 9 count = 4 seq_step = 1 [374.340078] (kms_flip:7115) DEBUG: Vblank took 61us [374.356697] (kms_flip:7115) DEBUG: name = flip last_ts = 375.855682 last_received_ts = 375.855103 last_seq = 9 current_ts = 375.872345 current_received_ts = 375.871796 current_seq = 10 count = 5 seq_step = 1 [374.356767] (kms_flip:7115) DEBUG: Vblank took 63us [374.373324] (kms_flip:7115) DEBUG: name = flip last_ts = 375.872345 last_received_ts = 375.871796 last_seq = 10 current_ts = 375.889008 current_received_ts = 375.888428 current_seq = 11 count = 6 seq_step = 1 [374.373464] (kms_flip:7115) DEBUG: Vblank took 131us [374.389997] (kms_flip:7115) DEBUG: name = flip last_ts = 375.889008 last_received_ts = 375.888428 last_seq = 11 current_ts = 375.905670 current_received_ts = 375.905090 current_seq = 12 count = 7 seq_step = 1 [374.390068] (kms_flip:7115) DEBUG: Vblank took 62us [374.406665] (kms_flip:7115) DEBUG: name = flip last_ts = 375.905670 last_received_ts = 375.905090 last_seq = 12 current_ts = 375.922363 current_received_ts = 375.921783 current_seq = 13 count = 8 seq_step = 1 [374.406737] (kms_flip:7115) DEBUG: Vblank took 63us [374.423334] (kms_flip:7115) DEBUG: name = flip last_ts = 375.922363 last_received_ts = 375.921783 last_seq = 13 current_ts = 375.939026 current_received_ts = 375.938446 current_seq = 14 count = 9 seq_step = 1 [374.423466] (kms_flip:7115) DEBUG: Vblank took 124us [374.440002] (kms_flip:7115) DEBUG: name = flip last_ts = 375.939026 last_received_ts = 375.938446 last_seq = 14 current_ts = 375.955688 current_received_ts = 375.955109 current_seq = 15 count = 10 seq_step = 1 [374.440070] (kms_flip:7115) DEBUG: Vblank took 60us [374.456655] (kms_flip:7115) DEBUG: name = flip last_ts = 375.955688 last_received_ts = 375.955109 last_seq = 15 current_ts = 375.972351 current_received_ts = 375.971771 current_seq = 16 count = 11 seq_step = 1 [374.456722] (kms_flip:7115) DEBUG: Vblank took 60us [374.473328] (kms_flip:7115) DEBUG: name = flip last_ts = 375.972351 last_received_ts = 375.971771 last_seq = 16 current_ts = 375.989014 current_received_ts = 375.988434 current_seq = 17 count = 12 seq_step = 1 [374.473447] (kms_flip:7115) DEBUG: Vblank took 112us [374.490005] (kms_flip:7115) DEBUG: name = flip last_ts = 375.989014 last_received_ts = 375.988434 last_seq = 17 current_ts = 376.005676 current_received_ts = 376.005127 current_seq = 18 count = 13 seq_step = 1 [374.490072] (kms_flip:7115) DEBUG: Vblank took 59us [374.506648] (kms_flip:7115) DEBUG: name = flip last_ts = 376.005676 last_received_ts = 376.005127 last_seq = 18 current_ts = 376.022339 current_received_ts = 376.021759 current_seq = 19 count = 14 seq_step = 1 [374.506719] (kms_flip:7115) DEBUG: Vblank took 63us [374.523317] (kms_flip:7115) DEBUG: name = flip last_ts = 376.022339 last_received_ts = 376.021759 last_seq = 19 current_ts = 376.039001 current_received_ts = 376.038422 current_seq = 20 count = 15 seq_step = 1 [374.523428] (kms_flip:7115) DEBUG: Vblank took 104us [374.539976] (kms_flip:7115) DEBUG: name = flip last_ts = 376.039001 last_received_ts = 376.038422 last_seq = 20 current_ts = 376.055664 current_received_ts = 376.055084 current_seq = 21 count = 16 seq_step = 1 [374.540046] (kms_flip:7115) DEBUG: Vblank took 63us [374.556653] (kms_flip:7115) DEBUG: name = flip last_ts = 376.055664 last_received_ts = 376.055084 last_seq = 21 current_ts = 376.072327 current_received_ts = 376.071747 current_seq = 22 count = 17 seq_step = 1 [374.556723] (kms_flip:7115) DEBUG: Vblank took 64us [374.573311] (kms_flip:7115) DEBUG: name = flip last_ts = 376.072327 last_received_ts = 376.071747 last_seq = 22 current_ts = 376.088989 current_received_ts = 376.088409 current_seq = 23 count = 18 seq_step = 1 [374.573438] (kms_flip:7115) DEBUG: Vblank took 120us [374.589982] (kms_flip:7115) DEBUG: name = flip last_ts = 376.088989 last_received_ts = 376.088409 last_seq = 23 current_ts = 376.105652 current_received_ts = 376.105103 current_seq = 24 count = 19 seq_step = 1 [374.590053] (kms_flip:7115) DEBUG: Vblank took 64us [374.606628] (kms_flip:7115) DEBUG: name = flip last_ts = 376.105652 last_received_ts = 376.105103 last_seq = 24 current_ts = 376.122314 current_received_ts = 376.121735 current_seq = 25 count = 20 seq_step = 1 [374.606698] (kms_flip:7115) DEBUG: Vblank took 63us [374.623272] (kms_flip:7115) DEBUG: name = flip last_ts = 376.122314 last_received_ts = 376.121735 last_seq = 25 current_ts = 376.138977 current_received_ts = 376.138397 current_seq = 26 count = 21 seq_step = 1 [374.623400] (kms_flip:7115) DEBUG: Vblank took 120us [374.639958] (kms_flip:7115) DEBUG: name = flip last_ts = 376.138977 last_received_ts = 376.138397 last_seq = 26 current_ts = 376.155640 current_received_ts = 376.155060 current_seq = 27 count = 22 seq_step = 1 [374.640028] (kms_flip:7115) DEBUG: Vblank took 63us [374.656611] (kms_flip:7115) DEBUG: name = flip last_ts = 376.155640 last_received_ts = 376.155060 last_seq = 27 current_ts = 376.172302 current_received_ts = 376.171722 current_seq = 28 count = 23 seq_step = 1 [374.656679] (kms_flip:7115) DEBUG: Vblank took 60us [374.673266] (kms_flip:7115) DEBUG: name = flip last_ts = 376.172302 last_received_ts = 376.171722 last_seq = 28 current_ts = 376.188965 current_received_ts = 376.188385 current_seq = 29 count = 24 seq_step = 1 [374.673381] (kms_flip:7115) DEBUG: Vblank took 108us [374.689951] (kms_flip:7115) DEBUG: name = flip last_ts = 376.188965 last_received_ts = 376.188385 last_seq = 29 current_ts = 376.205627 current_received_ts = 376.205078 current_seq = 30 count = 25 seq_step = 1 [374.690019] (kms_flip:7115) DEBUG: Vblank took 61us [374.706593] (kms_flip:7115) DEBUG: name = flip last_ts = 376.205627 last_received_ts = 376.205078 last_seq = 30 current_ts = 376.222321 current_received_ts = 376.221710 current_seq = 31 count = 26 seq_step = 1 [374.706660] (kms_flip:7115) DEBUG: Vblank took 60us [374.723261] (kms_flip:7115) DEBUG: name = flip last_ts = 376.222321 last_received_ts = 376.221710 last_seq = 31 current_ts = 376.238983 current_received_ts = 376.238373 current_seq = 32 count = 27 seq_step = 1 [374.723390] (kms_flip:7115) DEBUG: Vblank took 121us [374.739956] (kms_flip:7115) DEBUG: name = flip last_ts = 376.238983 last_received_ts = 376.238373 last_seq = 32 current_ts = 376.255646 current_received_ts = 376.255066 current_seq = 33 count = 28 seq_step = 1 [374.740028] (kms_flip:7115) DEBUG: Vblank took 65us [374.756602] (kms_flip:7115) DEBUG: name = flip last_ts = 376.255646 last_received_ts = 376.255066 last_seq = 33 current_ts = 376.272308 current_received_ts = 376.271729 current_seq = 34 count = 29 seq_step = 1 [374.756672] (kms_flip:7115) DEBUG: Vblank took 63us [374.773256] (kms_flip:7115) DEBUG: name = flip last_ts = 376.272308 last_received_ts = 376.271729 last_seq = 34 current_ts = 376.288971 current_received_ts = 376.288361 current_seq = 35 count = 30 seq_step = 1 [374.773359] (kms_flip:7115) DEBUG: Vblank took 97us [374.789968] (kms_flip:7115) DEBUG: name = flip last_ts = 376.288971 last_received_ts = 376.288361 last_seq = 35 current_ts = 376.305634 current_received_ts = 376.305084 current_seq = 36 count = 31 seq_step = 1 [374.790039] (kms_flip:7115) DEBUG: Vblank took 63us [374.806589] (kms_flip:7115) DEBUG: name = flip last_ts = 376.305634 last_received_ts = 376.305084 last_seq = 36 current_ts = 376.322296 current_received_ts = 376.321716 current_seq = 37 count = 32 seq_step = 1 [374.806656] (kms_flip:7115) DEBUG: Vblank took 61us [374.823252] (kms_flip:7115) DEBUG: name = flip last_ts = 376.322296 last_received_ts = 376.321716 last_seq = 37 current_ts = 376.338959 current_received_ts = 376.338379 current_seq = 38 count = 33 seq_step = 1 [374.823378] (kms_flip:7115) DEBUG: Vblank took 119us [374.839937] (kms_flip:7115) DEBUG: name = flip last_ts = 376.338959 last_received_ts = 376.338379 last_seq = 38 current_ts = 376.355621 current_received_ts = 376.355042 current_seq = 39 count = 34 seq_step = 1 [374.840012] (kms_flip:7115) DEBUG: Vblank took 66us [374.856584] (kms_flip:7115) DEBUG: name = flip last_ts = 376.355621 last_received_ts = 376.355042 last_seq = 39 current_ts = 376.372284 current_received_ts = 376.371704 current_seq = 40 count = 35 seq_step = 1 [374.856656] (kms_flip:7115) DEBUG: Vblank took 66us [374.873236] (kms_flip:7115) DEBUG: name = flip last_ts = 376.372284 last_received_ts = 376.371704 last_seq = 40 current_ts = 376.388947 current_received_ts = 376.388336 current_seq = 41 count = 36 seq_step = 1 [374.873384] (kms_flip:7115) DEBUG: Vblank took 139us [374.889935] (kms_flip:7115) DEBUG: name = flip last_ts = 376.388947 last_received_ts = 376.388336 last_seq = 41 current_ts = 376.405609 current_received_ts = 376.405060 current_seq = 42 count = 37 seq_step = 1 [374.890001] (kms_flip:7115) DEBUG: Vblank took 59us [374.906586] (kms_flip:7115) DEBUG: name = flip last_ts = 376.405609 last_received_ts = 376.405060 last_seq = 42 current_ts = 376.422272 current_received_ts = 376.421692 current_seq = 43 count = 38 seq_step = 1 [374.906655] (kms_flip:7115) DEBUG: Vblank took 61us [374.923240] (kms_flip:7115) DEBUG: name = flip last_ts = 376.422272 last_received_ts = 376.421692 last_seq = 43 current_ts = 376.438934 current_received_ts = 376.438354 current_seq = 44 count = 39 seq_step = 1 [374.923375] (kms_flip:7115) DEBUG: Vblank took 128us [374.939921] (kms_flip:7115) DEBUG: name = flip last_ts = 376.438934 last_received_ts = 376.438354 last_seq = 44 current_ts = 376.455597 current_received_ts = 376.455048 current_seq = 45 count = 40 seq_step = 1 [374.939987] (kms_flip:7115) DEBUG: Vblank took 59us [374.956570] (kms_flip:7115) DEBUG: name = flip last_ts = 376.455597 last_received_ts = 376.455048 last_seq = 45 current_ts = 376.472260 current_received_ts = 376.471680 current_seq = 46 count = 41 seq_step = 1 [374.956642] (kms_flip:7115) DEBUG: Vblank took 63us [374.973237] (kms_flip:7115) DEBUG: name = flip last_ts = 376.472260 last_received_ts = 376.471680 last_seq = 46 current_ts = 376.488922 current_received_ts = 376.488342 current_seq = 47 count = 42 seq_step = 1 [374.973365] (kms_flip:7115) DEBUG: Vblank took 120us [374.989936] (kms_flip:7115) DEBUG: name = flip last_ts = 376.488922 last_received_ts = 376.488342 last_seq = 47 current_ts = 376.505585 current_received_ts = 376.505066 current_seq = 48 count = 43 seq_step = 1 [374.990006] (kms_flip:7115) DEBUG: Vblank took 61us [375.006580] (kms_flip:7115) DEBUG: name = flip last_ts = 376.505585 last_received_ts = 376.505066 last_seq = 48 current_ts = 376.522247 current_received_ts = 376.521698 current_seq = 49 count = 44 seq_step = 1 [375.006652] (kms_flip:7115) DEBUG: Vblank took 64us [375.023231] (kms_flip:7115) DEBUG: name = flip last_ts = 376.522247 last_received_ts = 376.521698 last_seq = 49 current_ts = 376.538940 current_received_ts = 376.538361 current_seq = 50 count = 45 seq_step = 1 [375.023348] (kms_flip:7115) DEBUG: Vblank took 110us [375.039924] (kms_flip:7115) DEBUG: name = flip last_ts = 376.538940 last_received_ts = 376.538361 last_seq = 50 current_ts = 376.555603 current_received_ts = 376.555054 current_seq = 51 count = 46 seq_step = 1 [375.039995] (kms_flip:7115) DEBUG: Vblank took 63us [375.056568] (kms_flip:7115) DEBUG: name = flip last_ts = 376.555603 last_received_ts = 376.555054 last_seq = 51 current_ts = 376.572266 current_received_ts = 376.571686 current_seq = 52 count = 47 seq_step = 1 [375.056641] (kms_flip:7115) DEBUG: Vblank took 65us [375.073214] (kms_flip:7115) DEBUG: name = flip last_ts = 376.572266 last_received_ts = 376.571686 last_seq = 52 current_ts = 376.588928 current_received_ts = 376.588318 current_seq = 53 count = 48 seq_step = 1 [375.073335] (kms_flip:7115) DEBUG: Vblank took 113us [375.089925] (kms_flip:7115) DEBUG: name = flip last_ts = 376.588928 last_received_ts = 376.588318 last_seq = 53 current_ts = 376.605591 current_received_ts = 376.605042 current_seq = 54 count = 49 seq_step = 1 [375.089996] (kms_flip:7115) DEBUG: Vblank took 62us [375.106536] (kms_flip:7115) DEBUG: name = flip last_ts = 376.605591 last_received_ts = 376.605042 last_seq = 54 current_ts = 376.622253 current_received_ts = 376.621643 current_seq = 55 count = 50 seq_step = 1 [375.106608] (kms_flip:7115) DEBUG: Vblank took 64us [375.123204] (kms_flip:7115) DEBUG: name = flip last_ts = 376.622253 last_received_ts = 376.621643 last_seq = 55 current_ts = 376.638916 current_received_ts = 376.638336 current_seq = 56 count = 51 seq_step = 1 [375.123321] (kms_flip:7115) DEBUG: Vblank took 107us [375.139904] (kms_flip:7115) DEBUG: name = flip last_ts = 376.638916 last_received_ts = 376.638336 last_seq = 56 current_ts = 376.655579 current_received_ts = 376.654999 current_seq = 57 count = 52 seq_step = 1 [375.139974] (kms_flip:7115) DEBUG: Vblank took 62us [375.156563] (kms_flip:7115) DEBUG: name = flip last_ts = 376.655579 last_received_ts = 376.654999 last_seq = 57 current_ts = 376.672241 current_received_ts = 376.671692 current_seq = 58 count = 53 seq_step = 1 [375.156615] (kms_flip:7115) DEBUG: Vblank took 44us [375.173202] (kms_flip:7115) DEBUG: name = flip last_ts = 376.672241 last_received_ts = 376.671692 last_seq = 58 current_ts = 376.688904 current_received_ts = 376.688324 current_seq = 59 count = 54 seq_step = 1 [375.173310] (kms_flip:7115) DEBUG: Vblank took 101us [375.189909] (kms_flip:7115) DEBUG: name = flip last_ts = 376.688904 last_received_ts = 376.688324 last_seq = 59 current_ts = 376.705566 current_received_ts = 376.705017 current_seq = 60 count = 55 seq_step = 1 [375.189980] (kms_flip:7115) DEBUG: Vblank took 63us [375.206523] (kms_flip:7115) DEBUG: name = flip last_ts = 376.705566 last_received_ts = 376.705017 last_seq = 60 current_ts = 376.722229 current_received_ts = 376.721649 current_seq = 61 count = 56 seq_step = 1 [375.206590] (kms_flip:7115) DEBUG: Vblank took 60us [375.223199] (kms_flip:7115) DEBUG: name = flip last_ts = 376.722229 last_received_ts = 376.721649 last_seq = 61 current_ts = 376.738892 current_received_ts = 376.738312 current_seq = 62 count = 57 seq_step = 1 [375.223332] (kms_flip:7115) DEBUG: Vblank took 126us [375.239897] (kms_flip:7115) DEBUG: name = flip last_ts = 376.738892 last_received_ts = 376.738312 last_seq = 62 current_ts = 376.755554 current_received_ts = 376.755005 current_seq = 63 count = 58 seq_step = 1 [375.239966] (kms_flip:7115) DEBUG: Vblank took 61us [375.256490] (kms_flip:7115) DEBUG: name = flip last_ts = 376.755554 last_received_ts = 376.755005 last_seq = 63 current_ts = 376.772217 current_received_ts = 376.771606 current_seq = 64 count = 59 seq_step = 1 [375.256543] (kms_flip:7115) DEBUG: Vblank took 45us [375.273197] (kms_flip:7115) DEBUG: name = flip last_ts = 376.772217 last_received_ts = 376.771606 last_seq = 64 current_ts = 376.788879 current_received_ts = 376.788330 current_seq = 65 count = 60 seq_step = 1 [375.273311] (kms_flip:7115) DEBUG: Vblank took 106us [375.289925] (kms_flip:7115) DEBUG: name = flip last_ts = 376.788879 last_received_ts = 376.788330 last_seq = 65 current_ts = 376.805573 current_received_ts = 376.805054 current_seq = 66 count = 61 seq_step = 1 [375.290070] (kms_flip:7115) DEBUG: Vblank took 136us [375.306519] (kms_flip:7115) DEBUG: name = flip last_ts = 376.805573 last_received_ts = 376.805054 last_seq = 66 current_ts = 376.822235 current_received_ts = 376.821655 current_seq = 67 count = 62 seq_step = 1 [375.306586] (kms_flip:7115) DEBUG: Vblank took 60us [375.323195] (kms_flip:7115) DEBUG: name = flip last_ts = 376.822235 last_received_ts = 376.821655 last_seq = 67 current_ts = 376.838898 current_received_ts = 376.838318 current_seq = 68 count = 63 seq_step = 1 [375.323330] (kms_flip:7115) DEBUG: Vblank took 127us [375.339834] (kms_flip:7115) DEBUG: name = flip last_ts = 376.838898 last_received_ts = 376.838318 last_seq = 68 current_ts = 376.855560 current_received_ts = 376.854950 current_seq = 69 count = 64 seq_step = 1 [375.339924] (kms_flip:7115) DEBUG: Vblank took 82us [375.356521] (kms_flip:7115) DEBUG: name = flip last_ts = 376.855560 last_received_ts = 376.854950 last_seq = 69 current_ts = 376.872223 current_received_ts = 376.871643 current_seq = 70 count = 65 seq_step = 1 [375.356588] (kms_flip:7115) DEBUG: Vblank took 60us [375.373172] (kms_flip:7115) DEBUG: name = flip last_ts = 376.872223 last_received_ts = 376.871643 last_seq = 70 current_ts = 376.888885 current_received_ts = 376.888306 current_seq = 71 count = 66 seq_step = 1 [375.373289] (kms_flip:7115) DEBUG: Vblank took 111us [375.389846] (kms_flip:7115) DEBUG: name = flip last_ts = 376.888885 last_received_ts = 376.888306 last_seq = 71 current_ts = 376.905548 current_received_ts = 376.904968 current_seq = 72 count = 67 seq_step = 1 [375.389939] (kms_flip:7115) DEBUG: Vblank took 85us [375.406497] (kms_flip:7115) DEBUG: name = flip last_ts = 376.905548 last_received_ts = 376.904968 last_seq = 72 current_ts = 376.922211 current_received_ts = 376.921631 current_seq = 73 count = 68 seq_step = 1 [375.406565] (kms_flip:7115) DEBUG: Vblank took 61us [375.423161] (kms_flip:7115) DEBUG: name = flip last_ts = 376.922211 last_received_ts = 376.921631 last_seq = 73 current_ts = 376.938873 current_received_ts = 376.938293 current_seq = 74 count = 69 seq_step = 1 [375.423283] (kms_flip:7115) DEBUG: Vblank took 115us [375.439838] (kms_flip:7115) DEBUG: name = flip last_ts = 376.938873 last_received_ts = 376.938293 last_seq = 74 current_ts = 376.955536 current_received_ts = 376.954956 current_seq = 75 count = 70 seq_step = 1 [375.439940] (kms_flip:7115) DEBUG: Vblank took 96us [375.456500] (kms_flip:7115) DEBUG: name = flip last_ts = 376.955536 last_received_ts = 376.954956 last_seq = 75 current_ts = 376.972198 current_received_ts = 376.971619 current_seq = 76 count = 71 seq_step = 1 [375.456567] (kms_flip:7115) DEBUG: Vblank took 60us [375.473161] (kms_flip:7115) DEBUG: name = flip last_ts = 376.972198 last_received_ts = 376.971619 last_seq = 76 current_ts = 376.988861 current_received_ts = 376.988281 current_seq = 77 count = 72 seq_step = 1 [375.473294] (kms_flip:7115) DEBUG: Vblank took 126us [375.489847] (kms_flip:7115) DEBUG: name = flip last_ts = 376.988861 last_received_ts = 376.988281 last_seq = 77 current_ts = 377.005524 current_received_ts = 377.004974 current_seq = 78 count = 73 seq_step = 1 [375.490080] (kms_flip:7115) DEBUG: Vblank took 220us [375.506496] (kms_flip:7115) DEBUG: name = flip last_ts = 377.005524 last_received_ts = 377.004974 last_seq = 78 current_ts = 377.022186 current_received_ts = 377.021606 current_seq = 79 count = 74 seq_step = 1 [375.506550] (kms_flip:7115) DEBUG: Vblank took 45us [375.523141] (kms_flip:7115) DEBUG: name = flip last_ts = 377.022186 last_received_ts = 377.021606 last_seq = 79 current_ts = 377.038849 current_received_ts = 377.038269 current_seq = 80 count = 75 seq_step = 1 [375.523213] (kms_flip:7115) DEBUG: Vblank took 64us [375.539819] (kms_flip:7115) DEBUG: name = flip last_ts = 377.038849 last_received_ts = 377.038269 last_seq = 80 current_ts = 377.055511 current_received_ts = 377.054932 current_seq = 81 count = 76 seq_step = 1 [375.539907] (kms_flip:7115) DEBUG: Vblank took 79us [375.556500] (kms_flip:7115) DEBUG: name = flip last_ts = 377.055511 last_received_ts = 377.054932 last_seq = 81 current_ts = 377.072174 current_received_ts = 377.071625 current_seq = 82 count = 77 seq_step = 1 [375.556571] (kms_flip:7115) DEBUG: Vblank took 63us [375.573126] (kms_flip:7115) DEBUG: name = flip last_ts = 377.072174 last_received_ts = 377.071625 last_seq = 82 current_ts = 377.088867 current_received_ts = 377.088257 current_seq = 83 count = 78 seq_step = 1 [375.573225] (kms_flip:7115) DEBUG: Vblank took 91us [375.589828] (kms_flip:7115) DEBUG: name = flip last_ts = 377.088867 last_received_ts = 377.088257 last_seq = 83 current_ts = 377.105530 current_received_ts = 377.104950 current_seq = 84 count = 79 seq_step = 1 [375.589930] (kms_flip:7115) DEBUG: Vblank took 92us [375.606466] (kms_flip:7115) DEBUG: name = flip last_ts = 377.105530 last_received_ts = 377.104950 last_seq = 84 current_ts = 377.122162 current_received_ts = 377.121582 current_seq = 85 count = 80 seq_step = 1 [375.606538] (kms_flip:7115) DEBUG: Vblank took 65us [375.623129] (kms_flip:7115) DEBUG: name = flip last_ts = 377.122162 last_received_ts = 377.121582 last_seq = 85 current_ts = 377.138855 current_received_ts = 377.138245 current_seq = 86 count = 81 seq_step = 1 [375.623216] (kms_flip:7115) DEBUG: Vblank took 79us [375.639793] (kms_flip:7115) DEBUG: name = flip last_ts = 377.138855 last_received_ts = 377.138245 last_seq = 86 current_ts = 377.155518 current_received_ts = 377.154907 current_seq = 87 count = 82 seq_step = 1 [375.639860] (kms_flip:7115) DEBUG: Vblank took 60us [375.656407] (kms_flip:7115) DEBUG: name = flip last_ts = 377.155518 last_received_ts = 377.154907 last_seq = 87 current_ts = 377.172180 current_received_ts = 377.171509 current_seq = 88 count = 83 seq_step = 1 [375.656504] (kms_flip:7115) DEBUG: Vblank took 85us [375.673078] (kms_flip:7115) DEBUG: name = flip last_ts = 377.172180 last_received_ts = 377.171509 last_seq = 88 current_ts = 377.188843 current_received_ts = 377.188202 current_seq = 89 count = 84 seq_step = 1 [375.674187] (kms_flip:7115) DEBUG: Vblank took 1087us [375.674201] (kms_flip:7115) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [375.674298] (kms_flip:7115) CRITICAL: Failed assertion: end - start < 500 [375.676614] (kms_flip:7115) igt_core-INFO: Stack trace: [375.679364] (kms_flip:7115) igt_core-INFO: #0 ../lib/igt_core.c:2106 __igt_fail_assert() [375.680762] (kms_flip:7115) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [375.680808] (kms_flip:7115) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [375.680843] (kms_flip:7115) igt_core-INFO: #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() [375.680888] (kms_flip:7115) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [375.683617] (kms_flip:7115) igt_core-INFO: #5 [__libc_init_first+0x8a] [375.685225] (kms_flip:7115) igt_core-INFO: #6 [__libc_start_main+0x8b] [375.685609] (kms_flip:7115) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (2.655s)
Dmesg	<6> [374.752473] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [374.753246] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:433] <7> [374.756702] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:434] <7> [374.838704] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [374.838958] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [374.839381] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [374.839670] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [374.839949] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [374.840217] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0) <7> [374.840532] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [374.840814] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [374.841083] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [374.841370] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [374.841657] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [374.841990] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [374.842298] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [374.842599] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [374.842901] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [374.843208] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [374.843560] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [374.843881] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [374.844197] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [374.844637] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [374.844984] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [374.845349] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [374.845748] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [374.846093] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [374.846472] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [374.846818] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [374.847128] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [374.847452] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [374.847721] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [374.847984] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [374.848318] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [374.848592] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [374.848901] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [374.849141] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [374.849414] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [374.849696] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [374.849944] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [374.850165] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [374.850394] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [374.850629] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [374.850832] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [374.851111] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [374.851319] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [374.851513] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 4051) -> ( 0 - 0), size 4051 -> 0 <7> [374.851682] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [374.851831] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] level wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm <7> [374.851957] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [374.852081] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [374.852209] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [374.852401] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0 <7> [374.852588] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 0 qgv_peak_bw: 38400 <7> [374.852767] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 0 qgv_peak_bw: 38400 <7> [374.852941] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [374.853130] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [374.853302] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 0 <7> [374.853458] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [374.853634] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 21732 kHz -> 0 kHz <7> [374.853799] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [374.853955] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [374.854095] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [374.854277] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [374.854452] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [374.854590] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [374.854718] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [374.854841] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [374.854961] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [374.855080] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [374.855269] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [374.856078] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [374.856245] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2 <7> [374.857334] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [374.857489] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [375.062440] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [375.062879] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [375.073653] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [375.073999] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power off time <7> [375.074367] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [375.126494] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [375.126833] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [375.134470] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [375.134835] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [375.134874] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [375.136294] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [375.136804] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [375.137335] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [375.137677] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [375.137995] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [375.138387] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [375.138744] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [375.139076] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [375.139481] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [375.139796] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [375.140110] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [375.140483] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [375.140785] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [375.141082] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [375.141408] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [375.141706] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [375.142092] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [375.142437] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [375.142781] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [375.143315] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [375.143767] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [375.144290] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [375.144651] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Post changing CDCLK to 153600 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [375.145078] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [375.145478] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [375.146490] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [375.146853] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [375.147145] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [375.147208] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [375.147400] xe 0000:00:02.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:393:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [375.147806] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:270:pipe B] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [375.148134] xe 0000:00:02.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 HDR no link rate required 1303913 available 1728000 <7> [375.148516] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [375.148869] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:270:pipe B] <7> [375.149182] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [375.149518] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [375.149806] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [375.150101] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [375.150392] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [375.150648] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [375.150910] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [375.151148] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [375.151392] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [375.151600] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [375.151838] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [375.152037] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [375.152234] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [375.152474] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [375.152656] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [375.152825] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [375.153009] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [375.153168] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [375.153344] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [375.153501] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [375.153671] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [375.153834] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [375.153977] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [375.154116] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [375.154272] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [375.154437] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [375.154567] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [375.154696] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [375.154824] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [375.154948] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [375.155067] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [375.155183] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [375.155306] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [375.155438] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [375.155565] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in dpll_hw_state <7> [375.155685] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] expected: <7> [375.155791] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 0, ssc_enabled: no, use_c10: no, tbt_mode: no <7> [375.155894] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] c20pll_hw_state: <7> [375.155994] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] tx[0] = 0x0000, tx[1] = 0x0000, tx[2] = 0x0000 <7> [375.156093] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] cmn[0] = 0x0000, cmn[1] = 0x0000, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [375.156191] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[0] = 0x0000 <7> [375.156293] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[1] = 0x0000 <7> [375.156392] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[2] = 0x0000 <7> [375.156487] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[3] = 0x0000 <7> [375.156579] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[4] = 0x0000 <7> [375.156667] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[5] = 0x0000 <7> [375.156757] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[6] = 0x0000 <7> [375.156846] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[7] = 0x0000 <7> [375.156932] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[8] = 0x0000 <7> [375.157017] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[9] = 0x0000 <7> [375.157100] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mpllb[10] = 0x0000 <7> [375.157180] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] vdr: custom width: 0x00, serdes rate: 0x00, hdmi rate: 0x00 <7> [375.157261] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] found: <7> [375.157394] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no <7> [375.157500] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] c10pll_hw_state: fracen: no, <7> [375.157598] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] multiplier: 225, tx_clk_div: 1. <7> [375.157683] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] c10pll_rawhw_state: <7> [375.157764] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] tx: 0x10, cmn: 0x21 <7> [375.157842] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [375.157918] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [375.157994] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [375.158069] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [375.158144] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [375.158217] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [375.158298] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [375.158396] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [375.158492] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in port_clock (expected 0, found 432000) <7> [375.158588] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] fastset requirement not met, forcing full modeset <7> [375.158708] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [375.158778] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:270:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [375.158871] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:154:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [375.158939] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:264:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [375.158997] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [375.159052] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [375.159107] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [375.159162] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [375.159234] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:270:pipe B] data rate 1390840 num active planes 1 <7> [375.159345] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [375.159462] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [375.159576] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [375.159685] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [375.159770] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [375.159861] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:270:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [375.159965] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 0 kHz -> 21732 kHz <7> [375.160065] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [375.160159] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [375.160248] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [375.160371] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:270:pipe B] allocated DPLL 0 <7> [375.160489] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:270:pipe B] reserving DPLL 0 <7> [375.160609] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:270:pipe B] enable: yes [modeset] <7> [375.160709] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [375.160795] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [375.160879] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [375.160961] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [375.161045] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [375.161126] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [375.161206] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 6329869, data_n: 8388608, link_m: 421991, link_n: 524288, tu: 64 <7> [375.161290] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [375.161394] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [375.161493] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [375.161594] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [375.161683] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [375.161762] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [375.161840] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [375.161919] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [375.161997] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [375.162075] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [375.162157] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [375.162237] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [375.162337] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [375.162439] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [375.162538] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 104 vsync start: 103, vsync end: 97 <7> [375.162637] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1906, vmax vtotal: 1906 <7> [375.162717] xe 0000:00:02.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> [375.162794] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [375.162873] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [375.162953] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [375.163035] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa <7> [375.163115] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [375.163193] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0 <7> [375.163284] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [375.163387] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [375.163487] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0 <7> [375.163585] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [375.163671] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [375.163746] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [375.163821] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no <7> [375.163902] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [375.163980] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [375.164056] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [375.164131] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [375.164206] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [375.164290] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [375.164304] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [375.164390] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [375.164492] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [375.164493] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [375.164589] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [375.164639] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [375.164678] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [375.164759] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [375.164777] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling always-on <7> [375.164843] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [375.164932] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [375.165019] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [375.165110] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [375.165192] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [375.165284] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [375.165398] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [375.165509] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [375.165601] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [375.165677] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [375.165751] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:154:plane 1B] fb: [FB:433] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [375.165832] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [375.165925] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [375.166024] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:184:plane 2B] fb: [NOFB], visible: no <7> [375.166114] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:214:plane 3B] fb: [NOFB], visible: no <7> [375.166195] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:244:plane 4B] fb: [NOFB], visible: no <7> [375.166270] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:254:plane 5B] fb: [NOFB], visible: no <7> [375.166386] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:264:cursor B] fb: [NOFB], visible: no <7> [375.166703] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling always-on <7> [375.166811] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [375.167061] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [375.167085] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [375.167203] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [375.167223] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [375.167316] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [375.167392] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [375.167442] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [375.167562] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000) <7> [375.167686] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 192000 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [375.167798] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [375.167888] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [375.167974] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [375.168047] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [375.168118] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [375.168188] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [375.168258] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [375.168357] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [375.168450] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [375.168537] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [375.168625] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [375.168703] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [375.168773] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [375.168841] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [375.168905] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [375.168989] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [375.169150] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: ) <7> [375.169212] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [375.169326] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [375.170349] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:270:pipe B] <7> [375.170473] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [375.172497] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [375.172600] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (463 ms remaining) <7> [375.638504] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [375.699693] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [375.700014] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power on <7> [375.700335] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [375.736788] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [375.737125] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [375.737408] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [375.737815] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [375.912664] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [375.913014] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [375.913348] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [375.915308] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e 44 c1 00 00 01 c0 02 00 02 00 00 0b 80 <7> [375.916779] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [375.917483] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [375.918565] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [375.919896] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [375.921047] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Clock recovery OK <7> [375.921474] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [375.922980] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [375.923351] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [375.924199] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [375.924728] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [375.925109] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [375.925577] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 4518 <7> [375.958471] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [375.960037] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [375.960348] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:270:pipe B] <6> [377.408503] [IGT] kms_flip: finished subtest B-eDP1, FAIL <7> [377.409377] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [377.409647] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6

Detail

Value

Duration

2.65 seconds

Hostname

shard-lnl-7

Igt-Version

IGT-Version: 2.4-g3c74f6044 (x86_64) (Linux: 7.1.0-rc5-lgci-xe-xe-5127-6b6931ea69504481e-debug+ x86_64)

Out

Starting dynamic subtest: B-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Stack trace:
  #0 ../lib/igt_core.c:2106 __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 B-eDP1: FAIL (2.655s)

Err

Starting dynamic subtest: B-eDP1
[375.674201] (kms_flip:7115) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[375.674298] (kms_flip:7115) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
[373.034310] (kms_flip:7115) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x100000000000009, size=0)
[373.034320] (kms_flip:7115) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
[373.034334] (kms_flip:7115) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
[373.034840] (kms_flip:7115) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=11520)
[373.034842] (kms_flip:7115) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
[373.034879] (kms_flip:7115) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x100000000000009, size=0)
[373.034886] (kms_flip:7115) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
[373.034899] (kms_flip:7115) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
[373.038302] (kms_flip:7115) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=4, pitch=11520)
[373.038305] (kms_flip:7115) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
[373.044230] (kms_flip:7115) intel_allocator_simple-DEBUG: Using simple allocator
[373.048520] (kms_flip:7115) intel_allocator_simple-DEBUG: <ial: 0x61df3a655040, fd: 5> objects: 3, reserved_areas: 0
[373.048522] (kms_flip:7115) intel_allocator_simple-DEBUG: <ial: 0x61df3a655040, fd: 5> objects: 3, reserved_areas: 0
[373.065924] (kms_flip:7115) intel_allocator_simple-DEBUG: Using simple allocator
[373.069808] (kms_flip:7115) intel_allocator_simple-DEBUG: <ial: 0x61df3a655040, fd: 5> objects: 3, reserved_areas: 0
[373.069809] (kms_flip:7115) intel_allocator_simple-DEBUG: <ial: 0x61df3a655040, fd: 5> objects: 3, reserved_areas: 0
[373.074683] (kms_flip:7115) intel_allocator_simple-DEBUG: Using simple allocator
[373.079052] (kms_flip:7115) intel_allocator_simple-DEBUG: <ial: 0x61df3a6dd610, fd: 5> objects: 3, reserved_areas: 0
[373.079057] (kms_flip:7115) intel_allocator_simple-DEBUG: <ial: 0x61df3a6dd610, fd: 5> objects: 3, reserved_areas: 0
[373.094648] (kms_flip:7115) intel_allocator_simple-DEBUG: Using simple allocator
[373.098542] (kms_flip:7115) intel_allocator_simple-DEBUG: <ial: 0x61df3a655040, fd: 5> objects: 3, reserved_areas: 0
[373.098544] (kms_flip:7115) intel_allocator_simple-DEBUG: <ial: 0x61df3a655040, fd: 5> objects: 3, reserved_areas: 0
[373.100192] (kms_flip:7115) igt_kms-INFO:   2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
[373.120316] (kms_flip:7115) DEBUG: No stale events found
[374.245101] (kms_flip:7115) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
[374.245296] (kms_flip:7115) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
[374.273270] (kms_flip:7115) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 375.789032
current_received_ts = 375.788361
current_seq = 5
count = 0
seq_step = 1
[374.273359] (kms_flip:7115) DEBUG: Vblank took 78us
[374.290041] (kms_flip:7115) DEBUG: name = flip
last_ts = 375.789032
last_received_ts = 375.788361
last_seq = 5
current_ts = 375.805695
current_received_ts = 375.805145
current_seq = 6
count = 1
seq_step = 1
[374.290117] (kms_flip:7115) DEBUG: Vblank took 68us
[374.306669] (kms_flip:7115) DEBUG: name = flip
last_ts = 375.805695
last_received_ts = 375.805145
last_seq = 6
current_ts = 375.822357
current_received_ts = 375.821777
current_seq = 7
count = 2
seq_step = 1
[374.306741] (kms_flip:7115) DEBUG: Vblank took 64us
[374.323331] (kms_flip:7115) DEBUG: name = flip
last_ts = 375.822357
last_received_ts = 375.821777
last_seq = 7
current_ts = 375.839020
current_received_ts = 375.838440
current_seq = 8
count = 3
seq_step = 1
[374.323469] (kms_flip:7115) DEBUG: Vblank took 131us
[374.340011] (kms_flip:7115) DEBUG: name = flip
last_ts = 375.839020
last_received_ts = 375.838440
last_seq = 8
current_ts = 375.855682
current_received_ts = 375.855103
current_seq = 9
count = 4
seq_step = 1
[374.340078] (kms_flip:7115) DEBUG: Vblank took 61us
[374.356697] (kms_flip:7115) DEBUG: name = flip
last_ts = 375.855682
last_received_ts = 375.855103
last_seq = 9
current_ts = 375.872345
current_received_ts = 375.871796
current_seq = 10
count = 5
seq_step = 1
[374.356767] (kms_flip:7115) DEBUG: Vblank took 63us
[374.373324] (kms_flip:7115) DEBUG: name = flip
last_ts = 375.872345
last_received_ts = 375.871796
last_seq = 10
current_ts = 375.889008
current_received_ts = 375.888428
current_seq = 11
count = 6
seq_step = 1
[374.373464] (kms_flip:7115) DEBUG: Vblank took 131us
[374.389997] (kms_flip:7115) DEBUG: name = flip
last_ts = 375.889008
last_received_ts = 375.888428
last_seq = 11
current_ts = 375.905670
current_received_ts = 375.905090
current_seq = 12
count = 7
seq_step = 1
[374.390068] (kms_flip:7115) DEBUG: Vblank took 62us
[374.406665] (kms_flip:7115) DEBUG: name = flip
last_ts = 375.905670
last_received_ts = 375.905090
last_seq = 12
current_ts = 375.922363
current_received_ts = 375.921783
current_seq = 13
count = 8
seq_step = 1
[374.406737] (kms_flip:7115) DEBUG: Vblank took 63us
[374.423334] (kms_flip:7115) DEBUG: name = flip
last_ts = 375.922363
last_received_ts = 375.921783
last_seq = 13
current_ts = 375.939026
current_received_ts = 375.938446
current_seq = 14
count = 9
seq_step = 1
[374.423466] (kms_flip:7115) DEBUG: Vblank took 124us
[374.440002] (kms_flip:7115) DEBUG: name = flip
last_ts = 375.939026
last_received_ts = 375.938446
last_seq = 14
current_ts = 375.955688
current_received_ts = 375.955109
current_seq = 15
count = 10
seq_step = 1
[374.440070] (kms_flip:7115) DEBUG: Vblank took 60us
[374.456655] (kms_flip:7115) DEBUG: name = flip
last_ts = 375.955688
last_received_ts = 375.955109
last_seq = 15
current_ts = 375.972351
current_received_ts = 375.971771
current_seq = 16
count = 11
seq_step = 1
[374.456722] (kms_flip:7115) DEBUG: Vblank took 60us
[374.473328] (kms_flip:7115) DEBUG: name = flip
last_ts = 375.972351
last_received_ts = 375.971771
last_seq = 16
current_ts = 375.989014
current_received_ts = 375.988434
current_seq = 17
count = 12
seq_step = 1
[374.473447] (kms_flip:7115) DEBUG: Vblank took 112us
[374.490005] (kms_flip:7115) DEBUG: name = flip
last_ts = 375.989014
last_received_ts = 375.988434
last_seq = 17
current_ts = 376.005676
current_received_ts = 376.005127
current_seq = 18
count = 13
seq_step = 1
[374.490072] (kms_flip:7115) DEBUG: Vblank took 59us
[374.506648] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.005676
last_received_ts = 376.005127
last_seq = 18
current_ts = 376.022339
current_received_ts = 376.021759
current_seq = 19
count = 14
seq_step = 1
[374.506719] (kms_flip:7115) DEBUG: Vblank took 63us
[374.523317] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.022339
last_received_ts = 376.021759
last_seq = 19
current_ts = 376.039001
current_received_ts = 376.038422
current_seq = 20
count = 15
seq_step = 1
[374.523428] (kms_flip:7115) DEBUG: Vblank took 104us
[374.539976] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.039001
last_received_ts = 376.038422
last_seq = 20
current_ts = 376.055664
current_received_ts = 376.055084
current_seq = 21
count = 16
seq_step = 1
[374.540046] (kms_flip:7115) DEBUG: Vblank took 63us
[374.556653] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.055664
last_received_ts = 376.055084
last_seq = 21
current_ts = 376.072327
current_received_ts = 376.071747
current_seq = 22
count = 17
seq_step = 1
[374.556723] (kms_flip:7115) DEBUG: Vblank took 64us
[374.573311] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.072327
last_received_ts = 376.071747
last_seq = 22
current_ts = 376.088989
current_received_ts = 376.088409
current_seq = 23
count = 18
seq_step = 1
[374.573438] (kms_flip:7115) DEBUG: Vblank took 120us
[374.589982] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.088989
last_received_ts = 376.088409
last_seq = 23
current_ts = 376.105652
current_received_ts = 376.105103
current_seq = 24
count = 19
seq_step = 1
[374.590053] (kms_flip:7115) DEBUG: Vblank took 64us
[374.606628] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.105652
last_received_ts = 376.105103
last_seq = 24
current_ts = 376.122314
current_received_ts = 376.121735
current_seq = 25
count = 20
seq_step = 1
[374.606698] (kms_flip:7115) DEBUG: Vblank took 63us
[374.623272] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.122314
last_received_ts = 376.121735
last_seq = 25
current_ts = 376.138977
current_received_ts = 376.138397
current_seq = 26
count = 21
seq_step = 1
[374.623400] (kms_flip:7115) DEBUG: Vblank took 120us
[374.639958] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.138977
last_received_ts = 376.138397
last_seq = 26
current_ts = 376.155640
current_received_ts = 376.155060
current_seq = 27
count = 22
seq_step = 1
[374.640028] (kms_flip:7115) DEBUG: Vblank took 63us
[374.656611] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.155640
last_received_ts = 376.155060
last_seq = 27
current_ts = 376.172302
current_received_ts = 376.171722
current_seq = 28
count = 23
seq_step = 1
[374.656679] (kms_flip:7115) DEBUG: Vblank took 60us
[374.673266] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.172302
last_received_ts = 376.171722
last_seq = 28
current_ts = 376.188965
current_received_ts = 376.188385
current_seq = 29
count = 24
seq_step = 1
[374.673381] (kms_flip:7115) DEBUG: Vblank took 108us
[374.689951] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.188965
last_received_ts = 376.188385
last_seq = 29
current_ts = 376.205627
current_received_ts = 376.205078
current_seq = 30
count = 25
seq_step = 1
[374.690019] (kms_flip:7115) DEBUG: Vblank took 61us
[374.706593] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.205627
last_received_ts = 376.205078
last_seq = 30
current_ts = 376.222321
current_received_ts = 376.221710
current_seq = 31
count = 26
seq_step = 1
[374.706660] (kms_flip:7115) DEBUG: Vblank took 60us
[374.723261] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.222321
last_received_ts = 376.221710
last_seq = 31
current_ts = 376.238983
current_received_ts = 376.238373
current_seq = 32
count = 27
seq_step = 1
[374.723390] (kms_flip:7115) DEBUG: Vblank took 121us
[374.739956] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.238983
last_received_ts = 376.238373
last_seq = 32
current_ts = 376.255646
current_received_ts = 376.255066
current_seq = 33
count = 28
seq_step = 1
[374.740028] (kms_flip:7115) DEBUG: Vblank took 65us
[374.756602] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.255646
last_received_ts = 376.255066
last_seq = 33
current_ts = 376.272308
current_received_ts = 376.271729
current_seq = 34
count = 29
seq_step = 1
[374.756672] (kms_flip:7115) DEBUG: Vblank took 63us
[374.773256] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.272308
last_received_ts = 376.271729
last_seq = 34
current_ts = 376.288971
current_received_ts = 376.288361
current_seq = 35
count = 30
seq_step = 1
[374.773359] (kms_flip:7115) DEBUG: Vblank took 97us
[374.789968] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.288971
last_received_ts = 376.288361
last_seq = 35
current_ts = 376.305634
current_received_ts = 376.305084
current_seq = 36
count = 31
seq_step = 1
[374.790039] (kms_flip:7115) DEBUG: Vblank took 63us
[374.806589] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.305634
last_received_ts = 376.305084
last_seq = 36
current_ts = 376.322296
current_received_ts = 376.321716
current_seq = 37
count = 32
seq_step = 1
[374.806656] (kms_flip:7115) DEBUG: Vblank took 61us
[374.823252] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.322296
last_received_ts = 376.321716
last_seq = 37
current_ts = 376.338959
current_received_ts = 376.338379
current_seq = 38
count = 33
seq_step = 1
[374.823378] (kms_flip:7115) DEBUG: Vblank took 119us
[374.839937] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.338959
last_received_ts = 376.338379
last_seq = 38
current_ts = 376.355621
current_received_ts = 376.355042
current_seq = 39
count = 34
seq_step = 1
[374.840012] (kms_flip:7115) DEBUG: Vblank took 66us
[374.856584] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.355621
last_received_ts = 376.355042
last_seq = 39
current_ts = 376.372284
current_received_ts = 376.371704
current_seq = 40
count = 35
seq_step = 1
[374.856656] (kms_flip:7115) DEBUG: Vblank took 66us
[374.873236] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.372284
last_received_ts = 376.371704
last_seq = 40
current_ts = 376.388947
current_received_ts = 376.388336
current_seq = 41
count = 36
seq_step = 1
[374.873384] (kms_flip:7115) DEBUG: Vblank took 139us
[374.889935] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.388947
last_received_ts = 376.388336
last_seq = 41
current_ts = 376.405609
current_received_ts = 376.405060
current_seq = 42
count = 37
seq_step = 1
[374.890001] (kms_flip:7115) DEBUG: Vblank took 59us
[374.906586] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.405609
last_received_ts = 376.405060
last_seq = 42
current_ts = 376.422272
current_received_ts = 376.421692
current_seq = 43
count = 38
seq_step = 1
[374.906655] (kms_flip:7115) DEBUG: Vblank took 61us
[374.923240] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.422272
last_received_ts = 376.421692
last_seq = 43
current_ts = 376.438934
current_received_ts = 376.438354
current_seq = 44
count = 39
seq_step = 1
[374.923375] (kms_flip:7115) DEBUG: Vblank took 128us
[374.939921] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.438934
last_received_ts = 376.438354
last_seq = 44
current_ts = 376.455597
current_received_ts = 376.455048
current_seq = 45
count = 40
seq_step = 1
[374.939987] (kms_flip:7115) DEBUG: Vblank took 59us
[374.956570] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.455597
last_received_ts = 376.455048
last_seq = 45
current_ts = 376.472260
current_received_ts = 376.471680
current_seq = 46
count = 41
seq_step = 1
[374.956642] (kms_flip:7115) DEBUG: Vblank took 63us
[374.973237] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.472260
last_received_ts = 376.471680
last_seq = 46
current_ts = 376.488922
current_received_ts = 376.488342
current_seq = 47
count = 42
seq_step = 1
[374.973365] (kms_flip:7115) DEBUG: Vblank took 120us
[374.989936] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.488922
last_received_ts = 376.488342
last_seq = 47
current_ts = 376.505585
current_received_ts = 376.505066
current_seq = 48
count = 43
seq_step = 1
[374.990006] (kms_flip:7115) DEBUG: Vblank took 61us
[375.006580] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.505585
last_received_ts = 376.505066
last_seq = 48
current_ts = 376.522247
current_received_ts = 376.521698
current_seq = 49
count = 44
seq_step = 1
[375.006652] (kms_flip:7115) DEBUG: Vblank took 64us
[375.023231] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.522247
last_received_ts = 376.521698
last_seq = 49
current_ts = 376.538940
current_received_ts = 376.538361
current_seq = 50
count = 45
seq_step = 1
[375.023348] (kms_flip:7115) DEBUG: Vblank took 110us
[375.039924] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.538940
last_received_ts = 376.538361
last_seq = 50
current_ts = 376.555603
current_received_ts = 376.555054
current_seq = 51
count = 46
seq_step = 1
[375.039995] (kms_flip:7115) DEBUG: Vblank took 63us
[375.056568] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.555603
last_received_ts = 376.555054
last_seq = 51
current_ts = 376.572266
current_received_ts = 376.571686
current_seq = 52
count = 47
seq_step = 1
[375.056641] (kms_flip:7115) DEBUG: Vblank took 65us
[375.073214] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.572266
last_received_ts = 376.571686
last_seq = 52
current_ts = 376.588928
current_received_ts = 376.588318
current_seq = 53
count = 48
seq_step = 1
[375.073335] (kms_flip:7115) DEBUG: Vblank took 113us
[375.089925] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.588928
last_received_ts = 376.588318
last_seq = 53
current_ts = 376.605591
current_received_ts = 376.605042
current_seq = 54
count = 49
seq_step = 1
[375.089996] (kms_flip:7115) DEBUG: Vblank took 62us
[375.106536] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.605591
last_received_ts = 376.605042
last_seq = 54
current_ts = 376.622253
current_received_ts = 376.621643
current_seq = 55
count = 50
seq_step = 1
[375.106608] (kms_flip:7115) DEBUG: Vblank took 64us
[375.123204] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.622253
last_received_ts = 376.621643
last_seq = 55
current_ts = 376.638916
current_received_ts = 376.638336
current_seq = 56
count = 51
seq_step = 1
[375.123321] (kms_flip:7115) DEBUG: Vblank took 107us
[375.139904] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.638916
last_received_ts = 376.638336
last_seq = 56
current_ts = 376.655579
current_received_ts = 376.654999
current_seq = 57
count = 52
seq_step = 1
[375.139974] (kms_flip:7115) DEBUG: Vblank took 62us
[375.156563] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.655579
last_received_ts = 376.654999
last_seq = 57
current_ts = 376.672241
current_received_ts = 376.671692
current_seq = 58
count = 53
seq_step = 1
[375.156615] (kms_flip:7115) DEBUG: Vblank took 44us
[375.173202] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.672241
last_received_ts = 376.671692
last_seq = 58
current_ts = 376.688904
current_received_ts = 376.688324
current_seq = 59
count = 54
seq_step = 1
[375.173310] (kms_flip:7115) DEBUG: Vblank took 101us
[375.189909] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.688904
last_received_ts = 376.688324
last_seq = 59
current_ts = 376.705566
current_received_ts = 376.705017
current_seq = 60
count = 55
seq_step = 1
[375.189980] (kms_flip:7115) DEBUG: Vblank took 63us
[375.206523] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.705566
last_received_ts = 376.705017
last_seq = 60
current_ts = 376.722229
current_received_ts = 376.721649
current_seq = 61
count = 56
seq_step = 1
[375.206590] (kms_flip:7115) DEBUG: Vblank took 60us
[375.223199] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.722229
last_received_ts = 376.721649
last_seq = 61
current_ts = 376.738892
current_received_ts = 376.738312
current_seq = 62
count = 57
seq_step = 1
[375.223332] (kms_flip:7115) DEBUG: Vblank took 126us
[375.239897] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.738892
last_received_ts = 376.738312
last_seq = 62
current_ts = 376.755554
current_received_ts = 376.755005
current_seq = 63
count = 58
seq_step = 1
[375.239966] (kms_flip:7115) DEBUG: Vblank took 61us
[375.256490] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.755554
last_received_ts = 376.755005
last_seq = 63
current_ts = 376.772217
current_received_ts = 376.771606
current_seq = 64
count = 59
seq_step = 1
[375.256543] (kms_flip:7115) DEBUG: Vblank took 45us
[375.273197] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.772217
last_received_ts = 376.771606
last_seq = 64
current_ts = 376.788879
current_received_ts = 376.788330
current_seq = 65
count = 60
seq_step = 1
[375.273311] (kms_flip:7115) DEBUG: Vblank took 106us
[375.289925] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.788879
last_received_ts = 376.788330
last_seq = 65
current_ts = 376.805573
current_received_ts = 376.805054
current_seq = 66
count = 61
seq_step = 1
[375.290070] (kms_flip:7115) DEBUG: Vblank took 136us
[375.306519] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.805573
last_received_ts = 376.805054
last_seq = 66
current_ts = 376.822235
current_received_ts = 376.821655
current_seq = 67
count = 62
seq_step = 1
[375.306586] (kms_flip:7115) DEBUG: Vblank took 60us
[375.323195] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.822235
last_received_ts = 376.821655
last_seq = 67
current_ts = 376.838898
current_received_ts = 376.838318
current_seq = 68
count = 63
seq_step = 1
[375.323330] (kms_flip:7115) DEBUG: Vblank took 127us
[375.339834] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.838898
last_received_ts = 376.838318
last_seq = 68
current_ts = 376.855560
current_received_ts = 376.854950
current_seq = 69
count = 64
seq_step = 1
[375.339924] (kms_flip:7115) DEBUG: Vblank took 82us
[375.356521] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.855560
last_received_ts = 376.854950
last_seq = 69
current_ts = 376.872223
current_received_ts = 376.871643
current_seq = 70
count = 65
seq_step = 1
[375.356588] (kms_flip:7115) DEBUG: Vblank took 60us
[375.373172] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.872223
last_received_ts = 376.871643
last_seq = 70
current_ts = 376.888885
current_received_ts = 376.888306
current_seq = 71
count = 66
seq_step = 1
[375.373289] (kms_flip:7115) DEBUG: Vblank took 111us
[375.389846] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.888885
last_received_ts = 376.888306
last_seq = 71
current_ts = 376.905548
current_received_ts = 376.904968
current_seq = 72
count = 67
seq_step = 1
[375.389939] (kms_flip:7115) DEBUG: Vblank took 85us
[375.406497] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.905548
last_received_ts = 376.904968
last_seq = 72
current_ts = 376.922211
current_received_ts = 376.921631
current_seq = 73
count = 68
seq_step = 1
[375.406565] (kms_flip:7115) DEBUG: Vblank took 61us
[375.423161] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.922211
last_received_ts = 376.921631
last_seq = 73
current_ts = 376.938873
current_received_ts = 376.938293
current_seq = 74
count = 69
seq_step = 1
[375.423283] (kms_flip:7115) DEBUG: Vblank took 115us
[375.439838] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.938873
last_received_ts = 376.938293
last_seq = 74
current_ts = 376.955536
current_received_ts = 376.954956
current_seq = 75
count = 70
seq_step = 1
[375.439940] (kms_flip:7115) DEBUG: Vblank took 96us
[375.456500] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.955536
last_received_ts = 376.954956
last_seq = 75
current_ts = 376.972198
current_received_ts = 376.971619
current_seq = 76
count = 71
seq_step = 1
[375.456567] (kms_flip:7115) DEBUG: Vblank took 60us
[375.473161] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.972198
last_received_ts = 376.971619
last_seq = 76
current_ts = 376.988861
current_received_ts = 376.988281
current_seq = 77
count = 72
seq_step = 1
[375.473294] (kms_flip:7115) DEBUG: Vblank took 126us
[375.489847] (kms_flip:7115) DEBUG: name = flip
last_ts = 376.988861
last_received_ts = 376.988281
last_seq = 77
current_ts = 377.005524
current_received_ts = 377.004974
current_seq = 78
count = 73
seq_step = 1
[375.490080] (kms_flip:7115) DEBUG: Vblank took 220us
[375.506496] (kms_flip:7115) DEBUG: name = flip
last_ts = 377.005524
last_received_ts = 377.004974
last_seq = 78
current_ts = 377.022186
current_received_ts = 377.021606
current_seq = 79
count = 74
seq_step = 1
[375.506550] (kms_flip:7115) DEBUG: Vblank took 45us
[375.523141] (kms_flip:7115) DEBUG: name = flip
last_ts = 377.022186
last_received_ts = 377.021606
last_seq = 79
current_ts = 377.038849
current_received_ts = 377.038269
current_seq = 80
count = 75
seq_step = 1
[375.523213] (kms_flip:7115) DEBUG: Vblank took 64us
[375.539819] (kms_flip:7115) DEBUG: name = flip
last_ts = 377.038849
last_received_ts = 377.038269
last_seq = 80
current_ts = 377.055511
current_received_ts = 377.054932
current_seq = 81
count = 76
seq_step = 1
[375.539907] (kms_flip:7115) DEBUG: Vblank took 79us
[375.556500] (kms_flip:7115) DEBUG: name = flip
last_ts = 377.055511
last_received_ts = 377.054932
last_seq = 81
current_ts = 377.072174
current_received_ts = 377.071625
current_seq = 82
count = 77
seq_step = 1
[375.556571] (kms_flip:7115) DEBUG: Vblank took 63us
[375.573126] (kms_flip:7115) DEBUG: name = flip
last_ts = 377.072174
last_received_ts = 377.071625
last_seq = 82
current_ts = 377.088867
current_received_ts = 377.088257
current_seq = 83
count = 78
seq_step = 1
[375.573225] (kms_flip:7115) DEBUG: Vblank took 91us
[375.589828] (kms_flip:7115) DEBUG: name = flip
last_ts = 377.088867
last_received_ts = 377.088257
last_seq = 83
current_ts = 377.105530
current_received_ts = 377.104950
current_seq = 84
count = 79
seq_step = 1
[375.589930] (kms_flip:7115) DEBUG: Vblank took 92us
[375.606466] (kms_flip:7115) DEBUG: name = flip
last_ts = 377.105530
last_received_ts = 377.104950
last_seq = 84
current_ts = 377.122162
current_received_ts = 377.121582
current_seq = 85
count = 80
seq_step = 1
[375.606538] (kms_flip:7115) DEBUG: Vblank took 65us
[375.623129] (kms_flip:7115) DEBUG: name = flip
last_ts = 377.122162
last_received_ts = 377.121582
last_seq = 85
current_ts = 377.138855
current_received_ts = 377.138245
current_seq = 86
count = 81
seq_step = 1
[375.623216] (kms_flip:7115) DEBUG: Vblank took 79us
[375.639793] (kms_flip:7115) DEBUG: name = flip
last_ts = 377.138855
last_received_ts = 377.138245
last_seq = 86
current_ts = 377.155518
current_received_ts = 377.154907
current_seq = 87
count = 82
seq_step = 1
[375.639860] (kms_flip:7115) DEBUG: Vblank took 60us
[375.656407] (kms_flip:7115) DEBUG: name = flip
last_ts = 377.155518
last_received_ts = 377.154907
last_seq = 87
current_ts = 377.172180
current_received_ts = 377.171509
current_seq = 88
count = 83
seq_step = 1
[375.656504] (kms_flip:7115) DEBUG: Vblank took 85us
[375.673078] (kms_flip:7115) DEBUG: name = flip
last_ts = 377.172180
last_received_ts = 377.171509
last_seq = 88
current_ts = 377.188843
current_received_ts = 377.188202
current_seq = 89
count = 84
seq_step = 1
[375.674187] (kms_flip:7115) DEBUG: Vblank took 1087us
[375.674201] (kms_flip:7115) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[375.674298] (kms_flip:7115) CRITICAL: Failed assertion: end - start < 500
[375.676614] (kms_flip:7115) igt_core-INFO: Stack trace:
[375.679364] (kms_flip:7115) igt_core-INFO:   #0 ../lib/igt_core.c:2106 __igt_fail_assert()
[375.680762] (kms_flip:7115) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[375.680808] (kms_flip:7115) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[375.680843] (kms_flip:7115) igt_core-INFO:   #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
[375.680888] (kms_flip:7115) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[375.683617] (kms_flip:7115) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[375.685225] (kms_flip:7115) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[375.685609] (kms_flip:7115) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (2.655s)

Dmesg

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

<7> [374.753246] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:433]

<7> [374.756702] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:434]

<7> [374.838704] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [374.850832] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0

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

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

<7> [374.851513] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 4051) -> ( 0 - 0), size 4051 -> 0

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

<7> [374.851831] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] level *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm

<7> [374.851957] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [374.852081] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [374.852209] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [374.852401] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0

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

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

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

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

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

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

<7> [374.853634] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 21732 kHz -> 0 kHz

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

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

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

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

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

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

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

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

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

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

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

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

<7> [374.856245] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2

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

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

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

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

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

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

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

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

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

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

<7> [375.134835] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A]

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

<7> [375.136294] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [375.143767] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000)

<7> [375.144290] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A]

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

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

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

<7> [375.146490] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B]

<7> [375.146853] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C]

<7> [375.147145] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B]

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

<7> [375.147400] xe 0000:00:02.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:393:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36)

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

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

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

<7> [375.148869] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:270:pipe B]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [375.155565] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in dpll_hw_state

<7> [375.155685] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] expected:

<7> [375.155791] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 0, ssc_enabled: no, use_c10: no, tbt_mode: no

<7> [375.155894] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] c20pll_hw_state:

<7> [375.155994] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] tx[0] = 0x0000, tx[1] = 0x0000, tx[2] = 0x0000

<7> [375.156093] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] cmn[0] = 0x0000, cmn[1] = 0x0000, cmn[2] = 0x0000, cmn[3] = 0x0000

<7> [375.156191] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[0] = 0x0000

<7> [375.156293] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[1] = 0x0000

<7> [375.156392] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[2] = 0x0000

<7> [375.156487] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[3] = 0x0000

<7> [375.156579] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[4] = 0x0000

<7> [375.156667] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[5] = 0x0000

<7> [375.156757] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[6] = 0x0000

<7> [375.156846] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[7] = 0x0000

<7> [375.156932] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[8] = 0x0000

<7> [375.157017] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mplla[9] = 0x0000

<7> [375.157100] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] mpllb[10] = 0x0000

<7> [375.157180] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] vdr: custom width: 0x00, serdes rate: 0x00, hdmi rate: 0x00

<7> [375.157261] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] found:

<7> [375.157394] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no

<7> [375.157500] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] c10pll_hw_state: fracen: no,

<7> [375.157598] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] multiplier: 225, tx_clk_div: 1.

<7> [375.157683] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] c10pll_rawhw_state:

<7> [375.157764] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] tx: 0x10, cmn: 0x21

<7> [375.157842] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1

<7> [375.157918] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0

<7> [375.157994] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0

<7> [375.158069] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1

<7> [375.158144] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23

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

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

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

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

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

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

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

<7> [375.158871] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:154:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051

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

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

<7> [375.159052] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0

<7> [375.159107] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197

<7> [375.159162] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198

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

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

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

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

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

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

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

<7> [375.159965] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 0 kHz -> 21732 kHz

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

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

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

<7> [375.160371] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:270:pipe B] allocated DPLL 0

<7> [375.160489] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:270:pipe B] reserving DPLL 0

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

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

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

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

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

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

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

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

<7> [375.161290] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0

<7> [375.161394] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

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

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

<7> [375.161683] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0

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

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

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

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

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

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

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

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

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

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

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

<7> [375.162717] xe 0000:00:02.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> [375.162794] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa

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

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

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

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

<7> [375.163193] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0

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

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

<7> [375.163487] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0

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

<7> [375.163671] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0

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

<7> [375.163821] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no

<7> [375.163902] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no,

<7> [375.163980] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1.

<7> [375.164056] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state:

<7> [375.164131] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21

<7> [375.164206] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1

<7> [375.164290] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0

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

<7> [375.164390] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0

<7> [375.164492] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1

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

<7> [375.164589] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [375.167562] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [375.170349] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:270:pipe B]

<7> [375.170473] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [375.960348] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:270:pipe B]

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

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

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

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