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

Detail	Value
Duration	3.09 seconds
Hostname	shard-bmg-1
Igt-Version	IGT-Version: 2.4-gf67fcb244 (x86_64) (Linux: 7.1.0-rc1-lgci-xe-xe-4944-aea2c496abcf55b64-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:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest C-DP2: FAIL (3.087s)
Err	Starting dynamic subtest: C-DP2 (kms_flip:4222) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:4222) CRITICAL: Failed assertion: end - start < 500 (kms_flip:4222) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest C-DP2 failed. ** DEBUG (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 172.670746 last_received_ts = 172.670380 last_seq = 107 current_ts = 172.687408 current_received_ts = 172.687057 current_seq = 108 count = 48 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 172.687408 last_received_ts = 172.687057 last_seq = 108 current_ts = 172.704086 current_received_ts = 172.703720 current_seq = 109 count = 49 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 172.704086 last_received_ts = 172.703720 last_seq = 109 current_ts = 172.720749 current_received_ts = 172.720383 current_seq = 110 count = 50 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 172.720749 last_received_ts = 172.720383 last_seq = 110 current_ts = 172.737411 current_received_ts = 172.737045 current_seq = 111 count = 51 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 172.737411 last_received_ts = 172.737045 last_seq = 111 current_ts = 172.754074 current_received_ts = 172.753708 current_seq = 112 count = 52 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 172.754074 last_received_ts = 172.753708 last_seq = 112 current_ts = 172.770752 current_received_ts = 172.770370 current_seq = 113 count = 53 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 172.770752 last_received_ts = 172.770370 last_seq = 113 current_ts = 172.787415 current_received_ts = 172.787048 current_seq = 114 count = 54 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 172.787415 last_received_ts = 172.787048 last_seq = 114 current_ts = 172.804092 current_received_ts = 172.803711 current_seq = 115 count = 55 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 172.804092 last_received_ts = 172.803711 last_seq = 115 current_ts = 172.820740 current_received_ts = 172.820389 current_seq = 116 count = 56 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 27us (kms_flip:4222) DEBUG: name = flip last_ts = 172.820740 last_received_ts = 172.820389 last_seq = 116 current_ts = 172.837418 current_received_ts = 172.837051 current_seq = 117 count = 57 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 172.837418 last_received_ts = 172.837051 last_seq = 117 current_ts = 172.854080 current_received_ts = 172.853714 current_seq = 118 count = 58 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 172.854080 last_received_ts = 172.853714 last_seq = 118 current_ts = 172.870743 current_received_ts = 172.870377 current_seq = 119 count = 59 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 172.870743 last_received_ts = 172.870377 last_seq = 119 current_ts = 172.887405 current_received_ts = 172.887039 current_seq = 120 count = 60 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 239us (kms_flip:4222) DEBUG: name = flip last_ts = 172.887405 last_received_ts = 172.887039 last_seq = 120 current_ts = 172.904083 current_received_ts = 172.903702 current_seq = 121 count = 61 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 172.904083 last_received_ts = 172.903702 last_seq = 121 current_ts = 172.920746 current_received_ts = 172.920364 current_seq = 122 count = 62 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 172.920746 last_received_ts = 172.920364 last_seq = 122 current_ts = 172.937408 current_received_ts = 172.937042 current_seq = 123 count = 63 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 172.937408 last_received_ts = 172.937042 last_seq = 123 current_ts = 172.954086 current_received_ts = 172.953705 current_seq = 124 count = 64 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 172.954086 last_received_ts = 172.953705 last_seq = 124 current_ts = 172.970734 current_received_ts = 172.970367 current_seq = 125 count = 65 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 172.970734 last_received_ts = 172.970367 last_seq = 125 current_ts = 172.987411 current_received_ts = 172.987045 current_seq = 126 count = 66 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 172.987411 last_received_ts = 172.987045 last_seq = 126 current_ts = 173.004074 current_received_ts = 173.003708 current_seq = 127 count = 67 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.004074 last_received_ts = 173.003708 last_seq = 127 current_ts = 173.020737 current_received_ts = 173.020386 current_seq = 128 count = 68 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 29us (kms_flip:4222) DEBUG: name = flip last_ts = 173.020737 last_received_ts = 173.020386 last_seq = 128 current_ts = 173.037415 current_received_ts = 173.037033 current_seq = 129 count = 69 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 173.037415 last_received_ts = 173.037033 last_seq = 129 current_ts = 173.054077 current_received_ts = 173.053696 current_seq = 130 count = 70 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.054077 last_received_ts = 173.053696 last_seq = 130 current_ts = 173.070740 current_received_ts = 173.070374 current_seq = 131 count = 71 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.070740 last_received_ts = 173.070374 last_seq = 131 current_ts = 173.087402 current_received_ts = 173.087051 current_seq = 132 count = 72 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 173.087402 last_received_ts = 173.087051 last_seq = 132 current_ts = 173.104065 current_received_ts = 173.103699 current_seq = 133 count = 73 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.104065 last_received_ts = 173.103699 last_seq = 133 current_ts = 173.120743 current_received_ts = 173.120361 current_seq = 134 count = 74 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.120743 last_received_ts = 173.120361 last_seq = 134 current_ts = 173.137405 current_received_ts = 173.137039 current_seq = 135 count = 75 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.137405 last_received_ts = 173.137039 last_seq = 135 current_ts = 173.154068 current_received_ts = 173.153702 current_seq = 136 count = 76 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.154068 last_received_ts = 173.153702 last_seq = 136 current_ts = 173.170731 current_received_ts = 173.170364 current_seq = 137 count = 77 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.170731 last_received_ts = 173.170364 last_seq = 137 current_ts = 173.187408 current_received_ts = 173.187042 current_seq = 138 count = 78 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 24us (kms_flip:4222) DEBUG: name = flip last_ts = 173.187408 last_received_ts = 173.187042 last_seq = 138 current_ts = 173.204071 current_received_ts = 173.203690 current_seq = 139 count = 79 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.204071 last_received_ts = 173.203690 last_seq = 139 current_ts = 173.220734 current_received_ts = 173.220367 current_seq = 140 count = 80 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.220734 last_received_ts = 173.220367 last_seq = 140 current_ts = 173.237396 current_received_ts = 173.237045 current_seq = 141 count = 81 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.237396 last_received_ts = 173.237045 last_seq = 141 current_ts = 173.254059 current_received_ts = 173.253693 current_seq = 142 count = 82 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.254059 last_received_ts = 173.253693 last_seq = 142 current_ts = 173.270737 current_received_ts = 173.270355 current_seq = 143 count = 83 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.270737 last_received_ts = 173.270355 last_seq = 143 current_ts = 173.287399 current_received_ts = 173.287033 current_seq = 144 count = 84 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 24us (kms_flip:4222) DEBUG: name = flip last_ts = 173.287399 last_received_ts = 173.287033 last_seq = 144 current_ts = 173.304077 current_received_ts = 173.303772 current_seq = 145 count = 85 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 173.304077 last_received_ts = 173.303772 last_seq = 145 current_ts = 173.320740 current_received_ts = 173.320435 current_seq = 146 count = 86 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 173.320740 last_received_ts = 173.320435 last_seq = 146 current_ts = 173.337402 current_received_ts = 173.337112 current_seq = 147 count = 87 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.337402 last_received_ts = 173.337112 last_seq = 147 current_ts = 173.354065 current_received_ts = 173.353775 current_seq = 148 count = 88 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 173.354065 last_received_ts = 173.353775 last_seq = 148 current_ts = 173.370743 current_received_ts = 173.370422 current_seq = 149 count = 89 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.370743 last_received_ts = 173.370422 last_seq = 149 current_ts = 173.387405 current_received_ts = 173.387100 current_seq = 150 count = 90 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 173.387405 last_received_ts = 173.387100 last_seq = 150 current_ts = 173.404068 current_received_ts = 173.403763 current_seq = 151 count = 91 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.404068 last_received_ts = 173.403763 last_seq = 151 current_ts = 173.420731 current_received_ts = 173.420456 current_seq = 152 count = 92 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 27us (kms_flip:4222) DEBUG: name = flip last_ts = 173.420731 last_received_ts = 173.420456 last_seq = 152 current_ts = 173.437393 current_received_ts = 173.437073 current_seq = 153 count = 93 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 34us (kms_flip:4222) DEBUG: name = flip last_ts = 173.437393 last_received_ts = 173.437073 last_seq = 153 current_ts = 173.454056 current_received_ts = 173.453690 current_seq = 154 count = 94 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 27us (kms_flip:4222) DEBUG: name = flip last_ts = 173.454056 last_received_ts = 173.453690 last_seq = 154 current_ts = 173.470718 current_received_ts = 173.470352 current_seq = 155 count = 95 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.470718 last_received_ts = 173.470352 last_seq = 155 current_ts = 173.487396 current_received_ts = 173.487061 current_seq = 156 count = 96 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 173.487396 last_received_ts = 173.487061 last_seq = 156 current_ts = 173.504059 current_received_ts = 173.503693 current_seq = 157 count = 97 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.504059 last_received_ts = 173.503693 last_seq = 157 current_ts = 173.520721 current_received_ts = 173.520355 current_seq = 158 count = 98 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.520721 last_received_ts = 173.520355 last_seq = 158 current_ts = 173.537384 current_received_ts = 173.537033 current_seq = 159 count = 99 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.537384 last_received_ts = 173.537033 last_seq = 159 current_ts = 173.554062 current_received_ts = 173.553680 current_seq = 160 count = 100 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 173.554062 last_received_ts = 173.553680 last_seq = 160 current_ts = 173.570724 current_received_ts = 173.570358 current_seq = 161 count = 101 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 173.570724 last_received_ts = 173.570358 last_seq = 161 current_ts = 173.587387 current_received_ts = 173.587036 current_seq = 162 count = 102 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 173.587387 last_received_ts = 173.587036 last_seq = 162 current_ts = 173.604050 current_received_ts = 173.603683 current_seq = 163 count = 103 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 173.604050 last_received_ts = 173.603683 last_seq = 163 current_ts = 173.620728 current_received_ts = 173.620346 current_seq = 164 count = 104 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 173.620728 last_received_ts = 173.620346 last_seq = 164 current_ts = 173.637390 current_received_ts = 173.637039 current_seq = 165 count = 105 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 173.637390 last_received_ts = 173.637039 last_seq = 165 current_ts = 173.654053 current_received_ts = 173.653687 current_seq = 166 count = 106 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 173.654053 last_received_ts = 173.653687 last_seq = 166 current_ts = 173.670715 current_received_ts = 173.670349 current_seq = 167 count = 107 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.670715 last_received_ts = 173.670349 last_seq = 167 current_ts = 173.687378 current_received_ts = 173.687042 current_seq = 168 count = 108 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 173.687378 last_received_ts = 173.687042 last_seq = 168 current_ts = 173.704056 current_received_ts = 173.703674 current_seq = 169 count = 109 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.704056 last_received_ts = 173.703674 last_seq = 169 current_ts = 173.720718 current_received_ts = 173.720352 current_seq = 170 count = 110 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 173.720718 last_received_ts = 173.720352 last_seq = 170 current_ts = 173.737381 current_received_ts = 173.737900 current_seq = 171 count = 111 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 288us (kms_flip:4222) DEBUG: name = flip last_ts = 173.737381 last_received_ts = 173.737900 last_seq = 171 current_ts = 173.754059 current_received_ts = 173.753693 current_seq = 172 count = 112 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.754059 last_received_ts = 173.753693 last_seq = 172 current_ts = 173.770721 current_received_ts = 173.770340 current_seq = 173 count = 113 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.770721 last_received_ts = 173.770340 last_seq = 173 current_ts = 173.787384 current_received_ts = 173.787048 current_seq = 174 count = 114 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 173.787384 last_received_ts = 173.787048 last_seq = 174 current_ts = 173.804047 current_received_ts = 173.803680 current_seq = 175 count = 115 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 173.804047 last_received_ts = 173.803680 last_seq = 175 current_ts = 173.820709 current_received_ts = 173.820343 current_seq = 176 count = 116 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.820709 last_received_ts = 173.820343 last_seq = 176 current_ts = 173.837387 current_received_ts = 173.837891 current_seq = 177 count = 117 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 38us (kms_flip:4222) DEBUG: name = flip last_ts = 173.837387 last_received_ts = 173.837891 last_seq = 177 current_ts = 173.854050 current_received_ts = 173.853699 current_seq = 178 count = 118 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 40us (kms_flip:4222) DEBUG: name = flip last_ts = 173.854050 last_received_ts = 173.853699 last_seq = 178 current_ts = 173.870712 current_received_ts = 173.870300 current_seq = 179 count = 119 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 34us (kms_flip:4222) DEBUG: name = flip last_ts = 173.870712 last_received_ts = 173.870300 last_seq = 179 current_ts = 173.887390 current_received_ts = 173.887283 current_seq = 180 count = 120 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 31us (kms_flip:4222) DEBUG: name = flip last_ts = 173.887390 last_received_ts = 173.887283 last_seq = 180 current_ts = 173.904037 current_received_ts = 173.903702 current_seq = 181 count = 121 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 29us (kms_flip:4222) DEBUG: name = flip last_ts = 173.904037 last_received_ts = 173.903702 last_seq = 181 current_ts = 173.920715 current_received_ts = 173.920364 current_seq = 182 count = 122 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 29us (kms_flip:4222) DEBUG: name = flip last_ts = 173.920715 last_received_ts = 173.920364 last_seq = 182 current_ts = 173.937378 current_received_ts = 173.937057 current_seq = 183 count = 123 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 172us (kms_flip:4222) DEBUG: name = flip last_ts = 173.937378 last_received_ts = 173.937057 last_seq = 183 current_ts = 173.954041 current_received_ts = 173.953690 current_seq = 184 count = 124 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 40us (kms_flip:4222) DEBUG: name = flip last_ts = 173.954041 last_received_ts = 173.953690 last_seq = 184 current_ts = 173.970703 current_received_ts = 173.970352 current_seq = 185 count = 125 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 28us (kms_flip:4222) DEBUG: name = flip last_ts = 173.970703 last_received_ts = 173.970352 last_seq = 185 current_ts = 173.987381 current_received_ts = 173.987030 current_seq = 186 count = 126 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 173.987381 last_received_ts = 173.987030 last_seq = 186 current_ts = 174.004044 current_received_ts = 174.003677 current_seq = 187 count = 127 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 174.004044 last_received_ts = 174.003677 last_seq = 187 current_ts = 174.020721 current_received_ts = 174.020447 current_seq = 188 count = 128 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 39us (kms_flip:4222) DEBUG: name = flip last_ts = 174.020721 last_received_ts = 174.020447 last_seq = 188 current_ts = 174.037384 current_received_ts = 174.037033 current_seq = 189 count = 129 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 30us (kms_flip:4222) DEBUG: name = flip last_ts = 174.037384 last_received_ts = 174.037033 last_seq = 189 current_ts = 174.054047 current_received_ts = 174.053665 current_seq = 190 count = 130 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 24us (kms_flip:4222) DEBUG: name = flip last_ts = 174.054047 last_received_ts = 174.053665 last_seq = 190 current_ts = 174.070724 current_received_ts = 174.070312 current_seq = 191 count = 131 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 20us (kms_flip:4222) DEBUG: name = flip last_ts = 174.070724 last_received_ts = 174.070312 last_seq = 191 current_ts = 174.087387 current_received_ts = 174.086960 current_seq = 192 count = 132 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 17us (kms_flip:4222) DEBUG: name = flip last_ts = 174.087387 last_received_ts = 174.086960 last_seq = 192 current_ts = 174.104050 current_received_ts = 174.103577 current_seq = 193 count = 133 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 174.104050 last_received_ts = 174.103577 last_seq = 193 current_ts = 174.120712 current_received_ts = 174.120300 current_seq = 194 count = 134 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 18us (kms_flip:4222) DEBUG: name = flip last_ts = 174.120712 last_received_ts = 174.120300 last_seq = 194 current_ts = 174.137375 current_received_ts = 174.136810 current_seq = 195 count = 135 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 17us (kms_flip:4222) DEBUG: name = flip last_ts = 174.137375 last_received_ts = 174.136810 last_seq = 195 current_ts = 174.154037 current_received_ts = 174.153671 current_seq = 196 count = 136 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 235us (kms_flip:4222) DEBUG: name = flip last_ts = 174.154037 last_received_ts = 174.153671 last_seq = 196 current_ts = 174.170715 current_received_ts = 174.170349 current_seq = 197 count = 137 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 234us (kms_flip:4222) DEBUG: name = flip last_ts = 174.170715 last_received_ts = 174.170349 last_seq = 197 current_ts = 174.187378 current_received_ts = 174.187042 current_seq = 198 count = 138 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 202us (kms_flip:4222) DEBUG: name = flip last_ts = 174.187378 last_received_ts = 174.187042 last_seq = 198 current_ts = 174.204041 current_received_ts = 174.203674 current_seq = 199 count = 139 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 27us (kms_flip:4222) DEBUG: name = flip last_ts = 174.204041 last_received_ts = 174.203674 last_seq = 199 current_ts = 174.220703 current_received_ts = 174.220337 current_seq = 200 count = 140 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 174.220703 last_received_ts = 174.220337 last_seq = 200 current_ts = 174.237366 current_received_ts = 174.237045 current_seq = 201 count = 141 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 28us (kms_flip:4222) DEBUG: name = flip last_ts = 174.237366 last_received_ts = 174.237045 last_seq = 201 current_ts = 174.254044 current_received_ts = 174.253677 current_seq = 202 count = 142 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 174.254044 last_received_ts = 174.253677 last_seq = 202 current_ts = 174.270706 current_received_ts = 174.270340 current_seq = 203 count = 143 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 174.270706 last_received_ts = 174.270340 last_seq = 203 current_ts = 174.287369 current_received_ts = 174.287033 current_seq = 204 count = 144 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 32us (kms_flip:4222) DEBUG: name = flip last_ts = 174.287369 last_received_ts = 174.287033 last_seq = 204 current_ts = 174.304031 current_received_ts = 174.303665 current_seq = 205 count = 145 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 27us (kms_flip:4222) DEBUG: name = flip last_ts = 174.304031 last_received_ts = 174.303665 last_seq = 205 current_ts = 174.320709 current_received_ts = 174.320374 current_seq = 206 count = 146 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 31us (kms_flip:4222) DEBUG: name = flip last_ts = 174.320709 last_received_ts = 174.320374 last_seq = 206 current_ts = 174.337372 current_received_ts = 174.337036 current_seq = 207 count = 147 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 41us (kms_flip:4222) DEBUG: name = flip last_ts = 174.337372 last_received_ts = 174.337036 last_seq = 207 current_ts = 174.354034 current_received_ts = 174.353699 current_seq = 208 count = 148 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 27us (kms_flip:4222) DEBUG: name = flip last_ts = 174.354034 last_received_ts = 174.353699 last_seq = 208 current_ts = 174.370697 current_received_ts = 174.370331 current_seq = 209 count = 149 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 27us (kms_flip:4222) DEBUG: name = flip last_ts = 174.370697 last_received_ts = 174.370331 last_seq = 209 current_ts = 174.387375 current_received_ts = 174.386993 current_seq = 210 count = 150 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 174.387375 last_received_ts = 174.386993 last_seq = 210 current_ts = 174.404037 current_received_ts = 174.403717 current_seq = 211 count = 151 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 235us (kms_flip:4222) DEBUG: name = flip last_ts = 174.404037 last_received_ts = 174.403717 last_seq = 211 current_ts = 174.420715 current_received_ts = 174.420395 current_seq = 212 count = 152 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 239us (kms_flip:4222) DEBUG: name = flip last_ts = 174.420715 last_received_ts = 174.420395 last_seq = 212 current_ts = 174.437378 current_received_ts = 174.437027 current_seq = 213 count = 153 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 230us (kms_flip:4222) DEBUG: name = flip last_ts = 174.437378 last_received_ts = 174.437027 last_seq = 213 current_ts = 174.454041 current_received_ts = 174.453659 current_seq = 214 count = 154 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 239us (kms_flip:4222) DEBUG: name = flip last_ts = 174.454041 last_received_ts = 174.453659 last_seq = 214 current_ts = 174.470703 current_received_ts = 174.470398 current_seq = 215 count = 155 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 233us (kms_flip:4222) DEBUG: name = flip last_ts = 174.470703 last_received_ts = 174.470398 last_seq = 215 current_ts = 174.487381 current_received_ts = 174.487061 current_seq = 216 count = 156 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 239us (kms_flip:4222) DEBUG: name = flip last_ts = 174.487381 last_received_ts = 174.487061 last_seq = 216 current_ts = 174.504044 current_received_ts = 174.503723 current_seq = 217 count = 157 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 234us (kms_flip:4222) DEBUG: name = flip last_ts = 174.504044 last_received_ts = 174.503723 last_seq = 217 current_ts = 174.520691 current_received_ts = 174.520401 current_seq = 218 count = 158 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 245us (kms_flip:4222) DEBUG: name = flip last_ts = 174.520691 last_received_ts = 174.520401 last_seq = 218 current_ts = 174.537369 current_received_ts = 174.537033 current_seq = 219 count = 159 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 230us (kms_flip:4222) DEBUG: name = flip last_ts = 174.537369 last_received_ts = 174.537033 last_seq = 219 current_ts = 174.554031 current_received_ts = 174.553665 current_seq = 220 count = 160 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 174.554031 last_received_ts = 174.553665 last_seq = 220 current_ts = 174.570694 current_received_ts = 174.570328 current_seq = 221 count = 161 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 174.570694 last_received_ts = 174.570328 last_seq = 221 current_ts = 174.587357 current_received_ts = 174.586990 current_seq = 222 count = 162 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 42us (kms_flip:4222) DEBUG: name = flip last_ts = 174.587357 last_received_ts = 174.586990 last_seq = 222 current_ts = 174.604019 current_received_ts = 174.603653 current_seq = 223 count = 163 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 174.604019 last_received_ts = 174.603653 last_seq = 223 current_ts = 174.620697 current_received_ts = 174.620316 current_seq = 224 count = 164 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 174.620697 last_received_ts = 174.620316 last_seq = 224 current_ts = 174.637360 current_received_ts = 174.636993 current_seq = 225 count = 165 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 25us (kms_flip:4222) DEBUG: name = flip last_ts = 174.637360 last_received_ts = 174.636993 last_seq = 225 current_ts = 174.654022 current_received_ts = 174.653656 current_seq = 226 count = 166 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 174.654022 last_received_ts = 174.653656 last_seq = 226 current_ts = 174.670700 current_received_ts = 174.670319 current_seq = 227 count = 167 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 26us (kms_flip:4222) DEBUG: name = flip last_ts = 174.670700 last_received_ts = 174.670319 last_seq = 227 current_ts = 174.687363 current_received_ts = 174.686981 current_seq = 228 count = 168 seq_step = 1 (kms_flip:4222) DEBUG: Vblank took 1171us (kms_flip:4222) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:4222) CRITICAL: Failed assertion: end - start < 500 (kms_flip:4222) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:4222) igt_core-INFO: Stack trace: (kms_flip:4222) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:4222) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() (kms_flip:4222) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() (kms_flip:4222) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() (kms_flip:4222) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() (kms_flip:4222) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:4222) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:4222) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest C-DP2: FAIL (3.087s)
Dmesg	<6> [171.850306] [IGT] kms_flip: starting dynamic subtest C-DP2 <7> [171.851247] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:556] <7> [171.851540] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:559] <7> [171.894413] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [171.894534] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe C] <7> [171.894604] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.enable (expected yes, found no) <7> [171.894730] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.active (expected yes, found no) <7> [171.894834] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in cpu_transcoder (expected 2, found -1) <7> [171.894938] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in lane_count (expected 4, found 0) <7> [171.895039] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in dp_m_n (expected tu 64 data 5767168/8388608 link 480597/524288, found tu 0, data 0/0 link 0/0) <7> [171.895141] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in output_types (expected 0x00000080, found 0x00000000) <7> [171.895239] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [171.895338] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [171.895436] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [171.895543] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [171.895640] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [171.895736] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [171.895832] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [171.895932] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [171.896035] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [171.896135] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0) <7> [171.896234] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0) <7> [171.896330] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [171.896429] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [171.896535] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [171.896633] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [171.896729] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [171.896827] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [171.896925] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [171.897023] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [171.897120] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [171.897216] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [171.897353] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0) <7> [171.897450] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0) <7> [171.897555] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [171.897651] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [171.897747] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [171.897842] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [171.897939] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0) <7> [171.898034] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in enhanced_framing (expected yes, found no) <7> [171.898132] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [171.898228] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [171.898324] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [171.898420] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe C] fastset requirement not met in port_clock (expected 162000, found 0) <7> [171.898521] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:269:pipe C] fastset requirement not met, forcing full modeset <7> [171.898624] xe 0000:03:00.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:269:pipe C] releasing TC PLL 2 <7> [171.898742] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xd -> 0x1 (total dbuf slices 0xf), mbus joined? no->no <7> [171.898828] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:269:pipe C] dbuf slices 0xc -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x4 -> 0x0 <7> [171.898931] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:263:cursor C] ddb (1989 - 2048) -> ( 0 - 0), size 59 -> 0 <7> [171.899025] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:269:pipe C] min cdclk: 192000 kHz -> 0 kHz <7> [171.899155] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:269:pipe C] enable: no [modeset] <7> [171.899257] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:153:plane 1C] fb: [NOFB], visible: no <7> [171.899358] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:183:plane 2C] fb: [NOFB], visible: no <7> [171.899459] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:213:plane 3C] fb: [NOFB], visible: no <7> [171.899573] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:243:plane 4C] fb: [NOFB], visible: no <7> [171.899671] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:253:plane 5C] fb: [NOFB], visible: no <7> [171.899770] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:263:cursor C] fb: [NOFB], visible: no <7> [171.900172] 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 C] <7> [171.928048] xe 0000:03:00.0: [drm:intel_audio_component_get_eld [xe]] Not valid for port E <7> [171.928674] xe 0000:03:00.0: [drm:intel_disable_transcoder [xe]] disabling pipe C <7> [171.944745] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2 <7> [171.947636] xe 0000:03:00.0: [drm:intel_dpll_disable [xe]] disable TC PLL 2 (active 0x4, on? 1) for [CRTC:269:pipe C] <7> [171.950138] xe 0000:03:00.0: [drm:intel_dpll_disable [xe]] disabling TC PLL 2 <7> [171.951016] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:507:DDI TC1/PHY F] <7> [171.951545] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:509:DP-MST A] <7> [171.952017] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:510:DP-MST B] <7> [171.952423] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:511:DP-MST C] <7> [171.952859] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:512:DP-MST D] <7> [171.952872] xe 0000:03:00.0: [drm:intel_audio_component_get_power [xe]] restored AUD_FREQ_CNTRL to 0x8010 <6> [171.953242] pcieport 0000:00:01.0: PME: Spurious native interrupt! <7> [171.953284] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:526:DDI TC2/PHY G] <7> [171.953909] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:528:DP-MST A] <7> [171.954266] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:529:DP-MST B] <7> [171.954665] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:530:DP-MST C] <7> [171.955111] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:531:DP-MST D] <7> [171.955439] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:538:DDI TC3/PHY H] <7> [171.955791] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:542:DDI TC4/PHY I] <7> [171.956082] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:544:DP-MST A] <7> [171.956365] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:545:DP-MST B] <7> [171.956661] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:546:DP-MST C] <7> [171.956926] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:547:DP-MST D] <7> [171.957186] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:527:DP-2] <7> [171.957700] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no) <7> [171.958138] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [171.958692] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_C <7> [171.959148] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x4 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [171.959642] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:269:pipe C] <7> [171.960271] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe B] <7> [171.961046] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:505:pipe D] <7> [171.961224] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe B] <7> [171.961256] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:527:DP-2] <7> [171.961358] xe 0000:03:00.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:527:DP-2] Limiting target display pipe bpp to 24 (EDID bpp 48, max requested bpp 24, max platform bpp 36) <7> [171.961574] xe 0000:03:00.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:526:DDI TC2/PHY G][CRTC:387:pipe B] DP link limits: pixel clock 148500 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 24 min link_bpp 18.0000 max link_bpp 24.0000 <7> [171.961759] xe 0000:03:00.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 162000 bpp input 24 compressed 0.0000 HDR no link rate required 445500 available 648000 <7> [171.961943] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:387:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [171.962117] xe 0000:03:00.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:526:DDI TC2/PHY G] [CRTC:387:pipe B] <7> [171.962284] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [171.962443] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [171.962618] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [171.962818] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [171.962985] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 5767168/8388608 link 480597/524288) <7> [171.963135] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000080) <7> [171.963279] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [171.963421] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [171.963582] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [171.963731] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [171.963877] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [171.964021] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [171.964170] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [171.964325] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [171.964494] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [171.964657] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084) <7> [171.964812] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089) <7> [171.964960] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [171.965111] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [171.965258] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [171.965398] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [171.965557] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [171.965696] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [171.965828] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [171.965963] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [171.966105] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [171.966245] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [171.966381] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084) <7> [171.966460] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_2 <7> [171.966523] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089) <7> [171.966653] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [171.966777] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [171.966899] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [171.967020] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [171.967136] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [171.967252] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in enhanced_framing (expected no, found yes) <7> [171.967363] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24) <7> [171.967471] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [171.967601] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [171.967709] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe B] fastset requirement not met in port_clock (expected 0, found 162000) <7> [171.967815] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:387:pipe B] fastset requirement not met, forcing full modeset <7> [171.967951] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [171.968045] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:387:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [171.968156] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:271:plane 1B] ddb ( 0 - 0) -> ( 0 - 4037), size 0 -> 4037 <7> [171.968241] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:381:cursor B] ddb ( 0 - 0) -> (4037 - 4096), size 0 -> 59 <7> [171.968321] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [171.968398] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 4, 9, 9, 17, 17, 17, 17, 0, 15, 0 <7> [171.968475] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 62, 62, 139, 139, 261, 261, 261, 261, 137, 230, 244 <7> [171.968564] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1B] 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> [171.968654] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] [CRTC:387:pipe B] data rate 594000 num active planes 1 <7> [171.968760] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 33600 required 624 qgv_peak_bw: 48000 <7> [171.968862] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 53000 required 624 qgv_peak_bw: 48000 <7> [171.968960] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 48000 for required data rate: 624 <7> [171.969057] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:387:pipe B] min cdclk: 0 kHz -> 192000 kHz <7> [171.969181] xe 0000:03:00.0: [drm:intel_find_dpll [xe]] [CRTC:387:pipe B] allocated TC PLL 2 <7> [171.969281] xe 0000:03:00.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:387:pipe B] reserving TC PLL 2 <7> [171.969382] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:387:pipe B] enable: yes [modeset] <7> [171.969495] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: DP (0x80), output format: RGB, sink format: RGB <7> [171.969597] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 24, dithering: 0 <7> [171.969697] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [171.969795] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [171.969894] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [171.969992] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [171.970089] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 5767168, data_n: 8388608, link_m: 480597, link_n: 524288, tu: 64 <7> [171.970187] 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> [171.970284] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: enabled <7> [171.970379] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [171.970474] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] psr: disabled, selective update: disabled, panel replay: disabled, selective fetch: disabled <7> [171.970582] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [171.970677] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] audio: 1, infoframes: 0, infoframes enabled: 0x0 <7> [171.970778] 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> [171.970875] 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> [171.970973] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 17 50 51 07 00 00 00 00 <7> [171.971071] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [171.971165] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [171.971260] 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> [171.971355] 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> [171.971450] 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> [171.971553] 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> [171.971649] 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> [171.971743] 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> [171.971838] 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> [171.971933] 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> [171.972028] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port clock: 162000, pixel rate 148500, min cdclk 192000, min voltage level 0 <7> [171.972123] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] linetime: 119, ips linetime: 0 <7> [171.972216] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [171.972315] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe src: 1920x1080+0+0 <7> [171.972409] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [171.972511] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [171.972608] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [171.972703] 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> [171.972798] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] c20pll_hw_state: <7> [171.972892] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] tx[0] = 0xbe88, tx[1] = 0x5800, tx[2] = 0x0000 <7> [171.972987] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [171.973080] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[0] = 0x50a8 <7> [171.973174] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[1] = 0x2120 <7> [171.973273] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[2] = 0xcd9a <7> [171.973372] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[3] = 0xbfc1 <7> [171.973466] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[4] = 0x5ab8 <7> [171.973576] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[5] = 0x4c34 <7> [171.973672] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[6] = 0x2000 <7> [171.973767] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[7] = 0x0001 <7> [171.973863] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[8] = 0x6000 <7> [171.973955] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[9] = 0x0000 <7> [171.974050] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[10] = 0x0000 <7> [171.974144] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vdr: custom width: 0x00, serdes rate: 0x40, hdmi rate: 0x00 <7> [171.974238] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [171.974332] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [171.974426] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [171.974527] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [171.974622] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [171.974716] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [171.974812] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [171.974907] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [171.975001] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [171.975100] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [171.975198] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [171.975295] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [171.975390] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:271:plane 1B] fb: [FB:556] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [171.975489] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [171.975585] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [171.975681] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:301:plane 2B] fb: [NOFB], visible: no <7> [171.975774] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:331:plane 3B] fb: [NOFB], visible: no <7> [171.975868] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:361:plane 4B] fb: [NOFB], visible: no <7> [171.975962] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:371:plane 5B] fb: [NOFB], visible: no <7> [171.976056] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:381:cursor B] fb: [NOFB], visible: no <7> [171.976681] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [171.976795] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [171.976917] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000) <7> [171.977029] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:507:DDI TC1/PHY F] <7> [171.977126] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:509:DP-MST A] <7> [171.977219] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:510:DP-MST B] <7> [171.977308] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:511:DP-MST C] <7> [171.977396] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:512:DP-MST D] <7> [171.977501] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:526:DDI TC2/PHY G] <7> [171.977591] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:528:DP-MST A] <7> [171.977678] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:529:DP-MST B] <7> [171.977765] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:530:DP-MST C] <7> [171.977850] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:531:DP-MST D] <7> [171.977936] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:538:DDI TC3/PHY H] <7> [171.978027] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:542:DDI TC4/PHY I] <7> [171.978117] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:544:DP-MST A] <7> [171.978206] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:545:DP-MST B] <7> [171.978294] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:546:DP-MST C] <7> [171.978380] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:547:DP-MST D] <7> [171.978475] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [171.978655] xe 0000:03:00.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: ) <7> [171.978738] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: yes) <7> [171.978842] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enable TC PLL 2 (active 0x2, on? 0) for [CRTC:387:pipe B] <7> [171.978942] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enabling TC PLL 2 <7> [171.983051] 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> [171.987806] 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> [171.988819] 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> [171.989261] xe 0000:03:00.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using LINK_BW_SET value 06 <7> [171.990772] 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> [171.991326] 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> [171.997429] 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> [171.997557] 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> [172.004457] 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> [172.004738] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Link Training passed at link rate = 162000, lane count = 4 <7> [172.006110] xe 0000:03:00.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [172.023698] 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 B], 40 bytes ELD <7> [172.037135] xe 0000:03:00.0: [drm:intel_audio_component_get_power [xe]] restored AUD_FREQ_CNTRL to 0x8010 <7> [172.040676] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:527:DP-2] <7> [172.041472] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:387:pipe B] <7> [172.110611] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2 <7> [174.021935] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2 <7> [174.043801] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2 <6> [174.313174] xe 0000:03:00.0: [drm] PL2 disabled for channel 0, val 0x00000000 <7> [174.321831] xe 0000:03:00.0: [drm:xe_hwmon_read [xe]] thermal data for group 0 val 0x25262525 <7> [174.321996] xe 0000:03:00.0: [drm:xe_hwmon_read [xe]] thermal data for group 1 val 0x26262525 <6> [174.938991] [IGT] kms_flip: finished subtest C-DP2, FAIL

Detail

Value

Duration

3.09 seconds

Hostname

shard-bmg-1

Igt-Version

IGT-Version: 2.4-gf67fcb244 (x86_64) (Linux: 7.1.0-rc1-lgci-xe-xe-4944-aea2c496abcf55b64-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:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-DP2: FAIL (3.087s)

Err

Starting dynamic subtest: C-DP2
(kms_flip:4222) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:4222) CRITICAL: Failed assertion: end - start < 500
(kms_flip:4222) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest C-DP2 failed.
**** DEBUG ****
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.670746
last_received_ts = 172.670380
last_seq = 107
current_ts = 172.687408
current_received_ts = 172.687057
current_seq = 108
count = 48
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.687408
last_received_ts = 172.687057
last_seq = 108
current_ts = 172.704086
current_received_ts = 172.703720
current_seq = 109
count = 49
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.704086
last_received_ts = 172.703720
last_seq = 109
current_ts = 172.720749
current_received_ts = 172.720383
current_seq = 110
count = 50
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.720749
last_received_ts = 172.720383
last_seq = 110
current_ts = 172.737411
current_received_ts = 172.737045
current_seq = 111
count = 51
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.737411
last_received_ts = 172.737045
last_seq = 111
current_ts = 172.754074
current_received_ts = 172.753708
current_seq = 112
count = 52
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.754074
last_received_ts = 172.753708
last_seq = 112
current_ts = 172.770752
current_received_ts = 172.770370
current_seq = 113
count = 53
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.770752
last_received_ts = 172.770370
last_seq = 113
current_ts = 172.787415
current_received_ts = 172.787048
current_seq = 114
count = 54
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.787415
last_received_ts = 172.787048
last_seq = 114
current_ts = 172.804092
current_received_ts = 172.803711
current_seq = 115
count = 55
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.804092
last_received_ts = 172.803711
last_seq = 115
current_ts = 172.820740
current_received_ts = 172.820389
current_seq = 116
count = 56
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 27us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.820740
last_received_ts = 172.820389
last_seq = 116
current_ts = 172.837418
current_received_ts = 172.837051
current_seq = 117
count = 57
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.837418
last_received_ts = 172.837051
last_seq = 117
current_ts = 172.854080
current_received_ts = 172.853714
current_seq = 118
count = 58
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.854080
last_received_ts = 172.853714
last_seq = 118
current_ts = 172.870743
current_received_ts = 172.870377
current_seq = 119
count = 59
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.870743
last_received_ts = 172.870377
last_seq = 119
current_ts = 172.887405
current_received_ts = 172.887039
current_seq = 120
count = 60
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 239us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.887405
last_received_ts = 172.887039
last_seq = 120
current_ts = 172.904083
current_received_ts = 172.903702
current_seq = 121
count = 61
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.904083
last_received_ts = 172.903702
last_seq = 121
current_ts = 172.920746
current_received_ts = 172.920364
current_seq = 122
count = 62
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.920746
last_received_ts = 172.920364
last_seq = 122
current_ts = 172.937408
current_received_ts = 172.937042
current_seq = 123
count = 63
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.937408
last_received_ts = 172.937042
last_seq = 123
current_ts = 172.954086
current_received_ts = 172.953705
current_seq = 124
count = 64
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.954086
last_received_ts = 172.953705
last_seq = 124
current_ts = 172.970734
current_received_ts = 172.970367
current_seq = 125
count = 65
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.970734
last_received_ts = 172.970367
last_seq = 125
current_ts = 172.987411
current_received_ts = 172.987045
current_seq = 126
count = 66
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 172.987411
last_received_ts = 172.987045
last_seq = 126
current_ts = 173.004074
current_received_ts = 173.003708
current_seq = 127
count = 67
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.004074
last_received_ts = 173.003708
last_seq = 127
current_ts = 173.020737
current_received_ts = 173.020386
current_seq = 128
count = 68
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 29us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.020737
last_received_ts = 173.020386
last_seq = 128
current_ts = 173.037415
current_received_ts = 173.037033
current_seq = 129
count = 69
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.037415
last_received_ts = 173.037033
last_seq = 129
current_ts = 173.054077
current_received_ts = 173.053696
current_seq = 130
count = 70
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.054077
last_received_ts = 173.053696
last_seq = 130
current_ts = 173.070740
current_received_ts = 173.070374
current_seq = 131
count = 71
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.070740
last_received_ts = 173.070374
last_seq = 131
current_ts = 173.087402
current_received_ts = 173.087051
current_seq = 132
count = 72
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.087402
last_received_ts = 173.087051
last_seq = 132
current_ts = 173.104065
current_received_ts = 173.103699
current_seq = 133
count = 73
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.104065
last_received_ts = 173.103699
last_seq = 133
current_ts = 173.120743
current_received_ts = 173.120361
current_seq = 134
count = 74
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.120743
last_received_ts = 173.120361
last_seq = 134
current_ts = 173.137405
current_received_ts = 173.137039
current_seq = 135
count = 75
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.137405
last_received_ts = 173.137039
last_seq = 135
current_ts = 173.154068
current_received_ts = 173.153702
current_seq = 136
count = 76
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.154068
last_received_ts = 173.153702
last_seq = 136
current_ts = 173.170731
current_received_ts = 173.170364
current_seq = 137
count = 77
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.170731
last_received_ts = 173.170364
last_seq = 137
current_ts = 173.187408
current_received_ts = 173.187042
current_seq = 138
count = 78
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 24us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.187408
last_received_ts = 173.187042
last_seq = 138
current_ts = 173.204071
current_received_ts = 173.203690
current_seq = 139
count = 79
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.204071
last_received_ts = 173.203690
last_seq = 139
current_ts = 173.220734
current_received_ts = 173.220367
current_seq = 140
count = 80
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.220734
last_received_ts = 173.220367
last_seq = 140
current_ts = 173.237396
current_received_ts = 173.237045
current_seq = 141
count = 81
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.237396
last_received_ts = 173.237045
last_seq = 141
current_ts = 173.254059
current_received_ts = 173.253693
current_seq = 142
count = 82
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.254059
last_received_ts = 173.253693
last_seq = 142
current_ts = 173.270737
current_received_ts = 173.270355
current_seq = 143
count = 83
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.270737
last_received_ts = 173.270355
last_seq = 143
current_ts = 173.287399
current_received_ts = 173.287033
current_seq = 144
count = 84
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 24us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.287399
last_received_ts = 173.287033
last_seq = 144
current_ts = 173.304077
current_received_ts = 173.303772
current_seq = 145
count = 85
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.304077
last_received_ts = 173.303772
last_seq = 145
current_ts = 173.320740
current_received_ts = 173.320435
current_seq = 146
count = 86
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.320740
last_received_ts = 173.320435
last_seq = 146
current_ts = 173.337402
current_received_ts = 173.337112
current_seq = 147
count = 87
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.337402
last_received_ts = 173.337112
last_seq = 147
current_ts = 173.354065
current_received_ts = 173.353775
current_seq = 148
count = 88
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.354065
last_received_ts = 173.353775
last_seq = 148
current_ts = 173.370743
current_received_ts = 173.370422
current_seq = 149
count = 89
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.370743
last_received_ts = 173.370422
last_seq = 149
current_ts = 173.387405
current_received_ts = 173.387100
current_seq = 150
count = 90
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.387405
last_received_ts = 173.387100
last_seq = 150
current_ts = 173.404068
current_received_ts = 173.403763
current_seq = 151
count = 91
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.404068
last_received_ts = 173.403763
last_seq = 151
current_ts = 173.420731
current_received_ts = 173.420456
current_seq = 152
count = 92
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 27us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.420731
last_received_ts = 173.420456
last_seq = 152
current_ts = 173.437393
current_received_ts = 173.437073
current_seq = 153
count = 93
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 34us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.437393
last_received_ts = 173.437073
last_seq = 153
current_ts = 173.454056
current_received_ts = 173.453690
current_seq = 154
count = 94
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 27us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.454056
last_received_ts = 173.453690
last_seq = 154
current_ts = 173.470718
current_received_ts = 173.470352
current_seq = 155
count = 95
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.470718
last_received_ts = 173.470352
last_seq = 155
current_ts = 173.487396
current_received_ts = 173.487061
current_seq = 156
count = 96
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.487396
last_received_ts = 173.487061
last_seq = 156
current_ts = 173.504059
current_received_ts = 173.503693
current_seq = 157
count = 97
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.504059
last_received_ts = 173.503693
last_seq = 157
current_ts = 173.520721
current_received_ts = 173.520355
current_seq = 158
count = 98
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.520721
last_received_ts = 173.520355
last_seq = 158
current_ts = 173.537384
current_received_ts = 173.537033
current_seq = 159
count = 99
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.537384
last_received_ts = 173.537033
last_seq = 159
current_ts = 173.554062
current_received_ts = 173.553680
current_seq = 160
count = 100
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.554062
last_received_ts = 173.553680
last_seq = 160
current_ts = 173.570724
current_received_ts = 173.570358
current_seq = 161
count = 101
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.570724
last_received_ts = 173.570358
last_seq = 161
current_ts = 173.587387
current_received_ts = 173.587036
current_seq = 162
count = 102
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.587387
last_received_ts = 173.587036
last_seq = 162
current_ts = 173.604050
current_received_ts = 173.603683
current_seq = 163
count = 103
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.604050
last_received_ts = 173.603683
last_seq = 163
current_ts = 173.620728
current_received_ts = 173.620346
current_seq = 164
count = 104
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.620728
last_received_ts = 173.620346
last_seq = 164
current_ts = 173.637390
current_received_ts = 173.637039
current_seq = 165
count = 105
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.637390
last_received_ts = 173.637039
last_seq = 165
current_ts = 173.654053
current_received_ts = 173.653687
current_seq = 166
count = 106
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.654053
last_received_ts = 173.653687
last_seq = 166
current_ts = 173.670715
current_received_ts = 173.670349
current_seq = 167
count = 107
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.670715
last_received_ts = 173.670349
last_seq = 167
current_ts = 173.687378
current_received_ts = 173.687042
current_seq = 168
count = 108
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.687378
last_received_ts = 173.687042
last_seq = 168
current_ts = 173.704056
current_received_ts = 173.703674
current_seq = 169
count = 109
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.704056
last_received_ts = 173.703674
last_seq = 169
current_ts = 173.720718
current_received_ts = 173.720352
current_seq = 170
count = 110
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.720718
last_received_ts = 173.720352
last_seq = 170
current_ts = 173.737381
current_received_ts = 173.737900
current_seq = 171
count = 111
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 288us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.737381
last_received_ts = 173.737900
last_seq = 171
current_ts = 173.754059
current_received_ts = 173.753693
current_seq = 172
count = 112
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.754059
last_received_ts = 173.753693
last_seq = 172
current_ts = 173.770721
current_received_ts = 173.770340
current_seq = 173
count = 113
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.770721
last_received_ts = 173.770340
last_seq = 173
current_ts = 173.787384
current_received_ts = 173.787048
current_seq = 174
count = 114
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.787384
last_received_ts = 173.787048
last_seq = 174
current_ts = 173.804047
current_received_ts = 173.803680
current_seq = 175
count = 115
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.804047
last_received_ts = 173.803680
last_seq = 175
current_ts = 173.820709
current_received_ts = 173.820343
current_seq = 176
count = 116
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.820709
last_received_ts = 173.820343
last_seq = 176
current_ts = 173.837387
current_received_ts = 173.837891
current_seq = 177
count = 117
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 38us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.837387
last_received_ts = 173.837891
last_seq = 177
current_ts = 173.854050
current_received_ts = 173.853699
current_seq = 178
count = 118
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 40us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.854050
last_received_ts = 173.853699
last_seq = 178
current_ts = 173.870712
current_received_ts = 173.870300
current_seq = 179
count = 119
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 34us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.870712
last_received_ts = 173.870300
last_seq = 179
current_ts = 173.887390
current_received_ts = 173.887283
current_seq = 180
count = 120
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 31us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.887390
last_received_ts = 173.887283
last_seq = 180
current_ts = 173.904037
current_received_ts = 173.903702
current_seq = 181
count = 121
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 29us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.904037
last_received_ts = 173.903702
last_seq = 181
current_ts = 173.920715
current_received_ts = 173.920364
current_seq = 182
count = 122
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 29us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.920715
last_received_ts = 173.920364
last_seq = 182
current_ts = 173.937378
current_received_ts = 173.937057
current_seq = 183
count = 123
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 172us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.937378
last_received_ts = 173.937057
last_seq = 183
current_ts = 173.954041
current_received_ts = 173.953690
current_seq = 184
count = 124
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 40us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.954041
last_received_ts = 173.953690
last_seq = 184
current_ts = 173.970703
current_received_ts = 173.970352
current_seq = 185
count = 125
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 28us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.970703
last_received_ts = 173.970352
last_seq = 185
current_ts = 173.987381
current_received_ts = 173.987030
current_seq = 186
count = 126
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 173.987381
last_received_ts = 173.987030
last_seq = 186
current_ts = 174.004044
current_received_ts = 174.003677
current_seq = 187
count = 127
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.004044
last_received_ts = 174.003677
last_seq = 187
current_ts = 174.020721
current_received_ts = 174.020447
current_seq = 188
count = 128
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 39us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.020721
last_received_ts = 174.020447
last_seq = 188
current_ts = 174.037384
current_received_ts = 174.037033
current_seq = 189
count = 129
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 30us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.037384
last_received_ts = 174.037033
last_seq = 189
current_ts = 174.054047
current_received_ts = 174.053665
current_seq = 190
count = 130
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 24us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.054047
last_received_ts = 174.053665
last_seq = 190
current_ts = 174.070724
current_received_ts = 174.070312
current_seq = 191
count = 131
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 20us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.070724
last_received_ts = 174.070312
last_seq = 191
current_ts = 174.087387
current_received_ts = 174.086960
current_seq = 192
count = 132
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 17us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.087387
last_received_ts = 174.086960
last_seq = 192
current_ts = 174.104050
current_received_ts = 174.103577
current_seq = 193
count = 133
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.104050
last_received_ts = 174.103577
last_seq = 193
current_ts = 174.120712
current_received_ts = 174.120300
current_seq = 194
count = 134
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 18us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.120712
last_received_ts = 174.120300
last_seq = 194
current_ts = 174.137375
current_received_ts = 174.136810
current_seq = 195
count = 135
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 17us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.137375
last_received_ts = 174.136810
last_seq = 195
current_ts = 174.154037
current_received_ts = 174.153671
current_seq = 196
count = 136
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 235us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.154037
last_received_ts = 174.153671
last_seq = 196
current_ts = 174.170715
current_received_ts = 174.170349
current_seq = 197
count = 137
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 234us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.170715
last_received_ts = 174.170349
last_seq = 197
current_ts = 174.187378
current_received_ts = 174.187042
current_seq = 198
count = 138
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 202us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.187378
last_received_ts = 174.187042
last_seq = 198
current_ts = 174.204041
current_received_ts = 174.203674
current_seq = 199
count = 139
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 27us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.204041
last_received_ts = 174.203674
last_seq = 199
current_ts = 174.220703
current_received_ts = 174.220337
current_seq = 200
count = 140
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.220703
last_received_ts = 174.220337
last_seq = 200
current_ts = 174.237366
current_received_ts = 174.237045
current_seq = 201
count = 141
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 28us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.237366
last_received_ts = 174.237045
last_seq = 201
current_ts = 174.254044
current_received_ts = 174.253677
current_seq = 202
count = 142
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.254044
last_received_ts = 174.253677
last_seq = 202
current_ts = 174.270706
current_received_ts = 174.270340
current_seq = 203
count = 143
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.270706
last_received_ts = 174.270340
last_seq = 203
current_ts = 174.287369
current_received_ts = 174.287033
current_seq = 204
count = 144
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 32us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.287369
last_received_ts = 174.287033
last_seq = 204
current_ts = 174.304031
current_received_ts = 174.303665
current_seq = 205
count = 145
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 27us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.304031
last_received_ts = 174.303665
last_seq = 205
current_ts = 174.320709
current_received_ts = 174.320374
current_seq = 206
count = 146
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 31us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.320709
last_received_ts = 174.320374
last_seq = 206
current_ts = 174.337372
current_received_ts = 174.337036
current_seq = 207
count = 147
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 41us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.337372
last_received_ts = 174.337036
last_seq = 207
current_ts = 174.354034
current_received_ts = 174.353699
current_seq = 208
count = 148
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 27us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.354034
last_received_ts = 174.353699
last_seq = 208
current_ts = 174.370697
current_received_ts = 174.370331
current_seq = 209
count = 149
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 27us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.370697
last_received_ts = 174.370331
last_seq = 209
current_ts = 174.387375
current_received_ts = 174.386993
current_seq = 210
count = 150
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.387375
last_received_ts = 174.386993
last_seq = 210
current_ts = 174.404037
current_received_ts = 174.403717
current_seq = 211
count = 151
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 235us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.404037
last_received_ts = 174.403717
last_seq = 211
current_ts = 174.420715
current_received_ts = 174.420395
current_seq = 212
count = 152
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 239us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.420715
last_received_ts = 174.420395
last_seq = 212
current_ts = 174.437378
current_received_ts = 174.437027
current_seq = 213
count = 153
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 230us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.437378
last_received_ts = 174.437027
last_seq = 213
current_ts = 174.454041
current_received_ts = 174.453659
current_seq = 214
count = 154
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 239us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.454041
last_received_ts = 174.453659
last_seq = 214
current_ts = 174.470703
current_received_ts = 174.470398
current_seq = 215
count = 155
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 233us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.470703
last_received_ts = 174.470398
last_seq = 215
current_ts = 174.487381
current_received_ts = 174.487061
current_seq = 216
count = 156
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 239us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.487381
last_received_ts = 174.487061
last_seq = 216
current_ts = 174.504044
current_received_ts = 174.503723
current_seq = 217
count = 157
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 234us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.504044
last_received_ts = 174.503723
last_seq = 217
current_ts = 174.520691
current_received_ts = 174.520401
current_seq = 218
count = 158
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 245us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.520691
last_received_ts = 174.520401
last_seq = 218
current_ts = 174.537369
current_received_ts = 174.537033
current_seq = 219
count = 159
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 230us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.537369
last_received_ts = 174.537033
last_seq = 219
current_ts = 174.554031
current_received_ts = 174.553665
current_seq = 220
count = 160
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.554031
last_received_ts = 174.553665
last_seq = 220
current_ts = 174.570694
current_received_ts = 174.570328
current_seq = 221
count = 161
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.570694
last_received_ts = 174.570328
last_seq = 221
current_ts = 174.587357
current_received_ts = 174.586990
current_seq = 222
count = 162
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 42us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.587357
last_received_ts = 174.586990
last_seq = 222
current_ts = 174.604019
current_received_ts = 174.603653
current_seq = 223
count = 163
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.604019
last_received_ts = 174.603653
last_seq = 223
current_ts = 174.620697
current_received_ts = 174.620316
current_seq = 224
count = 164
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.620697
last_received_ts = 174.620316
last_seq = 224
current_ts = 174.637360
current_received_ts = 174.636993
current_seq = 225
count = 165
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 25us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.637360
last_received_ts = 174.636993
last_seq = 225
current_ts = 174.654022
current_received_ts = 174.653656
current_seq = 226
count = 166
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.654022
last_received_ts = 174.653656
last_seq = 226
current_ts = 174.670700
current_received_ts = 174.670319
current_seq = 227
count = 167
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 26us
(kms_flip:4222) DEBUG: name = flip
last_ts = 174.670700
last_received_ts = 174.670319
last_seq = 227
current_ts = 174.687363
current_received_ts = 174.686981
current_seq = 228
count = 168
seq_step = 1
(kms_flip:4222) DEBUG: Vblank took 1171us
(kms_flip:4222) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:4222) CRITICAL: Failed assertion: end - start < 500
(kms_flip:4222) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:4222) igt_core-INFO: Stack trace:
(kms_flip:4222) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:4222) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
(kms_flip:4222) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
(kms_flip:4222) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
(kms_flip:4222) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
(kms_flip:4222) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:4222) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:4222) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-DP2: FAIL (3.087s)

Dmesg

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

<7> [171.851247] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:556]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [171.900172] 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 C]

<7> [171.928048] xe 0000:03:00.0: [drm:intel_audio_component_get_eld [xe]] Not valid for port E

<7> [171.928674] xe 0000:03:00.0: [drm:intel_disable_transcoder [xe]] disabling pipe C

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

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

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

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

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

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

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

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

<7> [171.952872] xe 0000:03:00.0: [drm:intel_audio_component_get_power [xe]] restored AUD_FREQ_CNTRL to 0x8010

<6> [171.953242] pcieport 0000:00:01.0: PME: Spurious native interrupt!

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [171.958692] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_C

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

<7> [171.959642] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:269:pipe C]

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

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

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

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

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

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

<7> [171.961759] xe 0000:03:00.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 162000 bpp input 24 compressed 0.0000 HDR no link rate required 445500 available 648000

<7> [171.961943] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:387:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [171.968156] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:271:plane 1B] ddb ( 0 - 0) -> ( 0 - 4037), size 0 -> 4037

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

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

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

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

<7> [171.968564] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1B] 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> [171.968654] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] [CRTC:387:pipe B] data rate 594000 num active planes 1

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

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

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

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

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

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

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

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

<7> [171.969597] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 24, dithering: 0

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

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

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

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

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

<7> [171.970187] 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> [171.970284] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: enabled

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

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

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

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

<7> [171.970778] 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> [171.970875] 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> [171.970973] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 17 50 51 07 00 00 00 00

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

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

<7> [171.971260] 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> [171.971355] 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> [171.971450] 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> [171.971553] 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> [171.971649] 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> [171.971743] 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> [171.971838] 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> [171.971933] 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> [171.972028] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port clock: 162000, pixel rate 148500, min cdclk 192000, min voltage level 0

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

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

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

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

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

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

<7> [171.972703] 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> [171.972798] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] c20pll_hw_state:

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [171.976795] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_B

<7> [171.976917] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [171.978738] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: yes)

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

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

<7> [171.983051] 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> [171.987806] 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> [171.988819] 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> [171.989261] xe 0000:03:00.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using LINK_BW_SET value 06

<7> [171.990772] 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> [171.991326] 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> [171.997429] 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> [171.997557] 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> [172.004457] 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> [172.004738] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Link Training passed at link rate = 162000, lane count = 4

<7> [172.006110] xe 0000:03:00.0: [drm:intel_enable_transcoder [xe]] enabling pipe B

<7> [172.023698] 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 B], 40 bytes ELD

<7> [172.037135] xe 0000:03:00.0: [drm:intel_audio_component_get_power [xe]] restored AUD_FREQ_CNTRL to 0x8010

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

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

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

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

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

<6> [174.313174] xe 0000:03:00.0: [drm] PL2 disabled for channel 0, val 0x00000000

<7> [174.321831] xe 0000:03:00.0: [drm:xe_hwmon_read [xe]] thermal data for group 0 val 0x25262525

<7> [174.321996] xe 0000:03:00.0: [drm:xe_hwmon_read [xe]] thermal data for group 1 val 0x26262525

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

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