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

shard-rkl-5

IGT-Version: 1.30-gbf8a8a073 (x86_64) (Linux: 6.14.0-rc5-CI_DRM_16222-gff2d693d8872+ x86_64)

Using IGT_SRANDOM=1741135864 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-fb-recreate
Starting dynamic subtest: A-HDMI-A2
  1920x1080: 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 18974us; measured 19245.7us +- 14.727us accuracy 0.23%
vblank interval differs from modeline! expected 18973.8us, measured 19246us +- 14.727us, difference 271.9us (18.5 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-HDMI-A2: FAIL (6.363s)
Starting dynamic subtest: B-HDMI-A2
  1920x1080: 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 18974us; measured 19093.4us +- 4.858us accuracy 0.08%
vblank interval differs from modeline! expected 18973.8us, measured 19093us +- 4.858us, difference 119.7us (24.6 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A2: FAIL (12.108s)
Subtest plain-flip-fb-recreate: FAIL (18.473s)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2246 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2934 igt_atexit_handler()
  #3 [erand48_r+0x1d6]
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2390 igt_exit()
  #6 [main+0x3f]
  #7 [__libc_init_first+0x8a]
  #8 [__libc_start_main+0x8b]
  #9 [_start+0x25]

Starting subtest: plain-flip-fb-recreate
Starting dynamic subtest: A-HDMI-A2
(kms_flip:2058) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2058) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-HDMI-A2 failed.
**** DEBUG ****
(kms_flip:2058) DEBUG: flip ts/seq: last 62.242706/503, current 62.261940/504: elapsed=19231.0us expected=19245.7us +- 96.2us, error 0.1%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.261940
last_received_ts = 62.261406
last_seq = 504
current_ts = 62.281178
current_received_ts = 62.280682
current_seq = 505
count = 25
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.261940/504, current 62.281178/505: elapsed=19240.0us expected=19245.7us +- 96.2us, error 0.0%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.281178
last_received_ts = 62.280682
last_seq = 505
current_ts = 62.300419
current_received_ts = 62.299862
current_seq = 506
count = 26
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.281178/505, current 62.300419/506: elapsed=19239.0us expected=19245.7us +- 96.2us, error 0.0%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.300419
last_received_ts = 62.299862
last_seq = 506
current_ts = 62.319668
current_received_ts = 62.319168
current_seq = 507
count = 27
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.300419/506, current 62.319668/507: elapsed=19249.0us expected=19245.7us +- 96.2us, error 0.0%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.319668
last_received_ts = 62.319168
last_seq = 507
current_ts = 62.338890
current_received_ts = 62.338341
current_seq = 508
count = 28
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.319668/507, current 62.338890/508: elapsed=19223.0us expected=19245.7us +- 96.2us, error 0.1%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.338890
last_received_ts = 62.338341
last_seq = 508
current_ts = 62.358135
current_received_ts = 62.357578
current_seq = 509
count = 29
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.338890/508, current 62.358135/509: elapsed=19244.0us expected=19245.7us +- 96.2us, error 0.0%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.358135
last_received_ts = 62.357578
last_seq = 509
current_ts = 62.377380
current_received_ts = 62.376820
current_seq = 510
count = 30
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.358135/509, current 62.377380/510: elapsed=19245.0us expected=19245.7us +- 96.2us, error 0.0%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.377380
last_received_ts = 62.376820
last_seq = 510
current_ts = 62.396618
current_received_ts = 62.396095
current_seq = 511
count = 31
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.377380/510, current 62.396618/511: elapsed=19239.0us expected=19245.7us +- 96.2us, error 0.0%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.396618
last_received_ts = 62.396095
last_seq = 511
current_ts = 62.415855
current_received_ts = 62.415352
current_seq = 512
count = 32
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.396618/511, current 62.415855/512: elapsed=19236.0us expected=19245.7us +- 96.2us, error 0.1%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.415855
last_received_ts = 62.415352
last_seq = 512
current_ts = 62.435097
current_received_ts = 62.434597
current_seq = 513
count = 33
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.415855/512, current 62.435097/513: elapsed=19243.0us expected=19245.7us +- 96.2us, error 0.0%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.435097
last_received_ts = 62.434597
last_seq = 513
current_ts = 62.454338
current_received_ts = 62.453793
current_seq = 514
count = 34
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.435097/513, current 62.454338/514: elapsed=19240.0us expected=19245.7us +- 96.2us, error 0.0%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.454338
last_received_ts = 62.453793
last_seq = 514
current_ts = 62.473576
current_received_ts = 62.473091
current_seq = 515
count = 35
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.454338/514, current 62.473576/515: elapsed=19240.0us expected=19245.7us +- 96.2us, error 0.0%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.473576
last_received_ts = 62.473091
last_seq = 515
current_ts = 62.492809
current_received_ts = 62.492226
current_seq = 516
count = 36
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.473576/515, current 62.492809/516: elapsed=19232.0us expected=19245.7us +- 96.2us, error 0.1%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.492809
last_received_ts = 62.492226
last_seq = 516
current_ts = 62.512043
current_received_ts = 62.511543
current_seq = 517
count = 37
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.492809/516, current 62.512043/517: elapsed=19235.0us expected=19245.7us +- 96.2us, error 0.1%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.512043
last_received_ts = 62.511543
last_seq = 517
current_ts = 62.531242
current_received_ts = 62.530731
current_seq = 518
count = 38
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.512043/517, current 62.531242/518: elapsed=19200.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.531242
last_received_ts = 62.530731
last_seq = 518
current_ts = 62.550449
current_received_ts = 62.549854
current_seq = 519
count = 39
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.531242/518, current 62.550449/519: elapsed=19205.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.550449
last_received_ts = 62.549854
last_seq = 519
current_ts = 62.569649
current_received_ts = 62.569080
current_seq = 520
count = 40
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.550449/519, current 62.569649/520: elapsed=19199.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.569649
last_received_ts = 62.569080
last_seq = 520
current_ts = 62.588860
current_received_ts = 62.588272
current_seq = 521
count = 41
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.569649/520, current 62.588860/521: elapsed=19213.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.588860
last_received_ts = 62.588272
last_seq = 521
current_ts = 62.608074
current_received_ts = 62.607525
current_seq = 522
count = 42
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.588860/521, current 62.608074/522: elapsed=19213.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.608074
last_received_ts = 62.607525
last_seq = 522
current_ts = 62.627274
current_received_ts = 62.626701
current_seq = 523
count = 43
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.608074/522, current 62.627274/523: elapsed=19201.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.627274
last_received_ts = 62.626701
last_seq = 523
current_ts = 62.646484
current_received_ts = 62.646099
current_seq = 524
count = 44
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.627274/523, current 62.646484/524: elapsed=19208.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.646484
last_received_ts = 62.646099
last_seq = 524
current_ts = 62.665688
current_received_ts = 62.665146
current_seq = 525
count = 45
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.646484/524, current 62.665688/525: elapsed=19206.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.665688
last_received_ts = 62.665146
last_seq = 525
current_ts = 62.684898
current_received_ts = 62.684380
current_seq = 526
count = 46
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.665688/525, current 62.684898/526: elapsed=19208.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.684898
last_received_ts = 62.684380
last_seq = 526
current_ts = 62.704094
current_received_ts = 62.703537
current_seq = 527
count = 47
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.684898/526, current 62.704094/527: elapsed=19198.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.704094
last_received_ts = 62.703537
last_seq = 527
current_ts = 62.723309
current_received_ts = 62.722713
current_seq = 528
count = 48
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.704094/527, current 62.723309/528: elapsed=19215.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.723309
last_received_ts = 62.722713
last_seq = 528
current_ts = 62.742508
current_received_ts = 62.742001
current_seq = 529
count = 49
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.723309/528, current 62.742508/529: elapsed=19199.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.742508
last_received_ts = 62.742001
last_seq = 529
current_ts = 62.761723
current_received_ts = 62.761223
current_seq = 530
count = 50
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.742508/529, current 62.761723/530: elapsed=19214.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.761723
last_received_ts = 62.761223
last_seq = 530
current_ts = 62.780933
current_received_ts = 62.780418
current_seq = 531
count = 51
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.761723/530, current 62.780933/531: elapsed=19209.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.780933
last_received_ts = 62.780418
last_seq = 531
current_ts = 62.800129
current_received_ts = 62.799644
current_seq = 532
count = 52
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.780933/531, current 62.800129/532: elapsed=19198.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.800129
last_received_ts = 62.799644
last_seq = 532
current_ts = 62.819336
current_received_ts = 62.818947
current_seq = 533
count = 53
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.800129/532, current 62.819336/533: elapsed=19206.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.819336
last_received_ts = 62.818947
last_seq = 533
current_ts = 62.838547
current_received_ts = 62.838051
current_seq = 534
count = 54
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.819336/533, current 62.838547/534: elapsed=19209.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.838547
last_received_ts = 62.838051
last_seq = 534
current_ts = 62.857746
current_received_ts = 62.857239
current_seq = 535
count = 55
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.838547/534, current 62.857746/535: elapsed=19202.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.857746
last_received_ts = 62.857239
last_seq = 535
current_ts = 62.876961
current_received_ts = 62.876480
current_seq = 536
count = 56
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.857746/535, current 62.876961/536: elapsed=19212.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.876961
last_received_ts = 62.876480
last_seq = 536
current_ts = 62.896168
current_received_ts = 62.895794
current_seq = 537
count = 57
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.876961/536, current 62.896168/537: elapsed=19209.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.896168
last_received_ts = 62.895794
last_seq = 537
current_ts = 62.915375
current_received_ts = 62.914837
current_seq = 538
count = 58
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.896168/537, current 62.915375/538: elapsed=19205.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.915375
last_received_ts = 62.914837
last_seq = 538
current_ts = 62.934582
current_received_ts = 62.934074
current_seq = 539
count = 59
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.915375/538, current 62.934582/539: elapsed=19210.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.934582
last_received_ts = 62.934074
last_seq = 539
current_ts = 62.953781
current_received_ts = 62.953266
current_seq = 540
count = 60
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.934582/539, current 62.953781/540: elapsed=19197.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.953781
last_received_ts = 62.953266
last_seq = 540
current_ts = 62.972984
current_received_ts = 62.972439
current_seq = 541
count = 61
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.953781/540, current 62.972984/541: elapsed=19206.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.972984
last_received_ts = 62.972439
last_seq = 541
current_ts = 62.992199
current_received_ts = 62.991737
current_seq = 542
count = 62
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.972984/541, current 62.992199/542: elapsed=19214.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 62.992199
last_received_ts = 62.991737
last_seq = 542
current_ts = 63.011410
current_received_ts = 63.010853
current_seq = 543
count = 63
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 62.992199/542, current 63.011410/543: elapsed=19210.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.011410
last_received_ts = 63.010853
last_seq = 543
current_ts = 63.030617
current_received_ts = 63.030121
current_seq = 544
count = 64
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.011410/543, current 63.030617/544: elapsed=19207.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.030617
last_received_ts = 63.030121
last_seq = 544
current_ts = 63.049828
current_received_ts = 63.049255
current_seq = 545
count = 65
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.030617/544, current 63.049828/545: elapsed=19210.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.049828
last_received_ts = 63.049255
last_seq = 545
current_ts = 63.069027
current_received_ts = 63.068462
current_seq = 546
count = 66
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.049828/545, current 63.069027/546: elapsed=19199.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.069027
last_received_ts = 63.068462
last_seq = 546
current_ts = 63.088234
current_received_ts = 63.087666
current_seq = 547
count = 67
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.069027/546, current 63.088234/547: elapsed=19208.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.088234
last_received_ts = 63.087666
last_seq = 547
current_ts = 63.107437
current_received_ts = 63.106804
current_seq = 548
count = 68
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.088234/547, current 63.107437/548: elapsed=19204.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.107437
last_received_ts = 63.106804
last_seq = 548
current_ts = 63.126648
current_received_ts = 63.126740
current_seq = 549
count = 69
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.107437/548, current 63.126648/549: elapsed=19209.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.126648
last_received_ts = 63.126740
last_seq = 549
current_ts = 63.145844
current_received_ts = 63.145206
current_seq = 550
count = 70
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.126648/549, current 63.145844/550: elapsed=19198.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.145844
last_received_ts = 63.145206
last_seq = 550
current_ts = 63.165058
current_received_ts = 63.164509
current_seq = 551
count = 71
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.145844/550, current 63.165058/551: elapsed=19215.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.165058
last_received_ts = 63.164509
last_seq = 551
current_ts = 63.184269
current_received_ts = 63.183727
current_seq = 552
count = 72
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.165058/551, current 63.184269/552: elapsed=19208.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.184269
last_received_ts = 63.183727
last_seq = 552
current_ts = 63.203472
current_received_ts = 63.202923
current_seq = 553
count = 73
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.184269/552, current 63.203472/553: elapsed=19206.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.203472
last_received_ts = 63.202923
last_seq = 553
current_ts = 63.222672
current_received_ts = 63.222157
current_seq = 554
count = 74
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.203472/553, current 63.222672/554: elapsed=19199.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.222672
last_received_ts = 63.222157
last_seq = 554
current_ts = 63.241879
current_received_ts = 63.241322
current_seq = 555
count = 75
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.222672/554, current 63.241879/555: elapsed=19205.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.241879
last_received_ts = 63.241322
last_seq = 555
current_ts = 63.261093
current_received_ts = 63.260525
current_seq = 556
count = 76
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.241879/555, current 63.261093/556: elapsed=19214.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.261093
last_received_ts = 63.260525
last_seq = 556
current_ts = 63.280300
current_received_ts = 63.279743
current_seq = 557
count = 77
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.261093/556, current 63.280300/557: elapsed=19210.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.280300
last_received_ts = 63.279743
last_seq = 557
current_ts = 63.299507
current_received_ts = 63.298939
current_seq = 558
count = 78
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.280300/557, current 63.299507/558: elapsed=19205.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.299507
last_received_ts = 63.298939
last_seq = 558
current_ts = 63.318714
current_received_ts = 63.318195
current_seq = 559
count = 79
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.299507/558, current 63.318714/559: elapsed=19206.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.318714
last_received_ts = 63.318195
last_seq = 559
current_ts = 63.337917
current_received_ts = 63.337345
current_seq = 560
count = 80
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.318714/559, current 63.337917/560: elapsed=19204.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.337917
last_received_ts = 63.337345
last_seq = 560
current_ts = 63.357128
current_received_ts = 63.356586
current_seq = 561
count = 81
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.337917/560, current 63.357128/561: elapsed=19212.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.357128
last_received_ts = 63.356586
last_seq = 561
current_ts = 63.376331
current_received_ts = 63.375767
current_seq = 562
count = 82
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.357128/561, current 63.376331/562: elapsed=19204.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.376331
last_received_ts = 63.375767
last_seq = 562
current_ts = 63.395538
current_received_ts = 63.395782
current_seq = 563
count = 83
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.376331/562, current 63.395538/563: elapsed=19204.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.395538
last_received_ts = 63.395782
last_seq = 563
current_ts = 63.414738
current_received_ts = 63.414116
current_seq = 564
count = 84
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.395538/563, current 63.414738/564: elapsed=19201.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.414738
last_received_ts = 63.414116
last_seq = 564
current_ts = 63.433952
current_received_ts = 63.433395
current_seq = 565
count = 85
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.414738/564, current 63.433952/565: elapsed=19215.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.433952
last_received_ts = 63.433395
last_seq = 565
current_ts = 63.453163
current_received_ts = 63.452595
current_seq = 566
count = 86
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.433952/565, current 63.453163/566: elapsed=19210.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.453163
last_received_ts = 63.452595
last_seq = 566
current_ts = 63.472363
current_received_ts = 63.471802
current_seq = 567
count = 87
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.453163/566, current 63.472363/567: elapsed=19201.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.472363
last_received_ts = 63.471802
last_seq = 567
current_ts = 63.491566
current_received_ts = 63.491127
current_seq = 568
count = 88
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.472363/567, current 63.491566/568: elapsed=19201.0us expected=19245.7us +- 96.2us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.491566
last_received_ts = 63.491127
last_seq = 568
current_ts = 63.510757
current_received_ts = 63.510201
current_seq = 569
count = 89
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.491566/568, current 63.510757/569: elapsed=19194.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.510757
last_received_ts = 63.510201
last_seq = 569
current_ts = 63.529938
current_received_ts = 63.529400
current_seq = 570
count = 90
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.510757/569, current 63.529938/570: elapsed=19179.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.529938
last_received_ts = 63.529400
last_seq = 570
current_ts = 63.549114
current_received_ts = 63.548542
current_seq = 571
count = 91
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.529938/570, current 63.549114/571: elapsed=19176.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.549114
last_received_ts = 63.548542
last_seq = 571
current_ts = 63.568295
current_received_ts = 63.567753
current_seq = 572
count = 92
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.549114/571, current 63.568295/572: elapsed=19180.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.568295
last_received_ts = 63.567753
last_seq = 572
current_ts = 63.587463
current_received_ts = 63.587063
current_seq = 573
count = 93
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.568295/572, current 63.587463/573: elapsed=19169.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.587463
last_received_ts = 63.587063
last_seq = 573
current_ts = 63.606647
current_received_ts = 63.606091
current_seq = 574
count = 94
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.587463/573, current 63.606647/574: elapsed=19185.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.606647
last_received_ts = 63.606091
last_seq = 574
current_ts = 63.625828
current_received_ts = 63.625271
current_seq = 575
count = 95
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.606647/574, current 63.625828/575: elapsed=19179.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.625828
last_received_ts = 63.625271
last_seq = 575
current_ts = 63.645004
current_received_ts = 63.644436
current_seq = 576
count = 96
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.625828/575, current 63.645004/576: elapsed=19176.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.645004
last_received_ts = 63.644436
last_seq = 576
current_ts = 63.664181
current_received_ts = 63.663597
current_seq = 577
count = 97
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.645004/576, current 63.664181/577: elapsed=19177.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.664181
last_received_ts = 63.663597
last_seq = 577
current_ts = 63.683361
current_received_ts = 63.682796
current_seq = 578
count = 98
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.664181/577, current 63.683361/578: elapsed=19180.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.683361
last_received_ts = 63.682796
last_seq = 578
current_ts = 63.702534
current_received_ts = 63.701927
current_seq = 579
count = 99
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.683361/578, current 63.702534/579: elapsed=19173.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.702534
last_received_ts = 63.701927
last_seq = 579
current_ts = 63.721703
current_received_ts = 63.721165
current_seq = 580
count = 100
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.702534/579, current 63.721703/580: elapsed=19171.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.721703
last_received_ts = 63.721165
last_seq = 580
current_ts = 63.740894
current_received_ts = 63.740337
current_seq = 581
count = 101
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.721703/580, current 63.740894/581: elapsed=19189.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.740894
last_received_ts = 63.740337
last_seq = 581
current_ts = 63.760063
current_received_ts = 63.759476
current_seq = 582
count = 102
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.740894/581, current 63.760063/582: elapsed=19171.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.760063
last_received_ts = 63.759476
last_seq = 582
current_ts = 63.779251
current_received_ts = 63.778572
current_seq = 583
count = 103
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.760063/582, current 63.779251/583: elapsed=19187.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.779251
last_received_ts = 63.778572
last_seq = 583
current_ts = 63.798424
current_received_ts = 63.797745
current_seq = 584
count = 104
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.779251/583, current 63.798424/584: elapsed=19173.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.798424
last_received_ts = 63.797745
last_seq = 584
current_ts = 63.817608
current_received_ts = 63.817116
current_seq = 585
count = 105
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.798424/584, current 63.817608/585: elapsed=19184.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.817608
last_received_ts = 63.817116
last_seq = 585
current_ts = 63.836781
current_received_ts = 63.836292
current_seq = 586
count = 106
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.817608/585, current 63.836781/586: elapsed=19174.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.836781
last_received_ts = 63.836292
last_seq = 586
current_ts = 63.855953
current_received_ts = 63.855381
current_seq = 587
count = 107
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.836781/586, current 63.855953/587: elapsed=19170.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.855953
last_received_ts = 63.855381
last_seq = 587
current_ts = 63.875134
current_received_ts = 63.874573
current_seq = 588
count = 108
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.855953/587, current 63.875134/588: elapsed=19182.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.875134
last_received_ts = 63.874573
last_seq = 588
current_ts = 63.894306
current_received_ts = 63.893875
current_seq = 589
count = 109
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.875134/588, current 63.894306/589: elapsed=19172.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.894306
last_received_ts = 63.893875
last_seq = 589
current_ts = 63.913490
current_received_ts = 63.912945
current_seq = 590
count = 110
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.894306/589, current 63.913490/590: elapsed=19186.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.913490
last_received_ts = 63.912945
last_seq = 590
current_ts = 63.932663
current_received_ts = 63.932117
current_seq = 591
count = 111
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.913490/590, current 63.932663/591: elapsed=19170.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.932663
last_received_ts = 63.932117
last_seq = 591
current_ts = 63.951836
current_received_ts = 63.951286
current_seq = 592
count = 112
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.932663/591, current 63.951836/592: elapsed=19175.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.951836
last_received_ts = 63.951286
last_seq = 592
current_ts = 63.971024
current_received_ts = 63.970394
current_seq = 593
count = 113
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.951836/592, current 63.971024/593: elapsed=19186.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.971024
last_received_ts = 63.970394
last_seq = 593
current_ts = 63.990192
current_received_ts = 63.989613
current_seq = 594
count = 114
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.971024/593, current 63.990192/594: elapsed=19168.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 63.990192
last_received_ts = 63.989613
last_seq = 594
current_ts = 64.009369
current_received_ts = 64.008789
current_seq = 595
count = 115
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 63.990192/594, current 64.009369/595: elapsed=19176.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.009369
last_received_ts = 64.008789
last_seq = 595
current_ts = 64.028557
current_received_ts = 64.027946
current_seq = 596
count = 116
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.009369/595, current 64.028557/596: elapsed=19188.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.028557
last_received_ts = 64.027946
last_seq = 596
current_ts = 64.047729
current_received_ts = 64.047142
current_seq = 597
count = 117
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.028557/596, current 64.047729/597: elapsed=19171.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.047729
last_received_ts = 64.047142
last_seq = 597
current_ts = 64.066910
current_received_ts = 64.066345
current_seq = 598
count = 118
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.047729/597, current 64.066910/598: elapsed=19181.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.066910
last_received_ts = 64.066345
last_seq = 598
current_ts = 64.086082
current_received_ts = 64.085526
current_seq = 599
count = 119
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.066910/598, current 64.086082/599: elapsed=19175.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.086082
last_received_ts = 64.085526
last_seq = 599
current_ts = 64.105270
current_received_ts = 64.104668
current_seq = 600
count = 120
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.086082/599, current 64.105270/600: elapsed=19187.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.105270
last_received_ts = 64.104668
last_seq = 600
current_ts = 64.124435
current_received_ts = 64.123817
current_seq = 601
count = 121
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.105270/600, current 64.124435/601: elapsed=19167.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.124435
last_received_ts = 64.123817
last_seq = 601
current_ts = 64.143623
current_received_ts = 64.143150
current_seq = 602
count = 122
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.124435/601, current 64.143623/602: elapsed=19187.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.143623
last_received_ts = 64.143150
last_seq = 602
current_ts = 64.162796
current_received_ts = 64.162224
current_seq = 603
count = 123
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.143623/602, current 64.162796/603: elapsed=19173.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.162796
last_received_ts = 64.162224
last_seq = 603
current_ts = 64.181969
current_received_ts = 64.181389
current_seq = 604
count = 124
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.162796/603, current 64.181969/604: elapsed=19171.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.181969
last_received_ts = 64.181389
last_seq = 604
current_ts = 64.201157
current_received_ts = 64.200554
current_seq = 605
count = 125
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.181969/604, current 64.201157/605: elapsed=19186.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.201157
last_received_ts = 64.200554
last_seq = 605
current_ts = 64.220329
current_received_ts = 64.219749
current_seq = 606
count = 126
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.201157/605, current 64.220329/606: elapsed=19177.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.220329
last_received_ts = 64.219749
last_seq = 606
current_ts = 64.239510
current_received_ts = 64.238945
current_seq = 607
count = 127
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.220329/606, current 64.239510/607: elapsed=19177.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.239510
last_received_ts = 64.238945
last_seq = 607
current_ts = 64.258682
current_received_ts = 64.258057
current_seq = 608
count = 128
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.239510/607, current 64.258682/608: elapsed=19176.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.258682
last_received_ts = 64.258057
last_seq = 608
current_ts = 64.277855
current_received_ts = 64.277306
current_seq = 609
count = 129
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.258682/608, current 64.277855/609: elapsed=19174.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.277855
last_received_ts = 64.277306
last_seq = 609
current_ts = 64.297028
current_received_ts = 64.296448
current_seq = 610
count = 130
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.277855/609, current 64.297028/610: elapsed=19172.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.297028
last_received_ts = 64.296448
last_seq = 610
current_ts = 64.316216
current_received_ts = 64.315674
current_seq = 611
count = 131
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.297028/610, current 64.316216/611: elapsed=19186.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.316216
last_received_ts = 64.315674
last_seq = 611
current_ts = 64.335396
current_received_ts = 64.334946
current_seq = 612
count = 132
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.316216/611, current 64.335396/612: elapsed=19181.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.335396
last_received_ts = 64.334946
last_seq = 612
current_ts = 64.354568
current_received_ts = 64.353966
current_seq = 613
count = 133
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.335396/612, current 64.354568/613: elapsed=19170.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.354568
last_received_ts = 64.353966
last_seq = 613
current_ts = 64.373749
current_received_ts = 64.373245
current_seq = 614
count = 134
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.354568/613, current 64.373749/614: elapsed=19186.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.373749
last_received_ts = 64.373245
last_seq = 614
current_ts = 64.392914
current_received_ts = 64.392342
current_seq = 615
count = 135
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.373749/614, current 64.392914/615: elapsed=19165.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.392914
last_received_ts = 64.392342
last_seq = 615
current_ts = 64.412102
current_received_ts = 64.411545
current_seq = 616
count = 136
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.392914/615, current 64.412102/616: elapsed=19188.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.412102
last_received_ts = 64.411545
last_seq = 616
current_ts = 64.431282
current_received_ts = 64.430832
current_seq = 617
count = 137
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.412102/616, current 64.431282/617: elapsed=19174.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.431282
last_received_ts = 64.430832
last_seq = 617
current_ts = 64.450455
current_received_ts = 64.449890
current_seq = 618
count = 138
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.431282/617, current 64.450455/618: elapsed=19177.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.450455
last_received_ts = 64.449890
last_seq = 618
current_ts = 64.469635
current_received_ts = 64.469124
current_seq = 619
count = 139
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.450455/618, current 64.469635/619: elapsed=19182.0us expected=19245.7us +- 96.2us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.469635
last_received_ts = 64.469124
last_seq = 619
current_ts = 64.488808
current_received_ts = 64.488258
current_seq = 620
count = 140
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.469635/619, current 64.488808/620: elapsed=19171.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.488808
last_received_ts = 64.488258
last_seq = 620
current_ts = 64.507973
current_received_ts = 64.507355
current_seq = 621
count = 141
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.488808/620, current 64.507973/621: elapsed=19160.0us expected=19245.7us +- 96.2us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.507973
last_received_ts = 64.507355
last_seq = 621
current_ts = 64.527130
current_received_ts = 64.526550
current_seq = 622
count = 142
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.507973/621, current 64.527130/622: elapsed=19159.0us expected=19245.7us +- 96.2us, error 0.5%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.527130
last_received_ts = 64.526550
last_seq = 622
current_ts = 64.546288
current_received_ts = 64.545708
current_seq = 623
count = 143
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.527130/622, current 64.546288/623: elapsed=19158.0us expected=19245.7us +- 96.2us, error 0.5%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.546288
last_received_ts = 64.545708
last_seq = 623
current_ts = 64.565437
current_received_ts = 64.564781
current_seq = 624
count = 144
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.546288/623, current 64.565437/624: elapsed=19149.0us expected=19245.7us +- 96.2us, error 0.5%
(kms_flip:2058) DEBUG: inconsistent flip ts/seq: last 64.546288/623, current 64.565437/624: elapsed=19149.0us expected=19245.7us
(kms_flip:2058) DEBUG: expected 113110, counted 144, encoder type 2
(kms_flip:2058) DEBUG: dropped frames, expected 113110, counted 144, encoder type 2
(kms_flip:2058) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2058) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2058) igt_core-INFO: Stack trace:
(kms_flip:2058) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2058) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2058) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2058) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2058) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2058) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2058) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2058) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A2: FAIL (6.363s)
Starting dynamic subtest: B-HDMI-A2
(kms_flip:2058) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2058) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-HDMI-A2 failed.
**** DEBUG ****
(kms_flip:2058) DEBUG: flip ts/seq: last 74.416367/351, current 74.435394/352: elapsed=19028.0us expected=19093.4us +- 95.5us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.435394
last_received_ts = 74.434845
last_seq = 352
current_ts = 74.454422
current_received_ts = 74.453873
current_seq = 353
count = 329
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.435394/352, current 74.454422/353: elapsed=19025.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.454422
last_received_ts = 74.453873
last_seq = 353
current_ts = 74.473442
current_received_ts = 74.472908
current_seq = 354
count = 330
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.454422/353, current 74.473442/354: elapsed=19023.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.473442
last_received_ts = 74.472908
last_seq = 354
current_ts = 74.492477
current_received_ts = 74.491913
current_seq = 355
count = 331
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.473442/354, current 74.492477/355: elapsed=19031.0us expected=19093.4us +- 95.5us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.492477
last_received_ts = 74.491913
last_seq = 355
current_ts = 74.511490
current_received_ts = 74.510948
current_seq = 356
count = 332
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.492477/355, current 74.511490/356: elapsed=19014.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.511490
last_received_ts = 74.510948
last_seq = 356
current_ts = 74.530525
current_received_ts = 74.530113
current_seq = 357
count = 333
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.511490/356, current 74.530525/357: elapsed=19036.0us expected=19093.4us +- 95.5us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.530525
last_received_ts = 74.530113
last_seq = 357
current_ts = 74.549538
current_received_ts = 74.549042
current_seq = 358
count = 334
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.530525/357, current 74.549538/358: elapsed=19014.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.549538
last_received_ts = 74.549042
last_seq = 358
current_ts = 74.568565
current_received_ts = 74.568047
current_seq = 359
count = 335
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.549538/358, current 74.568565/359: elapsed=19025.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.568565
last_received_ts = 74.568047
last_seq = 359
current_ts = 74.587585
current_received_ts = 74.587128
current_seq = 360
count = 336
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.568565/359, current 74.587585/360: elapsed=19018.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.587585
last_received_ts = 74.587128
last_seq = 360
current_ts = 74.606606
current_received_ts = 74.606079
current_seq = 361
count = 337
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.587585/360, current 74.606606/361: elapsed=19022.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.606606
last_received_ts = 74.606079
last_seq = 361
current_ts = 74.625610
current_received_ts = 74.625122
current_seq = 362
count = 338
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.606606/361, current 74.625610/362: elapsed=19009.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.625610
last_received_ts = 74.625122
last_seq = 362
current_ts = 74.644646
current_received_ts = 74.644135
current_seq = 363
count = 339
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.625610/362, current 74.644646/363: elapsed=19033.0us expected=19093.4us +- 95.5us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.644646
last_received_ts = 74.644135
last_seq = 363
current_ts = 74.663658
current_received_ts = 74.663223
current_seq = 364
count = 340
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.644646/363, current 74.663658/364: elapsed=19011.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.663658
last_received_ts = 74.663223
last_seq = 364
current_ts = 74.682678
current_received_ts = 74.682236
current_seq = 365
count = 341
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.663658/364, current 74.682678/365: elapsed=19018.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.682678
last_received_ts = 74.682236
last_seq = 365
current_ts = 74.701706
current_received_ts = 74.701218
current_seq = 366
count = 342
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.682678/365, current 74.701706/366: elapsed=19027.0us expected=19093.4us +- 95.5us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.701706
last_received_ts = 74.701218
last_seq = 366
current_ts = 74.720734
current_received_ts = 74.720245
current_seq = 367
count = 343
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.701706/366, current 74.720734/367: elapsed=19028.0us expected=19093.4us +- 95.5us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.720734
last_received_ts = 74.720245
last_seq = 367
current_ts = 74.739754
current_received_ts = 74.739220
current_seq = 368
count = 344
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.720734/367, current 74.739754/368: elapsed=19020.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.739754
last_received_ts = 74.739220
last_seq = 368
current_ts = 74.758774
current_received_ts = 74.758255
current_seq = 369
count = 345
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.739754/368, current 74.758774/369: elapsed=19024.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.758774
last_received_ts = 74.758255
last_seq = 369
current_ts = 74.777779
current_received_ts = 74.777237
current_seq = 370
count = 346
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.758774/369, current 74.777779/370: elapsed=19006.0us expected=19093.4us +- 95.5us, error 0.5%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.777779
last_received_ts = 74.777237
last_seq = 370
current_ts = 74.796806
current_received_ts = 74.796257
current_seq = 371
count = 347
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.777779/370, current 74.796806/371: elapsed=19025.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.796806
last_received_ts = 74.796257
last_seq = 371
current_ts = 74.815826
current_received_ts = 74.815277
current_seq = 372
count = 348
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.796806/371, current 74.815826/372: elapsed=19023.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.815826
last_received_ts = 74.815277
last_seq = 372
current_ts = 74.834846
current_received_ts = 74.834282
current_seq = 373
count = 349
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.815826/372, current 74.834846/373: elapsed=19021.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.834846
last_received_ts = 74.834282
last_seq = 373
current_ts = 74.853874
current_received_ts = 74.853455
current_seq = 374
count = 350
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.834846/373, current 74.853874/374: elapsed=19023.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.853874
last_received_ts = 74.853455
last_seq = 374
current_ts = 74.872894
current_received_ts = 74.872345
current_seq = 375
count = 351
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.853874/374, current 74.872894/375: elapsed=19019.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.872894
last_received_ts = 74.872345
last_seq = 375
current_ts = 74.891914
current_received_ts = 74.891373
current_seq = 376
count = 352
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.872894/375, current 74.891914/376: elapsed=19021.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.891914
last_received_ts = 74.891373
last_seq = 376
current_ts = 74.910934
current_received_ts = 74.910370
current_seq = 377
count = 353
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.891914/376, current 74.910934/377: elapsed=19021.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.910934
last_received_ts = 74.910370
last_seq = 377
current_ts = 74.929947
current_received_ts = 74.929420
current_seq = 378
count = 354
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.910934/377, current 74.929947/378: elapsed=19011.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.929947
last_received_ts = 74.929420
last_seq = 378
current_ts = 74.948975
current_received_ts = 74.948441
current_seq = 379
count = 355
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.929947/378, current 74.948975/379: elapsed=19031.0us expected=19093.4us +- 95.5us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.948975
last_received_ts = 74.948441
last_seq = 379
current_ts = 74.967995
current_received_ts = 74.967445
current_seq = 380
count = 356
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.948975/379, current 74.967995/380: elapsed=19020.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.967995
last_received_ts = 74.967445
last_seq = 380
current_ts = 74.987015
current_received_ts = 74.986473
current_seq = 381
count = 357
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.967995/380, current 74.987015/381: elapsed=19016.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 74.987015
last_received_ts = 74.986473
last_seq = 381
current_ts = 75.006035
current_received_ts = 75.005501
current_seq = 382
count = 358
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 74.987015/381, current 75.006035/382: elapsed=19026.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.006035
last_received_ts = 75.005501
last_seq = 382
current_ts = 75.025055
current_received_ts = 75.024483
current_seq = 383
count = 359
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.006035/382, current 75.025055/383: elapsed=19018.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.025055
last_received_ts = 75.024483
last_seq = 383
current_ts = 75.044083
current_received_ts = 75.043549
current_seq = 384
count = 360
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.025055/383, current 75.044083/384: elapsed=19027.0us expected=19093.4us +- 95.5us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.044083
last_received_ts = 75.043549
last_seq = 384
current_ts = 75.063103
current_received_ts = 75.062561
current_seq = 385
count = 361
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.044083/384, current 75.063103/385: elapsed=19022.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.063103
last_received_ts = 75.062561
last_seq = 385
current_ts = 75.082115
current_received_ts = 75.081573
current_seq = 386
count = 362
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.063103/385, current 75.082115/386: elapsed=19010.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.082115
last_received_ts = 75.081573
last_seq = 386
current_ts = 75.101135
current_received_ts = 75.100594
current_seq = 387
count = 363
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.082115/386, current 75.101135/387: elapsed=19023.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.101135
last_received_ts = 75.100594
last_seq = 387
current_ts = 75.120155
current_received_ts = 75.119637
current_seq = 388
count = 364
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.101135/387, current 75.120155/388: elapsed=19017.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.120155
last_received_ts = 75.119637
last_seq = 388
current_ts = 75.139191
current_received_ts = 75.138634
current_seq = 389
count = 365
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.120155/388, current 75.139191/389: elapsed=19032.0us expected=19093.4us +- 95.5us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.139191
last_received_ts = 75.138634
last_seq = 389
current_ts = 75.158203
current_received_ts = 75.157661
current_seq = 390
count = 366
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.139191/389, current 75.158203/390: elapsed=19013.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.158203
last_received_ts = 75.157661
last_seq = 390
current_ts = 75.177223
current_received_ts = 75.176674
current_seq = 391
count = 367
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.158203/390, current 75.177223/391: elapsed=19025.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.177223
last_received_ts = 75.176674
last_seq = 391
current_ts = 75.196243
current_received_ts = 75.195679
current_seq = 392
count = 368
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.177223/391, current 75.196243/392: elapsed=19016.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.196243
last_received_ts = 75.195679
last_seq = 392
current_ts = 75.215263
current_received_ts = 75.214806
current_seq = 393
count = 369
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.196243/392, current 75.215263/393: elapsed=19021.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.215263
last_received_ts = 75.214806
last_seq = 393
current_ts = 75.234291
current_received_ts = 75.233734
current_seq = 394
count = 370
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.215263/393, current 75.234291/394: elapsed=19027.0us expected=19093.4us +- 95.5us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.234291
last_received_ts = 75.233734
last_seq = 394
current_ts = 75.253311
current_received_ts = 75.252754
current_seq = 395
count = 371
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.234291/394, current 75.253311/395: elapsed=19019.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.253311
last_received_ts = 75.252754
last_seq = 395
current_ts = 75.272331
current_received_ts = 75.271759
current_seq = 396
count = 372
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.253311/395, current 75.272331/396: elapsed=19020.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.272331
last_received_ts = 75.271759
last_seq = 396
current_ts = 75.291336
current_received_ts = 75.290909
current_seq = 397
count = 373
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.272331/396, current 75.291336/397: elapsed=19010.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.291336
last_received_ts = 75.290909
last_seq = 397
current_ts = 75.310364
current_received_ts = 75.309830
current_seq = 398
count = 374
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.291336/397, current 75.310364/398: elapsed=19028.0us expected=19093.4us +- 95.5us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.310364
last_received_ts = 75.309830
last_seq = 398
current_ts = 75.329391
current_received_ts = 75.328857
current_seq = 399
count = 375
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.310364/398, current 75.329391/399: elapsed=19028.0us expected=19093.4us +- 95.5us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.329391
last_received_ts = 75.328857
last_seq = 399
current_ts = 75.348396
current_received_ts = 75.347832
current_seq = 400
count = 376
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.329391/399, current 75.348396/400: elapsed=19005.0us expected=19093.4us +- 95.5us, error 0.5%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.348396
last_received_ts = 75.347832
last_seq = 400
current_ts = 75.367424
current_received_ts = 75.366890
current_seq = 401
count = 377
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.348396/400, current 75.367424/401: elapsed=19027.0us expected=19093.4us +- 95.5us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.367424
last_received_ts = 75.366890
last_seq = 401
current_ts = 75.386452
current_received_ts = 75.385872
current_seq = 402
count = 378
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.367424/401, current 75.386452/402: elapsed=19022.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.386452
last_received_ts = 75.385872
last_seq = 402
current_ts = 75.405472
current_received_ts = 75.404915
current_seq = 403
count = 379
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.386452/402, current 75.405472/403: elapsed=19021.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.405472
last_received_ts = 75.404915
last_seq = 403
current_ts = 75.424492
current_received_ts = 75.423950
current_seq = 404
count = 380
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.405472/403, current 75.424492/404: elapsed=19024.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.424492
last_received_ts = 75.423950
last_seq = 404
current_ts = 75.443512
current_received_ts = 75.442970
current_seq = 405
count = 381
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.424492/404, current 75.443512/405: elapsed=19018.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.443512
last_received_ts = 75.442970
last_seq = 405
current_ts = 75.462532
current_received_ts = 75.461998
current_seq = 406
count = 382
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.443512/405, current 75.462532/406: elapsed=19024.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.462532
last_received_ts = 75.461998
last_seq = 406
current_ts = 75.481552
current_received_ts = 75.480995
current_seq = 407
count = 383
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.462532/406, current 75.481552/407: elapsed=19020.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.481552
last_received_ts = 75.480995
last_seq = 407
current_ts = 75.500580
current_received_ts = 75.500076
current_seq = 408
count = 384
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.481552/407, current 75.500580/408: elapsed=19023.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.500580
last_received_ts = 75.500076
last_seq = 408
current_ts = 75.519585
current_received_ts = 75.519127
current_seq = 409
count = 385
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.500580/408, current 75.519585/409: elapsed=19008.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.519585
last_received_ts = 75.519127
last_seq = 409
current_ts = 75.538597
current_received_ts = 75.538155
current_seq = 410
count = 386
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.519585/409, current 75.538597/410: elapsed=19014.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.538597
last_received_ts = 75.538155
last_seq = 410
current_ts = 75.557625
current_received_ts = 75.557114
current_seq = 411
count = 387
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.538597/410, current 75.557625/411: elapsed=19023.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.557625
last_received_ts = 75.557114
last_seq = 411
current_ts = 75.576637
current_received_ts = 75.576187
current_seq = 412
count = 388
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.557625/411, current 75.576637/412: elapsed=19017.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.576637
last_received_ts = 75.576187
last_seq = 412
current_ts = 75.595650
current_received_ts = 75.595139
current_seq = 413
count = 389
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.576637/412, current 75.595650/413: elapsed=19012.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.595650
last_received_ts = 75.595139
last_seq = 413
current_ts = 75.614655
current_received_ts = 75.614143
current_seq = 414
count = 390
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.595650/413, current 75.614655/414: elapsed=19002.0us expected=19093.4us +- 95.5us, error 0.5%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.614655
last_received_ts = 75.614143
last_seq = 414
current_ts = 75.633675
current_received_ts = 75.633240
current_seq = 415
count = 391
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.614655/414, current 75.633675/415: elapsed=19024.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.633675
last_received_ts = 75.633240
last_seq = 415
current_ts = 75.652687
current_received_ts = 75.652237
current_seq = 416
count = 392
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.633675/415, current 75.652687/416: elapsed=19011.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.652687
last_received_ts = 75.652237
last_seq = 416
current_ts = 75.671707
current_received_ts = 75.671150
current_seq = 417
count = 393
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.652687/416, current 75.671707/417: elapsed=19019.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.671707
last_received_ts = 75.671150
last_seq = 417
current_ts = 75.690720
current_received_ts = 75.690201
current_seq = 418
count = 394
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.671707/417, current 75.690720/418: elapsed=19014.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.690720
last_received_ts = 75.690201
last_seq = 418
current_ts = 75.709740
current_received_ts = 75.709221
current_seq = 419
count = 395
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.690720/418, current 75.709740/419: elapsed=19019.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.709740
last_received_ts = 75.709221
last_seq = 419
current_ts = 75.728745
current_received_ts = 75.728203
current_seq = 420
count = 396
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.709740/419, current 75.728745/420: elapsed=19002.0us expected=19093.4us +- 95.5us, error 0.5%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.728745
last_received_ts = 75.728203
last_seq = 420
current_ts = 75.747772
current_received_ts = 75.747238
current_seq = 421
count = 397
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.728745/420, current 75.747772/421: elapsed=19026.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.747772
last_received_ts = 75.747238
last_seq = 421
current_ts = 75.766785
current_received_ts = 75.766243
current_seq = 422
count = 398
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.747772/421, current 75.766785/422: elapsed=19014.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.766785
last_received_ts = 75.766243
last_seq = 422
current_ts = 75.785789
current_received_ts = 75.785248
current_seq = 423
count = 399
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.766785/422, current 75.785789/423: elapsed=19004.0us expected=19093.4us +- 95.5us, error 0.5%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.785789
last_received_ts = 75.785248
last_seq = 423
current_ts = 75.804810
current_received_ts = 75.804237
current_seq = 424
count = 400
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.785789/423, current 75.804810/424: elapsed=19019.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.804810
last_received_ts = 75.804237
last_seq = 424
current_ts = 75.823822
current_received_ts = 75.823265
current_seq = 425
count = 401
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.804810/424, current 75.823822/425: elapsed=19018.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.823822
last_received_ts = 75.823265
last_seq = 425
current_ts = 75.842842
current_received_ts = 75.842285
current_seq = 426
count = 402
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.823822/425, current 75.842842/426: elapsed=19016.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.842842
last_received_ts = 75.842285
last_seq = 426
current_ts = 75.861855
current_received_ts = 75.861305
current_seq = 427
count = 403
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.842842/426, current 75.861855/427: elapsed=19017.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.861855
last_received_ts = 75.861305
last_seq = 427
current_ts = 75.880867
current_received_ts = 75.880302
current_seq = 428
count = 404
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.861855/427, current 75.880867/428: elapsed=19010.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.880867
last_received_ts = 75.880302
last_seq = 428
current_ts = 75.899879
current_received_ts = 75.899323
current_seq = 429
count = 405
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.880867/428, current 75.899879/429: elapsed=19015.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.899879
last_received_ts = 75.899323
last_seq = 429
current_ts = 75.918900
current_received_ts = 75.918343
current_seq = 430
count = 406
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.899879/429, current 75.918900/430: elapsed=19020.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.918900
last_received_ts = 75.918343
last_seq = 430
current_ts = 75.937912
current_received_ts = 75.937302
current_seq = 431
count = 407
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.918900/430, current 75.937912/431: elapsed=19009.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.937912
last_received_ts = 75.937302
last_seq = 431
current_ts = 75.956932
current_received_ts = 75.956375
current_seq = 432
count = 408
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.937912/431, current 75.956932/432: elapsed=19021.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.956932
last_received_ts = 75.956375
last_seq = 432
current_ts = 75.975937
current_received_ts = 75.975410
current_seq = 433
count = 409
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.956932/432, current 75.975937/433: elapsed=19002.0us expected=19093.4us +- 95.5us, error 0.5%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.975937
last_received_ts = 75.975410
last_seq = 433
current_ts = 75.994965
current_received_ts = 75.994431
current_seq = 434
count = 410
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.975937/433, current 75.994965/434: elapsed=19028.0us expected=19093.4us +- 95.5us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 75.994965
last_received_ts = 75.994431
last_seq = 434
current_ts = 76.013977
current_received_ts = 76.013428
current_seq = 435
count = 411
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 75.994965/434, current 76.013977/435: elapsed=19016.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.013977
last_received_ts = 76.013428
last_seq = 435
current_ts = 76.032982
current_received_ts = 76.032425
current_seq = 436
count = 412
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.013977/435, current 76.032982/436: elapsed=19006.0us expected=19093.4us +- 95.5us, error 0.5%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.032982
last_received_ts = 76.032425
last_seq = 436
current_ts = 76.052010
current_received_ts = 76.051460
current_seq = 437
count = 413
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.032982/436, current 76.052010/437: elapsed=19023.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.052010
last_received_ts = 76.051460
last_seq = 437
current_ts = 76.071022
current_received_ts = 76.070480
current_seq = 438
count = 414
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.052010/437, current 76.071022/438: elapsed=19012.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.071022
last_received_ts = 76.070480
last_seq = 438
current_ts = 76.090034
current_received_ts = 76.089485
current_seq = 439
count = 415
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.071022/438, current 76.090034/439: elapsed=19017.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.090034
last_received_ts = 76.089485
last_seq = 439
current_ts = 76.109047
current_received_ts = 76.108597
current_seq = 440
count = 416
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.090034/439, current 76.109047/440: elapsed=19011.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.109047
last_received_ts = 76.108597
last_seq = 440
current_ts = 76.128067
current_received_ts = 76.127518
current_seq = 441
count = 417
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.109047/440, current 76.128067/441: elapsed=19020.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.128067
last_received_ts = 76.127518
last_seq = 441
current_ts = 76.147072
current_received_ts = 76.146500
current_seq = 442
count = 418
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.128067/441, current 76.147072/442: elapsed=19008.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.147072
last_received_ts = 76.146500
last_seq = 442
current_ts = 76.166092
current_received_ts = 76.165543
current_seq = 443
count = 419
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.147072/442, current 76.166092/443: elapsed=19020.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.166092
last_received_ts = 76.165543
last_seq = 443
current_ts = 76.185097
current_received_ts = 76.184570
current_seq = 444
count = 420
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.166092/443, current 76.185097/444: elapsed=19003.0us expected=19093.4us +- 95.5us, error 0.5%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.185097
last_received_ts = 76.184570
last_seq = 444
current_ts = 76.204124
current_received_ts = 76.203560
current_seq = 445
count = 421
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.185097/444, current 76.204124/445: elapsed=19026.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.204124
last_received_ts = 76.203560
last_seq = 445
current_ts = 76.223129
current_received_ts = 76.222588
current_seq = 446
count = 422
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.204124/445, current 76.223129/446: elapsed=19003.0us expected=19093.4us +- 95.5us, error 0.5%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.223129
last_received_ts = 76.222588
last_seq = 446
current_ts = 76.242142
current_received_ts = 76.241623
current_seq = 447
count = 423
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.223129/446, current 76.242142/447: elapsed=19016.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.242142
last_received_ts = 76.241623
last_seq = 447
current_ts = 76.261162
current_received_ts = 76.260620
current_seq = 448
count = 424
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.242142/447, current 76.261162/448: elapsed=19019.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.261162
last_received_ts = 76.260620
last_seq = 448
current_ts = 76.280174
current_received_ts = 76.279617
current_seq = 449
count = 425
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.261162/448, current 76.280174/449: elapsed=19016.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.280174
last_received_ts = 76.279617
last_seq = 449
current_ts = 76.299194
current_received_ts = 76.298645
current_seq = 450
count = 426
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.280174/449, current 76.299194/450: elapsed=19020.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.299194
last_received_ts = 76.298645
last_seq = 450
current_ts = 76.318207
current_received_ts = 76.317772
current_seq = 451
count = 427
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.299194/450, current 76.318207/451: elapsed=19010.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.318207
last_received_ts = 76.317772
last_seq = 451
current_ts = 76.337227
current_received_ts = 76.336685
current_seq = 452
count = 428
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.318207/451, current 76.337227/452: elapsed=19018.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.337227
last_received_ts = 76.336685
last_seq = 452
current_ts = 76.356232
current_received_ts = 76.355766
current_seq = 453
count = 429
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.337227/452, current 76.356232/453: elapsed=19008.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.356232
last_received_ts = 76.355766
last_seq = 453
current_ts = 76.375259
current_received_ts = 76.374725
current_seq = 454
count = 430
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.356232/453, current 76.375259/454: elapsed=19027.0us expected=19093.4us +- 95.5us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.375259
last_received_ts = 76.374725
last_seq = 454
current_ts = 76.394272
current_received_ts = 76.393715
current_seq = 455
count = 431
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.375259/454, current 76.394272/455: elapsed=19010.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.394272
last_received_ts = 76.393715
last_seq = 455
current_ts = 76.413284
current_received_ts = 76.412674
current_seq = 456
count = 432
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.394272/455, current 76.413284/456: elapsed=19015.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.413284
last_received_ts = 76.412674
last_seq = 456
current_ts = 76.432297
current_received_ts = 76.431740
current_seq = 457
count = 433
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.413284/456, current 76.432297/457: elapsed=19014.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.432297
last_received_ts = 76.431740
last_seq = 457
current_ts = 76.451317
current_received_ts = 76.450760
current_seq = 458
count = 434
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.432297/457, current 76.451317/458: elapsed=19017.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.451317
last_received_ts = 76.450760
last_seq = 458
current_ts = 76.470322
current_received_ts = 76.469887
current_seq = 459
count = 435
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.451317/458, current 76.470322/459: elapsed=19003.0us expected=19093.4us +- 95.5us, error 0.5%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.470322
last_received_ts = 76.469887
last_seq = 459
current_ts = 76.489342
current_received_ts = 76.488792
current_seq = 460
count = 436
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.470322/459, current 76.489342/460: elapsed=19024.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.489342
last_received_ts = 76.488792
last_seq = 460
current_ts = 76.508362
current_received_ts = 76.507805
current_seq = 461
count = 437
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.489342/460, current 76.508362/461: elapsed=19014.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.508362
last_received_ts = 76.507805
last_seq = 461
current_ts = 76.527367
current_received_ts = 76.526917
current_seq = 462
count = 438
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.508362/461, current 76.527367/462: elapsed=19009.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.527367
last_received_ts = 76.526917
last_seq = 462
current_ts = 76.546371
current_received_ts = 76.545937
current_seq = 463
count = 439
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.527367/462, current 76.546371/463: elapsed=19004.0us expected=19093.4us +- 95.5us, error 0.5%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.546371
last_received_ts = 76.545937
last_seq = 463
current_ts = 76.565384
current_received_ts = 76.564819
current_seq = 464
count = 440
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.546371/463, current 76.565384/464: elapsed=19016.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.565384
last_received_ts = 76.564819
last_seq = 464
current_ts = 76.584396
current_received_ts = 76.583862
current_seq = 465
count = 441
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.565384/464, current 76.584396/465: elapsed=19013.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.584396
last_received_ts = 76.583862
last_seq = 465
current_ts = 76.603409
current_received_ts = 76.602844
current_seq = 466
count = 442
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.584396/465, current 76.603409/466: elapsed=19006.0us expected=19093.4us +- 95.5us, error 0.5%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.603409
last_received_ts = 76.602844
last_seq = 466
current_ts = 76.622406
current_received_ts = 76.621880
current_seq = 467
count = 443
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.603409/466, current 76.622406/467: elapsed=18998.0us expected=19093.4us +- 95.5us, error 0.5%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.622406
last_received_ts = 76.621880
last_seq = 467
current_ts = 76.641426
current_received_ts = 76.640869
current_seq = 468
count = 444
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.622406/467, current 76.641426/468: elapsed=19021.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.641426
last_received_ts = 76.640869
last_seq = 468
current_ts = 76.660439
current_received_ts = 76.659897
current_seq = 469
count = 445
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.641426/468, current 76.660439/469: elapsed=19010.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.660439
last_received_ts = 76.659897
last_seq = 469
current_ts = 76.679443
current_received_ts = 76.678879
current_seq = 470
count = 446
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.660439/469, current 76.679443/470: elapsed=19008.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.679443
last_received_ts = 76.678879
last_seq = 470
current_ts = 76.698456
current_received_ts = 76.698044
current_seq = 471
count = 447
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.679443/470, current 76.698456/471: elapsed=19015.0us expected=19093.4us +- 95.5us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 76.698456
last_received_ts = 76.698044
last_seq = 471
current_ts = 76.717453
current_received_ts = 76.716866
current_seq = 472
count = 448
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 76.698456/471, current 76.717453/472: elapsed=18997.0us expected=19093.4us +- 95.5us, error 0.5%
(kms_flip:2058) DEBUG: inconsistent flip ts/seq: last 76.698456/471, current 76.717453/472: elapsed=18997.0us expected=19093.4us
(kms_flip:2058) DEBUG: expected 114012, counted 448, encoder type 2
(kms_flip:2058) DEBUG: dropped frames, expected 114012, counted 448, encoder type 2
(kms_flip:2058) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2058) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2058) igt_core-INFO: Stack trace:
(kms_flip:2058) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2058) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2058) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2058) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2058) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2058) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2058) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2058) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A2: FAIL (12.108s)
Subtest plain-flip-fb-recreate: FAIL (18.473s)
(kms_flip:2058) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2246:
(kms_flip:2058) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:2058) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:2058) igt_kms-CRITICAL: DPMS property not found on 147