igt@kms_flip@flip-vs-expired-vblank@a-edp1 on shard-lnl@xe-pw-166549v4 Test details

Detail	Value
Duration	3.28 seconds
Hostname	shard-lnl-8
Igt-Version	IGT-Version: 2.4-gb024a3b67 (x86_64) (Linux: 7.1.0-rc5-lgci-xe-xe-pw-166549v4-debug+ x86_64)
Out	Using IGT_SRANDOM=1779837425 for randomisation Opened device: /dev/dri/card0 Using monotonic timestamps Starting subtest: flip-vs-expired-vblank Starting dynamic subtest: A-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2106 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest A-eDP1: FAIL (3.279s)
Err	Starting subtest: flip-vs-expired-vblank Starting dynamic subtest: A-eDP1 [251.399189] (kms_flip:6990) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [251.399285] (kms_flip:6990) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest A-eDP1 failed. ** DEBUG [248.320949] (kms_flip:6990) intel_allocator_simple-DEBUG: <ial: 0x61154167c9a0, fd: 5> objects: 3, reserved_areas: 0 [248.320950] (kms_flip:6990) intel_allocator_simple-DEBUG: <ial: 0x61154167c9a0, fd: 5> objects: 3, reserved_areas: 0 [248.325185] (kms_flip:6990) intel_allocator_simple-DEBUG: Using simple allocator [248.328790] (kms_flip:6990) intel_allocator_simple-DEBUG: <ial: 0x611541679ae0, fd: 5> objects: 3, reserved_areas: 0 [248.328791] (kms_flip:6990) intel_allocator_simple-DEBUG: <ial: 0x611541679ae0, fd: 5> objects: 3, reserved_areas: 0 [248.344304] (kms_flip:6990) intel_allocator_simple-DEBUG: Using simple allocator [248.347729] (kms_flip:6990) intel_allocator_simple-DEBUG: <ial: 0x61154167c890, fd: 5> objects: 3, reserved_areas: 0 [248.347731] (kms_flip:6990) intel_allocator_simple-DEBUG: <ial: 0x61154167c890, fd: 5> objects: 3, reserved_areas: 0 [248.349234] (kms_flip:6990) igt_kms-INFO: 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa [248.369373] (kms_flip:6990) DEBUG: No stale events found [249.453697] (kms_flip:6990) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0 [249.453966] (kms_flip:6990) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0 [249.481888] (kms_flip:6990) DEBUG: name = flip last_ts = 0.000000 last_received_ts = 0.000000 last_seq = 0 current_ts = 251.020309 current_received_ts = 251.019608 current_seq = 3083 count = 0 seq_step = 1 [249.482036] (kms_flip:6990) DEBUG: Vblank took 138us [249.498508] (kms_flip:6990) DEBUG: name = flip last_ts = 251.020309 last_received_ts = 251.019608 last_seq = 3083 current_ts = 251.036957 current_received_ts = 251.036240 current_seq = 3084 count = 1 seq_step = 1 [249.498618] (kms_flip:6990) DEBUG: Vblank took 106us [249.515218] (kms_flip:6990) DEBUG: name = flip last_ts = 251.036957 last_received_ts = 251.036240 last_seq = 3084 current_ts = 251.053635 current_received_ts = 251.052948 current_seq = 3085 count = 2 seq_step = 1 [249.515266] (kms_flip:6990) DEBUG: Vblank took 45us [249.531877] (kms_flip:6990) DEBUG: name = flip last_ts = 251.053635 last_received_ts = 251.052948 last_seq = 3085 current_ts = 251.070297 current_received_ts = 251.069611 current_seq = 3086 count = 3 seq_step = 1 [249.531926] (kms_flip:6990) DEBUG: Vblank took 44us [249.548519] (kms_flip:6990) DEBUG: name = flip last_ts = 251.070297 last_received_ts = 251.069611 last_seq = 3086 current_ts = 251.086960 current_received_ts = 251.086243 current_seq = 3087 count = 4 seq_step = 1 [249.548561] (kms_flip:6990) DEBUG: Vblank took 40us [249.565346] (kms_flip:6990) DEBUG: name = flip last_ts = 251.086960 last_received_ts = 251.086243 last_seq = 3087 current_ts = 251.103622 current_received_ts = 251.103073 current_seq = 3088 count = 5 seq_step = 1 [249.565407] (kms_flip:6990) DEBUG: Vblank took 53us [249.581893] (kms_flip:6990) DEBUG: name = flip last_ts = 251.103622 last_received_ts = 251.103073 last_seq = 3088 current_ts = 251.120285 current_received_ts = 251.119614 current_seq = 3089 count = 6 seq_step = 1 [249.582023] (kms_flip:6990) DEBUG: Vblank took 123us [249.598524] (kms_flip:6990) DEBUG: name = flip last_ts = 251.120285 last_received_ts = 251.119614 last_seq = 3089 current_ts = 251.136963 current_received_ts = 251.136246 current_seq = 3090 count = 7 seq_step = 1 [249.598643] (kms_flip:6990) DEBUG: Vblank took 116us [249.615307] (kms_flip:6990) DEBUG: name = flip last_ts = 251.136963 last_received_ts = 251.136246 last_seq = 3090 current_ts = 251.153625 current_received_ts = 251.153030 current_seq = 3091 count = 8 seq_step = 1 [249.615367] (kms_flip:6990) DEBUG: Vblank took 52us [249.631875] (kms_flip:6990) DEBUG: name = flip last_ts = 251.153625 last_received_ts = 251.153030 last_seq = 3091 current_ts = 251.170273 current_received_ts = 251.169601 current_seq = 3092 count = 9 seq_step = 1 [249.631931] (kms_flip:6990) DEBUG: Vblank took 52us [249.648622] (kms_flip:6990) DEBUG: name = flip last_ts = 251.170273 last_received_ts = 251.169601 last_seq = 3092 current_ts = 251.186951 current_received_ts = 251.186340 current_seq = 3093 count = 10 seq_step = 1 [249.648697] (kms_flip:6990) DEBUG: Vblank took 67us [249.665316] (kms_flip:6990) DEBUG: name = flip last_ts = 251.186951 last_received_ts = 251.186340 last_seq = 3093 current_ts = 251.203613 current_received_ts = 251.203033 current_seq = 3094 count = 11 seq_step = 1 [249.665376] (kms_flip:6990) DEBUG: Vblank took 53us [249.681886] (kms_flip:6990) DEBUG: name = flip last_ts = 251.203613 last_received_ts = 251.203033 last_seq = 3094 current_ts = 251.220276 current_received_ts = 251.219604 current_seq = 3095 count = 12 seq_step = 1 [249.682012] (kms_flip:6990) DEBUG: Vblank took 118us [249.698461] (kms_flip:6990) DEBUG: name = flip last_ts = 251.220276 last_received_ts = 251.219604 last_seq = 3095 current_ts = 251.236938 current_received_ts = 251.236191 current_seq = 3096 count = 13 seq_step = 1 [249.698571] (kms_flip:6990) DEBUG: Vblank took 107us [249.715324] (kms_flip:6990) DEBUG: name = flip last_ts = 251.236938 last_received_ts = 251.236191 last_seq = 3096 current_ts = 251.253601 current_received_ts = 251.253052 current_seq = 3097 count = 14 seq_step = 1 [249.715385] (kms_flip:6990) DEBUG: Vblank took 53us [249.731853] (kms_flip:6990) DEBUG: name = flip last_ts = 251.253601 last_received_ts = 251.253052 last_seq = 3097 current_ts = 251.270264 current_received_ts = 251.269592 current_seq = 3098 count = 15 seq_step = 1 [249.731900] (kms_flip:6990) DEBUG: Vblank took 44us [249.748575] (kms_flip:6990) DEBUG: name = flip last_ts = 251.270264 last_received_ts = 251.269592 last_seq = 3098 current_ts = 251.286926 current_received_ts = 251.286301 current_seq = 3099 count = 16 seq_step = 1 [249.748649] (kms_flip:6990) DEBUG: Vblank took 65us [249.765319] (kms_flip:6990) DEBUG: name = flip last_ts = 251.286926 last_received_ts = 251.286301 last_seq = 3099 current_ts = 251.303604 current_received_ts = 251.303040 current_seq = 3100 count = 17 seq_step = 1 [249.765380] (kms_flip:6990) DEBUG: Vblank took 53us [249.781864] (kms_flip:6990) DEBUG: name = flip last_ts = 251.303604 last_received_ts = 251.303040 last_seq = 3100 current_ts = 251.320267 current_received_ts = 251.319595 current_seq = 3101 count = 18 seq_step = 1 [249.781970] (kms_flip:6990) DEBUG: Vblank took 99us [249.798477] (kms_flip:6990) DEBUG: name = flip last_ts = 251.320267 last_received_ts = 251.319595 last_seq = 3101 current_ts = 251.336929 current_received_ts = 251.336212 current_seq = 3102 count = 19 seq_step = 1 [249.798596] (kms_flip:6990) DEBUG: Vblank took 115us [249.815160] (kms_flip:6990) DEBUG: name = flip last_ts = 251.336929 last_received_ts = 251.336212 last_seq = 3102 current_ts = 251.353592 current_received_ts = 251.352905 current_seq = 3103 count = 20 seq_step = 1 [249.815204] (kms_flip:6990) DEBUG: Vblank took 41us [249.831960] (kms_flip:6990) DEBUG: name = flip last_ts = 251.353592 last_received_ts = 251.352905 last_seq = 3103 current_ts = 251.370255 current_received_ts = 251.369690 current_seq = 3104 count = 21 seq_step = 1 [249.832024] (kms_flip:6990) DEBUG: Vblank took 55us [249.848606] (kms_flip:6990) DEBUG: name = flip last_ts = 251.370255 last_received_ts = 251.369690 last_seq = 3104 current_ts = 251.386917 current_received_ts = 251.386337 current_seq = 3105 count = 22 seq_step = 1 [249.848669] (kms_flip:6990) DEBUG: Vblank took 56us [249.865191] (kms_flip:6990) DEBUG: name = flip last_ts = 251.386917 last_received_ts = 251.386337 last_seq = 3105 current_ts = 251.403580 current_received_ts = 251.402924 current_seq = 3106 count = 23 seq_step = 1 [249.865304] (kms_flip:6990) DEBUG: Vblank took 105us [249.881812] (kms_flip:6990) DEBUG: name = flip last_ts = 251.403580 last_received_ts = 251.402924 last_seq = 3106 current_ts = 251.420258 current_received_ts = 251.419556 current_seq = 3107 count = 24 seq_step = 1 [249.881927] (kms_flip:6990) DEBUG: Vblank took 112us [249.898526] (kms_flip:6990) DEBUG: name = flip last_ts = 251.420258 last_received_ts = 251.419556 last_seq = 3107 current_ts = 251.436920 current_received_ts = 251.436264 current_seq = 3108 count = 25 seq_step = 1 [249.898587] (kms_flip:6990) DEBUG: Vblank took 53us [249.915184] (kms_flip:6990) DEBUG: name = flip last_ts = 251.436920 last_received_ts = 251.436264 last_seq = 3108 current_ts = 251.453583 current_received_ts = 251.452911 current_seq = 3109 count = 26 seq_step = 1 [249.915296] (kms_flip:6990) DEBUG: Vblank took 106us [249.931938] (kms_flip:6990) DEBUG: name = flip last_ts = 251.453583 last_received_ts = 251.452911 last_seq = 3109 current_ts = 251.470245 current_received_ts = 251.469666 current_seq = 3110 count = 27 seq_step = 1 [249.932002] (kms_flip:6990) DEBUG: Vblank took 55us [249.948419] (kms_flip:6990) DEBUG: name = flip last_ts = 251.470245 last_received_ts = 251.469666 last_seq = 3110 current_ts = 251.486908 current_received_ts = 251.486160 current_seq = 3111 count = 28 seq_step = 1 [249.948518] (kms_flip:6990) DEBUG: Vblank took 92us [249.965165] (kms_flip:6990) DEBUG: name = flip last_ts = 251.486908 last_received_ts = 251.486160 last_seq = 3111 current_ts = 251.503571 current_received_ts = 251.502899 current_seq = 3112 count = 29 seq_step = 1 [249.965281] (kms_flip:6990) DEBUG: Vblank took 109us [249.981828] (kms_flip:6990) DEBUG: name = flip last_ts = 251.503571 last_received_ts = 251.502899 last_seq = 3112 current_ts = 251.520233 current_received_ts = 251.519577 current_seq = 3113 count = 30 seq_step = 1 [249.981877] (kms_flip:6990) DEBUG: Vblank took 46us [249.998394] (kms_flip:6990) DEBUG: name = flip last_ts = 251.520233 last_received_ts = 251.519577 last_seq = 3113 current_ts = 251.536896 current_received_ts = 251.536133 current_seq = 3114 count = 31 seq_step = 1 [249.998525] (kms_flip:6990) DEBUG: Vblank took 129us [250.015302] (kms_flip:6990) DEBUG: name = flip last_ts = 251.536896 last_received_ts = 251.536133 last_seq = 3114 current_ts = 251.553574 current_received_ts = 251.553040 current_seq = 3115 count = 32 seq_step = 1 [250.015361] (kms_flip:6990) DEBUG: Vblank took 52us [250.031820] (kms_flip:6990) DEBUG: name = flip last_ts = 251.553574 last_received_ts = 251.553040 last_seq = 3115 current_ts = 251.570236 current_received_ts = 251.569550 current_seq = 3116 count = 33 seq_step = 1 [250.031921] (kms_flip:6990) DEBUG: Vblank took 95us [250.048478] (kms_flip:6990) DEBUG: name = flip last_ts = 251.570236 last_received_ts = 251.569550 last_seq = 3116 current_ts = 251.586899 current_received_ts = 251.586212 current_seq = 3117 count = 34 seq_step = 1 [250.048564] (kms_flip:6990) DEBUG: Vblank took 76us [250.065156] (kms_flip:6990) DEBUG: name = flip last_ts = 251.586899 last_received_ts = 251.586212 last_seq = 3117 current_ts = 251.603561 current_received_ts = 251.602890 current_seq = 3118 count = 35 seq_step = 1 [250.065274] (kms_flip:6990) DEBUG: Vblank took 110us [250.081787] (kms_flip:6990) DEBUG: name = flip last_ts = 251.603561 last_received_ts = 251.602890 last_seq = 3118 current_ts = 251.620224 current_received_ts = 251.619537 current_seq = 3119 count = 36 seq_step = 1 [250.081837] (kms_flip:6990) DEBUG: Vblank took 46us [250.098469] (kms_flip:6990) DEBUG: name = flip last_ts = 251.620224 last_received_ts = 251.619537 last_seq = 3119 current_ts = 251.636887 current_received_ts = 251.636215 current_seq = 3120 count = 37 seq_step = 1 [250.098562] (kms_flip:6990) DEBUG: Vblank took 86us [250.115279] (kms_flip:6990) DEBUG: name = flip last_ts = 251.636887 last_received_ts = 251.636215 last_seq = 3120 current_ts = 251.653549 current_received_ts = 251.652985 current_seq = 3121 count = 38 seq_step = 1 [250.115341] (kms_flip:6990) DEBUG: Vblank took 54us [250.131820] (kms_flip:6990) DEBUG: name = flip last_ts = 251.653549 last_received_ts = 251.652985 last_seq = 3121 current_ts = 251.670212 current_received_ts = 251.669556 current_seq = 3122 count = 39 seq_step = 1 [250.131931] (kms_flip:6990) DEBUG: Vblank took 105us [250.148503] (kms_flip:6990) DEBUG: name = flip last_ts = 251.670212 last_received_ts = 251.669556 last_seq = 3122 current_ts = 251.686890 current_received_ts = 251.686249 current_seq = 3123 count = 40 seq_step = 1 [250.148574] (kms_flip:6990) DEBUG: Vblank took 63us [250.165211] (kms_flip:6990) DEBUG: name = flip last_ts = 251.686890 last_received_ts = 251.686249 last_seq = 3123 current_ts = 251.703552 current_received_ts = 251.702957 current_seq = 3124 count = 41 seq_step = 1 [250.165295] (kms_flip:6990) DEBUG: Vblank took 77us [250.181822] (kms_flip:6990) DEBUG: name = flip last_ts = 251.703552 last_received_ts = 251.702957 last_seq = 3124 current_ts = 251.720215 current_received_ts = 251.719559 current_seq = 3125 count = 42 seq_step = 1 [250.181925] (kms_flip:6990) DEBUG: Vblank took 96us [250.198492] (kms_flip:6990) DEBUG: name = flip last_ts = 251.720215 last_received_ts = 251.719559 last_seq = 3125 current_ts = 251.736877 current_received_ts = 251.736237 current_seq = 3126 count = 43 seq_step = 1 [250.198569] (kms_flip:6990) DEBUG: Vblank took 69us [250.215232] (kms_flip:6990) DEBUG: name = flip last_ts = 251.736877 last_received_ts = 251.736237 last_seq = 3126 current_ts = 251.753540 current_received_ts = 251.752975 current_seq = 3127 count = 44 seq_step = 1 [250.215323] (kms_flip:6990) DEBUG: Vblank took 84us [250.231797] (kms_flip:6990) DEBUG: name = flip last_ts = 251.753540 last_received_ts = 251.752975 last_seq = 3127 current_ts = 251.770203 current_received_ts = 251.769547 current_seq = 3128 count = 45 seq_step = 1 [250.231917] (kms_flip:6990) DEBUG: Vblank took 113us [250.248492] (kms_flip:6990) DEBUG: name = flip last_ts = 251.770203 last_received_ts = 251.769547 last_seq = 3128 current_ts = 251.786865 current_received_ts = 251.786240 current_seq = 3129 count = 46 seq_step = 1 [250.248565] (kms_flip:6990) DEBUG: Vblank took 65us [250.265235] (kms_flip:6990) DEBUG: name = flip last_ts = 251.786865 last_received_ts = 251.786240 last_seq = 3129 current_ts = 251.803528 current_received_ts = 251.802979 current_seq = 3130 count = 47 seq_step = 1 [250.265317] (kms_flip:6990) DEBUG: Vblank took 75us [250.281807] (kms_flip:6990) DEBUG: name = flip last_ts = 251.803528 last_received_ts = 251.802979 last_seq = 3130 current_ts = 251.820206 current_received_ts = 251.819550 current_seq = 3131 count = 48 seq_step = 1 [250.281916] (kms_flip:6990) DEBUG: Vblank took 102us [250.298464] (kms_flip:6990) DEBUG: name = flip last_ts = 251.820206 last_received_ts = 251.819550 last_seq = 3131 current_ts = 251.836868 current_received_ts = 251.836212 current_seq = 3132 count = 49 seq_step = 1 [250.298532] (kms_flip:6990) DEBUG: Vblank took 61us [250.315212] (kms_flip:6990) DEBUG: name = flip last_ts = 251.836868 last_received_ts = 251.836212 last_seq = 3132 current_ts = 251.853531 current_received_ts = 251.852951 current_seq = 3133 count = 50 seq_step = 1 [250.315296] (kms_flip:6990) DEBUG: Vblank took 77us [250.331769] (kms_flip:6990) DEBUG: name = flip last_ts = 251.853531 last_received_ts = 251.852951 last_seq = 3133 current_ts = 251.870193 current_received_ts = 251.869522 current_seq = 3134 count = 51 seq_step = 1 [250.331902] (kms_flip:6990) DEBUG: Vblank took 125us [250.348502] (kms_flip:6990) DEBUG: name = flip last_ts = 251.870193 last_received_ts = 251.869522 last_seq = 3134 current_ts = 251.886856 current_received_ts = 251.886246 current_seq = 3135 count = 52 seq_step = 1 [250.348566] (kms_flip:6990) DEBUG: Vblank took 56us [250.365210] (kms_flip:6990) DEBUG: name = flip last_ts = 251.886856 last_received_ts = 251.886246 last_seq = 3135 current_ts = 251.903519 current_received_ts = 251.902954 current_seq = 3136 count = 53 seq_step = 1 [250.365293] (kms_flip:6990) DEBUG: Vblank took 73us [250.381778] (kms_flip:6990) DEBUG: name = flip last_ts = 251.903519 last_received_ts = 251.902954 last_seq = 3136 current_ts = 251.920197 current_received_ts = 251.919525 current_seq = 3137 count = 54 seq_step = 1 [250.381891] (kms_flip:6990) DEBUG: Vblank took 105us [250.398455] (kms_flip:6990) DEBUG: name = flip last_ts = 251.920197 last_received_ts = 251.919525 last_seq = 3137 current_ts = 251.936859 current_received_ts = 251.936203 current_seq = 3138 count = 55 seq_step = 1 [250.398553] (kms_flip:6990) DEBUG: Vblank took 90us [250.415204] (kms_flip:6990) DEBUG: name = flip last_ts = 251.936859 last_received_ts = 251.936203 last_seq = 3138 current_ts = 251.953522 current_received_ts = 251.952957 current_seq = 3139 count = 56 seq_step = 1 [250.415287] (kms_flip:6990) DEBUG: Vblank took 76us [250.431779] (kms_flip:6990) DEBUG: name = flip last_ts = 251.953522 last_received_ts = 251.952957 last_seq = 3139 current_ts = 251.970184 current_received_ts = 251.969528 current_seq = 3140 count = 57 seq_step = 1 [250.431889] (kms_flip:6990) DEBUG: Vblank took 103us [250.448470] (kms_flip:6990) DEBUG: name = flip last_ts = 251.970184 last_received_ts = 251.969528 last_seq = 3140 current_ts = 251.986847 current_received_ts = 251.986221 current_seq = 3141 count = 58 seq_step = 1 [250.448536] (kms_flip:6990) DEBUG: Vblank took 57us [250.465173] (kms_flip:6990) DEBUG: name = flip last_ts = 251.986847 last_received_ts = 251.986221 last_seq = 3141 current_ts = 252.003510 current_received_ts = 252.002930 current_seq = 3142 count = 59 seq_step = 1 [250.465236] (kms_flip:6990) DEBUG: Vblank took 56us [250.481748] (kms_flip:6990) DEBUG: name = flip last_ts = 252.003510 last_received_ts = 252.002930 last_seq = 3142 current_ts = 252.020172 current_received_ts = 252.019501 current_seq = 3143 count = 60 seq_step = 1 [250.481865] (kms_flip:6990) DEBUG: Vblank took 109us [250.498430] (kms_flip:6990) DEBUG: name = flip last_ts = 252.020172 last_received_ts = 252.019501 last_seq = 3143 current_ts = 252.036835 current_received_ts = 252.036179 current_seq = 3144 count = 61 seq_step = 1 [250.498518] (kms_flip:6990) DEBUG: Vblank took 81us [250.515099] (kms_flip:6990) DEBUG: name = flip last_ts = 252.036835 last_received_ts = 252.036179 last_seq = 3144 current_ts = 252.053513 current_received_ts = 252.052856 current_seq = 3145 count = 62 seq_step = 1 [250.515210] (kms_flip:6990) DEBUG: Vblank took 104us [250.531752] (kms_flip:6990) DEBUG: name = flip last_ts = 252.053513 last_received_ts = 252.052856 last_seq = 3145 current_ts = 252.070175 current_received_ts = 252.069519 current_seq = 3146 count = 63 seq_step = 1 [250.531793] (kms_flip:6990) DEBUG: Vblank took 38us [250.548526] (kms_flip:6990) DEBUG: name = flip last_ts = 252.070175 last_received_ts = 252.069519 last_seq = 3146 current_ts = 252.086838 current_received_ts = 252.086273 current_seq = 3147 count = 64 seq_step = 1 [250.548592] (kms_flip:6990) DEBUG: Vblank took 58us [250.565168] (kms_flip:6990) DEBUG: name = flip last_ts = 252.086838 last_received_ts = 252.086273 last_seq = 3147 current_ts = 252.103500 current_received_ts = 252.102921 current_seq = 3148 count = 65 seq_step = 1 [250.565258] (kms_flip:6990) DEBUG: Vblank took 81us [250.581733] (kms_flip:6990) DEBUG: name = flip last_ts = 252.103500 last_received_ts = 252.102921 last_seq = 3148 current_ts = 252.120163 current_received_ts = 252.119492 current_seq = 3149 count = 66 seq_step = 1 [250.581851] (kms_flip:6990) DEBUG: Vblank took 115us [250.598425] (kms_flip:6990) DEBUG: name = flip last_ts = 252.120163 last_received_ts = 252.119492 last_seq = 3149 current_ts = 252.136826 current_received_ts = 252.136185 current_seq = 3150 count = 67 seq_step = 1 [250.598495] (kms_flip:6990) DEBUG: Vblank took 62us [250.615158] (kms_flip:6990) DEBUG: name = flip last_ts = 252.136826 last_received_ts = 252.136185 last_seq = 3150 current_ts = 252.153488 current_received_ts = 252.152908 current_seq = 3151 count = 68 seq_step = 1 [250.615224] (kms_flip:6990) DEBUG: Vblank took 59us [250.631743] (kms_flip:6990) DEBUG: name = flip last_ts = 252.153488 last_received_ts = 252.152908 last_seq = 3151 current_ts = 252.170151 current_received_ts = 252.169495 current_seq = 3152 count = 69 seq_step = 1 [250.631857] (kms_flip:6990) DEBUG: Vblank took 107us [250.648410] (kms_flip:6990) DEBUG: name = flip last_ts = 252.170151 last_received_ts = 252.169495 last_seq = 3152 current_ts = 252.186829 current_received_ts = 252.186172 current_seq = 3153 count = 70 seq_step = 1 [250.648484] (kms_flip:6990) DEBUG: Vblank took 66us [250.665148] (kms_flip:6990) DEBUG: name = flip last_ts = 252.186829 last_received_ts = 252.186172 last_seq = 3153 current_ts = 252.203491 current_received_ts = 252.202911 current_seq = 3154 count = 71 seq_step = 1 [250.665208] (kms_flip:6990) DEBUG: Vblank took 52us [250.681742] (kms_flip:6990) DEBUG: name = flip last_ts = 252.203491 last_received_ts = 252.202911 last_seq = 3154 current_ts = 252.220154 current_received_ts = 252.219498 current_seq = 3155 count = 72 seq_step = 1 [250.681853] (kms_flip:6990) DEBUG: Vblank took 103us [250.698366] (kms_flip:6990) DEBUG: name = flip last_ts = 252.220154 last_received_ts = 252.219498 last_seq = 3155 current_ts = 252.236816 current_received_ts = 252.236130 current_seq = 3156 count = 73 seq_step = 1 [250.698464] (kms_flip:6990) DEBUG: Vblank took 92us [250.715048] (kms_flip:6990) DEBUG: name = flip last_ts = 252.236816 last_received_ts = 252.236130 last_seq = 3156 current_ts = 252.253479 current_received_ts = 252.252808 current_seq = 3157 count = 74 seq_step = 1 [250.715167] (kms_flip:6990) DEBUG: Vblank took 111us [250.731803] (kms_flip:6990) DEBUG: name = flip last_ts = 252.253479 last_received_ts = 252.252808 last_seq = 3157 current_ts = 252.270142 current_received_ts = 252.269562 current_seq = 3158 count = 75 seq_step = 1 [250.731867] (kms_flip:6990) DEBUG: Vblank took 56us [250.748369] (kms_flip:6990) DEBUG: name = flip last_ts = 252.270142 last_received_ts = 252.269562 last_seq = 3158 current_ts = 252.286819 current_received_ts = 252.286133 current_seq = 3159 count = 76 seq_step = 1 [250.748473] (kms_flip:6990) DEBUG: Vblank took 97us [250.765006] (kms_flip:6990) DEBUG: name = flip last_ts = 252.286819 last_received_ts = 252.286133 last_seq = 3159 current_ts = 252.303467 current_received_ts = 252.302780 current_seq = 3160 count = 77 seq_step = 1 [250.765058] (kms_flip:6990) DEBUG: Vblank took 48us [250.781721] (kms_flip:6990) DEBUG: name = flip last_ts = 252.303467 last_received_ts = 252.302780 last_seq = 3160 current_ts = 252.320145 current_received_ts = 252.319489 current_seq = 3161 count = 78 seq_step = 1 [250.781835] (kms_flip:6990) DEBUG: Vblank took 106us [250.798341] (kms_flip:6990) DEBUG: name = flip last_ts = 252.320145 last_received_ts = 252.319489 last_seq = 3161 current_ts = 252.336807 current_received_ts = 252.336105 current_seq = 3162 count = 79 seq_step = 1 [250.798482] (kms_flip:6990) DEBUG: Vblank took 137us [250.815137] (kms_flip:6990) DEBUG: name = flip last_ts = 252.336807 last_received_ts = 252.336105 last_seq = 3162 current_ts = 252.353470 current_received_ts = 252.352905 current_seq = 3163 count = 80 seq_step = 1 [250.815197] (kms_flip:6990) DEBUG: Vblank took 53us [250.831711] (kms_flip:6990) DEBUG: name = flip last_ts = 252.353470 last_received_ts = 252.352905 last_seq = 3163 current_ts = 252.370132 current_received_ts = 252.369476 current_seq = 3164 count = 81 seq_step = 1 [250.831826] (kms_flip:6990) DEBUG: Vblank took 108us [250.848399] (kms_flip:6990) DEBUG: name = flip last_ts = 252.370132 last_received_ts = 252.369476 last_seq = 3164 current_ts = 252.386795 current_received_ts = 252.386169 current_seq = 3165 count = 82 seq_step = 1 [250.848459] (kms_flip:6990) DEBUG: Vblank took 54us [250.865107] (kms_flip:6990) DEBUG: name = flip last_ts = 252.386795 last_received_ts = 252.386169 last_seq = 3165 current_ts = 252.403458 current_received_ts = 252.402878 current_seq = 3166 count = 83 seq_step = 1 [250.865170] (kms_flip:6990) DEBUG: Vblank took 55us [250.881678] (kms_flip:6990) DEBUG: name = flip last_ts = 252.403458 last_received_ts = 252.402878 last_seq = 3166 current_ts = 252.420120 current_received_ts = 252.419449 current_seq = 3167 count = 84 seq_step = 1 [250.881800] (kms_flip:6990) DEBUG: Vblank took 114us [250.898327] (kms_flip:6990) DEBUG: name = flip last_ts = 252.420120 last_received_ts = 252.419449 last_seq = 3167 current_ts = 252.436783 current_received_ts = 252.436096 current_seq = 3168 count = 85 seq_step = 1 [250.898428] (kms_flip:6990) DEBUG: Vblank took 94us [250.915116] (kms_flip:6990) DEBUG: name = flip last_ts = 252.436783 last_received_ts = 252.436096 last_seq = 3168 current_ts = 252.453461 current_received_ts = 252.452881 current_seq = 3169 count = 86 seq_step = 1 [250.915185] (kms_flip:6990) DEBUG: Vblank took 61us [250.931675] (kms_flip:6990) DEBUG: name = flip last_ts = 252.453461 last_received_ts = 252.452881 last_seq = 3169 current_ts = 252.470123 current_received_ts = 252.469437 current_seq = 3170 count = 87 seq_step = 1 [250.931795] (kms_flip:6990) DEBUG: Vblank took 112us [250.948441] (kms_flip:6990) DEBUG: name = flip last_ts = 252.470123 last_received_ts = 252.469437 last_seq = 3170 current_ts = 252.486786 current_received_ts = 252.486206 current_seq = 3171 count = 88 seq_step = 1 [250.948504] (kms_flip:6990) DEBUG: Vblank took 55us [250.965108] (kms_flip:6990) DEBUG: name = flip last_ts = 252.486786 last_received_ts = 252.486206 last_seq = 3171 current_ts = 252.503448 current_received_ts = 252.502884 current_seq = 3172 count = 89 seq_step = 1 [250.965172] (kms_flip:6990) DEBUG: Vblank took 57us [250.981680] (kms_flip:6990) DEBUG: name = flip last_ts = 252.503448 last_received_ts = 252.502884 last_seq = 3172 current_ts = 252.520111 current_received_ts = 252.519455 current_seq = 3173 count = 90 seq_step = 1 [250.981791] (kms_flip:6990) DEBUG: Vblank took 103us [250.998380] (kms_flip:6990) DEBUG: name = flip last_ts = 252.520111 last_received_ts = 252.519455 last_seq = 3173 current_ts = 252.536774 current_received_ts = 252.536148 current_seq = 3174 count = 91 seq_step = 1 [250.998443] (kms_flip:6990) DEBUG: Vblank took 56us [251.015125] (kms_flip:6990) DEBUG: name = flip last_ts = 252.536774 last_received_ts = 252.536148 last_seq = 3174 current_ts = 252.553452 current_received_ts = 252.552902 current_seq = 3175 count = 92 seq_step = 1 [251.015188] (kms_flip:6990) DEBUG: Vblank took 56us [251.031687] (kms_flip:6990) DEBUG: name = flip last_ts = 252.553452 last_received_ts = 252.552902 last_seq = 3175 current_ts = 252.570114 current_received_ts = 252.569458 current_seq = 3176 count = 93 seq_step = 1 [251.031781] (kms_flip:6990) DEBUG: Vblank took 86us [251.048378] (kms_flip:6990) DEBUG: name = flip last_ts = 252.570114 last_received_ts = 252.569458 last_seq = 3176 current_ts = 252.586777 current_received_ts = 252.586151 current_seq = 3177 count = 94 seq_step = 1 [251.048423] (kms_flip:6990) DEBUG: Vblank took 37us [251.065090] (kms_flip:6990) DEBUG: name = flip last_ts = 252.586777 last_received_ts = 252.586151 last_seq = 3177 current_ts = 252.603439 current_received_ts = 252.602859 current_seq = 3178 count = 95 seq_step = 1 [251.065154] (kms_flip:6990) DEBUG: Vblank took 55us [251.081670] (kms_flip:6990) DEBUG: name = flip last_ts = 252.603439 last_received_ts = 252.602859 last_seq = 3178 current_ts = 252.620102 current_received_ts = 252.619446 current_seq = 3179 count = 96 seq_step = 1 [251.081785] (kms_flip:6990) DEBUG: Vblank took 108us [251.098350] (kms_flip:6990) DEBUG: name = flip last_ts = 252.620102 last_received_ts = 252.619446 last_seq = 3179 current_ts = 252.636765 current_received_ts = 252.636124 current_seq = 3180 count = 97 seq_step = 1 [251.098426] (kms_flip:6990) DEBUG: Vblank took 69us [251.114980] (kms_flip:6990) DEBUG: name = flip last_ts = 252.636765 last_received_ts = 252.636124 last_seq = 3180 current_ts = 252.653427 current_received_ts = 252.652756 current_seq = 3181 count = 98 seq_step = 1 [251.115044] (kms_flip:6990) DEBUG: Vblank took 56us [251.131658] (kms_flip:6990) DEBUG: name = flip last_ts = 252.653427 last_received_ts = 252.652756 last_seq = 3181 current_ts = 252.670090 current_received_ts = 252.669434 current_seq = 3182 count = 99 seq_step = 1 [251.131771] (kms_flip:6990) DEBUG: Vblank took 107us [251.148365] (kms_flip:6990) DEBUG: name = flip last_ts = 252.670090 last_received_ts = 252.669434 last_seq = 3182 current_ts = 252.686768 current_received_ts = 252.686142 current_seq = 3183 count = 100 seq_step = 1 [251.148429] (kms_flip:6990) DEBUG: Vblank took 56us [251.164972] (kms_flip:6990) DEBUG: name = flip last_ts = 252.686768 last_received_ts = 252.686142 last_seq = 3183 current_ts = 252.703430 current_received_ts = 252.702744 current_seq = 3184 count = 101 seq_step = 1 [251.165085] (kms_flip:6990) DEBUG: Vblank took 105us [251.181601] (kms_flip:6990) DEBUG: name = flip last_ts = 252.703430 last_received_ts = 252.702744 last_seq = 3184 current_ts = 252.720078 current_received_ts = 252.719391 current_seq = 3185 count = 102 seq_step = 1 [251.181722] (kms_flip:6990) DEBUG: Vblank took 118us [251.198309] (kms_flip:6990) DEBUG: name = flip last_ts = 252.720078 last_received_ts = 252.719391 last_seq = 3185 current_ts = 252.736755 current_received_ts = 252.736084 current_seq = 3186 count = 103 seq_step = 1 [251.198421] (kms_flip:6990) DEBUG: Vblank took 104us [251.214970] (kms_flip:6990) DEBUG: name = flip last_ts = 252.736755 last_received_ts = 252.736084 last_seq = 3186 current_ts = 252.753418 current_received_ts = 252.752747 current_seq = 3187 count = 104 seq_step = 1 [251.215081] (kms_flip:6990) DEBUG: Vblank took 102us [251.231599] (kms_flip:6990) DEBUG: name = flip last_ts = 252.753418 last_received_ts = 252.752747 last_seq = 3187 current_ts = 252.770081 current_received_ts = 252.769379 current_seq = 3188 count = 105 seq_step = 1 [251.231719] (kms_flip:6990) DEBUG: Vblank took 116us [251.248364] (kms_flip:6990) DEBUG: name = flip last_ts = 252.770081 last_received_ts = 252.769379 last_seq = 3188 current_ts = 252.786743 current_received_ts = 252.786148 current_seq = 3189 count = 106 seq_step = 1 [251.248428] (kms_flip:6990) DEBUG: Vblank took 56us [251.264989] (kms_flip:6990) DEBUG: name = flip last_ts = 252.786743 last_received_ts = 252.786148 last_seq = 3189 current_ts = 252.803406 current_received_ts = 252.802765 current_seq = 3190 count = 107 seq_step = 1 [251.265094] (kms_flip:6990) DEBUG: Vblank took 98us [251.281670] (kms_flip:6990) DEBUG: name = flip last_ts = 252.803406 last_received_ts = 252.802765 last_seq = 3190 current_ts = 252.820068 current_received_ts = 252.819443 current_seq = 3191 count = 108 seq_step = 1 [251.281733] (kms_flip:6990) DEBUG: Vblank took 56us [251.298322] (kms_flip:6990) DEBUG: name = flip last_ts = 252.820068 last_received_ts = 252.819443 last_seq = 3191 current_ts = 252.836731 current_received_ts = 252.836105 current_seq = 3192 count = 109 seq_step = 1 [251.298415] (kms_flip:6990) DEBUG: Vblank took 86us [251.315074] (kms_flip:6990) DEBUG: name = flip last_ts = 252.836731 last_received_ts = 252.836105 last_seq = 3192 current_ts = 252.853409 current_received_ts = 252.852859 current_seq = 3193 count = 110 seq_step = 1 [251.315137] (kms_flip:6990) DEBUG: Vblank took 55us [251.331640] (kms_flip:6990) DEBUG: name = flip last_ts = 252.853409 last_received_ts = 252.852859 last_seq = 3193 current_ts = 252.870071 current_received_ts = 252.869415 current_seq = 3194 count = 111 seq_step = 1 [251.331737] (kms_flip:6990) DEBUG: Vblank took 90us [251.348368] (kms_flip:6990) DEBUG: name = flip last_ts = 252.870071 last_received_ts = 252.869415 last_seq = 3194 current_ts = 252.886734 current_received_ts = 252.886154 current_seq = 3195 count = 112 seq_step = 1 [251.348431] (kms_flip:6990) DEBUG: Vblank took 55us [251.364963] (kms_flip:6990) DEBUG: name = flip last_ts = 252.886734 last_received_ts = 252.886154 last_seq = 3195 current_ts = 252.903397 current_received_ts = 252.902740 current_seq = 3196 count = 113 seq_step = 1 [251.365083] (kms_flip:6990) DEBUG: Vblank took 111us [251.381546] (kms_flip:6990) DEBUG: name = flip last_ts = 252.903397 last_received_ts = 252.902740 last_seq = 3196 current_ts = 252.920059 current_received_ts = 252.919327 current_seq = 3197 count = 114 seq_step = 1 [251.381674] (kms_flip:6990) DEBUG: Vblank took 123us [251.398244] (kms_flip:6990) DEBUG: name = flip last_ts = 252.920059 last_received_ts = 252.919327 last_seq = 3197 current_ts = 252.936737 current_received_ts = 252.936035 current_seq = 3198 count = 115 seq_step = 1 [251.399184] (kms_flip:6990) DEBUG: Vblank took 935us [251.399189] (kms_flip:6990) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [251.399285] (kms_flip:6990) CRITICAL: Failed assertion: end - start < 500 [251.411517] (kms_flip:6990) igt_core-INFO: Stack trace: [251.421785] (kms_flip:6990) igt_core-INFO: #0 ../lib/igt_core.c:2106 __igt_fail_assert() [251.423329] (kms_flip:6990) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [251.423429] (kms_flip:6990) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [251.423472] (kms_flip:6990) igt_core-INFO: #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() [251.423521] (kms_flip:6990) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [251.427294] (kms_flip:6990) igt_core-INFO: #5 [__libc_init_first+0x8a] [251.428320] (kms_flip:6990) igt_core-INFO: #6 [__libc_start_main+0x8b] [251.428614] (kms_flip:6990) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest A-eDP1: FAIL (3.279s)
Dmesg	<6> [264.998657] Console: switching to colour dummy device 80x25 <6> [264.998959] [IGT] kms_flip: executing <7> [265.005494] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] <7> [265.005506] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1] <7> [265.005685] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4 <7> [265.005780] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected <7> [265.005996] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] <7> [265.005998] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2] <7> [265.006117] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4 <7> [265.006746] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected <7> [265.006982] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] <7> [265.006985] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3] <7> [265.007114] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4 <7> [265.007207] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected <7> [265.007445] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] <7> [265.007449] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:393:eDP-1] <7> [265.007924] xe 0000:00:02.0: [drm:intel_dp_read_dsc_dpcd [xe]] DSC DPCD: 00 11 00 76 0b 01 01 80 00 01 06 66 08 00 00 00 <7> [265.008245] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000 <7> [265.008450] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] sink rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000 <7> [265.008564] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] common rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000 <7> [265.008691] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Supported Monitor Refresh rate range is 40 Hz - 120 Hz <5> [265.008695] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [265.008697] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [265.008698] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] DisplayID extension version 0x13, primary use 0x00 <7> [265.008700] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Assigning EDID-1.4 digital sink color depth as 10 bpc. <5> [265.008702] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [265.008703] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD monitor <5> [265.008706] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [265.008707] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD size 20, SAD count 0 <5> [265.008709] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [265.008722] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] VRR capable: yes <7> [265.008829] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] DFP max bpc 0, max dotclock 0, TMDS clock 0-0, PCON Max FRL BW 0Gbps <7> [265.008934] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] RGB->YcbCr conversion? no, YCbCr 4:2:0 allowed? yes, YCbCr 4:4:4->4:2:0 conversion? no <5> [265.009261] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [265.009264] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [265.009266] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [265.009318] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] probed modes: <7> [265.009322] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [265.009326] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 120 695310 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa <7> [265.009339] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] <7> [265.009343] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1] <7> [265.009484] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected <7> [265.009495] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] <7> [265.009498] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2] <7> [265.009634] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected <7> [265.009642] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] <7> [265.009645] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3] <7> [265.009757] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected <6> [265.010198] [IGT] kms_flip: starting subtest flip-vs-expired-vblank <6> [265.011505] [IGT] kms_flip: starting dynamic subtest A-eDP1 <7> [265.012129] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:431] <7> [265.012641] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432] <7> [265.090378] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [265.090587] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [265.090938] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [265.091234] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [265.091545] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [265.091812] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0) <7> [265.092065] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [265.092318] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [265.092557] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [265.092783] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [265.093013] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [265.093243] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [265.093515] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [265.093727] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [265.093928] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [265.094118] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [265.094312] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [265.094492] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [265.094671] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [265.094843] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [265.095017] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [265.095185] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [265.095355] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [265.095512] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [265.095662] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [265.095804] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [265.095969] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [265.096131] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [265.096281] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [265.096443] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [265.096581] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [265.096714] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [265.096846] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [265.096975] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [265.097102] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [265.097241] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [265.097378] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [265.097502] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [265.097626] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [265.097750] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [265.097871] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [265.098053] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [265.098165] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [265.098292] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 4051) -> ( 0 - 0), size 4051 -> 0 <7> [265.098405] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [265.098488] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] level wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm <7> [265.098568] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 1, 13, 13, 13, 13, 13, 0, 0, 0, 3, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [265.098647] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 24, 313, 313, 313, 313, 313, 0, 0, 38, 73, 87 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [265.098723] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 28, 346, 346, 346, 346, 346, 0, 0, 39, 82, 88 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [265.098819] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0 <7> [265.098952] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 0 qgv_peak_bw: 38400 <7> [265.099084] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 0 qgv_peak_bw: 38400 <7> [265.099199] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [265.099316] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [265.099427] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 0 <7> [265.099535] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [265.099669] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 21732 kHz -> 0 kHz <7> [265.099783] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [265.099896] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [265.099999] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [265.100125] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [265.100225] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [265.100327] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [265.100434] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [265.100526] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [265.100616] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [265.100704] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [265.100851] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [265.101563] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [265.101714] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2 <7> [265.102419] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [265.102532] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [265.305596] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [265.306033] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [265.319723] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [265.320180] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power off time <7> [265.320669] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [265.373157] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [265.373488] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [265.381348] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [265.381710] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [265.381794] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [265.383142] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [265.383630] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [265.384087] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [265.384489] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [265.384807] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [265.385104] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [265.385423] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [265.385748] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [265.386030] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [265.386322] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [265.386597] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [265.386871] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [265.387154] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [265.387462] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [265.387759] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [265.388029] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [265.388412] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [265.388693] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [265.388951] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [265.389437] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [265.389849] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [265.390305] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [265.390639] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Post changing CDCLK to 153600 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [265.391060] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [265.391361] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [265.392204] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [265.392601] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [265.392920] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [265.392995] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [265.393183] xe 0000:00:02.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:393:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [265.393670] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:151:pipe A] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [265.394041] xe 0000:00:02.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 HDR no link rate required 1303913 available 1728000 <7> [265.394454] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [265.394799] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:151:pipe A] <7> [265.395117] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected no, found yes) <7> [265.395442] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected no, found yes) <7> [265.395765] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected -1, found 0) <7> [265.396030] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 0, found 4) <7> [265.396276] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [265.396561] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [265.396797] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [265.397026] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [265.397274] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [265.397523] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [265.397724] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [265.397920] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [265.398134] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [265.398329] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [265.398512] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [265.398686] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [265.398859] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [265.399029] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [265.399216] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [265.399396] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [265.399554] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [265.399707] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [265.399854] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [265.400001] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [265.400147] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [265.400314] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [265.400454] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [265.400587] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [265.400719] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [265.400848] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [265.400979] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [265.401109] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [265.401240] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [265.401374] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [265.401516] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [265.401655] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [265.401768] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [265.401878] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 0, found 432000) <7> [265.401984] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [265.402133] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [265.402232] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x1 <7> [265.402364] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [265.402456] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [265.402529] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [265.402601] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [265.402673] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [265.402745] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [265.402836] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 1390840 num active planes 1 <7> [265.402961] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [265.403080] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [265.403185] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [265.403282] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [265.403446] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [265.403561] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 0 kHz -> 173855 kHz <7> [265.403674] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 0 kHz -> 21732 kHz <7> [265.403774] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [265.403871] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [265.403965] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [265.404071] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:151:pipe A] allocated DPLL 0 <7> [265.404160] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:151:pipe A] reserving DPLL 0 <7> [265.404244] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: yes [modeset] <7> [265.404345] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [265.404455] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: A, pipe bpp: 30, dithering: 0 <7> [265.404561] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [265.404668] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [265.404754] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [265.404836] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [265.404918] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 6329869, data_n: 8388608, link_m: 421991, link_n: 524288, tu: 64 <7> [265.405000] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [265.405080] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [265.405160] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [265.405238] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [265.405325] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [265.405412] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [265.405498] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [265.405584] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [265.405668] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [265.405745] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [265.405822] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [265.405900] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [265.405977] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [265.406054] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [265.406131] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 104 vsync start: 103, vsync end: 97 <7> [265.406209] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1906, vmax vtotal: 1906 <7> [265.406284] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [265.406382] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [265.406466] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [265.406551] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [265.406634] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa <7> [265.406715] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [265.406796] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0 <7> [265.406871] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [265.406944] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [265.407019] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0 <7> [265.407094] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [265.407168] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [265.407243] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [265.407329] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no <7> [265.407429] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [265.407524] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [265.407619] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [265.407698] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [265.407771] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [265.407845] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [265.407920] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [265.407997] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [265.408099] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [265.408174] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [265.408247] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [265.408342] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [265.408396] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [265.408452] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [265.408558] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [265.408652] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [265.408734] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [265.408812] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [265.408890] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [265.408966] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [265.409042] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [265.409119] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [265.409194] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [265.409268] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [265.409366] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [265.409474] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [FB:431] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [265.409579] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [265.409663] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [265.409739] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [265.409815] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [265.409891] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [265.409967] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [265.410044] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [265.410274] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_A <7> [265.410452] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xa8000000) <7> [265.410578] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 192000 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [265.410685] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [265.410776] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [265.410860] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [265.410931] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [265.410999] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [265.411068] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [265.411136] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [265.411203] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [265.411269] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [265.411357] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [265.411444] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [265.411529] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [265.411619] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [265.411713] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [265.411800] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [265.411899] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [265.412059] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: ) <7> [265.412122] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [265.412226] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [265.413394] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x1, on? 0) for [CRTC:151:pipe A] <7> [265.413524] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [265.415499] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [265.415598] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (467 ms remaining) <7> [265.889500] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [265.910086] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [265.910504] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power on <7> [265.910814] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [265.947350] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [265.947686] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [265.947981] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [265.948596] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [266.025589] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4 <7> [266.025745] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4 <7> [266.025927] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4 <7> [266.123303] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [266.123787] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [266.124192] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [266.126423] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e 44 c1 00 00 01 c0 02 00 02 00 00 0b 80 <7> [266.127963] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [266.128806] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [266.129927] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [266.131290] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [266.132456] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Clock recovery OK <7> [266.132812] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [266.134257] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [266.134656] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [266.135487] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe A <7> [266.135990] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [266.136418] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe A <7> [266.136865] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 4518 <7> [266.169609] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [266.171169] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [266.171486] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [268.137261] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [268.137665] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [268.137968] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [268.291416] [IGT] kms_flip: finished subtest A-eDP1, FAIL

Detail

Value

Duration

3.28 seconds

Hostname

shard-lnl-8

Igt-Version

IGT-Version: 2.4-gb024a3b67 (x86_64) (Linux: 7.1.0-rc5-lgci-xe-xe-pw-166549v4-debug+ x86_64)

Out

Using IGT_SRANDOM=1779837425 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: flip-vs-expired-vblank
Starting dynamic subtest: A-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Stack trace:
  #0 ../lib/igt_core.c:2106 __igt_fail_assert()
  #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-eDP1: FAIL (3.279s)

Err

Starting subtest: flip-vs-expired-vblank
Starting dynamic subtest: A-eDP1
[251.399189] (kms_flip:6990) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[251.399285] (kms_flip:6990) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
[248.320949] (kms_flip:6990) intel_allocator_simple-DEBUG: <ial: 0x61154167c9a0, fd: 5> objects: 3, reserved_areas: 0
[248.320950] (kms_flip:6990) intel_allocator_simple-DEBUG: <ial: 0x61154167c9a0, fd: 5> objects: 3, reserved_areas: 0
[248.325185] (kms_flip:6990) intel_allocator_simple-DEBUG: Using simple allocator
[248.328790] (kms_flip:6990) intel_allocator_simple-DEBUG: <ial: 0x611541679ae0, fd: 5> objects: 3, reserved_areas: 0
[248.328791] (kms_flip:6990) intel_allocator_simple-DEBUG: <ial: 0x611541679ae0, fd: 5> objects: 3, reserved_areas: 0
[248.344304] (kms_flip:6990) intel_allocator_simple-DEBUG: Using simple allocator
[248.347729] (kms_flip:6990) intel_allocator_simple-DEBUG: <ial: 0x61154167c890, fd: 5> objects: 3, reserved_areas: 0
[248.347731] (kms_flip:6990) intel_allocator_simple-DEBUG: <ial: 0x61154167c890, fd: 5> objects: 3, reserved_areas: 0
[248.349234] (kms_flip:6990) igt_kms-INFO:   2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
[248.369373] (kms_flip:6990) DEBUG: No stale events found
[249.453697] (kms_flip:6990) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
[249.453966] (kms_flip:6990) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
[249.481888] (kms_flip:6990) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 251.020309
current_received_ts = 251.019608
current_seq = 3083
count = 0
seq_step = 1
[249.482036] (kms_flip:6990) DEBUG: Vblank took 138us
[249.498508] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.020309
last_received_ts = 251.019608
last_seq = 3083
current_ts = 251.036957
current_received_ts = 251.036240
current_seq = 3084
count = 1
seq_step = 1
[249.498618] (kms_flip:6990) DEBUG: Vblank took 106us
[249.515218] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.036957
last_received_ts = 251.036240
last_seq = 3084
current_ts = 251.053635
current_received_ts = 251.052948
current_seq = 3085
count = 2
seq_step = 1
[249.515266] (kms_flip:6990) DEBUG: Vblank took 45us
[249.531877] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.053635
last_received_ts = 251.052948
last_seq = 3085
current_ts = 251.070297
current_received_ts = 251.069611
current_seq = 3086
count = 3
seq_step = 1
[249.531926] (kms_flip:6990) DEBUG: Vblank took 44us
[249.548519] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.070297
last_received_ts = 251.069611
last_seq = 3086
current_ts = 251.086960
current_received_ts = 251.086243
current_seq = 3087
count = 4
seq_step = 1
[249.548561] (kms_flip:6990) DEBUG: Vblank took 40us
[249.565346] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.086960
last_received_ts = 251.086243
last_seq = 3087
current_ts = 251.103622
current_received_ts = 251.103073
current_seq = 3088
count = 5
seq_step = 1
[249.565407] (kms_flip:6990) DEBUG: Vblank took 53us
[249.581893] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.103622
last_received_ts = 251.103073
last_seq = 3088
current_ts = 251.120285
current_received_ts = 251.119614
current_seq = 3089
count = 6
seq_step = 1
[249.582023] (kms_flip:6990) DEBUG: Vblank took 123us
[249.598524] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.120285
last_received_ts = 251.119614
last_seq = 3089
current_ts = 251.136963
current_received_ts = 251.136246
current_seq = 3090
count = 7
seq_step = 1
[249.598643] (kms_flip:6990) DEBUG: Vblank took 116us
[249.615307] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.136963
last_received_ts = 251.136246
last_seq = 3090
current_ts = 251.153625
current_received_ts = 251.153030
current_seq = 3091
count = 8
seq_step = 1
[249.615367] (kms_flip:6990) DEBUG: Vblank took 52us
[249.631875] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.153625
last_received_ts = 251.153030
last_seq = 3091
current_ts = 251.170273
current_received_ts = 251.169601
current_seq = 3092
count = 9
seq_step = 1
[249.631931] (kms_flip:6990) DEBUG: Vblank took 52us
[249.648622] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.170273
last_received_ts = 251.169601
last_seq = 3092
current_ts = 251.186951
current_received_ts = 251.186340
current_seq = 3093
count = 10
seq_step = 1
[249.648697] (kms_flip:6990) DEBUG: Vblank took 67us
[249.665316] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.186951
last_received_ts = 251.186340
last_seq = 3093
current_ts = 251.203613
current_received_ts = 251.203033
current_seq = 3094
count = 11
seq_step = 1
[249.665376] (kms_flip:6990) DEBUG: Vblank took 53us
[249.681886] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.203613
last_received_ts = 251.203033
last_seq = 3094
current_ts = 251.220276
current_received_ts = 251.219604
current_seq = 3095
count = 12
seq_step = 1
[249.682012] (kms_flip:6990) DEBUG: Vblank took 118us
[249.698461] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.220276
last_received_ts = 251.219604
last_seq = 3095
current_ts = 251.236938
current_received_ts = 251.236191
current_seq = 3096
count = 13
seq_step = 1
[249.698571] (kms_flip:6990) DEBUG: Vblank took 107us
[249.715324] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.236938
last_received_ts = 251.236191
last_seq = 3096
current_ts = 251.253601
current_received_ts = 251.253052
current_seq = 3097
count = 14
seq_step = 1
[249.715385] (kms_flip:6990) DEBUG: Vblank took 53us
[249.731853] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.253601
last_received_ts = 251.253052
last_seq = 3097
current_ts = 251.270264
current_received_ts = 251.269592
current_seq = 3098
count = 15
seq_step = 1
[249.731900] (kms_flip:6990) DEBUG: Vblank took 44us
[249.748575] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.270264
last_received_ts = 251.269592
last_seq = 3098
current_ts = 251.286926
current_received_ts = 251.286301
current_seq = 3099
count = 16
seq_step = 1
[249.748649] (kms_flip:6990) DEBUG: Vblank took 65us
[249.765319] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.286926
last_received_ts = 251.286301
last_seq = 3099
current_ts = 251.303604
current_received_ts = 251.303040
current_seq = 3100
count = 17
seq_step = 1
[249.765380] (kms_flip:6990) DEBUG: Vblank took 53us
[249.781864] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.303604
last_received_ts = 251.303040
last_seq = 3100
current_ts = 251.320267
current_received_ts = 251.319595
current_seq = 3101
count = 18
seq_step = 1
[249.781970] (kms_flip:6990) DEBUG: Vblank took 99us
[249.798477] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.320267
last_received_ts = 251.319595
last_seq = 3101
current_ts = 251.336929
current_received_ts = 251.336212
current_seq = 3102
count = 19
seq_step = 1
[249.798596] (kms_flip:6990) DEBUG: Vblank took 115us
[249.815160] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.336929
last_received_ts = 251.336212
last_seq = 3102
current_ts = 251.353592
current_received_ts = 251.352905
current_seq = 3103
count = 20
seq_step = 1
[249.815204] (kms_flip:6990) DEBUG: Vblank took 41us
[249.831960] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.353592
last_received_ts = 251.352905
last_seq = 3103
current_ts = 251.370255
current_received_ts = 251.369690
current_seq = 3104
count = 21
seq_step = 1
[249.832024] (kms_flip:6990) DEBUG: Vblank took 55us
[249.848606] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.370255
last_received_ts = 251.369690
last_seq = 3104
current_ts = 251.386917
current_received_ts = 251.386337
current_seq = 3105
count = 22
seq_step = 1
[249.848669] (kms_flip:6990) DEBUG: Vblank took 56us
[249.865191] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.386917
last_received_ts = 251.386337
last_seq = 3105
current_ts = 251.403580
current_received_ts = 251.402924
current_seq = 3106
count = 23
seq_step = 1
[249.865304] (kms_flip:6990) DEBUG: Vblank took 105us
[249.881812] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.403580
last_received_ts = 251.402924
last_seq = 3106
current_ts = 251.420258
current_received_ts = 251.419556
current_seq = 3107
count = 24
seq_step = 1
[249.881927] (kms_flip:6990) DEBUG: Vblank took 112us
[249.898526] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.420258
last_received_ts = 251.419556
last_seq = 3107
current_ts = 251.436920
current_received_ts = 251.436264
current_seq = 3108
count = 25
seq_step = 1
[249.898587] (kms_flip:6990) DEBUG: Vblank took 53us
[249.915184] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.436920
last_received_ts = 251.436264
last_seq = 3108
current_ts = 251.453583
current_received_ts = 251.452911
current_seq = 3109
count = 26
seq_step = 1
[249.915296] (kms_flip:6990) DEBUG: Vblank took 106us
[249.931938] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.453583
last_received_ts = 251.452911
last_seq = 3109
current_ts = 251.470245
current_received_ts = 251.469666
current_seq = 3110
count = 27
seq_step = 1
[249.932002] (kms_flip:6990) DEBUG: Vblank took 55us
[249.948419] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.470245
last_received_ts = 251.469666
last_seq = 3110
current_ts = 251.486908
current_received_ts = 251.486160
current_seq = 3111
count = 28
seq_step = 1
[249.948518] (kms_flip:6990) DEBUG: Vblank took 92us
[249.965165] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.486908
last_received_ts = 251.486160
last_seq = 3111
current_ts = 251.503571
current_received_ts = 251.502899
current_seq = 3112
count = 29
seq_step = 1
[249.965281] (kms_flip:6990) DEBUG: Vblank took 109us
[249.981828] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.503571
last_received_ts = 251.502899
last_seq = 3112
current_ts = 251.520233
current_received_ts = 251.519577
current_seq = 3113
count = 30
seq_step = 1
[249.981877] (kms_flip:6990) DEBUG: Vblank took 46us
[249.998394] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.520233
last_received_ts = 251.519577
last_seq = 3113
current_ts = 251.536896
current_received_ts = 251.536133
current_seq = 3114
count = 31
seq_step = 1
[249.998525] (kms_flip:6990) DEBUG: Vblank took 129us
[250.015302] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.536896
last_received_ts = 251.536133
last_seq = 3114
current_ts = 251.553574
current_received_ts = 251.553040
current_seq = 3115
count = 32
seq_step = 1
[250.015361] (kms_flip:6990) DEBUG: Vblank took 52us
[250.031820] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.553574
last_received_ts = 251.553040
last_seq = 3115
current_ts = 251.570236
current_received_ts = 251.569550
current_seq = 3116
count = 33
seq_step = 1
[250.031921] (kms_flip:6990) DEBUG: Vblank took 95us
[250.048478] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.570236
last_received_ts = 251.569550
last_seq = 3116
current_ts = 251.586899
current_received_ts = 251.586212
current_seq = 3117
count = 34
seq_step = 1
[250.048564] (kms_flip:6990) DEBUG: Vblank took 76us
[250.065156] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.586899
last_received_ts = 251.586212
last_seq = 3117
current_ts = 251.603561
current_received_ts = 251.602890
current_seq = 3118
count = 35
seq_step = 1
[250.065274] (kms_flip:6990) DEBUG: Vblank took 110us
[250.081787] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.603561
last_received_ts = 251.602890
last_seq = 3118
current_ts = 251.620224
current_received_ts = 251.619537
current_seq = 3119
count = 36
seq_step = 1
[250.081837] (kms_flip:6990) DEBUG: Vblank took 46us
[250.098469] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.620224
last_received_ts = 251.619537
last_seq = 3119
current_ts = 251.636887
current_received_ts = 251.636215
current_seq = 3120
count = 37
seq_step = 1
[250.098562] (kms_flip:6990) DEBUG: Vblank took 86us
[250.115279] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.636887
last_received_ts = 251.636215
last_seq = 3120
current_ts = 251.653549
current_received_ts = 251.652985
current_seq = 3121
count = 38
seq_step = 1
[250.115341] (kms_flip:6990) DEBUG: Vblank took 54us
[250.131820] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.653549
last_received_ts = 251.652985
last_seq = 3121
current_ts = 251.670212
current_received_ts = 251.669556
current_seq = 3122
count = 39
seq_step = 1
[250.131931] (kms_flip:6990) DEBUG: Vblank took 105us
[250.148503] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.670212
last_received_ts = 251.669556
last_seq = 3122
current_ts = 251.686890
current_received_ts = 251.686249
current_seq = 3123
count = 40
seq_step = 1
[250.148574] (kms_flip:6990) DEBUG: Vblank took 63us
[250.165211] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.686890
last_received_ts = 251.686249
last_seq = 3123
current_ts = 251.703552
current_received_ts = 251.702957
current_seq = 3124
count = 41
seq_step = 1
[250.165295] (kms_flip:6990) DEBUG: Vblank took 77us
[250.181822] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.703552
last_received_ts = 251.702957
last_seq = 3124
current_ts = 251.720215
current_received_ts = 251.719559
current_seq = 3125
count = 42
seq_step = 1
[250.181925] (kms_flip:6990) DEBUG: Vblank took 96us
[250.198492] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.720215
last_received_ts = 251.719559
last_seq = 3125
current_ts = 251.736877
current_received_ts = 251.736237
current_seq = 3126
count = 43
seq_step = 1
[250.198569] (kms_flip:6990) DEBUG: Vblank took 69us
[250.215232] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.736877
last_received_ts = 251.736237
last_seq = 3126
current_ts = 251.753540
current_received_ts = 251.752975
current_seq = 3127
count = 44
seq_step = 1
[250.215323] (kms_flip:6990) DEBUG: Vblank took 84us
[250.231797] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.753540
last_received_ts = 251.752975
last_seq = 3127
current_ts = 251.770203
current_received_ts = 251.769547
current_seq = 3128
count = 45
seq_step = 1
[250.231917] (kms_flip:6990) DEBUG: Vblank took 113us
[250.248492] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.770203
last_received_ts = 251.769547
last_seq = 3128
current_ts = 251.786865
current_received_ts = 251.786240
current_seq = 3129
count = 46
seq_step = 1
[250.248565] (kms_flip:6990) DEBUG: Vblank took 65us
[250.265235] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.786865
last_received_ts = 251.786240
last_seq = 3129
current_ts = 251.803528
current_received_ts = 251.802979
current_seq = 3130
count = 47
seq_step = 1
[250.265317] (kms_flip:6990) DEBUG: Vblank took 75us
[250.281807] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.803528
last_received_ts = 251.802979
last_seq = 3130
current_ts = 251.820206
current_received_ts = 251.819550
current_seq = 3131
count = 48
seq_step = 1
[250.281916] (kms_flip:6990) DEBUG: Vblank took 102us
[250.298464] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.820206
last_received_ts = 251.819550
last_seq = 3131
current_ts = 251.836868
current_received_ts = 251.836212
current_seq = 3132
count = 49
seq_step = 1
[250.298532] (kms_flip:6990) DEBUG: Vblank took 61us
[250.315212] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.836868
last_received_ts = 251.836212
last_seq = 3132
current_ts = 251.853531
current_received_ts = 251.852951
current_seq = 3133
count = 50
seq_step = 1
[250.315296] (kms_flip:6990) DEBUG: Vblank took 77us
[250.331769] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.853531
last_received_ts = 251.852951
last_seq = 3133
current_ts = 251.870193
current_received_ts = 251.869522
current_seq = 3134
count = 51
seq_step = 1
[250.331902] (kms_flip:6990) DEBUG: Vblank took 125us
[250.348502] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.870193
last_received_ts = 251.869522
last_seq = 3134
current_ts = 251.886856
current_received_ts = 251.886246
current_seq = 3135
count = 52
seq_step = 1
[250.348566] (kms_flip:6990) DEBUG: Vblank took 56us
[250.365210] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.886856
last_received_ts = 251.886246
last_seq = 3135
current_ts = 251.903519
current_received_ts = 251.902954
current_seq = 3136
count = 53
seq_step = 1
[250.365293] (kms_flip:6990) DEBUG: Vblank took 73us
[250.381778] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.903519
last_received_ts = 251.902954
last_seq = 3136
current_ts = 251.920197
current_received_ts = 251.919525
current_seq = 3137
count = 54
seq_step = 1
[250.381891] (kms_flip:6990) DEBUG: Vblank took 105us
[250.398455] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.920197
last_received_ts = 251.919525
last_seq = 3137
current_ts = 251.936859
current_received_ts = 251.936203
current_seq = 3138
count = 55
seq_step = 1
[250.398553] (kms_flip:6990) DEBUG: Vblank took 90us
[250.415204] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.936859
last_received_ts = 251.936203
last_seq = 3138
current_ts = 251.953522
current_received_ts = 251.952957
current_seq = 3139
count = 56
seq_step = 1
[250.415287] (kms_flip:6990) DEBUG: Vblank took 76us
[250.431779] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.953522
last_received_ts = 251.952957
last_seq = 3139
current_ts = 251.970184
current_received_ts = 251.969528
current_seq = 3140
count = 57
seq_step = 1
[250.431889] (kms_flip:6990) DEBUG: Vblank took 103us
[250.448470] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.970184
last_received_ts = 251.969528
last_seq = 3140
current_ts = 251.986847
current_received_ts = 251.986221
current_seq = 3141
count = 58
seq_step = 1
[250.448536] (kms_flip:6990) DEBUG: Vblank took 57us
[250.465173] (kms_flip:6990) DEBUG: name = flip
last_ts = 251.986847
last_received_ts = 251.986221
last_seq = 3141
current_ts = 252.003510
current_received_ts = 252.002930
current_seq = 3142
count = 59
seq_step = 1
[250.465236] (kms_flip:6990) DEBUG: Vblank took 56us
[250.481748] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.003510
last_received_ts = 252.002930
last_seq = 3142
current_ts = 252.020172
current_received_ts = 252.019501
current_seq = 3143
count = 60
seq_step = 1
[250.481865] (kms_flip:6990) DEBUG: Vblank took 109us
[250.498430] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.020172
last_received_ts = 252.019501
last_seq = 3143
current_ts = 252.036835
current_received_ts = 252.036179
current_seq = 3144
count = 61
seq_step = 1
[250.498518] (kms_flip:6990) DEBUG: Vblank took 81us
[250.515099] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.036835
last_received_ts = 252.036179
last_seq = 3144
current_ts = 252.053513
current_received_ts = 252.052856
current_seq = 3145
count = 62
seq_step = 1
[250.515210] (kms_flip:6990) DEBUG: Vblank took 104us
[250.531752] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.053513
last_received_ts = 252.052856
last_seq = 3145
current_ts = 252.070175
current_received_ts = 252.069519
current_seq = 3146
count = 63
seq_step = 1
[250.531793] (kms_flip:6990) DEBUG: Vblank took 38us
[250.548526] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.070175
last_received_ts = 252.069519
last_seq = 3146
current_ts = 252.086838
current_received_ts = 252.086273
current_seq = 3147
count = 64
seq_step = 1
[250.548592] (kms_flip:6990) DEBUG: Vblank took 58us
[250.565168] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.086838
last_received_ts = 252.086273
last_seq = 3147
current_ts = 252.103500
current_received_ts = 252.102921
current_seq = 3148
count = 65
seq_step = 1
[250.565258] (kms_flip:6990) DEBUG: Vblank took 81us
[250.581733] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.103500
last_received_ts = 252.102921
last_seq = 3148
current_ts = 252.120163
current_received_ts = 252.119492
current_seq = 3149
count = 66
seq_step = 1
[250.581851] (kms_flip:6990) DEBUG: Vblank took 115us
[250.598425] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.120163
last_received_ts = 252.119492
last_seq = 3149
current_ts = 252.136826
current_received_ts = 252.136185
current_seq = 3150
count = 67
seq_step = 1
[250.598495] (kms_flip:6990) DEBUG: Vblank took 62us
[250.615158] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.136826
last_received_ts = 252.136185
last_seq = 3150
current_ts = 252.153488
current_received_ts = 252.152908
current_seq = 3151
count = 68
seq_step = 1
[250.615224] (kms_flip:6990) DEBUG: Vblank took 59us
[250.631743] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.153488
last_received_ts = 252.152908
last_seq = 3151
current_ts = 252.170151
current_received_ts = 252.169495
current_seq = 3152
count = 69
seq_step = 1
[250.631857] (kms_flip:6990) DEBUG: Vblank took 107us
[250.648410] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.170151
last_received_ts = 252.169495
last_seq = 3152
current_ts = 252.186829
current_received_ts = 252.186172
current_seq = 3153
count = 70
seq_step = 1
[250.648484] (kms_flip:6990) DEBUG: Vblank took 66us
[250.665148] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.186829
last_received_ts = 252.186172
last_seq = 3153
current_ts = 252.203491
current_received_ts = 252.202911
current_seq = 3154
count = 71
seq_step = 1
[250.665208] (kms_flip:6990) DEBUG: Vblank took 52us
[250.681742] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.203491
last_received_ts = 252.202911
last_seq = 3154
current_ts = 252.220154
current_received_ts = 252.219498
current_seq = 3155
count = 72
seq_step = 1
[250.681853] (kms_flip:6990) DEBUG: Vblank took 103us
[250.698366] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.220154
last_received_ts = 252.219498
last_seq = 3155
current_ts = 252.236816
current_received_ts = 252.236130
current_seq = 3156
count = 73
seq_step = 1
[250.698464] (kms_flip:6990) DEBUG: Vblank took 92us
[250.715048] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.236816
last_received_ts = 252.236130
last_seq = 3156
current_ts = 252.253479
current_received_ts = 252.252808
current_seq = 3157
count = 74
seq_step = 1
[250.715167] (kms_flip:6990) DEBUG: Vblank took 111us
[250.731803] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.253479
last_received_ts = 252.252808
last_seq = 3157
current_ts = 252.270142
current_received_ts = 252.269562
current_seq = 3158
count = 75
seq_step = 1
[250.731867] (kms_flip:6990) DEBUG: Vblank took 56us
[250.748369] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.270142
last_received_ts = 252.269562
last_seq = 3158
current_ts = 252.286819
current_received_ts = 252.286133
current_seq = 3159
count = 76
seq_step = 1
[250.748473] (kms_flip:6990) DEBUG: Vblank took 97us
[250.765006] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.286819
last_received_ts = 252.286133
last_seq = 3159
current_ts = 252.303467
current_received_ts = 252.302780
current_seq = 3160
count = 77
seq_step = 1
[250.765058] (kms_flip:6990) DEBUG: Vblank took 48us
[250.781721] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.303467
last_received_ts = 252.302780
last_seq = 3160
current_ts = 252.320145
current_received_ts = 252.319489
current_seq = 3161
count = 78
seq_step = 1
[250.781835] (kms_flip:6990) DEBUG: Vblank took 106us
[250.798341] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.320145
last_received_ts = 252.319489
last_seq = 3161
current_ts = 252.336807
current_received_ts = 252.336105
current_seq = 3162
count = 79
seq_step = 1
[250.798482] (kms_flip:6990) DEBUG: Vblank took 137us
[250.815137] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.336807
last_received_ts = 252.336105
last_seq = 3162
current_ts = 252.353470
current_received_ts = 252.352905
current_seq = 3163
count = 80
seq_step = 1
[250.815197] (kms_flip:6990) DEBUG: Vblank took 53us
[250.831711] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.353470
last_received_ts = 252.352905
last_seq = 3163
current_ts = 252.370132
current_received_ts = 252.369476
current_seq = 3164
count = 81
seq_step = 1
[250.831826] (kms_flip:6990) DEBUG: Vblank took 108us
[250.848399] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.370132
last_received_ts = 252.369476
last_seq = 3164
current_ts = 252.386795
current_received_ts = 252.386169
current_seq = 3165
count = 82
seq_step = 1
[250.848459] (kms_flip:6990) DEBUG: Vblank took 54us
[250.865107] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.386795
last_received_ts = 252.386169
last_seq = 3165
current_ts = 252.403458
current_received_ts = 252.402878
current_seq = 3166
count = 83
seq_step = 1
[250.865170] (kms_flip:6990) DEBUG: Vblank took 55us
[250.881678] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.403458
last_received_ts = 252.402878
last_seq = 3166
current_ts = 252.420120
current_received_ts = 252.419449
current_seq = 3167
count = 84
seq_step = 1
[250.881800] (kms_flip:6990) DEBUG: Vblank took 114us
[250.898327] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.420120
last_received_ts = 252.419449
last_seq = 3167
current_ts = 252.436783
current_received_ts = 252.436096
current_seq = 3168
count = 85
seq_step = 1
[250.898428] (kms_flip:6990) DEBUG: Vblank took 94us
[250.915116] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.436783
last_received_ts = 252.436096
last_seq = 3168
current_ts = 252.453461
current_received_ts = 252.452881
current_seq = 3169
count = 86
seq_step = 1
[250.915185] (kms_flip:6990) DEBUG: Vblank took 61us
[250.931675] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.453461
last_received_ts = 252.452881
last_seq = 3169
current_ts = 252.470123
current_received_ts = 252.469437
current_seq = 3170
count = 87
seq_step = 1
[250.931795] (kms_flip:6990) DEBUG: Vblank took 112us
[250.948441] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.470123
last_received_ts = 252.469437
last_seq = 3170
current_ts = 252.486786
current_received_ts = 252.486206
current_seq = 3171
count = 88
seq_step = 1
[250.948504] (kms_flip:6990) DEBUG: Vblank took 55us
[250.965108] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.486786
last_received_ts = 252.486206
last_seq = 3171
current_ts = 252.503448
current_received_ts = 252.502884
current_seq = 3172
count = 89
seq_step = 1
[250.965172] (kms_flip:6990) DEBUG: Vblank took 57us
[250.981680] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.503448
last_received_ts = 252.502884
last_seq = 3172
current_ts = 252.520111
current_received_ts = 252.519455
current_seq = 3173
count = 90
seq_step = 1
[250.981791] (kms_flip:6990) DEBUG: Vblank took 103us
[250.998380] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.520111
last_received_ts = 252.519455
last_seq = 3173
current_ts = 252.536774
current_received_ts = 252.536148
current_seq = 3174
count = 91
seq_step = 1
[250.998443] (kms_flip:6990) DEBUG: Vblank took 56us
[251.015125] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.536774
last_received_ts = 252.536148
last_seq = 3174
current_ts = 252.553452
current_received_ts = 252.552902
current_seq = 3175
count = 92
seq_step = 1
[251.015188] (kms_flip:6990) DEBUG: Vblank took 56us
[251.031687] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.553452
last_received_ts = 252.552902
last_seq = 3175
current_ts = 252.570114
current_received_ts = 252.569458
current_seq = 3176
count = 93
seq_step = 1
[251.031781] (kms_flip:6990) DEBUG: Vblank took 86us
[251.048378] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.570114
last_received_ts = 252.569458
last_seq = 3176
current_ts = 252.586777
current_received_ts = 252.586151
current_seq = 3177
count = 94
seq_step = 1
[251.048423] (kms_flip:6990) DEBUG: Vblank took 37us
[251.065090] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.586777
last_received_ts = 252.586151
last_seq = 3177
current_ts = 252.603439
current_received_ts = 252.602859
current_seq = 3178
count = 95
seq_step = 1
[251.065154] (kms_flip:6990) DEBUG: Vblank took 55us
[251.081670] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.603439
last_received_ts = 252.602859
last_seq = 3178
current_ts = 252.620102
current_received_ts = 252.619446
current_seq = 3179
count = 96
seq_step = 1
[251.081785] (kms_flip:6990) DEBUG: Vblank took 108us
[251.098350] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.620102
last_received_ts = 252.619446
last_seq = 3179
current_ts = 252.636765
current_received_ts = 252.636124
current_seq = 3180
count = 97
seq_step = 1
[251.098426] (kms_flip:6990) DEBUG: Vblank took 69us
[251.114980] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.636765
last_received_ts = 252.636124
last_seq = 3180
current_ts = 252.653427
current_received_ts = 252.652756
current_seq = 3181
count = 98
seq_step = 1
[251.115044] (kms_flip:6990) DEBUG: Vblank took 56us
[251.131658] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.653427
last_received_ts = 252.652756
last_seq = 3181
current_ts = 252.670090
current_received_ts = 252.669434
current_seq = 3182
count = 99
seq_step = 1
[251.131771] (kms_flip:6990) DEBUG: Vblank took 107us
[251.148365] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.670090
last_received_ts = 252.669434
last_seq = 3182
current_ts = 252.686768
current_received_ts = 252.686142
current_seq = 3183
count = 100
seq_step = 1
[251.148429] (kms_flip:6990) DEBUG: Vblank took 56us
[251.164972] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.686768
last_received_ts = 252.686142
last_seq = 3183
current_ts = 252.703430
current_received_ts = 252.702744
current_seq = 3184
count = 101
seq_step = 1
[251.165085] (kms_flip:6990) DEBUG: Vblank took 105us
[251.181601] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.703430
last_received_ts = 252.702744
last_seq = 3184
current_ts = 252.720078
current_received_ts = 252.719391
current_seq = 3185
count = 102
seq_step = 1
[251.181722] (kms_flip:6990) DEBUG: Vblank took 118us
[251.198309] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.720078
last_received_ts = 252.719391
last_seq = 3185
current_ts = 252.736755
current_received_ts = 252.736084
current_seq = 3186
count = 103
seq_step = 1
[251.198421] (kms_flip:6990) DEBUG: Vblank took 104us
[251.214970] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.736755
last_received_ts = 252.736084
last_seq = 3186
current_ts = 252.753418
current_received_ts = 252.752747
current_seq = 3187
count = 104
seq_step = 1
[251.215081] (kms_flip:6990) DEBUG: Vblank took 102us
[251.231599] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.753418
last_received_ts = 252.752747
last_seq = 3187
current_ts = 252.770081
current_received_ts = 252.769379
current_seq = 3188
count = 105
seq_step = 1
[251.231719] (kms_flip:6990) DEBUG: Vblank took 116us
[251.248364] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.770081
last_received_ts = 252.769379
last_seq = 3188
current_ts = 252.786743
current_received_ts = 252.786148
current_seq = 3189
count = 106
seq_step = 1
[251.248428] (kms_flip:6990) DEBUG: Vblank took 56us
[251.264989] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.786743
last_received_ts = 252.786148
last_seq = 3189
current_ts = 252.803406
current_received_ts = 252.802765
current_seq = 3190
count = 107
seq_step = 1
[251.265094] (kms_flip:6990) DEBUG: Vblank took 98us
[251.281670] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.803406
last_received_ts = 252.802765
last_seq = 3190
current_ts = 252.820068
current_received_ts = 252.819443
current_seq = 3191
count = 108
seq_step = 1
[251.281733] (kms_flip:6990) DEBUG: Vblank took 56us
[251.298322] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.820068
last_received_ts = 252.819443
last_seq = 3191
current_ts = 252.836731
current_received_ts = 252.836105
current_seq = 3192
count = 109
seq_step = 1
[251.298415] (kms_flip:6990) DEBUG: Vblank took 86us
[251.315074] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.836731
last_received_ts = 252.836105
last_seq = 3192
current_ts = 252.853409
current_received_ts = 252.852859
current_seq = 3193
count = 110
seq_step = 1
[251.315137] (kms_flip:6990) DEBUG: Vblank took 55us
[251.331640] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.853409
last_received_ts = 252.852859
last_seq = 3193
current_ts = 252.870071
current_received_ts = 252.869415
current_seq = 3194
count = 111
seq_step = 1
[251.331737] (kms_flip:6990) DEBUG: Vblank took 90us
[251.348368] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.870071
last_received_ts = 252.869415
last_seq = 3194
current_ts = 252.886734
current_received_ts = 252.886154
current_seq = 3195
count = 112
seq_step = 1
[251.348431] (kms_flip:6990) DEBUG: Vblank took 55us
[251.364963] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.886734
last_received_ts = 252.886154
last_seq = 3195
current_ts = 252.903397
current_received_ts = 252.902740
current_seq = 3196
count = 113
seq_step = 1
[251.365083] (kms_flip:6990) DEBUG: Vblank took 111us
[251.381546] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.903397
last_received_ts = 252.902740
last_seq = 3196
current_ts = 252.920059
current_received_ts = 252.919327
current_seq = 3197
count = 114
seq_step = 1
[251.381674] (kms_flip:6990) DEBUG: Vblank took 123us
[251.398244] (kms_flip:6990) DEBUG: name = flip
last_ts = 252.920059
last_received_ts = 252.919327
last_seq = 3197
current_ts = 252.936737
current_received_ts = 252.936035
current_seq = 3198
count = 115
seq_step = 1
[251.399184] (kms_flip:6990) DEBUG: Vblank took 935us
[251.399189] (kms_flip:6990) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[251.399285] (kms_flip:6990) CRITICAL: Failed assertion: end - start < 500
[251.411517] (kms_flip:6990) igt_core-INFO: Stack trace:
[251.421785] (kms_flip:6990) igt_core-INFO:   #0 ../lib/igt_core.c:2106 __igt_fail_assert()
[251.423329] (kms_flip:6990) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[251.423429] (kms_flip:6990) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[251.423472] (kms_flip:6990) igt_core-INFO:   #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
[251.423521] (kms_flip:6990) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[251.427294] (kms_flip:6990) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[251.428320] (kms_flip:6990) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[251.428614] (kms_flip:6990) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (3.279s)

Dmesg

<6> [264.998657] Console: switching to colour dummy device 80x25

<6> [264.998959] [IGT] kms_flip: executing

<7> [265.005494] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1]

<7> [265.005506] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1]

<7> [265.005685] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4

<7> [265.005780] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected

<7> [265.005996] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2]

<7> [265.005998] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2]

<7> [265.006117] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4

<7> [265.006746] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected

<7> [265.006982] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3]

<7> [265.006985] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3]

<7> [265.007114] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (disconnected -> tbt-alt) pin assignment: - max lanes: 4

<7> [265.007207] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected

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

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

<7> [265.007924] xe 0000:00:02.0: [drm:intel_dp_read_dsc_dpcd [xe]] DSC DPCD: 00 11 00 76 0b 01 01 80 00 01 06 66 08 00 00 00

<7> [265.008245] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000

<7> [265.008450] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] sink rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000

<7> [265.008564] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] common rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000

<7> [265.008691] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Supported Monitor Refresh rate range is 40 Hz - 120 Hz

<5> [265.008695] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<5> [265.008697] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [265.008698] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] DisplayID extension version 0x13, primary use 0x00

<7> [265.008700] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Assigning EDID-1.4 digital sink color depth as 10 bpc.

<5> [265.008702] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [265.008703] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD monitor

<5> [265.008706] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [265.008707] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD size 20, SAD count 0

<5> [265.008709] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [265.008722] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] VRR capable: yes

<7> [265.008829] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] DFP max bpc 0, max dotclock 0, TMDS clock 0-0, PCON Max FRL BW 0Gbps

<7> [265.008934] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] RGB->YcbCr conversion? no, YCbCr 4:2:0 allowed? yes, YCbCr 4:4:4->4:2:0 conversion? no

<5> [265.009261] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<5> [265.009264] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<5> [265.009266] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [265.009318] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] probed modes:

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

<7> [265.009326] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 120 695310 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa

<7> [265.009339] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1]

<7> [265.009343] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1]

<7> [265.009484] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected

<7> [265.009495] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2]

<7> [265.009498] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2]

<7> [265.009634] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected

<7> [265.009642] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3]

<7> [265.009645] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3]

<7> [265.009757] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected

<6> [265.010198] [IGT] kms_flip: starting subtest flip-vs-expired-vblank

<6> [265.011505] [IGT] kms_flip: starting dynamic subtest A-eDP1

<7> [265.012129] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:431]

<7> [265.012641] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [265.098647] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 24, 313, 313, 313, 313, 313, 0, 0, 38, 73, 87 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [265.098723] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 28, 346, 346, 346, 346, 346, 0, 0, 39, 82, 88 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [265.394454] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [265.404071] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:151:pipe A] allocated DPLL 0

<7> [265.404160] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:151:pipe A] reserving DPLL 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [265.410274] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_A

<7> [265.410452] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xa8000000)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [265.413394] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x1, on? 0) for [CRTC:151:pipe A]

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

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

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

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

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

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

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

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

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

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

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

<7> [266.025589] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4

<7> [266.025745] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4

<7> [266.025927] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4

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

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

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

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

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

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

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

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

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

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

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

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

<7> [266.135487] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe A

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

<7> [266.136418] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe A

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

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

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

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

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

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

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

<6> [268.291416] [IGT] kms_flip: finished subtest A-eDP1, FAIL

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