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.89 seconds
Hostname 
shard-snb4
Igt-Version 
IGT-Version: 2.3-ga50285a68 (x86_64) (Linux: 7.0.0-rc2-CI_DRM_18081-g17ea88b18f33+ 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 16723.7us +- 5.275us accuracy 0.09%
vblank interval differs from modeline! expected 16665.6us, measured 16724us +- 5.275us, difference 58.1us (11.0 sigma)
Event flip: expected 449, counted 440, passrate = 18.64%, encoder type 1
Expected frametime: 16666us; measured 16906.1us +- 1.914us accuracy 0.03%
vblank interval differs from modeline! expected 16665.6us, measured 16906us +- 1.914us, difference 240.5us (125.6 sigma)
Event flip: expected 444, counted 446, passrate = 59.42%, 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.894s)
Err 
Starting dynamic subtest: B-VGA1
(kms_flip:2997) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1707:
(kms_flip:2997) CRITICAL: Failed assertion: !retried
Dynamic subtest B-VGA1 failed.
**** DEBUG ****
(kms_flip:2997) DEBUG: flip ts/seq: last 391.930878/5144, current 391.947693/5145: elapsed=16806.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 391.930878/5144, current 391.947693/5145: elapsed=16806.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 391.947693
last_received_ts = 391.947113
last_seq = 5145
current_ts = 391.964508
current_received_ts = 391.963959
current_seq = 5146
count = 366
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 391.947693/5145, current 391.964508/5146: elapsed=16807.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 391.947693/5145, current 391.964508/5146: elapsed=16807.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 391.964508
last_received_ts = 391.963959
last_seq = 5146
current_ts = 391.981323
current_received_ts = 391.980743
current_seq = 5147
count = 367
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 391.964508/5146, current 391.981323/5147: elapsed=16806.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 391.964508/5146, current 391.981323/5147: elapsed=16806.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 391.981323
last_received_ts = 391.980743
last_seq = 5147
current_ts = 391.998108
current_received_ts = 391.997559
current_seq = 5148
count = 368
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 391.981323/5147, current 391.998108/5148: elapsed=16807.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 391.981323/5147, current 391.998108/5148: elapsed=16807.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 391.998108
last_received_ts = 391.997559
last_seq = 5148
current_ts = 392.014923
current_received_ts = 392.014343
current_seq = 5149
count = 369
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 391.998108/5148, current 392.014923/5149: elapsed=16799.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 391.998108/5148, current 392.014923/5149: elapsed=16799.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.014923
last_received_ts = 392.014343
last_seq = 5149
current_ts = 392.031738
current_received_ts = 392.031158
current_seq = 5150
count = 370
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.014923/5149, current 392.031738/5150: elapsed=16811.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.014923/5149, current 392.031738/5150: elapsed=16811.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.031738
last_received_ts = 392.031158
last_seq = 5150
current_ts = 392.048523
current_received_ts = 392.047974
current_seq = 5151
count = 371
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.031738/5150, current 392.048523/5151: elapsed=16809.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.031738/5150, current 392.048523/5151: elapsed=16809.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.048523
last_received_ts = 392.047974
last_seq = 5151
current_ts = 392.065338
current_received_ts = 392.064758
current_seq = 5152
count = 372
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.048523/5151, current 392.065338/5152: elapsed=16806.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.048523/5151, current 392.065338/5152: elapsed=16806.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.065338
last_received_ts = 392.064758
last_seq = 5152
current_ts = 392.082153
current_received_ts = 392.081573
current_seq = 5153
count = 373
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.065338/5152, current 392.082153/5153: elapsed=16806.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.065338/5152, current 392.082153/5153: elapsed=16806.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.082153
last_received_ts = 392.081573
last_seq = 5153
current_ts = 392.098969
current_received_ts = 392.098389
current_seq = 5154
count = 374
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.082153/5153, current 392.098969/5154: elapsed=16807.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.082153/5153, current 392.098969/5154: elapsed=16807.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.098969
last_received_ts = 392.098389
last_seq = 5154
current_ts = 392.115753
current_received_ts = 392.115204
current_seq = 5155
count = 375
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.098969/5154, current 392.115753/5155: elapsed=16806.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.098969/5154, current 392.115753/5155: elapsed=16806.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.115753
last_received_ts = 392.115204
last_seq = 5155
current_ts = 392.132568
current_received_ts = 392.132050
current_seq = 5156
count = 376
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.115753/5155, current 392.132568/5156: elapsed=16807.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.115753/5155, current 392.132568/5156: elapsed=16807.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.132568
last_received_ts = 392.132050
last_seq = 5156
current_ts = 392.149384
current_received_ts = 392.148834
current_seq = 5157
count = 377
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.132568/5156, current 392.149384/5157: elapsed=16806.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.132568/5156, current 392.149384/5157: elapsed=16806.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.149384
last_received_ts = 392.148834
last_seq = 5157
current_ts = 392.166168
current_received_ts = 392.165619
current_seq = 5158
count = 378
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.149384/5157, current 392.166168/5158: elapsed=16807.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.149384/5157, current 392.166168/5158: elapsed=16807.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.166168
last_received_ts = 392.165619
last_seq = 5158
current_ts = 392.182983
current_received_ts = 392.182434
current_seq = 5159
count = 379
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.166168/5158, current 392.182983/5159: elapsed=16815.0us expected=16906.1us +- 84.5us, error 0.5%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.166168/5158, current 392.182983/5159: elapsed=16815.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.182983
last_received_ts = 392.182434
last_seq = 5159
current_ts = 392.199768
current_received_ts = 392.199219
current_seq = 5160
count = 380
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.182983/5159, current 392.199768/5160: elapsed=16787.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.182983/5159, current 392.199768/5160: elapsed=16787.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.199768
last_received_ts = 392.199219
last_seq = 5160
current_ts = 392.216583
current_received_ts = 392.216034
current_seq = 5161
count = 381
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.199768/5160, current 392.216583/5161: elapsed=16797.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.199768/5160, current 392.216583/5161: elapsed=16797.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.216583
last_received_ts = 392.216034
last_seq = 5161
current_ts = 392.233368
current_received_ts = 392.232788
current_seq = 5162
count = 382
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.216583/5161, current 392.233368/5162: elapsed=16795.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.216583/5161, current 392.233368/5162: elapsed=16795.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.233368
last_received_ts = 392.232788
last_seq = 5162
current_ts = 392.250183
current_received_ts = 392.249603
current_seq = 5163
count = 383
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.233368/5162, current 392.250183/5163: elapsed=16796.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.233368/5162, current 392.250183/5163: elapsed=16796.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.250183
last_received_ts = 392.249603
last_seq = 5163
current_ts = 392.266968
current_received_ts = 392.266388
current_seq = 5164
count = 384
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.250183/5163, current 392.266968/5164: elapsed=16796.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.250183/5163, current 392.266968/5164: elapsed=16796.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.266968
last_received_ts = 392.266388
last_seq = 5164
current_ts = 392.283752
current_received_ts = 392.283203
current_seq = 5165
count = 385
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.266968/5164, current 392.283752/5165: elapsed=16796.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.266968/5164, current 392.283752/5165: elapsed=16796.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.283752
last_received_ts = 392.283203
last_seq = 5165
current_ts = 392.300568
current_received_ts = 392.299988
current_seq = 5166
count = 386
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.283752/5165, current 392.300568/5166: elapsed=16798.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.283752/5165, current 392.300568/5166: elapsed=16798.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.300568
last_received_ts = 392.299988
last_seq = 5166
current_ts = 392.317352
current_received_ts = 392.316803
current_seq = 5167
count = 387
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.300568/5166, current 392.317352/5167: elapsed=16795.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.300568/5166, current 392.317352/5167: elapsed=16795.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.317352
last_received_ts = 392.316803
last_seq = 5167
current_ts = 392.334137
current_received_ts = 392.333588
current_seq = 5168
count = 388
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.317352/5167, current 392.334137/5168: elapsed=16794.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.317352/5167, current 392.334137/5168: elapsed=16794.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.334137
last_received_ts = 392.333588
last_seq = 5168
current_ts = 392.350952
current_received_ts = 392.350372
current_seq = 5169
count = 389
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.334137/5168, current 392.350952/5169: elapsed=16796.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.334137/5168, current 392.350952/5169: elapsed=16796.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.350952
last_received_ts = 392.350372
last_seq = 5169
current_ts = 392.367737
current_received_ts = 392.367188
current_seq = 5170
count = 390
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.350952/5169, current 392.367737/5170: elapsed=16799.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.350952/5169, current 392.367737/5170: elapsed=16799.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.367737
last_received_ts = 392.367188
last_seq = 5170
current_ts = 392.384552
current_received_ts = 392.383972
current_seq = 5171
count = 391
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.367737/5170, current 392.384552/5171: elapsed=16806.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.367737/5170, current 392.384552/5171: elapsed=16806.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.384552
last_received_ts = 392.383972
last_seq = 5171
current_ts = 392.401337
current_received_ts = 392.400787
current_seq = 5172
count = 392
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.384552/5171, current 392.401337/5172: elapsed=16786.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.384552/5171, current 392.401337/5172: elapsed=16786.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.401337
last_received_ts = 392.400787
last_seq = 5172
current_ts = 392.418121
current_received_ts = 392.417542
current_seq = 5173
count = 393
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.401337/5172, current 392.418121/5173: elapsed=16797.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.401337/5172, current 392.418121/5173: elapsed=16797.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.418121
last_received_ts = 392.417542
last_seq = 5173
current_ts = 392.434937
current_received_ts = 392.434357
current_seq = 5174
count = 394
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.418121/5173, current 392.434937/5174: elapsed=16796.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.418121/5173, current 392.434937/5174: elapsed=16796.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.434937
last_received_ts = 392.434357
last_seq = 5174
current_ts = 392.451721
current_received_ts = 392.451050
current_seq = 5175
count = 395
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.434937/5174, current 392.451721/5175: elapsed=16796.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.434937/5174, current 392.451721/5175: elapsed=16796.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.451721
last_received_ts = 392.451050
last_seq = 5175
current_ts = 392.468536
current_received_ts = 392.467957
current_seq = 5176
count = 396
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.451721/5175, current 392.468536/5176: elapsed=16798.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.451721/5175, current 392.468536/5176: elapsed=16798.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.468536
last_received_ts = 392.467957
last_seq = 5176
current_ts = 392.485321
current_received_ts = 392.484741
current_seq = 5177
count = 397
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.468536/5176, current 392.485321/5177: elapsed=16795.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.468536/5176, current 392.485321/5177: elapsed=16795.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.485321
last_received_ts = 392.484741
last_seq = 5177
current_ts = 392.502106
current_received_ts = 392.501556
current_seq = 5178
count = 398
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.485321/5177, current 392.502106/5178: elapsed=16797.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.485321/5177, current 392.502106/5178: elapsed=16797.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.502106
last_received_ts = 392.501556
last_seq = 5178
current_ts = 392.518921
current_received_ts = 392.518341
current_seq = 5179
count = 399
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.502106/5178, current 392.518921/5179: elapsed=16796.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.502106/5178, current 392.518921/5179: elapsed=16796.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.518921
last_received_ts = 392.518341
last_seq = 5179
current_ts = 392.535706
current_received_ts = 392.535126
current_seq = 5180
count = 400
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.518921/5179, current 392.535706/5180: elapsed=16795.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.518921/5179, current 392.535706/5180: elapsed=16795.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.535706
last_received_ts = 392.535126
last_seq = 5180
current_ts = 392.552490
current_received_ts = 392.551941
current_seq = 5181
count = 401
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.535706/5180, current 392.552490/5181: elapsed=16798.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.535706/5180, current 392.552490/5181: elapsed=16798.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.552490
last_received_ts = 392.551941
last_seq = 5181
current_ts = 392.569305
current_received_ts = 392.568726
current_seq = 5182
count = 402
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.552490/5181, current 392.569305/5182: elapsed=16794.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.552490/5181, current 392.569305/5182: elapsed=16794.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.569305
last_received_ts = 392.568726
last_seq = 5182
current_ts = 392.586090
current_received_ts = 392.585541
current_seq = 5183
count = 403
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.569305/5182, current 392.586090/5183: elapsed=16798.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.569305/5182, current 392.586090/5183: elapsed=16798.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.586090
last_received_ts = 392.585541
last_seq = 5183
current_ts = 392.602905
current_received_ts = 392.602356
current_seq = 5184
count = 404
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.586090/5183, current 392.602905/5184: elapsed=16798.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.586090/5183, current 392.602905/5184: elapsed=16798.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.602905
last_received_ts = 392.602356
last_seq = 5184
current_ts = 392.619690
current_received_ts = 392.619080
current_seq = 5185
count = 405
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.602905/5184, current 392.619690/5185: elapsed=16786.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.602905/5184, current 392.619690/5185: elapsed=16786.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.619690
last_received_ts = 392.619080
last_seq = 5185
current_ts = 392.636475
current_received_ts = 392.635895
current_seq = 5186
count = 406
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.619690/5185, current 392.636475/5186: elapsed=16804.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.619690/5185, current 392.636475/5186: elapsed=16804.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.636475
last_received_ts = 392.635895
last_seq = 5186
current_ts = 392.653290
current_received_ts = 392.652710
current_seq = 5187
count = 407
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.636475/5186, current 392.653290/5187: elapsed=16796.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.636475/5186, current 392.653290/5187: elapsed=16796.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.653290
last_received_ts = 392.652710
last_seq = 5187
current_ts = 392.670074
current_received_ts = 392.669495
current_seq = 5188
count = 408
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.653290/5187, current 392.670074/5188: elapsed=16793.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.653290/5187, current 392.670074/5188: elapsed=16793.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.670074
last_received_ts = 392.669495
last_seq = 5188
current_ts = 392.686859
current_received_ts = 392.686279
current_seq = 5189
count = 409
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.670074/5188, current 392.686859/5189: elapsed=16800.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.670074/5188, current 392.686859/5189: elapsed=16800.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.686859
last_received_ts = 392.686279
last_seq = 5189
current_ts = 392.703674
current_received_ts = 392.703094
current_seq = 5190
count = 410
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.686859/5189, current 392.703674/5190: elapsed=16796.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.686859/5189, current 392.703674/5190: elapsed=16796.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.703674
last_received_ts = 392.703094
last_seq = 5190
current_ts = 392.720459
current_received_ts = 392.719879
current_seq = 5191
count = 411
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.703674/5190, current 392.720459/5191: elapsed=16796.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.703674/5190, current 392.720459/5191: elapsed=16796.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.720459
last_received_ts = 392.719879
last_seq = 5191
current_ts = 392.737274
current_received_ts = 392.736633
current_seq = 5192
count = 412
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.720459/5191, current 392.737274/5192: elapsed=16807.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.720459/5191, current 392.737274/5192: elapsed=16807.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.737274
last_received_ts = 392.736633
last_seq = 5192
current_ts = 392.754059
current_received_ts = 392.753510
current_seq = 5193
count = 413
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.737274/5192, current 392.754059/5193: elapsed=16785.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.737274/5192, current 392.754059/5193: elapsed=16785.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.754059
last_received_ts = 392.753510
last_seq = 5193
current_ts = 392.770844
current_received_ts = 392.770264
current_seq = 5194
count = 414
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.754059/5193, current 392.770844/5194: elapsed=16797.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.754059/5193, current 392.770844/5194: elapsed=16797.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.770844
last_received_ts = 392.770264
last_seq = 5194
current_ts = 392.787659
current_received_ts = 392.787079
current_seq = 5195
count = 415
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.770844/5194, current 392.787659/5195: elapsed=16795.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.770844/5194, current 392.787659/5195: elapsed=16795.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.787659
last_received_ts = 392.787079
last_seq = 5195
current_ts = 392.804443
current_received_ts = 392.803864
current_seq = 5196
count = 416
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.787659/5195, current 392.804443/5196: elapsed=16793.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.787659/5195, current 392.804443/5196: elapsed=16793.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.804443
last_received_ts = 392.803864
last_seq = 5196
current_ts = 392.821228
current_received_ts = 392.820709
current_seq = 5197
count = 417
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.804443/5196, current 392.821228/5197: elapsed=16800.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.804443/5196, current 392.821228/5197: elapsed=16800.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.821228
last_received_ts = 392.820709
last_seq = 5197
current_ts = 392.838043
current_received_ts = 392.837311
current_seq = 5198
count = 418
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.821228/5197, current 392.838043/5198: elapsed=16793.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.821228/5197, current 392.838043/5198: elapsed=16793.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.838043
last_received_ts = 392.837311
last_seq = 5198
current_ts = 392.854828
current_received_ts = 392.854156
current_seq = 5199
count = 419
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.838043/5198, current 392.854828/5199: elapsed=16804.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.838043/5198, current 392.854828/5199: elapsed=16804.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.854828
last_received_ts = 392.854156
last_seq = 5199
current_ts = 392.871643
current_received_ts = 392.870941
current_seq = 5200
count = 420
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.854828/5199, current 392.871643/5200: elapsed=16795.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.854828/5199, current 392.871643/5200: elapsed=16795.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.871643
last_received_ts = 392.870941
last_seq = 5200
current_ts = 392.888428
current_received_ts = 392.887726
current_seq = 5201
count = 421
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.871643/5200, current 392.888428/5201: elapsed=16795.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.871643/5200, current 392.888428/5201: elapsed=16795.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.888428
last_received_ts = 392.887726
last_seq = 5201
current_ts = 392.905212
current_received_ts = 392.904663
current_seq = 5202
count = 422
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.888428/5201, current 392.905212/5202: elapsed=16791.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.888428/5201, current 392.905212/5202: elapsed=16791.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.905212
last_received_ts = 392.904663
last_seq = 5202
current_ts = 392.922028
current_received_ts = 392.921478
current_seq = 5203
count = 423
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.905212/5202, current 392.922028/5203: elapsed=16802.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.905212/5202, current 392.922028/5203: elapsed=16802.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.922028
last_received_ts = 392.921478
last_seq = 5203
current_ts = 392.938812
current_received_ts = 392.938263
current_seq = 5204
count = 424
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.922028/5203, current 392.938812/5204: elapsed=16794.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.922028/5203, current 392.938812/5204: elapsed=16794.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.938812
last_received_ts = 392.938263
last_seq = 5204
current_ts = 392.955597
current_received_ts = 392.955078
current_seq = 5205
count = 425
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.938812/5204, current 392.955597/5205: elapsed=16796.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.938812/5204, current 392.955597/5205: elapsed=16796.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.955597
last_received_ts = 392.955078
last_seq = 5205
current_ts = 392.972412
current_received_ts = 392.971863
current_seq = 5206
count = 426
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.955597/5205, current 392.972412/5206: elapsed=16793.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.955597/5205, current 392.972412/5206: elapsed=16793.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.972412
last_received_ts = 392.971863
last_seq = 5206
current_ts = 392.989197
current_received_ts = 392.988647
current_seq = 5207
count = 427
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.972412/5206, current 392.989197/5207: elapsed=16800.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.972412/5206, current 392.989197/5207: elapsed=16800.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 392.989197
last_received_ts = 392.988647
last_seq = 5207
current_ts = 393.006012
current_received_ts = 393.005432
current_seq = 5208
count = 428
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 392.989197/5207, current 393.006012/5208: elapsed=16796.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 392.989197/5207, current 393.006012/5208: elapsed=16796.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 393.006012
last_received_ts = 393.005432
last_seq = 5208
current_ts = 393.022797
current_received_ts = 393.022247
current_seq = 5209
count = 429
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 393.006012/5208, current 393.022797/5209: elapsed=16796.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 393.006012/5208, current 393.022797/5209: elapsed=16796.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 393.022797
last_received_ts = 393.022247
last_seq = 5209
current_ts = 393.039581
current_received_ts = 393.039032
current_seq = 5210
count = 430
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 393.022797/5209, current 393.039581/5210: elapsed=16794.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 393.022797/5209, current 393.039581/5210: elapsed=16794.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 393.039581
last_received_ts = 393.039032
last_seq = 5210
current_ts = 393.056396
current_received_ts = 393.055817
current_seq = 5211
count = 431
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 393.039581/5210, current 393.056396/5211: elapsed=16799.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 393.039581/5210, current 393.056396/5211: elapsed=16799.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 393.056396
last_received_ts = 393.055817
last_seq = 5211
current_ts = 393.073181
current_received_ts = 393.072601
current_seq = 5212
count = 432
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 393.056396/5211, current 393.073181/5212: elapsed=16798.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 393.056396/5211, current 393.073181/5212: elapsed=16798.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 393.073181
last_received_ts = 393.072601
last_seq = 5212
current_ts = 393.089996
current_received_ts = 393.089386
current_seq = 5213
count = 433
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 393.073181/5212, current 393.089996/5213: elapsed=16794.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 393.073181/5212, current 393.089996/5213: elapsed=16794.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 393.089996
last_received_ts = 393.089386
last_seq = 5213
current_ts = 393.106781
current_received_ts = 393.106201
current_seq = 5214
count = 434
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 393.089996/5213, current 393.106781/5214: elapsed=16796.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 393.089996/5213, current 393.106781/5214: elapsed=16796.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 393.106781
last_received_ts = 393.106201
last_seq = 5214
current_ts = 393.123566
current_received_ts = 393.123047
current_seq = 5215
count = 435
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 393.106781/5214, current 393.123566/5215: elapsed=16796.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 393.106781/5214, current 393.123566/5215: elapsed=16796.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 393.123566
last_received_ts = 393.123047
last_seq = 5215
current_ts = 393.140381
current_received_ts = 393.139801
current_seq = 5216
count = 436
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 393.123566/5215, current 393.140381/5216: elapsed=16797.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 393.123566/5215, current 393.140381/5216: elapsed=16797.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 393.140381
last_received_ts = 393.139801
last_seq = 5216
current_ts = 393.157166
current_received_ts = 393.156586
current_seq = 5217
count = 437
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 393.140381/5216, current 393.157166/5217: elapsed=16794.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 393.140381/5216, current 393.157166/5217: elapsed=16794.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 393.157166
last_received_ts = 393.156586
last_seq = 5217
current_ts = 393.173950
current_received_ts = 393.173370
current_seq = 5218
count = 438
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 393.157166/5217, current 393.173950/5218: elapsed=16798.0us expected=16906.1us +- 84.5us, error 0.6%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 393.157166/5217, current 393.173950/5218: elapsed=16798.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 393.173950
last_received_ts = 393.173370
last_seq = 5218
current_ts = 393.190765
current_received_ts = 393.190155
current_seq = 5219
count = 439
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 393.173950/5218, current 393.190765/5219: elapsed=16790.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 393.173950/5218, current 393.190765/5219: elapsed=16790.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 393.190765
last_received_ts = 393.190155
last_seq = 5219
current_ts = 393.207550
current_received_ts = 393.206970
current_seq = 5220
count = 440
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 393.190765/5219, current 393.207550/5220: elapsed=16789.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 393.190765/5219, current 393.207550/5220: elapsed=16789.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 393.207550
last_received_ts = 393.206970
last_seq = 5220
current_ts = 393.224335
current_received_ts = 393.223755
current_seq = 5221
count = 441
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 393.207550/5220, current 393.224335/5221: elapsed=16786.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 393.207550/5220, current 393.224335/5221: elapsed=16786.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 393.224335
last_received_ts = 393.223755
last_seq = 5221
current_ts = 393.241119
current_received_ts = 393.240540
current_seq = 5222
count = 442
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 393.224335/5221, current 393.241119/5222: elapsed=16788.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 393.224335/5221, current 393.241119/5222: elapsed=16788.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 393.241119
last_received_ts = 393.240540
last_seq = 5222
current_ts = 393.257904
current_received_ts = 393.257355
current_seq = 5223
count = 443
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 393.241119/5222, current 393.257904/5223: elapsed=16778.0us expected=16906.1us +- 84.5us, error 0.8%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 393.241119/5222, current 393.257904/5223: elapsed=16778.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 393.257904
last_received_ts = 393.257355
last_seq = 5223
current_ts = 393.274689
current_received_ts = 393.274170
current_seq = 5224
count = 444
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 393.257904/5223, current 393.274689/5224: elapsed=16796.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 393.257904/5223, current 393.274689/5224: elapsed=16796.0us expected=16906.1us
(kms_flip:2997) DEBUG: name = flip
last_ts = 393.274689
last_received_ts = 393.274170
last_seq = 5224
current_ts = 393.291473
current_received_ts = 393.290985
current_seq = 5225
count = 445
seq_step = 1
(kms_flip:2997) DEBUG: flip ts/seq: last 393.274689/5224, current 393.291473/5225: elapsed=16788.0us expected=16906.1us +- 84.5us, error 0.7%
(kms_flip:2997) DEBUG: inconsistent flip ts/seq: last 393.274689/5224, current 393.291473/5225: elapsed=16788.0us expected=16906.1us
(kms_flip:2997) INFO: Event flip: expected 444, counted 446, passrate = 59.42%, encoder type 1
(kms_flip:2997) DEBUG: dropped frames, expected 444, counted 446, passrate = 59.42%, encoder type 1
(kms_flip:2997) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1707:
(kms_flip:2997) CRITICAL: Failed assertion: !retried
(kms_flip:2997) igt_core-INFO: Stack trace:
(kms_flip:2997) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2997) igt_core-INFO:   #1 ../tests/kms_flip.c:428 run_test_on_crtc_set.constprop.0()
(kms_flip:2997) igt_core-INFO:   #2 ../tests/kms_flip.c:1887 run_test()
(kms_flip:2997) igt_core-INFO:   #3 ../tests/kms_flip.c:2120 __igt_unique____real_main2043()
(kms_flip:2997) igt_core-INFO:   #4 ../tests/kms_flip.c:2043 main()
(kms_flip:2997) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2997) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2997) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-VGA1: FAIL (18.894s)
Dmesg
<6> [373.774886] [IGT] kms_flip: starting dynamic subtest B-VGA1
<7> [373.775361] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:89]
<7> [373.775496] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:91]
<7> [373.810485] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:52:pipe A]
<7> [373.810695] 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> [373.811272] 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> [373.811828] 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> [373.812364] 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> [373.812913] 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> [373.813486] 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> [373.814112] 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> [373.814374] 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> [373.814604] 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> [373.814888] 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> [373.815186] 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> [373.815444] 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> [373.815695] 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> [373.815965] 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> [373.816230] 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> [373.816459] 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> [373.816724] 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> [373.817022] 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> [373.817288] 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> [373.817516] 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> [373.817745] 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> [373.818022] 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> [373.818288] 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> [373.818516] 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> [373.818743] 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> [373.819010] 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> [373.819250] 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> [373.819478] 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> [373.819706] 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> [373.819969] 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> [373.820228] 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> [373.820466] 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> [373.820696] 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> [373.820978] 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> [373.821216] 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> [373.821484] 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> [373.821738] 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> [373.822023] 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> [373.822263] 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> [373.822492] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:52:pipe A] fastset requirement not met, forcing full modeset
<7> [373.822722] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:52:pipe A] releasing PCH DPLL A
<7> [373.823077] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:52:pipe A] min cdclk: 72000 kHz -> 0 kHz
<7> [373.823341] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:52:pipe A] enable: no [modeset]
<7> [373.823583] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:34:primary A] fb: [NOFB], visible: no
<7> [373.824022] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A
<7> [373.840150] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found
<7> [373.840632] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found
<7> [373.841145] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found
<7> [373.857753] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PCH DPLL A (active 0x1, on? 1) for [CRTC:52:pipe A]
<7> [373.858303] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PCH DPLL A
<7> [373.859016] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:73:CRT]
<7> [373.859495] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:HDMI D]
<7> [373.860005] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:82:DP D]
<7> [373.860472] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:72:VGA-1]
<7> [373.861239] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:52:pipe A]
<7> [373.861617] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:71:pipe B]
<7> [373.861755] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:71:pipe B]
<7> [373.861782] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:72:VGA-1]
<7> [373.861896] 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> [373.862149] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:71:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0
<7> [373.862380] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe B, lanes 1
<7> [373.862646] 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> [373.862943] 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> [373.863203] 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> [373.863433] 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> [373.863662] 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> [373.863940] 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> [373.864217] 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> [373.864494] 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> [373.864754] 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> [373.865043] 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> [373.865283] 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> [373.865512] 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> [373.865751] 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> [373.866057] 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> [373.866313] 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> [373.866557] 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> [373.866793] 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> [373.867053] 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> [373.867289] 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> [373.867582] 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> [373.867849] 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> [373.868085] 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> [373.868325] 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> [373.868569] 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> [373.868804] 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> [373.869055] 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> [373.869295] 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> [373.869544] 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> [373.869778] 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> [373.870075] 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> [373.870322] 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> [373.870564] 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> [373.870800] 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> [373.871064] 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> [373.871310] 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> [373.871559] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:71:pipe B] fastset requirement not met in dpll_hw_state
<7> [373.871794] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:
<7> [373.872043] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0xc4010001, dpll_md: 0x0, fp0: 0x30f06, fp1: 0x30f06
<7> [373.872278] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:
<7> [373.872512] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [373.872747] 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> [373.873002] 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> [373.873238] 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> [373.873472] 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> [373.873707] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:71:pipe B] fastset requirement not met, forcing full modeset
<7> [373.873985] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:71:pipe B] min cdclk: 0 kHz -> 72000 kHz
<7> [373.874221] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:71:pipe B] allocated PCH DPLL A
<7> [373.874452] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:71:pipe B] reserving PCH DPLL A
<7> [373.874687] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:71:pipe B] enable: yes [modeset]
<7> [373.874950] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: ANALOG (0x2), output format: RGB, sink format: RGB
<7> [373.875192] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0
<7> [373.875418] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [373.875644] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [373.875921] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [373.876173] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [373.876399] 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> [373.876627] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0
<7> [373.876891] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1
<7> [373.877129] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0
<7> [373.877356] 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> [373.877584] 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> [373.877848] 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> [373.878094] 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> [373.878323] 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> [373.878551] 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> [373.878779] 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> [373.879137] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on
<7> [373.879137] 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> [373.879424] 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> [373.879659] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0
<7> [373.879913] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [373.880148] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [373.880382] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [373.880616] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [373.880880] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [373.881129] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [373.881363] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [373.881597] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [373.881841] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [373.882094] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0
<7> [373.882370] 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> [373.882613] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [373.882864] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1024.000000x768.000000+0.000000+0.000000 dst: 1024x768+0+0
<7> [373.884020] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on
<7> [373.884266] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:73:CRT]
<7> [373.884490] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:HDMI D]
<7> [373.884712] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:82:DP D]
<7> [373.885558] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B
<7> [373.886815] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100
<7> [373.887141] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done.
<7> [373.888190] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x200
<7> [373.888529] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done.
<7> [373.888788] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done.
<7> [373.889132] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PCH DPLL A (active 0x2, on? 0) for [CRTC:71:pipe B]
<7> [373.889493] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PCH DPLL A
<7> [373.941640] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:72:VGA-1]
<7> [373.942230] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:71:pipe B]
<7> [384.578657] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:52:pipe A]
<7> [384.578974] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:71:pipe B]
<7> [384.579153] 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> [384.579773] 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> [384.580250] 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> [384.580834] 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> [384.581333] 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> [384.581934] 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> [384.582235] 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> [384.582474] 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> [384.582727] 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> [384.582973] 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> [384.583218] 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> [384.583446] 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> [384.583717] 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> [384.583962] 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> [384.584190] 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> [384.584431] 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> [384.584720] 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> [384.584973] 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> [384.585201] 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> [384.585430] 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> [384.585702] 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> [384.585948] 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> [384.586192] 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> [384.586420] 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> [384.586687] 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> [384.586933] 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> [384.587162] 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> [384.587389] 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> [384.587666] 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> [384.587931] 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> [384.588174] 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> [384.588401] 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> [384.588664] 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> [384.588908] 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> [384.589144] 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> [384.589380] 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> [384.589650] 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> [384.589910] 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> [384.590138] 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> [384.590367] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:71:pipe B] fastset requirement not met, forcing full modeset
<7> [384.590644] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:71:pipe B] releasing PCH DPLL A
<7> [384.590936] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:71:pipe B] min cdclk: 72000 kHz -> 0 kHz
<7> [384.591169] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:71:pipe B] enable: no [modeset]
<7> [384.591410] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:53:primary B] fb: [NOFB], visible: no
<7> [384.591773] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe B
<7> [384.608907] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found
<7> [384.609426] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found
<7> [384.609894] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found
<7> [384.626120] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PCH DPLL A (active 0x2, on? 1) for [CRTC:71:pipe B]
<7> [384.626635] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PCH DPLL A
<7> [384.627403] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:73:CRT]
<7> [384.628108] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:HDMI D]
<7> [384.628764] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:82:DP D]
<7> [384.629578] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:72:VGA-1]
<7> [384.630126] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:71:pipe B]
<7> [384.630544] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:71:pipe B]
<7> [384.630591] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:72:VGA-1]
<7> [384.630754] 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> [384.631165] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:71:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0
<7> [384.631521] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe B, lanes 1
<7> [384.631870] 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> [384.632406] 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> [384.632784] 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> [384.633177] 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> [384.633532] 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> [384.633927] 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> [384.634391] 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> [384.634781] 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> [384.635184] 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> [384.635558] 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> [384.635911] 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> [384.636327] 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> [384.636704] 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> [384.637090] 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> [384.637445] 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> [384.637798] 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> [384.638267] 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> [384.638696] 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> [384.639101] 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> [384.639458] 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> [384.639811] 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> [384.640222] 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> [384.640595] 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> [384.641002] 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> [384.641392] 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> [384.641746] 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> [384.642177] 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> [384.642570] 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> [384.642998] 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> [384.643279] 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> [384.643533] 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> [384.643763] 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> [384.644036] 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> [384.644271] 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> [384.644552] 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> [384.644808] 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> [384.645095] 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> [384.645331] 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> [384.645566] 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> [384.645802] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:71:pipe B] fastset requirement not met, forcing full modeset
<7> [384.646104] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:71:pipe B] min cdclk: 0 kHz -> 72000 kHz
<7> [384.646366] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:71:pipe B] allocated PCH DPLL A
<7> [384.646616] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:71:pipe B] reserving PCH DPLL A
<7> [384.646865] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:71:pipe B] enable: yes [modeset]
<7> [384.647101] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: ANALOG (0x2), output format: RGB, sink format: RGB
<7> [384.647344] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0
<7> [384.647594] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [384.647892] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on
<7> [384.647900] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [384.648271] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [384.648522] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [384.648770] 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> [384.649079] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0
<7> [384.649349] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1
<7> [384.649583] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0
<7> [384.649841] 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> [384.650112] 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> [384.650387] 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> [384.650640] 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> [384.650953] 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> [384.651216] 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> [384.651446] 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> [384.651674] 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> [384.651971] 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> [384.652278] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0
<7> [384.652520] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [384.652755] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [384.653012] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [384.653282] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [384.653535] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [384.653822] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [384.654070] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [384.654304] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [384.654550] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [384.654812] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0
<7> [384.655097] 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> [384.655334] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [384.655567] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1024.000000x768.000000+0.000000+0.000000 dst: 1024x768+0+0
<7> [384.655933] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on
<7> [384.656230] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:73:CRT]
<7> [384.656473] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:HDMI D]
<7> [384.656722] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:82:DP D]
<7> [384.657575] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B
<7> [384.658696] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100
<7> [384.658982] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done.
<7> [384.659907] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x200
<7> [384.660142] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done.
<7> [384.660378] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done.
<7> [384.660640] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PCH DPLL A (active 0x2, on? 0) for [CRTC:71:pipe B]
<7> [384.660908] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PCH DPLL A
<7> [384.712854] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:72:VGA-1]
<7> [384.713483] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:71:pipe B]
<6> [392.669583] [IGT] kms_flip: finished subtest B-VGA1, FAIL
Created at 2026-03-03 17:36:37