Results for igt@kms_flip@plain-flip-ts-check@b-vga1

Machine description: shard-snb6

Result: Fail

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

DetailValue
Duration 8.95 seconds
Hostname 
shard-snb6
Igt-Version 
IGT-Version: 2.0-gfda353526 (x86_64) (Linux: 6.14.0-rc6-CI_DRM_16292-gdeccd667e475+ 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 16860.4us +- 6.021us accuracy 0.11%
vblank interval differs from modeline! expected 16665.6us, measured 16860us +- 6.021us, difference 194.8us (32.4 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1831 run_test()
  #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-VGA1: FAIL (8.951s)
Err 
Starting dynamic subtest: B-VGA1
(kms_flip:2625) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2625) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-VGA1 failed.
**** DEBUG ****
(kms_flip:2625) DEBUG: flip ts/seq: last 213.989777/1932, current 214.006577/1933: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.006577
last_received_ts = 214.006042
last_seq = 1933
current_ts = 214.023376
current_received_ts = 214.022812
current_seq = 1934
count = 190
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.006577/1933, current 214.023376/1934: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.023376
last_received_ts = 214.022812
last_seq = 1934
current_ts = 214.040176
current_received_ts = 214.039627
current_seq = 1935
count = 191
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.023376/1934, current 214.040176/1935: elapsed=16805.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.040176
last_received_ts = 214.039627
last_seq = 1935
current_ts = 214.056992
current_received_ts = 214.056427
current_seq = 1936
count = 192
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.040176/1935, current 214.056992/1936: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.056992
last_received_ts = 214.056427
last_seq = 1936
current_ts = 214.073792
current_received_ts = 214.073227
current_seq = 1937
count = 193
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.056992/1936, current 214.073792/1937: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.073792
last_received_ts = 214.073227
last_seq = 1937
current_ts = 214.090591
current_received_ts = 214.090057
current_seq = 1938
count = 194
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.073792/1937, current 214.090591/1938: elapsed=16801.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.090591
last_received_ts = 214.090057
last_seq = 1938
current_ts = 214.107407
current_received_ts = 214.106842
current_seq = 1939
count = 195
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.090591/1938, current 214.107407/1939: elapsed=16808.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.107407
last_received_ts = 214.106842
last_seq = 1939
current_ts = 214.124207
current_received_ts = 214.123642
current_seq = 1940
count = 196
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.107407/1939, current 214.124207/1940: elapsed=16803.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.124207
last_received_ts = 214.123642
last_seq = 1940
current_ts = 214.141006
current_received_ts = 214.140457
current_seq = 1941
count = 197
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.124207/1940, current 214.141006/1941: elapsed=16805.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.141006
last_received_ts = 214.140457
last_seq = 1941
current_ts = 214.157806
current_received_ts = 214.157257
current_seq = 1942
count = 198
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.141006/1941, current 214.157806/1942: elapsed=16803.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.157806
last_received_ts = 214.157257
last_seq = 1942
current_ts = 214.174622
current_received_ts = 214.174072
current_seq = 1943
count = 199
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.157806/1942, current 214.174622/1943: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.174622
last_received_ts = 214.174072
last_seq = 1943
current_ts = 214.191422
current_received_ts = 214.190826
current_seq = 1944
count = 200
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.174622/1943, current 214.191422/1944: elapsed=16800.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.191422
last_received_ts = 214.190826
last_seq = 1944
current_ts = 214.208221
current_received_ts = 214.207657
current_seq = 1945
count = 201
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.191422/1944, current 214.208221/1945: elapsed=16810.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.208221
last_received_ts = 214.207657
last_seq = 1945
current_ts = 214.225021
current_received_ts = 214.224426
current_seq = 1946
count = 202
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.208221/1945, current 214.225021/1946: elapsed=16799.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.225021
last_received_ts = 214.224426
last_seq = 1946
current_ts = 214.241837
current_received_ts = 214.241272
current_seq = 1947
count = 203
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.225021/1946, current 214.241837/1947: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.241837
last_received_ts = 214.241272
last_seq = 1947
current_ts = 214.258636
current_received_ts = 214.258087
current_seq = 1948
count = 204
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.241837/1947, current 214.258636/1948: elapsed=16808.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.258636
last_received_ts = 214.258087
last_seq = 1948
current_ts = 214.275436
current_received_ts = 214.274887
current_seq = 1949
count = 205
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.258636/1948, current 214.275436/1949: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.275436
last_received_ts = 214.274887
last_seq = 1949
current_ts = 214.292252
current_received_ts = 214.291672
current_seq = 1950
count = 206
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.275436/1949, current 214.292252/1950: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.292252
last_received_ts = 214.291672
last_seq = 1950
current_ts = 214.309052
current_received_ts = 214.308487
current_seq = 1951
count = 207
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.292252/1950, current 214.309052/1951: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.309052
last_received_ts = 214.308487
last_seq = 1951
current_ts = 214.325851
current_received_ts = 214.325287
current_seq = 1952
count = 208
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.309052/1951, current 214.325851/1952: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.325851
last_received_ts = 214.325287
last_seq = 1952
current_ts = 214.342651
current_received_ts = 214.342102
current_seq = 1953
count = 209
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.325851/1952, current 214.342651/1953: elapsed=16805.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.342651
last_received_ts = 214.342102
last_seq = 1953
current_ts = 214.359467
current_received_ts = 214.358902
current_seq = 1954
count = 210
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.342651/1953, current 214.359467/1954: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.359467
last_received_ts = 214.358902
last_seq = 1954
current_ts = 214.376266
current_received_ts = 214.375702
current_seq = 1955
count = 211
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.359467/1954, current 214.376266/1955: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.376266
last_received_ts = 214.375702
last_seq = 1955
current_ts = 214.393066
current_received_ts = 214.392487
current_seq = 1956
count = 212
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.376266/1955, current 214.393066/1956: elapsed=16805.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.393066
last_received_ts = 214.392487
last_seq = 1956
current_ts = 214.409882
current_received_ts = 214.409302
current_seq = 1957
count = 213
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.393066/1956, current 214.409882/1957: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.409882
last_received_ts = 214.409302
last_seq = 1957
current_ts = 214.426682
current_received_ts = 214.426117
current_seq = 1958
count = 214
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.409882/1957, current 214.426682/1958: elapsed=16803.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.426682
last_received_ts = 214.426117
last_seq = 1958
current_ts = 214.443481
current_received_ts = 214.442886
current_seq = 1959
count = 215
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.426682/1958, current 214.443481/1959: elapsed=16807.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.443481
last_received_ts = 214.442886
last_seq = 1959
current_ts = 214.460281
current_received_ts = 214.459717
current_seq = 1960
count = 216
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.443481/1959, current 214.460281/1960: elapsed=16801.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.460281
last_received_ts = 214.459717
last_seq = 1960
current_ts = 214.477097
current_received_ts = 214.476517
current_seq = 1961
count = 217
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.460281/1960, current 214.477097/1961: elapsed=16805.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.477097
last_received_ts = 214.476517
last_seq = 1961
current_ts = 214.493896
current_received_ts = 214.493332
current_seq = 1962
count = 218
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.477097/1961, current 214.493896/1962: elapsed=16805.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.493896
last_received_ts = 214.493332
last_seq = 1962
current_ts = 214.510712
current_received_ts = 214.510117
current_seq = 1963
count = 219
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.493896/1962, current 214.510712/1963: elapsed=16811.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.510712
last_received_ts = 214.510117
last_seq = 1963
current_ts = 214.527496
current_received_ts = 214.526947
current_seq = 1964
count = 220
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.510712/1963, current 214.527496/1964: elapsed=16796.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.527496
last_received_ts = 214.526947
last_seq = 1964
current_ts = 214.544312
current_received_ts = 214.543747
current_seq = 1965
count = 221
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.527496/1964, current 214.544312/1965: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.544312
last_received_ts = 214.543747
last_seq = 1965
current_ts = 214.561111
current_received_ts = 214.560516
current_seq = 1966
count = 222
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.544312/1965, current 214.561111/1966: elapsed=16806.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.561111
last_received_ts = 214.560516
last_seq = 1966
current_ts = 214.577911
current_received_ts = 214.577332
current_seq = 1967
count = 223
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.561111/1966, current 214.577911/1967: elapsed=16803.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.577911
last_received_ts = 214.577332
last_seq = 1967
current_ts = 214.594727
current_received_ts = 214.594147
current_seq = 1968
count = 224
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.577911/1967, current 214.594727/1968: elapsed=16803.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.594727
last_received_ts = 214.594147
last_seq = 1968
current_ts = 214.611526
current_received_ts = 214.610931
current_seq = 1969
count = 225
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.594727/1968, current 214.611526/1969: elapsed=16805.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.611526
last_received_ts = 214.610931
last_seq = 1969
current_ts = 214.628342
current_received_ts = 214.627701
current_seq = 1970
count = 226
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.611526/1969, current 214.628342/1970: elapsed=16813.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.628342
last_received_ts = 214.627701
last_seq = 1970
current_ts = 214.645126
current_received_ts = 214.644562
current_seq = 1971
count = 227
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.628342/1970, current 214.645126/1971: elapsed=16795.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.645126
last_received_ts = 214.644562
last_seq = 1971
current_ts = 214.661942
current_received_ts = 214.661346
current_seq = 1972
count = 228
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.645126/1971, current 214.661942/1972: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.661942
last_received_ts = 214.661346
last_seq = 1972
current_ts = 214.678741
current_received_ts = 214.678116
current_seq = 1973
count = 229
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.661942/1972, current 214.678741/1973: elapsed=16808.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.678741
last_received_ts = 214.678116
last_seq = 1973
current_ts = 214.695541
current_received_ts = 214.694931
current_seq = 1974
count = 230
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.678741/1973, current 214.695541/1974: elapsed=16791.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.695541
last_received_ts = 214.694931
last_seq = 1974
current_ts = 214.712341
current_received_ts = 214.711761
current_seq = 1975
count = 231
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.695541/1974, current 214.712341/1975: elapsed=16813.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.712341
last_received_ts = 214.711761
last_seq = 1975
current_ts = 214.729156
current_received_ts = 214.728577
current_seq = 1976
count = 232
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.712341/1975, current 214.729156/1976: elapsed=16805.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.729156
last_received_ts = 214.728577
last_seq = 1976
current_ts = 214.745956
current_received_ts = 214.745377
current_seq = 1977
count = 233
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.729156/1976, current 214.745956/1977: elapsed=16801.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.745956
last_received_ts = 214.745377
last_seq = 1977
current_ts = 214.762756
current_received_ts = 214.762192
current_seq = 1978
count = 234
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.745956/1977, current 214.762756/1978: elapsed=16806.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.762756
last_received_ts = 214.762192
last_seq = 1978
current_ts = 214.779556
current_received_ts = 214.778992
current_seq = 1979
count = 235
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.762756/1978, current 214.779556/1979: elapsed=16799.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.779556
last_received_ts = 214.778992
last_seq = 1979
current_ts = 214.796356
current_received_ts = 214.795776
current_seq = 1980
count = 236
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.779556/1979, current 214.796356/1980: elapsed=16803.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.796356
last_received_ts = 214.795776
last_seq = 1980
current_ts = 214.813171
current_received_ts = 214.812607
current_seq = 1981
count = 237
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.796356/1980, current 214.813171/1981: elapsed=16806.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.813171
last_received_ts = 214.812607
last_seq = 1981
current_ts = 214.829971
current_received_ts = 214.829407
current_seq = 1982
count = 238
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.813171/1981, current 214.829971/1982: elapsed=16809.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.829971
last_received_ts = 214.829407
last_seq = 1982
current_ts = 214.846786
current_received_ts = 214.846222
current_seq = 1983
count = 239
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.829971/1982, current 214.846786/1983: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.846786
last_received_ts = 214.846222
last_seq = 1983
current_ts = 214.863586
current_received_ts = 214.863037
current_seq = 1984
count = 240
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.846786/1983, current 214.863586/1984: elapsed=16807.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.863586
last_received_ts = 214.863037
last_seq = 1984
current_ts = 214.880386
current_received_ts = 214.879791
current_seq = 1985
count = 241
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.863586/1984, current 214.880386/1985: elapsed=16802.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.880386
last_received_ts = 214.879791
last_seq = 1985
current_ts = 214.897202
current_received_ts = 214.896637
current_seq = 1986
count = 242
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.880386/1985, current 214.897202/1986: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.897202
last_received_ts = 214.896637
last_seq = 1986
current_ts = 214.914001
current_received_ts = 214.913422
current_seq = 1987
count = 243
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.897202/1986, current 214.914001/1987: elapsed=16806.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.914001
last_received_ts = 214.913422
last_seq = 1987
current_ts = 214.930801
current_received_ts = 214.930222
current_seq = 1988
count = 244
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.914001/1987, current 214.930801/1988: elapsed=16802.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.930801
last_received_ts = 214.930222
last_seq = 1988
current_ts = 214.947601
current_received_ts = 214.947052
current_seq = 1989
count = 245
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.930801/1988, current 214.947601/1989: elapsed=16805.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.947601
last_received_ts = 214.947052
last_seq = 1989
current_ts = 214.964417
current_received_ts = 214.963837
current_seq = 1990
count = 246
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.947601/1989, current 214.964417/1990: elapsed=16803.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.964417
last_received_ts = 214.963837
last_seq = 1990
current_ts = 214.981216
current_received_ts = 214.980637
current_seq = 1991
count = 247
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.964417/1990, current 214.981216/1991: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.981216
last_received_ts = 214.980637
last_seq = 1991
current_ts = 214.998016
current_received_ts = 214.997437
current_seq = 1992
count = 248
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.981216/1991, current 214.998016/1992: elapsed=16796.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 214.998016
last_received_ts = 214.997437
last_seq = 1992
current_ts = 215.014801
current_received_ts = 215.014175
current_seq = 1993
count = 249
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 214.998016/1992, current 215.014801/1993: elapsed=16789.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.014801
last_received_ts = 215.014175
last_seq = 1993
current_ts = 215.031601
current_received_ts = 215.031006
current_seq = 1994
count = 250
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.014801/1993, current 215.031601/1994: elapsed=16795.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.031601
last_received_ts = 215.031006
last_seq = 1994
current_ts = 215.048401
current_received_ts = 215.047821
current_seq = 1995
count = 251
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.031601/1994, current 215.048401/1995: elapsed=16809.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.048401
last_received_ts = 215.047821
last_seq = 1995
current_ts = 215.065186
current_received_ts = 215.064590
current_seq = 1996
count = 252
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.048401/1995, current 215.065186/1996: elapsed=16784.0us expected=16860.4us +- 84.3us, error 0.5%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.065186
last_received_ts = 215.064590
last_seq = 1996
current_ts = 215.081985
current_received_ts = 215.081406
current_seq = 1997
count = 253
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.065186/1996, current 215.081985/1997: elapsed=16794.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.081985
last_received_ts = 215.081406
last_seq = 1997
current_ts = 215.098770
current_received_ts = 215.098221
current_seq = 1998
count = 254
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.081985/1997, current 215.098770/1998: elapsed=16794.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.098770
last_received_ts = 215.098221
last_seq = 1998
current_ts = 215.115570
current_received_ts = 215.114975
current_seq = 1999
count = 255
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.098770/1998, current 215.115570/1999: elapsed=16795.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.115570
last_received_ts = 215.114975
last_seq = 1999
current_ts = 215.132355
current_received_ts = 215.131775
current_seq = 2000
count = 256
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.115570/1999, current 215.132355/2000: elapsed=16790.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.132355
last_received_ts = 215.131775
last_seq = 2000
current_ts = 215.149155
current_received_ts = 215.148590
current_seq = 2001
count = 257
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.132355/2000, current 215.149155/2001: elapsed=16799.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.149155
last_received_ts = 215.148590
last_seq = 2001
current_ts = 215.165955
current_received_ts = 215.165359
current_seq = 2002
count = 258
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.149155/2001, current 215.165955/2002: elapsed=16794.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.165955
last_received_ts = 215.165359
last_seq = 2002
current_ts = 215.182755
current_received_ts = 215.182159
current_seq = 2003
count = 259
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.165955/2002, current 215.182755/2003: elapsed=16794.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.182755
last_received_ts = 215.182159
last_seq = 2003
current_ts = 215.199539
current_received_ts = 215.198959
current_seq = 2004
count = 260
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.182755/2003, current 215.199539/2004: elapsed=16794.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.199539
last_received_ts = 215.198959
last_seq = 2004
current_ts = 215.216339
current_received_ts = 215.215652
current_seq = 2005
count = 261
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.199539/2004, current 215.216339/2005: elapsed=16801.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.216339
last_received_ts = 215.215652
last_seq = 2005
current_ts = 215.233124
current_received_ts = 215.232544
current_seq = 2006
count = 262
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.216339/2005, current 215.233124/2006: elapsed=16788.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.233124
last_received_ts = 215.232544
last_seq = 2006
current_ts = 215.249924
current_received_ts = 215.249359
current_seq = 2007
count = 263
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.233124/2006, current 215.249924/2007: elapsed=16792.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.249924
last_received_ts = 215.249359
last_seq = 2007
current_ts = 215.266708
current_received_ts = 215.266113
current_seq = 2008
count = 264
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.249924/2007, current 215.266708/2008: elapsed=16790.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.266708
last_received_ts = 215.266113
last_seq = 2008
current_ts = 215.283508
current_received_ts = 215.282944
current_seq = 2009
count = 265
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.266708/2008, current 215.283508/2009: elapsed=16803.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.283508
last_received_ts = 215.282944
last_seq = 2009
current_ts = 215.300308
current_received_ts = 215.299744
current_seq = 2010
count = 266
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.283508/2009, current 215.300308/2010: elapsed=16792.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.300308
last_received_ts = 215.299744
last_seq = 2010
current_ts = 215.317108
current_received_ts = 215.316513
current_seq = 2011
count = 267
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.300308/2010, current 215.317108/2011: elapsed=16802.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.317108
last_received_ts = 215.316513
last_seq = 2011
current_ts = 215.333893
current_received_ts = 215.333298
current_seq = 2012
count = 268
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.317108/2011, current 215.333893/2012: elapsed=16786.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.333893
last_received_ts = 215.333298
last_seq = 2012
current_ts = 215.350693
current_received_ts = 215.350128
current_seq = 2013
count = 269
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.333893/2012, current 215.350693/2013: elapsed=16796.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.350693
last_received_ts = 215.350128
last_seq = 2013
current_ts = 215.367477
current_received_ts = 215.366882
current_seq = 2014
count = 270
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.350693/2013, current 215.367477/2014: elapsed=16791.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.367477
last_received_ts = 215.366882
last_seq = 2014
current_ts = 215.384277
current_received_ts = 215.383698
current_seq = 2015
count = 271
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.367477/2014, current 215.384277/2015: elapsed=16798.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.384277
last_received_ts = 215.383698
last_seq = 2015
current_ts = 215.401077
current_received_ts = 215.400497
current_seq = 2016
count = 272
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.384277/2015, current 215.401077/2016: elapsed=16793.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.401077
last_received_ts = 215.400497
last_seq = 2016
current_ts = 215.417862
current_received_ts = 215.417267
current_seq = 2017
count = 273
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.401077/2016, current 215.417862/2017: elapsed=16792.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.417862
last_received_ts = 215.417267
last_seq = 2017
current_ts = 215.434662
current_received_ts = 215.434128
current_seq = 2018
count = 274
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.417862/2017, current 215.434662/2018: elapsed=16796.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.434662
last_received_ts = 215.434128
last_seq = 2018
current_ts = 215.451462
current_received_ts = 215.450897
current_seq = 2019
count = 275
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.434662/2018, current 215.451462/2019: elapsed=16795.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.451462
last_received_ts = 215.450897
last_seq = 2019
current_ts = 215.468246
current_received_ts = 215.467651
current_seq = 2020
count = 276
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.451462/2019, current 215.468246/2020: elapsed=16795.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.468246
last_received_ts = 215.467651
last_seq = 2020
current_ts = 215.485046
current_received_ts = 215.484467
current_seq = 2021
count = 277
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.468246/2020, current 215.485046/2021: elapsed=16794.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.485046
last_received_ts = 215.484467
last_seq = 2021
current_ts = 215.501846
current_received_ts = 215.501282
current_seq = 2022
count = 278
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.485046/2021, current 215.501846/2022: elapsed=16794.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.501846
last_received_ts = 215.501282
last_seq = 2022
current_ts = 215.518631
current_received_ts = 215.518158
current_seq = 2023
count = 279
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.501846/2022, current 215.518631/2023: elapsed=16794.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.518631
last_received_ts = 215.518158
last_seq = 2023
current_ts = 215.535431
current_received_ts = 215.534836
current_seq = 2024
count = 280
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.518631/2023, current 215.535431/2024: elapsed=16793.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.535431
last_received_ts = 215.534836
last_seq = 2024
current_ts = 215.552216
current_received_ts = 215.551651
current_seq = 2025
count = 281
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.535431/2024, current 215.552216/2025: elapsed=16795.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.552216
last_received_ts = 215.551651
last_seq = 2025
current_ts = 215.569016
current_received_ts = 215.568436
current_seq = 2026
count = 282
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.552216/2025, current 215.569016/2026: elapsed=16794.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.569016
last_received_ts = 215.568436
last_seq = 2026
current_ts = 215.585815
current_received_ts = 215.585236
current_seq = 2027
count = 283
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.569016/2026, current 215.585815/2027: elapsed=16795.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.585815
last_received_ts = 215.585236
last_seq = 2027
current_ts = 215.602600
current_received_ts = 215.602036
current_seq = 2028
count = 284
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.585815/2027, current 215.602600/2028: elapsed=16794.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.602600
last_received_ts = 215.602036
last_seq = 2028
current_ts = 215.619400
current_received_ts = 215.618820
current_seq = 2029
count = 285
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.602600/2028, current 215.619400/2029: elapsed=16794.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.619400
last_received_ts = 215.618820
last_seq = 2029
current_ts = 215.636200
current_received_ts = 215.635620
current_seq = 2030
count = 286
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.619400/2029, current 215.636200/2030: elapsed=16795.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.636200
last_received_ts = 215.635620
last_seq = 2030
current_ts = 215.652985
current_received_ts = 215.652451
current_seq = 2031
count = 287
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.636200/2030, current 215.652985/2031: elapsed=16796.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.652985
last_received_ts = 215.652451
last_seq = 2031
current_ts = 215.669785
current_received_ts = 215.669235
current_seq = 2032
count = 288
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.652985/2031, current 215.669785/2032: elapsed=16792.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.669785
last_received_ts = 215.669235
last_seq = 2032
current_ts = 215.686569
current_received_ts = 215.686035
current_seq = 2033
count = 289
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.669785/2032, current 215.686569/2033: elapsed=16792.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.686569
last_received_ts = 215.686035
last_seq = 2033
current_ts = 215.703354
current_received_ts = 215.702759
current_seq = 2034
count = 290
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.686569/2033, current 215.703354/2034: elapsed=16787.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.703354
last_received_ts = 215.702759
last_seq = 2034
current_ts = 215.720154
current_received_ts = 215.719543
current_seq = 2035
count = 291
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.703354/2034, current 215.720154/2035: elapsed=16795.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.720154
last_received_ts = 215.719543
last_seq = 2035
current_ts = 215.736954
current_received_ts = 215.736404
current_seq = 2036
count = 292
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.720154/2035, current 215.736954/2036: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.736954
last_received_ts = 215.736404
last_seq = 2036
current_ts = 215.753754
current_received_ts = 215.753204
current_seq = 2037
count = 293
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.736954/2036, current 215.753754/2037: elapsed=16795.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.753754
last_received_ts = 215.753204
last_seq = 2037
current_ts = 215.770554
current_received_ts = 215.769897
current_seq = 2038
count = 294
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.753754/2037, current 215.770554/2038: elapsed=16793.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.770554
last_received_ts = 215.769897
last_seq = 2038
current_ts = 215.787338
current_received_ts = 215.786789
current_seq = 2039
count = 295
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.770554/2038, current 215.787338/2039: elapsed=16789.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.787338
last_received_ts = 215.786789
last_seq = 2039
current_ts = 215.804138
current_received_ts = 215.803589
current_seq = 2040
count = 296
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.787338/2039, current 215.804138/2040: elapsed=16800.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.804138
last_received_ts = 215.803589
last_seq = 2040
current_ts = 215.820938
current_received_ts = 215.820282
current_seq = 2041
count = 297
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.804138/2040, current 215.820938/2041: elapsed=16803.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.820938
last_received_ts = 215.820282
last_seq = 2041
current_ts = 215.837723
current_received_ts = 215.837158
current_seq = 2042
count = 298
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.820938/2041, current 215.837723/2042: elapsed=16786.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.837723
last_received_ts = 215.837158
last_seq = 2042
current_ts = 215.854523
current_received_ts = 215.853943
current_seq = 2043
count = 299
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.837723/2042, current 215.854523/2043: elapsed=16793.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.854523
last_received_ts = 215.853943
last_seq = 2043
current_ts = 215.871307
current_received_ts = 215.870743
current_seq = 2044
count = 300
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.854523/2043, current 215.871307/2044: elapsed=16793.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.871307
last_received_ts = 215.870743
last_seq = 2044
current_ts = 215.888107
current_received_ts = 215.887558
current_seq = 2045
count = 301
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.871307/2044, current 215.888107/2045: elapsed=16796.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.888107
last_received_ts = 215.887558
last_seq = 2045
current_ts = 215.904907
current_received_ts = 215.904358
current_seq = 2046
count = 302
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.888107/2045, current 215.904907/2046: elapsed=16795.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.904907
last_received_ts = 215.904358
last_seq = 2046
current_ts = 215.921707
current_received_ts = 215.921082
current_seq = 2047
count = 303
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.904907/2046, current 215.921707/2047: elapsed=16804.0us expected=16860.4us +- 84.3us, error 0.3%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.921707
last_received_ts = 215.921082
last_seq = 2047
current_ts = 215.938492
current_received_ts = 215.937912
current_seq = 2048
count = 304
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.921707/2047, current 215.938492/2048: elapsed=16783.0us expected=16860.4us +- 84.3us, error 0.5%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.938492
last_received_ts = 215.937912
last_seq = 2048
current_ts = 215.955276
current_received_ts = 215.954742
current_seq = 2049
count = 305
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.938492/2048, current 215.955276/2049: elapsed=16795.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.955276
last_received_ts = 215.954742
last_seq = 2049
current_ts = 215.972076
current_received_ts = 215.971451
current_seq = 2050
count = 306
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.955276/2049, current 215.972076/2050: elapsed=16791.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.972076
last_received_ts = 215.971451
last_seq = 2050
current_ts = 215.988861
current_received_ts = 215.988297
current_seq = 2051
count = 307
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.972076/2050, current 215.988861/2051: elapsed=16788.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 215.988861
last_received_ts = 215.988297
last_seq = 2051
current_ts = 216.005661
current_received_ts = 216.005142
current_seq = 2052
count = 308
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 215.988861/2051, current 216.005661/2052: elapsed=16792.0us expected=16860.4us +- 84.3us, error 0.4%
(kms_flip:2625) DEBUG: name = flip
last_ts = 216.005661
last_received_ts = 216.005142
last_seq = 2052
current_ts = 216.022430
current_received_ts = 216.021820
current_seq = 2053
count = 309
seq_step = 1
(kms_flip:2625) DEBUG: flip ts/seq: last 216.005661/2052, current 216.022430/2053: elapsed=16776.0us expected=16860.4us +- 84.3us, error 0.5%
(kms_flip:2625) DEBUG: inconsistent flip ts/seq: last 216.005661/2052, current 216.022430/2053: elapsed=16776.0us expected=16860.4us
(kms_flip:2625) DEBUG: expected 0, counted 309, encoder type 1
(kms_flip:2625) DEBUG: dropped frames, expected 0, counted 309, encoder type 1
(kms_flip:2625) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2625) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2625) igt_core-INFO: Stack trace:
(kms_flip:2625) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2625) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2625) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2625) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2625) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2625) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2625) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2625) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-VGA1: FAIL (8.951s)
Dmesg
<6> [209.941819] [IGT] kms_flip: starting dynamic subtest B-VGA1
<7> [209.942334] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:84]
<7> [209.942432] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:85]
<7> [209.979766] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:47:pipe A]
<7> [209.979993] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.enable (expected yes, found no)
<7> [209.980497] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.active (expected yes, found no)
<7> [209.980949] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1)
<7> [209.981345] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in has_pch_encoder (expected yes, found no)
<7> [209.981872] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in fdi_lanes (expected 1, found 0)
<7> [209.982325] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47: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> [209.982782] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in output_types (expected 0x00000002, found 0x00000000)
<7> [209.983142] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [209.983566] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1024, found 0)
<7> [209.984026] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 1344, found 0)
<7> [209.984479] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1024, found 0)
<7> [209.984749] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 1344, found 0)
<7> [209.984972] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1048, found 0)
<7> [209.985186] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 1184, found 0)
<7> [209.985397] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 768, found 0)
<7> [209.985646] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 768, found 0)
<7> [209.985864] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 771, found 0)
<7> [209.986075] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 777, found 0)
<7> [209.986292] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 806, found 0)
<7> [209.986531] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 806, found 0)
<7> [209.986837] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1024, found 0)
<7> [209.987048] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 1344, found 0)
<7> [209.987259] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1024, found 0)
<7> [209.987539] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 1344, found 0)
<7> [209.987746] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1048, found 0)
<7> [209.987959] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 1184, found 0)
<7> [209.988175] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 768, found 0)
<7> [209.988392] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 768, found 0)
<7> [209.988635] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 771, found 0)
<7> [209.988840] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 777, found 0)
<7> [209.989072] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 806, found 0)
<7> [209.989277] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 806, found 0)
<7> [209.989532] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [209.989758] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)
<7> [209.990014] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)
<7> [209.990239] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0)
<7> [209.990476] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 64800, found 0)
<7> [209.990698] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 64800, found 0)
<7> [209.990925] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in port_clock (expected 64800, found 0)
<7> [209.991140] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:47:pipe A] fastset requirement not met, forcing full modeset
<7> [209.991346] i915 0000:00:02.0: [drm:intel_unreference_shared_dpll_crtc [i915]] [CRTC:47:pipe A] releasing PCH DPLL A
<7> [209.991665] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 400000 kHz, actual 400000 kHz
<7> [209.991910] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [209.992148] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:47:pipe A] enable: no [modeset]
<7> [209.992355] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:32:primary A] fb: [NOFB], visible: no
<7> [209.992789] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A
<7> [210.007590] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found
<7> [210.008035] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found
<7> [210.008501] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found
<7> [210.024847] i915 0000:00:02.0: [drm:intel_disable_shared_dpll [i915]] disable PCH DPLL A (active 0x1, on? 1) for [CRTC:47:pipe A]
<7> [210.025337] i915 0000:00:02.0: [drm:intel_disable_shared_dpll [i915]] disabling PCH DPLL A
<7> [210.025994] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:65:CRT]
<7> [210.026462] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:66:HDMI D]
<7> [210.026875] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:DP D]
<7> [210.027316] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:64:VGA-1]
<7> [210.027823] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:47:pipe A]
<7> [210.028391] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:63:pipe B]
<7> [210.028492] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:63:pipe B]
<7> [210.028519] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:64:VGA-1]
<7> [210.028602] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:64:VGA-1] Limiting display bpp to 24 (EDID bpp 0, max requested bpp 0, max platform bpp 36)
<7> [210.028830] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:63:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0
<7> [210.029043] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe B, lanes 1
<7> [210.029259] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.enable (expected no, found yes)
<7> [210.029471] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.active (expected no, found yes)
<7> [210.029682] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)
<7> [210.029894] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in has_pch_encoder (expected no, found yes)
<7> [210.030113] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in fdi_lanes (expected 0, found 1)
<7> [210.030324] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63: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> [210.030554] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000002)
<7> [210.030790] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [210.031029] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1024)
<7> [210.031253] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 1344)
<7> [210.031465] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1024)
<7> [210.031686] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 1344)
<7> [210.031892] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1048)
<7> [210.032129] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 1184)
<7> [210.032359] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 768)
<7> [210.032565] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 768)
<7> [210.032771] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 771)
<7> [210.032976] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 777)
<7> [210.033205] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 806)
<7> [210.033427] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 806)
<7> [210.033632] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1024)
<7> [210.033836] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 1344)
<7> [210.034041] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1024)
<7> [210.034270] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 1344)
<7> [210.034491] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1048)
<7> [210.034697] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 1184)
<7> [210.034902] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 768)
<7> [210.035139] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 768)
<7> [210.035354] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 771)
<7> [210.035560] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 777)
<7> [210.035765] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 806)
<7> [210.035970] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 806)
<7> [210.036200] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [210.036422] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)
<7> [210.036626] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)
<7> [210.036832] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in dpll_hw_state
<7> [210.037051] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:
<7> [210.037280] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0xc4040004, dpll_md: 0x0, fp0: 0x21006, fp1: 0x21006
<7> [210.037485] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:
<7> [210.037689] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [210.037893] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24)
<7> [210.038121] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 64800)
<7> [210.038343] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 64800)
<7> [210.038548] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in port_clock (expected 0, found 64800)
<7> [210.038753] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:63:pipe B] fastset requirement not met, forcing full modeset
<7> [210.039013] i915 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [i915]] [PLANE:48:primary B] min cdclk (64800 kHz) > [CRTC:63:pipe B] min cdclk (0 kHz)
<7> [210.039343] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 400000 kHz, actual 400000 kHz
<7> [210.039549] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [210.039762] i915 0000:00:02.0: [drm:intel_find_shared_dpll [i915]] [CRTC:63:pipe B] allocated PCH DPLL A
<7> [210.039975] i915 0000:00:02.0: [drm:intel_reference_shared_dpll_crtc [i915]] [CRTC:63:pipe B] reserving PCH DPLL A
<7> [210.040235] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:63:pipe B] enable: yes [modeset]
<7> [210.040465] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: ANALOG (0x2), output format: RGB, sink format: RGB
<7> [210.040670] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0
<7> [210.040902] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [210.041138] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [210.041380] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [210.041597] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [210.041815] 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> [210.042059] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0
<7> [210.042286] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1
<7> [210.042519] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0
<7> [210.042724] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0
<7> [210.042930] 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> [210.043196] 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> [210.043485] 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> [210.043698] 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> [210.043910] 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> [210.044174] 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> [210.044401] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 64800, pipe src: 1024x768+0+0, pixel rate 64800
<7> [210.044606] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0
<7> [210.044839] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [210.045088] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [210.045313] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [210.045518] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [210.045755] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [210.045981] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [210.046012] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on
<7> [210.046223] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [210.046464] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [210.046690] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [210.046895] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:48:primary B] fb: [FB:84] 1024x768 format = XR24 little-endian (0x34325258) modifier = 0x0, visible: yes
<7> [210.047161] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [210.047405] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1024.000000x768.000000+0.000000+0.000000 dst: 1024x768+0+0
<7> [210.048551] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on
<7> [210.048771] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:65:CRT]
<7> [210.049036] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:66:HDMI D]
<7> [210.049256] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:DP D]
<7> [210.050027] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B
<7> [210.051079] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100
<7> [210.051340] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done.
<7> [210.052216] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x200
<7> [210.052421] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done.
<7> [210.052628] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done.
<7> [210.052959] i915 0000:00:02.0: [drm:intel_enable_shared_dpll [i915]] enable PCH DPLL A (active 0x2, on? 0) for [CRTC:63:pipe B]
<7> [210.053198] i915 0000:00:02.0: [drm:intel_enable_shared_dpll [i915]] enabling PCH DPLL A
<7> [210.105046] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:64:VGA-1]
<7> [210.105629] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:63:pipe B]
<6> [218.893457] [IGT] kms_flip: finished subtest B-VGA1, FAIL
Created at 2025-03-15 13:05:42