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

shard-lnl-2

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

Using IGT_SRANDOM=1740434628 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Expected frametime: 16664us; measured 16664.8us +- 3.449us accuracy 0.06%
Dynamic subtest A-eDP1: SUCCESS (11.644s)
Starting dynamic subtest: B-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Expected frametime: 16664us; measured 16664.9us +- 4.234us accuracy 0.08%
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (5.841s)
Starting dynamic subtest: C-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Expected frametime: 16664us; measured 16733.9us +- 3.890us accuracy 0.07%
vblank interval differs from modeline! expected 16664.0us, measured 16734us +- 3.890us, difference 69.9us (18.0 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-eDP1: FAIL (14.815s)
Subtest plain-flip-ts-check: FAIL (32.308s)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2246 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2930 igt_atexit_handler()
  #3 [erand48_r+0x1d6]
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2386 igt_exit()
  #6 [main+0x3f]
  #7 [__libc_init_first+0x8a]
  #8 [__libc_start_main+0x8b]
  #9 [_start+0x25]

Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-eDP1
Dynamic subtest A-eDP1: SUCCESS (11.644s)
Starting dynamic subtest: B-eDP1
(kms_flip:6406) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:6406) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:6406) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:6406) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=11520)
(kms_flip:6406) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:6406) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:6406) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=11520)
(kms_flip:6406) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:6406) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:6406) intel_allocator_simple-DEBUG: <ial: 0x5a0eb7a54570, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:6406) intel_allocator_simple-DEBUG: <ial: 0x5a0eb7a54570, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:6406) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:6406) intel_allocator_simple-DEBUG: <ial: 0x5a0eb7a54570, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:6406) intel_allocator_simple-DEBUG: <ial: 0x5a0eb7a54570, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:6406) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:6406) intel_allocator_simple-DEBUG: <ial: 0x5a0eb79f5e90, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:6406) intel_allocator_simple-DEBUG: <ial: 0x5a0eb79f5e90, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:6406) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:6406) intel_allocator_simple-DEBUG: <ial: 0x5a0eb7a54570, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:6406) intel_allocator_simple-DEBUG: <ial: 0x5a0eb7a54570, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:6406) igt_kms-INFO:   2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
(kms_flip:6406) DEBUG: No stale events found
(kms_flip:6406) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:6406) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:6406) INFO: Expected frametime: 16664us; measured 16664.9us +- 4.234us accuracy 0.08%
(kms_flip:6406) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 181.629852
current_received_ts = 181.629196
current_seq = 63
count = 0
seq_step = 1
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.629852
last_received_ts = 181.629196
last_seq = 63
current_ts = 181.646515
current_received_ts = 181.645844
current_seq = 64
count = 1
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.629852/63, current 181.646515/64: elapsed=16666.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.646515
last_received_ts = 181.645844
last_seq = 64
current_ts = 181.663177
current_received_ts = 181.662460
current_seq = 65
count = 2
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.646515/64, current 181.663177/65: elapsed=16665.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.663177
last_received_ts = 181.662460
last_seq = 65
current_ts = 181.679840
current_received_ts = 181.679199
current_seq = 66
count = 3
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.663177/65, current 181.679840/66: elapsed=16662.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.679840
last_received_ts = 181.679199
last_seq = 66
current_ts = 181.696503
current_received_ts = 181.695969
current_seq = 67
count = 4
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.679840/66, current 181.696503/67: elapsed=16660.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.696503
last_received_ts = 181.695969
last_seq = 67
current_ts = 181.713181
current_received_ts = 181.712448
current_seq = 68
count = 5
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.696503/67, current 181.713181/68: elapsed=16673.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.713181
last_received_ts = 181.712448
last_seq = 68
current_ts = 181.729843
current_received_ts = 181.729172
current_seq = 69
count = 6
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.713181/68, current 181.729843/69: elapsed=16661.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.729843
last_received_ts = 181.729172
last_seq = 69
current_ts = 181.746506
current_received_ts = 181.745850
current_seq = 70
count = 7
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.729843/69, current 181.746506/70: elapsed=16664.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.746506
last_received_ts = 181.745850
last_seq = 70
current_ts = 181.763168
current_received_ts = 181.762451
current_seq = 71
count = 8
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.746506/70, current 181.763168/71: elapsed=16668.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.763168
last_received_ts = 181.762451
last_seq = 71
current_ts = 181.779831
current_received_ts = 181.779175
current_seq = 72
count = 9
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.763168/71, current 181.779831/72: elapsed=16664.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.779831
last_received_ts = 181.779175
last_seq = 72
current_ts = 181.796494
current_received_ts = 181.795822
current_seq = 73
count = 10
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.779831/72, current 181.796494/73: elapsed=16663.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.796494
last_received_ts = 181.795822
last_seq = 73
current_ts = 181.813171
current_received_ts = 181.812485
current_seq = 74
count = 11
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.796494/73, current 181.813171/74: elapsed=16666.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.813171
last_received_ts = 181.812485
last_seq = 74
current_ts = 181.829834
current_received_ts = 181.829163
current_seq = 75
count = 12
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.813171/74, current 181.829834/75: elapsed=16665.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.829834
last_received_ts = 181.829163
last_seq = 75
current_ts = 181.846497
current_received_ts = 181.845917
current_seq = 76
count = 13
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.829834/75, current 181.846497/76: elapsed=16660.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.846497
last_received_ts = 181.845917
last_seq = 76
current_ts = 181.863159
current_received_ts = 181.862549
current_seq = 77
count = 14
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.846497/76, current 181.863159/77: elapsed=16667.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.863159
last_received_ts = 181.862549
last_seq = 77
current_ts = 181.879822
current_received_ts = 181.879211
current_seq = 78
count = 15
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.863159/77, current 181.879822/78: elapsed=16669.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.879822
last_received_ts = 181.879211
last_seq = 78
current_ts = 181.896484
current_received_ts = 181.895889
current_seq = 79
count = 16
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.879822/78, current 181.896484/79: elapsed=16661.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.896484
last_received_ts = 181.895889
last_seq = 79
current_ts = 181.913147
current_received_ts = 181.912567
current_seq = 80
count = 17
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.896484/79, current 181.913147/80: elapsed=16663.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.913147
last_received_ts = 181.912567
last_seq = 80
current_ts = 181.929825
current_received_ts = 181.929230
current_seq = 81
count = 18
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.913147/80, current 181.929825/81: elapsed=16671.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.929825
last_received_ts = 181.929230
last_seq = 81
current_ts = 181.946487
current_received_ts = 181.945908
current_seq = 82
count = 19
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.929825/81, current 181.946487/82: elapsed=16660.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.946487
last_received_ts = 181.945908
last_seq = 82
current_ts = 181.963150
current_received_ts = 181.962677
current_seq = 83
count = 20
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.946487/82, current 181.963150/83: elapsed=16666.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.963150
last_received_ts = 181.962677
last_seq = 83
current_ts = 181.979813
current_received_ts = 181.979218
current_seq = 84
count = 21
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.963150/83, current 181.979813/84: elapsed=16663.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.979813
last_received_ts = 181.979218
last_seq = 84
current_ts = 181.996475
current_received_ts = 181.995895
current_seq = 85
count = 22
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.979813/84, current 181.996475/85: elapsed=16667.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 181.996475
last_received_ts = 181.995895
last_seq = 85
current_ts = 182.013138
current_received_ts = 182.012512
current_seq = 86
count = 23
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 181.996475/85, current 182.013138/86: elapsed=16667.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.013138
last_received_ts = 182.012512
last_seq = 86
current_ts = 182.029816
current_received_ts = 182.029205
current_seq = 87
count = 24
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.013138/86, current 182.029816/87: elapsed=16666.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.029816
last_received_ts = 182.029205
last_seq = 87
current_ts = 182.046478
current_received_ts = 182.045853
current_seq = 88
count = 25
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.029816/87, current 182.046478/88: elapsed=16661.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.046478
last_received_ts = 182.045853
last_seq = 88
current_ts = 182.063141
current_received_ts = 182.062469
current_seq = 89
count = 26
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.046478/88, current 182.063141/89: elapsed=16664.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.063141
last_received_ts = 182.062469
last_seq = 89
current_ts = 182.079803
current_received_ts = 182.079208
current_seq = 90
count = 27
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.063141/89, current 182.079803/90: elapsed=16668.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.079803
last_received_ts = 182.079208
last_seq = 90
current_ts = 182.096466
current_received_ts = 182.095901
current_seq = 91
count = 28
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.079803/90, current 182.096466/91: elapsed=16664.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.096466
last_received_ts = 182.095901
last_seq = 91
current_ts = 182.113129
current_received_ts = 182.112549
current_seq = 92
count = 29
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.096466/91, current 182.113129/92: elapsed=16661.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.113129
last_received_ts = 182.112549
last_seq = 92
current_ts = 182.129807
current_received_ts = 182.129211
current_seq = 93
count = 30
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.113129/92, current 182.129807/93: elapsed=16671.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.129807
last_received_ts = 182.129211
last_seq = 93
current_ts = 182.146469
current_received_ts = 182.145889
current_seq = 94
count = 31
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.129807/93, current 182.146469/94: elapsed=16665.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.146469
last_received_ts = 182.145889
last_seq = 94
current_ts = 182.163132
current_received_ts = 182.162537
current_seq = 95
count = 32
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.146469/94, current 182.163132/95: elapsed=16664.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.163132
last_received_ts = 182.162537
last_seq = 95
current_ts = 182.179794
current_received_ts = 182.179199
current_seq = 96
count = 33
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.163132/95, current 182.179794/96: elapsed=16663.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.179794
last_received_ts = 182.179199
last_seq = 96
current_ts = 182.196457
current_received_ts = 182.195877
current_seq = 97
count = 34
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.179794/96, current 182.196457/97: elapsed=16668.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.196457
last_received_ts = 182.195877
last_seq = 97
current_ts = 182.213120
current_received_ts = 182.212677
current_seq = 98
count = 35
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.196457/97, current 182.213120/98: elapsed=16662.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.213120
last_received_ts = 182.212677
last_seq = 98
current_ts = 182.229797
current_received_ts = 182.229202
current_seq = 99
count = 36
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.213120/98, current 182.229797/99: elapsed=16668.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.229797
last_received_ts = 182.229202
last_seq = 99
current_ts = 182.246460
current_received_ts = 182.245819
current_seq = 100
count = 37
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.229797/99, current 182.246460/100: elapsed=16663.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.246460
last_received_ts = 182.245819
last_seq = 100
current_ts = 182.263107
current_received_ts = 182.262482
current_seq = 101
count = 38
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.246460/100, current 182.263107/101: elapsed=16661.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.263107
last_received_ts = 182.262482
last_seq = 101
current_ts = 182.279785
current_received_ts = 182.279205
current_seq = 102
count = 39
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.263107/101, current 182.279785/102: elapsed=16669.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.279785
last_received_ts = 182.279205
last_seq = 102
current_ts = 182.296448
current_received_ts = 182.295837
current_seq = 103
count = 40
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.279785/102, current 182.296448/103: elapsed=16666.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.296448
last_received_ts = 182.295837
last_seq = 103
current_ts = 182.313110
current_received_ts = 182.312454
current_seq = 104
count = 41
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.296448/103, current 182.313110/104: elapsed=16659.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.313110
last_received_ts = 182.312454
last_seq = 104
current_ts = 182.329773
current_received_ts = 182.329193
current_seq = 105
count = 42
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.313110/104, current 182.329773/105: elapsed=16666.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.329773
last_received_ts = 182.329193
last_seq = 105
current_ts = 182.346436
current_received_ts = 182.345840
current_seq = 106
count = 43
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.329773/105, current 182.346436/106: elapsed=16662.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.346436
last_received_ts = 182.345840
last_seq = 106
current_ts = 182.363113
current_received_ts = 182.362518
current_seq = 107
count = 44
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.346436/106, current 182.363113/107: elapsed=16672.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.363113
last_received_ts = 182.362518
last_seq = 107
current_ts = 182.379761
current_received_ts = 182.379181
current_seq = 108
count = 45
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.363113/107, current 182.379761/108: elapsed=16657.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.379761
last_received_ts = 182.379181
last_seq = 108
current_ts = 182.396439
current_received_ts = 182.395859
current_seq = 109
count = 46
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.379761/108, current 182.396439/109: elapsed=16668.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.396439
last_received_ts = 182.395859
last_seq = 109
current_ts = 182.413101
current_received_ts = 182.412552
current_seq = 110
count = 47
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.396439/109, current 182.413101/110: elapsed=16668.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.413101
last_received_ts = 182.412552
last_seq = 110
current_ts = 182.429764
current_received_ts = 182.429184
current_seq = 111
count = 48
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.413101/110, current 182.429764/111: elapsed=16659.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.429764
last_received_ts = 182.429184
last_seq = 111
current_ts = 182.446426
current_received_ts = 182.445847
current_seq = 112
count = 49
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.429764/111, current 182.446426/112: elapsed=16666.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.446426
last_received_ts = 182.445847
last_seq = 112
current_ts = 182.463089
current_received_ts = 182.462616
current_seq = 113
count = 50
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.446426/112, current 182.463089/113: elapsed=16668.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.463089
last_received_ts = 182.462616
last_seq = 113
current_ts = 182.479767
current_received_ts = 182.479187
current_seq = 114
count = 51
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.463089/113, current 182.479767/114: elapsed=16667.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.479767
last_received_ts = 182.479187
last_seq = 114
current_ts = 182.496429
current_received_ts = 182.495834
current_seq = 115
count = 52
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.479767/114, current 182.496429/115: elapsed=16662.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.496429
last_received_ts = 182.495834
last_seq = 115
current_ts = 182.513092
current_received_ts = 182.512466
current_seq = 116
count = 53
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.496429/115, current 182.513092/116: elapsed=16662.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.513092
last_received_ts = 182.512466
last_seq = 116
current_ts = 182.529755
current_received_ts = 182.529175
current_seq = 117
count = 54
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.513092/116, current 182.529755/117: elapsed=16672.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.529755
last_received_ts = 182.529175
last_seq = 117
current_ts = 182.546417
current_received_ts = 182.545837
current_seq = 118
count = 55
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.529755/117, current 182.546417/118: elapsed=16660.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.546417
last_received_ts = 182.545837
last_seq = 118
current_ts = 182.563080
current_received_ts = 182.562469
current_seq = 119
count = 56
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.546417/118, current 182.563080/119: elapsed=16668.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.563080
last_received_ts = 182.562469
last_seq = 119
current_ts = 182.579742
current_received_ts = 182.579193
current_seq = 120
count = 57
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.563080/119, current 182.579742/120: elapsed=16663.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.579742
last_received_ts = 182.579193
last_seq = 120
current_ts = 182.596420
current_received_ts = 182.595825
current_seq = 121
count = 58
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.579742/120, current 182.596420/121: elapsed=16666.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.596420
last_received_ts = 182.595825
last_seq = 121
current_ts = 182.613083
current_received_ts = 182.612457
current_seq = 122
count = 59
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.596420/121, current 182.613083/122: elapsed=16663.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.613083
last_received_ts = 182.612457
last_seq = 122
current_ts = 182.629745
current_received_ts = 182.629181
current_seq = 123
count = 60
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.613083/122, current 182.629745/123: elapsed=16664.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.629745
last_received_ts = 182.629181
last_seq = 123
current_ts = 182.646408
current_received_ts = 182.645844
current_seq = 124
count = 61
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.629745/123, current 182.646408/124: elapsed=16663.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.646408
last_received_ts = 182.645844
last_seq = 124
current_ts = 182.663071
current_received_ts = 182.662445
current_seq = 125
count = 62
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.646408/124, current 182.663071/125: elapsed=16666.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.663071
last_received_ts = 182.662445
last_seq = 125
current_ts = 182.679733
current_received_ts = 182.679184
current_seq = 126
count = 63
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.663071/125, current 182.679733/126: elapsed=16670.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.679733
last_received_ts = 182.679184
last_seq = 126
current_ts = 182.696396
current_received_ts = 182.695847
current_seq = 127
count = 64
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.679733/126, current 182.696396/127: elapsed=16662.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.696396
last_received_ts = 182.695847
last_seq = 127
current_ts = 182.713074
current_received_ts = 182.712601
current_seq = 128
count = 65
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.696396/127, current 182.713074/128: elapsed=16667.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.713074
last_received_ts = 182.712601
last_seq = 128
current_ts = 182.729736
current_received_ts = 182.729156
current_seq = 129
count = 66
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.713074/128, current 182.729736/129: elapsed=16664.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.729736
last_received_ts = 182.729156
last_seq = 129
current_ts = 182.746399
current_received_ts = 182.745834
current_seq = 130
count = 67
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.729736/129, current 182.746399/130: elapsed=16664.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.746399
last_received_ts = 182.745834
last_seq = 130
current_ts = 182.763062
current_received_ts = 182.762436
current_seq = 131
count = 68
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.746399/130, current 182.763062/131: elapsed=16665.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.763062
last_received_ts = 182.762436
last_seq = 131
current_ts = 182.779724
current_received_ts = 182.779160
current_seq = 132
count = 69
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.763062/131, current 182.779724/132: elapsed=16664.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.779724
last_received_ts = 182.779160
last_seq = 132
current_ts = 182.796387
current_received_ts = 182.795807
current_seq = 133
count = 70
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.779724/132, current 182.796387/133: elapsed=16663.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.796387
last_received_ts = 182.795807
last_seq = 133
current_ts = 182.813049
current_received_ts = 182.812485
current_seq = 134
count = 71
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.796387/133, current 182.813049/134: elapsed=16667.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.813049
last_received_ts = 182.812485
last_seq = 134
current_ts = 182.829727
current_received_ts = 182.829163
current_seq = 135
count = 72
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.813049/134, current 182.829727/135: elapsed=16665.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.829727
last_received_ts = 182.829163
last_seq = 135
current_ts = 182.846390
current_received_ts = 182.845795
current_seq = 136
count = 73
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.829727/135, current 182.846390/136: elapsed=16668.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.846390
last_received_ts = 182.845795
last_seq = 136
current_ts = 182.863052
current_received_ts = 182.862411
current_seq = 137
count = 74
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.846390/136, current 182.863052/137: elapsed=16663.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.863052
last_received_ts = 182.862411
last_seq = 137
current_ts = 182.879715
current_received_ts = 182.879166
current_seq = 138
count = 75
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.863052/137, current 182.879715/138: elapsed=16665.0us expected=16664.9us +- 83.3us, error 0.0%
(kms_flip:6406) DEBUG: name = flip
last_ts = 182.879715
last_received_ts = 182.879166
last_seq = 138
current_ts = 182.896484
current_received_ts = 182.895844
current_seq = 139
count = 76
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 182.879715/138, current 182.896484/139: elapsed=16770.0us expected=16664.9us +- 83.3us, error 0.6%
(kms_flip:6406) DEBUG: inconsistent flip ts/seq: last 182.879715/138, current 182.896484/139: elapsed=16770.0us expected=16664.9us
(kms_flip:6406) DEBUG: expected 601, counted 76, encoder type 2
(kms_flip:6406) DEBUG: dropped frames, expected 601, counted 76, encoder type 2
(kms_flip:6406) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:6406) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:6406) igt_core-INFO: Stack trace:
(kms_flip:6406) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:6406) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:6406) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:6406) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:6406) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:6406) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:6406) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:6406) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (5.841s)
Starting dynamic subtest: C-eDP1
(kms_flip:6406) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:6406) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest C-eDP1 failed.
**** DEBUG ****
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.529892
last_received_ts = 195.529373
last_seq = 511
current_ts = 195.546585
current_received_ts = 195.546066
current_seq = 512
count = 478
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.529892/511, current 195.546585/512: elapsed=16694.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.546585
last_received_ts = 195.546066
last_seq = 512
current_ts = 195.563278
current_received_ts = 195.562714
current_seq = 513
count = 479
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.546585/512, current 195.563278/513: elapsed=16695.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.563278
last_received_ts = 195.562714
last_seq = 513
current_ts = 195.579971
current_received_ts = 195.579361
current_seq = 514
count = 480
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.563278/513, current 195.579971/514: elapsed=16693.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.579971
last_received_ts = 195.579361
last_seq = 514
current_ts = 195.596664
current_received_ts = 195.596115
current_seq = 515
count = 481
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.579971/514, current 195.596664/515: elapsed=16690.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.596664
last_received_ts = 195.596115
last_seq = 515
current_ts = 195.613358
current_received_ts = 195.612808
current_seq = 516
count = 482
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.596664/515, current 195.613358/516: elapsed=16694.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.613358
last_received_ts = 195.612808
last_seq = 516
current_ts = 195.630051
current_received_ts = 195.629501
current_seq = 517
count = 483
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.613358/516, current 195.630051/517: elapsed=16695.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.630051
last_received_ts = 195.629501
last_seq = 517
current_ts = 195.646744
current_received_ts = 195.646194
current_seq = 518
count = 484
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.630051/517, current 195.646744/518: elapsed=16691.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.646744
last_received_ts = 195.646194
last_seq = 518
current_ts = 195.663437
current_received_ts = 195.662903
current_seq = 519
count = 485
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.646744/518, current 195.663437/519: elapsed=16694.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.663437
last_received_ts = 195.662903
last_seq = 519
current_ts = 195.680130
current_received_ts = 195.679565
current_seq = 520
count = 486
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.663437/519, current 195.680130/520: elapsed=16695.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.680130
last_received_ts = 195.679565
last_seq = 520
current_ts = 195.696823
current_received_ts = 195.696198
current_seq = 521
count = 487
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.680130/520, current 195.696823/521: elapsed=16693.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.696823
last_received_ts = 195.696198
last_seq = 521
current_ts = 195.713531
current_received_ts = 195.712982
current_seq = 522
count = 488
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.696823/521, current 195.713531/522: elapsed=16696.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.713531
last_received_ts = 195.712982
last_seq = 522
current_ts = 195.730209
current_received_ts = 195.729645
current_seq = 523
count = 489
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.713531/522, current 195.730209/523: elapsed=16691.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.730209
last_received_ts = 195.729645
last_seq = 523
current_ts = 195.746902
current_received_ts = 195.746338
current_seq = 524
count = 490
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.730209/523, current 195.746902/524: elapsed=16691.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.746902
last_received_ts = 195.746338
last_seq = 524
current_ts = 195.763596
current_received_ts = 195.763077
current_seq = 525
count = 491
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.746902/524, current 195.763596/525: elapsed=16696.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.763596
last_received_ts = 195.763077
last_seq = 525
current_ts = 195.780289
current_received_ts = 195.779739
current_seq = 526
count = 492
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.763596/525, current 195.780289/526: elapsed=16694.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.780289
last_received_ts = 195.779739
last_seq = 526
current_ts = 195.796982
current_received_ts = 195.796432
current_seq = 527
count = 493
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.780289/526, current 195.796982/527: elapsed=16693.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.796982
last_received_ts = 195.796432
last_seq = 527
current_ts = 195.813675
current_received_ts = 195.813126
current_seq = 528
count = 494
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.796982/527, current 195.813675/528: elapsed=16693.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.813675
last_received_ts = 195.813126
last_seq = 528
current_ts = 195.830368
current_received_ts = 195.829849
current_seq = 529
count = 495
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.813675/528, current 195.830368/529: elapsed=16688.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.830368
last_received_ts = 195.829849
last_seq = 529
current_ts = 195.847061
current_received_ts = 195.846481
current_seq = 530
count = 496
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.830368/529, current 195.847061/530: elapsed=16694.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.847061
last_received_ts = 195.846481
last_seq = 530
current_ts = 195.863754
current_received_ts = 195.863190
current_seq = 531
count = 497
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.847061/530, current 195.863754/531: elapsed=16697.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.863754
last_received_ts = 195.863190
last_seq = 531
current_ts = 195.880463
current_received_ts = 195.879898
current_seq = 532
count = 498
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.863754/531, current 195.880463/532: elapsed=16696.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.880463
last_received_ts = 195.879898
last_seq = 532
current_ts = 195.897141
current_received_ts = 195.896530
current_seq = 533
count = 499
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.880463/532, current 195.897141/533: elapsed=16686.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.897141
last_received_ts = 195.896530
last_seq = 533
current_ts = 195.913834
current_received_ts = 195.913193
current_seq = 534
count = 500
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.897141/533, current 195.913834/534: elapsed=16695.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.913834
last_received_ts = 195.913193
last_seq = 534
current_ts = 195.930527
current_received_ts = 195.929962
current_seq = 535
count = 501
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.913834/534, current 195.930527/535: elapsed=16690.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.930527
last_received_ts = 195.929962
last_seq = 535
current_ts = 195.947220
current_received_ts = 195.946640
current_seq = 536
count = 502
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.930527/535, current 195.947220/536: elapsed=16689.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.947220
last_received_ts = 195.946640
last_seq = 536
current_ts = 195.963913
current_received_ts = 195.963318
current_seq = 537
count = 503
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.947220/536, current 195.963913/537: elapsed=16693.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.963913
last_received_ts = 195.963318
last_seq = 537
current_ts = 195.980606
current_received_ts = 195.980194
current_seq = 538
count = 504
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.963913/537, current 195.980606/538: elapsed=16692.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.980606
last_received_ts = 195.980194
last_seq = 538
current_ts = 195.997299
current_received_ts = 195.996719
current_seq = 539
count = 505
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.980606/538, current 195.997299/539: elapsed=16690.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 195.997299
last_received_ts = 195.996719
last_seq = 539
current_ts = 196.013977
current_received_ts = 196.013428
current_seq = 540
count = 506
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 195.997299/539, current 196.013977/540: elapsed=16690.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.013977
last_received_ts = 196.013428
last_seq = 540
current_ts = 196.030670
current_received_ts = 196.030121
current_seq = 541
count = 507
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.013977/540, current 196.030670/541: elapsed=16689.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.030670
last_received_ts = 196.030121
last_seq = 541
current_ts = 196.047363
current_received_ts = 196.046814
current_seq = 542
count = 508
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.030670/541, current 196.047363/542: elapsed=16691.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.047363
last_received_ts = 196.046814
last_seq = 542
current_ts = 196.064056
current_received_ts = 196.063431
current_seq = 543
count = 509
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.047363/542, current 196.064056/543: elapsed=16690.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.064056
last_received_ts = 196.063431
last_seq = 543
current_ts = 196.080750
current_received_ts = 196.080200
current_seq = 544
count = 510
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.064056/543, current 196.080750/544: elapsed=16691.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.080750
last_received_ts = 196.080200
last_seq = 544
current_ts = 196.097443
current_received_ts = 196.096848
current_seq = 545
count = 511
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.080750/544, current 196.097443/545: elapsed=16693.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.097443
last_received_ts = 196.096848
last_seq = 545
current_ts = 196.114120
current_received_ts = 196.113510
current_seq = 546
count = 512
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.097443/545, current 196.114120/546: elapsed=16689.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.114120
last_received_ts = 196.113510
last_seq = 546
current_ts = 196.130814
current_received_ts = 196.130234
current_seq = 547
count = 513
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.114120/546, current 196.130814/547: elapsed=16693.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.130814
last_received_ts = 196.130234
last_seq = 547
current_ts = 196.147507
current_received_ts = 196.147095
current_seq = 548
count = 514
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.130814/547, current 196.147507/548: elapsed=16690.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.147507
last_received_ts = 196.147095
last_seq = 548
current_ts = 196.164200
current_received_ts = 196.163620
current_seq = 549
count = 515
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.147507/548, current 196.164200/549: elapsed=16690.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.164200
last_received_ts = 196.163620
last_seq = 549
current_ts = 196.180878
current_received_ts = 196.180328
current_seq = 550
count = 516
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.164200/549, current 196.180878/550: elapsed=16686.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.180878
last_received_ts = 196.180328
last_seq = 550
current_ts = 196.197586
current_received_ts = 196.197067
current_seq = 551
count = 517
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.180878/550, current 196.197586/551: elapsed=16695.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.197586
last_received_ts = 196.197067
last_seq = 551
current_ts = 196.214264
current_received_ts = 196.213699
current_seq = 552
count = 518
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.197586/551, current 196.214264/552: elapsed=16691.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.214264
last_received_ts = 196.213699
last_seq = 552
current_ts = 196.230957
current_received_ts = 196.230362
current_seq = 553
count = 519
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.214264/552, current 196.230957/553: elapsed=16692.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.230957
last_received_ts = 196.230362
last_seq = 553
current_ts = 196.247650
current_received_ts = 196.247086
current_seq = 554
count = 520
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.230957/553, current 196.247650/554: elapsed=16689.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.247650
last_received_ts = 196.247086
last_seq = 554
current_ts = 196.264343
current_received_ts = 196.263809
current_seq = 555
count = 521
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.247650/554, current 196.264343/555: elapsed=16693.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.264343
last_received_ts = 196.263809
last_seq = 555
current_ts = 196.281036
current_received_ts = 196.280472
current_seq = 556
count = 522
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.264343/555, current 196.281036/556: elapsed=16690.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.281036
last_received_ts = 196.280472
last_seq = 556
current_ts = 196.297729
current_received_ts = 196.297180
current_seq = 557
count = 523
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.281036/556, current 196.297729/557: elapsed=16691.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.297729
last_received_ts = 196.297180
last_seq = 557
current_ts = 196.314423
current_received_ts = 196.313858
current_seq = 558
count = 524
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.297729/557, current 196.314423/558: elapsed=16692.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.314423
last_received_ts = 196.313858
last_seq = 558
current_ts = 196.331100
current_received_ts = 196.330551
current_seq = 559
count = 525
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.314423/558, current 196.331100/559: elapsed=16689.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.331100
last_received_ts = 196.330551
last_seq = 559
current_ts = 196.347794
current_received_ts = 196.347229
current_seq = 560
count = 526
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.331100/559, current 196.347794/560: elapsed=16691.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.347794
last_received_ts = 196.347229
last_seq = 560
current_ts = 196.364487
current_received_ts = 196.363937
current_seq = 561
count = 527
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.347794/560, current 196.364487/561: elapsed=16691.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.364487
last_received_ts = 196.363937
last_seq = 561
current_ts = 196.381180
current_received_ts = 196.380630
current_seq = 562
count = 528
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.364487/561, current 196.381180/562: elapsed=16692.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.381180
last_received_ts = 196.380630
last_seq = 562
current_ts = 196.397873
current_received_ts = 196.397202
current_seq = 563
count = 529
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.381180/562, current 196.397873/563: elapsed=16688.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.397873
last_received_ts = 196.397202
last_seq = 563
current_ts = 196.414551
current_received_ts = 196.414032
current_seq = 564
count = 530
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.397873/563, current 196.414551/564: elapsed=16688.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.414551
last_received_ts = 196.414032
last_seq = 564
current_ts = 196.431244
current_received_ts = 196.430710
current_seq = 565
count = 531
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.414551/564, current 196.431244/565: elapsed=16695.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.431244
last_received_ts = 196.430710
last_seq = 565
current_ts = 196.447937
current_received_ts = 196.447403
current_seq = 566
count = 532
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.431244/565, current 196.447937/566: elapsed=16688.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.447937
last_received_ts = 196.447403
last_seq = 566
current_ts = 196.464630
current_received_ts = 196.464096
current_seq = 567
count = 533
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.447937/566, current 196.464630/567: elapsed=16692.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.464630
last_received_ts = 196.464096
last_seq = 567
current_ts = 196.481323
current_received_ts = 196.480896
current_seq = 568
count = 534
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.464630/567, current 196.481323/568: elapsed=16690.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.481323
last_received_ts = 196.480896
last_seq = 568
current_ts = 196.498016
current_received_ts = 196.497391
current_seq = 569
count = 535
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.481323/568, current 196.498016/569: elapsed=16696.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.498016
last_received_ts = 196.497391
last_seq = 569
current_ts = 196.514709
current_received_ts = 196.514145
current_seq = 570
count = 536
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.498016/569, current 196.514709/570: elapsed=16687.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.514709
last_received_ts = 196.514145
last_seq = 570
current_ts = 196.531403
current_received_ts = 196.530823
current_seq = 571
count = 537
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.514709/570, current 196.531403/571: elapsed=16694.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.531403
last_received_ts = 196.530823
last_seq = 571
current_ts = 196.548080
current_received_ts = 196.547455
current_seq = 572
count = 538
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.531403/571, current 196.548080/572: elapsed=16689.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.548080
last_received_ts = 196.547455
last_seq = 572
current_ts = 196.564774
current_received_ts = 196.564194
current_seq = 573
count = 539
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.548080/572, current 196.564774/573: elapsed=16686.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.564774
last_received_ts = 196.564194
last_seq = 573
current_ts = 196.581467
current_received_ts = 196.580933
current_seq = 574
count = 540
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.564774/573, current 196.581467/574: elapsed=16693.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.581467
last_received_ts = 196.580933
last_seq = 574
current_ts = 196.598160
current_received_ts = 196.597595
current_seq = 575
count = 541
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.581467/574, current 196.598160/575: elapsed=16694.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.598160
last_received_ts = 196.597595
last_seq = 575
current_ts = 196.614853
current_received_ts = 196.614319
current_seq = 576
count = 542
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.598160/575, current 196.614853/576: elapsed=16692.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.614853
last_received_ts = 196.614319
last_seq = 576
current_ts = 196.631546
current_received_ts = 196.630981
current_seq = 577
count = 543
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.614853/576, current 196.631546/577: elapsed=16688.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.631546
last_received_ts = 196.630981
last_seq = 577
current_ts = 196.648239
current_received_ts = 196.647675
current_seq = 578
count = 544
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.631546/577, current 196.648239/578: elapsed=16692.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.648239
last_received_ts = 196.647675
last_seq = 578
current_ts = 196.664917
current_received_ts = 196.664352
current_seq = 579
count = 545
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.648239/578, current 196.664917/579: elapsed=16686.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.664917
last_received_ts = 196.664352
last_seq = 579
current_ts = 196.681610
current_received_ts = 196.681091
current_seq = 580
count = 546
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.664917/579, current 196.681610/580: elapsed=16695.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.681610
last_received_ts = 196.681091
last_seq = 580
current_ts = 196.698303
current_received_ts = 196.697739
current_seq = 581
count = 547
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.681610/580, current 196.698303/581: elapsed=16691.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.698303
last_received_ts = 196.697739
last_seq = 581
current_ts = 196.714996
current_received_ts = 196.714417
current_seq = 582
count = 548
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.698303/581, current 196.714996/582: elapsed=16691.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.714996
last_received_ts = 196.714417
last_seq = 582
current_ts = 196.731689
current_received_ts = 196.731140
current_seq = 583
count = 549
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.714996/582, current 196.731689/583: elapsed=16690.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.731689
last_received_ts = 196.731140
last_seq = 583
current_ts = 196.748383
current_received_ts = 196.747818
current_seq = 584
count = 550
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.731689/583, current 196.748383/584: elapsed=16690.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.748383
last_received_ts = 196.747818
last_seq = 584
current_ts = 196.765060
current_received_ts = 196.764511
current_seq = 585
count = 551
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.748383/584, current 196.765060/585: elapsed=16692.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.765060
last_received_ts = 196.764511
last_seq = 585
current_ts = 196.781754
current_received_ts = 196.781204
current_seq = 586
count = 552
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.765060/585, current 196.781754/586: elapsed=16688.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.781754
last_received_ts = 196.781204
last_seq = 586
current_ts = 196.798447
current_received_ts = 196.798065
current_seq = 587
count = 553
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.781754/586, current 196.798447/587: elapsed=16688.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.798447
last_received_ts = 196.798065
last_seq = 587
current_ts = 196.815140
current_received_ts = 196.814453
current_seq = 588
count = 554
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.798447/587, current 196.815140/588: elapsed=16696.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.815140
last_received_ts = 196.814453
last_seq = 588
current_ts = 196.831833
current_received_ts = 196.831284
current_seq = 589
count = 555
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.815140/588, current 196.831833/589: elapsed=16690.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.831833
last_received_ts = 196.831284
last_seq = 589
current_ts = 196.848526
current_received_ts = 196.847961
current_seq = 590
count = 556
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.831833/589, current 196.848526/590: elapsed=16691.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.848526
last_received_ts = 196.847961
last_seq = 590
current_ts = 196.865204
current_received_ts = 196.864685
current_seq = 591
count = 557
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.848526/590, current 196.865204/591: elapsed=16685.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.865204
last_received_ts = 196.864685
last_seq = 591
current_ts = 196.881897
current_received_ts = 196.881363
current_seq = 592
count = 558
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.865204/591, current 196.881897/592: elapsed=16693.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.881897
last_received_ts = 196.881363
last_seq = 592
current_ts = 196.898590
current_received_ts = 196.898087
current_seq = 593
count = 559
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.881897/592, current 196.898590/593: elapsed=16693.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.898590
last_received_ts = 196.898087
last_seq = 593
current_ts = 196.915268
current_received_ts = 196.914886
current_seq = 594
count = 560
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.898590/593, current 196.915268/594: elapsed=16682.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.915268
last_received_ts = 196.914886
last_seq = 594
current_ts = 196.931961
current_received_ts = 196.931366
current_seq = 595
count = 561
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.915268/594, current 196.931961/595: elapsed=16695.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.931961
last_received_ts = 196.931366
last_seq = 595
current_ts = 196.948654
current_received_ts = 196.948105
current_seq = 596
count = 562
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.931961/595, current 196.948654/596: elapsed=16687.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.948654
last_received_ts = 196.948105
last_seq = 596
current_ts = 196.965347
current_received_ts = 196.964798
current_seq = 597
count = 563
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.948654/596, current 196.965347/597: elapsed=16687.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.965347
last_received_ts = 196.964798
last_seq = 597
current_ts = 196.982040
current_received_ts = 196.981476
current_seq = 598
count = 564
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.965347/597, current 196.982040/598: elapsed=16691.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.982040
last_received_ts = 196.981476
last_seq = 598
current_ts = 196.998718
current_received_ts = 196.998169
current_seq = 599
count = 565
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.982040/598, current 196.998718/599: elapsed=16689.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 196.998718
last_received_ts = 196.998169
last_seq = 599
current_ts = 197.015411
current_received_ts = 197.014847
current_seq = 600
count = 566
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 196.998718/599, current 197.015411/600: elapsed=16682.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.015411
last_received_ts = 197.014847
last_seq = 600
current_ts = 197.032089
current_received_ts = 197.031540
current_seq = 601
count = 567
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.015411/600, current 197.032089/601: elapsed=16690.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.032089
last_received_ts = 197.031540
last_seq = 601
current_ts = 197.048782
current_received_ts = 197.048218
current_seq = 602
count = 568
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.032089/601, current 197.048782/602: elapsed=16693.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.048782
last_received_ts = 197.048218
last_seq = 602
current_ts = 197.065475
current_received_ts = 197.064941
current_seq = 603
count = 569
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.048782/602, current 197.065475/603: elapsed=16684.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.065475
last_received_ts = 197.064941
last_seq = 603
current_ts = 197.082169
current_received_ts = 197.081619
current_seq = 604
count = 570
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.065475/603, current 197.082169/604: elapsed=16693.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.082169
last_received_ts = 197.081619
last_seq = 604
current_ts = 197.098846
current_received_ts = 197.098450
current_seq = 605
count = 571
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.082169/604, current 197.098846/605: elapsed=16687.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.098846
last_received_ts = 197.098450
last_seq = 605
current_ts = 197.115540
current_received_ts = 197.114990
current_seq = 606
count = 572
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.098846/605, current 197.115540/606: elapsed=16689.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.115540
last_received_ts = 197.114990
last_seq = 606
current_ts = 197.132233
current_received_ts = 197.131668
current_seq = 607
count = 573
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.115540/606, current 197.132233/607: elapsed=16689.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.132233
last_received_ts = 197.131668
last_seq = 607
current_ts = 197.148926
current_received_ts = 197.148392
current_seq = 608
count = 574
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.132233/607, current 197.148926/608: elapsed=16690.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.148926
last_received_ts = 197.148392
last_seq = 608
current_ts = 197.165604
current_received_ts = 197.165085
current_seq = 609
count = 575
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.148926/608, current 197.165604/609: elapsed=16687.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.165604
last_received_ts = 197.165085
last_seq = 609
current_ts = 197.182297
current_received_ts = 197.181747
current_seq = 610
count = 576
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.165604/609, current 197.182297/610: elapsed=16686.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.182297
last_received_ts = 197.181747
last_seq = 610
current_ts = 197.198975
current_received_ts = 197.198441
current_seq = 611
count = 577
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.182297/610, current 197.198975/611: elapsed=16686.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.198975
last_received_ts = 197.198441
last_seq = 611
current_ts = 197.215668
current_received_ts = 197.215134
current_seq = 612
count = 578
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.198975/611, current 197.215668/612: elapsed=16694.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.215668
last_received_ts = 197.215134
last_seq = 612
current_ts = 197.232361
current_received_ts = 197.231827
current_seq = 613
count = 579
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.215668/612, current 197.232361/613: elapsed=16687.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.232361
last_received_ts = 197.231827
last_seq = 613
current_ts = 197.249054
current_received_ts = 197.248489
current_seq = 614
count = 580
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.232361/613, current 197.249054/614: elapsed=16688.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.249054
last_received_ts = 197.248489
last_seq = 614
current_ts = 197.265732
current_received_ts = 197.265198
current_seq = 615
count = 581
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.249054/614, current 197.265732/615: elapsed=16691.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.265732
last_received_ts = 197.265198
last_seq = 615
current_ts = 197.282425
current_received_ts = 197.281845
current_seq = 616
count = 582
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.265732/615, current 197.282425/616: elapsed=16688.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.282425
last_received_ts = 197.281845
last_seq = 616
current_ts = 197.299118
current_received_ts = 197.298523
current_seq = 617
count = 583
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.282425/616, current 197.299118/617: elapsed=16687.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.299118
last_received_ts = 197.298523
last_seq = 617
current_ts = 197.315796
current_received_ts = 197.315201
current_seq = 618
count = 584
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.299118/617, current 197.315796/618: elapsed=16688.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.315796
last_received_ts = 197.315201
last_seq = 618
current_ts = 197.332489
current_received_ts = 197.331894
current_seq = 619
count = 585
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.315796/618, current 197.332489/619: elapsed=16683.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.332489
last_received_ts = 197.331894
last_seq = 619
current_ts = 197.349182
current_received_ts = 197.348557
current_seq = 620
count = 586
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.332489/619, current 197.349182/620: elapsed=16691.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.349182
last_received_ts = 197.348557
last_seq = 620
current_ts = 197.365875
current_received_ts = 197.365204
current_seq = 621
count = 587
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.349182/620, current 197.365875/621: elapsed=16694.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.365875
last_received_ts = 197.365204
last_seq = 621
current_ts = 197.382553
current_received_ts = 197.381973
current_seq = 622
count = 588
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.365875/621, current 197.382553/622: elapsed=16686.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.382553
last_received_ts = 197.381973
last_seq = 622
current_ts = 197.399246
current_received_ts = 197.398666
current_seq = 623
count = 589
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.382553/622, current 197.399246/623: elapsed=16686.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.399246
last_received_ts = 197.398666
last_seq = 623
current_ts = 197.415924
current_received_ts = 197.415375
current_seq = 624
count = 590
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.399246/623, current 197.415924/624: elapsed=16686.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.415924
last_received_ts = 197.415375
last_seq = 624
current_ts = 197.432617
current_received_ts = 197.432083
current_seq = 625
count = 591
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.415924/624, current 197.432617/625: elapsed=16693.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.432617
last_received_ts = 197.432083
last_seq = 625
current_ts = 197.449310
current_received_ts = 197.448853
current_seq = 626
count = 592
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.432617/625, current 197.449310/626: elapsed=16685.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.449310
last_received_ts = 197.448853
last_seq = 626
current_ts = 197.465988
current_received_ts = 197.465363
current_seq = 627
count = 593
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.449310/626, current 197.465988/627: elapsed=16690.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.465988
last_received_ts = 197.465363
last_seq = 627
current_ts = 197.482681
current_received_ts = 197.482147
current_seq = 628
count = 594
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.465988/627, current 197.482681/628: elapsed=16690.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.482681
last_received_ts = 197.482147
last_seq = 628
current_ts = 197.499374
current_received_ts = 197.498795
current_seq = 629
count = 595
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.482681/628, current 197.499374/629: elapsed=16688.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.499374
last_received_ts = 197.498795
last_seq = 629
current_ts = 197.516068
current_received_ts = 197.515457
current_seq = 630
count = 596
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.499374/629, current 197.516068/630: elapsed=16693.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.516068
last_received_ts = 197.515457
last_seq = 630
current_ts = 197.532745
current_received_ts = 197.532196
current_seq = 631
count = 597
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.516068/630, current 197.532745/631: elapsed=16681.0us expected=16733.9us +- 83.7us, error 0.3%
(kms_flip:6406) DEBUG: name = flip
last_ts = 197.532745
last_received_ts = 197.532196
last_seq = 631
current_ts = 197.549438
current_received_ts = 197.548889
current_seq = 632
count = 598
seq_step = 1
(kms_flip:6406) DEBUG: flip ts/seq: last 197.532745/631, current 197.549438/632: elapsed=16694.0us expected=16733.9us +- 83.7us, error 0.2%
(kms_flip:6406) DEBUG: expected 597, counted 599, encoder type 2
(kms_flip:6406) DEBUG: dropped frames, expected 597, counted 599, encoder type 2
(kms_flip:6406) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:6406) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:6406) igt_core-INFO: Stack trace:
(kms_flip:6406) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:6406) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:6406) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:6406) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:6406) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:6406) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:6406) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:6406) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-eDP1: FAIL (14.815s)
Subtest plain-flip-ts-check: FAIL (32.308s)
(kms_flip:6406) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2246:
(kms_flip:6406) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:6406) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:6406) igt_kms-CRITICAL: DPMS property not found on 189