igt@kms_flip@flip-vs-expired-vblank-interruptible@c-dp2 on shard-bmg@xe-pw-160184v5 Test details

Detail	Value
Duration	4.33 seconds
Hostname	shard-bmg-6
Igt-Version	IGT-Version: 2.4-g2a9f1c1ae (x86_64) (Linux: 7.0.0-rc7-lgci-xe-xe-pw-160184v5-debug+ x86_64)
Out	Starting dynamic subtest: C-DP2 1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1919 run_test() #3 ../tests/kms_flip.c:2219 __igt_unique____real_main2104() #4 ../tests/kms_flip.c:2104 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest C-DP2: FAIL (4.334s)
Err	Starting dynamic subtest: C-DP2 (kms_flip:20245) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:20245) CRITICAL: Failed assertion: end - start < 500 (kms_flip:20245) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest C-DP2 failed. ** DEBUG (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.250366 last_received_ts = 579.250061 last_seq = 1978 current_ts = 579.267029 current_received_ts = 579.266602 current_seq = 1979 count = 88 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.267029 last_received_ts = 579.266602 last_seq = 1979 current_ts = 579.283691 current_received_ts = 579.283386 current_seq = 1980 count = 89 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 41us (kms_flip:20245) DEBUG: name = flip last_ts = 579.283691 last_received_ts = 579.283386 last_seq = 1980 current_ts = 579.300354 current_received_ts = 579.300049 current_seq = 1981 count = 90 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 39us (kms_flip:20245) DEBUG: name = flip last_ts = 579.300354 last_received_ts = 579.300049 last_seq = 1981 current_ts = 579.317017 current_received_ts = 579.316711 current_seq = 1982 count = 91 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 579.317017 last_received_ts = 579.316711 last_seq = 1982 current_ts = 579.333679 current_received_ts = 579.333252 current_seq = 1983 count = 92 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.333679 last_received_ts = 579.333252 last_seq = 1983 current_ts = 579.350342 current_received_ts = 579.350037 current_seq = 1984 count = 93 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.350342 last_received_ts = 579.350037 last_seq = 1984 current_ts = 579.367004 current_received_ts = 579.366699 current_seq = 1985 count = 94 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 579.367004 last_received_ts = 579.366699 last_seq = 1985 current_ts = 579.383667 current_received_ts = 579.383484 current_seq = 1986 count = 95 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 40us (kms_flip:20245) DEBUG: name = flip last_ts = 579.383667 last_received_ts = 579.383484 last_seq = 1986 current_ts = 579.400330 current_received_ts = 579.400085 current_seq = 1987 count = 96 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 38us (kms_flip:20245) DEBUG: name = flip last_ts = 579.400330 last_received_ts = 579.400085 last_seq = 1987 current_ts = 579.417053 current_received_ts = 579.416748 current_seq = 1988 count = 97 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.417053 last_received_ts = 579.416748 last_seq = 1988 current_ts = 579.433716 current_received_ts = 579.433411 current_seq = 1989 count = 98 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.433716 last_received_ts = 579.433411 last_seq = 1989 current_ts = 579.450378 current_received_ts = 579.450073 current_seq = 1990 count = 99 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.450378 last_received_ts = 579.450073 last_seq = 1990 current_ts = 579.467041 current_received_ts = 579.466736 current_seq = 1991 count = 100 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.467041 last_received_ts = 579.466736 last_seq = 1991 current_ts = 579.483704 current_received_ts = 579.483398 current_seq = 1992 count = 101 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.483704 last_received_ts = 579.483398 last_seq = 1992 current_ts = 579.500366 current_received_ts = 579.500061 current_seq = 1993 count = 102 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.500366 last_received_ts = 579.500061 last_seq = 1993 current_ts = 579.517029 current_received_ts = 579.516724 current_seq = 1994 count = 103 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 579.517029 last_received_ts = 579.516724 last_seq = 1994 current_ts = 579.533691 current_received_ts = 579.533264 current_seq = 1995 count = 104 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.533691 last_received_ts = 579.533264 last_seq = 1995 current_ts = 579.550354 current_received_ts = 579.549988 current_seq = 1996 count = 105 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 24us (kms_flip:20245) DEBUG: name = flip last_ts = 579.550354 last_received_ts = 579.549988 last_seq = 1996 current_ts = 579.567017 current_received_ts = 579.566650 current_seq = 1997 count = 106 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 579.567017 last_received_ts = 579.566650 last_seq = 1997 current_ts = 579.583679 current_received_ts = 579.583435 current_seq = 1998 count = 107 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.583679 last_received_ts = 579.583435 last_seq = 1998 current_ts = 579.600403 current_received_ts = 579.600098 current_seq = 1999 count = 108 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 579.600403 last_received_ts = 579.600098 last_seq = 1999 current_ts = 579.617065 current_received_ts = 579.616638 current_seq = 2000 count = 109 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.617065 last_received_ts = 579.616638 last_seq = 2000 current_ts = 579.633728 current_received_ts = 579.633362 current_seq = 2001 count = 110 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 579.633728 last_received_ts = 579.633362 last_seq = 2001 current_ts = 579.650391 current_received_ts = 579.650085 current_seq = 2002 count = 111 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 43us (kms_flip:20245) DEBUG: name = flip last_ts = 579.650391 last_received_ts = 579.650085 last_seq = 2002 current_ts = 579.667053 current_received_ts = 579.666748 current_seq = 2003 count = 112 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.667053 last_received_ts = 579.666748 last_seq = 2003 current_ts = 579.683716 current_received_ts = 579.683411 current_seq = 2004 count = 113 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.683716 last_received_ts = 579.683411 last_seq = 2004 current_ts = 579.700378 current_received_ts = 579.700073 current_seq = 2005 count = 114 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.700378 last_received_ts = 579.700073 last_seq = 2005 current_ts = 579.717041 current_received_ts = 579.716736 current_seq = 2006 count = 115 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 579.717041 last_received_ts = 579.716736 last_seq = 2006 current_ts = 579.733704 current_received_ts = 579.733398 current_seq = 2007 count = 116 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.733704 last_received_ts = 579.733398 last_seq = 2007 current_ts = 579.750366 current_received_ts = 579.750000 current_seq = 2008 count = 117 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 40us (kms_flip:20245) DEBUG: name = flip last_ts = 579.750366 last_received_ts = 579.750000 last_seq = 2008 current_ts = 579.767090 current_received_ts = 579.766785 current_seq = 2009 count = 118 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 29us (kms_flip:20245) DEBUG: name = flip last_ts = 579.767090 last_received_ts = 579.766785 last_seq = 2009 current_ts = 579.783752 current_received_ts = 579.783447 current_seq = 2010 count = 119 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 579.783752 last_received_ts = 579.783447 last_seq = 2010 current_ts = 579.800415 current_received_ts = 579.799988 current_seq = 2011 count = 120 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 40us (kms_flip:20245) DEBUG: name = flip last_ts = 579.800415 last_received_ts = 579.799988 last_seq = 2011 current_ts = 579.817078 current_received_ts = 579.816772 current_seq = 2012 count = 121 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 28us (kms_flip:20245) DEBUG: name = flip last_ts = 579.817078 last_received_ts = 579.816772 last_seq = 2012 current_ts = 579.833740 current_received_ts = 579.833435 current_seq = 2013 count = 122 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 579.833740 last_received_ts = 579.833435 last_seq = 2013 current_ts = 579.850403 current_received_ts = 579.850098 current_seq = 2014 count = 123 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 579.850403 last_received_ts = 579.850098 last_seq = 2014 current_ts = 579.867065 current_received_ts = 579.866577 current_seq = 2015 count = 124 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 579.867065 last_received_ts = 579.866577 last_seq = 2015 current_ts = 579.883728 current_received_ts = 579.883423 current_seq = 2016 count = 125 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.883728 last_received_ts = 579.883423 last_seq = 2016 current_ts = 579.900391 current_received_ts = 579.900085 current_seq = 2017 count = 126 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 579.900391 last_received_ts = 579.900085 last_seq = 2017 current_ts = 579.917053 current_received_ts = 579.916748 current_seq = 2018 count = 127 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 579.917053 last_received_ts = 579.916748 last_seq = 2018 current_ts = 579.933777 current_received_ts = 579.933411 current_seq = 2019 count = 128 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.933777 last_received_ts = 579.933411 last_seq = 2019 current_ts = 579.950439 current_received_ts = 579.950073 current_seq = 2020 count = 129 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 579.950439 last_received_ts = 579.950073 last_seq = 2020 current_ts = 579.967102 current_received_ts = 579.966797 current_seq = 2021 count = 130 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 579.967102 last_received_ts = 579.966797 last_seq = 2021 current_ts = 579.983765 current_received_ts = 579.983337 current_seq = 2022 count = 131 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 579.983765 last_received_ts = 579.983337 last_seq = 2022 current_ts = 580.000427 current_received_ts = 580.000122 current_seq = 2023 count = 132 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 580.000427 last_received_ts = 580.000122 last_seq = 2023 current_ts = 580.017090 current_received_ts = 580.016785 current_seq = 2024 count = 133 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 580.017090 last_received_ts = 580.016785 last_seq = 2024 current_ts = 580.033752 current_received_ts = 580.033325 current_seq = 2025 count = 134 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 580.033752 last_received_ts = 580.033325 last_seq = 2025 current_ts = 580.050415 current_received_ts = 580.050049 current_seq = 2026 count = 135 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 580.050415 last_received_ts = 580.050049 last_seq = 2026 current_ts = 580.067078 current_received_ts = 580.066650 current_seq = 2027 count = 136 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 580.067078 last_received_ts = 580.066650 last_seq = 2027 current_ts = 580.083740 current_received_ts = 580.083435 current_seq = 2028 count = 137 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.083740 last_received_ts = 580.083435 last_seq = 2028 current_ts = 580.100403 current_received_ts = 580.100098 current_seq = 2029 count = 138 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 580.100403 last_received_ts = 580.100098 last_seq = 2029 current_ts = 580.117126 current_received_ts = 580.116699 current_seq = 2030 count = 139 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 580.117126 last_received_ts = 580.116699 last_seq = 2030 current_ts = 580.133789 current_received_ts = 580.133362 current_seq = 2031 count = 140 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 580.133789 last_received_ts = 580.133362 last_seq = 2031 current_ts = 580.150452 current_received_ts = 580.150085 current_seq = 2032 count = 141 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 34us (kms_flip:20245) DEBUG: name = flip last_ts = 580.150452 last_received_ts = 580.150085 last_seq = 2032 current_ts = 580.167114 current_received_ts = 580.166748 current_seq = 2033 count = 142 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 580.167114 last_received_ts = 580.166748 last_seq = 2033 current_ts = 580.183777 current_received_ts = 580.183350 current_seq = 2034 count = 143 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.183777 last_received_ts = 580.183350 last_seq = 2034 current_ts = 580.200439 current_received_ts = 580.200073 current_seq = 2035 count = 144 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 580.200439 last_received_ts = 580.200073 last_seq = 2035 current_ts = 580.217102 current_received_ts = 580.216675 current_seq = 2036 count = 145 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 24us (kms_flip:20245) DEBUG: name = flip last_ts = 580.217102 last_received_ts = 580.216675 last_seq = 2036 current_ts = 580.233765 current_received_ts = 580.233398 current_seq = 2037 count = 146 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.233765 last_received_ts = 580.233398 last_seq = 2037 current_ts = 580.250427 current_received_ts = 580.250122 current_seq = 2038 count = 147 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.250427 last_received_ts = 580.250122 last_seq = 2038 current_ts = 580.267090 current_received_ts = 580.266785 current_seq = 2039 count = 148 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 580.267090 last_received_ts = 580.266785 last_seq = 2039 current_ts = 580.283752 current_received_ts = 580.283447 current_seq = 2040 count = 149 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.283752 last_received_ts = 580.283447 last_seq = 2040 current_ts = 580.300415 current_received_ts = 580.300049 current_seq = 2041 count = 150 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.300415 last_received_ts = 580.300049 last_seq = 2041 current_ts = 580.317139 current_received_ts = 580.316772 current_seq = 2042 count = 151 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 580.317139 last_received_ts = 580.316772 last_seq = 2042 current_ts = 580.333801 current_received_ts = 580.333496 current_seq = 2043 count = 152 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.333801 last_received_ts = 580.333496 last_seq = 2043 current_ts = 580.350464 current_received_ts = 580.350159 current_seq = 2044 count = 153 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 241us (kms_flip:20245) DEBUG: name = flip last_ts = 580.350464 last_received_ts = 580.350159 last_seq = 2044 current_ts = 580.367126 current_received_ts = 580.366760 current_seq = 2045 count = 154 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 24us (kms_flip:20245) DEBUG: name = flip last_ts = 580.367126 last_received_ts = 580.366760 last_seq = 2045 current_ts = 580.383789 current_received_ts = 580.383362 current_seq = 2046 count = 155 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 24us (kms_flip:20245) DEBUG: name = flip last_ts = 580.383789 last_received_ts = 580.383362 last_seq = 2046 current_ts = 580.400452 current_received_ts = 580.400024 current_seq = 2047 count = 156 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 214us (kms_flip:20245) DEBUG: name = flip last_ts = 580.400452 last_received_ts = 580.400024 last_seq = 2047 current_ts = 580.417114 current_received_ts = 580.416748 current_seq = 2048 count = 157 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.417114 last_received_ts = 580.416748 last_seq = 2048 current_ts = 580.433777 current_received_ts = 580.433350 current_seq = 2049 count = 158 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 580.433777 last_received_ts = 580.433350 last_seq = 2049 current_ts = 580.450439 current_received_ts = 580.449951 current_seq = 2050 count = 159 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 42us (kms_flip:20245) DEBUG: name = flip last_ts = 580.450439 last_received_ts = 580.449951 last_seq = 2050 current_ts = 580.467102 current_received_ts = 580.466736 current_seq = 2051 count = 160 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 580.467102 last_received_ts = 580.466736 last_seq = 2051 current_ts = 580.483765 current_received_ts = 580.483521 current_seq = 2052 count = 161 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 233us (kms_flip:20245) DEBUG: name = flip last_ts = 580.483765 last_received_ts = 580.483521 last_seq = 2052 current_ts = 580.500488 current_received_ts = 580.500183 current_seq = 2053 count = 162 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 240us (kms_flip:20245) DEBUG: name = flip last_ts = 580.500488 last_received_ts = 580.500183 last_seq = 2053 current_ts = 580.517151 current_received_ts = 580.516785 current_seq = 2054 count = 163 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 580.517151 last_received_ts = 580.516785 last_seq = 2054 current_ts = 580.533813 current_received_ts = 580.533386 current_seq = 2055 count = 164 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.533813 last_received_ts = 580.533386 last_seq = 2055 current_ts = 580.550476 current_received_ts = 580.550110 current_seq = 2056 count = 165 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.550476 last_received_ts = 580.550110 last_seq = 2056 current_ts = 580.567139 current_received_ts = 580.566772 current_seq = 2057 count = 166 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 580.567139 last_received_ts = 580.566772 last_seq = 2057 current_ts = 580.583801 current_received_ts = 580.583435 current_seq = 2058 count = 167 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.583801 last_received_ts = 580.583435 last_seq = 2058 current_ts = 580.600464 current_received_ts = 580.600098 current_seq = 2059 count = 168 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 580.600464 last_received_ts = 580.600098 last_seq = 2059 current_ts = 580.617126 current_received_ts = 580.616760 current_seq = 2060 count = 169 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.617126 last_received_ts = 580.616760 last_seq = 2060 current_ts = 580.633789 current_received_ts = 580.633545 current_seq = 2061 count = 170 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 41us (kms_flip:20245) DEBUG: name = flip last_ts = 580.633789 last_received_ts = 580.633545 last_seq = 2061 current_ts = 580.650452 current_received_ts = 580.650146 current_seq = 2062 count = 171 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 40us (kms_flip:20245) DEBUG: name = flip last_ts = 580.650452 last_received_ts = 580.650146 last_seq = 2062 current_ts = 580.667175 current_received_ts = 580.666748 current_seq = 2063 count = 172 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 580.667175 last_received_ts = 580.666748 last_seq = 2063 current_ts = 580.683838 current_received_ts = 580.683472 current_seq = 2064 count = 173 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.683838 last_received_ts = 580.683472 last_seq = 2064 current_ts = 580.700500 current_received_ts = 580.700134 current_seq = 2065 count = 174 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.700500 last_received_ts = 580.700134 last_seq = 2065 current_ts = 580.717163 current_received_ts = 580.716797 current_seq = 2066 count = 175 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.717163 last_received_ts = 580.716797 last_seq = 2066 current_ts = 580.733826 current_received_ts = 580.733459 current_seq = 2067 count = 176 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.733826 last_received_ts = 580.733459 last_seq = 2067 current_ts = 580.750488 current_received_ts = 580.750061 current_seq = 2068 count = 177 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 39us (kms_flip:20245) DEBUG: name = flip last_ts = 580.750488 last_received_ts = 580.750061 last_seq = 2068 current_ts = 580.767151 current_received_ts = 580.766785 current_seq = 2069 count = 178 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 580.767151 last_received_ts = 580.766785 last_seq = 2069 current_ts = 580.783813 current_received_ts = 580.783386 current_seq = 2070 count = 179 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 580.783813 last_received_ts = 580.783386 last_seq = 2070 current_ts = 580.800476 current_received_ts = 580.800049 current_seq = 2071 count = 180 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 580.800476 last_received_ts = 580.800049 last_seq = 2071 current_ts = 580.817139 current_received_ts = 580.816833 current_seq = 2072 count = 181 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 580.817139 last_received_ts = 580.816833 last_seq = 2072 current_ts = 580.833801 current_received_ts = 580.833557 current_seq = 2073 count = 182 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.833801 last_received_ts = 580.833557 last_seq = 2073 current_ts = 580.850464 current_received_ts = 580.850281 current_seq = 2074 count = 183 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 40us (kms_flip:20245) DEBUG: name = flip last_ts = 580.850464 last_received_ts = 580.850281 last_seq = 2074 current_ts = 580.867188 current_received_ts = 580.866821 current_seq = 2075 count = 184 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 28us (kms_flip:20245) DEBUG: name = flip last_ts = 580.867188 last_received_ts = 580.866821 last_seq = 2075 current_ts = 580.883850 current_received_ts = 580.883484 current_seq = 2076 count = 185 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 25us (kms_flip:20245) DEBUG: name = flip last_ts = 580.883850 last_received_ts = 580.883484 last_seq = 2076 current_ts = 580.900513 current_received_ts = 580.900146 current_seq = 2077 count = 186 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.900513 last_received_ts = 580.900146 last_seq = 2077 current_ts = 580.917175 current_received_ts = 580.916809 current_seq = 2078 count = 187 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.917175 last_received_ts = 580.916809 last_seq = 2078 current_ts = 580.933838 current_received_ts = 580.933411 current_seq = 2079 count = 188 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 580.933838 last_received_ts = 580.933411 last_seq = 2079 current_ts = 580.950500 current_received_ts = 580.950256 current_seq = 2080 count = 189 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 41us (kms_flip:20245) DEBUG: name = flip last_ts = 580.950500 last_received_ts = 580.950256 last_seq = 2080 current_ts = 580.967163 current_received_ts = 580.966797 current_seq = 2081 count = 190 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 39us (kms_flip:20245) DEBUG: name = flip last_ts = 580.967163 last_received_ts = 580.966797 last_seq = 2081 current_ts = 580.983826 current_received_ts = 580.983459 current_seq = 2082 count = 191 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 580.983826 last_received_ts = 580.983459 last_seq = 2082 current_ts = 581.000488 current_received_ts = 581.000061 current_seq = 2083 count = 192 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 581.000488 last_received_ts = 581.000061 last_seq = 2083 current_ts = 581.017151 current_received_ts = 581.016785 current_seq = 2084 count = 193 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 581.017151 last_received_ts = 581.016785 last_seq = 2084 current_ts = 581.033875 current_received_ts = 581.033386 current_seq = 2085 count = 194 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 581.033875 last_received_ts = 581.033386 last_seq = 2085 current_ts = 581.050537 current_received_ts = 581.050171 current_seq = 2086 count = 195 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 30us (kms_flip:20245) DEBUG: name = flip last_ts = 581.050537 last_received_ts = 581.050171 last_seq = 2086 current_ts = 581.067200 current_received_ts = 581.066833 current_seq = 2087 count = 196 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 581.067200 last_received_ts = 581.066833 last_seq = 2087 current_ts = 581.083862 current_received_ts = 581.083435 current_seq = 2088 count = 197 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 581.083862 last_received_ts = 581.083435 last_seq = 2088 current_ts = 581.100525 current_received_ts = 581.100098 current_seq = 2089 count = 198 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 581.100525 last_received_ts = 581.100098 last_seq = 2089 current_ts = 581.117188 current_received_ts = 581.116821 current_seq = 2090 count = 199 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 581.117188 last_received_ts = 581.116821 last_seq = 2090 current_ts = 581.133850 current_received_ts = 581.133423 current_seq = 2091 count = 200 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 581.133850 last_received_ts = 581.133423 last_seq = 2091 current_ts = 581.150513 current_received_ts = 581.150146 current_seq = 2092 count = 201 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 581.150513 last_received_ts = 581.150146 last_seq = 2092 current_ts = 581.167175 current_received_ts = 581.166809 current_seq = 2093 count = 202 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 581.167175 last_received_ts = 581.166809 last_seq = 2093 current_ts = 581.183838 current_received_ts = 581.183411 current_seq = 2094 count = 203 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 581.183838 last_received_ts = 581.183411 last_seq = 2094 current_ts = 581.200500 current_received_ts = 581.200134 current_seq = 2095 count = 204 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 27us (kms_flip:20245) DEBUG: name = flip last_ts = 581.200500 last_received_ts = 581.200134 last_seq = 2095 current_ts = 581.217224 current_received_ts = 581.216797 current_seq = 2096 count = 205 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 254us (kms_flip:20245) DEBUG: name = flip last_ts = 581.217224 last_received_ts = 581.216797 last_seq = 2096 current_ts = 581.233887 current_received_ts = 581.233582 current_seq = 2097 count = 206 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 581.233887 last_received_ts = 581.233582 last_seq = 2097 current_ts = 581.250549 current_received_ts = 581.250244 current_seq = 2098 count = 207 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 26us (kms_flip:20245) DEBUG: name = flip last_ts = 581.250549 last_received_ts = 581.250244 last_seq = 2098 current_ts = 581.267212 current_received_ts = 581.266907 current_seq = 2099 count = 208 seq_step = 1 (kms_flip:20245) DEBUG: Vblank took 538us (kms_flip:20245) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:20245) CRITICAL: Failed assertion: end - start < 500 (kms_flip:20245) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:20245) igt_core-INFO: Stack trace: (kms_flip:20245) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:20245) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() (kms_flip:20245) igt_core-INFO: #2 ../tests/kms_flip.c:1919 run_test() (kms_flip:20245) igt_core-INFO: #3 ../tests/kms_flip.c:2219 __igt_unique____real_main2104() (kms_flip:20245) igt_core-INFO: #4 ../tests/kms_flip.c:2104 main() (kms_flip:20245) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:20245) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:20245) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest C-DP2: FAIL (4.334s)
Dmesg	<6> [577.475518] [IGT] kms_flip: starting dynamic subtest C-DP2 <7> [577.476616] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:554] <7> [577.476917] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:557] <7> [577.524125] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [577.524263] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B] <7> [577.524330] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.enable (expected yes, found no) <7> [577.524469] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.active (expected yes, found no) <7> [577.524586] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in cpu_transcoder (expected 1, found -1) <7> [577.524700] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in lane_count (expected 4, found 0) <7> [577.524810] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in dp_m_n (expected tu 64 data 5190451/8388608 link 288358/524288, found tu 0, data 0/0 link 0/0) <7> [577.524919] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in output_types (expected 0x00000080, found 0x00000000) <7> [577.525037] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [577.525145] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [577.525250] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [577.525355] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [577.525459] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [577.525563] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [577.525667] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [577.525771] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [577.525874] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [577.525978] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0) <7> [577.526094] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0) <7> [577.526204] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [577.526314] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [577.526421] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [577.526528] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [577.526633] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [577.526736] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [577.526839] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [577.526943] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [577.527102] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [577.527207] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [577.527311] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0) <7> [577.527414] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0) <7> [577.527517] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [577.527619] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [577.527721] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [577.527825] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [577.527929] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0) <7> [577.528060] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in enhanced_framing (expected yes, found no) <7> [577.528164] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in pipe_bpp (expected 36, found 0) <7> [577.528267] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [577.528370] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [577.528472] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:269:pipe B] fastset requirement not met in port_clock (expected 270000, found 0) <7> [577.528576] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:269:pipe B] fastset requirement not met, forcing full modeset <7> [577.528682] xe 0000:03:00.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:269:pipe B] releasing TC PLL 2 <7> [577.528817] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [577.528909] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:269:pipe B] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x2 -> 0x0 <7> [577.529023] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:263:cursor B] ddb (4037 - 4096) -> ( 0 - 0), size 59 -> 0 <7> [577.529123] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:269:pipe B] min cdclk: 192000 kHz -> 0 kHz <7> [577.529250] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:269:pipe B] enable: no [modeset] <7> [577.529363] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:153:plane 1B] fb: [NOFB], visible: no <7> [577.529475] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:183:plane 2B] fb: [NOFB], visible: no <7> [577.529583] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:213:plane 3B] fb: [NOFB], visible: no <7> [577.529689] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:243:plane 4B] fb: [NOFB], visible: no <7> [577.529792] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:253:plane 5B] fb: [NOFB], visible: no <7> [577.529896] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:263:cursor B] fb: [NOFB], visible: no <7> [577.530311] xe 0000:03:00.0: [drm:intel_audio_codec_disable [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G] Disable audio codec on [CRTC:269:pipe B] <7> [577.553529] xe 0000:03:00.0: [drm:intel_disable_transcoder [xe]] disabling pipe B <7> [577.571245] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2 <7> [577.574135] xe 0000:03:00.0: [drm:intel_dpll_disable [xe]] disable TC PLL 2 (active 0x2, on? 1) for [CRTC:269:pipe B] <7> [577.576646] xe 0000:03:00.0: [drm:intel_dpll_disable [xe]] disabling TC PLL 2 <7> [577.577418] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:507:DDI TC1/PHY F] <7> [577.577846] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:509:DP-MST A] <7> [577.578280] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:510:DP-MST B] <7> [577.578662] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:511:DP-MST C] <7> [577.579044] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:512:DP-MST D] <7> [577.579386] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:526:DDI TC2/PHY G] <7> [577.579922] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:528:DP-MST A] <7> [577.580284] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:529:DP-MST B] <7> [577.580609] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:530:DP-MST C] <7> [577.580925] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:531:DP-MST D] <7> [577.581250] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:538:DDI TC3/PHY H] <7> [577.581523] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:542:DDI TC4/PHY I] <7> [577.581782] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:544:DP-MST A] <7> [577.582046] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:545:DP-MST B] <7> [577.582325] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:546:DP-MST C] <7> [577.582587] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:547:DP-MST D] <7> [577.582831] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:527:DP-2] <7> [577.583321] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no) <7> [577.583537] xe 0000:03:00.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [577.583935] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [577.584482] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_B <7> [577.584923] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [577.585394] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling PW_2 <7> [577.585635] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:269:pipe B] <7> [577.586217] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C] <7> [577.586938] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:505:pipe D] <7> [577.587098] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C] <7> [577.587124] xe 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:527:DP-2] <7> [577.587223] xe 0000:03:00.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:526:DDI TC2/PHY G][CRTC:387:pipe C] DP link limits: pixel clock 148500 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 36 min link_bpp 18.0000 max link_bpp 36.0000 <7> [577.587389] xe 0000:03:00.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 270000 bpp input 36 compressed 0.0000 HDR no link rate required 668250 available 1080000 <7> [577.587548] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:387:pipe C] hw max bpp: 36, pipe bpp: 36, dithering: 0 <7> [577.587702] xe 0000:03:00.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:526:DDI TC2/PHY G] [CRTC:387:pipe C] <7> [577.587858] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.enable (expected no, found yes) <7> [577.588014] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.active (expected no, found yes) <7> [577.588160] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2) <7> [577.588304] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in lane_count (expected 0, found 4) <7> [577.588438] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 5190451/8388608 link 288358/524288) <7> [577.588571] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in output_types (expected 0x00000000, found 0x00000080) <7> [577.588698] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [577.588829] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [577.588956] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [577.589096] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [577.589220] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [577.589342] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [577.589455] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [577.589566] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [577.589676] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [577.589784] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084) <7> [577.589891] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089) <7> [577.590003] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [577.590109] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [577.590207] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [577.590306] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [577.590409] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [577.590512] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [577.590612] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [577.590709] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [577.590806] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [577.590903] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [577.591010] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084) <7> [577.591111] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089) <7> [577.591212] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [577.591311] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [577.591410] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [577.591507] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [577.591604] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [577.591700] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in enhanced_framing (expected no, found yes) <7> [577.591795] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 36) <7> [577.591892] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [577.591992] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [577.592088] xe 0000:03:00.0: [drm:intel_pipe_config_compare [xe]] [CRTC:387:pipe C] fastset requirement not met in port_clock (expected 0, found 270000) <7> [577.592186] xe 0000:03:00.0: [drm:intel_atomic_check [xe]] [CRTC:387:pipe C] fastset requirement not met, forcing full modeset <7> [577.592300] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xd (total dbuf slices 0xf), mbus joined? no->no <7> [577.592386] xe 0000:03:00.0: [drm:skl_compute_wm [xe]] [CRTC:387:pipe C] dbuf slices 0x0 -> 0xc, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4 <7> [577.592491] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:271:plane 1C] ddb ( 0 - 0) -> ( 0 - 1989), size 0 -> 1989 <7> [577.592574] xe 0000:03:00.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:381:cursor C] ddb ( 0 - 0) -> (1989 - 2048), size 0 -> 59 <7> [577.592653] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [577.592730] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 4, 9, 9, 17, 17, 17, 17, 0, 15, 0 <7> [577.592806] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 62, 62, 139, 139, 261, 261, 261, 261, 137, 230, 244 <7> [577.592881] xe 0000:03:00.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:271:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 123, 123, 245, 245, 367, 367, 0, 0, 138, 306, 306 <7> [577.592967] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] [CRTC:387:pipe C] data rate 594000 num active planes 1 <7> [577.593088] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 33600 required 624 qgv_peak_bw: 48000 <7> [577.593192] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 53000 required 624 qgv_peak_bw: 48000 <7> [577.593291] xe 0000:03:00.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 48000 for required data rate: 624 <7> [577.593400] xe 0000:03:00.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:387:pipe C] min cdclk: 0 kHz -> 192000 kHz <7> [577.593524] xe 0000:03:00.0: [drm:intel_find_dpll [xe]] [CRTC:387:pipe C] allocated TC PLL 2 <7> [577.593625] xe 0000:03:00.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:387:pipe C] reserving TC PLL 2 <7> [577.593725] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [CRTC:387:pipe C] enable: yes [modeset] <7> [577.593834] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: DP (0x80), output format: RGB, sink format: RGB <7> [577.593939] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: C, pipe bpp: 36, dithering: 0 <7> [577.594048] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [577.594147] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [577.594246] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [577.594345] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [577.594444] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 5190451, data_n: 8388608, link_m: 288358, link_n: 524288, tu: 64 <7> [577.594543] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [577.594641] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: enabled <7> [577.594738] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [577.594835] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] psr: disabled, selective update: disabled, panel replay: disabled, selective fetch: disabled <7> [577.594932] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [577.595036] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] audio: 1, infoframes: 0, infoframes enabled: 0x0 <7> [577.595132] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 10 00 09 00 68 36 00 01 00 00 00 00 00 00 00 00 <7> [577.595228] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 61 a4 9a 00 44 50 46 39 30 34 33 35 09 07 07 11 <7> [577.595324] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ELD: 17 50 51 07 00 00 00 00 <7> [577.595426] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [577.595527] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [577.595627] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1125, vmax: 1125, flipline: 1125, pipeline full: 0, guardband: 42 vsync start: 41, vsync end: 36 <7> [577.595725] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1083, vmax vblank: 1083, vmin vtotal: 1125, vmax vtotal: 1125 <7> [577.595822] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [577.595919] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 <7> [577.596024] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 <7> [577.596122] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [577.596219] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x40 0x5 <7> [577.596316] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [577.596415] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port clock: 270000, pixel rate 148500, min cdclk 192000, min voltage level 0 <7> [577.596518] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] linetime: 119, ips linetime: 0 <7> [577.596618] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [577.596716] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe src: 1920x1080+0+0 <7> [577.596813] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [577.596911] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [577.597012] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [577.597109] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: no, tbt_mode: no <7> [577.597207] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] c20pll_hw_state: <7> [577.597303] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] tx[0] = 0xbe88, tx[1] = 0x4800, tx[2] = 0x0000 <7> [577.597399] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] cmn[0] = 0x0500, cmn[1] = 0x0005, cmn[2] = 0x0000, cmn[3] = 0x0000 <7> [577.597494] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[0] = 0x308c <7> [577.597590] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[1] = 0x2110 <7> [577.597685] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[2] = 0xcc9c <7> [577.597780] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[3] = 0xbfc1 <7> [577.597875] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[4] = 0x4b9a <7> [577.597970] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[5] = 0x3f81 <7> [577.598106] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[6] = 0x2000 <7> [577.598202] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[7] = 0x0001 <7> [577.598298] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[8] = 0x5000 <7> [577.598394] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[9] = 0x0000 <7> [577.598489] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] mpllb[10] = 0x0000 <7> [577.598589] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] vdr: custom width: 0x00, serdes rate: 0x42, hdmi rate: 0x00 <7> [577.598688] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [577.598786] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [577.598884] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [577.598984] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [577.599079] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [577.599174] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [577.599270] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [577.599364] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [577.599461] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [577.599557] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [577.599655] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [577.599756] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [577.599855] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:271:plane 1C] fb: [FB:554] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [577.599956] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [577.600067] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [577.600167] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:301:plane 2C] fb: [NOFB], visible: no <7> [577.600265] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:331:plane 3C] fb: [NOFB], visible: no <7> [577.600361] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:361:plane 4C] fb: [NOFB], visible: no <7> [577.600458] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:371:plane 5C] fb: [NOFB], visible: no <7> [577.600553] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] [PLANE:381:cursor C] fb: [NOFB], visible: no <7> [577.601166] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [577.601285] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling PW_C <7> [577.601408] xe 0000:03:00.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x4 (CLKGATE_DIS_DSSDSC=0x8a000000) <7> [577.601519] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:507:DDI TC1/PHY F] <7> [577.601615] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:509:DP-MST A] <7> [577.601708] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:510:DP-MST B] <7> [577.601796] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:511:DP-MST C] <7> [577.601884] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:512:DP-MST D] <7> [577.601972] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:526:DDI TC2/PHY G] <7> [577.602074] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:528:DP-MST A] <7> [577.602165] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:529:DP-MST B] <7> [577.602254] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:530:DP-MST C] <7> [577.602340] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:531:DP-MST D] <7> [577.602425] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:538:DDI TC3/PHY H] <7> [577.602512] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:542:DDI TC4/PHY I] <7> [577.602604] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:544:DP-MST A] <7> [577.602694] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:545:DP-MST B] <7> [577.602782] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:546:DP-MST C] <7> [577.602869] xe 0000:03:00.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:547:DP-MST D] <7> [577.602965] xe 0000:03:00.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xd <7> [577.603149] xe 0000:03:00.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 2 (mbus joined: no) <7> [577.603256] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enable TC PLL 2 (active 0x4, on? 0) for [CRTC:387:pipe C] <7> [577.603357] xe 0000:03:00.0: [drm:intel_dpll_enable [xe]] enabling TC PLL 2 <7> [577.607463] xe 0000:03:00.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX USBC2/DDI TC2/PHY G: DPCD: 12 14 c4 01 01 15 01 81 00 01 04 01 0f 00 01 <7> [577.612205] xe 0000:03:00.0: [drm:intel_dp_init_lttpr_and_dprx_caps [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] LTTPR common capabilities: 00 00 00 00 00 00 00 00 <7> [577.613214] xe 0000:03:00.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX USBC2/DDI TC2/PHY G: DPCD: 12 14 c4 01 01 15 01 81 00 01 04 01 0f 00 01 <7> [577.613655] xe 0000:03:00.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using LINK_BW_SET value 0a <7> [577.615162] xe 0000:03:00.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [577.615723] xe 0000:03:00.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using DP training pattern TPS1 <7> [577.623032] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Clock recovery OK <7> [577.623146] xe 0000:03:00.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Using DP training pattern TPS3 <7> [577.630036] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Channel EQ done. DP Training successful <7> [577.630284] xe 0000:03:00.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G][DPRX] Link Training passed at link rate = 270000, lane count = 4 <7> [577.631656] xe 0000:03:00.0: [drm:intel_enable_transcoder [xe]] enabling pipe C <7> [577.649338] xe 0000:03:00.0: [drm:intel_audio_codec_enable [xe]] [CONNECTOR:527:DP-2][ENCODER:526:DDI TC2/PHY G] Enable audio codec on [CRTC:387:pipe C], 40 bytes ELD <7> [577.665952] xe 0000:03:00.0: [drm:verify_connector_state [xe]] [CONNECTOR:527:DP-2] <7> [577.666886] xe 0000:03:00.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:387:pipe C] <7> [577.732169] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2 <7> [579.660153] xe 0000:03:00.0: [drm:intel_power_well_enable [xe]] enabling AUX_TC2 <7> [579.763996] xe 0000:03:00.0: [drm:intel_power_well_disable [xe]] disabling AUX_TC2 <6> [581.823437] [IGT] kms_flip: finished subtest C-DP2, FAIL

Detail

Value

Duration

4.33 seconds

Hostname

shard-bmg-6

Igt-Version

IGT-Version: 2.4-g2a9f1c1ae (x86_64) (Linux: 7.0.0-rc7-lgci-xe-xe-pw-160184v5-debug+ x86_64)

Out

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

Err

Starting dynamic subtest: C-DP2
(kms_flip:20245) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:20245) CRITICAL: Failed assertion: end - start < 500
(kms_flip:20245) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest C-DP2 failed.
**** DEBUG ****
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.250366
last_received_ts = 579.250061
last_seq = 1978
current_ts = 579.267029
current_received_ts = 579.266602
current_seq = 1979
count = 88
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.267029
last_received_ts = 579.266602
last_seq = 1979
current_ts = 579.283691
current_received_ts = 579.283386
current_seq = 1980
count = 89
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 41us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.283691
last_received_ts = 579.283386
last_seq = 1980
current_ts = 579.300354
current_received_ts = 579.300049
current_seq = 1981
count = 90
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 39us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.300354
last_received_ts = 579.300049
last_seq = 1981
current_ts = 579.317017
current_received_ts = 579.316711
current_seq = 1982
count = 91
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.317017
last_received_ts = 579.316711
last_seq = 1982
current_ts = 579.333679
current_received_ts = 579.333252
current_seq = 1983
count = 92
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.333679
last_received_ts = 579.333252
last_seq = 1983
current_ts = 579.350342
current_received_ts = 579.350037
current_seq = 1984
count = 93
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.350342
last_received_ts = 579.350037
last_seq = 1984
current_ts = 579.367004
current_received_ts = 579.366699
current_seq = 1985
count = 94
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.367004
last_received_ts = 579.366699
last_seq = 1985
current_ts = 579.383667
current_received_ts = 579.383484
current_seq = 1986
count = 95
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 40us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.383667
last_received_ts = 579.383484
last_seq = 1986
current_ts = 579.400330
current_received_ts = 579.400085
current_seq = 1987
count = 96
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 38us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.400330
last_received_ts = 579.400085
last_seq = 1987
current_ts = 579.417053
current_received_ts = 579.416748
current_seq = 1988
count = 97
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.417053
last_received_ts = 579.416748
last_seq = 1988
current_ts = 579.433716
current_received_ts = 579.433411
current_seq = 1989
count = 98
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.433716
last_received_ts = 579.433411
last_seq = 1989
current_ts = 579.450378
current_received_ts = 579.450073
current_seq = 1990
count = 99
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.450378
last_received_ts = 579.450073
last_seq = 1990
current_ts = 579.467041
current_received_ts = 579.466736
current_seq = 1991
count = 100
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.467041
last_received_ts = 579.466736
last_seq = 1991
current_ts = 579.483704
current_received_ts = 579.483398
current_seq = 1992
count = 101
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.483704
last_received_ts = 579.483398
last_seq = 1992
current_ts = 579.500366
current_received_ts = 579.500061
current_seq = 1993
count = 102
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.500366
last_received_ts = 579.500061
last_seq = 1993
current_ts = 579.517029
current_received_ts = 579.516724
current_seq = 1994
count = 103
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.517029
last_received_ts = 579.516724
last_seq = 1994
current_ts = 579.533691
current_received_ts = 579.533264
current_seq = 1995
count = 104
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.533691
last_received_ts = 579.533264
last_seq = 1995
current_ts = 579.550354
current_received_ts = 579.549988
current_seq = 1996
count = 105
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 24us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.550354
last_received_ts = 579.549988
last_seq = 1996
current_ts = 579.567017
current_received_ts = 579.566650
current_seq = 1997
count = 106
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.567017
last_received_ts = 579.566650
last_seq = 1997
current_ts = 579.583679
current_received_ts = 579.583435
current_seq = 1998
count = 107
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.583679
last_received_ts = 579.583435
last_seq = 1998
current_ts = 579.600403
current_received_ts = 579.600098
current_seq = 1999
count = 108
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.600403
last_received_ts = 579.600098
last_seq = 1999
current_ts = 579.617065
current_received_ts = 579.616638
current_seq = 2000
count = 109
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.617065
last_received_ts = 579.616638
last_seq = 2000
current_ts = 579.633728
current_received_ts = 579.633362
current_seq = 2001
count = 110
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.633728
last_received_ts = 579.633362
last_seq = 2001
current_ts = 579.650391
current_received_ts = 579.650085
current_seq = 2002
count = 111
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 43us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.650391
last_received_ts = 579.650085
last_seq = 2002
current_ts = 579.667053
current_received_ts = 579.666748
current_seq = 2003
count = 112
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.667053
last_received_ts = 579.666748
last_seq = 2003
current_ts = 579.683716
current_received_ts = 579.683411
current_seq = 2004
count = 113
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.683716
last_received_ts = 579.683411
last_seq = 2004
current_ts = 579.700378
current_received_ts = 579.700073
current_seq = 2005
count = 114
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.700378
last_received_ts = 579.700073
last_seq = 2005
current_ts = 579.717041
current_received_ts = 579.716736
current_seq = 2006
count = 115
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.717041
last_received_ts = 579.716736
last_seq = 2006
current_ts = 579.733704
current_received_ts = 579.733398
current_seq = 2007
count = 116
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.733704
last_received_ts = 579.733398
last_seq = 2007
current_ts = 579.750366
current_received_ts = 579.750000
current_seq = 2008
count = 117
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 40us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.750366
last_received_ts = 579.750000
last_seq = 2008
current_ts = 579.767090
current_received_ts = 579.766785
current_seq = 2009
count = 118
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 29us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.767090
last_received_ts = 579.766785
last_seq = 2009
current_ts = 579.783752
current_received_ts = 579.783447
current_seq = 2010
count = 119
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.783752
last_received_ts = 579.783447
last_seq = 2010
current_ts = 579.800415
current_received_ts = 579.799988
current_seq = 2011
count = 120
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 40us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.800415
last_received_ts = 579.799988
last_seq = 2011
current_ts = 579.817078
current_received_ts = 579.816772
current_seq = 2012
count = 121
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 28us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.817078
last_received_ts = 579.816772
last_seq = 2012
current_ts = 579.833740
current_received_ts = 579.833435
current_seq = 2013
count = 122
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.833740
last_received_ts = 579.833435
last_seq = 2013
current_ts = 579.850403
current_received_ts = 579.850098
current_seq = 2014
count = 123
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.850403
last_received_ts = 579.850098
last_seq = 2014
current_ts = 579.867065
current_received_ts = 579.866577
current_seq = 2015
count = 124
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.867065
last_received_ts = 579.866577
last_seq = 2015
current_ts = 579.883728
current_received_ts = 579.883423
current_seq = 2016
count = 125
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.883728
last_received_ts = 579.883423
last_seq = 2016
current_ts = 579.900391
current_received_ts = 579.900085
current_seq = 2017
count = 126
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.900391
last_received_ts = 579.900085
last_seq = 2017
current_ts = 579.917053
current_received_ts = 579.916748
current_seq = 2018
count = 127
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.917053
last_received_ts = 579.916748
last_seq = 2018
current_ts = 579.933777
current_received_ts = 579.933411
current_seq = 2019
count = 128
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.933777
last_received_ts = 579.933411
last_seq = 2019
current_ts = 579.950439
current_received_ts = 579.950073
current_seq = 2020
count = 129
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.950439
last_received_ts = 579.950073
last_seq = 2020
current_ts = 579.967102
current_received_ts = 579.966797
current_seq = 2021
count = 130
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.967102
last_received_ts = 579.966797
last_seq = 2021
current_ts = 579.983765
current_received_ts = 579.983337
current_seq = 2022
count = 131
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 579.983765
last_received_ts = 579.983337
last_seq = 2022
current_ts = 580.000427
current_received_ts = 580.000122
current_seq = 2023
count = 132
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.000427
last_received_ts = 580.000122
last_seq = 2023
current_ts = 580.017090
current_received_ts = 580.016785
current_seq = 2024
count = 133
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.017090
last_received_ts = 580.016785
last_seq = 2024
current_ts = 580.033752
current_received_ts = 580.033325
current_seq = 2025
count = 134
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.033752
last_received_ts = 580.033325
last_seq = 2025
current_ts = 580.050415
current_received_ts = 580.050049
current_seq = 2026
count = 135
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.050415
last_received_ts = 580.050049
last_seq = 2026
current_ts = 580.067078
current_received_ts = 580.066650
current_seq = 2027
count = 136
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.067078
last_received_ts = 580.066650
last_seq = 2027
current_ts = 580.083740
current_received_ts = 580.083435
current_seq = 2028
count = 137
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.083740
last_received_ts = 580.083435
last_seq = 2028
current_ts = 580.100403
current_received_ts = 580.100098
current_seq = 2029
count = 138
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.100403
last_received_ts = 580.100098
last_seq = 2029
current_ts = 580.117126
current_received_ts = 580.116699
current_seq = 2030
count = 139
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.117126
last_received_ts = 580.116699
last_seq = 2030
current_ts = 580.133789
current_received_ts = 580.133362
current_seq = 2031
count = 140
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.133789
last_received_ts = 580.133362
last_seq = 2031
current_ts = 580.150452
current_received_ts = 580.150085
current_seq = 2032
count = 141
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 34us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.150452
last_received_ts = 580.150085
last_seq = 2032
current_ts = 580.167114
current_received_ts = 580.166748
current_seq = 2033
count = 142
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.167114
last_received_ts = 580.166748
last_seq = 2033
current_ts = 580.183777
current_received_ts = 580.183350
current_seq = 2034
count = 143
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.183777
last_received_ts = 580.183350
last_seq = 2034
current_ts = 580.200439
current_received_ts = 580.200073
current_seq = 2035
count = 144
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.200439
last_received_ts = 580.200073
last_seq = 2035
current_ts = 580.217102
current_received_ts = 580.216675
current_seq = 2036
count = 145
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 24us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.217102
last_received_ts = 580.216675
last_seq = 2036
current_ts = 580.233765
current_received_ts = 580.233398
current_seq = 2037
count = 146
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.233765
last_received_ts = 580.233398
last_seq = 2037
current_ts = 580.250427
current_received_ts = 580.250122
current_seq = 2038
count = 147
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.250427
last_received_ts = 580.250122
last_seq = 2038
current_ts = 580.267090
current_received_ts = 580.266785
current_seq = 2039
count = 148
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.267090
last_received_ts = 580.266785
last_seq = 2039
current_ts = 580.283752
current_received_ts = 580.283447
current_seq = 2040
count = 149
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.283752
last_received_ts = 580.283447
last_seq = 2040
current_ts = 580.300415
current_received_ts = 580.300049
current_seq = 2041
count = 150
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.300415
last_received_ts = 580.300049
last_seq = 2041
current_ts = 580.317139
current_received_ts = 580.316772
current_seq = 2042
count = 151
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.317139
last_received_ts = 580.316772
last_seq = 2042
current_ts = 580.333801
current_received_ts = 580.333496
current_seq = 2043
count = 152
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.333801
last_received_ts = 580.333496
last_seq = 2043
current_ts = 580.350464
current_received_ts = 580.350159
current_seq = 2044
count = 153
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 241us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.350464
last_received_ts = 580.350159
last_seq = 2044
current_ts = 580.367126
current_received_ts = 580.366760
current_seq = 2045
count = 154
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 24us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.367126
last_received_ts = 580.366760
last_seq = 2045
current_ts = 580.383789
current_received_ts = 580.383362
current_seq = 2046
count = 155
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 24us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.383789
last_received_ts = 580.383362
last_seq = 2046
current_ts = 580.400452
current_received_ts = 580.400024
current_seq = 2047
count = 156
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 214us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.400452
last_received_ts = 580.400024
last_seq = 2047
current_ts = 580.417114
current_received_ts = 580.416748
current_seq = 2048
count = 157
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.417114
last_received_ts = 580.416748
last_seq = 2048
current_ts = 580.433777
current_received_ts = 580.433350
current_seq = 2049
count = 158
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.433777
last_received_ts = 580.433350
last_seq = 2049
current_ts = 580.450439
current_received_ts = 580.449951
current_seq = 2050
count = 159
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 42us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.450439
last_received_ts = 580.449951
last_seq = 2050
current_ts = 580.467102
current_received_ts = 580.466736
current_seq = 2051
count = 160
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.467102
last_received_ts = 580.466736
last_seq = 2051
current_ts = 580.483765
current_received_ts = 580.483521
current_seq = 2052
count = 161
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 233us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.483765
last_received_ts = 580.483521
last_seq = 2052
current_ts = 580.500488
current_received_ts = 580.500183
current_seq = 2053
count = 162
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 240us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.500488
last_received_ts = 580.500183
last_seq = 2053
current_ts = 580.517151
current_received_ts = 580.516785
current_seq = 2054
count = 163
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.517151
last_received_ts = 580.516785
last_seq = 2054
current_ts = 580.533813
current_received_ts = 580.533386
current_seq = 2055
count = 164
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.533813
last_received_ts = 580.533386
last_seq = 2055
current_ts = 580.550476
current_received_ts = 580.550110
current_seq = 2056
count = 165
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.550476
last_received_ts = 580.550110
last_seq = 2056
current_ts = 580.567139
current_received_ts = 580.566772
current_seq = 2057
count = 166
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.567139
last_received_ts = 580.566772
last_seq = 2057
current_ts = 580.583801
current_received_ts = 580.583435
current_seq = 2058
count = 167
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.583801
last_received_ts = 580.583435
last_seq = 2058
current_ts = 580.600464
current_received_ts = 580.600098
current_seq = 2059
count = 168
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.600464
last_received_ts = 580.600098
last_seq = 2059
current_ts = 580.617126
current_received_ts = 580.616760
current_seq = 2060
count = 169
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.617126
last_received_ts = 580.616760
last_seq = 2060
current_ts = 580.633789
current_received_ts = 580.633545
current_seq = 2061
count = 170
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 41us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.633789
last_received_ts = 580.633545
last_seq = 2061
current_ts = 580.650452
current_received_ts = 580.650146
current_seq = 2062
count = 171
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 40us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.650452
last_received_ts = 580.650146
last_seq = 2062
current_ts = 580.667175
current_received_ts = 580.666748
current_seq = 2063
count = 172
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.667175
last_received_ts = 580.666748
last_seq = 2063
current_ts = 580.683838
current_received_ts = 580.683472
current_seq = 2064
count = 173
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.683838
last_received_ts = 580.683472
last_seq = 2064
current_ts = 580.700500
current_received_ts = 580.700134
current_seq = 2065
count = 174
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.700500
last_received_ts = 580.700134
last_seq = 2065
current_ts = 580.717163
current_received_ts = 580.716797
current_seq = 2066
count = 175
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.717163
last_received_ts = 580.716797
last_seq = 2066
current_ts = 580.733826
current_received_ts = 580.733459
current_seq = 2067
count = 176
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.733826
last_received_ts = 580.733459
last_seq = 2067
current_ts = 580.750488
current_received_ts = 580.750061
current_seq = 2068
count = 177
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 39us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.750488
last_received_ts = 580.750061
last_seq = 2068
current_ts = 580.767151
current_received_ts = 580.766785
current_seq = 2069
count = 178
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.767151
last_received_ts = 580.766785
last_seq = 2069
current_ts = 580.783813
current_received_ts = 580.783386
current_seq = 2070
count = 179
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.783813
last_received_ts = 580.783386
last_seq = 2070
current_ts = 580.800476
current_received_ts = 580.800049
current_seq = 2071
count = 180
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.800476
last_received_ts = 580.800049
last_seq = 2071
current_ts = 580.817139
current_received_ts = 580.816833
current_seq = 2072
count = 181
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.817139
last_received_ts = 580.816833
last_seq = 2072
current_ts = 580.833801
current_received_ts = 580.833557
current_seq = 2073
count = 182
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.833801
last_received_ts = 580.833557
last_seq = 2073
current_ts = 580.850464
current_received_ts = 580.850281
current_seq = 2074
count = 183
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 40us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.850464
last_received_ts = 580.850281
last_seq = 2074
current_ts = 580.867188
current_received_ts = 580.866821
current_seq = 2075
count = 184
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 28us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.867188
last_received_ts = 580.866821
last_seq = 2075
current_ts = 580.883850
current_received_ts = 580.883484
current_seq = 2076
count = 185
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 25us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.883850
last_received_ts = 580.883484
last_seq = 2076
current_ts = 580.900513
current_received_ts = 580.900146
current_seq = 2077
count = 186
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.900513
last_received_ts = 580.900146
last_seq = 2077
current_ts = 580.917175
current_received_ts = 580.916809
current_seq = 2078
count = 187
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.917175
last_received_ts = 580.916809
last_seq = 2078
current_ts = 580.933838
current_received_ts = 580.933411
current_seq = 2079
count = 188
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.933838
last_received_ts = 580.933411
last_seq = 2079
current_ts = 580.950500
current_received_ts = 580.950256
current_seq = 2080
count = 189
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 41us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.950500
last_received_ts = 580.950256
last_seq = 2080
current_ts = 580.967163
current_received_ts = 580.966797
current_seq = 2081
count = 190
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 39us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.967163
last_received_ts = 580.966797
last_seq = 2081
current_ts = 580.983826
current_received_ts = 580.983459
current_seq = 2082
count = 191
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 580.983826
last_received_ts = 580.983459
last_seq = 2082
current_ts = 581.000488
current_received_ts = 581.000061
current_seq = 2083
count = 192
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 581.000488
last_received_ts = 581.000061
last_seq = 2083
current_ts = 581.017151
current_received_ts = 581.016785
current_seq = 2084
count = 193
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 581.017151
last_received_ts = 581.016785
last_seq = 2084
current_ts = 581.033875
current_received_ts = 581.033386
current_seq = 2085
count = 194
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 581.033875
last_received_ts = 581.033386
last_seq = 2085
current_ts = 581.050537
current_received_ts = 581.050171
current_seq = 2086
count = 195
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 30us
(kms_flip:20245) DEBUG: name = flip
last_ts = 581.050537
last_received_ts = 581.050171
last_seq = 2086
current_ts = 581.067200
current_received_ts = 581.066833
current_seq = 2087
count = 196
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 581.067200
last_received_ts = 581.066833
last_seq = 2087
current_ts = 581.083862
current_received_ts = 581.083435
current_seq = 2088
count = 197
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 581.083862
last_received_ts = 581.083435
last_seq = 2088
current_ts = 581.100525
current_received_ts = 581.100098
current_seq = 2089
count = 198
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 581.100525
last_received_ts = 581.100098
last_seq = 2089
current_ts = 581.117188
current_received_ts = 581.116821
current_seq = 2090
count = 199
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 581.117188
last_received_ts = 581.116821
last_seq = 2090
current_ts = 581.133850
current_received_ts = 581.133423
current_seq = 2091
count = 200
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 581.133850
last_received_ts = 581.133423
last_seq = 2091
current_ts = 581.150513
current_received_ts = 581.150146
current_seq = 2092
count = 201
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 581.150513
last_received_ts = 581.150146
last_seq = 2092
current_ts = 581.167175
current_received_ts = 581.166809
current_seq = 2093
count = 202
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 581.167175
last_received_ts = 581.166809
last_seq = 2093
current_ts = 581.183838
current_received_ts = 581.183411
current_seq = 2094
count = 203
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 581.183838
last_received_ts = 581.183411
last_seq = 2094
current_ts = 581.200500
current_received_ts = 581.200134
current_seq = 2095
count = 204
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 27us
(kms_flip:20245) DEBUG: name = flip
last_ts = 581.200500
last_received_ts = 581.200134
last_seq = 2095
current_ts = 581.217224
current_received_ts = 581.216797
current_seq = 2096
count = 205
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 254us
(kms_flip:20245) DEBUG: name = flip
last_ts = 581.217224
last_received_ts = 581.216797
last_seq = 2096
current_ts = 581.233887
current_received_ts = 581.233582
current_seq = 2097
count = 206
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 581.233887
last_received_ts = 581.233582
last_seq = 2097
current_ts = 581.250549
current_received_ts = 581.250244
current_seq = 2098
count = 207
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 26us
(kms_flip:20245) DEBUG: name = flip
last_ts = 581.250549
last_received_ts = 581.250244
last_seq = 2098
current_ts = 581.267212
current_received_ts = 581.266907
current_seq = 2099
count = 208
seq_step = 1
(kms_flip:20245) DEBUG: Vblank took 538us
(kms_flip:20245) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:20245) CRITICAL: Failed assertion: end - start < 500
(kms_flip:20245) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:20245) igt_core-INFO: Stack trace:
(kms_flip:20245) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:20245) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
(kms_flip:20245) igt_core-INFO:   #2 ../tests/kms_flip.c:1919 run_test()
(kms_flip:20245) igt_core-INFO:   #3 ../tests/kms_flip.c:2219 __igt_unique____real_main2104()
(kms_flip:20245) igt_core-INFO:   #4 ../tests/kms_flip.c:2104 main()
(kms_flip:20245) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:20245) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:20245) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-DP2: FAIL (4.334s)

Dmesg

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

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

<7> [577.476917] xe 0000:03:00.0: [drm:drm_mode_addfb2] [FB:557]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [577.596415] xe 0000:03:00.0: [drm:intel_crtc_state_dump [xe]] port clock: 270000, pixel rate 148500, min cdclk 192000, min voltage level 0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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