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

Machine description: shard-snb7

Result: Fail

git-log-oneline i915_display_info21 igt_runner21 runtimes21 results21.json results21-i915-load.json i915_display_info_post_exec21 boot21 dmesg21

DetailValue
Duration 5.91 seconds
Hostname 
shard-snb7
Igt-Version 
IGT-Version: 2.0-gf05383af3 (x86_64) (Linux: 6.14.0-rc7-CI_DRM_16300-g74f632d1bd3b+ 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 17036.8us +- 3.000us accuracy 0.05%
vblank interval differs from modeline! expected 16665.6us, measured 17037us +- 3.000us, difference 371.2us (123.7 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 (5.910s)
Err 
Starting dynamic subtest: B-VGA1
(kms_flip:2600) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2600) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-VGA1 failed.
**** DEBUG ****
(kms_flip:2600) DEBUG: flip ts/seq: last 222.363983/2044, current 222.381012/2045: elapsed=17038.0us expected=17036.8us +- 85.2us, error 0.0%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.381012
last_received_ts = 222.380463
last_seq = 2045
current_ts = 222.398056
current_received_ts = 222.397507
current_seq = 2046
count = 21
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.381012/2045, current 222.398056/2046: elapsed=17036.0us expected=17036.8us +- 85.2us, error 0.0%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.398056
last_received_ts = 222.397507
last_seq = 2046
current_ts = 222.415054
current_received_ts = 222.414490
current_seq = 2047
count = 22
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.398056/2046, current 222.415054/2047: elapsed=17008.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.415054
last_received_ts = 222.414490
last_seq = 2047
current_ts = 222.432053
current_received_ts = 222.431488
current_seq = 2048
count = 23
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.415054/2047, current 222.432053/2048: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.432053
last_received_ts = 222.431488
last_seq = 2048
current_ts = 222.449051
current_received_ts = 222.448502
current_seq = 2049
count = 24
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.432053/2048, current 222.449051/2049: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.449051
last_received_ts = 222.448502
last_seq = 2049
current_ts = 222.466064
current_received_ts = 222.465454
current_seq = 2050
count = 25
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.449051/2049, current 222.466064/2050: elapsed=17000.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.466064
last_received_ts = 222.465454
last_seq = 2050
current_ts = 222.483047
current_received_ts = 222.482498
current_seq = 2051
count = 26
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.466064/2050, current 222.483047/2051: elapsed=16995.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.483047
last_received_ts = 222.482498
last_seq = 2051
current_ts = 222.500046
current_received_ts = 222.499496
current_seq = 2052
count = 27
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.483047/2051, current 222.500046/2052: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.500046
last_received_ts = 222.499496
last_seq = 2052
current_ts = 222.517044
current_received_ts = 222.516479
current_seq = 2053
count = 28
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.500046/2052, current 222.517044/2053: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.517044
last_received_ts = 222.516479
last_seq = 2053
current_ts = 222.534042
current_received_ts = 222.533478
current_seq = 2054
count = 29
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.517044/2053, current 222.534042/2054: elapsed=16997.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.534042
last_received_ts = 222.533478
last_seq = 2054
current_ts = 222.551041
current_received_ts = 222.550507
current_seq = 2055
count = 30
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.534042/2054, current 222.551041/2055: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.551041
last_received_ts = 222.550507
last_seq = 2055
current_ts = 222.568039
current_received_ts = 222.567474
current_seq = 2056
count = 31
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.551041/2055, current 222.568039/2056: elapsed=16994.0us expected=17036.8us +- 85.2us, error 0.3%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.568039
last_received_ts = 222.567474
last_seq = 2056
current_ts = 222.585037
current_received_ts = 222.584473
current_seq = 2057
count = 32
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.568039/2056, current 222.585037/2057: elapsed=17001.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.585037
last_received_ts = 222.584473
last_seq = 2057
current_ts = 222.602036
current_received_ts = 222.601471
current_seq = 2058
count = 33
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.585037/2057, current 222.602036/2058: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.602036
last_received_ts = 222.601471
last_seq = 2058
current_ts = 222.619034
current_received_ts = 222.618469
current_seq = 2059
count = 34
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.602036/2058, current 222.619034/2059: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.619034
last_received_ts = 222.618469
last_seq = 2059
current_ts = 222.636032
current_received_ts = 222.635468
current_seq = 2060
count = 35
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.619034/2059, current 222.636032/2060: elapsed=16999.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.636032
last_received_ts = 222.635468
last_seq = 2060
current_ts = 222.653030
current_received_ts = 222.652481
current_seq = 2061
count = 36
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.636032/2060, current 222.653030/2061: elapsed=16996.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.653030
last_received_ts = 222.652481
last_seq = 2061
current_ts = 222.670029
current_received_ts = 222.669479
current_seq = 2062
count = 37
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.653030/2061, current 222.670029/2062: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.670029
last_received_ts = 222.669479
last_seq = 2062
current_ts = 222.687027
current_received_ts = 222.686462
current_seq = 2063
count = 38
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.670029/2062, current 222.687027/2063: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.687027
last_received_ts = 222.686462
last_seq = 2063
current_ts = 222.704025
current_received_ts = 222.703461
current_seq = 2064
count = 39
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.687027/2063, current 222.704025/2064: elapsed=16997.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.704025
last_received_ts = 222.703461
last_seq = 2064
current_ts = 222.721024
current_received_ts = 222.720444
current_seq = 2065
count = 40
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.704025/2064, current 222.721024/2065: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.721024
last_received_ts = 222.720444
last_seq = 2065
current_ts = 222.738022
current_received_ts = 222.737442
current_seq = 2066
count = 41
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.721024/2065, current 222.738022/2066: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.738022
last_received_ts = 222.737442
last_seq = 2066
current_ts = 222.755020
current_received_ts = 222.754440
current_seq = 2067
count = 42
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.738022/2066, current 222.755020/2067: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.755020
last_received_ts = 222.754440
last_seq = 2067
current_ts = 222.772018
current_received_ts = 222.771439
current_seq = 2068
count = 43
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.755020/2067, current 222.772018/2068: elapsed=16997.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.772018
last_received_ts = 222.771439
last_seq = 2068
current_ts = 222.789017
current_received_ts = 222.788467
current_seq = 2069
count = 44
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.772018/2068, current 222.789017/2069: elapsed=17000.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.789017
last_received_ts = 222.788467
last_seq = 2069
current_ts = 222.806015
current_received_ts = 222.805466
current_seq = 2070
count = 45
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.789017/2069, current 222.806015/2070: elapsed=16996.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.806015
last_received_ts = 222.805466
last_seq = 2070
current_ts = 222.822998
current_received_ts = 222.822449
current_seq = 2071
count = 46
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.806015/2070, current 222.822998/2071: elapsed=16992.0us expected=17036.8us +- 85.2us, error 0.3%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.822998
last_received_ts = 222.822449
last_seq = 2071
current_ts = 222.840012
current_received_ts = 222.839462
current_seq = 2072
count = 47
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.822998/2071, current 222.840012/2072: elapsed=17004.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.840012
last_received_ts = 222.839462
last_seq = 2072
current_ts = 222.857010
current_received_ts = 222.856430
current_seq = 2073
count = 48
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.840012/2072, current 222.857010/2073: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.857010
last_received_ts = 222.856430
last_seq = 2073
current_ts = 222.873993
current_received_ts = 222.873398
current_seq = 2074
count = 49
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.857010/2073, current 222.873993/2074: elapsed=16997.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.873993
last_received_ts = 222.873398
last_seq = 2074
current_ts = 222.891006
current_received_ts = 222.890457
current_seq = 2075
count = 50
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.873993/2074, current 222.891006/2075: elapsed=16999.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.891006
last_received_ts = 222.890457
last_seq = 2075
current_ts = 222.907990
current_received_ts = 222.907425
current_seq = 2076
count = 51
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.891006/2075, current 222.907990/2076: elapsed=16997.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.907990
last_received_ts = 222.907425
last_seq = 2076
current_ts = 222.924988
current_received_ts = 222.924408
current_seq = 2077
count = 52
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.907990/2076, current 222.924988/2077: elapsed=16997.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.924988
last_received_ts = 222.924408
last_seq = 2077
current_ts = 222.941986
current_received_ts = 222.941422
current_seq = 2078
count = 53
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.924988/2077, current 222.941986/2078: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.941986
last_received_ts = 222.941422
last_seq = 2078
current_ts = 222.958984
current_received_ts = 222.958420
current_seq = 2079
count = 54
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.941986/2078, current 222.958984/2079: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.958984
last_received_ts = 222.958420
last_seq = 2079
current_ts = 222.975983
current_received_ts = 222.975433
current_seq = 2080
count = 55
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.958984/2079, current 222.975983/2080: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.975983
last_received_ts = 222.975433
last_seq = 2080
current_ts = 222.992981
current_received_ts = 222.992401
current_seq = 2081
count = 56
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.975983/2080, current 222.992981/2081: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 222.992981
last_received_ts = 222.992401
last_seq = 2081
current_ts = 223.009979
current_received_ts = 223.009354
current_seq = 2082
count = 57
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 222.992981/2081, current 223.009979/2082: elapsed=17001.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.009979
last_received_ts = 223.009354
last_seq = 2082
current_ts = 223.026978
current_received_ts = 223.026382
current_seq = 2083
count = 58
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.009979/2082, current 223.026978/2083: elapsed=16984.0us expected=17036.8us +- 85.2us, error 0.3%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.026978
last_received_ts = 223.026382
last_seq = 2083
current_ts = 223.043976
current_received_ts = 223.043411
current_seq = 2084
count = 59
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.026978/2083, current 223.043976/2084: elapsed=17007.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.043976
last_received_ts = 223.043411
last_seq = 2084
current_ts = 223.060974
current_received_ts = 223.060410
current_seq = 2085
count = 60
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.043976/2084, current 223.060974/2085: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.060974
last_received_ts = 223.060410
last_seq = 2085
current_ts = 223.077972
current_received_ts = 223.077408
current_seq = 2086
count = 61
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.060974/2085, current 223.077972/2086: elapsed=16996.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.077972
last_received_ts = 223.077408
last_seq = 2086
current_ts = 223.094971
current_received_ts = 223.094421
current_seq = 2087
count = 62
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.077972/2086, current 223.094971/2087: elapsed=17000.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.094971
last_received_ts = 223.094421
last_seq = 2087
current_ts = 223.111969
current_received_ts = 223.111420
current_seq = 2088
count = 63
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.094971/2087, current 223.111969/2088: elapsed=17000.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.111969
last_received_ts = 223.111420
last_seq = 2088
current_ts = 223.128952
current_received_ts = 223.128342
current_seq = 2089
count = 64
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.111969/2088, current 223.128952/2089: elapsed=16985.0us expected=17036.8us +- 85.2us, error 0.3%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.128952
last_received_ts = 223.128342
last_seq = 2089
current_ts = 223.145966
current_received_ts = 223.145401
current_seq = 2090
count = 65
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.128952/2089, current 223.145966/2090: elapsed=17008.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.145966
last_received_ts = 223.145401
last_seq = 2090
current_ts = 223.162964
current_received_ts = 223.162399
current_seq = 2091
count = 66
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.145966/2090, current 223.162964/2091: elapsed=16997.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.162964
last_received_ts = 223.162399
last_seq = 2091
current_ts = 223.179962
current_received_ts = 223.179382
current_seq = 2092
count = 67
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.162964/2091, current 223.179962/2092: elapsed=16994.0us expected=17036.8us +- 85.2us, error 0.3%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.179962
last_received_ts = 223.179382
last_seq = 2092
current_ts = 223.196960
current_received_ts = 223.196411
current_seq = 2093
count = 68
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.179962/2092, current 223.196960/2093: elapsed=17002.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.196960
last_received_ts = 223.196411
last_seq = 2093
current_ts = 223.213959
current_received_ts = 223.213379
current_seq = 2094
count = 69
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.196960/2093, current 223.213959/2094: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.213959
last_received_ts = 223.213379
last_seq = 2094
current_ts = 223.230957
current_received_ts = 223.230377
current_seq = 2095
count = 70
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.213959/2094, current 223.230957/2095: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.230957
last_received_ts = 223.230377
last_seq = 2095
current_ts = 223.247955
current_received_ts = 223.247345
current_seq = 2096
count = 71
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.230957/2095, current 223.247955/2096: elapsed=17007.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.247955
last_received_ts = 223.247345
last_seq = 2096
current_ts = 223.264954
current_received_ts = 223.264389
current_seq = 2097
count = 72
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.247955/2096, current 223.264954/2097: elapsed=16989.0us expected=17036.8us +- 85.2us, error 0.3%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.264954
last_received_ts = 223.264389
last_seq = 2097
current_ts = 223.281952
current_received_ts = 223.281357
current_seq = 2098
count = 73
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.264954/2097, current 223.281952/2098: elapsed=16997.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.281952
last_received_ts = 223.281357
last_seq = 2098
current_ts = 223.298950
current_received_ts = 223.298370
current_seq = 2099
count = 74
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.281952/2098, current 223.298950/2099: elapsed=16997.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.298950
last_received_ts = 223.298370
last_seq = 2099
current_ts = 223.315948
current_received_ts = 223.315384
current_seq = 2100
count = 75
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.298950/2099, current 223.315948/2100: elapsed=16999.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.315948
last_received_ts = 223.315384
last_seq = 2100
current_ts = 223.332947
current_received_ts = 223.332397
current_seq = 2101
count = 76
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.315948/2100, current 223.332947/2101: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.332947
last_received_ts = 223.332397
last_seq = 2101
current_ts = 223.349945
current_received_ts = 223.349380
current_seq = 2102
count = 77
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.332947/2101, current 223.349945/2102: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.349945
last_received_ts = 223.349380
last_seq = 2102
current_ts = 223.366928
current_received_ts = 223.366379
current_seq = 2103
count = 78
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.349945/2102, current 223.366928/2103: elapsed=16997.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.366928
last_received_ts = 223.366379
last_seq = 2103
current_ts = 223.383926
current_received_ts = 223.383377
current_seq = 2104
count = 79
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.366928/2103, current 223.383926/2104: elapsed=16997.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.383926
last_received_ts = 223.383377
last_seq = 2104
current_ts = 223.400925
current_received_ts = 223.400375
current_seq = 2105
count = 80
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.383926/2104, current 223.400925/2105: elapsed=16998.0us expected=17036.8us +- 85.2us, error 0.2%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.400925
last_received_ts = 223.400375
last_seq = 2105
current_ts = 223.417892
current_received_ts = 223.417328
current_seq = 2106
count = 81
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.400925/2105, current 223.417892/2106: elapsed=16966.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.417892
last_received_ts = 223.417328
last_seq = 2106
current_ts = 223.434860
current_received_ts = 223.434311
current_seq = 2107
count = 82
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.417892/2106, current 223.434860/2107: elapsed=16962.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.434860
last_received_ts = 223.434311
last_seq = 2107
current_ts = 223.451828
current_received_ts = 223.451279
current_seq = 2108
count = 83
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.434860/2107, current 223.451828/2108: elapsed=16965.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.451828
last_received_ts = 223.451279
last_seq = 2108
current_ts = 223.468781
current_received_ts = 223.468231
current_seq = 2109
count = 84
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.451828/2108, current 223.468781/2109: elapsed=16963.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.468781
last_received_ts = 223.468231
last_seq = 2109
current_ts = 223.485748
current_received_ts = 223.485184
current_seq = 2110
count = 85
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.468781/2109, current 223.485748/2110: elapsed=16964.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.485748
last_received_ts = 223.485184
last_seq = 2110
current_ts = 223.502716
current_received_ts = 223.502182
current_seq = 2111
count = 86
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.485748/2110, current 223.502716/2111: elapsed=16964.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.502716
last_received_ts = 223.502182
last_seq = 2111
current_ts = 223.519669
current_received_ts = 223.519104
current_seq = 2112
count = 87
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.502716/2111, current 223.519669/2112: elapsed=16958.0us expected=17036.8us +- 85.2us, error 0.5%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.519669
last_received_ts = 223.519104
last_seq = 2112
current_ts = 223.536636
current_received_ts = 223.536102
current_seq = 2113
count = 88
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.519669/2112, current 223.536636/2113: elapsed=16968.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.536636
last_received_ts = 223.536102
last_seq = 2113
current_ts = 223.553604
current_received_ts = 223.553055
current_seq = 2114
count = 89
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.536636/2113, current 223.553604/2114: elapsed=16968.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.553604
last_received_ts = 223.553055
last_seq = 2114
current_ts = 223.570572
current_received_ts = 223.569992
current_seq = 2115
count = 90
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.553604/2114, current 223.570572/2115: elapsed=16960.0us expected=17036.8us +- 85.2us, error 0.5%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.570572
last_received_ts = 223.569992
last_seq = 2115
current_ts = 223.587524
current_received_ts = 223.586975
current_seq = 2116
count = 91
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.570572/2115, current 223.587524/2116: elapsed=16957.0us expected=17036.8us +- 85.2us, error 0.5%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.587524
last_received_ts = 223.586975
last_seq = 2116
current_ts = 223.604492
current_received_ts = 223.603928
current_seq = 2117
count = 92
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.587524/2116, current 223.604492/2117: elapsed=16971.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.604492
last_received_ts = 223.603928
last_seq = 2117
current_ts = 223.621460
current_received_ts = 223.620895
current_seq = 2118
count = 93
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.604492/2117, current 223.621460/2118: elapsed=16963.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.621460
last_received_ts = 223.620895
last_seq = 2118
current_ts = 223.638412
current_received_ts = 223.637848
current_seq = 2119
count = 94
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.621460/2118, current 223.638412/2119: elapsed=16961.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.638412
last_received_ts = 223.637848
last_seq = 2119
current_ts = 223.655380
current_received_ts = 223.654846
current_seq = 2120
count = 95
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.638412/2119, current 223.655380/2120: elapsed=16966.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.655380
last_received_ts = 223.654846
last_seq = 2120
current_ts = 223.672348
current_received_ts = 223.671799
current_seq = 2121
count = 96
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.655380/2120, current 223.672348/2121: elapsed=16964.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.672348
last_received_ts = 223.671799
last_seq = 2121
current_ts = 223.689316
current_received_ts = 223.688751
current_seq = 2122
count = 97
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.672348/2121, current 223.689316/2122: elapsed=16964.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.689316
last_received_ts = 223.688751
last_seq = 2122
current_ts = 223.706284
current_received_ts = 223.705719
current_seq = 2123
count = 98
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.689316/2122, current 223.706284/2123: elapsed=16964.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.706284
last_received_ts = 223.705719
last_seq = 2123
current_ts = 223.723236
current_received_ts = 223.722656
current_seq = 2124
count = 99
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.706284/2123, current 223.723236/2124: elapsed=16963.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.723236
last_received_ts = 223.722656
last_seq = 2124
current_ts = 223.740204
current_received_ts = 223.739639
current_seq = 2125
count = 100
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.723236/2124, current 223.740204/2125: elapsed=16964.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.740204
last_received_ts = 223.739639
last_seq = 2125
current_ts = 223.757172
current_received_ts = 223.756592
current_seq = 2126
count = 101
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.740204/2125, current 223.757172/2126: elapsed=16965.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.757172
last_received_ts = 223.756592
last_seq = 2126
current_ts = 223.774139
current_received_ts = 223.773483
current_seq = 2127
count = 102
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.757172/2126, current 223.774139/2127: elapsed=16970.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.774139
last_received_ts = 223.773483
last_seq = 2127
current_ts = 223.791092
current_received_ts = 223.790543
current_seq = 2128
count = 103
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.774139/2127, current 223.791092/2128: elapsed=16957.0us expected=17036.8us +- 85.2us, error 0.5%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.791092
last_received_ts = 223.790543
last_seq = 2128
current_ts = 223.808060
current_received_ts = 223.807480
current_seq = 2129
count = 104
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.791092/2128, current 223.808060/2129: elapsed=16963.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.808060
last_received_ts = 223.807480
last_seq = 2129
current_ts = 223.825027
current_received_ts = 223.824448
current_seq = 2130
count = 105
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.808060/2129, current 223.825027/2130: elapsed=16965.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.825027
last_received_ts = 223.824448
last_seq = 2130
current_ts = 223.841980
current_received_ts = 223.841431
current_seq = 2131
count = 106
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.825027/2130, current 223.841980/2131: elapsed=16962.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.841980
last_received_ts = 223.841431
last_seq = 2131
current_ts = 223.858948
current_received_ts = 223.858383
current_seq = 2132
count = 107
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.841980/2131, current 223.858948/2132: elapsed=16964.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.858948
last_received_ts = 223.858383
last_seq = 2132
current_ts = 223.875916
current_received_ts = 223.875336
current_seq = 2133
count = 108
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.858948/2132, current 223.875916/2133: elapsed=16963.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.875916
last_received_ts = 223.875336
last_seq = 2133
current_ts = 223.892883
current_received_ts = 223.892319
current_seq = 2134
count = 109
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.875916/2133, current 223.892883/2134: elapsed=16965.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.892883
last_received_ts = 223.892319
last_seq = 2134
current_ts = 223.909836
current_received_ts = 223.909210
current_seq = 2135
count = 110
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.892883/2134, current 223.909836/2135: elapsed=16963.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.909836
last_received_ts = 223.909210
last_seq = 2135
current_ts = 223.926804
current_received_ts = 223.926239
current_seq = 2136
count = 111
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.909836/2135, current 223.926804/2136: elapsed=16963.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.926804
last_received_ts = 223.926239
last_seq = 2136
current_ts = 223.943771
current_received_ts = 223.943207
current_seq = 2137
count = 112
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.926804/2136, current 223.943771/2137: elapsed=16964.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.943771
last_received_ts = 223.943207
last_seq = 2137
current_ts = 223.960739
current_received_ts = 223.960190
current_seq = 2138
count = 113
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.943771/2137, current 223.960739/2138: elapsed=16964.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.960739
last_received_ts = 223.960190
last_seq = 2138
current_ts = 223.977692
current_received_ts = 223.977127
current_seq = 2139
count = 114
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.960739/2138, current 223.977692/2139: elapsed=16965.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.977692
last_received_ts = 223.977127
last_seq = 2139
current_ts = 223.994659
current_received_ts = 223.994110
current_seq = 2140
count = 115
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.977692/2139, current 223.994659/2140: elapsed=16962.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 223.994659
last_received_ts = 223.994110
last_seq = 2140
current_ts = 224.011627
current_received_ts = 224.011093
current_seq = 2141
count = 116
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 223.994659/2140, current 224.011627/2141: elapsed=16965.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.011627
last_received_ts = 224.011093
last_seq = 2141
current_ts = 224.028595
current_received_ts = 224.028046
current_seq = 2142
count = 117
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.011627/2141, current 224.028595/2142: elapsed=16963.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.028595
last_received_ts = 224.028046
last_seq = 2142
current_ts = 224.045547
current_received_ts = 224.044968
current_seq = 2143
count = 118
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.028595/2142, current 224.045547/2143: elapsed=16955.0us expected=17036.8us +- 85.2us, error 0.5%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.045547
last_received_ts = 224.044968
last_seq = 2143
current_ts = 224.062515
current_received_ts = 224.061951
current_seq = 2144
count = 119
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.045547/2143, current 224.062515/2144: elapsed=16967.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.062515
last_received_ts = 224.061951
last_seq = 2144
current_ts = 224.079468
current_received_ts = 224.078918
current_seq = 2145
count = 120
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.062515/2144, current 224.079468/2145: elapsed=16964.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.079468
last_received_ts = 224.078918
last_seq = 2145
current_ts = 224.096451
current_received_ts = 224.095840
current_seq = 2146
count = 121
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.079468/2145, current 224.096451/2146: elapsed=16975.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.096451
last_received_ts = 224.095840
last_seq = 2146
current_ts = 224.113403
current_received_ts = 224.112854
current_seq = 2147
count = 122
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.096451/2146, current 224.113403/2147: elapsed=16954.0us expected=17036.8us +- 85.2us, error 0.5%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.113403
last_received_ts = 224.112854
last_seq = 2147
current_ts = 224.130371
current_received_ts = 224.129837
current_seq = 2148
count = 123
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.113403/2147, current 224.130371/2148: elapsed=16967.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.130371
last_received_ts = 224.129837
last_seq = 2148
current_ts = 224.147339
current_received_ts = 224.146790
current_seq = 2149
count = 124
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.130371/2148, current 224.147339/2149: elapsed=16964.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.147339
last_received_ts = 224.146790
last_seq = 2149
current_ts = 224.164291
current_received_ts = 224.163742
current_seq = 2150
count = 125
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.147339/2149, current 224.164291/2150: elapsed=16964.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.164291
last_received_ts = 224.163742
last_seq = 2150
current_ts = 224.181259
current_received_ts = 224.180695
current_seq = 2151
count = 126
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.164291/2150, current 224.181259/2151: elapsed=16968.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.181259
last_received_ts = 224.180695
last_seq = 2151
current_ts = 224.198227
current_received_ts = 224.197678
current_seq = 2152
count = 127
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.181259/2151, current 224.198227/2152: elapsed=16959.0us expected=17036.8us +- 85.2us, error 0.5%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.198227
last_received_ts = 224.197678
last_seq = 2152
current_ts = 224.215195
current_received_ts = 224.214645
current_seq = 2153
count = 128
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.198227/2152, current 224.215195/2153: elapsed=16963.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.215195
last_received_ts = 224.214645
last_seq = 2153
current_ts = 224.232147
current_received_ts = 224.231598
current_seq = 2154
count = 129
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.215195/2153, current 224.232147/2154: elapsed=16964.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.232147
last_received_ts = 224.231598
last_seq = 2154
current_ts = 224.249115
current_received_ts = 224.248566
current_seq = 2155
count = 130
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.232147/2154, current 224.249115/2155: elapsed=16963.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.249115
last_received_ts = 224.248566
last_seq = 2155
current_ts = 224.266083
current_received_ts = 224.265533
current_seq = 2156
count = 131
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.249115/2155, current 224.266083/2156: elapsed=16964.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.266083
last_received_ts = 224.265533
last_seq = 2156
current_ts = 224.283051
current_received_ts = 224.282501
current_seq = 2157
count = 132
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.266083/2156, current 224.283051/2157: elapsed=16964.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.283051
last_received_ts = 224.282501
last_seq = 2157
current_ts = 224.300003
current_received_ts = 224.299454
current_seq = 2158
count = 133
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.283051/2157, current 224.300003/2158: elapsed=16963.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.300003
last_received_ts = 224.299454
last_seq = 2158
current_ts = 224.316971
current_received_ts = 224.316422
current_seq = 2159
count = 134
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.300003/2158, current 224.316971/2159: elapsed=16965.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.316971
last_received_ts = 224.316422
last_seq = 2159
current_ts = 224.333939
current_received_ts = 224.333359
current_seq = 2160
count = 135
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.316971/2159, current 224.333939/2160: elapsed=16962.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.333939
last_received_ts = 224.333359
last_seq = 2160
current_ts = 224.350906
current_received_ts = 224.350327
current_seq = 2161
count = 136
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.333939/2160, current 224.350906/2161: elapsed=16966.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.350906
last_received_ts = 224.350327
last_seq = 2161
current_ts = 224.367859
current_received_ts = 224.367310
current_seq = 2162
count = 137
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.350906/2161, current 224.367859/2162: elapsed=16962.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.367859
last_received_ts = 224.367310
last_seq = 2162
current_ts = 224.384827
current_received_ts = 224.384277
current_seq = 2163
count = 138
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.367859/2162, current 224.384827/2163: elapsed=16964.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.384827
last_received_ts = 224.384277
last_seq = 2163
current_ts = 224.401794
current_received_ts = 224.401230
current_seq = 2164
count = 139
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.384827/2163, current 224.401794/2164: elapsed=16964.0us expected=17036.8us +- 85.2us, error 0.4%
(kms_flip:2600) DEBUG: name = flip
last_ts = 224.401794
last_received_ts = 224.401230
last_seq = 2164
current_ts = 224.418716
current_received_ts = 224.418167
current_seq = 2165
count = 140
seq_step = 1
(kms_flip:2600) DEBUG: flip ts/seq: last 224.401794/2164, current 224.418716/2165: elapsed=16935.0us expected=17036.8us +- 85.2us, error 0.6%
(kms_flip:2600) DEBUG: inconsistent flip ts/seq: last 224.401794/2164, current 224.418716/2165: elapsed=16935.0us expected=17036.8us
(kms_flip:2600) DEBUG: expected 21527, counted 140, encoder type 1
(kms_flip:2600) DEBUG: dropped frames, expected 21527, counted 140, encoder type 1
(kms_flip:2600) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2600) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2600) igt_core-INFO: Stack trace:
(kms_flip:2600) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2600) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2600) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2600) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2600) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2600) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2600) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2600) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-VGA1: FAIL (5.910s)
Dmesg
<6> [221.273690] [IGT] kms_flip: starting dynamic subtest B-VGA1
<7> [221.274139] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:84]
<7> [221.274234] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:85]
<7> [221.308829] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:47:pipe A]
<7> [221.309034] 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> [221.309429] 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> [221.309859] 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> [221.310186] 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> [221.310461] 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> [221.310778] 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> [221.311056] 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> [221.311331] 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> [221.311605] 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> [221.311916] 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> [221.312191] 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> [221.312464] 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> [221.312795] 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> [221.313069] 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> [221.313343] 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> [221.313654] 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> [221.313889] 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> [221.314100] 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> [221.314311] 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> [221.314521] 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> [221.314748] 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> [221.314960] 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> [221.315170] 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> [221.315381] 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> [221.315599] 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> [221.315810] 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> [221.316021] 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> [221.316232] 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> [221.316442] 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> [221.316677] 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> [221.316883] 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> [221.317089] 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> [221.317294] 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> [221.317498] 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> [221.317726] 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> [221.317934] 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> [221.318139] 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> [221.318343] 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> [221.318574] 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> [221.318800] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:47:pipe A] fastset requirement not met, forcing full modeset
<7> [221.319006] i915 0000:00:02.0: [drm:intel_unreference_shared_dpll_crtc [i915]] [CRTC:47:pipe A] releasing PCH DPLL A
<7> [221.319269] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 400000 kHz, actual 400000 kHz
<7> [221.319511] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [221.319731] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:47:pipe A] enable: no [modeset]
<7> [221.319937] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:32:primary A] fb: [NOFB], visible: no
<7> [221.320262] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A
<7> [221.334455] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found
<7> [221.334679] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found
<7> [221.334882] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found
<7> [221.351314] 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> [221.351779] i915 0000:00:02.0: [drm:intel_disable_shared_dpll [i915]] disabling PCH DPLL A
<7> [221.352485] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:65:CRT]
<7> [221.352956] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:66:HDMI D]
<7> [221.353403] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:DP D]
<7> [221.353854] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:64:VGA-1]
<7> [221.354378] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:47:pipe A]
<7> [221.354876] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:63:pipe B]
<7> [221.355033] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:63:pipe B]
<7> [221.355061] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:64:VGA-1]
<7> [221.355153] 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> [221.355381] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:63:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0
<7> [221.355595] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe B, lanes 1
<7> [221.355813] 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> [221.356027] 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> [221.356239] 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> [221.356451] 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> [221.356663] 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> [221.356906] 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> [221.357127] 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> [221.357340] 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> [221.357552] 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> [221.357771] 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> [221.357983] 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> [221.358195] 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> [221.358406] 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> [221.358617] 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> [221.358843] 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> [221.359050] 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> [221.359256] 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> [221.359460] 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> [221.359675] 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> [221.359912] 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> [221.360144] 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> [221.360355] 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> [221.360565] 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> [221.360811] 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> [221.361057] 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> [221.361268] 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> [221.361480] 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> [221.361703] 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> [221.361916] 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> [221.362127] 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> [221.362338] 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> [221.362549] 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> [221.362767] 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> [221.362979] 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> [221.363190] 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> [221.363403] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in dpll_hw_state
<7> [221.363614] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:
<7> [221.363830] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0xc4010001, dpll_md: 0x0, fp0: 0x30f06, fp1: 0x30f06
<7> [221.364042] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:
<7> [221.364252] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [221.364463] 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> [221.364705] 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> [221.364922] 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> [221.365133] 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> [221.365345] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:63:pipe B] fastset requirement not met, forcing full modeset
<7> [221.365623] 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> [221.365873] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 400000 kHz, actual 400000 kHz
<7> [221.366090] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [221.366302] i915 0000:00:02.0: [drm:intel_find_shared_dpll [i915]] [CRTC:63:pipe B] allocated PCH DPLL A
<7> [221.366511] i915 0000:00:02.0: [drm:intel_reference_shared_dpll_crtc [i915]] [CRTC:63:pipe B] reserving PCH DPLL A
<7> [221.366778] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:63:pipe B] enable: yes [modeset]
<7> [221.367001] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: ANALOG (0x2), output format: RGB, sink format: RGB
<7> [221.367218] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0
<7> [221.367428] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [221.367653] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [221.367885] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [221.368089] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [221.368305] 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> [221.368516] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0
<7> [221.368747] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1
<7> [221.368980] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0
<7> [221.369189] 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> [221.369401] 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> [221.369628] 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> [221.369855] 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> [221.370069] 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> [221.370281] 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> [221.370492] 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> [221.370755] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 64800, pipe src: 1024x768+0+0, pixel rate 64800
<7> [221.370966] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0
<7> [221.371177] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [221.371387] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [221.371689] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [221.371968] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [221.372186] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [221.372396] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [221.372519] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on
<7> [221.372627] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [221.372868] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [221.373078] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [221.373289] 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> [221.373520] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [221.373742] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1024.000000x768.000000+0.000000+0.000000 dst: 1024x768+0+0
<7> [221.374844] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on
<7> [221.375073] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:65:CRT]
<7> [221.375282] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:66:HDMI D]
<7> [221.375513] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:DP D]
<7> [221.376289] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B
<7> [221.377371] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100
<7> [221.377587] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done.
<7> [221.378457] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x200
<7> [221.378661] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done.
<7> [221.378871] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done.
<7> [221.379095] 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> [221.379305] i915 0000:00:02.0: [drm:intel_enable_shared_dpll [i915]] enabling PCH DPLL A
<7> [221.431311] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:64:VGA-1]
<7> [221.431862] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:63:pipe B]
<6> [227.184819] [IGT] kms_flip: finished subtest B-VGA1, FAIL
Created at 2025-03-21 22:58:29