igt@kms_flip@flip-vs-expired-vblank-interruptible@a-edp1 on shard-lnl@xe-pw-166291v2 Test details

Detail	Value
Duration	4.55 seconds
Hostname	shard-lnl-1
Igt-Version	IGT-Version: 2.4-gd88ebc53b (x86_64) (Linux: 7.1.0-rc5-lgci-xe-xe-pw-166291v2-debug+ x86_64)
Out	Using IGT_SRANDOM=1779814810 for randomisation Opened device: /dev/dri/card0 Using monotonic timestamps Starting subtest: flip-vs-expired-vblank-interruptible 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:2220 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest A-eDP1: FAIL (4.551s)
Err	Starting subtest: flip-vs-expired-vblank-interruptible Starting dynamic subtest: A-eDP1 [288.776695] (kms_flip:5587) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [288.776868] (kms_flip:5587) CRITICAL: Failed assertion: end - start < 500 [288.776964] (kms_flip:5587) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest A-eDP1 failed. ** DEBUG [286.757421] (kms_flip:5587) DEBUG: Vblank took 95us [286.773964] (kms_flip:5587) DEBUG: name = flip last_ts = 288.309113 last_received_ts = 288.308441 last_seq = 894 current_ts = 288.325775 current_received_ts = 288.325073 current_seq = 895 count = 75 seq_step = 1 [286.774049] (kms_flip:5587) DEBUG: Vblank took 77us [286.790563] (kms_flip:5587) DEBUG: name = flip last_ts = 288.325775 last_received_ts = 288.325073 last_seq = 895 current_ts = 288.342438 current_received_ts = 288.341675 current_seq = 896 count = 76 seq_step = 1 [286.790645] (kms_flip:5587) DEBUG: Vblank took 66us [286.807148] (kms_flip:5587) DEBUG: name = flip last_ts = 288.342438 last_received_ts = 288.341675 last_seq = 896 current_ts = 288.359100 current_received_ts = 288.358276 current_seq = 897 count = 77 seq_step = 1 [286.807212] (kms_flip:5587) DEBUG: Vblank took 60us [286.823901] (kms_flip:5587) DEBUG: name = flip last_ts = 288.359100 last_received_ts = 288.358276 last_seq = 897 current_ts = 288.375763 current_received_ts = 288.375000 current_seq = 898 count = 78 seq_step = 1 [286.823983] (kms_flip:5587) DEBUG: Vblank took 67us [286.840491] (kms_flip:5587) DEBUG: name = flip last_ts = 288.375763 last_received_ts = 288.375000 last_seq = 898 current_ts = 288.392426 current_received_ts = 288.391632 current_seq = 899 count = 79 seq_step = 1 [286.840539] (kms_flip:5587) DEBUG: Vblank took 45us [286.857140] (kms_flip:5587) DEBUG: name = flip last_ts = 288.392426 last_received_ts = 288.391632 last_seq = 899 current_ts = 288.409088 current_received_ts = 288.408264 current_seq = 900 count = 80 seq_step = 1 [286.857187] (kms_flip:5587) DEBUG: Vblank took 44us [286.873851] (kms_flip:5587) DEBUG: name = flip last_ts = 288.409088 last_received_ts = 288.408264 last_seq = 900 current_ts = 288.425751 current_received_ts = 288.424988 current_seq = 901 count = 81 seq_step = 1 [286.874022] (kms_flip:5587) DEBUG: Vblank took 166us [286.890476] (kms_flip:5587) DEBUG: name = flip last_ts = 288.425751 last_received_ts = 288.424988 last_seq = 901 current_ts = 288.442413 current_received_ts = 288.441620 current_seq = 902 count = 82 seq_step = 1 [286.890525] (kms_flip:5587) DEBUG: Vblank took 47us [286.907225] (kms_flip:5587) DEBUG: name = flip last_ts = 288.442413 last_received_ts = 288.441620 last_seq = 902 current_ts = 288.459076 current_received_ts = 288.458374 current_seq = 903 count = 83 seq_step = 1 [286.907269] (kms_flip:5587) DEBUG: Vblank took 42us [286.923909] (kms_flip:5587) DEBUG: name = flip last_ts = 288.459076 last_received_ts = 288.458374 last_seq = 903 current_ts = 288.475739 current_received_ts = 288.475037 current_seq = 904 count = 84 seq_step = 1 [286.923946] (kms_flip:5587) DEBUG: Vblank took 35us [286.940589] (kms_flip:5587) DEBUG: name = flip last_ts = 288.475739 last_received_ts = 288.475037 last_seq = 904 current_ts = 288.492401 current_received_ts = 288.491730 current_seq = 905 count = 85 seq_step = 1 [286.940637] (kms_flip:5587) DEBUG: Vblank took 44us [286.957260] (kms_flip:5587) DEBUG: name = flip last_ts = 288.492401 last_received_ts = 288.491730 last_seq = 905 current_ts = 288.509094 current_received_ts = 288.508392 current_seq = 906 count = 86 seq_step = 1 [286.957302] (kms_flip:5587) DEBUG: Vblank took 40us [286.973901] (kms_flip:5587) DEBUG: name = flip last_ts = 288.509094 last_received_ts = 288.508392 last_seq = 906 current_ts = 288.525757 current_received_ts = 288.525055 current_seq = 907 count = 87 seq_step = 1 [286.973940] (kms_flip:5587) DEBUG: Vblank took 36us [286.990576] (kms_flip:5587) DEBUG: name = flip last_ts = 288.525757 last_received_ts = 288.525055 last_seq = 907 current_ts = 288.542419 current_received_ts = 288.541718 current_seq = 908 count = 88 seq_step = 1 [286.990626] (kms_flip:5587) DEBUG: Vblank took 48us [287.007251] (kms_flip:5587) DEBUG: name = flip last_ts = 288.542419 last_received_ts = 288.541718 last_seq = 908 current_ts = 288.559082 current_received_ts = 288.558380 current_seq = 909 count = 89 seq_step = 1 [287.007307] (kms_flip:5587) DEBUG: Vblank took 52us [287.023906] (kms_flip:5587) DEBUG: name = flip last_ts = 288.559082 last_received_ts = 288.558380 last_seq = 909 current_ts = 288.575745 current_received_ts = 288.575043 current_seq = 910 count = 90 seq_step = 1 [287.023954] (kms_flip:5587) DEBUG: Vblank took 46us [287.040557] (kms_flip:5587) DEBUG: name = flip last_ts = 288.575745 last_received_ts = 288.575043 last_seq = 910 current_ts = 288.592407 current_received_ts = 288.591705 current_seq = 911 count = 91 seq_step = 1 [287.040601] (kms_flip:5587) DEBUG: Vblank took 42us [287.057219] (kms_flip:5587) DEBUG: name = flip last_ts = 288.592407 last_received_ts = 288.591705 last_seq = 911 current_ts = 288.609070 current_received_ts = 288.608368 current_seq = 912 count = 92 seq_step = 1 [287.057265] (kms_flip:5587) DEBUG: Vblank took 44us [287.073912] (kms_flip:5587) DEBUG: name = flip last_ts = 288.609070 last_received_ts = 288.608368 last_seq = 912 current_ts = 288.625732 current_received_ts = 288.625061 current_seq = 913 count = 93 seq_step = 1 [287.074030] (kms_flip:5587) DEBUG: Vblank took 114us [287.090446] (kms_flip:5587) DEBUG: name = flip last_ts = 288.625732 last_received_ts = 288.625061 last_seq = 913 current_ts = 288.642395 current_received_ts = 288.641602 current_seq = 914 count = 94 seq_step = 1 [287.090564] (kms_flip:5587) DEBUG: Vblank took 115us [287.107196] (kms_flip:5587) DEBUG: name = flip last_ts = 288.642395 last_received_ts = 288.641602 last_seq = 914 current_ts = 288.659058 current_received_ts = 288.658356 current_seq = 915 count = 95 seq_step = 1 [287.107240] (kms_flip:5587) DEBUG: Vblank took 41us [287.123877] (kms_flip:5587) DEBUG: name = flip last_ts = 288.659058 last_received_ts = 288.658356 last_seq = 915 current_ts = 288.675720 current_received_ts = 288.675018 current_seq = 916 count = 96 seq_step = 1 [287.123917] (kms_flip:5587) DEBUG: Vblank took 38us [287.140534] (kms_flip:5587) DEBUG: name = flip last_ts = 288.675720 last_received_ts = 288.675018 last_seq = 916 current_ts = 288.692383 current_received_ts = 288.691681 current_seq = 917 count = 97 seq_step = 1 [287.140581] (kms_flip:5587) DEBUG: Vblank took 44us [287.157231] (kms_flip:5587) DEBUG: name = flip last_ts = 288.692383 last_received_ts = 288.691681 last_seq = 917 current_ts = 288.709076 current_received_ts = 288.708374 current_seq = 918 count = 98 seq_step = 1 [287.157282] (kms_flip:5587) DEBUG: Vblank took 48us [287.173805] (kms_flip:5587) DEBUG: name = flip last_ts = 288.709076 last_received_ts = 288.708374 last_seq = 918 current_ts = 288.725739 current_received_ts = 288.724945 current_seq = 919 count = 99 seq_step = 1 [287.173881] (kms_flip:5587) DEBUG: Vblank took 71us [287.190457] (kms_flip:5587) DEBUG: name = flip last_ts = 288.725739 last_received_ts = 288.724945 last_seq = 919 current_ts = 288.742401 current_received_ts = 288.741608 current_seq = 920 count = 100 seq_step = 1 [287.190505] (kms_flip:5587) DEBUG: Vblank took 41us [287.207120] (kms_flip:5587) DEBUG: name = flip last_ts = 288.742401 last_received_ts = 288.741608 last_seq = 920 current_ts = 288.759064 current_received_ts = 288.758270 current_seq = 921 count = 101 seq_step = 1 [287.207281] (kms_flip:5587) DEBUG: Vblank took 150us [287.223804] (kms_flip:5587) DEBUG: name = flip last_ts = 288.759064 last_received_ts = 288.758270 last_seq = 921 current_ts = 288.775726 current_received_ts = 288.774963 current_seq = 922 count = 102 seq_step = 1 [287.223876] (kms_flip:5587) DEBUG: Vblank took 69us [287.240543] (kms_flip:5587) DEBUG: name = flip last_ts = 288.775726 last_received_ts = 288.774963 last_seq = 922 current_ts = 288.792389 current_received_ts = 288.791718 current_seq = 923 count = 103 seq_step = 1 [287.240598] (kms_flip:5587) DEBUG: Vblank took 53us [287.257077] (kms_flip:5587) DEBUG: name = flip last_ts = 288.792389 last_received_ts = 288.791718 last_seq = 923 current_ts = 288.809052 current_received_ts = 288.808228 current_seq = 924 count = 104 seq_step = 1 [287.257131] (kms_flip:5587) DEBUG: Vblank took 51us [287.273762] (kms_flip:5587) DEBUG: name = flip last_ts = 288.809052 last_received_ts = 288.808228 last_seq = 924 current_ts = 288.825714 current_received_ts = 288.824921 current_seq = 925 count = 105 seq_step = 1 [287.273820] (kms_flip:5587) DEBUG: Vblank took 54us [287.290432] (kms_flip:5587) DEBUG: name = flip last_ts = 288.825714 last_received_ts = 288.824921 last_seq = 925 current_ts = 288.842377 current_received_ts = 288.841583 current_seq = 926 count = 106 seq_step = 1 [287.290475] (kms_flip:5587) DEBUG: Vblank took 40us [287.307045] (kms_flip:5587) DEBUG: name = flip last_ts = 288.842377 last_received_ts = 288.841583 last_seq = 926 current_ts = 288.859039 current_received_ts = 288.858215 current_seq = 927 count = 107 seq_step = 1 [287.307097] (kms_flip:5587) DEBUG: Vblank took 49us [287.323756] (kms_flip:5587) DEBUG: name = flip last_ts = 288.859039 last_received_ts = 288.858215 last_seq = 927 current_ts = 288.875702 current_received_ts = 288.874908 current_seq = 928 count = 108 seq_step = 1 [287.323805] (kms_flip:5587) DEBUG: Vblank took 47us [287.340411] (kms_flip:5587) DEBUG: name = flip last_ts = 288.875702 last_received_ts = 288.874908 last_seq = 928 current_ts = 288.892365 current_received_ts = 288.891571 current_seq = 929 count = 109 seq_step = 1 [287.340524] (kms_flip:5587) DEBUG: Vblank took 111us [287.357038] (kms_flip:5587) DEBUG: name = flip last_ts = 288.892365 last_received_ts = 288.891571 last_seq = 929 current_ts = 288.909027 current_received_ts = 288.908203 current_seq = 930 count = 110 seq_step = 1 [287.357078] (kms_flip:5587) DEBUG: Vblank took 37us [287.373739] (kms_flip:5587) DEBUG: name = flip last_ts = 288.909027 last_received_ts = 288.908203 last_seq = 930 current_ts = 288.925720 current_received_ts = 288.924896 current_seq = 931 count = 111 seq_step = 1 [287.373788] (kms_flip:5587) DEBUG: Vblank took 47us [287.390391] (kms_flip:5587) DEBUG: name = flip last_ts = 288.925720 last_received_ts = 288.924896 last_seq = 931 current_ts = 288.942383 current_received_ts = 288.941559 current_seq = 932 count = 112 seq_step = 1 [287.390426] (kms_flip:5587) DEBUG: Vblank took 34us [287.407059] (kms_flip:5587) DEBUG: name = flip last_ts = 288.942383 last_received_ts = 288.941559 last_seq = 932 current_ts = 288.959045 current_received_ts = 288.958221 current_seq = 933 count = 113 seq_step = 1 [287.407104] (kms_flip:5587) DEBUG: Vblank took 42us [287.423799] (kms_flip:5587) DEBUG: name = flip last_ts = 288.959045 last_received_ts = 288.958221 last_seq = 933 current_ts = 288.975708 current_received_ts = 288.974976 current_seq = 934 count = 114 seq_step = 1 [287.423852] (kms_flip:5587) DEBUG: Vblank took 51us [287.440498] (kms_flip:5587) DEBUG: name = flip last_ts = 288.975708 last_received_ts = 288.974976 last_seq = 934 current_ts = 288.992371 current_received_ts = 288.991669 current_seq = 935 count = 115 seq_step = 1 [287.440544] (kms_flip:5587) DEBUG: Vblank took 43us [287.457144] (kms_flip:5587) DEBUG: name = flip last_ts = 288.992371 last_received_ts = 288.991669 last_seq = 935 current_ts = 289.009033 current_received_ts = 289.008331 current_seq = 936 count = 116 seq_step = 1 [287.457180] (kms_flip:5587) DEBUG: Vblank took 34us [287.473854] (kms_flip:5587) DEBUG: name = flip last_ts = 289.009033 last_received_ts = 289.008331 last_seq = 936 current_ts = 289.025696 current_received_ts = 289.025024 current_seq = 937 count = 117 seq_step = 1 [287.473904] (kms_flip:5587) DEBUG: Vblank took 47us [287.490496] (kms_flip:5587) DEBUG: name = flip last_ts = 289.025696 last_received_ts = 289.025024 last_seq = 937 current_ts = 289.042358 current_received_ts = 289.041687 current_seq = 938 count = 118 seq_step = 1 [287.490532] (kms_flip:5587) DEBUG: Vblank took 34us [287.507138] (kms_flip:5587) DEBUG: name = flip last_ts = 289.042358 last_received_ts = 289.041687 last_seq = 938 current_ts = 289.059021 current_received_ts = 289.058319 current_seq = 939 count = 119 seq_step = 1 [287.507185] (kms_flip:5587) DEBUG: Vblank took 43us [287.523856] (kms_flip:5587) DEBUG: name = flip last_ts = 289.059021 last_received_ts = 289.058319 last_seq = 939 current_ts = 289.075684 current_received_ts = 289.075043 current_seq = 940 count = 120 seq_step = 1 [287.523905] (kms_flip:5587) DEBUG: Vblank took 46us [287.540477] (kms_flip:5587) DEBUG: name = flip last_ts = 289.075684 last_received_ts = 289.075043 last_seq = 940 current_ts = 289.092346 current_received_ts = 289.091675 current_seq = 941 count = 121 seq_step = 1 [287.540519] (kms_flip:5587) DEBUG: Vblank took 40us [287.557140] (kms_flip:5587) DEBUG: name = flip last_ts = 289.092346 last_received_ts = 289.091675 last_seq = 941 current_ts = 289.109009 current_received_ts = 289.108307 current_seq = 942 count = 122 seq_step = 1 [287.557174] (kms_flip:5587) DEBUG: Vblank took 31us [287.573724] (kms_flip:5587) DEBUG: name = flip last_ts = 289.109009 last_received_ts = 289.108307 last_seq = 942 current_ts = 289.125702 current_received_ts = 289.124908 current_seq = 943 count = 123 seq_step = 1 [287.573768] (kms_flip:5587) DEBUG: Vblank took 41us [287.590463] (kms_flip:5587) DEBUG: name = flip last_ts = 289.125702 last_received_ts = 289.124908 last_seq = 943 current_ts = 289.142365 current_received_ts = 289.141663 current_seq = 944 count = 124 seq_step = 1 [287.590508] (kms_flip:5587) DEBUG: Vblank took 43us [287.607168] (kms_flip:5587) DEBUG: name = flip last_ts = 289.142365 last_received_ts = 289.141663 last_seq = 944 current_ts = 289.159027 current_received_ts = 289.158356 current_seq = 945 count = 125 seq_step = 1 [287.607249] (kms_flip:5587) DEBUG: Vblank took 71us [287.623726] (kms_flip:5587) DEBUG: name = flip last_ts = 289.159027 last_received_ts = 289.158356 last_seq = 945 current_ts = 289.175690 current_received_ts = 289.174927 current_seq = 946 count = 126 seq_step = 1 [287.623887] (kms_flip:5587) DEBUG: Vblank took 158us [287.640352] (kms_flip:5587) DEBUG: name = flip last_ts = 289.175690 last_received_ts = 289.174927 last_seq = 946 current_ts = 289.192352 current_received_ts = 289.191528 current_seq = 947 count = 127 seq_step = 1 [287.640399] (kms_flip:5587) DEBUG: Vblank took 45us [287.657119] (kms_flip:5587) DEBUG: name = flip last_ts = 289.192352 last_received_ts = 289.191528 last_seq = 947 current_ts = 289.209015 current_received_ts = 289.208313 current_seq = 948 count = 128 seq_step = 1 [287.657154] (kms_flip:5587) DEBUG: Vblank took 33us [287.673729] (kms_flip:5587) DEBUG: name = flip last_ts = 289.209015 last_received_ts = 289.208313 last_seq = 948 current_ts = 289.225677 current_received_ts = 289.224915 current_seq = 949 count = 129 seq_step = 1 [287.673771] (kms_flip:5587) DEBUG: Vblank took 40us [287.690442] (kms_flip:5587) DEBUG: name = flip last_ts = 289.225677 last_received_ts = 289.224915 last_seq = 949 current_ts = 289.242340 current_received_ts = 289.241638 current_seq = 950 count = 130 seq_step = 1 [287.690479] (kms_flip:5587) DEBUG: Vblank took 34us [287.707079] (kms_flip:5587) DEBUG: name = flip last_ts = 289.242340 last_received_ts = 289.241638 last_seq = 950 current_ts = 289.259003 current_received_ts = 289.258270 current_seq = 951 count = 131 seq_step = 1 [287.707113] (kms_flip:5587) DEBUG: Vblank took 31us [287.723777] (kms_flip:5587) DEBUG: name = flip last_ts = 289.259003 last_received_ts = 289.258270 last_seq = 951 current_ts = 289.275665 current_received_ts = 289.274963 current_seq = 952 count = 132 seq_step = 1 [287.723826] (kms_flip:5587) DEBUG: Vblank took 46us [287.740434] (kms_flip:5587) DEBUG: name = flip last_ts = 289.275665 last_received_ts = 289.274963 last_seq = 952 current_ts = 289.292328 current_received_ts = 289.291626 current_seq = 953 count = 133 seq_step = 1 [287.740557] (kms_flip:5587) DEBUG: Vblank took 121us [287.757079] (kms_flip:5587) DEBUG: name = flip last_ts = 289.292328 last_received_ts = 289.291626 last_seq = 953 current_ts = 289.309021 current_received_ts = 289.308289 current_seq = 954 count = 134 seq_step = 1 [287.757120] (kms_flip:5587) DEBUG: Vblank took 39us [287.773665] (kms_flip:5587) DEBUG: name = flip last_ts = 289.309021 last_received_ts = 289.308289 last_seq = 954 current_ts = 289.325684 current_received_ts = 289.324860 current_seq = 955 count = 135 seq_step = 1 [287.773702] (kms_flip:5587) DEBUG: Vblank took 34us [287.790438] (kms_flip:5587) DEBUG: name = flip last_ts = 289.325684 last_received_ts = 289.324860 last_seq = 955 current_ts = 289.342346 current_received_ts = 289.341644 current_seq = 956 count = 136 seq_step = 1 [287.790565] (kms_flip:5587) DEBUG: Vblank took 124us [287.807083] (kms_flip:5587) DEBUG: name = flip last_ts = 289.342346 last_received_ts = 289.341644 last_seq = 956 current_ts = 289.359009 current_received_ts = 289.358276 current_seq = 957 count = 137 seq_step = 1 [287.807125] (kms_flip:5587) DEBUG: Vblank took 38us [287.823755] (kms_flip:5587) DEBUG: name = flip last_ts = 289.359009 last_received_ts = 289.358276 last_seq = 957 current_ts = 289.375671 current_received_ts = 289.374969 current_seq = 958 count = 138 seq_step = 1 [287.823819] (kms_flip:5587) DEBUG: Vblank took 61us [287.840449] (kms_flip:5587) DEBUG: name = flip last_ts = 289.375671 last_received_ts = 289.374969 last_seq = 958 current_ts = 289.392334 current_received_ts = 289.391663 current_seq = 959 count = 139 seq_step = 1 [287.840492] (kms_flip:5587) DEBUG: Vblank took 41us [287.857087] (kms_flip:5587) DEBUG: name = flip last_ts = 289.392334 last_received_ts = 289.391663 last_seq = 959 current_ts = 289.408997 current_received_ts = 289.408295 current_seq = 960 count = 140 seq_step = 1 [287.857206] (kms_flip:5587) DEBUG: Vblank took 117us [287.873663] (kms_flip:5587) DEBUG: name = flip last_ts = 289.408997 last_received_ts = 289.408295 last_seq = 960 current_ts = 289.425659 current_received_ts = 289.424866 current_seq = 961 count = 141 seq_step = 1 [287.873702] (kms_flip:5587) DEBUG: Vblank took 36us [287.890318] (kms_flip:5587) DEBUG: name = flip last_ts = 289.425659 last_received_ts = 289.424866 last_seq = 961 current_ts = 289.442322 current_received_ts = 289.441528 current_seq = 962 count = 142 seq_step = 1 [287.890365] (kms_flip:5587) DEBUG: Vblank took 44us [287.907059] (kms_flip:5587) DEBUG: name = flip last_ts = 289.442322 last_received_ts = 289.441528 last_seq = 962 current_ts = 289.458984 current_received_ts = 289.458252 current_seq = 963 count = 143 seq_step = 1 [287.907097] (kms_flip:5587) DEBUG: Vblank took 35us [287.923758] (kms_flip:5587) DEBUG: name = flip last_ts = 289.458984 last_received_ts = 289.458252 last_seq = 963 current_ts = 289.475647 current_received_ts = 289.474976 current_seq = 964 count = 144 seq_step = 1 [287.923815] (kms_flip:5587) DEBUG: Vblank took 56us [287.940403] (kms_flip:5587) DEBUG: name = flip last_ts = 289.475647 last_received_ts = 289.474976 last_seq = 964 current_ts = 289.492310 current_received_ts = 289.491608 current_seq = 965 count = 145 seq_step = 1 [287.940445] (kms_flip:5587) DEBUG: Vblank took 40us [287.957005] (kms_flip:5587) DEBUG: name = flip last_ts = 289.492310 last_received_ts = 289.491608 last_seq = 965 current_ts = 289.509003 current_received_ts = 289.508209 current_seq = 966 count = 146 seq_step = 1 [287.957044] (kms_flip:5587) DEBUG: Vblank took 37us [287.973673] (kms_flip:5587) DEBUG: name = flip last_ts = 289.509003 last_received_ts = 289.508209 last_seq = 966 current_ts = 289.525665 current_received_ts = 289.524872 current_seq = 967 count = 147 seq_step = 1 [287.973708] (kms_flip:5587) DEBUG: Vblank took 32us [287.990310] (kms_flip:5587) DEBUG: name = flip last_ts = 289.525665 last_received_ts = 289.524872 last_seq = 967 current_ts = 289.542328 current_received_ts = 289.541534 current_seq = 968 count = 148 seq_step = 1 [287.990354] (kms_flip:5587) DEBUG: Vblank took 42us [288.006973] (kms_flip:5587) DEBUG: name = flip last_ts = 289.542328 last_received_ts = 289.541534 last_seq = 968 current_ts = 289.558990 current_received_ts = 289.558197 current_seq = 969 count = 149 seq_step = 1 [288.007015] (kms_flip:5587) DEBUG: Vblank took 38us [288.023754] (kms_flip:5587) DEBUG: name = flip last_ts = 289.558990 last_received_ts = 289.558197 last_seq = 969 current_ts = 289.575653 current_received_ts = 289.574951 current_seq = 970 count = 150 seq_step = 1 [288.023812] (kms_flip:5587) DEBUG: Vblank took 52us [288.040410] (kms_flip:5587) DEBUG: name = flip last_ts = 289.575653 last_received_ts = 289.574951 last_seq = 970 current_ts = 289.592316 current_received_ts = 289.591614 current_seq = 971 count = 151 seq_step = 1 [288.040466] (kms_flip:5587) DEBUG: Vblank took 51us [288.057073] (kms_flip:5587) DEBUG: name = flip last_ts = 289.592316 last_received_ts = 289.591614 last_seq = 971 current_ts = 289.608978 current_received_ts = 289.608276 current_seq = 972 count = 152 seq_step = 1 [288.057125] (kms_flip:5587) DEBUG: Vblank took 49us [288.073730] (kms_flip:5587) DEBUG: name = flip last_ts = 289.608978 last_received_ts = 289.608276 last_seq = 972 current_ts = 289.625641 current_received_ts = 289.624939 current_seq = 973 count = 153 seq_step = 1 [288.073768] (kms_flip:5587) DEBUG: Vblank took 35us [288.090384] (kms_flip:5587) DEBUG: name = flip last_ts = 289.625641 last_received_ts = 289.624939 last_seq = 973 current_ts = 289.642303 current_received_ts = 289.641602 current_seq = 974 count = 154 seq_step = 1 [288.090435] (kms_flip:5587) DEBUG: Vblank took 48us [288.107028] (kms_flip:5587) DEBUG: name = flip last_ts = 289.642303 last_received_ts = 289.641602 last_seq = 974 current_ts = 289.658966 current_received_ts = 289.658264 current_seq = 975 count = 155 seq_step = 1 [288.107076] (kms_flip:5587) DEBUG: Vblank took 46us [288.123634] (kms_flip:5587) DEBUG: name = flip last_ts = 289.658966 last_received_ts = 289.658264 last_seq = 975 current_ts = 289.675629 current_received_ts = 289.674866 current_seq = 976 count = 156 seq_step = 1 [288.123671] (kms_flip:5587) DEBUG: Vblank took 34us [288.140312] (kms_flip:5587) DEBUG: name = flip last_ts = 289.675629 last_received_ts = 289.674866 last_seq = 976 current_ts = 289.692291 current_received_ts = 289.691528 current_seq = 977 count = 157 seq_step = 1 [288.140366] (kms_flip:5587) DEBUG: Vblank took 51us [288.156986] (kms_flip:5587) DEBUG: name = flip last_ts = 289.692291 last_received_ts = 289.691528 last_seq = 977 current_ts = 289.708984 current_received_ts = 289.708221 current_seq = 978 count = 158 seq_step = 1 [288.157028] (kms_flip:5587) DEBUG: Vblank took 40us [288.173696] (kms_flip:5587) DEBUG: name = flip last_ts = 289.708984 last_received_ts = 289.708221 last_seq = 978 current_ts = 289.725647 current_received_ts = 289.724915 current_seq = 979 count = 159 seq_step = 1 [288.173740] (kms_flip:5587) DEBUG: Vblank took 42us [288.190452] (kms_flip:5587) DEBUG: name = flip last_ts = 289.725647 last_received_ts = 289.724915 last_seq = 979 current_ts = 289.742310 current_received_ts = 289.741669 current_seq = 980 count = 160 seq_step = 1 [288.190542] (kms_flip:5587) DEBUG: Vblank took 78us [288.206921] (kms_flip:5587) DEBUG: name = flip last_ts = 289.742310 last_received_ts = 289.741669 last_seq = 980 current_ts = 289.758972 current_received_ts = 289.758148 current_seq = 981 count = 161 seq_step = 1 [288.207095] (kms_flip:5587) DEBUG: Vblank took 166us [288.223614] (kms_flip:5587) DEBUG: name = flip last_ts = 289.758972 last_received_ts = 289.758148 last_seq = 981 current_ts = 289.775635 current_received_ts = 289.774841 current_seq = 982 count = 162 seq_step = 1 [288.223672] (kms_flip:5587) DEBUG: Vblank took 53us [288.240281] (kms_flip:5587) DEBUG: name = flip last_ts = 289.775635 last_received_ts = 289.774841 last_seq = 982 current_ts = 289.792297 current_received_ts = 289.791504 current_seq = 983 count = 163 seq_step = 1 [288.240421] (kms_flip:5587) DEBUG: Vblank took 136us [288.256885] (kms_flip:5587) DEBUG: name = flip last_ts = 289.792297 last_received_ts = 289.791504 last_seq = 983 current_ts = 289.808960 current_received_ts = 289.808105 current_seq = 984 count = 164 seq_step = 1 [288.256930] (kms_flip:5587) DEBUG: Vblank took 42us [288.273593] (kms_flip:5587) DEBUG: name = flip last_ts = 289.808960 last_received_ts = 289.808105 last_seq = 984 current_ts = 289.825623 current_received_ts = 289.824829 current_seq = 985 count = 165 seq_step = 1 [288.273637] (kms_flip:5587) DEBUG: Vblank took 42us [288.290261] (kms_flip:5587) DEBUG: name = flip last_ts = 289.825623 last_received_ts = 289.824829 last_seq = 985 current_ts = 289.842285 current_received_ts = 289.841492 current_seq = 986 count = 166 seq_step = 1 [288.290310] (kms_flip:5587) DEBUG: Vblank took 46us [288.307013] (kms_flip:5587) DEBUG: name = flip last_ts = 289.842285 last_received_ts = 289.841492 last_seq = 986 current_ts = 289.858948 current_received_ts = 289.858246 current_seq = 987 count = 167 seq_step = 1 [288.307058] (kms_flip:5587) DEBUG: Vblank took 42us [288.323602] (kms_flip:5587) DEBUG: name = flip last_ts = 289.858948 last_received_ts = 289.858246 last_seq = 987 current_ts = 289.875610 current_received_ts = 289.874847 current_seq = 988 count = 168 seq_step = 1 [288.323638] (kms_flip:5587) DEBUG: Vblank took 33us [288.340259] (kms_flip:5587) DEBUG: name = flip last_ts = 289.875610 last_received_ts = 289.874847 last_seq = 988 current_ts = 289.892303 current_received_ts = 289.891510 current_seq = 989 count = 169 seq_step = 1 [288.340307] (kms_flip:5587) DEBUG: Vblank took 44us [288.357017] (kms_flip:5587) DEBUG: name = flip last_ts = 289.892303 last_received_ts = 289.891510 last_seq = 989 current_ts = 289.908966 current_received_ts = 289.908264 current_seq = 990 count = 170 seq_step = 1 [288.357074] (kms_flip:5587) DEBUG: Vblank took 54us [288.373682] (kms_flip:5587) DEBUG: name = flip last_ts = 289.908966 last_received_ts = 289.908264 last_seq = 990 current_ts = 289.925629 current_received_ts = 289.924927 current_seq = 991 count = 171 seq_step = 1 [288.373722] (kms_flip:5587) DEBUG: Vblank took 37us [288.390356] (kms_flip:5587) DEBUG: name = flip last_ts = 289.925629 last_received_ts = 289.924927 last_seq = 991 current_ts = 289.942291 current_received_ts = 289.941589 current_seq = 992 count = 172 seq_step = 1 [288.390393] (kms_flip:5587) DEBUG: Vblank took 34us [288.406998] (kms_flip:5587) DEBUG: name = flip last_ts = 289.942291 last_received_ts = 289.941589 last_seq = 992 current_ts = 289.958954 current_received_ts = 289.958252 current_seq = 993 count = 173 seq_step = 1 [288.407043] (kms_flip:5587) DEBUG: Vblank took 42us [288.423664] (kms_flip:5587) DEBUG: name = flip last_ts = 289.958954 last_received_ts = 289.958252 last_seq = 993 current_ts = 289.975616 current_received_ts = 289.974915 current_seq = 994 count = 174 seq_step = 1 [288.423706] (kms_flip:5587) DEBUG: Vblank took 39us [288.440253] (kms_flip:5587) DEBUG: name = flip last_ts = 289.975616 last_received_ts = 289.974915 last_seq = 994 current_ts = 289.992279 current_received_ts = 289.991516 current_seq = 995 count = 175 seq_step = 1 [288.440300] (kms_flip:5587) DEBUG: Vblank took 43us [288.457011] (kms_flip:5587) DEBUG: name = flip last_ts = 289.992279 last_received_ts = 289.991516 last_seq = 995 current_ts = 290.008942 current_received_ts = 290.008270 current_seq = 996 count = 176 seq_step = 1 [288.457063] (kms_flip:5587) DEBUG: Vblank took 48us [288.473683] (kms_flip:5587) DEBUG: name = flip last_ts = 290.008942 last_received_ts = 290.008270 last_seq = 996 current_ts = 290.025604 current_received_ts = 290.024933 current_seq = 997 count = 177 seq_step = 1 [288.473729] (kms_flip:5587) DEBUG: Vblank took 43us [288.490331] (kms_flip:5587) DEBUG: name = flip last_ts = 290.025604 last_received_ts = 290.024933 last_seq = 997 current_ts = 290.042267 current_received_ts = 290.041595 current_seq = 998 count = 178 seq_step = 1 [288.490372] (kms_flip:5587) DEBUG: Vblank took 37us [288.507021] (kms_flip:5587) DEBUG: name = flip last_ts = 290.042267 last_received_ts = 290.041595 last_seq = 998 current_ts = 290.058929 current_received_ts = 290.058258 current_seq = 999 count = 179 seq_step = 1 [288.507087] (kms_flip:5587) DEBUG: Vblank took 61us [288.523665] (kms_flip:5587) DEBUG: name = flip last_ts = 290.058929 last_received_ts = 290.058258 last_seq = 999 current_ts = 290.075623 current_received_ts = 290.074921 current_seq = 1000 count = 180 seq_step = 1 [288.523700] (kms_flip:5587) DEBUG: Vblank took 33us [288.540315] (kms_flip:5587) DEBUG: name = flip last_ts = 290.075623 last_received_ts = 290.074921 last_seq = 1000 current_ts = 290.092285 current_received_ts = 290.091583 current_seq = 1001 count = 181 seq_step = 1 [288.540355] (kms_flip:5587) DEBUG: Vblank took 37us [288.556962] (kms_flip:5587) DEBUG: name = flip last_ts = 290.092285 last_received_ts = 290.091583 last_seq = 1001 current_ts = 290.108948 current_received_ts = 290.108215 current_seq = 1002 count = 182 seq_step = 1 [288.557007] (kms_flip:5587) DEBUG: Vblank took 41us [288.573661] (kms_flip:5587) DEBUG: name = flip last_ts = 290.108948 last_received_ts = 290.108215 last_seq = 1002 current_ts = 290.125610 current_received_ts = 290.124908 current_seq = 1003 count = 183 seq_step = 1 [288.573713] (kms_flip:5587) DEBUG: Vblank took 49us [288.590286] (kms_flip:5587) DEBUG: name = flip last_ts = 290.125610 last_received_ts = 290.124908 last_seq = 1003 current_ts = 290.142273 current_received_ts = 290.141541 current_seq = 1004 count = 184 seq_step = 1 [288.590324] (kms_flip:5587) DEBUG: Vblank took 35us [288.606964] (kms_flip:5587) DEBUG: name = flip last_ts = 290.142273 last_received_ts = 290.141541 last_seq = 1004 current_ts = 290.158936 current_received_ts = 290.158234 current_seq = 1005 count = 185 seq_step = 1 [288.607027] (kms_flip:5587) DEBUG: Vblank took 40us [288.623643] (kms_flip:5587) DEBUG: name = flip last_ts = 290.158936 last_received_ts = 290.158234 last_seq = 1005 current_ts = 290.175598 current_received_ts = 290.174896 current_seq = 1006 count = 186 seq_step = 1 [288.623687] (kms_flip:5587) DEBUG: Vblank took 42us [288.640296] (kms_flip:5587) DEBUG: name = flip last_ts = 290.175598 last_received_ts = 290.174896 last_seq = 1006 current_ts = 290.192261 current_received_ts = 290.191559 current_seq = 1007 count = 187 seq_step = 1 [288.640337] (kms_flip:5587) DEBUG: Vblank took 38us [288.656966] (kms_flip:5587) DEBUG: name = flip last_ts = 290.192261 last_received_ts = 290.191559 last_seq = 1007 current_ts = 290.208923 current_received_ts = 290.208221 current_seq = 1008 count = 188 seq_step = 1 [288.657017] (kms_flip:5587) DEBUG: Vblank took 48us [288.673636] (kms_flip:5587) DEBUG: name = flip last_ts = 290.208923 last_received_ts = 290.208221 last_seq = 1008 current_ts = 290.225586 current_received_ts = 290.224915 current_seq = 1009 count = 189 seq_step = 1 [288.673684] (kms_flip:5587) DEBUG: Vblank took 46us [288.690312] (kms_flip:5587) DEBUG: name = flip last_ts = 290.225586 last_received_ts = 290.224915 last_seq = 1009 current_ts = 290.242249 current_received_ts = 290.241577 current_seq = 1010 count = 190 seq_step = 1 [288.690360] (kms_flip:5587) DEBUG: Vblank took 44us [288.706940] (kms_flip:5587) DEBUG: name = flip last_ts = 290.242249 last_received_ts = 290.241577 last_seq = 1010 current_ts = 290.258942 current_received_ts = 290.258209 current_seq = 1011 count = 191 seq_step = 1 [288.706984] (kms_flip:5587) DEBUG: Vblank took 41us [288.723748] (kms_flip:5587) DEBUG: name = flip last_ts = 290.258942 last_received_ts = 290.258209 last_seq = 1011 current_ts = 290.275604 current_received_ts = 290.274963 current_seq = 1012 count = 192 seq_step = 1 [288.723862] (kms_flip:5587) DEBUG: Vblank took 85us [288.740325] (kms_flip:5587) DEBUG: name = flip last_ts = 290.275604 last_received_ts = 290.274963 last_seq = 1012 current_ts = 290.292267 current_received_ts = 290.291595 current_seq = 1013 count = 193 seq_step = 1 [288.740422] (kms_flip:5587) DEBUG: Vblank took 88us [288.757016] (kms_flip:5587) DEBUG: name = flip last_ts = 290.292267 last_received_ts = 290.291595 last_seq = 1013 current_ts = 290.308929 current_received_ts = 290.308289 current_seq = 1014 count = 194 seq_step = 1 [288.757103] (kms_flip:5587) DEBUG: Vblank took 80us [288.775974] (kms_flip:5587) DEBUG: name = flip last_ts = 290.308929 last_received_ts = 290.308289 last_seq = 1014 current_ts = 290.325592 current_received_ts = 290.327240 current_seq = 1015 count = 195 seq_step = 1 [288.776684] (kms_flip:5587) DEBUG: Vblank took 696us [288.776695] (kms_flip:5587) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [288.776868] (kms_flip:5587) CRITICAL: Failed assertion: end - start < 500 [288.776964] (kms_flip:5587) CRITICAL: Last errno: 4, Interrupted system call [288.799762] (kms_flip:5587) igt_core-INFO: Stack trace: [288.812897] (kms_flip:5587) igt_core-INFO: #0 ../lib/igt_core.c:2106 __igt_fail_assert() [288.813736] (kms_flip:5587) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [288.813782] (kms_flip:5587) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [288.813803] (kms_flip:5587) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() [288.813842] (kms_flip:5587) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [288.817542] (kms_flip:5587) igt_core-INFO: #5 [__libc_init_first+0x8a] [288.818326] (kms_flip:5587) igt_core-INFO: #6 [__libc_start_main+0x8b] [288.818532] (kms_flip:5587) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest A-eDP1: FAIL (4.551s)
Dmesg	<6> [407.619447] Console: switching to colour dummy device 80x25 <6> [407.619954] [IGT] kms_flip: executing <7> [407.628215] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] <7> [407.628225] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1] <7> [407.628407] 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> [407.628528] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected <7> [407.628782] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] <7> [407.628786] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2] <7> [407.628919] 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> [407.629023] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected <7> [407.629297] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] <7> [407.629301] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3] <7> [407.629465] 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> [407.629573] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected <7> [407.629831] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] <7> [407.629835] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:393:eDP-1] <7> [407.630309] 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> [407.630682] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000 <7> [407.630798] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] sink rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000 <7> [407.630927] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] common rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000 <7> [407.631331] 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> [407.631371] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [407.631379] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [407.631384] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] DisplayID extension version 0x13, primary use 0x00 <7> [407.631391] 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> [407.631397] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [407.631402] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD monitor <5> [407.631411] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [407.631418] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD size 20, SAD count 0 <5> [407.631425] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [407.631467] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] VRR capable: yes <7> [407.631752] 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> [407.631937] 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> [407.632743] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [407.632747] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [407.632749] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [407.632831] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] probed modes: <7> [407.632836] 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> [407.632841] 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> [407.632868] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] <7> [407.632880] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1] <7> [407.633250] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected <7> [407.633283] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] <7> [407.633293] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2] <7> [407.633829] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected <7> [407.633905] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] <7> [407.633910] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3] <7> [407.634120] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected <6> [407.639372] [IGT] kms_flip: starting subtest flip-vs-expired-vblank-interruptible <6> [407.640807] [IGT] kms_flip: starting dynamic subtest A-eDP1 <7> [407.643555] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:431] <7> [407.644779] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432] <7> [407.710241] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [407.710418] 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> [407.710594] 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> [407.710720] 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> [407.710842] 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> [407.710959] 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> [407.711071] 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> [407.711177] 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> [407.711280] 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> [407.711420] 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> [407.711532] 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> [407.711641] 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> [407.711734] 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> [407.711824] 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> [407.711912] 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> [407.711996] 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> [407.712082] 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> [407.712171] 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> [407.712258] 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> [407.712363] 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> [407.712466] 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> [407.712569] 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> [407.712664] 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> [407.712742] 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> [407.712820] 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> [407.712899] 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> [407.712977] 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> [407.713054] 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> [407.713129] 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> [407.713206] 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> [407.713290] 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> [407.713386] 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> [407.713486] 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> [407.713585] 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> [407.713675] 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> [407.713753] 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> [407.713828] 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> [407.713904] 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> [407.713979] 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> [407.714057] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [407.714135] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [407.714274] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [407.714354] 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> [407.714471] 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> [407.714561] 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> [407.714639] 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> [407.714699] 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> [407.714755] 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> [407.714811] 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> [407.714884] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0 <7> [407.714982] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 0 qgv_peak_bw: 38400 <7> [407.715090] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 0 qgv_peak_bw: 38400 <7> [407.715186] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [407.715279] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [407.715378] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 0 <7> [407.715491] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [407.715619] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 21732 kHz -> 0 kHz <7> [407.715720] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [407.715813] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [407.715906] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [407.716016] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [407.716103] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [407.716187] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [407.716270] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [407.716564] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [407.716676] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [407.716768] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [407.716912] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [407.717632] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [407.717777] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2 <7> [407.718479] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [407.718604] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [407.924478] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [407.924998] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [407.936680] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [407.936929] 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> [407.937190] 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> [407.989411] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [407.989759] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [407.993379] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [407.993668] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [407.993723] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [407.995068] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [407.995523] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [407.995958] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [407.996231] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [407.996507] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [407.996748] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [407.996985] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [407.997219] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [407.997487] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [407.997717] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [407.997952] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [407.998187] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [407.998443] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [407.998669] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [407.998911] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [407.999129] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [407.999428] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [407.999631] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [407.999825] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [408.000192] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [408.000510] 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> [408.000847] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [408.001084] 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> [408.001397] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [408.001618] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [408.002293] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [408.002594] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [408.002829] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [408.002891] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [408.003030] 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> [408.003368] 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> [408.003638] 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> [408.003905] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [408.004155] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:151:pipe A] <7> [408.004446] 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> [408.004709] 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> [408.004953] 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> [408.005189] 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> [408.005433] 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> [408.005680] 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> [408.005912] 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> [408.006128] 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> [408.006329] 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> [408.006563] 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> [408.006748] 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> [408.006927] 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> [408.007098] 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> [408.007295] 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> [408.007501] 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> [408.007674] 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> [408.007840] 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> [408.008019] 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> [408.008188] 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> [408.008347] 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> [408.008496] 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> [408.008643] 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> [408.008788] 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> [408.008929] 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> [408.009065] 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> [408.009195] 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> [408.009356] 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> [408.009504] 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> [408.009633] 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> [408.009766] 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> [408.009893] 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> [408.010024] 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> [408.010145] 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> [408.010262] 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> [408.010445] 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> [408.010577] 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> [408.010696] 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> [408.010804] 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> [408.010908] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [408.011053] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [408.011135] 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> [408.011239] 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> [408.011315] 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> [408.011414] 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> [408.011489] 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> [408.011571] 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> [408.011656] 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> [408.011740] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 1390840 num active planes 1 <7> [408.011859] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [408.011975] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [408.012073] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [408.012180] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [408.012279] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [408.012390] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 0 kHz -> 173855 kHz <7> [408.012523] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 0 kHz -> 21732 kHz <7> [408.012656] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [408.012753] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [408.012842] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [408.012941] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:151:pipe A] allocated DPLL 0 <7> [408.013025] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:151:pipe A] reserving DPLL 0 <7> [408.013107] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: yes [modeset] <7> [408.013189] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [408.013272] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: A, pipe bpp: 30, dithering: 0 <7> [408.013374] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [408.013481] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [408.013585] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [408.013681] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [408.013761] 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> [408.013843] 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> [408.013923] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [408.014002] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [408.014081] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [408.014161] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [408.014253] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [408.014350] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [408.014452] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [408.014553] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [408.014651] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [408.014738] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [408.014820] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [408.014898] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [408.014973] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [408.015050] 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> [408.015124] 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> [408.015199] 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> [408.015274] 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> [408.015359] 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> [408.015474] 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> [408.015590] 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> [408.015687] 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> [408.015761] 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> [408.015840] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [408.015919] 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> [408.015998] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0 <7> [408.016076] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [408.016152] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [408.016226] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [408.016300] 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> [408.016402] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [408.016513] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [408.016622] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [408.016707] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [408.016786] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [408.016862] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [408.016941] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [408.017016] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [408.017091] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [408.017165] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [408.017239] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [408.017315] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [408.017420] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [408.017516] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [408.017617] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [408.017712] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [408.017786] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [408.017862] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [408.017942] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [408.018022] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [408.018101] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [408.018188] 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> [408.018273] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [408.018357] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [408.018458] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [408.018557] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [408.018652] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [408.018735] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [408.018835] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [408.019167] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_A <7> [408.019687] 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> [408.019829] 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> [408.019933] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [408.020025] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [408.020111] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [408.020184] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [408.020255] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [408.020324] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [408.020434] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [408.020538] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [408.020628] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [408.020715] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [408.020786] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [408.020854] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [408.020926] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [408.020996] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [408.021066] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [408.021156] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [408.021324] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: ) <7> [408.021431] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [408.021561] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [408.022483] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x1, on? 0) for [CRTC:151:pipe A] <7> [408.022665] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [408.025651] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [408.025745] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (468 ms remaining) <7> [408.027312] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [408.027411] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [408.027521] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [408.027640] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [408.499502] 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> [408.576239] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [408.576671] 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> [408.576980] 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> [408.613374] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [408.613687] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [408.613973] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [408.614538] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [408.651472] 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> [408.651624] 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> [408.651641] 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> [408.786044] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [408.786413] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [408.786690] 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> [408.788590] 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> [408.790050] 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> [408.790722] 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> [408.791701] 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> [408.792885] 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> [408.793825] 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> [408.794066] 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> [408.795373] 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> [408.795623] 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> [408.796237] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe A <7> [408.796593] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [408.796827] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe A <7> [408.797110] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 4518 <7> [408.830142] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [408.831685] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [408.831976] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [411.340189] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD off <7> [411.340530] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 <7> [412.131148] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [412.132036] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [412.132783] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [412.195403] [IGT] kms_flip: finished subtest A-eDP1, FAIL

Detail

Value

Duration

4.55 seconds

Hostname

shard-lnl-1

Igt-Version

IGT-Version: 2.4-gd88ebc53b (x86_64) (Linux: 7.1.0-rc5-lgci-xe-xe-pw-166291v2-debug+ x86_64)

Out

Using IGT_SRANDOM=1779814810 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: flip-vs-expired-vblank-interruptible
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:2220 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-eDP1: FAIL (4.551s)

Err

Starting subtest: flip-vs-expired-vblank-interruptible
Starting dynamic subtest: A-eDP1
[288.776695] (kms_flip:5587) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[288.776868] (kms_flip:5587) CRITICAL: Failed assertion: end - start < 500
[288.776964] (kms_flip:5587) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
[286.757421] (kms_flip:5587) DEBUG: Vblank took 95us
[286.773964] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.309113
last_received_ts = 288.308441
last_seq = 894
current_ts = 288.325775
current_received_ts = 288.325073
current_seq = 895
count = 75
seq_step = 1
[286.774049] (kms_flip:5587) DEBUG: Vblank took 77us
[286.790563] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.325775
last_received_ts = 288.325073
last_seq = 895
current_ts = 288.342438
current_received_ts = 288.341675
current_seq = 896
count = 76
seq_step = 1
[286.790645] (kms_flip:5587) DEBUG: Vblank took 66us
[286.807148] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.342438
last_received_ts = 288.341675
last_seq = 896
current_ts = 288.359100
current_received_ts = 288.358276
current_seq = 897
count = 77
seq_step = 1
[286.807212] (kms_flip:5587) DEBUG: Vblank took 60us
[286.823901] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.359100
last_received_ts = 288.358276
last_seq = 897
current_ts = 288.375763
current_received_ts = 288.375000
current_seq = 898
count = 78
seq_step = 1
[286.823983] (kms_flip:5587) DEBUG: Vblank took 67us
[286.840491] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.375763
last_received_ts = 288.375000
last_seq = 898
current_ts = 288.392426
current_received_ts = 288.391632
current_seq = 899
count = 79
seq_step = 1
[286.840539] (kms_flip:5587) DEBUG: Vblank took 45us
[286.857140] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.392426
last_received_ts = 288.391632
last_seq = 899
current_ts = 288.409088
current_received_ts = 288.408264
current_seq = 900
count = 80
seq_step = 1
[286.857187] (kms_flip:5587) DEBUG: Vblank took 44us
[286.873851] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.409088
last_received_ts = 288.408264
last_seq = 900
current_ts = 288.425751
current_received_ts = 288.424988
current_seq = 901
count = 81
seq_step = 1
[286.874022] (kms_flip:5587) DEBUG: Vblank took 166us
[286.890476] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.425751
last_received_ts = 288.424988
last_seq = 901
current_ts = 288.442413
current_received_ts = 288.441620
current_seq = 902
count = 82
seq_step = 1
[286.890525] (kms_flip:5587) DEBUG: Vblank took 47us
[286.907225] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.442413
last_received_ts = 288.441620
last_seq = 902
current_ts = 288.459076
current_received_ts = 288.458374
current_seq = 903
count = 83
seq_step = 1
[286.907269] (kms_flip:5587) DEBUG: Vblank took 42us
[286.923909] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.459076
last_received_ts = 288.458374
last_seq = 903
current_ts = 288.475739
current_received_ts = 288.475037
current_seq = 904
count = 84
seq_step = 1
[286.923946] (kms_flip:5587) DEBUG: Vblank took 35us
[286.940589] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.475739
last_received_ts = 288.475037
last_seq = 904
current_ts = 288.492401
current_received_ts = 288.491730
current_seq = 905
count = 85
seq_step = 1
[286.940637] (kms_flip:5587) DEBUG: Vblank took 44us
[286.957260] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.492401
last_received_ts = 288.491730
last_seq = 905
current_ts = 288.509094
current_received_ts = 288.508392
current_seq = 906
count = 86
seq_step = 1
[286.957302] (kms_flip:5587) DEBUG: Vblank took 40us
[286.973901] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.509094
last_received_ts = 288.508392
last_seq = 906
current_ts = 288.525757
current_received_ts = 288.525055
current_seq = 907
count = 87
seq_step = 1
[286.973940] (kms_flip:5587) DEBUG: Vblank took 36us
[286.990576] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.525757
last_received_ts = 288.525055
last_seq = 907
current_ts = 288.542419
current_received_ts = 288.541718
current_seq = 908
count = 88
seq_step = 1
[286.990626] (kms_flip:5587) DEBUG: Vblank took 48us
[287.007251] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.542419
last_received_ts = 288.541718
last_seq = 908
current_ts = 288.559082
current_received_ts = 288.558380
current_seq = 909
count = 89
seq_step = 1
[287.007307] (kms_flip:5587) DEBUG: Vblank took 52us
[287.023906] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.559082
last_received_ts = 288.558380
last_seq = 909
current_ts = 288.575745
current_received_ts = 288.575043
current_seq = 910
count = 90
seq_step = 1
[287.023954] (kms_flip:5587) DEBUG: Vblank took 46us
[287.040557] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.575745
last_received_ts = 288.575043
last_seq = 910
current_ts = 288.592407
current_received_ts = 288.591705
current_seq = 911
count = 91
seq_step = 1
[287.040601] (kms_flip:5587) DEBUG: Vblank took 42us
[287.057219] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.592407
last_received_ts = 288.591705
last_seq = 911
current_ts = 288.609070
current_received_ts = 288.608368
current_seq = 912
count = 92
seq_step = 1
[287.057265] (kms_flip:5587) DEBUG: Vblank took 44us
[287.073912] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.609070
last_received_ts = 288.608368
last_seq = 912
current_ts = 288.625732
current_received_ts = 288.625061
current_seq = 913
count = 93
seq_step = 1
[287.074030] (kms_flip:5587) DEBUG: Vblank took 114us
[287.090446] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.625732
last_received_ts = 288.625061
last_seq = 913
current_ts = 288.642395
current_received_ts = 288.641602
current_seq = 914
count = 94
seq_step = 1
[287.090564] (kms_flip:5587) DEBUG: Vblank took 115us
[287.107196] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.642395
last_received_ts = 288.641602
last_seq = 914
current_ts = 288.659058
current_received_ts = 288.658356
current_seq = 915
count = 95
seq_step = 1
[287.107240] (kms_flip:5587) DEBUG: Vblank took 41us
[287.123877] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.659058
last_received_ts = 288.658356
last_seq = 915
current_ts = 288.675720
current_received_ts = 288.675018
current_seq = 916
count = 96
seq_step = 1
[287.123917] (kms_flip:5587) DEBUG: Vblank took 38us
[287.140534] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.675720
last_received_ts = 288.675018
last_seq = 916
current_ts = 288.692383
current_received_ts = 288.691681
current_seq = 917
count = 97
seq_step = 1
[287.140581] (kms_flip:5587) DEBUG: Vblank took 44us
[287.157231] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.692383
last_received_ts = 288.691681
last_seq = 917
current_ts = 288.709076
current_received_ts = 288.708374
current_seq = 918
count = 98
seq_step = 1
[287.157282] (kms_flip:5587) DEBUG: Vblank took 48us
[287.173805] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.709076
last_received_ts = 288.708374
last_seq = 918
current_ts = 288.725739
current_received_ts = 288.724945
current_seq = 919
count = 99
seq_step = 1
[287.173881] (kms_flip:5587) DEBUG: Vblank took 71us
[287.190457] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.725739
last_received_ts = 288.724945
last_seq = 919
current_ts = 288.742401
current_received_ts = 288.741608
current_seq = 920
count = 100
seq_step = 1
[287.190505] (kms_flip:5587) DEBUG: Vblank took 41us
[287.207120] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.742401
last_received_ts = 288.741608
last_seq = 920
current_ts = 288.759064
current_received_ts = 288.758270
current_seq = 921
count = 101
seq_step = 1
[287.207281] (kms_flip:5587) DEBUG: Vblank took 150us
[287.223804] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.759064
last_received_ts = 288.758270
last_seq = 921
current_ts = 288.775726
current_received_ts = 288.774963
current_seq = 922
count = 102
seq_step = 1
[287.223876] (kms_flip:5587) DEBUG: Vblank took 69us
[287.240543] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.775726
last_received_ts = 288.774963
last_seq = 922
current_ts = 288.792389
current_received_ts = 288.791718
current_seq = 923
count = 103
seq_step = 1
[287.240598] (kms_flip:5587) DEBUG: Vblank took 53us
[287.257077] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.792389
last_received_ts = 288.791718
last_seq = 923
current_ts = 288.809052
current_received_ts = 288.808228
current_seq = 924
count = 104
seq_step = 1
[287.257131] (kms_flip:5587) DEBUG: Vblank took 51us
[287.273762] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.809052
last_received_ts = 288.808228
last_seq = 924
current_ts = 288.825714
current_received_ts = 288.824921
current_seq = 925
count = 105
seq_step = 1
[287.273820] (kms_flip:5587) DEBUG: Vblank took 54us
[287.290432] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.825714
last_received_ts = 288.824921
last_seq = 925
current_ts = 288.842377
current_received_ts = 288.841583
current_seq = 926
count = 106
seq_step = 1
[287.290475] (kms_flip:5587) DEBUG: Vblank took 40us
[287.307045] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.842377
last_received_ts = 288.841583
last_seq = 926
current_ts = 288.859039
current_received_ts = 288.858215
current_seq = 927
count = 107
seq_step = 1
[287.307097] (kms_flip:5587) DEBUG: Vblank took 49us
[287.323756] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.859039
last_received_ts = 288.858215
last_seq = 927
current_ts = 288.875702
current_received_ts = 288.874908
current_seq = 928
count = 108
seq_step = 1
[287.323805] (kms_flip:5587) DEBUG: Vblank took 47us
[287.340411] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.875702
last_received_ts = 288.874908
last_seq = 928
current_ts = 288.892365
current_received_ts = 288.891571
current_seq = 929
count = 109
seq_step = 1
[287.340524] (kms_flip:5587) DEBUG: Vblank took 111us
[287.357038] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.892365
last_received_ts = 288.891571
last_seq = 929
current_ts = 288.909027
current_received_ts = 288.908203
current_seq = 930
count = 110
seq_step = 1
[287.357078] (kms_flip:5587) DEBUG: Vblank took 37us
[287.373739] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.909027
last_received_ts = 288.908203
last_seq = 930
current_ts = 288.925720
current_received_ts = 288.924896
current_seq = 931
count = 111
seq_step = 1
[287.373788] (kms_flip:5587) DEBUG: Vblank took 47us
[287.390391] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.925720
last_received_ts = 288.924896
last_seq = 931
current_ts = 288.942383
current_received_ts = 288.941559
current_seq = 932
count = 112
seq_step = 1
[287.390426] (kms_flip:5587) DEBUG: Vblank took 34us
[287.407059] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.942383
last_received_ts = 288.941559
last_seq = 932
current_ts = 288.959045
current_received_ts = 288.958221
current_seq = 933
count = 113
seq_step = 1
[287.407104] (kms_flip:5587) DEBUG: Vblank took 42us
[287.423799] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.959045
last_received_ts = 288.958221
last_seq = 933
current_ts = 288.975708
current_received_ts = 288.974976
current_seq = 934
count = 114
seq_step = 1
[287.423852] (kms_flip:5587) DEBUG: Vblank took 51us
[287.440498] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.975708
last_received_ts = 288.974976
last_seq = 934
current_ts = 288.992371
current_received_ts = 288.991669
current_seq = 935
count = 115
seq_step = 1
[287.440544] (kms_flip:5587) DEBUG: Vblank took 43us
[287.457144] (kms_flip:5587) DEBUG: name = flip
last_ts = 288.992371
last_received_ts = 288.991669
last_seq = 935
current_ts = 289.009033
current_received_ts = 289.008331
current_seq = 936
count = 116
seq_step = 1
[287.457180] (kms_flip:5587) DEBUG: Vblank took 34us
[287.473854] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.009033
last_received_ts = 289.008331
last_seq = 936
current_ts = 289.025696
current_received_ts = 289.025024
current_seq = 937
count = 117
seq_step = 1
[287.473904] (kms_flip:5587) DEBUG: Vblank took 47us
[287.490496] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.025696
last_received_ts = 289.025024
last_seq = 937
current_ts = 289.042358
current_received_ts = 289.041687
current_seq = 938
count = 118
seq_step = 1
[287.490532] (kms_flip:5587) DEBUG: Vblank took 34us
[287.507138] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.042358
last_received_ts = 289.041687
last_seq = 938
current_ts = 289.059021
current_received_ts = 289.058319
current_seq = 939
count = 119
seq_step = 1
[287.507185] (kms_flip:5587) DEBUG: Vblank took 43us
[287.523856] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.059021
last_received_ts = 289.058319
last_seq = 939
current_ts = 289.075684
current_received_ts = 289.075043
current_seq = 940
count = 120
seq_step = 1
[287.523905] (kms_flip:5587) DEBUG: Vblank took 46us
[287.540477] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.075684
last_received_ts = 289.075043
last_seq = 940
current_ts = 289.092346
current_received_ts = 289.091675
current_seq = 941
count = 121
seq_step = 1
[287.540519] (kms_flip:5587) DEBUG: Vblank took 40us
[287.557140] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.092346
last_received_ts = 289.091675
last_seq = 941
current_ts = 289.109009
current_received_ts = 289.108307
current_seq = 942
count = 122
seq_step = 1
[287.557174] (kms_flip:5587) DEBUG: Vblank took 31us
[287.573724] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.109009
last_received_ts = 289.108307
last_seq = 942
current_ts = 289.125702
current_received_ts = 289.124908
current_seq = 943
count = 123
seq_step = 1
[287.573768] (kms_flip:5587) DEBUG: Vblank took 41us
[287.590463] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.125702
last_received_ts = 289.124908
last_seq = 943
current_ts = 289.142365
current_received_ts = 289.141663
current_seq = 944
count = 124
seq_step = 1
[287.590508] (kms_flip:5587) DEBUG: Vblank took 43us
[287.607168] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.142365
last_received_ts = 289.141663
last_seq = 944
current_ts = 289.159027
current_received_ts = 289.158356
current_seq = 945
count = 125
seq_step = 1
[287.607249] (kms_flip:5587) DEBUG: Vblank took 71us
[287.623726] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.159027
last_received_ts = 289.158356
last_seq = 945
current_ts = 289.175690
current_received_ts = 289.174927
current_seq = 946
count = 126
seq_step = 1
[287.623887] (kms_flip:5587) DEBUG: Vblank took 158us
[287.640352] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.175690
last_received_ts = 289.174927
last_seq = 946
current_ts = 289.192352
current_received_ts = 289.191528
current_seq = 947
count = 127
seq_step = 1
[287.640399] (kms_flip:5587) DEBUG: Vblank took 45us
[287.657119] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.192352
last_received_ts = 289.191528
last_seq = 947
current_ts = 289.209015
current_received_ts = 289.208313
current_seq = 948
count = 128
seq_step = 1
[287.657154] (kms_flip:5587) DEBUG: Vblank took 33us
[287.673729] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.209015
last_received_ts = 289.208313
last_seq = 948
current_ts = 289.225677
current_received_ts = 289.224915
current_seq = 949
count = 129
seq_step = 1
[287.673771] (kms_flip:5587) DEBUG: Vblank took 40us
[287.690442] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.225677
last_received_ts = 289.224915
last_seq = 949
current_ts = 289.242340
current_received_ts = 289.241638
current_seq = 950
count = 130
seq_step = 1
[287.690479] (kms_flip:5587) DEBUG: Vblank took 34us
[287.707079] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.242340
last_received_ts = 289.241638
last_seq = 950
current_ts = 289.259003
current_received_ts = 289.258270
current_seq = 951
count = 131
seq_step = 1
[287.707113] (kms_flip:5587) DEBUG: Vblank took 31us
[287.723777] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.259003
last_received_ts = 289.258270
last_seq = 951
current_ts = 289.275665
current_received_ts = 289.274963
current_seq = 952
count = 132
seq_step = 1
[287.723826] (kms_flip:5587) DEBUG: Vblank took 46us
[287.740434] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.275665
last_received_ts = 289.274963
last_seq = 952
current_ts = 289.292328
current_received_ts = 289.291626
current_seq = 953
count = 133
seq_step = 1
[287.740557] (kms_flip:5587) DEBUG: Vblank took 121us
[287.757079] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.292328
last_received_ts = 289.291626
last_seq = 953
current_ts = 289.309021
current_received_ts = 289.308289
current_seq = 954
count = 134
seq_step = 1
[287.757120] (kms_flip:5587) DEBUG: Vblank took 39us
[287.773665] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.309021
last_received_ts = 289.308289
last_seq = 954
current_ts = 289.325684
current_received_ts = 289.324860
current_seq = 955
count = 135
seq_step = 1
[287.773702] (kms_flip:5587) DEBUG: Vblank took 34us
[287.790438] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.325684
last_received_ts = 289.324860
last_seq = 955
current_ts = 289.342346
current_received_ts = 289.341644
current_seq = 956
count = 136
seq_step = 1
[287.790565] (kms_flip:5587) DEBUG: Vblank took 124us
[287.807083] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.342346
last_received_ts = 289.341644
last_seq = 956
current_ts = 289.359009
current_received_ts = 289.358276
current_seq = 957
count = 137
seq_step = 1
[287.807125] (kms_flip:5587) DEBUG: Vblank took 38us
[287.823755] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.359009
last_received_ts = 289.358276
last_seq = 957
current_ts = 289.375671
current_received_ts = 289.374969
current_seq = 958
count = 138
seq_step = 1
[287.823819] (kms_flip:5587) DEBUG: Vblank took 61us
[287.840449] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.375671
last_received_ts = 289.374969
last_seq = 958
current_ts = 289.392334
current_received_ts = 289.391663
current_seq = 959
count = 139
seq_step = 1
[287.840492] (kms_flip:5587) DEBUG: Vblank took 41us
[287.857087] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.392334
last_received_ts = 289.391663
last_seq = 959
current_ts = 289.408997
current_received_ts = 289.408295
current_seq = 960
count = 140
seq_step = 1
[287.857206] (kms_flip:5587) DEBUG: Vblank took 117us
[287.873663] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.408997
last_received_ts = 289.408295
last_seq = 960
current_ts = 289.425659
current_received_ts = 289.424866
current_seq = 961
count = 141
seq_step = 1
[287.873702] (kms_flip:5587) DEBUG: Vblank took 36us
[287.890318] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.425659
last_received_ts = 289.424866
last_seq = 961
current_ts = 289.442322
current_received_ts = 289.441528
current_seq = 962
count = 142
seq_step = 1
[287.890365] (kms_flip:5587) DEBUG: Vblank took 44us
[287.907059] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.442322
last_received_ts = 289.441528
last_seq = 962
current_ts = 289.458984
current_received_ts = 289.458252
current_seq = 963
count = 143
seq_step = 1
[287.907097] (kms_flip:5587) DEBUG: Vblank took 35us
[287.923758] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.458984
last_received_ts = 289.458252
last_seq = 963
current_ts = 289.475647
current_received_ts = 289.474976
current_seq = 964
count = 144
seq_step = 1
[287.923815] (kms_flip:5587) DEBUG: Vblank took 56us
[287.940403] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.475647
last_received_ts = 289.474976
last_seq = 964
current_ts = 289.492310
current_received_ts = 289.491608
current_seq = 965
count = 145
seq_step = 1
[287.940445] (kms_flip:5587) DEBUG: Vblank took 40us
[287.957005] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.492310
last_received_ts = 289.491608
last_seq = 965
current_ts = 289.509003
current_received_ts = 289.508209
current_seq = 966
count = 146
seq_step = 1
[287.957044] (kms_flip:5587) DEBUG: Vblank took 37us
[287.973673] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.509003
last_received_ts = 289.508209
last_seq = 966
current_ts = 289.525665
current_received_ts = 289.524872
current_seq = 967
count = 147
seq_step = 1
[287.973708] (kms_flip:5587) DEBUG: Vblank took 32us
[287.990310] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.525665
last_received_ts = 289.524872
last_seq = 967
current_ts = 289.542328
current_received_ts = 289.541534
current_seq = 968
count = 148
seq_step = 1
[287.990354] (kms_flip:5587) DEBUG: Vblank took 42us
[288.006973] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.542328
last_received_ts = 289.541534
last_seq = 968
current_ts = 289.558990
current_received_ts = 289.558197
current_seq = 969
count = 149
seq_step = 1
[288.007015] (kms_flip:5587) DEBUG: Vblank took 38us
[288.023754] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.558990
last_received_ts = 289.558197
last_seq = 969
current_ts = 289.575653
current_received_ts = 289.574951
current_seq = 970
count = 150
seq_step = 1
[288.023812] (kms_flip:5587) DEBUG: Vblank took 52us
[288.040410] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.575653
last_received_ts = 289.574951
last_seq = 970
current_ts = 289.592316
current_received_ts = 289.591614
current_seq = 971
count = 151
seq_step = 1
[288.040466] (kms_flip:5587) DEBUG: Vblank took 51us
[288.057073] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.592316
last_received_ts = 289.591614
last_seq = 971
current_ts = 289.608978
current_received_ts = 289.608276
current_seq = 972
count = 152
seq_step = 1
[288.057125] (kms_flip:5587) DEBUG: Vblank took 49us
[288.073730] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.608978
last_received_ts = 289.608276
last_seq = 972
current_ts = 289.625641
current_received_ts = 289.624939
current_seq = 973
count = 153
seq_step = 1
[288.073768] (kms_flip:5587) DEBUG: Vblank took 35us
[288.090384] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.625641
last_received_ts = 289.624939
last_seq = 973
current_ts = 289.642303
current_received_ts = 289.641602
current_seq = 974
count = 154
seq_step = 1
[288.090435] (kms_flip:5587) DEBUG: Vblank took 48us
[288.107028] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.642303
last_received_ts = 289.641602
last_seq = 974
current_ts = 289.658966
current_received_ts = 289.658264
current_seq = 975
count = 155
seq_step = 1
[288.107076] (kms_flip:5587) DEBUG: Vblank took 46us
[288.123634] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.658966
last_received_ts = 289.658264
last_seq = 975
current_ts = 289.675629
current_received_ts = 289.674866
current_seq = 976
count = 156
seq_step = 1
[288.123671] (kms_flip:5587) DEBUG: Vblank took 34us
[288.140312] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.675629
last_received_ts = 289.674866
last_seq = 976
current_ts = 289.692291
current_received_ts = 289.691528
current_seq = 977
count = 157
seq_step = 1
[288.140366] (kms_flip:5587) DEBUG: Vblank took 51us
[288.156986] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.692291
last_received_ts = 289.691528
last_seq = 977
current_ts = 289.708984
current_received_ts = 289.708221
current_seq = 978
count = 158
seq_step = 1
[288.157028] (kms_flip:5587) DEBUG: Vblank took 40us
[288.173696] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.708984
last_received_ts = 289.708221
last_seq = 978
current_ts = 289.725647
current_received_ts = 289.724915
current_seq = 979
count = 159
seq_step = 1
[288.173740] (kms_flip:5587) DEBUG: Vblank took 42us
[288.190452] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.725647
last_received_ts = 289.724915
last_seq = 979
current_ts = 289.742310
current_received_ts = 289.741669
current_seq = 980
count = 160
seq_step = 1
[288.190542] (kms_flip:5587) DEBUG: Vblank took 78us
[288.206921] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.742310
last_received_ts = 289.741669
last_seq = 980
current_ts = 289.758972
current_received_ts = 289.758148
current_seq = 981
count = 161
seq_step = 1
[288.207095] (kms_flip:5587) DEBUG: Vblank took 166us
[288.223614] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.758972
last_received_ts = 289.758148
last_seq = 981
current_ts = 289.775635
current_received_ts = 289.774841
current_seq = 982
count = 162
seq_step = 1
[288.223672] (kms_flip:5587) DEBUG: Vblank took 53us
[288.240281] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.775635
last_received_ts = 289.774841
last_seq = 982
current_ts = 289.792297
current_received_ts = 289.791504
current_seq = 983
count = 163
seq_step = 1
[288.240421] (kms_flip:5587) DEBUG: Vblank took 136us
[288.256885] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.792297
last_received_ts = 289.791504
last_seq = 983
current_ts = 289.808960
current_received_ts = 289.808105
current_seq = 984
count = 164
seq_step = 1
[288.256930] (kms_flip:5587) DEBUG: Vblank took 42us
[288.273593] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.808960
last_received_ts = 289.808105
last_seq = 984
current_ts = 289.825623
current_received_ts = 289.824829
current_seq = 985
count = 165
seq_step = 1
[288.273637] (kms_flip:5587) DEBUG: Vblank took 42us
[288.290261] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.825623
last_received_ts = 289.824829
last_seq = 985
current_ts = 289.842285
current_received_ts = 289.841492
current_seq = 986
count = 166
seq_step = 1
[288.290310] (kms_flip:5587) DEBUG: Vblank took 46us
[288.307013] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.842285
last_received_ts = 289.841492
last_seq = 986
current_ts = 289.858948
current_received_ts = 289.858246
current_seq = 987
count = 167
seq_step = 1
[288.307058] (kms_flip:5587) DEBUG: Vblank took 42us
[288.323602] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.858948
last_received_ts = 289.858246
last_seq = 987
current_ts = 289.875610
current_received_ts = 289.874847
current_seq = 988
count = 168
seq_step = 1
[288.323638] (kms_flip:5587) DEBUG: Vblank took 33us
[288.340259] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.875610
last_received_ts = 289.874847
last_seq = 988
current_ts = 289.892303
current_received_ts = 289.891510
current_seq = 989
count = 169
seq_step = 1
[288.340307] (kms_flip:5587) DEBUG: Vblank took 44us
[288.357017] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.892303
last_received_ts = 289.891510
last_seq = 989
current_ts = 289.908966
current_received_ts = 289.908264
current_seq = 990
count = 170
seq_step = 1
[288.357074] (kms_flip:5587) DEBUG: Vblank took 54us
[288.373682] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.908966
last_received_ts = 289.908264
last_seq = 990
current_ts = 289.925629
current_received_ts = 289.924927
current_seq = 991
count = 171
seq_step = 1
[288.373722] (kms_flip:5587) DEBUG: Vblank took 37us
[288.390356] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.925629
last_received_ts = 289.924927
last_seq = 991
current_ts = 289.942291
current_received_ts = 289.941589
current_seq = 992
count = 172
seq_step = 1
[288.390393] (kms_flip:5587) DEBUG: Vblank took 34us
[288.406998] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.942291
last_received_ts = 289.941589
last_seq = 992
current_ts = 289.958954
current_received_ts = 289.958252
current_seq = 993
count = 173
seq_step = 1
[288.407043] (kms_flip:5587) DEBUG: Vblank took 42us
[288.423664] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.958954
last_received_ts = 289.958252
last_seq = 993
current_ts = 289.975616
current_received_ts = 289.974915
current_seq = 994
count = 174
seq_step = 1
[288.423706] (kms_flip:5587) DEBUG: Vblank took 39us
[288.440253] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.975616
last_received_ts = 289.974915
last_seq = 994
current_ts = 289.992279
current_received_ts = 289.991516
current_seq = 995
count = 175
seq_step = 1
[288.440300] (kms_flip:5587) DEBUG: Vblank took 43us
[288.457011] (kms_flip:5587) DEBUG: name = flip
last_ts = 289.992279
last_received_ts = 289.991516
last_seq = 995
current_ts = 290.008942
current_received_ts = 290.008270
current_seq = 996
count = 176
seq_step = 1
[288.457063] (kms_flip:5587) DEBUG: Vblank took 48us
[288.473683] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.008942
last_received_ts = 290.008270
last_seq = 996
current_ts = 290.025604
current_received_ts = 290.024933
current_seq = 997
count = 177
seq_step = 1
[288.473729] (kms_flip:5587) DEBUG: Vblank took 43us
[288.490331] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.025604
last_received_ts = 290.024933
last_seq = 997
current_ts = 290.042267
current_received_ts = 290.041595
current_seq = 998
count = 178
seq_step = 1
[288.490372] (kms_flip:5587) DEBUG: Vblank took 37us
[288.507021] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.042267
last_received_ts = 290.041595
last_seq = 998
current_ts = 290.058929
current_received_ts = 290.058258
current_seq = 999
count = 179
seq_step = 1
[288.507087] (kms_flip:5587) DEBUG: Vblank took 61us
[288.523665] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.058929
last_received_ts = 290.058258
last_seq = 999
current_ts = 290.075623
current_received_ts = 290.074921
current_seq = 1000
count = 180
seq_step = 1
[288.523700] (kms_flip:5587) DEBUG: Vblank took 33us
[288.540315] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.075623
last_received_ts = 290.074921
last_seq = 1000
current_ts = 290.092285
current_received_ts = 290.091583
current_seq = 1001
count = 181
seq_step = 1
[288.540355] (kms_flip:5587) DEBUG: Vblank took 37us
[288.556962] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.092285
last_received_ts = 290.091583
last_seq = 1001
current_ts = 290.108948
current_received_ts = 290.108215
current_seq = 1002
count = 182
seq_step = 1
[288.557007] (kms_flip:5587) DEBUG: Vblank took 41us
[288.573661] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.108948
last_received_ts = 290.108215
last_seq = 1002
current_ts = 290.125610
current_received_ts = 290.124908
current_seq = 1003
count = 183
seq_step = 1
[288.573713] (kms_flip:5587) DEBUG: Vblank took 49us
[288.590286] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.125610
last_received_ts = 290.124908
last_seq = 1003
current_ts = 290.142273
current_received_ts = 290.141541
current_seq = 1004
count = 184
seq_step = 1
[288.590324] (kms_flip:5587) DEBUG: Vblank took 35us
[288.606964] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.142273
last_received_ts = 290.141541
last_seq = 1004
current_ts = 290.158936
current_received_ts = 290.158234
current_seq = 1005
count = 185
seq_step = 1
[288.607027] (kms_flip:5587) DEBUG: Vblank took 40us
[288.623643] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.158936
last_received_ts = 290.158234
last_seq = 1005
current_ts = 290.175598
current_received_ts = 290.174896
current_seq = 1006
count = 186
seq_step = 1
[288.623687] (kms_flip:5587) DEBUG: Vblank took 42us
[288.640296] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.175598
last_received_ts = 290.174896
last_seq = 1006
current_ts = 290.192261
current_received_ts = 290.191559
current_seq = 1007
count = 187
seq_step = 1
[288.640337] (kms_flip:5587) DEBUG: Vblank took 38us
[288.656966] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.192261
last_received_ts = 290.191559
last_seq = 1007
current_ts = 290.208923
current_received_ts = 290.208221
current_seq = 1008
count = 188
seq_step = 1
[288.657017] (kms_flip:5587) DEBUG: Vblank took 48us
[288.673636] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.208923
last_received_ts = 290.208221
last_seq = 1008
current_ts = 290.225586
current_received_ts = 290.224915
current_seq = 1009
count = 189
seq_step = 1
[288.673684] (kms_flip:5587) DEBUG: Vblank took 46us
[288.690312] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.225586
last_received_ts = 290.224915
last_seq = 1009
current_ts = 290.242249
current_received_ts = 290.241577
current_seq = 1010
count = 190
seq_step = 1
[288.690360] (kms_flip:5587) DEBUG: Vblank took 44us
[288.706940] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.242249
last_received_ts = 290.241577
last_seq = 1010
current_ts = 290.258942
current_received_ts = 290.258209
current_seq = 1011
count = 191
seq_step = 1
[288.706984] (kms_flip:5587) DEBUG: Vblank took 41us
[288.723748] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.258942
last_received_ts = 290.258209
last_seq = 1011
current_ts = 290.275604
current_received_ts = 290.274963
current_seq = 1012
count = 192
seq_step = 1
[288.723862] (kms_flip:5587) DEBUG: Vblank took 85us
[288.740325] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.275604
last_received_ts = 290.274963
last_seq = 1012
current_ts = 290.292267
current_received_ts = 290.291595
current_seq = 1013
count = 193
seq_step = 1
[288.740422] (kms_flip:5587) DEBUG: Vblank took 88us
[288.757016] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.292267
last_received_ts = 290.291595
last_seq = 1013
current_ts = 290.308929
current_received_ts = 290.308289
current_seq = 1014
count = 194
seq_step = 1
[288.757103] (kms_flip:5587) DEBUG: Vblank took 80us
[288.775974] (kms_flip:5587) DEBUG: name = flip
last_ts = 290.308929
last_received_ts = 290.308289
last_seq = 1014
current_ts = 290.325592
current_received_ts = 290.327240
current_seq = 1015
count = 195
seq_step = 1
[288.776684] (kms_flip:5587) DEBUG: Vblank took 696us
[288.776695] (kms_flip:5587) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[288.776868] (kms_flip:5587) CRITICAL: Failed assertion: end - start < 500
[288.776964] (kms_flip:5587) CRITICAL: Last errno: 4, Interrupted system call
[288.799762] (kms_flip:5587) igt_core-INFO: Stack trace:
[288.812897] (kms_flip:5587) igt_core-INFO:   #0 ../lib/igt_core.c:2106 __igt_fail_assert()
[288.813736] (kms_flip:5587) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[288.813782] (kms_flip:5587) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[288.813803] (kms_flip:5587) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
[288.813842] (kms_flip:5587) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[288.817542] (kms_flip:5587) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[288.818326] (kms_flip:5587) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[288.818532] (kms_flip:5587) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (4.551s)

Dmesg

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

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

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

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

<7> [407.628407] 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> [407.628528] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected

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

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

<7> [407.628919] 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> [407.629023] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected

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

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

<7> [407.629465] 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> [407.629573] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected

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

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

<7> [407.630309] 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> [407.630682] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000

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

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

<7> [407.631331] 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> [407.631371] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

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

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

<7> [407.631391] 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> [407.631397] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

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

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

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

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

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

<7> [407.631752] 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> [407.631937] 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> [407.632743] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

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

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

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

<7> [407.632836] 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> [407.632841] 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> [407.632868] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1]

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [407.710418] 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> [407.710594] 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> [407.710720] 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> [407.710842] 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> [407.710959] 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> [407.711071] 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> [407.711177] 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> [407.711280] 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> [407.711420] 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> [407.711532] 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> [407.711641] 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> [407.711734] 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> [407.711824] 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> [407.711912] 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> [407.711996] 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> [407.712082] 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> [407.712171] 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> [407.712258] 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> [407.712363] 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> [407.712466] 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> [407.712569] 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> [407.712664] 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> [407.712742] 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> [407.712820] 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> [407.712899] 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> [407.712977] 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> [407.713054] 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> [407.713129] 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> [407.713206] 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> [407.713290] 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> [407.713386] 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> [407.713486] 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> [407.713585] 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> [407.713675] 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> [407.713753] 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> [407.713828] 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> [407.713904] 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> [407.713979] 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> [407.714057] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset

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

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

<7> [407.714354] 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> [407.714471] 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> [407.714561] 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> [407.714639] 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> [407.714699] 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> [407.714755] 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> [407.714811] 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> [407.714884] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [408.003030] 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> [408.003368] 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> [408.003638] 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> [408.003905] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0

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

<7> [408.004446] 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> [408.004709] 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> [408.004953] 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> [408.005189] 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> [408.005433] 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> [408.005680] 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> [408.005912] 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> [408.006128] 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> [408.006329] 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> [408.006563] 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> [408.006748] 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> [408.006927] 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> [408.007098] 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> [408.007295] 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> [408.007501] 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> [408.007674] 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> [408.007840] 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> [408.008019] 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> [408.008188] 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> [408.008347] 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> [408.008496] 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> [408.008643] 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> [408.008788] 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> [408.008929] 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> [408.009065] 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> [408.009195] 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> [408.009356] 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> [408.009504] 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> [408.009633] 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> [408.009766] 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> [408.009893] 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> [408.010024] 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> [408.010145] 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> [408.010262] 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> [408.010445] 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> [408.010577] 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> [408.010696] 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> [408.010804] 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> [408.010908] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset

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

<7> [408.011135] 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> [408.011239] 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> [408.011315] 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> [408.011414] 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> [408.011489] 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> [408.011571] 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> [408.011656] 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> [408.011740] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 1390840 num active planes 1

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [408.013761] 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> [408.013843] 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> [408.013923] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

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

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

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

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

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

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

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

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

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

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

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

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

<7> [408.015050] 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> [408.015124] 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> [408.015199] 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> [408.015274] 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> [408.015359] 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> [408.015474] 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> [408.015590] 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> [408.015687] 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> [408.015761] 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> [408.015840] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [408.651472] 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> [408.651624] 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> [408.651641] 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> [408.786044] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

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

<7> [408.786690] 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> [408.788590] 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> [408.790050] 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> [408.790722] 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> [408.791701] 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> [408.792885] 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> [408.793825] 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> [408.794066] 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> [408.795373] 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> [408.795623] 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> [408.796237] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe A

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

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

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

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

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

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

<7> [411.340189] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD off

<7> [411.340530] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067

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

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

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

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

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