igt@kms_flip@flip-vs-expired-vblank-interruptible@c-dp2 on shard-bmg@IGTPW

Detail	Value
Duration	2.82 seconds
Hostname	shard-bmg-10
Igt-Version	IGT-Version: 2.3-gf57041a8e (x86_64) (Linux: 7.0.0-rc5-lgci-xe-xe-4769-0c7d9ab970be1e932-debug+ x86_64)
Out	Starting dynamic subtest: C-DP2 1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1891 run_test() #3 ../tests/kms_flip.c:2162 __igt_unique____real_main2047() #4 ../tests/kms_flip.c:2047 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest C-DP2: FAIL (2.821s)
Err	Starting dynamic subtest: C-DP2 (kms_flip:3397) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930: (kms_flip:3397) CRITICAL: Failed assertion: end - start < 500 (kms_flip:3397) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest C-DP2 failed. ** DEBUG (kms_flip:3397) intel_allocator_simple-DEBUG: Using simple allocator (kms_flip:3397) intel_allocator_simple-DEBUG: <ial: 0x558cbec34d40, fd: 5> objects: 3, reserved_areas: 0 (kms_flip:3397) intel_allocator_simple-DEBUG: <ial: 0x558cbec34d40, fd: 5> objects: 3, reserved_areas: 0 (kms_flip:3397) igt_kms-INFO: 1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 (kms_flip:3397) DEBUG: No stale events found (kms_flip:3397) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0 (kms_flip:3397) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0 (kms_flip:3397) DEBUG: name = flip last_ts = 0.000000 last_received_ts = 0.000000 last_seq = 0 current_ts = 119.175880 current_received_ts = 119.175491 current_seq = 5 count = 0 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 29us (kms_flip:3397) DEBUG: name = flip last_ts = 119.175880 last_received_ts = 119.175491 last_seq = 5 current_ts = 119.192551 current_received_ts = 119.192108 current_seq = 6 count = 1 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.192551 last_received_ts = 119.192108 last_seq = 6 current_ts = 119.209213 current_received_ts = 119.208847 current_seq = 7 count = 2 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 25us (kms_flip:3397) DEBUG: name = flip last_ts = 119.209213 last_received_ts = 119.208847 last_seq = 7 current_ts = 119.225883 current_received_ts = 119.225441 current_seq = 8 count = 3 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.225883 last_received_ts = 119.225441 last_seq = 8 current_ts = 119.242554 current_received_ts = 119.242111 current_seq = 9 count = 4 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 25us (kms_flip:3397) DEBUG: name = flip last_ts = 119.242554 last_received_ts = 119.242111 last_seq = 9 current_ts = 119.259224 current_received_ts = 119.258774 current_seq = 10 count = 5 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.259224 last_received_ts = 119.258774 last_seq = 10 current_ts = 119.275894 current_received_ts = 119.275520 current_seq = 11 count = 6 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 27us (kms_flip:3397) DEBUG: name = flip last_ts = 119.275894 last_received_ts = 119.275520 last_seq = 11 current_ts = 119.292557 current_received_ts = 119.292091 current_seq = 12 count = 7 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.292557 last_received_ts = 119.292091 last_seq = 12 current_ts = 119.309235 current_received_ts = 119.308784 current_seq = 13 count = 8 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 25us (kms_flip:3397) DEBUG: name = flip last_ts = 119.309235 last_received_ts = 119.308784 last_seq = 13 current_ts = 119.325905 current_received_ts = 119.325531 current_seq = 14 count = 9 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.325905 last_received_ts = 119.325531 last_seq = 14 current_ts = 119.342575 current_received_ts = 119.342087 current_seq = 15 count = 10 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.342575 last_received_ts = 119.342087 last_seq = 15 current_ts = 119.359238 current_received_ts = 119.358788 current_seq = 16 count = 11 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.359238 last_received_ts = 119.358788 last_seq = 16 current_ts = 119.375908 current_received_ts = 119.375534 current_seq = 17 count = 12 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.375908 last_received_ts = 119.375534 last_seq = 17 current_ts = 119.392578 current_received_ts = 119.392128 current_seq = 18 count = 13 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.392578 last_received_ts = 119.392128 last_seq = 18 current_ts = 119.409241 current_received_ts = 119.408875 current_seq = 19 count = 14 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.409241 last_received_ts = 119.408875 last_seq = 19 current_ts = 119.425919 current_received_ts = 119.425468 current_seq = 20 count = 15 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.425919 last_received_ts = 119.425468 last_seq = 20 current_ts = 119.442581 current_received_ts = 119.442207 current_seq = 21 count = 16 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 25us (kms_flip:3397) DEBUG: name = flip last_ts = 119.442581 last_received_ts = 119.442207 last_seq = 21 current_ts = 119.459251 current_received_ts = 119.458878 current_seq = 22 count = 17 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 25us (kms_flip:3397) DEBUG: name = flip last_ts = 119.459251 last_received_ts = 119.458878 last_seq = 22 current_ts = 119.475922 current_received_ts = 119.475471 current_seq = 23 count = 18 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.475922 last_received_ts = 119.475471 last_seq = 23 current_ts = 119.492584 current_received_ts = 119.492210 current_seq = 24 count = 19 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.492584 last_received_ts = 119.492210 last_seq = 24 current_ts = 119.509254 current_received_ts = 119.508812 current_seq = 25 count = 20 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.509254 last_received_ts = 119.508812 last_seq = 25 current_ts = 119.525932 current_received_ts = 119.525558 current_seq = 26 count = 21 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.525932 last_received_ts = 119.525558 last_seq = 26 current_ts = 119.542595 current_received_ts = 119.542145 current_seq = 27 count = 22 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 24us (kms_flip:3397) DEBUG: name = flip last_ts = 119.542595 last_received_ts = 119.542145 last_seq = 27 current_ts = 119.559265 current_received_ts = 119.558815 current_seq = 28 count = 23 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.559265 last_received_ts = 119.558815 last_seq = 28 current_ts = 119.575935 current_received_ts = 119.575562 current_seq = 29 count = 24 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 27us (kms_flip:3397) DEBUG: name = flip last_ts = 119.575935 last_received_ts = 119.575562 last_seq = 29 current_ts = 119.592606 current_received_ts = 119.592155 current_seq = 30 count = 25 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.592606 last_received_ts = 119.592155 last_seq = 30 current_ts = 119.609268 current_received_ts = 119.608826 current_seq = 31 count = 26 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.609268 last_received_ts = 119.608826 last_seq = 31 current_ts = 119.625938 current_received_ts = 119.625572 current_seq = 32 count = 27 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.625938 last_received_ts = 119.625572 last_seq = 32 current_ts = 119.642609 current_received_ts = 119.642166 current_seq = 33 count = 28 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.642609 last_received_ts = 119.642166 last_seq = 33 current_ts = 119.659279 current_received_ts = 119.658829 current_seq = 34 count = 29 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.659279 last_received_ts = 119.658829 last_seq = 34 current_ts = 119.675949 current_received_ts = 119.675575 current_seq = 35 count = 30 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 25us (kms_flip:3397) DEBUG: name = flip last_ts = 119.675949 last_received_ts = 119.675575 last_seq = 35 current_ts = 119.692619 current_received_ts = 119.692245 current_seq = 36 count = 31 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.692619 last_received_ts = 119.692245 last_seq = 36 current_ts = 119.709282 current_received_ts = 119.708839 current_seq = 37 count = 32 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 25us (kms_flip:3397) DEBUG: name = flip last_ts = 119.709282 last_received_ts = 119.708839 last_seq = 37 current_ts = 119.725952 current_received_ts = 119.725578 current_seq = 38 count = 33 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 119.725952 last_received_ts = 119.725578 last_seq = 38 current_ts = 119.742622 current_received_ts = 119.742172 current_seq = 39 count = 34 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 243us (kms_flip:3397) DEBUG: name = flip last_ts = 119.742622 last_received_ts = 119.742172 last_seq = 39 current_ts = 119.759300 current_received_ts = 119.758919 current_seq = 40 count = 35 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 254us (kms_flip:3397) DEBUG: name = flip last_ts = 119.759300 last_received_ts = 119.758919 last_seq = 40 current_ts = 119.775955 current_received_ts = 119.775581 current_seq = 41 count = 36 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 238us (kms_flip:3397) DEBUG: name = flip last_ts = 119.775955 last_received_ts = 119.775581 last_seq = 41 current_ts = 119.792633 current_received_ts = 119.792252 current_seq = 42 count = 37 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 238us (kms_flip:3397) DEBUG: name = flip last_ts = 119.792633 last_received_ts = 119.792252 last_seq = 42 current_ts = 119.809303 current_received_ts = 119.808929 current_seq = 43 count = 38 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 257us (kms_flip:3397) DEBUG: name = flip last_ts = 119.809303 last_received_ts = 119.808929 last_seq = 43 current_ts = 119.825966 current_received_ts = 119.825592 current_seq = 44 count = 39 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 239us (kms_flip:3397) DEBUG: name = flip last_ts = 119.825966 last_received_ts = 119.825592 last_seq = 44 current_ts = 119.842644 current_received_ts = 119.842270 current_seq = 45 count = 40 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 237us (kms_flip:3397) DEBUG: name = flip last_ts = 119.842644 last_received_ts = 119.842270 last_seq = 45 current_ts = 119.859306 current_received_ts = 119.858932 current_seq = 46 count = 41 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 249us (kms_flip:3397) DEBUG: name = flip last_ts = 119.859306 last_received_ts = 119.858932 last_seq = 46 current_ts = 119.875977 current_received_ts = 119.875603 current_seq = 47 count = 42 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 246us (kms_flip:3397) DEBUG: name = flip last_ts = 119.875977 last_received_ts = 119.875603 last_seq = 47 current_ts = 119.892654 current_received_ts = 119.892265 current_seq = 48 count = 43 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 244us (kms_flip:3397) DEBUG: name = flip last_ts = 119.892654 last_received_ts = 119.892265 last_seq = 48 current_ts = 119.909309 current_received_ts = 119.908936 current_seq = 49 count = 44 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 131us (kms_flip:3397) DEBUG: name = flip last_ts = 119.909309 last_received_ts = 119.908936 last_seq = 49 current_ts = 119.925980 current_received_ts = 119.925606 current_seq = 50 count = 45 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 243us (kms_flip:3397) DEBUG: name = flip last_ts = 119.925980 last_received_ts = 119.925606 last_seq = 50 current_ts = 119.942650 current_received_ts = 119.942276 current_seq = 51 count = 46 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 237us (kms_flip:3397) DEBUG: name = flip last_ts = 119.942650 last_received_ts = 119.942276 last_seq = 51 current_ts = 119.959320 current_received_ts = 119.958946 current_seq = 52 count = 47 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 245us (kms_flip:3397) DEBUG: name = flip last_ts = 119.959320 last_received_ts = 119.958946 last_seq = 52 current_ts = 119.975990 current_received_ts = 119.975616 current_seq = 53 count = 48 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 246us (kms_flip:3397) DEBUG: name = flip last_ts = 119.975990 last_received_ts = 119.975616 last_seq = 53 current_ts = 119.992661 current_received_ts = 119.992287 current_seq = 54 count = 49 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 242us (kms_flip:3397) DEBUG: name = flip last_ts = 119.992661 last_received_ts = 119.992287 last_seq = 54 current_ts = 120.009323 current_received_ts = 120.008949 current_seq = 55 count = 50 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 256us (kms_flip:3397) DEBUG: name = flip last_ts = 120.009323 last_received_ts = 120.008949 last_seq = 55 current_ts = 120.025993 current_received_ts = 120.025620 current_seq = 56 count = 51 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 251us (kms_flip:3397) DEBUG: name = flip last_ts = 120.025993 last_received_ts = 120.025620 last_seq = 56 current_ts = 120.042679 current_received_ts = 120.042290 current_seq = 57 count = 52 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 244us (kms_flip:3397) DEBUG: name = flip last_ts = 120.042679 last_received_ts = 120.042290 last_seq = 57 current_ts = 120.059334 current_received_ts = 120.058960 current_seq = 58 count = 53 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 255us (kms_flip:3397) DEBUG: name = flip last_ts = 120.059334 last_received_ts = 120.058960 last_seq = 58 current_ts = 120.076012 current_received_ts = 120.075623 current_seq = 59 count = 54 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 244us (kms_flip:3397) DEBUG: name = flip last_ts = 120.076012 last_received_ts = 120.075623 last_seq = 59 current_ts = 120.092682 current_received_ts = 120.092293 current_seq = 60 count = 55 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 244us (kms_flip:3397) DEBUG: name = flip last_ts = 120.092682 last_received_ts = 120.092293 last_seq = 60 current_ts = 120.109337 current_received_ts = 120.108963 current_seq = 61 count = 56 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 254us (kms_flip:3397) DEBUG: name = flip last_ts = 120.109337 last_received_ts = 120.108963 last_seq = 61 current_ts = 120.126007 current_received_ts = 120.125633 current_seq = 62 count = 57 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 240us (kms_flip:3397) DEBUG: name = flip last_ts = 120.126007 last_received_ts = 120.125633 last_seq = 62 current_ts = 120.142677 current_received_ts = 120.142311 current_seq = 63 count = 58 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 235us (kms_flip:3397) DEBUG: name = flip last_ts = 120.142677 last_received_ts = 120.142311 last_seq = 63 current_ts = 120.159355 current_received_ts = 120.158966 current_seq = 64 count = 59 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 253us (kms_flip:3397) DEBUG: name = flip last_ts = 120.159355 last_received_ts = 120.158966 last_seq = 64 current_ts = 120.176018 current_received_ts = 120.175644 current_seq = 65 count = 60 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 239us (kms_flip:3397) DEBUG: name = flip last_ts = 120.176018 last_received_ts = 120.175644 last_seq = 65 current_ts = 120.192680 current_received_ts = 120.192314 current_seq = 66 count = 61 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 247us (kms_flip:3397) DEBUG: name = flip last_ts = 120.192680 last_received_ts = 120.192314 last_seq = 66 current_ts = 120.209351 current_received_ts = 120.208984 current_seq = 67 count = 62 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 254us (kms_flip:3397) DEBUG: name = flip last_ts = 120.209351 last_received_ts = 120.208984 last_seq = 67 current_ts = 120.226021 current_received_ts = 120.225647 current_seq = 68 count = 63 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 242us (kms_flip:3397) DEBUG: name = flip last_ts = 120.226021 last_received_ts = 120.225647 last_seq = 68 current_ts = 120.242691 current_received_ts = 120.242317 current_seq = 69 count = 64 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 239us (kms_flip:3397) DEBUG: name = flip last_ts = 120.242691 last_received_ts = 120.242317 last_seq = 69 current_ts = 120.259369 current_received_ts = 120.258980 current_seq = 70 count = 65 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 251us (kms_flip:3397) DEBUG: name = flip last_ts = 120.259369 last_received_ts = 120.258980 last_seq = 70 current_ts = 120.276031 current_received_ts = 120.275658 current_seq = 71 count = 66 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 248us (kms_flip:3397) DEBUG: name = flip last_ts = 120.276031 last_received_ts = 120.275658 last_seq = 71 current_ts = 120.292702 current_received_ts = 120.292328 current_seq = 72 count = 67 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 242us (kms_flip:3397) DEBUG: name = flip last_ts = 120.292702 last_received_ts = 120.292328 last_seq = 72 current_ts = 120.309364 current_received_ts = 120.308990 current_seq = 73 count = 68 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 229us (kms_flip:3397) DEBUG: name = flip last_ts = 120.309364 last_received_ts = 120.308990 last_seq = 73 current_ts = 120.326035 current_received_ts = 120.325661 current_seq = 74 count = 69 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 120us (kms_flip:3397) DEBUG: name = flip last_ts = 120.326035 last_received_ts = 120.325661 last_seq = 74 current_ts = 120.342705 current_received_ts = 120.342331 current_seq = 75 count = 70 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 241us (kms_flip:3397) DEBUG: name = flip last_ts = 120.342705 last_received_ts = 120.342331 last_seq = 75 current_ts = 120.359375 current_received_ts = 120.359001 current_seq = 76 count = 71 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 233us (kms_flip:3397) DEBUG: name = flip last_ts = 120.359375 last_received_ts = 120.359001 last_seq = 76 current_ts = 120.376045 current_received_ts = 120.375664 current_seq = 77 count = 72 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 247us (kms_flip:3397) DEBUG: name = flip last_ts = 120.376045 last_received_ts = 120.375664 last_seq = 77 current_ts = 120.392708 current_received_ts = 120.392334 current_seq = 78 count = 73 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 243us (kms_flip:3397) DEBUG: name = flip last_ts = 120.392708 last_received_ts = 120.392334 last_seq = 78 current_ts = 120.409378 current_received_ts = 120.409027 current_seq = 79 count = 74 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 230us (kms_flip:3397) DEBUG: name = flip last_ts = 120.409378 last_received_ts = 120.409027 last_seq = 79 current_ts = 120.426048 current_received_ts = 120.425674 current_seq = 80 count = 75 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 248us (kms_flip:3397) DEBUG: name = flip last_ts = 120.426048 last_received_ts = 120.425674 last_seq = 80 current_ts = 120.442719 current_received_ts = 120.442345 current_seq = 81 count = 76 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 240us (kms_flip:3397) DEBUG: name = flip last_ts = 120.442719 last_received_ts = 120.442345 last_seq = 81 current_ts = 120.459389 current_received_ts = 120.459068 current_seq = 82 count = 77 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 40us (kms_flip:3397) DEBUG: name = flip last_ts = 120.459389 last_received_ts = 120.459068 last_seq = 82 current_ts = 120.476059 current_received_ts = 120.475700 current_seq = 83 count = 78 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 30us (kms_flip:3397) DEBUG: name = flip last_ts = 120.476059 last_received_ts = 120.475700 last_seq = 83 current_ts = 120.492722 current_received_ts = 120.492355 current_seq = 84 count = 79 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 120.492722 last_received_ts = 120.492355 last_seq = 84 current_ts = 120.509392 current_received_ts = 120.509033 current_seq = 85 count = 80 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 27us (kms_flip:3397) DEBUG: name = flip last_ts = 120.509392 last_received_ts = 120.509033 last_seq = 85 current_ts = 120.526062 current_received_ts = 120.525688 current_seq = 86 count = 81 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 120.526062 last_received_ts = 120.525688 last_seq = 86 current_ts = 120.542732 current_received_ts = 120.542358 current_seq = 87 count = 82 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 120.542732 last_received_ts = 120.542358 last_seq = 87 current_ts = 120.559395 current_received_ts = 120.559036 current_seq = 88 count = 83 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 120.559395 last_received_ts = 120.559036 last_seq = 88 current_ts = 120.576073 current_received_ts = 120.575699 current_seq = 89 count = 84 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 120.576073 last_received_ts = 120.575699 last_seq = 89 current_ts = 120.592735 current_received_ts = 120.592369 current_seq = 90 count = 85 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 25us (kms_flip:3397) DEBUG: name = flip last_ts = 120.592735 last_received_ts = 120.592369 last_seq = 90 current_ts = 120.609421 current_received_ts = 120.609047 current_seq = 91 count = 86 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 25us (kms_flip:3397) DEBUG: name = flip last_ts = 120.609421 last_received_ts = 120.609047 last_seq = 91 current_ts = 120.626083 current_received_ts = 120.625702 current_seq = 92 count = 87 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 120.626083 last_received_ts = 120.625702 last_seq = 92 current_ts = 120.642746 current_received_ts = 120.642372 current_seq = 93 count = 88 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 120.642746 last_received_ts = 120.642372 last_seq = 93 current_ts = 120.659409 current_received_ts = 120.659042 current_seq = 94 count = 89 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 27us (kms_flip:3397) DEBUG: name = flip last_ts = 120.659409 last_received_ts = 120.659042 last_seq = 94 current_ts = 120.676086 current_received_ts = 120.675667 current_seq = 95 count = 90 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 31us (kms_flip:3397) DEBUG: name = flip last_ts = 120.676086 last_received_ts = 120.675667 last_seq = 95 current_ts = 120.692749 current_received_ts = 120.692307 current_seq = 96 count = 91 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 27us (kms_flip:3397) DEBUG: name = flip last_ts = 120.692749 last_received_ts = 120.692307 last_seq = 96 current_ts = 120.709427 current_received_ts = 120.708939 current_seq = 97 count = 92 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 120.709427 last_received_ts = 120.708939 last_seq = 97 current_ts = 120.726089 current_received_ts = 120.725647 current_seq = 98 count = 93 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 120.726089 last_received_ts = 120.725647 last_seq = 98 current_ts = 120.742760 current_received_ts = 120.742310 current_seq = 99 count = 94 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 120.742760 last_received_ts = 120.742310 last_seq = 99 current_ts = 120.759430 current_received_ts = 120.758980 current_seq = 100 count = 95 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 50us (kms_flip:3397) DEBUG: name = flip last_ts = 120.759430 last_received_ts = 120.758980 last_seq = 100 current_ts = 120.776093 current_received_ts = 120.775719 current_seq = 101 count = 96 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 120.776093 last_received_ts = 120.775719 last_seq = 101 current_ts = 120.792763 current_received_ts = 120.792389 current_seq = 102 count = 97 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 120.792763 last_received_ts = 120.792389 last_seq = 102 current_ts = 120.809441 current_received_ts = 120.808945 current_seq = 103 count = 98 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 120.809441 last_received_ts = 120.808945 last_seq = 103 current_ts = 120.826111 current_received_ts = 120.825829 current_seq = 104 count = 99 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 252us (kms_flip:3397) DEBUG: name = flip last_ts = 120.826111 last_received_ts = 120.825829 last_seq = 104 current_ts = 120.842773 current_received_ts = 120.842476 current_seq = 105 count = 100 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 120.842773 last_received_ts = 120.842476 last_seq = 105 current_ts = 120.859436 current_received_ts = 120.859146 current_seq = 106 count = 101 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 25us (kms_flip:3397) DEBUG: name = flip last_ts = 120.859436 last_received_ts = 120.859146 last_seq = 106 current_ts = 120.876106 current_received_ts = 120.875809 current_seq = 107 count = 102 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 25us (kms_flip:3397) DEBUG: name = flip last_ts = 120.876106 last_received_ts = 120.875809 last_seq = 107 current_ts = 120.892784 current_received_ts = 120.892494 current_seq = 108 count = 103 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 27us (kms_flip:3397) DEBUG: name = flip last_ts = 120.892784 last_received_ts = 120.892494 last_seq = 108 current_ts = 120.909447 current_received_ts = 120.909157 current_seq = 109 count = 104 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 120.909447 last_received_ts = 120.909157 last_seq = 109 current_ts = 120.926117 current_received_ts = 120.925819 current_seq = 110 count = 105 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 120.926117 last_received_ts = 120.925819 last_seq = 110 current_ts = 120.942787 current_received_ts = 120.942490 current_seq = 111 count = 106 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 120.942787 last_received_ts = 120.942490 last_seq = 111 current_ts = 120.959457 current_received_ts = 120.959183 current_seq = 112 count = 107 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 120.959457 last_received_ts = 120.959183 last_seq = 112 current_ts = 120.976120 current_received_ts = 120.975822 current_seq = 113 count = 108 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 25us (kms_flip:3397) DEBUG: name = flip last_ts = 120.976120 last_received_ts = 120.975822 last_seq = 113 current_ts = 120.992790 current_received_ts = 120.992493 current_seq = 114 count = 109 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 25us (kms_flip:3397) DEBUG: name = flip last_ts = 120.992790 last_received_ts = 120.992493 last_seq = 114 current_ts = 121.009468 current_received_ts = 121.009109 current_seq = 115 count = 110 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 121.009468 last_received_ts = 121.009109 last_seq = 115 current_ts = 121.026131 current_received_ts = 121.025764 current_seq = 116 count = 111 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 25us (kms_flip:3397) DEBUG: name = flip last_ts = 121.026131 last_received_ts = 121.025764 last_seq = 116 current_ts = 121.042801 current_received_ts = 121.042427 current_seq = 117 count = 112 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 121.042801 last_received_ts = 121.042427 last_seq = 117 current_ts = 121.059464 current_received_ts = 121.059097 current_seq = 118 count = 113 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 25us (kms_flip:3397) DEBUG: name = flip last_ts = 121.059464 last_received_ts = 121.059097 last_seq = 118 current_ts = 121.076134 current_received_ts = 121.075760 current_seq = 119 count = 114 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 121.076134 last_received_ts = 121.075760 last_seq = 119 current_ts = 121.092804 current_received_ts = 121.092361 current_seq = 120 count = 115 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 121.092804 last_received_ts = 121.092361 last_seq = 120 current_ts = 121.109474 current_received_ts = 121.109039 current_seq = 121 count = 116 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 26us (kms_flip:3397) DEBUG: name = flip last_ts = 121.109474 last_received_ts = 121.109039 last_seq = 121 current_ts = 121.126144 current_received_ts = 121.125595 current_seq = 122 count = 117 seq_step = 1 (kms_flip:3397) DEBUG: Vblank took 625us (kms_flip:3397) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930: (kms_flip:3397) CRITICAL: Failed assertion: end - start < 500 (kms_flip:3397) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:3397) igt_core-INFO: Stack trace: (kms_flip:3397) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:3397) igt_core-INFO: #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0() (kms_flip:3397) igt_core-INFO: #2 ../tests/kms_flip.c:1891 run_test() (kms_flip:3397) igt_core-INFO: #3 ../tests/kms_flip.c:2162 __igt_unique____real_main2047() (kms_flip:3397) igt_core-INFO: #4 ../tests/kms_flip.c:2047 main() (kms_flip:3397) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:3397) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:3397) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest C-DP2: FAIL (2.821s)
Dmesg	<6> [119.426046] [IGT] kms_flip: starting dynamic subtest C-DP2 <7> [119.428796] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:554] <7> [119.430728] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:558] <7> [119.474873] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [119.475157] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B] <7> [119.475223] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.enable (expected yes, found no) <7> [119.475355] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.active (expected yes, found no) <7> [119.475459] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in cpu_transcoder (expected 1, found -1) <7> [119.475559] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in lane_count (expected 4, found 0) <7> [119.475656] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in dp_m_n (expected tu 64 data 5190451/8388608 link 288358/524288, found tu 0, data 0/0 link 0/0) <7> [119.475752] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in output_types (expected 0x00000080, found 0x00000000) <7> [119.475846] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [119.475939] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [119.476045] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [119.476157] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [119.476252] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [119.476346] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [119.476439] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [119.476532] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [119.476626] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [119.476718] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0) <7> [119.476811] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0) <7> [119.476903] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [119.477009] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [119.477122] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [119.477221] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [119.477316] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [119.477408] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [119.477500] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [119.477591] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [119.477682] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [119.477774] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [119.477867] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0) <7> [119.477959] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0) <7> [119.478072] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [119.478183] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [119.478280] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [119.478375] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [119.478466] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0) <7> [119.478559] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in enhanced_framing (expected yes, found no) <7> [119.478649] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in pipe_bpp (expected 36, found 0) <7> [119.478740] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [119.478829] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [119.478920] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in port_clock (expected 270000, found 0) <7> [119.479026] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:269:pipe B] fastset requirement not met, forcing full modeset <7> [119.479132] xe 0000:03:00.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:269:pipe B] releasing TC PLL 2 <7> [119.479254] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [119.479334] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:269:pipe B] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x2 -> 0x0 <7> [119.479428] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:263:cursor B] ddb (4037 - 4096) -> ( 0 - 0), size 59 -> 0 <7> [119.479515] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:269:pipe B] min cdclk: 192000 kHz -> 0 kHz <7> [119.479634] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:269:pipe B] enable: no [modeset] <7> [119.479737] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:153:plane 1B] fb: [NOFB], visible: no <7> [119.479839] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:183:plane 2B] fb: [NOFB], visible: no <7> [119.479938] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:213:plane 3B] fb: [NOFB], visible: no <7> [119.480045] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:243:plane 4B] fb: [NOFB], visible: no <7> [119.480155] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:253:plane 5B] fb: [NOFB], visible: no <7> [119.480250] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:263:cursor B] fb: [NOFB], visible: no <7> [119.480655] xe 0000:03:00.0: [drm:intel_audio_codec_disable [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G] Disable audio codec on [CRTC:269:pipe B] <7> [119.504655] xe 0000:03:00.0: [drm:intel_disable_transcoder [xe]] disabling pipe B <7> [119.526059] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2 <7> [119.529164] xe 0000:03:00.0: [drm:intel_dpll_disable [xe]] disable TC PLL 2 (active 0x2, on? 1) for [CRTC:269:pipe B] <7> [119.531633] xe 0000:03:00.0: [drm:intel_dpll_disable [xe]] disabling TC PLL 2 <7> [119.532479] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:507:DDI TC1/PHY F] <7> [119.532941] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:509:DP-MST A] <7> [119.533465] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:510:DP-MST B] <7> [119.533998] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:511:DP-MST C] <7> [119.534381] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:512:DP-MST D] <7> [119.534751] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:526:DDI TC2/PHY G] <7> [119.535357] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:528:DP-MST A] <7> [119.535705] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:529:DP-MST B] <7> [119.536052] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:530:DP-MST C] <7> [119.536385] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:531:DP-MST D] <7> [119.536669] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:538:DDI TC3/PHY H] <7> [119.536951] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:542:DDI TC4/PHY I] <7> [119.537282] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:544:DP-MST A] <7> [119.537601] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:545:DP-MST B] <7> [119.537879] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:546:DP-MST C] <7> [119.538165] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:547:DP-MST D] <7> [119.538435] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:527:DP-2] <7> [119.538910] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no) <7> [119.539380] xe 0000:03:00.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [119.539599] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [119.540157] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_B <7> [119.540616] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [119.541103] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_2 <7> [119.541568] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:269:pipe B] <7> [119.541947] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C] <7> [119.542550] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:505:pipe D] <7> [119.542727] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C] <7> [119.542761] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:527:DP-2] <7> [119.542873] xe 0000:03:00.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:526:DDI TC2/PHY G][CRTC:387:pipe C] DP link limits: pixel clock 148500 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 36 min link_bpp 18.0000 max link_bpp 36.0000 <7> [119.543073] xe 0000:03:00.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 270000 bpp input 36 compressed 0.0000 HDR no link rate required 668250 available 1080000 <7> [119.543264] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:387:pipe C] hw max bpp: 36, pipe bpp: 36, dithering: 0 <7> [119.543440] xe 0000:03:00.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:526:DDI TC2/PHY G] [CRTC:387:pipe C] <7> [119.543617] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.enable (expected no, found yes) <7> [119.543788] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.active (expected no, found yes) <7> [119.543940] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2) <7> [119.544109] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in lane_count (expected 0, found 4) <7> [119.544271] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 5190451/8388608 link 288358/524288) <7> [119.544409] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in output_types (expected 0x00000000, found 0x00000080) <7> [119.544545] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [119.544681] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [119.544811] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [119.544938] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [119.545081] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [119.545216] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [119.545334] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [119.545448] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [119.545561] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [119.545678] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084) <7> [119.545783] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089) <7> [119.545890] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [119.546006] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [119.546124] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [119.546227] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [119.546328] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [119.546428] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [119.546528] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [119.546628] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [119.546722] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [119.546816] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [119.546908] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084) <7> [119.547009] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089) <7> [119.547112] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [119.547202] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [119.547291] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [119.547380] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [119.547470] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [119.547561] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in enhanced_framing (expected no, found yes) <7> [119.547650] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in dpll_hw_state <7> [119.547738] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] expected: <7> [119.547827] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 0, ssc_enabled: no, use_c10: no, tbt_mode: no <7> [119.547916] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] c20pll_hw_state: <7> [119.548015] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] tx[0] = 0x0000, tx[1] = 0x0000, tx[2] = 0x0000 <7> [119.548118] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cmn[0] = 0x0000, cmn[1] = 0x0000, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [119.548207] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mplla[0] = 0x0000 <7> [119.548296] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mplla[1] = 0x0000 <7> [119.548383] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mplla[2] = 0x0000 <7> [119.548479] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mplla[3] = 0x0000 <7> [119.548571] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mplla[4] = 0x0000 <7> [119.548662] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mplla[5] = 0x0000 <7> [119.548752] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mplla[6] = 0x0000 <7> [119.548840] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mplla[7] = 0x0000 <7> [119.548929] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mplla[8] = 0x0000 <7> [119.549031] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mplla[9] = 0x0000 <7> [119.549133] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[10] = 0x0000 <7> [119.549222] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] vdr: custom width: 0x00, serdes rate: 0x00, hdmi rate: 0x00 <7> [119.549310] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] found: <7> [119.549399] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no <7> [119.549488] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] c20pll_hw_state: <7> [119.549576] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] tx[0] = 0xbe88, tx[1] = 0x4800, tx[2] = 0x0000 <7> [119.549664] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [119.549753] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[0] = 0x308c <7> [119.549841] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[1] = 0x2110 <7> [119.549929] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[2] = 0xcc9c <7> [119.550032] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[3] = 0xbfc1 <7> [119.550137] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[4] = 0x4b9a <7> [119.550227] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[5] = 0x3f81 <7> [119.550316] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[6] = 0x2000 <7> [119.550404] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[7] = 0x0001 <7> [119.550494] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[8] = 0x5000 <7> [119.550582] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[9] = 0x0000 <7> [119.550670] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mpllb[10] = 0x0000 <7> [119.550758] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] vdr: custom width: 0x00, serdes rate: 0x42, hdmi rate: 0x00 <7> [119.550846] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 36) <7> [119.550935] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [119.551036] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [119.551147] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in port_clock (expected 0, found 270000) <7> [119.551243] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:387:pipe C] fastset requirement not met, forcing full modeset <7> [119.551356] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xd (total dbuf slices 0xf), mbus joined? no->no <7> [119.551436] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:387:pipe C] dbuf slices 0x0 -> 0xc, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4 <7> [119.551531] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:271:plane 1C] ddb ( 0 - 0) -> ( 0 - 1989), size 0 -> 1989 <7> [119.551606] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:381:cursor C] ddb ( 0 - 0) -> (1989 - 2048), size 0 -> 59 <7> [119.551678] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [119.551748] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 4, 9, 9, 17, 17, 17, 17, 0, 15, 0 <7> [119.551821] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 62, 62, 139, 139, 261, 261, 261, 261, 137, 230, 244 <7> [119.551895] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 123, 123, 245, 245, 367, 367, 0, 0, 138, 306, 306 <7> [119.552016] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] [CRTC:387:pipe C] data rate 594000 num active planes 1 <7> [119.552130] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 33600 required 624 qgv_peak_bw: 48000 <7> [119.552234] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 53000 required 624 qgv_peak_bw: 48000 <7> [119.552335] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 48000 for required data rate: 624 <7> [119.552446] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:387:pipe C] min cdclk: 0 kHz -> 192000 kHz <7> [119.552570] xe 0000:03:00.0: [drm:intel_find_dpll [xe]] [CRTC:387:pipe C] allocated TC PLL 2 <7> [119.552664] xe 0000:03:00.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:387:pipe C] reserving TC PLL 2 <7> [119.552757] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:387:pipe C] enable: yes [modeset] <7> [119.552860] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: DP (0x80), output format: RGB, sink format: RGB <7> [119.552967] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: C, pipe bpp: 36, dithering: 0 <7> [119.553081] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [119.553179] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [119.553277] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [119.553373] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [119.553469] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 5190451, data_n: 8388608, link_m: 288358, link_n: 524288, tu: 64 <7> [119.553565] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [119.553660] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: enabled <7> [119.553754] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [119.553848] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] psr: disabled, selective update: disabled, panel replay: disabled, selective fetch: disabled <7> [119.553942] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0 <7> [119.554078] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] audio: 1, infoframes: 0, infoframes enabled: 0x0 <7> [119.554177] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 10 00 09 00 68 36 00 01 00 00 00 00 00 00 00 00 <7> [119.554271] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 61 a4 9a 00 44 50 46 39 30 34 33 35 09 07 07 11 <7> [119.554365] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 17 50 51 07 00 00 00 00 <7> [119.554458] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [119.554552] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [119.554646] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1125, vmax: 1125, flipline: 1125, pipeline full: 0, guardband: 42 vsync start: 41, vsync end: 36 <7> [119.554741] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1083, vmax vblank: 1083, vmin vtotal: 1125, vmax vtotal: 1125 <7> [119.554834] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [119.554929] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 <7> [119.555055] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 <7> [119.555164] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [119.555259] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x40 0x5 <7> [119.555353] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [119.555446] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port clock: 270000, pipe src: 1920x1080+0+0, pixel rate 148500, min cdclk 192000 <7> [119.555541] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] linetime: 119, ips linetime: 0 <7> [119.555634] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [119.555727] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [119.555821] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [119.555914] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no <7> [119.556018] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] c20pll_hw_state: <7> [119.556130] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] tx[0] = 0xbe88, tx[1] = 0x4800, tx[2] = 0x0000 <7> [119.556228] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [119.556322] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[0] = 0x308c <7> [119.556416] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[1] = 0x2110 <7> [119.556509] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[2] = 0xcc9c <7> [119.556600] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[3] = 0xbfc1 <7> [119.556692] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[4] = 0x4b9a <7> [119.556784] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[5] = 0x3f81 <7> [119.556875] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[6] = 0x2000 <7> [119.557016] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[7] = 0x0001 <7> [119.557118] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[8] = 0x5000 <7> [119.557210] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[9] = 0x0000 <7> [119.557299] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[10] = 0x0000 <7> [119.557389] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vdr: custom width: 0x00, serdes rate: 0x42, hdmi rate: 0x00 <7> [119.557480] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x40000000 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [119.557573] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [119.557668] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [119.557761] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0db0 0x0000 0x0000 <7> [119.557852] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0db0 0x0000 <7> [119.557941] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0db0 <7> [119.558049] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0100 0x0100 0x0100 <7> [119.558156] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [119.558248] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [119.558340] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [119.558431] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [119.558522] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [119.558614] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [119.558711] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:271:plane 1C] fb: [FB:554] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [119.558806] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [119.558899] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [119.559004] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:301:plane 2C] fb: [NOFB], visible: no <7> [119.559133] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:331:plane 3C] fb: [NOFB], visible: no <7> [119.559226] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:361:plane 4C] fb: [NOFB], visible: no <7> [119.559322] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:371:plane 5C] fb: [NOFB], visible: no <7> [119.559413] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:381:cursor C] fb: [NOFB], visible: no <7> [119.560057] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [119.560193] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_C <7> [119.560332] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x4 (CLKGATE_DIS_DSSDSC=0x8a000000) <7> [119.560439] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:507:DDI TC1/PHY F] <7> [119.560529] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:509:DP-MST A] <7> [119.560614] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:510:DP-MST B] <7> [119.560695] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:511:DP-MST C] <7> [119.560774] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:512:DP-MST D] <7> [119.560852] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:526:DDI TC2/PHY G] <7> [119.560930] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:528:DP-MST A] <7> [119.561022] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:529:DP-MST B] <7> [119.561113] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:530:DP-MST C] <7> [119.561191] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:531:DP-MST D] <7> [119.561267] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:538:DDI TC3/PHY H] <7> [119.561347] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:542:DDI TC4/PHY I] <7> [119.561427] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:544:DP-MST A] <7> [119.561505] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:545:DP-MST B] <7> [119.561581] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:546:DP-MST C] <7> [119.561657] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:547:DP-MST D] <7> [119.561742] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xd <7> [119.561905] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no) <7> [119.562016] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enable TC PLL 2 (active 0x4, on? 0) for [CRTC:387:pipe C] <7> [119.562113] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enabling TC PLL 2 <7> [119.566547] xe 0000:03:00.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX USBC2/DDI TC2/PHY G: DPCD: 12 14 c4 01 01 15 01 81 00 01 04 01 0f 00 01 <7> [119.571295] xe 0000:03:00.0: [drm:intel_dp_init_lttpr_and_dprx_caps [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] LTTPR common capabilities: 00 00 00 00 00 00 00 00 <7> [119.572307] xe 0000:03:00.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX USBC2/DDI TC2/PHY G: DPCD: 12 14 c4 01 01 15 01 81 00 01 04 01 0f 00 01 <7> [119.572741] xe 0000:03:00.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using LINK_BW_SET value 0a <7> [119.574257] xe 0000:03:00.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [119.574813] xe 0000:03:00.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using DP training pattern TPS1 <7> [119.580856] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Clock recovery OK <7> [119.580979] xe 0000:03:00.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using DP training pattern TPS3 <7> [119.586856] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Channel EQ done. DP Training successful <7> [119.587024] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Link Training passed at link rate = 270000, lane count = 4 <7> [119.588306] xe 0000:03:00.0: [drm:intel_enable_transcoder [xe]] enabling pipe C <7> [119.605470] xe 0000:03:00.0: [drm:intel_audio_codec_enable [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G] Enable audio codec on [CRTC:387:pipe C], 40 bytes ELD <7> [119.622283] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:527:DP-2] <7> [119.623139] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:387:pipe C] <7> [119.690980] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2 <7> [121.603013] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2 <7> [121.622846] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2 <6> [122.254555] [IGT] kms_flip: finished subtest C-DP2, FAIL

Detail

Value

Duration

2.82 seconds

Hostname

shard-bmg-10

Igt-Version

IGT-Version: 2.3-gf57041a8e (x86_64) (Linux: 7.0.0-rc5-lgci-xe-xe-4769-0c7d9ab970be1e932-debug+ x86_64)

Out

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

Err

Starting dynamic subtest: C-DP2
(kms_flip:3397) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930:
(kms_flip:3397) CRITICAL: Failed assertion: end - start < 500
(kms_flip:3397) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest C-DP2 failed.
**** DEBUG ****
(kms_flip:3397) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3397) intel_allocator_simple-DEBUG: <ial: 0x558cbec34d40, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3397) intel_allocator_simple-DEBUG: <ial: 0x558cbec34d40, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3397) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3397) DEBUG: No stale events found
(kms_flip:3397) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3397) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3397) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 119.175880
current_received_ts = 119.175491
current_seq = 5
count = 0
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 29us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.175880
last_received_ts = 119.175491
last_seq = 5
current_ts = 119.192551
current_received_ts = 119.192108
current_seq = 6
count = 1
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.192551
last_received_ts = 119.192108
last_seq = 6
current_ts = 119.209213
current_received_ts = 119.208847
current_seq = 7
count = 2
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 25us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.209213
last_received_ts = 119.208847
last_seq = 7
current_ts = 119.225883
current_received_ts = 119.225441
current_seq = 8
count = 3
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.225883
last_received_ts = 119.225441
last_seq = 8
current_ts = 119.242554
current_received_ts = 119.242111
current_seq = 9
count = 4
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 25us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.242554
last_received_ts = 119.242111
last_seq = 9
current_ts = 119.259224
current_received_ts = 119.258774
current_seq = 10
count = 5
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.259224
last_received_ts = 119.258774
last_seq = 10
current_ts = 119.275894
current_received_ts = 119.275520
current_seq = 11
count = 6
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 27us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.275894
last_received_ts = 119.275520
last_seq = 11
current_ts = 119.292557
current_received_ts = 119.292091
current_seq = 12
count = 7
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.292557
last_received_ts = 119.292091
last_seq = 12
current_ts = 119.309235
current_received_ts = 119.308784
current_seq = 13
count = 8
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 25us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.309235
last_received_ts = 119.308784
last_seq = 13
current_ts = 119.325905
current_received_ts = 119.325531
current_seq = 14
count = 9
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.325905
last_received_ts = 119.325531
last_seq = 14
current_ts = 119.342575
current_received_ts = 119.342087
current_seq = 15
count = 10
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.342575
last_received_ts = 119.342087
last_seq = 15
current_ts = 119.359238
current_received_ts = 119.358788
current_seq = 16
count = 11
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.359238
last_received_ts = 119.358788
last_seq = 16
current_ts = 119.375908
current_received_ts = 119.375534
current_seq = 17
count = 12
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.375908
last_received_ts = 119.375534
last_seq = 17
current_ts = 119.392578
current_received_ts = 119.392128
current_seq = 18
count = 13
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.392578
last_received_ts = 119.392128
last_seq = 18
current_ts = 119.409241
current_received_ts = 119.408875
current_seq = 19
count = 14
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.409241
last_received_ts = 119.408875
last_seq = 19
current_ts = 119.425919
current_received_ts = 119.425468
current_seq = 20
count = 15
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.425919
last_received_ts = 119.425468
last_seq = 20
current_ts = 119.442581
current_received_ts = 119.442207
current_seq = 21
count = 16
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 25us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.442581
last_received_ts = 119.442207
last_seq = 21
current_ts = 119.459251
current_received_ts = 119.458878
current_seq = 22
count = 17
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 25us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.459251
last_received_ts = 119.458878
last_seq = 22
current_ts = 119.475922
current_received_ts = 119.475471
current_seq = 23
count = 18
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.475922
last_received_ts = 119.475471
last_seq = 23
current_ts = 119.492584
current_received_ts = 119.492210
current_seq = 24
count = 19
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.492584
last_received_ts = 119.492210
last_seq = 24
current_ts = 119.509254
current_received_ts = 119.508812
current_seq = 25
count = 20
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.509254
last_received_ts = 119.508812
last_seq = 25
current_ts = 119.525932
current_received_ts = 119.525558
current_seq = 26
count = 21
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.525932
last_received_ts = 119.525558
last_seq = 26
current_ts = 119.542595
current_received_ts = 119.542145
current_seq = 27
count = 22
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 24us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.542595
last_received_ts = 119.542145
last_seq = 27
current_ts = 119.559265
current_received_ts = 119.558815
current_seq = 28
count = 23
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.559265
last_received_ts = 119.558815
last_seq = 28
current_ts = 119.575935
current_received_ts = 119.575562
current_seq = 29
count = 24
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 27us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.575935
last_received_ts = 119.575562
last_seq = 29
current_ts = 119.592606
current_received_ts = 119.592155
current_seq = 30
count = 25
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.592606
last_received_ts = 119.592155
last_seq = 30
current_ts = 119.609268
current_received_ts = 119.608826
current_seq = 31
count = 26
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.609268
last_received_ts = 119.608826
last_seq = 31
current_ts = 119.625938
current_received_ts = 119.625572
current_seq = 32
count = 27
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.625938
last_received_ts = 119.625572
last_seq = 32
current_ts = 119.642609
current_received_ts = 119.642166
current_seq = 33
count = 28
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.642609
last_received_ts = 119.642166
last_seq = 33
current_ts = 119.659279
current_received_ts = 119.658829
current_seq = 34
count = 29
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.659279
last_received_ts = 119.658829
last_seq = 34
current_ts = 119.675949
current_received_ts = 119.675575
current_seq = 35
count = 30
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 25us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.675949
last_received_ts = 119.675575
last_seq = 35
current_ts = 119.692619
current_received_ts = 119.692245
current_seq = 36
count = 31
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.692619
last_received_ts = 119.692245
last_seq = 36
current_ts = 119.709282
current_received_ts = 119.708839
current_seq = 37
count = 32
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 25us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.709282
last_received_ts = 119.708839
last_seq = 37
current_ts = 119.725952
current_received_ts = 119.725578
current_seq = 38
count = 33
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.725952
last_received_ts = 119.725578
last_seq = 38
current_ts = 119.742622
current_received_ts = 119.742172
current_seq = 39
count = 34
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 243us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.742622
last_received_ts = 119.742172
last_seq = 39
current_ts = 119.759300
current_received_ts = 119.758919
current_seq = 40
count = 35
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 254us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.759300
last_received_ts = 119.758919
last_seq = 40
current_ts = 119.775955
current_received_ts = 119.775581
current_seq = 41
count = 36
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 238us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.775955
last_received_ts = 119.775581
last_seq = 41
current_ts = 119.792633
current_received_ts = 119.792252
current_seq = 42
count = 37
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 238us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.792633
last_received_ts = 119.792252
last_seq = 42
current_ts = 119.809303
current_received_ts = 119.808929
current_seq = 43
count = 38
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 257us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.809303
last_received_ts = 119.808929
last_seq = 43
current_ts = 119.825966
current_received_ts = 119.825592
current_seq = 44
count = 39
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 239us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.825966
last_received_ts = 119.825592
last_seq = 44
current_ts = 119.842644
current_received_ts = 119.842270
current_seq = 45
count = 40
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 237us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.842644
last_received_ts = 119.842270
last_seq = 45
current_ts = 119.859306
current_received_ts = 119.858932
current_seq = 46
count = 41
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 249us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.859306
last_received_ts = 119.858932
last_seq = 46
current_ts = 119.875977
current_received_ts = 119.875603
current_seq = 47
count = 42
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 246us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.875977
last_received_ts = 119.875603
last_seq = 47
current_ts = 119.892654
current_received_ts = 119.892265
current_seq = 48
count = 43
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 244us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.892654
last_received_ts = 119.892265
last_seq = 48
current_ts = 119.909309
current_received_ts = 119.908936
current_seq = 49
count = 44
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 131us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.909309
last_received_ts = 119.908936
last_seq = 49
current_ts = 119.925980
current_received_ts = 119.925606
current_seq = 50
count = 45
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 243us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.925980
last_received_ts = 119.925606
last_seq = 50
current_ts = 119.942650
current_received_ts = 119.942276
current_seq = 51
count = 46
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 237us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.942650
last_received_ts = 119.942276
last_seq = 51
current_ts = 119.959320
current_received_ts = 119.958946
current_seq = 52
count = 47
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 245us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.959320
last_received_ts = 119.958946
last_seq = 52
current_ts = 119.975990
current_received_ts = 119.975616
current_seq = 53
count = 48
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 246us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.975990
last_received_ts = 119.975616
last_seq = 53
current_ts = 119.992661
current_received_ts = 119.992287
current_seq = 54
count = 49
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 242us
(kms_flip:3397) DEBUG: name = flip
last_ts = 119.992661
last_received_ts = 119.992287
last_seq = 54
current_ts = 120.009323
current_received_ts = 120.008949
current_seq = 55
count = 50
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 256us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.009323
last_received_ts = 120.008949
last_seq = 55
current_ts = 120.025993
current_received_ts = 120.025620
current_seq = 56
count = 51
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 251us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.025993
last_received_ts = 120.025620
last_seq = 56
current_ts = 120.042679
current_received_ts = 120.042290
current_seq = 57
count = 52
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 244us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.042679
last_received_ts = 120.042290
last_seq = 57
current_ts = 120.059334
current_received_ts = 120.058960
current_seq = 58
count = 53
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 255us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.059334
last_received_ts = 120.058960
last_seq = 58
current_ts = 120.076012
current_received_ts = 120.075623
current_seq = 59
count = 54
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 244us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.076012
last_received_ts = 120.075623
last_seq = 59
current_ts = 120.092682
current_received_ts = 120.092293
current_seq = 60
count = 55
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 244us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.092682
last_received_ts = 120.092293
last_seq = 60
current_ts = 120.109337
current_received_ts = 120.108963
current_seq = 61
count = 56
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 254us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.109337
last_received_ts = 120.108963
last_seq = 61
current_ts = 120.126007
current_received_ts = 120.125633
current_seq = 62
count = 57
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 240us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.126007
last_received_ts = 120.125633
last_seq = 62
current_ts = 120.142677
current_received_ts = 120.142311
current_seq = 63
count = 58
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 235us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.142677
last_received_ts = 120.142311
last_seq = 63
current_ts = 120.159355
current_received_ts = 120.158966
current_seq = 64
count = 59
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 253us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.159355
last_received_ts = 120.158966
last_seq = 64
current_ts = 120.176018
current_received_ts = 120.175644
current_seq = 65
count = 60
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 239us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.176018
last_received_ts = 120.175644
last_seq = 65
current_ts = 120.192680
current_received_ts = 120.192314
current_seq = 66
count = 61
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 247us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.192680
last_received_ts = 120.192314
last_seq = 66
current_ts = 120.209351
current_received_ts = 120.208984
current_seq = 67
count = 62
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 254us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.209351
last_received_ts = 120.208984
last_seq = 67
current_ts = 120.226021
current_received_ts = 120.225647
current_seq = 68
count = 63
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 242us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.226021
last_received_ts = 120.225647
last_seq = 68
current_ts = 120.242691
current_received_ts = 120.242317
current_seq = 69
count = 64
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 239us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.242691
last_received_ts = 120.242317
last_seq = 69
current_ts = 120.259369
current_received_ts = 120.258980
current_seq = 70
count = 65
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 251us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.259369
last_received_ts = 120.258980
last_seq = 70
current_ts = 120.276031
current_received_ts = 120.275658
current_seq = 71
count = 66
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 248us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.276031
last_received_ts = 120.275658
last_seq = 71
current_ts = 120.292702
current_received_ts = 120.292328
current_seq = 72
count = 67
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 242us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.292702
last_received_ts = 120.292328
last_seq = 72
current_ts = 120.309364
current_received_ts = 120.308990
current_seq = 73
count = 68
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 229us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.309364
last_received_ts = 120.308990
last_seq = 73
current_ts = 120.326035
current_received_ts = 120.325661
current_seq = 74
count = 69
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 120us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.326035
last_received_ts = 120.325661
last_seq = 74
current_ts = 120.342705
current_received_ts = 120.342331
current_seq = 75
count = 70
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 241us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.342705
last_received_ts = 120.342331
last_seq = 75
current_ts = 120.359375
current_received_ts = 120.359001
current_seq = 76
count = 71
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 233us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.359375
last_received_ts = 120.359001
last_seq = 76
current_ts = 120.376045
current_received_ts = 120.375664
current_seq = 77
count = 72
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 247us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.376045
last_received_ts = 120.375664
last_seq = 77
current_ts = 120.392708
current_received_ts = 120.392334
current_seq = 78
count = 73
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 243us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.392708
last_received_ts = 120.392334
last_seq = 78
current_ts = 120.409378
current_received_ts = 120.409027
current_seq = 79
count = 74
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 230us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.409378
last_received_ts = 120.409027
last_seq = 79
current_ts = 120.426048
current_received_ts = 120.425674
current_seq = 80
count = 75
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 248us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.426048
last_received_ts = 120.425674
last_seq = 80
current_ts = 120.442719
current_received_ts = 120.442345
current_seq = 81
count = 76
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 240us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.442719
last_received_ts = 120.442345
last_seq = 81
current_ts = 120.459389
current_received_ts = 120.459068
current_seq = 82
count = 77
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 40us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.459389
last_received_ts = 120.459068
last_seq = 82
current_ts = 120.476059
current_received_ts = 120.475700
current_seq = 83
count = 78
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 30us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.476059
last_received_ts = 120.475700
last_seq = 83
current_ts = 120.492722
current_received_ts = 120.492355
current_seq = 84
count = 79
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.492722
last_received_ts = 120.492355
last_seq = 84
current_ts = 120.509392
current_received_ts = 120.509033
current_seq = 85
count = 80
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 27us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.509392
last_received_ts = 120.509033
last_seq = 85
current_ts = 120.526062
current_received_ts = 120.525688
current_seq = 86
count = 81
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.526062
last_received_ts = 120.525688
last_seq = 86
current_ts = 120.542732
current_received_ts = 120.542358
current_seq = 87
count = 82
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.542732
last_received_ts = 120.542358
last_seq = 87
current_ts = 120.559395
current_received_ts = 120.559036
current_seq = 88
count = 83
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.559395
last_received_ts = 120.559036
last_seq = 88
current_ts = 120.576073
current_received_ts = 120.575699
current_seq = 89
count = 84
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.576073
last_received_ts = 120.575699
last_seq = 89
current_ts = 120.592735
current_received_ts = 120.592369
current_seq = 90
count = 85
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 25us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.592735
last_received_ts = 120.592369
last_seq = 90
current_ts = 120.609421
current_received_ts = 120.609047
current_seq = 91
count = 86
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 25us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.609421
last_received_ts = 120.609047
last_seq = 91
current_ts = 120.626083
current_received_ts = 120.625702
current_seq = 92
count = 87
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.626083
last_received_ts = 120.625702
last_seq = 92
current_ts = 120.642746
current_received_ts = 120.642372
current_seq = 93
count = 88
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.642746
last_received_ts = 120.642372
last_seq = 93
current_ts = 120.659409
current_received_ts = 120.659042
current_seq = 94
count = 89
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 27us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.659409
last_received_ts = 120.659042
last_seq = 94
current_ts = 120.676086
current_received_ts = 120.675667
current_seq = 95
count = 90
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 31us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.676086
last_received_ts = 120.675667
last_seq = 95
current_ts = 120.692749
current_received_ts = 120.692307
current_seq = 96
count = 91
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 27us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.692749
last_received_ts = 120.692307
last_seq = 96
current_ts = 120.709427
current_received_ts = 120.708939
current_seq = 97
count = 92
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.709427
last_received_ts = 120.708939
last_seq = 97
current_ts = 120.726089
current_received_ts = 120.725647
current_seq = 98
count = 93
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.726089
last_received_ts = 120.725647
last_seq = 98
current_ts = 120.742760
current_received_ts = 120.742310
current_seq = 99
count = 94
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.742760
last_received_ts = 120.742310
last_seq = 99
current_ts = 120.759430
current_received_ts = 120.758980
current_seq = 100
count = 95
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 50us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.759430
last_received_ts = 120.758980
last_seq = 100
current_ts = 120.776093
current_received_ts = 120.775719
current_seq = 101
count = 96
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.776093
last_received_ts = 120.775719
last_seq = 101
current_ts = 120.792763
current_received_ts = 120.792389
current_seq = 102
count = 97
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.792763
last_received_ts = 120.792389
last_seq = 102
current_ts = 120.809441
current_received_ts = 120.808945
current_seq = 103
count = 98
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.809441
last_received_ts = 120.808945
last_seq = 103
current_ts = 120.826111
current_received_ts = 120.825829
current_seq = 104
count = 99
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 252us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.826111
last_received_ts = 120.825829
last_seq = 104
current_ts = 120.842773
current_received_ts = 120.842476
current_seq = 105
count = 100
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.842773
last_received_ts = 120.842476
last_seq = 105
current_ts = 120.859436
current_received_ts = 120.859146
current_seq = 106
count = 101
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 25us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.859436
last_received_ts = 120.859146
last_seq = 106
current_ts = 120.876106
current_received_ts = 120.875809
current_seq = 107
count = 102
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 25us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.876106
last_received_ts = 120.875809
last_seq = 107
current_ts = 120.892784
current_received_ts = 120.892494
current_seq = 108
count = 103
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 27us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.892784
last_received_ts = 120.892494
last_seq = 108
current_ts = 120.909447
current_received_ts = 120.909157
current_seq = 109
count = 104
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.909447
last_received_ts = 120.909157
last_seq = 109
current_ts = 120.926117
current_received_ts = 120.925819
current_seq = 110
count = 105
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.926117
last_received_ts = 120.925819
last_seq = 110
current_ts = 120.942787
current_received_ts = 120.942490
current_seq = 111
count = 106
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.942787
last_received_ts = 120.942490
last_seq = 111
current_ts = 120.959457
current_received_ts = 120.959183
current_seq = 112
count = 107
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.959457
last_received_ts = 120.959183
last_seq = 112
current_ts = 120.976120
current_received_ts = 120.975822
current_seq = 113
count = 108
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 25us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.976120
last_received_ts = 120.975822
last_seq = 113
current_ts = 120.992790
current_received_ts = 120.992493
current_seq = 114
count = 109
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 25us
(kms_flip:3397) DEBUG: name = flip
last_ts = 120.992790
last_received_ts = 120.992493
last_seq = 114
current_ts = 121.009468
current_received_ts = 121.009109
current_seq = 115
count = 110
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 121.009468
last_received_ts = 121.009109
last_seq = 115
current_ts = 121.026131
current_received_ts = 121.025764
current_seq = 116
count = 111
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 25us
(kms_flip:3397) DEBUG: name = flip
last_ts = 121.026131
last_received_ts = 121.025764
last_seq = 116
current_ts = 121.042801
current_received_ts = 121.042427
current_seq = 117
count = 112
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 121.042801
last_received_ts = 121.042427
last_seq = 117
current_ts = 121.059464
current_received_ts = 121.059097
current_seq = 118
count = 113
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 25us
(kms_flip:3397) DEBUG: name = flip
last_ts = 121.059464
last_received_ts = 121.059097
last_seq = 118
current_ts = 121.076134
current_received_ts = 121.075760
current_seq = 119
count = 114
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 121.076134
last_received_ts = 121.075760
last_seq = 119
current_ts = 121.092804
current_received_ts = 121.092361
current_seq = 120
count = 115
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 121.092804
last_received_ts = 121.092361
last_seq = 120
current_ts = 121.109474
current_received_ts = 121.109039
current_seq = 121
count = 116
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 26us
(kms_flip:3397) DEBUG: name = flip
last_ts = 121.109474
last_received_ts = 121.109039
last_seq = 121
current_ts = 121.126144
current_received_ts = 121.125595
current_seq = 122
count = 117
seq_step = 1
(kms_flip:3397) DEBUG: Vblank took 625us
(kms_flip:3397) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930:
(kms_flip:3397) CRITICAL: Failed assertion: end - start < 500
(kms_flip:3397) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:3397) igt_core-INFO: Stack trace:
(kms_flip:3397) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:3397) igt_core-INFO:   #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0()
(kms_flip:3397) igt_core-INFO:   #2 ../tests/kms_flip.c:1891 run_test()
(kms_flip:3397) igt_core-INFO:   #3 ../tests/kms_flip.c:2162 __igt_unique____real_main2047()
(kms_flip:3397) igt_core-INFO:   #4 ../tests/kms_flip.c:2047 main()
(kms_flip:3397) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3397) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3397) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-DP2: FAIL (2.821s)

Dmesg

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [119.548207] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mplla[0] = 0x0000

<7> [119.548296] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mplla[1] = 0x0000

<7> [119.548383] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mplla[2] = 0x0000

<7> [119.548479] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mplla[3] = 0x0000

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

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

<7> [119.548752] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mplla[6] = 0x0000

<7> [119.548840] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mplla[7] = 0x0000

<7> [119.548929] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] mplla[8] = 0x0000

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [119.553942] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] minimum HBlank: 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [119.555446] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port clock: 270000, pipe src: 1920x1080+0+0, pixel rate 148500, min cdclk 192000

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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