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

shard-dg2-4

IGT-Version: 1.30-gccabe5b43 (x86_64) (Linux: 6.14.0-rc6-CI_DRM_16261-g003c44ec0b7d+ x86_64)

Using IGT_SRANDOM=1741667019 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A1
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 17094.8us +- 6.061us accuracy 0.11%
vblank interval differs from modeline! expected 16666.7us, measured 17095us +- 6.061us, difference 428.1us (70.6 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 A-HDMI-A1: FAIL (4.752s)
Starting dynamic subtest: B-HDMI-A1
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16890.3us +- 7.115us accuracy 0.13%
vblank interval differs from modeline! expected 16666.7us, measured 16890us +- 7.115us, difference 223.6us (31.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-HDMI-A1: FAIL (7.155s)
Starting dynamic subtest: C-HDMI-A1
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16760.1us +- 4.897us accuracy 0.09%
vblank interval differs from modeline! expected 16666.7us, measured 16760us +- 4.897us, difference 93.5us (19.1 sigma)
Dynamic subtest C-HDMI-A1: SUCCESS (7.960s)
Starting dynamic subtest: D-HDMI-A1
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16703.8us +- 3.449us accuracy 0.06%
vblank interval differs from modeline! expected 16666.7us, measured 16704us +- 3.449us, difference 37.1us (10.8 sigma)
Dynamic subtest D-HDMI-A1: SUCCESS (7.961s)
Subtest plain-flip-ts-check: FAIL (27.843s)

Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A1
(kms_flip:2503) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2503) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2503) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2503) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:2503) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2503) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2503) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:2503) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2503) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2503) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2503) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2503) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2503) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2503) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2503) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2503) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2503) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2503) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2503) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2503) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2503) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2503) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2503) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2503) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2503) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2503) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2503) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2503) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2503) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2503) DEBUG: No stale events found
(kms_flip:2503) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2503) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2503) INFO: Expected frametime: 16667us; measured 17094.8us +- 6.061us accuracy 0.11%
(kms_flip:2503) INFO: vblank interval differs from modeline! expected 16666.7us, measured 17095us +- 6.061us, difference 428.1us (70.6 sigma)
(kms_flip:2503) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 361.825012
current_received_ts = 361.824646
current_seq = 2488
count = 0
seq_step = 1
(kms_flip:2503) DEBUG: name = flip
last_ts = 361.825012
last_received_ts = 361.824646
last_seq = 2488
current_ts = 361.842102
current_received_ts = 361.841705
current_seq = 2489
count = 1
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 361.825012/2488, current 361.842102/2489: elapsed=17091.0us expected=17094.8us +- 85.5us, error 0.0%
(kms_flip:2503) DEBUG: name = flip
last_ts = 361.842102
last_received_ts = 361.841705
last_seq = 2489
current_ts = 361.859222
current_received_ts = 361.858795
current_seq = 2490
count = 2
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 361.842102/2489, current 361.859222/2490: elapsed=17094.0us expected=17094.8us +- 85.5us, error 0.0%
(kms_flip:2503) DEBUG: name = flip
last_ts = 361.859222
last_received_ts = 361.858795
last_seq = 2490
current_ts = 361.876312
current_received_ts = 361.875916
current_seq = 2491
count = 3
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 361.859222/2490, current 361.876312/2491: elapsed=17093.0us expected=17094.8us +- 85.5us, error 0.0%
(kms_flip:2503) DEBUG: name = flip
last_ts = 361.876312
last_received_ts = 361.875916
last_seq = 2491
current_ts = 361.893402
current_received_ts = 361.892944
current_seq = 2492
count = 4
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 361.876312/2491, current 361.893402/2492: elapsed=17098.0us expected=17094.8us +- 85.5us, error 0.0%
(kms_flip:2503) DEBUG: name = flip
last_ts = 361.893402
last_received_ts = 361.892944
last_seq = 2492
current_ts = 361.910492
current_received_ts = 361.910065
current_seq = 2493
count = 5
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 361.893402/2492, current 361.910492/2493: elapsed=17093.0us expected=17094.8us +- 85.5us, error 0.0%
(kms_flip:2503) DEBUG: name = flip
last_ts = 361.910492
last_received_ts = 361.910065
last_seq = 2493
current_ts = 361.927582
current_received_ts = 361.927185
current_seq = 2494
count = 6
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 361.910492/2493, current 361.927582/2494: elapsed=17100.0us expected=17094.8us +- 85.5us, error 0.0%
(kms_flip:2503) DEBUG: name = flip
last_ts = 361.927582
last_received_ts = 361.927185
last_seq = 2494
current_ts = 361.944702
current_received_ts = 361.944336
current_seq = 2495
count = 7
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 361.927582/2494, current 361.944702/2495: elapsed=17093.0us expected=17094.8us +- 85.5us, error 0.0%
(kms_flip:2503) DEBUG: name = flip
last_ts = 361.944702
last_received_ts = 361.944336
last_seq = 2495
current_ts = 361.961792
current_received_ts = 361.961426
current_seq = 2496
count = 8
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 361.944702/2495, current 361.961792/2496: elapsed=17098.0us expected=17094.8us +- 85.5us, error 0.0%
(kms_flip:2503) DEBUG: name = flip
last_ts = 361.961792
last_received_ts = 361.961426
last_seq = 2496
current_ts = 361.978882
current_received_ts = 361.978485
current_seq = 2497
count = 9
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 361.961792/2496, current 361.978882/2497: elapsed=17083.0us expected=17094.8us +- 85.5us, error 0.1%
(kms_flip:2503) DEBUG: name = flip
last_ts = 361.978882
last_received_ts = 361.978485
last_seq = 2497
current_ts = 361.995972
current_received_ts = 361.995575
current_seq = 2498
count = 10
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 361.978882/2497, current 361.995972/2498: elapsed=17103.0us expected=17094.8us +- 85.5us, error 0.0%
(kms_flip:2503) DEBUG: name = flip
last_ts = 361.995972
last_received_ts = 361.995575
last_seq = 2498
current_ts = 362.013062
current_received_ts = 362.012665
current_seq = 2499
count = 11
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 361.995972/2498, current 362.013062/2499: elapsed=17094.0us expected=17094.8us +- 85.5us, error 0.0%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.013062
last_received_ts = 362.012665
last_seq = 2499
current_ts = 362.030151
current_received_ts = 362.029785
current_seq = 2500
count = 12
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.013062/2499, current 362.030151/2500: elapsed=17086.0us expected=17094.8us +- 85.5us, error 0.1%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.030151
last_received_ts = 362.029785
last_seq = 2500
current_ts = 362.047241
current_received_ts = 362.046967
current_seq = 2501
count = 13
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.030151/2500, current 362.047241/2501: elapsed=17098.0us expected=17094.8us +- 85.5us, error 0.0%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.047241
last_received_ts = 362.046967
last_seq = 2501
current_ts = 362.064362
current_received_ts = 362.063934
current_seq = 2502
count = 14
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.047241/2501, current 362.064362/2502: elapsed=17098.0us expected=17094.8us +- 85.5us, error 0.0%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.064362
last_received_ts = 362.063934
last_seq = 2502
current_ts = 362.081451
current_received_ts = 362.081177
current_seq = 2503
count = 15
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.064362/2502, current 362.081451/2503: elapsed=17096.0us expected=17094.8us +- 85.5us, error 0.0%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.081451
last_received_ts = 362.081177
last_seq = 2503
current_ts = 362.098541
current_received_ts = 362.098175
current_seq = 2504
count = 16
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.081451/2503, current 362.098541/2504: elapsed=17099.0us expected=17094.8us +- 85.5us, error 0.0%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.098541
last_received_ts = 362.098175
last_seq = 2504
current_ts = 362.115631
current_received_ts = 362.115234
current_seq = 2505
count = 17
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.098541/2504, current 362.115631/2505: elapsed=17079.0us expected=17094.8us +- 85.5us, error 0.1%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.115631
last_received_ts = 362.115234
last_seq = 2505
current_ts = 362.132690
current_received_ts = 362.132324
current_seq = 2506
count = 18
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.115631/2505, current 362.132690/2506: elapsed=17070.0us expected=17094.8us +- 85.5us, error 0.1%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.132690
last_received_ts = 362.132324
last_seq = 2506
current_ts = 362.149750
current_received_ts = 362.149323
current_seq = 2507
count = 19
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.132690/2506, current 362.149750/2507: elapsed=17045.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.149750
last_received_ts = 362.149323
last_seq = 2507
current_ts = 362.166779
current_received_ts = 362.166351
current_seq = 2508
count = 20
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.149750/2507, current 362.166779/2508: elapsed=17042.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.166779
last_received_ts = 362.166351
last_seq = 2508
current_ts = 362.183838
current_received_ts = 362.183380
current_seq = 2509
count = 21
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.166779/2508, current 362.183838/2509: elapsed=17044.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.183838
last_received_ts = 362.183380
last_seq = 2509
current_ts = 362.200867
current_received_ts = 362.200470
current_seq = 2510
count = 22
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.183838/2509, current 362.200867/2510: elapsed=17037.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.200867
last_received_ts = 362.200470
last_seq = 2510
current_ts = 362.217896
current_received_ts = 362.217499
current_seq = 2511
count = 23
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.200867/2510, current 362.217896/2511: elapsed=17039.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.217896
last_received_ts = 362.217499
last_seq = 2511
current_ts = 362.234955
current_received_ts = 362.234558
current_seq = 2512
count = 24
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.217896/2511, current 362.234955/2512: elapsed=17051.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.234955
last_received_ts = 362.234558
last_seq = 2512
current_ts = 362.251984
current_received_ts = 362.251587
current_seq = 2513
count = 25
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.234955/2512, current 362.251984/2513: elapsed=17032.0us expected=17094.8us +- 85.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.251984
last_received_ts = 362.251587
last_seq = 2513
current_ts = 362.269043
current_received_ts = 362.268768
current_seq = 2514
count = 26
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.251984/2513, current 362.269043/2514: elapsed=17058.0us expected=17094.8us +- 85.5us, error 0.2%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.269043
last_received_ts = 362.268768
last_seq = 2514
current_ts = 362.286072
current_received_ts = 362.285645
current_seq = 2515
count = 27
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.269043/2514, current 362.286072/2515: elapsed=17039.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.286072
last_received_ts = 362.285645
last_seq = 2515
current_ts = 362.303101
current_received_ts = 362.302734
current_seq = 2516
count = 28
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.286072/2515, current 362.303101/2516: elapsed=17035.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.303101
last_received_ts = 362.302734
last_seq = 2516
current_ts = 362.320160
current_received_ts = 362.319885
current_seq = 2517
count = 29
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.303101/2516, current 362.320160/2517: elapsed=17049.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.320160
last_received_ts = 362.319885
last_seq = 2517
current_ts = 362.337219
current_received_ts = 362.336884
current_seq = 2518
count = 30
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.320160/2517, current 362.337219/2518: elapsed=17041.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.337219
last_received_ts = 362.336884
last_seq = 2518
current_ts = 362.354248
current_received_ts = 362.353943
current_seq = 2519
count = 31
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.337219/2518, current 362.354248/2519: elapsed=17039.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.354248
last_received_ts = 362.353943
last_seq = 2519
current_ts = 362.371277
current_received_ts = 362.370911
current_seq = 2520
count = 32
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.354248/2519, current 362.371277/2520: elapsed=17043.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.371277
last_received_ts = 362.370911
last_seq = 2520
current_ts = 362.388336
current_received_ts = 362.387970
current_seq = 2521
count = 33
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.371277/2520, current 362.388336/2521: elapsed=17043.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.388336
last_received_ts = 362.387970
last_seq = 2521
current_ts = 362.405365
current_received_ts = 362.404907
current_seq = 2522
count = 34
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.388336/2521, current 362.405365/2522: elapsed=17036.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.405365
last_received_ts = 362.404907
last_seq = 2522
current_ts = 362.422394
current_received_ts = 362.421936
current_seq = 2523
count = 35
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.405365/2522, current 362.422394/2523: elapsed=17044.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.422394
last_received_ts = 362.421936
last_seq = 2523
current_ts = 362.439453
current_received_ts = 362.438965
current_seq = 2524
count = 36
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.422394/2523, current 362.439453/2524: elapsed=17044.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.439453
last_received_ts = 362.438965
last_seq = 2524
current_ts = 362.456512
current_received_ts = 362.456207
current_seq = 2525
count = 37
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.439453/2524, current 362.456512/2525: elapsed=17050.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.456512
last_received_ts = 362.456207
last_seq = 2525
current_ts = 362.473541
current_received_ts = 362.473175
current_seq = 2526
count = 38
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.456512/2525, current 362.473541/2526: elapsed=17032.0us expected=17094.8us +- 85.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.473541
last_received_ts = 362.473175
last_seq = 2526
current_ts = 362.490570
current_received_ts = 362.490204
current_seq = 2527
count = 39
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.473541/2526, current 362.490570/2527: elapsed=17044.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.490570
last_received_ts = 362.490204
last_seq = 2527
current_ts = 362.507629
current_received_ts = 362.507233
current_seq = 2528
count = 40
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.490570/2527, current 362.507629/2528: elapsed=17042.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.507629
last_received_ts = 362.507233
last_seq = 2528
current_ts = 362.524658
current_received_ts = 362.524292
current_seq = 2529
count = 41
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.507629/2528, current 362.524658/2529: elapsed=17038.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.524658
last_received_ts = 362.524292
last_seq = 2529
current_ts = 362.541718
current_received_ts = 362.541412
current_seq = 2530
count = 42
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.524658/2529, current 362.541718/2530: elapsed=17050.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.541718
last_received_ts = 362.541412
last_seq = 2530
current_ts = 362.558746
current_received_ts = 362.558289
current_seq = 2531
count = 43
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.541718/2530, current 362.558746/2531: elapsed=17031.0us expected=17094.8us +- 85.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.558746
last_received_ts = 362.558289
last_seq = 2531
current_ts = 362.575775
current_received_ts = 362.575439
current_seq = 2532
count = 44
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.558746/2531, current 362.575775/2532: elapsed=17046.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.575775
last_received_ts = 362.575439
last_seq = 2532
current_ts = 362.592834
current_received_ts = 362.592407
current_seq = 2533
count = 45
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.575775/2532, current 362.592834/2533: elapsed=17036.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.592834
last_received_ts = 362.592407
last_seq = 2533
current_ts = 362.609863
current_received_ts = 362.609467
current_seq = 2534
count = 46
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.592834/2533, current 362.609863/2534: elapsed=17049.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.609863
last_received_ts = 362.609467
last_seq = 2534
current_ts = 362.626923
current_received_ts = 362.626495
current_seq = 2535
count = 47
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.609863/2534, current 362.626923/2535: elapsed=17043.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.626923
last_received_ts = 362.626495
last_seq = 2535
current_ts = 362.643951
current_received_ts = 362.643555
current_seq = 2536
count = 48
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.626923/2535, current 362.643951/2536: elapsed=17036.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.643951
last_received_ts = 362.643555
last_seq = 2536
current_ts = 362.660980
current_received_ts = 362.660553
current_seq = 2537
count = 49
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.643951/2536, current 362.660980/2537: elapsed=17042.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.660980
last_received_ts = 362.660553
last_seq = 2537
current_ts = 362.678040
current_received_ts = 362.677643
current_seq = 2538
count = 50
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.660980/2537, current 362.678040/2538: elapsed=17048.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.678040
last_received_ts = 362.677643
last_seq = 2538
current_ts = 362.695068
current_received_ts = 362.694763
current_seq = 2539
count = 51
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.678040/2538, current 362.695068/2539: elapsed=17037.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.695068
last_received_ts = 362.694763
last_seq = 2539
current_ts = 362.712128
current_received_ts = 362.711700
current_seq = 2540
count = 52
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.695068/2539, current 362.712128/2540: elapsed=17046.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.712128
last_received_ts = 362.711700
last_seq = 2540
current_ts = 362.729156
current_received_ts = 362.728851
current_seq = 2541
count = 53
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.712128/2540, current 362.729156/2541: elapsed=17048.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.729156
last_received_ts = 362.728851
last_seq = 2541
current_ts = 362.746216
current_received_ts = 362.745819
current_seq = 2542
count = 54
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.729156/2541, current 362.746216/2542: elapsed=17036.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.746216
last_received_ts = 362.745819
last_seq = 2542
current_ts = 362.763245
current_received_ts = 362.762848
current_seq = 2543
count = 55
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.746216/2542, current 362.763245/2543: elapsed=17045.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.763245
last_received_ts = 362.762848
last_seq = 2543
current_ts = 362.780304
current_received_ts = 362.779907
current_seq = 2544
count = 56
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.763245/2543, current 362.780304/2544: elapsed=17040.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.780304
last_received_ts = 362.779907
last_seq = 2544
current_ts = 362.797333
current_received_ts = 362.796936
current_seq = 2545
count = 57
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.780304/2544, current 362.797333/2545: elapsed=17043.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.797333
last_received_ts = 362.796936
last_seq = 2545
current_ts = 362.814362
current_received_ts = 362.813965
current_seq = 2546
count = 58
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.797333/2545, current 362.814362/2546: elapsed=17037.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.814362
last_received_ts = 362.813965
last_seq = 2546
current_ts = 362.831421
current_received_ts = 362.831055
current_seq = 2547
count = 59
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.814362/2546, current 362.831421/2547: elapsed=17048.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.831421
last_received_ts = 362.831055
last_seq = 2547
current_ts = 362.848450
current_received_ts = 362.848114
current_seq = 2548
count = 60
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.831421/2547, current 362.848450/2548: elapsed=17040.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.848450
last_received_ts = 362.848114
last_seq = 2548
current_ts = 362.865479
current_received_ts = 362.865112
current_seq = 2549
count = 61
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.848450/2548, current 362.865479/2549: elapsed=17033.0us expected=17094.8us +- 85.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.865479
last_received_ts = 362.865112
last_seq = 2549
current_ts = 362.882538
current_received_ts = 362.882141
current_seq = 2550
count = 62
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.865479/2549, current 362.882538/2550: elapsed=17044.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.882538
last_received_ts = 362.882141
last_seq = 2550
current_ts = 362.899567
current_received_ts = 362.899170
current_seq = 2551
count = 63
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.882538/2550, current 362.899567/2551: elapsed=17043.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.899567
last_received_ts = 362.899170
last_seq = 2551
current_ts = 362.916626
current_received_ts = 362.916168
current_seq = 2552
count = 64
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.899567/2551, current 362.916626/2552: elapsed=17045.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.916626
last_received_ts = 362.916168
last_seq = 2552
current_ts = 362.933685
current_received_ts = 362.933319
current_seq = 2553
count = 65
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.916626/2552, current 362.933685/2553: elapsed=17050.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.933685
last_received_ts = 362.933319
last_seq = 2553
current_ts = 362.950714
current_received_ts = 362.950409
current_seq = 2554
count = 66
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.933685/2553, current 362.950714/2554: elapsed=17042.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.950714
last_received_ts = 362.950409
last_seq = 2554
current_ts = 362.967743
current_received_ts = 362.967438
current_seq = 2555
count = 67
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.950714/2554, current 362.967743/2555: elapsed=17033.0us expected=17094.8us +- 85.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.967743
last_received_ts = 362.967438
last_seq = 2555
current_ts = 362.984802
current_received_ts = 362.984436
current_seq = 2556
count = 68
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.967743/2555, current 362.984802/2556: elapsed=17048.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 362.984802
last_received_ts = 362.984436
last_seq = 2556
current_ts = 363.001831
current_received_ts = 363.001434
current_seq = 2557
count = 69
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 362.984802/2556, current 363.001831/2557: elapsed=17040.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 363.001831
last_received_ts = 363.001434
last_seq = 2557
current_ts = 363.018890
current_received_ts = 363.018463
current_seq = 2558
count = 70
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 363.001831/2557, current 363.018890/2558: elapsed=17040.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 363.018890
last_received_ts = 363.018463
last_seq = 2558
current_ts = 363.035919
current_received_ts = 363.035492
current_seq = 2559
count = 71
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 363.018890/2558, current 363.035919/2559: elapsed=17039.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 363.035919
last_received_ts = 363.035492
last_seq = 2559
current_ts = 363.052948
current_received_ts = 363.052643
current_seq = 2560
count = 72
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 363.035919/2559, current 363.052948/2560: elapsed=17044.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 363.052948
last_received_ts = 363.052643
last_seq = 2560
current_ts = 363.070007
current_received_ts = 363.069580
current_seq = 2561
count = 73
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 363.052948/2560, current 363.070007/2561: elapsed=17039.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 363.070007
last_received_ts = 363.069580
last_seq = 2561
current_ts = 363.087036
current_received_ts = 363.086639
current_seq = 2562
count = 74
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 363.070007/2561, current 363.087036/2562: elapsed=17045.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 363.087036
last_received_ts = 363.086639
last_seq = 2562
current_ts = 363.104095
current_received_ts = 363.103699
current_seq = 2563
count = 75
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 363.087036/2562, current 363.104095/2563: elapsed=17044.0us expected=17094.8us +- 85.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 363.104095
last_received_ts = 363.103699
last_seq = 2563
current_ts = 363.121124
current_received_ts = 363.120697
current_seq = 2564
count = 76
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 363.104095/2563, current 363.121124/2564: elapsed=17034.0us expected=17094.8us +- 85.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 363.121124
last_received_ts = 363.120697
last_seq = 2564
current_ts = 363.138123
current_received_ts = 363.137726
current_seq = 2565
count = 77
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 363.121124/2564, current 363.138123/2565: elapsed=17004.0us expected=17094.8us +- 85.5us, error 0.5%
(kms_flip:2503) DEBUG: inconsistent flip ts/seq: last 363.121124/2564, current 363.138123/2565: elapsed=17004.0us expected=17094.8us
(kms_flip:2503) DEBUG: expected 0, counted 77, encoder type 2
(kms_flip:2503) DEBUG: dropped frames, expected 0, counted 77, encoder type 2
(kms_flip:2503) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2503) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2503) igt_core-INFO: Stack trace:
(kms_flip:2503) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2503) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2503) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2503) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2503) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2503) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2503) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2503) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A1: FAIL (4.752s)
Starting dynamic subtest: B-HDMI-A1
(kms_flip:2503) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2503) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2503) DEBUG: flip ts/seq: last 368.095520/145, current 368.112396/146: elapsed=16863.0us expected=16890.3us +- 84.5us, error 0.2%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.112396
last_received_ts = 368.112091
last_seq = 146
current_ts = 368.129242
current_received_ts = 368.128815
current_seq = 147
count = 88
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.112396/146, current 368.129242/147: elapsed=16860.0us expected=16890.3us +- 84.5us, error 0.2%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.129242
last_received_ts = 368.128815
last_seq = 147
current_ts = 368.146088
current_received_ts = 368.145660
current_seq = 148
count = 89
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.129242/147, current 368.146088/148: elapsed=16833.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.146088
last_received_ts = 368.145660
last_seq = 148
current_ts = 368.162933
current_received_ts = 368.162476
current_seq = 149
count = 90
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.146088/148, current 368.162933/149: elapsed=16843.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.162933
last_received_ts = 368.162476
last_seq = 149
current_ts = 368.179749
current_received_ts = 368.179321
current_seq = 150
count = 91
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.162933/149, current 368.179749/150: elapsed=16834.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.179749
last_received_ts = 368.179321
last_seq = 150
current_ts = 368.196594
current_received_ts = 368.196167
current_seq = 151
count = 92
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.179749/150, current 368.196594/151: elapsed=16837.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.196594
last_received_ts = 368.196167
last_seq = 151
current_ts = 368.213440
current_received_ts = 368.213043
current_seq = 152
count = 93
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.196594/151, current 368.213440/152: elapsed=16846.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.213440
last_received_ts = 368.213043
last_seq = 152
current_ts = 368.230286
current_received_ts = 368.229950
current_seq = 153
count = 94
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.213440/152, current 368.230286/153: elapsed=16835.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.230286
last_received_ts = 368.229950
last_seq = 153
current_ts = 368.247131
current_received_ts = 368.246704
current_seq = 154
count = 95
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.230286/153, current 368.247131/154: elapsed=16849.0us expected=16890.3us +- 84.5us, error 0.2%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.247131
last_received_ts = 368.246704
last_seq = 154
current_ts = 368.263947
current_received_ts = 368.263611
current_seq = 155
count = 96
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.247131/154, current 368.263947/155: elapsed=16828.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.263947
last_received_ts = 368.263611
last_seq = 155
current_ts = 368.280792
current_received_ts = 368.280304
current_seq = 156
count = 97
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.263947/155, current 368.280792/156: elapsed=16853.0us expected=16890.3us +- 84.5us, error 0.2%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.280792
last_received_ts = 368.280304
last_seq = 156
current_ts = 368.297638
current_received_ts = 368.297241
current_seq = 157
count = 98
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.280792/156, current 368.297638/157: elapsed=16835.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.297638
last_received_ts = 368.297241
last_seq = 157
current_ts = 368.314484
current_received_ts = 368.314056
current_seq = 158
count = 99
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.297638/157, current 368.314484/158: elapsed=16837.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.314484
last_received_ts = 368.314056
last_seq = 158
current_ts = 368.331329
current_received_ts = 368.330902
current_seq = 159
count = 100
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.314484/158, current 368.331329/159: elapsed=16841.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.331329
last_received_ts = 368.330902
last_seq = 159
current_ts = 368.348175
current_received_ts = 368.347748
current_seq = 160
count = 101
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.331329/159, current 368.348175/160: elapsed=16845.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.348175
last_received_ts = 368.347748
last_seq = 160
current_ts = 368.364990
current_received_ts = 368.364655
current_seq = 161
count = 102
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.348175/160, current 368.364990/161: elapsed=16841.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.364990
last_received_ts = 368.364655
last_seq = 161
current_ts = 368.381836
current_received_ts = 368.381378
current_seq = 162
count = 103
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.364990/161, current 368.381836/162: elapsed=16831.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.381836
last_received_ts = 368.381378
last_seq = 162
current_ts = 368.398682
current_received_ts = 368.398285
current_seq = 163
count = 104
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.381836/162, current 368.398682/163: elapsed=16847.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.398682
last_received_ts = 368.398285
last_seq = 163
current_ts = 368.415527
current_received_ts = 368.415222
current_seq = 164
count = 105
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.398682/163, current 368.415527/164: elapsed=16834.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.415527
last_received_ts = 368.415222
last_seq = 164
current_ts = 368.432373
current_received_ts = 368.431946
current_seq = 165
count = 106
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.415527/164, current 368.432373/165: elapsed=16845.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.432373
last_received_ts = 368.431946
last_seq = 165
current_ts = 368.449188
current_received_ts = 368.448761
current_seq = 166
count = 107
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.432373/165, current 368.449188/166: elapsed=16837.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.449188
last_received_ts = 368.448761
last_seq = 166
current_ts = 368.466034
current_received_ts = 368.465576
current_seq = 167
count = 108
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.449188/166, current 368.466034/167: elapsed=16845.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.466034
last_received_ts = 368.465576
last_seq = 167
current_ts = 368.482880
current_received_ts = 368.482422
current_seq = 168
count = 109
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.466034/167, current 368.482880/168: elapsed=16831.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.482880
last_received_ts = 368.482422
last_seq = 168
current_ts = 368.499725
current_received_ts = 368.499268
current_seq = 169
count = 110
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.482880/168, current 368.499725/169: elapsed=16843.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.499725
last_received_ts = 368.499268
last_seq = 169
current_ts = 368.516571
current_received_ts = 368.516296
current_seq = 170
count = 111
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.499725/169, current 368.516571/170: elapsed=16841.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.516571
last_received_ts = 368.516296
last_seq = 170
current_ts = 368.533386
current_received_ts = 368.532990
current_seq = 171
count = 112
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.516571/170, current 368.533386/171: elapsed=16841.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.533386
last_received_ts = 368.532990
last_seq = 171
current_ts = 368.550232
current_received_ts = 368.549805
current_seq = 172
count = 113
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.533386/171, current 368.550232/172: elapsed=16836.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.550232
last_received_ts = 368.549805
last_seq = 172
current_ts = 368.567078
current_received_ts = 368.566620
current_seq = 173
count = 114
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.550232/172, current 368.567078/173: elapsed=16842.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.567078
last_received_ts = 368.566620
last_seq = 173
current_ts = 368.583923
current_received_ts = 368.583496
current_seq = 174
count = 115
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.567078/173, current 368.583923/174: elapsed=16841.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.583923
last_received_ts = 368.583496
last_seq = 174
current_ts = 368.600769
current_received_ts = 368.600403
current_seq = 175
count = 116
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.583923/174, current 368.600769/175: elapsed=16839.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.600769
last_received_ts = 368.600403
last_seq = 175
current_ts = 368.617615
current_received_ts = 368.617188
current_seq = 176
count = 117
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.600769/175, current 368.617615/176: elapsed=16848.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.617615
last_received_ts = 368.617188
last_seq = 176
current_ts = 368.634430
current_received_ts = 368.634003
current_seq = 177
count = 118
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.617615/176, current 368.634430/177: elapsed=16828.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.634430
last_received_ts = 368.634003
last_seq = 177
current_ts = 368.651276
current_received_ts = 368.650848
current_seq = 178
count = 119
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.634430/177, current 368.651276/178: elapsed=16838.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.651276
last_received_ts = 368.650848
last_seq = 178
current_ts = 368.668121
current_received_ts = 368.667694
current_seq = 179
count = 120
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.651276/178, current 368.668121/179: elapsed=16850.0us expected=16890.3us +- 84.5us, error 0.2%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.668121
last_received_ts = 368.667694
last_seq = 179
current_ts = 368.684967
current_received_ts = 368.684601
current_seq = 180
count = 121
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.668121/179, current 368.684967/180: elapsed=16842.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.684967
last_received_ts = 368.684601
last_seq = 180
current_ts = 368.701782
current_received_ts = 368.701355
current_seq = 181
count = 122
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.684967/180, current 368.701782/181: elapsed=16830.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.701782
last_received_ts = 368.701355
last_seq = 181
current_ts = 368.718628
current_received_ts = 368.718323
current_seq = 182
count = 123
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.701782/181, current 368.718628/182: elapsed=16844.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.718628
last_received_ts = 368.718323
last_seq = 182
current_ts = 368.735474
current_received_ts = 368.735077
current_seq = 183
count = 124
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.718628/182, current 368.735474/183: elapsed=16845.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.735474
last_received_ts = 368.735077
last_seq = 183
current_ts = 368.752319
current_received_ts = 368.751984
current_seq = 184
count = 125
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.735474/183, current 368.752319/184: elapsed=16836.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.752319
last_received_ts = 368.751984
last_seq = 184
current_ts = 368.769165
current_received_ts = 368.768707
current_seq = 185
count = 126
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.752319/184, current 368.769165/185: elapsed=16843.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.769165
last_received_ts = 368.768707
last_seq = 185
current_ts = 368.785980
current_received_ts = 368.785553
current_seq = 186
count = 127
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.769165/185, current 368.785980/186: elapsed=16830.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.785980
last_received_ts = 368.785553
last_seq = 186
current_ts = 368.802826
current_received_ts = 368.802338
current_seq = 187
count = 128
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.785980/186, current 368.802826/187: elapsed=16842.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.802826
last_received_ts = 368.802338
last_seq = 187
current_ts = 368.819672
current_received_ts = 368.819397
current_seq = 188
count = 129
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.802826/187, current 368.819672/188: elapsed=16847.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.819672
last_received_ts = 368.819397
last_seq = 188
current_ts = 368.836517
current_received_ts = 368.836121
current_seq = 189
count = 130
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.819672/188, current 368.836517/189: elapsed=16831.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.836517
last_received_ts = 368.836121
last_seq = 189
current_ts = 368.853363
current_received_ts = 368.852936
current_seq = 190
count = 131
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.836517/189, current 368.853363/190: elapsed=16850.0us expected=16890.3us +- 84.5us, error 0.2%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.853363
last_received_ts = 368.852936
last_seq = 190
current_ts = 368.870209
current_received_ts = 368.869781
current_seq = 191
count = 132
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.853363/190, current 368.870209/191: elapsed=16840.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.870209
last_received_ts = 368.869781
last_seq = 191
current_ts = 368.887024
current_received_ts = 368.886627
current_seq = 192
count = 133
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.870209/191, current 368.887024/192: elapsed=16835.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.887024
last_received_ts = 368.886627
last_seq = 192
current_ts = 368.903870
current_received_ts = 368.903412
current_seq = 193
count = 134
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.887024/192, current 368.903870/193: elapsed=16835.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.903870
last_received_ts = 368.903412
last_seq = 193
current_ts = 368.920715
current_received_ts = 368.920288
current_seq = 194
count = 135
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.903870/193, current 368.920715/194: elapsed=16850.0us expected=16890.3us +- 84.5us, error 0.2%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.920715
last_received_ts = 368.920288
last_seq = 194
current_ts = 368.937561
current_received_ts = 368.937164
current_seq = 195
count = 136
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.920715/194, current 368.937561/195: elapsed=16835.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.937561
last_received_ts = 368.937164
last_seq = 195
current_ts = 368.954407
current_received_ts = 368.954102
current_seq = 196
count = 137
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.937561/195, current 368.954407/196: elapsed=16844.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.954407
last_received_ts = 368.954102
last_seq = 196
current_ts = 368.971222
current_received_ts = 368.970825
current_seq = 197
count = 138
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.954407/196, current 368.971222/197: elapsed=16830.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.971222
last_received_ts = 368.970825
last_seq = 197
current_ts = 368.988068
current_received_ts = 368.987640
current_seq = 198
count = 139
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.971222/197, current 368.988068/198: elapsed=16843.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 368.988068
last_received_ts = 368.987640
last_seq = 198
current_ts = 369.004913
current_received_ts = 369.004456
current_seq = 199
count = 140
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 368.988068/198, current 369.004913/199: elapsed=16837.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.004913
last_received_ts = 369.004456
last_seq = 199
current_ts = 369.021759
current_received_ts = 369.021393
current_seq = 200
count = 141
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.004913/199, current 369.021759/200: elapsed=16849.0us expected=16890.3us +- 84.5us, error 0.2%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.021759
last_received_ts = 369.021393
last_seq = 200
current_ts = 369.038605
current_received_ts = 369.038300
current_seq = 201
count = 142
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.021759/200, current 369.038605/201: elapsed=16840.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.038605
last_received_ts = 369.038300
last_seq = 201
current_ts = 369.055420
current_received_ts = 369.054993
current_seq = 202
count = 143
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.038605/201, current 369.055420/202: elapsed=16837.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.055420
last_received_ts = 369.054993
last_seq = 202
current_ts = 369.072266
current_received_ts = 369.071838
current_seq = 203
count = 144
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.055420/202, current 369.072266/203: elapsed=16844.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.072266
last_received_ts = 369.071838
last_seq = 203
current_ts = 369.089111
current_received_ts = 369.088684
current_seq = 204
count = 145
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.072266/203, current 369.089111/204: elapsed=16837.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.089111
last_received_ts = 369.088684
last_seq = 204
current_ts = 369.105957
current_received_ts = 369.105469
current_seq = 205
count = 146
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.089111/204, current 369.105957/205: elapsed=16842.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.105957
last_received_ts = 369.105469
last_seq = 205
current_ts = 369.122803
current_received_ts = 369.122345
current_seq = 206
count = 147
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.105957/205, current 369.122803/206: elapsed=16837.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.122803
last_received_ts = 369.122345
last_seq = 206
current_ts = 369.139618
current_received_ts = 369.139221
current_seq = 207
count = 148
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.122803/206, current 369.139618/207: elapsed=16814.0us expected=16890.3us +- 84.5us, error 0.5%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.139618
last_received_ts = 369.139221
last_seq = 207
current_ts = 369.156433
current_received_ts = 369.156097
current_seq = 208
count = 149
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.139618/207, current 369.156433/208: elapsed=16831.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.156433
last_received_ts = 369.156097
last_seq = 208
current_ts = 369.173248
current_received_ts = 369.172852
current_seq = 209
count = 150
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.156433/208, current 369.173248/209: elapsed=16820.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.173248
last_received_ts = 369.172852
last_seq = 209
current_ts = 369.190063
current_received_ts = 369.189667
current_seq = 210
count = 151
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.173248/209, current 369.190063/210: elapsed=16815.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.190063
last_received_ts = 369.189667
last_seq = 210
current_ts = 369.206879
current_received_ts = 369.206543
current_seq = 211
count = 152
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.190063/210, current 369.206879/211: elapsed=16813.0us expected=16890.3us +- 84.5us, error 0.5%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.206879
last_received_ts = 369.206543
last_seq = 211
current_ts = 369.223724
current_received_ts = 369.223236
current_seq = 212
count = 153
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.206879/211, current 369.223724/212: elapsed=16823.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.223724
last_received_ts = 369.223236
last_seq = 212
current_ts = 369.240540
current_received_ts = 369.240143
current_seq = 213
count = 154
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.223724/212, current 369.240540/213: elapsed=16822.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.240540
last_received_ts = 369.240143
last_seq = 213
current_ts = 369.257355
current_received_ts = 369.256897
current_seq = 214
count = 155
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.240540/213, current 369.257355/214: elapsed=16813.0us expected=16890.3us +- 84.5us, error 0.5%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.257355
last_received_ts = 369.256897
last_seq = 214
current_ts = 369.274170
current_received_ts = 369.273743
current_seq = 215
count = 156
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.257355/214, current 369.274170/215: elapsed=16828.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.274170
last_received_ts = 369.273743
last_seq = 215
current_ts = 369.290985
current_received_ts = 369.290558
current_seq = 216
count = 157
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.274170/215, current 369.290985/216: elapsed=16823.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.290985
last_received_ts = 369.290558
last_seq = 216
current_ts = 369.307800
current_received_ts = 369.307373
current_seq = 217
count = 158
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.290985/216, current 369.307800/217: elapsed=16811.0us expected=16890.3us +- 84.5us, error 0.5%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.307800
last_received_ts = 369.307373
last_seq = 217
current_ts = 369.324646
current_received_ts = 369.324219
current_seq = 218
count = 159
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.307800/217, current 369.324646/218: elapsed=16828.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.324646
last_received_ts = 369.324219
last_seq = 218
current_ts = 369.341461
current_received_ts = 369.341064
current_seq = 219
count = 160
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.324646/218, current 369.341461/219: elapsed=16813.0us expected=16890.3us +- 84.5us, error 0.5%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.341461
last_received_ts = 369.341064
last_seq = 219
current_ts = 369.358276
current_received_ts = 369.357819
current_seq = 220
count = 161
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.341461/219, current 369.358276/220: elapsed=16813.0us expected=16890.3us +- 84.5us, error 0.5%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.358276
last_received_ts = 369.357819
last_seq = 220
current_ts = 369.375092
current_received_ts = 369.374664
current_seq = 221
count = 162
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.358276/220, current 369.375092/221: elapsed=16827.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.375092
last_received_ts = 369.374664
last_seq = 221
current_ts = 369.391907
current_received_ts = 369.391418
current_seq = 222
count = 163
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.375092/221, current 369.391907/222: elapsed=16822.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.391907
last_received_ts = 369.391418
last_seq = 222
current_ts = 369.408722
current_received_ts = 369.408295
current_seq = 223
count = 164
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.391907/222, current 369.408722/223: elapsed=16820.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.408722
last_received_ts = 369.408295
last_seq = 223
current_ts = 369.425537
current_received_ts = 369.425140
current_seq = 224
count = 165
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.408722/223, current 369.425537/224: elapsed=16817.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.425537
last_received_ts = 369.425140
last_seq = 224
current_ts = 369.442352
current_received_ts = 369.441956
current_seq = 225
count = 166
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.425537/224, current 369.442352/225: elapsed=16817.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.442352
last_received_ts = 369.441956
last_seq = 225
current_ts = 369.459198
current_received_ts = 369.458740
current_seq = 226
count = 167
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.442352/225, current 369.459198/226: elapsed=16826.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.459198
last_received_ts = 369.458740
last_seq = 226
current_ts = 369.476013
current_received_ts = 369.475586
current_seq = 227
count = 168
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.459198/226, current 369.476013/227: elapsed=16815.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.476013
last_received_ts = 369.475586
last_seq = 227
current_ts = 369.492828
current_received_ts = 369.492371
current_seq = 228
count = 169
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.476013/227, current 369.492828/228: elapsed=16812.0us expected=16890.3us +- 84.5us, error 0.5%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.492828
last_received_ts = 369.492371
last_seq = 228
current_ts = 369.509644
current_received_ts = 369.509338
current_seq = 229
count = 170
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.492828/228, current 369.509644/229: elapsed=16832.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.509644
last_received_ts = 369.509338
last_seq = 229
current_ts = 369.526459
current_received_ts = 369.526154
current_seq = 230
count = 171
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.509644/229, current 369.526459/230: elapsed=16810.0us expected=16890.3us +- 84.5us, error 0.5%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.526459
last_received_ts = 369.526154
last_seq = 230
current_ts = 369.543274
current_received_ts = 369.542969
current_seq = 231
count = 172
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.526459/230, current 369.543274/231: elapsed=16825.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.543274
last_received_ts = 369.542969
last_seq = 231
current_ts = 369.560089
current_received_ts = 369.559662
current_seq = 232
count = 173
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.543274/231, current 369.560089/232: elapsed=16809.0us expected=16890.3us +- 84.5us, error 0.5%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.560089
last_received_ts = 369.559662
last_seq = 232
current_ts = 369.576935
current_received_ts = 369.576416
current_seq = 233
count = 174
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.560089/232, current 369.576935/233: elapsed=16832.0us expected=16890.3us +- 84.5us, error 0.3%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.576935
last_received_ts = 369.576416
last_seq = 233
current_ts = 369.593750
current_received_ts = 369.593262
current_seq = 234
count = 175
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.576935/233, current 369.593750/234: elapsed=16818.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.593750
last_received_ts = 369.593262
last_seq = 234
current_ts = 369.610565
current_received_ts = 369.610138
current_seq = 235
count = 176
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.593750/234, current 369.610565/235: elapsed=16808.0us expected=16890.3us +- 84.5us, error 0.5%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.610565
last_received_ts = 369.610138
last_seq = 235
current_ts = 369.627380
current_received_ts = 369.626984
current_seq = 236
count = 177
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.610565/235, current 369.627380/236: elapsed=16831.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.627380
last_received_ts = 369.626984
last_seq = 236
current_ts = 369.644196
current_received_ts = 369.643799
current_seq = 237
count = 178
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.627380/236, current 369.644196/237: elapsed=16808.0us expected=16890.3us +- 84.5us, error 0.5%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.644196
last_received_ts = 369.643799
last_seq = 237
current_ts = 369.661011
current_received_ts = 369.660583
current_seq = 238
count = 179
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.644196/237, current 369.661011/238: elapsed=16820.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.661011
last_received_ts = 369.660583
last_seq = 238
current_ts = 369.677826
current_received_ts = 369.677399
current_seq = 239
count = 180
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.661011/238, current 369.677826/239: elapsed=16829.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.677826
last_received_ts = 369.677399
last_seq = 239
current_ts = 369.694672
current_received_ts = 369.694366
current_seq = 240
count = 181
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.677826/239, current 369.694672/240: elapsed=16822.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.694672
last_received_ts = 369.694366
last_seq = 240
current_ts = 369.711487
current_received_ts = 369.711029
current_seq = 241
count = 182
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.694672/240, current 369.711487/241: elapsed=16815.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.711487
last_received_ts = 369.711029
last_seq = 241
current_ts = 369.728302
current_received_ts = 369.727875
current_seq = 242
count = 183
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.711487/241, current 369.728302/242: elapsed=16820.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.728302
last_received_ts = 369.727875
last_seq = 242
current_ts = 369.745117
current_received_ts = 369.744659
current_seq = 243
count = 184
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.728302/242, current 369.745117/243: elapsed=16817.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.745117
last_received_ts = 369.744659
last_seq = 243
current_ts = 369.761932
current_received_ts = 369.761475
current_seq = 244
count = 185
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.745117/243, current 369.761932/244: elapsed=16820.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.761932
last_received_ts = 369.761475
last_seq = 244
current_ts = 369.778748
current_received_ts = 369.778381
current_seq = 245
count = 186
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.761932/244, current 369.778748/245: elapsed=16822.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.778748
last_received_ts = 369.778381
last_seq = 245
current_ts = 369.795563
current_received_ts = 369.795288
current_seq = 246
count = 187
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.778748/245, current 369.795563/246: elapsed=16818.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.795563
last_received_ts = 369.795288
last_seq = 246
current_ts = 369.812408
current_received_ts = 369.811920
current_seq = 247
count = 188
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.795563/246, current 369.812408/247: elapsed=16821.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.812408
last_received_ts = 369.811920
last_seq = 247
current_ts = 369.829224
current_received_ts = 369.828796
current_seq = 248
count = 189
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.812408/247, current 369.829224/248: elapsed=16819.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.829224
last_received_ts = 369.828796
last_seq = 248
current_ts = 369.846039
current_received_ts = 369.845673
current_seq = 249
count = 190
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.829224/248, current 369.846039/249: elapsed=16817.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.846039
last_received_ts = 369.845673
last_seq = 249
current_ts = 369.862854
current_received_ts = 369.862396
current_seq = 250
count = 191
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.846039/249, current 369.862854/250: elapsed=16819.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.862854
last_received_ts = 369.862396
last_seq = 250
current_ts = 369.879669
current_received_ts = 369.879272
current_seq = 251
count = 192
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.862854/250, current 369.879669/251: elapsed=16819.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.879669
last_received_ts = 369.879272
last_seq = 251
current_ts = 369.896484
current_received_ts = 369.896088
current_seq = 252
count = 193
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.879669/251, current 369.896484/252: elapsed=16823.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.896484
last_received_ts = 369.896088
last_seq = 252
current_ts = 369.913300
current_received_ts = 369.912903
current_seq = 253
count = 194
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.896484/252, current 369.913300/253: elapsed=16811.0us expected=16890.3us +- 84.5us, error 0.5%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.913300
last_received_ts = 369.912903
last_seq = 253
current_ts = 369.930115
current_received_ts = 369.929718
current_seq = 254
count = 195
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.913300/253, current 369.930115/254: elapsed=16825.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.930115
last_received_ts = 369.929718
last_seq = 254
current_ts = 369.946960
current_received_ts = 369.946503
current_seq = 255
count = 196
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.930115/254, current 369.946960/255: elapsed=16819.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.946960
last_received_ts = 369.946503
last_seq = 255
current_ts = 369.963776
current_received_ts = 369.963257
current_seq = 256
count = 197
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.946960/255, current 369.963776/256: elapsed=16824.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.963776
last_received_ts = 369.963257
last_seq = 256
current_ts = 369.980591
current_received_ts = 369.980164
current_seq = 257
count = 198
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.963776/256, current 369.980591/257: elapsed=16811.0us expected=16890.3us +- 84.5us, error 0.5%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.980591
last_received_ts = 369.980164
last_seq = 257
current_ts = 369.997406
current_received_ts = 369.996979
current_seq = 258
count = 199
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.980591/257, current 369.997406/258: elapsed=16820.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 369.997406
last_received_ts = 369.996979
last_seq = 258
current_ts = 370.014221
current_received_ts = 370.013885
current_seq = 259
count = 200
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 369.997406/258, current 370.014221/259: elapsed=16819.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 370.014221
last_received_ts = 370.013885
last_seq = 259
current_ts = 370.031036
current_received_ts = 370.030640
current_seq = 260
count = 201
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 370.014221/259, current 370.031036/260: elapsed=16823.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 370.031036
last_received_ts = 370.030640
last_seq = 260
current_ts = 370.047852
current_received_ts = 370.047455
current_seq = 261
count = 202
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 370.031036/260, current 370.047852/261: elapsed=16820.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 370.047852
last_received_ts = 370.047455
last_seq = 261
current_ts = 370.064697
current_received_ts = 370.064270
current_seq = 262
count = 203
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 370.047852/261, current 370.064697/262: elapsed=16820.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 370.064697
last_received_ts = 370.064270
last_seq = 262
current_ts = 370.081512
current_received_ts = 370.081116
current_seq = 263
count = 204
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 370.064697/262, current 370.081512/263: elapsed=16817.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 370.081512
last_received_ts = 370.081116
last_seq = 263
current_ts = 370.098328
current_received_ts = 370.097900
current_seq = 264
count = 205
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 370.081512/263, current 370.098328/264: elapsed=16815.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 370.098328
last_received_ts = 370.097900
last_seq = 264
current_ts = 370.115143
current_received_ts = 370.114716
current_seq = 265
count = 206
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 370.098328/264, current 370.115143/265: elapsed=16828.0us expected=16890.3us +- 84.5us, error 0.4%
(kms_flip:2503) DEBUG: name = flip
last_ts = 370.115143
last_received_ts = 370.114716
last_seq = 265
current_ts = 370.131958
current_received_ts = 370.131531
current_seq = 266
count = 207
seq_step = 1
(kms_flip:2503) DEBUG: flip ts/seq: last 370.115143/265, current 370.131958/266: elapsed=16800.0us expected=16890.3us +- 84.5us, error 0.5%
(kms_flip:2503) DEBUG: inconsistent flip ts/seq: last 370.115143/265, current 370.131958/266: elapsed=16800.0us expected=16890.3us
(kms_flip:2503) DEBUG: expected 0, counted 207, encoder type 2
(kms_flip:2503) DEBUG: dropped frames, expected 0, counted 207, encoder type 2
(kms_flip:2503) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2503) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2503) igt_core-INFO: Stack trace:
(kms_flip:2503) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2503) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2503) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2503) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2503) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2503) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2503) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2503) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A1: FAIL (7.155s)
Starting dynamic subtest: C-HDMI-A1
Dynamic subtest C-HDMI-A1: SUCCESS (7.960s)
Starting dynamic subtest: D-HDMI-A1
Dynamic subtest D-HDMI-A1: SUCCESS (7.961s)
Subtest plain-flip-ts-check: FAIL (27.843s)