Results for igt@kms_flip@plain-flip-fb-recreate

shard-dg2-5

IGT-Version: 1.30-g8bce68b09 (x86_64) (Linux: 6.13.0-rc3-CI_DRM_15862-g1d0ef0c9b38e+ x86_64)

Using IGT_SRANDOM=1734544450 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-fb-recreate
Starting dynamic subtest: A-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16667.6us +- 5.058us accuracy 0.09%
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 A-HDMI-A3: FAIL (10.170s)
Starting dynamic subtest: B-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 17031.6us +- 6.791us accuracy 0.12%
vblank interval differs from modeline! expected 16666.7us, measured 17032us +- 6.791us, difference 365.0us (53.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-HDMI-A3: FAIL (4.679s)
Starting dynamic subtest: C-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16858.3us +- 5.805us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 16858us +- 5.805us, difference 191.6us (33.0 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 C-HDMI-A3: FAIL (7.375s)
Starting dynamic subtest: D-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16746.9us +- 5.265us accuracy 0.09%
vblank interval differs from modeline! expected 16666.7us, measured 16747us +- 5.265us, difference 80.2us (15.2 sigma)
Dynamic subtest D-HDMI-A3: SUCCESS (7.924s)
Subtest plain-flip-fb-recreate: FAIL (30.162s)

Starting subtest: plain-flip-fb-recreate
Starting dynamic subtest: A-HDMI-A3
(kms_flip:2297) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2297) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:2297) DEBUG: flip ts/seq: last 184.752258/2879, current 184.768936/2880: elapsed=16672.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 184.768936
last_received_ts = 184.768539
last_seq = 2880
current_ts = 184.785599
current_received_ts = 184.785202
current_seq = 2881
count = 271
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 184.768936/2880, current 184.785599/2881: elapsed=16672.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 184.785599
last_received_ts = 184.785202
last_seq = 2881
current_ts = 184.802277
current_received_ts = 184.801834
current_seq = 2882
count = 272
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 184.785599/2881, current 184.802277/2882: elapsed=16664.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 184.802277
last_received_ts = 184.801834
last_seq = 2882
current_ts = 184.818924
current_received_ts = 184.818497
current_seq = 2883
count = 273
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 184.802277/2882, current 184.818924/2883: elapsed=16660.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 184.818924
last_received_ts = 184.818497
last_seq = 2883
current_ts = 184.835602
current_received_ts = 184.835358
current_seq = 2884
count = 274
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 184.818924/2883, current 184.835602/2884: elapsed=16676.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 184.835602
last_received_ts = 184.835358
last_seq = 2884
current_ts = 184.852264
current_received_ts = 184.851883
current_seq = 2885
count = 275
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 184.835602/2884, current 184.852264/2885: elapsed=16663.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 184.852264
last_received_ts = 184.851883
last_seq = 2885
current_ts = 184.868942
current_received_ts = 184.868530
current_seq = 2886
count = 276
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 184.852264/2885, current 184.868942/2886: elapsed=16673.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 184.868942
last_received_ts = 184.868530
last_seq = 2886
current_ts = 184.885605
current_received_ts = 184.885193
current_seq = 2887
count = 277
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 184.868942/2886, current 184.885605/2887: elapsed=16669.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 184.885605
last_received_ts = 184.885193
last_seq = 2887
current_ts = 184.902283
current_received_ts = 184.901978
current_seq = 2888
count = 278
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 184.885605/2887, current 184.902283/2888: elapsed=16667.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 184.902283
last_received_ts = 184.901978
last_seq = 2888
current_ts = 184.918930
current_received_ts = 184.918655
current_seq = 2889
count = 279
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 184.902283/2888, current 184.918930/2889: elapsed=16658.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 184.918930
last_received_ts = 184.918655
last_seq = 2889
current_ts = 184.935608
current_received_ts = 184.935394
current_seq = 2890
count = 280
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 184.918930/2889, current 184.935608/2890: elapsed=16675.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 184.935608
last_received_ts = 184.935394
last_seq = 2890
current_ts = 184.952286
current_received_ts = 184.951859
current_seq = 2891
count = 281
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 184.935608/2890, current 184.952286/2891: elapsed=16669.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 184.952286
last_received_ts = 184.951859
last_seq = 2891
current_ts = 184.968948
current_received_ts = 184.968536
current_seq = 2892
count = 282
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 184.952286/2891, current 184.968948/2892: elapsed=16664.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 184.968948
last_received_ts = 184.968536
last_seq = 2892
current_ts = 184.985611
current_received_ts = 184.985214
current_seq = 2893
count = 283
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 184.968948/2892, current 184.985611/2893: elapsed=16665.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 184.985611
last_received_ts = 184.985214
last_seq = 2893
current_ts = 185.002274
current_received_ts = 185.001984
current_seq = 2894
count = 284
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 184.985611/2893, current 185.002274/2894: elapsed=16670.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.002274
last_received_ts = 185.001984
last_seq = 2894
current_ts = 185.018936
current_received_ts = 185.018524
current_seq = 2895
count = 285
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.002274/2894, current 185.018936/2895: elapsed=16660.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.018936
last_received_ts = 185.018524
last_seq = 2895
current_ts = 185.035599
current_received_ts = 185.035202
current_seq = 2896
count = 286
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.018936/2895, current 185.035599/2896: elapsed=16667.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.035599
last_received_ts = 185.035202
last_seq = 2896
current_ts = 185.052277
current_received_ts = 185.051987
current_seq = 2897
count = 287
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.035599/2896, current 185.052277/2897: elapsed=16674.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.052277
last_received_ts = 185.051987
last_seq = 2897
current_ts = 185.068954
current_received_ts = 185.068542
current_seq = 2898
count = 288
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.052277/2897, current 185.068954/2898: elapsed=16670.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.068954
last_received_ts = 185.068542
last_seq = 2898
current_ts = 185.085617
current_received_ts = 185.085342
current_seq = 2899
count = 289
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.068954/2898, current 185.085617/2899: elapsed=16666.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.085617
last_received_ts = 185.085342
last_seq = 2899
current_ts = 185.102280
current_received_ts = 185.101868
current_seq = 2900
count = 290
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.085617/2899, current 185.102280/2900: elapsed=16669.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.102280
last_received_ts = 185.101868
last_seq = 2900
current_ts = 185.118958
current_received_ts = 185.118530
current_seq = 2901
count = 291
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.102280/2900, current 185.118958/2901: elapsed=16665.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.118958
last_received_ts = 185.118530
last_seq = 2901
current_ts = 185.135620
current_received_ts = 185.135376
current_seq = 2902
count = 292
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.118958/2901, current 185.135620/2902: elapsed=16668.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.135620
last_received_ts = 185.135376
last_seq = 2902
current_ts = 185.152267
current_received_ts = 185.152039
current_seq = 2903
count = 293
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.135620/2902, current 185.152267/2903: elapsed=16656.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.152267
last_received_ts = 185.152039
last_seq = 2903
current_ts = 185.168945
current_received_ts = 185.168549
current_seq = 2904
count = 294
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.152267/2903, current 185.168945/2904: elapsed=16672.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.168945
last_received_ts = 185.168549
last_seq = 2904
current_ts = 185.185623
current_received_ts = 185.185257
current_seq = 2905
count = 295
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.168945/2904, current 185.185623/2905: elapsed=16671.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.185623
last_received_ts = 185.185257
last_seq = 2905
current_ts = 185.202286
current_received_ts = 185.201889
current_seq = 2906
count = 296
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.185623/2905, current 185.202286/2906: elapsed=16672.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.202286
last_received_ts = 185.201889
last_seq = 2906
current_ts = 185.218948
current_received_ts = 185.218628
current_seq = 2907
count = 297
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.202286/2906, current 185.218948/2907: elapsed=16659.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.218948
last_received_ts = 185.218628
last_seq = 2907
current_ts = 185.235611
current_received_ts = 185.235214
current_seq = 2908
count = 298
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.218948/2907, current 185.235611/2908: elapsed=16664.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.235611
last_received_ts = 185.235214
last_seq = 2908
current_ts = 185.252289
current_received_ts = 185.251892
current_seq = 2909
count = 299
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.235611/2908, current 185.252289/2909: elapsed=16676.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.252289
last_received_ts = 185.251892
last_seq = 2909
current_ts = 185.268951
current_received_ts = 185.268661
current_seq = 2910
count = 300
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.252289/2909, current 185.268951/2910: elapsed=16657.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.268951
last_received_ts = 185.268661
last_seq = 2910
current_ts = 185.285629
current_received_ts = 185.285278
current_seq = 2911
count = 301
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.268951/2910, current 185.285629/2911: elapsed=16677.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.285629
last_received_ts = 185.285278
last_seq = 2911
current_ts = 185.302292
current_received_ts = 185.301895
current_seq = 2912
count = 302
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.285629/2911, current 185.302292/2912: elapsed=16665.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.302292
last_received_ts = 185.301895
last_seq = 2912
current_ts = 185.318954
current_received_ts = 185.318588
current_seq = 2913
count = 303
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.302292/2912, current 185.318954/2913: elapsed=16669.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.318954
last_received_ts = 185.318588
last_seq = 2913
current_ts = 185.335632
current_received_ts = 185.335403
current_seq = 2914
count = 304
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.318954/2913, current 185.335632/2914: elapsed=16671.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.335632
last_received_ts = 185.335403
last_seq = 2914
current_ts = 185.352295
current_received_ts = 185.351898
current_seq = 2915
count = 305
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.335632/2914, current 185.352295/2915: elapsed=16664.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.352295
last_received_ts = 185.351898
last_seq = 2915
current_ts = 185.368942
current_received_ts = 185.368637
current_seq = 2916
count = 306
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.352295/2915, current 185.368942/2916: elapsed=16657.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.368942
last_received_ts = 185.368637
last_seq = 2916
current_ts = 185.385620
current_received_ts = 185.385406
current_seq = 2917
count = 307
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.368942/2916, current 185.385620/2917: elapsed=16669.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.385620
last_received_ts = 185.385406
last_seq = 2917
current_ts = 185.402298
current_received_ts = 185.401886
current_seq = 2918
count = 308
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.385620/2917, current 185.402298/2918: elapsed=16675.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.402298
last_received_ts = 185.401886
last_seq = 2918
current_ts = 185.418961
current_received_ts = 185.418655
current_seq = 2919
count = 309
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.402298/2918, current 185.418961/2919: elapsed=16670.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.418961
last_received_ts = 185.418655
last_seq = 2919
current_ts = 185.435623
current_received_ts = 185.435196
current_seq = 2920
count = 310
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.418961/2919, current 185.435623/2920: elapsed=16658.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.435623
last_received_ts = 185.435196
last_seq = 2920
current_ts = 185.452301
current_received_ts = 185.452057
current_seq = 2921
count = 311
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.435623/2920, current 185.452301/2921: elapsed=16678.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.452301
last_received_ts = 185.452057
last_seq = 2921
current_ts = 185.468964
current_received_ts = 185.468567
current_seq = 2922
count = 312
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.452301/2921, current 185.468964/2922: elapsed=16665.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.468964
last_received_ts = 185.468567
last_seq = 2922
current_ts = 185.485626
current_received_ts = 185.485413
current_seq = 2923
count = 313
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.468964/2922, current 185.485626/2923: elapsed=16665.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.485626
last_received_ts = 185.485413
last_seq = 2923
current_ts = 185.502289
current_received_ts = 185.501862
current_seq = 2924
count = 314
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.485626/2923, current 185.502289/2924: elapsed=16660.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.502289
last_received_ts = 185.501862
last_seq = 2924
current_ts = 185.518967
current_received_ts = 185.518555
current_seq = 2925
count = 315
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.502289/2924, current 185.518967/2925: elapsed=16675.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.518967
last_received_ts = 185.518555
last_seq = 2925
current_ts = 185.535629
current_received_ts = 185.535370
current_seq = 2926
count = 316
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.518967/2925, current 185.535629/2926: elapsed=16670.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.535629
last_received_ts = 185.535370
last_seq = 2926
current_ts = 185.552292
current_received_ts = 185.552063
current_seq = 2927
count = 317
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.535629/2926, current 185.552292/2927: elapsed=16666.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.552292
last_received_ts = 185.552063
last_seq = 2927
current_ts = 185.568970
current_received_ts = 185.568558
current_seq = 2928
count = 318
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.552292/2927, current 185.568970/2928: elapsed=16667.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.568970
last_received_ts = 185.568558
last_seq = 2928
current_ts = 185.585632
current_received_ts = 185.585251
current_seq = 2929
count = 319
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.568970/2928, current 185.585632/2929: elapsed=16665.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.585632
last_received_ts = 185.585251
last_seq = 2929
current_ts = 185.602295
current_received_ts = 185.601868
current_seq = 2930
count = 320
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.585632/2929, current 185.602295/2930: elapsed=16658.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.602295
last_received_ts = 185.601868
last_seq = 2930
current_ts = 185.618958
current_received_ts = 185.618561
current_seq = 2931
count = 321
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.602295/2930, current 185.618958/2931: elapsed=16670.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.618958
last_received_ts = 185.618561
last_seq = 2931
current_ts = 185.635635
current_received_ts = 185.635284
current_seq = 2932
count = 322
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.618958/2931, current 185.635635/2932: elapsed=16674.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.635635
last_received_ts = 185.635284
last_seq = 2932
current_ts = 185.652298
current_received_ts = 185.651855
current_seq = 2933
count = 323
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.635635/2932, current 185.652298/2933: elapsed=16672.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.652298
last_received_ts = 185.651855
last_seq = 2933
current_ts = 185.668961
current_received_ts = 185.668564
current_seq = 2934
count = 324
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.652298/2933, current 185.668961/2934: elapsed=16657.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.668961
last_received_ts = 185.668564
last_seq = 2934
current_ts = 185.685638
current_received_ts = 185.685410
current_seq = 2935
count = 325
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.668961/2934, current 185.685638/2935: elapsed=16672.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.685638
last_received_ts = 185.685410
last_seq = 2935
current_ts = 185.702301
current_received_ts = 185.701904
current_seq = 2936
count = 326
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.685638/2935, current 185.702301/2936: elapsed=16671.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.702301
last_received_ts = 185.701904
last_seq = 2936
current_ts = 185.718964
current_received_ts = 185.718567
current_seq = 2937
count = 327
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.702301/2936, current 185.718964/2937: elapsed=16661.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.718964
last_received_ts = 185.718567
last_seq = 2937
current_ts = 185.735641
current_received_ts = 185.735428
current_seq = 2938
count = 328
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.718964/2937, current 185.735641/2938: elapsed=16676.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.735641
last_received_ts = 185.735428
last_seq = 2938
current_ts = 185.752304
current_received_ts = 185.752075
current_seq = 2939
count = 329
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.735641/2938, current 185.752304/2939: elapsed=16662.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.752304
last_received_ts = 185.752075
last_seq = 2939
current_ts = 185.768967
current_received_ts = 185.768600
current_seq = 2940
count = 330
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.752304/2939, current 185.768967/2940: elapsed=16662.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.768967
last_received_ts = 185.768600
last_seq = 2940
current_ts = 185.785645
current_received_ts = 185.785431
current_seq = 2941
count = 331
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.768967/2940, current 185.785645/2941: elapsed=16672.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.785645
last_received_ts = 185.785431
last_seq = 2941
current_ts = 185.802307
current_received_ts = 185.802078
current_seq = 2942
count = 332
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.785645/2941, current 185.802307/2942: elapsed=16670.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.802307
last_received_ts = 185.802078
last_seq = 2942
current_ts = 185.818970
current_received_ts = 185.818604
current_seq = 2943
count = 333
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.802307/2942, current 185.818970/2943: elapsed=16656.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.818970
last_received_ts = 185.818604
last_seq = 2943
current_ts = 185.835632
current_received_ts = 185.835236
current_seq = 2944
count = 334
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.818970/2943, current 185.835632/2944: elapsed=16670.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.835632
last_received_ts = 185.835236
last_seq = 2944
current_ts = 185.852310
current_received_ts = 185.852066
current_seq = 2945
count = 335
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.835632/2944, current 185.852310/2945: elapsed=16676.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.852310
last_received_ts = 185.852066
last_seq = 2945
current_ts = 185.868973
current_received_ts = 185.868607
current_seq = 2946
count = 336
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.852310/2945, current 185.868973/2946: elapsed=16660.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.868973
last_received_ts = 185.868607
last_seq = 2946
current_ts = 185.885651
current_received_ts = 185.885223
current_seq = 2947
count = 337
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.868973/2946, current 185.885651/2947: elapsed=16673.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.885651
last_received_ts = 185.885223
last_seq = 2947
current_ts = 185.902298
current_received_ts = 185.902054
current_seq = 2948
count = 338
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.885651/2947, current 185.902298/2948: elapsed=16660.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.902298
last_received_ts = 185.902054
last_seq = 2948
current_ts = 185.918976
current_received_ts = 185.918610
current_seq = 2949
count = 339
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.902298/2948, current 185.918976/2949: elapsed=16667.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.918976
last_received_ts = 185.918610
last_seq = 2949
current_ts = 185.935654
current_received_ts = 185.935242
current_seq = 2950
count = 340
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.918976/2949, current 185.935654/2950: elapsed=16679.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.935654
last_received_ts = 185.935242
last_seq = 2950
current_ts = 185.952316
current_received_ts = 185.952057
current_seq = 2951
count = 341
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.935654/2950, current 185.952316/2951: elapsed=16661.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.952316
last_received_ts = 185.952057
last_seq = 2951
current_ts = 185.968964
current_received_ts = 185.968597
current_seq = 2952
count = 342
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.952316/2951, current 185.968964/2952: elapsed=16659.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.968964
last_received_ts = 185.968597
last_seq = 2952
current_ts = 185.985641
current_received_ts = 185.985291
current_seq = 2953
count = 343
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.968964/2952, current 185.985641/2953: elapsed=16677.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 185.985641
last_received_ts = 185.985291
last_seq = 2953
current_ts = 186.002319
current_received_ts = 186.002060
current_seq = 2954
count = 344
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 185.985641/2953, current 186.002319/2954: elapsed=16671.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.002319
last_received_ts = 186.002060
last_seq = 2954
current_ts = 186.018982
current_received_ts = 186.018585
current_seq = 2955
count = 345
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.002319/2954, current 186.018982/2955: elapsed=16659.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.018982
last_received_ts = 186.018585
last_seq = 2955
current_ts = 186.035645
current_received_ts = 186.035416
current_seq = 2956
count = 346
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.018982/2955, current 186.035645/2956: elapsed=16673.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.035645
last_received_ts = 186.035416
last_seq = 2956
current_ts = 186.052307
current_received_ts = 186.052078
current_seq = 2957
count = 347
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.035645/2956, current 186.052307/2957: elapsed=16658.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.052307
last_received_ts = 186.052078
last_seq = 2957
current_ts = 186.068985
current_received_ts = 186.068588
current_seq = 2958
count = 348
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.052307/2957, current 186.068985/2958: elapsed=16675.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.068985
last_received_ts = 186.068588
last_seq = 2958
current_ts = 186.085648
current_received_ts = 186.085281
current_seq = 2959
count = 349
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.068985/2958, current 186.085648/2959: elapsed=16662.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.085648
last_received_ts = 186.085281
last_seq = 2959
current_ts = 186.102325
current_received_ts = 186.101883
current_seq = 2960
count = 350
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.085648/2959, current 186.102325/2960: elapsed=16678.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.102325
last_received_ts = 186.101883
last_seq = 2960
current_ts = 186.118988
current_received_ts = 186.118576
current_seq = 2961
count = 351
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.102325/2960, current 186.118988/2961: elapsed=16660.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.118988
last_received_ts = 186.118576
last_seq = 2961
current_ts = 186.135651
current_received_ts = 186.135284
current_seq = 2962
count = 352
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.118988/2961, current 186.135651/2962: elapsed=16671.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.135651
last_received_ts = 186.135284
last_seq = 2962
current_ts = 186.152313
current_received_ts = 186.151901
current_seq = 2963
count = 353
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.135651/2962, current 186.152313/2963: elapsed=16658.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.152313
last_received_ts = 186.151901
last_seq = 2963
current_ts = 186.168991
current_received_ts = 186.168579
current_seq = 2964
count = 354
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.152313/2963, current 186.168991/2964: elapsed=16673.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.168991
last_received_ts = 186.168579
last_seq = 2964
current_ts = 186.185654
current_received_ts = 186.185257
current_seq = 2965
count = 355
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.168991/2964, current 186.185654/2965: elapsed=16669.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.185654
last_received_ts = 186.185257
last_seq = 2965
current_ts = 186.202332
current_received_ts = 186.201874
current_seq = 2966
count = 356
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.185654/2965, current 186.202332/2966: elapsed=16672.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.202332
last_received_ts = 186.201874
last_seq = 2966
current_ts = 186.218994
current_received_ts = 186.218582
current_seq = 2967
count = 357
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.202332/2966, current 186.218994/2967: elapsed=16665.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.218994
last_received_ts = 186.218582
last_seq = 2967
current_ts = 186.235657
current_received_ts = 186.235306
current_seq = 2968
count = 358
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.218994/2967, current 186.235657/2968: elapsed=16663.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.235657
last_received_ts = 186.235306
last_seq = 2968
current_ts = 186.252319
current_received_ts = 186.252060
current_seq = 2969
count = 359
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.235657/2968, current 186.252319/2969: elapsed=16673.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.252319
last_received_ts = 186.252060
last_seq = 2969
current_ts = 186.268982
current_received_ts = 186.268539
current_seq = 2970
count = 360
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.252319/2969, current 186.268982/2970: elapsed=16663.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.268982
last_received_ts = 186.268539
last_seq = 2970
current_ts = 186.285645
current_received_ts = 186.285141
current_seq = 2971
count = 361
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.268982/2970, current 186.285645/2971: elapsed=16659.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.285645
last_received_ts = 186.285141
last_seq = 2971
current_ts = 186.302322
current_received_ts = 186.301819
current_seq = 2972
count = 362
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.285645/2971, current 186.302322/2972: elapsed=16668.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.302322
last_received_ts = 186.301819
last_seq = 2972
current_ts = 186.318985
current_received_ts = 186.318512
current_seq = 2973
count = 363
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.302322/2972, current 186.318985/2973: elapsed=16674.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.318985
last_received_ts = 186.318512
last_seq = 2973
current_ts = 186.335663
current_received_ts = 186.335251
current_seq = 2974
count = 364
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.318985/2973, current 186.335663/2974: elapsed=16671.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.335663
last_received_ts = 186.335251
last_seq = 2974
current_ts = 186.352325
current_received_ts = 186.351929
current_seq = 2975
count = 365
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.335663/2974, current 186.352325/2975: elapsed=16663.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.352325
last_received_ts = 186.351929
last_seq = 2975
current_ts = 186.368988
current_received_ts = 186.368591
current_seq = 2976
count = 366
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.352325/2975, current 186.368988/2976: elapsed=16665.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.368988
last_received_ts = 186.368591
last_seq = 2976
current_ts = 186.385666
current_received_ts = 186.385208
current_seq = 2977
count = 367
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.368988/2976, current 186.385666/2977: elapsed=16673.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.385666
last_received_ts = 186.385208
last_seq = 2977
current_ts = 186.402313
current_received_ts = 186.401901
current_seq = 2978
count = 368
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.385666/2977, current 186.402313/2978: elapsed=16658.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.402313
last_received_ts = 186.401901
last_seq = 2978
current_ts = 186.418991
current_received_ts = 186.418655
current_seq = 2979
count = 369
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.402313/2978, current 186.418991/2979: elapsed=16669.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.418991
last_received_ts = 186.418655
last_seq = 2979
current_ts = 186.435669
current_received_ts = 186.435257
current_seq = 2980
count = 370
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.418991/2979, current 186.435669/2980: elapsed=16673.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.435669
last_received_ts = 186.435257
last_seq = 2980
current_ts = 186.452332
current_received_ts = 186.452087
current_seq = 2981
count = 371
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.435669/2980, current 186.452332/2981: elapsed=16669.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.452332
last_received_ts = 186.452087
last_seq = 2981
current_ts = 186.468994
current_received_ts = 186.468567
current_seq = 2982
count = 372
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.452332/2981, current 186.468994/2982: elapsed=16670.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.468994
last_received_ts = 186.468567
last_seq = 2982
current_ts = 186.485672
current_received_ts = 186.485245
current_seq = 2983
count = 373
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.468994/2982, current 186.485672/2983: elapsed=16669.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.485672
last_received_ts = 186.485245
last_seq = 2983
current_ts = 186.502350
current_received_ts = 186.501892
current_seq = 2984
count = 374
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.485672/2983, current 186.502350/2984: elapsed=16676.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.502350
last_received_ts = 186.501892
last_seq = 2984
current_ts = 186.519028
current_received_ts = 186.518570
current_seq = 2985
count = 375
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.502350/2984, current 186.519028/2985: elapsed=16675.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.519028
last_received_ts = 186.518570
last_seq = 2985
current_ts = 186.535690
current_received_ts = 186.535248
current_seq = 2986
count = 376
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.519028/2985, current 186.535690/2986: elapsed=16674.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.535690
last_received_ts = 186.535248
last_seq = 2986
current_ts = 186.552383
current_received_ts = 186.551910
current_seq = 2987
count = 377
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.535690/2986, current 186.552383/2987: elapsed=16681.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.552383
last_received_ts = 186.551910
last_seq = 2987
current_ts = 186.569046
current_received_ts = 186.568588
current_seq = 2988
count = 378
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.552383/2987, current 186.569046/2988: elapsed=16668.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.569046
last_received_ts = 186.568588
last_seq = 2988
current_ts = 186.585724
current_received_ts = 186.585236
current_seq = 2989
count = 379
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.569046/2988, current 186.585724/2989: elapsed=16677.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.585724
last_received_ts = 186.585236
last_seq = 2989
current_ts = 186.602402
current_received_ts = 186.601944
current_seq = 2990
count = 380
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.585724/2989, current 186.602402/2990: elapsed=16675.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.602402
last_received_ts = 186.601944
last_seq = 2990
current_ts = 186.619080
current_received_ts = 186.618744
current_seq = 2991
count = 381
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.602402/2990, current 186.619080/2991: elapsed=16679.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.619080
last_received_ts = 186.618744
last_seq = 2991
current_ts = 186.635742
current_received_ts = 186.635269
current_seq = 2992
count = 382
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.619080/2991, current 186.635742/2992: elapsed=16672.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.635742
last_received_ts = 186.635269
last_seq = 2992
current_ts = 186.652420
current_received_ts = 186.652130
current_seq = 2993
count = 383
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.635742/2992, current 186.652420/2993: elapsed=16677.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.652420
last_received_ts = 186.652130
last_seq = 2993
current_ts = 186.669113
current_received_ts = 186.668777
current_seq = 2994
count = 384
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.652420/2993, current 186.669113/2994: elapsed=16685.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.669113
last_received_ts = 186.668777
last_seq = 2994
current_ts = 186.685776
current_received_ts = 186.685257
current_seq = 2995
count = 385
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.669113/2994, current 186.685776/2995: elapsed=16666.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.685776
last_received_ts = 186.685257
last_seq = 2995
current_ts = 186.702454
current_received_ts = 186.701996
current_seq = 2996
count = 386
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.685776/2995, current 186.702454/2996: elapsed=16684.0us expected=16667.6us +- 83.3us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.702454
last_received_ts = 186.701996
last_seq = 2996
current_ts = 186.719131
current_received_ts = 186.718689
current_seq = 2997
count = 387
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.702454/2996, current 186.719131/2997: elapsed=16674.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.719131
last_received_ts = 186.718689
last_seq = 2997
current_ts = 186.735809
current_received_ts = 186.735382
current_seq = 2998
count = 388
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.719131/2997, current 186.735809/2998: elapsed=16675.0us expected=16667.6us +- 83.3us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.735809
last_received_ts = 186.735382
last_seq = 2998
current_ts = 186.752533
current_received_ts = 186.752136
current_seq = 2999
count = 389
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.735809/2998, current 186.752533/2999: elapsed=16725.0us expected=16667.6us +- 83.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 186.752533
last_received_ts = 186.752136
last_seq = 2999
current_ts = 186.769745
current_received_ts = 186.769348
current_seq = 3000
count = 390
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 186.752533/2999, current 186.769745/3000: elapsed=17210.0us expected=16667.6us +- 83.3us, error 3.3%
(kms_flip:2297) DEBUG: inconsistent flip ts/seq: last 186.752533/2999, current 186.769745/3000: elapsed=17210.0us expected=16667.6us
(kms_flip:2297) DEBUG: expected 144340, counted 390, encoder type 2
(kms_flip:2297) DEBUG: dropped frames, expected 144340, counted 390, encoder type 2
(kms_flip:2297) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2297) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2297) igt_core-INFO: Stack trace:
(kms_flip:2297) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2297) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2297) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2297) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2297) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2297) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2297) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2297) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A3: FAIL (10.170s)
Starting dynamic subtest: B-HDMI-A3
(kms_flip:2297) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2297) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:2297) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2297) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:2297) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2297) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2297) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=11, pitch=7680)
(kms_flip:2297) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2297) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2297) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2297) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2297) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2297) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2297) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2297) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2297) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2297) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2297) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2297) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2297) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2297) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2297) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2297) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2297) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2297) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2297) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2297) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2297) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2297) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2297) DEBUG: No stale events found
(kms_flip:2297) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2297) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2297) INFO: Expected frametime: 16667us; measured 17031.6us +- 6.791us accuracy 0.12%
(kms_flip:2297) INFO: vblank interval differs from modeline! expected 16666.7us, measured 17032us +- 6.791us, difference 365.0us (53.7 sigma)
(kms_flip:2297) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 190.530746
current_received_ts = 190.530334
current_seq = 21
count = 0
seq_step = 1
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.530746
last_received_ts = 190.530334
last_seq = 21
current_ts = 190.547775
current_received_ts = 190.547363
current_seq = 22
count = 1
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.530746/21, current 190.547775/22: elapsed=17031.0us expected=17031.6us +- 85.2us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.547775
last_received_ts = 190.547363
last_seq = 22
current_ts = 190.564804
current_received_ts = 190.564346
current_seq = 23
count = 2
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.547775/22, current 190.564804/23: elapsed=17028.0us expected=17031.6us +- 85.2us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.564804
last_received_ts = 190.564346
last_seq = 23
current_ts = 190.581833
current_received_ts = 190.581390
current_seq = 24
count = 3
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.564804/23, current 190.581833/24: elapsed=17034.0us expected=17031.6us +- 85.2us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.581833
last_received_ts = 190.581390
last_seq = 24
current_ts = 190.598862
current_received_ts = 190.598434
current_seq = 25
count = 4
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.581833/24, current 190.598862/25: elapsed=17026.0us expected=17031.6us +- 85.2us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.598862
last_received_ts = 190.598434
last_seq = 25
current_ts = 190.615891
current_received_ts = 190.615479
current_seq = 26
count = 5
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.598862/25, current 190.615891/26: elapsed=17033.0us expected=17031.6us +- 85.2us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.615891
last_received_ts = 190.615479
last_seq = 26
current_ts = 190.632935
current_received_ts = 190.632538
current_seq = 27
count = 6
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.615891/26, current 190.632935/27: elapsed=17041.0us expected=17031.6us +- 85.2us, error 0.1%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.632935
last_received_ts = 190.632538
last_seq = 27
current_ts = 190.649963
current_received_ts = 190.649597
current_seq = 28
count = 7
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.632935/27, current 190.649963/28: elapsed=17028.0us expected=17031.6us +- 85.2us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.649963
last_received_ts = 190.649597
last_seq = 28
current_ts = 190.666992
current_received_ts = 190.666626
current_seq = 29
count = 8
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.649963/28, current 190.666992/29: elapsed=17033.0us expected=17031.6us +- 85.2us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.666992
last_received_ts = 190.666626
last_seq = 29
current_ts = 190.684021
current_received_ts = 190.683762
current_seq = 30
count = 9
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.666992/29, current 190.684021/30: elapsed=17028.0us expected=17031.6us +- 85.2us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.684021
last_received_ts = 190.683762
last_seq = 30
current_ts = 190.701065
current_received_ts = 190.700790
current_seq = 31
count = 10
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.684021/30, current 190.701065/31: elapsed=17036.0us expected=17031.6us +- 85.2us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.701065
last_received_ts = 190.700790
last_seq = 31
current_ts = 190.718094
current_received_ts = 190.717804
current_seq = 32
count = 11
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.701065/31, current 190.718094/32: elapsed=17034.0us expected=17031.6us +- 85.2us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.718094
last_received_ts = 190.717804
last_seq = 32
current_ts = 190.735123
current_received_ts = 190.734741
current_seq = 33
count = 12
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.718094/32, current 190.735123/33: elapsed=17032.0us expected=17031.6us +- 85.2us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.735123
last_received_ts = 190.734741
last_seq = 33
current_ts = 190.752151
current_received_ts = 190.751785
current_seq = 34
count = 13
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.735123/33, current 190.752151/34: elapsed=17026.0us expected=17031.6us +- 85.2us, error 0.0%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.752151
last_received_ts = 190.751785
last_seq = 34
current_ts = 190.769135
current_received_ts = 190.768723
current_seq = 35
count = 14
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.752151/34, current 190.769135/35: elapsed=16976.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.769135
last_received_ts = 190.768723
last_seq = 35
current_ts = 190.786118
current_received_ts = 190.785858
current_seq = 36
count = 15
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.769135/35, current 190.786118/36: elapsed=16990.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.786118
last_received_ts = 190.785858
last_seq = 36
current_ts = 190.803101
current_received_ts = 190.802734
current_seq = 37
count = 16
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.786118/36, current 190.803101/37: elapsed=16988.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.803101
last_received_ts = 190.802734
last_seq = 37
current_ts = 190.820099
current_received_ts = 190.819702
current_seq = 38
count = 17
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.803101/37, current 190.820099/38: elapsed=16990.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.820099
last_received_ts = 190.819702
last_seq = 38
current_ts = 190.837082
current_received_ts = 190.836716
current_seq = 39
count = 18
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.820099/38, current 190.837082/39: elapsed=16982.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.837082
last_received_ts = 190.836716
last_seq = 39
current_ts = 190.854080
current_received_ts = 190.853668
current_seq = 40
count = 19
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.837082/39, current 190.854080/40: elapsed=16994.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.854080
last_received_ts = 190.853668
last_seq = 40
current_ts = 190.871048
current_received_ts = 190.870758
current_seq = 41
count = 20
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.854080/40, current 190.871048/41: elapsed=16979.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.871048
last_received_ts = 190.870758
last_seq = 41
current_ts = 190.888046
current_received_ts = 190.887650
current_seq = 42
count = 21
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.871048/41, current 190.888046/42: elapsed=16998.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.888046
last_received_ts = 190.887650
last_seq = 42
current_ts = 190.905029
current_received_ts = 190.904663
current_seq = 43
count = 22
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.888046/42, current 190.905029/43: elapsed=16984.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.905029
last_received_ts = 190.904663
last_seq = 43
current_ts = 190.922028
current_received_ts = 190.921722
current_seq = 44
count = 23
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.905029/43, current 190.922028/44: elapsed=16990.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.922028
last_received_ts = 190.921722
last_seq = 44
current_ts = 190.938995
current_received_ts = 190.938644
current_seq = 45
count = 24
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.922028/44, current 190.938995/45: elapsed=16976.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.938995
last_received_ts = 190.938644
last_seq = 45
current_ts = 190.955994
current_received_ts = 190.955627
current_seq = 46
count = 25
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.938995/45, current 190.955994/46: elapsed=16998.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.955994
last_received_ts = 190.955627
last_seq = 46
current_ts = 190.972977
current_received_ts = 190.972656
current_seq = 47
count = 26
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.955994/46, current 190.972977/47: elapsed=16977.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.972977
last_received_ts = 190.972656
last_seq = 47
current_ts = 190.989975
current_received_ts = 190.989670
current_seq = 48
count = 27
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.972977/47, current 190.989975/48: elapsed=16997.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 190.989975
last_received_ts = 190.989670
last_seq = 48
current_ts = 191.006943
current_received_ts = 191.006531
current_seq = 49
count = 28
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 190.989975/48, current 191.006943/49: elapsed=16975.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.006943
last_received_ts = 191.006531
last_seq = 49
current_ts = 191.023941
current_received_ts = 191.023499
current_seq = 50
count = 29
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.006943/49, current 191.023941/50: elapsed=16998.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.023941
last_received_ts = 191.023499
last_seq = 50
current_ts = 191.040939
current_received_ts = 191.040527
current_seq = 51
count = 30
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.023941/50, current 191.040939/51: elapsed=16986.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.040939
last_received_ts = 191.040527
last_seq = 51
current_ts = 191.057922
current_received_ts = 191.057510
current_seq = 52
count = 31
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.040939/51, current 191.057922/52: elapsed=16985.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.057922
last_received_ts = 191.057510
last_seq = 52
current_ts = 191.074905
current_received_ts = 191.074509
current_seq = 53
count = 32
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.057922/52, current 191.074905/53: elapsed=16981.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.074905
last_received_ts = 191.074509
last_seq = 53
current_ts = 191.091888
current_received_ts = 191.091476
current_seq = 54
count = 33
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.074905/53, current 191.091888/54: elapsed=16994.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.091888
last_received_ts = 191.091476
last_seq = 54
current_ts = 191.108871
current_received_ts = 191.108444
current_seq = 55
count = 34
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.091888/54, current 191.108871/55: elapsed=16981.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.108871
last_received_ts = 191.108444
last_seq = 55
current_ts = 191.125854
current_received_ts = 191.125397
current_seq = 56
count = 35
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.108871/55, current 191.125854/56: elapsed=16982.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.125854
last_received_ts = 191.125397
last_seq = 56
current_ts = 191.142853
current_received_ts = 191.142410
current_seq = 57
count = 36
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.125854/56, current 191.142853/57: elapsed=16991.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.142853
last_received_ts = 191.142410
last_seq = 57
current_ts = 191.159836
current_received_ts = 191.159363
current_seq = 58
count = 37
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.142853/57, current 191.159836/58: elapsed=16994.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.159836
last_received_ts = 191.159363
last_seq = 58
current_ts = 191.176819
current_received_ts = 191.176361
current_seq = 59
count = 38
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.159836/58, current 191.176819/59: elapsed=16979.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.176819
last_received_ts = 191.176361
last_seq = 59
current_ts = 191.193817
current_received_ts = 191.193329
current_seq = 60
count = 39
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.176819/59, current 191.193817/60: elapsed=16995.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.193817
last_received_ts = 191.193329
last_seq = 60
current_ts = 191.210800
current_received_ts = 191.210419
current_seq = 61
count = 40
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.193817/60, current 191.210800/61: elapsed=16982.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.210800
last_received_ts = 191.210419
last_seq = 61
current_ts = 191.227783
current_received_ts = 191.227264
current_seq = 62
count = 41
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.210800/61, current 191.227783/62: elapsed=16985.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.227783
last_received_ts = 191.227264
last_seq = 62
current_ts = 191.244766
current_received_ts = 191.244263
current_seq = 63
count = 42
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.227783/62, current 191.244766/63: elapsed=16989.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.244766
last_received_ts = 191.244263
last_seq = 63
current_ts = 191.261765
current_received_ts = 191.261459
current_seq = 64
count = 43
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.244766/63, current 191.261765/64: elapsed=16995.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.261765
last_received_ts = 191.261459
last_seq = 64
current_ts = 191.278748
current_received_ts = 191.278427
current_seq = 65
count = 44
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.261765/64, current 191.278748/65: elapsed=16987.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.278748
last_received_ts = 191.278427
last_seq = 65
current_ts = 191.295731
current_received_ts = 191.295441
current_seq = 66
count = 45
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.278748/65, current 191.295731/66: elapsed=16981.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.295731
last_received_ts = 191.295441
last_seq = 66
current_ts = 191.312714
current_received_ts = 191.312439
current_seq = 67
count = 46
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.295731/66, current 191.312714/67: elapsed=16983.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.312714
last_received_ts = 191.312439
last_seq = 67
current_ts = 191.329697
current_received_ts = 191.329315
current_seq = 68
count = 47
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.312714/67, current 191.329697/68: elapsed=16986.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.329697
last_received_ts = 191.329315
last_seq = 68
current_ts = 191.346695
current_received_ts = 191.346344
current_seq = 69
count = 48
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.329697/68, current 191.346695/69: elapsed=16987.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.346695
last_received_ts = 191.346344
last_seq = 69
current_ts = 191.363678
current_received_ts = 191.363327
current_seq = 70
count = 49
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.346695/69, current 191.363678/70: elapsed=16990.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.363678
last_received_ts = 191.363327
last_seq = 70
current_ts = 191.380676
current_received_ts = 191.380402
current_seq = 71
count = 50
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.363678/70, current 191.380676/71: elapsed=16992.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.380676
last_received_ts = 191.380402
last_seq = 71
current_ts = 191.397644
current_received_ts = 191.397263
current_seq = 72
count = 51
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.380676/71, current 191.397644/72: elapsed=16979.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.397644
last_received_ts = 191.397263
last_seq = 72
current_ts = 191.414642
current_received_ts = 191.414215
current_seq = 73
count = 52
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.397644/72, current 191.414642/73: elapsed=16991.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.414642
last_received_ts = 191.414215
last_seq = 73
current_ts = 191.431641
current_received_ts = 191.431168
current_seq = 74
count = 53
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.414642/73, current 191.431641/74: elapsed=16992.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.431641
last_received_ts = 191.431168
last_seq = 74
current_ts = 191.448608
current_received_ts = 191.448212
current_seq = 75
count = 54
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.431641/74, current 191.448608/75: elapsed=16980.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.448608
last_received_ts = 191.448212
last_seq = 75
current_ts = 191.465591
current_received_ts = 191.465134
current_seq = 76
count = 55
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.448608/75, current 191.465591/76: elapsed=16986.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.465591
last_received_ts = 191.465134
last_seq = 76
current_ts = 191.482590
current_received_ts = 191.482147
current_seq = 77
count = 56
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.465591/76, current 191.482590/77: elapsed=16992.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.482590
last_received_ts = 191.482147
last_seq = 77
current_ts = 191.499573
current_received_ts = 191.499298
current_seq = 78
count = 57
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.482590/77, current 191.499573/78: elapsed=16984.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.499573
last_received_ts = 191.499298
last_seq = 78
current_ts = 191.516571
current_received_ts = 191.516296
current_seq = 79
count = 58
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.499573/78, current 191.516571/79: elapsed=16990.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.516571
last_received_ts = 191.516296
last_seq = 79
current_ts = 191.533554
current_received_ts = 191.533127
current_seq = 80
count = 59
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.516571/79, current 191.533554/80: elapsed=16986.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.533554
last_received_ts = 191.533127
last_seq = 80
current_ts = 191.550537
current_received_ts = 191.550156
current_seq = 81
count = 60
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.533554/80, current 191.550537/81: elapsed=16979.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.550537
last_received_ts = 191.550156
last_seq = 81
current_ts = 191.567520
current_received_ts = 191.567230
current_seq = 82
count = 61
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.550537/81, current 191.567520/82: elapsed=16994.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.567520
last_received_ts = 191.567230
last_seq = 82
current_ts = 191.584503
current_received_ts = 191.584076
current_seq = 83
count = 62
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.567520/82, current 191.584503/83: elapsed=16982.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.584503
last_received_ts = 191.584076
last_seq = 83
current_ts = 191.601501
current_received_ts = 191.601105
current_seq = 84
count = 63
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.584503/83, current 191.601501/84: elapsed=16988.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.601501
last_received_ts = 191.601105
last_seq = 84
current_ts = 191.618484
current_received_ts = 191.618011
current_seq = 85
count = 64
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.601501/84, current 191.618484/85: elapsed=16986.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.618484
last_received_ts = 191.618011
last_seq = 85
current_ts = 191.635468
current_received_ts = 191.634995
current_seq = 86
count = 65
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.618484/85, current 191.635468/86: elapsed=16986.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.635468
last_received_ts = 191.634995
last_seq = 86
current_ts = 191.652451
current_received_ts = 191.652100
current_seq = 87
count = 66
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.635468/86, current 191.652451/87: elapsed=16991.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.652451
last_received_ts = 191.652100
last_seq = 87
current_ts = 191.669449
current_received_ts = 191.669174
current_seq = 88
count = 67
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.652451/87, current 191.669449/88: elapsed=16997.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.669449
last_received_ts = 191.669174
last_seq = 88
current_ts = 191.686432
current_received_ts = 191.686142
current_seq = 89
count = 68
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.669449/88, current 191.686432/89: elapsed=16977.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.686432
last_received_ts = 191.686142
last_seq = 89
current_ts = 191.703430
current_received_ts = 191.702942
current_seq = 90
count = 69
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.686432/89, current 191.703430/90: elapsed=16992.0us expected=17031.6us +- 85.2us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.703430
last_received_ts = 191.702942
last_seq = 90
current_ts = 191.720413
current_received_ts = 191.719940
current_seq = 91
count = 70
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.703430/90, current 191.720413/91: elapsed=16988.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.720413
last_received_ts = 191.719940
last_seq = 91
current_ts = 191.737381
current_received_ts = 191.736847
current_seq = 92
count = 71
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.720413/91, current 191.737381/92: elapsed=16977.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.737381
last_received_ts = 191.736847
last_seq = 92
current_ts = 191.754379
current_received_ts = 191.753799
current_seq = 93
count = 72
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.737381/92, current 191.754379/93: elapsed=16987.0us expected=17031.6us +- 85.2us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 191.754379
last_received_ts = 191.753799
last_seq = 93
current_ts = 191.771317
current_received_ts = 191.771332
current_seq = 94
count = 73
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 191.754379/93, current 191.771317/94: elapsed=16939.0us expected=17031.6us +- 85.2us, error 0.5%
(kms_flip:2297) DEBUG: inconsistent flip ts/seq: last 191.754379/93, current 191.771317/94: elapsed=16939.0us expected=17031.6us
(kms_flip:2297) DEBUG: expected 141255, counted 73, encoder type 2
(kms_flip:2297) DEBUG: dropped frames, expected 141255, counted 73, encoder type 2
(kms_flip:2297) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2297) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2297) igt_core-INFO: Stack trace:
(kms_flip:2297) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2297) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2297) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2297) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2297) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2297) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2297) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2297) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A3: FAIL (4.679s)
Starting dynamic subtest: C-HDMI-A3
(kms_flip:2297) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2297) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest C-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:2297) DEBUG: flip ts/seq: last 196.932632/121, current 196.949448/122: elapsed=16811.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 196.949448
last_received_ts = 196.949066
last_seq = 122
current_ts = 196.966263
current_received_ts = 196.965820
current_seq = 123
count = 102
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 196.949448/122, current 196.966263/123: elapsed=16827.0us expected=16858.3us +- 84.3us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 196.966263
last_received_ts = 196.965820
last_seq = 123
current_ts = 196.983078
current_received_ts = 196.982605
current_seq = 124
count = 103
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 196.966263/123, current 196.983078/124: elapsed=16803.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 196.983078
last_received_ts = 196.982605
last_seq = 124
current_ts = 196.999893
current_received_ts = 196.999466
current_seq = 125
count = 104
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 196.983078/124, current 196.999893/125: elapsed=16826.0us expected=16858.3us +- 84.3us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 196.999893
last_received_ts = 196.999466
last_seq = 125
current_ts = 197.016708
current_received_ts = 197.016266
current_seq = 126
count = 105
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 196.999893/125, current 197.016708/126: elapsed=16806.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.016708
last_received_ts = 197.016266
last_seq = 126
current_ts = 197.033524
current_received_ts = 197.033218
current_seq = 127
count = 106
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.016708/126, current 197.033524/127: elapsed=16825.0us expected=16858.3us +- 84.3us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.033524
last_received_ts = 197.033218
last_seq = 127
current_ts = 197.050339
current_received_ts = 197.049911
current_seq = 128
count = 107
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.033524/127, current 197.050339/128: elapsed=16814.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.050339
last_received_ts = 197.049911
last_seq = 128
current_ts = 197.067154
current_received_ts = 197.066711
current_seq = 129
count = 108
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.050339/128, current 197.067154/129: elapsed=16810.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.067154
last_received_ts = 197.066711
last_seq = 129
current_ts = 197.083969
current_received_ts = 197.083527
current_seq = 130
count = 109
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.067154/129, current 197.083969/130: elapsed=16814.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.083969
last_received_ts = 197.083527
last_seq = 130
current_ts = 197.100784
current_received_ts = 197.100266
current_seq = 131
count = 110
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.083969/130, current 197.100784/131: elapsed=16823.0us expected=16858.3us +- 84.3us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.100784
last_received_ts = 197.100266
last_seq = 131
current_ts = 197.117599
current_received_ts = 197.117325
current_seq = 132
count = 111
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.100784/131, current 197.117599/132: elapsed=16807.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.117599
last_received_ts = 197.117325
last_seq = 132
current_ts = 197.134415
current_received_ts = 197.134109
current_seq = 133
count = 112
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.117599/132, current 197.134415/133: elapsed=16813.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.134415
last_received_ts = 197.134109
last_seq = 133
current_ts = 197.151230
current_received_ts = 197.150925
current_seq = 134
count = 113
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.134415/133, current 197.151230/134: elapsed=16818.0us expected=16858.3us +- 84.3us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.151230
last_received_ts = 197.150925
last_seq = 134
current_ts = 197.168045
current_received_ts = 197.167572
current_seq = 135
count = 114
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.151230/134, current 197.168045/135: elapsed=16816.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.168045
last_received_ts = 197.167572
last_seq = 135
current_ts = 197.184860
current_received_ts = 197.184387
current_seq = 136
count = 115
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.168045/135, current 197.184860/136: elapsed=16808.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.184860
last_received_ts = 197.184387
last_seq = 136
current_ts = 197.201675
current_received_ts = 197.201294
current_seq = 137
count = 116
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.184860/136, current 197.201675/137: elapsed=16826.0us expected=16858.3us +- 84.3us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.201675
last_received_ts = 197.201294
last_seq = 137
current_ts = 197.218491
current_received_ts = 197.218079
current_seq = 138
count = 117
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.201675/137, current 197.218491/138: elapsed=16806.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.218491
last_received_ts = 197.218079
last_seq = 138
current_ts = 197.235306
current_received_ts = 197.234879
current_seq = 139
count = 118
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.218491/138, current 197.235306/139: elapsed=16823.0us expected=16858.3us +- 84.3us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.235306
last_received_ts = 197.234879
last_seq = 139
current_ts = 197.252121
current_received_ts = 197.251709
current_seq = 140
count = 119
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.235306/139, current 197.252121/140: elapsed=16807.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.252121
last_received_ts = 197.251709
last_seq = 140
current_ts = 197.268936
current_received_ts = 197.268448
current_seq = 141
count = 120
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.252121/140, current 197.268936/141: elapsed=16818.0us expected=16858.3us +- 84.3us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.268936
last_received_ts = 197.268448
last_seq = 141
current_ts = 197.285751
current_received_ts = 197.285294
current_seq = 142
count = 121
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.268936/141, current 197.285751/142: elapsed=16821.0us expected=16858.3us +- 84.3us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.285751
last_received_ts = 197.285294
last_seq = 142
current_ts = 197.302567
current_received_ts = 197.302292
current_seq = 143
count = 122
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.285751/142, current 197.302567/143: elapsed=16817.0us expected=16858.3us +- 84.3us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.302567
last_received_ts = 197.302292
last_seq = 143
current_ts = 197.319382
current_received_ts = 197.318939
current_seq = 144
count = 123
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.302567/143, current 197.319382/144: elapsed=16816.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.319382
last_received_ts = 197.318939
last_seq = 144
current_ts = 197.336197
current_received_ts = 197.335876
current_seq = 145
count = 124
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.319382/144, current 197.336197/145: elapsed=16809.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.336197
last_received_ts = 197.335876
last_seq = 145
current_ts = 197.353012
current_received_ts = 197.352585
current_seq = 146
count = 125
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.336197/145, current 197.353012/146: elapsed=16822.0us expected=16858.3us +- 84.3us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.353012
last_received_ts = 197.352585
last_seq = 146
current_ts = 197.369827
current_received_ts = 197.369339
current_seq = 147
count = 126
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.353012/146, current 197.369827/147: elapsed=16806.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.369827
last_received_ts = 197.369339
last_seq = 147
current_ts = 197.386642
current_received_ts = 197.386185
current_seq = 148
count = 127
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.369827/147, current 197.386642/148: elapsed=16821.0us expected=16858.3us +- 84.3us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.386642
last_received_ts = 197.386185
last_seq = 148
current_ts = 197.403458
current_received_ts = 197.403000
current_seq = 149
count = 128
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.386642/148, current 197.403458/149: elapsed=16815.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.403458
last_received_ts = 197.403000
last_seq = 149
current_ts = 197.420273
current_received_ts = 197.419830
current_seq = 150
count = 129
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.403458/149, current 197.420273/150: elapsed=16815.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.420273
last_received_ts = 197.419830
last_seq = 150
current_ts = 197.437088
current_received_ts = 197.436646
current_seq = 151
count = 130
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.420273/150, current 197.437088/151: elapsed=16815.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.437088
last_received_ts = 197.436646
last_seq = 151
current_ts = 197.453903
current_received_ts = 197.453506
current_seq = 152
count = 131
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.437088/151, current 197.453903/152: elapsed=16809.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.453903
last_received_ts = 197.453506
last_seq = 152
current_ts = 197.470718
current_received_ts = 197.470306
current_seq = 153
count = 132
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.453903/152, current 197.470718/153: elapsed=16813.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.470718
last_received_ts = 197.470306
last_seq = 153
current_ts = 197.487534
current_received_ts = 197.487106
current_seq = 154
count = 133
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.470718/153, current 197.487534/154: elapsed=16824.0us expected=16858.3us +- 84.3us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.487534
last_received_ts = 197.487106
last_seq = 154
current_ts = 197.504349
current_received_ts = 197.503952
current_seq = 155
count = 134
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.487534/154, current 197.504349/155: elapsed=16808.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.504349
last_received_ts = 197.503952
last_seq = 155
current_ts = 197.521164
current_received_ts = 197.520706
current_seq = 156
count = 135
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.504349/155, current 197.521164/156: elapsed=16822.0us expected=16858.3us +- 84.3us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.521164
last_received_ts = 197.520706
last_seq = 156
current_ts = 197.537994
current_received_ts = 197.537628
current_seq = 157
count = 136
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.521164/156, current 197.537994/157: elapsed=16822.0us expected=16858.3us +- 84.3us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.537994
last_received_ts = 197.537628
last_seq = 157
current_ts = 197.554794
current_received_ts = 197.554276
current_seq = 158
count = 137
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.537994/157, current 197.554794/158: elapsed=16807.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.554794
last_received_ts = 197.554276
last_seq = 158
current_ts = 197.571609
current_received_ts = 197.571182
current_seq = 159
count = 138
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.554794/158, current 197.571609/159: elapsed=16811.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.571609
last_received_ts = 197.571182
last_seq = 159
current_ts = 197.588425
current_received_ts = 197.588058
current_seq = 160
count = 139
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.571609/159, current 197.588425/160: elapsed=16823.0us expected=16858.3us +- 84.3us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.588425
last_received_ts = 197.588058
last_seq = 160
current_ts = 197.605240
current_received_ts = 197.604813
current_seq = 161
count = 140
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.588425/160, current 197.605240/161: elapsed=16816.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.605240
last_received_ts = 197.604813
last_seq = 161
current_ts = 197.622055
current_received_ts = 197.621628
current_seq = 162
count = 141
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.605240/161, current 197.622055/162: elapsed=16817.0us expected=16858.3us +- 84.3us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.622055
last_received_ts = 197.621628
last_seq = 162
current_ts = 197.638870
current_received_ts = 197.638428
current_seq = 163
count = 142
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.622055/162, current 197.638870/163: elapsed=16815.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.638870
last_received_ts = 197.638428
last_seq = 163
current_ts = 197.655685
current_received_ts = 197.655258
current_seq = 164
count = 143
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.638870/163, current 197.655685/164: elapsed=16814.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.655685
last_received_ts = 197.655258
last_seq = 164
current_ts = 197.672501
current_received_ts = 197.672089
current_seq = 165
count = 144
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.655685/164, current 197.672501/165: elapsed=16815.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.672501
last_received_ts = 197.672089
last_seq = 165
current_ts = 197.689316
current_received_ts = 197.689056
current_seq = 166
count = 145
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.672501/165, current 197.689316/166: elapsed=16808.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.689316
last_received_ts = 197.689056
last_seq = 166
current_ts = 197.706131
current_received_ts = 197.705734
current_seq = 167
count = 146
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.689316/166, current 197.706131/167: elapsed=16811.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.706131
last_received_ts = 197.705734
last_seq = 167
current_ts = 197.722946
current_received_ts = 197.722519
current_seq = 168
count = 147
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.706131/167, current 197.722946/168: elapsed=16826.0us expected=16858.3us +- 84.3us, error 0.2%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.722946
last_received_ts = 197.722519
last_seq = 168
current_ts = 197.739761
current_received_ts = 197.739304
current_seq = 169
count = 148
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.722946/168, current 197.739761/169: elapsed=16808.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.739761
last_received_ts = 197.739304
last_seq = 169
current_ts = 197.756577
current_received_ts = 197.756302
current_seq = 170
count = 149
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.739761/169, current 197.756577/170: elapsed=16810.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.756577
last_received_ts = 197.756302
last_seq = 170
current_ts = 197.773376
current_received_ts = 197.772934
current_seq = 171
count = 150
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.756577/170, current 197.773376/171: elapsed=16806.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.773376
last_received_ts = 197.772934
last_seq = 171
current_ts = 197.790161
current_received_ts = 197.789841
current_seq = 172
count = 151
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.773376/171, current 197.790161/172: elapsed=16792.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.790161
last_received_ts = 197.789841
last_seq = 172
current_ts = 197.806976
current_received_ts = 197.806534
current_seq = 173
count = 152
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.790161/172, current 197.806976/173: elapsed=16804.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.806976
last_received_ts = 197.806534
last_seq = 173
current_ts = 197.823761
current_received_ts = 197.824142
current_seq = 174
count = 153
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.806976/173, current 197.823761/174: elapsed=16788.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.823761
last_received_ts = 197.824142
last_seq = 174
current_ts = 197.840561
current_received_ts = 197.840164
current_seq = 175
count = 154
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.823761/174, current 197.840561/175: elapsed=16798.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.840561
last_received_ts = 197.840164
last_seq = 175
current_ts = 197.857361
current_received_ts = 197.856918
current_seq = 176
count = 155
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.840561/175, current 197.857361/176: elapsed=16805.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.857361
last_received_ts = 197.856918
last_seq = 176
current_ts = 197.874161
current_received_ts = 197.873703
current_seq = 177
count = 156
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.857361/176, current 197.874161/177: elapsed=16794.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.874161
last_received_ts = 197.873703
last_seq = 177
current_ts = 197.890945
current_received_ts = 197.890625
current_seq = 178
count = 157
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.874161/177, current 197.890945/178: elapsed=16794.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.890945
last_received_ts = 197.890625
last_seq = 178
current_ts = 197.907745
current_received_ts = 197.907257
current_seq = 179
count = 158
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.890945/178, current 197.907745/179: elapsed=16798.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.907745
last_received_ts = 197.907257
last_seq = 179
current_ts = 197.924545
current_received_ts = 197.924133
current_seq = 180
count = 159
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.907745/179, current 197.924545/180: elapsed=16795.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.924545
last_received_ts = 197.924133
last_seq = 180
current_ts = 197.941345
current_received_ts = 197.940948
current_seq = 181
count = 160
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.924545/180, current 197.941345/181: elapsed=16800.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.941345
last_received_ts = 197.940948
last_seq = 181
current_ts = 197.958145
current_received_ts = 197.957703
current_seq = 182
count = 161
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.941345/181, current 197.958145/182: elapsed=16806.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.958145
last_received_ts = 197.957703
last_seq = 182
current_ts = 197.974945
current_received_ts = 197.974503
current_seq = 183
count = 162
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.958145/182, current 197.974945/183: elapsed=16794.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.974945
last_received_ts = 197.974503
last_seq = 183
current_ts = 197.991745
current_received_ts = 197.991241
current_seq = 184
count = 163
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.974945/183, current 197.991745/184: elapsed=16804.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 197.991745
last_received_ts = 197.991241
last_seq = 184
current_ts = 198.008545
current_received_ts = 198.008148
current_seq = 185
count = 164
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 197.991745/184, current 198.008545/185: elapsed=16797.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.008545
last_received_ts = 198.008148
last_seq = 185
current_ts = 198.025330
current_received_ts = 198.025009
current_seq = 186
count = 165
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.008545/185, current 198.025330/186: elapsed=16793.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.025330
last_received_ts = 198.025009
last_seq = 186
current_ts = 198.042130
current_received_ts = 198.041733
current_seq = 187
count = 166
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.025330/186, current 198.042130/187: elapsed=16797.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.042130
last_received_ts = 198.041733
last_seq = 187
current_ts = 198.058929
current_received_ts = 198.058502
current_seq = 188
count = 167
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.042130/187, current 198.058929/188: elapsed=16795.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.058929
last_received_ts = 198.058502
last_seq = 188
current_ts = 198.075729
current_received_ts = 198.075256
current_seq = 189
count = 168
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.058929/188, current 198.075729/189: elapsed=16794.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.075729
last_received_ts = 198.075256
last_seq = 189
current_ts = 198.092529
current_received_ts = 198.092117
current_seq = 190
count = 169
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.075729/189, current 198.092529/190: elapsed=16800.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.092529
last_received_ts = 198.092117
last_seq = 190
current_ts = 198.109329
current_received_ts = 198.108887
current_seq = 191
count = 170
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.092529/190, current 198.109329/191: elapsed=16802.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.109329
last_received_ts = 198.108887
last_seq = 191
current_ts = 198.126114
current_received_ts = 198.125702
current_seq = 192
count = 171
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.109329/191, current 198.126114/192: elapsed=16791.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.126114
last_received_ts = 198.125702
last_seq = 192
current_ts = 198.142914
current_received_ts = 198.142471
current_seq = 193
count = 172
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.126114/192, current 198.142914/193: elapsed=16800.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.142914
last_received_ts = 198.142471
last_seq = 193
current_ts = 198.159714
current_received_ts = 198.159302
current_seq = 194
count = 173
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.142914/193, current 198.159714/194: elapsed=16805.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.159714
last_received_ts = 198.159302
last_seq = 194
current_ts = 198.176514
current_received_ts = 198.176208
current_seq = 195
count = 174
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.159714/194, current 198.176514/195: elapsed=16798.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.176514
last_received_ts = 198.176208
last_seq = 195
current_ts = 198.193314
current_received_ts = 198.193069
current_seq = 196
count = 175
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.176514/195, current 198.193314/196: elapsed=16791.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.193314
last_received_ts = 198.193069
last_seq = 196
current_ts = 198.210114
current_received_ts = 198.209793
current_seq = 197
count = 176
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.193314/196, current 198.210114/197: elapsed=16806.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.210114
last_received_ts = 198.209793
last_seq = 197
current_ts = 198.226913
current_received_ts = 198.226486
current_seq = 198
count = 177
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.210114/197, current 198.226913/198: elapsed=16799.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.226913
last_received_ts = 198.226486
last_seq = 198
current_ts = 198.243713
current_received_ts = 198.243393
current_seq = 199
count = 178
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.226913/198, current 198.243713/199: elapsed=16794.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.243713
last_received_ts = 198.243393
last_seq = 199
current_ts = 198.260498
current_received_ts = 198.260086
current_seq = 200
count = 179
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.243713/199, current 198.260498/200: elapsed=16793.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.260498
last_received_ts = 198.260086
last_seq = 200
current_ts = 198.277313
current_received_ts = 198.276871
current_seq = 201
count = 180
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.260498/200, current 198.277313/201: elapsed=16804.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.277313
last_received_ts = 198.276871
last_seq = 201
current_ts = 198.294098
current_received_ts = 198.293655
current_seq = 202
count = 181
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.277313/201, current 198.294098/202: elapsed=16796.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.294098
last_received_ts = 198.293655
last_seq = 202
current_ts = 198.310898
current_received_ts = 198.310547
current_seq = 203
count = 182
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.294098/202, current 198.310898/203: elapsed=16794.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.310898
last_received_ts = 198.310547
last_seq = 203
current_ts = 198.327698
current_received_ts = 198.327286
current_seq = 204
count = 183
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.310898/203, current 198.327698/204: elapsed=16800.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.327698
last_received_ts = 198.327286
last_seq = 204
current_ts = 198.344498
current_received_ts = 198.344086
current_seq = 205
count = 184
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.327698/204, current 198.344498/205: elapsed=16803.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.344498
last_received_ts = 198.344086
last_seq = 205
current_ts = 198.361282
current_received_ts = 198.360855
current_seq = 206
count = 185
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.344498/205, current 198.361282/206: elapsed=16790.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.361282
last_received_ts = 198.360855
last_seq = 206
current_ts = 198.378098
current_received_ts = 198.377594
current_seq = 207
count = 186
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.361282/206, current 198.378098/207: elapsed=16802.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.378098
last_received_ts = 198.377594
last_seq = 207
current_ts = 198.394882
current_received_ts = 198.394516
current_seq = 208
count = 187
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.378098/207, current 198.394882/208: elapsed=16794.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.394882
last_received_ts = 198.394516
last_seq = 208
current_ts = 198.411682
current_received_ts = 198.411469
current_seq = 209
count = 188
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.394882/208, current 198.411682/209: elapsed=16801.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.411682
last_received_ts = 198.411469
last_seq = 209
current_ts = 198.428482
current_received_ts = 198.428101
current_seq = 210
count = 189
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.411682/209, current 198.428482/210: elapsed=16798.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.428482
last_received_ts = 198.428101
last_seq = 210
current_ts = 198.445282
current_received_ts = 198.444870
current_seq = 211
count = 190
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.428482/210, current 198.445282/211: elapsed=16802.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.445282
last_received_ts = 198.444870
last_seq = 211
current_ts = 198.462082
current_received_ts = 198.461685
current_seq = 212
count = 191
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.445282/211, current 198.462082/212: elapsed=16794.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.462082
last_received_ts = 198.461685
last_seq = 212
current_ts = 198.478867
current_received_ts = 198.478485
current_seq = 213
count = 192
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.462082/212, current 198.478867/213: elapsed=16789.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.478867
last_received_ts = 198.478485
last_seq = 213
current_ts = 198.495667
current_received_ts = 198.495316
current_seq = 214
count = 193
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.478867/213, current 198.495667/214: elapsed=16801.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.495667
last_received_ts = 198.495316
last_seq = 214
current_ts = 198.512466
current_received_ts = 198.512115
current_seq = 215
count = 194
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.495667/214, current 198.512466/215: elapsed=16795.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.512466
last_received_ts = 198.512115
last_seq = 215
current_ts = 198.529266
current_received_ts = 198.528870
current_seq = 216
count = 195
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.512466/215, current 198.529266/216: elapsed=16805.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.529266
last_received_ts = 198.528870
last_seq = 216
current_ts = 198.546066
current_received_ts = 198.545670
current_seq = 217
count = 196
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.529266/216, current 198.546066/217: elapsed=16791.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.546066
last_received_ts = 198.545670
last_seq = 217
current_ts = 198.562866
current_received_ts = 198.562378
current_seq = 218
count = 197
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.546066/217, current 198.562866/218: elapsed=16806.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.562866
last_received_ts = 198.562378
last_seq = 218
current_ts = 198.579666
current_received_ts = 198.579254
current_seq = 219
count = 198
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.562866/218, current 198.579666/219: elapsed=16798.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.579666
last_received_ts = 198.579254
last_seq = 219
current_ts = 198.596451
current_received_ts = 198.596191
current_seq = 220
count = 199
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.579666/219, current 198.596451/220: elapsed=16790.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.596451
last_received_ts = 198.596191
last_seq = 220
current_ts = 198.613251
current_received_ts = 198.612885
current_seq = 221
count = 200
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.596451/220, current 198.613251/221: elapsed=16797.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.613251
last_received_ts = 198.612885
last_seq = 221
current_ts = 198.630051
current_received_ts = 198.629654
current_seq = 222
count = 201
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.613251/221, current 198.630051/222: elapsed=16805.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.630051
last_received_ts = 198.629654
last_seq = 222
current_ts = 198.646851
current_received_ts = 198.646423
current_seq = 223
count = 202
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.630051/222, current 198.646851/223: elapsed=16791.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.646851
last_received_ts = 198.646423
last_seq = 223
current_ts = 198.663651
current_received_ts = 198.663269
current_seq = 224
count = 203
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.646851/223, current 198.663651/224: elapsed=16809.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.663651
last_received_ts = 198.663269
last_seq = 224
current_ts = 198.680450
current_received_ts = 198.680069
current_seq = 225
count = 204
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.663651/224, current 198.680450/225: elapsed=16790.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.680450
last_received_ts = 198.680069
last_seq = 225
current_ts = 198.697250
current_received_ts = 198.696823
current_seq = 226
count = 205
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.680450/225, current 198.697250/226: elapsed=16801.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.697250
last_received_ts = 198.696823
last_seq = 226
current_ts = 198.714035
current_received_ts = 198.713654
current_seq = 227
count = 206
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.697250/226, current 198.714035/227: elapsed=16790.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.714035
last_received_ts = 198.713654
last_seq = 227
current_ts = 198.730850
current_received_ts = 198.730408
current_seq = 228
count = 207
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.714035/227, current 198.730850/228: elapsed=16807.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.730850
last_received_ts = 198.730408
last_seq = 228
current_ts = 198.747650
current_received_ts = 198.747208
current_seq = 229
count = 208
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.730850/228, current 198.747650/229: elapsed=16800.0us expected=16858.3us +- 84.3us, error 0.3%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.747650
last_received_ts = 198.747208
last_seq = 229
current_ts = 198.764435
current_received_ts = 198.764038
current_seq = 230
count = 209
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.747650/229, current 198.764435/230: elapsed=16784.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.764435
last_received_ts = 198.764038
last_seq = 230
current_ts = 198.781204
current_received_ts = 198.780807
current_seq = 231
count = 210
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.764435/230, current 198.781204/231: elapsed=16779.0us expected=16858.3us +- 84.3us, error 0.5%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.781204
last_received_ts = 198.780807
last_seq = 231
current_ts = 198.797989
current_received_ts = 198.797592
current_seq = 232
count = 211
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.781204/231, current 198.797989/232: elapsed=16781.0us expected=16858.3us +- 84.3us, error 0.5%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.797989
last_received_ts = 198.797592
last_seq = 232
current_ts = 198.814774
current_received_ts = 198.814346
current_seq = 233
count = 212
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.797989/232, current 198.814774/233: elapsed=16779.0us expected=16858.3us +- 84.3us, error 0.5%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.814774
last_received_ts = 198.814346
last_seq = 233
current_ts = 198.831558
current_received_ts = 198.831177
current_seq = 234
count = 213
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.814774/233, current 198.831558/234: elapsed=16789.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.831558
last_received_ts = 198.831177
last_seq = 234
current_ts = 198.848343
current_received_ts = 198.848099
current_seq = 235
count = 214
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.831558/234, current 198.848343/235: elapsed=16784.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.848343
last_received_ts = 198.848099
last_seq = 235
current_ts = 198.865112
current_received_ts = 198.864838
current_seq = 236
count = 215
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.848343/235, current 198.865112/236: elapsed=16776.0us expected=16858.3us +- 84.3us, error 0.5%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.865112
last_received_ts = 198.864838
last_seq = 236
current_ts = 198.881897
current_received_ts = 198.881500
current_seq = 237
count = 216
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.865112/236, current 198.881897/237: elapsed=16786.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.881897
last_received_ts = 198.881500
last_seq = 237
current_ts = 198.898682
current_received_ts = 198.898331
current_seq = 238
count = 217
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.881897/237, current 198.898682/238: elapsed=16775.0us expected=16858.3us +- 84.3us, error 0.5%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.898682
last_received_ts = 198.898331
last_seq = 238
current_ts = 198.915466
current_received_ts = 198.915192
current_seq = 239
count = 218
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.898682/238, current 198.915466/239: elapsed=16787.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.915466
last_received_ts = 198.915192
last_seq = 239
current_ts = 198.932251
current_received_ts = 198.931854
current_seq = 240
count = 219
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.915466/239, current 198.932251/240: elapsed=16786.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.932251
last_received_ts = 198.931854
last_seq = 240
current_ts = 198.949036
current_received_ts = 198.948746
current_seq = 241
count = 220
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.932251/240, current 198.949036/241: elapsed=16783.0us expected=16858.3us +- 84.3us, error 0.4%
(kms_flip:2297) DEBUG: name = flip
last_ts = 198.949036
last_received_ts = 198.948746
last_seq = 241
current_ts = 198.965805
current_received_ts = 198.965378
current_seq = 242
count = 221
seq_step = 1
(kms_flip:2297) DEBUG: flip ts/seq: last 198.949036/241, current 198.965805/242: elapsed=16772.0us expected=16858.3us +- 84.3us, error 0.5%
(kms_flip:2297) DEBUG: inconsistent flip ts/seq: last 198.949036/241, current 198.965805/242: elapsed=16772.0us expected=16858.3us
(kms_flip:2297) DEBUG: expected 142707, counted 221, encoder type 2
(kms_flip:2297) DEBUG: dropped frames, expected 142707, counted 221, encoder type 2
(kms_flip:2297) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2297) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2297) igt_core-INFO: Stack trace:
(kms_flip:2297) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2297) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2297) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2297) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2297) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2297) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2297) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2297) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-HDMI-A3: FAIL (7.375s)
Starting dynamic subtest: D-HDMI-A3
Dynamic subtest D-HDMI-A3: SUCCESS (7.924s)
Subtest plain-flip-fb-recreate: FAIL (30.162s)