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

shard-lnl-2

IGT-Version: 2.3-g31b303e63 (x86_64) (Linux: 7.0.0-rc5-lgci-xe-xe-pw-163758v1-debug+ x86_64)

Using IGT_SRANDOM=1774377096 for randomisation
Opened device: /dev/dri/card1
Using monotonic timestamps
Starting subtest: plain-flip-ts-check-interruptible
Starting dynamic subtest: A-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Expected frametime: 16664us; measured 17035.9us +- 3.442us accuracy 0.06%
vblank interval differs from modeline! expected 16664.0us, measured 17036us +- 3.442us, difference 371.9us (108.0 sigma)
Event flip: expected 587, counted 593, passrate = 18.72%, encoder type 2
Expected frametime: 16664us; measured 16727.4us +- 5.537us accuracy 0.10%
vblank interval differs from modeline! expected 16664.0us, measured 16727us +- 5.537us, difference 63.4us (11.5 sigma)
Event flip: expected 598, counted 592, passrate = 19.59%, encoder type 2
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:428 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1891 run_test()
  #3 ../tests/kms_flip.c:2162 __igt_unique____real_main2047()
  #4 ../tests/kms_flip.c:2047 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-eDP1: FAIL (25.683s)
Starting dynamic subtest: B-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Expected frametime: 16664us; measured 16798.9us +- 3.403us accuracy 0.06%
vblank interval differs from modeline! expected 16664.0us, measured 16799us +- 3.403us, difference 134.9us (39.6 sigma)
Event flip: expected 595, counted 598, passrate = 81.27%, encoder type 2
Expected frametime: 16664us; measured 16691.1us +- 3.568us accuracy 0.06%
vblank interval differs from modeline! expected 16664.0us, measured 16691us +- 3.568us, difference 27.1us (7.6 sigma)
Event flip: expected 599, counted 601, passrate = 78.54%, encoder type 2
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:428 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1891 run_test()
  #3 ../tests/kms_flip.c:2162 __igt_unique____real_main2047()
  #4 ../tests/kms_flip.c:2047 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (25.985s)
Starting dynamic subtest: C-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Expected frametime: 16664us; measured 16552.9us +- 4.297us accuracy 0.08%
vblank interval differs from modeline! expected 16664.0us, measured 16553us +- 4.297us, difference 111.1us (25.8 sigma)
Event flip: expected 604, counted 603, passrate = 99.83%, encoder type 2
Dynamic subtest C-eDP1: SUCCESS (11.535s)
Subtest plain-flip-ts-check-interruptible: FAIL (63.215s)

Starting subtest: plain-flip-ts-check-interruptible
Starting dynamic subtest: A-eDP1
(kms_flip:5618) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1711:
(kms_flip:5618) CRITICAL: Failed assertion: !retried
(kms_flip:5618) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.005417/3378, current 230.022278/3379: elapsed=16861.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.022278
last_received_ts = 230.021469
last_seq = 3379
current_ts = 230.039154
current_received_ts = 230.038437
current_seq = 3380
count = 512
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.022278/3379, current 230.039154/3380: elapsed=16867.0us expected=16727.4us +- 83.6us, error 0.8%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.022278/3379, current 230.039154/3380: elapsed=16867.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.039154
last_received_ts = 230.038437
last_seq = 3380
current_ts = 230.056015
current_received_ts = 230.055252
current_seq = 3381
count = 513
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.039154/3380, current 230.056015/3381: elapsed=16860.0us expected=16727.4us +- 83.6us, error 0.8%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.039154/3380, current 230.056015/3381: elapsed=16860.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.056015
last_received_ts = 230.055252
last_seq = 3381
current_ts = 230.072876
current_received_ts = 230.072144
current_seq = 3382
count = 514
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.056015/3381, current 230.072876/3382: elapsed=16860.0us expected=16727.4us +- 83.6us, error 0.8%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.056015/3381, current 230.072876/3382: elapsed=16860.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.072876
last_received_ts = 230.072144
last_seq = 3382
current_ts = 230.089737
current_received_ts = 230.088898
current_seq = 3383
count = 515
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.072876/3382, current 230.089737/3383: elapsed=16861.0us expected=16727.4us +- 83.6us, error 0.8%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.072876/3382, current 230.089737/3383: elapsed=16861.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.089737
last_received_ts = 230.088898
last_seq = 3383
current_ts = 230.106598
current_received_ts = 230.105865
current_seq = 3384
count = 516
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.089737/3383, current 230.106598/3384: elapsed=16866.0us expected=16727.4us +- 83.6us, error 0.8%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.089737/3383, current 230.106598/3384: elapsed=16866.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.106598
last_received_ts = 230.105865
last_seq = 3384
current_ts = 230.123459
current_received_ts = 230.122696
current_seq = 3385
count = 517
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.106598/3384, current 230.123459/3385: elapsed=16855.0us expected=16727.4us +- 83.6us, error 0.8%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.106598/3384, current 230.123459/3385: elapsed=16855.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.123459
last_received_ts = 230.122696
last_seq = 3385
current_ts = 230.140320
current_received_ts = 230.139557
current_seq = 3386
count = 518
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.123459/3385, current 230.140320/3386: elapsed=16868.0us expected=16727.4us +- 83.6us, error 0.8%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.123459/3385, current 230.140320/3386: elapsed=16868.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.140320
last_received_ts = 230.139557
last_seq = 3386
current_ts = 230.157181
current_received_ts = 230.156448
current_seq = 3387
count = 519
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.140320/3386, current 230.157181/3387: elapsed=16863.0us expected=16727.4us +- 83.6us, error 0.8%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.140320/3386, current 230.157181/3387: elapsed=16863.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.157181
last_received_ts = 230.156448
last_seq = 3387
current_ts = 230.174042
current_received_ts = 230.173218
current_seq = 3388
count = 520
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.157181/3387, current 230.174042/3388: elapsed=16860.0us expected=16727.4us +- 83.6us, error 0.8%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.157181/3387, current 230.174042/3388: elapsed=16860.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.174042
last_received_ts = 230.173218
last_seq = 3388
current_ts = 230.190903
current_received_ts = 230.190186
current_seq = 3389
count = 521
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.174042/3388, current 230.190903/3389: elapsed=16863.0us expected=16727.4us +- 83.6us, error 0.8%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.174042/3388, current 230.190903/3389: elapsed=16863.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.190903
last_received_ts = 230.190186
last_seq = 3389
current_ts = 230.207764
current_received_ts = 230.207047
current_seq = 3390
count = 522
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.190903/3389, current 230.207764/3390: elapsed=16861.0us expected=16727.4us +- 83.6us, error 0.8%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.190903/3389, current 230.207764/3390: elapsed=16861.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.207764
last_received_ts = 230.207047
last_seq = 3390
current_ts = 230.224625
current_received_ts = 230.223831
current_seq = 3391
count = 523
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.207764/3390, current 230.224625/3391: elapsed=16854.0us expected=16727.4us +- 83.6us, error 0.8%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.207764/3390, current 230.224625/3391: elapsed=16854.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.224625
last_received_ts = 230.223831
last_seq = 3391
current_ts = 230.241486
current_received_ts = 230.240646
current_seq = 3392
count = 524
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.224625/3391, current 230.241486/3392: elapsed=16867.0us expected=16727.4us +- 83.6us, error 0.8%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.224625/3391, current 230.241486/3392: elapsed=16867.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.241486
last_received_ts = 230.240646
last_seq = 3392
current_ts = 230.258347
current_received_ts = 230.257523
current_seq = 3393
count = 525
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.241486/3392, current 230.258347/3393: elapsed=16860.0us expected=16727.4us +- 83.6us, error 0.8%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.241486/3392, current 230.258347/3393: elapsed=16860.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.258347
last_received_ts = 230.257523
last_seq = 3393
current_ts = 230.275208
current_received_ts = 230.274384
current_seq = 3394
count = 526
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.258347/3393, current 230.275208/3394: elapsed=16858.0us expected=16727.4us +- 83.6us, error 0.8%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.258347/3393, current 230.275208/3394: elapsed=16858.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.275208
last_received_ts = 230.274384
last_seq = 3394
current_ts = 230.292068
current_received_ts = 230.291214
current_seq = 3395
count = 527
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.275208/3394, current 230.292068/3395: elapsed=16868.0us expected=16727.4us +- 83.6us, error 0.8%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.275208/3394, current 230.292068/3395: elapsed=16868.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.292068
last_received_ts = 230.291214
last_seq = 3395
current_ts = 230.308929
current_received_ts = 230.308121
current_seq = 3396
count = 528
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.292068/3395, current 230.308929/3396: elapsed=16853.0us expected=16727.4us +- 83.6us, error 0.8%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.292068/3395, current 230.308929/3396: elapsed=16853.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.308929
last_received_ts = 230.308121
last_seq = 3396
current_ts = 230.325760
current_received_ts = 230.324905
current_seq = 3397
count = 529
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.308929/3396, current 230.325760/3397: elapsed=16831.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.308929/3396, current 230.325760/3397: elapsed=16831.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.325760
last_received_ts = 230.324905
last_seq = 3397
current_ts = 230.342606
current_received_ts = 230.341751
current_seq = 3398
count = 530
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.325760/3397, current 230.342606/3398: elapsed=16845.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.325760/3397, current 230.342606/3398: elapsed=16845.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.342606
last_received_ts = 230.341751
last_seq = 3398
current_ts = 230.359436
current_received_ts = 230.358627
current_seq = 3399
count = 531
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.342606/3398, current 230.359436/3399: elapsed=16830.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.342606/3398, current 230.359436/3399: elapsed=16830.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.359436
last_received_ts = 230.358627
last_seq = 3399
current_ts = 230.376282
current_received_ts = 230.375580
current_seq = 3400
count = 532
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.359436/3399, current 230.376282/3400: elapsed=16844.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.359436/3399, current 230.376282/3400: elapsed=16844.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.376282
last_received_ts = 230.375580
last_seq = 3400
current_ts = 230.393112
current_received_ts = 230.392395
current_seq = 3401
count = 533
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.376282/3400, current 230.393112/3401: elapsed=16837.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.376282/3400, current 230.393112/3401: elapsed=16837.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.393112
last_received_ts = 230.392395
last_seq = 3401
current_ts = 230.409958
current_received_ts = 230.409210
current_seq = 3402
count = 534
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.393112/3401, current 230.409958/3402: elapsed=16836.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.393112/3401, current 230.409958/3402: elapsed=16836.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.409958
last_received_ts = 230.409210
last_seq = 3402
current_ts = 230.426788
current_received_ts = 230.426056
current_seq = 3403
count = 535
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.409958/3402, current 230.426788/3403: elapsed=16837.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.409958/3402, current 230.426788/3403: elapsed=16837.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.426788
last_received_ts = 230.426056
last_seq = 3403
current_ts = 230.443634
current_received_ts = 230.442825
current_seq = 3404
count = 536
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.426788/3403, current 230.443634/3404: elapsed=16839.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.426788/3403, current 230.443634/3404: elapsed=16839.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.443634
last_received_ts = 230.442825
last_seq = 3404
current_ts = 230.460464
current_received_ts = 230.459763
current_seq = 3405
count = 537
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.443634/3404, current 230.460464/3405: elapsed=16842.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.443634/3404, current 230.460464/3405: elapsed=16842.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.460464
last_received_ts = 230.459763
last_seq = 3405
current_ts = 230.477310
current_received_ts = 230.476593
current_seq = 3406
count = 538
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.460464/3405, current 230.477310/3406: elapsed=16836.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.460464/3405, current 230.477310/3406: elapsed=16836.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.477310
last_received_ts = 230.476593
last_seq = 3406
current_ts = 230.494141
current_received_ts = 230.493362
current_seq = 3407
count = 539
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.477310/3406, current 230.494141/3407: elapsed=16835.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.477310/3406, current 230.494141/3407: elapsed=16835.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.494141
last_received_ts = 230.493362
last_seq = 3407
current_ts = 230.510986
current_received_ts = 230.510223
current_seq = 3408
count = 540
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.494141/3407, current 230.510986/3408: elapsed=16842.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.494141/3407, current 230.510986/3408: elapsed=16842.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.510986
last_received_ts = 230.510223
last_seq = 3408
current_ts = 230.527817
current_received_ts = 230.527084
current_seq = 3409
count = 541
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.510986/3408, current 230.527817/3409: elapsed=16836.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.510986/3408, current 230.527817/3409: elapsed=16836.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.527817
last_received_ts = 230.527084
last_seq = 3409
current_ts = 230.544662
current_received_ts = 230.543976
current_seq = 3410
count = 542
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.527817/3409, current 230.544662/3410: elapsed=16840.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.527817/3409, current 230.544662/3410: elapsed=16840.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.544662
last_received_ts = 230.543976
last_seq = 3410
current_ts = 230.561493
current_received_ts = 230.560776
current_seq = 3411
count = 543
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.544662/3410, current 230.561493/3411: elapsed=16836.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.544662/3410, current 230.561493/3411: elapsed=16836.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.561493
last_received_ts = 230.560776
last_seq = 3411
current_ts = 230.578339
current_received_ts = 230.577637
current_seq = 3412
count = 544
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.561493/3411, current 230.578339/3412: elapsed=16840.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.561493/3411, current 230.578339/3412: elapsed=16840.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.578339
last_received_ts = 230.577637
last_seq = 3412
current_ts = 230.595169
current_received_ts = 230.594421
current_seq = 3413
count = 545
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.578339/3412, current 230.595169/3413: elapsed=16833.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.578339/3412, current 230.595169/3413: elapsed=16833.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.595169
last_received_ts = 230.594421
last_seq = 3413
current_ts = 230.612015
current_received_ts = 230.611282
current_seq = 3414
count = 546
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.595169/3413, current 230.612015/3414: elapsed=16844.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.595169/3413, current 230.612015/3414: elapsed=16844.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.612015
last_received_ts = 230.611282
last_seq = 3414
current_ts = 230.628845
current_received_ts = 230.628098
current_seq = 3415
count = 547
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.612015/3414, current 230.628845/3415: elapsed=16836.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.612015/3414, current 230.628845/3415: elapsed=16836.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.628845
last_received_ts = 230.628098
last_seq = 3415
current_ts = 230.645676
current_received_ts = 230.644974
current_seq = 3416
count = 548
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.628845/3415, current 230.645676/3416: elapsed=16836.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.628845/3415, current 230.645676/3416: elapsed=16836.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.645676
last_received_ts = 230.644974
last_seq = 3416
current_ts = 230.662521
current_received_ts = 230.661774
current_seq = 3417
count = 549
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.645676/3416, current 230.662521/3417: elapsed=16837.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.645676/3416, current 230.662521/3417: elapsed=16837.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.662521
last_received_ts = 230.661774
last_seq = 3417
current_ts = 230.679352
current_received_ts = 230.678619
current_seq = 3418
count = 550
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.662521/3417, current 230.679352/3418: elapsed=16839.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.662521/3417, current 230.679352/3418: elapsed=16839.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.679352
last_received_ts = 230.678619
last_seq = 3418
current_ts = 230.696198
current_received_ts = 230.695465
current_seq = 3419
count = 551
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.679352/3418, current 230.696198/3419: elapsed=16840.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.679352/3418, current 230.696198/3419: elapsed=16840.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.696198
last_received_ts = 230.695465
last_seq = 3419
current_ts = 230.713028
current_received_ts = 230.712296
current_seq = 3420
count = 552
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.696198/3419, current 230.713028/3420: elapsed=16835.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.696198/3419, current 230.713028/3420: elapsed=16835.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.713028
last_received_ts = 230.712296
last_seq = 3420
current_ts = 230.729874
current_received_ts = 230.729126
current_seq = 3421
count = 553
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.713028/3420, current 230.729874/3421: elapsed=16840.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.713028/3420, current 230.729874/3421: elapsed=16840.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.729874
last_received_ts = 230.729126
last_seq = 3421
current_ts = 230.746704
current_received_ts = 230.745956
current_seq = 3422
count = 554
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.729874/3421, current 230.746704/3422: elapsed=16834.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.729874/3421, current 230.746704/3422: elapsed=16834.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.746704
last_received_ts = 230.745956
last_seq = 3422
current_ts = 230.763550
current_received_ts = 230.762817
current_seq = 3423
count = 555
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.746704/3422, current 230.763550/3423: elapsed=16841.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.746704/3422, current 230.763550/3423: elapsed=16841.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.763550
last_received_ts = 230.762817
last_seq = 3423
current_ts = 230.780380
current_received_ts = 230.779663
current_seq = 3424
count = 556
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.763550/3423, current 230.780380/3424: elapsed=16838.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.763550/3423, current 230.780380/3424: elapsed=16838.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.780380
last_received_ts = 230.779663
last_seq = 3424
current_ts = 230.797226
current_received_ts = 230.796402
current_seq = 3425
count = 557
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.780380/3424, current 230.797226/3425: elapsed=16837.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.780380/3424, current 230.797226/3425: elapsed=16837.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.797226
last_received_ts = 230.796402
last_seq = 3425
current_ts = 230.814056
current_received_ts = 230.813324
current_seq = 3426
count = 558
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.797226/3425, current 230.814056/3426: elapsed=16838.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.797226/3425, current 230.814056/3426: elapsed=16838.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.814056
last_received_ts = 230.813324
last_seq = 3426
current_ts = 230.830902
current_received_ts = 230.830170
current_seq = 3427
count = 559
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.814056/3426, current 230.830902/3427: elapsed=16841.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.814056/3426, current 230.830902/3427: elapsed=16841.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.830902
last_received_ts = 230.830170
last_seq = 3427
current_ts = 230.847733
current_received_ts = 230.847000
current_seq = 3428
count = 560
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.830902/3427, current 230.847733/3428: elapsed=16836.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.830902/3427, current 230.847733/3428: elapsed=16836.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.847733
last_received_ts = 230.847000
last_seq = 3428
current_ts = 230.864578
current_received_ts = 230.863739
current_seq = 3429
count = 561
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.847733/3428, current 230.864578/3429: elapsed=16834.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.847733/3428, current 230.864578/3429: elapsed=16834.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.864578
last_received_ts = 230.863739
last_seq = 3429
current_ts = 230.881409
current_received_ts = 230.880569
current_seq = 3430
count = 562
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.864578/3429, current 230.881409/3430: elapsed=16841.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.864578/3429, current 230.881409/3430: elapsed=16841.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.881409
last_received_ts = 230.880569
last_seq = 3430
current_ts = 230.898254
current_received_ts = 230.897552
current_seq = 3431
count = 563
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.881409/3430, current 230.898254/3431: elapsed=16834.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.881409/3430, current 230.898254/3431: elapsed=16834.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.898254
last_received_ts = 230.897552
last_seq = 3431
current_ts = 230.915085
current_received_ts = 230.914261
current_seq = 3432
count = 564
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.898254/3431, current 230.915085/3432: elapsed=16841.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.898254/3431, current 230.915085/3432: elapsed=16841.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.915085
last_received_ts = 230.914261
last_seq = 3432
current_ts = 230.931931
current_received_ts = 230.931122
current_seq = 3433
count = 565
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.915085/3432, current 230.931931/3433: elapsed=16842.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.915085/3432, current 230.931931/3433: elapsed=16842.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.931931
last_received_ts = 230.931122
last_seq = 3433
current_ts = 230.948761
current_received_ts = 230.947922
current_seq = 3434
count = 566
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.931931/3433, current 230.948761/3434: elapsed=16832.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.931931/3433, current 230.948761/3434: elapsed=16832.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.948761
last_received_ts = 230.947922
last_seq = 3434
current_ts = 230.965607
current_received_ts = 230.964767
current_seq = 3435
count = 567
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.948761/3434, current 230.965607/3435: elapsed=16841.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.948761/3434, current 230.965607/3435: elapsed=16841.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.965607
last_received_ts = 230.964767
last_seq = 3435
current_ts = 230.982437
current_received_ts = 230.981598
current_seq = 3436
count = 568
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.965607/3435, current 230.982437/3436: elapsed=16840.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.965607/3435, current 230.982437/3436: elapsed=16840.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.982437
last_received_ts = 230.981598
last_seq = 3436
current_ts = 230.999283
current_received_ts = 230.998428
current_seq = 3437
count = 569
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.982437/3436, current 230.999283/3437: elapsed=16840.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.982437/3436, current 230.999283/3437: elapsed=16840.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 230.999283
last_received_ts = 230.998428
last_seq = 3437
current_ts = 231.016113
current_received_ts = 231.015259
current_seq = 3438
count = 570
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 230.999283/3437, current 231.016113/3438: elapsed=16832.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 230.999283/3437, current 231.016113/3438: elapsed=16832.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.016113
last_received_ts = 231.015259
last_seq = 3438
current_ts = 231.032959
current_received_ts = 231.032211
current_seq = 3439
count = 571
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.016113/3438, current 231.032959/3439: elapsed=16839.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.016113/3438, current 231.032959/3439: elapsed=16839.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.032959
last_received_ts = 231.032211
last_seq = 3439
current_ts = 231.049789
current_received_ts = 231.048965
current_seq = 3440
count = 572
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.032959/3439, current 231.049789/3440: elapsed=16838.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.032959/3439, current 231.049789/3440: elapsed=16838.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.049789
last_received_ts = 231.048965
last_seq = 3440
current_ts = 231.066635
current_received_ts = 231.065933
current_seq = 3441
count = 573
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.049789/3440, current 231.066635/3441: elapsed=16840.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.049789/3440, current 231.066635/3441: elapsed=16840.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.066635
last_received_ts = 231.065933
last_seq = 3441
current_ts = 231.083466
current_received_ts = 231.082733
current_seq = 3442
count = 574
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.066635/3441, current 231.083466/3442: elapsed=16834.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.066635/3441, current 231.083466/3442: elapsed=16834.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.083466
last_received_ts = 231.082733
last_seq = 3442
current_ts = 231.100311
current_received_ts = 231.099503
current_seq = 3443
count = 575
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.083466/3442, current 231.100311/3443: elapsed=16843.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.083466/3442, current 231.100311/3443: elapsed=16843.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.100311
last_received_ts = 231.099503
last_seq = 3443
current_ts = 231.117142
current_received_ts = 231.116409
current_seq = 3444
count = 576
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.100311/3443, current 231.117142/3444: elapsed=16839.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.100311/3443, current 231.117142/3444: elapsed=16839.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.117142
last_received_ts = 231.116409
last_seq = 3444
current_ts = 231.133987
current_received_ts = 231.133224
current_seq = 3445
count = 577
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.117142/3444, current 231.133987/3445: elapsed=16837.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.117142/3444, current 231.133987/3445: elapsed=16837.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.133987
last_received_ts = 231.133224
last_seq = 3445
current_ts = 231.150818
current_received_ts = 231.150085
current_seq = 3446
count = 578
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.133987/3445, current 231.150818/3446: elapsed=16836.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.133987/3445, current 231.150818/3446: elapsed=16836.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.150818
last_received_ts = 231.150085
last_seq = 3446
current_ts = 231.167664
current_received_ts = 231.166946
current_seq = 3447
count = 579
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.150818/3446, current 231.167664/3447: elapsed=16835.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.150818/3446, current 231.167664/3447: elapsed=16835.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.167664
last_received_ts = 231.166946
last_seq = 3447
current_ts = 231.184494
current_received_ts = 231.183762
current_seq = 3448
count = 580
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.167664/3447, current 231.184494/3448: elapsed=16838.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.167664/3447, current 231.184494/3448: elapsed=16838.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.184494
last_received_ts = 231.183762
last_seq = 3448
current_ts = 231.201340
current_received_ts = 231.200516
current_seq = 3449
count = 581
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.184494/3448, current 231.201340/3449: elapsed=16842.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.184494/3448, current 231.201340/3449: elapsed=16842.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.201340
last_received_ts = 231.200516
last_seq = 3449
current_ts = 231.218185
current_received_ts = 231.217484
current_seq = 3450
count = 582
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.201340/3449, current 231.218185/3450: elapsed=16841.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.201340/3449, current 231.218185/3450: elapsed=16841.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.218185
last_received_ts = 231.217484
last_seq = 3450
current_ts = 231.235016
current_received_ts = 231.234299
current_seq = 3451
count = 583
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.218185/3450, current 231.235016/3451: elapsed=16836.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.218185/3450, current 231.235016/3451: elapsed=16836.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.235016
last_received_ts = 231.234299
last_seq = 3451
current_ts = 231.251846
current_received_ts = 231.251053
current_seq = 3452
count = 584
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.235016/3451, current 231.251846/3452: elapsed=16837.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.235016/3451, current 231.251846/3452: elapsed=16837.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.251846
last_received_ts = 231.251053
last_seq = 3452
current_ts = 231.268692
current_received_ts = 231.267975
current_seq = 3453
count = 585
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.251846/3452, current 231.268692/3453: elapsed=16835.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.251846/3452, current 231.268692/3453: elapsed=16835.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.268692
last_received_ts = 231.267975
last_seq = 3453
current_ts = 231.285522
current_received_ts = 231.284790
current_seq = 3454
count = 586
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.268692/3453, current 231.285522/3454: elapsed=16840.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.268692/3453, current 231.285522/3454: elapsed=16840.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.285522
last_received_ts = 231.284790
last_seq = 3454
current_ts = 231.302368
current_received_ts = 231.301651
current_seq = 3455
count = 587
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.285522/3454, current 231.302368/3455: elapsed=16837.0us expected=16727.4us +- 83.6us, error 0.7%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.285522/3454, current 231.302368/3455: elapsed=16837.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.302368
last_received_ts = 231.301651
last_seq = 3455
current_ts = 231.319183
current_received_ts = 231.318390
current_seq = 3456
count = 588
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.302368/3455, current 231.319183/3456: elapsed=16816.0us expected=16727.4us +- 83.6us, error 0.5%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.302368/3455, current 231.319183/3456: elapsed=16816.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.319183
last_received_ts = 231.318390
last_seq = 3456
current_ts = 231.335999
current_received_ts = 231.335236
current_seq = 3457
count = 589
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.319183/3456, current 231.335999/3457: elapsed=16816.0us expected=16727.4us +- 83.6us, error 0.5%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.319183/3456, current 231.335999/3457: elapsed=16816.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.335999
last_received_ts = 231.335236
last_seq = 3457
current_ts = 231.352814
current_received_ts = 231.352066
current_seq = 3458
count = 590
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.335999/3457, current 231.352814/3458: elapsed=16818.0us expected=16727.4us +- 83.6us, error 0.5%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.335999/3457, current 231.352814/3458: elapsed=16818.0us expected=16727.4us
(kms_flip:5618) DEBUG: name = flip
last_ts = 231.352814
last_received_ts = 231.352066
last_seq = 3458
current_ts = 231.369629
current_received_ts = 231.368912
current_seq = 3459
count = 591
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 231.352814/3458, current 231.369629/3459: elapsed=16821.0us expected=16727.4us +- 83.6us, error 0.6%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 231.352814/3458, current 231.369629/3459: elapsed=16821.0us expected=16727.4us
(kms_flip:5618) INFO: Event flip: expected 598, counted 592, passrate = 19.59%, encoder type 2
(kms_flip:5618) DEBUG: dropped frames, expected 598, counted 592, passrate = 19.59%, encoder type 2
(kms_flip:5618) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1711:
(kms_flip:5618) CRITICAL: Failed assertion: !retried
(kms_flip:5618) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:5618) igt_core-INFO: Stack trace:
(kms_flip:5618) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:5618) igt_core-INFO:   #1 ../tests/kms_flip.c:428 run_test_on_crtc_set.constprop.0()
(kms_flip:5618) igt_core-INFO:   #2 ../tests/kms_flip.c:1891 run_test()
(kms_flip:5618) igt_core-INFO:   #3 ../tests/kms_flip.c:2162 __igt_unique____real_main2047()
(kms_flip:5618) igt_core-INFO:   #4 ../tests/kms_flip.c:2047 main()
(kms_flip:5618) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:5618) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:5618) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (25.683s)
Starting dynamic subtest: B-eDP1
(kms_flip:5618) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1711:
(kms_flip:5618) CRITICAL: Failed assertion: !retried
(kms_flip:5618) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.087006/1158, current 256.103516/1159: elapsed=16501.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.103516
last_received_ts = 256.102692
last_seq = 1159
current_ts = 256.120026
current_received_ts = 256.119171
current_seq = 1160
count = 521
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.103516/1159, current 256.120026/1160: elapsed=16498.0us expected=16691.1us +- 83.5us, error 1.2%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.103516/1159, current 256.120026/1160: elapsed=16498.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.120026
last_received_ts = 256.119171
last_seq = 1160
current_ts = 256.136505
current_received_ts = 256.135681
current_seq = 1161
count = 522
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.120026/1160, current 256.136505/1161: elapsed=16501.0us expected=16691.1us +- 83.5us, error 1.1%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.120026/1160, current 256.136505/1161: elapsed=16501.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.136505
last_received_ts = 256.135681
last_seq = 1161
current_ts = 256.153015
current_received_ts = 256.152161
current_seq = 1162
count = 523
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.136505/1161, current 256.153015/1162: elapsed=16510.0us expected=16691.1us +- 83.5us, error 1.1%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.136505/1161, current 256.153015/1162: elapsed=16510.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.153015
last_received_ts = 256.152161
last_seq = 1162
current_ts = 256.169525
current_received_ts = 256.168671
current_seq = 1163
count = 524
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.153015/1162, current 256.169525/1163: elapsed=16496.0us expected=16691.1us +- 83.5us, error 1.2%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.153015/1162, current 256.169525/1163: elapsed=16496.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.169525
last_received_ts = 256.168671
last_seq = 1163
current_ts = 256.186035
current_received_ts = 256.185150
current_seq = 1164
count = 525
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.169525/1163, current 256.186035/1164: elapsed=16501.0us expected=16691.1us +- 83.5us, error 1.1%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.169525/1163, current 256.186035/1164: elapsed=16501.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.186035
last_received_ts = 256.185150
last_seq = 1164
current_ts = 256.202545
current_received_ts = 256.201691
current_seq = 1165
count = 526
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.186035/1164, current 256.202545/1165: elapsed=16510.0us expected=16691.1us +- 83.5us, error 1.1%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.186035/1164, current 256.202545/1165: elapsed=16510.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.202545
last_received_ts = 256.201691
last_seq = 1165
current_ts = 256.219025
current_received_ts = 256.218170
current_seq = 1166
count = 527
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.202545/1165, current 256.219025/1166: elapsed=16495.0us expected=16691.1us +- 83.5us, error 1.2%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.202545/1165, current 256.219025/1166: elapsed=16495.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.219025
last_received_ts = 256.218170
last_seq = 1166
current_ts = 256.235535
current_received_ts = 256.234680
current_seq = 1167
count = 528
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.219025/1166, current 256.235535/1167: elapsed=16506.0us expected=16691.1us +- 83.5us, error 1.1%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.219025/1166, current 256.235535/1167: elapsed=16506.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.235535
last_received_ts = 256.234680
last_seq = 1167
current_ts = 256.252045
current_received_ts = 256.251190
current_seq = 1168
count = 529
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.235535/1167, current 256.252045/1168: elapsed=16502.0us expected=16691.1us +- 83.5us, error 1.1%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.235535/1167, current 256.252045/1168: elapsed=16502.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.252045
last_received_ts = 256.251190
last_seq = 1168
current_ts = 256.268555
current_received_ts = 256.267700
current_seq = 1169
count = 530
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.252045/1168, current 256.268555/1169: elapsed=16507.0us expected=16691.1us +- 83.5us, error 1.1%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.252045/1168, current 256.268555/1169: elapsed=16507.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.268555
last_received_ts = 256.267700
last_seq = 1169
current_ts = 256.285034
current_received_ts = 256.284180
current_seq = 1170
count = 531
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.268555/1169, current 256.285034/1170: elapsed=16502.0us expected=16691.1us +- 83.5us, error 1.1%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.268555/1169, current 256.285034/1170: elapsed=16502.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.285034
last_received_ts = 256.284180
last_seq = 1170
current_ts = 256.301544
current_received_ts = 256.300690
current_seq = 1171
count = 532
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.285034/1170, current 256.301544/1171: elapsed=16498.0us expected=16691.1us +- 83.5us, error 1.2%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.285034/1170, current 256.301544/1171: elapsed=16498.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.301544
last_received_ts = 256.300690
last_seq = 1171
current_ts = 256.318054
current_received_ts = 256.317200
current_seq = 1172
count = 533
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.301544/1171, current 256.318054/1172: elapsed=16525.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.301544/1171, current 256.318054/1172: elapsed=16525.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.318054
last_received_ts = 256.317200
last_seq = 1172
current_ts = 256.334595
current_received_ts = 256.333771
current_seq = 1173
count = 534
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.318054/1172, current 256.334595/1173: elapsed=16515.0us expected=16691.1us +- 83.5us, error 1.1%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.318054/1172, current 256.334595/1173: elapsed=16515.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.334595
last_received_ts = 256.333771
last_seq = 1173
current_ts = 256.351105
current_received_ts = 256.350250
current_seq = 1174
count = 535
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.334595/1173, current 256.351105/1174: elapsed=16529.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.334595/1173, current 256.351105/1174: elapsed=16529.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.351105
last_received_ts = 256.350250
last_seq = 1174
current_ts = 256.367615
current_received_ts = 256.366791
current_seq = 1175
count = 536
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.351105/1174, current 256.367615/1175: elapsed=16520.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.351105/1174, current 256.367615/1175: elapsed=16520.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.367615
last_received_ts = 256.366791
last_seq = 1175
current_ts = 256.384155
current_received_ts = 256.383301
current_seq = 1176
count = 537
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.367615/1175, current 256.384155/1176: elapsed=16517.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.367615/1175, current 256.384155/1176: elapsed=16517.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.384155
last_received_ts = 256.383301
last_seq = 1176
current_ts = 256.400665
current_received_ts = 256.399841
current_seq = 1177
count = 538
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.384155/1176, current 256.400665/1177: elapsed=16519.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.384155/1176, current 256.400665/1177: elapsed=16519.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.400665
last_received_ts = 256.399841
last_seq = 1177
current_ts = 256.417206
current_received_ts = 256.416321
current_seq = 1178
count = 539
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.400665/1177, current 256.417206/1178: elapsed=16530.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.400665/1177, current 256.417206/1178: elapsed=16530.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.417206
last_received_ts = 256.416321
last_seq = 1178
current_ts = 256.433716
current_received_ts = 256.432861
current_seq = 1179
count = 540
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.417206/1178, current 256.433716/1179: elapsed=16521.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.417206/1178, current 256.433716/1179: elapsed=16521.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.433716
last_received_ts = 256.432861
last_seq = 1179
current_ts = 256.450226
current_received_ts = 256.449402
current_seq = 1180
count = 541
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.433716/1179, current 256.450226/1180: elapsed=16521.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.433716/1179, current 256.450226/1180: elapsed=16521.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.450226
last_received_ts = 256.449402
last_seq = 1180
current_ts = 256.466766
current_received_ts = 256.465912
current_seq = 1181
count = 542
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.450226/1180, current 256.466766/1181: elapsed=16520.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.450226/1180, current 256.466766/1181: elapsed=16520.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.466766
last_received_ts = 256.465912
last_seq = 1181
current_ts = 256.483276
current_received_ts = 256.482544
current_seq = 1182
count = 543
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.466766/1181, current 256.483276/1182: elapsed=16519.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.466766/1181, current 256.483276/1182: elapsed=16519.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.483276
last_received_ts = 256.482544
last_seq = 1182
current_ts = 256.499786
current_received_ts = 256.499023
current_seq = 1183
count = 544
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.483276/1182, current 256.499786/1183: elapsed=16524.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.483276/1182, current 256.499786/1183: elapsed=16524.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.499786
last_received_ts = 256.499023
last_seq = 1183
current_ts = 256.516327
current_received_ts = 256.515564
current_seq = 1184
count = 545
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.499786/1183, current 256.516327/1184: elapsed=16515.0us expected=16691.1us +- 83.5us, error 1.1%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.499786/1183, current 256.516327/1184: elapsed=16515.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.516327
last_received_ts = 256.515564
last_seq = 1184
current_ts = 256.532837
current_received_ts = 256.532104
current_seq = 1185
count = 546
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.516327/1184, current 256.532837/1185: elapsed=16525.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.516327/1184, current 256.532837/1185: elapsed=16525.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.532837
last_received_ts = 256.532104
last_seq = 1185
current_ts = 256.549377
current_received_ts = 256.548553
current_seq = 1186
count = 547
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.532837/1185, current 256.549377/1186: elapsed=16525.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.532837/1185, current 256.549377/1186: elapsed=16525.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.549377
last_received_ts = 256.548553
last_seq = 1186
current_ts = 256.565887
current_received_ts = 256.565155
current_seq = 1187
count = 548
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.549377/1186, current 256.565887/1187: elapsed=16517.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.549377/1186, current 256.565887/1187: elapsed=16517.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.565887
last_received_ts = 256.565155
last_seq = 1187
current_ts = 256.582397
current_received_ts = 256.581665
current_seq = 1188
count = 549
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.565887/1187, current 256.582397/1188: elapsed=16522.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.565887/1187, current 256.582397/1188: elapsed=16522.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.582397
last_received_ts = 256.581665
last_seq = 1188
current_ts = 256.598938
current_received_ts = 256.598206
current_seq = 1189
count = 550
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.582397/1188, current 256.598938/1189: elapsed=16524.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.582397/1188, current 256.598938/1189: elapsed=16524.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.598938
last_received_ts = 256.598206
last_seq = 1189
current_ts = 256.615448
current_received_ts = 256.614685
current_seq = 1190
count = 551
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.598938/1189, current 256.615448/1190: elapsed=16522.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.598938/1189, current 256.615448/1190: elapsed=16522.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.615448
last_received_ts = 256.614685
last_seq = 1190
current_ts = 256.631989
current_received_ts = 256.631226
current_seq = 1191
count = 552
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.615448/1190, current 256.631989/1191: elapsed=16524.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.615448/1190, current 256.631989/1191: elapsed=16524.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.631989
last_received_ts = 256.631226
last_seq = 1191
current_ts = 256.648499
current_received_ts = 256.647766
current_seq = 1192
count = 553
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.631989/1191, current 256.648499/1192: elapsed=16522.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.631989/1191, current 256.648499/1192: elapsed=16522.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.648499
last_received_ts = 256.647766
last_seq = 1192
current_ts = 256.665009
current_received_ts = 256.664246
current_seq = 1193
count = 554
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.648499/1192, current 256.665009/1193: elapsed=16522.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.648499/1192, current 256.665009/1193: elapsed=16522.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.665009
last_received_ts = 256.664246
last_seq = 1193
current_ts = 256.681549
current_received_ts = 256.680817
current_seq = 1194
count = 555
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.665009/1193, current 256.681549/1194: elapsed=16519.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.665009/1193, current 256.681549/1194: elapsed=16519.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.681549
last_received_ts = 256.680817
last_seq = 1194
current_ts = 256.698059
current_received_ts = 256.697296
current_seq = 1195
count = 556
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.681549/1194, current 256.698059/1195: elapsed=16519.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.681549/1194, current 256.698059/1195: elapsed=16519.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.698059
last_received_ts = 256.697296
last_seq = 1195
current_ts = 256.714569
current_received_ts = 256.713867
current_seq = 1196
count = 557
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.698059/1195, current 256.714569/1196: elapsed=16519.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.698059/1195, current 256.714569/1196: elapsed=16519.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.714569
last_received_ts = 256.713867
last_seq = 1196
current_ts = 256.731110
current_received_ts = 256.730377
current_seq = 1197
count = 558
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.714569/1196, current 256.731110/1197: elapsed=16528.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.714569/1196, current 256.731110/1197: elapsed=16528.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.731110
last_received_ts = 256.730377
last_seq = 1197
current_ts = 256.747620
current_received_ts = 256.746887
current_seq = 1198
count = 559
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.731110/1197, current 256.747620/1198: elapsed=16515.0us expected=16691.1us +- 83.5us, error 1.1%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.731110/1197, current 256.747620/1198: elapsed=16515.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.747620
last_received_ts = 256.746887
last_seq = 1198
current_ts = 256.764130
current_received_ts = 256.763397
current_seq = 1199
count = 560
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.747620/1198, current 256.764130/1199: elapsed=16521.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.747620/1198, current 256.764130/1199: elapsed=16521.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.764130
last_received_ts = 256.763397
last_seq = 1199
current_ts = 256.780670
current_received_ts = 256.779938
current_seq = 1200
count = 561
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.764130/1199, current 256.780670/1200: elapsed=16528.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.764130/1199, current 256.780670/1200: elapsed=16528.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.780670
last_received_ts = 256.779938
last_seq = 1200
current_ts = 256.797180
current_received_ts = 256.796417
current_seq = 1201
count = 562
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.780670/1200, current 256.797180/1201: elapsed=16522.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.780670/1200, current 256.797180/1201: elapsed=16522.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.797180
last_received_ts = 256.796417
last_seq = 1201
current_ts = 256.813690
current_received_ts = 256.812988
current_seq = 1202
count = 563
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.797180/1201, current 256.813690/1202: elapsed=16515.0us expected=16691.1us +- 83.5us, error 1.1%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.797180/1201, current 256.813690/1202: elapsed=16515.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.813690
last_received_ts = 256.812988
last_seq = 1202
current_ts = 256.830231
current_received_ts = 256.829407
current_seq = 1203
count = 564
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.813690/1202, current 256.830231/1203: elapsed=16530.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.813690/1202, current 256.830231/1203: elapsed=16530.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.830231
last_received_ts = 256.829407
last_seq = 1203
current_ts = 256.846741
current_received_ts = 256.846039
current_seq = 1204
count = 565
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.830231/1203, current 256.846741/1204: elapsed=16517.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.830231/1203, current 256.846741/1204: elapsed=16517.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.846741
last_received_ts = 256.846039
last_seq = 1204
current_ts = 256.863281
current_received_ts = 256.862549
current_seq = 1205
count = 566
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.846741/1204, current 256.863281/1205: elapsed=16518.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.846741/1204, current 256.863281/1205: elapsed=16518.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.863281
last_received_ts = 256.862549
last_seq = 1205
current_ts = 256.879791
current_received_ts = 256.879059
current_seq = 1206
count = 567
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.863281/1205, current 256.879791/1206: elapsed=16530.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.863281/1205, current 256.879791/1206: elapsed=16530.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.879791
last_received_ts = 256.879059
last_seq = 1206
current_ts = 256.896332
current_received_ts = 256.895569
current_seq = 1207
count = 568
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.879791/1206, current 256.896332/1207: elapsed=16521.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.879791/1206, current 256.896332/1207: elapsed=16521.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.896332
last_received_ts = 256.895569
last_seq = 1207
current_ts = 256.912842
current_received_ts = 256.912109
current_seq = 1208
count = 569
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.896332/1207, current 256.912842/1208: elapsed=16519.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.896332/1207, current 256.912842/1208: elapsed=16519.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.912842
last_received_ts = 256.912109
last_seq = 1208
current_ts = 256.929352
current_received_ts = 256.928650
current_seq = 1209
count = 570
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.912842/1208, current 256.929352/1209: elapsed=16520.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.912842/1208, current 256.929352/1209: elapsed=16520.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.929352
last_received_ts = 256.928650
last_seq = 1209
current_ts = 256.945892
current_received_ts = 256.945160
current_seq = 1210
count = 571
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.929352/1209, current 256.945892/1210: elapsed=16521.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.929352/1209, current 256.945892/1210: elapsed=16521.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.945892
last_received_ts = 256.945160
last_seq = 1210
current_ts = 256.962402
current_received_ts = 256.961670
current_seq = 1211
count = 572
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.945892/1210, current 256.962402/1211: elapsed=16521.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.945892/1210, current 256.962402/1211: elapsed=16521.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.962402
last_received_ts = 256.961670
last_seq = 1211
current_ts = 256.978912
current_received_ts = 256.978180
current_seq = 1212
count = 573
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.962402/1211, current 256.978912/1212: elapsed=16520.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.962402/1211, current 256.978912/1212: elapsed=16520.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.978912
last_received_ts = 256.978180
last_seq = 1212
current_ts = 256.995453
current_received_ts = 256.994720
current_seq = 1213
count = 574
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.978912/1212, current 256.995453/1213: elapsed=16523.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.978912/1212, current 256.995453/1213: elapsed=16523.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 256.995453
last_received_ts = 256.994720
last_seq = 1213
current_ts = 257.011963
current_received_ts = 257.011139
current_seq = 1214
count = 575
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 256.995453/1213, current 257.011963/1214: elapsed=16528.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 256.995453/1213, current 257.011963/1214: elapsed=16528.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.011963
last_received_ts = 257.011139
last_seq = 1214
current_ts = 257.028503
current_received_ts = 257.027649
current_seq = 1215
count = 576
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.011963/1214, current 257.028503/1215: elapsed=16521.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.011963/1214, current 257.028503/1215: elapsed=16521.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.028503
last_received_ts = 257.027649
last_seq = 1215
current_ts = 257.045013
current_received_ts = 257.044250
current_seq = 1216
count = 577
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.028503/1215, current 257.045013/1216: elapsed=16514.0us expected=16691.1us +- 83.5us, error 1.1%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.028503/1215, current 257.045013/1216: elapsed=16514.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.045013
last_received_ts = 257.044250
last_seq = 1216
current_ts = 257.061523
current_received_ts = 257.060791
current_seq = 1217
count = 578
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.045013/1216, current 257.061523/1217: elapsed=16526.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.045013/1216, current 257.061523/1217: elapsed=16526.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.061523
last_received_ts = 257.060791
last_seq = 1217
current_ts = 257.078064
current_received_ts = 257.077209
current_seq = 1218
count = 579
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.061523/1217, current 257.078064/1218: elapsed=16524.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.061523/1217, current 257.078064/1218: elapsed=16524.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.078064
last_received_ts = 257.077209
last_seq = 1218
current_ts = 257.094574
current_received_ts = 257.093842
current_seq = 1219
count = 580
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.078064/1218, current 257.094574/1219: elapsed=16521.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.078064/1218, current 257.094574/1219: elapsed=16521.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.094574
last_received_ts = 257.093842
last_seq = 1219
current_ts = 257.111084
current_received_ts = 257.110352
current_seq = 1220
count = 581
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.094574/1219, current 257.111084/1220: elapsed=16518.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.094574/1219, current 257.111084/1220: elapsed=16518.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.111084
last_received_ts = 257.110352
last_seq = 1220
current_ts = 257.127625
current_received_ts = 257.126862
current_seq = 1221
count = 582
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.111084/1220, current 257.127625/1221: elapsed=16522.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.111084/1220, current 257.127625/1221: elapsed=16522.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.127625
last_received_ts = 257.126862
last_seq = 1221
current_ts = 257.144135
current_received_ts = 257.143402
current_seq = 1222
count = 583
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.127625/1221, current 257.144135/1222: elapsed=16523.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.127625/1221, current 257.144135/1222: elapsed=16523.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.144135
last_received_ts = 257.143402
last_seq = 1222
current_ts = 257.160645
current_received_ts = 257.159912
current_seq = 1223
count = 584
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.144135/1222, current 257.160645/1223: elapsed=16517.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.144135/1222, current 257.160645/1223: elapsed=16517.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.160645
last_received_ts = 257.159912
last_seq = 1223
current_ts = 257.177185
current_received_ts = 257.176453
current_seq = 1224
count = 585
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.160645/1223, current 257.177185/1224: elapsed=16530.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.160645/1223, current 257.177185/1224: elapsed=16530.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.177185
last_received_ts = 257.176453
last_seq = 1224
current_ts = 257.193695
current_received_ts = 257.193024
current_seq = 1225
count = 586
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.177185/1224, current 257.193695/1225: elapsed=16516.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.177185/1224, current 257.193695/1225: elapsed=16516.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.193695
last_received_ts = 257.193024
last_seq = 1225
current_ts = 257.210236
current_received_ts = 257.209503
current_seq = 1226
count = 587
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.193695/1225, current 257.210236/1226: elapsed=16519.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.193695/1225, current 257.210236/1226: elapsed=16519.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.210236
last_received_ts = 257.209503
last_seq = 1226
current_ts = 257.226746
current_received_ts = 257.226044
current_seq = 1227
count = 588
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.210236/1226, current 257.226746/1227: elapsed=16525.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.210236/1226, current 257.226746/1227: elapsed=16525.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.226746
last_received_ts = 257.226044
last_seq = 1227
current_ts = 257.243286
current_received_ts = 257.242523
current_seq = 1228
count = 589
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.226746/1227, current 257.243286/1228: elapsed=16524.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.226746/1227, current 257.243286/1228: elapsed=16524.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.243286
last_received_ts = 257.242523
last_seq = 1228
current_ts = 257.259796
current_received_ts = 257.259033
current_seq = 1229
count = 590
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.243286/1228, current 257.259796/1229: elapsed=16522.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.243286/1228, current 257.259796/1229: elapsed=16522.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.259796
last_received_ts = 257.259033
last_seq = 1229
current_ts = 257.276306
current_received_ts = 257.275543
current_seq = 1230
count = 591
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.259796/1229, current 257.276306/1230: elapsed=16523.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.259796/1229, current 257.276306/1230: elapsed=16523.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.276306
last_received_ts = 257.275543
last_seq = 1230
current_ts = 257.292847
current_received_ts = 257.292084
current_seq = 1231
count = 592
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.276306/1230, current 257.292847/1231: elapsed=16522.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.276306/1230, current 257.292847/1231: elapsed=16522.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.292847
last_received_ts = 257.292084
last_seq = 1231
current_ts = 257.309357
current_received_ts = 257.308624
current_seq = 1232
count = 593
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.292847/1231, current 257.309357/1232: elapsed=16528.0us expected=16691.1us +- 83.5us, error 1.0%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.292847/1231, current 257.309357/1232: elapsed=16528.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.309357
last_received_ts = 257.308624
last_seq = 1232
current_ts = 257.325897
current_received_ts = 257.325073
current_seq = 1233
count = 594
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.309357/1232, current 257.325897/1233: elapsed=16533.0us expected=16691.1us +- 83.5us, error 0.9%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.309357/1232, current 257.325897/1233: elapsed=16533.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.325897
last_received_ts = 257.325073
last_seq = 1233
current_ts = 257.342438
current_received_ts = 257.341705
current_seq = 1234
count = 595
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.325897/1233, current 257.342438/1234: elapsed=16543.0us expected=16691.1us +- 83.5us, error 0.9%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.325897/1233, current 257.342438/1234: elapsed=16543.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.342438
last_received_ts = 257.341705
last_seq = 1234
current_ts = 257.358978
current_received_ts = 257.358215
current_seq = 1235
count = 596
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.342438/1234, current 257.358978/1235: elapsed=16537.0us expected=16691.1us +- 83.5us, error 0.9%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.342438/1234, current 257.358978/1235: elapsed=16537.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.358978
last_received_ts = 257.358215
last_seq = 1235
current_ts = 257.375519
current_received_ts = 257.374786
current_seq = 1236
count = 597
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.358978/1235, current 257.375519/1236: elapsed=16536.0us expected=16691.1us +- 83.5us, error 0.9%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.358978/1235, current 257.375519/1236: elapsed=16536.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.375519
last_received_ts = 257.374786
last_seq = 1236
current_ts = 257.392059
current_received_ts = 257.391327
current_seq = 1237
count = 598
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.375519/1236, current 257.392059/1237: elapsed=16541.0us expected=16691.1us +- 83.5us, error 0.9%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.375519/1236, current 257.392059/1237: elapsed=16541.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.392059
last_received_ts = 257.391327
last_seq = 1237
current_ts = 257.408600
current_received_ts = 257.407837
current_seq = 1238
count = 599
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.392059/1237, current 257.408600/1238: elapsed=16540.0us expected=16691.1us +- 83.5us, error 0.9%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.392059/1237, current 257.408600/1238: elapsed=16540.0us expected=16691.1us
(kms_flip:5618) DEBUG: name = flip
last_ts = 257.408600
last_received_ts = 257.407837
last_seq = 1238
current_ts = 257.425140
current_received_ts = 257.424408
current_seq = 1239
count = 600
seq_step = 1
(kms_flip:5618) DEBUG: flip ts/seq: last 257.408600/1238, current 257.425140/1239: elapsed=16540.0us expected=16691.1us +- 83.5us, error 0.9%
(kms_flip:5618) DEBUG: inconsistent flip ts/seq: last 257.408600/1238, current 257.425140/1239: elapsed=16540.0us expected=16691.1us
(kms_flip:5618) INFO: Event flip: expected 599, counted 601, passrate = 78.54%, encoder type 2
(kms_flip:5618) DEBUG: dropped frames, expected 599, counted 601, passrate = 78.54%, encoder type 2
(kms_flip:5618) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1711:
(kms_flip:5618) CRITICAL: Failed assertion: !retried
(kms_flip:5618) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:5618) igt_core-INFO: Stack trace:
(kms_flip:5618) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:5618) igt_core-INFO:   #1 ../tests/kms_flip.c:428 run_test_on_crtc_set.constprop.0()
(kms_flip:5618) igt_core-INFO:   #2 ../tests/kms_flip.c:1891 run_test()
(kms_flip:5618) igt_core-INFO:   #3 ../tests/kms_flip.c:2162 __igt_unique____real_main2047()
(kms_flip:5618) igt_core-INFO:   #4 ../tests/kms_flip.c:2047 main()
(kms_flip:5618) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:5618) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:5618) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (25.985s)
Starting dynamic subtest: C-eDP1
Dynamic subtest C-eDP1: SUCCESS (11.535s)
Subtest plain-flip-ts-check-interruptible: FAIL (63.215s)