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

shard-bmg-2

IGT-Version: 2.0-g2c31c3eb5 (x86_64) (Linux: 6.14.0-rc6-xe+ x86_64)

Using IGT_SRANDOM=1742361237 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-fb-recreate
Starting dynamic subtest: A-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 15965.2us +- 27.769us accuracy 0.52%
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:1714 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1831 run_test()
  #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-DP2: FAIL (0.635s)
Starting dynamic subtest: B-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16045.1us +- 7.637us accuracy 0.14%
vblank interval differs from modeline! expected 16666.7us, measured 16045us +- 7.637us, difference 621.6us (81.4 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1831 run_test()
  #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-DP2: FAIL (4.113s)
Starting dynamic subtest: C-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16302.6us +- 3.948us accuracy 0.07%
vblank interval differs from modeline! expected 16666.7us, measured 16303us +- 3.948us, difference 364.0us (92.2 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1831 run_test()
  #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-DP2: FAIL (5.213s)
Starting dynamic subtest: D-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16480.0us +- 3.540us accuracy 0.06%
vblank interval differs from modeline! expected 16666.7us, measured 16480us +- 3.540us, difference 186.7us (52.7 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1831 run_test()
  #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest D-DP2: FAIL (7.261s)
Starting dynamic subtest: A-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Expected frametime: 16667us; measured 16594.3us +- 5.770us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 16594us +- 5.770us, difference 72.4us (12.5 sigma)
Dynamic subtest A-HDMI-A3: SUCCESS (4.283s)
Starting dynamic subtest: B-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Expected frametime: 16667us; measured 16627.2us +- 6.379us accuracy 0.12%
vblank interval differs from modeline! expected 16666.7us, measured 16627us +- 6.379us, difference 39.5us (6.2 sigma)
Dynamic subtest B-HDMI-A3: SUCCESS (4.262s)
Starting dynamic subtest: C-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Expected frametime: 16667us; measured 16645.1us +- 5.071us accuracy 0.09%
vblank interval differs from modeline! expected 16666.7us, measured 16645us +- 5.071us, difference 21.5us (4.2 sigma)
Dynamic subtest C-HDMI-A3: SUCCESS (4.265s)
Starting dynamic subtest: D-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Expected frametime: 16667us; measured 16654.8us +- 2.834us accuracy 0.05%
vblank interval differs from modeline! expected 16666.7us, measured 16655us +- 2.834us, difference 11.9us (4.2 sigma)
Dynamic subtest D-HDMI-A3: SUCCESS (4.249s)
Subtest plain-flip-fb-recreate: FAIL (34.299s)

Starting subtest: plain-flip-fb-recreate
Starting dynamic subtest: A-DP2
(kms_flip:2393) CRITICAL: Test assertion failure function calibrate_ts, file ../tests/kms_flip.c:1440:
(kms_flip:2393) CRITICAL: Failed assertion: 3 * stddev / mean < 0.005
Dynamic subtest A-DP2 failed.
**** DEBUG ****
(kms_flip:2393) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2393) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:2393) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2393) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2393) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:2393) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2393) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e585cf0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e585cf0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e597400, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e597400, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e597400, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e597400, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e590fb0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e590fb0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2393) DEBUG: No stale events found
(kms_flip:2393) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2393) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2393) INFO: Expected frametime: 16667us; measured 15965.2us +- 27.769us accuracy 0.52%
(kms_flip:2393) CRITICAL: Test assertion failure function calibrate_ts, file ../tests/kms_flip.c:1440:
(kms_flip:2393) CRITICAL: Failed assertion: 3 * stddev / mean < 0.005
(kms_flip:2393) igt_core-INFO: Stack trace:
(kms_flip:2393) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2393) igt_core-INFO:   #1 ../tests/kms_flip.c:1714 run_test_on_crtc_set.constprop.0()
(kms_flip:2393) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2393) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2393) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2393) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2393) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2393) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-DP2: FAIL (0.635s)
Starting dynamic subtest: B-DP2
(kms_flip:2393) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2393) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-DP2 failed.
**** DEBUG ****
(kms_flip:2393) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2393) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:2393) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2393) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2393) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=4, pitch=7680)
(kms_flip:2393) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2393) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e5e6d40, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e5e6d40, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e5e6f40, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e5e6f40, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e5e6f40, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e5e6f40, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e5e6f40, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e5e6f40, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2393) DEBUG: No stale events found
(kms_flip:2393) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2393) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2393) INFO: Expected frametime: 16667us; measured 16045.1us +- 7.637us accuracy 0.14%
(kms_flip:2393) INFO: vblank interval differs from modeline! expected 16666.7us, measured 16045us +- 7.637us, difference 621.6us (81.4 sigma)
(kms_flip:2393) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 47.963573
current_received_ts = 47.963089
current_seq = 638
count = 0
seq_step = 1
(kms_flip:2393) DEBUG: name = flip
last_ts = 47.963573
last_received_ts = 47.963089
last_seq = 638
current_ts = 47.979622
current_received_ts = 47.979065
current_seq = 639
count = 1
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 47.963573/638, current 47.979622/639: elapsed=16049.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 47.979622
last_received_ts = 47.979065
last_seq = 639
current_ts = 47.995674
current_received_ts = 47.995079
current_seq = 640
count = 2
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 47.979622/639, current 47.995674/640: elapsed=16055.0us expected=16045.1us +- 80.2us, error 0.1%
(kms_flip:2393) DEBUG: name = flip
last_ts = 47.995674
last_received_ts = 47.995079
last_seq = 640
current_ts = 48.011719
current_received_ts = 48.011127
current_seq = 641
count = 3
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 47.995674/640, current 48.011719/641: elapsed=16043.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.011719
last_received_ts = 48.011127
last_seq = 641
current_ts = 48.027763
current_received_ts = 48.027168
current_seq = 642
count = 4
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.011719/641, current 48.027763/642: elapsed=16044.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.027763
last_received_ts = 48.027168
last_seq = 642
current_ts = 48.043808
current_received_ts = 48.043209
current_seq = 643
count = 5
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.027763/642, current 48.043808/643: elapsed=16046.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.043808
last_received_ts = 48.043209
last_seq = 643
current_ts = 48.059853
current_received_ts = 48.059254
current_seq = 644
count = 6
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.043808/643, current 48.059853/644: elapsed=16045.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.059853
last_received_ts = 48.059254
last_seq = 644
current_ts = 48.075897
current_received_ts = 48.075344
current_seq = 645
count = 7
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.059853/644, current 48.075897/645: elapsed=16042.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.075897
last_received_ts = 48.075344
last_seq = 645
current_ts = 48.091938
current_received_ts = 48.091385
current_seq = 646
count = 8
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.075897/645, current 48.091938/646: elapsed=16043.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.091938
last_received_ts = 48.091385
last_seq = 646
current_ts = 48.107979
current_received_ts = 48.107445
current_seq = 647
count = 9
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.091938/646, current 48.107979/647: elapsed=16040.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.107979
last_received_ts = 48.107445
last_seq = 647
current_ts = 48.124027
current_received_ts = 48.123524
current_seq = 648
count = 10
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.107979/647, current 48.124027/648: elapsed=16048.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.124027
last_received_ts = 48.123524
last_seq = 648
current_ts = 48.140072
current_received_ts = 48.139568
current_seq = 649
count = 11
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.124027/648, current 48.140072/649: elapsed=16046.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.140072
last_received_ts = 48.139568
last_seq = 649
current_ts = 48.156113
current_received_ts = 48.155609
current_seq = 650
count = 12
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.140072/649, current 48.156113/650: elapsed=16041.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.156113
last_received_ts = 48.155609
last_seq = 650
current_ts = 48.172169
current_received_ts = 48.171665
current_seq = 651
count = 13
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.156113/650, current 48.172169/651: elapsed=16054.0us expected=16045.1us +- 80.2us, error 0.1%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.172169
last_received_ts = 48.171665
last_seq = 651
current_ts = 48.188206
current_received_ts = 48.187698
current_seq = 652
count = 14
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.172169/651, current 48.188206/652: elapsed=16038.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.188206
last_received_ts = 48.187698
last_seq = 652
current_ts = 48.204254
current_received_ts = 48.203747
current_seq = 653
count = 15
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.188206/652, current 48.204254/653: elapsed=16049.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.204254
last_received_ts = 48.203747
last_seq = 653
current_ts = 48.220295
current_received_ts = 48.219799
current_seq = 654
count = 16
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.204254/653, current 48.220295/654: elapsed=16039.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.220295
last_received_ts = 48.219799
last_seq = 654
current_ts = 48.236343
current_received_ts = 48.235844
current_seq = 655
count = 17
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.220295/654, current 48.236343/655: elapsed=16049.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.236343
last_received_ts = 48.235844
last_seq = 655
current_ts = 48.252388
current_received_ts = 48.251881
current_seq = 656
count = 18
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.236343/655, current 48.252388/656: elapsed=16044.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.252388
last_received_ts = 48.251881
last_seq = 656
current_ts = 48.268429
current_received_ts = 48.267925
current_seq = 657
count = 19
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.252388/656, current 48.268429/657: elapsed=16043.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.268429
last_received_ts = 48.267925
last_seq = 657
current_ts = 48.284473
current_received_ts = 48.283974
current_seq = 658
count = 20
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.268429/657, current 48.284473/658: elapsed=16045.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.284473
last_received_ts = 48.283974
last_seq = 658
current_ts = 48.300518
current_received_ts = 48.300030
current_seq = 659
count = 21
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.284473/658, current 48.300518/659: elapsed=16043.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.300518
last_received_ts = 48.300030
last_seq = 659
current_ts = 48.316566
current_received_ts = 48.316059
current_seq = 660
count = 22
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.300518/659, current 48.316566/660: elapsed=16047.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.316566
last_received_ts = 48.316059
last_seq = 660
current_ts = 48.332607
current_received_ts = 48.332134
current_seq = 661
count = 23
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.316566/660, current 48.332607/661: elapsed=16043.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.332607
last_received_ts = 48.332134
last_seq = 661
current_ts = 48.348656
current_received_ts = 48.348148
current_seq = 662
count = 24
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.332607/661, current 48.348656/662: elapsed=16049.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.348656
last_received_ts = 48.348148
last_seq = 662
current_ts = 48.364700
current_received_ts = 48.364193
current_seq = 663
count = 25
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.348656/662, current 48.364700/663: elapsed=16044.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.364700
last_received_ts = 48.364193
last_seq = 663
current_ts = 48.380756
current_received_ts = 48.380253
current_seq = 664
count = 26
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.364700/663, current 48.380756/664: elapsed=16054.0us expected=16045.1us +- 80.2us, error 0.1%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.380756
last_received_ts = 48.380253
last_seq = 664
current_ts = 48.396805
current_received_ts = 48.396267
current_seq = 665
count = 27
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.380756/664, current 48.396805/665: elapsed=16048.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.396805
last_received_ts = 48.396267
last_seq = 665
current_ts = 48.412849
current_received_ts = 48.412273
current_seq = 666
count = 28
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.396805/665, current 48.412849/666: elapsed=16046.0us expected=16045.1us +- 80.2us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.412849
last_received_ts = 48.412273
last_seq = 666
current_ts = 48.428932
current_received_ts = 48.428352
current_seq = 667
count = 29
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.412849/666, current 48.428932/667: elapsed=16083.0us expected=16045.1us +- 80.2us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 48.428932
last_received_ts = 48.428352
last_seq = 667
current_ts = 48.445065
current_received_ts = 48.444473
current_seq = 668
count = 30
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 48.428932/667, current 48.445065/668: elapsed=16132.0us expected=16045.1us +- 80.2us, error 0.5%
(kms_flip:2393) DEBUG: inconsistent flip ts/seq: last 48.428932/667, current 48.445065/668: elapsed=16132.0us expected=16045.1us
(kms_flip:2393) DEBUG: expected 0, counted 30, encoder type 2
(kms_flip:2393) DEBUG: dropped frames, expected 0, counted 30, encoder type 2
(kms_flip:2393) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2393) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2393) igt_core-INFO: Stack trace:
(kms_flip:2393) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2393) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2393) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2393) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2393) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2393) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2393) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2393) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-DP2: FAIL (4.113s)
Starting dynamic subtest: C-DP2
(kms_flip:2393) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2393) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest C-DP2 failed.
**** DEBUG ****
(kms_flip:2393) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2393) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=5, pitch=7680)
(kms_flip:2393) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2393) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2393) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=6, pitch=7680)
(kms_flip:2393) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2393) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e5eadb0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e5eadb0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e610250, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e610250, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e5eae60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e5eae60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e610110, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) intel_allocator_simple-DEBUG: <ial: 0x5f087e610110, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2393) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2393) DEBUG: No stale events found
(kms_flip:2393) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2393) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2393) INFO: Expected frametime: 16667us; measured 16302.6us +- 3.948us accuracy 0.07%
(kms_flip:2393) INFO: vblank interval differs from modeline! expected 16666.7us, measured 16303us +- 3.948us, difference 364.0us (92.2 sigma)
(kms_flip:2393) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 51.983383
current_received_ts = 51.985176
current_seq = 22
count = 0
seq_step = 1
(kms_flip:2393) DEBUG: name = flip
last_ts = 51.983383
last_received_ts = 51.985176
last_seq = 22
current_ts = 51.999683
current_received_ts = 51.999325
current_seq = 23
count = 1
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 51.983383/22, current 51.999683/23: elapsed=16301.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 51.999683
last_received_ts = 51.999325
last_seq = 23
current_ts = 52.015984
current_received_ts = 52.015572
current_seq = 24
count = 2
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 51.999683/23, current 52.015984/24: elapsed=16302.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.015984
last_received_ts = 52.015572
last_seq = 24
current_ts = 52.032280
current_received_ts = 52.031822
current_seq = 25
count = 3
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.015984/24, current 52.032280/25: elapsed=16294.0us expected=16302.6us +- 81.5us, error 0.1%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.032280
last_received_ts = 52.031822
last_seq = 25
current_ts = 52.048592
current_received_ts = 52.048088
current_seq = 26
count = 4
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.032280/25, current 52.048592/26: elapsed=16314.0us expected=16302.6us +- 81.5us, error 0.1%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.048592
last_received_ts = 52.048088
last_seq = 26
current_ts = 52.064884
current_received_ts = 52.064384
current_seq = 27
count = 5
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.048592/26, current 52.064884/27: elapsed=16291.0us expected=16302.6us +- 81.5us, error 0.1%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.064884
last_received_ts = 52.064384
last_seq = 27
current_ts = 52.081196
current_received_ts = 52.080696
current_seq = 28
count = 6
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.064884/27, current 52.081196/28: elapsed=16312.0us expected=16302.6us +- 81.5us, error 0.1%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.081196
last_received_ts = 52.080696
last_seq = 28
current_ts = 52.097500
current_received_ts = 52.096989
current_seq = 29
count = 7
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.081196/28, current 52.097500/29: elapsed=16304.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.097500
last_received_ts = 52.096989
last_seq = 29
current_ts = 52.113804
current_received_ts = 52.113289
current_seq = 30
count = 8
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.097500/29, current 52.113804/30: elapsed=16303.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.113804
last_received_ts = 52.113289
last_seq = 30
current_ts = 52.130108
current_received_ts = 52.129589
current_seq = 31
count = 9
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.113804/30, current 52.130108/31: elapsed=16304.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.130108
last_received_ts = 52.129589
last_seq = 31
current_ts = 52.146397
current_received_ts = 52.145893
current_seq = 32
count = 10
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.130108/31, current 52.146397/32: elapsed=16289.0us expected=16302.6us +- 81.5us, error 0.1%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.146397
last_received_ts = 52.145893
last_seq = 32
current_ts = 52.162712
current_received_ts = 52.162193
current_seq = 33
count = 11
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.146397/32, current 52.162712/33: elapsed=16315.0us expected=16302.6us +- 81.5us, error 0.1%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.162712
last_received_ts = 52.162193
last_seq = 33
current_ts = 52.179005
current_received_ts = 52.178501
current_seq = 34
count = 12
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.162712/33, current 52.179005/34: elapsed=16293.0us expected=16302.6us +- 81.5us, error 0.1%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.179005
last_received_ts = 52.178501
last_seq = 34
current_ts = 52.195309
current_received_ts = 52.194813
current_seq = 35
count = 13
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.179005/34, current 52.195309/35: elapsed=16306.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.195309
last_received_ts = 52.194813
last_seq = 35
current_ts = 52.211620
current_received_ts = 52.211113
current_seq = 36
count = 14
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.195309/35, current 52.211620/36: elapsed=16310.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.211620
last_received_ts = 52.211113
last_seq = 36
current_ts = 52.227924
current_received_ts = 52.227383
current_seq = 37
count = 15
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.211620/36, current 52.227924/37: elapsed=16304.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.227924
last_received_ts = 52.227383
last_seq = 37
current_ts = 52.244213
current_received_ts = 52.243641
current_seq = 38
count = 16
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.227924/37, current 52.244213/38: elapsed=16290.0us expected=16302.6us +- 81.5us, error 0.1%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.244213
last_received_ts = 52.243641
last_seq = 38
current_ts = 52.260529
current_received_ts = 52.259926
current_seq = 39
count = 17
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.244213/38, current 52.260529/39: elapsed=16313.0us expected=16302.6us +- 81.5us, error 0.1%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.260529
last_received_ts = 52.259926
last_seq = 39
current_ts = 52.276829
current_received_ts = 52.276314
current_seq = 40
count = 18
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.260529/39, current 52.276829/40: elapsed=16303.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.276829
last_received_ts = 52.276314
last_seq = 40
current_ts = 52.293133
current_received_ts = 52.292614
current_seq = 41
count = 19
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.276829/40, current 52.293133/41: elapsed=16303.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.293133
last_received_ts = 52.292614
last_seq = 41
current_ts = 52.309425
current_received_ts = 52.308918
current_seq = 42
count = 20
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.293133/41, current 52.309425/42: elapsed=16291.0us expected=16302.6us +- 81.5us, error 0.1%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.309425
last_received_ts = 52.308918
last_seq = 42
current_ts = 52.325726
current_received_ts = 52.325161
current_seq = 43
count = 21
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.309425/42, current 52.325726/43: elapsed=16303.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.325726
last_received_ts = 52.325161
last_seq = 43
current_ts = 52.342030
current_received_ts = 52.341450
current_seq = 44
count = 22
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.325726/43, current 52.342030/44: elapsed=16303.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.342030
last_received_ts = 52.341450
last_seq = 44
current_ts = 52.358341
current_received_ts = 52.357738
current_seq = 45
count = 23
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.342030/44, current 52.358341/45: elapsed=16312.0us expected=16302.6us +- 81.5us, error 0.1%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.358341
last_received_ts = 52.357738
last_seq = 45
current_ts = 52.374641
current_received_ts = 52.374046
current_seq = 46
count = 24
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.358341/45, current 52.374641/46: elapsed=16300.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.374641
last_received_ts = 52.374046
last_seq = 46
current_ts = 52.390945
current_received_ts = 52.390343
current_seq = 47
count = 25
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.374641/46, current 52.390945/47: elapsed=16304.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.390945
last_received_ts = 52.390343
last_seq = 47
current_ts = 52.407249
current_received_ts = 52.406643
current_seq = 48
count = 26
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.390945/47, current 52.407249/48: elapsed=16303.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.407249
last_received_ts = 52.406643
last_seq = 48
current_ts = 52.423565
current_received_ts = 52.422958
current_seq = 49
count = 27
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.407249/48, current 52.423565/49: elapsed=16316.0us expected=16302.6us +- 81.5us, error 0.1%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.423565
last_received_ts = 52.422958
last_seq = 49
current_ts = 52.439915
current_received_ts = 52.439411
current_seq = 50
count = 28
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.423565/49, current 52.439915/50: elapsed=16349.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.439915
last_received_ts = 52.439411
last_seq = 50
current_ts = 52.456257
current_received_ts = 52.455753
current_seq = 51
count = 29
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.439915/50, current 52.456257/51: elapsed=16342.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.456257
last_received_ts = 52.455753
last_seq = 51
current_ts = 52.472610
current_received_ts = 52.472107
current_seq = 52
count = 30
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.456257/51, current 52.472610/52: elapsed=16356.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.472610
last_received_ts = 52.472107
last_seq = 52
current_ts = 52.488956
current_received_ts = 52.488457
current_seq = 53
count = 31
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.472610/52, current 52.488956/53: elapsed=16344.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.488956
last_received_ts = 52.488457
last_seq = 53
current_ts = 52.505299
current_received_ts = 52.504791
current_seq = 54
count = 32
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.488956/53, current 52.505299/54: elapsed=16341.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.505299
last_received_ts = 52.504791
last_seq = 54
current_ts = 52.521648
current_received_ts = 52.521145
current_seq = 55
count = 33
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.505299/54, current 52.521648/55: elapsed=16352.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.521648
last_received_ts = 52.521145
last_seq = 55
current_ts = 52.538002
current_received_ts = 52.537498
current_seq = 56
count = 34
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.521648/55, current 52.538002/56: elapsed=16354.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.538002
last_received_ts = 52.537498
last_seq = 56
current_ts = 52.554352
current_received_ts = 52.553848
current_seq = 57
count = 35
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.538002/56, current 52.554352/57: elapsed=16349.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.554352
last_received_ts = 52.553848
last_seq = 57
current_ts = 52.570702
current_received_ts = 52.570221
current_seq = 58
count = 36
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.554352/57, current 52.570702/58: elapsed=16348.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.570702
last_received_ts = 52.570221
last_seq = 58
current_ts = 52.587044
current_received_ts = 52.586552
current_seq = 59
count = 37
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.570702/58, current 52.587044/59: elapsed=16342.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.587044
last_received_ts = 52.586552
last_seq = 59
current_ts = 52.603397
current_received_ts = 52.602898
current_seq = 60
count = 38
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.587044/59, current 52.603397/60: elapsed=16354.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.603397
last_received_ts = 52.602898
last_seq = 60
current_ts = 52.619740
current_received_ts = 52.619240
current_seq = 61
count = 39
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.603397/60, current 52.619740/61: elapsed=16343.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.619740
last_received_ts = 52.619240
last_seq = 61
current_ts = 52.636093
current_received_ts = 52.635590
current_seq = 62
count = 40
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.619740/61, current 52.636093/62: elapsed=16353.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.636093
last_received_ts = 52.635590
last_seq = 62
current_ts = 52.652443
current_received_ts = 52.651939
current_seq = 63
count = 41
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.636093/62, current 52.652443/63: elapsed=16349.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.652443
last_received_ts = 52.651939
last_seq = 63
current_ts = 52.668785
current_received_ts = 52.668285
current_seq = 64
count = 42
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.652443/63, current 52.668785/64: elapsed=16345.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.668785
last_received_ts = 52.668285
last_seq = 64
current_ts = 52.685139
current_received_ts = 52.684635
current_seq = 65
count = 43
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.668785/64, current 52.685139/65: elapsed=16351.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.685139
last_received_ts = 52.684635
last_seq = 65
current_ts = 52.701477
current_received_ts = 52.700993
current_seq = 66
count = 44
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.685139/65, current 52.701477/66: elapsed=16340.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.701477
last_received_ts = 52.700993
last_seq = 66
current_ts = 52.717827
current_received_ts = 52.717323
current_seq = 67
count = 45
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.701477/66, current 52.717827/67: elapsed=16348.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.717827
last_received_ts = 52.717323
last_seq = 67
current_ts = 52.734180
current_received_ts = 52.733681
current_seq = 68
count = 46
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.717827/67, current 52.734180/68: elapsed=16357.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.734180
last_received_ts = 52.733681
last_seq = 68
current_ts = 52.750530
current_received_ts = 52.750046
current_seq = 69
count = 47
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.734180/68, current 52.750530/69: elapsed=16349.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.750530
last_received_ts = 52.750046
last_seq = 69
current_ts = 52.766869
current_received_ts = 52.766380
current_seq = 70
count = 48
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.750530/69, current 52.766869/70: elapsed=16338.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.766869
last_received_ts = 52.766380
last_seq = 70
current_ts = 52.783230
current_received_ts = 52.782719
current_seq = 71
count = 49
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.766869/70, current 52.783230/71: elapsed=16362.0us expected=16302.6us +- 81.5us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.783230
last_received_ts = 52.782719
last_seq = 71
current_ts = 52.799576
current_received_ts = 52.799080
current_seq = 72
count = 50
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.783230/71, current 52.799576/72: elapsed=16345.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.799576
last_received_ts = 52.799080
last_seq = 72
current_ts = 52.815914
current_received_ts = 52.815437
current_seq = 73
count = 51
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.799576/72, current 52.815914/73: elapsed=16340.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.815914
last_received_ts = 52.815437
last_seq = 73
current_ts = 52.832275
current_received_ts = 52.831764
current_seq = 74
count = 52
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.815914/73, current 52.832275/74: elapsed=16360.0us expected=16302.6us +- 81.5us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.832275
last_received_ts = 52.831764
last_seq = 74
current_ts = 52.848621
current_received_ts = 52.848122
current_seq = 75
count = 53
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.832275/74, current 52.848621/75: elapsed=16344.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.848621
last_received_ts = 52.848122
last_seq = 75
current_ts = 52.864960
current_received_ts = 52.864471
current_seq = 76
count = 54
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.848621/75, current 52.864960/76: elapsed=16339.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.864960
last_received_ts = 52.864471
last_seq = 76
current_ts = 52.881313
current_received_ts = 52.880806
current_seq = 77
count = 55
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.864960/76, current 52.881313/77: elapsed=16353.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.881313
last_received_ts = 52.880806
last_seq = 77
current_ts = 52.897671
current_received_ts = 52.897167
current_seq = 78
count = 56
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.881313/77, current 52.897671/78: elapsed=16357.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.897671
last_received_ts = 52.897167
last_seq = 78
current_ts = 52.914005
current_received_ts = 52.913502
current_seq = 79
count = 57
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.897671/78, current 52.914005/79: elapsed=16335.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.914005
last_received_ts = 52.913502
last_seq = 79
current_ts = 52.930355
current_received_ts = 52.929852
current_seq = 80
count = 58
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.914005/79, current 52.930355/80: elapsed=16352.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.930355
last_received_ts = 52.929852
last_seq = 80
current_ts = 52.946716
current_received_ts = 52.946198
current_seq = 81
count = 59
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.930355/80, current 52.946716/81: elapsed=16359.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.946716
last_received_ts = 52.946198
last_seq = 81
current_ts = 52.963055
current_received_ts = 52.962555
current_seq = 82
count = 60
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.946716/81, current 52.963055/82: elapsed=16340.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.963055
last_received_ts = 52.962555
last_seq = 82
current_ts = 52.979412
current_received_ts = 52.978889
current_seq = 83
count = 61
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.963055/82, current 52.979412/83: elapsed=16356.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.979412
last_received_ts = 52.978889
last_seq = 83
current_ts = 52.995758
current_received_ts = 52.995243
current_seq = 84
count = 62
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.979412/83, current 52.995758/84: elapsed=16348.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 52.995758
last_received_ts = 52.995243
last_seq = 84
current_ts = 53.012108
current_received_ts = 53.011589
current_seq = 85
count = 63
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 52.995758/84, current 53.012108/85: elapsed=16349.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.012108
last_received_ts = 53.011589
last_seq = 85
current_ts = 53.028458
current_received_ts = 53.027935
current_seq = 86
count = 64
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.012108/85, current 53.028458/86: elapsed=16348.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.028458
last_received_ts = 53.027935
last_seq = 86
current_ts = 53.044792
current_received_ts = 53.044289
current_seq = 87
count = 65
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.028458/86, current 53.044792/87: elapsed=16338.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.044792
last_received_ts = 53.044289
last_seq = 87
current_ts = 53.061142
current_received_ts = 53.060635
current_seq = 88
count = 66
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.044792/87, current 53.061142/88: elapsed=16348.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.061142
last_received_ts = 53.060635
last_seq = 88
current_ts = 53.077488
current_received_ts = 53.076889
current_seq = 89
count = 67
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.061142/88, current 53.077488/89: elapsed=16347.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.077488
last_received_ts = 53.076889
last_seq = 89
current_ts = 53.093842
current_received_ts = 53.093246
current_seq = 90
count = 68
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.077488/89, current 53.093842/90: elapsed=16354.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.093842
last_received_ts = 53.093246
last_seq = 90
current_ts = 53.110191
current_received_ts = 53.109623
current_seq = 91
count = 69
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.093842/90, current 53.110191/91: elapsed=16349.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.110191
last_received_ts = 53.109623
last_seq = 91
current_ts = 53.126541
current_received_ts = 53.125931
current_seq = 92
count = 70
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.110191/91, current 53.126541/92: elapsed=16348.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.126541
last_received_ts = 53.125931
last_seq = 92
current_ts = 53.142891
current_received_ts = 53.142311
current_seq = 93
count = 71
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.126541/92, current 53.142891/93: elapsed=16350.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.142891
last_received_ts = 53.142311
last_seq = 93
current_ts = 53.159229
current_received_ts = 53.159477
current_seq = 94
count = 72
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.142891/93, current 53.159229/94: elapsed=16339.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.159229
last_received_ts = 53.159477
last_seq = 94
current_ts = 53.175591
current_received_ts = 53.175087
current_seq = 95
count = 73
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.159229/94, current 53.175591/95: elapsed=16361.0us expected=16302.6us +- 81.5us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.175591
last_received_ts = 53.175087
last_seq = 95
current_ts = 53.191929
current_received_ts = 53.191437
current_seq = 96
count = 74
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.175591/95, current 53.191929/96: elapsed=16338.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.191929
last_received_ts = 53.191437
last_seq = 96
current_ts = 53.208279
current_received_ts = 53.207783
current_seq = 97
count = 75
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.191929/96, current 53.208279/97: elapsed=16350.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.208279
last_received_ts = 53.207783
last_seq = 97
current_ts = 53.224628
current_received_ts = 53.224136
current_seq = 98
count = 76
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.208279/97, current 53.224628/98: elapsed=16349.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.224628
last_received_ts = 53.224136
last_seq = 98
current_ts = 53.240971
current_received_ts = 53.240475
current_seq = 99
count = 77
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.224628/98, current 53.240971/99: elapsed=16344.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.240971
last_received_ts = 53.240475
last_seq = 99
current_ts = 53.257324
current_received_ts = 53.256821
current_seq = 100
count = 78
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.240971/99, current 53.257324/100: elapsed=16353.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.257324
last_received_ts = 53.256821
last_seq = 100
current_ts = 53.273682
current_received_ts = 53.273167
current_seq = 101
count = 79
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.257324/100, current 53.273682/101: elapsed=16357.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.273682
last_received_ts = 53.273167
last_seq = 101
current_ts = 53.290016
current_received_ts = 53.289516
current_seq = 102
count = 80
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.273682/101, current 53.290016/102: elapsed=16337.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.290016
last_received_ts = 53.289516
last_seq = 102
current_ts = 53.306370
current_received_ts = 53.305862
current_seq = 103
count = 81
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.290016/102, current 53.306370/103: elapsed=16351.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.306370
last_received_ts = 53.305862
last_seq = 103
current_ts = 53.322712
current_received_ts = 53.322205
current_seq = 104
count = 82
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.306370/103, current 53.322712/104: elapsed=16343.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.322712
last_received_ts = 53.322205
last_seq = 104
current_ts = 53.339062
current_received_ts = 53.338558
current_seq = 105
count = 83
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.322712/104, current 53.339062/105: elapsed=16350.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.339062
last_received_ts = 53.338558
last_seq = 105
current_ts = 53.355415
current_received_ts = 53.354908
current_seq = 106
count = 84
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.339062/105, current 53.355415/106: elapsed=16352.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.355415
last_received_ts = 53.354908
last_seq = 106
current_ts = 53.371761
current_received_ts = 53.371254
current_seq = 107
count = 85
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.355415/106, current 53.371761/107: elapsed=16346.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.371761
last_received_ts = 53.371254
last_seq = 107
current_ts = 53.388107
current_received_ts = 53.387600
current_seq = 108
count = 86
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.371761/107, current 53.388107/108: elapsed=16347.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.388107
last_received_ts = 53.387600
last_seq = 108
current_ts = 53.404457
current_received_ts = 53.403954
current_seq = 109
count = 87
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.388107/108, current 53.404457/109: elapsed=16351.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.404457
last_received_ts = 53.403954
last_seq = 109
current_ts = 53.420811
current_received_ts = 53.420307
current_seq = 110
count = 88
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.404457/109, current 53.420811/110: elapsed=16352.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 53.420811
last_received_ts = 53.420307
last_seq = 110
current_ts = 53.437199
current_received_ts = 53.436691
current_seq = 111
count = 89
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 53.420811/110, current 53.437199/111: elapsed=16388.0us expected=16302.6us +- 81.5us, error 0.5%
(kms_flip:2393) DEBUG: inconsistent flip ts/seq: last 53.420811/110, current 53.437199/111: elapsed=16388.0us expected=16302.6us
(kms_flip:2393) DEBUG: expected 0, counted 89, encoder type 2
(kms_flip:2393) DEBUG: dropped frames, expected 0, counted 89, encoder type 2
(kms_flip:2393) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2393) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2393) igt_core-INFO: Stack trace:
(kms_flip:2393) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2393) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2393) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2393) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2393) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2393) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2393) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2393) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-DP2: FAIL (5.213s)
Starting dynamic subtest: D-DP2
(kms_flip:2393) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2393) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest D-DP2 failed.
**** DEBUG ****
(kms_flip:2393) DEBUG: flip ts/seq: last 58.651421/115, current 58.667942/116: elapsed=16521.0us expected=16480.0us +- 82.4us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.667942
last_received_ts = 58.667454
last_seq = 116
current_ts = 58.684471
current_received_ts = 58.683975
current_seq = 117
count = 95
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.667942/116, current 58.684471/117: elapsed=16530.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.684471
last_received_ts = 58.683975
last_seq = 117
current_ts = 58.701004
current_received_ts = 58.700493
current_seq = 118
count = 96
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.684471/117, current 58.701004/118: elapsed=16533.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.701004
last_received_ts = 58.700493
last_seq = 118
current_ts = 58.717514
current_received_ts = 58.717037
current_seq = 119
count = 97
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.701004/118, current 58.717514/119: elapsed=16511.0us expected=16480.0us +- 82.4us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.717514
last_received_ts = 58.717037
last_seq = 119
current_ts = 58.734051
current_received_ts = 58.733551
current_seq = 120
count = 98
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.717514/119, current 58.734051/120: elapsed=16536.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.734051
last_received_ts = 58.733551
last_seq = 120
current_ts = 58.750561
current_received_ts = 58.750065
current_seq = 121
count = 99
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.734051/120, current 58.750561/121: elapsed=16511.0us expected=16480.0us +- 82.4us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.750561
last_received_ts = 58.750065
last_seq = 121
current_ts = 58.767090
current_received_ts = 58.766582
current_seq = 122
count = 100
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.750561/121, current 58.767090/122: elapsed=16526.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.767090
last_received_ts = 58.766582
last_seq = 122
current_ts = 58.783611
current_received_ts = 58.783112
current_seq = 123
count = 101
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.767090/122, current 58.783611/123: elapsed=16525.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.783611
last_received_ts = 58.783112
last_seq = 123
current_ts = 58.800137
current_received_ts = 58.799637
current_seq = 124
count = 102
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.783611/123, current 58.800137/124: elapsed=16523.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.800137
last_received_ts = 58.799637
last_seq = 124
current_ts = 58.816662
current_received_ts = 58.816158
current_seq = 125
count = 103
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.800137/124, current 58.816662/125: elapsed=16525.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.816662
last_received_ts = 58.816158
last_seq = 125
current_ts = 58.833191
current_received_ts = 58.832687
current_seq = 126
count = 104
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.816662/125, current 58.833191/126: elapsed=16530.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.833191
last_received_ts = 58.832687
last_seq = 126
current_ts = 58.849712
current_received_ts = 58.849209
current_seq = 127
count = 105
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.833191/126, current 58.849712/127: elapsed=16520.0us expected=16480.0us +- 82.4us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.849712
last_received_ts = 58.849209
last_seq = 127
current_ts = 58.866241
current_received_ts = 58.865738
current_seq = 128
count = 106
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.849712/127, current 58.866241/128: elapsed=16529.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.866241
last_received_ts = 58.865738
last_seq = 128
current_ts = 58.882771
current_received_ts = 58.882248
current_seq = 129
count = 107
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.866241/128, current 58.882771/129: elapsed=16530.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.882771
last_received_ts = 58.882248
last_seq = 129
current_ts = 58.899288
current_received_ts = 58.898788
current_seq = 130
count = 108
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.882771/129, current 58.899288/130: elapsed=16520.0us expected=16480.0us +- 82.4us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.899288
last_received_ts = 58.898788
last_seq = 130
current_ts = 58.915806
current_received_ts = 58.915302
current_seq = 131
count = 109
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.899288/130, current 58.915806/131: elapsed=16515.0us expected=16480.0us +- 82.4us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.915806
last_received_ts = 58.915302
last_seq = 131
current_ts = 58.932335
current_received_ts = 58.931831
current_seq = 132
count = 110
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.915806/131, current 58.932335/132: elapsed=16529.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.932335
last_received_ts = 58.931831
last_seq = 132
current_ts = 58.948860
current_received_ts = 58.948330
current_seq = 133
count = 111
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.932335/132, current 58.948860/133: elapsed=16527.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.948860
last_received_ts = 58.948330
last_seq = 133
current_ts = 58.965389
current_received_ts = 58.964890
current_seq = 134
count = 112
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.948860/133, current 58.965389/134: elapsed=16529.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.965389
last_received_ts = 58.964890
last_seq = 134
current_ts = 58.981907
current_received_ts = 58.981407
current_seq = 135
count = 113
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.965389/134, current 58.981907/135: elapsed=16517.0us expected=16480.0us +- 82.4us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.981907
last_received_ts = 58.981407
last_seq = 135
current_ts = 58.998432
current_received_ts = 58.997929
current_seq = 136
count = 114
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.981907/135, current 58.998432/136: elapsed=16527.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 58.998432
last_received_ts = 58.997929
last_seq = 136
current_ts = 59.014954
current_received_ts = 59.014450
current_seq = 137
count = 115
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 58.998432/136, current 59.014954/137: elapsed=16521.0us expected=16480.0us +- 82.4us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.014954
last_received_ts = 59.014450
last_seq = 137
current_ts = 59.031475
current_received_ts = 59.030972
current_seq = 138
count = 116
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.014954/137, current 59.031475/138: elapsed=16520.0us expected=16480.0us +- 82.4us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.031475
last_received_ts = 59.030972
last_seq = 138
current_ts = 59.048004
current_received_ts = 59.047497
current_seq = 139
count = 117
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.031475/138, current 59.048004/139: elapsed=16529.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.048004
last_received_ts = 59.047497
last_seq = 139
current_ts = 59.064526
current_received_ts = 59.064045
current_seq = 140
count = 118
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.048004/139, current 59.064526/140: elapsed=16520.0us expected=16480.0us +- 82.4us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.064526
last_received_ts = 59.064045
last_seq = 140
current_ts = 59.081051
current_received_ts = 59.080544
current_seq = 141
count = 119
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.064526/140, current 59.081051/141: elapsed=16526.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.081051
last_received_ts = 59.080544
last_seq = 141
current_ts = 59.097576
current_received_ts = 59.097073
current_seq = 142
count = 120
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.081051/141, current 59.097576/142: elapsed=16528.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.097576
last_received_ts = 59.097073
last_seq = 142
current_ts = 59.114098
current_received_ts = 59.113598
current_seq = 143
count = 121
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.097576/142, current 59.114098/143: elapsed=16521.0us expected=16480.0us +- 82.4us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.114098
last_received_ts = 59.113598
last_seq = 143
current_ts = 59.130627
current_received_ts = 59.130119
current_seq = 144
count = 122
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.114098/143, current 59.130627/144: elapsed=16527.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.130627
last_received_ts = 59.130119
last_seq = 144
current_ts = 59.147148
current_received_ts = 59.146641
current_seq = 145
count = 123
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.130627/144, current 59.147148/145: elapsed=16521.0us expected=16480.0us +- 82.4us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.147148
last_received_ts = 59.146641
last_seq = 145
current_ts = 59.163673
current_received_ts = 59.163174
current_seq = 146
count = 124
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.147148/145, current 59.163673/146: elapsed=16528.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.163673
last_received_ts = 59.163174
last_seq = 146
current_ts = 59.180195
current_received_ts = 59.179691
current_seq = 147
count = 125
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.163673/146, current 59.180195/147: elapsed=16519.0us expected=16480.0us +- 82.4us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.180195
last_received_ts = 59.179691
last_seq = 147
current_ts = 59.196724
current_received_ts = 59.196220
current_seq = 148
count = 126
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.180195/147, current 59.196724/148: elapsed=16529.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.196724
last_received_ts = 59.196220
last_seq = 148
current_ts = 59.213242
current_received_ts = 59.212753
current_seq = 149
count = 127
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.196724/148, current 59.213242/149: elapsed=16519.0us expected=16480.0us +- 82.4us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.213242
last_received_ts = 59.212753
last_seq = 149
current_ts = 59.229767
current_received_ts = 59.229321
current_seq = 150
count = 128
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.213242/149, current 59.229767/150: elapsed=16525.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.229767
last_received_ts = 59.229321
last_seq = 150
current_ts = 59.246292
current_received_ts = 59.245800
current_seq = 151
count = 129
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.229767/150, current 59.246292/151: elapsed=16525.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.246292
last_received_ts = 59.245800
last_seq = 151
current_ts = 59.262821
current_received_ts = 59.262337
current_seq = 152
count = 130
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.246292/151, current 59.262821/152: elapsed=16530.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.262821
last_received_ts = 59.262337
last_seq = 152
current_ts = 59.279350
current_received_ts = 59.278851
current_seq = 153
count = 131
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.262821/152, current 59.279350/153: elapsed=16529.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.279350
last_received_ts = 59.278851
last_seq = 153
current_ts = 59.295868
current_received_ts = 59.295364
current_seq = 154
count = 132
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.279350/153, current 59.295868/154: elapsed=16515.0us expected=16480.0us +- 82.4us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.295868
last_received_ts = 59.295364
last_seq = 154
current_ts = 59.312389
current_received_ts = 59.311886
current_seq = 155
count = 133
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.295868/154, current 59.312389/155: elapsed=16523.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.312389
last_received_ts = 59.311886
last_seq = 155
current_ts = 59.328915
current_received_ts = 59.328411
current_seq = 156
count = 134
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.312389/155, current 59.328915/156: elapsed=16527.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.328915
last_received_ts = 59.328411
last_seq = 156
current_ts = 59.345440
current_received_ts = 59.344860
current_seq = 157
count = 135
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.328915/156, current 59.345440/157: elapsed=16523.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.345440
last_received_ts = 59.344860
last_seq = 157
current_ts = 59.361973
current_received_ts = 59.361374
current_seq = 158
count = 136
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.345440/157, current 59.361973/158: elapsed=16534.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.361973
last_received_ts = 59.361374
last_seq = 158
current_ts = 59.378490
current_received_ts = 59.377983
current_seq = 159
count = 137
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.361973/158, current 59.378490/159: elapsed=16518.0us expected=16480.0us +- 82.4us, error 0.2%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.378490
last_received_ts = 59.377983
last_seq = 159
current_ts = 59.395016
current_received_ts = 59.394508
current_seq = 160
count = 138
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.378490/159, current 59.395016/160: elapsed=16524.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.395016
last_received_ts = 59.394508
last_seq = 160
current_ts = 59.411541
current_received_ts = 59.411053
current_seq = 161
count = 139
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.395016/160, current 59.411541/161: elapsed=16527.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.411541
last_received_ts = 59.411053
last_seq = 161
current_ts = 59.428074
current_received_ts = 59.427570
current_seq = 162
count = 140
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.411541/161, current 59.428074/162: elapsed=16532.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.428074
last_received_ts = 59.427570
last_seq = 162
current_ts = 59.444611
current_received_ts = 59.444118
current_seq = 163
count = 141
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.428074/162, current 59.444611/163: elapsed=16538.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.444611
last_received_ts = 59.444118
last_seq = 163
current_ts = 59.461166
current_received_ts = 59.460663
current_seq = 164
count = 142
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.444611/163, current 59.461166/164: elapsed=16553.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.461166
last_received_ts = 59.460663
last_seq = 164
current_ts = 59.477695
current_received_ts = 59.477196
current_seq = 165
count = 143
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.461166/164, current 59.477695/165: elapsed=16531.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.477695
last_received_ts = 59.477196
last_seq = 165
current_ts = 59.494240
current_received_ts = 59.493736
current_seq = 166
count = 144
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.477695/165, current 59.494240/166: elapsed=16544.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.494240
last_received_ts = 59.493736
last_seq = 166
current_ts = 59.510780
current_received_ts = 59.510277
current_seq = 167
count = 145
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.494240/166, current 59.510780/167: elapsed=16539.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.510780
last_received_ts = 59.510277
last_seq = 167
current_ts = 59.527328
current_received_ts = 59.526829
current_seq = 168
count = 146
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.510780/167, current 59.527328/168: elapsed=16550.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.527328
last_received_ts = 59.526829
last_seq = 168
current_ts = 59.543865
current_received_ts = 59.543369
current_seq = 169
count = 147
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.527328/168, current 59.543865/169: elapsed=16537.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.543865
last_received_ts = 59.543369
last_seq = 169
current_ts = 59.560406
current_received_ts = 59.559902
current_seq = 170
count = 148
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.543865/169, current 59.560406/170: elapsed=16541.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.560406
last_received_ts = 59.559902
last_seq = 170
current_ts = 59.576958
current_received_ts = 59.576454
current_seq = 171
count = 149
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.560406/170, current 59.576958/171: elapsed=16549.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.576958
last_received_ts = 59.576454
last_seq = 171
current_ts = 59.593502
current_received_ts = 59.593029
current_seq = 172
count = 150
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.576958/171, current 59.593502/172: elapsed=16545.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.593502
last_received_ts = 59.593029
last_seq = 172
current_ts = 59.610035
current_received_ts = 59.609531
current_seq = 173
count = 151
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.593502/172, current 59.610035/173: elapsed=16534.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.610035
last_received_ts = 59.609531
last_seq = 173
current_ts = 59.626579
current_received_ts = 59.626163
current_seq = 174
count = 152
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.610035/173, current 59.626579/174: elapsed=16546.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.626579
last_received_ts = 59.626163
last_seq = 174
current_ts = 59.643124
current_received_ts = 59.642628
current_seq = 175
count = 153
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.626579/174, current 59.643124/175: elapsed=16541.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.643124
last_received_ts = 59.642628
last_seq = 175
current_ts = 59.659660
current_received_ts = 59.659176
current_seq = 176
count = 154
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.643124/175, current 59.659660/176: elapsed=16540.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.659660
last_received_ts = 59.659176
last_seq = 176
current_ts = 59.676201
current_received_ts = 59.675732
current_seq = 177
count = 155
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.659660/176, current 59.676201/177: elapsed=16540.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.676201
last_received_ts = 59.675732
last_seq = 177
current_ts = 59.692749
current_received_ts = 59.692173
current_seq = 178
count = 156
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.676201/177, current 59.692749/178: elapsed=16546.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.692749
last_received_ts = 59.692173
last_seq = 178
current_ts = 59.709293
current_received_ts = 59.708694
current_seq = 179
count = 157
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.692749/178, current 59.709293/179: elapsed=16547.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.709293
last_received_ts = 59.708694
last_seq = 179
current_ts = 59.725842
current_received_ts = 59.725342
current_seq = 180
count = 158
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.709293/179, current 59.725842/180: elapsed=16547.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.725842
last_received_ts = 59.725342
last_seq = 180
current_ts = 59.742371
current_received_ts = 59.741871
current_seq = 181
count = 159
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.725842/180, current 59.742371/181: elapsed=16529.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.742371
last_received_ts = 59.741871
last_seq = 181
current_ts = 59.758911
current_received_ts = 59.758427
current_seq = 182
count = 160
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.742371/181, current 59.758911/182: elapsed=16542.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.758911
last_received_ts = 59.758427
last_seq = 182
current_ts = 59.775459
current_received_ts = 59.774963
current_seq = 183
count = 161
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.758911/182, current 59.775459/183: elapsed=16545.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.775459
last_received_ts = 59.774963
last_seq = 183
current_ts = 59.792000
current_received_ts = 59.791420
current_seq = 184
count = 162
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.775459/183, current 59.792000/184: elapsed=16541.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.792000
last_received_ts = 59.791420
last_seq = 184
current_ts = 59.808552
current_received_ts = 59.807949
current_seq = 185
count = 163
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.792000/184, current 59.808552/185: elapsed=16552.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.808552
last_received_ts = 59.807949
last_seq = 185
current_ts = 59.825085
current_received_ts = 59.824577
current_seq = 186
count = 164
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.808552/185, current 59.825085/186: elapsed=16533.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.825085
last_received_ts = 59.824577
last_seq = 186
current_ts = 59.841637
current_received_ts = 59.841145
current_seq = 187
count = 165
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.825085/186, current 59.841637/187: elapsed=16553.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.841637
last_received_ts = 59.841145
last_seq = 187
current_ts = 59.858170
current_received_ts = 59.857590
current_seq = 188
count = 166
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.841637/187, current 59.858170/188: elapsed=16532.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.858170
last_received_ts = 59.857590
last_seq = 188
current_ts = 59.874714
current_received_ts = 59.874207
current_seq = 189
count = 167
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.858170/188, current 59.874714/189: elapsed=16544.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.874714
last_received_ts = 59.874207
last_seq = 189
current_ts = 59.891251
current_received_ts = 59.890747
current_seq = 190
count = 168
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.874714/189, current 59.891251/190: elapsed=16538.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.891251
last_received_ts = 59.890747
last_seq = 190
current_ts = 59.907799
current_received_ts = 59.907215
current_seq = 191
count = 169
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.891251/190, current 59.907799/191: elapsed=16546.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.907799
last_received_ts = 59.907215
last_seq = 191
current_ts = 59.924343
current_received_ts = 59.923748
current_seq = 192
count = 170
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.907799/191, current 59.924343/192: elapsed=16547.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.924343
last_received_ts = 59.923748
last_seq = 192
current_ts = 59.940880
current_received_ts = 59.940395
current_seq = 193
count = 171
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.924343/192, current 59.940880/193: elapsed=16536.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.940880
last_received_ts = 59.940395
last_seq = 193
current_ts = 59.957420
current_received_ts = 59.956917
current_seq = 194
count = 172
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.940880/193, current 59.957420/194: elapsed=16539.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.957420
last_received_ts = 59.956917
last_seq = 194
current_ts = 59.973972
current_received_ts = 59.973469
current_seq = 195
count = 173
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.957420/194, current 59.973972/195: elapsed=16553.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.973972
last_received_ts = 59.973469
last_seq = 195
current_ts = 59.990505
current_received_ts = 59.989998
current_seq = 196
count = 174
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.973972/195, current 59.990505/196: elapsed=16532.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 59.990505
last_received_ts = 59.989998
last_seq = 196
current_ts = 60.007050
current_received_ts = 60.006466
current_seq = 197
count = 175
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 59.990505/196, current 60.007050/197: elapsed=16544.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.007050
last_received_ts = 60.006466
last_seq = 197
current_ts = 60.023598
current_received_ts = 60.023022
current_seq = 198
count = 176
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.007050/197, current 60.023598/198: elapsed=16551.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.023598
last_received_ts = 60.023022
last_seq = 198
current_ts = 60.040134
current_received_ts = 60.039551
current_seq = 199
count = 177
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.023598/198, current 60.040134/199: elapsed=16534.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.040134
last_received_ts = 60.039551
last_seq = 199
current_ts = 60.056675
current_received_ts = 60.056187
current_seq = 200
count = 178
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.040134/199, current 60.056675/200: elapsed=16541.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.056675
last_received_ts = 60.056187
last_seq = 200
current_ts = 60.073215
current_received_ts = 60.072712
current_seq = 201
count = 179
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.056675/200, current 60.073215/201: elapsed=16541.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.073215
last_received_ts = 60.072712
last_seq = 201
current_ts = 60.089760
current_received_ts = 60.089260
current_seq = 202
count = 180
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.073215/201, current 60.089760/202: elapsed=16546.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.089760
last_received_ts = 60.089260
last_seq = 202
current_ts = 60.106300
current_received_ts = 60.105797
current_seq = 203
count = 181
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.089760/202, current 60.106300/203: elapsed=16538.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.106300
last_received_ts = 60.105797
last_seq = 203
current_ts = 60.122849
current_received_ts = 60.122314
current_seq = 204
count = 182
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.106300/203, current 60.122849/204: elapsed=16548.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.122849
last_received_ts = 60.122314
last_seq = 204
current_ts = 60.139397
current_received_ts = 60.138847
current_seq = 205
count = 183
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.122849/204, current 60.139397/205: elapsed=16549.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.139397
last_received_ts = 60.138847
last_seq = 205
current_ts = 60.155937
current_received_ts = 60.155388
current_seq = 206
count = 184
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.139397/205, current 60.155937/206: elapsed=16542.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.155937
last_received_ts = 60.155388
last_seq = 206
current_ts = 60.172478
current_received_ts = 60.171925
current_seq = 207
count = 185
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.155937/206, current 60.172478/207: elapsed=16540.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.172478
last_received_ts = 60.171925
last_seq = 207
current_ts = 60.189022
current_received_ts = 60.188473
current_seq = 208
count = 186
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.172478/207, current 60.189022/208: elapsed=16544.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.189022
last_received_ts = 60.188473
last_seq = 208
current_ts = 60.205551
current_received_ts = 60.205051
current_seq = 209
count = 187
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.189022/208, current 60.205551/209: elapsed=16531.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.205551
last_received_ts = 60.205051
last_seq = 209
current_ts = 60.222103
current_received_ts = 60.221527
current_seq = 210
count = 188
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.205551/209, current 60.222103/210: elapsed=16552.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.222103
last_received_ts = 60.221527
last_seq = 210
current_ts = 60.238647
current_received_ts = 60.238052
current_seq = 211
count = 189
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.222103/210, current 60.238647/211: elapsed=16541.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.238647
last_received_ts = 60.238052
last_seq = 211
current_ts = 60.255180
current_received_ts = 60.254677
current_seq = 212
count = 190
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.238647/211, current 60.255180/212: elapsed=16533.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.255180
last_received_ts = 60.254677
last_seq = 212
current_ts = 60.271725
current_received_ts = 60.271145
current_seq = 213
count = 191
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.255180/212, current 60.271725/213: elapsed=16545.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.271725
last_received_ts = 60.271145
last_seq = 213
current_ts = 60.288277
current_received_ts = 60.287674
current_seq = 214
count = 192
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.271725/213, current 60.288277/214: elapsed=16551.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.288277
last_received_ts = 60.287674
last_seq = 214
current_ts = 60.304806
current_received_ts = 60.304283
current_seq = 215
count = 193
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.288277/214, current 60.304806/215: elapsed=16530.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.304806
last_received_ts = 60.304283
last_seq = 215
current_ts = 60.321354
current_received_ts = 60.320854
current_seq = 216
count = 194
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.304806/215, current 60.321354/216: elapsed=16550.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.321354
last_received_ts = 60.320854
last_seq = 216
current_ts = 60.337894
current_received_ts = 60.337395
current_seq = 217
count = 195
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.321354/216, current 60.337894/217: elapsed=16539.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.337894
last_received_ts = 60.337395
last_seq = 217
current_ts = 60.354435
current_received_ts = 60.353855
current_seq = 218
count = 196
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.337894/217, current 60.354435/218: elapsed=16540.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.354435
last_received_ts = 60.353855
last_seq = 218
current_ts = 60.370987
current_received_ts = 60.370392
current_seq = 219
count = 197
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.354435/218, current 60.370987/219: elapsed=16553.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.370987
last_received_ts = 60.370392
last_seq = 219
current_ts = 60.387520
current_received_ts = 60.387047
current_seq = 220
count = 198
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.370987/219, current 60.387520/220: elapsed=16531.0us expected=16480.0us +- 82.4us, error 0.3%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.387520
last_received_ts = 60.387047
last_seq = 220
current_ts = 60.404064
current_received_ts = 60.403561
current_seq = 221
count = 199
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.387520/220, current 60.404064/221: elapsed=16545.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.404064
last_received_ts = 60.403561
last_seq = 221
current_ts = 60.420605
current_received_ts = 60.420101
current_seq = 222
count = 200
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.404064/221, current 60.420605/222: elapsed=16541.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.420605
last_received_ts = 60.420101
last_seq = 222
current_ts = 60.437164
current_received_ts = 60.436668
current_seq = 223
count = 201
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.420605/222, current 60.437164/223: elapsed=16562.0us expected=16480.0us +- 82.4us, error 0.5%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.437164
last_received_ts = 60.436668
last_seq = 223
current_ts = 60.453724
current_received_ts = 60.453152
current_seq = 224
count = 202
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.437164/223, current 60.453724/224: elapsed=16558.0us expected=16480.0us +- 82.4us, error 0.5%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.453724
last_received_ts = 60.453152
last_seq = 224
current_ts = 60.470284
current_received_ts = 60.469707
current_seq = 225
count = 203
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.453724/224, current 60.470284/225: elapsed=16561.0us expected=16480.0us +- 82.4us, error 0.5%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.470284
last_received_ts = 60.469707
last_seq = 225
current_ts = 60.486835
current_received_ts = 60.486336
current_seq = 226
count = 204
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.470284/225, current 60.486835/226: elapsed=16549.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.486835
last_received_ts = 60.486336
last_seq = 226
current_ts = 60.503391
current_received_ts = 60.502888
current_seq = 227
count = 205
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.486835/226, current 60.503391/227: elapsed=16558.0us expected=16480.0us +- 82.4us, error 0.5%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.503391
last_received_ts = 60.502888
last_seq = 227
current_ts = 60.519955
current_received_ts = 60.519466
current_seq = 228
count = 206
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.503391/227, current 60.519955/228: elapsed=16562.0us expected=16480.0us +- 82.4us, error 0.5%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.519955
last_received_ts = 60.519466
last_seq = 228
current_ts = 60.536507
current_received_ts = 60.536034
current_seq = 229
count = 207
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.519955/228, current 60.536507/229: elapsed=16553.0us expected=16480.0us +- 82.4us, error 0.4%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.536507
last_received_ts = 60.536034
last_seq = 229
current_ts = 60.553066
current_received_ts = 60.552563
current_seq = 230
count = 208
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.536507/229, current 60.553066/230: elapsed=16559.0us expected=16480.0us +- 82.4us, error 0.5%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.553066
last_received_ts = 60.552563
last_seq = 230
current_ts = 60.569626
current_received_ts = 60.569122
current_seq = 231
count = 209
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.553066/230, current 60.569626/231: elapsed=16558.0us expected=16480.0us +- 82.4us, error 0.5%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.569626
last_received_ts = 60.569122
last_seq = 231
current_ts = 60.586182
current_received_ts = 60.585678
current_seq = 232
count = 210
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.569626/231, current 60.586182/232: elapsed=16558.0us expected=16480.0us +- 82.4us, error 0.5%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.586182
last_received_ts = 60.585678
last_seq = 232
current_ts = 60.602741
current_received_ts = 60.602253
current_seq = 233
count = 211
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.586182/232, current 60.602741/233: elapsed=16558.0us expected=16480.0us +- 82.4us, error 0.5%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.602741
last_received_ts = 60.602253
last_seq = 233
current_ts = 60.619297
current_received_ts = 60.618793
current_seq = 234
count = 212
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.602741/233, current 60.619297/234: elapsed=16556.0us expected=16480.0us +- 82.4us, error 0.5%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.619297
last_received_ts = 60.618793
last_seq = 234
current_ts = 60.635853
current_received_ts = 60.635349
current_seq = 235
count = 213
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.619297/234, current 60.635853/235: elapsed=16558.0us expected=16480.0us +- 82.4us, error 0.5%
(kms_flip:2393) DEBUG: name = flip
last_ts = 60.635853
last_received_ts = 60.635349
last_seq = 235
current_ts = 60.652416
current_received_ts = 60.651917
current_seq = 236
count = 214
seq_step = 1
(kms_flip:2393) DEBUG: flip ts/seq: last 60.635853/235, current 60.652416/236: elapsed=16563.0us expected=16480.0us +- 82.4us, error 0.5%
(kms_flip:2393) DEBUG: inconsistent flip ts/seq: last 60.635853/235, current 60.652416/236: elapsed=16563.0us expected=16480.0us
(kms_flip:2393) DEBUG: expected 0, counted 214, encoder type 2
(kms_flip:2393) DEBUG: dropped frames, expected 0, counted 214, encoder type 2
(kms_flip:2393) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2393) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2393) igt_core-INFO: Stack trace:
(kms_flip:2393) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2393) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2393) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2393) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2393) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2393) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2393) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2393) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest D-DP2: FAIL (7.261s)
Starting dynamic subtest: A-HDMI-A3
Dynamic subtest A-HDMI-A3: SUCCESS (4.283s)
Starting dynamic subtest: B-HDMI-A3
Dynamic subtest B-HDMI-A3: SUCCESS (4.262s)
Starting dynamic subtest: C-HDMI-A3
Dynamic subtest C-HDMI-A3: SUCCESS (4.265s)
Starting dynamic subtest: D-HDMI-A3
Dynamic subtest D-HDMI-A3: SUCCESS (4.249s)
Subtest plain-flip-fb-recreate: FAIL (34.299s)