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

Machine description: shard-snb5

Result: Fail

integration-manifest git-log-oneline i915_display_info13 igt_runner13 run13 runtimes13 results13.json i915_display_info_post_exec13 boot13 dmesg13

DetailValue
Duration 9.77 seconds
Hostname 
shard-snb5
Igt-Version 
IGT-Version: 1.29-NO-GIT (x86_64) (Linux: 6.12.0-rc6-CI_DRM_15631-g2af747587f44+ 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 16864.2us +- 2.401us accuracy 0.04%
vblank interval differs from modeline! expected 16665.6us, measured 16864us +- 2.401us, difference 198.6us (82.7 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-VGA1: FAIL (9.768s)
Err 
Starting dynamic subtest: B-VGA1
(kms_flip:1678) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:1678) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-VGA1 failed.
**** DEBUG ****
(kms_flip:1678) DEBUG: flip ts/seq: last 105.660690/641, current 105.677490/642: elapsed=16804.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.677490
last_received_ts = 105.676903
last_seq = 642
current_ts = 105.694290
current_received_ts = 105.693733
current_seq = 643
count = 258
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.677490/642, current 105.694290/643: elapsed=16799.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.694290
last_received_ts = 105.693733
last_seq = 643
current_ts = 105.711090
current_received_ts = 105.710518
current_seq = 644
count = 259
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.694290/643, current 105.711090/644: elapsed=16797.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.711090
last_received_ts = 105.710518
last_seq = 644
current_ts = 105.727890
current_received_ts = 105.727310
current_seq = 645
count = 260
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.711090/644, current 105.727890/645: elapsed=16797.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.727890
last_received_ts = 105.727310
last_seq = 645
current_ts = 105.744682
current_received_ts = 105.744110
current_seq = 646
count = 261
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.727890/645, current 105.744682/646: elapsed=16795.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.744682
last_received_ts = 105.744110
last_seq = 646
current_ts = 105.761475
current_received_ts = 105.760902
current_seq = 647
count = 262
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.744682/646, current 105.761475/647: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.761475
last_received_ts = 105.760902
last_seq = 647
current_ts = 105.778275
current_received_ts = 105.777702
current_seq = 648
count = 263
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.761475/647, current 105.778275/648: elapsed=16797.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.778275
last_received_ts = 105.777702
last_seq = 648
current_ts = 105.795074
current_received_ts = 105.794479
current_seq = 649
count = 264
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.778275/648, current 105.795074/649: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.795074
last_received_ts = 105.794479
last_seq = 649
current_ts = 105.811867
current_received_ts = 105.811302
current_seq = 650
count = 265
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.795074/649, current 105.811867/650: elapsed=16797.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.811867
last_received_ts = 105.811302
last_seq = 650
current_ts = 105.828667
current_received_ts = 105.828094
current_seq = 651
count = 266
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.811867/650, current 105.828667/651: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.828667
last_received_ts = 105.828094
last_seq = 651
current_ts = 105.845459
current_received_ts = 105.844887
current_seq = 652
count = 267
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.828667/651, current 105.845459/652: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.845459
last_received_ts = 105.844887
last_seq = 652
current_ts = 105.862259
current_received_ts = 105.861687
current_seq = 653
count = 268
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.845459/652, current 105.862259/653: elapsed=16797.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.862259
last_received_ts = 105.861687
last_seq = 653
current_ts = 105.879051
current_received_ts = 105.878479
current_seq = 654
count = 269
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.862259/653, current 105.879051/654: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.879051
last_received_ts = 105.878479
last_seq = 654
current_ts = 105.895851
current_received_ts = 105.895279
current_seq = 655
count = 270
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.879051/654, current 105.895851/655: elapsed=16797.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.895851
last_received_ts = 105.895279
last_seq = 655
current_ts = 105.912643
current_received_ts = 105.912071
current_seq = 656
count = 271
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.895851/655, current 105.912643/656: elapsed=16795.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.912643
last_received_ts = 105.912071
last_seq = 656
current_ts = 105.929443
current_received_ts = 105.928879
current_seq = 657
count = 272
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.912643/656, current 105.929443/657: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.929443
last_received_ts = 105.928879
last_seq = 657
current_ts = 105.946236
current_received_ts = 105.945663
current_seq = 658
count = 273
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.929443/657, current 105.946236/658: elapsed=16797.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.946236
last_received_ts = 105.945663
last_seq = 658
current_ts = 105.963036
current_received_ts = 105.962463
current_seq = 659
count = 274
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.946236/658, current 105.963036/659: elapsed=16797.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.963036
last_received_ts = 105.962463
last_seq = 659
current_ts = 105.979828
current_received_ts = 105.979256
current_seq = 660
count = 275
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.963036/659, current 105.979828/660: elapsed=16794.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.979828
last_received_ts = 105.979256
last_seq = 660
current_ts = 105.996628
current_received_ts = 105.996086
current_seq = 661
count = 276
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.979828/660, current 105.996628/661: elapsed=16801.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 105.996628
last_received_ts = 105.996086
last_seq = 661
current_ts = 106.013428
current_received_ts = 106.012833
current_seq = 662
count = 277
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 105.996628/661, current 106.013428/662: elapsed=16794.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.013428
last_received_ts = 106.012833
last_seq = 662
current_ts = 106.030220
current_received_ts = 106.029655
current_seq = 663
count = 278
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.013428/662, current 106.030220/663: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.030220
last_received_ts = 106.029655
last_seq = 663
current_ts = 106.047020
current_received_ts = 106.046448
current_seq = 664
count = 279
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.030220/663, current 106.047020/664: elapsed=16797.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.047020
last_received_ts = 106.046448
last_seq = 664
current_ts = 106.063820
current_received_ts = 106.063171
current_seq = 665
count = 280
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.047020/664, current 106.063820/665: elapsed=16801.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.063820
last_received_ts = 106.063171
last_seq = 665
current_ts = 106.080612
current_received_ts = 106.080093
current_seq = 666
count = 281
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.063820/665, current 106.080612/666: elapsed=16792.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.080612
last_received_ts = 106.080093
last_seq = 666
current_ts = 106.097404
current_received_ts = 106.096832
current_seq = 667
count = 282
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.080612/666, current 106.097404/667: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.097404
last_received_ts = 106.096832
last_seq = 667
current_ts = 106.114204
current_received_ts = 106.113632
current_seq = 668
count = 283
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.097404/667, current 106.114204/668: elapsed=16797.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.114204
last_received_ts = 106.113632
last_seq = 668
current_ts = 106.130997
current_received_ts = 106.130402
current_seq = 669
count = 284
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.114204/668, current 106.130997/669: elapsed=16795.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.130997
last_received_ts = 106.130402
last_seq = 669
current_ts = 106.147797
current_received_ts = 106.147224
current_seq = 670
count = 285
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.130997/669, current 106.147797/670: elapsed=16797.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.147797
last_received_ts = 106.147224
last_seq = 670
current_ts = 106.164589
current_received_ts = 106.164047
current_seq = 671
count = 286
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.147797/670, current 106.164589/671: elapsed=16797.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.164589
last_received_ts = 106.164047
last_seq = 671
current_ts = 106.181389
current_received_ts = 106.180840
current_seq = 672
count = 287
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.164589/671, current 106.181389/672: elapsed=16795.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.181389
last_received_ts = 106.180840
last_seq = 672
current_ts = 106.198189
current_received_ts = 106.197624
current_seq = 673
count = 288
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.181389/672, current 106.198189/673: elapsed=16798.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.198189
last_received_ts = 106.197624
last_seq = 673
current_ts = 106.214981
current_received_ts = 106.214417
current_seq = 674
count = 289
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.198189/673, current 106.214981/674: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.214981
last_received_ts = 106.214417
last_seq = 674
current_ts = 106.231781
current_received_ts = 106.231216
current_seq = 675
count = 290
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.214981/674, current 106.231781/675: elapsed=16797.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.231781
last_received_ts = 106.231216
last_seq = 675
current_ts = 106.248573
current_received_ts = 106.247978
current_seq = 676
count = 291
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.231781/675, current 106.248573/676: elapsed=16795.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.248573
last_received_ts = 106.247978
last_seq = 676
current_ts = 106.265366
current_received_ts = 106.264793
current_seq = 677
count = 292
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.248573/676, current 106.265366/677: elapsed=16794.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.265366
last_received_ts = 106.264793
last_seq = 677
current_ts = 106.282166
current_received_ts = 106.281601
current_seq = 678
count = 293
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.265366/677, current 106.282166/678: elapsed=16799.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.282166
last_received_ts = 106.281601
last_seq = 678
current_ts = 106.298965
current_received_ts = 106.298393
current_seq = 679
count = 294
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.282166/678, current 106.298965/679: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.298965
last_received_ts = 106.298393
last_seq = 679
current_ts = 106.315758
current_received_ts = 106.315201
current_seq = 680
count = 295
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.298965/679, current 106.315758/680: elapsed=16798.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.315758
last_received_ts = 106.315201
last_seq = 680
current_ts = 106.332558
current_received_ts = 106.331993
current_seq = 681
count = 296
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.315758/680, current 106.332558/681: elapsed=16795.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.332558
last_received_ts = 106.331993
last_seq = 681
current_ts = 106.349350
current_received_ts = 106.348793
current_seq = 682
count = 297
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.332558/681, current 106.349350/682: elapsed=16797.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.349350
last_received_ts = 106.348793
last_seq = 682
current_ts = 106.366150
current_received_ts = 106.365547
current_seq = 683
count = 298
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.349350/682, current 106.366150/683: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.366150
last_received_ts = 106.365547
last_seq = 683
current_ts = 106.382942
current_received_ts = 106.382393
current_seq = 684
count = 299
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.366150/683, current 106.382942/684: elapsed=16797.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.382942
last_received_ts = 106.382393
last_seq = 684
current_ts = 106.399742
current_received_ts = 106.399178
current_seq = 685
count = 300
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.382942/684, current 106.399742/685: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.399742
last_received_ts = 106.399178
last_seq = 685
current_ts = 106.416534
current_received_ts = 106.415977
current_seq = 686
count = 301
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.399742/685, current 106.416534/686: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.416534
last_received_ts = 106.415977
last_seq = 686
current_ts = 106.433334
current_received_ts = 106.432770
current_seq = 687
count = 302
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.416534/686, current 106.433334/687: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.433334
last_received_ts = 106.432770
last_seq = 687
current_ts = 106.450127
current_received_ts = 106.449570
current_seq = 688
count = 303
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.433334/687, current 106.450127/688: elapsed=16797.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.450127
last_received_ts = 106.449570
last_seq = 688
current_ts = 106.466927
current_received_ts = 106.466354
current_seq = 689
count = 304
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.450127/688, current 106.466927/689: elapsed=16799.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.466927
last_received_ts = 106.466354
last_seq = 689
current_ts = 106.483719
current_received_ts = 106.483131
current_seq = 690
count = 305
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.466927/689, current 106.483719/690: elapsed=16790.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.483719
last_received_ts = 106.483131
last_seq = 690
current_ts = 106.500519
current_received_ts = 106.499954
current_seq = 691
count = 306
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.483719/690, current 106.500519/691: elapsed=16800.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.500519
last_received_ts = 106.499954
last_seq = 691
current_ts = 106.517319
current_received_ts = 106.516747
current_seq = 692
count = 307
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.500519/691, current 106.517319/692: elapsed=16798.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.517319
last_received_ts = 106.516747
last_seq = 692
current_ts = 106.534111
current_received_ts = 106.533539
current_seq = 693
count = 308
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.517319/692, current 106.534111/693: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.534111
last_received_ts = 106.533539
last_seq = 693
current_ts = 106.550911
current_received_ts = 106.550339
current_seq = 694
count = 309
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.534111/693, current 106.550911/694: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.550911
last_received_ts = 106.550339
last_seq = 694
current_ts = 106.567703
current_received_ts = 106.567131
current_seq = 695
count = 310
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.550911/694, current 106.567703/695: elapsed=16797.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.567703
last_received_ts = 106.567131
last_seq = 695
current_ts = 106.584503
current_received_ts = 106.583931
current_seq = 696
count = 311
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.567703/695, current 106.584503/696: elapsed=16795.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.584503
last_received_ts = 106.583931
last_seq = 696
current_ts = 106.601295
current_received_ts = 106.600700
current_seq = 697
count = 312
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.584503/696, current 106.601295/697: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.601295
last_received_ts = 106.600700
last_seq = 697
current_ts = 106.618095
current_received_ts = 106.617531
current_seq = 698
count = 313
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.601295/697, current 106.618095/698: elapsed=16798.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.618095
last_received_ts = 106.617531
last_seq = 698
current_ts = 106.634888
current_received_ts = 106.634315
current_seq = 699
count = 314
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.618095/698, current 106.634888/699: elapsed=16795.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.634888
last_received_ts = 106.634315
last_seq = 699
current_ts = 106.651688
current_received_ts = 106.651115
current_seq = 700
count = 315
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.634888/699, current 106.651688/700: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.651688
last_received_ts = 106.651115
last_seq = 700
current_ts = 106.668480
current_received_ts = 106.667908
current_seq = 701
count = 316
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.651688/700, current 106.668480/701: elapsed=16796.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.668480
last_received_ts = 106.667908
last_seq = 701
current_ts = 106.685272
current_received_ts = 106.684700
current_seq = 702
count = 317
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.668480/701, current 106.685272/702: elapsed=16791.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.685272
last_received_ts = 106.684700
last_seq = 702
current_ts = 106.702057
current_received_ts = 106.701492
current_seq = 703
count = 318
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.685272/702, current 106.702057/703: elapsed=16786.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.702057
last_received_ts = 106.701492
last_seq = 703
current_ts = 106.718849
current_received_ts = 106.718254
current_seq = 704
count = 319
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.702057/703, current 106.718849/704: elapsed=16788.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.718849
last_received_ts = 106.718254
last_seq = 704
current_ts = 106.735634
current_received_ts = 106.735092
current_seq = 705
count = 320
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.718849/704, current 106.735634/705: elapsed=16788.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.735634
last_received_ts = 106.735092
last_seq = 705
current_ts = 106.752426
current_received_ts = 106.751846
current_seq = 706
count = 321
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.735634/705, current 106.752426/706: elapsed=16788.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.752426
last_received_ts = 106.751846
last_seq = 706
current_ts = 106.769211
current_received_ts = 106.768639
current_seq = 707
count = 322
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.752426/706, current 106.769211/707: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.769211
last_received_ts = 106.768639
last_seq = 707
current_ts = 106.785995
current_received_ts = 106.785423
current_seq = 708
count = 323
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.769211/707, current 106.785995/708: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.785995
last_received_ts = 106.785423
last_seq = 708
current_ts = 106.802788
current_received_ts = 106.802155
current_seq = 709
count = 324
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.785995/708, current 106.802788/709: elapsed=16794.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.802788
last_received_ts = 106.802155
last_seq = 709
current_ts = 106.819572
current_received_ts = 106.819038
current_seq = 710
count = 325
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.802788/709, current 106.819572/710: elapsed=16782.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.819572
last_received_ts = 106.819038
last_seq = 710
current_ts = 106.836357
current_received_ts = 106.835770
current_seq = 711
count = 326
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.819572/710, current 106.836357/711: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.836357
last_received_ts = 106.835770
last_seq = 711
current_ts = 106.853149
current_received_ts = 106.852585
current_seq = 712
count = 327
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.836357/711, current 106.853149/712: elapsed=16788.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.853149
last_received_ts = 106.852585
last_seq = 712
current_ts = 106.869934
current_received_ts = 106.869362
current_seq = 713
count = 328
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.853149/712, current 106.869934/713: elapsed=16786.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.869934
last_received_ts = 106.869362
last_seq = 713
current_ts = 106.886719
current_received_ts = 106.886147
current_seq = 714
count = 329
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.869934/713, current 106.886719/714: elapsed=16788.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.886719
last_received_ts = 106.886147
last_seq = 714
current_ts = 106.903511
current_received_ts = 106.902939
current_seq = 715
count = 330
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.886719/714, current 106.903511/715: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.903511
last_received_ts = 106.902939
last_seq = 715
current_ts = 106.920296
current_received_ts = 106.919701
current_seq = 716
count = 331
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.903511/715, current 106.920296/716: elapsed=16789.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.920296
last_received_ts = 106.919701
last_seq = 716
current_ts = 106.937088
current_received_ts = 106.936516
current_seq = 717
count = 332
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.920296/716, current 106.937088/717: elapsed=16789.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.937088
last_received_ts = 106.936516
last_seq = 717
current_ts = 106.953873
current_received_ts = 106.953300
current_seq = 718
count = 333
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.937088/717, current 106.953873/718: elapsed=16786.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.953873
last_received_ts = 106.953300
last_seq = 718
current_ts = 106.970657
current_received_ts = 106.970116
current_seq = 719
count = 334
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.953873/718, current 106.970657/719: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.970657
last_received_ts = 106.970116
last_seq = 719
current_ts = 106.987442
current_received_ts = 106.986847
current_seq = 720
count = 335
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.970657/719, current 106.987442/720: elapsed=16784.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 106.987442
last_received_ts = 106.986847
last_seq = 720
current_ts = 107.004234
current_received_ts = 107.003654
current_seq = 721
count = 336
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 106.987442/720, current 107.004234/721: elapsed=16791.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.004234
last_received_ts = 107.003654
last_seq = 721
current_ts = 107.021019
current_received_ts = 107.020447
current_seq = 722
count = 337
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.004234/721, current 107.021019/722: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.021019
last_received_ts = 107.020447
last_seq = 722
current_ts = 107.037811
current_received_ts = 107.037239
current_seq = 723
count = 338
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.021019/722, current 107.037811/723: elapsed=16788.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.037811
last_received_ts = 107.037239
last_seq = 723
current_ts = 107.054596
current_received_ts = 107.054047
current_seq = 724
count = 339
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.037811/723, current 107.054596/724: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.054596
last_received_ts = 107.054047
last_seq = 724
current_ts = 107.071388
current_received_ts = 107.070808
current_seq = 725
count = 340
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.054596/724, current 107.071388/725: elapsed=16788.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.071388
last_received_ts = 107.070808
last_seq = 725
current_ts = 107.088173
current_received_ts = 107.087608
current_seq = 726
count = 341
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.071388/725, current 107.088173/726: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.088173
last_received_ts = 107.087608
last_seq = 726
current_ts = 107.104958
current_received_ts = 107.104385
current_seq = 727
count = 342
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.088173/726, current 107.104958/727: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.104958
last_received_ts = 107.104385
last_seq = 727
current_ts = 107.121750
current_received_ts = 107.121170
current_seq = 728
count = 343
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.104958/727, current 107.121750/728: elapsed=16788.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.121750
last_received_ts = 107.121170
last_seq = 728
current_ts = 107.138535
current_received_ts = 107.137962
current_seq = 729
count = 344
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.121750/728, current 107.138535/729: elapsed=16788.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.138535
last_received_ts = 107.137962
last_seq = 729
current_ts = 107.155319
current_received_ts = 107.154747
current_seq = 730
count = 345
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.138535/729, current 107.155319/730: elapsed=16782.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.155319
last_received_ts = 107.154747
last_seq = 730
current_ts = 107.172112
current_received_ts = 107.171516
current_seq = 731
count = 346
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.155319/730, current 107.172112/731: elapsed=16794.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.172112
last_received_ts = 107.171516
last_seq = 731
current_ts = 107.188896
current_received_ts = 107.188324
current_seq = 732
count = 347
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.172112/731, current 107.188896/732: elapsed=16786.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.188896
last_received_ts = 107.188324
last_seq = 732
current_ts = 107.205681
current_received_ts = 107.205116
current_seq = 733
count = 348
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.188896/732, current 107.205681/733: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.205681
last_received_ts = 107.205116
last_seq = 733
current_ts = 107.222473
current_received_ts = 107.221901
current_seq = 734
count = 349
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.205681/733, current 107.222473/734: elapsed=16789.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.222473
last_received_ts = 107.221901
last_seq = 734
current_ts = 107.239258
current_received_ts = 107.238686
current_seq = 735
count = 350
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.222473/734, current 107.239258/735: elapsed=16786.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.239258
last_received_ts = 107.238686
last_seq = 735
current_ts = 107.256050
current_received_ts = 107.255478
current_seq = 736
count = 351
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.239258/735, current 107.256050/736: elapsed=16788.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.256050
last_received_ts = 107.255478
last_seq = 736
current_ts = 107.272835
current_received_ts = 107.272263
current_seq = 737
count = 352
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.256050/736, current 107.272835/737: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.272835
last_received_ts = 107.272263
last_seq = 737
current_ts = 107.289619
current_received_ts = 107.289078
current_seq = 738
count = 353
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.272835/737, current 107.289619/738: elapsed=16789.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.289619
last_received_ts = 107.289078
last_seq = 738
current_ts = 107.306412
current_received_ts = 107.305817
current_seq = 739
count = 354
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.289619/738, current 107.306412/739: elapsed=16786.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.306412
last_received_ts = 107.305817
last_seq = 739
current_ts = 107.323196
current_received_ts = 107.322632
current_seq = 740
count = 355
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.306412/739, current 107.323196/740: elapsed=16788.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.323196
last_received_ts = 107.322632
last_seq = 740
current_ts = 107.339981
current_received_ts = 107.339409
current_seq = 741
count = 356
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.323196/740, current 107.339981/741: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.339981
last_received_ts = 107.339409
last_seq = 741
current_ts = 107.356773
current_received_ts = 107.356201
current_seq = 742
count = 357
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.339981/741, current 107.356773/742: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.356773
last_received_ts = 107.356201
last_seq = 742
current_ts = 107.373558
current_received_ts = 107.372986
current_seq = 743
count = 358
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.356773/742, current 107.373558/743: elapsed=16788.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.373558
last_received_ts = 107.372986
last_seq = 743
current_ts = 107.390350
current_received_ts = 107.389771
current_seq = 744
count = 359
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.373558/743, current 107.390350/744: elapsed=16788.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.390350
last_received_ts = 107.389771
last_seq = 744
current_ts = 107.407135
current_received_ts = 107.406563
current_seq = 745
count = 360
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.390350/744, current 107.407135/745: elapsed=16790.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.407135
last_received_ts = 107.406563
last_seq = 745
current_ts = 107.423927
current_received_ts = 107.423332
current_seq = 746
count = 361
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.407135/745, current 107.423927/746: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.423927
last_received_ts = 107.423332
last_seq = 746
current_ts = 107.440712
current_received_ts = 107.440147
current_seq = 747
count = 362
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.423927/746, current 107.440712/747: elapsed=16786.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.440712
last_received_ts = 107.440147
last_seq = 747
current_ts = 107.457497
current_received_ts = 107.456924
current_seq = 748
count = 363
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.440712/747, current 107.457497/748: elapsed=16786.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.457497
last_received_ts = 107.456924
last_seq = 748
current_ts = 107.474281
current_received_ts = 107.473717
current_seq = 749
count = 364
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.457497/748, current 107.474281/749: elapsed=16789.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.474281
last_received_ts = 107.473717
last_seq = 749
current_ts = 107.491066
current_received_ts = 107.490494
current_seq = 750
count = 365
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.474281/749, current 107.491066/750: elapsed=16783.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.491066
last_received_ts = 107.490494
last_seq = 750
current_ts = 107.507858
current_received_ts = 107.507294
current_seq = 751
count = 366
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.491066/750, current 107.507858/751: elapsed=16791.0us expected=16864.2us +- 84.3us, error 0.4%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.507858
last_received_ts = 107.507294
last_seq = 751
current_ts = 107.524651
current_received_ts = 107.524094
current_seq = 752
count = 367
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.507858/751, current 107.524651/752: elapsed=16788.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.524651
last_received_ts = 107.524094
last_seq = 752
current_ts = 107.541435
current_received_ts = 107.540840
current_seq = 753
count = 368
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.524651/752, current 107.541435/753: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.541435
last_received_ts = 107.540840
last_seq = 753
current_ts = 107.558220
current_received_ts = 107.557655
current_seq = 754
count = 369
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.541435/753, current 107.558220/754: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.558220
last_received_ts = 107.557655
last_seq = 754
current_ts = 107.575012
current_received_ts = 107.574432
current_seq = 755
count = 370
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.558220/754, current 107.575012/755: elapsed=16788.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.575012
last_received_ts = 107.574432
last_seq = 755
current_ts = 107.591797
current_received_ts = 107.591225
current_seq = 756
count = 371
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.575012/755, current 107.591797/756: elapsed=16788.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.591797
last_received_ts = 107.591225
last_seq = 756
current_ts = 107.608582
current_received_ts = 107.608047
current_seq = 757
count = 372
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.591797/756, current 107.608582/757: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.608582
last_received_ts = 107.608047
last_seq = 757
current_ts = 107.625374
current_received_ts = 107.624802
current_seq = 758
count = 373
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.608582/757, current 107.625374/758: elapsed=16788.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.625374
last_received_ts = 107.624802
last_seq = 758
current_ts = 107.642159
current_received_ts = 107.641563
current_seq = 759
count = 374
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.625374/758, current 107.642159/759: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.642159
last_received_ts = 107.641563
last_seq = 759
current_ts = 107.658943
current_received_ts = 107.658379
current_seq = 760
count = 375
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.642159/759, current 107.658943/760: elapsed=16787.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.658943
last_received_ts = 107.658379
last_seq = 760
current_ts = 107.675735
current_received_ts = 107.675163
current_seq = 761
count = 376
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.658943/760, current 107.675735/761: elapsed=16788.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: name = flip
last_ts = 107.675735
last_received_ts = 107.675163
last_seq = 761
current_ts = 107.692505
current_received_ts = 107.691895
current_seq = 762
count = 377
seq_step = 1
(kms_flip:1678) DEBUG: flip ts/seq: last 107.675735/761, current 107.692505/762: elapsed=16773.0us expected=16864.2us +- 84.3us, error 0.5%
(kms_flip:1678) DEBUG: inconsistent flip ts/seq: last 107.675735/761, current 107.692505/762: elapsed=16773.0us expected=16864.2us
(kms_flip:1678) DEBUG: expected 191425, counted 377, encoder type 1
(kms_flip:1678) DEBUG: dropped frames, expected 191425, counted 377, encoder type 1
(kms_flip:1678) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:1678) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:1678) igt_core-INFO: Stack trace:
(kms_flip:1678) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:1678) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:1678) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:1678) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:1678) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:1678) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:1678) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:1678) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-VGA1: FAIL (9.768s)
Dmesg
<6> [100.744665] [IGT] kms_flip: starting dynamic subtest B-VGA1
<7> [100.745271] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:84]
<7> [100.745404] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:85]
<7> [100.779285] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:47:pipe A]
<7> [100.779468] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.enable (expected yes, found no)
<7> [100.779927] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.active (expected yes, found no)
<7> [100.780251] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1)
<7> [100.780585] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in has_pch_encoder (expected yes, found no)
<7> [100.780884] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in fdi_lanes (expected 1, found 0)
<7> [100.781194] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in fdi_m_n (expected tu 64 data 6039797/8388608 link 125829/524288, found tu 0, data 0/0 link 0/0)
<7> [100.781592] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in output_types (expected 0x00000002, found 0x00000000)
<7> [100.781819] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [100.782025] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1024, found 0)
<7> [100.782230] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 1344, found 0)
<7> [100.782435] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1024, found 0)
<7> [100.782652] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 1344, found 0)
<7> [100.782858] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1048, found 0)
<7> [100.783063] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 1184, found 0)
<7> [100.783267] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 768, found 0)
<7> [100.783472] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 768, found 0)
<7> [100.783702] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 771, found 0)
<7> [100.783889] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 777, found 0)
<7> [100.784066] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 806, found 0)
<7> [100.784242] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 806, found 0)
<7> [100.784418] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1024, found 0)
<7> [100.784610] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 1344, found 0)
<7> [100.784853] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1024, found 0)
<7> [100.785061] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 1344, found 0)
<7> [100.785238] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1048, found 0)
<7> [100.785427] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 1184, found 0)
<7> [100.785653] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 768, found 0)
<7> [100.785863] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 768, found 0)
<7> [100.786055] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 771, found 0)
<7> [100.786255] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 777, found 0)
<7> [100.786463] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 806, found 0)
<7> [100.786680] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 806, found 0)
<7> [100.786878] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [100.787083] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)
<7> [100.787299] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)
<7> [100.787493] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0)
<7> [100.787705] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 64800, found 0)
<7> [100.787921] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 64800, found 0)
<7> [100.788128] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in port_clock (expected 64800, found 0)
<7> [100.788320] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:47:pipe A] fastset requirement not met, forcing full modeset
<7> [100.788507] i915 0000:00:02.0: [drm:intel_unreference_shared_dpll_crtc [i915]] [CRTC:47:pipe A] releasing PCH DPLL A
<7> [100.788780] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 400000 kHz, actual 400000 kHz
<7> [100.788970] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [100.789173] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:47:pipe A] enable: no [modeset]
<7> [100.789387] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:32:primary A] fb: [NOFB], visible: no
<7> [100.790054] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A
<7> [100.795666] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found
<7> [100.795845] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found
<7> [100.796024] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found
<7> [100.811659] i915 0000:00:02.0: [drm:intel_disable_shared_dpll [i915]] disable PCH DPLL A (active 0x1, on? 1) for [CRTC:47:pipe A]
<7> [100.812079] i915 0000:00:02.0: [drm:intel_disable_shared_dpll [i915]] disabling PCH DPLL A
<7> [100.812720] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:65:CRT]
<7> [100.812899] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:66:HDMI D]
<7> [100.813067] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:DP D]
<7> [100.813320] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:64:VGA-1]
<7> [100.813587] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:47:pipe A]
<7> [100.813855] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:63:pipe B]
<7> [100.813971] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:63:pipe B]
<7> [100.813992] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:64:VGA-1]
<7> [100.814046] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:64:VGA-1] Limiting display bpp to 24 (EDID bpp 0, max requested bpp 0, max platform bpp 36)
<7> [100.814288] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:63:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0
<7> [100.814625] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe B, lanes 1
<7> [100.814817] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.enable (expected no, found yes)
<7> [100.815001] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.active (expected no, found yes)
<7> [100.815183] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)
<7> [100.815431] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in has_pch_encoder (expected no, found yes)
<7> [100.815655] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in fdi_lanes (expected 0, found 1)
<7> [100.815838] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in fdi_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6039797/8388608 link 125829/524288)
<7> [100.816038] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000002)
<7> [100.816220] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [100.816415] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1024)
<7> [100.816658] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 1344)
<7> [100.816878] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1024)
<7> [100.817067] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 1344)
<7> [100.817272] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1048)
<7> [100.817469] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 1184)
<7> [100.817696] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 768)
<7> [100.817912] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 768)
<7> [100.818111] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 771)
<7> [100.818311] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 777)
<7> [100.818533] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 806)
<7> [100.818739] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 806)
<7> [100.818919] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1024)
<7> [100.819105] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 1344)
<7> [100.819310] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1024)
<7> [100.819523] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 1344)
<7> [100.819750] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1048)
<7> [100.819960] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 1184)
<7> [100.820148] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 768)
<7> [100.820364] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 768)
<7> [100.820551] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 771)
<7> [100.820769] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 777)
<7> [100.820975] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 806)
<7> [100.821155] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 806)
<7> [100.821378] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [100.821590] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)
<7> [100.821826] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)
<7> [100.822033] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in dpll_hw_state
<7> [100.822246] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:
<7> [100.822428] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0xc4010001, dpll_md: 0x0, fp0: 0x30f06, fp1: 0x30f06
<7> [100.822657] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:
<7> [100.822864] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [100.823061] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24)
<7> [100.823268] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 64800)
<7> [100.823450] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 64800)
<7> [100.823676] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in port_clock (expected 0, found 64800)
<7> [100.823876] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:63:pipe B] fastset requirement not met, forcing full modeset
<7> [100.824103] i915 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [i915]] [PLANE:48:primary B] min cdclk (64800 kHz) > [CRTC:63:pipe B] min cdclk (0 kHz)
<7> [100.824327] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 400000 kHz, actual 400000 kHz
<7> [100.824518] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [100.824734] i915 0000:00:02.0: [drm:intel_find_shared_dpll [i915]] [CRTC:63:pipe B] allocated PCH DPLL A
<7> [100.824933] i915 0000:00:02.0: [drm:intel_reference_shared_dpll_crtc [i915]] [CRTC:63:pipe B] reserving PCH DPLL A
<7> [100.825136] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:63:pipe B] enable: yes [modeset]
<7> [100.825355] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: ANALOG (0x2), output format: RGB, sink format: RGB
<7> [100.825553] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0
<7> [100.825735] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [100.825967] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [100.826191] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [100.826400] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [100.826583] 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> [100.826791] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0
<7> [100.827004] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0
<7> [100.827241] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, vmin: 0, vmax: 0, pipeline full: 0, guardband: 0 flipline: 0, vmin vblank: -1, vmax vblank: -2
<7> [100.827448] 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> [100.827627] 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> [100.827870] 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> [100.828077] 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> [100.828298] 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> [100.828494] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 64800, pipe src: 1024x768+0+0, pixel rate 64800
<7> [100.828677] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0
<7> [100.828858] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [100.829059] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [100.829285] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [100.829471] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [100.829658] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [100.829840] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [100.830022] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [100.830230] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [100.830415] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [100.830608] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:48:primary B] fb: [FB:84] 1024x768 format = XR24 little-endian (0x34325258) modifier = 0x0, visible: yes
<7> [100.830786] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [100.830995] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1024.000000x768.000000+0.000000+0.000000 dst: 1024x768+0+0
<7> [100.831199] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on
<7> [100.832111] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on
<7> [100.832334] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:65:CRT]
<7> [100.832504] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:66:HDMI D]
<7> [100.832684] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:DP D]
<7> [100.833456] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B
<7> [100.834477] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100
<7> [100.834655] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done.
<7> [100.835491] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x200
<7> [100.835684] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done.
<7> [100.835858] i915 0000:00:02.0: [drm:ilk_pch_enable [i915]] FDI train done.
<7> [100.836034] i915 0000:00:02.0: [drm:intel_enable_shared_dpll [i915]] enable PCH DPLL A (active 0x2, on? 0) for [CRTC:63:pipe B]
<7> [100.836234] i915 0000:00:02.0: [drm:intel_enable_shared_dpll [i915]] enabling PCH DPLL A
<7> [100.888058] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:64:VGA-1]
<7> [100.888487] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:63:pipe B]
<6> [110.512509] [IGT] kms_flip: finished subtest B-VGA1, FAIL
Created at 2024-11-06 02:57:52