Results for igt@kms_flip@flip-vs-absolute-wf_vblank-interruptible@b-vga1

Result: Fail

integration-manifest git-log-oneline i915_display_info24 igt_runner24 runtimes24 results24.json results24-i915-load.json i915_display_info_post_exec24 boot24 dmesg24

DetailValue
Duration 18.79 seconds
Hostname 
shard-snb7
Igt-Version 
IGT-Version: 2.1-g96108ec3f (x86_64) (Linux: 6.17.0-rc3-CI_DRM_17074-g3a2760f3080e+ x86_64)
Out 
Starting dynamic subtest: B-VGA1
  1024x768: 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa 
Expected frametime: 16666us; measured 17438.1us +- 10.372us accuracy 0.18%
vblank interval differs from modeline! expected 16665.6us, measured 17438us +- 10.372us, difference 772.5us (74.5 sigma)
Event flip: expected 433, counted 440, passrate = 9.09%, encoder type 1
Event vblank: expected 433, counted 440, passrate = 6.82%, encoder type 1
Expected frametime: 16666us; measured 16889.4us +- 11.026us accuracy 0.20%
vblank interval differs from modeline! expected 16665.6us, measured 16889us +- 11.026us, difference 223.8us (20.3 sigma)
Event flip: expected 448, counted 450, passrate = 75.56%, encoder type 1
Event vblank: expected 448, counted 450, passrate = 73.33%, encoder type 1
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:973 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1884 run_test()
  #3 ../tests/kms_flip.c:2153 __igt_unique____real_main2040()
  #4 ../tests/kms_flip.c:2040 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-VGA1: FAIL (18.787s)
Err 
Starting dynamic subtest: B-VGA1
(kms_flip:2765) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1704:
(kms_flip:2765) CRITICAL: Failed assertion: !retried
(kms_flip:2765) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-VGA1 failed.
**** DEBUG ****
(kms_flip:2765) DEBUG: inconsistent flip ts/seq: last 284.085449/904, current 284.255493/914: elapsed=170065.0us expected=174381.2us
(kms_flip:2765) DEBUG: name = vblank
last_ts = 284.238495
last_received_ts = 284.237915
last_seq = 913
current_ts = 284.408539
current_received_ts = 284.407837
current_seq = 923
count = 39
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 284.238495/913, current 284.408539/923: elapsed=170054.0us expected=174381.2us +- 871.9us, error 2.5%
(kms_flip:2765) DEBUG: inconsistent vblank ts/seq: last 284.238495/913, current 284.408539/923: elapsed=170054.0us expected=174381.2us
(kms_flip:2765) DEBUG: name = flip
last_ts = 284.255493
last_received_ts = 284.254883
last_seq = 914
current_ts = 284.425537
current_received_ts = 284.424896
current_seq = 924
count = 40
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 284.255493/914, current 284.425537/924: elapsed=170041.0us expected=174381.2us +- 871.9us, error 2.5%
(kms_flip:2765) DEBUG: inconsistent flip ts/seq: last 284.255493/914, current 284.425537/924: elapsed=170041.0us expected=174381.2us
(kms_flip:2765) DEBUG: name = vblank
last_ts = 284.408539
last_received_ts = 284.407837
last_seq = 923
current_ts = 284.578583
current_received_ts = 284.577972
current_seq = 933
count = 40
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 284.408539/923, current 284.578583/933: elapsed=170042.0us expected=174381.2us +- 871.9us, error 2.5%
(kms_flip:2765) DEBUG: inconsistent vblank ts/seq: last 284.408539/923, current 284.578583/933: elapsed=170042.0us expected=174381.2us
(kms_flip:2765) DEBUG: name = flip
last_ts = 284.425537
last_received_ts = 284.424896
last_seq = 924
current_ts = 284.595612
current_received_ts = 284.594971
current_seq = 934
count = 41
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 284.425537/924, current 284.595612/934: elapsed=170068.0us expected=174381.2us +- 871.9us, error 2.5%
(kms_flip:2765) DEBUG: inconsistent flip ts/seq: last 284.425537/924, current 284.595612/934: elapsed=170068.0us expected=174381.2us
(kms_flip:2765) DEBUG: name = vblank
last_ts = 284.578583
last_received_ts = 284.577972
last_seq = 933
current_ts = 284.748657
current_received_ts = 284.748077
current_seq = 943
count = 41
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 284.578583/933, current 284.748657/943: elapsed=170054.0us expected=174381.2us +- 871.9us, error 2.5%
(kms_flip:2765) DEBUG: inconsistent vblank ts/seq: last 284.578583/933, current 284.748657/943: elapsed=170054.0us expected=174381.2us
(kms_flip:2765) DEBUG: name = flip
last_ts = 284.595612
last_received_ts = 284.594971
last_seq = 934
current_ts = 284.765656
current_received_ts = 284.765106
current_seq = 944
count = 42
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 284.595612/934, current 284.765656/944: elapsed=170037.0us expected=174381.2us +- 871.9us, error 2.5%
(kms_flip:2765) DEBUG: inconsistent flip ts/seq: last 284.595612/934, current 284.765656/944: elapsed=170037.0us expected=174381.2us
(kms_flip:2765) DEBUG: name = vblank
last_ts = 284.748657
last_received_ts = 284.748077
last_seq = 943
current_ts = 284.918701
current_received_ts = 284.918121
current_seq = 953
count = 42
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 284.748657/943, current 284.918701/953: elapsed=170052.0us expected=174381.2us +- 871.9us, error 2.5%
(kms_flip:2765) DEBUG: inconsistent vblank ts/seq: last 284.748657/943, current 284.918701/953: elapsed=170052.0us expected=174381.2us
(kms_flip:2765) DEBUG: name = flip
last_ts = 284.765656
last_received_ts = 284.765106
last_seq = 944
current_ts = 284.935699
current_received_ts = 284.935120
current_seq = 954
count = 43
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 284.765656/944, current 284.935699/954: elapsed=170054.0us expected=174381.2us +- 871.9us, error 2.5%
(kms_flip:2765) DEBUG: inconsistent flip ts/seq: last 284.765656/944, current 284.935699/954: elapsed=170054.0us expected=174381.2us
(kms_flip:2765) DEBUG: name = vblank
last_ts = 284.918701
last_received_ts = 284.918121
last_seq = 953
current_ts = 285.088654
current_received_ts = 285.088104
current_seq = 963
count = 43
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 284.918701/953, current 285.088654/963: elapsed=169971.0us expected=174381.2us +- 871.9us, error 2.5%
(kms_flip:2765) DEBUG: inconsistent vblank ts/seq: last 284.918701/953, current 285.088654/963: elapsed=169971.0us expected=174381.2us
(kms_flip:2765) INFO: Event flip: expected 433, counted 440, passrate = 9.09%, encoder type 1
(kms_flip:2765) DEBUG: dropped frames, expected 433, counted 440, passrate = 9.09%, encoder type 1
(kms_flip:2765) INFO: Event vblank: expected 433, counted 440, passrate = 6.82%, encoder type 1
(kms_flip:2765) DEBUG: dropped frames, expected 433, counted 440, passrate = 6.82%, encoder type 1
(kms_flip:2765) DEBUG: Retrying without a hotplug event
(kms_flip:2765) DEBUG: No stale events found
(kms_flip:2765) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2765) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2765) INFO: Expected frametime: 16666us; measured 16889.4us +- 11.026us accuracy 0.20%
(kms_flip:2765) INFO: vblank interval differs from modeline! expected 16665.6us, measured 16889us +- 11.026us, difference 223.8us (20.3 sigma)
(kms_flip:2765) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 288.539307
current_received_ts = 288.538605
current_seq = 987
count = 0
seq_step = 1
(kms_flip:2765) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 288.691315
current_received_ts = 288.690643
current_seq = 996
count = 0
seq_step = 10
(kms_flip:2765) DEBUG: name = flip
last_ts = 288.539307
last_received_ts = 288.538605
last_seq = 987
current_ts = 288.708191
current_received_ts = 288.707550
current_seq = 997
count = 1
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 288.539307/987, current 288.708191/997: elapsed=168887.0us expected=168893.8us +- 844.5us, error 0.0%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 288.691315
last_received_ts = 288.690643
last_seq = 996
current_ts = 288.860199
current_received_ts = 288.859558
current_seq = 1006
count = 1
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 288.691315/996, current 288.860199/1006: elapsed=168897.0us expected=168893.8us +- 844.5us, error 0.0%
(kms_flip:2765) DEBUG: name = flip
last_ts = 288.708191
last_received_ts = 288.707550
last_seq = 997
current_ts = 288.877075
current_received_ts = 288.876495
current_seq = 1007
count = 2
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 288.708191/997, current 288.877075/1007: elapsed=168890.0us expected=168893.8us +- 844.5us, error 0.0%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 288.860199
last_received_ts = 288.859558
last_seq = 1006
current_ts = 289.029083
current_received_ts = 289.028473
current_seq = 1016
count = 2
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 288.860199/1006, current 289.029083/1016: elapsed=168894.0us expected=168893.8us +- 844.5us, error 0.0%
(kms_flip:2765) DEBUG: name = flip
last_ts = 288.877075
last_received_ts = 288.876495
last_seq = 1007
current_ts = 289.045990
current_received_ts = 289.045380
current_seq = 1017
count = 3
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 288.877075/1007, current 289.045990/1017: elapsed=168895.0us expected=168893.8us +- 844.5us, error 0.0%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 289.029083
last_received_ts = 289.028473
last_seq = 1016
current_ts = 289.197815
current_received_ts = 289.197174
current_seq = 1026
count = 3
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 289.029083/1016, current 289.197815/1026: elapsed=168707.0us expected=168893.8us +- 844.5us, error 0.1%
(kms_flip:2765) DEBUG: name = flip
last_ts = 289.045990
last_received_ts = 289.045380
last_seq = 1017
current_ts = 289.214661
current_received_ts = 289.214081
current_seq = 1027
count = 4
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 289.045990/1017, current 289.214661/1027: elapsed=168693.0us expected=168893.8us +- 844.5us, error 0.1%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 289.197815
last_received_ts = 289.197174
last_seq = 1026
current_ts = 289.366516
current_received_ts = 289.365753
current_seq = 1036
count = 4
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 289.197815/1026, current 289.366516/1036: elapsed=168699.0us expected=168893.8us +- 844.5us, error 0.1%
(kms_flip:2765) DEBUG: name = flip
last_ts = 289.214661
last_received_ts = 289.214081
last_seq = 1027
current_ts = 289.383392
current_received_ts = 289.382660
current_seq = 1037
count = 5
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 289.214661/1027, current 289.383392/1037: elapsed=168704.0us expected=168893.8us +- 844.5us, error 0.1%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 289.366516
last_received_ts = 289.365753
last_seq = 1036
current_ts = 289.535187
current_received_ts = 289.534576
current_seq = 1046
count = 5
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 289.366516/1036, current 289.535187/1046: elapsed=168682.0us expected=168893.8us +- 844.5us, error 0.1%
(kms_flip:2765) DEBUG: name = flip
last_ts = 289.383392
last_received_ts = 289.382660
last_seq = 1037
current_ts = 289.552063
current_received_ts = 289.551422
current_seq = 1047
count = 6
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 289.383392/1037, current 289.552063/1047: elapsed=168682.0us expected=168893.8us +- 844.5us, error 0.1%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 289.535187
last_received_ts = 289.534576
last_seq = 1046
current_ts = 289.703857
current_received_ts = 289.703217
current_seq = 1056
count = 6
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 289.535187/1046, current 289.703857/1056: elapsed=168686.0us expected=168893.8us +- 844.5us, error 0.1%
(kms_flip:2765) DEBUG: name = flip
last_ts = 289.552063
last_received_ts = 289.551422
last_seq = 1047
current_ts = 289.720764
current_received_ts = 289.720062
current_seq = 1057
count = 7
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 289.552063/1047, current 289.720764/1057: elapsed=168689.0us expected=168893.8us +- 844.5us, error 0.1%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 289.703857
last_received_ts = 289.703217
last_seq = 1056
current_ts = 289.872559
current_received_ts = 289.871887
current_seq = 1066
count = 7
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 289.703857/1056, current 289.872559/1066: elapsed=168695.0us expected=168893.8us +- 844.5us, error 0.1%
(kms_flip:2765) DEBUG: name = flip
last_ts = 289.720764
last_received_ts = 289.720062
last_seq = 1057
current_ts = 289.889435
current_received_ts = 289.888702
current_seq = 1067
count = 8
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 289.720764/1057, current 289.889435/1067: elapsed=168695.0us expected=168893.8us +- 844.5us, error 0.1%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 289.872559
last_received_ts = 289.871887
last_seq = 1066
current_ts = 290.041260
current_received_ts = 290.040649
current_seq = 1076
count = 8
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 289.872559/1066, current 290.041260/1076: elapsed=168682.0us expected=168893.8us +- 844.5us, error 0.1%
(kms_flip:2765) DEBUG: name = flip
last_ts = 289.889435
last_received_ts = 289.888702
last_seq = 1067
current_ts = 290.058105
current_received_ts = 290.057526
current_seq = 1077
count = 9
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 289.889435/1067, current 290.058105/1077: elapsed=168671.0us expected=168893.8us +- 844.5us, error 0.1%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 290.041260
last_received_ts = 290.040649
last_seq = 1076
current_ts = 290.209778
current_received_ts = 290.209167
current_seq = 1086
count = 9
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 290.041260/1076, current 290.209778/1086: elapsed=168530.0us expected=168893.8us +- 844.5us, error 0.2%
(kms_flip:2765) DEBUG: name = flip
last_ts = 290.058105
last_received_ts = 290.057526
last_seq = 1077
current_ts = 290.226624
current_received_ts = 290.226044
current_seq = 1087
count = 10
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 290.058105/1077, current 290.226624/1087: elapsed=168505.0us expected=168893.8us +- 844.5us, error 0.2%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 290.209778
last_received_ts = 290.209167
last_seq = 1086
current_ts = 290.378296
current_received_ts = 290.377625
current_seq = 1096
count = 10
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 290.209778/1086, current 290.378296/1096: elapsed=168517.0us expected=168893.8us +- 844.5us, error 0.2%
(kms_flip:2765) DEBUG: name = flip
last_ts = 290.226624
last_received_ts = 290.226044
last_seq = 1087
current_ts = 290.395142
current_received_ts = 290.394562
current_seq = 1097
count = 11
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 290.226624/1087, current 290.395142/1097: elapsed=168511.0us expected=168893.8us +- 844.5us, error 0.2%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 290.378296
last_received_ts = 290.377625
last_seq = 1096
current_ts = 290.546814
current_received_ts = 290.546173
current_seq = 1106
count = 11
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 290.378296/1096, current 290.546814/1106: elapsed=168507.0us expected=168893.8us +- 844.5us, error 0.2%
(kms_flip:2765) DEBUG: name = flip
last_ts = 290.395142
last_received_ts = 290.394562
last_seq = 1097
current_ts = 290.563660
current_received_ts = 290.562958
current_seq = 1107
count = 12
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 290.395142/1097, current 290.563660/1107: elapsed=168525.0us expected=168893.8us +- 844.5us, error 0.2%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 290.546814
last_received_ts = 290.546173
last_seq = 1106
current_ts = 290.715302
current_received_ts = 290.714630
current_seq = 1116
count = 12
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 290.546814/1106, current 290.715302/1116: elapsed=168504.0us expected=168893.8us +- 844.5us, error 0.2%
(kms_flip:2765) DEBUG: name = flip
last_ts = 290.563660
last_received_ts = 290.562958
last_seq = 1107
current_ts = 290.732147
current_received_ts = 290.731567
current_seq = 1117
count = 13
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 290.563660/1107, current 290.732147/1117: elapsed=168492.0us expected=168893.8us +- 844.5us, error 0.2%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 290.715302
last_received_ts = 290.714630
last_seq = 1116
current_ts = 290.883820
current_received_ts = 290.883118
current_seq = 1126
count = 13
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 290.715302/1116, current 290.883820/1126: elapsed=168501.0us expected=168893.8us +- 844.5us, error 0.2%
(kms_flip:2765) DEBUG: name = flip
last_ts = 290.732147
last_received_ts = 290.731567
last_seq = 1117
current_ts = 290.900665
current_received_ts = 290.900055
current_seq = 1127
count = 14
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 290.732147/1117, current 290.900665/1127: elapsed=168512.0us expected=168893.8us +- 844.5us, error 0.2%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 290.883820
last_received_ts = 290.883118
last_seq = 1126
current_ts = 291.052338
current_received_ts = 291.051666
current_seq = 1136
count = 14
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 290.883820/1126, current 291.052338/1136: elapsed=168523.0us expected=168893.8us +- 844.5us, error 0.2%
(kms_flip:2765) DEBUG: name = flip
last_ts = 290.900665
last_received_ts = 290.900055
last_seq = 1127
current_ts = 291.069153
current_received_ts = 291.068573
current_seq = 1137
count = 15
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 290.900665/1127, current 291.069153/1137: elapsed=168490.0us expected=168893.8us +- 844.5us, error 0.2%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 291.052338
last_received_ts = 291.051666
last_seq = 1136
current_ts = 291.220673
current_received_ts = 291.220032
current_seq = 1146
count = 15
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 291.052338/1136, current 291.220673/1146: elapsed=168338.0us expected=168893.8us +- 844.5us, error 0.3%
(kms_flip:2765) DEBUG: name = flip
last_ts = 291.069153
last_received_ts = 291.068573
last_seq = 1137
current_ts = 291.237518
current_received_ts = 291.236969
current_seq = 1147
count = 16
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 291.069153/1137, current 291.237518/1147: elapsed=168358.0us expected=168893.8us +- 844.5us, error 0.3%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 291.220673
last_received_ts = 291.220032
last_seq = 1146
current_ts = 291.389008
current_received_ts = 291.388428
current_seq = 1156
count = 16
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 291.220673/1146, current 291.389008/1156: elapsed=168352.0us expected=168893.8us +- 844.5us, error 0.3%
(kms_flip:2765) DEBUG: name = flip
last_ts = 291.237518
last_received_ts = 291.236969
last_seq = 1147
current_ts = 291.405853
current_received_ts = 291.405182
current_seq = 1157
count = 17
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 291.237518/1147, current 291.405853/1157: elapsed=168353.0us expected=168893.8us +- 844.5us, error 0.3%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 291.389008
last_received_ts = 291.388428
last_seq = 1156
current_ts = 291.557373
current_received_ts = 291.556671
current_seq = 1166
count = 17
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 291.389008/1156, current 291.557373/1166: elapsed=168362.0us expected=168893.8us +- 844.5us, error 0.3%
(kms_flip:2765) DEBUG: name = flip
last_ts = 291.405853
last_received_ts = 291.405182
last_seq = 1157
current_ts = 291.574219
current_received_ts = 291.573547
current_seq = 1167
count = 18
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 291.405853/1157, current 291.574219/1167: elapsed=168344.0us expected=168893.8us +- 844.5us, error 0.3%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 291.557373
last_received_ts = 291.556671
last_seq = 1166
current_ts = 291.725739
current_received_ts = 291.725098
current_seq = 1176
count = 18
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 291.557373/1166, current 291.725739/1176: elapsed=168343.0us expected=168893.8us +- 844.5us, error 0.3%
(kms_flip:2765) DEBUG: name = flip
last_ts = 291.574219
last_received_ts = 291.573547
last_seq = 1167
current_ts = 291.742554
current_received_ts = 291.741974
current_seq = 1177
count = 19
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 291.574219/1167, current 291.742554/1177: elapsed=168352.0us expected=168893.8us +- 844.5us, error 0.3%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 291.725739
last_received_ts = 291.725098
last_seq = 1176
current_ts = 291.894073
current_received_ts = 291.893463
current_seq = 1186
count = 19
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 291.725739/1176, current 291.894073/1186: elapsed=168354.0us expected=168893.8us +- 844.5us, error 0.3%
(kms_flip:2765) DEBUG: name = flip
last_ts = 291.742554
last_received_ts = 291.741974
last_seq = 1177
current_ts = 291.910919
current_received_ts = 291.910309
current_seq = 1187
count = 20
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 291.742554/1177, current 291.910919/1187: elapsed=168370.0us expected=168893.8us +- 844.5us, error 0.3%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 291.894073
last_received_ts = 291.893463
last_seq = 1186
current_ts = 292.062408
current_received_ts = 292.061798
current_seq = 1196
count = 20
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 291.894073/1186, current 292.062408/1196: elapsed=168339.0us expected=168893.8us +- 844.5us, error 0.3%
(kms_flip:2765) DEBUG: name = flip
last_ts = 291.910919
last_received_ts = 291.910309
last_seq = 1187
current_ts = 292.079254
current_received_ts = 292.078644
current_seq = 1197
count = 21
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 291.910919/1187, current 292.079254/1197: elapsed=168313.0us expected=168893.8us +- 844.5us, error 0.3%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 292.062408
last_received_ts = 292.061798
last_seq = 1196
current_ts = 292.230621
current_received_ts = 292.230103
current_seq = 1206
count = 21
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 292.062408/1196, current 292.230621/1206: elapsed=168215.0us expected=168893.8us +- 844.5us, error 0.4%
(kms_flip:2765) DEBUG: name = flip
last_ts = 292.079254
last_received_ts = 292.078644
last_seq = 1197
current_ts = 292.247467
current_received_ts = 292.246796
current_seq = 1207
count = 22
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 292.079254/1197, current 292.247467/1207: elapsed=168229.0us expected=168893.8us +- 844.5us, error 0.4%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 292.230621
last_received_ts = 292.230103
last_seq = 1206
current_ts = 292.398865
current_received_ts = 292.398224
current_seq = 1216
count = 22
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 292.230621/1206, current 292.398865/1216: elapsed=168227.0us expected=168893.8us +- 844.5us, error 0.4%
(kms_flip:2765) DEBUG: name = flip
last_ts = 292.247467
last_received_ts = 292.246796
last_seq = 1207
current_ts = 292.415680
current_received_ts = 292.415161
current_seq = 1217
count = 23
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 292.247467/1207, current 292.415680/1217: elapsed=168212.0us expected=168893.8us +- 844.5us, error 0.4%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 292.398865
last_received_ts = 292.398224
last_seq = 1216
current_ts = 292.567078
current_received_ts = 292.566437
current_seq = 1226
count = 23
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 292.398865/1216, current 292.567078/1226: elapsed=168210.0us expected=168893.8us +- 844.5us, error 0.4%
(kms_flip:2765) DEBUG: name = flip
last_ts = 292.415680
last_received_ts = 292.415161
last_seq = 1217
current_ts = 292.583893
current_received_ts = 292.583252
current_seq = 1227
count = 24
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 292.415680/1217, current 292.583893/1227: elapsed=168208.0us expected=168893.8us +- 844.5us, error 0.4%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 292.567078
last_received_ts = 292.566437
last_seq = 1226
current_ts = 292.735291
current_received_ts = 292.734650
current_seq = 1236
count = 24
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 292.567078/1226, current 292.735291/1236: elapsed=168214.0us expected=168893.8us +- 844.5us, error 0.4%
(kms_flip:2765) DEBUG: name = flip
last_ts = 292.583893
last_received_ts = 292.583252
last_seq = 1227
current_ts = 292.752106
current_received_ts = 292.751495
current_seq = 1237
count = 25
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 292.583893/1227, current 292.752106/1237: elapsed=168207.0us expected=168893.8us +- 844.5us, error 0.4%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 292.735291
last_received_ts = 292.734650
last_seq = 1236
current_ts = 292.903503
current_received_ts = 292.902893
current_seq = 1246
count = 25
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 292.735291/1236, current 292.903503/1246: elapsed=168213.0us expected=168893.8us +- 844.5us, error 0.4%
(kms_flip:2765) DEBUG: name = flip
last_ts = 292.752106
last_received_ts = 292.751495
last_seq = 1237
current_ts = 292.920319
current_received_ts = 292.919708
current_seq = 1247
count = 26
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 292.752106/1237, current 292.920319/1247: elapsed=168218.0us expected=168893.8us +- 844.5us, error 0.4%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 292.903503
last_received_ts = 292.902893
last_seq = 1246
current_ts = 293.071686
current_received_ts = 293.071106
current_seq = 1256
count = 26
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 292.903503/1246, current 293.071686/1256: elapsed=168194.0us expected=168893.8us +- 844.5us, error 0.4%
(kms_flip:2765) DEBUG: name = flip
last_ts = 292.920319
last_received_ts = 292.919708
last_seq = 1247
current_ts = 293.088501
current_received_ts = 293.087891
current_seq = 1257
count = 27
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 292.920319/1247, current 293.088501/1257: elapsed=168195.0us expected=168893.8us +- 844.5us, error 0.4%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 293.071686
last_received_ts = 293.071106
last_seq = 1256
current_ts = 293.239777
current_received_ts = 293.239136
current_seq = 1266
count = 27
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 293.071686/1256, current 293.239777/1266: elapsed=168093.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: name = flip
last_ts = 293.088501
last_received_ts = 293.087891
last_seq = 1257
current_ts = 293.256592
current_received_ts = 293.255981
current_seq = 1267
count = 28
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 293.088501/1257, current 293.256592/1267: elapsed=168092.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 293.239777
last_received_ts = 293.239136
last_seq = 1266
current_ts = 293.407898
current_received_ts = 293.407227
current_seq = 1276
count = 28
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 293.239777/1266, current 293.407898/1276: elapsed=168111.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: name = flip
last_ts = 293.256592
last_received_ts = 293.255981
last_seq = 1267
current_ts = 293.424683
current_received_ts = 293.424103
current_seq = 1277
count = 29
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 293.256592/1267, current 293.424683/1277: elapsed=168091.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 293.407898
last_received_ts = 293.407227
last_seq = 1276
current_ts = 293.575989
current_received_ts = 293.575348
current_seq = 1286
count = 29
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 293.407898/1276, current 293.575989/1286: elapsed=168089.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: name = flip
last_ts = 293.424683
last_received_ts = 293.424103
last_seq = 1277
current_ts = 293.592804
current_received_ts = 293.592133
current_seq = 1287
count = 30
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 293.424683/1277, current 293.592804/1287: elapsed=168103.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 293.575989
last_received_ts = 293.575348
last_seq = 1286
current_ts = 293.744080
current_received_ts = 293.743469
current_seq = 1296
count = 30
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 293.575989/1286, current 293.744080/1296: elapsed=168101.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: name = flip
last_ts = 293.592804
last_received_ts = 293.592133
last_seq = 1287
current_ts = 293.760864
current_received_ts = 293.760254
current_seq = 1297
count = 31
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 293.592804/1287, current 293.760864/1297: elapsed=168081.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 293.744080
last_received_ts = 293.743469
last_seq = 1296
current_ts = 293.912170
current_received_ts = 293.911560
current_seq = 1306
count = 31
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 293.744080/1296, current 293.912170/1306: elapsed=168078.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: name = flip
last_ts = 293.760864
last_received_ts = 293.760254
last_seq = 1297
current_ts = 293.928986
current_received_ts = 293.928436
current_seq = 1307
count = 32
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 293.760864/1297, current 293.928986/1307: elapsed=168101.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 293.912170
last_received_ts = 293.911560
last_seq = 1306
current_ts = 294.080231
current_received_ts = 294.079590
current_seq = 1316
count = 32
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 293.912170/1306, current 294.080231/1316: elapsed=168076.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: name = flip
last_ts = 293.928986
last_received_ts = 293.928436
last_seq = 1307
current_ts = 294.097046
current_received_ts = 294.096405
current_seq = 1317
count = 33
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 293.928986/1307, current 294.097046/1317: elapsed=168068.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: name = vblank
last_ts = 294.080231
last_received_ts = 294.079590
last_seq = 1316
current_ts = 294.248230
current_received_ts = 294.247559
current_seq = 1326
count = 33
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 294.080231/1316, current 294.248230/1326: elapsed=167987.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: inconsistent vblank ts/seq: last 294.080231/1316, current 294.248230/1326: elapsed=167987.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = flip
last_ts = 294.097046
last_received_ts = 294.096405
last_seq = 1317
current_ts = 294.265045
current_received_ts = 294.264404
current_seq = 1327
count = 34
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 294.097046/1317, current 294.265045/1327: elapsed=167986.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: inconsistent flip ts/seq: last 294.097046/1317, current 294.265045/1327: elapsed=167986.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = vblank
last_ts = 294.248230
last_received_ts = 294.247559
last_seq = 1326
current_ts = 294.416229
current_received_ts = 294.415588
current_seq = 1336
count = 34
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 294.248230/1326, current 294.416229/1336: elapsed=167998.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: inconsistent vblank ts/seq: last 294.248230/1326, current 294.416229/1336: elapsed=167998.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = flip
last_ts = 294.265045
last_received_ts = 294.264404
last_seq = 1327
current_ts = 294.433014
current_received_ts = 294.432373
current_seq = 1337
count = 35
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 294.265045/1327, current 294.433014/1337: elapsed=167983.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: inconsistent flip ts/seq: last 294.265045/1327, current 294.433014/1337: elapsed=167983.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = vblank
last_ts = 294.416229
last_received_ts = 294.415588
last_seq = 1336
current_ts = 294.584229
current_received_ts = 294.583588
current_seq = 1346
count = 35
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 294.416229/1336, current 294.584229/1346: elapsed=167991.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: inconsistent vblank ts/seq: last 294.416229/1336, current 294.584229/1346: elapsed=167991.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = flip
last_ts = 294.433014
last_received_ts = 294.432373
last_seq = 1337
current_ts = 294.601013
current_received_ts = 294.600403
current_seq = 1347
count = 36
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 294.433014/1337, current 294.601013/1347: elapsed=167995.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: inconsistent flip ts/seq: last 294.433014/1337, current 294.601013/1347: elapsed=167995.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = vblank
last_ts = 294.584229
last_received_ts = 294.583588
last_seq = 1346
current_ts = 294.752197
current_received_ts = 294.751587
current_seq = 1356
count = 36
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 294.584229/1346, current 294.752197/1356: elapsed=167987.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: inconsistent vblank ts/seq: last 294.584229/1346, current 294.752197/1356: elapsed=167987.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = flip
last_ts = 294.601013
last_received_ts = 294.600403
last_seq = 1347
current_ts = 294.769012
current_received_ts = 294.768372
current_seq = 1357
count = 37
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 294.601013/1347, current 294.769012/1357: elapsed=167989.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: inconsistent flip ts/seq: last 294.601013/1347, current 294.769012/1357: elapsed=167989.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = vblank
last_ts = 294.752197
last_received_ts = 294.751587
last_seq = 1356
current_ts = 294.920197
current_received_ts = 294.919525
current_seq = 1366
count = 37
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 294.752197/1356, current 294.920197/1366: elapsed=167982.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: inconsistent vblank ts/seq: last 294.752197/1356, current 294.920197/1366: elapsed=167982.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = flip
last_ts = 294.769012
last_received_ts = 294.768372
last_seq = 1357
current_ts = 294.936981
current_received_ts = 294.936340
current_seq = 1367
count = 38
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 294.769012/1357, current 294.936981/1367: elapsed=167991.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: inconsistent flip ts/seq: last 294.769012/1357, current 294.936981/1367: elapsed=167991.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = vblank
last_ts = 294.920197
last_received_ts = 294.919525
last_seq = 1366
current_ts = 295.088165
current_received_ts = 295.087494
current_seq = 1376
count = 38
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 294.920197/1366, current 295.088165/1376: elapsed=167969.0us expected=168893.8us +- 844.5us, error 0.5%
(kms_flip:2765) DEBUG: inconsistent vblank ts/seq: last 294.920197/1366, current 295.088165/1376: elapsed=167969.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = flip
last_ts = 294.936981
last_received_ts = 294.936340
last_seq = 1367
current_ts = 295.104950
current_received_ts = 295.104279
current_seq = 1377
count = 39
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 294.936981/1367, current 295.104950/1377: elapsed=167952.0us expected=168893.8us +- 844.5us, error 0.6%
(kms_flip:2765) DEBUG: inconsistent flip ts/seq: last 294.936981/1367, current 295.104950/1377: elapsed=167952.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = vblank
last_ts = 295.088165
last_received_ts = 295.087494
last_seq = 1376
current_ts = 295.256073
current_received_ts = 295.255402
current_seq = 1386
count = 39
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 295.088165/1376, current 295.256073/1386: elapsed=167909.0us expected=168893.8us +- 844.5us, error 0.6%
(kms_flip:2765) DEBUG: inconsistent vblank ts/seq: last 295.088165/1376, current 295.256073/1386: elapsed=167909.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = flip
last_ts = 295.104950
last_received_ts = 295.104279
last_seq = 1377
current_ts = 295.272827
current_received_ts = 295.272217
current_seq = 1387
count = 40
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 295.104950/1377, current 295.272827/1387: elapsed=167901.0us expected=168893.8us +- 844.5us, error 0.6%
(kms_flip:2765) DEBUG: inconsistent flip ts/seq: last 295.104950/1377, current 295.272827/1387: elapsed=167901.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = vblank
last_ts = 295.256073
last_received_ts = 295.255402
last_seq = 1386
current_ts = 295.423950
current_received_ts = 295.423309
current_seq = 1396
count = 40
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 295.256073/1386, current 295.423950/1396: elapsed=167888.0us expected=168893.8us +- 844.5us, error 0.6%
(kms_flip:2765) DEBUG: inconsistent vblank ts/seq: last 295.256073/1386, current 295.423950/1396: elapsed=167888.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = flip
last_ts = 295.272827
last_received_ts = 295.272217
last_seq = 1387
current_ts = 295.440735
current_received_ts = 295.440125
current_seq = 1397
count = 41
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 295.272827/1387, current 295.440735/1397: elapsed=167898.0us expected=168893.8us +- 844.5us, error 0.6%
(kms_flip:2765) DEBUG: inconsistent flip ts/seq: last 295.272827/1387, current 295.440735/1397: elapsed=167898.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = vblank
last_ts = 295.423950
last_received_ts = 295.423309
last_seq = 1396
current_ts = 295.591858
current_received_ts = 295.591217
current_seq = 1406
count = 41
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 295.423950/1396, current 295.591858/1406: elapsed=167897.0us expected=168893.8us +- 844.5us, error 0.6%
(kms_flip:2765) DEBUG: inconsistent vblank ts/seq: last 295.423950/1396, current 295.591858/1406: elapsed=167897.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = flip
last_ts = 295.440735
last_received_ts = 295.440125
last_seq = 1397
current_ts = 295.608643
current_received_ts = 295.608002
current_seq = 1407
count = 42
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 295.440735/1397, current 295.608643/1407: elapsed=167895.0us expected=168893.8us +- 844.5us, error 0.6%
(kms_flip:2765) DEBUG: inconsistent flip ts/seq: last 295.440735/1397, current 295.608643/1407: elapsed=167895.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = vblank
last_ts = 295.591858
last_received_ts = 295.591217
last_seq = 1406
current_ts = 295.759735
current_received_ts = 295.759155
current_seq = 1416
count = 42
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 295.591858/1406, current 295.759735/1416: elapsed=167895.0us expected=168893.8us +- 844.5us, error 0.6%
(kms_flip:2765) DEBUG: inconsistent vblank ts/seq: last 295.591858/1406, current 295.759735/1416: elapsed=167895.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = flip
last_ts = 295.608643
last_received_ts = 295.608002
last_seq = 1407
current_ts = 295.776520
current_received_ts = 295.775909
current_seq = 1417
count = 43
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 295.608643/1407, current 295.776520/1417: elapsed=167900.0us expected=168893.8us +- 844.5us, error 0.6%
(kms_flip:2765) DEBUG: inconsistent flip ts/seq: last 295.608643/1407, current 295.776520/1417: elapsed=167900.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = vblank
last_ts = 295.759735
last_received_ts = 295.759155
last_seq = 1416
current_ts = 295.927643
current_received_ts = 295.927032
current_seq = 1426
count = 43
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 295.759735/1416, current 295.927643/1426: elapsed=167915.0us expected=168893.8us +- 844.5us, error 0.6%
(kms_flip:2765) DEBUG: inconsistent vblank ts/seq: last 295.759735/1416, current 295.927643/1426: elapsed=167915.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = flip
last_ts = 295.776520
last_received_ts = 295.775909
last_seq = 1417
current_ts = 295.944458
current_received_ts = 295.943756
current_seq = 1427
count = 44
seq_step = 1
(kms_flip:2765) DEBUG: flip ts/seq: last 295.776520/1417, current 295.944458/1427: elapsed=167911.0us expected=168893.8us +- 844.5us, error 0.6%
(kms_flip:2765) DEBUG: inconsistent flip ts/seq: last 295.776520/1417, current 295.944458/1427: elapsed=167911.0us expected=168893.8us
(kms_flip:2765) DEBUG: name = vblank
last_ts = 295.927643
last_received_ts = 295.927032
last_seq = 1426
current_ts = 296.095520
current_received_ts = 296.094910
current_seq = 1436
count = 44
seq_step = 10
(kms_flip:2765) DEBUG: vblank ts/seq: last 295.927643/1426, current 296.095520/1436: elapsed=167859.0us expected=168893.8us +- 844.5us, error 0.6%
(kms_flip:2765) DEBUG: inconsistent vblank ts/seq: last 295.927643/1426, current 296.095520/1436: elapsed=167859.0us expected=168893.8us
(kms_flip:2765) INFO: Event flip: expected 448, counted 450, passrate = 75.56%, encoder type 1
(kms_flip:2765) DEBUG: dropped frames, expected 448, counted 450, passrate = 75.56%, encoder type 1
(kms_flip:2765) INFO: Event vblank: expected 448, counted 450, passrate = 73.33%, encoder type 1
(kms_flip:2765) DEBUG: dropped frames, expected 448, counted 450, passrate = 73.33%, encoder type 1
(kms_flip:2765) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1704:
(kms_flip:2765) CRITICAL: Failed assertion: !retried
(kms_flip:2765) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2765) igt_core-INFO: Stack trace:
(kms_flip:2765) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2765) igt_core-INFO:   #1 ../tests/kms_flip.c:973 run_test_on_crtc_set.constprop.0()
(kms_flip:2765) igt_core-INFO:   #2 ../tests/kms_flip.c:1884 run_test()
(kms_flip:2765) igt_core-INFO:   #3 ../tests/kms_flip.c:2153 __igt_unique____real_main2040()
(kms_flip:2765) igt_core-INFO:   #4 ../tests/kms_flip.c:2040 main()
(kms_flip:2765) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2765) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2765) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-VGA1: FAIL (18.787s)
Dmesg
<6> [276.452528] [IGT] kms_flip: starting dynamic subtest B-VGA1
<7> [276.453243] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:85]
<7> [276.453372] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:86]
<7> [276.469315] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:49:pipe A]
<7> [276.469500] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.enable (expected yes, found no)
<7> [276.469799] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.active (expected yes, found no)
<7> [276.470072] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1)
<7> [276.470524] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in has_pch_encoder (expected yes, found no)
<7> [276.470889] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in fdi_lanes (expected 1, found 0)
<7> [276.471235] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in fdi_m_n (expected tu 64 data 6039797/8388608 link 125829/524288, found tu 0, data 0/0 link 0/0)
<7> [276.471579] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in output_types (expected 0x00000002, found 0x00000000)
<7> [276.471828] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [276.472070] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1024, found 0)
<7> [276.472476] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 1344, found 0)
<7> [276.472837] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1024, found 0)
<7> [276.473227] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 1344, found 0)
<7> [276.473573] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1048, found 0)
<7> [276.473804] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 1184, found 0)
<7> [276.474079] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 768, found 0)
<7> [276.474471] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 768, found 0)
<7> [276.474828] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 771, found 0)
<7> [276.475241] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 777, found 0)
<7> [276.475515] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 806, found 0)
<7> [276.475746] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 806, found 0)
<7> [276.476120] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1024, found 0)
<7> [276.476477] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 1344, found 0)
<7> [276.476832] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1024, found 0)
<7> [276.477219] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 1344, found 0)
<7> [276.477504] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1048, found 0)
<7> [276.477735] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 1184, found 0)
<7> [276.478002] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 768, found 0)
<7> [276.478363] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 768, found 0)
<7> [276.478720] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 771, found 0)
<7> [276.479107] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 777, found 0)
<7> [276.479442] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 806, found 0)
<7> [276.479692] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 806, found 0)
<7> [276.480010] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [276.480368] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)
<7> [276.480724] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)
<7> [276.481101] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0)
<7> [276.481378] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 64800, found 0)
<7> [276.481609] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 64800, found 0)
<7> [276.481964] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:49:pipe A] fastset requirement not met in port_clock (expected 64800, found 0)
<7> [276.482323] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:49:pipe A] fastset requirement not met, forcing full modeset
<7> [276.482679] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:49:pipe A] releasing PCH DPLL A
<7> [276.483159] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 400000 kHz, actual 400000 kHz
<7> [276.483428] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [276.483664] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:49:pipe A] enable: no [modeset]
<7> [276.483985] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:33:primary A] fb: [NOFB], visible: no
<7> [276.484513] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A
<7> [276.500560] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found
<7> [276.501072] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found
<7> [276.501544] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found
<7> [276.517617] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PCH DPLL A (active 0x1, on? 1) for [CRTC:49:pipe A]
<7> [276.518127] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PCH DPLL A
<7> [276.518907] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:68:CRT]
<7> [276.519691] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:69:HDMI D]
<7> [276.520456] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:77:DP D]
<7> [276.521201] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:67:VGA-1]
<7> [276.521570] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:49:pipe A]
<7> [276.521916] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:66:pipe B]
<7> [276.522055] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:66:pipe B]
<7> [276.522103] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:67:VGA-1]
<7> [276.522214] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:67:VGA-1] Limiting display bpp to 24 (EDID bpp 0, max requested bpp 0, max platform bpp 36)
<7> [276.522459] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:66:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0
<7> [276.522691] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe B, lanes 1
<7> [276.522916] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.enable (expected no, found yes)
<7> [276.523189] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.active (expected no, found yes)
<7> [276.523563] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)
<7> [276.523922] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in has_pch_encoder (expected no, found yes)
<7> [276.524312] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in fdi_lanes (expected 0, found 1)
<7> [276.524672] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in fdi_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6039797/8388608 link 125829/524288)
<7> [276.525033] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000002)
<7> [276.525291] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [276.525522] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1024)
<7> [276.525799] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 1344)
<7> [276.526188] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1024)
<7> [276.526563] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 1344)
<7> [276.526942] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1048)
<7> [276.527269] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 1184)
<7> [276.527498] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 768)
<7> [276.527808] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 768)
<7> [276.528202] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 771)
<7> [276.528590] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 777)
<7> [276.528962] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 806)
<7> [276.529229] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 806)
<7> [276.529508] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1024)
<7> [276.529895] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 1344)
<7> [276.530278] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1024)
<7> [276.530625] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 1344)
<7> [276.530984] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1048)
<7> [276.531239] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 1184)
<7> [276.531490] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 768)
<7> [276.531892] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 768)
<7> [276.532259] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 771)
<7> [276.532620] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 777)
<7> [276.532966] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 806)
<7> [276.533205] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 806)
<7> [276.533516] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [276.533904] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)
<7> [276.534271] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)
<7> [276.534637] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in dpll_hw_state
<7> [276.534883] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:
<7> [276.535122] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0xc4010001, dpll_md: 0x0, fp0: 0x30f06, fp1: 0x30f06
<7> [276.535447] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:
<7> [276.535834] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [276.536220] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24)
<7> [276.536583] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 64800)
<7> [276.536832] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 64800)
<7> [276.537071] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in port_clock (expected 0, found 64800)
<7> [276.537454] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:66:pipe B] fastset requirement not met, forcing full modeset
<7> [276.537919] i915 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [i915]] [PLANE:50:primary B] min cdclk (64800 kHz) > [CRTC:66:pipe B] min cdclk (0 kHz)
<7> [276.538276] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 400000 kHz, actual 400000 kHz
<7> [276.538631] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [276.538641] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on
<7> [276.538884] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:66:pipe B] allocated PCH DPLL A
<7> [276.539119] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:66:pipe B] reserving PCH DPLL A
<7> [276.539417] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:66:pipe B] enable: yes [modeset]
<7> [276.539784] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: ANALOG (0x2), output format: RGB, sink format: RGB
<7> [276.540148] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0
<7> [276.540529] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [276.540829] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [276.541064] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [276.541391] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [276.541757] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fdi: lanes: 1; data_m: 6039797, data_n: 8388608, link_m: 125829, link_n: 524288, tu: 64
<7> [276.542123] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0
<7> [276.542493] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1
<7> [276.542738] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0
<7> [276.542995] 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> [276.543386] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: -1, vmax vblank: -2, vmin vtotal: 1, vmax vtotal: 0
<7> [276.543746] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1024x768": 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa
<7> [276.544098] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1024x768": 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa
<7> [276.544470] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=64800, hd=1024 hb=1024-1344 hs=1048-1184 ht=1344, vd=768 vb=768-806 vs=771-777 vt=806, flags=0xa
<7> [276.544742] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1024x768": 60 64800 1024 1048 1184 1344 768 771 777 806 0x40 0xa
<7> [276.544978] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=64800, hd=1024 hb=1024-1344 hs=1048-1184 ht=1344, vd=768 vb=768-806 vs=771-777 vt=806, flags=0xa
<7> [276.545306] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 64800, pipe src: 1024x768+0+0, pixel rate 64800
<7> [276.545668] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0
<7> [276.546022] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [276.546395] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [276.546709] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [276.546946] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [276.547303] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [276.547667] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [276.548049] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [276.548382] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [276.548625] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [276.548889] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:50:primary B] fb: [FB:85] 1024x768 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes
<7> [276.549273] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [276.549634] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1024.000000x768.000000+0.000000+0.000000 dst: 1024x768+0+0
<7> [276.551009] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on
<7> [276.551250] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:68:CRT]
<7> [276.551472] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:69:HDMI D]
<7> [276.551691] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:77:DP D]
<7> [276.552544] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B
<7> [276.553797] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100
<7> [276.554028] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done.
<7> [276.554915] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x200
<7> [276.555269] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done.
<7> [276.555620] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done.
<7> [276.556032] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PCH DPLL A (active 0x2, on? 0) for [CRTC:66:pipe B]
<7> [276.556292] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PCH DPLL A
<7> [276.608321] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:67:VGA-1]
<7> [276.608922] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:66:pipe B]
<7> [287.228991] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:49:pipe A]
<7> [287.229430] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:66:pipe B]
<7> [287.229600] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.enable (expected yes, found no)
<7> [287.230209] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.active (expected yes, found no)
<7> [287.230773] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in cpu_transcoder (expected 1, found -1)
<7> [287.231355] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in has_pch_encoder (expected yes, found no)
<7> [287.231859] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in fdi_lanes (expected 1, found 0)
<7> [287.232220] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in fdi_m_n (expected tu 64 data 6039797/8388608 link 125829/524288, found tu 0, data 0/0 link 0/0)
<7> [287.232512] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in output_types (expected 0x00000002, found 0x00000000)
<7> [287.232779] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [287.233172] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1024, found 0)
<7> [287.233530] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 1344, found 0)
<7> [287.233771] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1024, found 0)
<7> [287.234026] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 1344, found 0)
<7> [287.234289] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1048, found 0)
<7> [287.234525] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 1184, found 0)
<7> [287.234761] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 768, found 0)
<7> [287.235016] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 768, found 0)
<7> [287.235284] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 771, found 0)
<7> [287.235520] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 777, found 0)
<7> [287.235756] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 806, found 0)
<7> [287.236009] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 806, found 0)
<7> [287.236274] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1024, found 0)
<7> [287.236510] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 1344, found 0)
<7> [287.236745] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1024, found 0)
<7> [287.237002] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 1344, found 0)
<7> [287.237274] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1048, found 0)
<7> [287.237504] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 1184, found 0)
<7> [287.237741] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 768, found 0)
<7> [287.237994] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 768, found 0)
<7> [287.238249] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 771, found 0)
<7> [287.238485] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 777, found 0)
<7> [287.238721] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 806, found 0)
<7> [287.238996] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 806, found 0)
<7> [287.239249] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [287.239497] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)
<7> [287.239852] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)
<7> [287.240234] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in pipe_bpp (expected 24, found 0)
<7> [287.240601] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 64800, found 0)
<7> [287.240965] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 64800, found 0)
<7> [287.241223] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in port_clock (expected 64800, found 0)
<7> [287.241473] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:66:pipe B] fastset requirement not met, forcing full modeset
<7> [287.241703] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:66:pipe B] releasing PCH DPLL A
<7> [287.242181] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 400000 kHz, actual 400000 kHz
<7> [287.242537] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [287.242893] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:66:pipe B] enable: no [modeset]
<7> [287.243232] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:50:primary B] fb: [NOFB], visible: no
<7> [287.243637] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe B
<7> [287.257266] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found
<7> [287.257818] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found
<7> [287.258388] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found
<7> [287.273918] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PCH DPLL A (active 0x2, on? 1) for [CRTC:66:pipe B]
<7> [287.274429] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PCH DPLL A
<7> [287.275191] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:68:CRT]
<7> [287.275724] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:69:HDMI D]
<7> [287.276088] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:77:DP D]
<7> [287.276467] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:67:VGA-1]
<7> [287.276934] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:66:pipe B]
<7> [287.277290] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:66:pipe B]
<7> [287.277317] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:67:VGA-1]
<7> [287.277404] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:67:VGA-1] Limiting display bpp to 24 (EDID bpp 0, max requested bpp 0, max platform bpp 36)
<7> [287.277680] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:66:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0
<7> [287.277910] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe B, lanes 1
<7> [287.278135] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.enable (expected no, found yes)
<7> [287.278364] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.active (expected no, found yes)
<7> [287.278617] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)
<7> [287.278865] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in has_pch_encoder (expected no, found yes)
<7> [287.279094] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in fdi_lanes (expected 0, found 1)
<7> [287.279335] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in fdi_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6039797/8388608 link 125829/524288)
<7> [287.279614] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000002)
<7> [287.279882] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [287.280118] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1024)
<7> [287.280354] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 1344)
<7> [287.280598] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1024)
<7> [287.280835] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 1344)
<7> [287.281071] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1048)
<7> [287.281307] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 1184)
<7> [287.281558] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 768)
<7> [287.281794] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 768)
<7> [287.282030] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 771)
<7> [287.282265] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 777)
<7> [287.282508] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 806)
<7> [287.282744] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 806)
<7> [287.282979] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1024)
<7> [287.283215] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 1344)
<7> [287.283448] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1024)
<7> [287.283708] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 1344)
<7> [287.283958] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1048)
<7> [287.284187] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 1184)
<7> [287.284416] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 768)
<7> [287.284676] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 768)
<7> [287.284924] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 771)
<7> [287.285154] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 777)
<7> [287.285382] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 806)
<7> [287.285642] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 806)
<7> [287.285898] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [287.286134] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)
<7> [287.286369] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)
<7> [287.286616] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24)
<7> [287.286870] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 64800)
<7> [287.287111] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 64800)
<7> [287.287347] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:66:pipe B] fastset requirement not met in port_clock (expected 0, found 64800)
<7> [287.287608] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:66:pipe B] fastset requirement not met, forcing full modeset
<7> [287.287895] i915 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [i915]] [PLANE:50:primary B] min cdclk (64800 kHz) > [CRTC:66:pipe B] min cdclk (0 kHz)
<7> [287.288121] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 400000 kHz, actual 400000 kHz
<7> [287.288349] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [287.288616] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:66:pipe B] allocated PCH DPLL A
<7> [287.288869] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:66:pipe B] reserving PCH DPLL A
<7> [287.289098] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:66:pipe B] enable: yes [modeset]
<7> [287.289328] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: ANALOG (0x2), output format: RGB, sink format: RGB
<7> [287.289590] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0
<7> [287.289838] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [287.290066] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [287.290294] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [287.290545] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [287.290793] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fdi: lanes: 1; data_m: 6039797, data_n: 8388608, link_m: 125829, link_n: 524288, tu: 64
<7> [287.291022] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0
<7> [287.291251] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1
<7> [287.291513] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0
<7> [287.291752] 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> [287.291982] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: -1, vmax vblank: -2, vmin vtotal: 1, vmax vtotal: 0
<7> [287.292210] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1024x768": 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa
<7> [287.292470] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1024x768": 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa
<7> [287.292736] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=64800, hd=1024 hb=1024-1344 hs=1048-1184 ht=1344, vd=768 vb=768-806 vs=771-777 vt=806, flags=0xa
<7> [287.292966] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1024x768": 60 64800 1024 1048 1184 1344 768 771 777 806 0x40 0xa
<7> [287.293193] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=64800, hd=1024 hb=1024-1344 hs=1048-1184 ht=1344, vd=768 vb=768-806 vs=771-777 vt=806, flags=0xa
<7> [287.293479] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 64800, pipe src: 1024x768+0+0, pixel rate 64800
<7> [287.293737] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0
<7> [287.293975] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [287.294208] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [287.294464] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [287.294464] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on
<7> [287.294701] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [287.294935] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [287.295170] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [287.295426] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [287.295661] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [287.295896] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [287.296131] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:50:primary B] fb: [FB:85] 1024x768 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes
<7> [287.296374] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [287.296609] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1024.000000x768.000000+0.000000+0.000000 dst: 1024x768+0+0
<7> [287.296902] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on
<7> [287.297144] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:68:CRT]
<7> [287.297388] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:69:HDMI D]
<7> [287.297616] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:77:DP D]
<7> [287.298417] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B
<7> [287.299503] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100
<7> [287.299735] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done.
<7> [287.300630] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x200
<7> [287.300856] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done.
<7> [287.301078] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done.
<7> [287.301342] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PCH DPLL A (active 0x2, on? 0) for [CRTC:66:pipe B]
<7> [287.301578] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PCH DPLL A
<7> [287.353519] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:67:VGA-1]
<7> [287.354118] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:66:pipe B]
<6> [295.242482] [IGT] kms_flip: finished subtest B-VGA1, FAIL
Created at 2025-08-27 06:40:37