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

shard-lnl-8

IGT-Version: 1.30-g267088686 (x86_64) (Linux: 6.14.0-rc4-xe+ x86_64)

Using IGT_SRANDOM=1740452723 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Expected frametime: 16664us; measured 16979.9us +- 4.524us accuracy 0.08%
vblank interval differs from modeline! expected 16664.0us, measured 16980us +- 4.524us, difference 315.9us (69.8 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-eDP1: FAIL (7.084s)
Starting dynamic subtest: B-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Expected frametime: 16664us; measured 16793.2us +- 4.626us accuracy 0.08%
vblank interval differs from modeline! expected 16664.0us, measured 16793us +- 4.626us, difference 129.2us (27.9 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (11.972s)
Starting dynamic subtest: C-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Expected frametime: 16664us; measured 16696.8us +- 3.907us accuracy 0.07%
vblank interval differs from modeline! expected 16664.0us, measured 16697us +- 3.907us, difference 32.7us (8.4 sigma)
Dynamic subtest C-eDP1: SUCCESS (11.636s)
Subtest plain-flip-ts-check: FAIL (30.699s)

Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-eDP1
(kms_flip:6373) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:6373) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
(kms_flip:6373) DEBUG: flip ts/seq: last 174.436249/540, current 174.453217/541: elapsed=16976.0us expected=16979.9us +- 84.9us, error 0.0%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.453217
last_received_ts = 174.452560
last_seq = 541
current_ts = 174.470200
current_received_ts = 174.469513
current_seq = 542
count = 24
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.453217/541, current 174.470200/542: elapsed=16980.0us expected=16979.9us +- 84.9us, error 0.0%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.470200
last_received_ts = 174.469513
last_seq = 542
current_ts = 174.487137
current_received_ts = 174.486481
current_seq = 543
count = 25
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.470200/542, current 174.487137/543: elapsed=16940.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.487137
last_received_ts = 174.486481
last_seq = 543
current_ts = 174.504089
current_received_ts = 174.503357
current_seq = 544
count = 26
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.487137/543, current 174.504089/544: elapsed=16940.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.504089
last_received_ts = 174.503357
last_seq = 544
current_ts = 174.521027
current_received_ts = 174.520309
current_seq = 545
count = 27
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.504089/544, current 174.521027/545: elapsed=16945.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.521027
last_received_ts = 174.520309
last_seq = 545
current_ts = 174.537964
current_received_ts = 174.537323
current_seq = 546
count = 28
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.521027/545, current 174.537964/546: elapsed=16937.0us expected=16979.9us +- 84.9us, error 0.3%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.537964
last_received_ts = 174.537323
last_seq = 546
current_ts = 174.554916
current_received_ts = 174.554321
current_seq = 547
count = 29
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.537964/546, current 174.554916/547: elapsed=16950.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.554916
last_received_ts = 174.554321
last_seq = 547
current_ts = 174.571854
current_received_ts = 174.571182
current_seq = 548
count = 30
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.554916/547, current 174.571854/548: elapsed=16940.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.571854
last_received_ts = 174.571182
last_seq = 548
current_ts = 174.588791
current_received_ts = 174.588196
current_seq = 549
count = 31
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.571854/548, current 174.588791/549: elapsed=16941.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.588791
last_received_ts = 174.588196
last_seq = 549
current_ts = 174.605728
current_received_ts = 174.605133
current_seq = 550
count = 32
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.588791/549, current 174.605728/550: elapsed=16938.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.605728
last_received_ts = 174.605133
last_seq = 550
current_ts = 174.622681
current_received_ts = 174.622086
current_seq = 551
count = 33
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.605728/550, current 174.622681/551: elapsed=16941.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.622681
last_received_ts = 174.622086
last_seq = 551
current_ts = 174.639618
current_received_ts = 174.639038
current_seq = 552
count = 34
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.622681/551, current 174.639618/552: elapsed=16942.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.639618
last_received_ts = 174.639038
last_seq = 552
current_ts = 174.656570
current_received_ts = 174.655960
current_seq = 553
count = 35
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.639618/552, current 174.656570/553: elapsed=16946.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.656570
last_received_ts = 174.655960
last_seq = 553
current_ts = 174.673508
current_received_ts = 174.672913
current_seq = 554
count = 36
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.656570/553, current 174.673508/554: elapsed=16941.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.673508
last_received_ts = 174.672913
last_seq = 554
current_ts = 174.690445
current_received_ts = 174.690002
current_seq = 555
count = 37
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.673508/554, current 174.690445/555: elapsed=16942.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.690445
last_received_ts = 174.690002
last_seq = 555
current_ts = 174.707382
current_received_ts = 174.706772
current_seq = 556
count = 38
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.690445/555, current 174.707382/556: elapsed=16939.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.707382
last_received_ts = 174.706772
last_seq = 556
current_ts = 174.724319
current_received_ts = 174.723724
current_seq = 557
count = 39
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.707382/556, current 174.724319/557: elapsed=16939.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.724319
last_received_ts = 174.723724
last_seq = 557
current_ts = 174.741272
current_received_ts = 174.740662
current_seq = 558
count = 40
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.724319/557, current 174.741272/558: elapsed=16943.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.741272
last_received_ts = 174.740662
last_seq = 558
current_ts = 174.758209
current_received_ts = 174.757614
current_seq = 559
count = 41
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.741272/558, current 174.758209/559: elapsed=16943.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.758209
last_received_ts = 174.757614
last_seq = 559
current_ts = 174.775146
current_received_ts = 174.774551
current_seq = 560
count = 42
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.758209/559, current 174.775146/560: elapsed=16943.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.775146
last_received_ts = 174.774551
last_seq = 560
current_ts = 174.792099
current_received_ts = 174.791489
current_seq = 561
count = 43
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.775146/560, current 174.792099/561: elapsed=16941.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.792099
last_received_ts = 174.791489
last_seq = 561
current_ts = 174.809036
current_received_ts = 174.808380
current_seq = 562
count = 44
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.792099/561, current 174.809036/562: elapsed=16944.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.809036
last_received_ts = 174.808380
last_seq = 562
current_ts = 174.825974
current_received_ts = 174.825363
current_seq = 563
count = 45
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.809036/562, current 174.825974/563: elapsed=16940.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.825974
last_received_ts = 174.825363
last_seq = 563
current_ts = 174.842926
current_received_ts = 174.842178
current_seq = 564
count = 46
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.825974/563, current 174.842926/564: elapsed=16942.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.842926
last_received_ts = 174.842178
last_seq = 564
current_ts = 174.859863
current_received_ts = 174.859268
current_seq = 565
count = 47
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.842926/564, current 174.859863/565: elapsed=16940.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.859863
last_received_ts = 174.859268
last_seq = 565
current_ts = 174.876801
current_received_ts = 174.876221
current_seq = 566
count = 48
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.859863/565, current 174.876801/566: elapsed=16939.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.876801
last_received_ts = 174.876221
last_seq = 566
current_ts = 174.893738
current_received_ts = 174.893158
current_seq = 567
count = 49
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.876801/566, current 174.893738/567: elapsed=16943.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.893738
last_received_ts = 174.893158
last_seq = 567
current_ts = 174.910690
current_received_ts = 174.910065
current_seq = 568
count = 50
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.893738/567, current 174.910690/568: elapsed=16940.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.910690
last_received_ts = 174.910065
last_seq = 568
current_ts = 174.927628
current_received_ts = 174.927032
current_seq = 569
count = 51
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.910690/568, current 174.927628/569: elapsed=16946.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.927628
last_received_ts = 174.927032
last_seq = 569
current_ts = 174.944565
current_received_ts = 174.943970
current_seq = 570
count = 52
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.927628/569, current 174.944565/570: elapsed=16937.0us expected=16979.9us +- 84.9us, error 0.3%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.944565
last_received_ts = 174.943970
last_seq = 570
current_ts = 174.961517
current_received_ts = 174.960907
current_seq = 571
count = 53
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.944565/570, current 174.961517/571: elapsed=16945.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.961517
last_received_ts = 174.960907
last_seq = 571
current_ts = 174.978455
current_received_ts = 174.977844
current_seq = 572
count = 54
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.961517/571, current 174.978455/572: elapsed=16941.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.978455
last_received_ts = 174.977844
last_seq = 572
current_ts = 174.995392
current_received_ts = 174.994766
current_seq = 573
count = 55
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.978455/572, current 174.995392/573: elapsed=16939.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 174.995392
last_received_ts = 174.994766
last_seq = 573
current_ts = 175.012329
current_received_ts = 175.011734
current_seq = 574
count = 56
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 174.995392/573, current 175.012329/574: elapsed=16942.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.012329
last_received_ts = 175.011734
last_seq = 574
current_ts = 175.029282
current_received_ts = 175.028671
current_seq = 575
count = 57
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.012329/574, current 175.029282/575: elapsed=16944.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.029282
last_received_ts = 175.028671
last_seq = 575
current_ts = 175.046219
current_received_ts = 175.045609
current_seq = 576
count = 58
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.029282/575, current 175.046219/576: elapsed=16940.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.046219
last_received_ts = 175.045609
last_seq = 576
current_ts = 175.063156
current_received_ts = 175.062515
current_seq = 577
count = 59
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.046219/576, current 175.063156/577: elapsed=16940.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.063156
last_received_ts = 175.062515
last_seq = 577
current_ts = 175.080093
current_received_ts = 175.079407
current_seq = 578
count = 60
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.063156/577, current 175.080093/578: elapsed=16944.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.080093
last_received_ts = 175.079407
last_seq = 578
current_ts = 175.097046
current_received_ts = 175.096420
current_seq = 579
count = 61
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.080093/578, current 175.097046/579: elapsed=16942.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.097046
last_received_ts = 175.096420
last_seq = 579
current_ts = 175.113983
current_received_ts = 175.113373
current_seq = 580
count = 62
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.097046/579, current 175.113983/580: elapsed=16938.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.113983
last_received_ts = 175.113373
last_seq = 580
current_ts = 175.130920
current_received_ts = 175.130341
current_seq = 581
count = 63
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.113983/580, current 175.130920/581: elapsed=16942.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.130920
last_received_ts = 175.130341
last_seq = 581
current_ts = 175.147873
current_received_ts = 175.147186
current_seq = 582
count = 64
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.130920/581, current 175.147873/582: elapsed=16943.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.147873
last_received_ts = 175.147186
last_seq = 582
current_ts = 175.164810
current_received_ts = 175.164169
current_seq = 583
count = 65
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.147873/582, current 175.164810/583: elapsed=16942.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.164810
last_received_ts = 175.164169
last_seq = 583
current_ts = 175.181747
current_received_ts = 175.181137
current_seq = 584
count = 66
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.164810/583, current 175.181747/584: elapsed=16940.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.181747
last_received_ts = 175.181137
last_seq = 584
current_ts = 175.198685
current_received_ts = 175.198074
current_seq = 585
count = 67
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.181747/584, current 175.198685/585: elapsed=16940.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.198685
last_received_ts = 175.198074
last_seq = 585
current_ts = 175.215637
current_received_ts = 175.215057
current_seq = 586
count = 68
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.198685/585, current 175.215637/586: elapsed=16945.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.215637
last_received_ts = 175.215057
last_seq = 586
current_ts = 175.232574
current_received_ts = 175.231949
current_seq = 587
count = 69
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.215637/586, current 175.232574/587: elapsed=16942.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.232574
last_received_ts = 175.231949
last_seq = 587
current_ts = 175.249512
current_received_ts = 175.248901
current_seq = 588
count = 70
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.232574/587, current 175.249512/588: elapsed=16938.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.249512
last_received_ts = 175.248901
last_seq = 588
current_ts = 175.266449
current_received_ts = 175.265854
current_seq = 589
count = 71
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.249512/588, current 175.266449/589: elapsed=16941.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.266449
last_received_ts = 175.265854
last_seq = 589
current_ts = 175.283401
current_received_ts = 175.282791
current_seq = 590
count = 72
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.266449/589, current 175.283401/590: elapsed=16946.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.283401
last_received_ts = 175.282791
last_seq = 590
current_ts = 175.300339
current_received_ts = 175.299744
current_seq = 591
count = 73
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.283401/590, current 175.300339/591: elapsed=16937.0us expected=16979.9us +- 84.9us, error 0.3%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.300339
last_received_ts = 175.299744
last_seq = 591
current_ts = 175.317276
current_received_ts = 175.316666
current_seq = 592
count = 74
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.300339/591, current 175.317276/592: elapsed=16944.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.317276
last_received_ts = 175.316666
last_seq = 592
current_ts = 175.334229
current_received_ts = 175.333633
current_seq = 593
count = 75
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.317276/592, current 175.334229/593: elapsed=16942.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.334229
last_received_ts = 175.333633
last_seq = 593
current_ts = 175.351166
current_received_ts = 175.350571
current_seq = 594
count = 76
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.334229/593, current 175.351166/594: elapsed=16941.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.351166
last_received_ts = 175.350571
last_seq = 594
current_ts = 175.368103
current_received_ts = 175.367477
current_seq = 595
count = 77
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.351166/594, current 175.368103/595: elapsed=16938.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.368103
last_received_ts = 175.367477
last_seq = 595
current_ts = 175.385040
current_received_ts = 175.384445
current_seq = 596
count = 78
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.368103/595, current 175.385040/596: elapsed=16944.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.385040
last_received_ts = 175.384445
last_seq = 596
current_ts = 175.401993
current_received_ts = 175.401382
current_seq = 597
count = 79
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.385040/596, current 175.401993/597: elapsed=16946.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.401993
last_received_ts = 175.401382
last_seq = 597
current_ts = 175.418930
current_received_ts = 175.418289
current_seq = 598
count = 80
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.401993/597, current 175.418930/598: elapsed=16944.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.418930
last_received_ts = 175.418289
last_seq = 598
current_ts = 175.435883
current_received_ts = 175.435165
current_seq = 599
count = 81
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.418930/598, current 175.435883/599: elapsed=16940.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.435883
last_received_ts = 175.435165
last_seq = 599
current_ts = 175.452820
current_received_ts = 175.452194
current_seq = 600
count = 82
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.435883/599, current 175.452820/600: elapsed=16941.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.452820
last_received_ts = 175.452194
last_seq = 600
current_ts = 175.469757
current_received_ts = 175.469147
current_seq = 601
count = 83
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.452820/600, current 175.469757/601: elapsed=16938.0us expected=16979.9us +- 84.9us, error 0.2%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.469757
last_received_ts = 175.469147
last_seq = 601
current_ts = 175.486664
current_received_ts = 175.486069
current_seq = 602
count = 84
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.469757/601, current 175.486664/602: elapsed=16904.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.486664
last_received_ts = 175.486069
last_seq = 602
current_ts = 175.503571
current_received_ts = 175.502975
current_seq = 603
count = 85
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.486664/602, current 175.503571/603: elapsed=16910.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.503571
last_received_ts = 175.502975
last_seq = 603
current_ts = 175.520477
current_received_ts = 175.519867
current_seq = 604
count = 86
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.503571/603, current 175.520477/604: elapsed=16906.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.520477
last_received_ts = 175.519867
last_seq = 604
current_ts = 175.537384
current_received_ts = 175.536774
current_seq = 605
count = 87
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.520477/604, current 175.537384/605: elapsed=16912.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.537384
last_received_ts = 175.536774
last_seq = 605
current_ts = 175.554291
current_received_ts = 175.553696
current_seq = 606
count = 88
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.537384/605, current 175.554291/606: elapsed=16908.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.554291
last_received_ts = 175.553696
last_seq = 606
current_ts = 175.571198
current_received_ts = 175.570618
current_seq = 607
count = 89
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.554291/606, current 175.571198/607: elapsed=16907.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.571198
last_received_ts = 175.570618
last_seq = 607
current_ts = 175.588104
current_received_ts = 175.587494
current_seq = 608
count = 90
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.571198/607, current 175.588104/608: elapsed=16905.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.588104
last_received_ts = 175.587494
last_seq = 608
current_ts = 175.605026
current_received_ts = 175.604370
current_seq = 609
count = 91
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.588104/608, current 175.605026/609: elapsed=16915.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.605026
last_received_ts = 175.604370
last_seq = 609
current_ts = 175.621933
current_received_ts = 175.621201
current_seq = 610
count = 92
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.605026/609, current 175.621933/610: elapsed=16907.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.621933
last_received_ts = 175.621201
last_seq = 610
current_ts = 175.638824
current_received_ts = 175.638199
current_seq = 611
count = 93
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.621933/610, current 175.638824/611: elapsed=16902.0us expected=16979.9us +- 84.9us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.638824
last_received_ts = 175.638199
last_seq = 611
current_ts = 175.655746
current_received_ts = 175.655136
current_seq = 612
count = 94
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.638824/611, current 175.655746/612: elapsed=16910.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.655746
last_received_ts = 175.655136
last_seq = 612
current_ts = 175.672653
current_received_ts = 175.672058
current_seq = 613
count = 95
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.655746/612, current 175.672653/613: elapsed=16912.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.672653
last_received_ts = 175.672058
last_seq = 613
current_ts = 175.689560
current_received_ts = 175.688950
current_seq = 614
count = 96
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.672653/613, current 175.689560/614: elapsed=16901.0us expected=16979.9us +- 84.9us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.689560
last_received_ts = 175.688950
last_seq = 614
current_ts = 175.706467
current_received_ts = 175.705856
current_seq = 615
count = 97
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.689560/614, current 175.706467/615: elapsed=16911.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.706467
last_received_ts = 175.705856
last_seq = 615
current_ts = 175.723373
current_received_ts = 175.722748
current_seq = 616
count = 98
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.706467/615, current 175.723373/616: elapsed=16908.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.723373
last_received_ts = 175.722748
last_seq = 616
current_ts = 175.740280
current_received_ts = 175.739670
current_seq = 617
count = 99
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.723373/616, current 175.740280/617: elapsed=16908.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.740280
last_received_ts = 175.739670
last_seq = 617
current_ts = 175.757187
current_received_ts = 175.756592
current_seq = 618
count = 100
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.740280/617, current 175.757187/618: elapsed=16906.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.757187
last_received_ts = 175.756592
last_seq = 618
current_ts = 175.774094
current_received_ts = 175.773483
current_seq = 619
count = 101
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.757187/618, current 175.774094/619: elapsed=16913.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.774094
last_received_ts = 175.773483
last_seq = 619
current_ts = 175.791000
current_received_ts = 175.790405
current_seq = 620
count = 102
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.774094/619, current 175.791000/620: elapsed=16904.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.791000
last_received_ts = 175.790405
last_seq = 620
current_ts = 175.807907
current_received_ts = 175.807297
current_seq = 621
count = 103
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.791000/620, current 175.807907/621: elapsed=16909.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.807907
last_received_ts = 175.807297
last_seq = 621
current_ts = 175.824814
current_received_ts = 175.824173
current_seq = 622
count = 104
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.807907/621, current 175.824814/622: elapsed=16908.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.824814
last_received_ts = 175.824173
last_seq = 622
current_ts = 175.841721
current_received_ts = 175.841125
current_seq = 623
count = 105
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.824814/622, current 175.841721/623: elapsed=16904.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.841721
last_received_ts = 175.841125
last_seq = 623
current_ts = 175.858643
current_received_ts = 175.858047
current_seq = 624
count = 106
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.841721/623, current 175.858643/624: elapsed=16910.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.858643
last_received_ts = 175.858047
last_seq = 624
current_ts = 175.875549
current_received_ts = 175.874939
current_seq = 625
count = 107
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.858643/624, current 175.875549/625: elapsed=16913.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.875549
last_received_ts = 175.874939
last_seq = 625
current_ts = 175.892456
current_received_ts = 175.891861
current_seq = 626
count = 108
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.875549/625, current 175.892456/626: elapsed=16903.0us expected=16979.9us +- 84.9us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.892456
last_received_ts = 175.891861
last_seq = 626
current_ts = 175.909363
current_received_ts = 175.908752
current_seq = 627
count = 109
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.892456/626, current 175.909363/627: elapsed=16912.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.909363
last_received_ts = 175.908752
last_seq = 627
current_ts = 175.926270
current_received_ts = 175.925659
current_seq = 628
count = 110
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.909363/627, current 175.926270/628: elapsed=16908.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.926270
last_received_ts = 175.925659
last_seq = 628
current_ts = 175.943176
current_received_ts = 175.942566
current_seq = 629
count = 111
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.926270/628, current 175.943176/629: elapsed=16908.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.943176
last_received_ts = 175.942566
last_seq = 629
current_ts = 175.960083
current_received_ts = 175.959488
current_seq = 630
count = 112
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.943176/629, current 175.960083/630: elapsed=16906.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.960083
last_received_ts = 175.959488
last_seq = 630
current_ts = 175.976990
current_received_ts = 175.976379
current_seq = 631
count = 113
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.960083/630, current 175.976990/631: elapsed=16907.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.976990
last_received_ts = 175.976379
last_seq = 631
current_ts = 175.993896
current_received_ts = 175.993271
current_seq = 632
count = 114
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.976990/631, current 175.993896/632: elapsed=16905.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 175.993896
last_received_ts = 175.993271
last_seq = 632
current_ts = 176.010803
current_received_ts = 176.010193
current_seq = 633
count = 115
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 175.993896/632, current 176.010803/633: elapsed=16910.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.010803
last_received_ts = 176.010193
last_seq = 633
current_ts = 176.027710
current_received_ts = 176.027115
current_seq = 634
count = 116
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.010803/633, current 176.027710/634: elapsed=16910.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.027710
last_received_ts = 176.027115
last_seq = 634
current_ts = 176.044617
current_received_ts = 176.044006
current_seq = 635
count = 117
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.027710/634, current 176.044617/635: elapsed=16905.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.044617
last_received_ts = 176.044006
last_seq = 635
current_ts = 176.061523
current_received_ts = 176.060913
current_seq = 636
count = 118
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.044617/635, current 176.061523/636: elapsed=16907.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.061523
last_received_ts = 176.060913
last_seq = 636
current_ts = 176.078445
current_received_ts = 176.077820
current_seq = 637
count = 119
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.061523/636, current 176.078445/637: elapsed=16913.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.078445
last_received_ts = 176.077820
last_seq = 637
current_ts = 176.095352
current_received_ts = 176.094727
current_seq = 638
count = 120
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.078445/637, current 176.095352/638: elapsed=16907.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.095352
last_received_ts = 176.094727
last_seq = 638
current_ts = 176.112259
current_received_ts = 176.111664
current_seq = 639
count = 121
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.095352/638, current 176.112259/639: elapsed=16906.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.112259
last_received_ts = 176.111664
last_seq = 639
current_ts = 176.129166
current_received_ts = 176.128555
current_seq = 640
count = 122
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.112259/639, current 176.129166/640: elapsed=16906.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.129166
last_received_ts = 176.128555
last_seq = 640
current_ts = 176.146072
current_received_ts = 176.145477
current_seq = 641
count = 123
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.129166/640, current 176.146072/641: elapsed=16907.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.146072
last_received_ts = 176.145477
last_seq = 641
current_ts = 176.162979
current_received_ts = 176.162369
current_seq = 642
count = 124
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.146072/641, current 176.162979/642: elapsed=16914.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.162979
last_received_ts = 176.162369
last_seq = 642
current_ts = 176.179886
current_received_ts = 176.179291
current_seq = 643
count = 125
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.162979/642, current 176.179886/643: elapsed=16903.0us expected=16979.9us +- 84.9us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.179886
last_received_ts = 176.179291
last_seq = 643
current_ts = 176.196793
current_received_ts = 176.196167
current_seq = 644
count = 126
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.179886/643, current 176.196793/644: elapsed=16909.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.196793
last_received_ts = 176.196167
last_seq = 644
current_ts = 176.213699
current_received_ts = 176.213104
current_seq = 645
count = 127
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.196793/644, current 176.213699/645: elapsed=16909.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.213699
last_received_ts = 176.213104
last_seq = 645
current_ts = 176.230606
current_received_ts = 176.230011
current_seq = 646
count = 128
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.213699/645, current 176.230606/646: elapsed=16905.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.230606
last_received_ts = 176.230011
last_seq = 646
current_ts = 176.247513
current_received_ts = 176.246902
current_seq = 647
count = 129
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.230606/646, current 176.247513/647: elapsed=16909.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.247513
last_received_ts = 176.246902
last_seq = 647
current_ts = 176.264420
current_received_ts = 176.263824
current_seq = 648
count = 130
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.247513/647, current 176.264420/648: elapsed=16908.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.264420
last_received_ts = 176.263824
last_seq = 648
current_ts = 176.281342
current_received_ts = 176.280731
current_seq = 649
count = 131
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.264420/648, current 176.281342/649: elapsed=16914.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.281342
last_received_ts = 176.280731
last_seq = 649
current_ts = 176.298233
current_received_ts = 176.297607
current_seq = 650
count = 132
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.281342/649, current 176.298233/650: elapsed=16901.0us expected=16979.9us +- 84.9us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.298233
last_received_ts = 176.297607
last_seq = 650
current_ts = 176.315155
current_received_ts = 176.314514
current_seq = 651
count = 133
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.298233/650, current 176.315155/651: elapsed=16913.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.315155
last_received_ts = 176.314514
last_seq = 651
current_ts = 176.332062
current_received_ts = 176.331467
current_seq = 652
count = 134
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.315155/651, current 176.332062/652: elapsed=16906.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.332062
last_received_ts = 176.331467
last_seq = 652
current_ts = 176.348969
current_received_ts = 176.348297
current_seq = 653
count = 135
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.332062/652, current 176.348969/653: elapsed=16911.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.348969
last_received_ts = 176.348297
last_seq = 653
current_ts = 176.365875
current_received_ts = 176.365295
current_seq = 654
count = 136
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.348969/653, current 176.365875/654: elapsed=16905.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.365875
last_received_ts = 176.365295
last_seq = 654
current_ts = 176.382782
current_received_ts = 176.382187
current_seq = 655
count = 137
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.365875/654, current 176.382782/655: elapsed=16910.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.382782
last_received_ts = 176.382187
last_seq = 655
current_ts = 176.399689
current_received_ts = 176.399109
current_seq = 656
count = 138
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.382782/655, current 176.399689/656: elapsed=16906.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.399689
last_received_ts = 176.399109
last_seq = 656
current_ts = 176.416595
current_received_ts = 176.416000
current_seq = 657
count = 139
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.399689/656, current 176.416595/657: elapsed=16906.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.416595
last_received_ts = 176.416000
last_seq = 657
current_ts = 176.433502
current_received_ts = 176.432907
current_seq = 658
count = 140
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.416595/657, current 176.433502/658: elapsed=16907.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.433502
last_received_ts = 176.432907
last_seq = 658
current_ts = 176.450409
current_received_ts = 176.449814
current_seq = 659
count = 141
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.433502/658, current 176.450409/659: elapsed=16909.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.450409
last_received_ts = 176.449814
last_seq = 659
current_ts = 176.467331
current_received_ts = 176.466705
current_seq = 660
count = 142
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.450409/659, current 176.467331/660: elapsed=16912.0us expected=16979.9us +- 84.9us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 176.467331
last_received_ts = 176.466705
last_seq = 660
current_ts = 176.484207
current_received_ts = 176.483597
current_seq = 661
count = 143
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 176.467331/660, current 176.484207/661: elapsed=16877.0us expected=16979.9us +- 84.9us, error 0.6%
(kms_flip:6373) DEBUG: inconsistent flip ts/seq: last 176.467331/660, current 176.484207/661: elapsed=16877.0us expected=16979.9us
(kms_flip:6373) DEBUG: expected 242419, counted 143, encoder type 2
(kms_flip:6373) DEBUG: dropped frames, expected 242419, counted 143, encoder type 2
(kms_flip:6373) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:6373) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:6373) igt_core-INFO: Stack trace:
(kms_flip:6373) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:6373) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:6373) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:6373) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:6373) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:6373) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:6373) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:6373) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (7.084s)
Starting dynamic subtest: B-eDP1
(kms_flip:6373) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:6373) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:6373) DEBUG: flip ts/seq: last 186.532089/369, current 186.548813/370: elapsed=16725.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.548813
last_received_ts = 186.548187
last_seq = 370
current_ts = 186.565536
current_received_ts = 186.564926
current_seq = 371
count = 309
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.548813/370, current 186.565536/371: elapsed=16726.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.565536
last_received_ts = 186.564926
last_seq = 371
current_ts = 186.582260
current_received_ts = 186.581665
current_seq = 372
count = 310
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.565536/371, current 186.582260/372: elapsed=16727.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.582260
last_received_ts = 186.581665
last_seq = 372
current_ts = 186.598984
current_received_ts = 186.598404
current_seq = 373
count = 311
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.582260/372, current 186.598984/373: elapsed=16724.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.598984
last_received_ts = 186.598404
last_seq = 373
current_ts = 186.615723
current_received_ts = 186.615128
current_seq = 374
count = 312
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.598984/373, current 186.615723/374: elapsed=16733.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.615723
last_received_ts = 186.615128
last_seq = 374
current_ts = 186.632446
current_received_ts = 186.631836
current_seq = 375
count = 313
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.615723/374, current 186.632446/375: elapsed=16720.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.632446
last_received_ts = 186.631836
last_seq = 375
current_ts = 186.649170
current_received_ts = 186.648575
current_seq = 376
count = 314
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.632446/375, current 186.649170/376: elapsed=16731.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.649170
last_received_ts = 186.648575
last_seq = 376
current_ts = 186.665909
current_received_ts = 186.665283
current_seq = 377
count = 315
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.649170/376, current 186.665909/377: elapsed=16730.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.665909
last_received_ts = 186.665283
last_seq = 377
current_ts = 186.682617
current_received_ts = 186.682037
current_seq = 378
count = 316
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.665909/377, current 186.682617/378: elapsed=16721.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.682617
last_received_ts = 186.682037
last_seq = 378
current_ts = 186.699356
current_received_ts = 186.698746
current_seq = 379
count = 317
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.682617/378, current 186.699356/379: elapsed=16728.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.699356
last_received_ts = 186.698746
last_seq = 379
current_ts = 186.716080
current_received_ts = 186.715469
current_seq = 380
count = 318
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.699356/379, current 186.716080/380: elapsed=16725.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.716080
last_received_ts = 186.715469
last_seq = 380
current_ts = 186.732803
current_received_ts = 186.732193
current_seq = 381
count = 319
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.716080/380, current 186.732803/381: elapsed=16728.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.732803
last_received_ts = 186.732193
last_seq = 381
current_ts = 186.749527
current_received_ts = 186.748932
current_seq = 382
count = 320
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.732803/381, current 186.749527/382: elapsed=16730.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.749527
last_received_ts = 186.748932
last_seq = 382
current_ts = 186.766266
current_received_ts = 186.765656
current_seq = 383
count = 321
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.749527/382, current 186.766266/383: elapsed=16726.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.766266
last_received_ts = 186.765656
last_seq = 383
current_ts = 186.782990
current_received_ts = 186.782364
current_seq = 384
count = 322
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.766266/383, current 186.782990/384: elapsed=16725.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.782990
last_received_ts = 186.782364
last_seq = 384
current_ts = 186.799713
current_received_ts = 186.799103
current_seq = 385
count = 323
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.782990/384, current 186.799713/385: elapsed=16725.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.799713
last_received_ts = 186.799103
last_seq = 385
current_ts = 186.816437
current_received_ts = 186.815842
current_seq = 386
count = 324
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.799713/385, current 186.816437/386: elapsed=16731.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.816437
last_received_ts = 186.815842
last_seq = 386
current_ts = 186.833160
current_received_ts = 186.832565
current_seq = 387
count = 325
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.816437/386, current 186.833160/387: elapsed=16722.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.833160
last_received_ts = 186.832565
last_seq = 387
current_ts = 186.849884
current_received_ts = 186.849289
current_seq = 388
count = 326
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.833160/387, current 186.849884/388: elapsed=16725.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.849884
last_received_ts = 186.849289
last_seq = 388
current_ts = 186.866608
current_received_ts = 186.866196
current_seq = 389
count = 327
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.849884/388, current 186.866608/389: elapsed=16727.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.866608
last_received_ts = 186.866196
last_seq = 389
current_ts = 186.883347
current_received_ts = 186.882751
current_seq = 390
count = 328
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.866608/389, current 186.883347/390: elapsed=16732.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.883347
last_received_ts = 186.882751
last_seq = 390
current_ts = 186.900070
current_received_ts = 186.899460
current_seq = 391
count = 329
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.883347/390, current 186.900070/391: elapsed=16723.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.900070
last_received_ts = 186.899460
last_seq = 391
current_ts = 186.916794
current_received_ts = 186.916183
current_seq = 392
count = 330
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.900070/391, current 186.916794/392: elapsed=16725.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.916794
last_received_ts = 186.916183
last_seq = 392
current_ts = 186.933517
current_received_ts = 186.932907
current_seq = 393
count = 331
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.916794/392, current 186.933517/393: elapsed=16729.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.933517
last_received_ts = 186.932907
last_seq = 393
current_ts = 186.950256
current_received_ts = 186.949631
current_seq = 394
count = 332
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.933517/393, current 186.950256/394: elapsed=16727.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.950256
last_received_ts = 186.949631
last_seq = 394
current_ts = 186.966980
current_received_ts = 186.966370
current_seq = 395
count = 333
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.950256/394, current 186.966980/395: elapsed=16727.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.966980
last_received_ts = 186.966370
last_seq = 395
current_ts = 186.983704
current_received_ts = 186.983109
current_seq = 396
count = 334
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.966980/395, current 186.983704/396: elapsed=16729.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 186.983704
last_received_ts = 186.983109
last_seq = 396
current_ts = 187.000427
current_received_ts = 186.999817
current_seq = 397
count = 335
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 186.983704/396, current 187.000427/397: elapsed=16725.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.000427
last_received_ts = 186.999817
last_seq = 397
current_ts = 187.017151
current_received_ts = 187.016556
current_seq = 398
count = 336
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.000427/397, current 187.017151/398: elapsed=16723.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.017151
last_received_ts = 187.016556
last_seq = 398
current_ts = 187.033875
current_received_ts = 187.033279
current_seq = 399
count = 337
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.017151/398, current 187.033875/399: elapsed=16726.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.033875
last_received_ts = 187.033279
last_seq = 399
current_ts = 187.050613
current_received_ts = 187.050018
current_seq = 400
count = 338
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.033875/399, current 187.050613/400: elapsed=16730.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.050613
last_received_ts = 187.050018
last_seq = 400
current_ts = 187.067337
current_received_ts = 187.066910
current_seq = 401
count = 339
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.050613/400, current 187.067337/401: elapsed=16725.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.067337
last_received_ts = 187.066910
last_seq = 401
current_ts = 187.084061
current_received_ts = 187.083405
current_seq = 402
count = 340
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.067337/401, current 187.084061/402: elapsed=16727.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.084061
last_received_ts = 187.083405
last_seq = 402
current_ts = 187.100784
current_received_ts = 187.100159
current_seq = 403
count = 341
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.084061/402, current 187.100784/403: elapsed=16725.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.100784
last_received_ts = 187.100159
last_seq = 403
current_ts = 187.117508
current_received_ts = 187.117111
current_seq = 404
count = 342
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.100784/403, current 187.117508/404: elapsed=16725.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.117508
last_received_ts = 187.117111
last_seq = 404
current_ts = 187.134247
current_received_ts = 187.133820
current_seq = 405
count = 343
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.117508/404, current 187.134247/405: elapsed=16732.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.134247
last_received_ts = 187.133820
last_seq = 405
current_ts = 187.150970
current_received_ts = 187.150299
current_seq = 406
count = 344
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.134247/405, current 187.150970/406: elapsed=16726.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.150970
last_received_ts = 187.150299
last_seq = 406
current_ts = 187.167694
current_received_ts = 187.167114
current_seq = 407
count = 345
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.150970/406, current 187.167694/407: elapsed=16720.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.167694
last_received_ts = 187.167114
last_seq = 407
current_ts = 187.184418
current_received_ts = 187.183807
current_seq = 408
count = 346
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.167694/407, current 187.184418/408: elapsed=16730.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.184418
last_received_ts = 187.183807
last_seq = 408
current_ts = 187.201141
current_received_ts = 187.200562
current_seq = 409
count = 347
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.184418/408, current 187.201141/409: elapsed=16727.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.201141
last_received_ts = 187.200562
last_seq = 409
current_ts = 187.217880
current_received_ts = 187.217270
current_seq = 410
count = 348
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.201141/409, current 187.217880/410: elapsed=16726.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.217880
last_received_ts = 187.217270
last_seq = 410
current_ts = 187.234604
current_received_ts = 187.233994
current_seq = 411
count = 349
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.217880/410, current 187.234604/411: elapsed=16727.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.234604
last_received_ts = 187.233994
last_seq = 411
current_ts = 187.251328
current_received_ts = 187.250732
current_seq = 412
count = 350
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.234604/411, current 187.251328/412: elapsed=16727.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.251328
last_received_ts = 187.250732
last_seq = 412
current_ts = 187.268051
current_received_ts = 187.267471
current_seq = 413
count = 351
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.251328/412, current 187.268051/413: elapsed=16724.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.268051
last_received_ts = 187.267471
last_seq = 413
current_ts = 187.284790
current_received_ts = 187.284180
current_seq = 414
count = 352
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.268051/413, current 187.284790/414: elapsed=16732.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.284790
last_received_ts = 187.284180
last_seq = 414
current_ts = 187.301514
current_received_ts = 187.300903
current_seq = 415
count = 353
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.284790/414, current 187.301514/415: elapsed=16726.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.301514
last_received_ts = 187.300903
last_seq = 415
current_ts = 187.318237
current_received_ts = 187.317642
current_seq = 416
count = 354
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.301514/415, current 187.318237/416: elapsed=16723.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.318237
last_received_ts = 187.317642
last_seq = 416
current_ts = 187.334961
current_received_ts = 187.334351
current_seq = 417
count = 355
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.318237/416, current 187.334961/417: elapsed=16729.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.334961
last_received_ts = 187.334351
last_seq = 417
current_ts = 187.351685
current_received_ts = 187.351089
current_seq = 418
count = 356
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.334961/417, current 187.351685/418: elapsed=16728.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.351685
last_received_ts = 187.351089
last_seq = 418
current_ts = 187.368408
current_received_ts = 187.367813
current_seq = 419
count = 357
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.351685/418, current 187.368408/419: elapsed=16725.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.368408
last_received_ts = 187.367813
last_seq = 419
current_ts = 187.385147
current_received_ts = 187.384537
current_seq = 420
count = 358
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.368408/419, current 187.385147/420: elapsed=16726.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.385147
last_received_ts = 187.384537
last_seq = 420
current_ts = 187.401871
current_received_ts = 187.401260
current_seq = 421
count = 359
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.385147/420, current 187.401871/421: elapsed=16726.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.401871
last_received_ts = 187.401260
last_seq = 421
current_ts = 187.418594
current_received_ts = 187.418182
current_seq = 422
count = 360
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.401871/421, current 187.418594/422: elapsed=16729.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.418594
last_received_ts = 187.418182
last_seq = 422
current_ts = 187.435318
current_received_ts = 187.434723
current_seq = 423
count = 361
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.418594/422, current 187.435318/423: elapsed=16727.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.435318
last_received_ts = 187.434723
last_seq = 423
current_ts = 187.452042
current_received_ts = 187.451431
current_seq = 424
count = 362
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.435318/423, current 187.452042/424: elapsed=16726.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.452042
last_received_ts = 187.451431
last_seq = 424
current_ts = 187.468781
current_received_ts = 187.468170
current_seq = 425
count = 363
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.452042/424, current 187.468781/425: elapsed=16728.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.468781
last_received_ts = 187.468170
last_seq = 425
current_ts = 187.485489
current_received_ts = 187.484879
current_seq = 426
count = 364
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.468781/425, current 187.485489/426: elapsed=16716.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.485489
last_received_ts = 187.484879
last_seq = 426
current_ts = 187.502213
current_received_ts = 187.501541
current_seq = 427
count = 365
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.485489/426, current 187.502213/427: elapsed=16719.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.502213
last_received_ts = 187.501541
last_seq = 427
current_ts = 187.518936
current_received_ts = 187.518280
current_seq = 428
count = 366
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.502213/427, current 187.518936/428: elapsed=16719.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.518936
last_received_ts = 187.518280
last_seq = 428
current_ts = 187.535660
current_received_ts = 187.535049
current_seq = 429
count = 367
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.518936/428, current 187.535660/429: elapsed=16722.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.535660
last_received_ts = 187.535049
last_seq = 429
current_ts = 187.552368
current_received_ts = 187.551788
current_seq = 430
count = 368
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.535660/429, current 187.552368/430: elapsed=16720.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.552368
last_received_ts = 187.551788
last_seq = 430
current_ts = 187.569092
current_received_ts = 187.568695
current_seq = 431
count = 369
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.552368/430, current 187.569092/431: elapsed=16724.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.569092
last_received_ts = 187.568695
last_seq = 431
current_ts = 187.585815
current_received_ts = 187.585190
current_seq = 432
count = 370
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.569092/431, current 187.585815/432: elapsed=16718.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.585815
last_received_ts = 187.585190
last_seq = 432
current_ts = 187.602524
current_received_ts = 187.602097
current_seq = 433
count = 371
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.585815/432, current 187.602524/433: elapsed=16715.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.602524
last_received_ts = 187.602097
last_seq = 433
current_ts = 187.619247
current_received_ts = 187.618622
current_seq = 434
count = 372
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.602524/433, current 187.619247/434: elapsed=16722.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.619247
last_received_ts = 187.618622
last_seq = 434
current_ts = 187.635971
current_received_ts = 187.635345
current_seq = 435
count = 373
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.619247/434, current 187.635971/435: elapsed=16718.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.635971
last_received_ts = 187.635345
last_seq = 435
current_ts = 187.652695
current_received_ts = 187.652100
current_seq = 436
count = 374
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.635971/435, current 187.652695/436: elapsed=16723.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.652695
last_received_ts = 187.652100
last_seq = 436
current_ts = 187.669403
current_received_ts = 187.668808
current_seq = 437
count = 375
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.652695/436, current 187.669403/437: elapsed=16715.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.669403
last_received_ts = 187.668808
last_seq = 437
current_ts = 187.686127
current_received_ts = 187.685501
current_seq = 438
count = 376
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.669403/437, current 187.686127/438: elapsed=16721.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.686127
last_received_ts = 187.685501
last_seq = 438
current_ts = 187.702850
current_received_ts = 187.702240
current_seq = 439
count = 377
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.686127/438, current 187.702850/439: elapsed=16719.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.702850
last_received_ts = 187.702240
last_seq = 439
current_ts = 187.719574
current_received_ts = 187.718964
current_seq = 440
count = 378
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.702850/439, current 187.719574/440: elapsed=16725.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.719574
last_received_ts = 187.718964
last_seq = 440
current_ts = 187.736298
current_received_ts = 187.735687
current_seq = 441
count = 379
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.719574/440, current 187.736298/441: elapsed=16718.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.736298
last_received_ts = 187.735687
last_seq = 441
current_ts = 187.753006
current_received_ts = 187.752396
current_seq = 442
count = 380
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.736298/441, current 187.753006/442: elapsed=16717.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.753006
last_received_ts = 187.752396
last_seq = 442
current_ts = 187.769730
current_received_ts = 187.769135
current_seq = 443
count = 381
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.753006/442, current 187.769730/443: elapsed=16720.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.769730
last_received_ts = 187.769135
last_seq = 443
current_ts = 187.786453
current_received_ts = 187.785843
current_seq = 444
count = 382
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.769730/443, current 187.786453/444: elapsed=16724.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.786453
last_received_ts = 187.785843
last_seq = 444
current_ts = 187.803162
current_received_ts = 187.802551
current_seq = 445
count = 383
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.786453/444, current 187.803162/445: elapsed=16716.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.803162
last_received_ts = 187.802551
last_seq = 445
current_ts = 187.819885
current_received_ts = 187.819290
current_seq = 446
count = 384
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.803162/445, current 187.819885/446: elapsed=16720.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.819885
last_received_ts = 187.819290
last_seq = 446
current_ts = 187.836609
current_received_ts = 187.835999
current_seq = 447
count = 385
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.819885/446, current 187.836609/447: elapsed=16717.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.836609
last_received_ts = 187.835999
last_seq = 447
current_ts = 187.853333
current_received_ts = 187.852707
current_seq = 448
count = 386
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.836609/447, current 187.853333/448: elapsed=16727.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.853333
last_received_ts = 187.852707
last_seq = 448
current_ts = 187.870041
current_received_ts = 187.869446
current_seq = 449
count = 387
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.853333/448, current 187.870041/449: elapsed=16712.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.870041
last_received_ts = 187.869446
last_seq = 449
current_ts = 187.886765
current_received_ts = 187.886169
current_seq = 450
count = 388
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.870041/449, current 187.886765/450: elapsed=16726.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.886765
last_received_ts = 187.886169
last_seq = 450
current_ts = 187.903488
current_received_ts = 187.902878
current_seq = 451
count = 389
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.886765/450, current 187.903488/451: elapsed=16715.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.903488
last_received_ts = 187.902878
last_seq = 451
current_ts = 187.920212
current_received_ts = 187.919586
current_seq = 452
count = 390
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.903488/451, current 187.920212/452: elapsed=16721.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.920212
last_received_ts = 187.919586
last_seq = 452
current_ts = 187.936920
current_received_ts = 187.936325
current_seq = 453
count = 391
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.920212/452, current 187.936920/453: elapsed=16721.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.936920
last_received_ts = 187.936325
last_seq = 453
current_ts = 187.953644
current_received_ts = 187.953049
current_seq = 454
count = 392
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.936920/453, current 187.953644/454: elapsed=16721.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.953644
last_received_ts = 187.953049
last_seq = 454
current_ts = 187.970367
current_received_ts = 187.969772
current_seq = 455
count = 393
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.953644/454, current 187.970367/455: elapsed=16715.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.970367
last_received_ts = 187.969772
last_seq = 455
current_ts = 187.987091
current_received_ts = 187.986465
current_seq = 456
count = 394
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.970367/455, current 187.987091/456: elapsed=16722.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 187.987091
last_received_ts = 187.986465
last_seq = 456
current_ts = 188.003799
current_received_ts = 188.003174
current_seq = 457
count = 395
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 187.987091/456, current 188.003799/457: elapsed=16722.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.003799
last_received_ts = 188.003174
last_seq = 457
current_ts = 188.020523
current_received_ts = 188.019882
current_seq = 458
count = 396
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.003799/457, current 188.020523/458: elapsed=16716.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.020523
last_received_ts = 188.019882
last_seq = 458
current_ts = 188.037247
current_received_ts = 188.036636
current_seq = 459
count = 397
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.020523/458, current 188.037247/459: elapsed=16722.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.037247
last_received_ts = 188.036636
last_seq = 459
current_ts = 188.053970
current_received_ts = 188.053314
current_seq = 460
count = 398
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.037247/459, current 188.053970/460: elapsed=16719.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.053970
last_received_ts = 188.053314
last_seq = 460
current_ts = 188.070679
current_received_ts = 188.070084
current_seq = 461
count = 399
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.053970/460, current 188.070679/461: elapsed=16721.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.070679
last_received_ts = 188.070084
last_seq = 461
current_ts = 188.087402
current_received_ts = 188.086807
current_seq = 462
count = 400
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.070679/461, current 188.087402/462: elapsed=16722.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.087402
last_received_ts = 188.086807
last_seq = 462
current_ts = 188.104126
current_received_ts = 188.103531
current_seq = 463
count = 401
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.087402/462, current 188.104126/463: elapsed=16714.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.104126
last_received_ts = 188.103531
last_seq = 463
current_ts = 188.120850
current_received_ts = 188.120270
current_seq = 464
count = 402
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.104126/463, current 188.120850/464: elapsed=16725.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.120850
last_received_ts = 188.120270
last_seq = 464
current_ts = 188.137558
current_received_ts = 188.137146
current_seq = 465
count = 403
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.120850/464, current 188.137558/465: elapsed=16715.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.137558
last_received_ts = 188.137146
last_seq = 465
current_ts = 188.154282
current_received_ts = 188.153870
current_seq = 466
count = 404
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.137558/465, current 188.154282/466: elapsed=16725.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.154282
last_received_ts = 188.153870
last_seq = 466
current_ts = 188.171005
current_received_ts = 188.170395
current_seq = 467
count = 405
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.154282/466, current 188.171005/467: elapsed=16717.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.171005
last_received_ts = 188.170395
last_seq = 467
current_ts = 188.187714
current_received_ts = 188.187119
current_seq = 468
count = 406
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.171005/467, current 188.187714/468: elapsed=16718.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.187714
last_received_ts = 188.187119
last_seq = 468
current_ts = 188.204453
current_received_ts = 188.203827
current_seq = 469
count = 407
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.187714/468, current 188.204453/469: elapsed=16724.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.204453
last_received_ts = 188.203827
last_seq = 469
current_ts = 188.221161
current_received_ts = 188.220551
current_seq = 470
count = 408
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.204453/469, current 188.221161/470: elapsed=16718.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.221161
last_received_ts = 188.220551
last_seq = 470
current_ts = 188.237885
current_received_ts = 188.237167
current_seq = 471
count = 409
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.221161/470, current 188.237885/471: elapsed=16724.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.237885
last_received_ts = 188.237167
last_seq = 471
current_ts = 188.254608
current_received_ts = 188.253967
current_seq = 472
count = 410
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.237885/471, current 188.254608/472: elapsed=16714.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.254608
last_received_ts = 188.253967
last_seq = 472
current_ts = 188.271317
current_received_ts = 188.270721
current_seq = 473
count = 411
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.254608/472, current 188.271317/473: elapsed=16718.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.271317
last_received_ts = 188.270721
last_seq = 473
current_ts = 188.288040
current_received_ts = 188.287415
current_seq = 474
count = 412
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.271317/473, current 188.288040/474: elapsed=16720.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.288040
last_received_ts = 188.287415
last_seq = 474
current_ts = 188.304764
current_received_ts = 188.304169
current_seq = 475
count = 413
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.288040/474, current 188.304764/475: elapsed=16721.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.304764
last_received_ts = 188.304169
last_seq = 475
current_ts = 188.321472
current_received_ts = 188.320908
current_seq = 476
count = 414
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.304764/475, current 188.321472/476: elapsed=16718.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.321472
last_received_ts = 188.320908
last_seq = 476
current_ts = 188.338196
current_received_ts = 188.337585
current_seq = 477
count = 415
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.321472/476, current 188.338196/477: elapsed=16722.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.338196
last_received_ts = 188.337585
last_seq = 477
current_ts = 188.354919
current_received_ts = 188.354309
current_seq = 478
count = 416
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.338196/477, current 188.354919/478: elapsed=16724.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.354919
last_received_ts = 188.354309
last_seq = 478
current_ts = 188.371643
current_received_ts = 188.371048
current_seq = 479
count = 417
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.354919/478, current 188.371643/479: elapsed=16714.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.371643
last_received_ts = 188.371048
last_seq = 479
current_ts = 188.388351
current_received_ts = 188.387772
current_seq = 480
count = 418
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.371643/479, current 188.388351/480: elapsed=16720.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.388351
last_received_ts = 188.387772
last_seq = 480
current_ts = 188.405075
current_received_ts = 188.404480
current_seq = 481
count = 419
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.388351/480, current 188.405075/481: elapsed=16721.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.405075
last_received_ts = 188.404480
last_seq = 481
current_ts = 188.421799
current_received_ts = 188.421188
current_seq = 482
count = 420
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.405075/481, current 188.421799/482: elapsed=16721.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.421799
last_received_ts = 188.421188
last_seq = 482
current_ts = 188.438522
current_received_ts = 188.437912
current_seq = 483
count = 421
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.421799/482, current 188.438522/483: elapsed=16721.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.438522
last_received_ts = 188.437912
last_seq = 483
current_ts = 188.455246
current_received_ts = 188.454620
current_seq = 484
count = 422
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.438522/483, current 188.455246/484: elapsed=16721.0us expected=16793.2us +- 84.0us, error 0.4%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.455246
last_received_ts = 188.454620
last_seq = 484
current_ts = 188.471954
current_received_ts = 188.471359
current_seq = 485
count = 423
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.455246/484, current 188.471954/485: elapsed=16715.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.471954
last_received_ts = 188.471359
last_seq = 485
current_ts = 188.488678
current_received_ts = 188.488068
current_seq = 486
count = 424
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.471954/485, current 188.488678/486: elapsed=16715.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.488678
last_received_ts = 188.488068
last_seq = 486
current_ts = 188.505386
current_received_ts = 188.504776
current_seq = 487
count = 425
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.488678/486, current 188.505386/487: elapsed=16713.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.505386
last_received_ts = 188.504776
last_seq = 487
current_ts = 188.522095
current_received_ts = 188.521484
current_seq = 488
count = 426
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.505386/487, current 188.522095/488: elapsed=16716.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.522095
last_received_ts = 188.521484
last_seq = 488
current_ts = 188.538818
current_received_ts = 188.538208
current_seq = 489
count = 427
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.522095/488, current 188.538818/489: elapsed=16716.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: name = flip
last_ts = 188.538818
last_received_ts = 188.538208
last_seq = 489
current_ts = 188.555527
current_received_ts = 188.554916
current_seq = 490
count = 428
seq_step = 1
(kms_flip:6373) DEBUG: flip ts/seq: last 188.538818/489, current 188.555527/490: elapsed=16708.0us expected=16793.2us +- 84.0us, error 0.5%
(kms_flip:6373) DEBUG: inconsistent flip ts/seq: last 188.538818/489, current 188.555527/490: elapsed=16708.0us expected=16793.2us
(kms_flip:6373) DEBUG: expected 245114, counted 428, encoder type 2
(kms_flip:6373) DEBUG: dropped frames, expected 245114, counted 428, encoder type 2
(kms_flip:6373) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:6373) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:6373) igt_core-INFO: Stack trace:
(kms_flip:6373) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:6373) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:6373) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:6373) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:6373) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:6373) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:6373) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:6373) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (11.972s)
Starting dynamic subtest: C-eDP1
Dynamic subtest C-eDP1: SUCCESS (11.636s)
Subtest plain-flip-ts-check: FAIL (30.699s)