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

shard-dg2-4

IGT-Version: 2.0-g534d75199 (x86_64) (Linux: 6.14.0-rc6-CI_DRM_16293-ga958e31a81b3+ x86_64)

Using IGT_SRANDOM=1742090363 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-fb-recreate
Starting dynamic subtest: A-HDMI-A1
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16665.1us +- 6.588us accuracy 0.12%
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1831 run_test()
  #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-HDMI-A1: FAIL (5.783s)
Starting dynamic subtest: B-HDMI-A1
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 17048.3us +- 6.437us accuracy 0.11%
vblank interval differs from modeline! expected 16666.7us, measured 17048us +- 6.437us, difference 381.6us (59.3 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1831 run_test()
  #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A1: FAIL (4.725s)
Starting dynamic subtest: C-HDMI-A1
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16866.8us +- 6.210us accuracy 0.11%
vblank interval differs from modeline! expected 16666.7us, measured 16867us +- 6.210us, difference 200.1us (32.2 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1831 run_test()
  #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-HDMI-A1: FAIL (7.192s)
Starting dynamic subtest: D-HDMI-A1
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16750.7us +- 5.618us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 16751us +- 5.618us, difference 84.0us (15.0 sigma)
Dynamic subtest D-HDMI-A1: SUCCESS (7.971s)
Subtest plain-flip-fb-recreate: FAIL (25.692s)

Starting subtest: plain-flip-fb-recreate
Starting dynamic subtest: A-HDMI-A1
(kms_flip:2744) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2744) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2744) DEBUG: flip ts/seq: last 321.074982/13241, current 321.091644/13242: elapsed=16661.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.091644
last_received_ts = 321.091217
last_seq = 13242
current_ts = 321.108307
current_received_ts = 321.107880
current_seq = 13243
count = 3
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.091644/13242, current 321.108307/13243: elapsed=16669.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.108307
last_received_ts = 321.107880
last_seq = 13243
current_ts = 321.124969
current_received_ts = 321.124542
current_seq = 13244
count = 4
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.108307/13243, current 321.124969/13244: elapsed=16664.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.124969
last_received_ts = 321.124542
last_seq = 13244
current_ts = 321.141632
current_received_ts = 321.141235
current_seq = 13245
count = 5
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.124969/13244, current 321.141632/13245: elapsed=16667.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.141632
last_received_ts = 321.141235
last_seq = 13245
current_ts = 321.158295
current_received_ts = 321.157898
current_seq = 13246
count = 6
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.141632/13245, current 321.158295/13246: elapsed=16657.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.158295
last_received_ts = 321.157898
last_seq = 13246
current_ts = 321.174957
current_received_ts = 321.174530
current_seq = 13247
count = 7
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.158295/13246, current 321.174957/13247: elapsed=16667.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.174957
last_received_ts = 321.174530
last_seq = 13247
current_ts = 321.191620
current_received_ts = 321.191376
current_seq = 13248
count = 8
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.174957/13247, current 321.191620/13248: elapsed=16671.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.191620
last_received_ts = 321.191376
last_seq = 13248
current_ts = 321.208282
current_received_ts = 321.207886
current_seq = 13249
count = 9
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.191620/13248, current 321.208282/13249: elapsed=16658.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.208282
last_received_ts = 321.207886
last_seq = 13249
current_ts = 321.224945
current_received_ts = 321.224609
current_seq = 13250
count = 10
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.208282/13249, current 321.224945/13250: elapsed=16673.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.224945
last_received_ts = 321.224609
last_seq = 13250
current_ts = 321.241608
current_received_ts = 321.241394
current_seq = 13251
count = 11
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.224945/13250, current 321.241608/13251: elapsed=16664.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.241608
last_received_ts = 321.241394
last_seq = 13251
current_ts = 321.258270
current_received_ts = 321.257996
current_seq = 13252
count = 12
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.241608/13251, current 321.258270/13252: elapsed=16659.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.258270
last_received_ts = 321.257996
last_seq = 13252
current_ts = 321.274933
current_received_ts = 321.274506
current_seq = 13253
count = 13
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.258270/13252, current 321.274933/13253: elapsed=16665.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.274933
last_received_ts = 321.274506
last_seq = 13253
current_ts = 321.291626
current_received_ts = 321.291168
current_seq = 13254
count = 14
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.274933/13253, current 321.291626/13254: elapsed=16677.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.291626
last_received_ts = 321.291168
last_seq = 13254
current_ts = 321.308289
current_received_ts = 321.307861
current_seq = 13255
count = 15
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.291626/13254, current 321.308289/13255: elapsed=16662.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.308289
last_received_ts = 321.307861
last_seq = 13255
current_ts = 321.324951
current_received_ts = 321.324493
current_seq = 13256
count = 16
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.308289/13255, current 321.324951/13256: elapsed=16658.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.324951
last_received_ts = 321.324493
last_seq = 13256
current_ts = 321.341614
current_received_ts = 321.341370
current_seq = 13257
count = 17
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.324951/13256, current 321.341614/13257: elapsed=16670.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.341614
last_received_ts = 321.341370
last_seq = 13257
current_ts = 321.358276
current_received_ts = 321.357849
current_seq = 13258
count = 18
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.341614/13257, current 321.358276/13258: elapsed=16655.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.358276
last_received_ts = 321.357849
last_seq = 13258
current_ts = 321.374939
current_received_ts = 321.374512
current_seq = 13259
count = 19
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.358276/13258, current 321.374939/13259: elapsed=16676.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.374939
last_received_ts = 321.374512
last_seq = 13259
current_ts = 321.391602
current_received_ts = 321.391144
current_seq = 13260
count = 20
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.374939/13259, current 321.391602/13260: elapsed=16657.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.391602
last_received_ts = 321.391144
last_seq = 13260
current_ts = 321.408264
current_received_ts = 321.407990
current_seq = 13261
count = 21
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.391602/13260, current 321.408264/13261: elapsed=16675.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.408264
last_received_ts = 321.407990
last_seq = 13261
current_ts = 321.424927
current_received_ts = 321.424500
current_seq = 13262
count = 22
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.408264/13261, current 321.424927/13262: elapsed=16660.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.424927
last_received_ts = 321.424500
last_seq = 13262
current_ts = 321.441620
current_received_ts = 321.441162
current_seq = 13263
count = 23
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.424927/13262, current 321.441620/13263: elapsed=16672.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.441620
last_received_ts = 321.441162
last_seq = 13263
current_ts = 321.458282
current_received_ts = 321.457825
current_seq = 13264
count = 24
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.441620/13263, current 321.458282/13264: elapsed=16666.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.458282
last_received_ts = 321.457825
last_seq = 13264
current_ts = 321.474945
current_received_ts = 321.474457
current_seq = 13265
count = 25
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.458282/13264, current 321.474945/13265: elapsed=16663.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.474945
last_received_ts = 321.474457
last_seq = 13265
current_ts = 321.491608
current_received_ts = 321.491608
current_seq = 13266
count = 26
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.474945/13265, current 321.491608/13266: elapsed=16666.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.491608
last_received_ts = 321.491608
last_seq = 13266
current_ts = 321.508270
current_received_ts = 321.507782
current_seq = 13267
count = 27
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.491608/13266, current 321.508270/13267: elapsed=16656.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.508270
last_received_ts = 321.507782
last_seq = 13267
current_ts = 321.524933
current_received_ts = 321.524445
current_seq = 13268
count = 28
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.508270/13267, current 321.524933/13268: elapsed=16673.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.524933
last_received_ts = 321.524445
last_seq = 13268
current_ts = 321.541595
current_received_ts = 321.541046
current_seq = 13269
count = 29
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.524933/13268, current 321.541595/13269: elapsed=16655.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.541595
last_received_ts = 321.541046
last_seq = 13269
current_ts = 321.558258
current_received_ts = 321.557709
current_seq = 13270
count = 30
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.541595/13269, current 321.558258/13270: elapsed=16665.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.558258
last_received_ts = 321.557709
last_seq = 13270
current_ts = 321.574921
current_received_ts = 321.574371
current_seq = 13271
count = 31
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.558258/13270, current 321.574921/13271: elapsed=16665.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.574921
last_received_ts = 321.574371
last_seq = 13271
current_ts = 321.591583
current_received_ts = 321.591125
current_seq = 13272
count = 32
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.574921/13271, current 321.591583/13272: elapsed=16673.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.591583
last_received_ts = 321.591125
last_seq = 13272
current_ts = 321.608246
current_received_ts = 321.607880
current_seq = 13273
count = 33
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.591583/13272, current 321.608246/13273: elapsed=16663.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.608246
last_received_ts = 321.607880
last_seq = 13273
current_ts = 321.624908
current_received_ts = 321.624451
current_seq = 13274
count = 34
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.608246/13273, current 321.624908/13274: elapsed=16670.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.624908
last_received_ts = 321.624451
last_seq = 13274
current_ts = 321.641571
current_received_ts = 321.641144
current_seq = 13275
count = 35
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.624908/13274, current 321.641571/13275: elapsed=16657.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.641571
last_received_ts = 321.641144
last_seq = 13275
current_ts = 321.658264
current_received_ts = 321.657837
current_seq = 13276
count = 36
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.641571/13275, current 321.658264/13276: elapsed=16677.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.658264
last_received_ts = 321.657837
last_seq = 13276
current_ts = 321.674927
current_received_ts = 321.674438
current_seq = 13277
count = 37
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.658264/13276, current 321.674927/13277: elapsed=16660.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.674927
last_received_ts = 321.674438
last_seq = 13277
current_ts = 321.691589
current_received_ts = 321.691345
current_seq = 13278
count = 38
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.674927/13277, current 321.691589/13278: elapsed=16669.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.691589
last_received_ts = 321.691345
last_seq = 13278
current_ts = 321.708252
current_received_ts = 321.707916
current_seq = 13279
count = 39
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.691589/13278, current 321.708252/13279: elapsed=16655.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.708252
last_received_ts = 321.707916
last_seq = 13279
current_ts = 321.724915
current_received_ts = 321.724548
current_seq = 13280
count = 40
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.708252/13279, current 321.724915/13280: elapsed=16678.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.724915
last_received_ts = 321.724548
last_seq = 13280
current_ts = 321.741577
current_received_ts = 321.741302
current_seq = 13281
count = 41
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.724915/13280, current 321.741577/13281: elapsed=16652.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.741577
last_received_ts = 321.741302
last_seq = 13281
current_ts = 321.758240
current_received_ts = 321.757904
current_seq = 13282
count = 42
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.741577/13281, current 321.758240/13282: elapsed=16668.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.758240
last_received_ts = 321.757904
last_seq = 13282
current_ts = 321.774902
current_received_ts = 321.774445
current_seq = 13283
count = 43
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.758240/13282, current 321.774902/13283: elapsed=16674.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.774902
last_received_ts = 321.774445
last_seq = 13283
current_ts = 321.791565
current_received_ts = 321.791168
current_seq = 13284
count = 44
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.774902/13283, current 321.791565/13284: elapsed=16654.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.791565
last_received_ts = 321.791168
last_seq = 13284
current_ts = 321.808228
current_received_ts = 321.807800
current_seq = 13285
count = 45
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.791565/13284, current 321.808228/13285: elapsed=16674.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.808228
last_received_ts = 321.807800
last_seq = 13285
current_ts = 321.824890
current_received_ts = 321.824432
current_seq = 13286
count = 46
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.808228/13285, current 321.824890/13286: elapsed=16665.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.824890
last_received_ts = 321.824432
last_seq = 13286
current_ts = 321.841583
current_received_ts = 321.841187
current_seq = 13287
count = 47
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.824890/13286, current 321.841583/13287: elapsed=16670.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.841583
last_received_ts = 321.841187
last_seq = 13287
current_ts = 321.858246
current_received_ts = 321.857758
current_seq = 13288
count = 48
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.841583/13287, current 321.858246/13288: elapsed=16662.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.858246
last_received_ts = 321.857758
last_seq = 13288
current_ts = 321.874908
current_received_ts = 321.874420
current_seq = 13289
count = 49
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.858246/13288, current 321.874908/13289: elapsed=16659.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.874908
last_received_ts = 321.874420
last_seq = 13289
current_ts = 321.891571
current_received_ts = 321.891174
current_seq = 13290
count = 50
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.874908/13289, current 321.891571/13290: elapsed=16662.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.891571
last_received_ts = 321.891174
last_seq = 13290
current_ts = 321.908234
current_received_ts = 321.907928
current_seq = 13291
count = 51
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.891571/13290, current 321.908234/13291: elapsed=16668.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.908234
last_received_ts = 321.907928
last_seq = 13291
current_ts = 321.924896
current_received_ts = 321.924469
current_seq = 13292
count = 52
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.908234/13291, current 321.924896/13292: elapsed=16664.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.924896
last_received_ts = 321.924469
last_seq = 13292
current_ts = 321.941559
current_received_ts = 321.941315
current_seq = 13293
count = 53
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.924896/13292, current 321.941559/13293: elapsed=16677.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.941559
last_received_ts = 321.941315
last_seq = 13293
current_ts = 321.958221
current_received_ts = 321.957916
current_seq = 13294
count = 54
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.941559/13293, current 321.958221/13294: elapsed=16653.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.958221
last_received_ts = 321.957916
last_seq = 13294
current_ts = 321.974884
current_received_ts = 321.974426
current_seq = 13295
count = 55
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.958221/13294, current 321.974884/13295: elapsed=16670.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.974884
last_received_ts = 321.974426
last_seq = 13295
current_ts = 321.991547
current_received_ts = 321.991211
current_seq = 13296
count = 56
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.974884/13295, current 321.991547/13296: elapsed=16664.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 321.991547
last_received_ts = 321.991211
last_seq = 13296
current_ts = 322.008240
current_received_ts = 322.007782
current_seq = 13297
count = 57
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 321.991547/13296, current 322.008240/13297: elapsed=16673.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.008240
last_received_ts = 322.007782
last_seq = 13297
current_ts = 322.024872
current_received_ts = 322.024445
current_seq = 13298
count = 58
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.008240/13297, current 322.024872/13298: elapsed=16659.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.024872
last_received_ts = 322.024445
last_seq = 13298
current_ts = 322.041565
current_received_ts = 322.041168
current_seq = 13299
count = 59
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.024872/13298, current 322.041565/13299: elapsed=16673.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.041565
last_received_ts = 322.041168
last_seq = 13299
current_ts = 322.058228
current_received_ts = 322.057892
current_seq = 13300
count = 60
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.041565/13299, current 322.058228/13300: elapsed=16664.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.058228
last_received_ts = 322.057892
last_seq = 13300
current_ts = 322.074890
current_received_ts = 322.074463
current_seq = 13301
count = 61
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.058228/13300, current 322.074890/13301: elapsed=16659.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.074890
last_received_ts = 322.074463
last_seq = 13301
current_ts = 322.091553
current_received_ts = 322.091187
current_seq = 13302
count = 62
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.074890/13301, current 322.091553/13302: elapsed=16664.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.091553
last_received_ts = 322.091187
last_seq = 13302
current_ts = 322.108215
current_received_ts = 322.107819
current_seq = 13303
count = 63
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.091553/13302, current 322.108215/13303: elapsed=16675.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.108215
last_received_ts = 322.107819
last_seq = 13303
current_ts = 322.124878
current_received_ts = 322.124420
current_seq = 13304
count = 64
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.108215/13303, current 322.124878/13304: elapsed=16658.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.124878
last_received_ts = 322.124420
last_seq = 13304
current_ts = 322.141541
current_received_ts = 322.141266
current_seq = 13305
count = 65
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.124878/13304, current 322.141541/13305: elapsed=16667.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.141541
last_received_ts = 322.141266
last_seq = 13305
current_ts = 322.158203
current_received_ts = 322.157776
current_seq = 13306
count = 66
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.141541/13305, current 322.158203/13306: elapsed=16669.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.158203
last_received_ts = 322.157776
last_seq = 13306
current_ts = 322.174866
current_received_ts = 322.174408
current_seq = 13307
count = 67
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.158203/13306, current 322.174866/13307: elapsed=16657.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.174866
last_received_ts = 322.174408
last_seq = 13307
current_ts = 322.191528
current_received_ts = 322.191162
current_seq = 13308
count = 68
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.174866/13307, current 322.191528/13308: elapsed=16664.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.191528
last_received_ts = 322.191162
last_seq = 13308
current_ts = 322.208191
current_received_ts = 322.207886
current_seq = 13309
count = 69
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.191528/13308, current 322.208191/13309: elapsed=16670.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.208191
last_received_ts = 322.207886
last_seq = 13309
current_ts = 322.224884
current_received_ts = 322.224426
current_seq = 13310
count = 70
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.208191/13309, current 322.224884/13310: elapsed=16666.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.224884
last_received_ts = 322.224426
last_seq = 13310
current_ts = 322.241547
current_received_ts = 322.241180
current_seq = 13311
count = 71
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.224884/13310, current 322.241547/13311: elapsed=16665.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.241547
last_received_ts = 322.241180
last_seq = 13311
current_ts = 322.258209
current_received_ts = 322.257782
current_seq = 13312
count = 72
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.241547/13311, current 322.258209/13312: elapsed=16670.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.258209
last_received_ts = 322.257782
last_seq = 13312
current_ts = 322.274872
current_received_ts = 322.274414
current_seq = 13313
count = 73
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.258209/13312, current 322.274872/13313: elapsed=16664.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.274872
last_received_ts = 322.274414
last_seq = 13313
current_ts = 322.291534
current_received_ts = 322.291260
current_seq = 13314
count = 74
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.274872/13313, current 322.291534/13314: elapsed=16665.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.291534
last_received_ts = 322.291260
last_seq = 13314
current_ts = 322.308197
current_received_ts = 322.307861
current_seq = 13315
count = 75
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.291534/13314, current 322.308197/13315: elapsed=16660.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.308197
last_received_ts = 322.307861
last_seq = 13315
current_ts = 322.324860
current_received_ts = 322.324402
current_seq = 13316
count = 76
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.308197/13315, current 322.324860/13316: elapsed=16677.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.324860
last_received_ts = 322.324402
last_seq = 13316
current_ts = 322.341553
current_received_ts = 322.341156
current_seq = 13317
count = 77
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.324860/13316, current 322.341553/13317: elapsed=16666.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.341553
last_received_ts = 322.341156
last_seq = 13317
current_ts = 322.358185
current_received_ts = 322.357788
current_seq = 13318
count = 78
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.341553/13317, current 322.358185/13318: elapsed=16661.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.358185
last_received_ts = 322.357788
last_seq = 13318
current_ts = 322.374878
current_received_ts = 322.374420
current_seq = 13319
count = 79
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.358185/13318, current 322.374878/13319: elapsed=16666.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.374878
last_received_ts = 322.374420
last_seq = 13319
current_ts = 322.391541
current_received_ts = 322.391235
current_seq = 13320
count = 80
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.374878/13319, current 322.391541/13320: elapsed=16664.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.391541
last_received_ts = 322.391235
last_seq = 13320
current_ts = 322.408203
current_received_ts = 322.407867
current_seq = 13321
count = 81
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.391541/13320, current 322.408203/13321: elapsed=16658.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.408203
last_received_ts = 322.407867
last_seq = 13321
current_ts = 322.424866
current_received_ts = 322.424438
current_seq = 13322
count = 82
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.408203/13321, current 322.424866/13322: elapsed=16668.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.424866
last_received_ts = 322.424438
last_seq = 13322
current_ts = 322.441528
current_received_ts = 322.441193
current_seq = 13323
count = 83
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.424866/13322, current 322.441528/13323: elapsed=16668.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.441528
last_received_ts = 322.441193
last_seq = 13323
current_ts = 322.458191
current_received_ts = 322.457855
current_seq = 13324
count = 84
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.441528/13323, current 322.458191/13324: elapsed=16672.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.458191
last_received_ts = 322.457855
last_seq = 13324
current_ts = 322.474854
current_received_ts = 322.474426
current_seq = 13325
count = 85
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.458191/13324, current 322.474854/13325: elapsed=16657.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.474854
last_received_ts = 322.474426
last_seq = 13325
current_ts = 322.491516
current_received_ts = 322.491180
current_seq = 13326
count = 86
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.474854/13325, current 322.491516/13326: elapsed=16667.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.491516
last_received_ts = 322.491180
last_seq = 13326
current_ts = 322.508179
current_received_ts = 322.507751
current_seq = 13327
count = 87
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.491516/13326, current 322.508179/13327: elapsed=16661.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.508179
last_received_ts = 322.507751
last_seq = 13327
current_ts = 322.524841
current_received_ts = 322.524414
current_seq = 13328
count = 88
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.508179/13327, current 322.524841/13328: elapsed=16668.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.524841
last_received_ts = 322.524414
last_seq = 13328
current_ts = 322.541534
current_received_ts = 322.541138
current_seq = 13329
count = 89
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.524841/13328, current 322.541534/13329: elapsed=16677.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.541534
last_received_ts = 322.541138
last_seq = 13329
current_ts = 322.558197
current_received_ts = 322.557770
current_seq = 13330
count = 90
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.541534/13329, current 322.558197/13330: elapsed=16657.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.558197
last_received_ts = 322.557770
last_seq = 13330
current_ts = 322.574860
current_received_ts = 322.574402
current_seq = 13331
count = 91
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.558197/13330, current 322.574860/13331: elapsed=16665.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.574860
last_received_ts = 322.574402
last_seq = 13331
current_ts = 322.591522
current_received_ts = 322.591095
current_seq = 13332
count = 92
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.574860/13331, current 322.591522/13332: elapsed=16668.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.591522
last_received_ts = 322.591095
last_seq = 13332
current_ts = 322.608185
current_received_ts = 322.607727
current_seq = 13333
count = 93
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.591522/13332, current 322.608185/13333: elapsed=16666.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.608185
last_received_ts = 322.607727
last_seq = 13333
current_ts = 322.624847
current_received_ts = 322.624390
current_seq = 13334
count = 94
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.608185/13333, current 322.624847/13334: elapsed=16662.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.624847
last_received_ts = 322.624390
last_seq = 13334
current_ts = 322.641510
current_received_ts = 322.641144
current_seq = 13335
count = 95
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.624847/13334, current 322.641510/13335: elapsed=16675.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.641510
last_received_ts = 322.641144
last_seq = 13335
current_ts = 322.658173
current_received_ts = 322.657745
current_seq = 13336
count = 96
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.641510/13335, current 322.658173/13336: elapsed=16665.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.658173
last_received_ts = 322.657745
last_seq = 13336
current_ts = 322.674835
current_received_ts = 322.674408
current_seq = 13337
count = 97
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.658173/13336, current 322.674835/13337: elapsed=16656.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.674835
last_received_ts = 322.674408
last_seq = 13337
current_ts = 322.691498
current_received_ts = 322.691132
current_seq = 13338
count = 98
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.674835/13337, current 322.691498/13338: elapsed=16663.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.691498
last_received_ts = 322.691132
last_seq = 13338
current_ts = 322.708160
current_received_ts = 322.707733
current_seq = 13339
count = 99
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.691498/13338, current 322.708160/13339: elapsed=16672.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.708160
last_received_ts = 322.707733
last_seq = 13339
current_ts = 322.724823
current_received_ts = 322.724426
current_seq = 13340
count = 100
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.708160/13339, current 322.724823/13340: elapsed=16662.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.724823
last_received_ts = 322.724426
last_seq = 13340
current_ts = 322.741516
current_received_ts = 322.741119
current_seq = 13341
count = 101
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.724823/13340, current 322.741516/13341: elapsed=16675.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.741516
last_received_ts = 322.741119
last_seq = 13341
current_ts = 322.758179
current_received_ts = 322.757721
current_seq = 13342
count = 102
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.741516/13341, current 322.758179/13342: elapsed=16659.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.758179
last_received_ts = 322.757721
last_seq = 13342
current_ts = 322.774841
current_received_ts = 322.774414
current_seq = 13343
count = 103
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.758179/13342, current 322.774841/13343: elapsed=16671.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.774841
last_received_ts = 322.774414
last_seq = 13343
current_ts = 322.791504
current_received_ts = 322.791138
current_seq = 13344
count = 104
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.774841/13343, current 322.791504/13344: elapsed=16664.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.791504
last_received_ts = 322.791138
last_seq = 13344
current_ts = 322.808167
current_received_ts = 322.807709
current_seq = 13345
count = 105
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.791504/13344, current 322.808167/13345: elapsed=16667.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.808167
last_received_ts = 322.807709
last_seq = 13345
current_ts = 322.824829
current_received_ts = 322.824432
current_seq = 13346
count = 106
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.808167/13345, current 322.824829/13346: elapsed=16668.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.824829
last_received_ts = 322.824432
last_seq = 13346
current_ts = 322.841522
current_received_ts = 322.841156
current_seq = 13347
count = 107
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.824829/13346, current 322.841522/13347: elapsed=16671.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.841522
last_received_ts = 322.841156
last_seq = 13347
current_ts = 322.858185
current_received_ts = 322.857758
current_seq = 13348
count = 108
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.841522/13347, current 322.858185/13348: elapsed=16671.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.858185
last_received_ts = 322.857758
last_seq = 13348
current_ts = 322.874847
current_received_ts = 322.874390
current_seq = 13349
count = 109
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.858185/13348, current 322.874847/13349: elapsed=16671.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.874847
last_received_ts = 322.874390
last_seq = 13349
current_ts = 322.891510
current_received_ts = 322.891113
current_seq = 13350
count = 110
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.874847/13349, current 322.891510/13350: elapsed=16670.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.891510
last_received_ts = 322.891113
last_seq = 13350
current_ts = 322.908173
current_received_ts = 322.907745
current_seq = 13351
count = 111
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.891510/13350, current 322.908173/13351: elapsed=16658.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.908173
last_received_ts = 322.907745
last_seq = 13351
current_ts = 322.924866
current_received_ts = 322.924408
current_seq = 13352
count = 112
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.908173/13351, current 322.924866/13352: elapsed=16678.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.924866
last_received_ts = 322.924408
last_seq = 13352
current_ts = 322.941528
current_received_ts = 322.941162
current_seq = 13353
count = 113
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.924866/13352, current 322.941528/13353: elapsed=16659.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.941528
last_received_ts = 322.941162
last_seq = 13353
current_ts = 322.958191
current_received_ts = 322.957764
current_seq = 13354
count = 114
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.941528/13353, current 322.958191/13354: elapsed=16673.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.958191
last_received_ts = 322.957764
last_seq = 13354
current_ts = 322.974854
current_received_ts = 322.974396
current_seq = 13355
count = 115
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.958191/13354, current 322.974854/13355: elapsed=16671.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.974854
last_received_ts = 322.974396
last_seq = 13355
current_ts = 322.991516
current_received_ts = 322.991241
current_seq = 13356
count = 116
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.974854/13355, current 322.991516/13356: elapsed=16664.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 322.991516
last_received_ts = 322.991241
last_seq = 13356
current_ts = 323.008209
current_received_ts = 323.007874
current_seq = 13357
count = 117
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 322.991516/13356, current 323.008209/13357: elapsed=16673.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 323.008209
last_received_ts = 323.007874
last_seq = 13357
current_ts = 323.024872
current_received_ts = 323.024414
current_seq = 13358
count = 118
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 323.008209/13357, current 323.024872/13358: elapsed=16658.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 323.024872
last_received_ts = 323.024414
last_seq = 13358
current_ts = 323.041534
current_received_ts = 323.041199
current_seq = 13359
count = 119
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 323.024872/13358, current 323.041534/13359: elapsed=16667.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 323.041534
last_received_ts = 323.041199
last_seq = 13359
current_ts = 323.058197
current_received_ts = 323.057770
current_seq = 13360
count = 120
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 323.041534/13359, current 323.058197/13360: elapsed=16677.0us expected=16665.1us +- 83.3us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 323.058197
last_received_ts = 323.057770
last_seq = 13360
current_ts = 323.074860
current_received_ts = 323.074432
current_seq = 13361
count = 121
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 323.058197/13360, current 323.074860/13361: elapsed=16669.0us expected=16665.1us +- 83.3us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 323.074860
last_received_ts = 323.074432
last_seq = 13361
current_ts = 323.091675
current_received_ts = 323.091431
current_seq = 13362
count = 122
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 323.074860/13361, current 323.091675/13362: elapsed=16799.0us expected=16665.1us +- 83.3us, error 0.8%
(kms_flip:2744) DEBUG: inconsistent flip ts/seq: last 323.074860/13361, current 323.091675/13362: elapsed=16799.0us expected=16665.1us
(kms_flip:2744) DEBUG: expected 0, counted 122, encoder type 2
(kms_flip:2744) DEBUG: dropped frames, expected 0, counted 122, encoder type 2
(kms_flip:2744) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2744) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2744) igt_core-INFO: Stack trace:
(kms_flip:2744) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2744) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2744) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2744) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2744) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2744) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2744) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2744) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A1: FAIL (5.783s)
Starting dynamic subtest: B-HDMI-A1
(kms_flip:2744) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2744) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2744) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2744) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:2744) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2744) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2744) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=11, pitch=7680)
(kms_flip:2744) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2744) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2744) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2744) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2744) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2744) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2744) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2744) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2744) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2744) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2744) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2744) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2744) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2744) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2744) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2744) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2744) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2744) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2744) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2744) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2744) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2744) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2744) DEBUG: No stale events found
(kms_flip:2744) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2744) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2744) INFO: Expected frametime: 16667us; measured 17048.3us +- 6.437us accuracy 0.11%
(kms_flip:2744) INFO: vblank interval differs from modeline! expected 16666.7us, measured 17048us +- 6.437us, difference 381.6us (59.3 sigma)
(kms_flip:2744) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 326.876801
current_received_ts = 326.876343
current_seq = 594
count = 0
seq_step = 1
(kms_flip:2744) DEBUG: name = flip
last_ts = 326.876801
last_received_ts = 326.876343
last_seq = 594
current_ts = 326.893860
current_received_ts = 326.893402
current_seq = 595
count = 1
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 326.876801/594, current 326.893860/595: elapsed=17050.0us expected=17048.3us +- 85.2us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 326.893860
last_received_ts = 326.893402
last_seq = 595
current_ts = 326.910889
current_received_ts = 326.910461
current_seq = 596
count = 2
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 326.893860/595, current 326.910889/596: elapsed=17053.0us expected=17048.3us +- 85.2us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 326.910889
last_received_ts = 326.910461
last_seq = 596
current_ts = 326.927948
current_received_ts = 326.927490
current_seq = 597
count = 3
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 326.910889/596, current 326.927948/597: elapsed=17044.0us expected=17048.3us +- 85.2us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 326.927948
last_received_ts = 326.927490
last_seq = 597
current_ts = 326.944977
current_received_ts = 326.944580
current_seq = 598
count = 4
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 326.927948/597, current 326.944977/598: elapsed=17041.0us expected=17048.3us +- 85.2us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 326.944977
last_received_ts = 326.944580
last_seq = 598
current_ts = 326.962036
current_received_ts = 326.961670
current_seq = 599
count = 5
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 326.944977/598, current 326.962036/599: elapsed=17052.0us expected=17048.3us +- 85.2us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 326.962036
last_received_ts = 326.961670
last_seq = 599
current_ts = 326.979095
current_received_ts = 326.978638
current_seq = 600
count = 6
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 326.962036/599, current 326.979095/600: elapsed=17049.0us expected=17048.3us +- 85.2us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 326.979095
last_received_ts = 326.978638
last_seq = 600
current_ts = 326.996124
current_received_ts = 326.995697
current_seq = 601
count = 7
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 326.979095/600, current 326.996124/601: elapsed=17055.0us expected=17048.3us +- 85.2us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 326.996124
last_received_ts = 326.995697
last_seq = 601
current_ts = 327.013184
current_received_ts = 327.012756
current_seq = 602
count = 8
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 326.996124/601, current 327.013184/602: elapsed=17048.0us expected=17048.3us +- 85.2us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.013184
last_received_ts = 327.012756
last_seq = 602
current_ts = 327.030243
current_received_ts = 327.029907
current_seq = 603
count = 9
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.013184/602, current 327.030243/603: elapsed=17049.0us expected=17048.3us +- 85.2us, error 0.0%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.030243
last_received_ts = 327.029907
last_seq = 603
current_ts = 327.047272
current_received_ts = 327.046844
current_seq = 604
count = 10
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.030243/603, current 327.047272/604: elapsed=17032.0us expected=17048.3us +- 85.2us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.047272
last_received_ts = 327.046844
last_seq = 604
current_ts = 327.064331
current_received_ts = 327.063904
current_seq = 605
count = 11
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.047272/604, current 327.064331/605: elapsed=17062.0us expected=17048.3us +- 85.2us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.064331
last_received_ts = 327.063904
last_seq = 605
current_ts = 327.081360
current_received_ts = 327.080933
current_seq = 606
count = 12
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.064331/605, current 327.081360/606: elapsed=17038.0us expected=17048.3us +- 85.2us, error 0.1%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.081360
last_received_ts = 327.080933
last_seq = 606
current_ts = 327.098389
current_received_ts = 327.097961
current_seq = 607
count = 13
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.081360/606, current 327.098389/607: elapsed=17019.0us expected=17048.3us +- 85.2us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.098389
last_received_ts = 327.097961
last_seq = 607
current_ts = 327.115387
current_received_ts = 327.114990
current_seq = 608
count = 14
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.098389/607, current 327.115387/608: elapsed=16999.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.115387
last_received_ts = 327.114990
last_seq = 608
current_ts = 327.132385
current_received_ts = 327.131958
current_seq = 609
count = 15
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.115387/608, current 327.132385/609: elapsed=17001.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.132385
last_received_ts = 327.131958
last_seq = 609
current_ts = 327.149384
current_received_ts = 327.148987
current_seq = 610
count = 16
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.132385/609, current 327.149384/610: elapsed=16999.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.149384
last_received_ts = 327.148987
last_seq = 610
current_ts = 327.166382
current_received_ts = 327.165985
current_seq = 611
count = 17
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.149384/610, current 327.166382/611: elapsed=17011.0us expected=17048.3us +- 85.2us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.166382
last_received_ts = 327.165985
last_seq = 611
current_ts = 327.183380
current_received_ts = 327.182953
current_seq = 612
count = 18
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.166382/611, current 327.183380/612: elapsed=16994.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.183380
last_received_ts = 327.182953
last_seq = 612
current_ts = 327.200378
current_received_ts = 327.199982
current_seq = 613
count = 19
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.183380/612, current 327.200378/613: elapsed=16998.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.200378
last_received_ts = 327.199982
last_seq = 613
current_ts = 327.217407
current_received_ts = 327.216980
current_seq = 614
count = 20
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.200378/613, current 327.217407/614: elapsed=17012.0us expected=17048.3us +- 85.2us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.217407
last_received_ts = 327.216980
last_seq = 614
current_ts = 327.234406
current_received_ts = 327.234131
current_seq = 615
count = 21
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.217407/614, current 327.234406/615: elapsed=16996.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.234406
last_received_ts = 327.234131
last_seq = 615
current_ts = 327.251404
current_received_ts = 327.250977
current_seq = 616
count = 22
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.234406/615, current 327.251404/616: elapsed=17007.0us expected=17048.3us +- 85.2us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.251404
last_received_ts = 327.250977
last_seq = 616
current_ts = 327.268402
current_received_ts = 327.267975
current_seq = 617
count = 23
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.251404/616, current 327.268402/617: elapsed=16999.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.268402
last_received_ts = 327.267975
last_seq = 617
current_ts = 327.285400
current_received_ts = 327.285004
current_seq = 618
count = 24
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.268402/617, current 327.285400/618: elapsed=17002.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.285400
last_received_ts = 327.285004
last_seq = 618
current_ts = 327.302399
current_received_ts = 327.302002
current_seq = 619
count = 25
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.285400/618, current 327.302399/619: elapsed=17004.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.302399
last_received_ts = 327.302002
last_seq = 619
current_ts = 327.319397
current_received_ts = 327.319000
current_seq = 620
count = 26
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.302399/619, current 327.319397/620: elapsed=16996.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.319397
last_received_ts = 327.319000
last_seq = 620
current_ts = 327.336395
current_received_ts = 327.336121
current_seq = 621
count = 27
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.319397/620, current 327.336395/621: elapsed=17003.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.336395
last_received_ts = 327.336121
last_seq = 621
current_ts = 327.353424
current_received_ts = 327.352997
current_seq = 622
count = 28
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.336395/621, current 327.353424/622: elapsed=17005.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.353424
last_received_ts = 327.352997
last_seq = 622
current_ts = 327.370422
current_received_ts = 327.369995
current_seq = 623
count = 29
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.353424/622, current 327.370422/623: elapsed=16995.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.370422
last_received_ts = 327.369995
last_seq = 623
current_ts = 327.387421
current_received_ts = 327.386963
current_seq = 624
count = 30
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.370422/623, current 327.387421/624: elapsed=17000.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.387421
last_received_ts = 327.386963
last_seq = 624
current_ts = 327.404388
current_received_ts = 327.404022
current_seq = 625
count = 31
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.387421/624, current 327.404388/625: elapsed=16995.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.404388
last_received_ts = 327.404022
last_seq = 625
current_ts = 327.421417
current_received_ts = 327.420990
current_seq = 626
count = 32
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.404388/625, current 327.421417/626: elapsed=17007.0us expected=17048.3us +- 85.2us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.421417
last_received_ts = 327.420990
last_seq = 626
current_ts = 327.438416
current_received_ts = 327.437958
current_seq = 627
count = 33
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.421417/626, current 327.438416/627: elapsed=17000.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.438416
last_received_ts = 327.437958
last_seq = 627
current_ts = 327.455414
current_received_ts = 327.455017
current_seq = 628
count = 34
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.438416/627, current 327.455414/628: elapsed=17011.0us expected=17048.3us +- 85.2us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.455414
last_received_ts = 327.455017
last_seq = 628
current_ts = 327.472412
current_received_ts = 327.471985
current_seq = 629
count = 35
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.455414/628, current 327.472412/629: elapsed=16992.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.472412
last_received_ts = 327.471985
last_seq = 629
current_ts = 327.489410
current_received_ts = 327.488983
current_seq = 630
count = 36
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.472412/629, current 327.489410/630: elapsed=17001.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.489410
last_received_ts = 327.488983
last_seq = 630
current_ts = 327.506439
current_received_ts = 327.506165
current_seq = 631
count = 37
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.489410/630, current 327.506439/631: elapsed=17012.0us expected=17048.3us +- 85.2us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.506439
last_received_ts = 327.506165
last_seq = 631
current_ts = 327.523407
current_received_ts = 327.522980
current_seq = 632
count = 38
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.506439/631, current 327.523407/632: elapsed=16991.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.523407
last_received_ts = 327.522980
last_seq = 632
current_ts = 327.540405
current_received_ts = 327.539978
current_seq = 633
count = 39
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.523407/632, current 327.540405/633: elapsed=17002.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.540405
last_received_ts = 327.539978
last_seq = 633
current_ts = 327.557434
current_received_ts = 327.557159
current_seq = 634
count = 40
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.540405/633, current 327.557434/634: elapsed=17007.0us expected=17048.3us +- 85.2us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.557434
last_received_ts = 327.557159
last_seq = 634
current_ts = 327.574402
current_received_ts = 327.574005
current_seq = 635
count = 41
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.557434/634, current 327.574402/635: elapsed=16991.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.574402
last_received_ts = 327.574005
last_seq = 635
current_ts = 327.591431
current_received_ts = 327.590973
current_seq = 636
count = 42
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.574402/635, current 327.591431/636: elapsed=17005.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.591431
last_received_ts = 327.590973
last_seq = 636
current_ts = 327.608429
current_received_ts = 327.608063
current_seq = 637
count = 43
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.591431/636, current 327.608429/637: elapsed=16997.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.608429
last_received_ts = 327.608063
last_seq = 637
current_ts = 327.625427
current_received_ts = 327.625000
current_seq = 638
count = 44
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.608429/637, current 327.625427/638: elapsed=17001.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.625427
last_received_ts = 327.625000
last_seq = 638
current_ts = 327.642426
current_received_ts = 327.642151
current_seq = 639
count = 45
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.625427/638, current 327.642426/639: elapsed=17013.0us expected=17048.3us +- 85.2us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.642426
last_received_ts = 327.642151
last_seq = 639
current_ts = 327.659424
current_received_ts = 327.659088
current_seq = 640
count = 46
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.642426/639, current 327.659424/640: elapsed=16994.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.659424
last_received_ts = 327.659088
last_seq = 640
current_ts = 327.676422
current_received_ts = 327.675995
current_seq = 641
count = 47
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.659424/640, current 327.676422/641: elapsed=17010.0us expected=17048.3us +- 85.2us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.676422
last_received_ts = 327.675995
last_seq = 641
current_ts = 327.693420
current_received_ts = 327.692993
current_seq = 642
count = 48
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.676422/641, current 327.693420/642: elapsed=16993.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.693420
last_received_ts = 327.692993
last_seq = 642
current_ts = 327.710449
current_received_ts = 327.710052
current_seq = 643
count = 49
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.693420/642, current 327.710449/643: elapsed=17010.0us expected=17048.3us +- 85.2us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.710449
last_received_ts = 327.710052
last_seq = 643
current_ts = 327.727448
current_received_ts = 327.727020
current_seq = 644
count = 50
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.710449/643, current 327.727448/644: elapsed=17000.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.727448
last_received_ts = 327.727020
last_seq = 644
current_ts = 327.744446
current_received_ts = 327.744049
current_seq = 645
count = 51
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.727448/644, current 327.744446/645: elapsed=16994.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.744446
last_received_ts = 327.744049
last_seq = 645
current_ts = 327.761444
current_received_ts = 327.761047
current_seq = 646
count = 52
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.744446/645, current 327.761444/646: elapsed=17009.0us expected=17048.3us +- 85.2us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.761444
last_received_ts = 327.761047
last_seq = 646
current_ts = 327.778442
current_received_ts = 327.778015
current_seq = 647
count = 53
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.761444/646, current 327.778442/647: elapsed=16998.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.778442
last_received_ts = 327.778015
last_seq = 647
current_ts = 327.795441
current_received_ts = 327.795044
current_seq = 648
count = 54
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.778442/647, current 327.795441/648: elapsed=16997.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.795441
last_received_ts = 327.795044
last_seq = 648
current_ts = 327.812439
current_received_ts = 327.812042
current_seq = 649
count = 55
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.795441/648, current 327.812439/649: elapsed=17000.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.812439
last_received_ts = 327.812042
last_seq = 649
current_ts = 327.829437
current_received_ts = 327.829010
current_seq = 650
count = 56
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.812439/649, current 327.829437/650: elapsed=17008.0us expected=17048.3us +- 85.2us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.829437
last_received_ts = 327.829010
last_seq = 650
current_ts = 327.846436
current_received_ts = 327.846100
current_seq = 651
count = 57
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.829437/650, current 327.846436/651: elapsed=16998.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.846436
last_received_ts = 327.846100
last_seq = 651
current_ts = 327.863434
current_received_ts = 327.863007
current_seq = 652
count = 58
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.846436/651, current 327.863434/652: elapsed=17005.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.863434
last_received_ts = 327.863007
last_seq = 652
current_ts = 327.880432
current_received_ts = 327.880005
current_seq = 653
count = 59
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.863434/652, current 327.880432/653: elapsed=16996.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.880432
last_received_ts = 327.880005
last_seq = 653
current_ts = 327.897430
current_received_ts = 327.897064
current_seq = 654
count = 60
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.880432/653, current 327.897430/654: elapsed=16995.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.897430
last_received_ts = 327.897064
last_seq = 654
current_ts = 327.914459
current_received_ts = 327.914001
current_seq = 655
count = 61
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.897430/654, current 327.914459/655: elapsed=17012.0us expected=17048.3us +- 85.2us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.914459
last_received_ts = 327.914001
last_seq = 655
current_ts = 327.931458
current_received_ts = 327.931061
current_seq = 656
count = 62
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.914459/655, current 327.931458/656: elapsed=16998.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.931458
last_received_ts = 327.931061
last_seq = 656
current_ts = 327.948456
current_received_ts = 327.948090
current_seq = 657
count = 63
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.931458/656, current 327.948456/657: elapsed=16995.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.948456
last_received_ts = 327.948090
last_seq = 657
current_ts = 327.965454
current_received_ts = 327.965088
current_seq = 658
count = 64
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.948456/657, current 327.965454/658: elapsed=17014.0us expected=17048.3us +- 85.2us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.965454
last_received_ts = 327.965088
last_seq = 658
current_ts = 327.982452
current_received_ts = 327.982056
current_seq = 659
count = 65
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.965454/658, current 327.982452/659: elapsed=16992.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.982452
last_received_ts = 327.982056
last_seq = 659
current_ts = 327.999451
current_received_ts = 327.999054
current_seq = 660
count = 66
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.982452/659, current 327.999451/660: elapsed=17000.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 327.999451
last_received_ts = 327.999054
last_seq = 660
current_ts = 328.016449
current_received_ts = 328.016083
current_seq = 661
count = 67
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 327.999451/660, current 328.016449/661: elapsed=17012.0us expected=17048.3us +- 85.2us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 328.016449
last_received_ts = 328.016083
last_seq = 661
current_ts = 328.033447
current_received_ts = 328.033081
current_seq = 662
count = 68
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 328.016449/661, current 328.033447/662: elapsed=16991.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 328.033447
last_received_ts = 328.033081
last_seq = 662
current_ts = 328.050446
current_received_ts = 328.050079
current_seq = 663
count = 69
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 328.033447/662, current 328.050446/663: elapsed=17003.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 328.050446
last_received_ts = 328.050079
last_seq = 663
current_ts = 328.067474
current_received_ts = 328.067078
current_seq = 664
count = 70
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 328.050446/663, current 328.067474/664: elapsed=17009.0us expected=17048.3us +- 85.2us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 328.067474
last_received_ts = 328.067078
last_seq = 664
current_ts = 328.084473
current_received_ts = 328.084076
current_seq = 665
count = 71
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 328.067474/664, current 328.084473/665: elapsed=16994.0us expected=17048.3us +- 85.2us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 328.084473
last_received_ts = 328.084076
last_seq = 665
current_ts = 328.101440
current_received_ts = 328.101074
current_seq = 666
count = 72
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 328.084473/665, current 328.101440/666: elapsed=16966.0us expected=17048.3us +- 85.2us, error 0.5%
(kms_flip:2744) DEBUG: name = flip
last_ts = 328.101440
last_received_ts = 328.101074
last_seq = 666
current_ts = 328.118408
current_received_ts = 328.117981
current_seq = 667
count = 73
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 328.101440/666, current 328.118408/667: elapsed=16970.0us expected=17048.3us +- 85.2us, error 0.5%
(kms_flip:2744) DEBUG: name = flip
last_ts = 328.118408
last_received_ts = 328.117981
last_seq = 667
current_ts = 328.135345
current_received_ts = 328.134918
current_seq = 668
count = 74
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 328.118408/667, current 328.135345/668: elapsed=16960.0us expected=17048.3us +- 85.2us, error 0.5%
(kms_flip:2744) DEBUG: inconsistent flip ts/seq: last 328.118408/667, current 328.135345/668: elapsed=16960.0us expected=17048.3us
(kms_flip:2744) DEBUG: expected 0, counted 74, encoder type 2
(kms_flip:2744) DEBUG: dropped frames, expected 0, counted 74, encoder type 2
(kms_flip:2744) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2744) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2744) igt_core-INFO: Stack trace:
(kms_flip:2744) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2744) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2744) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2744) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2744) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2744) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2744) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2744) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A1: FAIL (4.725s)
Starting dynamic subtest: C-HDMI-A1
(kms_flip:2744) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2744) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest C-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2744) DEBUG: flip ts/seq: last 333.133728/682, current 333.150543/683: elapsed=16825.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.150543
last_received_ts = 333.150177
last_seq = 683
current_ts = 333.167389
current_received_ts = 333.166992
current_seq = 684
count = 91
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.150543/683, current 333.167389/684: elapsed=16823.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.167389
last_received_ts = 333.166992
last_seq = 684
current_ts = 333.184204
current_received_ts = 333.183777
current_seq = 685
count = 92
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.167389/684, current 333.184204/685: elapsed=16820.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.184204
last_received_ts = 333.183777
last_seq = 685
current_ts = 333.201019
current_received_ts = 333.200623
current_seq = 686
count = 93
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.184204/685, current 333.201019/686: elapsed=16829.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.201019
last_received_ts = 333.200623
last_seq = 686
current_ts = 333.217834
current_received_ts = 333.217438
current_seq = 687
count = 94
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.201019/686, current 333.217834/687: elapsed=16820.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.217834
last_received_ts = 333.217438
last_seq = 687
current_ts = 333.234680
current_received_ts = 333.234283
current_seq = 688
count = 95
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.217834/687, current 333.234680/688: elapsed=16818.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.234680
last_received_ts = 333.234283
last_seq = 688
current_ts = 333.251465
current_received_ts = 333.251068
current_seq = 689
count = 96
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.234680/688, current 333.251465/689: elapsed=16815.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.251465
last_received_ts = 333.251068
last_seq = 689
current_ts = 333.268311
current_received_ts = 333.267883
current_seq = 690
count = 97
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.251465/689, current 333.268311/690: elapsed=16828.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.268311
last_received_ts = 333.267883
last_seq = 690
current_ts = 333.285126
current_received_ts = 333.284698
current_seq = 691
count = 98
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.268311/690, current 333.285126/691: elapsed=16815.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.285126
last_received_ts = 333.284698
last_seq = 691
current_ts = 333.301971
current_received_ts = 333.301544
current_seq = 692
count = 99
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.285126/691, current 333.301971/692: elapsed=16835.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.301971
last_received_ts = 333.301544
last_seq = 692
current_ts = 333.318787
current_received_ts = 333.318420
current_seq = 693
count = 100
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.301971/692, current 333.318787/693: elapsed=16815.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.318787
last_received_ts = 333.318420
last_seq = 693
current_ts = 333.335602
current_received_ts = 333.335205
current_seq = 694
count = 101
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.318787/693, current 333.335602/694: elapsed=16825.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.335602
last_received_ts = 333.335205
last_seq = 694
current_ts = 333.352417
current_received_ts = 333.352051
current_seq = 695
count = 102
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.335602/694, current 333.352417/695: elapsed=16811.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.352417
last_received_ts = 333.352051
last_seq = 695
current_ts = 333.369232
current_received_ts = 333.368805
current_seq = 696
count = 103
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.352417/695, current 333.369232/696: elapsed=16828.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.369232
last_received_ts = 333.368805
last_seq = 696
current_ts = 333.386047
current_received_ts = 333.385681
current_seq = 697
count = 104
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.369232/696, current 333.386047/697: elapsed=16825.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.386047
last_received_ts = 333.385681
last_seq = 697
current_ts = 333.402893
current_received_ts = 333.402466
current_seq = 698
count = 105
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.386047/697, current 333.402893/698: elapsed=16817.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.402893
last_received_ts = 333.402466
last_seq = 698
current_ts = 333.419708
current_received_ts = 333.419281
current_seq = 699
count = 106
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.402893/698, current 333.419708/699: elapsed=16826.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.419708
last_received_ts = 333.419281
last_seq = 699
current_ts = 333.436523
current_received_ts = 333.436127
current_seq = 700
count = 107
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.419708/699, current 333.436523/700: elapsed=16813.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.436523
last_received_ts = 333.436127
last_seq = 700
current_ts = 333.453339
current_received_ts = 333.453094
current_seq = 701
count = 108
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.436523/700, current 333.453339/701: elapsed=16826.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.453339
last_received_ts = 333.453094
last_seq = 701
current_ts = 333.470154
current_received_ts = 333.469849
current_seq = 702
count = 109
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.453339/701, current 333.470154/702: elapsed=16818.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.470154
last_received_ts = 333.469849
last_seq = 702
current_ts = 333.486969
current_received_ts = 333.486572
current_seq = 703
count = 110
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.470154/702, current 333.486969/703: elapsed=16820.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.486969
last_received_ts = 333.486572
last_seq = 703
current_ts = 333.503815
current_received_ts = 333.503387
current_seq = 704
count = 111
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.486969/703, current 333.503815/704: elapsed=16829.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.503815
last_received_ts = 333.503387
last_seq = 704
current_ts = 333.520630
current_received_ts = 333.520203
current_seq = 705
count = 112
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.503815/704, current 333.520630/705: elapsed=16819.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.520630
last_received_ts = 333.520203
last_seq = 705
current_ts = 333.537445
current_received_ts = 333.537170
current_seq = 706
count = 113
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.520630/705, current 333.537445/706: elapsed=16829.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.537445
last_received_ts = 333.537170
last_seq = 706
current_ts = 333.554260
current_received_ts = 333.553894
current_seq = 707
count = 114
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.537445/706, current 333.554260/707: elapsed=16814.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.554260
last_received_ts = 333.553894
last_seq = 707
current_ts = 333.571106
current_received_ts = 333.570770
current_seq = 708
count = 115
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.554260/707, current 333.571106/708: elapsed=16828.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.571106
last_received_ts = 333.570770
last_seq = 708
current_ts = 333.587921
current_received_ts = 333.587494
current_seq = 709
count = 116
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.571106/708, current 333.587921/709: elapsed=16818.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.587921
last_received_ts = 333.587494
last_seq = 709
current_ts = 333.604736
current_received_ts = 333.604309
current_seq = 710
count = 117
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.587921/709, current 333.604736/710: elapsed=16819.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.604736
last_received_ts = 333.604309
last_seq = 710
current_ts = 333.621552
current_received_ts = 333.621155
current_seq = 711
count = 118
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.604736/710, current 333.621552/711: elapsed=16817.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.621552
last_received_ts = 333.621155
last_seq = 711
current_ts = 333.638367
current_received_ts = 333.637970
current_seq = 712
count = 119
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.621552/711, current 333.638367/712: elapsed=16825.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.638367
last_received_ts = 333.637970
last_seq = 712
current_ts = 333.655212
current_received_ts = 333.654907
current_seq = 713
count = 120
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.638367/712, current 333.655212/713: elapsed=16834.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.655212
last_received_ts = 333.654907
last_seq = 713
current_ts = 333.672028
current_received_ts = 333.671600
current_seq = 714
count = 121
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.655212/713, current 333.672028/714: elapsed=16809.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.672028
last_received_ts = 333.671600
last_seq = 714
current_ts = 333.688843
current_received_ts = 333.688446
current_seq = 715
count = 122
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.672028/714, current 333.688843/715: elapsed=16827.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.688843
last_received_ts = 333.688446
last_seq = 715
current_ts = 333.705658
current_received_ts = 333.705414
current_seq = 716
count = 123
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.688843/715, current 333.705658/716: elapsed=16816.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.705658
last_received_ts = 333.705414
last_seq = 716
current_ts = 333.722504
current_received_ts = 333.722198
current_seq = 717
count = 124
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.705658/716, current 333.722504/717: elapsed=16831.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.722504
last_received_ts = 333.722198
last_seq = 717
current_ts = 333.739319
current_received_ts = 333.738922
current_seq = 718
count = 125
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.722504/717, current 333.739319/718: elapsed=16821.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.739319
last_received_ts = 333.738922
last_seq = 718
current_ts = 333.756134
current_received_ts = 333.755737
current_seq = 719
count = 126
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.739319/718, current 333.756134/719: elapsed=16825.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.756134
last_received_ts = 333.755737
last_seq = 719
current_ts = 333.772949
current_received_ts = 333.772522
current_seq = 720
count = 127
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.756134/719, current 333.772949/720: elapsed=16816.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.772949
last_received_ts = 333.772522
last_seq = 720
current_ts = 333.789795
current_received_ts = 333.789307
current_seq = 721
count = 128
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.772949/720, current 333.789795/721: elapsed=16823.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.789795
last_received_ts = 333.789307
last_seq = 721
current_ts = 333.806610
current_received_ts = 333.806213
current_seq = 722
count = 129
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.789795/721, current 333.806610/722: elapsed=16826.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.806610
last_received_ts = 333.806213
last_seq = 722
current_ts = 333.823425
current_received_ts = 333.822998
current_seq = 723
count = 130
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.806610/722, current 333.823425/723: elapsed=16815.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.823425
last_received_ts = 333.822998
last_seq = 723
current_ts = 333.840240
current_received_ts = 333.839844
current_seq = 724
count = 131
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.823425/723, current 333.840240/724: elapsed=16814.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.840240
last_received_ts = 333.839844
last_seq = 724
current_ts = 333.857086
current_received_ts = 333.856659
current_seq = 725
count = 132
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.840240/724, current 333.857086/725: elapsed=16835.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.857086
last_received_ts = 333.856659
last_seq = 725
current_ts = 333.873901
current_received_ts = 333.873444
current_seq = 726
count = 133
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.857086/725, current 333.873901/726: elapsed=16816.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.873901
last_received_ts = 333.873444
last_seq = 726
current_ts = 333.890717
current_received_ts = 333.890320
current_seq = 727
count = 134
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.873901/726, current 333.890717/727: elapsed=16819.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.890717
last_received_ts = 333.890320
last_seq = 727
current_ts = 333.907532
current_received_ts = 333.907196
current_seq = 728
count = 135
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.890717/727, current 333.907532/728: elapsed=16821.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.907532
last_received_ts = 333.907196
last_seq = 728
current_ts = 333.924347
current_received_ts = 333.923889
current_seq = 729
count = 136
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.907532/728, current 333.924347/729: elapsed=16817.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.924347
last_received_ts = 333.923889
last_seq = 729
current_ts = 333.941162
current_received_ts = 333.940887
current_seq = 730
count = 137
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.924347/729, current 333.941162/730: elapsed=16823.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.941162
last_received_ts = 333.940887
last_seq = 730
current_ts = 333.958008
current_received_ts = 333.957581
current_seq = 731
count = 138
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.941162/730, current 333.958008/731: elapsed=16825.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.958008
last_received_ts = 333.957581
last_seq = 731
current_ts = 333.974823
current_received_ts = 333.974335
current_seq = 732
count = 139
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.958008/731, current 333.974823/732: elapsed=16820.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.974823
last_received_ts = 333.974335
last_seq = 732
current_ts = 333.991638
current_received_ts = 333.991241
current_seq = 733
count = 140
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.974823/732, current 333.991638/733: elapsed=16825.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 333.991638
last_received_ts = 333.991241
last_seq = 733
current_ts = 334.008453
current_received_ts = 334.008087
current_seq = 734
count = 141
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 333.991638/733, current 334.008453/734: elapsed=16830.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.008453
last_received_ts = 334.008087
last_seq = 734
current_ts = 334.025269
current_received_ts = 334.024841
current_seq = 735
count = 142
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.008453/734, current 334.025269/735: elapsed=16812.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.025269
last_received_ts = 334.024841
last_seq = 735
current_ts = 334.042114
current_received_ts = 334.041809
current_seq = 736
count = 143
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.025269/735, current 334.042114/736: elapsed=16826.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.042114
last_received_ts = 334.041809
last_seq = 736
current_ts = 334.058929
current_received_ts = 334.058533
current_seq = 737
count = 144
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.042114/736, current 334.058929/737: elapsed=16814.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.058929
last_received_ts = 334.058533
last_seq = 737
current_ts = 334.075745
current_received_ts = 334.075348
current_seq = 738
count = 145
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.058929/737, current 334.075745/738: elapsed=16830.0us expected=16866.8us +- 84.3us, error 0.2%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.075745
last_received_ts = 334.075348
last_seq = 738
current_ts = 334.092560
current_received_ts = 334.092316
current_seq = 739
count = 146
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.075745/738, current 334.092560/739: elapsed=16818.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.092560
last_received_ts = 334.092316
last_seq = 739
current_ts = 334.109375
current_received_ts = 334.108978
current_seq = 740
count = 147
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.092560/739, current 334.109375/740: elapsed=16806.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.109375
last_received_ts = 334.108978
last_seq = 740
current_ts = 334.126160
current_received_ts = 334.125732
current_seq = 741
count = 148
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.109375/740, current 334.126160/741: elapsed=16795.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.126160
last_received_ts = 334.125732
last_seq = 741
current_ts = 334.142975
current_received_ts = 334.142609
current_seq = 742
count = 149
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.126160/741, current 334.142975/742: elapsed=16807.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.142975
last_received_ts = 334.142609
last_seq = 742
current_ts = 334.159760
current_received_ts = 334.159332
current_seq = 743
count = 150
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.142975/742, current 334.159760/743: elapsed=16798.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.159760
last_received_ts = 334.159332
last_seq = 743
current_ts = 334.176575
current_received_ts = 334.176147
current_seq = 744
count = 151
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.159760/743, current 334.176575/744: elapsed=16806.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.176575
last_received_ts = 334.176147
last_seq = 744
current_ts = 334.193390
current_received_ts = 334.193146
current_seq = 745
count = 152
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.176575/744, current 334.193390/745: elapsed=16811.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.193390
last_received_ts = 334.193146
last_seq = 745
current_ts = 334.210205
current_received_ts = 334.209778
current_seq = 746
count = 153
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.193390/745, current 334.210205/746: elapsed=16800.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.210205
last_received_ts = 334.209778
last_seq = 746
current_ts = 334.226990
current_received_ts = 334.226593
current_seq = 747
count = 154
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.210205/746, current 334.226990/747: elapsed=16805.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.226990
last_received_ts = 334.226593
last_seq = 747
current_ts = 334.243805
current_received_ts = 334.243408
current_seq = 748
count = 155
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.226990/747, current 334.243805/748: elapsed=16799.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.243805
last_received_ts = 334.243408
last_seq = 748
current_ts = 334.260590
current_received_ts = 334.260193
current_seq = 749
count = 156
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.243805/748, current 334.260590/749: elapsed=16804.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.260590
last_received_ts = 334.260193
last_seq = 749
current_ts = 334.277405
current_received_ts = 334.276947
current_seq = 750
count = 157
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.260590/749, current 334.277405/750: elapsed=16802.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.277405
last_received_ts = 334.276947
last_seq = 750
current_ts = 334.294189
current_received_ts = 334.293823
current_seq = 751
count = 158
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.277405/750, current 334.294189/751: elapsed=16801.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.294189
last_received_ts = 334.293823
last_seq = 751
current_ts = 334.311005
current_received_ts = 334.310669
current_seq = 752
count = 159
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.294189/751, current 334.311005/752: elapsed=16811.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.311005
last_received_ts = 334.310669
last_seq = 752
current_ts = 334.327820
current_received_ts = 334.327362
current_seq = 753
count = 160
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.311005/752, current 334.327820/753: elapsed=16799.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.327820
last_received_ts = 334.327362
last_seq = 753
current_ts = 334.344604
current_received_ts = 334.344208
current_seq = 754
count = 161
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.327820/753, current 334.344604/754: elapsed=16806.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.344604
last_received_ts = 334.344208
last_seq = 754
current_ts = 334.361420
current_received_ts = 334.361053
current_seq = 755
count = 162
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.344604/754, current 334.361420/755: elapsed=16802.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.361420
last_received_ts = 334.361053
last_seq = 755
current_ts = 334.378235
current_received_ts = 334.377777
current_seq = 756
count = 163
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.361420/755, current 334.378235/756: elapsed=16801.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.378235
last_received_ts = 334.377777
last_seq = 756
current_ts = 334.395020
current_received_ts = 334.394623
current_seq = 757
count = 164
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.378235/756, current 334.395020/757: elapsed=16811.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.395020
last_received_ts = 334.394623
last_seq = 757
current_ts = 334.411835
current_received_ts = 334.411377
current_seq = 758
count = 165
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.395020/757, current 334.411835/758: elapsed=16803.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.411835
last_received_ts = 334.411377
last_seq = 758
current_ts = 334.428650
current_received_ts = 334.428192
current_seq = 759
count = 166
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.411835/758, current 334.428650/759: elapsed=16802.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.428650
last_received_ts = 334.428192
last_seq = 759
current_ts = 334.445435
current_received_ts = 334.445160
current_seq = 760
count = 167
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.428650/759, current 334.445435/760: elapsed=16802.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.445435
last_received_ts = 334.445160
last_seq = 760
current_ts = 334.462250
current_received_ts = 334.461823
current_seq = 761
count = 168
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.445435/760, current 334.462250/761: elapsed=16797.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.462250
last_received_ts = 334.461823
last_seq = 761
current_ts = 334.479034
current_received_ts = 334.478607
current_seq = 762
count = 169
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.462250/761, current 334.479034/762: elapsed=16804.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.479034
last_received_ts = 334.478607
last_seq = 762
current_ts = 334.495850
current_received_ts = 334.495453
current_seq = 763
count = 170
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.479034/762, current 334.495850/763: elapsed=16805.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.495850
last_received_ts = 334.495453
last_seq = 763
current_ts = 334.512665
current_received_ts = 334.512268
current_seq = 764
count = 171
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.495850/763, current 334.512665/764: elapsed=16811.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.512665
last_received_ts = 334.512268
last_seq = 764
current_ts = 334.529449
current_received_ts = 334.529053
current_seq = 765
count = 172
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.512665/764, current 334.529449/765: elapsed=16796.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.529449
last_received_ts = 334.529053
last_seq = 765
current_ts = 334.546265
current_received_ts = 334.545837
current_seq = 766
count = 173
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.529449/765, current 334.546265/766: elapsed=16798.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.546265
last_received_ts = 334.545837
last_seq = 766
current_ts = 334.563049
current_received_ts = 334.562622
current_seq = 767
count = 174
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.546265/766, current 334.563049/767: elapsed=16803.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.563049
last_received_ts = 334.562622
last_seq = 767
current_ts = 334.579865
current_received_ts = 334.579437
current_seq = 768
count = 175
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.563049/767, current 334.579865/768: elapsed=16814.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.579865
last_received_ts = 334.579437
last_seq = 768
current_ts = 334.596680
current_received_ts = 334.596405
current_seq = 769
count = 176
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.579865/768, current 334.596680/769: elapsed=16798.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.596680
last_received_ts = 334.596405
last_seq = 769
current_ts = 334.613464
current_received_ts = 334.613190
current_seq = 770
count = 177
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.596680/769, current 334.613464/770: elapsed=16807.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.613464
last_received_ts = 334.613190
last_seq = 770
current_ts = 334.630280
current_received_ts = 334.629974
current_seq = 771
count = 178
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.613464/770, current 334.630280/771: elapsed=16796.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.630280
last_received_ts = 334.629974
last_seq = 771
current_ts = 334.647064
current_received_ts = 334.646729
current_seq = 772
count = 179
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.630280/771, current 334.647064/772: elapsed=16808.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.647064
last_received_ts = 334.646729
last_seq = 772
current_ts = 334.663879
current_received_ts = 334.663483
current_seq = 773
count = 180
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.647064/772, current 334.663879/773: elapsed=16802.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.663879
last_received_ts = 334.663483
last_seq = 773
current_ts = 334.680664
current_received_ts = 334.680298
current_seq = 774
count = 181
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.663879/773, current 334.680664/774: elapsed=16801.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.680664
last_received_ts = 334.680298
last_seq = 774
current_ts = 334.697479
current_received_ts = 334.697083
current_seq = 775
count = 182
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.680664/774, current 334.697479/775: elapsed=16814.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.697479
last_received_ts = 334.697083
last_seq = 775
current_ts = 334.714294
current_received_ts = 334.713898
current_seq = 776
count = 183
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.697479/775, current 334.714294/776: elapsed=16792.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.714294
last_received_ts = 334.713898
last_seq = 776
current_ts = 334.731079
current_received_ts = 334.730682
current_seq = 777
count = 184
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.714294/776, current 334.731079/777: elapsed=16802.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.731079
last_received_ts = 334.730682
last_seq = 777
current_ts = 334.747894
current_received_ts = 334.747437
current_seq = 778
count = 185
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.731079/777, current 334.747894/778: elapsed=16805.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.747894
last_received_ts = 334.747437
last_seq = 778
current_ts = 334.764679
current_received_ts = 334.764282
current_seq = 779
count = 186
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.747894/778, current 334.764679/779: elapsed=16802.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.764679
last_received_ts = 334.764282
last_seq = 779
current_ts = 334.781494
current_received_ts = 334.781128
current_seq = 780
count = 187
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.764679/779, current 334.781494/780: elapsed=16812.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.781494
last_received_ts = 334.781128
last_seq = 780
current_ts = 334.798309
current_received_ts = 334.798065
current_seq = 781
count = 188
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.781494/780, current 334.798309/781: elapsed=16797.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.798309
last_received_ts = 334.798065
last_seq = 781
current_ts = 334.815125
current_received_ts = 334.814697
current_seq = 782
count = 189
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.798309/781, current 334.815125/782: elapsed=16810.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.815125
last_received_ts = 334.814697
last_seq = 782
current_ts = 334.831909
current_received_ts = 334.831482
current_seq = 783
count = 190
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.815125/782, current 334.831909/783: elapsed=16793.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.831909
last_received_ts = 334.831482
last_seq = 783
current_ts = 334.848724
current_received_ts = 334.848419
current_seq = 784
count = 191
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.831909/783, current 334.848724/784: elapsed=16812.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.848724
last_received_ts = 334.848419
last_seq = 784
current_ts = 334.865509
current_received_ts = 334.865112
current_seq = 785
count = 192
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.848724/784, current 334.865509/785: elapsed=16804.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.865509
last_received_ts = 334.865112
last_seq = 785
current_ts = 334.882324
current_received_ts = 334.882050
current_seq = 786
count = 193
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.865509/785, current 334.882324/786: elapsed=16802.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.882324
last_received_ts = 334.882050
last_seq = 786
current_ts = 334.899139
current_received_ts = 334.898834
current_seq = 787
count = 194
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.882324/786, current 334.899139/787: elapsed=16802.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.899139
last_received_ts = 334.898834
last_seq = 787
current_ts = 334.915924
current_received_ts = 334.915497
current_seq = 788
count = 195
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.899139/787, current 334.915924/788: elapsed=16801.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.915924
last_received_ts = 334.915497
last_seq = 788
current_ts = 334.932739
current_received_ts = 334.932343
current_seq = 789
count = 196
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.915924/788, current 334.932739/789: elapsed=16804.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.932739
last_received_ts = 334.932343
last_seq = 789
current_ts = 334.949524
current_received_ts = 334.949188
current_seq = 790
count = 197
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.932739/789, current 334.949524/790: elapsed=16805.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.949524
last_received_ts = 334.949188
last_seq = 790
current_ts = 334.966339
current_received_ts = 334.965912
current_seq = 791
count = 198
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.949524/790, current 334.966339/791: elapsed=16801.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.966339
last_received_ts = 334.965912
last_seq = 791
current_ts = 334.983154
current_received_ts = 334.982727
current_seq = 792
count = 199
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.966339/791, current 334.983154/792: elapsed=16813.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.983154
last_received_ts = 334.982727
last_seq = 792
current_ts = 334.999939
current_received_ts = 334.999542
current_seq = 793
count = 200
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.983154/792, current 334.999939/793: elapsed=16803.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 334.999939
last_received_ts = 334.999542
last_seq = 793
current_ts = 335.016754
current_received_ts = 335.016418
current_seq = 794
count = 201
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 334.999939/793, current 335.016754/794: elapsed=16804.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 335.016754
last_received_ts = 335.016418
last_seq = 794
current_ts = 335.033539
current_received_ts = 335.033142
current_seq = 795
count = 202
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 335.016754/794, current 335.033539/795: elapsed=16794.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 335.033539
last_received_ts = 335.033142
last_seq = 795
current_ts = 335.050354
current_received_ts = 335.050110
current_seq = 796
count = 203
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 335.033539/795, current 335.050354/796: elapsed=16808.0us expected=16866.8us +- 84.3us, error 0.3%
(kms_flip:2744) DEBUG: name = flip
last_ts = 335.050354
last_received_ts = 335.050110
last_seq = 796
current_ts = 335.067169
current_received_ts = 335.066833
current_seq = 797
count = 204
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 335.050354/796, current 335.067169/797: elapsed=16802.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 335.067169
last_received_ts = 335.066833
last_seq = 797
current_ts = 335.083954
current_received_ts = 335.083557
current_seq = 798
count = 205
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 335.067169/797, current 335.083954/798: elapsed=16799.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 335.083954
last_received_ts = 335.083557
last_seq = 798
current_ts = 335.100739
current_received_ts = 335.100311
current_seq = 799
count = 206
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 335.083954/798, current 335.100739/799: elapsed=16793.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 335.100739
last_received_ts = 335.100311
last_seq = 799
current_ts = 335.117554
current_received_ts = 335.117279
current_seq = 800
count = 207
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 335.100739/799, current 335.117554/800: elapsed=16793.0us expected=16866.8us +- 84.3us, error 0.4%
(kms_flip:2744) DEBUG: name = flip
last_ts = 335.117554
last_received_ts = 335.117279
last_seq = 800
current_ts = 335.134338
current_received_ts = 335.134094
current_seq = 801
count = 208
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 335.117554/800, current 335.134338/801: elapsed=16788.0us expected=16866.8us +- 84.3us, error 0.5%
(kms_flip:2744) DEBUG: name = flip
last_ts = 335.134338
last_received_ts = 335.134094
last_seq = 801
current_ts = 335.151123
current_received_ts = 335.150726
current_seq = 802
count = 209
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 335.134338/801, current 335.151123/802: elapsed=16790.0us expected=16866.8us +- 84.3us, error 0.5%
(kms_flip:2744) DEBUG: name = flip
last_ts = 335.151123
last_received_ts = 335.150726
last_seq = 802
current_ts = 335.167908
current_received_ts = 335.167480
current_seq = 803
count = 210
seq_step = 1
(kms_flip:2744) DEBUG: flip ts/seq: last 335.151123/802, current 335.167908/803: elapsed=16782.0us expected=16866.8us +- 84.3us, error 0.5%
(kms_flip:2744) DEBUG: inconsistent flip ts/seq: last 335.151123/802, current 335.167908/803: elapsed=16782.0us expected=16866.8us
(kms_flip:2744) DEBUG: expected 0, counted 210, encoder type 2
(kms_flip:2744) DEBUG: dropped frames, expected 0, counted 210, encoder type 2
(kms_flip:2744) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2744) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2744) igt_core-INFO: Stack trace:
(kms_flip:2744) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2744) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2744) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2744) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2744) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2744) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2744) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2744) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-HDMI-A1: FAIL (7.192s)
Starting dynamic subtest: D-HDMI-A1
Dynamic subtest D-HDMI-A1: SUCCESS (7.971s)
Subtest plain-flip-fb-recreate: FAIL (25.692s)