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

Result: Fail

git-log-oneline i915_display_info22 igt_runner22 runtimes22 results22.json results22-i915-load.json guc_logs22.tar i915_display_info_post_exec22 boot22 dmesg22

DetailValue
Duration 18.78 seconds
Hostname 
shard-snb4
Igt-Version 
IGT-Version: 2.4-g8966d7c15 (x86_64) (Linux: 7.1.0-rc3-CI_DRM_18470-g767b83aa80c6+ 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 16719.6us +- 9.164us accuracy 0.16%
vblank interval differs from modeline! expected 16665.6us, measured 16720us +- 9.164us, difference 54.0us (5.9 sigma)
Event flip: expected 449, counted 440, passrate = 13.64%, encoder type 1
Event vblank: expected 449, counted 440, passrate = 11.36%, encoder type 1
Expected frametime: 16666us; measured 16891.7us +- 12.515us accuracy 0.22%
vblank interval differs from modeline! expected 16665.6us, measured 16892us +- 12.515us, difference 226.1us (18.1 sigma)
Event flip: expected 448, counted 450, passrate = 66.67%, encoder type 1
Event vblank: expected 448, counted 450, passrate = 64.44%, encoder type 1
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:1071 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-VGA1: FAIL (18.780s)
Err 
Starting dynamic subtest: B-VGA1
(kms_flip:2796) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1722:
(kms_flip:2796) CRITICAL: Failed assertion: !retried
(kms_flip:2796) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-VGA1 failed.
**** DEBUG ****
(kms_flip:2796) DEBUG: vblank ts/seq: last 326.551239/12118, current 326.721191/12128: elapsed=169934.0us expected=167196.2us +- 836.0us, error 1.6%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 326.551239/12118, current 326.721191/12128: elapsed=169934.0us expected=167196.2us
(kms_flip:2796) DEBUG: name = flip
last_ts = 326.568268
last_received_ts = 326.567688
last_seq = 12119
current_ts = 326.738159
current_received_ts = 326.737549
current_seq = 12129
count = 41
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 326.568268/12119, current 326.738159/12129: elapsed=169887.0us expected=167196.2us +- 836.0us, error 1.6%
(kms_flip:2796) DEBUG: inconsistent flip ts/seq: last 326.568268/12119, current 326.738159/12129: elapsed=169887.0us expected=167196.2us
(kms_flip:2796) DEBUG: name = vblank
last_ts = 326.721191
last_received_ts = 326.720551
last_seq = 12128
current_ts = 326.890961
current_received_ts = 326.890320
current_seq = 12138
count = 41
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 326.721191/12128, current 326.890961/12138: elapsed=169793.0us expected=167196.2us +- 836.0us, error 1.6%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 326.721191/12128, current 326.890961/12138: elapsed=169793.0us expected=167196.2us
(kms_flip:2796) DEBUG: name = flip
last_ts = 326.738159
last_received_ts = 326.737549
last_seq = 12129
current_ts = 326.907928
current_received_ts = 326.907349
current_seq = 12139
count = 42
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 326.738159/12129, current 326.907928/12139: elapsed=169776.0us expected=167196.2us +- 836.0us, error 1.5%
(kms_flip:2796) DEBUG: inconsistent flip ts/seq: last 326.738159/12129, current 326.907928/12139: elapsed=169776.0us expected=167196.2us
(kms_flip:2796) DEBUG: name = vblank
last_ts = 326.890961
last_received_ts = 326.890320
last_seq = 12138
current_ts = 327.060760
current_received_ts = 327.060120
current_seq = 12148
count = 42
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 326.890961/12138, current 327.060760/12148: elapsed=169779.0us expected=167196.2us +- 836.0us, error 1.5%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 326.890961/12138, current 327.060760/12148: elapsed=169779.0us expected=167196.2us
(kms_flip:2796) DEBUG: name = flip
last_ts = 326.907928
last_received_ts = 326.907349
last_seq = 12139
current_ts = 327.077728
current_received_ts = 327.077118
current_seq = 12149
count = 43
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 326.907928/12139, current 327.077728/12149: elapsed=169790.0us expected=167196.2us +- 836.0us, error 1.6%
(kms_flip:2796) DEBUG: inconsistent flip ts/seq: last 326.907928/12139, current 327.077728/12149: elapsed=169790.0us expected=167196.2us
(kms_flip:2796) DEBUG: name = vblank
last_ts = 327.060760
last_received_ts = 327.060120
last_seq = 12148
current_ts = 327.230530
current_received_ts = 327.229919
current_seq = 12158
count = 43
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 327.060760/12148, current 327.230530/12158: elapsed=169781.0us expected=167196.2us +- 836.0us, error 1.5%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 327.060760/12148, current 327.230530/12158: elapsed=169781.0us expected=167196.2us
(kms_flip:2796) INFO: Event flip: expected 449, counted 440, passrate = 13.64%, encoder type 1
(kms_flip:2796) DEBUG: dropped frames, expected 449, counted 440, passrate = 13.64%, encoder type 1
(kms_flip:2796) INFO: Event vblank: expected 449, counted 440, passrate = 11.36%, encoder type 1
(kms_flip:2796) DEBUG: dropped frames, expected 449, counted 440, passrate = 11.36%, encoder type 1
(kms_flip:2796) DEBUG: Retrying without a hotplug event
(kms_flip:2796) DEBUG: No stale events found
(kms_flip:2796) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2796) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2796) INFO: Expected frametime: 16666us; measured 16891.7us +- 12.515us accuracy 0.22%
(kms_flip:2796) INFO: vblank interval differs from modeline! expected 16665.6us, measured 16892us +- 12.515us, difference 226.1us (18.1 sigma)
(kms_flip:2796) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 330.698303
current_received_ts = 330.697632
current_seq = 12183
count = 0
seq_step = 1
(kms_flip:2796) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 330.850159
current_received_ts = 330.849548
current_seq = 12192
count = 0
seq_step = 10
(kms_flip:2796) DEBUG: name = flip
last_ts = 330.698303
last_received_ts = 330.697632
last_seq = 12183
current_ts = 330.867035
current_received_ts = 330.866364
current_seq = 12193
count = 1
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 330.698303/12183, current 330.867035/12193: elapsed=168738.0us expected=168916.9us +- 844.6us, error 0.1%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 330.850159
last_received_ts = 330.849548
last_seq = 12192
current_ts = 331.018890
current_received_ts = 331.018250
current_seq = 12202
count = 1
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 330.850159/12192, current 331.018890/12202: elapsed=168738.0us expected=168916.9us +- 844.6us, error 0.1%
(kms_flip:2796) DEBUG: name = flip
last_ts = 330.867035
last_received_ts = 330.866364
last_seq = 12193
current_ts = 331.035767
current_received_ts = 331.035126
current_seq = 12203
count = 2
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 330.867035/12193, current 331.035767/12203: elapsed=168738.0us expected=168916.9us +- 844.6us, error 0.1%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 331.018890
last_received_ts = 331.018250
last_seq = 12202
current_ts = 331.187622
current_received_ts = 331.187042
current_seq = 12212
count = 2
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 331.018890/12202, current 331.187622/12212: elapsed=168738.0us expected=168916.9us +- 844.6us, error 0.1%
(kms_flip:2796) DEBUG: name = flip
last_ts = 331.035767
last_received_ts = 331.035126
last_seq = 12203
current_ts = 331.204529
current_received_ts = 331.203827
current_seq = 12213
count = 3
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 331.035767/12203, current 331.204529/12213: elapsed=168737.0us expected=168916.9us +- 844.6us, error 0.1%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 331.187622
last_received_ts = 331.187042
last_seq = 12212
current_ts = 331.356354
current_received_ts = 331.355743
current_seq = 12222
count = 3
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 331.187622/12212, current 331.356354/12222: elapsed=168740.0us expected=168916.9us +- 844.6us, error 0.1%
(kms_flip:2796) DEBUG: name = flip
last_ts = 331.204529
last_received_ts = 331.203827
last_seq = 12213
current_ts = 331.373230
current_received_ts = 331.372620
current_seq = 12223
count = 4
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 331.204529/12213, current 331.373230/12223: elapsed=168722.0us expected=168916.9us +- 844.6us, error 0.1%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 331.356354
last_received_ts = 331.355743
last_seq = 12222
current_ts = 331.525116
current_received_ts = 331.524414
current_seq = 12232
count = 4
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 331.356354/12222, current 331.525116/12232: elapsed=168745.0us expected=168916.9us +- 844.6us, error 0.1%
(kms_flip:2796) DEBUG: name = flip
last_ts = 331.373230
last_received_ts = 331.372620
last_seq = 12223
current_ts = 331.541962
current_received_ts = 331.541412
current_seq = 12233
count = 5
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 331.373230/12223, current 331.541962/12233: elapsed=168737.0us expected=168916.9us +- 844.6us, error 0.1%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 331.525116
last_received_ts = 331.524414
last_seq = 12232
current_ts = 331.693756
current_received_ts = 331.693115
current_seq = 12242
count = 5
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 331.525116/12232, current 331.693756/12242: elapsed=168657.0us expected=168916.9us +- 844.6us, error 0.2%
(kms_flip:2796) DEBUG: name = flip
last_ts = 331.541962
last_received_ts = 331.541412
last_seq = 12233
current_ts = 331.710602
current_received_ts = 331.710052
current_seq = 12243
count = 6
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 331.541962/12233, current 331.710602/12243: elapsed=168633.0us expected=168916.9us +- 844.6us, error 0.2%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 331.693756
last_received_ts = 331.693115
last_seq = 12242
current_ts = 331.862305
current_received_ts = 331.861664
current_seq = 12252
count = 6
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 331.693756/12242, current 331.862305/12252: elapsed=168542.0us expected=168916.9us +- 844.6us, error 0.2%
(kms_flip:2796) DEBUG: name = flip
last_ts = 331.710602
last_received_ts = 331.710052
last_seq = 12243
current_ts = 331.879150
current_received_ts = 331.878540
current_seq = 12253
count = 7
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 331.710602/12243, current 331.879150/12253: elapsed=168555.0us expected=168916.9us +- 844.6us, error 0.2%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 331.862305
last_received_ts = 331.861664
last_seq = 12252
current_ts = 332.030884
current_received_ts = 332.030212
current_seq = 12262
count = 7
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 331.862305/12252, current 332.030884/12262: elapsed=168563.0us expected=168916.9us +- 844.6us, error 0.2%
(kms_flip:2796) DEBUG: name = flip
last_ts = 331.879150
last_received_ts = 331.878540
last_seq = 12253
current_ts = 332.047729
current_received_ts = 332.047089
current_seq = 12263
count = 8
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 331.879150/12253, current 332.047729/12263: elapsed=168561.0us expected=168916.9us +- 844.6us, error 0.2%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 332.030884
last_received_ts = 332.030212
last_seq = 12262
current_ts = 332.199432
current_received_ts = 332.198883
current_seq = 12272
count = 8
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 332.030884/12262, current 332.199432/12272: elapsed=168544.0us expected=168916.9us +- 844.6us, error 0.2%
(kms_flip:2796) DEBUG: name = flip
last_ts = 332.047729
last_received_ts = 332.047089
last_seq = 12263
current_ts = 332.216278
current_received_ts = 332.215668
current_seq = 12273
count = 9
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 332.047729/12263, current 332.216278/12273: elapsed=168540.0us expected=168916.9us +- 844.6us, error 0.2%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 332.199432
last_received_ts = 332.198883
last_seq = 12272
current_ts = 332.367981
current_received_ts = 332.367340
current_seq = 12282
count = 9
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 332.199432/12272, current 332.367981/12282: elapsed=168557.0us expected=168916.9us +- 844.6us, error 0.2%
(kms_flip:2796) DEBUG: name = flip
last_ts = 332.216278
last_received_ts = 332.215668
last_seq = 12273
current_ts = 332.384857
current_received_ts = 332.384247
current_seq = 12283
count = 10
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 332.216278/12273, current 332.384857/12283: elapsed=168578.0us expected=168916.9us +- 844.6us, error 0.2%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 332.367981
last_received_ts = 332.367340
last_seq = 12282
current_ts = 332.536530
current_received_ts = 332.535889
current_seq = 12292
count = 10
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 332.367981/12282, current 332.536530/12292: elapsed=168552.0us expected=168916.9us +- 844.6us, error 0.2%
(kms_flip:2796) DEBUG: name = flip
last_ts = 332.384857
last_received_ts = 332.384247
last_seq = 12283
current_ts = 332.553375
current_received_ts = 332.552765
current_seq = 12293
count = 11
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 332.384857/12283, current 332.553375/12293: elapsed=168526.0us expected=168916.9us +- 844.6us, error 0.2%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 332.536530
last_received_ts = 332.535889
last_seq = 12292
current_ts = 332.704987
current_received_ts = 332.704376
current_seq = 12302
count = 11
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 332.536530/12292, current 332.704987/12302: elapsed=168454.0us expected=168916.9us +- 844.6us, error 0.3%
(kms_flip:2796) DEBUG: name = flip
last_ts = 332.553375
last_received_ts = 332.552765
last_seq = 12293
current_ts = 332.721832
current_received_ts = 332.721191
current_seq = 12303
count = 12
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 332.553375/12293, current 332.721832/12303: elapsed=168451.0us expected=168916.9us +- 844.6us, error 0.3%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 332.704987
last_received_ts = 332.704376
last_seq = 12302
current_ts = 332.873383
current_received_ts = 332.872742
current_seq = 12312
count = 12
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 332.704987/12302, current 332.873383/12312: elapsed=168392.0us expected=168916.9us +- 844.6us, error 0.3%
(kms_flip:2796) DEBUG: name = flip
last_ts = 332.721832
last_received_ts = 332.721191
last_seq = 12303
current_ts = 332.890198
current_received_ts = 332.889618
current_seq = 12313
count = 13
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 332.721832/12303, current 332.890198/12313: elapsed=168393.0us expected=168916.9us +- 844.6us, error 0.3%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 332.873383
last_received_ts = 332.872742
last_seq = 12312
current_ts = 333.041779
current_received_ts = 333.041168
current_seq = 12322
count = 13
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 332.873383/12312, current 333.041779/12322: elapsed=168402.0us expected=168916.9us +- 844.6us, error 0.3%
(kms_flip:2796) DEBUG: name = flip
last_ts = 332.890198
last_received_ts = 332.889618
last_seq = 12313
current_ts = 333.058594
current_received_ts = 333.057922
current_seq = 12323
count = 14
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 332.890198/12313, current 333.058594/12323: elapsed=168396.0us expected=168916.9us +- 844.6us, error 0.3%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 333.041779
last_received_ts = 333.041168
last_seq = 12322
current_ts = 333.210144
current_received_ts = 333.209473
current_seq = 12332
count = 14
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 333.041779/12322, current 333.210144/12332: elapsed=168377.0us expected=168916.9us +- 844.6us, error 0.3%
(kms_flip:2796) DEBUG: name = flip
last_ts = 333.058594
last_received_ts = 333.057922
last_seq = 12323
current_ts = 333.226990
current_received_ts = 333.226410
current_seq = 12333
count = 15
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 333.058594/12323, current 333.226990/12333: elapsed=168382.0us expected=168916.9us +- 844.6us, error 0.3%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 333.210144
last_received_ts = 333.209473
last_seq = 12332
current_ts = 333.378540
current_received_ts = 333.377869
current_seq = 12342
count = 15
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 333.210144/12332, current 333.378540/12342: elapsed=168401.0us expected=168916.9us +- 844.6us, error 0.3%
(kms_flip:2796) DEBUG: name = flip
last_ts = 333.226990
last_received_ts = 333.226410
last_seq = 12333
current_ts = 333.395386
current_received_ts = 333.394775
current_seq = 12343
count = 16
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 333.226990/12333, current 333.395386/12343: elapsed=168390.0us expected=168916.9us +- 844.6us, error 0.3%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 333.378540
last_received_ts = 333.377869
last_seq = 12342
current_ts = 333.546936
current_received_ts = 333.546265
current_seq = 12352
count = 16
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 333.378540/12342, current 333.546936/12352: elapsed=168386.0us expected=168916.9us +- 844.6us, error 0.3%
(kms_flip:2796) DEBUG: name = flip
last_ts = 333.395386
last_received_ts = 333.394775
last_seq = 12343
current_ts = 333.563782
current_received_ts = 333.563080
current_seq = 12353
count = 17
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 333.395386/12343, current 333.563782/12353: elapsed=168391.0us expected=168916.9us +- 844.6us, error 0.3%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 333.546936
last_received_ts = 333.546265
last_seq = 12352
current_ts = 333.715240
current_received_ts = 333.714630
current_seq = 12362
count = 17
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 333.546936/12352, current 333.715240/12362: elapsed=168302.0us expected=168916.9us +- 844.6us, error 0.4%
(kms_flip:2796) DEBUG: name = flip
last_ts = 333.563782
last_received_ts = 333.563080
last_seq = 12353
current_ts = 333.732056
current_received_ts = 333.731445
current_seq = 12363
count = 18
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 333.563782/12353, current 333.732056/12363: elapsed=168287.0us expected=168916.9us +- 844.6us, error 0.4%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 333.715240
last_received_ts = 333.714630
last_seq = 12362
current_ts = 333.883484
current_received_ts = 333.882874
current_seq = 12372
count = 18
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 333.715240/12362, current 333.883484/12372: elapsed=168245.0us expected=168916.9us +- 844.6us, error 0.4%
(kms_flip:2796) DEBUG: name = flip
last_ts = 333.732056
last_received_ts = 333.731445
last_seq = 12363
current_ts = 333.900330
current_received_ts = 333.899719
current_seq = 12373
count = 19
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 333.732056/12363, current 333.900330/12373: elapsed=168262.0us expected=168916.9us +- 844.6us, error 0.4%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 333.883484
last_received_ts = 333.882874
last_seq = 12372
current_ts = 334.051727
current_received_ts = 334.051117
current_seq = 12382
count = 19
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 333.883484/12372, current 334.051727/12382: elapsed=168248.0us expected=168916.9us +- 844.6us, error 0.4%
(kms_flip:2796) DEBUG: name = flip
last_ts = 333.900330
last_received_ts = 333.899719
last_seq = 12373
current_ts = 334.068573
current_received_ts = 334.067993
current_seq = 12383
count = 20
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 333.900330/12373, current 334.068573/12383: elapsed=168247.0us expected=168916.9us +- 844.6us, error 0.4%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 334.051727
last_received_ts = 334.051117
last_seq = 12382
current_ts = 334.220001
current_received_ts = 334.219360
current_seq = 12392
count = 20
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 334.051727/12382, current 334.220001/12392: elapsed=168257.0us expected=168916.9us +- 844.6us, error 0.4%
(kms_flip:2796) DEBUG: name = flip
last_ts = 334.068573
last_received_ts = 334.067993
last_seq = 12383
current_ts = 334.236816
current_received_ts = 334.236115
current_seq = 12393
count = 21
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 334.068573/12383, current 334.236816/12393: elapsed=168244.0us expected=168916.9us +- 844.6us, error 0.4%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 334.220001
last_received_ts = 334.219360
last_seq = 12392
current_ts = 334.388245
current_received_ts = 334.387573
current_seq = 12402
count = 21
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 334.220001/12392, current 334.388245/12402: elapsed=168249.0us expected=168916.9us +- 844.6us, error 0.4%
(kms_flip:2796) DEBUG: name = flip
last_ts = 334.236816
last_received_ts = 334.236115
last_seq = 12393
current_ts = 334.405060
current_received_ts = 334.404449
current_seq = 12403
count = 22
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 334.236816/12393, current 334.405060/12403: elapsed=168241.0us expected=168916.9us +- 844.6us, error 0.4%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 334.388245
last_received_ts = 334.387573
last_seq = 12402
current_ts = 334.556458
current_received_ts = 334.555878
current_seq = 12412
count = 22
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 334.388245/12402, current 334.556458/12412: elapsed=168232.0us expected=168916.9us +- 844.6us, error 0.4%
(kms_flip:2796) DEBUG: name = flip
last_ts = 334.405060
last_received_ts = 334.404449
last_seq = 12403
current_ts = 334.573303
current_received_ts = 334.572693
current_seq = 12413
count = 23
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 334.405060/12403, current 334.573303/12413: elapsed=168244.0us expected=168916.9us +- 844.6us, error 0.4%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 334.556458
last_received_ts = 334.555878
last_seq = 12412
current_ts = 334.724640
current_received_ts = 334.724030
current_seq = 12422
count = 23
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 334.556458/12412, current 334.724640/12422: elapsed=168174.0us expected=168916.9us +- 844.6us, error 0.4%
(kms_flip:2796) DEBUG: name = flip
last_ts = 334.573303
last_received_ts = 334.572693
last_seq = 12413
current_ts = 334.741455
current_received_ts = 334.740845
current_seq = 12423
count = 24
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 334.573303/12413, current 334.741455/12423: elapsed=168157.0us expected=168916.9us +- 844.6us, error 0.4%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 334.724640
last_received_ts = 334.724030
last_seq = 12422
current_ts = 334.892761
current_received_ts = 334.892059
current_seq = 12432
count = 24
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 334.724640/12422, current 334.892761/12432: elapsed=168116.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: name = flip
last_ts = 334.741455
last_received_ts = 334.740845
last_seq = 12423
current_ts = 334.909576
current_received_ts = 334.908966
current_seq = 12433
count = 25
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 334.741455/12423, current 334.909576/12433: elapsed=168135.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 334.892761
last_received_ts = 334.892059
last_seq = 12432
current_ts = 335.060883
current_received_ts = 335.060272
current_seq = 12442
count = 25
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 334.892761/12432, current 335.060883/12442: elapsed=168129.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: name = flip
last_ts = 334.909576
last_received_ts = 334.908966
last_seq = 12433
current_ts = 335.077698
current_received_ts = 335.077148
current_seq = 12443
count = 26
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 334.909576/12433, current 335.077698/12443: elapsed=168119.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 335.060883
last_received_ts = 335.060272
last_seq = 12442
current_ts = 335.229004
current_received_ts = 335.228363
current_seq = 12452
count = 26
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 335.060883/12442, current 335.229004/12452: elapsed=168122.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: name = flip
last_ts = 335.077698
last_received_ts = 335.077148
last_seq = 12443
current_ts = 335.245819
current_received_ts = 335.245117
current_seq = 12453
count = 27
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 335.077698/12443, current 335.245819/12453: elapsed=168125.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 335.229004
last_received_ts = 335.228363
last_seq = 12452
current_ts = 335.397156
current_received_ts = 335.396484
current_seq = 12462
count = 27
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 335.229004/12452, current 335.397156/12462: elapsed=168130.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: name = flip
last_ts = 335.245819
last_received_ts = 335.245117
last_seq = 12453
current_ts = 335.413940
current_received_ts = 335.413330
current_seq = 12463
count = 28
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 335.245819/12453, current 335.413940/12463: elapsed=168112.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 335.397156
last_received_ts = 335.396484
last_seq = 12462
current_ts = 335.565247
current_received_ts = 335.564606
current_seq = 12472
count = 28
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 335.397156/12462, current 335.565247/12472: elapsed=168114.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: name = flip
last_ts = 335.413940
last_received_ts = 335.413330
last_seq = 12463
current_ts = 335.582062
current_received_ts = 335.581482
current_seq = 12473
count = 29
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 335.413940/12463, current 335.582062/12473: elapsed=168126.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: name = vblank
last_ts = 335.565247
last_received_ts = 335.564606
last_seq = 12472
current_ts = 335.733307
current_received_ts = 335.732697
current_seq = 12482
count = 29
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 335.565247/12472, current 335.733307/12482: elapsed=168065.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 335.565247/12472, current 335.733307/12482: elapsed=168065.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = flip
last_ts = 335.582062
last_received_ts = 335.581482
last_seq = 12473
current_ts = 335.750122
current_received_ts = 335.749512
current_seq = 12483
count = 30
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 335.582062/12473, current 335.750122/12483: elapsed=168049.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: inconsistent flip ts/seq: last 335.582062/12473, current 335.750122/12483: elapsed=168049.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = vblank
last_ts = 335.733307
last_received_ts = 335.732697
last_seq = 12482
current_ts = 335.901337
current_received_ts = 335.900726
current_seq = 12492
count = 30
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 335.733307/12482, current 335.901337/12492: elapsed=168013.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 335.733307/12482, current 335.901337/12492: elapsed=168013.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = flip
last_ts = 335.750122
last_received_ts = 335.749512
last_seq = 12483
current_ts = 335.918121
current_received_ts = 335.917480
current_seq = 12493
count = 31
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 335.750122/12483, current 335.918121/12493: elapsed=168015.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: inconsistent flip ts/seq: last 335.750122/12483, current 335.918121/12493: elapsed=168015.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = vblank
last_ts = 335.901337
last_received_ts = 335.900726
last_seq = 12492
current_ts = 336.069336
current_received_ts = 336.068726
current_seq = 12502
count = 31
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 335.901337/12492, current 336.069336/12502: elapsed=168016.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 335.901337/12492, current 336.069336/12502: elapsed=168016.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = flip
last_ts = 335.918121
last_received_ts = 335.917480
last_seq = 12493
current_ts = 336.086151
current_received_ts = 336.085510
current_seq = 12503
count = 32
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 335.918121/12493, current 336.086151/12503: elapsed=168001.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: inconsistent flip ts/seq: last 335.918121/12493, current 336.086151/12503: elapsed=168001.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = vblank
last_ts = 336.069336
last_received_ts = 336.068726
last_seq = 12502
current_ts = 336.237366
current_received_ts = 336.236664
current_seq = 12512
count = 32
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 336.069336/12502, current 336.237366/12512: elapsed=168006.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 336.069336/12502, current 336.237366/12512: elapsed=168006.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = flip
last_ts = 336.086151
last_received_ts = 336.085510
last_seq = 12503
current_ts = 336.254150
current_received_ts = 336.253571
current_seq = 12513
count = 33
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 336.086151/12503, current 336.254150/12513: elapsed=168016.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: inconsistent flip ts/seq: last 336.086151/12503, current 336.254150/12513: elapsed=168016.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = vblank
last_ts = 336.237366
last_received_ts = 336.236664
last_seq = 12512
current_ts = 336.405365
current_received_ts = 336.404724
current_seq = 12522
count = 33
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 336.237366/12512, current 336.405365/12522: elapsed=168004.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 336.237366/12512, current 336.405365/12522: elapsed=168004.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = flip
last_ts = 336.254150
last_received_ts = 336.253571
last_seq = 12513
current_ts = 336.422150
current_received_ts = 336.421570
current_seq = 12523
count = 34
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 336.254150/12513, current 336.422150/12523: elapsed=168012.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: inconsistent flip ts/seq: last 336.254150/12513, current 336.422150/12523: elapsed=168012.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = vblank
last_ts = 336.405365
last_received_ts = 336.404724
last_seq = 12522
current_ts = 336.573395
current_received_ts = 336.572754
current_seq = 12532
count = 34
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 336.405365/12522, current 336.573395/12532: elapsed=168019.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 336.405365/12522, current 336.573395/12532: elapsed=168019.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = flip
last_ts = 336.422150
last_received_ts = 336.421570
last_seq = 12523
current_ts = 336.590179
current_received_ts = 336.589569
current_seq = 12533
count = 35
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 336.422150/12523, current 336.590179/12533: elapsed=168015.0us expected=168916.9us +- 844.6us, error 0.5%
(kms_flip:2796) DEBUG: inconsistent flip ts/seq: last 336.422150/12523, current 336.590179/12533: elapsed=168015.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = vblank
last_ts = 336.573395
last_received_ts = 336.572754
last_seq = 12532
current_ts = 336.741333
current_received_ts = 336.740692
current_seq = 12542
count = 35
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 336.573395/12532, current 336.741333/12542: elapsed=167941.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 336.573395/12532, current 336.741333/12542: elapsed=167941.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = flip
last_ts = 336.590179
last_received_ts = 336.589569
last_seq = 12533
current_ts = 336.758118
current_received_ts = 336.757477
current_seq = 12543
count = 36
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 336.590179/12533, current 336.758118/12543: elapsed=167947.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent flip ts/seq: last 336.590179/12533, current 336.758118/12543: elapsed=167947.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = vblank
last_ts = 336.741333
last_received_ts = 336.740692
last_seq = 12542
current_ts = 336.909241
current_received_ts = 336.908630
current_seq = 12552
count = 36
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 336.741333/12542, current 336.909241/12552: elapsed=167921.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 336.741333/12542, current 336.909241/12552: elapsed=167921.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = flip
last_ts = 336.758118
last_received_ts = 336.757477
last_seq = 12543
current_ts = 336.926056
current_received_ts = 336.925415
current_seq = 12553
count = 37
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 336.758118/12543, current 336.926056/12553: elapsed=167915.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent flip ts/seq: last 336.758118/12543, current 336.926056/12553: elapsed=167915.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = vblank
last_ts = 336.909241
last_received_ts = 336.908630
last_seq = 12552
current_ts = 337.077148
current_received_ts = 337.076569
current_seq = 12562
count = 37
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 336.909241/12552, current 337.077148/12562: elapsed=167920.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 336.909241/12552, current 337.077148/12562: elapsed=167920.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = flip
last_ts = 336.926056
last_received_ts = 336.925415
last_seq = 12553
current_ts = 337.093964
current_received_ts = 337.093353
current_seq = 12563
count = 38
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 336.926056/12553, current 337.093964/12563: elapsed=167912.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent flip ts/seq: last 336.926056/12553, current 337.093964/12563: elapsed=167912.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = vblank
last_ts = 337.077148
last_received_ts = 337.076569
last_seq = 12562
current_ts = 337.245087
current_received_ts = 337.244476
current_seq = 12572
count = 38
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 337.077148/12562, current 337.245087/12572: elapsed=167924.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 337.077148/12562, current 337.245087/12572: elapsed=167924.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = flip
last_ts = 337.093964
last_received_ts = 337.093353
last_seq = 12563
current_ts = 337.261871
current_received_ts = 337.261261
current_seq = 12573
count = 39
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 337.093964/12563, current 337.261871/12573: elapsed=167927.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent flip ts/seq: last 337.093964/12563, current 337.261871/12573: elapsed=167927.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = vblank
last_ts = 337.245087
last_received_ts = 337.244476
last_seq = 12572
current_ts = 337.412994
current_received_ts = 337.412384
current_seq = 12582
count = 39
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 337.245087/12572, current 337.412994/12582: elapsed=167915.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 337.245087/12572, current 337.412994/12582: elapsed=167915.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = flip
last_ts = 337.261871
last_received_ts = 337.261261
last_seq = 12573
current_ts = 337.429810
current_received_ts = 337.429230
current_seq = 12583
count = 40
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 337.261871/12573, current 337.429810/12583: elapsed=167915.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent flip ts/seq: last 337.261871/12573, current 337.429810/12583: elapsed=167915.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = vblank
last_ts = 337.412994
last_received_ts = 337.412384
last_seq = 12582
current_ts = 337.580933
current_received_ts = 337.580292
current_seq = 12592
count = 40
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 337.412994/12582, current 337.580933/12592: elapsed=167917.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 337.412994/12582, current 337.580933/12592: elapsed=167917.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = flip
last_ts = 337.429810
last_received_ts = 337.429230
last_seq = 12583
current_ts = 337.597717
current_received_ts = 337.597107
current_seq = 12593
count = 41
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 337.429810/12583, current 337.597717/12593: elapsed=167916.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent flip ts/seq: last 337.429810/12583, current 337.597717/12593: elapsed=167916.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = vblank
last_ts = 337.580933
last_received_ts = 337.580292
last_seq = 12592
current_ts = 337.748779
current_received_ts = 337.748169
current_seq = 12602
count = 41
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 337.580933/12592, current 337.748779/12602: elapsed=167856.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 337.580933/12592, current 337.748779/12602: elapsed=167856.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = flip
last_ts = 337.597717
last_received_ts = 337.597107
last_seq = 12593
current_ts = 337.765564
current_received_ts = 337.764893
current_seq = 12603
count = 42
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 337.597717/12593, current 337.765564/12603: elapsed=167857.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent flip ts/seq: last 337.597717/12593, current 337.765564/12603: elapsed=167857.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = vblank
last_ts = 337.748779
last_received_ts = 337.748169
last_seq = 12602
current_ts = 337.916595
current_received_ts = 337.915985
current_seq = 12612
count = 42
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 337.748779/12602, current 337.916595/12612: elapsed=167834.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 337.748779/12602, current 337.916595/12612: elapsed=167834.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = flip
last_ts = 337.765564
last_received_ts = 337.764893
last_seq = 12603
current_ts = 337.933411
current_received_ts = 337.932770
current_seq = 12613
count = 43
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 337.765564/12603, current 337.933411/12613: elapsed=167838.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent flip ts/seq: last 337.765564/12603, current 337.933411/12613: elapsed=167838.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = vblank
last_ts = 337.916595
last_received_ts = 337.915985
last_seq = 12612
current_ts = 338.084442
current_received_ts = 338.083893
current_seq = 12622
count = 43
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 337.916595/12612, current 338.084442/12622: elapsed=167837.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 337.916595/12612, current 338.084442/12622: elapsed=167837.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = flip
last_ts = 337.933411
last_received_ts = 337.932770
last_seq = 12613
current_ts = 338.101227
current_received_ts = 338.100616
current_seq = 12623
count = 44
seq_step = 1
(kms_flip:2796) DEBUG: flip ts/seq: last 337.933411/12613, current 338.101227/12623: elapsed=167822.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent flip ts/seq: last 337.933411/12613, current 338.101227/12623: elapsed=167822.0us expected=168916.9us
(kms_flip:2796) DEBUG: name = vblank
last_ts = 338.084442
last_received_ts = 338.083893
last_seq = 12622
current_ts = 338.252289
current_received_ts = 338.251678
current_seq = 12632
count = 44
seq_step = 10
(kms_flip:2796) DEBUG: vblank ts/seq: last 338.084442/12622, current 338.252289/12632: elapsed=167833.0us expected=168916.9us +- 844.6us, error 0.6%
(kms_flip:2796) DEBUG: inconsistent vblank ts/seq: last 338.084442/12622, current 338.252289/12632: elapsed=167833.0us expected=168916.9us
(kms_flip:2796) INFO: Event flip: expected 448, counted 450, passrate = 66.67%, encoder type 1
(kms_flip:2796) DEBUG: dropped frames, expected 448, counted 450, passrate = 66.67%, encoder type 1
(kms_flip:2796) INFO: Event vblank: expected 448, counted 450, passrate = 64.44%, encoder type 1
(kms_flip:2796) DEBUG: dropped frames, expected 448, counted 450, passrate = 64.44%, encoder type 1
(kms_flip:2796) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1722:
(kms_flip:2796) CRITICAL: Failed assertion: !retried
(kms_flip:2796) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2796) igt_core-INFO: Stack trace:
(kms_flip:2796) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2796) igt_core-INFO:   #1 ../tests/kms_flip.c:1071 run_test_on_crtc_set()
(kms_flip:2796) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
(kms_flip:2796) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
(kms_flip:2796) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
(kms_flip:2796) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2796) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2796) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-VGA1: FAIL (18.780s)
Dmesg
<6> [318.794755] [IGT] kms_flip: starting dynamic subtest B-VGA1
<7> [318.795356] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:91]
<7> [318.795501] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:92]
<7> [318.811969] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:53:pipe A]
<7> [318.812099] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.enable (expected yes, found no)
<7> [318.812393] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.active (expected yes, found no)
<7> [318.812661] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1)
<7> [318.812955] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in has_pch_encoder (expected yes, found no)
<7> [318.813284] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in fdi_lanes (expected 1, found 0)
<7> [318.813561] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53: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> [318.813823] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in output_types (expected 0x00000002, found 0x00000000)
<7> [318.814134] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [318.814410] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1024, found 0)
<7> [318.814640] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 1344, found 0)
<7> [318.815111] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1024, found 0)
<7> [318.815432] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 1344, found 0)
<7> [318.815740] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1048, found 0)
<7> [318.816097] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 1184, found 0)
<7> [318.816372] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 768, found 0)
<7> [318.816631] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 768, found 0)
<7> [318.816907] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 771, found 0)
<7> [318.817167] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 777, found 0)
<7> [318.817427] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 806, found 0)
<7> [318.817686] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 806, found 0)
<7> [318.817972] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1024, found 0)
<7> [318.818209] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 1344, found 0)
<7> [318.818446] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1024, found 0)
<7> [318.818683] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 1344, found 0)
<7> [318.818949] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1048, found 0)
<7> [318.819187] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 1184, found 0)
<7> [318.819424] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 768, found 0)
<7> [318.819661] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 768, found 0)
<7> [318.819919] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 771, found 0)
<7> [318.820156] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 777, found 0)
<7> [318.820393] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 806, found 0)
<7> [318.820630] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 806, found 0)
<7> [318.820882] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [318.821119] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)
<7> [318.821356] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)
<7> [318.821594] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0)
<7> [318.821846] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 64800, found 0)
<7> [318.822106] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 64800, found 0)
<7> [318.822344] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in port_clock (expected 64800, found 0)
<7> [318.822582] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:53:pipe A] fastset requirement not met, forcing full modeset
<7> [318.822821] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:53:pipe A] releasing PCH DPLL A
<7> [318.823148] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:53:pipe A] min cdclk: 72000 kHz -> 0 kHz
<7> [318.823404] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:53:pipe A] enable: no [modeset]
<7> [318.823635] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:35:primary A] fb: [NOFB], visible: no
<7> [318.824007] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A
<7> [318.825097] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found
<7> [318.825334] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found
<7> [318.825560] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found
<7> [318.843099] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PCH DPLL A (active 0x1, on? 1) for [CRTC:53:pipe A]
<7> [318.843616] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PCH DPLL A
<7> [318.844353] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:CRT]
<7> [318.844837] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:75:HDMI D]
<7> [318.845329] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:83:DP D]
<7> [318.845817] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:73:VGA-1]
<7> [318.846398] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:53:pipe A]
<7> [318.847050] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:72:pipe B]
<7> [318.847184] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:72:pipe B]
<7> [318.847209] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:73:VGA-1]
<7> [318.847296] i915 0000:00:02.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:73:VGA-1] Limiting target display pipe bpp to 24 (EDID bpp 0, max requested bpp 0, max platform bpp 36)
<7> [318.847544] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:72:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0
<7> [318.847795] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe B, lanes 1
<7> [318.848033] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.enable (expected no, found yes)
<7> [318.848265] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.active (expected no, found yes)
<7> [318.848496] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)
<7> [318.848727] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in has_pch_encoder (expected no, found yes)
<7> [318.848987] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in fdi_lanes (expected 0, found 1)
<7> [318.849228] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72: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> [318.849460] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000002)
<7> [318.849701] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [318.849964] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1024)
<7> [318.850196] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 1344)
<7> [318.850427] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1024)
<7> [318.850657] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 1344)
<7> [318.850899] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1048)
<7> [318.851166] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 1184)
<7> [318.851395] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 768)
<7> [318.851626] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 768)
<7> [318.851888] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 771)
<7> [318.852137] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 777)
<7> [318.852366] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 806)
<7> [318.852597] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 806)
<7> [318.852858] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1024)
<7> [318.853117] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 1344)
<7> [318.853348] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1024)
<7> [318.853577] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 1344)
<7> [318.853807] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1048)
<7> [318.854068] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 1184)
<7> [318.854319] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 768)
<7> [318.854549] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 768)
<7> [318.854779] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 771)
<7> [318.855053] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 777)
<7> [318.855317] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 806)
<7> [318.855557] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 806)
<7> [318.855790] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [318.856048] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)
<7> [318.856297] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)
<7> [318.856529] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in dpll_hw_state
<7> [318.856759] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:
<7> [318.857016] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0xc4010001, dpll_md: 0x0, fp0: 0x30f06, fp1: 0x30f06
<7> [318.857265] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:
<7> [318.857494] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [318.857724] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24)
<7> [318.858027] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 64800)
<7> [318.858276] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 64800)
<7> [318.858506] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in port_clock (expected 0, found 64800)
<7> [318.858737] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:72:pipe B] fastset requirement not met, forcing full modeset
<7> [318.859033] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:72:pipe B] min cdclk: 0 kHz -> 72000 kHz
<7> [318.859275] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:72:pipe B] allocated PCH DPLL A
<7> [318.859503] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:72:pipe B] reserving PCH DPLL A
<7> [318.859734] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:72:pipe B] enable: yes [modeset]
<7> [318.859994] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: ANALOG (0x2), output format: RGB, sink format: RGB
<7> [318.860242] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0
<7> [318.860472] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [318.860700] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [318.860965] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [318.861212] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [318.861441] 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> [318.861671] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0
<7> [318.861927] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1
<7> [318.862174] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0
<7> [318.862403] 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> [318.862633] 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> [318.862892] 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> [318.863141] 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> [318.863372] 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> [318.863603] 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> [318.863871] 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> [318.864120] 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> [318.864351] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 64800, pixel rate 64800, min cdclk 72000, min voltage level 0
<7> [318.864581] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0
<7> [318.864810] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1024x768+0+0
<7> [318.865083] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [318.865102] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on
<7> [318.865320] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0
<7> [318.865556] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [318.865791] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [318.866050] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [318.866306] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [318.866542] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [318.866780] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [318.867029] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [318.867276] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [318.867505] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:54:primary B] fb: [FB:91] 1024x768 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes
<7> [318.867737] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [318.867995] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1024.000000x768.000000+0.000000+0.000000 dst: 1024x768+0+0
<7> [318.869266] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on
<7> [318.869514] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:CRT]
<7> [318.869741] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:75:HDMI D]
<7> [318.870019] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:83:DP D]
<7> [318.870807] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B
<7> [318.871915] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100
<7> [318.872144] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done.
<7> [318.873027] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x200
<7> [318.873254] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done.
<7> [318.873478] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done.
<7> [318.873705] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PCH DPLL A (active 0x2, on? 0) for [CRTC:72:pipe B]
<7> [318.873973] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PCH DPLL A
<7> [318.942685] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:73:VGA-1]
<7> [318.943282] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:72:pipe B]
<7> [329.564798] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:53:pipe A]
<7> [329.565201] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:72:pipe B]
<7> [329.565479] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.enable (expected yes, found no)
<7> [329.566355] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.active (expected yes, found no)
<7> [329.567227] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in cpu_transcoder (expected 1, found -1)
<7> [329.568073] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in has_pch_encoder (expected yes, found no)
<7> [329.568479] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in fdi_lanes (expected 1, found 0)
<7> [329.568836] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72: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> [329.569238] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in output_types (expected 0x00000002, found 0x00000000)
<7> [329.569615] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [329.570021] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1024, found 0)
<7> [329.570394] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 1344, found 0)
<7> [329.570748] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1024, found 0)
<7> [329.571096] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 1344, found 0)
<7> [329.571430] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1048, found 0)
<7> [329.571785] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 1184, found 0)
<7> [329.572170] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 768, found 0)
<7> [329.572545] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 768, found 0)
<7> [329.572930] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 771, found 0)
<7> [329.573312] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 777, found 0)
<7> [329.573686] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 806, found 0)
<7> [329.574080] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 806, found 0)
<7> [329.574466] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1024, found 0)
<7> [329.574823] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 1344, found 0)
<7> [329.575230] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1024, found 0)
<7> [329.575613] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 1344, found 0)
<7> [329.576007] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1048, found 0)
<7> [329.576379] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 1184, found 0)
<7> [329.576741] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 768, found 0)
<7> [329.577119] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 768, found 0)
<7> [329.577490] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 771, found 0)
<7> [329.577859] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 777, found 0)
<7> [329.578146] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 806, found 0)
<7> [329.578514] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 806, found 0)
<7> [329.578911] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [329.579278] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)
<7> [329.579663] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)
<7> [329.580047] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in pipe_bpp (expected 24, found 0)
<7> [329.580418] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 64800, found 0)
<7> [329.580783] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 64800, found 0)
<7> [329.581135] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in port_clock (expected 64800, found 0)
<7> [329.581383] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:72:pipe B] fastset requirement not met, forcing full modeset
<7> [329.581620] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:72:pipe B] releasing PCH DPLL A
<7> [329.581925] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:72:pipe B] min cdclk: 72000 kHz -> 0 kHz
<7> [329.582196] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:72:pipe B] enable: no [modeset]
<7> [329.582434] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:54:primary B] fb: [NOFB], visible: no
<7> [329.582767] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe B
<7> [329.593603] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found
<7> [329.593868] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found
<7> [329.594090] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found
<7> [329.609184] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PCH DPLL A (active 0x2, on? 1) for [CRTC:72:pipe B]
<7> [329.609766] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PCH DPLL A
<7> [329.610492] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:CRT]
<7> [329.611017] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:75:HDMI D]
<7> [329.611492] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:83:DP D]
<7> [329.612011] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:73:VGA-1]
<7> [329.612343] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:72:pipe B]
<7> [329.612769] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:72:pipe B]
<7> [329.612798] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:73:VGA-1]
<7> [329.612889] i915 0000:00:02.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:73:VGA-1] Limiting target display pipe bpp to 24 (EDID bpp 0, max requested bpp 0, max platform bpp 36)
<7> [329.613145] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:72:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0
<7> [329.613380] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe B, lanes 1
<7> [329.613637] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.enable (expected no, found yes)
<7> [329.613887] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.active (expected no, found yes)
<7> [329.614118] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)
<7> [329.614350] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in has_pch_encoder (expected no, found yes)
<7> [329.614618] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in fdi_lanes (expected 0, found 1)
<7> [329.614868] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72: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> [329.615100] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000002)
<7> [329.615330] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [329.615590] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1024)
<7> [329.615841] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 1344)
<7> [329.616071] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1024)
<7> [329.616301] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 1344)
<7> [329.616563] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1048)
<7> [329.616815] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 1184)
<7> [329.617046] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 768)
<7> [329.617276] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 768)
<7> [329.617552] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 771)
<7> [329.617809] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 777)
<7> [329.618057] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 806)
<7> [329.618287] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 806)
<7> [329.618545] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1024)
<7> [329.618792] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 1344)
<7> [329.619023] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1024)
<7> [329.619252] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 1344)
<7> [329.619512] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1048)
<7> [329.619772] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 1184)
<7> [329.620009] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 768)
<7> [329.620246] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 768)
<7> [329.620504] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 771)
<7> [329.620742] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 777)
<7> [329.620979] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 806)
<7> [329.621215] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 806)
<7> [329.621468] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [329.621706] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)
<7> [329.621943] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)
<7> [329.622181] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24)
<7> [329.622432] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 64800)
<7> [329.622669] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 64800)
<7> [329.622906] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in port_clock (expected 0, found 64800)
<7> [329.623144] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:72:pipe B] fastset requirement not met, forcing full modeset
<7> [329.623437] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:72:pipe B] min cdclk: 0 kHz -> 72000 kHz
<7> [329.623673] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:72:pipe B] allocated PCH DPLL A
<7> [329.623908] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:72:pipe B] reserving PCH DPLL A
<7> [329.624146] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:72:pipe B] enable: yes [modeset]
<7> [329.624383] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: ANALOG (0x2), output format: RGB, sink format: RGB
<7> [329.624632] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0
<7> [329.624869] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [329.625104] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [329.625339] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [329.625606] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [329.625861] 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> [329.626103] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0
<7> [329.626339] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1
<7> [329.626620] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0
<7> [329.626868] 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> [329.627114] 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> [329.627343] 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> [329.627628] 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> [329.627880] 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> [329.628117] 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> [329.628353] 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> [329.628610] 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> [329.628848] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 64800, pixel rate 64800, min cdclk 72000, min voltage level 0
<7> [329.629084] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0
<7> [329.629318] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1024x768+0+0
<7> [329.629562] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [329.629798] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0
<7> [329.630033] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [329.630268] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [329.630523] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [329.630549] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on
<7> [329.630798] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [329.631047] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [329.631284] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [329.631549] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [329.631785] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [329.632072] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:54:primary B] fb: [FB:91] 1024x768 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes
<7> [329.632357] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [329.632595] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1024.000000x768.000000+0.000000+0.000000 dst: 1024x768+0+0
<7> [329.632875] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on
<7> [329.633120] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:CRT]
<7> [329.633384] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:75:HDMI D]
<7> [329.633613] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:83:DP D]
<7> [329.634390] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B
<7> [329.635456] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100
<7> [329.635690] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done.
<7> [329.636579] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x200
<7> [329.636814] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done.
<7> [329.637044] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done.
<7> [329.637344] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PCH DPLL A (active 0x2, on? 0) for [CRTC:72:pipe B]
<7> [329.637614] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PCH DPLL A
<7> [329.706268] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:73:VGA-1]
<7> [329.706876] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:72:pipe B]
<6> [337.575568] [IGT] kms_flip: finished subtest B-VGA1, FAIL
Created at 2026-05-12 18:26:08