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

Detail	Value
Duration	2.99 seconds
Hostname	shard-lnl-6
Igt-Version	IGT-Version: 2.4-g8b0b513dc (x86_64) (Linux: 7.1.0-rc5-lgci-xe-xe-5138-11a8456527f00d86d-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:2220 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-eDP1: FAIL (2.993s)
Err	Starting dynamic subtest: B-eDP1 [149.782832] (kms_flip:3752) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [149.783067] (kms_flip:3752) CRITICAL: Failed assertion: end - start < 500 [149.783118] (kms_flip:3752) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-eDP1 failed. ** DEBUG [146.838792] (kms_flip:3752) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x100000000000009, size=0) [146.838801] (kms_flip:3752) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) [146.838814] (kms_flip:3752) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) [146.839565] (kms_flip:3752) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=11520) [146.839569] (kms_flip:3752) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) [146.839608] (kms_flip:3752) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x100000000000009, size=0) [146.839617] (kms_flip:3752) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) [146.839633] (kms_flip:3752) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) [146.839979] (kms_flip:3752) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=4, pitch=11520) [146.839981] (kms_flip:3752) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) [146.842323] (kms_flip:3752) intel_allocator_simple-DEBUG: Using simple allocator [146.846247] (kms_flip:3752) intel_allocator_simple-DEBUG: <ial: 0x64a0a624d040, fd: 5> objects: 3, reserved_areas: 0 [146.846249] (kms_flip:3752) intel_allocator_simple-DEBUG: <ial: 0x64a0a624d040, fd: 5> objects: 3, reserved_areas: 0 [146.865553] (kms_flip:3752) intel_allocator_simple-DEBUG: Using simple allocator [146.869335] (kms_flip:3752) intel_allocator_simple-DEBUG: <ial: 0x64a0a62d7e70, fd: 5> objects: 3, reserved_areas: 0 [146.869337] (kms_flip:3752) intel_allocator_simple-DEBUG: <ial: 0x64a0a62d7e70, fd: 5> objects: 3, reserved_areas: 0 [146.876756] (kms_flip:3752) intel_allocator_simple-DEBUG: Using simple allocator [146.882298] (kms_flip:3752) intel_allocator_simple-DEBUG: <ial: 0x64a0a62f9ad0, fd: 5> objects: 3, reserved_areas: 0 [146.882301] (kms_flip:3752) intel_allocator_simple-DEBUG: <ial: 0x64a0a62f9ad0, fd: 5> objects: 3, reserved_areas: 0 [146.901171] (kms_flip:3752) intel_allocator_simple-DEBUG: Using simple allocator [146.904704] (kms_flip:3752) intel_allocator_simple-DEBUG: <ial: 0x64a0a62f9ad0, fd: 5> objects: 3, reserved_areas: 0 [146.904706] (kms_flip:3752) intel_allocator_simple-DEBUG: <ial: 0x64a0a62f9ad0, fd: 5> objects: 3, reserved_areas: 0 [146.906224] (kms_flip:3752) igt_kms-INFO: 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa [146.908023] (kms_flip:3752) DEBUG: No stale events found [148.071560] (kms_flip:3752) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0 [148.071838] (kms_flip:3752) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0 [148.098749] (kms_flip:3752) DEBUG: name = flip last_ts = 0.000000 last_received_ts = 0.000000 last_seq = 0 current_ts = 149.627487 current_received_ts = 149.626755 current_seq = 43 count = 0 seq_step = 1 [148.098943] (kms_flip:3752) DEBUG: Vblank took 180us [148.115448] (kms_flip:3752) DEBUG: name = flip last_ts = 149.627487 last_received_ts = 149.626755 last_seq = 43 current_ts = 149.644150 current_received_ts = 149.643478 current_seq = 44 count = 1 seq_step = 1 [148.115522] (kms_flip:3752) DEBUG: Vblank took 68us [148.132073] (kms_flip:3752) DEBUG: name = flip last_ts = 149.644150 last_received_ts = 149.643478 last_seq = 44 current_ts = 149.660812 current_received_ts = 149.660110 current_seq = 45 count = 2 seq_step = 1 [148.132128] (kms_flip:3752) DEBUG: Vblank took 51us [148.148763] (kms_flip:3752) DEBUG: name = flip last_ts = 149.660812 last_received_ts = 149.660110 last_seq = 45 current_ts = 149.677490 current_received_ts = 149.676788 current_seq = 46 count = 3 seq_step = 1 [148.148815] (kms_flip:3752) DEBUG: Vblank took 49us [148.165421] (kms_flip:3752) DEBUG: name = flip last_ts = 149.677490 last_received_ts = 149.676788 last_seq = 46 current_ts = 149.694138 current_received_ts = 149.693451 current_seq = 47 count = 4 seq_step = 1 [148.165475] (kms_flip:3752) DEBUG: Vblank took 49us [148.182060] (kms_flip:3752) DEBUG: name = flip last_ts = 149.694138 last_received_ts = 149.693451 last_seq = 47 current_ts = 149.710815 current_received_ts = 149.710098 current_seq = 48 count = 5 seq_step = 1 [148.182109] (kms_flip:3752) DEBUG: Vblank took 46us [148.198771] (kms_flip:3752) DEBUG: name = flip last_ts = 149.710815 last_received_ts = 149.710098 last_seq = 48 current_ts = 149.727478 current_received_ts = 149.726807 current_seq = 49 count = 6 seq_step = 1 [148.198824] (kms_flip:3752) DEBUG: Vblank took 49us [148.215407] (kms_flip:3752) DEBUG: name = flip last_ts = 149.727478 last_received_ts = 149.726807 last_seq = 49 current_ts = 149.744141 current_received_ts = 149.743439 current_seq = 50 count = 7 seq_step = 1 [148.215456] (kms_flip:3752) DEBUG: Vblank took 46us [148.232057] (kms_flip:3752) DEBUG: name = flip last_ts = 149.744141 last_received_ts = 149.743439 last_seq = 50 current_ts = 149.760803 current_received_ts = 149.760101 current_seq = 51 count = 8 seq_step = 1 [148.232114] (kms_flip:3752) DEBUG: Vblank took 54us [148.248715] (kms_flip:3752) DEBUG: name = flip last_ts = 149.760803 last_received_ts = 149.760101 last_seq = 51 current_ts = 149.777466 current_received_ts = 149.776749 current_seq = 52 count = 9 seq_step = 1 [148.248768] (kms_flip:3752) DEBUG: Vblank took 50us [148.265403] (kms_flip:3752) DEBUG: name = flip last_ts = 149.777466 last_received_ts = 149.776749 last_seq = 52 current_ts = 149.794144 current_received_ts = 149.793442 current_seq = 53 count = 10 seq_step = 1 [148.265445] (kms_flip:3752) DEBUG: Vblank took 39us [148.282047] (kms_flip:3752) DEBUG: name = flip last_ts = 149.794144 last_received_ts = 149.793442 last_seq = 53 current_ts = 149.810806 current_received_ts = 149.810089 current_seq = 54 count = 11 seq_step = 1 [148.282094] (kms_flip:3752) DEBUG: Vblank took 44us [148.298727] (kms_flip:3752) DEBUG: name = flip last_ts = 149.810806 last_received_ts = 149.810089 last_seq = 54 current_ts = 149.827469 current_received_ts = 149.826767 current_seq = 55 count = 12 seq_step = 1 [148.298774] (kms_flip:3752) DEBUG: Vblank took 44us [148.315380] (kms_flip:3752) DEBUG: name = flip last_ts = 149.827469 last_received_ts = 149.826767 last_seq = 55 current_ts = 149.844131 current_received_ts = 149.843430 current_seq = 56 count = 13 seq_step = 1 [148.315435] (kms_flip:3752) DEBUG: Vblank took 52us [148.332056] (kms_flip:3752) DEBUG: name = flip last_ts = 149.844131 last_received_ts = 149.843430 last_seq = 56 current_ts = 149.860794 current_received_ts = 149.860107 current_seq = 57 count = 14 seq_step = 1 [148.332107] (kms_flip:3752) DEBUG: Vblank took 49us [148.348721] (kms_flip:3752) DEBUG: name = flip last_ts = 149.860794 last_received_ts = 149.860107 last_seq = 57 current_ts = 149.877457 current_received_ts = 149.876770 current_seq = 58 count = 15 seq_step = 1 [148.348771] (kms_flip:3752) DEBUG: Vblank took 47us [148.365376] (kms_flip:3752) DEBUG: name = flip last_ts = 149.877457 last_received_ts = 149.876770 last_seq = 58 current_ts = 149.894119 current_received_ts = 149.893417 current_seq = 59 count = 16 seq_step = 1 [148.365421] (kms_flip:3752) DEBUG: Vblank took 44us [148.382043] (kms_flip:3752) DEBUG: name = flip last_ts = 149.894119 last_received_ts = 149.893417 last_seq = 59 current_ts = 149.910797 current_received_ts = 149.910095 current_seq = 60 count = 17 seq_step = 1 [148.382093] (kms_flip:3752) DEBUG: Vblank took 47us [148.398731] (kms_flip:3752) DEBUG: name = flip last_ts = 149.910797 last_received_ts = 149.910095 last_seq = 60 current_ts = 149.927460 current_received_ts = 149.926773 current_seq = 61 count = 18 seq_step = 1 [148.398792] (kms_flip:3752) DEBUG: Vblank took 59us [148.415348] (kms_flip:3752) DEBUG: name = flip last_ts = 149.927460 last_received_ts = 149.926773 last_seq = 61 current_ts = 149.944122 current_received_ts = 149.943405 current_seq = 62 count = 19 seq_step = 1 [148.415393] (kms_flip:3752) DEBUG: Vblank took 42us [148.432015] (kms_flip:3752) DEBUG: name = flip last_ts = 149.944122 last_received_ts = 149.943405 last_seq = 62 current_ts = 149.960785 current_received_ts = 149.960068 current_seq = 63 count = 20 seq_step = 1 [148.432060] (kms_flip:3752) DEBUG: Vblank took 43us [148.448716] (kms_flip:3752) DEBUG: name = flip last_ts = 149.960785 last_received_ts = 149.960068 last_seq = 63 current_ts = 149.977448 current_received_ts = 149.976761 current_seq = 64 count = 21 seq_step = 1 [148.448762] (kms_flip:3752) DEBUG: Vblank took 43us [148.465371] (kms_flip:3752) DEBUG: name = flip last_ts = 149.977448 last_received_ts = 149.976761 last_seq = 64 current_ts = 149.994125 current_received_ts = 149.993423 current_seq = 65 count = 22 seq_step = 1 [148.465415] (kms_flip:3752) DEBUG: Vblank took 43us [148.483134] (kms_flip:3752) DEBUG: name = flip last_ts = 149.994125 last_received_ts = 149.993423 last_seq = 65 current_ts = 150.010773 current_received_ts = 150.011185 current_seq = 66 count = 23 seq_step = 1 [148.483203] (kms_flip:3752) DEBUG: Vblank took 65us [148.498606] (kms_flip:3752) DEBUG: name = flip last_ts = 150.010773 last_received_ts = 150.011185 last_seq = 66 current_ts = 150.027451 current_received_ts = 150.026657 current_seq = 67 count = 24 seq_step = 1 [148.498664] (kms_flip:3752) DEBUG: Vblank took 55us [148.515235] (kms_flip:3752) DEBUG: name = flip last_ts = 150.027451 last_received_ts = 150.026657 last_seq = 67 current_ts = 150.044113 current_received_ts = 150.043289 current_seq = 68 count = 25 seq_step = 1 [148.515286] (kms_flip:3752) DEBUG: Vblank took 48us [148.532040] (kms_flip:3752) DEBUG: name = flip last_ts = 150.044113 last_received_ts = 150.043289 last_seq = 68 current_ts = 150.060776 current_received_ts = 150.060089 current_seq = 69 count = 26 seq_step = 1 [148.532098] (kms_flip:3752) DEBUG: Vblank took 55us [148.548657] (kms_flip:3752) DEBUG: name = flip last_ts = 150.060776 last_received_ts = 150.060089 last_seq = 69 current_ts = 150.077454 current_received_ts = 150.076721 current_seq = 70 count = 27 seq_step = 1 [148.548703] (kms_flip:3752) DEBUG: Vblank took 43us [148.565315] (kms_flip:3752) DEBUG: name = flip last_ts = 150.077454 last_received_ts = 150.076721 last_seq = 70 current_ts = 150.094101 current_received_ts = 150.093369 current_seq = 71 count = 28 seq_step = 1 [148.565359] (kms_flip:3752) DEBUG: Vblank took 43us [148.582008] (kms_flip:3752) DEBUG: name = flip last_ts = 150.094101 last_received_ts = 150.093369 last_seq = 71 current_ts = 150.110764 current_received_ts = 150.110062 current_seq = 72 count = 29 seq_step = 1 [148.582059] (kms_flip:3752) DEBUG: Vblank took 48us [148.598686] (kms_flip:3752) DEBUG: name = flip last_ts = 150.110764 last_received_ts = 150.110062 last_seq = 72 current_ts = 150.127441 current_received_ts = 150.126740 current_seq = 73 count = 30 seq_step = 1 [148.598735] (kms_flip:3752) DEBUG: Vblank took 47us [148.615330] (kms_flip:3752) DEBUG: name = flip last_ts = 150.127441 last_received_ts = 150.126740 last_seq = 73 current_ts = 150.144104 current_received_ts = 150.143387 current_seq = 74 count = 31 seq_step = 1 [148.615387] (kms_flip:3752) DEBUG: Vblank took 54us [148.631997] (kms_flip:3752) DEBUG: name = flip last_ts = 150.144104 last_received_ts = 150.143387 last_seq = 74 current_ts = 150.160767 current_received_ts = 150.160065 current_seq = 75 count = 32 seq_step = 1 [148.632042] (kms_flip:3752) DEBUG: Vblank took 42us [148.648690] (kms_flip:3752) DEBUG: name = flip last_ts = 150.160767 last_received_ts = 150.160065 last_seq = 75 current_ts = 150.177429 current_received_ts = 150.176758 current_seq = 76 count = 33 seq_step = 1 [148.648740] (kms_flip:3752) DEBUG: Vblank took 47us [148.665297] (kms_flip:3752) DEBUG: name = flip last_ts = 150.177429 last_received_ts = 150.176758 last_seq = 76 current_ts = 150.194107 current_received_ts = 150.193359 current_seq = 77 count = 34 seq_step = 1 [148.665343] (kms_flip:3752) DEBUG: Vblank took 43us [148.681986] (kms_flip:3752) DEBUG: name = flip last_ts = 150.194107 last_received_ts = 150.193359 last_seq = 77 current_ts = 150.210754 current_received_ts = 150.210052 current_seq = 78 count = 35 seq_step = 1 [148.682035] (kms_flip:3752) DEBUG: Vblank took 47us [148.698674] (kms_flip:3752) DEBUG: name = flip last_ts = 150.210754 last_received_ts = 150.210052 last_seq = 78 current_ts = 150.227432 current_received_ts = 150.226746 current_seq = 79 count = 36 seq_step = 1 [148.698719] (kms_flip:3752) DEBUG: Vblank took 43us [148.715288] (kms_flip:3752) DEBUG: name = flip last_ts = 150.227432 last_received_ts = 150.226746 last_seq = 79 current_ts = 150.244095 current_received_ts = 150.243362 current_seq = 80 count = 37 seq_step = 1 [148.715332] (kms_flip:3752) DEBUG: Vblank took 39us [148.731987] (kms_flip:3752) DEBUG: name = flip last_ts = 150.244095 last_received_ts = 150.243362 last_seq = 80 current_ts = 150.260757 current_received_ts = 150.260056 current_seq = 81 count = 38 seq_step = 1 [148.732062] (kms_flip:3752) DEBUG: Vblank took 72us [148.748656] (kms_flip:3752) DEBUG: name = flip last_ts = 150.260757 last_received_ts = 150.260056 last_seq = 81 current_ts = 150.277420 current_received_ts = 150.276703 current_seq = 82 count = 39 seq_step = 1 [148.748796] (kms_flip:3752) DEBUG: Vblank took 125us [148.765312] (kms_flip:3752) DEBUG: name = flip last_ts = 150.277420 last_received_ts = 150.276703 last_seq = 82 current_ts = 150.294083 current_received_ts = 150.293365 current_seq = 83 count = 40 seq_step = 1 [148.765382] (kms_flip:3752) DEBUG: Vblank took 62us [148.781997] (kms_flip:3752) DEBUG: name = flip last_ts = 150.294083 last_received_ts = 150.293365 last_seq = 83 current_ts = 150.310760 current_received_ts = 150.310059 current_seq = 84 count = 41 seq_step = 1 [148.782079] (kms_flip:3752) DEBUG: Vblank took 74us [148.798670] (kms_flip:3752) DEBUG: name = flip last_ts = 150.310760 last_received_ts = 150.310059 last_seq = 84 current_ts = 150.327423 current_received_ts = 150.326736 current_seq = 85 count = 42 seq_step = 1 [148.798731] (kms_flip:3752) DEBUG: Vblank took 57us [148.815329] (kms_flip:3752) DEBUG: name = flip last_ts = 150.327423 last_received_ts = 150.326736 last_seq = 85 current_ts = 150.344086 current_received_ts = 150.343399 current_seq = 86 count = 43 seq_step = 1 [148.815390] (kms_flip:3752) DEBUG: Vblank took 56us [148.831980] (kms_flip:3752) DEBUG: name = flip last_ts = 150.344086 last_received_ts = 150.343399 last_seq = 86 current_ts = 150.360748 current_received_ts = 150.360046 current_seq = 87 count = 44 seq_step = 1 [148.832037] (kms_flip:3752) DEBUG: Vblank took 53us [148.848661] (kms_flip:3752) DEBUG: name = flip last_ts = 150.360748 last_received_ts = 150.360046 last_seq = 87 current_ts = 150.377411 current_received_ts = 150.376740 current_seq = 88 count = 45 seq_step = 1 [148.848714] (kms_flip:3752) DEBUG: Vblank took 49us [148.865188] (kms_flip:3752) DEBUG: name = flip last_ts = 150.377411 last_received_ts = 150.376740 last_seq = 88 current_ts = 150.394073 current_received_ts = 150.393265 current_seq = 89 count = 46 seq_step = 1 [148.865234] (kms_flip:3752) DEBUG: Vblank took 44us [148.881983] (kms_flip:3752) DEBUG: name = flip last_ts = 150.394073 last_received_ts = 150.393265 last_seq = 89 current_ts = 150.410736 current_received_ts = 150.410065 current_seq = 90 count = 47 seq_step = 1 [148.882045] (kms_flip:3752) DEBUG: Vblank took 57us [148.898653] (kms_flip:3752) DEBUG: name = flip last_ts = 150.410736 last_received_ts = 150.410065 last_seq = 90 current_ts = 150.427399 current_received_ts = 150.426727 current_seq = 91 count = 48 seq_step = 1 [148.898716] (kms_flip:3752) DEBUG: Vblank took 60us [148.915334] (kms_flip:3752) DEBUG: name = flip last_ts = 150.427399 last_received_ts = 150.426727 last_seq = 91 current_ts = 150.444077 current_received_ts = 150.443405 current_seq = 92 count = 49 seq_step = 1 [148.915402] (kms_flip:3752) DEBUG: Vblank took 63us [148.931972] (kms_flip:3752) DEBUG: name = flip last_ts = 150.444077 last_received_ts = 150.443405 last_seq = 92 current_ts = 150.460739 current_received_ts = 150.460052 current_seq = 93 count = 50 seq_step = 1 [148.932024] (kms_flip:3752) DEBUG: Vblank took 49us [148.948659] (kms_flip:3752) DEBUG: name = flip last_ts = 150.460739 last_received_ts = 150.460052 last_seq = 93 current_ts = 150.477402 current_received_ts = 150.476746 current_seq = 94 count = 51 seq_step = 1 [148.948714] (kms_flip:3752) DEBUG: Vblank took 53us [148.965294] (kms_flip:3752) DEBUG: name = flip last_ts = 150.477402 last_received_ts = 150.476746 last_seq = 94 current_ts = 150.494064 current_received_ts = 150.493378 current_seq = 95 count = 52 seq_step = 1 [148.965344] (kms_flip:3752) DEBUG: Vblank took 48us [148.981975] (kms_flip:3752) DEBUG: name = flip last_ts = 150.494064 last_received_ts = 150.493378 last_seq = 95 current_ts = 150.510742 current_received_ts = 150.510056 current_seq = 96 count = 53 seq_step = 1 [148.982038] (kms_flip:3752) DEBUG: Vblank took 59us [148.998640] (kms_flip:3752) DEBUG: name = flip last_ts = 150.510742 last_received_ts = 150.510056 last_seq = 96 current_ts = 150.527390 current_received_ts = 150.526718 current_seq = 97 count = 54 seq_step = 1 [148.998694] (kms_flip:3752) DEBUG: Vblank took 51us [149.015240] (kms_flip:3752) DEBUG: name = flip last_ts = 150.527390 last_received_ts = 150.526718 last_seq = 97 current_ts = 150.544067 current_received_ts = 150.543320 current_seq = 98 count = 55 seq_step = 1 [149.015299] (kms_flip:3752) DEBUG: Vblank took 55us [149.031946] (kms_flip:3752) DEBUG: name = flip last_ts = 150.544067 last_received_ts = 150.543320 last_seq = 98 current_ts = 150.560730 current_received_ts = 150.560028 current_seq = 99 count = 56 seq_step = 1 [149.031997] (kms_flip:3752) DEBUG: Vblank took 48us [149.048613] (kms_flip:3752) DEBUG: name = flip last_ts = 150.560730 last_received_ts = 150.560028 last_seq = 99 current_ts = 150.577393 current_received_ts = 150.576706 current_seq = 100 count = 57 seq_step = 1 [149.048691] (kms_flip:3752) DEBUG: Vblank took 73us [149.065280] (kms_flip:3752) DEBUG: name = flip last_ts = 150.577393 last_received_ts = 150.576706 last_seq = 100 current_ts = 150.594055 current_received_ts = 150.593369 current_seq = 101 count = 58 seq_step = 1 [149.065331] (kms_flip:3752) DEBUG: Vblank took 48us [149.081957] (kms_flip:3752) DEBUG: name = flip last_ts = 150.594055 last_received_ts = 150.593369 last_seq = 101 current_ts = 150.610718 current_received_ts = 150.610046 current_seq = 102 count = 59 seq_step = 1 [149.082014] (kms_flip:3752) DEBUG: Vblank took 52us [149.098645] (kms_flip:3752) DEBUG: name = flip last_ts = 150.610718 last_received_ts = 150.610046 last_seq = 102 current_ts = 150.627380 current_received_ts = 150.626740 current_seq = 103 count = 60 seq_step = 1 [149.098708] (kms_flip:3752) DEBUG: Vblank took 60us [149.115273] (kms_flip:3752) DEBUG: name = flip last_ts = 150.627380 last_received_ts = 150.626740 last_seq = 103 current_ts = 150.644058 current_received_ts = 150.643372 current_seq = 104 count = 61 seq_step = 1 [149.115330] (kms_flip:3752) DEBUG: Vblank took 54us [149.131950] (kms_flip:3752) DEBUG: name = flip last_ts = 150.644058 last_received_ts = 150.643372 last_seq = 104 current_ts = 150.660721 current_received_ts = 150.660034 current_seq = 105 count = 62 seq_step = 1 [149.131992] (kms_flip:3752) DEBUG: Vblank took 39us [149.148598] (kms_flip:3752) DEBUG: name = flip last_ts = 150.660721 last_received_ts = 150.660034 last_seq = 105 current_ts = 150.677383 current_received_ts = 150.676697 current_seq = 106 count = 63 seq_step = 1 [149.148647] (kms_flip:3752) DEBUG: Vblank took 46us [149.165259] (kms_flip:3752) DEBUG: name = flip last_ts = 150.677383 last_received_ts = 150.676697 last_seq = 106 current_ts = 150.694046 current_received_ts = 150.693359 current_seq = 107 count = 64 seq_step = 1 [149.165304] (kms_flip:3752) DEBUG: Vblank took 43us [149.181885] (kms_flip:3752) DEBUG: name = flip last_ts = 150.694046 last_received_ts = 150.693359 last_seq = 107 current_ts = 150.710709 current_received_ts = 150.709976 current_seq = 108 count = 65 seq_step = 1 [149.181944] (kms_flip:3752) DEBUG: Vblank took 57us [149.198584] (kms_flip:3752) DEBUG: name = flip last_ts = 150.710709 last_received_ts = 150.709976 last_seq = 108 current_ts = 150.727371 current_received_ts = 150.726685 current_seq = 109 count = 66 seq_step = 1 [149.198633] (kms_flip:3752) DEBUG: Vblank took 47us [149.215147] (kms_flip:3752) DEBUG: name = flip last_ts = 150.727371 last_received_ts = 150.726685 last_seq = 109 current_ts = 150.744049 current_received_ts = 150.743240 current_seq = 110 count = 67 seq_step = 1 [149.215186] (kms_flip:3752) DEBUG: Vblank took 35us [149.231823] (kms_flip:3752) DEBUG: name = flip last_ts = 150.744049 last_received_ts = 150.743240 last_seq = 110 current_ts = 150.760712 current_received_ts = 150.759918 current_seq = 111 count = 68 seq_step = 1 [149.231875] (kms_flip:3752) DEBUG: Vblank took 50us [149.248471] (kms_flip:3752) DEBUG: name = flip last_ts = 150.760712 last_received_ts = 150.759918 last_seq = 111 current_ts = 150.777374 current_received_ts = 150.776566 current_seq = 112 count = 69 seq_step = 1 [149.248529] (kms_flip:3752) DEBUG: Vblank took 55us [149.265125] (kms_flip:3752) DEBUG: name = flip last_ts = 150.777374 last_received_ts = 150.776566 last_seq = 112 current_ts = 150.794037 current_received_ts = 150.793228 current_seq = 113 count = 70 seq_step = 1 [149.265182] (kms_flip:3752) DEBUG: Vblank took 54us [149.281931] (kms_flip:3752) DEBUG: name = flip last_ts = 150.794037 last_received_ts = 150.793228 last_seq = 113 current_ts = 150.810699 current_received_ts = 150.810028 current_seq = 114 count = 71 seq_step = 1 [149.281973] (kms_flip:3752) DEBUG: Vblank took 37us [149.298578] (kms_flip:3752) DEBUG: name = flip last_ts = 150.810699 last_received_ts = 150.810028 last_seq = 114 current_ts = 150.827377 current_received_ts = 150.826675 current_seq = 115 count = 72 seq_step = 1 [149.298640] (kms_flip:3752) DEBUG: Vblank took 56us [149.315237] (kms_flip:3752) DEBUG: name = flip last_ts = 150.827377 last_received_ts = 150.826675 last_seq = 115 current_ts = 150.844025 current_received_ts = 150.843338 current_seq = 116 count = 73 seq_step = 1 [149.315287] (kms_flip:3752) DEBUG: Vblank took 47us [149.331909] (kms_flip:3752) DEBUG: name = flip last_ts = 150.844025 last_received_ts = 150.843338 last_seq = 116 current_ts = 150.860703 current_received_ts = 150.860016 current_seq = 117 count = 74 seq_step = 1 [149.331966] (kms_flip:3752) DEBUG: Vblank took 53us [149.348541] (kms_flip:3752) DEBUG: name = flip last_ts = 150.860703 last_received_ts = 150.860016 last_seq = 117 current_ts = 150.877365 current_received_ts = 150.876648 current_seq = 118 count = 75 seq_step = 1 [149.348592] (kms_flip:3752) DEBUG: Vblank took 48us [149.365224] (kms_flip:3752) DEBUG: name = flip last_ts = 150.877365 last_received_ts = 150.876648 last_seq = 118 current_ts = 150.894028 current_received_ts = 150.893326 current_seq = 119 count = 76 seq_step = 1 [149.365296] (kms_flip:3752) DEBUG: Vblank took 69us [149.381905] (kms_flip:3752) DEBUG: name = flip last_ts = 150.894028 last_received_ts = 150.893326 last_seq = 119 current_ts = 150.910690 current_received_ts = 150.910019 current_seq = 120 count = 77 seq_step = 1 [149.381954] (kms_flip:3752) DEBUG: Vblank took 47us [149.398562] (kms_flip:3752) DEBUG: name = flip last_ts = 150.910690 last_received_ts = 150.910019 last_seq = 120 current_ts = 150.927353 current_received_ts = 150.926666 current_seq = 121 count = 78 seq_step = 1 [149.398612] (kms_flip:3752) DEBUG: Vblank took 48us [149.415228] (kms_flip:3752) DEBUG: name = flip last_ts = 150.927353 last_received_ts = 150.926666 last_seq = 121 current_ts = 150.944031 current_received_ts = 150.943344 current_seq = 122 count = 79 seq_step = 1 [149.415282] (kms_flip:3752) DEBUG: Vblank took 50us [149.431892] (kms_flip:3752) DEBUG: name = flip last_ts = 150.944031 last_received_ts = 150.943344 last_seq = 122 current_ts = 150.960693 current_received_ts = 150.959991 current_seq = 123 count = 80 seq_step = 1 [149.431944] (kms_flip:3752) DEBUG: Vblank took 48us [149.448448] (kms_flip:3752) DEBUG: name = flip last_ts = 150.960693 last_received_ts = 150.959991 last_seq = 123 current_ts = 150.977356 current_received_ts = 150.976562 current_seq = 124 count = 81 seq_step = 1 [149.448503] (kms_flip:3752) DEBUG: Vblank took 52us [149.465200] (kms_flip:3752) DEBUG: name = flip last_ts = 150.977356 last_received_ts = 150.976562 last_seq = 124 current_ts = 150.994019 current_received_ts = 150.993317 current_seq = 125 count = 82 seq_step = 1 [149.465257] (kms_flip:3752) DEBUG: Vblank took 53us [149.481904] (kms_flip:3752) DEBUG: name = flip last_ts = 150.994019 last_received_ts = 150.993317 last_seq = 125 current_ts = 151.010681 current_received_ts = 151.010010 current_seq = 126 count = 83 seq_step = 1 [149.481946] (kms_flip:3752) DEBUG: Vblank took 39us [149.498554] (kms_flip:3752) DEBUG: name = flip last_ts = 151.010681 last_received_ts = 151.010010 last_seq = 126 current_ts = 151.027344 current_received_ts = 151.026672 current_seq = 127 count = 84 seq_step = 1 [149.498615] (kms_flip:3752) DEBUG: Vblank took 58us [149.515147] (kms_flip:3752) DEBUG: name = flip last_ts = 151.027344 last_received_ts = 151.026672 last_seq = 127 current_ts = 151.044022 current_received_ts = 151.043259 current_seq = 128 count = 85 seq_step = 1 [149.515218] (kms_flip:3752) DEBUG: Vblank took 68us [149.531898] (kms_flip:3752) DEBUG: name = flip last_ts = 151.044022 last_received_ts = 151.043259 last_seq = 128 current_ts = 151.060684 current_received_ts = 151.060013 current_seq = 129 count = 86 seq_step = 1 [149.531953] (kms_flip:3752) DEBUG: Vblank took 52us [149.548570] (kms_flip:3752) DEBUG: name = flip last_ts = 151.060684 last_received_ts = 151.060013 last_seq = 129 current_ts = 151.077347 current_received_ts = 151.076691 current_seq = 130 count = 87 seq_step = 1 [149.548630] (kms_flip:3752) DEBUG: Vblank took 56us [149.565182] (kms_flip:3752) DEBUG: name = flip last_ts = 151.077347 last_received_ts = 151.076691 last_seq = 130 current_ts = 151.094009 current_received_ts = 151.093307 current_seq = 131 count = 88 seq_step = 1 [149.565231] (kms_flip:3752) DEBUG: Vblank took 46us [149.581859] (kms_flip:3752) DEBUG: name = flip last_ts = 151.094009 last_received_ts = 151.093307 last_seq = 131 current_ts = 151.110672 current_received_ts = 151.109985 current_seq = 132 count = 89 seq_step = 1 [149.581919] (kms_flip:3752) DEBUG: Vblank took 58us [149.598548] (kms_flip:3752) DEBUG: name = flip last_ts = 151.110672 last_received_ts = 151.109985 last_seq = 132 current_ts = 151.127335 current_received_ts = 151.126663 current_seq = 133 count = 90 seq_step = 1 [149.598598] (kms_flip:3752) DEBUG: Vblank took 48us [149.615170] (kms_flip:3752) DEBUG: name = flip last_ts = 151.127335 last_received_ts = 151.126663 last_seq = 133 current_ts = 151.143997 current_received_ts = 151.143295 current_seq = 134 count = 91 seq_step = 1 [149.615221] (kms_flip:3752) DEBUG: Vblank took 49us [149.631869] (kms_flip:3752) DEBUG: name = flip last_ts = 151.143997 last_received_ts = 151.143295 last_seq = 134 current_ts = 151.160660 current_received_ts = 151.159988 current_seq = 135 count = 92 seq_step = 1 [149.631938] (kms_flip:3752) DEBUG: Vblank took 67us [149.648526] (kms_flip:3752) DEBUG: name = flip last_ts = 151.160660 last_received_ts = 151.159988 last_seq = 135 current_ts = 151.177322 current_received_ts = 151.176651 current_seq = 136 count = 93 seq_step = 1 [149.648578] (kms_flip:3752) DEBUG: Vblank took 50us [149.665189] (kms_flip:3752) DEBUG: name = flip last_ts = 151.177322 last_received_ts = 151.176651 last_seq = 136 current_ts = 151.194000 current_received_ts = 151.193314 current_seq = 137 count = 94 seq_step = 1 [149.665241] (kms_flip:3752) DEBUG: Vblank took 49us [149.681847] (kms_flip:3752) DEBUG: name = flip last_ts = 151.194000 last_received_ts = 151.193314 last_seq = 137 current_ts = 151.210663 current_received_ts = 151.209976 current_seq = 138 count = 95 seq_step = 1 [149.681907] (kms_flip:3752) DEBUG: Vblank took 57us [149.698521] (kms_flip:3752) DEBUG: name = flip last_ts = 151.210663 last_received_ts = 151.209976 last_seq = 138 current_ts = 151.227325 current_received_ts = 151.226654 current_seq = 139 count = 96 seq_step = 1 [149.698573] (kms_flip:3752) DEBUG: Vblank took 50us [149.715146] (kms_flip:3752) DEBUG: name = flip last_ts = 151.227325 last_received_ts = 151.226654 last_seq = 139 current_ts = 151.244003 current_received_ts = 151.243271 current_seq = 140 count = 97 seq_step = 1 [149.715196] (kms_flip:3752) DEBUG: Vblank took 46us [149.731846] (kms_flip:3752) DEBUG: name = flip last_ts = 151.244003 last_received_ts = 151.243271 last_seq = 140 current_ts = 151.260666 current_received_ts = 151.259979 current_seq = 141 count = 98 seq_step = 1 [149.731894] (kms_flip:3752) DEBUG: Vblank took 45us [149.748525] (kms_flip:3752) DEBUG: name = flip last_ts = 151.260666 last_received_ts = 151.259979 last_seq = 141 current_ts = 151.277313 current_received_ts = 151.276657 current_seq = 142 count = 99 seq_step = 1 [149.748577] (kms_flip:3752) DEBUG: Vblank took 49us [149.765118] (kms_flip:3752) DEBUG: name = flip last_ts = 151.277313 last_received_ts = 151.276657 last_seq = 142 current_ts = 151.293991 current_received_ts = 151.293243 current_seq = 143 count = 100 seq_step = 1 [149.765173] (kms_flip:3752) DEBUG: Vblank took 52us [149.781829] (kms_flip:3752) DEBUG: name = flip last_ts = 151.293991 last_received_ts = 151.293243 last_seq = 143 current_ts = 151.310654 current_received_ts = 151.309952 current_seq = 144 count = 101 seq_step = 1 [149.782813] (kms_flip:3752) DEBUG: Vblank took 968us [149.782832] (kms_flip:3752) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [149.783067] (kms_flip:3752) CRITICAL: Failed assertion: end - start < 500 [149.783118] (kms_flip:3752) CRITICAL: Last errno: 4, Interrupted system call [149.786559] (kms_flip:3752) igt_core-INFO: Stack trace: [149.789948] (kms_flip:3752) igt_core-INFO: #0 ../lib/igt_core.c:2106 __igt_fail_assert() [149.791630] (kms_flip:3752) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [149.791680] (kms_flip:3752) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [149.791718] (kms_flip:3752) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() [149.791754] (kms_flip:3752) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [149.795140] (kms_flip:3752) igt_core-INFO: #5 [__libc_init_first+0x8a] [149.797099] (kms_flip:3752) igt_core-INFO: #6 [__libc_start_main+0x8b] [149.797550] (kms_flip:3752) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (2.993s)
Dmesg	<6> [148.560540] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [148.561539] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:433] <7> [148.561933] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:434] <7> [148.629968] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [148.630058] 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> [148.630211] 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> [148.630325] 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> [148.630426] 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> [148.630523] 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> [148.630619] 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> [148.630713] 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> [148.630805] 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> [148.630897] 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> [148.631000] 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> [148.631118] 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> [148.631233] 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> [148.631334] 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> [148.631433] 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> [148.631533] 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> [148.631631] 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> [148.631726] 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> [148.631820] 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> [148.631912] 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> [148.632020] 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> [148.632129] 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> [148.632237] 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> [148.632331] 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> [148.632419] 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> [148.632506] 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> [148.632593] 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> [148.632679] 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> [148.632765] 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> [148.632850] 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> [148.632936] 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> [148.633101] 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> [148.633225] 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> [148.633335] 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> [148.633427] 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> [148.633514] 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> [148.633601] 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> [148.633687] 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> [148.633772] 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> [148.633859] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [148.633945] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [148.634093] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [148.634185] 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> [148.634298] 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> [148.634371] 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> [148.634435] 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> [148.634498] 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> [148.634560] 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> [148.634622] 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> [148.634701] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0 <7> [148.634806] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 0 qgv_peak_bw: 38400 <7> [148.634913] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 0 qgv_peak_bw: 38400 <7> [148.635037] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [148.635147] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [148.635255] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 0 <7> [148.635360] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [148.635456] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 21732 kHz -> 0 kHz <7> [148.635547] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [148.635639] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [148.635740] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [148.635848] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [148.635952] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [148.636083] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [148.636191] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [148.636297] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [148.636402] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [148.636492] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [148.636612] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [148.636718] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [148.636871] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2 <7> [148.638798] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [148.638928] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [148.848272] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [148.848837] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [148.856356] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [148.856734] 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> [148.857176] 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> [148.909396] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [148.909742] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [148.918255] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [148.918691] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [148.918746] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [148.920381] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [148.920981] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [148.921508] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [148.921914] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [148.922324] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [148.922711] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [148.923052] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [148.923384] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [148.923700] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [148.924026] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [148.924361] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [148.924669] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [148.924983] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [148.925287] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [148.925584] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [148.925887] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [148.926328] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [148.926629] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [148.926916] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [148.927485] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [148.927942] 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> [148.928478] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [148.928834] 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> [148.929302] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [148.929626] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [148.930724] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [148.931148] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [148.931456] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [148.931526] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [148.931700] 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> [148.932123] 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> [148.932456] 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> [148.932819] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [148.933190] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:270:pipe B] <7> [148.933509] 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> [148.933811] 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> [148.934115] 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> [148.934416] 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> [148.934673] 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> [148.934931] 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> [148.935200] 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> [148.935458] 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> [148.935678] 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> [148.935907] 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> [148.936171] 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> [148.936372] 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> [148.936556] 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> [148.936738] 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> [148.936914] 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> [148.937104] 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> [148.937296] 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> [148.937457] 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> [148.937617] 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> [148.937769] 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> [148.937923] 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> [148.938088] 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> [148.938230] 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> [148.938367] 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> [148.938501] 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> [148.938636] 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> [148.938775] 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> [148.938909] 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> [148.939049] 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> [148.939171] 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> [148.939287] 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> [148.939403] 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> [148.939518] 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> [148.939543] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [148.939636] 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> [148.939688] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [148.939757] 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> [148.939818] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [148.939878] 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> [148.939947] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [148.940001] 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> [148.940113] 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> [148.940221] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] fastset requirement not met, forcing full modeset <7> [148.940365] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [148.940453] 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> [148.940577] 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> [148.940664] 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> [148.940736] 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> [148.940809] 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> [148.940882] 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> [148.940961] 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> [148.941056] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:270:pipe B] data rate 1390840 num active planes 1 <7> [148.941168] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [148.941275] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [148.941369] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [148.941462] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [148.941551] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [148.941638] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:270:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [148.941740] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 0 kHz -> 21732 kHz <7> [148.941843] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [148.941951] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [148.942126] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [148.942251] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:270:pipe B] allocated DPLL 0 <7> [148.942370] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:270:pipe B] reserving DPLL 0 <7> [148.942475] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:270:pipe B] enable: yes [modeset] <7> [148.942561] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [148.942644] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [148.942725] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [148.942807] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [148.942889] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [148.942980] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [148.943089] 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> [148.943196] 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> [148.943299] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [148.943390] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [148.943492] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [148.943589] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [148.943677] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [148.943767] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [148.943853] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [148.943939] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [148.944052] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [148.944156] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [148.944256] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [148.944341] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [148.944429] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [148.944516] 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> [148.944603] 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> [148.944698] 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> [148.944798] 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> [148.944898] 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> [148.945002] 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> [148.945105] 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> [148.945203] 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> [148.945300] 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> [148.945391] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [148.945482] 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> [148.945561] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0 <7> [148.945643] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [148.945724] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [148.945805] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [148.945886] 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> [148.945965] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [148.946057] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [148.946154] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [148.946254] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [148.946344] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [148.946429] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [148.946513] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [148.946613] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [148.946712] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [148.946812] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [148.946895] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [148.946974] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [148.947073] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [148.947171] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [148.947271] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [148.947359] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [148.947441] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [148.947523] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [148.947603] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [148.947683] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [148.947764] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [148.947839] 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> [148.947915] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [148.948011] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [148.948109] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:184:plane 2B] fb: [NOFB], visible: no <7> [148.948205] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:214:plane 3B] fb: [NOFB], visible: no <7> [148.948297] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:244:plane 4B] fb: [NOFB], visible: no <7> [148.948378] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:254:plane 5B] fb: [NOFB], visible: no <7> [148.948461] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:264:cursor B] fb: [NOFB], visible: no <7> [148.948782] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [148.948932] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [148.949109] 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> [148.949245] 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> [148.949362] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [148.949458] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [148.949553] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [148.949631] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [148.949708] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [148.949783] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [148.949855] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [148.949921] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [148.950004] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [148.950095] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [148.950186] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [148.950272] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [148.950342] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [148.950412] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [148.950482] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [148.950575] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [148.950744] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: ) <7> [148.950808] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [148.950915] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [148.951997] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:270:pipe B] <7> [148.952111] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [148.954122] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [148.954235] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (465 ms remaining) <7> [149.424265] 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> [149.525836] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [149.526443] 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> [149.526872] 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> [149.562789] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [149.563203] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [149.563562] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [149.564013] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [149.740692] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [149.741176] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [149.741513] 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> [149.743564] 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> [149.745139] 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> [149.746082] 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> [149.747315] 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> [149.748817] 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> [149.749988] 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> [149.750419] 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> [149.751945] 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> [149.752365] 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> [149.753216] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [149.753822] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [149.754294] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [149.754828] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 13892 <7> [149.787612] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [149.789435] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [149.789878] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:270:pipe B] <7> [151.520874] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [151.521289] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [151.521591] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [151.557070] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

2.99 seconds

Hostname

shard-lnl-6

Igt-Version

IGT-Version: 2.4-g8b0b513dc (x86_64) (Linux: 7.1.0-rc5-lgci-xe-xe-5138-11a8456527f00d86d-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:2220 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (2.993s)

Err

Starting dynamic subtest: B-eDP1
[149.782832] (kms_flip:3752) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[149.783067] (kms_flip:3752) CRITICAL: Failed assertion: end - start < 500
[149.783118] (kms_flip:3752) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
[146.838792] (kms_flip:3752) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x100000000000009, size=0)
[146.838801] (kms_flip:3752) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
[146.838814] (kms_flip:3752) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
[146.839565] (kms_flip:3752) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=11520)
[146.839569] (kms_flip:3752) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
[146.839608] (kms_flip:3752) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x100000000000009, size=0)
[146.839617] (kms_flip:3752) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
[146.839633] (kms_flip:3752) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
[146.839979] (kms_flip:3752) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=4, pitch=11520)
[146.839981] (kms_flip:3752) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
[146.842323] (kms_flip:3752) intel_allocator_simple-DEBUG: Using simple allocator
[146.846247] (kms_flip:3752) intel_allocator_simple-DEBUG: <ial: 0x64a0a624d040, fd: 5> objects: 3, reserved_areas: 0
[146.846249] (kms_flip:3752) intel_allocator_simple-DEBUG: <ial: 0x64a0a624d040, fd: 5> objects: 3, reserved_areas: 0
[146.865553] (kms_flip:3752) intel_allocator_simple-DEBUG: Using simple allocator
[146.869335] (kms_flip:3752) intel_allocator_simple-DEBUG: <ial: 0x64a0a62d7e70, fd: 5> objects: 3, reserved_areas: 0
[146.869337] (kms_flip:3752) intel_allocator_simple-DEBUG: <ial: 0x64a0a62d7e70, fd: 5> objects: 3, reserved_areas: 0
[146.876756] (kms_flip:3752) intel_allocator_simple-DEBUG: Using simple allocator
[146.882298] (kms_flip:3752) intel_allocator_simple-DEBUG: <ial: 0x64a0a62f9ad0, fd: 5> objects: 3, reserved_areas: 0
[146.882301] (kms_flip:3752) intel_allocator_simple-DEBUG: <ial: 0x64a0a62f9ad0, fd: 5> objects: 3, reserved_areas: 0
[146.901171] (kms_flip:3752) intel_allocator_simple-DEBUG: Using simple allocator
[146.904704] (kms_flip:3752) intel_allocator_simple-DEBUG: <ial: 0x64a0a62f9ad0, fd: 5> objects: 3, reserved_areas: 0
[146.904706] (kms_flip:3752) intel_allocator_simple-DEBUG: <ial: 0x64a0a62f9ad0, fd: 5> objects: 3, reserved_areas: 0
[146.906224] (kms_flip:3752) igt_kms-INFO:   2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
[146.908023] (kms_flip:3752) DEBUG: No stale events found
[148.071560] (kms_flip:3752) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
[148.071838] (kms_flip:3752) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
[148.098749] (kms_flip:3752) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 149.627487
current_received_ts = 149.626755
current_seq = 43
count = 0
seq_step = 1
[148.098943] (kms_flip:3752) DEBUG: Vblank took 180us
[148.115448] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.627487
last_received_ts = 149.626755
last_seq = 43
current_ts = 149.644150
current_received_ts = 149.643478
current_seq = 44
count = 1
seq_step = 1
[148.115522] (kms_flip:3752) DEBUG: Vblank took 68us
[148.132073] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.644150
last_received_ts = 149.643478
last_seq = 44
current_ts = 149.660812
current_received_ts = 149.660110
current_seq = 45
count = 2
seq_step = 1
[148.132128] (kms_flip:3752) DEBUG: Vblank took 51us
[148.148763] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.660812
last_received_ts = 149.660110
last_seq = 45
current_ts = 149.677490
current_received_ts = 149.676788
current_seq = 46
count = 3
seq_step = 1
[148.148815] (kms_flip:3752) DEBUG: Vblank took 49us
[148.165421] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.677490
last_received_ts = 149.676788
last_seq = 46
current_ts = 149.694138
current_received_ts = 149.693451
current_seq = 47
count = 4
seq_step = 1
[148.165475] (kms_flip:3752) DEBUG: Vblank took 49us
[148.182060] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.694138
last_received_ts = 149.693451
last_seq = 47
current_ts = 149.710815
current_received_ts = 149.710098
current_seq = 48
count = 5
seq_step = 1
[148.182109] (kms_flip:3752) DEBUG: Vblank took 46us
[148.198771] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.710815
last_received_ts = 149.710098
last_seq = 48
current_ts = 149.727478
current_received_ts = 149.726807
current_seq = 49
count = 6
seq_step = 1
[148.198824] (kms_flip:3752) DEBUG: Vblank took 49us
[148.215407] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.727478
last_received_ts = 149.726807
last_seq = 49
current_ts = 149.744141
current_received_ts = 149.743439
current_seq = 50
count = 7
seq_step = 1
[148.215456] (kms_flip:3752) DEBUG: Vblank took 46us
[148.232057] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.744141
last_received_ts = 149.743439
last_seq = 50
current_ts = 149.760803
current_received_ts = 149.760101
current_seq = 51
count = 8
seq_step = 1
[148.232114] (kms_flip:3752) DEBUG: Vblank took 54us
[148.248715] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.760803
last_received_ts = 149.760101
last_seq = 51
current_ts = 149.777466
current_received_ts = 149.776749
current_seq = 52
count = 9
seq_step = 1
[148.248768] (kms_flip:3752) DEBUG: Vblank took 50us
[148.265403] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.777466
last_received_ts = 149.776749
last_seq = 52
current_ts = 149.794144
current_received_ts = 149.793442
current_seq = 53
count = 10
seq_step = 1
[148.265445] (kms_flip:3752) DEBUG: Vblank took 39us
[148.282047] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.794144
last_received_ts = 149.793442
last_seq = 53
current_ts = 149.810806
current_received_ts = 149.810089
current_seq = 54
count = 11
seq_step = 1
[148.282094] (kms_flip:3752) DEBUG: Vblank took 44us
[148.298727] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.810806
last_received_ts = 149.810089
last_seq = 54
current_ts = 149.827469
current_received_ts = 149.826767
current_seq = 55
count = 12
seq_step = 1
[148.298774] (kms_flip:3752) DEBUG: Vblank took 44us
[148.315380] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.827469
last_received_ts = 149.826767
last_seq = 55
current_ts = 149.844131
current_received_ts = 149.843430
current_seq = 56
count = 13
seq_step = 1
[148.315435] (kms_flip:3752) DEBUG: Vblank took 52us
[148.332056] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.844131
last_received_ts = 149.843430
last_seq = 56
current_ts = 149.860794
current_received_ts = 149.860107
current_seq = 57
count = 14
seq_step = 1
[148.332107] (kms_flip:3752) DEBUG: Vblank took 49us
[148.348721] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.860794
last_received_ts = 149.860107
last_seq = 57
current_ts = 149.877457
current_received_ts = 149.876770
current_seq = 58
count = 15
seq_step = 1
[148.348771] (kms_flip:3752) DEBUG: Vblank took 47us
[148.365376] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.877457
last_received_ts = 149.876770
last_seq = 58
current_ts = 149.894119
current_received_ts = 149.893417
current_seq = 59
count = 16
seq_step = 1
[148.365421] (kms_flip:3752) DEBUG: Vblank took 44us
[148.382043] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.894119
last_received_ts = 149.893417
last_seq = 59
current_ts = 149.910797
current_received_ts = 149.910095
current_seq = 60
count = 17
seq_step = 1
[148.382093] (kms_flip:3752) DEBUG: Vblank took 47us
[148.398731] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.910797
last_received_ts = 149.910095
last_seq = 60
current_ts = 149.927460
current_received_ts = 149.926773
current_seq = 61
count = 18
seq_step = 1
[148.398792] (kms_flip:3752) DEBUG: Vblank took 59us
[148.415348] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.927460
last_received_ts = 149.926773
last_seq = 61
current_ts = 149.944122
current_received_ts = 149.943405
current_seq = 62
count = 19
seq_step = 1
[148.415393] (kms_flip:3752) DEBUG: Vblank took 42us
[148.432015] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.944122
last_received_ts = 149.943405
last_seq = 62
current_ts = 149.960785
current_received_ts = 149.960068
current_seq = 63
count = 20
seq_step = 1
[148.432060] (kms_flip:3752) DEBUG: Vblank took 43us
[148.448716] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.960785
last_received_ts = 149.960068
last_seq = 63
current_ts = 149.977448
current_received_ts = 149.976761
current_seq = 64
count = 21
seq_step = 1
[148.448762] (kms_flip:3752) DEBUG: Vblank took 43us
[148.465371] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.977448
last_received_ts = 149.976761
last_seq = 64
current_ts = 149.994125
current_received_ts = 149.993423
current_seq = 65
count = 22
seq_step = 1
[148.465415] (kms_flip:3752) DEBUG: Vblank took 43us
[148.483134] (kms_flip:3752) DEBUG: name = flip
last_ts = 149.994125
last_received_ts = 149.993423
last_seq = 65
current_ts = 150.010773
current_received_ts = 150.011185
current_seq = 66
count = 23
seq_step = 1
[148.483203] (kms_flip:3752) DEBUG: Vblank took 65us
[148.498606] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.010773
last_received_ts = 150.011185
last_seq = 66
current_ts = 150.027451
current_received_ts = 150.026657
current_seq = 67
count = 24
seq_step = 1
[148.498664] (kms_flip:3752) DEBUG: Vblank took 55us
[148.515235] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.027451
last_received_ts = 150.026657
last_seq = 67
current_ts = 150.044113
current_received_ts = 150.043289
current_seq = 68
count = 25
seq_step = 1
[148.515286] (kms_flip:3752) DEBUG: Vblank took 48us
[148.532040] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.044113
last_received_ts = 150.043289
last_seq = 68
current_ts = 150.060776
current_received_ts = 150.060089
current_seq = 69
count = 26
seq_step = 1
[148.532098] (kms_flip:3752) DEBUG: Vblank took 55us
[148.548657] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.060776
last_received_ts = 150.060089
last_seq = 69
current_ts = 150.077454
current_received_ts = 150.076721
current_seq = 70
count = 27
seq_step = 1
[148.548703] (kms_flip:3752) DEBUG: Vblank took 43us
[148.565315] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.077454
last_received_ts = 150.076721
last_seq = 70
current_ts = 150.094101
current_received_ts = 150.093369
current_seq = 71
count = 28
seq_step = 1
[148.565359] (kms_flip:3752) DEBUG: Vblank took 43us
[148.582008] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.094101
last_received_ts = 150.093369
last_seq = 71
current_ts = 150.110764
current_received_ts = 150.110062
current_seq = 72
count = 29
seq_step = 1
[148.582059] (kms_flip:3752) DEBUG: Vblank took 48us
[148.598686] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.110764
last_received_ts = 150.110062
last_seq = 72
current_ts = 150.127441
current_received_ts = 150.126740
current_seq = 73
count = 30
seq_step = 1
[148.598735] (kms_flip:3752) DEBUG: Vblank took 47us
[148.615330] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.127441
last_received_ts = 150.126740
last_seq = 73
current_ts = 150.144104
current_received_ts = 150.143387
current_seq = 74
count = 31
seq_step = 1
[148.615387] (kms_flip:3752) DEBUG: Vblank took 54us
[148.631997] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.144104
last_received_ts = 150.143387
last_seq = 74
current_ts = 150.160767
current_received_ts = 150.160065
current_seq = 75
count = 32
seq_step = 1
[148.632042] (kms_flip:3752) DEBUG: Vblank took 42us
[148.648690] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.160767
last_received_ts = 150.160065
last_seq = 75
current_ts = 150.177429
current_received_ts = 150.176758
current_seq = 76
count = 33
seq_step = 1
[148.648740] (kms_flip:3752) DEBUG: Vblank took 47us
[148.665297] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.177429
last_received_ts = 150.176758
last_seq = 76
current_ts = 150.194107
current_received_ts = 150.193359
current_seq = 77
count = 34
seq_step = 1
[148.665343] (kms_flip:3752) DEBUG: Vblank took 43us
[148.681986] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.194107
last_received_ts = 150.193359
last_seq = 77
current_ts = 150.210754
current_received_ts = 150.210052
current_seq = 78
count = 35
seq_step = 1
[148.682035] (kms_flip:3752) DEBUG: Vblank took 47us
[148.698674] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.210754
last_received_ts = 150.210052
last_seq = 78
current_ts = 150.227432
current_received_ts = 150.226746
current_seq = 79
count = 36
seq_step = 1
[148.698719] (kms_flip:3752) DEBUG: Vblank took 43us
[148.715288] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.227432
last_received_ts = 150.226746
last_seq = 79
current_ts = 150.244095
current_received_ts = 150.243362
current_seq = 80
count = 37
seq_step = 1
[148.715332] (kms_flip:3752) DEBUG: Vblank took 39us
[148.731987] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.244095
last_received_ts = 150.243362
last_seq = 80
current_ts = 150.260757
current_received_ts = 150.260056
current_seq = 81
count = 38
seq_step = 1
[148.732062] (kms_flip:3752) DEBUG: Vblank took 72us
[148.748656] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.260757
last_received_ts = 150.260056
last_seq = 81
current_ts = 150.277420
current_received_ts = 150.276703
current_seq = 82
count = 39
seq_step = 1
[148.748796] (kms_flip:3752) DEBUG: Vblank took 125us
[148.765312] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.277420
last_received_ts = 150.276703
last_seq = 82
current_ts = 150.294083
current_received_ts = 150.293365
current_seq = 83
count = 40
seq_step = 1
[148.765382] (kms_flip:3752) DEBUG: Vblank took 62us
[148.781997] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.294083
last_received_ts = 150.293365
last_seq = 83
current_ts = 150.310760
current_received_ts = 150.310059
current_seq = 84
count = 41
seq_step = 1
[148.782079] (kms_flip:3752) DEBUG: Vblank took 74us
[148.798670] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.310760
last_received_ts = 150.310059
last_seq = 84
current_ts = 150.327423
current_received_ts = 150.326736
current_seq = 85
count = 42
seq_step = 1
[148.798731] (kms_flip:3752) DEBUG: Vblank took 57us
[148.815329] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.327423
last_received_ts = 150.326736
last_seq = 85
current_ts = 150.344086
current_received_ts = 150.343399
current_seq = 86
count = 43
seq_step = 1
[148.815390] (kms_flip:3752) DEBUG: Vblank took 56us
[148.831980] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.344086
last_received_ts = 150.343399
last_seq = 86
current_ts = 150.360748
current_received_ts = 150.360046
current_seq = 87
count = 44
seq_step = 1
[148.832037] (kms_flip:3752) DEBUG: Vblank took 53us
[148.848661] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.360748
last_received_ts = 150.360046
last_seq = 87
current_ts = 150.377411
current_received_ts = 150.376740
current_seq = 88
count = 45
seq_step = 1
[148.848714] (kms_flip:3752) DEBUG: Vblank took 49us
[148.865188] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.377411
last_received_ts = 150.376740
last_seq = 88
current_ts = 150.394073
current_received_ts = 150.393265
current_seq = 89
count = 46
seq_step = 1
[148.865234] (kms_flip:3752) DEBUG: Vblank took 44us
[148.881983] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.394073
last_received_ts = 150.393265
last_seq = 89
current_ts = 150.410736
current_received_ts = 150.410065
current_seq = 90
count = 47
seq_step = 1
[148.882045] (kms_flip:3752) DEBUG: Vblank took 57us
[148.898653] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.410736
last_received_ts = 150.410065
last_seq = 90
current_ts = 150.427399
current_received_ts = 150.426727
current_seq = 91
count = 48
seq_step = 1
[148.898716] (kms_flip:3752) DEBUG: Vblank took 60us
[148.915334] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.427399
last_received_ts = 150.426727
last_seq = 91
current_ts = 150.444077
current_received_ts = 150.443405
current_seq = 92
count = 49
seq_step = 1
[148.915402] (kms_flip:3752) DEBUG: Vblank took 63us
[148.931972] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.444077
last_received_ts = 150.443405
last_seq = 92
current_ts = 150.460739
current_received_ts = 150.460052
current_seq = 93
count = 50
seq_step = 1
[148.932024] (kms_flip:3752) DEBUG: Vblank took 49us
[148.948659] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.460739
last_received_ts = 150.460052
last_seq = 93
current_ts = 150.477402
current_received_ts = 150.476746
current_seq = 94
count = 51
seq_step = 1
[148.948714] (kms_flip:3752) DEBUG: Vblank took 53us
[148.965294] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.477402
last_received_ts = 150.476746
last_seq = 94
current_ts = 150.494064
current_received_ts = 150.493378
current_seq = 95
count = 52
seq_step = 1
[148.965344] (kms_flip:3752) DEBUG: Vblank took 48us
[148.981975] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.494064
last_received_ts = 150.493378
last_seq = 95
current_ts = 150.510742
current_received_ts = 150.510056
current_seq = 96
count = 53
seq_step = 1
[148.982038] (kms_flip:3752) DEBUG: Vblank took 59us
[148.998640] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.510742
last_received_ts = 150.510056
last_seq = 96
current_ts = 150.527390
current_received_ts = 150.526718
current_seq = 97
count = 54
seq_step = 1
[148.998694] (kms_flip:3752) DEBUG: Vblank took 51us
[149.015240] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.527390
last_received_ts = 150.526718
last_seq = 97
current_ts = 150.544067
current_received_ts = 150.543320
current_seq = 98
count = 55
seq_step = 1
[149.015299] (kms_flip:3752) DEBUG: Vblank took 55us
[149.031946] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.544067
last_received_ts = 150.543320
last_seq = 98
current_ts = 150.560730
current_received_ts = 150.560028
current_seq = 99
count = 56
seq_step = 1
[149.031997] (kms_flip:3752) DEBUG: Vblank took 48us
[149.048613] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.560730
last_received_ts = 150.560028
last_seq = 99
current_ts = 150.577393
current_received_ts = 150.576706
current_seq = 100
count = 57
seq_step = 1
[149.048691] (kms_flip:3752) DEBUG: Vblank took 73us
[149.065280] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.577393
last_received_ts = 150.576706
last_seq = 100
current_ts = 150.594055
current_received_ts = 150.593369
current_seq = 101
count = 58
seq_step = 1
[149.065331] (kms_flip:3752) DEBUG: Vblank took 48us
[149.081957] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.594055
last_received_ts = 150.593369
last_seq = 101
current_ts = 150.610718
current_received_ts = 150.610046
current_seq = 102
count = 59
seq_step = 1
[149.082014] (kms_flip:3752) DEBUG: Vblank took 52us
[149.098645] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.610718
last_received_ts = 150.610046
last_seq = 102
current_ts = 150.627380
current_received_ts = 150.626740
current_seq = 103
count = 60
seq_step = 1
[149.098708] (kms_flip:3752) DEBUG: Vblank took 60us
[149.115273] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.627380
last_received_ts = 150.626740
last_seq = 103
current_ts = 150.644058
current_received_ts = 150.643372
current_seq = 104
count = 61
seq_step = 1
[149.115330] (kms_flip:3752) DEBUG: Vblank took 54us
[149.131950] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.644058
last_received_ts = 150.643372
last_seq = 104
current_ts = 150.660721
current_received_ts = 150.660034
current_seq = 105
count = 62
seq_step = 1
[149.131992] (kms_flip:3752) DEBUG: Vblank took 39us
[149.148598] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.660721
last_received_ts = 150.660034
last_seq = 105
current_ts = 150.677383
current_received_ts = 150.676697
current_seq = 106
count = 63
seq_step = 1
[149.148647] (kms_flip:3752) DEBUG: Vblank took 46us
[149.165259] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.677383
last_received_ts = 150.676697
last_seq = 106
current_ts = 150.694046
current_received_ts = 150.693359
current_seq = 107
count = 64
seq_step = 1
[149.165304] (kms_flip:3752) DEBUG: Vblank took 43us
[149.181885] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.694046
last_received_ts = 150.693359
last_seq = 107
current_ts = 150.710709
current_received_ts = 150.709976
current_seq = 108
count = 65
seq_step = 1
[149.181944] (kms_flip:3752) DEBUG: Vblank took 57us
[149.198584] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.710709
last_received_ts = 150.709976
last_seq = 108
current_ts = 150.727371
current_received_ts = 150.726685
current_seq = 109
count = 66
seq_step = 1
[149.198633] (kms_flip:3752) DEBUG: Vblank took 47us
[149.215147] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.727371
last_received_ts = 150.726685
last_seq = 109
current_ts = 150.744049
current_received_ts = 150.743240
current_seq = 110
count = 67
seq_step = 1
[149.215186] (kms_flip:3752) DEBUG: Vblank took 35us
[149.231823] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.744049
last_received_ts = 150.743240
last_seq = 110
current_ts = 150.760712
current_received_ts = 150.759918
current_seq = 111
count = 68
seq_step = 1
[149.231875] (kms_flip:3752) DEBUG: Vblank took 50us
[149.248471] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.760712
last_received_ts = 150.759918
last_seq = 111
current_ts = 150.777374
current_received_ts = 150.776566
current_seq = 112
count = 69
seq_step = 1
[149.248529] (kms_flip:3752) DEBUG: Vblank took 55us
[149.265125] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.777374
last_received_ts = 150.776566
last_seq = 112
current_ts = 150.794037
current_received_ts = 150.793228
current_seq = 113
count = 70
seq_step = 1
[149.265182] (kms_flip:3752) DEBUG: Vblank took 54us
[149.281931] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.794037
last_received_ts = 150.793228
last_seq = 113
current_ts = 150.810699
current_received_ts = 150.810028
current_seq = 114
count = 71
seq_step = 1
[149.281973] (kms_flip:3752) DEBUG: Vblank took 37us
[149.298578] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.810699
last_received_ts = 150.810028
last_seq = 114
current_ts = 150.827377
current_received_ts = 150.826675
current_seq = 115
count = 72
seq_step = 1
[149.298640] (kms_flip:3752) DEBUG: Vblank took 56us
[149.315237] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.827377
last_received_ts = 150.826675
last_seq = 115
current_ts = 150.844025
current_received_ts = 150.843338
current_seq = 116
count = 73
seq_step = 1
[149.315287] (kms_flip:3752) DEBUG: Vblank took 47us
[149.331909] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.844025
last_received_ts = 150.843338
last_seq = 116
current_ts = 150.860703
current_received_ts = 150.860016
current_seq = 117
count = 74
seq_step = 1
[149.331966] (kms_flip:3752) DEBUG: Vblank took 53us
[149.348541] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.860703
last_received_ts = 150.860016
last_seq = 117
current_ts = 150.877365
current_received_ts = 150.876648
current_seq = 118
count = 75
seq_step = 1
[149.348592] (kms_flip:3752) DEBUG: Vblank took 48us
[149.365224] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.877365
last_received_ts = 150.876648
last_seq = 118
current_ts = 150.894028
current_received_ts = 150.893326
current_seq = 119
count = 76
seq_step = 1
[149.365296] (kms_flip:3752) DEBUG: Vblank took 69us
[149.381905] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.894028
last_received_ts = 150.893326
last_seq = 119
current_ts = 150.910690
current_received_ts = 150.910019
current_seq = 120
count = 77
seq_step = 1
[149.381954] (kms_flip:3752) DEBUG: Vblank took 47us
[149.398562] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.910690
last_received_ts = 150.910019
last_seq = 120
current_ts = 150.927353
current_received_ts = 150.926666
current_seq = 121
count = 78
seq_step = 1
[149.398612] (kms_flip:3752) DEBUG: Vblank took 48us
[149.415228] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.927353
last_received_ts = 150.926666
last_seq = 121
current_ts = 150.944031
current_received_ts = 150.943344
current_seq = 122
count = 79
seq_step = 1
[149.415282] (kms_flip:3752) DEBUG: Vblank took 50us
[149.431892] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.944031
last_received_ts = 150.943344
last_seq = 122
current_ts = 150.960693
current_received_ts = 150.959991
current_seq = 123
count = 80
seq_step = 1
[149.431944] (kms_flip:3752) DEBUG: Vblank took 48us
[149.448448] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.960693
last_received_ts = 150.959991
last_seq = 123
current_ts = 150.977356
current_received_ts = 150.976562
current_seq = 124
count = 81
seq_step = 1
[149.448503] (kms_flip:3752) DEBUG: Vblank took 52us
[149.465200] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.977356
last_received_ts = 150.976562
last_seq = 124
current_ts = 150.994019
current_received_ts = 150.993317
current_seq = 125
count = 82
seq_step = 1
[149.465257] (kms_flip:3752) DEBUG: Vblank took 53us
[149.481904] (kms_flip:3752) DEBUG: name = flip
last_ts = 150.994019
last_received_ts = 150.993317
last_seq = 125
current_ts = 151.010681
current_received_ts = 151.010010
current_seq = 126
count = 83
seq_step = 1
[149.481946] (kms_flip:3752) DEBUG: Vblank took 39us
[149.498554] (kms_flip:3752) DEBUG: name = flip
last_ts = 151.010681
last_received_ts = 151.010010
last_seq = 126
current_ts = 151.027344
current_received_ts = 151.026672
current_seq = 127
count = 84
seq_step = 1
[149.498615] (kms_flip:3752) DEBUG: Vblank took 58us
[149.515147] (kms_flip:3752) DEBUG: name = flip
last_ts = 151.027344
last_received_ts = 151.026672
last_seq = 127
current_ts = 151.044022
current_received_ts = 151.043259
current_seq = 128
count = 85
seq_step = 1
[149.515218] (kms_flip:3752) DEBUG: Vblank took 68us
[149.531898] (kms_flip:3752) DEBUG: name = flip
last_ts = 151.044022
last_received_ts = 151.043259
last_seq = 128
current_ts = 151.060684
current_received_ts = 151.060013
current_seq = 129
count = 86
seq_step = 1
[149.531953] (kms_flip:3752) DEBUG: Vblank took 52us
[149.548570] (kms_flip:3752) DEBUG: name = flip
last_ts = 151.060684
last_received_ts = 151.060013
last_seq = 129
current_ts = 151.077347
current_received_ts = 151.076691
current_seq = 130
count = 87
seq_step = 1
[149.548630] (kms_flip:3752) DEBUG: Vblank took 56us
[149.565182] (kms_flip:3752) DEBUG: name = flip
last_ts = 151.077347
last_received_ts = 151.076691
last_seq = 130
current_ts = 151.094009
current_received_ts = 151.093307
current_seq = 131
count = 88
seq_step = 1
[149.565231] (kms_flip:3752) DEBUG: Vblank took 46us
[149.581859] (kms_flip:3752) DEBUG: name = flip
last_ts = 151.094009
last_received_ts = 151.093307
last_seq = 131
current_ts = 151.110672
current_received_ts = 151.109985
current_seq = 132
count = 89
seq_step = 1
[149.581919] (kms_flip:3752) DEBUG: Vblank took 58us
[149.598548] (kms_flip:3752) DEBUG: name = flip
last_ts = 151.110672
last_received_ts = 151.109985
last_seq = 132
current_ts = 151.127335
current_received_ts = 151.126663
current_seq = 133
count = 90
seq_step = 1
[149.598598] (kms_flip:3752) DEBUG: Vblank took 48us
[149.615170] (kms_flip:3752) DEBUG: name = flip
last_ts = 151.127335
last_received_ts = 151.126663
last_seq = 133
current_ts = 151.143997
current_received_ts = 151.143295
current_seq = 134
count = 91
seq_step = 1
[149.615221] (kms_flip:3752) DEBUG: Vblank took 49us
[149.631869] (kms_flip:3752) DEBUG: name = flip
last_ts = 151.143997
last_received_ts = 151.143295
last_seq = 134
current_ts = 151.160660
current_received_ts = 151.159988
current_seq = 135
count = 92
seq_step = 1
[149.631938] (kms_flip:3752) DEBUG: Vblank took 67us
[149.648526] (kms_flip:3752) DEBUG: name = flip
last_ts = 151.160660
last_received_ts = 151.159988
last_seq = 135
current_ts = 151.177322
current_received_ts = 151.176651
current_seq = 136
count = 93
seq_step = 1
[149.648578] (kms_flip:3752) DEBUG: Vblank took 50us
[149.665189] (kms_flip:3752) DEBUG: name = flip
last_ts = 151.177322
last_received_ts = 151.176651
last_seq = 136
current_ts = 151.194000
current_received_ts = 151.193314
current_seq = 137
count = 94
seq_step = 1
[149.665241] (kms_flip:3752) DEBUG: Vblank took 49us
[149.681847] (kms_flip:3752) DEBUG: name = flip
last_ts = 151.194000
last_received_ts = 151.193314
last_seq = 137
current_ts = 151.210663
current_received_ts = 151.209976
current_seq = 138
count = 95
seq_step = 1
[149.681907] (kms_flip:3752) DEBUG: Vblank took 57us
[149.698521] (kms_flip:3752) DEBUG: name = flip
last_ts = 151.210663
last_received_ts = 151.209976
last_seq = 138
current_ts = 151.227325
current_received_ts = 151.226654
current_seq = 139
count = 96
seq_step = 1
[149.698573] (kms_flip:3752) DEBUG: Vblank took 50us
[149.715146] (kms_flip:3752) DEBUG: name = flip
last_ts = 151.227325
last_received_ts = 151.226654
last_seq = 139
current_ts = 151.244003
current_received_ts = 151.243271
current_seq = 140
count = 97
seq_step = 1
[149.715196] (kms_flip:3752) DEBUG: Vblank took 46us
[149.731846] (kms_flip:3752) DEBUG: name = flip
last_ts = 151.244003
last_received_ts = 151.243271
last_seq = 140
current_ts = 151.260666
current_received_ts = 151.259979
current_seq = 141
count = 98
seq_step = 1
[149.731894] (kms_flip:3752) DEBUG: Vblank took 45us
[149.748525] (kms_flip:3752) DEBUG: name = flip
last_ts = 151.260666
last_received_ts = 151.259979
last_seq = 141
current_ts = 151.277313
current_received_ts = 151.276657
current_seq = 142
count = 99
seq_step = 1
[149.748577] (kms_flip:3752) DEBUG: Vblank took 49us
[149.765118] (kms_flip:3752) DEBUG: name = flip
last_ts = 151.277313
last_received_ts = 151.276657
last_seq = 142
current_ts = 151.293991
current_received_ts = 151.293243
current_seq = 143
count = 100
seq_step = 1
[149.765173] (kms_flip:3752) DEBUG: Vblank took 52us
[149.781829] (kms_flip:3752) DEBUG: name = flip
last_ts = 151.293991
last_received_ts = 151.293243
last_seq = 143
current_ts = 151.310654
current_received_ts = 151.309952
current_seq = 144
count = 101
seq_step = 1
[149.782813] (kms_flip:3752) DEBUG: Vblank took 968us
[149.782832] (kms_flip:3752) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[149.783067] (kms_flip:3752) CRITICAL: Failed assertion: end - start < 500
[149.783118] (kms_flip:3752) CRITICAL: Last errno: 4, Interrupted system call
[149.786559] (kms_flip:3752) igt_core-INFO: Stack trace:
[149.789948] (kms_flip:3752) igt_core-INFO:   #0 ../lib/igt_core.c:2106 __igt_fail_assert()
[149.791630] (kms_flip:3752) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[149.791680] (kms_flip:3752) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[149.791718] (kms_flip:3752) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
[149.791754] (kms_flip:3752) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[149.795140] (kms_flip:3752) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[149.797099] (kms_flip:3752) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[149.797550] (kms_flip:3752) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (2.993s)

Dmesg

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

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

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

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

<7> [148.630058] 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> [148.630211] 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> [148.630325] 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> [148.630426] 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> [148.630523] 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> [148.630619] 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> [148.630713] 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> [148.630805] 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> [148.630897] 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> [148.631000] 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> [148.631118] 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> [148.631233] 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> [148.631334] 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> [148.631433] 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> [148.631533] 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> [148.631631] 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> [148.631726] 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> [148.631820] 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> [148.631912] 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> [148.632020] 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> [148.632129] 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> [148.632237] 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> [148.632331] 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> [148.632419] 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> [148.632506] 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> [148.632593] 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> [148.632679] 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> [148.632765] 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> [148.632850] 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> [148.632936] 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> [148.633101] 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> [148.633225] 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> [148.633335] 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> [148.633427] 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> [148.633514] 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> [148.633601] 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> [148.633687] 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> [148.633772] 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> [148.633859] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset

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

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

<7> [148.634185] 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> [148.634298] 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> [148.634371] 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> [148.634435] 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> [148.634498] 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> [148.634560] 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> [148.634622] 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> [148.634701] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [148.856734] 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> [148.857176] 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> [148.909396] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [148.927942] 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> [148.928478] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A]

<7> [148.928834] 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> [148.929302] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

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

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

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

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

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

<7> [148.931700] 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> [148.932123] 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> [148.932456] 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> [148.932819] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0

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

<7> [148.933509] 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> [148.933811] 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> [148.934115] 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> [148.934416] 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> [148.934673] 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> [148.934931] 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> [148.935200] 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> [148.935458] 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> [148.935678] 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> [148.935907] 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> [148.936171] 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> [148.936372] 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> [148.936556] 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> [148.936738] 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> [148.936914] 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> [148.937104] 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> [148.937296] 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> [148.937457] 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> [148.937617] 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> [148.937769] 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> [148.937923] 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> [148.938088] 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> [148.938230] 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> [148.938367] 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> [148.938501] 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> [148.938636] 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> [148.938775] 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> [148.938909] 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> [148.939049] 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> [148.939171] 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> [148.939287] 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> [148.939403] 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> [148.939518] 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> [148.939543] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010

<7> [148.939636] 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> [148.939688] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long

<7> [148.939757] 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> [148.939818] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10

<7> [148.939878] 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> [148.939947] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A]

<7> [148.940001] 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> [148.940113] 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> [148.940221] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] fastset requirement not met, forcing full modeset

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

<7> [148.940453] 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> [148.940577] 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> [148.940664] 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> [148.940736] 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> [148.940809] 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> [148.940882] 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> [148.940961] 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> [148.941056] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:270:pipe B] data rate 1390840 num active planes 1

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [148.943089] 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> [148.943196] 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> [148.943299] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

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

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

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

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

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

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

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

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

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

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

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

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

<7> [148.944516] 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> [148.944603] 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> [148.944698] 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> [148.944798] 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> [148.944898] 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> [148.945002] 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> [148.945105] 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> [148.945203] 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> [148.945300] 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> [148.945391] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0

<7> [148.945482] 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> [148.945561] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0

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

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

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

<7> [148.945886] 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> [148.945965] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no,

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [148.947839] 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> [148.947915] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0

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

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

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

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

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

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

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

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

<7> [148.949109] 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> [148.949245] 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> [148.949362] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [149.424265] 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> [149.525836] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

<7> [149.526443] 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> [149.526872] 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> [149.562789] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010

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

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

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

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

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

<7> [149.741513] 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> [149.743564] 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> [149.745139] 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> [149.746082] 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> [149.747315] 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> [149.748817] 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> [149.749988] 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> [149.750419] 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> [149.751945] 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> [149.752365] 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> [149.753216] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B

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

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

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

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

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

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

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

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

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

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

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