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

shard-dg2-5

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

Using IGT_SRANDOM=1742296393 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16666.4us +- 6.418us accuracy 0.12%
Dynamic subtest A-HDMI-A3: SUCCESS (8.015s)
Starting dynamic subtest: B-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16667.2us +- 6.316us accuracy 0.11%
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-A3: FAIL (6.811s)
Starting dynamic subtest: C-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 17036.7us +- 8.031us accuracy 0.14%
vblank interval differs from modeline! expected 16666.7us, measured 17037us +- 8.031us, difference 370.0us (46.1 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-A3: FAIL (4.652s)
Starting dynamic subtest: D-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16861.1us +- 6.752us accuracy 0.12%
vblank interval differs from modeline! expected 16666.7us, measured 16861us +- 6.752us, difference 194.5us (28.8 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 D-HDMI-A3: FAIL (7.124s)
Subtest plain-flip-ts-check: FAIL (26.615s)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2246 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2934 igt_atexit_handler()
  #3 [erand48_r+0x1d6]
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2390 igt_exit()
  #6 [main+0x3f]
  #7 [__libc_init_first+0x8a]
  #8 [__libc_start_main+0x8b]
  #9 [_start+0x25]

Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A3
Dynamic subtest A-HDMI-A3: SUCCESS (8.015s)
Starting dynamic subtest: B-HDMI-A3
(kms_flip:2316) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2316) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:2316) DEBUG: flip ts/seq: last 278.435486/574, current 278.452179/575: elapsed=16675.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.452179
last_received_ts = 278.451782
last_seq = 575
current_ts = 278.468842
current_received_ts = 278.468384
current_seq = 576
count = 69
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.452179/575, current 278.468842/576: elapsed=16666.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.468842
last_received_ts = 278.468384
last_seq = 576
current_ts = 278.485504
current_received_ts = 278.485138
current_seq = 577
count = 70
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.468842/576, current 278.485504/577: elapsed=16669.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.485504
last_received_ts = 278.485138
last_seq = 577
current_ts = 278.502167
current_received_ts = 278.501770
current_seq = 578
count = 71
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.485504/577, current 278.502167/578: elapsed=16655.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.502167
last_received_ts = 278.501770
last_seq = 578
current_ts = 278.518829
current_received_ts = 278.518433
current_seq = 579
count = 72
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.502167/578, current 278.518829/579: elapsed=16676.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.518829
last_received_ts = 278.518433
last_seq = 579
current_ts = 278.535522
current_received_ts = 278.535217
current_seq = 580
count = 73
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.518829/579, current 278.535522/580: elapsed=16670.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.535522
last_received_ts = 278.535217
last_seq = 580
current_ts = 278.552185
current_received_ts = 278.551758
current_seq = 581
count = 74
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.535522/580, current 278.552185/581: elapsed=16664.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.552185
last_received_ts = 278.551758
last_seq = 581
current_ts = 278.568848
current_received_ts = 278.568420
current_seq = 582
count = 75
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.552185/581, current 278.568848/582: elapsed=16667.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.568848
last_received_ts = 278.568420
last_seq = 582
current_ts = 278.585510
current_received_ts = 278.585236
current_seq = 583
count = 76
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.568848/582, current 278.585510/583: elapsed=16665.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.585510
last_received_ts = 278.585236
last_seq = 583
current_ts = 278.602173
current_received_ts = 278.601776
current_seq = 584
count = 77
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.585510/583, current 278.602173/584: elapsed=16672.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.602173
last_received_ts = 278.601776
last_seq = 584
current_ts = 278.618835
current_received_ts = 278.618408
current_seq = 585
count = 78
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.602173/584, current 278.618835/585: elapsed=16662.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.618835
last_received_ts = 278.618408
last_seq = 585
current_ts = 278.635498
current_received_ts = 278.635223
current_seq = 586
count = 79
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.618835/585, current 278.635498/586: elapsed=16670.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.635498
last_received_ts = 278.635223
last_seq = 586
current_ts = 278.652191
current_received_ts = 278.651764
current_seq = 587
count = 80
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.635498/586, current 278.652191/587: elapsed=16669.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.652191
last_received_ts = 278.651764
last_seq = 587
current_ts = 278.668823
current_received_ts = 278.668396
current_seq = 588
count = 81
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.652191/587, current 278.668823/588: elapsed=16659.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.668823
last_received_ts = 278.668396
last_seq = 588
current_ts = 278.685516
current_received_ts = 278.685150
current_seq = 589
count = 82
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.668823/588, current 278.685516/589: elapsed=16678.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.685516
last_received_ts = 278.685150
last_seq = 589
current_ts = 278.702179
current_received_ts = 278.701782
current_seq = 590
count = 83
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.685516/589, current 278.702179/590: elapsed=16665.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.702179
last_received_ts = 278.701782
last_seq = 590
current_ts = 278.718842
current_received_ts = 278.718445
current_seq = 591
count = 84
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.702179/590, current 278.718842/591: elapsed=16668.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.718842
last_received_ts = 278.718445
last_seq = 591
current_ts = 278.735504
current_received_ts = 278.735229
current_seq = 592
count = 85
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.718842/591, current 278.735504/592: elapsed=16661.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.735504
last_received_ts = 278.735229
last_seq = 592
current_ts = 278.752167
current_received_ts = 278.751770
current_seq = 593
count = 86
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.735504/592, current 278.752167/593: elapsed=16670.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.752167
last_received_ts = 278.751770
last_seq = 593
current_ts = 278.768829
current_received_ts = 278.768433
current_seq = 594
count = 87
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.752167/593, current 278.768829/594: elapsed=16665.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.768829
last_received_ts = 278.768433
last_seq = 594
current_ts = 278.785492
current_received_ts = 278.785156
current_seq = 595
count = 88
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.768829/594, current 278.785492/595: elapsed=16661.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.785492
last_received_ts = 278.785156
last_seq = 595
current_ts = 278.802185
current_received_ts = 278.801788
current_seq = 596
count = 89
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.785492/595, current 278.802185/596: elapsed=16676.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.802185
last_received_ts = 278.801788
last_seq = 596
current_ts = 278.818848
current_received_ts = 278.818451
current_seq = 597
count = 90
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.802185/596, current 278.818848/597: elapsed=16657.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.818848
last_received_ts = 278.818451
last_seq = 597
current_ts = 278.835510
current_received_ts = 278.835175
current_seq = 598
count = 91
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.818848/597, current 278.835510/598: elapsed=16674.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.835510
last_received_ts = 278.835175
last_seq = 598
current_ts = 278.852173
current_received_ts = 278.851898
current_seq = 599
count = 92
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.835510/598, current 278.852173/599: elapsed=16671.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.852173
last_received_ts = 278.851898
last_seq = 599
current_ts = 278.868835
current_received_ts = 278.868439
current_seq = 600
count = 93
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.852173/599, current 278.868835/600: elapsed=16666.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.868835
last_received_ts = 278.868439
last_seq = 600
current_ts = 278.885498
current_received_ts = 278.885162
current_seq = 601
count = 94
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.868835/600, current 278.885498/601: elapsed=16662.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.885498
last_received_ts = 278.885162
last_seq = 601
current_ts = 278.902191
current_received_ts = 278.901764
current_seq = 602
count = 95
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.885498/601, current 278.902191/602: elapsed=16666.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.902191
last_received_ts = 278.901764
last_seq = 602
current_ts = 278.918854
current_received_ts = 278.918457
current_seq = 603
count = 96
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.902191/602, current 278.918854/603: elapsed=16666.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.918854
last_received_ts = 278.918457
last_seq = 603
current_ts = 278.935516
current_received_ts = 278.935242
current_seq = 604
count = 97
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.918854/603, current 278.935516/604: elapsed=16675.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.935516
last_received_ts = 278.935242
last_seq = 604
current_ts = 278.952179
current_received_ts = 278.951874
current_seq = 605
count = 98
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.935516/604, current 278.952179/605: elapsed=16659.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.952179
last_received_ts = 278.951874
last_seq = 605
current_ts = 278.968842
current_received_ts = 278.968445
current_seq = 606
count = 99
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.952179/605, current 278.968842/606: elapsed=16672.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.968842
last_received_ts = 278.968445
last_seq = 606
current_ts = 278.985504
current_received_ts = 278.985168
current_seq = 607
count = 100
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.968842/606, current 278.985504/607: elapsed=16665.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 278.985504
last_received_ts = 278.985168
last_seq = 607
current_ts = 279.002167
current_received_ts = 279.001892
current_seq = 608
count = 101
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 278.985504/607, current 279.002167/608: elapsed=16667.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.002167
last_received_ts = 279.001892
last_seq = 608
current_ts = 279.018829
current_received_ts = 279.018524
current_seq = 609
count = 102
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.002167/608, current 279.018829/609: elapsed=16664.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.018829
last_received_ts = 279.018524
last_seq = 609
current_ts = 279.035522
current_received_ts = 279.035248
current_seq = 610
count = 103
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.018829/609, current 279.035522/610: elapsed=16679.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.035522
last_received_ts = 279.035248
last_seq = 610
current_ts = 279.052185
current_received_ts = 279.051880
current_seq = 611
count = 104
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.035522/610, current 279.052185/611: elapsed=16661.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.052185
last_received_ts = 279.051880
last_seq = 611
current_ts = 279.068848
current_received_ts = 279.068390
current_seq = 612
count = 105
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.052185/611, current 279.068848/612: elapsed=16664.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.068848
last_received_ts = 279.068390
last_seq = 612
current_ts = 279.085510
current_received_ts = 279.085266
current_seq = 613
count = 106
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.068848/612, current 279.085510/613: elapsed=16665.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.085510
last_received_ts = 279.085266
last_seq = 613
current_ts = 279.102173
current_received_ts = 279.101776
current_seq = 614
count = 107
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.085510/613, current 279.102173/614: elapsed=16672.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.102173
last_received_ts = 279.101776
last_seq = 614
current_ts = 279.118866
current_received_ts = 279.118439
current_seq = 615
count = 108
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.102173/614, current 279.118866/615: elapsed=16669.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.118866
last_received_ts = 279.118439
last_seq = 615
current_ts = 279.135529
current_received_ts = 279.135162
current_seq = 616
count = 109
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.118866/615, current 279.135529/616: elapsed=16671.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.135529
last_received_ts = 279.135162
last_seq = 616
current_ts = 279.152191
current_received_ts = 279.151886
current_seq = 617
count = 110
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.135529/616, current 279.152191/617: elapsed=16655.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.152191
last_received_ts = 279.151886
last_seq = 617
current_ts = 279.168854
current_received_ts = 279.168549
current_seq = 618
count = 111
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.152191/617, current 279.168854/618: elapsed=16671.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.168854
last_received_ts = 279.168549
last_seq = 618
current_ts = 279.185516
current_received_ts = 279.185150
current_seq = 619
count = 112
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.168854/618, current 279.185516/619: elapsed=16666.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.185516
last_received_ts = 279.185150
last_seq = 619
current_ts = 279.202179
current_received_ts = 279.201874
current_seq = 620
count = 113
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.185516/619, current 279.202179/620: elapsed=16667.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.202179
last_received_ts = 279.201874
last_seq = 620
current_ts = 279.218842
current_received_ts = 279.218506
current_seq = 621
count = 114
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.202179/620, current 279.218842/621: elapsed=16668.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.218842
last_received_ts = 279.218506
last_seq = 621
current_ts = 279.235504
current_received_ts = 279.235168
current_seq = 622
count = 115
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.218842/621, current 279.235504/622: elapsed=16663.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.235504
last_received_ts = 279.235168
last_seq = 622
current_ts = 279.252197
current_received_ts = 279.251892
current_seq = 623
count = 116
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.235504/622, current 279.252197/623: elapsed=16680.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.252197
last_received_ts = 279.251892
last_seq = 623
current_ts = 279.268860
current_received_ts = 279.268402
current_seq = 624
count = 117
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.252197/623, current 279.268860/624: elapsed=16659.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.268860
last_received_ts = 279.268402
last_seq = 624
current_ts = 279.285522
current_received_ts = 279.285156
current_seq = 625
count = 118
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.268860/624, current 279.285522/625: elapsed=16674.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.285522
last_received_ts = 279.285156
last_seq = 625
current_ts = 279.302185
current_received_ts = 279.301910
current_seq = 626
count = 119
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.285522/625, current 279.302185/626: elapsed=16658.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.302185
last_received_ts = 279.301910
last_seq = 626
current_ts = 279.318848
current_received_ts = 279.318420
current_seq = 627
count = 120
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.302185/626, current 279.318848/627: elapsed=16669.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.318848
last_received_ts = 279.318420
last_seq = 627
current_ts = 279.335541
current_received_ts = 279.335144
current_seq = 628
count = 121
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.318848/627, current 279.335541/628: elapsed=16672.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.335541
last_received_ts = 279.335144
last_seq = 628
current_ts = 279.352173
current_received_ts = 279.351898
current_seq = 629
count = 122
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.335541/628, current 279.352173/629: elapsed=16660.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.352173
last_received_ts = 279.351898
last_seq = 629
current_ts = 279.368866
current_received_ts = 279.368530
current_seq = 630
count = 123
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.352173/629, current 279.368866/630: elapsed=16678.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.368866
last_received_ts = 279.368530
last_seq = 630
current_ts = 279.385529
current_received_ts = 279.385162
current_seq = 631
count = 124
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.368866/630, current 279.385529/631: elapsed=16663.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.385529
last_received_ts = 279.385162
last_seq = 631
current_ts = 279.402191
current_received_ts = 279.401825
current_seq = 632
count = 125
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.385529/631, current 279.402191/632: elapsed=16667.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.402191
last_received_ts = 279.401825
last_seq = 632
current_ts = 279.418854
current_received_ts = 279.418518
current_seq = 633
count = 126
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.402191/632, current 279.418854/633: elapsed=16664.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.418854
last_received_ts = 279.418518
last_seq = 633
current_ts = 279.435547
current_received_ts = 279.435272
current_seq = 634
count = 127
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.418854/633, current 279.435547/634: elapsed=16673.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.435547
last_received_ts = 279.435272
last_seq = 634
current_ts = 279.452179
current_received_ts = 279.451904
current_seq = 635
count = 128
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.435547/634, current 279.452179/635: elapsed=16661.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.452179
last_received_ts = 279.451904
last_seq = 635
current_ts = 279.468872
current_received_ts = 279.468445
current_seq = 636
count = 129
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.452179/635, current 279.468872/636: elapsed=16668.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.468872
last_received_ts = 279.468445
last_seq = 636
current_ts = 279.485535
current_received_ts = 279.485168
current_seq = 637
count = 130
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.468872/636, current 279.485535/637: elapsed=16663.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.485535
last_received_ts = 279.485168
last_seq = 637
current_ts = 279.502197
current_received_ts = 279.501801
current_seq = 638
count = 131
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.485535/637, current 279.502197/638: elapsed=16678.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.502197
last_received_ts = 279.501801
last_seq = 638
current_ts = 279.518860
current_received_ts = 279.518433
current_seq = 639
count = 132
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.502197/638, current 279.518860/639: elapsed=16660.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.518860
last_received_ts = 279.518433
last_seq = 639
current_ts = 279.535522
current_received_ts = 279.535095
current_seq = 640
count = 133
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.518860/639, current 279.535522/640: elapsed=16665.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.535522
last_received_ts = 279.535095
last_seq = 640
current_ts = 279.552216
current_received_ts = 279.551941
current_seq = 641
count = 134
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.535522/640, current 279.552216/641: elapsed=16678.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.552216
last_received_ts = 279.551941
last_seq = 641
current_ts = 279.568878
current_received_ts = 279.568298
current_seq = 642
count = 135
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.552216/641, current 279.568878/642: elapsed=16667.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.568878
last_received_ts = 279.568298
last_seq = 642
current_ts = 279.585510
current_received_ts = 279.584961
current_seq = 643
count = 136
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.568878/642, current 279.585510/643: elapsed=16653.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.585510
last_received_ts = 279.584961
last_seq = 643
current_ts = 279.602203
current_received_ts = 279.601624
current_seq = 644
count = 137
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.585510/643, current 279.602203/644: elapsed=16681.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.602203
last_received_ts = 279.601624
last_seq = 644
current_ts = 279.618866
current_received_ts = 279.618347
current_seq = 645
count = 138
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.602203/644, current 279.618866/645: elapsed=16666.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.618866
last_received_ts = 279.618347
last_seq = 645
current_ts = 279.635529
current_received_ts = 279.635071
current_seq = 646
count = 139
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.618866/645, current 279.635529/646: elapsed=16666.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.635529
last_received_ts = 279.635071
last_seq = 646
current_ts = 279.652191
current_received_ts = 279.651764
current_seq = 647
count = 140
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.635529/646, current 279.652191/647: elapsed=16668.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.652191
last_received_ts = 279.651764
last_seq = 647
current_ts = 279.668854
current_received_ts = 279.668304
current_seq = 648
count = 141
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.652191/647, current 279.668854/648: elapsed=16655.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.668854
last_received_ts = 279.668304
last_seq = 648
current_ts = 279.685547
current_received_ts = 279.685089
current_seq = 649
count = 142
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.668854/648, current 279.685547/649: elapsed=16675.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.685547
last_received_ts = 279.685089
last_seq = 649
current_ts = 279.702209
current_received_ts = 279.701660
current_seq = 650
count = 143
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.685547/649, current 279.702209/650: elapsed=16662.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.702209
last_received_ts = 279.701660
last_seq = 650
current_ts = 279.718872
current_received_ts = 279.718414
current_seq = 651
count = 144
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.702209/650, current 279.718872/651: elapsed=16668.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.718872
last_received_ts = 279.718414
last_seq = 651
current_ts = 279.735535
current_received_ts = 279.735107
current_seq = 652
count = 145
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.718872/651, current 279.735535/652: elapsed=16668.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.735535
last_received_ts = 279.735107
last_seq = 652
current_ts = 279.752197
current_received_ts = 279.751770
current_seq = 653
count = 146
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.735535/652, current 279.752197/653: elapsed=16667.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.752197
last_received_ts = 279.751770
last_seq = 653
current_ts = 279.768860
current_received_ts = 279.768433
current_seq = 654
count = 147
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.752197/653, current 279.768860/654: elapsed=16664.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.768860
last_received_ts = 279.768433
last_seq = 654
current_ts = 279.785553
current_received_ts = 279.785034
current_seq = 655
count = 148
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.768860/654, current 279.785553/655: elapsed=16674.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.785553
last_received_ts = 279.785034
last_seq = 655
current_ts = 279.802216
current_received_ts = 279.801666
current_seq = 656
count = 149
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.785553/655, current 279.802216/656: elapsed=16672.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.802216
last_received_ts = 279.801666
last_seq = 656
current_ts = 279.818878
current_received_ts = 279.818298
current_seq = 657
count = 150
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.802216/656, current 279.818878/657: elapsed=16669.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.818878
last_received_ts = 279.818298
last_seq = 657
current_ts = 279.835541
current_received_ts = 279.834991
current_seq = 658
count = 151
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.818878/657, current 279.835541/658: elapsed=16663.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.835541
last_received_ts = 279.834991
last_seq = 658
current_ts = 279.852203
current_received_ts = 279.851654
current_seq = 659
count = 152
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.835541/658, current 279.852203/659: elapsed=16668.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.852203
last_received_ts = 279.851654
last_seq = 659
current_ts = 279.868866
current_received_ts = 279.868317
current_seq = 660
count = 153
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.852203/659, current 279.868866/660: elapsed=16656.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.868866
last_received_ts = 279.868317
last_seq = 660
current_ts = 279.885529
current_received_ts = 279.884979
current_seq = 661
count = 154
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.868866/660, current 279.885529/661: elapsed=16667.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.885529
last_received_ts = 279.884979
last_seq = 661
current_ts = 279.902222
current_received_ts = 279.901642
current_seq = 662
count = 155
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.885529/661, current 279.902222/662: elapsed=16681.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.902222
last_received_ts = 279.901642
last_seq = 662
current_ts = 279.918884
current_received_ts = 279.918457
current_seq = 663
count = 156
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.902222/662, current 279.918884/663: elapsed=16663.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.918884
last_received_ts = 279.918457
last_seq = 663
current_ts = 279.935547
current_received_ts = 279.935089
current_seq = 664
count = 157
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.918884/663, current 279.935547/664: elapsed=16659.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.935547
last_received_ts = 279.935089
last_seq = 664
current_ts = 279.952209
current_received_ts = 279.951691
current_seq = 665
count = 158
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.935547/664, current 279.952209/665: elapsed=16679.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.952209
last_received_ts = 279.951691
last_seq = 665
current_ts = 279.968872
current_received_ts = 279.968323
current_seq = 666
count = 159
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.952209/665, current 279.968872/666: elapsed=16654.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.968872
last_received_ts = 279.968323
last_seq = 666
current_ts = 279.985535
current_received_ts = 279.985107
current_seq = 667
count = 160
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.968872/666, current 279.985535/667: elapsed=16678.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 279.985535
last_received_ts = 279.985107
last_seq = 667
current_ts = 280.002228
current_received_ts = 280.001648
current_seq = 668
count = 161
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 279.985535/667, current 280.002228/668: elapsed=16670.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.002228
last_received_ts = 280.001648
last_seq = 668
current_ts = 280.018890
current_received_ts = 280.018372
current_seq = 669
count = 162
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.002228/668, current 280.018890/669: elapsed=16663.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.018890
last_received_ts = 280.018372
last_seq = 669
current_ts = 280.035553
current_received_ts = 280.035858
current_seq = 670
count = 163
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.018890/669, current 280.035553/670: elapsed=16670.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.035553
last_received_ts = 280.035858
last_seq = 670
current_ts = 280.052216
current_received_ts = 280.051636
current_seq = 671
count = 164
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.035553/670, current 280.052216/671: elapsed=16668.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.052216
last_received_ts = 280.051636
last_seq = 671
current_ts = 280.068878
current_received_ts = 280.068298
current_seq = 672
count = 165
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.052216/671, current 280.068878/672: elapsed=16665.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.068878
last_received_ts = 280.068298
last_seq = 672
current_ts = 280.085541
current_received_ts = 280.085205
current_seq = 673
count = 166
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.068878/672, current 280.085541/673: elapsed=16656.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.085541
last_received_ts = 280.085205
last_seq = 673
current_ts = 280.102203
current_received_ts = 280.101746
current_seq = 674
count = 167
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.085541/673, current 280.102203/674: elapsed=16678.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.102203
last_received_ts = 280.101746
last_seq = 674
current_ts = 280.118896
current_received_ts = 280.118378
current_seq = 675
count = 168
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.102203/674, current 280.118896/675: elapsed=16665.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.118896
last_received_ts = 280.118378
last_seq = 675
current_ts = 280.135559
current_received_ts = 280.135040
current_seq = 676
count = 169
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.118896/675, current 280.135559/676: elapsed=16667.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.135559
last_received_ts = 280.135040
last_seq = 676
current_ts = 280.152222
current_received_ts = 280.151764
current_seq = 677
count = 170
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.135559/676, current 280.152222/677: elapsed=16661.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.152222
last_received_ts = 280.151764
last_seq = 677
current_ts = 280.168884
current_received_ts = 280.168427
current_seq = 678
count = 171
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.152222/677, current 280.168884/678: elapsed=16684.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.168884
last_received_ts = 280.168427
last_seq = 678
current_ts = 280.185577
current_received_ts = 280.185181
current_seq = 679
count = 172
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.168884/678, current 280.185577/679: elapsed=16678.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.185577
last_received_ts = 280.185181
last_seq = 679
current_ts = 280.202240
current_received_ts = 280.201813
current_seq = 680
count = 173
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.185577/679, current 280.202240/680: elapsed=16664.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.202240
last_received_ts = 280.201813
last_seq = 680
current_ts = 280.218933
current_received_ts = 280.218475
current_seq = 681
count = 174
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.202240/680, current 280.218933/681: elapsed=16681.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.218933
last_received_ts = 280.218475
last_seq = 681
current_ts = 280.235596
current_received_ts = 280.235138
current_seq = 682
count = 175
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.218933/681, current 280.235596/682: elapsed=16672.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.235596
last_received_ts = 280.235138
last_seq = 682
current_ts = 280.252258
current_received_ts = 280.251892
current_seq = 683
count = 176
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.235596/682, current 280.252258/683: elapsed=16677.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.252258
last_received_ts = 280.251892
last_seq = 683
current_ts = 280.268951
current_received_ts = 280.268402
current_seq = 684
count = 177
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.252258/683, current 280.268951/684: elapsed=16672.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.268951
last_received_ts = 280.268402
last_seq = 684
current_ts = 280.285614
current_received_ts = 280.285126
current_seq = 685
count = 178
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.268951/684, current 280.285614/685: elapsed=16682.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.285614
last_received_ts = 280.285126
last_seq = 685
current_ts = 280.302307
current_received_ts = 280.302002
current_seq = 686
count = 179
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.285614/685, current 280.302307/686: elapsed=16673.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.302307
last_received_ts = 280.302002
last_seq = 686
current_ts = 280.318970
current_received_ts = 280.318542
current_seq = 687
count = 180
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.302307/686, current 280.318970/687: elapsed=16677.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.318970
last_received_ts = 280.318542
last_seq = 687
current_ts = 280.335663
current_received_ts = 280.336151
current_seq = 688
count = 181
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.318970/687, current 280.335663/688: elapsed=16680.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.335663
last_received_ts = 280.336151
last_seq = 688
current_ts = 280.352325
current_received_ts = 280.351837
current_seq = 689
count = 182
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.335663/688, current 280.352325/689: elapsed=16671.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.352325
last_received_ts = 280.351837
last_seq = 689
current_ts = 280.368988
current_received_ts = 280.368500
current_seq = 690
count = 183
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.352325/689, current 280.368988/690: elapsed=16679.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.368988
last_received_ts = 280.368500
last_seq = 690
current_ts = 280.385681
current_received_ts = 280.385193
current_seq = 691
count = 184
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.368988/690, current 280.385681/691: elapsed=16676.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.385681
last_received_ts = 280.385193
last_seq = 691
current_ts = 280.402344
current_received_ts = 280.401917
current_seq = 692
count = 185
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.385681/691, current 280.402344/692: elapsed=16667.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.402344
last_received_ts = 280.401917
last_seq = 692
current_ts = 280.419006
current_received_ts = 280.418549
current_seq = 693
count = 186
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.402344/692, current 280.419006/693: elapsed=16673.0us expected=16667.2us +- 83.3us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.419006
last_received_ts = 280.418549
last_seq = 693
current_ts = 280.435699
current_received_ts = 280.435181
current_seq = 694
count = 187
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.419006/693, current 280.435699/694: elapsed=16686.0us expected=16667.2us +- 83.3us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 280.435699
last_received_ts = 280.435181
last_seq = 694
current_ts = 280.452820
current_received_ts = 280.452332
current_seq = 695
count = 188
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 280.435699/694, current 280.452820/695: elapsed=17117.0us expected=16667.2us +- 83.3us, error 2.7%
(kms_flip:2316) DEBUG: inconsistent flip ts/seq: last 280.435699/694, current 280.452820/695: elapsed=17117.0us expected=16667.2us
(kms_flip:2316) DEBUG: expected 449, counted 188, encoder type 2
(kms_flip:2316) DEBUG: dropped frames, expected 449, counted 188, encoder type 2
(kms_flip:2316) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2316) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2316) igt_core-INFO: Stack trace:
(kms_flip:2316) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2316) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2316) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2316) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2316) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2316) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2316) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2316) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A3: FAIL (6.811s)
Starting dynamic subtest: C-HDMI-A3
(kms_flip:2316) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2316) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest C-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:2316) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2316) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:2316) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2316) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2316) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=15, pitch=7680)
(kms_flip:2316) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2316) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2316) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2316) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2316) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2316) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2316) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2316) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2316) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2316) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2316) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2316) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2316) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2316) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2316) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2316) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2316) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2316) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2316) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2316) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2316) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2316) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2316) DEBUG: No stale events found
(kms_flip:2316) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2316) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2316) INFO: Expected frametime: 16667us; measured 17036.7us +- 8.031us accuracy 0.14%
(kms_flip:2316) INFO: vblank interval differs from modeline! expected 16666.7us, measured 17037us +- 8.031us, difference 370.0us (46.1 sigma)
(kms_flip:2316) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 284.252380
current_received_ts = 284.251831
current_seq = 209
count = 0
seq_step = 1
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.252380
last_received_ts = 284.251831
last_seq = 209
current_ts = 284.269409
current_received_ts = 284.268890
current_seq = 210
count = 1
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.252380/209, current 284.269409/210: elapsed=17040.0us expected=17036.7us +- 85.2us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.269409
last_received_ts = 284.268890
last_seq = 210
current_ts = 284.286469
current_received_ts = 284.286072
current_seq = 211
count = 2
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.269409/210, current 284.286469/211: elapsed=17030.0us expected=17036.7us +- 85.2us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.286469
last_received_ts = 284.286072
last_seq = 211
current_ts = 284.303497
current_received_ts = 284.303070
current_seq = 212
count = 3
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.286469/211, current 284.303497/212: elapsed=17038.0us expected=17036.7us +- 85.2us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.303497
last_received_ts = 284.303070
last_seq = 212
current_ts = 284.320526
current_received_ts = 284.320099
current_seq = 213
count = 4
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.303497/212, current 284.320526/213: elapsed=17046.0us expected=17036.7us +- 85.2us, error 0.1%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.320526
last_received_ts = 284.320099
last_seq = 213
current_ts = 284.337585
current_received_ts = 284.337128
current_seq = 214
count = 5
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.320526/213, current 284.337585/214: elapsed=17033.0us expected=17036.7us +- 85.2us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.337585
last_received_ts = 284.337128
last_seq = 214
current_ts = 284.354614
current_received_ts = 284.354187
current_seq = 215
count = 6
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.337585/214, current 284.354614/215: elapsed=17035.0us expected=17036.7us +- 85.2us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.354614
last_received_ts = 284.354187
last_seq = 215
current_ts = 284.371643
current_received_ts = 284.371246
current_seq = 216
count = 7
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.354614/215, current 284.371643/216: elapsed=17031.0us expected=17036.7us +- 85.2us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.371643
last_received_ts = 284.371246
last_seq = 216
current_ts = 284.388672
current_received_ts = 284.388336
current_seq = 217
count = 8
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.371643/216, current 284.388672/217: elapsed=17040.0us expected=17036.7us +- 85.2us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.388672
last_received_ts = 284.388336
last_seq = 217
current_ts = 284.405701
current_received_ts = 284.405334
current_seq = 218
count = 9
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.388672/217, current 284.405701/218: elapsed=17036.0us expected=17036.7us +- 85.2us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.405701
last_received_ts = 284.405334
last_seq = 218
current_ts = 284.422760
current_received_ts = 284.422363
current_seq = 219
count = 10
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.405701/218, current 284.422760/219: elapsed=17037.0us expected=17036.7us +- 85.2us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.422760
last_received_ts = 284.422363
last_seq = 219
current_ts = 284.439789
current_received_ts = 284.439453
current_seq = 220
count = 11
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.422760/219, current 284.439789/220: elapsed=17037.0us expected=17036.7us +- 85.2us, error 0.0%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.439789
last_received_ts = 284.439453
last_seq = 220
current_ts = 284.456787
current_received_ts = 284.456482
current_seq = 221
count = 12
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.439789/220, current 284.456787/221: elapsed=16995.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.456787
last_received_ts = 284.456482
last_seq = 221
current_ts = 284.473755
current_received_ts = 284.473358
current_seq = 222
count = 13
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.456787/221, current 284.473755/222: elapsed=16988.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.473755
last_received_ts = 284.473358
last_seq = 222
current_ts = 284.490753
current_received_ts = 284.490356
current_seq = 223
count = 14
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.473755/222, current 284.490753/223: elapsed=16986.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.490753
last_received_ts = 284.490356
last_seq = 223
current_ts = 284.507751
current_received_ts = 284.507355
current_seq = 224
count = 15
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.490753/223, current 284.507751/224: elapsed=16992.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.507751
last_received_ts = 284.507355
last_seq = 224
current_ts = 284.524750
current_received_ts = 284.524323
current_seq = 225
count = 16
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.507751/224, current 284.524750/225: elapsed=16995.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.524750
last_received_ts = 284.524323
last_seq = 225
current_ts = 284.541748
current_received_ts = 284.541321
current_seq = 226
count = 17
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.524750/225, current 284.541748/226: elapsed=16997.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.541748
last_received_ts = 284.541321
last_seq = 226
current_ts = 284.558716
current_received_ts = 284.558350
current_seq = 227
count = 18
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.541748/226, current 284.558716/227: elapsed=16978.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.558716
last_received_ts = 284.558350
last_seq = 227
current_ts = 284.575714
current_received_ts = 284.575317
current_seq = 228
count = 19
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.558716/227, current 284.575714/228: elapsed=16994.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.575714
last_received_ts = 284.575317
last_seq = 228
current_ts = 284.592712
current_received_ts = 284.592346
current_seq = 229
count = 20
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.575714/228, current 284.592712/229: elapsed=17002.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.592712
last_received_ts = 284.592346
last_seq = 229
current_ts = 284.609711
current_received_ts = 284.609344
current_seq = 230
count = 21
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.592712/229, current 284.609711/230: elapsed=16994.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.609711
last_received_ts = 284.609344
last_seq = 230
current_ts = 284.626678
current_received_ts = 284.626312
current_seq = 231
count = 22
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.609711/230, current 284.626678/231: elapsed=16980.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.626678
last_received_ts = 284.626312
last_seq = 231
current_ts = 284.643677
current_received_ts = 284.643311
current_seq = 232
count = 23
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.626678/231, current 284.643677/232: elapsed=16995.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.643677
last_received_ts = 284.643311
last_seq = 232
current_ts = 284.660675
current_received_ts = 284.660309
current_seq = 233
count = 24
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.643677/232, current 284.660675/233: elapsed=16995.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.660675
last_received_ts = 284.660309
last_seq = 233
current_ts = 284.677673
current_received_ts = 284.677338
current_seq = 234
count = 25
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.660675/233, current 284.677673/234: elapsed=16990.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.677673
last_received_ts = 284.677338
last_seq = 234
current_ts = 284.694672
current_received_ts = 284.694458
current_seq = 235
count = 26
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.677673/234, current 284.694672/235: elapsed=16999.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.694672
last_received_ts = 284.694458
last_seq = 235
current_ts = 284.711670
current_received_ts = 284.711243
current_seq = 236
count = 27
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.694672/235, current 284.711670/236: elapsed=16990.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.711670
last_received_ts = 284.711243
last_seq = 236
current_ts = 284.728638
current_received_ts = 284.728302
current_seq = 237
count = 28
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.711670/236, current 284.728638/237: elapsed=16982.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.728638
last_received_ts = 284.728302
last_seq = 237
current_ts = 284.745636
current_received_ts = 284.745300
current_seq = 238
count = 29
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.728638/237, current 284.745636/238: elapsed=16991.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.745636
last_received_ts = 284.745300
last_seq = 238
current_ts = 284.762604
current_received_ts = 284.762207
current_seq = 239
count = 30
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.745636/238, current 284.762604/239: elapsed=16988.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.762604
last_received_ts = 284.762207
last_seq = 239
current_ts = 284.779633
current_received_ts = 284.779175
current_seq = 240
count = 31
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.762604/239, current 284.779633/240: elapsed=17000.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.779633
last_received_ts = 284.779175
last_seq = 240
current_ts = 284.796600
current_received_ts = 284.796234
current_seq = 241
count = 32
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.779633/240, current 284.796600/241: elapsed=16984.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.796600
last_received_ts = 284.796234
last_seq = 241
current_ts = 284.813599
current_received_ts = 284.813354
current_seq = 242
count = 33
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.796600/241, current 284.813599/242: elapsed=17006.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.813599
last_received_ts = 284.813354
last_seq = 242
current_ts = 284.830597
current_received_ts = 284.830200
current_seq = 243
count = 34
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.813599/242, current 284.830597/243: elapsed=16985.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.830597
last_received_ts = 284.830200
last_seq = 243
current_ts = 284.847565
current_received_ts = 284.847198
current_seq = 244
count = 35
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.830597/243, current 284.847565/244: elapsed=16983.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.847565
last_received_ts = 284.847198
last_seq = 244
current_ts = 284.864563
current_received_ts = 284.864166
current_seq = 245
count = 36
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.847565/244, current 284.864563/245: elapsed=16995.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.864563
last_received_ts = 284.864166
last_seq = 245
current_ts = 284.881561
current_received_ts = 284.881348
current_seq = 246
count = 37
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.864563/245, current 284.881561/246: elapsed=17005.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.881561
last_received_ts = 284.881348
last_seq = 246
current_ts = 284.898560
current_received_ts = 284.898315
current_seq = 247
count = 38
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.881561/246, current 284.898560/247: elapsed=16978.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.898560
last_received_ts = 284.898315
last_seq = 247
current_ts = 284.915558
current_received_ts = 284.915161
current_seq = 248
count = 39
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.898560/247, current 284.915558/248: elapsed=16998.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.915558
last_received_ts = 284.915161
last_seq = 248
current_ts = 284.932556
current_received_ts = 284.932281
current_seq = 249
count = 40
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.915558/248, current 284.932556/249: elapsed=16996.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.932556
last_received_ts = 284.932281
last_seq = 249
current_ts = 284.949524
current_received_ts = 284.949127
current_seq = 250
count = 41
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.932556/249, current 284.949524/250: elapsed=16981.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.949524
last_received_ts = 284.949127
last_seq = 250
current_ts = 284.966522
current_received_ts = 284.966248
current_seq = 251
count = 42
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.949524/250, current 284.966522/251: elapsed=16995.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.966522
last_received_ts = 284.966248
last_seq = 251
current_ts = 284.983521
current_received_ts = 284.983154
current_seq = 252
count = 43
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.966522/251, current 284.983521/252: elapsed=16992.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 284.983521
last_received_ts = 284.983154
last_seq = 252
current_ts = 285.000488
current_received_ts = 285.000153
current_seq = 253
count = 44
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 284.983521/252, current 285.000488/253: elapsed=16987.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.000488
last_received_ts = 285.000153
last_seq = 253
current_ts = 285.017517
current_received_ts = 285.017212
current_seq = 254
count = 45
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.000488/253, current 285.017517/254: elapsed=17003.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.017517
last_received_ts = 285.017212
last_seq = 254
current_ts = 285.034485
current_received_ts = 285.034119
current_seq = 255
count = 46
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.017517/254, current 285.034485/255: elapsed=16988.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.034485
last_received_ts = 285.034119
last_seq = 255
current_ts = 285.051483
current_received_ts = 285.051208
current_seq = 256
count = 47
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.034485/255, current 285.051483/256: elapsed=16996.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.051483
last_received_ts = 285.051208
last_seq = 256
current_ts = 285.068481
current_received_ts = 285.068115
current_seq = 257
count = 48
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.051483/256, current 285.068481/257: elapsed=16981.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.068481
last_received_ts = 285.068115
last_seq = 257
current_ts = 285.085449
current_received_ts = 285.085114
current_seq = 258
count = 49
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.068481/257, current 285.085449/258: elapsed=16992.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.085449
last_received_ts = 285.085114
last_seq = 258
current_ts = 285.102448
current_received_ts = 285.102112
current_seq = 259
count = 50
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.085449/258, current 285.102448/259: elapsed=16992.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.102448
last_received_ts = 285.102112
last_seq = 259
current_ts = 285.119446
current_received_ts = 285.119080
current_seq = 260
count = 51
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.102448/259, current 285.119446/260: elapsed=16997.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.119446
last_received_ts = 285.119080
last_seq = 260
current_ts = 285.136444
current_received_ts = 285.136108
current_seq = 261
count = 52
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.119446/260, current 285.136444/261: elapsed=16984.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.136444
last_received_ts = 285.136108
last_seq = 261
current_ts = 285.153442
current_received_ts = 285.153107
current_seq = 262
count = 53
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.136444/261, current 285.153442/262: elapsed=16993.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.153442
last_received_ts = 285.153107
last_seq = 262
current_ts = 285.170441
current_received_ts = 285.170074
current_seq = 263
count = 54
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.153442/262, current 285.170441/263: elapsed=16999.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.170441
last_received_ts = 285.170074
last_seq = 263
current_ts = 285.187408
current_received_ts = 285.187103
current_seq = 264
count = 55
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.170441/263, current 285.187408/264: elapsed=16983.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.187408
last_received_ts = 285.187103
last_seq = 264
current_ts = 285.204407
current_received_ts = 285.204163
current_seq = 265
count = 56
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.187408/264, current 285.204407/265: elapsed=17002.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.204407
last_received_ts = 285.204163
last_seq = 265
current_ts = 285.221405
current_received_ts = 285.221039
current_seq = 266
count = 57
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.204407/265, current 285.221405/266: elapsed=16989.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.221405
last_received_ts = 285.221039
last_seq = 266
current_ts = 285.238403
current_received_ts = 285.238068
current_seq = 267
count = 58
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.221405/266, current 285.238403/267: elapsed=16988.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.238403
last_received_ts = 285.238068
last_seq = 267
current_ts = 285.255371
current_received_ts = 285.255066
current_seq = 268
count = 59
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.238403/267, current 285.255371/268: elapsed=16987.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.255371
last_received_ts = 285.255066
last_seq = 268
current_ts = 285.272369
current_received_ts = 285.272125
current_seq = 269
count = 60
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.255371/268, current 285.272369/269: elapsed=17005.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.272369
last_received_ts = 285.272125
last_seq = 269
current_ts = 285.289368
current_received_ts = 285.289001
current_seq = 270
count = 61
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.272369/269, current 285.289368/270: elapsed=16982.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.289368
last_received_ts = 285.289001
last_seq = 270
current_ts = 285.306366
current_received_ts = 285.305969
current_seq = 271
count = 62
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.289368/270, current 285.306366/271: elapsed=16988.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.306366
last_received_ts = 285.305969
last_seq = 271
current_ts = 285.323364
current_received_ts = 285.322937
current_seq = 272
count = 63
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.306366/271, current 285.323364/272: elapsed=17000.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.323364
last_received_ts = 285.322937
last_seq = 272
current_ts = 285.340332
current_received_ts = 285.339966
current_seq = 273
count = 64
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.323364/272, current 285.340332/273: elapsed=16982.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.340332
last_received_ts = 285.339966
last_seq = 273
current_ts = 285.357330
current_received_ts = 285.357117
current_seq = 274
count = 65
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.340332/273, current 285.357330/274: elapsed=16993.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.357330
last_received_ts = 285.357117
last_seq = 274
current_ts = 285.374329
current_received_ts = 285.373932
current_seq = 275
count = 66
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.357330/274, current 285.374329/275: elapsed=17001.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.374329
last_received_ts = 285.373932
last_seq = 275
current_ts = 285.391327
current_received_ts = 285.390961
current_seq = 276
count = 67
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.374329/275, current 285.391327/276: elapsed=16986.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.391327
last_received_ts = 285.390961
last_seq = 276
current_ts = 285.408295
current_received_ts = 285.407928
current_seq = 277
count = 68
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.391327/276, current 285.408295/277: elapsed=16987.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.408295
last_received_ts = 285.407928
last_seq = 277
current_ts = 285.425293
current_received_ts = 285.424896
current_seq = 278
count = 69
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.408295/277, current 285.425293/278: elapsed=17001.0us expected=17036.7us +- 85.2us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.425293
last_received_ts = 285.424896
last_seq = 278
current_ts = 285.442291
current_received_ts = 285.441925
current_seq = 279
count = 70
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.425293/278, current 285.442291/279: elapsed=16978.0us expected=17036.7us +- 85.2us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 285.442291
last_received_ts = 285.441925
last_seq = 279
current_ts = 285.459229
current_received_ts = 285.458954
current_seq = 280
count = 71
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 285.442291/279, current 285.459229/280: elapsed=16947.0us expected=17036.7us +- 85.2us, error 0.5%
(kms_flip:2316) DEBUG: inconsistent flip ts/seq: last 285.442291/279, current 285.459229/280: elapsed=16947.0us expected=17036.7us
(kms_flip:2316) DEBUG: expected 440, counted 71, encoder type 2
(kms_flip:2316) DEBUG: dropped frames, expected 440, counted 71, encoder type 2
(kms_flip:2316) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2316) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2316) igt_core-INFO: Stack trace:
(kms_flip:2316) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2316) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2316) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2316) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2316) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2316) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2316) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2316) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-HDMI-A3: FAIL (4.652s)
Starting dynamic subtest: D-HDMI-A3
(kms_flip:2316) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2316) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest D-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:2316) DEBUG: flip ts/seq: last 290.438629/826, current 290.455444/827: elapsed=16811.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.455444
last_received_ts = 290.455078
last_seq = 827
current_ts = 290.472260
current_received_ts = 290.471832
current_seq = 828
count = 90
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.455444/827, current 290.472260/828: elapsed=16820.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.472260
last_received_ts = 290.471832
last_seq = 828
current_ts = 290.489075
current_received_ts = 290.488586
current_seq = 829
count = 91
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.472260/828, current 290.489075/829: elapsed=16816.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.489075
last_received_ts = 290.488586
last_seq = 829
current_ts = 290.505890
current_received_ts = 290.505554
current_seq = 830
count = 92
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.489075/829, current 290.505890/830: elapsed=16815.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.505890
last_received_ts = 290.505554
last_seq = 830
current_ts = 290.522705
current_received_ts = 290.522278
current_seq = 831
count = 93
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.505890/830, current 290.522705/831: elapsed=16824.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.522705
last_received_ts = 290.522278
last_seq = 831
current_ts = 290.539520
current_received_ts = 290.539215
current_seq = 832
count = 94
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.522705/831, current 290.539520/832: elapsed=16813.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.539520
last_received_ts = 290.539215
last_seq = 832
current_ts = 290.556335
current_received_ts = 290.555939
current_seq = 833
count = 95
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.539520/832, current 290.556335/833: elapsed=16815.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.556335
last_received_ts = 290.555939
last_seq = 833
current_ts = 290.573151
current_received_ts = 290.572754
current_seq = 834
count = 96
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.556335/833, current 290.573151/834: elapsed=16811.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.573151
last_received_ts = 290.572754
last_seq = 834
current_ts = 290.589966
current_received_ts = 290.589508
current_seq = 835
count = 97
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.573151/834, current 290.589966/835: elapsed=16820.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.589966
last_received_ts = 290.589508
last_seq = 835
current_ts = 290.606781
current_received_ts = 290.606415
current_seq = 836
count = 98
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.589966/835, current 290.606781/836: elapsed=16824.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.606781
last_received_ts = 290.606415
last_seq = 836
current_ts = 290.623596
current_received_ts = 290.623230
current_seq = 837
count = 99
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.606781/836, current 290.623596/837: elapsed=16812.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.623596
last_received_ts = 290.623230
last_seq = 837
current_ts = 290.640411
current_received_ts = 290.639984
current_seq = 838
count = 100
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.623596/837, current 290.640411/838: elapsed=16813.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.640411
last_received_ts = 290.639984
last_seq = 838
current_ts = 290.657257
current_received_ts = 290.656921
current_seq = 839
count = 101
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.640411/838, current 290.657257/839: elapsed=16828.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.657257
last_received_ts = 290.656921
last_seq = 839
current_ts = 290.674042
current_received_ts = 290.673645
current_seq = 840
count = 102
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.657257/839, current 290.674042/840: elapsed=16807.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.674042
last_received_ts = 290.673645
last_seq = 840
current_ts = 290.690857
current_received_ts = 290.690399
current_seq = 841
count = 103
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.674042/840, current 290.690857/841: elapsed=16821.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.690857
last_received_ts = 290.690399
last_seq = 841
current_ts = 290.707703
current_received_ts = 290.707245
current_seq = 842
count = 104
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.690857/841, current 290.707703/842: elapsed=16818.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.707703
last_received_ts = 290.707245
last_seq = 842
current_ts = 290.724518
current_received_ts = 290.724243
current_seq = 843
count = 105
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.707703/842, current 290.724518/843: elapsed=16825.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.724518
last_received_ts = 290.724243
last_seq = 843
current_ts = 290.741333
current_received_ts = 290.740906
current_seq = 844
count = 106
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.724518/843, current 290.741333/844: elapsed=16816.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.741333
last_received_ts = 290.740906
last_seq = 844
current_ts = 290.758148
current_received_ts = 290.757721
current_seq = 845
count = 107
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.741333/844, current 290.758148/845: elapsed=16809.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.758148
last_received_ts = 290.757721
last_seq = 845
current_ts = 290.774963
current_received_ts = 290.774567
current_seq = 846
count = 108
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.758148/845, current 290.774963/846: elapsed=16817.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.774963
last_received_ts = 290.774567
last_seq = 846
current_ts = 290.791779
current_received_ts = 290.791382
current_seq = 847
count = 109
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.774963/846, current 290.791779/847: elapsed=16823.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.791779
last_received_ts = 290.791382
last_seq = 847
current_ts = 290.808594
current_received_ts = 290.808319
current_seq = 848
count = 110
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.791779/847, current 290.808594/848: elapsed=16811.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.808594
last_received_ts = 290.808319
last_seq = 848
current_ts = 290.825409
current_received_ts = 290.825073
current_seq = 849
count = 111
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.808594/848, current 290.825409/849: elapsed=16816.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.825409
last_received_ts = 290.825073
last_seq = 849
current_ts = 290.842224
current_received_ts = 290.841919
current_seq = 850
count = 112
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.825409/849, current 290.842224/850: elapsed=16827.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.842224
last_received_ts = 290.841919
last_seq = 850
current_ts = 290.859039
current_received_ts = 290.858643
current_seq = 851
count = 113
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.842224/850, current 290.859039/851: elapsed=16815.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.859039
last_received_ts = 290.858643
last_seq = 851
current_ts = 290.875854
current_received_ts = 290.875427
current_seq = 852
count = 114
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.859039/851, current 290.875854/852: elapsed=16816.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.875854
last_received_ts = 290.875427
last_seq = 852
current_ts = 290.892670
current_received_ts = 290.892395
current_seq = 853
count = 115
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.875854/852, current 290.892670/853: elapsed=16815.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.892670
last_received_ts = 290.892395
last_seq = 853
current_ts = 290.909485
current_received_ts = 290.909210
current_seq = 854
count = 116
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.892670/853, current 290.909485/854: elapsed=16817.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.909485
last_received_ts = 290.909210
last_seq = 854
current_ts = 290.926331
current_received_ts = 290.926056
current_seq = 855
count = 117
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.909485/854, current 290.926331/855: elapsed=16825.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.926331
last_received_ts = 290.926056
last_seq = 855
current_ts = 290.943146
current_received_ts = 290.942780
current_seq = 856
count = 118
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.926331/855, current 290.943146/856: elapsed=16810.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.943146
last_received_ts = 290.942780
last_seq = 856
current_ts = 290.959930
current_received_ts = 290.959503
current_seq = 857
count = 119
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.943146/856, current 290.959930/857: elapsed=16812.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.959930
last_received_ts = 290.959503
last_seq = 857
current_ts = 290.976776
current_received_ts = 290.976288
current_seq = 858
count = 120
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.959930/857, current 290.976776/858: elapsed=16822.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.976776
last_received_ts = 290.976288
last_seq = 858
current_ts = 290.993591
current_received_ts = 290.993164
current_seq = 859
count = 121
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.976776/858, current 290.993591/859: elapsed=16825.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 290.993591
last_received_ts = 290.993164
last_seq = 859
current_ts = 291.010406
current_received_ts = 291.010132
current_seq = 860
count = 122
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 290.993591/859, current 291.010406/860: elapsed=16817.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.010406
last_received_ts = 291.010132
last_seq = 860
current_ts = 291.027222
current_received_ts = 291.026825
current_seq = 861
count = 123
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.010406/860, current 291.027222/861: elapsed=16812.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.027222
last_received_ts = 291.026825
last_seq = 861
current_ts = 291.044037
current_received_ts = 291.043579
current_seq = 862
count = 124
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.027222/861, current 291.044037/862: elapsed=16818.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.044037
last_received_ts = 291.043579
last_seq = 862
current_ts = 291.060852
current_received_ts = 291.060394
current_seq = 863
count = 125
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.044037/862, current 291.060852/863: elapsed=16819.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.060852
last_received_ts = 291.060394
last_seq = 863
current_ts = 291.077667
current_received_ts = 291.077240
current_seq = 864
count = 126
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.060852/863, current 291.077667/864: elapsed=16817.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.077667
last_received_ts = 291.077240
last_seq = 864
current_ts = 291.094482
current_received_ts = 291.094086
current_seq = 865
count = 127
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.077667/864, current 291.094482/865: elapsed=16817.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.094482
last_received_ts = 291.094086
last_seq = 865
current_ts = 291.111298
current_received_ts = 291.110931
current_seq = 866
count = 128
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.094482/865, current 291.111298/866: elapsed=16814.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.111298
last_received_ts = 291.110931
last_seq = 866
current_ts = 291.128113
current_received_ts = 291.127716
current_seq = 867
count = 129
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.111298/866, current 291.128113/867: elapsed=16818.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.128113
last_received_ts = 291.127716
last_seq = 867
current_ts = 291.144928
current_received_ts = 291.144501
current_seq = 868
count = 130
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.128113/867, current 291.144928/868: elapsed=16815.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.144928
last_received_ts = 291.144501
last_seq = 868
current_ts = 291.161774
current_received_ts = 291.161407
current_seq = 869
count = 131
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.144928/868, current 291.161774/869: elapsed=16824.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.161774
last_received_ts = 291.161407
last_seq = 869
current_ts = 291.178589
current_received_ts = 291.178162
current_seq = 870
count = 132
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.161774/869, current 291.178589/870: elapsed=16822.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.178589
last_received_ts = 291.178162
last_seq = 870
current_ts = 291.195404
current_received_ts = 291.194946
current_seq = 871
count = 133
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.178589/870, current 291.195404/871: elapsed=16812.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.195404
last_received_ts = 291.194946
last_seq = 871
current_ts = 291.212219
current_received_ts = 291.211792
current_seq = 872
count = 134
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.195404/871, current 291.212219/872: elapsed=16810.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.212219
last_received_ts = 291.211792
last_seq = 872
current_ts = 291.229034
current_received_ts = 291.228607
current_seq = 873
count = 135
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.212219/872, current 291.229034/873: elapsed=16816.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.229034
last_received_ts = 291.228607
last_seq = 873
current_ts = 291.245850
current_received_ts = 291.245392
current_seq = 874
count = 136
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.229034/873, current 291.245850/874: elapsed=16827.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.245850
last_received_ts = 291.245392
last_seq = 874
current_ts = 291.262665
current_received_ts = 291.262268
current_seq = 875
count = 137
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.245850/874, current 291.262665/875: elapsed=16817.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.262665
last_received_ts = 291.262268
last_seq = 875
current_ts = 291.279480
current_received_ts = 291.279083
current_seq = 876
count = 138
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.262665/875, current 291.279480/876: elapsed=16819.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.279480
last_received_ts = 291.279083
last_seq = 876
current_ts = 291.296295
current_received_ts = 291.295837
current_seq = 877
count = 139
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.279480/876, current 291.296295/877: elapsed=16812.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.296295
last_received_ts = 291.295837
last_seq = 877
current_ts = 291.313110
current_received_ts = 291.312714
current_seq = 878
count = 140
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.296295/877, current 291.313110/878: elapsed=16815.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.313110
last_received_ts = 291.312714
last_seq = 878
current_ts = 291.329926
current_received_ts = 291.329468
current_seq = 879
count = 141
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.313110/878, current 291.329926/879: elapsed=16826.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.329926
last_received_ts = 291.329468
last_seq = 879
current_ts = 291.346741
current_received_ts = 291.346283
current_seq = 880
count = 142
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.329926/879, current 291.346741/880: elapsed=16808.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.346741
last_received_ts = 291.346283
last_seq = 880
current_ts = 291.363556
current_received_ts = 291.363159
current_seq = 881
count = 143
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.346741/880, current 291.363556/881: elapsed=16814.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.363556
last_received_ts = 291.363159
last_seq = 881
current_ts = 291.380402
current_received_ts = 291.380096
current_seq = 882
count = 144
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.363556/881, current 291.380402/882: elapsed=16832.0us expected=16861.1us +- 84.3us, error 0.2%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.380402
last_received_ts = 291.380096
last_seq = 882
current_ts = 291.397217
current_received_ts = 291.396759
current_seq = 883
count = 145
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.380402/882, current 291.397217/883: elapsed=16810.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.397217
last_received_ts = 291.396759
last_seq = 883
current_ts = 291.414032
current_received_ts = 291.413605
current_seq = 884
count = 146
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.397217/883, current 291.414032/884: elapsed=16815.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.414032
last_received_ts = 291.413605
last_seq = 884
current_ts = 291.430847
current_received_ts = 291.430359
current_seq = 885
count = 147
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.414032/884, current 291.430847/885: elapsed=16818.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.430847
last_received_ts = 291.430359
last_seq = 885
current_ts = 291.447662
current_received_ts = 291.447205
current_seq = 886
count = 148
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.430847/885, current 291.447662/886: elapsed=16814.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.447662
last_received_ts = 291.447205
last_seq = 886
current_ts = 291.464447
current_received_ts = 291.464142
current_seq = 887
count = 149
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.447662/886, current 291.464447/887: elapsed=16796.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.464447
last_received_ts = 291.464142
last_seq = 887
current_ts = 291.481232
current_received_ts = 291.480865
current_seq = 888
count = 150
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.464447/887, current 291.481232/888: elapsed=16798.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.481232
last_received_ts = 291.480865
last_seq = 888
current_ts = 291.498047
current_received_ts = 291.497589
current_seq = 889
count = 151
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.481232/888, current 291.498047/889: elapsed=16801.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.498047
last_received_ts = 291.497589
last_seq = 889
current_ts = 291.514862
current_received_ts = 291.514404
current_seq = 890
count = 152
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.498047/889, current 291.514862/890: elapsed=16803.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.514862
last_received_ts = 291.514404
last_seq = 890
current_ts = 291.531647
current_received_ts = 291.531250
current_seq = 891
count = 153
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.514862/890, current 291.531647/891: elapsed=16799.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.531647
last_received_ts = 291.531250
last_seq = 891
current_ts = 291.548431
current_received_ts = 291.548126
current_seq = 892
count = 154
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.531647/891, current 291.548431/892: elapsed=16796.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.548431
last_received_ts = 291.548126
last_seq = 892
current_ts = 291.565247
current_received_ts = 291.564941
current_seq = 893
count = 155
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.548431/892, current 291.565247/893: elapsed=16805.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.565247
last_received_ts = 291.564941
last_seq = 893
current_ts = 291.582031
current_received_ts = 291.581696
current_seq = 894
count = 156
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.565247/893, current 291.582031/894: elapsed=16797.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.582031
last_received_ts = 291.581696
last_seq = 894
current_ts = 291.598846
current_received_ts = 291.598389
current_seq = 895
count = 157
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.582031/894, current 291.598846/895: elapsed=16796.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.598846
last_received_ts = 291.598389
last_seq = 895
current_ts = 291.615631
current_received_ts = 291.615356
current_seq = 896
count = 158
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.598846/895, current 291.615631/896: elapsed=16802.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.615631
last_received_ts = 291.615356
last_seq = 896
current_ts = 291.632446
current_received_ts = 291.632050
current_seq = 897
count = 159
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.615631/896, current 291.632446/897: elapsed=16793.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.632446
last_received_ts = 291.632050
last_seq = 897
current_ts = 291.649231
current_received_ts = 291.648804
current_seq = 898
count = 160
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.632446/897, current 291.649231/898: elapsed=16807.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.649231
last_received_ts = 291.648804
last_seq = 898
current_ts = 291.666046
current_received_ts = 291.665649
current_seq = 899
count = 161
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.649231/898, current 291.666046/899: elapsed=16790.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.666046
last_received_ts = 291.665649
last_seq = 899
current_ts = 291.682831
current_received_ts = 291.682404
current_seq = 900
count = 162
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.666046/899, current 291.682831/900: elapsed=16801.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.682831
last_received_ts = 291.682404
last_seq = 900
current_ts = 291.699646
current_received_ts = 291.699341
current_seq = 901
count = 163
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.682831/900, current 291.699646/901: elapsed=16807.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.699646
last_received_ts = 291.699341
last_seq = 901
current_ts = 291.716431
current_received_ts = 291.716064
current_seq = 902
count = 164
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.699646/901, current 291.716431/902: elapsed=16791.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.716431
last_received_ts = 291.716064
last_seq = 902
current_ts = 291.733246
current_received_ts = 291.732849
current_seq = 903
count = 165
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.716431/902, current 291.733246/903: elapsed=16802.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.733246
last_received_ts = 291.732849
last_seq = 903
current_ts = 291.750031
current_received_ts = 291.749634
current_seq = 904
count = 166
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.733246/903, current 291.750031/904: elapsed=16801.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.750031
last_received_ts = 291.749634
last_seq = 904
current_ts = 291.766846
current_received_ts = 291.766388
current_seq = 905
count = 167
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.750031/904, current 291.766846/905: elapsed=16799.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.766846
last_received_ts = 291.766388
last_seq = 905
current_ts = 291.783630
current_received_ts = 291.783234
current_seq = 906
count = 168
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.766846/905, current 291.783630/906: elapsed=16805.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.783630
last_received_ts = 291.783234
last_seq = 906
current_ts = 291.800446
current_received_ts = 291.800140
current_seq = 907
count = 169
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.783630/906, current 291.800446/907: elapsed=16798.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.800446
last_received_ts = 291.800140
last_seq = 907
current_ts = 291.817230
current_received_ts = 291.816833
current_seq = 908
count = 170
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.800446/907, current 291.817230/908: elapsed=16795.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.817230
last_received_ts = 291.816833
last_seq = 908
current_ts = 291.834045
current_received_ts = 291.833588
current_seq = 909
count = 171
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.817230/908, current 291.834045/909: elapsed=16801.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.834045
last_received_ts = 291.833588
last_seq = 909
current_ts = 291.850830
current_received_ts = 291.850403
current_seq = 910
count = 172
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.834045/909, current 291.850830/910: elapsed=16797.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.850830
last_received_ts = 291.850403
last_seq = 910
current_ts = 291.867645
current_received_ts = 291.867371
current_seq = 911
count = 173
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.850830/910, current 291.867645/911: elapsed=16807.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.867645
last_received_ts = 291.867371
last_seq = 911
current_ts = 291.884430
current_received_ts = 291.884033
current_seq = 912
count = 174
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.867645/911, current 291.884430/912: elapsed=16789.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.884430
last_received_ts = 291.884033
last_seq = 912
current_ts = 291.901215
current_received_ts = 291.900940
current_seq = 913
count = 175
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.884430/912, current 291.901215/913: elapsed=16802.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.901215
last_received_ts = 291.900940
last_seq = 913
current_ts = 291.918030
current_received_ts = 291.917633
current_seq = 914
count = 176
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.901215/913, current 291.918030/914: elapsed=16799.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.918030
last_received_ts = 291.917633
last_seq = 914
current_ts = 291.934845
current_received_ts = 291.934387
current_seq = 915
count = 177
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.918030/914, current 291.934845/915: elapsed=16808.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.934845
last_received_ts = 291.934387
last_seq = 915
current_ts = 291.951630
current_received_ts = 291.951233
current_seq = 916
count = 178
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.934845/915, current 291.951630/916: elapsed=16798.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.951630
last_received_ts = 291.951233
last_seq = 916
current_ts = 291.968445
current_received_ts = 291.968170
current_seq = 917
count = 179
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.951630/916, current 291.968445/917: elapsed=16799.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.968445
last_received_ts = 291.968170
last_seq = 917
current_ts = 291.985229
current_received_ts = 291.984802
current_seq = 918
count = 180
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.968445/917, current 291.985229/918: elapsed=16804.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 291.985229
last_received_ts = 291.984802
last_seq = 918
current_ts = 292.002014
current_received_ts = 292.001587
current_seq = 919
count = 181
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 291.985229/918, current 292.002014/919: elapsed=16789.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.002014
last_received_ts = 292.001587
last_seq = 919
current_ts = 292.018829
current_received_ts = 292.018402
current_seq = 920
count = 182
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.002014/919, current 292.018829/920: elapsed=16805.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.018829
last_received_ts = 292.018402
last_seq = 920
current_ts = 292.035614
current_received_ts = 292.035217
current_seq = 921
count = 183
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.018829/920, current 292.035614/921: elapsed=16792.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.035614
last_received_ts = 292.035217
last_seq = 921
current_ts = 292.052429
current_received_ts = 292.052155
current_seq = 922
count = 184
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.035614/921, current 292.052429/922: elapsed=16811.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.052429
last_received_ts = 292.052155
last_seq = 922
current_ts = 292.069214
current_received_ts = 292.068817
current_seq = 923
count = 185
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.052429/922, current 292.069214/923: elapsed=16790.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.069214
last_received_ts = 292.068817
last_seq = 923
current_ts = 292.086029
current_received_ts = 292.085663
current_seq = 924
count = 186
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.069214/923, current 292.086029/924: elapsed=16804.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.086029
last_received_ts = 292.085663
last_seq = 924
current_ts = 292.102814
current_received_ts = 292.102386
current_seq = 925
count = 187
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.086029/924, current 292.102814/925: elapsed=16794.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.102814
last_received_ts = 292.102386
last_seq = 925
current_ts = 292.119629
current_received_ts = 292.119354
current_seq = 926
count = 188
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.102814/925, current 292.119629/926: elapsed=16812.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.119629
last_received_ts = 292.119354
last_seq = 926
current_ts = 292.136444
current_received_ts = 292.136169
current_seq = 927
count = 189
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.119629/926, current 292.136444/927: elapsed=16799.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.136444
last_received_ts = 292.136169
last_seq = 927
current_ts = 292.153229
current_received_ts = 292.152802
current_seq = 928
count = 190
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.136444/927, current 292.153229/928: elapsed=16789.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.153229
last_received_ts = 292.152802
last_seq = 928
current_ts = 292.170013
current_received_ts = 292.169617
current_seq = 929
count = 191
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.153229/928, current 292.170013/929: elapsed=16798.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.170013
last_received_ts = 292.169617
last_seq = 929
current_ts = 292.186829
current_received_ts = 292.186401
current_seq = 930
count = 192
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.170013/929, current 292.186829/930: elapsed=16810.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.186829
last_received_ts = 292.186401
last_seq = 930
current_ts = 292.203644
current_received_ts = 292.203217
current_seq = 931
count = 193
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.186829/930, current 292.203644/931: elapsed=16801.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.203644
last_received_ts = 292.203217
last_seq = 931
current_ts = 292.220428
current_received_ts = 292.220001
current_seq = 932
count = 194
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.203644/931, current 292.220428/932: elapsed=16786.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.220428
last_received_ts = 292.220001
last_seq = 932
current_ts = 292.237213
current_received_ts = 292.236877
current_seq = 933
count = 195
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.220428/932, current 292.237213/933: elapsed=16803.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.237213
last_received_ts = 292.236877
last_seq = 933
current_ts = 292.254028
current_received_ts = 292.253693
current_seq = 934
count = 196
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.237213/933, current 292.254028/934: elapsed=16803.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.254028
last_received_ts = 292.253693
last_seq = 934
current_ts = 292.270813
current_received_ts = 292.270386
current_seq = 935
count = 197
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.254028/934, current 292.270813/935: elapsed=16803.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.270813
last_received_ts = 292.270386
last_seq = 935
current_ts = 292.287628
current_received_ts = 292.287323
current_seq = 936
count = 198
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.270813/935, current 292.287628/936: elapsed=16801.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.287628
last_received_ts = 292.287323
last_seq = 936
current_ts = 292.304413
current_received_ts = 292.304138
current_seq = 937
count = 199
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.287628/936, current 292.304413/937: elapsed=16794.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.304413
last_received_ts = 292.304138
last_seq = 937
current_ts = 292.321228
current_received_ts = 292.320831
current_seq = 938
count = 200
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.304413/937, current 292.321228/938: elapsed=16799.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.321228
last_received_ts = 292.320831
last_seq = 938
current_ts = 292.338013
current_received_ts = 292.337585
current_seq = 939
count = 201
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.321228/938, current 292.338013/939: elapsed=16795.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.338013
last_received_ts = 292.337585
last_seq = 939
current_ts = 292.354828
current_received_ts = 292.354401
current_seq = 940
count = 202
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.338013/939, current 292.354828/940: elapsed=16810.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.354828
last_received_ts = 292.354401
last_seq = 940
current_ts = 292.371613
current_received_ts = 292.371338
current_seq = 941
count = 203
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.354828/940, current 292.371613/941: elapsed=16803.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.371613
last_received_ts = 292.371338
last_seq = 941
current_ts = 292.388397
current_received_ts = 292.388000
current_seq = 942
count = 204
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.371613/941, current 292.388397/942: elapsed=16785.0us expected=16861.1us +- 84.3us, error 0.5%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.388397
last_received_ts = 292.388000
last_seq = 942
current_ts = 292.405212
current_received_ts = 292.404907
current_seq = 943
count = 205
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.388397/942, current 292.405212/943: elapsed=16812.0us expected=16861.1us +- 84.3us, error 0.3%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.405212
last_received_ts = 292.404907
last_seq = 943
current_ts = 292.422028
current_received_ts = 292.421600
current_seq = 944
count = 206
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.405212/943, current 292.422028/944: elapsed=16790.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.422028
last_received_ts = 292.421600
last_seq = 944
current_ts = 292.438812
current_received_ts = 292.438385
current_seq = 945
count = 207
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.422028/944, current 292.438812/945: elapsed=16796.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.438812
last_received_ts = 292.438385
last_seq = 945
current_ts = 292.455597
current_received_ts = 292.455322
current_seq = 946
count = 208
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.438812/945, current 292.455597/946: elapsed=16798.0us expected=16861.1us +- 84.3us, error 0.4%
(kms_flip:2316) DEBUG: name = flip
last_ts = 292.455597
last_received_ts = 292.455322
last_seq = 946
current_ts = 292.472382
current_received_ts = 292.471985
current_seq = 947
count = 209
seq_step = 1
(kms_flip:2316) DEBUG: flip ts/seq: last 292.455597/946, current 292.472382/947: elapsed=16774.0us expected=16861.1us +- 84.3us, error 0.5%
(kms_flip:2316) DEBUG: inconsistent flip ts/seq: last 292.455597/946, current 292.472382/947: elapsed=16774.0us expected=16861.1us
(kms_flip:2316) DEBUG: expected 444, counted 209, encoder type 2
(kms_flip:2316) DEBUG: dropped frames, expected 444, counted 209, encoder type 2
(kms_flip:2316) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2316) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2316) igt_core-INFO: Stack trace:
(kms_flip:2316) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2316) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2316) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2316) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2316) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2316) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2316) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2316) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest D-HDMI-A3: FAIL (7.124s)
Subtest plain-flip-ts-check: FAIL (26.615s)
(kms_flip:2316) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2246:
(kms_flip:2316) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:2316) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:2316) igt_kms-CRITICAL: DPMS property not found on 289