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

Result: Fail

integration-manifest git-log-oneline i915_display_info20 igt_runner20 runtimes20 results20.json results20-i915-load.json guc_logs20.tar i915_display_info_post_exec20 boot20 dmesg20

DetailValue
Duration 18.76 seconds
Hostname 
shard-snb7
Igt-Version 
IGT-Version: 2.3-ga50285a68 (x86_64) (Linux: 7.0.0-rc2-CI_DRM_18096-g704ff20b65b8+ 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 17431.2us +- 3.082us accuracy 0.05%
vblank interval differs from modeline! expected 16665.6us, measured 17431us +- 3.082us, difference 765.6us (248.4 sigma)
Event flip: expected 430, counted 437, passrate = 6.86%, encoder type 1
Expected frametime: 16666us; measured 16887.8us +- 2.082us accuracy 0.04%
vblank interval differs from modeline! expected 16665.6us, measured 16888us +- 2.082us, difference 222.2us (106.7 sigma)
Event flip: expected 444, counted 446, passrate = 71.52%, encoder type 1
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:428 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1887 run_test()
  #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043()
  #4 ../tests/kms_flip.c:2043 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-VGA1: FAIL (18.764s)
Err 
Starting dynamic subtest: B-VGA1
(kms_flip:2920) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1707:
(kms_flip:2920) CRITICAL: Failed assertion: !retried
Dynamic subtest B-VGA1 failed.
**** DEBUG ****
(kms_flip:2920) DEBUG: name = flip
last_ts = 382.728973
last_received_ts = 382.728424
last_seq = 5038
current_ts = 382.745758
current_received_ts = 382.745209
current_seq = 5039
count = 365
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 382.728973/5038, current 382.745758/5039: elapsed=16797.0us expected=16887.8us +- 84.4us, error 0.5%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 382.728973/5038, current 382.745758/5039: elapsed=16797.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 382.745758
last_received_ts = 382.745209
last_seq = 5039
current_ts = 382.762573
current_received_ts = 382.762024
current_seq = 5040
count = 366
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 382.745758/5039, current 382.762573/5040: elapsed=16799.0us expected=16887.8us +- 84.4us, error 0.5%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 382.745758/5039, current 382.762573/5040: elapsed=16799.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 382.762573
last_received_ts = 382.762024
last_seq = 5040
current_ts = 382.779358
current_received_ts = 382.778809
current_seq = 5041
count = 367
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 382.762573/5040, current 382.779358/5041: elapsed=16799.0us expected=16887.8us +- 84.4us, error 0.5%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 382.762573/5040, current 382.779358/5041: elapsed=16799.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 382.779358
last_received_ts = 382.778809
last_seq = 5041
current_ts = 382.796173
current_received_ts = 382.795593
current_seq = 5042
count = 368
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 382.779358/5041, current 382.796173/5042: elapsed=16797.0us expected=16887.8us +- 84.4us, error 0.5%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 382.779358/5041, current 382.796173/5042: elapsed=16797.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 382.796173
last_received_ts = 382.795593
last_seq = 5042
current_ts = 382.812958
current_received_ts = 382.812408
current_seq = 5043
count = 369
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 382.796173/5042, current 382.812958/5043: elapsed=16798.0us expected=16887.8us +- 84.4us, error 0.5%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 382.796173/5042, current 382.812958/5043: elapsed=16798.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 382.812958
last_received_ts = 382.812408
last_seq = 5043
current_ts = 382.829773
current_received_ts = 382.829193
current_seq = 5044
count = 370
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 382.812958/5043, current 382.829773/5044: elapsed=16800.0us expected=16887.8us +- 84.4us, error 0.5%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 382.812958/5043, current 382.829773/5044: elapsed=16800.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 382.829773
last_received_ts = 382.829193
last_seq = 5044
current_ts = 382.846558
current_received_ts = 382.846039
current_seq = 5045
count = 371
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 382.829773/5044, current 382.846558/5045: elapsed=16796.0us expected=16887.8us +- 84.4us, error 0.5%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 382.829773/5044, current 382.846558/5045: elapsed=16796.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 382.846558
last_received_ts = 382.846039
last_seq = 5045
current_ts = 382.863373
current_received_ts = 382.862762
current_seq = 5046
count = 372
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 382.846558/5045, current 382.863373/5046: elapsed=16799.0us expected=16887.8us +- 84.4us, error 0.5%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 382.846558/5045, current 382.863373/5046: elapsed=16799.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 382.863373
last_received_ts = 382.862762
last_seq = 5046
current_ts = 382.880157
current_received_ts = 382.879578
current_seq = 5047
count = 373
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 382.863373/5046, current 382.880157/5047: elapsed=16797.0us expected=16887.8us +- 84.4us, error 0.5%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 382.863373/5046, current 382.880157/5047: elapsed=16797.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 382.880157
last_received_ts = 382.879578
last_seq = 5047
current_ts = 382.896942
current_received_ts = 382.896332
current_seq = 5048
count = 374
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 382.880157/5047, current 382.896942/5048: elapsed=16794.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 382.880157/5047, current 382.896942/5048: elapsed=16794.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 382.896942
last_received_ts = 382.896332
last_seq = 5048
current_ts = 382.913757
current_received_ts = 382.913177
current_seq = 5049
count = 375
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 382.896942/5048, current 382.913757/5049: elapsed=16804.0us expected=16887.8us +- 84.4us, error 0.5%
(kms_flip:2920) DEBUG: name = flip
last_ts = 382.913757
last_received_ts = 382.913177
last_seq = 5049
current_ts = 382.930542
current_received_ts = 382.930023
current_seq = 5050
count = 376
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 382.913757/5049, current 382.930542/5050: elapsed=16797.0us expected=16887.8us +- 84.4us, error 0.5%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 382.913757/5049, current 382.930542/5050: elapsed=16797.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 382.930542
last_received_ts = 382.930023
last_seq = 5050
current_ts = 382.947357
current_received_ts = 382.946838
current_seq = 5051
count = 377
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 382.930542/5050, current 382.947357/5051: elapsed=16800.0us expected=16887.8us +- 84.4us, error 0.5%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 382.930542/5050, current 382.947357/5051: elapsed=16800.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 382.947357
last_received_ts = 382.946838
last_seq = 5051
current_ts = 382.964142
current_received_ts = 382.963562
current_seq = 5052
count = 378
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 382.947357/5051, current 382.964142/5052: elapsed=16798.0us expected=16887.8us +- 84.4us, error 0.5%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 382.947357/5051, current 382.964142/5052: elapsed=16798.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 382.964142
last_received_ts = 382.963562
last_seq = 5052
current_ts = 382.980957
current_received_ts = 382.980377
current_seq = 5053
count = 379
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 382.964142/5052, current 382.980957/5053: elapsed=16797.0us expected=16887.8us +- 84.4us, error 0.5%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 382.964142/5052, current 382.980957/5053: elapsed=16797.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 382.980957
last_received_ts = 382.980377
last_seq = 5053
current_ts = 382.997742
current_received_ts = 382.997192
current_seq = 5054
count = 380
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 382.980957/5053, current 382.997742/5054: elapsed=16798.0us expected=16887.8us +- 84.4us, error 0.5%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 382.980957/5053, current 382.997742/5054: elapsed=16798.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 382.997742
last_received_ts = 382.997192
last_seq = 5054
current_ts = 383.014526
current_received_ts = 383.013947
current_seq = 5055
count = 381
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 382.997742/5054, current 383.014526/5055: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 382.997742/5054, current 383.014526/5055: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.014526
last_received_ts = 383.013947
last_seq = 5055
current_ts = 383.031311
current_received_ts = 383.030731
current_seq = 5056
count = 382
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.014526/5055, current 383.031311/5056: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.014526/5055, current 383.031311/5056: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.031311
last_received_ts = 383.030731
last_seq = 5056
current_ts = 383.048126
current_received_ts = 383.047516
current_seq = 5057
count = 383
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.031311/5056, current 383.048126/5057: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.031311/5056, current 383.048126/5057: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.048126
last_received_ts = 383.047516
last_seq = 5057
current_ts = 383.064911
current_received_ts = 383.064331
current_seq = 5058
count = 384
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.048126/5057, current 383.064911/5058: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.048126/5057, current 383.064911/5058: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.064911
last_received_ts = 383.064331
last_seq = 5058
current_ts = 383.081696
current_received_ts = 383.081146
current_seq = 5059
count = 385
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.064911/5058, current 383.081696/5059: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.064911/5058, current 383.081696/5059: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.081696
last_received_ts = 383.081146
last_seq = 5059
current_ts = 383.098480
current_received_ts = 383.097900
current_seq = 5060
count = 386
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.081696/5059, current 383.098480/5060: elapsed=16790.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.081696/5059, current 383.098480/5060: elapsed=16790.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.098480
last_received_ts = 383.097900
last_seq = 5060
current_ts = 383.115265
current_received_ts = 383.114716
current_seq = 5061
count = 387
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.098480/5060, current 383.115265/5061: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.098480/5060, current 383.115265/5061: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.115265
last_received_ts = 383.114716
last_seq = 5061
current_ts = 383.132050
current_received_ts = 383.131500
current_seq = 5062
count = 388
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.115265/5061, current 383.132050/5062: elapsed=16788.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.115265/5061, current 383.132050/5062: elapsed=16788.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.132050
last_received_ts = 383.131500
last_seq = 5062
current_ts = 383.148834
current_received_ts = 383.148285
current_seq = 5063
count = 389
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.132050/5062, current 383.148834/5063: elapsed=16787.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.132050/5062, current 383.148834/5063: elapsed=16787.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.148834
last_received_ts = 383.148285
last_seq = 5063
current_ts = 383.165649
current_received_ts = 383.165100
current_seq = 5064
count = 390
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.148834/5063, current 383.165649/5064: elapsed=16792.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.148834/5063, current 383.165649/5064: elapsed=16792.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.165649
last_received_ts = 383.165100
last_seq = 5064
current_ts = 383.182434
current_received_ts = 383.181854
current_seq = 5065
count = 391
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.165649/5064, current 383.182434/5065: elapsed=16788.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.165649/5064, current 383.182434/5065: elapsed=16788.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.182434
last_received_ts = 383.181854
last_seq = 5065
current_ts = 383.199219
current_received_ts = 383.198639
current_seq = 5066
count = 392
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.182434/5065, current 383.199219/5066: elapsed=16790.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.182434/5065, current 383.199219/5066: elapsed=16790.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.199219
last_received_ts = 383.198639
last_seq = 5066
current_ts = 383.216003
current_received_ts = 383.215424
current_seq = 5067
count = 393
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.199219/5066, current 383.216003/5067: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.199219/5066, current 383.216003/5067: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.216003
last_received_ts = 383.215424
last_seq = 5067
current_ts = 383.232788
current_received_ts = 383.232208
current_seq = 5068
count = 394
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.216003/5067, current 383.232788/5068: elapsed=16788.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.216003/5067, current 383.232788/5068: elapsed=16788.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.232788
last_received_ts = 383.232208
last_seq = 5068
current_ts = 383.249573
current_received_ts = 383.249023
current_seq = 5069
count = 395
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.232788/5068, current 383.249573/5069: elapsed=16790.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.232788/5068, current 383.249573/5069: elapsed=16790.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.249573
last_received_ts = 383.249023
last_seq = 5069
current_ts = 383.266357
current_received_ts = 383.265778
current_seq = 5070
count = 396
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.249573/5069, current 383.266357/5070: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.249573/5069, current 383.266357/5070: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.266357
last_received_ts = 383.265778
last_seq = 5070
current_ts = 383.283173
current_received_ts = 383.282562
current_seq = 5071
count = 397
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.266357/5070, current 383.283173/5071: elapsed=16788.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.266357/5070, current 383.283173/5071: elapsed=16788.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.283173
last_received_ts = 383.282562
last_seq = 5071
current_ts = 383.299957
current_received_ts = 383.299377
current_seq = 5072
count = 398
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.283173/5071, current 383.299957/5072: elapsed=16790.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.283173/5071, current 383.299957/5072: elapsed=16790.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.299957
last_received_ts = 383.299377
last_seq = 5072
current_ts = 383.316742
current_received_ts = 383.316193
current_seq = 5073
count = 399
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.299957/5072, current 383.316742/5073: elapsed=16792.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.299957/5072, current 383.316742/5073: elapsed=16792.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.316742
last_received_ts = 383.316193
last_seq = 5073
current_ts = 383.333527
current_received_ts = 383.332977
current_seq = 5074
count = 400
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.316742/5073, current 383.333527/5074: elapsed=16786.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.316742/5073, current 383.333527/5074: elapsed=16786.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.333527
last_received_ts = 383.332977
last_seq = 5074
current_ts = 383.350311
current_received_ts = 383.349762
current_seq = 5075
count = 401
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.333527/5074, current 383.350311/5075: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.333527/5074, current 383.350311/5075: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.350311
last_received_ts = 383.349762
last_seq = 5075
current_ts = 383.367096
current_received_ts = 383.366547
current_seq = 5076
count = 402
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.350311/5075, current 383.367096/5076: elapsed=16792.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.350311/5075, current 383.367096/5076: elapsed=16792.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.367096
last_received_ts = 383.366547
last_seq = 5076
current_ts = 383.383881
current_received_ts = 383.383331
current_seq = 5077
count = 403
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.367096/5076, current 383.383881/5077: elapsed=16787.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.367096/5076, current 383.383881/5077: elapsed=16787.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.383881
last_received_ts = 383.383331
last_seq = 5077
current_ts = 383.400696
current_received_ts = 383.400146
current_seq = 5078
count = 404
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.383881/5077, current 383.400696/5078: elapsed=16788.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.383881/5077, current 383.400696/5078: elapsed=16788.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.400696
last_received_ts = 383.400146
last_seq = 5078
current_ts = 383.417480
current_received_ts = 383.416901
current_seq = 5079
count = 405
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.400696/5078, current 383.417480/5079: elapsed=16790.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.400696/5078, current 383.417480/5079: elapsed=16790.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.417480
last_received_ts = 383.416901
last_seq = 5079
current_ts = 383.434265
current_received_ts = 383.433685
current_seq = 5080
count = 406
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.417480/5079, current 383.434265/5080: elapsed=16788.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.417480/5079, current 383.434265/5080: elapsed=16788.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.434265
last_received_ts = 383.433685
last_seq = 5080
current_ts = 383.451050
current_received_ts = 383.450470
current_seq = 5081
count = 407
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.434265/5080, current 383.451050/5081: elapsed=16790.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.434265/5080, current 383.451050/5081: elapsed=16790.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.451050
last_received_ts = 383.450470
last_seq = 5081
current_ts = 383.467834
current_received_ts = 383.467194
current_seq = 5082
count = 408
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.451050/5081, current 383.467834/5082: elapsed=16784.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.451050/5081, current 383.467834/5082: elapsed=16784.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.467834
last_received_ts = 383.467194
last_seq = 5082
current_ts = 383.484619
current_received_ts = 383.484070
current_seq = 5083
count = 409
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.467834/5082, current 383.484619/5083: elapsed=16793.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.467834/5082, current 383.484619/5083: elapsed=16793.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.484619
last_received_ts = 383.484070
last_seq = 5083
current_ts = 383.501404
current_received_ts = 383.500854
current_seq = 5084
count = 410
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.484619/5083, current 383.501404/5084: elapsed=16790.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.484619/5083, current 383.501404/5084: elapsed=16790.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.501404
last_received_ts = 383.500854
last_seq = 5084
current_ts = 383.518219
current_received_ts = 383.517609
current_seq = 5085
count = 411
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.501404/5084, current 383.518219/5085: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.501404/5084, current 383.518219/5085: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.518219
last_received_ts = 383.517609
last_seq = 5085
current_ts = 383.535004
current_received_ts = 383.534424
current_seq = 5086
count = 412
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.518219/5085, current 383.535004/5086: elapsed=16788.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.518219/5085, current 383.535004/5086: elapsed=16788.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.535004
last_received_ts = 383.534424
last_seq = 5086
current_ts = 383.551788
current_received_ts = 383.551208
current_seq = 5087
count = 413
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.535004/5086, current 383.551788/5087: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.535004/5086, current 383.551788/5087: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.551788
last_received_ts = 383.551208
last_seq = 5087
current_ts = 383.568573
current_received_ts = 383.567993
current_seq = 5088
count = 414
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.551788/5087, current 383.568573/5088: elapsed=16790.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.551788/5087, current 383.568573/5088: elapsed=16790.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.568573
last_received_ts = 383.567993
last_seq = 5088
current_ts = 383.585358
current_received_ts = 383.584778
current_seq = 5089
count = 415
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.568573/5088, current 383.585358/5089: elapsed=16783.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.568573/5088, current 383.585358/5089: elapsed=16783.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.585358
last_received_ts = 383.584778
last_seq = 5089
current_ts = 383.602142
current_received_ts = 383.601593
current_seq = 5090
count = 416
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.585358/5089, current 383.602142/5090: elapsed=16795.0us expected=16887.8us +- 84.4us, error 0.5%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.585358/5089, current 383.602142/5090: elapsed=16795.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.602142
last_received_ts = 383.601593
last_seq = 5090
current_ts = 383.618927
current_received_ts = 383.618378
current_seq = 5091
count = 417
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.602142/5090, current 383.618927/5091: elapsed=16790.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.602142/5090, current 383.618927/5091: elapsed=16790.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.618927
last_received_ts = 383.618378
last_seq = 5091
current_ts = 383.635742
current_received_ts = 383.635162
current_seq = 5092
count = 418
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.618927/5091, current 383.635742/5092: elapsed=16788.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.618927/5091, current 383.635742/5092: elapsed=16788.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.635742
last_received_ts = 383.635162
last_seq = 5092
current_ts = 383.652527
current_received_ts = 383.651947
current_seq = 5093
count = 419
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.635742/5092, current 383.652527/5093: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.635742/5092, current 383.652527/5093: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.652527
last_received_ts = 383.651947
last_seq = 5093
current_ts = 383.669312
current_received_ts = 383.668732
current_seq = 5094
count = 420
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.652527/5093, current 383.669312/5094: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.652527/5093, current 383.669312/5094: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.669312
last_received_ts = 383.668732
last_seq = 5094
current_ts = 383.686096
current_received_ts = 383.685547
current_seq = 5095
count = 421
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.669312/5094, current 383.686096/5095: elapsed=16790.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.669312/5094, current 383.686096/5095: elapsed=16790.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.686096
last_received_ts = 383.685547
last_seq = 5095
current_ts = 383.702881
current_received_ts = 383.702301
current_seq = 5096
count = 422
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.686096/5095, current 383.702881/5096: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.686096/5095, current 383.702881/5096: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.702881
last_received_ts = 383.702301
last_seq = 5096
current_ts = 383.719666
current_received_ts = 383.719177
current_seq = 5097
count = 423
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.702881/5096, current 383.719666/5097: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.702881/5096, current 383.719666/5097: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.719666
last_received_ts = 383.719177
last_seq = 5097
current_ts = 383.736450
current_received_ts = 383.735901
current_seq = 5098
count = 424
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.719666/5097, current 383.736450/5098: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.719666/5097, current 383.736450/5098: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.736450
last_received_ts = 383.735901
last_seq = 5098
current_ts = 383.753265
current_received_ts = 383.752686
current_seq = 5099
count = 425
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.736450/5098, current 383.753265/5099: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.736450/5098, current 383.753265/5099: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.753265
last_received_ts = 383.752686
last_seq = 5099
current_ts = 383.770050
current_received_ts = 383.769470
current_seq = 5100
count = 426
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.753265/5099, current 383.770050/5100: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.753265/5099, current 383.770050/5100: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.770050
last_received_ts = 383.769470
last_seq = 5100
current_ts = 383.786835
current_received_ts = 383.786255
current_seq = 5101
count = 427
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.770050/5100, current 383.786835/5101: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.770050/5100, current 383.786835/5101: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.786835
last_received_ts = 383.786255
last_seq = 5101
current_ts = 383.803619
current_received_ts = 383.803070
current_seq = 5102
count = 428
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.786835/5101, current 383.803619/5102: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.786835/5101, current 383.803619/5102: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.803619
last_received_ts = 383.803070
last_seq = 5102
current_ts = 383.820404
current_received_ts = 383.819824
current_seq = 5103
count = 429
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.803619/5102, current 383.820404/5103: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.803619/5102, current 383.820404/5103: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.820404
last_received_ts = 383.819824
last_seq = 5103
current_ts = 383.837189
current_received_ts = 383.836639
current_seq = 5104
count = 430
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.820404/5103, current 383.837189/5104: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.820404/5103, current 383.837189/5104: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.837189
last_received_ts = 383.836639
last_seq = 5104
current_ts = 383.853973
current_received_ts = 383.853424
current_seq = 5105
count = 431
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.837189/5104, current 383.853973/5105: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.837189/5104, current 383.853973/5105: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.853973
last_received_ts = 383.853424
last_seq = 5105
current_ts = 383.870789
current_received_ts = 383.870178
current_seq = 5106
count = 432
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.853973/5105, current 383.870789/5106: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.853973/5105, current 383.870789/5106: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.870789
last_received_ts = 383.870178
last_seq = 5106
current_ts = 383.887573
current_received_ts = 383.886993
current_seq = 5107
count = 433
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.870789/5106, current 383.887573/5107: elapsed=16790.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.870789/5106, current 383.887573/5107: elapsed=16790.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.887573
last_received_ts = 383.886993
last_seq = 5107
current_ts = 383.904358
current_received_ts = 383.903778
current_seq = 5108
count = 434
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.887573/5107, current 383.904358/5108: elapsed=16787.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.887573/5107, current 383.904358/5108: elapsed=16787.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.904358
last_received_ts = 383.903778
last_seq = 5108
current_ts = 383.921143
current_received_ts = 383.920563
current_seq = 5109
count = 435
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.904358/5108, current 383.921143/5109: elapsed=16790.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.904358/5108, current 383.921143/5109: elapsed=16790.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.921143
last_received_ts = 383.920563
last_seq = 5109
current_ts = 383.937927
current_received_ts = 383.937378
current_seq = 5110
count = 436
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.921143/5109, current 383.937927/5110: elapsed=16790.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.921143/5109, current 383.937927/5110: elapsed=16790.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.937927
last_received_ts = 383.937378
last_seq = 5110
current_ts = 383.954712
current_received_ts = 383.954163
current_seq = 5111
count = 437
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.937927/5110, current 383.954712/5111: elapsed=16788.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.937927/5110, current 383.954712/5111: elapsed=16788.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.954712
last_received_ts = 383.954163
last_seq = 5111
current_ts = 383.971497
current_received_ts = 383.970947
current_seq = 5112
count = 438
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.954712/5111, current 383.971497/5112: elapsed=16789.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.954712/5111, current 383.971497/5112: elapsed=16789.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.971497
last_received_ts = 383.970947
last_seq = 5112
current_ts = 383.988312
current_received_ts = 383.987732
current_seq = 5113
count = 439
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.971497/5112, current 383.988312/5113: elapsed=16790.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.971497/5112, current 383.988312/5113: elapsed=16790.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 383.988312
last_received_ts = 383.987732
last_seq = 5113
current_ts = 384.005096
current_received_ts = 384.004517
current_seq = 5114
count = 440
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 383.988312/5113, current 384.005096/5114: elapsed=16783.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 383.988312/5113, current 384.005096/5114: elapsed=16783.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 384.005096
last_received_ts = 384.004517
last_seq = 5114
current_ts = 384.021851
current_received_ts = 384.021271
current_seq = 5115
count = 441
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 384.005096/5114, current 384.021851/5115: elapsed=16782.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 384.005096/5114, current 384.021851/5115: elapsed=16782.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 384.021851
last_received_ts = 384.021271
last_seq = 5115
current_ts = 384.038635
current_received_ts = 384.038147
current_seq = 5116
count = 442
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 384.021851/5115, current 384.038635/5116: elapsed=16776.0us expected=16887.8us +- 84.4us, error 0.7%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 384.021851/5115, current 384.038635/5116: elapsed=16776.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 384.038635
last_received_ts = 384.038147
last_seq = 5116
current_ts = 384.055420
current_received_ts = 384.054840
current_seq = 5117
count = 443
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 384.038635/5116, current 384.055420/5117: elapsed=16786.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 384.038635/5116, current 384.055420/5117: elapsed=16786.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 384.055420
last_received_ts = 384.054840
last_seq = 5117
current_ts = 384.072205
current_received_ts = 384.071625
current_seq = 5118
count = 444
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 384.055420/5117, current 384.072205/5118: elapsed=16781.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 384.055420/5117, current 384.072205/5118: elapsed=16781.0us expected=16887.8us
(kms_flip:2920) DEBUG: name = flip
last_ts = 384.072205
last_received_ts = 384.071625
last_seq = 5118
current_ts = 384.088989
current_received_ts = 384.088409
current_seq = 5119
count = 445
seq_step = 1
(kms_flip:2920) DEBUG: flip ts/seq: last 384.072205/5118, current 384.088989/5119: elapsed=16781.0us expected=16887.8us +- 84.4us, error 0.6%
(kms_flip:2920) DEBUG: inconsistent flip ts/seq: last 384.072205/5118, current 384.088989/5119: elapsed=16781.0us expected=16887.8us
(kms_flip:2920) INFO: Event flip: expected 444, counted 446, passrate = 71.52%, encoder type 1
(kms_flip:2920) DEBUG: dropped frames, expected 444, counted 446, passrate = 71.52%, encoder type 1
(kms_flip:2920) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1707:
(kms_flip:2920) CRITICAL: Failed assertion: !retried
(kms_flip:2920) igt_core-INFO: Stack trace:
(kms_flip:2920) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2920) igt_core-INFO:   #1 ../tests/kms_flip.c:428 run_test_on_crtc_set.constprop.0()
(kms_flip:2920) igt_core-INFO:   #2 ../tests/kms_flip.c:1887 run_test()
(kms_flip:2920) igt_core-INFO:   #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043()
(kms_flip:2920) igt_core-INFO:   #4 ../tests/kms_flip.c:2043 main()
(kms_flip:2920) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2920) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2920) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-VGA1: FAIL (18.764s)
Dmesg
<6> [364.151765] [IGT] kms_flip: starting dynamic subtest B-VGA1
<7> [364.152414] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:89]
<7> [364.152601] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:93]
<7> [364.188669] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:52:pipe A]
<7> [364.188907] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.enable (expected yes, found no)
<7> [364.189474] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.active (expected yes, found no)
<7> [364.190026] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1)
<7> [364.190354] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in has_pch_encoder (expected yes, found no)
<7> [364.190649] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in fdi_lanes (expected 1, found 0)
<7> [364.190933] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52: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> [364.191296] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in output_types (expected 0x00000002, found 0x00000000)
<7> [364.191777] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [364.192088] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1024, found 0)
<7> [364.192371] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 1344, found 0)
<7> [364.192659] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1024, found 0)
<7> [364.192894] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 1344, found 0)
<7> [364.193129] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1048, found 0)
<7> [364.193370] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 1184, found 0)
<7> [364.193605] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 768, found 0)
<7> [364.193840] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 768, found 0)
<7> [364.194072] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 771, found 0)
<7> [364.194306] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 777, found 0)
<7> [364.194551] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 806, found 0)
<7> [364.194786] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 806, found 0)
<7> [364.195019] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1024, found 0)
<7> [364.195251] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 1344, found 0)
<7> [364.195522] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1024, found 0)
<7> [364.195757] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 1344, found 0)
<7> [364.195990] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1048, found 0)
<7> [364.196225] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 1184, found 0)
<7> [364.196471] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 768, found 0)
<7> [364.196706] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 768, found 0)
<7> [364.196955] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 771, found 0)
<7> [364.197201] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 777, found 0)
<7> [364.197445] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 806, found 0)
<7> [364.197678] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 806, found 0)
<7> [364.197911] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [364.198145] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)
<7> [364.198406] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)
<7> [364.198643] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0)
<7> [364.198877] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 64800, found 0)
<7> [364.199118] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 64800, found 0)
<7> [364.199367] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:52:pipe A] fastset requirement not met in port_clock (expected 64800, found 0)
<7> [364.199602] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:52:pipe A] fastset requirement not met, forcing full modeset
<7> [364.199837] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:52:pipe A] releasing PCH DPLL A
<7> [364.200113] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:52:pipe A] min cdclk: 72000 kHz -> 0 kHz
<7> [364.200371] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:52:pipe A] enable: no [modeset]
<7> [364.200643] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:34:primary A] fb: [NOFB], visible: no
<7> [364.201181] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A
<7> [364.214863] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found
<7> [364.215375] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found
<7> [364.215935] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found
<7> [364.232039] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PCH DPLL A (active 0x1, on? 1) for [CRTC:52:pipe A]
<7> [364.232553] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PCH DPLL A
<7> [364.233298] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:73:CRT]
<7> [364.233816] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:HDMI D]
<7> [364.234361] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:82:DP D]
<7> [364.234861] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:72:VGA-1]
<7> [364.235525] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:52:pipe A]
<7> [364.236255] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:71:pipe B]
<7> [364.236484] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:71:pipe B]
<7> [364.236555] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:72:VGA-1]
<7> [364.236741] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:72:VGA-1] Limiting target display pipe bpp to 24 (EDID bpp 0, max requested bpp 0, max platform bpp 36)
<7> [364.236991] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:71:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0
<7> [364.237253] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe B, lanes 1
<7> [364.237513] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.enable (expected no, found yes)
<7> [364.237767] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.active (expected no, found yes)
<7> [364.238003] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)
<7> [364.238238] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in has_pch_encoder (expected no, found yes)
<7> [364.238492] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in fdi_lanes (expected 0, found 1)
<7> [364.238755] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71: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> [364.238992] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000002)
<7> [364.239227] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [364.239486] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1024)
<7> [364.239747] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 1344)
<7> [364.239981] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1024)
<7> [364.240215] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 1344)
<7> [364.240485] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1048)
<7> [364.240742] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 1184)
<7> [364.240976] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 768)
<7> [364.241211] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 768)
<7> [364.241492] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 771)
<7> [364.241742] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 777)
<7> [364.241977] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 806)
<7> [364.242211] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 806)
<7> [364.242485] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1024)
<7> [364.242761] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 1344)
<7> [364.243007] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1024)
<7> [364.243258] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 1344)
<7> [364.243510] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1048)
<7> [364.243745] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 1184)
<7> [364.243979] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 768)
<7> [364.244246] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 768)
<7> [364.244507] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 771)
<7> [364.244748] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 777)
<7> [364.244982] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 806)
<7> [364.245269] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 806)
<7> [364.245515] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [364.245771] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)
<7> [364.246006] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)
<7> [364.246270] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in dpll_hw_state
<7> [364.246514] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:
<7> [364.246741] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0xc4010001, dpll_md: 0x0, fp0: 0x30f06, fp1: 0x30f06
<7> [364.246979] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:
<7> [364.247256] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [364.247515] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24)
<7> [364.247743] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 64800)
<7> [364.247971] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 64800)
<7> [364.248298] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in port_clock (expected 0, found 64800)
<7> [364.248561] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:71:pipe B] fastset requirement not met, forcing full modeset
<7> [364.248830] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:71:pipe B] min cdclk: 0 kHz -> 72000 kHz
<7> [364.249106] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:71:pipe B] allocated PCH DPLL A
<7> [364.249346] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:71:pipe B] reserving PCH DPLL A
<7> [364.249575] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:71:pipe B] enable: yes [modeset]
<7> [364.249802] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: ANALOG (0x2), output format: RGB, sink format: RGB
<7> [364.250068] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0
<7> [364.250353] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [364.250585] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [364.250819] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [364.251088] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [364.251357] 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> [364.251591] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0
<7> [364.251823] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1
<7> [364.252091] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0
<7> [364.252339] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0
<7> [364.252573] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0
<7> [364.252805] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0
<7> [364.253065] 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> [364.253087] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on
<7> [364.253323] 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> [364.253557] 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> [364.253812] 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> [364.254062] 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> [364.254296] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 64800, pipe src: 1024x768+0+0, pixel rate 64800, min cdclk 72000
<7> [364.254529] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0
<7> [364.254792] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [364.255044] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [364.255270] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [364.255496] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [364.255760] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [364.256049] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [364.256282] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [364.256514] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [364.256779] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [364.257023] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0
<7> [364.257262] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:53:primary B] fb: [FB:89] 1024x768 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes
<7> [364.257497] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [364.257768] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1024.000000x768.000000+0.000000+0.000000 dst: 1024x768+0+0
<7> [364.259005] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on
<7> [364.259261] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:73:CRT]
<7> [364.259490] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:HDMI D]
<7> [364.259742] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:82:DP D]
<7> [364.260549] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B
<7> [364.261627] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100
<7> [364.261853] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done.
<7> [364.262735] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x200
<7> [364.262973] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done.
<7> [364.263200] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done.
<7> [364.263470] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PCH DPLL A (active 0x2, on? 0) for [CRTC:71:pipe B]
<7> [364.263718] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PCH DPLL A
<7> [364.315759] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:72:VGA-1]
<7> [364.316308] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:71:pipe B]
<7> [374.906743] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:52:pipe A]
<7> [374.907047] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:71:pipe B]
<7> [374.907227] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.enable (expected yes, found no)
<7> [374.907848] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.active (expected yes, found no)
<7> [374.908374] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in cpu_transcoder (expected 1, found -1)
<7> [374.908876] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in has_pch_encoder (expected yes, found no)
<7> [374.909372] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in fdi_lanes (expected 1, found 0)
<7> [374.910055] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in fdi_m_n (expected tu 64 data 6039797/8388608 link 125829/524288, found tu 0, data 0/0 link 0/0)
<7> [374.910604] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in output_types (expected 0x00000002, found 0x00000000)
<7> [374.910842] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [374.911077] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1024, found 0)
<7> [374.911321] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 1344, found 0)
<7> [374.911577] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1024, found 0)
<7> [374.911829] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 1344, found 0)
<7> [374.912190] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1048, found 0)
<7> [374.912591] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 1184, found 0)
<7> [374.912951] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 768, found 0)
<7> [374.913307] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 768, found 0)
<7> [374.913604] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 771, found 0)
<7> [374.913841] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 777, found 0)
<7> [374.914130] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 806, found 0)
<7> [374.914504] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 806, found 0)
<7> [374.914870] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1024, found 0)
<7> [374.915236] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 1344, found 0)
<7> [374.915567] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1024, found 0)
<7> [374.915814] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 1344, found 0)
<7> [374.916116] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1048, found 0)
<7> [374.916524] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 1184, found 0)
<7> [374.916888] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 768, found 0)
<7> [374.917238] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 768, found 0)
<7> [374.917513] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 771, found 0)
<7> [374.917773] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 777, found 0)
<7> [374.918095] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 806, found 0)
<7> [374.918483] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 806, found 0)
<7> [374.918852] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [374.919203] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)
<7> [374.919536] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)
<7> [374.919792] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in pipe_bpp (expected 24, found 0)
<7> [374.920071] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 64800, found 0)
<7> [374.920456] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 64800, found 0)
<7> [374.920827] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in port_clock (expected 64800, found 0)
<7> [374.921181] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:71:pipe B] fastset requirement not met, forcing full modeset
<7> [374.921533] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:71:pipe B] releasing PCH DPLL A
<7> [374.921823] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:71:pipe B] min cdclk: 72000 kHz -> 0 kHz
<7> [374.922143] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:71:pipe B] enable: no [modeset]
<7> [374.922539] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:53:primary B] fb: [NOFB], visible: no
<7> [374.923025] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe B
<7> [374.931448] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found
<7> [374.931674] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found
<7> [374.931890] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found
<7> [374.948044] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PCH DPLL A (active 0x2, on? 1) for [CRTC:71:pipe B]
<7> [374.948577] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PCH DPLL A
<7> [374.949363] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:73:CRT]
<7> [374.950139] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:HDMI D]
<7> [374.950860] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:82:DP D]
<7> [374.951634] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:72:VGA-1]
<7> [374.952043] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:71:pipe B]
<7> [374.952412] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:71:pipe B]
<7> [374.952446] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:72:VGA-1]
<7> [374.952538] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:72:VGA-1] Limiting target display pipe bpp to 24 (EDID bpp 0, max requested bpp 0, max platform bpp 36)
<7> [374.952784] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:71:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0
<7> [374.953050] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe B, lanes 1
<7> [374.953292] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.enable (expected no, found yes)
<7> [374.953521] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.active (expected no, found yes)
<7> [374.953762] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)
<7> [374.954016] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in has_pch_encoder (expected no, found yes)
<7> [374.954252] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in fdi_lanes (expected 0, found 1)
<7> [374.954486] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71: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> [374.954722] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000002)
<7> [374.954971] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [374.955205] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1024)
<7> [374.955439] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 1344)
<7> [374.955673] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1024)
<7> [374.955907] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 1344)
<7> [374.956169] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1048)
<7> [374.956403] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 1184)
<7> [374.956637] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 768)
<7> [374.956871] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 768)
<7> [374.957135] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 771)
<7> [374.957377] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 777)
<7> [374.957604] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 806)
<7> [374.957841] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 806)
<7> [374.958134] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1024)
<7> [374.958385] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 1344)
<7> [374.958619] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1024)
<7> [374.958853] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 1344)
<7> [374.959103] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1048)
<7> [374.959378] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 1184)
<7> [374.959613] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 768)
<7> [374.959847] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 768)
<7> [374.960122] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 771)
<7> [374.960357] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 777)
<7> [374.960591] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 806)
<7> [374.960825] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 806)
<7> [374.961093] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [374.961327] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)
<7> [374.961561] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)
<7> [374.961796] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24)
<7> [374.962042] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 64800)
<7> [374.962276] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 64800)
<7> [374.962510] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in port_clock (expected 0, found 64800)
<7> [374.962745] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:71:pipe B] fastset requirement not met, forcing full modeset
<7> [374.963028] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:71:pipe B] min cdclk: 0 kHz -> 72000 kHz
<7> [374.963270] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:71:pipe B] allocated PCH DPLL A
<7> [374.963511] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:71:pipe B] reserving PCH DPLL A
<7> [374.963753] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:71:pipe B] enable: yes [modeset]
<7> [374.964009] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: ANALOG (0x2), output format: RGB, sink format: RGB
<7> [374.964243] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0
<7> [374.964475] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [374.964707] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [374.964965] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [374.965198] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [374.965430] 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> [374.965664] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0
<7> [374.965914] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1
<7> [374.966147] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0
<7> [374.966378] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0
<7> [374.966612] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0
<7> [374.966866] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0
<7> [374.967116] 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> [374.967349] 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> [374.967582] 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> [374.967832] 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> [374.968069] 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> [374.968316] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 64800, pipe src: 1024x768+0+0, pixel rate 64800, min cdclk 72000
<7> [374.968550] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0
<7> [374.968781] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [374.969032] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [374.969275] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [374.969508] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [374.969741] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [374.970007] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [374.970016] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on
<7> [374.970244] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [374.970471] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [374.970697] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [374.970966] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0
<7> [374.971201] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:53:primary B] fb: [FB:89] 1024x768 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes
<7> [374.971436] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [374.971668] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1024.000000x768.000000+0.000000+0.000000 dst: 1024x768+0+0
<7> [374.971979] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on
<7> [374.972240] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:73:CRT]
<7> [374.972471] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:HDMI D]
<7> [374.972696] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:82:DP D]
<7> [374.973519] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B
<7> [374.974610] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100
<7> [374.974950] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done.
<7> [374.975901] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x200
<7> [374.976143] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done.
<7> [374.976370] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done.
<7> [374.976602] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PCH DPLL A (active 0x2, on? 0) for [CRTC:71:pipe B]
<7> [374.976844] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PCH DPLL A
<7> [375.028831] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:72:VGA-1]
<7> [375.029441] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:71:pipe B]
<6> [382.917775] [IGT] kms_flip: finished subtest B-VGA1, FAIL
Created at 2026-03-06 07:09:03