igt@kms_flip@flip-vs-expired-vblank-interruptible@b-hdmi-a2 on shard-glk@IGTPW

Detail	Value
Duration	2.97 seconds
Hostname	shard-glk9
Igt-Version	IGT-Version: 2.4-g71dd1e2fa (x86_64) (Linux: 7.0.0-rc6-CI_DRM_18266-g35370a958ae2+ x86_64)
Out	Starting dynamic subtest: B-HDMI-A2 1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0() #2 ../tests/kms_flip.c:1891 run_test() #3 ../tests/kms_flip.c:2162 __igt_unique____real_main2047() #4 ../tests/kms_flip.c:2047 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest B-HDMI-A2: FAIL (2.974s)
Err	Starting dynamic subtest: B-HDMI-A2 (kms_flip:2340) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930: (kms_flip:2340) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2340) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-HDMI-A2 failed. ** DEBUG (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 167.316193 last_received_ts = 167.316071 last_seq = 3075 current_ts = 167.332855 current_received_ts = 167.332382 current_seq = 3076 count = 22 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 167.332855 last_received_ts = 167.332382 last_seq = 3076 current_ts = 167.349518 current_received_ts = 167.349670 current_seq = 3077 count = 23 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 21us (kms_flip:2340) DEBUG: name = flip last_ts = 167.349518 last_received_ts = 167.349670 last_seq = 3077 current_ts = 167.366180 current_received_ts = 167.366486 current_seq = 3078 count = 24 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 21us (kms_flip:2340) DEBUG: name = flip last_ts = 167.366180 last_received_ts = 167.366486 last_seq = 3078 current_ts = 167.382858 current_received_ts = 167.382370 current_seq = 3079 count = 25 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 167.382858 last_received_ts = 167.382370 last_seq = 3079 current_ts = 167.399521 current_received_ts = 167.399338 current_seq = 3080 count = 26 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 167.399521 last_received_ts = 167.399338 last_seq = 3080 current_ts = 167.416183 current_received_ts = 167.415787 current_seq = 3081 count = 27 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 25us (kms_flip:2340) DEBUG: name = flip last_ts = 167.416183 last_received_ts = 167.415787 last_seq = 3081 current_ts = 167.432861 current_received_ts = 167.432571 current_seq = 3082 count = 28 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 20us (kms_flip:2340) DEBUG: name = flip last_ts = 167.432861 last_received_ts = 167.432571 last_seq = 3082 current_ts = 167.449509 current_received_ts = 167.449295 current_seq = 3083 count = 29 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 167.449509 last_received_ts = 167.449295 last_seq = 3083 current_ts = 167.466171 current_received_ts = 167.465988 current_seq = 3084 count = 30 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 167.466171 last_received_ts = 167.465988 last_seq = 3084 current_ts = 167.482834 current_received_ts = 167.482376 current_seq = 3085 count = 31 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 25us (kms_flip:2340) DEBUG: name = flip last_ts = 167.482834 last_received_ts = 167.482376 last_seq = 3085 current_ts = 167.499512 current_received_ts = 167.499374 current_seq = 3086 count = 32 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 20us (kms_flip:2340) DEBUG: name = flip last_ts = 167.499512 last_received_ts = 167.499374 last_seq = 3086 current_ts = 167.516174 current_received_ts = 167.515976 current_seq = 3087 count = 33 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 167.516174 last_received_ts = 167.515976 last_seq = 3087 current_ts = 167.532852 current_received_ts = 167.532349 current_seq = 3088 count = 34 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 167.532852 last_received_ts = 167.532349 last_seq = 3088 current_ts = 167.549515 current_received_ts = 167.549393 current_seq = 3089 count = 35 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 21us (kms_flip:2340) DEBUG: name = flip last_ts = 167.549515 last_received_ts = 167.549393 last_seq = 3089 current_ts = 167.566193 current_received_ts = 167.565964 current_seq = 3090 count = 36 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 167.566193 last_received_ts = 167.565964 last_seq = 3090 current_ts = 167.582855 current_received_ts = 167.582352 current_seq = 3091 count = 37 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 167.582855 last_received_ts = 167.582352 last_seq = 3091 current_ts = 167.599518 current_received_ts = 167.599625 current_seq = 3092 count = 38 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 167.599518 last_received_ts = 167.599625 last_seq = 3092 current_ts = 167.616180 current_received_ts = 167.615768 current_seq = 3093 count = 39 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 167.616180 last_received_ts = 167.615768 last_seq = 3093 current_ts = 167.632858 current_received_ts = 167.632874 current_seq = 3094 count = 40 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 21us (kms_flip:2340) DEBUG: name = flip last_ts = 167.632858 last_received_ts = 167.632874 last_seq = 3094 current_ts = 167.649521 current_received_ts = 167.649200 current_seq = 3095 count = 41 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 167.649521 last_received_ts = 167.649200 last_seq = 3095 current_ts = 167.666183 current_received_ts = 167.666183 current_seq = 3096 count = 42 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 167.666183 last_received_ts = 167.666183 last_seq = 3096 current_ts = 167.682846 current_received_ts = 167.682465 current_seq = 3097 count = 43 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 167.682846 last_received_ts = 167.682465 last_seq = 3097 current_ts = 167.699524 current_received_ts = 167.699341 current_seq = 3098 count = 44 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 167.699524 last_received_ts = 167.699341 last_seq = 3098 current_ts = 167.716171 current_received_ts = 167.715805 current_seq = 3099 count = 45 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 167.716171 last_received_ts = 167.715805 last_seq = 3099 current_ts = 167.732849 current_received_ts = 167.732849 current_seq = 3100 count = 46 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 167.732849 last_received_ts = 167.732849 last_seq = 3100 current_ts = 167.749512 current_received_ts = 167.749115 current_seq = 3101 count = 47 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 167.749512 last_received_ts = 167.749115 last_seq = 3101 current_ts = 167.766174 current_received_ts = 167.766571 current_seq = 3102 count = 48 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 167.766174 last_received_ts = 167.766571 last_seq = 3102 current_ts = 167.782837 current_received_ts = 167.782852 current_seq = 3103 count = 49 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 167.782837 last_received_ts = 167.782852 last_seq = 3103 current_ts = 167.799515 current_received_ts = 167.799332 current_seq = 3104 count = 50 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 167.799515 last_received_ts = 167.799332 last_seq = 3104 current_ts = 167.816177 current_received_ts = 167.816071 current_seq = 3105 count = 51 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 167.816177 last_received_ts = 167.816071 last_seq = 3105 current_ts = 167.832840 current_received_ts = 167.832352 current_seq = 3106 count = 52 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 167.832840 last_received_ts = 167.832352 last_seq = 3106 current_ts = 167.849518 current_received_ts = 167.849274 current_seq = 3107 count = 53 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 167.849518 last_received_ts = 167.849274 last_seq = 3107 current_ts = 167.866180 current_received_ts = 167.865768 current_seq = 3108 count = 54 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 167.866180 last_received_ts = 167.865768 last_seq = 3108 current_ts = 167.882858 current_received_ts = 167.882492 current_seq = 3109 count = 55 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 167.882858 last_received_ts = 167.882492 last_seq = 3109 current_ts = 167.899521 current_received_ts = 167.899628 current_seq = 3110 count = 56 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 21us (kms_flip:2340) DEBUG: name = flip last_ts = 167.899521 last_received_ts = 167.899628 last_seq = 3110 current_ts = 167.916183 current_received_ts = 167.915710 current_seq = 3111 count = 57 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 167.916183 last_received_ts = 167.915710 last_seq = 3111 current_ts = 167.932846 current_received_ts = 167.932541 current_seq = 3112 count = 58 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 167.932846 last_received_ts = 167.932541 last_seq = 3112 current_ts = 167.949509 current_received_ts = 167.949051 current_seq = 3113 count = 59 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 167.949509 last_received_ts = 167.949051 last_seq = 3113 current_ts = 167.966187 current_received_ts = 167.966614 current_seq = 3114 count = 60 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 167.966187 last_received_ts = 167.966614 last_seq = 3114 current_ts = 167.982849 current_received_ts = 167.982452 current_seq = 3115 count = 61 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 167.982849 last_received_ts = 167.982452 last_seq = 3115 current_ts = 167.999512 current_received_ts = 167.999313 current_seq = 3116 count = 62 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 167.999512 last_received_ts = 167.999313 last_seq = 3116 current_ts = 168.016174 current_received_ts = 168.015976 current_seq = 3117 count = 63 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 168.016174 last_received_ts = 168.015976 last_seq = 3117 current_ts = 168.032852 current_received_ts = 168.032394 current_seq = 3118 count = 64 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 168.032852 last_received_ts = 168.032394 last_seq = 3118 current_ts = 168.049515 current_received_ts = 168.049805 current_seq = 3119 count = 65 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 21us (kms_flip:2340) DEBUG: name = flip last_ts = 168.049515 last_received_ts = 168.049805 last_seq = 3119 current_ts = 168.066177 current_received_ts = 168.065765 current_seq = 3120 count = 66 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 168.066177 last_received_ts = 168.065765 last_seq = 3120 current_ts = 168.082840 current_received_ts = 168.082855 current_seq = 3121 count = 67 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 168.082840 last_received_ts = 168.082855 last_seq = 3121 current_ts = 168.099518 current_received_ts = 168.099197 current_seq = 3122 count = 68 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 168.099518 last_received_ts = 168.099197 last_seq = 3122 current_ts = 168.116180 current_received_ts = 168.116196 current_seq = 3123 count = 69 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 21us (kms_flip:2340) DEBUG: name = flip last_ts = 168.116180 last_received_ts = 168.116196 last_seq = 3123 current_ts = 168.132858 current_received_ts = 168.132477 current_seq = 3124 count = 70 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 168.132858 last_received_ts = 168.132477 last_seq = 3124 current_ts = 168.149521 current_received_ts = 168.149185 current_seq = 3125 count = 71 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 21us (kms_flip:2340) DEBUG: name = flip last_ts = 168.149521 last_received_ts = 168.149185 last_seq = 3125 current_ts = 168.166183 current_received_ts = 168.166595 current_seq = 3126 count = 72 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 168.166183 last_received_ts = 168.166595 last_seq = 3126 current_ts = 168.182846 current_received_ts = 168.182449 current_seq = 3127 count = 73 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 168.182846 last_received_ts = 168.182449 last_seq = 3127 current_ts = 168.199509 current_received_ts = 168.199722 current_seq = 3128 count = 74 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 26us (kms_flip:2340) DEBUG: name = flip last_ts = 168.199509 last_received_ts = 168.199722 last_seq = 3128 current_ts = 168.216187 current_received_ts = 168.215683 current_seq = 3129 count = 75 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 168.216187 last_received_ts = 168.215683 last_seq = 3129 current_ts = 168.232849 current_received_ts = 168.232452 current_seq = 3130 count = 76 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 168.232849 last_received_ts = 168.232452 last_seq = 3130 current_ts = 168.249512 current_received_ts = 168.249329 current_seq = 3131 count = 77 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 168.249512 last_received_ts = 168.249329 last_seq = 3131 current_ts = 168.266190 current_received_ts = 168.265747 current_seq = 3132 count = 78 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 168.266190 last_received_ts = 168.265747 last_seq = 3132 current_ts = 168.282852 current_received_ts = 168.282532 current_seq = 3133 count = 79 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 21us (kms_flip:2340) DEBUG: name = flip last_ts = 168.282852 last_received_ts = 168.282532 last_seq = 3133 current_ts = 168.299515 current_received_ts = 168.299561 current_seq = 3134 count = 80 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 21us (kms_flip:2340) DEBUG: name = flip last_ts = 168.299515 last_received_ts = 168.299561 last_seq = 3134 current_ts = 168.316193 current_received_ts = 168.315720 current_seq = 3135 count = 81 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 168.316193 last_received_ts = 168.315720 last_seq = 3135 current_ts = 168.332855 current_received_ts = 168.332458 current_seq = 3136 count = 82 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 168.332855 last_received_ts = 168.332458 last_seq = 3136 current_ts = 168.349518 current_received_ts = 168.349335 current_seq = 3137 count = 83 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 25us (kms_flip:2340) DEBUG: name = flip last_ts = 168.349518 last_received_ts = 168.349335 last_seq = 3137 current_ts = 168.366180 current_received_ts = 168.365692 current_seq = 3138 count = 84 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 168.366180 last_received_ts = 168.365692 last_seq = 3138 current_ts = 168.382843 current_received_ts = 168.383041 current_seq = 3139 count = 85 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 21us (kms_flip:2340) DEBUG: name = flip last_ts = 168.382843 last_received_ts = 168.383041 last_seq = 3139 current_ts = 168.399521 current_received_ts = 168.399338 current_seq = 3140 count = 86 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 168.399521 last_received_ts = 168.399338 last_seq = 3140 current_ts = 168.416183 current_received_ts = 168.416046 current_seq = 3141 count = 87 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 25us (kms_flip:2340) DEBUG: name = flip last_ts = 168.416183 last_received_ts = 168.416046 last_seq = 3141 current_ts = 168.432846 current_received_ts = 168.432358 current_seq = 3142 count = 88 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 168.432846 last_received_ts = 168.432358 last_seq = 3142 current_ts = 168.449524 current_received_ts = 168.449783 current_seq = 3143 count = 89 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 20us (kms_flip:2340) DEBUG: name = flip last_ts = 168.449524 last_received_ts = 168.449783 last_seq = 3143 current_ts = 168.466187 current_received_ts = 168.465714 current_seq = 3144 count = 90 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 168.466187 last_received_ts = 168.465714 last_seq = 3144 current_ts = 168.482849 current_received_ts = 168.482498 current_seq = 3145 count = 91 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 168.482849 last_received_ts = 168.482498 last_seq = 3145 current_ts = 168.499527 current_received_ts = 168.499039 current_seq = 3146 count = 92 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 168.499527 last_received_ts = 168.499039 last_seq = 3146 current_ts = 168.516174 current_received_ts = 168.516525 current_seq = 3147 count = 93 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 21us (kms_flip:2340) DEBUG: name = flip last_ts = 168.516174 last_received_ts = 168.516525 last_seq = 3147 current_ts = 168.532852 current_received_ts = 168.532516 current_seq = 3148 count = 94 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 168.532852 last_received_ts = 168.532516 last_seq = 3148 current_ts = 168.549515 current_received_ts = 168.549667 current_seq = 3149 count = 95 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 21us (kms_flip:2340) DEBUG: name = flip last_ts = 168.549515 last_received_ts = 168.549667 last_seq = 3149 current_ts = 168.566193 current_received_ts = 168.565720 current_seq = 3150 count = 96 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 168.566193 last_received_ts = 168.565720 last_seq = 3150 current_ts = 168.582855 current_received_ts = 168.582458 current_seq = 3151 count = 97 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 168.582855 last_received_ts = 168.582458 last_seq = 3151 current_ts = 168.599518 current_received_ts = 168.599319 current_seq = 3152 count = 98 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 168.599518 last_received_ts = 168.599319 last_seq = 3152 current_ts = 168.616180 current_received_ts = 168.615784 current_seq = 3153 count = 99 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 168.616180 last_received_ts = 168.615784 last_seq = 3153 current_ts = 168.632843 current_received_ts = 168.632935 current_seq = 3154 count = 100 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 55us (kms_flip:2340) DEBUG: name = flip last_ts = 168.632843 last_received_ts = 168.632935 last_seq = 3154 current_ts = 168.649506 current_received_ts = 168.649338 current_seq = 3155 count = 101 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 168.649506 last_received_ts = 168.649338 last_seq = 3155 current_ts = 168.666183 current_received_ts = 168.665756 current_seq = 3156 count = 102 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 168.666183 last_received_ts = 168.665756 last_seq = 3156 current_ts = 168.682846 current_received_ts = 168.682861 current_seq = 3157 count = 103 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 168.682846 last_received_ts = 168.682861 last_seq = 3157 current_ts = 168.699524 current_received_ts = 168.699097 current_seq = 3158 count = 104 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 168.699524 last_received_ts = 168.699097 last_seq = 3158 current_ts = 168.716171 current_received_ts = 168.716232 current_seq = 3159 count = 105 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 168.716171 last_received_ts = 168.716232 last_seq = 3159 current_ts = 168.732849 current_received_ts = 168.732483 current_seq = 3160 count = 106 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 168.732849 last_received_ts = 168.732483 last_seq = 3160 current_ts = 168.749512 current_received_ts = 168.749466 current_seq = 3161 count = 107 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 168.749512 last_received_ts = 168.749466 last_seq = 3161 current_ts = 168.766190 current_received_ts = 168.766235 current_seq = 3162 count = 108 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 168.766190 last_received_ts = 168.766235 last_seq = 3162 current_ts = 168.782852 current_received_ts = 168.782516 current_seq = 3163 count = 109 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 168.782852 last_received_ts = 168.782516 last_seq = 3163 current_ts = 168.799515 current_received_ts = 168.799377 current_seq = 3164 count = 110 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 168.799515 last_received_ts = 168.799377 last_seq = 3164 current_ts = 168.816177 current_received_ts = 168.816116 current_seq = 3165 count = 111 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 168.816177 last_received_ts = 168.816116 last_seq = 3165 current_ts = 168.832840 current_received_ts = 168.832382 current_seq = 3166 count = 112 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 168.832840 last_received_ts = 168.832382 last_seq = 3166 current_ts = 168.849518 current_received_ts = 168.849365 current_seq = 3167 count = 113 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 21us (kms_flip:2340) DEBUG: name = flip last_ts = 168.849518 last_received_ts = 168.849365 last_seq = 3167 current_ts = 168.866180 current_received_ts = 168.865768 current_seq = 3168 count = 114 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 168.866180 last_received_ts = 168.865768 last_seq = 3168 current_ts = 168.882843 current_received_ts = 168.882492 current_seq = 3169 count = 115 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 168.882843 last_received_ts = 168.882492 last_seq = 3169 current_ts = 168.899521 current_received_ts = 168.899200 current_seq = 3170 count = 116 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 168.899521 last_received_ts = 168.899200 last_seq = 3170 current_ts = 168.916183 current_received_ts = 168.916229 current_seq = 3171 count = 117 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 25us (kms_flip:2340) DEBUG: name = flip last_ts = 168.916183 last_received_ts = 168.916229 last_seq = 3171 current_ts = 168.932846 current_received_ts = 168.932495 current_seq = 3172 count = 118 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 168.932846 last_received_ts = 168.932495 last_seq = 3172 current_ts = 168.949524 current_received_ts = 168.948990 current_seq = 3173 count = 119 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 14us (kms_flip:2340) DEBUG: name = flip last_ts = 168.949524 last_received_ts = 168.948990 last_seq = 3173 current_ts = 168.966187 current_received_ts = 168.965820 current_seq = 3174 count = 120 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 13us (kms_flip:2340) DEBUG: name = flip last_ts = 168.966187 last_received_ts = 168.965820 last_seq = 3174 current_ts = 168.982834 current_received_ts = 168.983246 current_seq = 3175 count = 121 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 13us (kms_flip:2340) DEBUG: name = flip last_ts = 168.982834 last_received_ts = 168.983246 last_seq = 3175 current_ts = 168.999512 current_received_ts = 168.998932 current_seq = 3176 count = 122 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 14us (kms_flip:2340) DEBUG: name = flip last_ts = 168.999512 last_received_ts = 168.998932 last_seq = 3176 current_ts = 169.016174 current_received_ts = 169.015854 current_seq = 3177 count = 123 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 18us (kms_flip:2340) DEBUG: name = flip last_ts = 169.016174 last_received_ts = 169.015854 last_seq = 3177 current_ts = 169.032837 current_received_ts = 169.032501 current_seq = 3178 count = 124 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 169.032837 last_received_ts = 169.032501 last_seq = 3178 current_ts = 169.049500 current_received_ts = 169.049622 current_seq = 3179 count = 125 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 21us (kms_flip:2340) DEBUG: name = flip last_ts = 169.049500 last_received_ts = 169.049622 last_seq = 3179 current_ts = 169.066177 current_received_ts = 169.066071 current_seq = 3180 count = 126 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 169.066177 last_received_ts = 169.066071 last_seq = 3180 current_ts = 169.082840 current_received_ts = 169.082886 current_seq = 3181 count = 127 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 169.082840 last_received_ts = 169.082886 last_seq = 3181 current_ts = 169.099518 current_received_ts = 169.099396 current_seq = 3182 count = 128 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 24us (kms_flip:2340) DEBUG: name = flip last_ts = 169.099518 last_received_ts = 169.099396 last_seq = 3182 current_ts = 169.116180 current_received_ts = 169.115936 current_seq = 3183 count = 129 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 79us (kms_flip:2340) DEBUG: name = flip last_ts = 169.116180 last_received_ts = 169.115936 last_seq = 3183 current_ts = 169.132843 current_received_ts = 169.132355 current_seq = 3184 count = 130 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 169.132843 last_received_ts = 169.132355 last_seq = 3184 current_ts = 169.149521 current_received_ts = 169.149368 current_seq = 3185 count = 131 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 21us (kms_flip:2340) DEBUG: name = flip last_ts = 169.149521 last_received_ts = 169.149368 last_seq = 3185 current_ts = 169.166183 current_received_ts = 169.165985 current_seq = 3186 count = 132 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 169.166183 last_received_ts = 169.165985 last_seq = 3186 current_ts = 169.182846 current_received_ts = 169.182358 current_seq = 3187 count = 133 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 169.182846 last_received_ts = 169.182358 last_seq = 3187 current_ts = 169.199509 current_received_ts = 169.199341 current_seq = 3188 count = 134 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 25us (kms_flip:2340) DEBUG: name = flip last_ts = 169.199509 last_received_ts = 169.199341 last_seq = 3188 current_ts = 169.216187 current_received_ts = 169.215973 current_seq = 3189 count = 135 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 169.216187 last_received_ts = 169.215973 last_seq = 3189 current_ts = 169.232849 current_received_ts = 169.232376 current_seq = 3190 count = 136 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 22us (kms_flip:2340) DEBUG: name = flip last_ts = 169.232849 last_received_ts = 169.232376 last_seq = 3190 current_ts = 169.249512 current_received_ts = 169.249634 current_seq = 3191 count = 137 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 169.249512 last_received_ts = 169.249634 last_seq = 3191 current_ts = 169.266190 current_received_ts = 169.266571 current_seq = 3192 count = 138 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 21us (kms_flip:2340) DEBUG: name = flip last_ts = 169.266190 last_received_ts = 169.266571 last_seq = 3192 current_ts = 169.282837 current_received_ts = 169.282837 current_seq = 3193 count = 139 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 169.282837 last_received_ts = 169.282837 last_seq = 3193 current_ts = 169.299515 current_received_ts = 169.299683 current_seq = 3194 count = 140 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 169.299515 last_received_ts = 169.299683 last_seq = 3194 current_ts = 169.316177 current_received_ts = 169.315979 current_seq = 3195 count = 141 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 23us (kms_flip:2340) DEBUG: name = flip last_ts = 169.316177 last_received_ts = 169.315979 last_seq = 3195 current_ts = 169.332840 current_received_ts = 169.332382 current_seq = 3196 count = 142 seq_step = 1 (kms_flip:2340) DEBUG: Vblank took 983us (kms_flip:2340) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930: (kms_flip:2340) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2340) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:2340) igt_core-INFO: Stack trace: (kms_flip:2340) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2340) igt_core-INFO: #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0() (kms_flip:2340) igt_core-INFO: #2 ../tests/kms_flip.c:1891 run_test() (kms_flip:2340) igt_core-INFO: #3 ../tests/kms_flip.c:2162 __igt_unique____real_main2047() (kms_flip:2340) igt_core-INFO: #4 ../tests/kms_flip.c:2047 main() (kms_flip:2340) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2340) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2340) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-HDMI-A2: FAIL (2.974s)
Dmesg	<6> [166.616363] [IGT] kms_flip: starting dynamic subtest B-HDMI-A2 <7> [166.619155] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:179] <7> [166.619507] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:182] <7> [166.658755] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:78:pipe A] <7> [166.659073] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [166.659590] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [166.660003] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [166.660387] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [166.660773] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in lane_lat_optim_mask (expected 0x0000000d, found 0x00000000) <7> [166.661235] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [166.661619] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [166.662112] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [166.662492] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [166.662935] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [166.663343] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [166.663722] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [166.664176] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [166.664555] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [166.664964] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [166.665370] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1083, found 0) <7> [166.665749] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1088, found 0) <7> [166.666155] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [166.666546] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [166.666991] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [166.667371] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [166.667746] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [166.668213] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [166.668593] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [166.669172] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [166.669558] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [166.669974] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [166.670353] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1083, found 0) <7> [166.670801] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1088, found 0) <7> [166.671216] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [166.671598] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [166.672034] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [166.672436] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [166.672815] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [166.673241] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in has_hdmi_sink (expected yes, found no) <7> [166.673646] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in has_infoframe (expected yes, found no) <7> [166.674142] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in pipe_bpp (expected 36, found 0) <7> [166.674529] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [166.674925] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [166.675338] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in port_clock (expected 222750, found 0) <7> [166.675720] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000) <7> [166.676131] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in infoframes.gcp (expected 0x00000006, found 0x00000000) <7> [166.676521] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in avi infoframe <7> [166.676956] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [166.677336] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [166.677341] i915 0000:00:02.0: colorspace: RGB <7> [166.677345] i915 0000:00:02.0: scan mode: Underscan <7> [166.677348] i915 0000:00:02.0: colorimetry: No Data <7> [166.677351] i915 0000:00:02.0: picture aspect: No Data <7> [166.677355] i915 0000:00:02.0: active aspect: Same as Picture <7> [166.677359] i915 0000:00:02.0: itc: No Data <7> [166.677362] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [166.677366] i915 0000:00:02.0: quantization range: Full <7> [166.677369] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [166.677372] i915 0000:00:02.0: video code: 0 <7> [166.677375] i915 0000:00:02.0: ycc quantization range: Full <7> [166.677379] i915 0000:00:02.0: hdmi content type: Graphics <7> [166.677382] i915 0000:00:02.0: pixel repeat: 0 <7> [166.677385] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [166.677389] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [166.677766] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in spd infoframe <7> [166.678232] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [166.678612] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [166.678616] i915 0000:00:02.0: vendor: Intel <7> [166.678620] i915 0000:00:02.0: product: Integrated gfx <7> [166.678623] i915 0000:00:02.0: source device information: PC General (0x9) <7> [166.678627] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [166.679185] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hdmi infoframe <7> [166.679628] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [166.680031] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [166.680036] i915 0000:00:02.0: empty frame <7> [166.680039] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [166.680417] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:78:pipe A] fastset requirement not met, forcing full modeset <7> [166.680800] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:78:pipe A] releasing PORT PLL C <7> [166.681299] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:78:pipe A] dbuf slices 0x1 -> 0x0, ddb (0 - 1020) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [166.681744] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:72:cursor A] ddb ( 988 - 1020) -> ( 0 - 0), size 32 -> 0 <7> [166.682304] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:78:pipe A] min cdclk: 192000 kHz -> 0 kHz <7> [166.682753] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [166.683212] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 79200 kHz, actual 79200 kHz <7> [166.683588] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 4, actual 4 <7> [166.683995] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:78:pipe A] enable: no [modeset] <7> [166.684417] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:36:plane 1A] fb: [NOFB], visible: no <7> [166.684797] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:45:plane 2A] fb: [NOFB], visible: no <7> [166.685231] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:54:plane 3A] fb: [NOFB], visible: no <7> [166.685611] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:63:plane 4A] fb: [NOFB], visible: no <7> [166.686019] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:72:cursor A] fb: [NOFB], visible: no <7> [166.686552] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:176:HDMI-A-2][ENCODER:175:DDI C/PHY C] Disable audio codec on [CRTC:78:pipe A] <7> [166.711534] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port C <7> [166.713749] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [166.724396] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x10 <7> [166.728916] i915 0000:00:02.0: [drm:intel_ddi_disable_transcoder_func [i915]] Quirk Increase DDI disabled time <7> [166.830983] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_C <7> [166.832100] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PORT PLL C (active 0x1, on? 1) for [CRTC:78:pipe A] <7> [166.834623] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PORT PLL C <7> [166.835267] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 79200 kHz, VCO 633600 kHz, ref 19200 kHz, bypass 19200 kHz, voltage level 4 <7> [166.835702] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B] <7> [166.836465] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C] <7> [166.837172] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:176:HDMI-A-2] <7> [166.837806] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling dpio-common-c <7> [166.838467] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:78:pipe A] <7> [166.839901] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [166.840336] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 316800 kHz, actual 316800 kHz <7> [166.840714] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 13, actual 13 <7> [166.841221] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 316800 kHz, VCO 633600 kHz, ref 19200 kHz, bypass 19200 kHz, voltage level 13 <7> [166.842195] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B] <7> [166.843935] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:164:pipe C] <7> [166.844298] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B] <7> [166.844360] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:176:HDMI-A-2] <7> [166.844550] i915 0000:00:02.0: [drm:intel_hdmi_compute_clock [i915]] picking 12 bpc for HDMI output (pipe bpp: 36) <7> [166.845619] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:121:pipe B] hw max bpp: 36, pipe bpp: 36, dithering: 0 <7> [166.846270] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:175:DDI C/PHY C] [CRTC:121:pipe B] <7> [166.846653] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [166.847226] azx_init_pci: snd_hda_intel 0000:00:0e.0: Clearing TCSEL <7> [166.847243] azx_init_pci: snd_hda_intel 0000:00:0e.0: SCH snoop: Enabled <7> [166.847300] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [166.847683] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [166.848324] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [166.848707] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in lane_lat_optim_mask (expected 0x00000000, found 0x0000000d) <7> [166.850595] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [166.851322] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [166.851708] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [166.852474] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [166.853140] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [166.853525] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [166.854122] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [166.854530] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [166.855208] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [166.855592] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [166.857299] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083) <7> [166.857747] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088) <7> [166.858473] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [166.859107] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [166.859494] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [166.860060] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [166.860442] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [166.860820] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [166.862447] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [166.863324] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [166.863713] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [166.864386] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [166.864775] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083) <7> [166.865340] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088) <7> [166.865721] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [166.866301] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [166.866685] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [166.867899] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [166.868317] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [166.868696] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in has_hdmi_sink (expected no, found yes) <7> [166.869746] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in has_infoframe (expected no, found yes) <7> [166.870473] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 36) <7> [166.871131] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [166.871514] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [166.872077] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in port_clock (expected 0, found 222750) <7> [166.872461] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071) <7> [166.873062] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in infoframes.gcp (expected 0x00000000, found 0x00000006) <7> [166.873450] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in avi infoframe <7> [166.873829] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [166.875491] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [166.876343] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [166.876349] i915 0000:00:02.0: colorspace: RGB <7> [166.876353] i915 0000:00:02.0: scan mode: Underscan <7> [166.876356] i915 0000:00:02.0: colorimetry: No Data <7> [166.876360] i915 0000:00:02.0: picture aspect: No Data <7> [166.876363] i915 0000:00:02.0: active aspect: Same as Picture <7> [166.876366] i915 0000:00:02.0: itc: No Data <7> [166.876369] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [166.876373] i915 0000:00:02.0: quantization range: Full <7> [166.876376] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [166.876379] i915 0000:00:02.0: video code: 0 <7> [166.876382] i915 0000:00:02.0: ycc quantization range: Full <7> [166.876386] i915 0000:00:02.0: hdmi content type: Graphics <7> [166.876389] i915 0000:00:02.0: pixel repeat: 0 <7> [166.876392] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [166.876397] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in spd infoframe <7> [166.876796] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [166.877555] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [166.878127] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [166.878132] i915 0000:00:02.0: vendor: Intel <7> [166.878136] i915 0000:00:02.0: product: Integrated gfx <7> [166.878140] i915 0000:00:02.0: source device information: PC General (0x9) <7> [166.878144] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hdmi infoframe <7> [166.878524] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [166.879129] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [166.879511] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [166.879515] i915 0000:00:02.0: empty frame <7> [166.879520] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:121:pipe B] fastset requirement not met, forcing full modeset <7> [166.880975] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:121:pipe B] dbuf slices 0x0 -> 0x1, ddb (0 - 0) -> (0 - 1020), active pipes 0x0 -> 0x2 <7> [166.881459] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:79:plane 1B] ddb ( 0 - 0) -> ( 0 - 988), size 0 -> 988 <7> [166.883108] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:115:cursor B] ddb ( 0 - 0) -> ( 988 - 1020), size 0 -> 32 <7> [166.883510] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5,wm6,wm7,*twm, swm, stwm <7> [166.884311] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 1, 1, 2, 2, 2, 2, 2, 0, 0, 0 <7> [166.884700] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 16, 16, 33, 33, 33, 33, 33, 30, 0, 0 <7> [166.885383] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 17, 17, 17, 34, 34, 34, 34, 34, 31, 0, 0 <7> [166.885763] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] min_ddb_uv 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [166.886398] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:121:pipe B] min cdclk: 0 kHz -> 192000 kHz <7> [166.886826] i915 0000:00:02.0: [drm:bxt_get_dpll [i915]] [CRTC:121:pipe B] using pre-allocated PORT PLL C <7> [166.887397] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:121:pipe B] reserving PORT PLL C <7> [166.887793] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:121:pipe B] enable: yes [modeset] <7> [166.888936] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [166.889350] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 36, dithering: 0 <7> [166.889726] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [166.891069] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [166.891466] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [166.892202] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [166.892586] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71 <7> [166.893222] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x6 <7> [166.893608] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [166.893612] i915 0000:00:02.0: colorspace: RGB <7> [166.893616] i915 0000:00:02.0: scan mode: Underscan <7> [166.893619] i915 0000:00:02.0: colorimetry: No Data <7> [166.893623] i915 0000:00:02.0: picture aspect: No Data <7> [166.893627] i915 0000:00:02.0: active aspect: Same as Picture <7> [166.893630] i915 0000:00:02.0: itc: No Data <7> [166.893633] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [166.893637] i915 0000:00:02.0: quantization range: Full <7> [166.893640] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [166.893643] i915 0000:00:02.0: video code: 0 <7> [166.893647] i915 0000:00:02.0: ycc quantization range: Full <7> [166.893650] i915 0000:00:02.0: hdmi content type: Graphics <7> [166.893653] i915 0000:00:02.0: pixel repeat: 0 <7> [166.893656] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [166.893660] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [166.893664] i915 0000:00:02.0: vendor: Intel <7> [166.893667] i915 0000:00:02.0: product: Integrated gfx <7> [166.893670] i915 0000:00:02.0: source device information: PC General (0x9) <7> [166.893674] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [166.893678] i915 0000:00:02.0: empty frame <7> [166.893681] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 10 00 07 00 66 10 00 01 00 00 00 00 00 00 00 00 <7> [166.894343] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 05 e3 cd 0c 32 38 45 38 35 30 09 07 07 00 00 00 <7> [166.894726] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [166.895344] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [166.895725] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0 <7> [166.897730] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0 <7> [166.898381] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [166.898765] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 <7> [166.899521] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 <7> [166.900199] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1083-1088 vt=1125, flags=0x9 <7> [166.900588] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x40 0x9 <7> [166.901156] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1083-1088 vt=1125, flags=0x9 <7> [166.901538] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 222750, pixel rate 148500, min cdclk 192000, min voltage level 0 <7> [166.902117] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0 <7> [166.902497] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0 <7> [166.904070] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0 <7> [166.904527] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [166.905338] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [166.905725] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [166.906387] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: ebb0: 0x6200, ebb4: 0x2000,pll0: 0x21, pll1: 0x100, pll2: 0x1a6666, pll3: 0x10000, pll6: 0x30904, pll8: 0x8, pll9: 0xa, pll10: 0x8003c00, pcsdw12: 0x4d <7> [166.906771] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [166.907374] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [166.907754] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [166.908313] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [166.908692] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [166.910261] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [166.910686] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [166.911463] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:79:plane 1B] fb: [FB:179] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [166.912147] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [166.912530] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [166.913127] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:88:plane 2B] fb: [NOFB], visible: no <7> [166.913514] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:97:plane 3B] fb: [NOFB], visible: no <7> [166.914076] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:106:plane 4B] fb: [NOFB], visible: no <7> [166.914461] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:115:cursor B] fb: [NOFB], visible: no <7> [166.916737] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling dpio-common-c <7> [166.918021] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B] <7> [166.918430] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C] <7> [166.919191] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PORT PLL C (active 0x2, on? 0) for [CRTC:121:pipe B] <7> [166.919584] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PORT PLL C <7> [166.920294] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_C <7> [166.920784] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B <7> [166.939454] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:176:HDMI-A-2][ENCODER:175:DDI C/PHY C] Enable audio codec on [CRTC:121:pipe B], 32 bytes ELD <7> [166.956069] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 148500 (0x00090000) <7> [166.956550] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N <7> [166.958052] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:176:HDMI-A-2] <7> [166.958684] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:121:pipe B] <6> [169.595477] [IGT] kms_flip: finished subtest B-HDMI-A2, FAIL

Detail

Value

Duration

2.97 seconds

Hostname

shard-glk9

Igt-Version

IGT-Version: 2.4-g71dd1e2fa (x86_64) (Linux: 7.0.0-rc6-CI_DRM_18266-g35370a958ae2+ x86_64)

Out

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

Err

Starting dynamic subtest: B-HDMI-A2
(kms_flip:2340) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930:
(kms_flip:2340) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2340) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-HDMI-A2 failed.
**** DEBUG ****
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.316193
last_received_ts = 167.316071
last_seq = 3075
current_ts = 167.332855
current_received_ts = 167.332382
current_seq = 3076
count = 22
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.332855
last_received_ts = 167.332382
last_seq = 3076
current_ts = 167.349518
current_received_ts = 167.349670
current_seq = 3077
count = 23
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 21us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.349518
last_received_ts = 167.349670
last_seq = 3077
current_ts = 167.366180
current_received_ts = 167.366486
current_seq = 3078
count = 24
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 21us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.366180
last_received_ts = 167.366486
last_seq = 3078
current_ts = 167.382858
current_received_ts = 167.382370
current_seq = 3079
count = 25
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.382858
last_received_ts = 167.382370
last_seq = 3079
current_ts = 167.399521
current_received_ts = 167.399338
current_seq = 3080
count = 26
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.399521
last_received_ts = 167.399338
last_seq = 3080
current_ts = 167.416183
current_received_ts = 167.415787
current_seq = 3081
count = 27
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 25us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.416183
last_received_ts = 167.415787
last_seq = 3081
current_ts = 167.432861
current_received_ts = 167.432571
current_seq = 3082
count = 28
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 20us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.432861
last_received_ts = 167.432571
last_seq = 3082
current_ts = 167.449509
current_received_ts = 167.449295
current_seq = 3083
count = 29
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.449509
last_received_ts = 167.449295
last_seq = 3083
current_ts = 167.466171
current_received_ts = 167.465988
current_seq = 3084
count = 30
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.466171
last_received_ts = 167.465988
last_seq = 3084
current_ts = 167.482834
current_received_ts = 167.482376
current_seq = 3085
count = 31
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 25us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.482834
last_received_ts = 167.482376
last_seq = 3085
current_ts = 167.499512
current_received_ts = 167.499374
current_seq = 3086
count = 32
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 20us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.499512
last_received_ts = 167.499374
last_seq = 3086
current_ts = 167.516174
current_received_ts = 167.515976
current_seq = 3087
count = 33
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.516174
last_received_ts = 167.515976
last_seq = 3087
current_ts = 167.532852
current_received_ts = 167.532349
current_seq = 3088
count = 34
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.532852
last_received_ts = 167.532349
last_seq = 3088
current_ts = 167.549515
current_received_ts = 167.549393
current_seq = 3089
count = 35
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 21us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.549515
last_received_ts = 167.549393
last_seq = 3089
current_ts = 167.566193
current_received_ts = 167.565964
current_seq = 3090
count = 36
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.566193
last_received_ts = 167.565964
last_seq = 3090
current_ts = 167.582855
current_received_ts = 167.582352
current_seq = 3091
count = 37
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.582855
last_received_ts = 167.582352
last_seq = 3091
current_ts = 167.599518
current_received_ts = 167.599625
current_seq = 3092
count = 38
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.599518
last_received_ts = 167.599625
last_seq = 3092
current_ts = 167.616180
current_received_ts = 167.615768
current_seq = 3093
count = 39
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.616180
last_received_ts = 167.615768
last_seq = 3093
current_ts = 167.632858
current_received_ts = 167.632874
current_seq = 3094
count = 40
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 21us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.632858
last_received_ts = 167.632874
last_seq = 3094
current_ts = 167.649521
current_received_ts = 167.649200
current_seq = 3095
count = 41
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.649521
last_received_ts = 167.649200
last_seq = 3095
current_ts = 167.666183
current_received_ts = 167.666183
current_seq = 3096
count = 42
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.666183
last_received_ts = 167.666183
last_seq = 3096
current_ts = 167.682846
current_received_ts = 167.682465
current_seq = 3097
count = 43
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.682846
last_received_ts = 167.682465
last_seq = 3097
current_ts = 167.699524
current_received_ts = 167.699341
current_seq = 3098
count = 44
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.699524
last_received_ts = 167.699341
last_seq = 3098
current_ts = 167.716171
current_received_ts = 167.715805
current_seq = 3099
count = 45
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.716171
last_received_ts = 167.715805
last_seq = 3099
current_ts = 167.732849
current_received_ts = 167.732849
current_seq = 3100
count = 46
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.732849
last_received_ts = 167.732849
last_seq = 3100
current_ts = 167.749512
current_received_ts = 167.749115
current_seq = 3101
count = 47
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.749512
last_received_ts = 167.749115
last_seq = 3101
current_ts = 167.766174
current_received_ts = 167.766571
current_seq = 3102
count = 48
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.766174
last_received_ts = 167.766571
last_seq = 3102
current_ts = 167.782837
current_received_ts = 167.782852
current_seq = 3103
count = 49
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.782837
last_received_ts = 167.782852
last_seq = 3103
current_ts = 167.799515
current_received_ts = 167.799332
current_seq = 3104
count = 50
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.799515
last_received_ts = 167.799332
last_seq = 3104
current_ts = 167.816177
current_received_ts = 167.816071
current_seq = 3105
count = 51
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.816177
last_received_ts = 167.816071
last_seq = 3105
current_ts = 167.832840
current_received_ts = 167.832352
current_seq = 3106
count = 52
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.832840
last_received_ts = 167.832352
last_seq = 3106
current_ts = 167.849518
current_received_ts = 167.849274
current_seq = 3107
count = 53
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.849518
last_received_ts = 167.849274
last_seq = 3107
current_ts = 167.866180
current_received_ts = 167.865768
current_seq = 3108
count = 54
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.866180
last_received_ts = 167.865768
last_seq = 3108
current_ts = 167.882858
current_received_ts = 167.882492
current_seq = 3109
count = 55
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.882858
last_received_ts = 167.882492
last_seq = 3109
current_ts = 167.899521
current_received_ts = 167.899628
current_seq = 3110
count = 56
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 21us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.899521
last_received_ts = 167.899628
last_seq = 3110
current_ts = 167.916183
current_received_ts = 167.915710
current_seq = 3111
count = 57
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.916183
last_received_ts = 167.915710
last_seq = 3111
current_ts = 167.932846
current_received_ts = 167.932541
current_seq = 3112
count = 58
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.932846
last_received_ts = 167.932541
last_seq = 3112
current_ts = 167.949509
current_received_ts = 167.949051
current_seq = 3113
count = 59
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.949509
last_received_ts = 167.949051
last_seq = 3113
current_ts = 167.966187
current_received_ts = 167.966614
current_seq = 3114
count = 60
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.966187
last_received_ts = 167.966614
last_seq = 3114
current_ts = 167.982849
current_received_ts = 167.982452
current_seq = 3115
count = 61
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.982849
last_received_ts = 167.982452
last_seq = 3115
current_ts = 167.999512
current_received_ts = 167.999313
current_seq = 3116
count = 62
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 167.999512
last_received_ts = 167.999313
last_seq = 3116
current_ts = 168.016174
current_received_ts = 168.015976
current_seq = 3117
count = 63
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.016174
last_received_ts = 168.015976
last_seq = 3117
current_ts = 168.032852
current_received_ts = 168.032394
current_seq = 3118
count = 64
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.032852
last_received_ts = 168.032394
last_seq = 3118
current_ts = 168.049515
current_received_ts = 168.049805
current_seq = 3119
count = 65
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 21us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.049515
last_received_ts = 168.049805
last_seq = 3119
current_ts = 168.066177
current_received_ts = 168.065765
current_seq = 3120
count = 66
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.066177
last_received_ts = 168.065765
last_seq = 3120
current_ts = 168.082840
current_received_ts = 168.082855
current_seq = 3121
count = 67
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.082840
last_received_ts = 168.082855
last_seq = 3121
current_ts = 168.099518
current_received_ts = 168.099197
current_seq = 3122
count = 68
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.099518
last_received_ts = 168.099197
last_seq = 3122
current_ts = 168.116180
current_received_ts = 168.116196
current_seq = 3123
count = 69
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 21us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.116180
last_received_ts = 168.116196
last_seq = 3123
current_ts = 168.132858
current_received_ts = 168.132477
current_seq = 3124
count = 70
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.132858
last_received_ts = 168.132477
last_seq = 3124
current_ts = 168.149521
current_received_ts = 168.149185
current_seq = 3125
count = 71
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 21us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.149521
last_received_ts = 168.149185
last_seq = 3125
current_ts = 168.166183
current_received_ts = 168.166595
current_seq = 3126
count = 72
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.166183
last_received_ts = 168.166595
last_seq = 3126
current_ts = 168.182846
current_received_ts = 168.182449
current_seq = 3127
count = 73
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.182846
last_received_ts = 168.182449
last_seq = 3127
current_ts = 168.199509
current_received_ts = 168.199722
current_seq = 3128
count = 74
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 26us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.199509
last_received_ts = 168.199722
last_seq = 3128
current_ts = 168.216187
current_received_ts = 168.215683
current_seq = 3129
count = 75
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.216187
last_received_ts = 168.215683
last_seq = 3129
current_ts = 168.232849
current_received_ts = 168.232452
current_seq = 3130
count = 76
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.232849
last_received_ts = 168.232452
last_seq = 3130
current_ts = 168.249512
current_received_ts = 168.249329
current_seq = 3131
count = 77
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.249512
last_received_ts = 168.249329
last_seq = 3131
current_ts = 168.266190
current_received_ts = 168.265747
current_seq = 3132
count = 78
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.266190
last_received_ts = 168.265747
last_seq = 3132
current_ts = 168.282852
current_received_ts = 168.282532
current_seq = 3133
count = 79
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 21us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.282852
last_received_ts = 168.282532
last_seq = 3133
current_ts = 168.299515
current_received_ts = 168.299561
current_seq = 3134
count = 80
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 21us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.299515
last_received_ts = 168.299561
last_seq = 3134
current_ts = 168.316193
current_received_ts = 168.315720
current_seq = 3135
count = 81
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.316193
last_received_ts = 168.315720
last_seq = 3135
current_ts = 168.332855
current_received_ts = 168.332458
current_seq = 3136
count = 82
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.332855
last_received_ts = 168.332458
last_seq = 3136
current_ts = 168.349518
current_received_ts = 168.349335
current_seq = 3137
count = 83
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 25us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.349518
last_received_ts = 168.349335
last_seq = 3137
current_ts = 168.366180
current_received_ts = 168.365692
current_seq = 3138
count = 84
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.366180
last_received_ts = 168.365692
last_seq = 3138
current_ts = 168.382843
current_received_ts = 168.383041
current_seq = 3139
count = 85
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 21us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.382843
last_received_ts = 168.383041
last_seq = 3139
current_ts = 168.399521
current_received_ts = 168.399338
current_seq = 3140
count = 86
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.399521
last_received_ts = 168.399338
last_seq = 3140
current_ts = 168.416183
current_received_ts = 168.416046
current_seq = 3141
count = 87
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 25us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.416183
last_received_ts = 168.416046
last_seq = 3141
current_ts = 168.432846
current_received_ts = 168.432358
current_seq = 3142
count = 88
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.432846
last_received_ts = 168.432358
last_seq = 3142
current_ts = 168.449524
current_received_ts = 168.449783
current_seq = 3143
count = 89
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 20us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.449524
last_received_ts = 168.449783
last_seq = 3143
current_ts = 168.466187
current_received_ts = 168.465714
current_seq = 3144
count = 90
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.466187
last_received_ts = 168.465714
last_seq = 3144
current_ts = 168.482849
current_received_ts = 168.482498
current_seq = 3145
count = 91
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.482849
last_received_ts = 168.482498
last_seq = 3145
current_ts = 168.499527
current_received_ts = 168.499039
current_seq = 3146
count = 92
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.499527
last_received_ts = 168.499039
last_seq = 3146
current_ts = 168.516174
current_received_ts = 168.516525
current_seq = 3147
count = 93
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 21us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.516174
last_received_ts = 168.516525
last_seq = 3147
current_ts = 168.532852
current_received_ts = 168.532516
current_seq = 3148
count = 94
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.532852
last_received_ts = 168.532516
last_seq = 3148
current_ts = 168.549515
current_received_ts = 168.549667
current_seq = 3149
count = 95
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 21us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.549515
last_received_ts = 168.549667
last_seq = 3149
current_ts = 168.566193
current_received_ts = 168.565720
current_seq = 3150
count = 96
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.566193
last_received_ts = 168.565720
last_seq = 3150
current_ts = 168.582855
current_received_ts = 168.582458
current_seq = 3151
count = 97
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.582855
last_received_ts = 168.582458
last_seq = 3151
current_ts = 168.599518
current_received_ts = 168.599319
current_seq = 3152
count = 98
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.599518
last_received_ts = 168.599319
last_seq = 3152
current_ts = 168.616180
current_received_ts = 168.615784
current_seq = 3153
count = 99
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.616180
last_received_ts = 168.615784
last_seq = 3153
current_ts = 168.632843
current_received_ts = 168.632935
current_seq = 3154
count = 100
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 55us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.632843
last_received_ts = 168.632935
last_seq = 3154
current_ts = 168.649506
current_received_ts = 168.649338
current_seq = 3155
count = 101
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.649506
last_received_ts = 168.649338
last_seq = 3155
current_ts = 168.666183
current_received_ts = 168.665756
current_seq = 3156
count = 102
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.666183
last_received_ts = 168.665756
last_seq = 3156
current_ts = 168.682846
current_received_ts = 168.682861
current_seq = 3157
count = 103
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.682846
last_received_ts = 168.682861
last_seq = 3157
current_ts = 168.699524
current_received_ts = 168.699097
current_seq = 3158
count = 104
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.699524
last_received_ts = 168.699097
last_seq = 3158
current_ts = 168.716171
current_received_ts = 168.716232
current_seq = 3159
count = 105
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.716171
last_received_ts = 168.716232
last_seq = 3159
current_ts = 168.732849
current_received_ts = 168.732483
current_seq = 3160
count = 106
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.732849
last_received_ts = 168.732483
last_seq = 3160
current_ts = 168.749512
current_received_ts = 168.749466
current_seq = 3161
count = 107
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.749512
last_received_ts = 168.749466
last_seq = 3161
current_ts = 168.766190
current_received_ts = 168.766235
current_seq = 3162
count = 108
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.766190
last_received_ts = 168.766235
last_seq = 3162
current_ts = 168.782852
current_received_ts = 168.782516
current_seq = 3163
count = 109
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.782852
last_received_ts = 168.782516
last_seq = 3163
current_ts = 168.799515
current_received_ts = 168.799377
current_seq = 3164
count = 110
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.799515
last_received_ts = 168.799377
last_seq = 3164
current_ts = 168.816177
current_received_ts = 168.816116
current_seq = 3165
count = 111
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.816177
last_received_ts = 168.816116
last_seq = 3165
current_ts = 168.832840
current_received_ts = 168.832382
current_seq = 3166
count = 112
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.832840
last_received_ts = 168.832382
last_seq = 3166
current_ts = 168.849518
current_received_ts = 168.849365
current_seq = 3167
count = 113
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 21us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.849518
last_received_ts = 168.849365
last_seq = 3167
current_ts = 168.866180
current_received_ts = 168.865768
current_seq = 3168
count = 114
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.866180
last_received_ts = 168.865768
last_seq = 3168
current_ts = 168.882843
current_received_ts = 168.882492
current_seq = 3169
count = 115
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.882843
last_received_ts = 168.882492
last_seq = 3169
current_ts = 168.899521
current_received_ts = 168.899200
current_seq = 3170
count = 116
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.899521
last_received_ts = 168.899200
last_seq = 3170
current_ts = 168.916183
current_received_ts = 168.916229
current_seq = 3171
count = 117
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 25us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.916183
last_received_ts = 168.916229
last_seq = 3171
current_ts = 168.932846
current_received_ts = 168.932495
current_seq = 3172
count = 118
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.932846
last_received_ts = 168.932495
last_seq = 3172
current_ts = 168.949524
current_received_ts = 168.948990
current_seq = 3173
count = 119
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 14us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.949524
last_received_ts = 168.948990
last_seq = 3173
current_ts = 168.966187
current_received_ts = 168.965820
current_seq = 3174
count = 120
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 13us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.966187
last_received_ts = 168.965820
last_seq = 3174
current_ts = 168.982834
current_received_ts = 168.983246
current_seq = 3175
count = 121
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 13us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.982834
last_received_ts = 168.983246
last_seq = 3175
current_ts = 168.999512
current_received_ts = 168.998932
current_seq = 3176
count = 122
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 14us
(kms_flip:2340) DEBUG: name = flip
last_ts = 168.999512
last_received_ts = 168.998932
last_seq = 3176
current_ts = 169.016174
current_received_ts = 169.015854
current_seq = 3177
count = 123
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 18us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.016174
last_received_ts = 169.015854
last_seq = 3177
current_ts = 169.032837
current_received_ts = 169.032501
current_seq = 3178
count = 124
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.032837
last_received_ts = 169.032501
last_seq = 3178
current_ts = 169.049500
current_received_ts = 169.049622
current_seq = 3179
count = 125
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 21us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.049500
last_received_ts = 169.049622
last_seq = 3179
current_ts = 169.066177
current_received_ts = 169.066071
current_seq = 3180
count = 126
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.066177
last_received_ts = 169.066071
last_seq = 3180
current_ts = 169.082840
current_received_ts = 169.082886
current_seq = 3181
count = 127
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.082840
last_received_ts = 169.082886
last_seq = 3181
current_ts = 169.099518
current_received_ts = 169.099396
current_seq = 3182
count = 128
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 24us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.099518
last_received_ts = 169.099396
last_seq = 3182
current_ts = 169.116180
current_received_ts = 169.115936
current_seq = 3183
count = 129
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 79us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.116180
last_received_ts = 169.115936
last_seq = 3183
current_ts = 169.132843
current_received_ts = 169.132355
current_seq = 3184
count = 130
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.132843
last_received_ts = 169.132355
last_seq = 3184
current_ts = 169.149521
current_received_ts = 169.149368
current_seq = 3185
count = 131
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 21us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.149521
last_received_ts = 169.149368
last_seq = 3185
current_ts = 169.166183
current_received_ts = 169.165985
current_seq = 3186
count = 132
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.166183
last_received_ts = 169.165985
last_seq = 3186
current_ts = 169.182846
current_received_ts = 169.182358
current_seq = 3187
count = 133
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.182846
last_received_ts = 169.182358
last_seq = 3187
current_ts = 169.199509
current_received_ts = 169.199341
current_seq = 3188
count = 134
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 25us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.199509
last_received_ts = 169.199341
last_seq = 3188
current_ts = 169.216187
current_received_ts = 169.215973
current_seq = 3189
count = 135
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.216187
last_received_ts = 169.215973
last_seq = 3189
current_ts = 169.232849
current_received_ts = 169.232376
current_seq = 3190
count = 136
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 22us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.232849
last_received_ts = 169.232376
last_seq = 3190
current_ts = 169.249512
current_received_ts = 169.249634
current_seq = 3191
count = 137
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.249512
last_received_ts = 169.249634
last_seq = 3191
current_ts = 169.266190
current_received_ts = 169.266571
current_seq = 3192
count = 138
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 21us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.266190
last_received_ts = 169.266571
last_seq = 3192
current_ts = 169.282837
current_received_ts = 169.282837
current_seq = 3193
count = 139
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.282837
last_received_ts = 169.282837
last_seq = 3193
current_ts = 169.299515
current_received_ts = 169.299683
current_seq = 3194
count = 140
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.299515
last_received_ts = 169.299683
last_seq = 3194
current_ts = 169.316177
current_received_ts = 169.315979
current_seq = 3195
count = 141
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 23us
(kms_flip:2340) DEBUG: name = flip
last_ts = 169.316177
last_received_ts = 169.315979
last_seq = 3195
current_ts = 169.332840
current_received_ts = 169.332382
current_seq = 3196
count = 142
seq_step = 1
(kms_flip:2340) DEBUG: Vblank took 983us
(kms_flip:2340) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:930:
(kms_flip:2340) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2340) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2340) igt_core-INFO: Stack trace:
(kms_flip:2340) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2340) igt_core-INFO:   #1 ../tests/kms_flip.c:925 run_test_on_crtc_set.constprop.0()
(kms_flip:2340) igt_core-INFO:   #2 ../tests/kms_flip.c:1891 run_test()
(kms_flip:2340) igt_core-INFO:   #3 ../tests/kms_flip.c:2162 __igt_unique____real_main2047()
(kms_flip:2340) igt_core-INFO:   #4 ../tests/kms_flip.c:2047 main()
(kms_flip:2340) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2340) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2340) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A2: FAIL (2.974s)

Dmesg

<6> [166.616363] [IGT] kms_flip: starting dynamic subtest B-HDMI-A2

<7> [166.619155] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:179]

<7> [166.619507] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:182]

<7> [166.658755] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:78:pipe A]

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

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

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

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

<7> [166.660773] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in lane_lat_optim_mask (expected 0x0000000d, found 0x00000000)

<7> [166.661235] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000)

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

<7> [166.662112] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0)

<7> [166.662492] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0)

<7> [166.662935] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0)

<7> [166.663343] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0)

<7> [166.663722] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0)

<7> [166.664176] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0)

<7> [166.664555] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0)

<7> [166.664964] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0)

<7> [166.665370] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1083, found 0)

<7> [166.665749] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1088, found 0)

<7> [166.666155] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0)

<7> [166.666546] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0)

<7> [166.666991] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0)

<7> [166.667371] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0)

<7> [166.667746] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0)

<7> [166.668213] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0)

<7> [166.668593] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0)

<7> [166.669172] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0)

<7> [166.669558] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0)

<7> [166.669974] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0)

<7> [166.670353] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1083, found 0)

<7> [166.670801] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1088, found 0)

<7> [166.671216] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0)

<7> [166.671598] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0)

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

<7> [166.672436] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0)

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

<7> [166.673241] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in has_hdmi_sink (expected yes, found no)

<7> [166.673646] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in has_infoframe (expected yes, found no)

<7> [166.674142] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in pipe_bpp (expected 36, found 0)

<7> [166.674529] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0)

<7> [166.674925] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0)

<7> [166.675338] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in port_clock (expected 222750, found 0)

<7> [166.675720] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000)

<7> [166.676131] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in infoframes.gcp (expected 0x00000006, found 0x00000000)

<7> [166.676521] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in avi infoframe

<7> [166.676956] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [166.677336] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13

<7> [166.677341] i915 0000:00:02.0: colorspace: RGB

<7> [166.677345] i915 0000:00:02.0: scan mode: Underscan

<7> [166.677348] i915 0000:00:02.0: colorimetry: No Data

<7> [166.677351] i915 0000:00:02.0: picture aspect: No Data

<7> [166.677355] i915 0000:00:02.0: active aspect: Same as Picture

<7> [166.677359] i915 0000:00:02.0: itc: No Data

<7> [166.677362] i915 0000:00:02.0: extended colorimetry: xvYCC 601

<7> [166.677366] i915 0000:00:02.0: quantization range: Full

<7> [166.677369] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling

<7> [166.677372] i915 0000:00:02.0: video code: 0

<7> [166.677375] i915 0000:00:02.0: ycc quantization range: Full

<7> [166.677379] i915 0000:00:02.0: hdmi content type: Graphics

<7> [166.677382] i915 0000:00:02.0: pixel repeat: 0

<7> [166.677385] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0

<7> [166.677389] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [166.677766] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in spd infoframe

<7> [166.678232] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [166.678612] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25

<7> [166.678616] i915 0000:00:02.0: vendor: Intel

<7> [166.678620] i915 0000:00:02.0: product: Integrated gfx

<7> [166.678623] i915 0000:00:02.0: source device information: PC General (0x9)

<7> [166.678627] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [166.679185] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hdmi infoframe

<7> [166.679628] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [166.680031] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4

<7> [166.680036] i915 0000:00:02.0: empty frame

<7> [166.680039] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [166.680417] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:78:pipe A] fastset requirement not met, forcing full modeset

<7> [166.680800] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:78:pipe A] releasing PORT PLL C

<7> [166.681299] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:78:pipe A] dbuf slices 0x1 -> 0x0, ddb (0 - 1020) -> (0 - 0), active pipes 0x1 -> 0x0

<7> [166.681744] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:72:cursor A] ddb ( 988 - 1020) -> ( 0 - 0), size 32 -> 0

<7> [166.682304] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:78:pipe A] min cdclk: 192000 kHz -> 0 kHz

<7> [166.682753] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change

<7> [166.683212] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 79200 kHz, actual 79200 kHz

<7> [166.683588] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 4, actual 4

<7> [166.683995] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:78:pipe A] enable: no [modeset]

<7> [166.684417] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:36:plane 1A] fb: [NOFB], visible: no

<7> [166.684797] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:45:plane 2A] fb: [NOFB], visible: no

<7> [166.685231] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:54:plane 3A] fb: [NOFB], visible: no

<7> [166.685611] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:63:plane 4A] fb: [NOFB], visible: no

<7> [166.686019] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:72:cursor A] fb: [NOFB], visible: no

<7> [166.686552] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:176:HDMI-A-2][ENCODER:175:DDI C/PHY C] Disable audio codec on [CRTC:78:pipe A]

<7> [166.711534] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port C

<7> [166.713749] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A

<7> [166.724396] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x10

<7> [166.728916] i915 0000:00:02.0: [drm:intel_ddi_disable_transcoder_func [i915]] Quirk Increase DDI disabled time

<7> [166.830983] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_C

<7> [166.832100] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PORT PLL C (active 0x1, on? 1) for [CRTC:78:pipe A]

<7> [166.834623] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PORT PLL C

<7> [166.835267] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 79200 kHz, VCO 633600 kHz, ref 19200 kHz, bypass 19200 kHz, voltage level 4

<7> [166.835702] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B]

<7> [166.836465] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C]

<7> [166.837172] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:176:HDMI-A-2]

<7> [166.837806] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling dpio-common-c

<7> [166.838467] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:78:pipe A]

<7> [166.839901] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change

<7> [166.840336] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 316800 kHz, actual 316800 kHz

<7> [166.840714] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 13, actual 13

<7> [166.841221] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 316800 kHz, VCO 633600 kHz, ref 19200 kHz, bypass 19200 kHz, voltage level 13

<7> [166.842195] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B]

<7> [166.843935] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:164:pipe C]

<7> [166.844298] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B]

<7> [166.844360] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:176:HDMI-A-2]

<7> [166.844550] i915 0000:00:02.0: [drm:intel_hdmi_compute_clock [i915]] picking 12 bpc for HDMI output (pipe bpp: 36)

<7> [166.845619] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:121:pipe B] hw max bpp: 36, pipe bpp: 36, dithering: 0

<7> [166.846270] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:175:DDI C/PHY C] [CRTC:121:pipe B]

<7> [166.846653] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.enable (expected no, found yes)

<7> [166.847226] azx_init_pci: snd_hda_intel 0000:00:0e.0: Clearing TCSEL

<7> [166.847243] azx_init_pci: snd_hda_intel 0000:00:0e.0: SCH snoop: Enabled

<7> [166.847300] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.active (expected no, found yes)

<7> [166.847683] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)

<7> [166.848324] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in lane_count (expected 0, found 4)

<7> [166.848707] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in lane_lat_optim_mask (expected 0x00000000, found 0x0000000d)

<7> [166.850595] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040)

<7> [166.851322] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)

<7> [166.851708] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920)

<7> [166.852474] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200)

<7> [166.853140] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920)

<7> [166.853525] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200)

<7> [166.854122] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008)

<7> [166.854530] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052)

<7> [166.855208] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080)

<7> [166.855592] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080)

<7> [166.857299] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083)

<7> [166.857747] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088)

<7> [166.858473] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125)

<7> [166.859107] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125)

<7> [166.859494] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920)

<7> [166.860060] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200)

<7> [166.860442] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920)

<7> [166.860820] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200)

<7> [166.862447] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008)

<7> [166.863324] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052)

<7> [166.863713] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080)

<7> [166.864386] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080)

<7> [166.864775] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083)

<7> [166.865340] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088)

<7> [166.865721] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125)

<7> [166.866301] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125)

<7> [166.866685] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)

<7> [166.867899] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1)

<7> [166.868317] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)

<7> [166.868696] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in has_hdmi_sink (expected no, found yes)

<7> [166.869746] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in has_infoframe (expected no, found yes)

<7> [166.870473] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 36)

<7> [166.871131] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500)

<7> [166.871514] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500)

<7> [166.872077] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in port_clock (expected 0, found 222750)

<7> [166.872461] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071)

<7> [166.873062] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in infoframes.gcp (expected 0x00000000, found 0x00000006)

<7> [166.873450] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in avi infoframe

<7> [166.873829] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [166.875491] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [166.876343] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13

<7> [166.876349] i915 0000:00:02.0: colorspace: RGB

<7> [166.876353] i915 0000:00:02.0: scan mode: Underscan

<7> [166.876356] i915 0000:00:02.0: colorimetry: No Data

<7> [166.876360] i915 0000:00:02.0: picture aspect: No Data

<7> [166.876363] i915 0000:00:02.0: active aspect: Same as Picture

<7> [166.876366] i915 0000:00:02.0: itc: No Data

<7> [166.876369] i915 0000:00:02.0: extended colorimetry: xvYCC 601

<7> [166.876373] i915 0000:00:02.0: quantization range: Full

<7> [166.876376] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling

<7> [166.876379] i915 0000:00:02.0: video code: 0

<7> [166.876382] i915 0000:00:02.0: ycc quantization range: Full

<7> [166.876386] i915 0000:00:02.0: hdmi content type: Graphics

<7> [166.876389] i915 0000:00:02.0: pixel repeat: 0

<7> [166.876392] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0

<7> [166.876397] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in spd infoframe

<7> [166.876796] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [166.877555] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [166.878127] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25

<7> [166.878132] i915 0000:00:02.0: vendor: Intel

<7> [166.878136] i915 0000:00:02.0: product: Integrated gfx

<7> [166.878140] i915 0000:00:02.0: source device information: PC General (0x9)

<7> [166.878144] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hdmi infoframe

<7> [166.878524] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [166.879129] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [166.879511] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4

<7> [166.879515] i915 0000:00:02.0: empty frame

<7> [166.879520] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:121:pipe B] fastset requirement not met, forcing full modeset

<7> [166.880975] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:121:pipe B] dbuf slices 0x0 -> 0x1, ddb (0 - 0) -> (0 - 1020), active pipes 0x0 -> 0x2

<7> [166.881459] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:79:plane 1B] ddb ( 0 - 0) -> ( 0 - 988), size 0 -> 988

<7> [166.883108] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:115:cursor B] ddb ( 0 - 0) -> ( 988 - 1020), size 0 -> 32

<7> [166.883510] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5,*wm6,*wm7,*twm, swm, stwm

<7> [166.884311] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 1, 1, 2, 2, 2, 2, 2, 0, 0, 0

<7> [166.884700] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 16, 16, 33, 33, 33, 33, 33, 30, 0, 0

<7> [166.885383] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 17, 17, 17, 34, 34, 34, 34, 34, 31, 0, 0

<7> [166.885763] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] min_ddb_uv 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [166.886398] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:121:pipe B] min cdclk: 0 kHz -> 192000 kHz

<7> [166.886826] i915 0000:00:02.0: [drm:bxt_get_dpll [i915]] [CRTC:121:pipe B] using pre-allocated PORT PLL C

<7> [166.887397] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:121:pipe B] reserving PORT PLL C

<7> [166.887793] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:121:pipe B] enable: yes [modeset]

<7> [166.888936] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB

<7> [166.889350] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 36, dithering: 0

<7> [166.889726] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>

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

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

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

<7> [166.892586] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71

<7> [166.893222] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x6

<7> [166.893608] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13

<7> [166.893612] i915 0000:00:02.0: colorspace: RGB

<7> [166.893616] i915 0000:00:02.0: scan mode: Underscan

<7> [166.893619] i915 0000:00:02.0: colorimetry: No Data

<7> [166.893623] i915 0000:00:02.0: picture aspect: No Data

<7> [166.893627] i915 0000:00:02.0: active aspect: Same as Picture

<7> [166.893630] i915 0000:00:02.0: itc: No Data

<7> [166.893633] i915 0000:00:02.0: extended colorimetry: xvYCC 601

<7> [166.893637] i915 0000:00:02.0: quantization range: Full

<7> [166.893640] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling

<7> [166.893643] i915 0000:00:02.0: video code: 0

<7> [166.893647] i915 0000:00:02.0: ycc quantization range: Full

<7> [166.893650] i915 0000:00:02.0: hdmi content type: Graphics

<7> [166.893653] i915 0000:00:02.0: pixel repeat: 0

<7> [166.893656] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0

<7> [166.893660] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25

<7> [166.893664] i915 0000:00:02.0: vendor: Intel

<7> [166.893667] i915 0000:00:02.0: product: Integrated gfx

<7> [166.893670] i915 0000:00:02.0: source device information: PC General (0x9)

<7> [166.893674] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4

<7> [166.893678] i915 0000:00:02.0: empty frame

<7> [166.893681] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 10 00 07 00 66 10 00 01 00 00 00 00 00 00 00 00

<7> [166.894343] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 05 e3 cd 0c 32 38 45 38 35 30 09 07 07 00 00 00

<7> [166.894726] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2

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

<7> [166.895725] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0

<7> [166.897730] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0

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

<7> [166.898765] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9

<7> [166.899521] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9

<7> [166.900199] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1083-1088 vt=1125, flags=0x9

<7> [166.900588] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x40 0x9

<7> [166.901156] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1083-1088 vt=1125, flags=0x9

<7> [166.901538] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 222750, pixel rate 148500, min cdclk 192000, min voltage level 0

<7> [166.902117] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0

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

<7> [166.904070] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0

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

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

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

<7> [166.906387] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: ebb0: 0x6200, ebb4: 0x2000,pll0: 0x21, pll1: 0x100, pll2: 0x1a6666, pll3: 0x10000, pll6: 0x30904, pll8: 0x8, pll9: 0xa, pll10: 0x8003c00, pcsdw12: 0x4d

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

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

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

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

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

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

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

<7> [166.911463] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:79:plane 1B] fb: [FB:179] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes

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

<7> [166.912530] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0

<7> [166.913127] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:88:plane 2B] fb: [NOFB], visible: no

<7> [166.913514] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:97:plane 3B] fb: [NOFB], visible: no

<7> [166.914076] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:106:plane 4B] fb: [NOFB], visible: no

<7> [166.914461] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:115:cursor B] fb: [NOFB], visible: no

<7> [166.916737] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling dpio-common-c

<7> [166.918021] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B]

<7> [166.918430] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C]

<7> [166.919191] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PORT PLL C (active 0x2, on? 0) for [CRTC:121:pipe B]

<7> [166.919584] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PORT PLL C

<7> [166.920294] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_C

<7> [166.920784] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B

<7> [166.939454] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:176:HDMI-A-2][ENCODER:175:DDI C/PHY C] Enable audio codec on [CRTC:121:pipe B], 32 bytes ELD

<7> [166.956069] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 148500 (0x00090000)

<7> [166.956550] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N

<7> [166.958052] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:176:HDMI-A-2]

<7> [166.958684] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:121:pipe B]

<6> [169.595477] [IGT] kms_flip: finished subtest B-HDMI-A2, FAIL

Results for igt@kms_flip@flip-vs-expired-vblank-interruptible@b-hdmi-a2