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

shard-lnl-5

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

Using IGT_SRANDOM=1740467252 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Expected frametime: 16664us; measured 16309.6us +- 3.500us accuracy 0.06%
vblank interval differs from modeline! expected 16664.0us, measured 16310us +- 3.500us, difference 354.4us (101.3 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-eDP1: FAIL (6.094s)
Starting dynamic subtest: B-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Expected frametime: 16664us; measured 16500.0us +- 4.531us accuracy 0.08%
vblank interval differs from modeline! expected 16664.0us, measured 16500us +- 4.531us, difference 164.0us (36.2 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (9.346s)
Starting dynamic subtest: C-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Expected frametime: 16664us; measured 16608.8us +- 3.331us accuracy 0.06%
vblank interval differs from modeline! expected 16664.0us, measured 16609us +- 3.331us, difference 55.2us (16.6 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-eDP1: FAIL (14.834s)
Subtest plain-flip-ts-check: FAIL (30.281s)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2246 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2930 igt_atexit_handler()
  #3 [erand48_r+0x1d6]
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2386 igt_exit()
  #6 [main+0x3f]
  #7 [__libc_init_first+0x8a]
  #8 [__libc_start_main+0x8b]
  #9 [_start+0x25]

Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-eDP1
(kms_flip:6382) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:6382) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
(kms_flip:6382) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:6382) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=11520)
(kms_flip:6382) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:6382) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:6382) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=11520)
(kms_flip:6382) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:6382) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:6382) intel_allocator_simple-DEBUG: <ial: 0x567b6c86e350, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:6382) intel_allocator_simple-DEBUG: <ial: 0x567b6c86e350, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:6382) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:6382) intel_allocator_simple-DEBUG: <ial: 0x567b6c87b6d0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:6382) intel_allocator_simple-DEBUG: <ial: 0x567b6c87b6d0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:6382) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:6382) intel_allocator_simple-DEBUG: <ial: 0x567b6c87f7d0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:6382) intel_allocator_simple-DEBUG: <ial: 0x567b6c87f7d0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:6382) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:6382) intel_allocator_simple-DEBUG: <ial: 0x567b6c8b4350, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:6382) intel_allocator_simple-DEBUG: <ial: 0x567b6c8b4350, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:6382) igt_kms-INFO:   2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
(kms_flip:6382) DEBUG: No stale events found
(kms_flip:6382) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:6382) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:6382) INFO: Expected frametime: 16664us; measured 16309.6us +- 3.500us accuracy 0.06%
(kms_flip:6382) INFO: vblank interval differs from modeline! expected 16664.0us, measured 16310us +- 3.500us, difference 354.4us (101.3 sigma)
(kms_flip:6382) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 177.077240
current_received_ts = 177.077499
current_seq = 527
count = 0
seq_step = 1
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.077240
last_received_ts = 177.077499
last_seq = 527
current_ts = 177.093552
current_received_ts = 177.092850
current_seq = 528
count = 1
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.077240/527, current 177.093552/528: elapsed=16309.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.093552
last_received_ts = 177.092850
last_seq = 528
current_ts = 177.109863
current_received_ts = 177.109177
current_seq = 529
count = 2
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.093552/528, current 177.109863/529: elapsed=16306.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.109863
last_received_ts = 177.109177
last_seq = 529
current_ts = 177.126175
current_received_ts = 177.125473
current_seq = 530
count = 3
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.109863/529, current 177.126175/530: elapsed=16309.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.126175
last_received_ts = 177.125473
last_seq = 530
current_ts = 177.142487
current_received_ts = 177.141785
current_seq = 531
count = 4
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.126175/530, current 177.142487/531: elapsed=16313.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.142487
last_received_ts = 177.141785
last_seq = 531
current_ts = 177.158798
current_received_ts = 177.158096
current_seq = 532
count = 5
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.142487/531, current 177.158798/532: elapsed=16310.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.158798
last_received_ts = 177.158096
last_seq = 532
current_ts = 177.175110
current_received_ts = 177.174347
current_seq = 533
count = 6
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.158798/532, current 177.175110/533: elapsed=16312.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.175110
last_received_ts = 177.174347
last_seq = 533
current_ts = 177.191406
current_received_ts = 177.191208
current_seq = 534
count = 7
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.175110/533, current 177.191406/534: elapsed=16306.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.191406
last_received_ts = 177.191208
last_seq = 534
current_ts = 177.207718
current_received_ts = 177.207047
current_seq = 535
count = 8
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.191406/534, current 177.207718/535: elapsed=16305.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.207718
last_received_ts = 177.207047
last_seq = 535
current_ts = 177.224030
current_received_ts = 177.223236
current_seq = 536
count = 9
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.207718/535, current 177.224030/536: elapsed=16313.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.224030
last_received_ts = 177.223236
last_seq = 536
current_ts = 177.240341
current_received_ts = 177.239639
current_seq = 537
count = 10
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.224030/536, current 177.240341/537: elapsed=16313.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.240341
last_received_ts = 177.239639
last_seq = 537
current_ts = 177.256653
current_received_ts = 177.256134
current_seq = 538
count = 11
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.240341/537, current 177.256653/538: elapsed=16307.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.256653
last_received_ts = 177.256134
last_seq = 538
current_ts = 177.272949
current_received_ts = 177.272263
current_seq = 539
count = 12
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.256653/538, current 177.272949/539: elapsed=16306.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.272949
last_received_ts = 177.272263
last_seq = 539
current_ts = 177.289261
current_received_ts = 177.288574
current_seq = 540
count = 13
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.272949/539, current 177.289261/540: elapsed=16312.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.289261
last_received_ts = 177.288574
last_seq = 540
current_ts = 177.305573
current_received_ts = 177.304886
current_seq = 541
count = 14
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.289261/540, current 177.305573/541: elapsed=16307.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.305573
last_received_ts = 177.304886
last_seq = 541
current_ts = 177.321884
current_received_ts = 177.321213
current_seq = 542
count = 15
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.305573/541, current 177.321884/542: elapsed=16310.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.321884
last_received_ts = 177.321213
last_seq = 542
current_ts = 177.338196
current_received_ts = 177.337494
current_seq = 543
count = 16
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.321884/542, current 177.338196/543: elapsed=16316.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.338196
last_received_ts = 177.337494
last_seq = 543
current_ts = 177.354507
current_received_ts = 177.353806
current_seq = 544
count = 17
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.338196/543, current 177.354507/544: elapsed=16308.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.354507
last_received_ts = 177.353806
last_seq = 544
current_ts = 177.370819
current_received_ts = 177.370132
current_seq = 545
count = 18
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.354507/544, current 177.370819/545: elapsed=16308.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.370819
last_received_ts = 177.370132
last_seq = 545
current_ts = 177.387115
current_received_ts = 177.386383
current_seq = 546
count = 19
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.370819/545, current 177.387115/546: elapsed=16307.0us expected=16309.6us +- 81.5us, error 0.0%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.387115
last_received_ts = 177.386383
last_seq = 546
current_ts = 177.403473
current_received_ts = 177.402771
current_seq = 547
count = 20
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.387115/546, current 177.403473/547: elapsed=16344.0us expected=16309.6us +- 81.5us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.403473
last_received_ts = 177.402771
last_seq = 547
current_ts = 177.419830
current_received_ts = 177.419144
current_seq = 548
count = 21
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.403473/547, current 177.419830/548: elapsed=16357.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.419830
last_received_ts = 177.419144
last_seq = 548
current_ts = 177.436172
current_received_ts = 177.435440
current_seq = 549
count = 22
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.419830/548, current 177.436172/549: elapsed=16354.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.436172
last_received_ts = 177.435440
last_seq = 549
current_ts = 177.452515
current_received_ts = 177.451828
current_seq = 550
count = 23
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.436172/549, current 177.452515/550: elapsed=16345.0us expected=16309.6us +- 81.5us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.452515
last_received_ts = 177.451828
last_seq = 550
current_ts = 177.468872
current_received_ts = 177.468185
current_seq = 551
count = 24
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.452515/550, current 177.468872/551: elapsed=16357.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.468872
last_received_ts = 177.468185
last_seq = 551
current_ts = 177.485229
current_received_ts = 177.484497
current_seq = 552
count = 25
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.468872/551, current 177.485229/552: elapsed=16349.0us expected=16309.6us +- 81.5us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.485229
last_received_ts = 177.484497
last_seq = 552
current_ts = 177.501587
current_received_ts = 177.500900
current_seq = 553
count = 26
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.485229/552, current 177.501587/553: elapsed=16358.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.501587
last_received_ts = 177.500900
last_seq = 553
current_ts = 177.517944
current_received_ts = 177.517242
current_seq = 554
count = 27
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.501587/553, current 177.517944/554: elapsed=16352.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.517944
last_received_ts = 177.517242
last_seq = 554
current_ts = 177.534286
current_received_ts = 177.533585
current_seq = 555
count = 28
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.517944/554, current 177.534286/555: elapsed=16352.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.534286
last_received_ts = 177.533585
last_seq = 555
current_ts = 177.550644
current_received_ts = 177.549942
current_seq = 556
count = 29
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.534286/555, current 177.550644/556: elapsed=16355.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.550644
last_received_ts = 177.549942
last_seq = 556
current_ts = 177.567001
current_received_ts = 177.566223
current_seq = 557
count = 30
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.550644/556, current 177.567001/557: elapsed=16353.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.567001
last_received_ts = 177.566223
last_seq = 557
current_ts = 177.583344
current_received_ts = 177.582657
current_seq = 558
count = 31
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.567001/557, current 177.583344/558: elapsed=16346.0us expected=16309.6us +- 81.5us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.583344
last_received_ts = 177.582657
last_seq = 558
current_ts = 177.599701
current_received_ts = 177.598999
current_seq = 559
count = 32
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.583344/558, current 177.599701/559: elapsed=16359.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.599701
last_received_ts = 177.598999
last_seq = 559
current_ts = 177.616058
current_received_ts = 177.615280
current_seq = 560
count = 33
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.599701/559, current 177.616058/560: elapsed=16348.0us expected=16309.6us +- 81.5us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.616058
last_received_ts = 177.615280
last_seq = 560
current_ts = 177.632401
current_received_ts = 177.631714
current_seq = 561
count = 34
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.616058/560, current 177.632401/561: elapsed=16356.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.632401
last_received_ts = 177.631714
last_seq = 561
current_ts = 177.648758
current_received_ts = 177.648071
current_seq = 562
count = 35
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.632401/561, current 177.648758/562: elapsed=16355.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.648758
last_received_ts = 177.648071
last_seq = 562
current_ts = 177.665115
current_received_ts = 177.664383
current_seq = 563
count = 36
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.648758/562, current 177.665115/563: elapsed=16348.0us expected=16309.6us +- 81.5us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.665115
last_received_ts = 177.664383
last_seq = 563
current_ts = 177.681458
current_received_ts = 177.680771
current_seq = 564
count = 37
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.665115/563, current 177.681458/564: elapsed=16354.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.681458
last_received_ts = 177.680771
last_seq = 564
current_ts = 177.697815
current_received_ts = 177.697128
current_seq = 565
count = 38
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.681458/564, current 177.697815/565: elapsed=16357.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.697815
last_received_ts = 177.697128
last_seq = 565
current_ts = 177.714172
current_received_ts = 177.713425
current_seq = 566
count = 39
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.697815/565, current 177.714172/566: elapsed=16353.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.714172
last_received_ts = 177.713425
last_seq = 566
current_ts = 177.730515
current_received_ts = 177.729828
current_seq = 567
count = 40
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.714172/566, current 177.730515/567: elapsed=16348.0us expected=16309.6us +- 81.5us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.730515
last_received_ts = 177.729828
last_seq = 567
current_ts = 177.746872
current_received_ts = 177.746201
current_seq = 568
count = 41
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.730515/567, current 177.746872/568: elapsed=16356.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.746872
last_received_ts = 177.746201
last_seq = 568
current_ts = 177.763229
current_received_ts = 177.762497
current_seq = 569
count = 42
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.746872/568, current 177.763229/569: elapsed=16350.0us expected=16309.6us +- 81.5us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.763229
last_received_ts = 177.762497
last_seq = 569
current_ts = 177.779587
current_received_ts = 177.778885
current_seq = 570
count = 43
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.763229/569, current 177.779587/570: elapsed=16359.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.779587
last_received_ts = 177.778885
last_seq = 570
current_ts = 177.795929
current_received_ts = 177.795212
current_seq = 571
count = 44
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.779587/570, current 177.795929/571: elapsed=16346.0us expected=16309.6us +- 81.5us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.795929
last_received_ts = 177.795212
last_seq = 571
current_ts = 177.812286
current_received_ts = 177.811615
current_seq = 572
count = 45
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.795929/571, current 177.812286/572: elapsed=16353.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.812286
last_received_ts = 177.811615
last_seq = 572
current_ts = 177.828644
current_received_ts = 177.827942
current_seq = 573
count = 46
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.812286/572, current 177.828644/573: elapsed=16357.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.828644
last_received_ts = 177.827942
last_seq = 573
current_ts = 177.845001
current_received_ts = 177.844208
current_seq = 574
count = 47
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.828644/573, current 177.845001/574: elapsed=16353.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.845001
last_received_ts = 177.844208
last_seq = 574
current_ts = 177.861343
current_received_ts = 177.860672
current_seq = 575
count = 48
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.845001/574, current 177.861343/575: elapsed=16353.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.861343
last_received_ts = 177.860672
last_seq = 575
current_ts = 177.877701
current_received_ts = 177.877014
current_seq = 576
count = 49
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.861343/575, current 177.877701/576: elapsed=16354.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.877701
last_received_ts = 177.877014
last_seq = 576
current_ts = 177.894058
current_received_ts = 177.893265
current_seq = 577
count = 50
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.877701/576, current 177.894058/577: elapsed=16352.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.894058
last_received_ts = 177.893265
last_seq = 577
current_ts = 177.910416
current_received_ts = 177.909714
current_seq = 578
count = 51
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.894058/577, current 177.910416/578: elapsed=16354.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.910416
last_received_ts = 177.909714
last_seq = 578
current_ts = 177.926758
current_received_ts = 177.926086
current_seq = 579
count = 52
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.910416/578, current 177.926758/579: elapsed=16350.0us expected=16309.6us +- 81.5us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.926758
last_received_ts = 177.926086
last_seq = 579
current_ts = 177.943115
current_received_ts = 177.942368
current_seq = 580
count = 53
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.926758/579, current 177.943115/580: elapsed=16357.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.943115
last_received_ts = 177.942368
last_seq = 580
current_ts = 177.959457
current_received_ts = 177.958786
current_seq = 581
count = 54
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.943115/580, current 177.959457/581: elapsed=16344.0us expected=16309.6us +- 81.5us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.959457
last_received_ts = 177.958786
last_seq = 581
current_ts = 177.975815
current_received_ts = 177.975143
current_seq = 582
count = 55
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.959457/581, current 177.975815/582: elapsed=16359.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.975815
last_received_ts = 177.975143
last_seq = 582
current_ts = 177.992172
current_received_ts = 177.991425
current_seq = 583
count = 56
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.975815/582, current 177.992172/583: elapsed=16348.0us expected=16309.6us +- 81.5us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 177.992172
last_received_ts = 177.991425
last_seq = 583
current_ts = 178.008530
current_received_ts = 178.007843
current_seq = 584
count = 57
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 177.992172/583, current 178.008530/584: elapsed=16357.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.008530
last_received_ts = 178.007843
last_seq = 584
current_ts = 178.024872
current_received_ts = 178.024200
current_seq = 585
count = 58
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.008530/584, current 178.024872/585: elapsed=16353.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.024872
last_received_ts = 178.024200
last_seq = 585
current_ts = 178.041229
current_received_ts = 178.040543
current_seq = 586
count = 59
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.024872/585, current 178.041229/586: elapsed=16354.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.041229
last_received_ts = 178.040543
last_seq = 586
current_ts = 178.057587
current_received_ts = 178.056885
current_seq = 587
count = 60
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.041229/586, current 178.057587/587: elapsed=16351.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.057587
last_received_ts = 178.056885
last_seq = 587
current_ts = 178.073929
current_received_ts = 178.073227
current_seq = 588
count = 61
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.057587/587, current 178.073929/588: elapsed=16351.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.073929
last_received_ts = 178.073227
last_seq = 588
current_ts = 178.090286
current_received_ts = 178.089600
current_seq = 589
count = 62
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.073929/588, current 178.090286/589: elapsed=16356.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.090286
last_received_ts = 178.089600
last_seq = 589
current_ts = 178.106644
current_received_ts = 178.105942
current_seq = 590
count = 63
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.090286/589, current 178.106644/590: elapsed=16349.0us expected=16309.6us +- 81.5us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.106644
last_received_ts = 178.105942
last_seq = 590
current_ts = 178.122986
current_received_ts = 178.122284
current_seq = 591
count = 64
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.106644/590, current 178.122986/591: elapsed=16352.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.122986
last_received_ts = 178.122284
last_seq = 591
current_ts = 178.139343
current_received_ts = 178.138657
current_seq = 592
count = 65
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.122986/591, current 178.139343/592: elapsed=16359.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.139343
last_received_ts = 178.138657
last_seq = 592
current_ts = 178.155701
current_received_ts = 178.155151
current_seq = 593
count = 66
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.139343/592, current 178.155701/593: elapsed=16353.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.155701
last_received_ts = 178.155151
last_seq = 593
current_ts = 178.172058
current_received_ts = 178.171494
current_seq = 594
count = 67
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.155701/593, current 178.172058/594: elapsed=16353.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.172058
last_received_ts = 178.171494
last_seq = 594
current_ts = 178.188400
current_received_ts = 178.187790
current_seq = 595
count = 68
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.172058/594, current 178.188400/595: elapsed=16349.0us expected=16309.6us +- 81.5us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.188400
last_received_ts = 178.187790
last_seq = 595
current_ts = 178.204758
current_received_ts = 178.204117
current_seq = 596
count = 69
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.188400/595, current 178.204758/596: elapsed=16349.0us expected=16309.6us +- 81.5us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.204758
last_received_ts = 178.204117
last_seq = 596
current_ts = 178.221115
current_received_ts = 178.220352
current_seq = 597
count = 70
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.204758/596, current 178.221115/597: elapsed=16360.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.221115
last_received_ts = 178.220352
last_seq = 597
current_ts = 178.237473
current_received_ts = 178.236755
current_seq = 598
count = 71
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.221115/597, current 178.237473/598: elapsed=16355.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.237473
last_received_ts = 178.236755
last_seq = 598
current_ts = 178.253815
current_received_ts = 178.253128
current_seq = 599
count = 72
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.237473/598, current 178.253815/599: elapsed=16349.0us expected=16309.6us +- 81.5us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.253815
last_received_ts = 178.253128
last_seq = 599
current_ts = 178.270172
current_received_ts = 178.269547
current_seq = 600
count = 73
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.253815/599, current 178.270172/600: elapsed=16356.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.270172
last_received_ts = 178.269547
last_seq = 600
current_ts = 178.286530
current_received_ts = 178.285751
current_seq = 601
count = 74
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.270172/600, current 178.286530/601: elapsed=16351.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.286530
last_received_ts = 178.285751
last_seq = 601
current_ts = 178.302872
current_received_ts = 178.302109
current_seq = 602
count = 75
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.286530/601, current 178.302872/602: elapsed=16355.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.302872
last_received_ts = 178.302109
last_seq = 602
current_ts = 178.319229
current_received_ts = 178.318527
current_seq = 603
count = 76
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.302872/602, current 178.319229/603: elapsed=16348.0us expected=16309.6us +- 81.5us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.319229
last_received_ts = 178.318527
last_seq = 603
current_ts = 178.335587
current_received_ts = 178.334900
current_seq = 604
count = 77
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.319229/603, current 178.335587/604: elapsed=16357.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.335587
last_received_ts = 178.334900
last_seq = 604
current_ts = 178.351929
current_received_ts = 178.351227
current_seq = 605
count = 78
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.335587/604, current 178.351929/605: elapsed=16347.0us expected=16309.6us +- 81.5us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.351929
last_received_ts = 178.351227
last_seq = 605
current_ts = 178.368286
current_received_ts = 178.367599
current_seq = 606
count = 79
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.351929/605, current 178.368286/606: elapsed=16354.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.368286
last_received_ts = 178.367599
last_seq = 606
current_ts = 178.384644
current_received_ts = 178.383835
current_seq = 607
count = 80
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.368286/606, current 178.384644/607: elapsed=16358.0us expected=16309.6us +- 81.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.384644
last_received_ts = 178.383835
last_seq = 607
current_ts = 178.401016
current_received_ts = 178.400330
current_seq = 608
count = 81
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.384644/607, current 178.401016/608: elapsed=16375.0us expected=16309.6us +- 81.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.401016
last_received_ts = 178.400330
last_seq = 608
current_ts = 178.417404
current_received_ts = 178.416718
current_seq = 609
count = 82
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.401016/608, current 178.417404/609: elapsed=16385.0us expected=16309.6us +- 81.5us, error 0.5%
(kms_flip:6382) DEBUG: name = flip
last_ts = 178.417404
last_received_ts = 178.416718
last_seq = 609
current_ts = 178.433792
current_received_ts = 178.432983
current_seq = 610
count = 83
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 178.417404/609, current 178.433792/610: elapsed=16393.0us expected=16309.6us +- 81.5us, error 0.5%
(kms_flip:6382) DEBUG: inconsistent flip ts/seq: last 178.417404/609, current 178.433792/610: elapsed=16393.0us expected=16309.6us
(kms_flip:6382) DEBUG: expected 68742, counted 83, encoder type 2
(kms_flip:6382) DEBUG: dropped frames, expected 68742, counted 83, encoder type 2
(kms_flip:6382) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:6382) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:6382) igt_core-INFO: Stack trace:
(kms_flip:6382) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:6382) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:6382) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:6382) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:6382) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:6382) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:6382) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:6382) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (6.094s)
Starting dynamic subtest: B-eDP1
(kms_flip:6382) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:6382) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:6382) DEBUG: flip ts/seq: last 185.517914/211, current 185.534470/212: elapsed=16552.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.534470
last_received_ts = 185.533936
last_seq = 212
current_ts = 185.551025
current_received_ts = 185.550400
current_seq = 213
count = 151
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.534470/212, current 185.551025/213: elapsed=16552.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.551025
last_received_ts = 185.550400
last_seq = 213
current_ts = 185.567581
current_received_ts = 185.567078
current_seq = 214
count = 152
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.551025/213, current 185.567581/214: elapsed=16551.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.567581
last_received_ts = 185.567078
last_seq = 214
current_ts = 185.584137
current_received_ts = 185.583572
current_seq = 215
count = 153
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.567581/214, current 185.584137/215: elapsed=16554.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.584137
last_received_ts = 185.583572
last_seq = 215
current_ts = 185.600693
current_received_ts = 185.600128
current_seq = 216
count = 154
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.584137/215, current 185.600693/216: elapsed=16556.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.600693
last_received_ts = 185.600128
last_seq = 216
current_ts = 185.617233
current_received_ts = 185.616669
current_seq = 217
count = 155
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.600693/216, current 185.617233/217: elapsed=16548.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.617233
last_received_ts = 185.616669
last_seq = 217
current_ts = 185.633789
current_received_ts = 185.633194
current_seq = 218
count = 156
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.617233/217, current 185.633789/218: elapsed=16554.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.633789
last_received_ts = 185.633194
last_seq = 218
current_ts = 185.650330
current_received_ts = 185.649765
current_seq = 219
count = 157
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.633789/218, current 185.650330/219: elapsed=16546.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.650330
last_received_ts = 185.649765
last_seq = 219
current_ts = 185.666885
current_received_ts = 185.666199
current_seq = 220
count = 158
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.650330/219, current 185.666885/220: elapsed=16555.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.666885
last_received_ts = 185.666199
last_seq = 220
current_ts = 185.683441
current_received_ts = 185.682877
current_seq = 221
count = 159
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.666885/220, current 185.683441/221: elapsed=16548.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.683441
last_received_ts = 185.682877
last_seq = 221
current_ts = 185.699982
current_received_ts = 185.699356
current_seq = 222
count = 160
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.683441/221, current 185.699982/222: elapsed=16552.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.699982
last_received_ts = 185.699356
last_seq = 222
current_ts = 185.716537
current_received_ts = 185.715988
current_seq = 223
count = 161
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.699982/222, current 185.716537/223: elapsed=16554.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.716537
last_received_ts = 185.715988
last_seq = 223
current_ts = 185.733093
current_received_ts = 185.732513
current_seq = 224
count = 162
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.716537/223, current 185.733093/224: elapsed=16556.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.733093
last_received_ts = 185.732513
last_seq = 224
current_ts = 185.749649
current_received_ts = 185.749084
current_seq = 225
count = 163
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.733093/224, current 185.749649/225: elapsed=16547.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.749649
last_received_ts = 185.749084
last_seq = 225
current_ts = 185.766205
current_received_ts = 185.765625
current_seq = 226
count = 164
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.749649/225, current 185.766205/226: elapsed=16556.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.766205
last_received_ts = 185.765625
last_seq = 226
current_ts = 185.782745
current_received_ts = 185.782196
current_seq = 227
count = 165
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.766205/226, current 185.782745/227: elapsed=16547.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.782745
last_received_ts = 185.782196
last_seq = 227
current_ts = 185.799301
current_received_ts = 185.798737
current_seq = 228
count = 166
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.782745/227, current 185.799301/228: elapsed=16552.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.799301
last_received_ts = 185.798737
last_seq = 228
current_ts = 185.815857
current_received_ts = 185.815430
current_seq = 229
count = 167
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.799301/228, current 185.815857/229: elapsed=16550.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.815857
last_received_ts = 185.815430
last_seq = 229
current_ts = 185.832397
current_received_ts = 185.831848
current_seq = 230
count = 168
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.815857/229, current 185.832397/230: elapsed=16550.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.832397
last_received_ts = 185.831848
last_seq = 230
current_ts = 185.848953
current_received_ts = 185.848328
current_seq = 231
count = 169
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.832397/230, current 185.848953/231: elapsed=16554.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.848953
last_received_ts = 185.848328
last_seq = 231
current_ts = 185.865509
current_received_ts = 185.864944
current_seq = 232
count = 170
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.848953/231, current 185.865509/232: elapsed=16553.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.865509
last_received_ts = 185.864944
last_seq = 232
current_ts = 185.882065
current_received_ts = 185.881500
current_seq = 233
count = 171
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.865509/232, current 185.882065/233: elapsed=16555.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.882065
last_received_ts = 185.881500
last_seq = 233
current_ts = 185.898621
current_received_ts = 185.898071
current_seq = 234
count = 172
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.882065/233, current 185.898621/234: elapsed=16552.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.898621
last_received_ts = 185.898071
last_seq = 234
current_ts = 185.915161
current_received_ts = 185.914597
current_seq = 235
count = 173
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.898621/234, current 185.915161/235: elapsed=16548.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.915161
last_received_ts = 185.914597
last_seq = 235
current_ts = 185.931717
current_received_ts = 185.931152
current_seq = 236
count = 174
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.915161/235, current 185.931717/236: elapsed=16550.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.931717
last_received_ts = 185.931152
last_seq = 236
current_ts = 185.948273
current_received_ts = 185.947693
current_seq = 237
count = 175
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.931717/236, current 185.948273/237: elapsed=16557.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.948273
last_received_ts = 185.947693
last_seq = 237
current_ts = 185.964828
current_received_ts = 185.964188
current_seq = 238
count = 176
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.948273/237, current 185.964828/238: elapsed=16552.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.964828
last_received_ts = 185.964188
last_seq = 238
current_ts = 185.981369
current_received_ts = 185.980804
current_seq = 239
count = 177
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.964828/238, current 185.981369/239: elapsed=16552.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.981369
last_received_ts = 185.980804
last_seq = 239
current_ts = 185.997925
current_received_ts = 185.997330
current_seq = 240
count = 178
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.981369/239, current 185.997925/240: elapsed=16546.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 185.997925
last_received_ts = 185.997330
last_seq = 240
current_ts = 186.014481
current_received_ts = 186.013901
current_seq = 241
count = 179
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 185.997925/240, current 186.014481/241: elapsed=16553.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.014481
last_received_ts = 186.013901
last_seq = 241
current_ts = 186.031021
current_received_ts = 186.030396
current_seq = 242
count = 180
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.014481/241, current 186.031021/242: elapsed=16553.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.031021
last_received_ts = 186.030396
last_seq = 242
current_ts = 186.047577
current_received_ts = 186.046997
current_seq = 243
count = 181
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.031021/242, current 186.047577/243: elapsed=16549.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.047577
last_received_ts = 186.046997
last_seq = 243
current_ts = 186.064133
current_received_ts = 186.063538
current_seq = 244
count = 182
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.047577/243, current 186.064133/244: elapsed=16556.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.064133
last_received_ts = 186.063538
last_seq = 244
current_ts = 186.080673
current_received_ts = 186.080124
current_seq = 245
count = 183
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.064133/244, current 186.080673/245: elapsed=16549.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.080673
last_received_ts = 186.080124
last_seq = 245
current_ts = 186.097229
current_received_ts = 186.096680
current_seq = 246
count = 184
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.080673/245, current 186.097229/246: elapsed=16554.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.097229
last_received_ts = 186.096680
last_seq = 246
current_ts = 186.113785
current_received_ts = 186.113220
current_seq = 247
count = 185
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.097229/246, current 186.113785/247: elapsed=16549.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.113785
last_received_ts = 186.113220
last_seq = 247
current_ts = 186.130341
current_received_ts = 186.129776
current_seq = 248
count = 186
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.113785/247, current 186.130341/248: elapsed=16552.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.130341
last_received_ts = 186.129776
last_seq = 248
current_ts = 186.146881
current_received_ts = 186.146210
current_seq = 249
count = 187
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.130341/248, current 186.146881/249: elapsed=16548.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.146881
last_received_ts = 186.146210
last_seq = 249
current_ts = 186.163437
current_received_ts = 186.162872
current_seq = 250
count = 188
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.146881/249, current 186.163437/250: elapsed=16552.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.163437
last_received_ts = 186.162872
last_seq = 250
current_ts = 186.179993
current_received_ts = 186.179352
current_seq = 251
count = 189
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.163437/250, current 186.179993/251: elapsed=16557.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.179993
last_received_ts = 186.179352
last_seq = 251
current_ts = 186.196533
current_received_ts = 186.195969
current_seq = 252
count = 190
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.179993/251, current 186.196533/252: elapsed=16547.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.196533
last_received_ts = 186.195969
last_seq = 252
current_ts = 186.213089
current_received_ts = 186.212463
current_seq = 253
count = 191
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.196533/252, current 186.213089/253: elapsed=16556.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.213089
last_received_ts = 186.212463
last_seq = 253
current_ts = 186.229645
current_received_ts = 186.229080
current_seq = 254
count = 192
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.213089/253, current 186.229645/254: elapsed=16547.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.229645
last_received_ts = 186.229080
last_seq = 254
current_ts = 186.246201
current_received_ts = 186.245621
current_seq = 255
count = 193
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.229645/254, current 186.246201/255: elapsed=16557.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.246201
last_received_ts = 186.245621
last_seq = 255
current_ts = 186.262741
current_received_ts = 186.262192
current_seq = 256
count = 194
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.246201/255, current 186.262741/256: elapsed=16545.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.262741
last_received_ts = 186.262192
last_seq = 256
current_ts = 186.279297
current_received_ts = 186.278732
current_seq = 257
count = 195
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.262741/256, current 186.279297/257: elapsed=16555.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.279297
last_received_ts = 186.278732
last_seq = 257
current_ts = 186.295853
current_received_ts = 186.295258
current_seq = 258
count = 196
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.279297/257, current 186.295853/258: elapsed=16549.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.295853
last_received_ts = 186.295258
last_seq = 258
current_ts = 186.312393
current_received_ts = 186.311615
current_seq = 259
count = 197
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.295853/258, current 186.312393/259: elapsed=16551.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.312393
last_received_ts = 186.311615
last_seq = 259
current_ts = 186.328949
current_received_ts = 186.328278
current_seq = 260
count = 198
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.312393/259, current 186.328949/260: elapsed=16553.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.328949
last_received_ts = 186.328278
last_seq = 260
current_ts = 186.345505
current_received_ts = 186.344818
current_seq = 261
count = 199
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.328949/260, current 186.345505/261: elapsed=16557.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.345505
last_received_ts = 186.344818
last_seq = 261
current_ts = 186.362061
current_received_ts = 186.361282
current_seq = 262
count = 200
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.345505/261, current 186.362061/262: elapsed=16547.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.362061
last_received_ts = 186.361282
last_seq = 262
current_ts = 186.378616
current_received_ts = 186.377930
current_seq = 263
count = 201
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.362061/262, current 186.378616/263: elapsed=16556.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.378616
last_received_ts = 186.377930
last_seq = 263
current_ts = 186.395172
current_received_ts = 186.394440
current_seq = 264
count = 202
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.378616/263, current 186.395172/264: elapsed=16555.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.395172
last_received_ts = 186.394440
last_seq = 264
current_ts = 186.411728
current_received_ts = 186.411072
current_seq = 265
count = 203
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.395172/264, current 186.411728/265: elapsed=16566.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.411728
last_received_ts = 186.411072
last_seq = 265
current_ts = 186.428284
current_received_ts = 186.427597
current_seq = 266
count = 204
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.411728/265, current 186.428284/266: elapsed=16557.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.428284
last_received_ts = 186.427597
last_seq = 266
current_ts = 186.444870
current_received_ts = 186.444199
current_seq = 267
count = 205
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.428284/266, current 186.444870/267: elapsed=16574.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.444870
last_received_ts = 186.444199
last_seq = 267
current_ts = 186.461426
current_received_ts = 186.460739
current_seq = 268
count = 206
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.444870/267, current 186.461426/268: elapsed=16557.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.461426
last_received_ts = 186.460739
last_seq = 268
current_ts = 186.477982
current_received_ts = 186.477325
current_seq = 269
count = 207
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.461426/268, current 186.477982/269: elapsed=16567.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.477982
last_received_ts = 186.477325
last_seq = 269
current_ts = 186.494553
current_received_ts = 186.493866
current_seq = 270
count = 208
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.477982/269, current 186.494553/270: elapsed=16563.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.494553
last_received_ts = 186.493866
last_seq = 270
current_ts = 186.511124
current_received_ts = 186.510391
current_seq = 271
count = 209
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.494553/270, current 186.511124/271: elapsed=16571.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.511124
last_received_ts = 186.510391
last_seq = 271
current_ts = 186.527679
current_received_ts = 186.527039
current_seq = 272
count = 210
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.511124/271, current 186.527679/272: elapsed=16561.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.527679
last_received_ts = 186.527039
last_seq = 272
current_ts = 186.544250
current_received_ts = 186.543564
current_seq = 273
count = 211
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.527679/272, current 186.544250/273: elapsed=16560.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.544250
last_received_ts = 186.543564
last_seq = 273
current_ts = 186.560822
current_received_ts = 186.560135
current_seq = 274
count = 212
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.544250/273, current 186.560822/274: elapsed=16571.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.560822
last_received_ts = 186.560135
last_seq = 274
current_ts = 186.577377
current_received_ts = 186.576706
current_seq = 275
count = 213
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.560822/274, current 186.577377/275: elapsed=16566.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.577377
last_received_ts = 186.576706
last_seq = 275
current_ts = 186.593933
current_received_ts = 186.593246
current_seq = 276
count = 214
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.577377/275, current 186.593933/276: elapsed=16559.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.593933
last_received_ts = 186.593246
last_seq = 276
current_ts = 186.610504
current_received_ts = 186.609818
current_seq = 277
count = 215
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.593933/276, current 186.610504/277: elapsed=16562.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.610504
last_received_ts = 186.609818
last_seq = 277
current_ts = 186.627075
current_received_ts = 186.626282
current_seq = 278
count = 216
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.610504/277, current 186.627075/278: elapsed=16567.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.627075
last_received_ts = 186.626282
last_seq = 278
current_ts = 186.643631
current_received_ts = 186.642975
current_seq = 279
count = 217
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.627075/278, current 186.643631/279: elapsed=16568.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.643631
last_received_ts = 186.642975
last_seq = 279
current_ts = 186.660202
current_received_ts = 186.659485
current_seq = 280
count = 218
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.643631/279, current 186.660202/280: elapsed=16564.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.660202
last_received_ts = 186.659485
last_seq = 280
current_ts = 186.676758
current_received_ts = 186.676086
current_seq = 281
count = 219
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.660202/280, current 186.676758/281: elapsed=16562.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.676758
last_received_ts = 186.676086
last_seq = 281
current_ts = 186.693329
current_received_ts = 186.692657
current_seq = 282
count = 220
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.676758/281, current 186.693329/282: elapsed=16562.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.693329
last_received_ts = 186.692657
last_seq = 282
current_ts = 186.709900
current_received_ts = 186.709213
current_seq = 283
count = 221
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.693329/282, current 186.709900/283: elapsed=16573.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.709900
last_received_ts = 186.709213
last_seq = 283
current_ts = 186.726456
current_received_ts = 186.725769
current_seq = 284
count = 222
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.709900/283, current 186.726456/284: elapsed=16556.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.726456
last_received_ts = 186.725769
last_seq = 284
current_ts = 186.743027
current_received_ts = 186.742249
current_seq = 285
count = 223
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.726456/284, current 186.743027/285: elapsed=16567.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.743027
last_received_ts = 186.742249
last_seq = 285
current_ts = 186.759583
current_received_ts = 186.758896
current_seq = 286
count = 224
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.743027/285, current 186.759583/286: elapsed=16564.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.759583
last_received_ts = 186.758896
last_seq = 286
current_ts = 186.776154
current_received_ts = 186.775406
current_seq = 287
count = 225
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.759583/286, current 186.776154/287: elapsed=16565.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.776154
last_received_ts = 186.775406
last_seq = 287
current_ts = 186.792725
current_received_ts = 186.792084
current_seq = 288
count = 226
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.776154/287, current 186.792725/288: elapsed=16568.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.792725
last_received_ts = 186.792084
last_seq = 288
current_ts = 186.809280
current_received_ts = 186.808609
current_seq = 289
count = 227
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.792725/288, current 186.809280/289: elapsed=16567.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.809280
last_received_ts = 186.808609
last_seq = 289
current_ts = 186.825836
current_received_ts = 186.825348
current_seq = 290
count = 228
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.809280/289, current 186.825836/290: elapsed=16557.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.825836
last_received_ts = 186.825348
last_seq = 290
current_ts = 186.842407
current_received_ts = 186.841721
current_seq = 291
count = 229
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.825836/290, current 186.842407/291: elapsed=16565.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.842407
last_received_ts = 186.841721
last_seq = 291
current_ts = 186.858978
current_received_ts = 186.858276
current_seq = 292
count = 230
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.842407/291, current 186.858978/292: elapsed=16570.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.858978
last_received_ts = 186.858276
last_seq = 292
current_ts = 186.875534
current_received_ts = 186.874847
current_seq = 293
count = 231
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.858978/292, current 186.875534/293: elapsed=16561.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.875534
last_received_ts = 186.874847
last_seq = 293
current_ts = 186.892105
current_received_ts = 186.891388
current_seq = 294
count = 232
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.875534/293, current 186.892105/294: elapsed=16569.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.892105
last_received_ts = 186.891388
last_seq = 294
current_ts = 186.908676
current_received_ts = 186.907974
current_seq = 295
count = 233
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.892105/294, current 186.908676/295: elapsed=16566.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.908676
last_received_ts = 186.907974
last_seq = 295
current_ts = 186.925232
current_received_ts = 186.924500
current_seq = 296
count = 234
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.908676/295, current 186.925232/296: elapsed=16557.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.925232
last_received_ts = 186.924500
last_seq = 296
current_ts = 186.941803
current_received_ts = 186.941116
current_seq = 297
count = 235
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.925232/296, current 186.941803/297: elapsed=16572.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.941803
last_received_ts = 186.941116
last_seq = 297
current_ts = 186.958359
current_received_ts = 186.957672
current_seq = 298
count = 236
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.941803/297, current 186.958359/298: elapsed=16565.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.958359
last_received_ts = 186.957672
last_seq = 298
current_ts = 186.974930
current_received_ts = 186.974228
current_seq = 299
count = 237
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.958359/298, current 186.974930/299: elapsed=16558.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.974930
last_received_ts = 186.974228
last_seq = 299
current_ts = 186.991486
current_received_ts = 186.990814
current_seq = 300
count = 238
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.974930/299, current 186.991486/300: elapsed=16569.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 186.991486
last_received_ts = 186.990814
last_seq = 300
current_ts = 187.008057
current_received_ts = 187.007355
current_seq = 301
count = 239
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 186.991486/300, current 187.008057/301: elapsed=16565.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.008057
last_received_ts = 187.007355
last_seq = 301
current_ts = 187.024612
current_received_ts = 187.023926
current_seq = 302
count = 240
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.008057/301, current 187.024612/302: elapsed=16560.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.024612
last_received_ts = 187.023926
last_seq = 302
current_ts = 187.041183
current_received_ts = 187.040466
current_seq = 303
count = 241
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.024612/302, current 187.041183/303: elapsed=16567.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.041183
last_received_ts = 187.040466
last_seq = 303
current_ts = 187.057755
current_received_ts = 187.057068
current_seq = 304
count = 242
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.041183/303, current 187.057755/304: elapsed=16564.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.057755
last_received_ts = 187.057068
last_seq = 304
current_ts = 187.074310
current_received_ts = 187.073624
current_seq = 305
count = 243
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.057755/304, current 187.074310/305: elapsed=16561.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.074310
last_received_ts = 187.073624
last_seq = 305
current_ts = 187.090881
current_received_ts = 187.090195
current_seq = 306
count = 244
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.074310/305, current 187.090881/306: elapsed=16569.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.090881
last_received_ts = 187.090195
last_seq = 306
current_ts = 187.107452
current_received_ts = 187.106750
current_seq = 307
count = 245
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.090881/306, current 187.107452/307: elapsed=16569.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.107452
last_received_ts = 187.106750
last_seq = 307
current_ts = 187.124008
current_received_ts = 187.123322
current_seq = 308
count = 246
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.107452/307, current 187.124008/308: elapsed=16557.0us expected=16500.0us +- 82.5us, error 0.3%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.124008
last_received_ts = 187.123322
last_seq = 308
current_ts = 187.140579
current_received_ts = 187.139893
current_seq = 309
count = 247
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.124008/308, current 187.140579/309: elapsed=16571.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.140579
last_received_ts = 187.139893
last_seq = 309
current_ts = 187.157135
current_received_ts = 187.156433
current_seq = 310
count = 248
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.140579/309, current 187.157135/310: elapsed=16564.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.157135
last_received_ts = 187.156433
last_seq = 310
current_ts = 187.173706
current_received_ts = 187.173050
current_seq = 311
count = 249
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.157135/310, current 187.173706/311: elapsed=16560.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.173706
last_received_ts = 187.173050
last_seq = 311
current_ts = 187.190277
current_received_ts = 187.189590
current_seq = 312
count = 250
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.173706/311, current 187.190277/312: elapsed=16571.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.190277
last_received_ts = 187.189590
last_seq = 312
current_ts = 187.206833
current_received_ts = 187.206146
current_seq = 313
count = 251
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.190277/312, current 187.206833/313: elapsed=16563.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.206833
last_received_ts = 187.206146
last_seq = 313
current_ts = 187.223389
current_received_ts = 187.222702
current_seq = 314
count = 252
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.206833/313, current 187.223389/314: elapsed=16559.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.223389
last_received_ts = 187.222702
last_seq = 314
current_ts = 187.239960
current_received_ts = 187.239273
current_seq = 315
count = 253
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.223389/314, current 187.239960/315: elapsed=16566.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.239960
last_received_ts = 187.239273
last_seq = 315
current_ts = 187.256531
current_received_ts = 187.255844
current_seq = 316
count = 254
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.239960/315, current 187.256531/316: elapsed=16570.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.256531
last_received_ts = 187.255844
last_seq = 316
current_ts = 187.273087
current_received_ts = 187.272400
current_seq = 317
count = 255
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.256531/316, current 187.273087/317: elapsed=16564.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.273087
last_received_ts = 187.272400
last_seq = 317
current_ts = 187.289658
current_received_ts = 187.288956
current_seq = 318
count = 256
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.273087/317, current 187.289658/318: elapsed=16565.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.289658
last_received_ts = 187.288956
last_seq = 318
current_ts = 187.306213
current_received_ts = 187.305481
current_seq = 319
count = 257
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.289658/318, current 187.306213/319: elapsed=16560.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.306213
last_received_ts = 187.305481
last_seq = 319
current_ts = 187.322784
current_received_ts = 187.322281
current_seq = 320
count = 258
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.306213/319, current 187.322784/320: elapsed=16565.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.322784
last_received_ts = 187.322281
last_seq = 320
current_ts = 187.339355
current_received_ts = 187.338684
current_seq = 321
count = 259
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.322784/320, current 187.339355/321: elapsed=16570.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.339355
last_received_ts = 187.338684
last_seq = 321
current_ts = 187.355911
current_received_ts = 187.355225
current_seq = 322
count = 260
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.339355/321, current 187.355911/322: elapsed=16564.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.355911
last_received_ts = 187.355225
last_seq = 322
current_ts = 187.372482
current_received_ts = 187.371796
current_seq = 323
count = 261
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.355911/322, current 187.372482/323: elapsed=16564.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.372482
last_received_ts = 187.371796
last_seq = 323
current_ts = 187.389053
current_received_ts = 187.388260
current_seq = 324
count = 262
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.372482/323, current 187.389053/324: elapsed=16567.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.389053
last_received_ts = 187.388260
last_seq = 324
current_ts = 187.405624
current_received_ts = 187.404922
current_seq = 325
count = 263
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.389053/324, current 187.405624/325: elapsed=16570.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.405624
last_received_ts = 187.404922
last_seq = 325
current_ts = 187.422195
current_received_ts = 187.421478
current_seq = 326
count = 264
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.405624/325, current 187.422195/326: elapsed=16576.0us expected=16500.0us +- 82.5us, error 0.5%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.422195
last_received_ts = 187.421478
last_seq = 326
current_ts = 187.438766
current_received_ts = 187.438095
current_seq = 327
count = 265
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.422195/326, current 187.438766/327: elapsed=16572.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.438766
last_received_ts = 187.438095
last_seq = 327
current_ts = 187.455338
current_received_ts = 187.454666
current_seq = 328
count = 266
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.438766/327, current 187.455338/328: elapsed=16577.0us expected=16500.0us +- 82.5us, error 0.5%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.455338
last_received_ts = 187.454666
last_seq = 328
current_ts = 187.471924
current_received_ts = 187.471237
current_seq = 329
count = 267
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.455338/328, current 187.471924/329: elapsed=16580.0us expected=16500.0us +- 82.5us, error 0.5%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.471924
last_received_ts = 187.471237
last_seq = 329
current_ts = 187.488510
current_received_ts = 187.487823
current_seq = 330
count = 268
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.471924/329, current 187.488510/330: elapsed=16580.0us expected=16500.0us +- 82.5us, error 0.5%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.488510
last_received_ts = 187.487823
last_seq = 330
current_ts = 187.505066
current_received_ts = 187.504379
current_seq = 331
count = 269
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.488510/330, current 187.505066/331: elapsed=16567.0us expected=16500.0us +- 82.5us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 187.505066
last_received_ts = 187.504379
last_seq = 331
current_ts = 187.521652
current_received_ts = 187.520950
current_seq = 332
count = 270
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 187.505066/331, current 187.521652/332: elapsed=16583.0us expected=16500.0us +- 82.5us, error 0.5%
(kms_flip:6382) DEBUG: inconsistent flip ts/seq: last 187.505066/331, current 187.521652/332: elapsed=16583.0us expected=16500.0us
(kms_flip:6382) DEBUG: expected 67949, counted 270, encoder type 2
(kms_flip:6382) DEBUG: dropped frames, expected 67949, counted 270, encoder type 2
(kms_flip:6382) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:6382) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:6382) igt_core-INFO: Stack trace:
(kms_flip:6382) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:6382) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:6382) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:6382) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:6382) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:6382) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:6382) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:6382) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (9.346s)
Starting dynamic subtest: C-eDP1
(kms_flip:6382) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:6382) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest C-eDP1 failed.
**** DEBUG ****
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.371048
last_received_ts = 200.370422
last_seq = 514
current_ts = 200.387680
current_received_ts = 200.387146
current_seq = 515
count = 481
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.371048/514, current 200.387680/515: elapsed=16636.0us expected=16608.8us +- 83.0us, error 0.2%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.387680
last_received_ts = 200.387146
last_seq = 515
current_ts = 200.404358
current_received_ts = 200.403778
current_seq = 516
count = 482
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.387680/515, current 200.404358/516: elapsed=16673.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.404358
last_received_ts = 200.403778
last_seq = 516
current_ts = 200.421036
current_received_ts = 200.420425
current_seq = 517
count = 483
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.404358/516, current 200.421036/517: elapsed=16675.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.421036
last_received_ts = 200.420425
last_seq = 517
current_ts = 200.437714
current_received_ts = 200.437195
current_seq = 518
count = 484
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.421036/517, current 200.437714/518: elapsed=16677.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.437714
last_received_ts = 200.437195
last_seq = 518
current_ts = 200.454391
current_received_ts = 200.453796
current_seq = 519
count = 485
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.437714/518, current 200.454391/519: elapsed=16682.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.454391
last_received_ts = 200.453796
last_seq = 519
current_ts = 200.471069
current_received_ts = 200.470444
current_seq = 520
count = 486
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.454391/519, current 200.471069/520: elapsed=16672.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.471069
last_received_ts = 200.470444
last_seq = 520
current_ts = 200.487747
current_received_ts = 200.487198
current_seq = 521
count = 487
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.471069/520, current 200.487747/521: elapsed=16680.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.487747
last_received_ts = 200.487198
last_seq = 521
current_ts = 200.504425
current_received_ts = 200.503845
current_seq = 522
count = 488
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.487747/521, current 200.504425/522: elapsed=16677.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.504425
last_received_ts = 200.503845
last_seq = 522
current_ts = 200.521103
current_received_ts = 200.520462
current_seq = 523
count = 489
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.504425/522, current 200.521103/523: elapsed=16677.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.521103
last_received_ts = 200.520462
last_seq = 523
current_ts = 200.537781
current_received_ts = 200.537186
current_seq = 524
count = 490
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.521103/523, current 200.537781/524: elapsed=16675.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.537781
last_received_ts = 200.537186
last_seq = 524
current_ts = 200.554459
current_received_ts = 200.553848
current_seq = 525
count = 491
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.537781/524, current 200.554459/525: elapsed=16679.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.554459
last_received_ts = 200.553848
last_seq = 525
current_ts = 200.571121
current_received_ts = 200.570526
current_seq = 526
count = 492
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.554459/525, current 200.571121/526: elapsed=16670.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.571121
last_received_ts = 200.570526
last_seq = 526
current_ts = 200.587799
current_received_ts = 200.587219
current_seq = 527
count = 493
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.571121/526, current 200.587799/527: elapsed=16678.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.587799
last_received_ts = 200.587219
last_seq = 527
current_ts = 200.604477
current_received_ts = 200.603912
current_seq = 528
count = 494
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.587799/527, current 200.604477/528: elapsed=16675.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.604477
last_received_ts = 200.603912
last_seq = 528
current_ts = 200.621155
current_received_ts = 200.620590
current_seq = 529
count = 495
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.604477/528, current 200.621155/529: elapsed=16680.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.621155
last_received_ts = 200.620590
last_seq = 529
current_ts = 200.637833
current_received_ts = 200.637238
current_seq = 530
count = 496
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.621155/529, current 200.637833/530: elapsed=16678.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.637833
last_received_ts = 200.637238
last_seq = 530
current_ts = 200.654510
current_received_ts = 200.653946
current_seq = 531
count = 497
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.637833/530, current 200.654510/531: elapsed=16673.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.654510
last_received_ts = 200.653946
last_seq = 531
current_ts = 200.671188
current_received_ts = 200.670593
current_seq = 532
count = 498
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.654510/531, current 200.671188/532: elapsed=16682.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.671188
last_received_ts = 200.670593
last_seq = 532
current_ts = 200.687866
current_received_ts = 200.687454
current_seq = 533
count = 499
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.671188/532, current 200.687866/533: elapsed=16675.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.687866
last_received_ts = 200.687454
last_seq = 533
current_ts = 200.704529
current_received_ts = 200.703964
current_seq = 534
count = 500
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.687866/533, current 200.704529/534: elapsed=16670.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.704529
last_received_ts = 200.703964
last_seq = 534
current_ts = 200.721207
current_received_ts = 200.720642
current_seq = 535
count = 501
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.704529/534, current 200.721207/535: elapsed=16677.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.721207
last_received_ts = 200.720642
last_seq = 535
current_ts = 200.737885
current_received_ts = 200.737320
current_seq = 536
count = 502
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.721207/535, current 200.737885/536: elapsed=16678.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.737885
last_received_ts = 200.737320
last_seq = 536
current_ts = 200.754562
current_received_ts = 200.754059
current_seq = 537
count = 503
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.737885/536, current 200.754562/537: elapsed=16680.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.754562
last_received_ts = 200.754059
last_seq = 537
current_ts = 200.771255
current_received_ts = 200.770676
current_seq = 538
count = 504
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.754562/537, current 200.771255/538: elapsed=16679.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.771255
last_received_ts = 200.770676
last_seq = 538
current_ts = 200.787918
current_received_ts = 200.787491
current_seq = 539
count = 505
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.771255/538, current 200.787918/539: elapsed=16674.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.787918
last_received_ts = 200.787491
last_seq = 539
current_ts = 200.804596
current_received_ts = 200.804062
current_seq = 540
count = 506
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.787918/539, current 200.804596/540: elapsed=16679.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.804596
last_received_ts = 200.804062
last_seq = 540
current_ts = 200.821274
current_received_ts = 200.820694
current_seq = 541
count = 507
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.804596/540, current 200.821274/541: elapsed=16672.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.821274
last_received_ts = 200.820694
last_seq = 541
current_ts = 200.837952
current_received_ts = 200.837387
current_seq = 542
count = 508
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.821274/541, current 200.837952/542: elapsed=16673.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.837952
last_received_ts = 200.837387
last_seq = 542
current_ts = 200.854630
current_received_ts = 200.854080
current_seq = 543
count = 509
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.837952/542, current 200.854630/543: elapsed=16678.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.854630
last_received_ts = 200.854080
last_seq = 543
current_ts = 200.871307
current_received_ts = 200.870758
current_seq = 544
count = 510
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.854630/543, current 200.871307/544: elapsed=16684.0us expected=16608.8us +- 83.0us, error 0.5%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.871307
last_received_ts = 200.870758
last_seq = 544
current_ts = 200.887985
current_received_ts = 200.887558
current_seq = 545
count = 511
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.871307/544, current 200.887985/545: elapsed=16672.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.887985
last_received_ts = 200.887558
last_seq = 545
current_ts = 200.904663
current_received_ts = 200.904083
current_seq = 546
count = 512
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.887985/545, current 200.904663/546: elapsed=16681.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.904663
last_received_ts = 200.904083
last_seq = 546
current_ts = 200.921341
current_received_ts = 200.920776
current_seq = 547
count = 513
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.904663/546, current 200.921341/547: elapsed=16676.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.921341
last_received_ts = 200.920776
last_seq = 547
current_ts = 200.938004
current_received_ts = 200.937592
current_seq = 548
count = 514
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.921341/547, current 200.938004/548: elapsed=16669.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.938004
last_received_ts = 200.937592
last_seq = 548
current_ts = 200.954681
current_received_ts = 200.954132
current_seq = 549
count = 515
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.938004/548, current 200.954681/549: elapsed=16677.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.954681
last_received_ts = 200.954132
last_seq = 549
current_ts = 200.971359
current_received_ts = 200.970947
current_seq = 550
count = 516
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.954681/549, current 200.971359/550: elapsed=16676.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.971359
last_received_ts = 200.970947
last_seq = 550
current_ts = 200.988037
current_received_ts = 200.987427
current_seq = 551
count = 517
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.971359/550, current 200.988037/551: elapsed=16683.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 200.988037
last_received_ts = 200.987427
last_seq = 551
current_ts = 201.004715
current_received_ts = 201.004166
current_seq = 552
count = 518
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 200.988037/551, current 201.004715/552: elapsed=16670.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.004715
last_received_ts = 201.004166
last_seq = 552
current_ts = 201.021393
current_received_ts = 201.020828
current_seq = 553
count = 519
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.004715/552, current 201.021393/553: elapsed=16679.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.021393
last_received_ts = 201.020828
last_seq = 553
current_ts = 201.038071
current_received_ts = 201.037506
current_seq = 554
count = 520
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.021393/553, current 201.038071/554: elapsed=16683.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.038071
last_received_ts = 201.037506
last_seq = 554
current_ts = 201.054749
current_received_ts = 201.054184
current_seq = 555
count = 521
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.038071/554, current 201.054749/555: elapsed=16670.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.054749
last_received_ts = 201.054184
last_seq = 555
current_ts = 201.071411
current_received_ts = 201.070847
current_seq = 556
count = 522
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.054749/555, current 201.071411/556: elapsed=16674.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.071411
last_received_ts = 201.070847
last_seq = 556
current_ts = 201.088104
current_received_ts = 201.087448
current_seq = 557
count = 523
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.071411/556, current 201.088104/557: elapsed=16683.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.088104
last_received_ts = 201.087448
last_seq = 557
current_ts = 201.104767
current_received_ts = 201.104218
current_seq = 558
count = 524
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.088104/557, current 201.104767/558: elapsed=16673.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.104767
last_received_ts = 201.104218
last_seq = 558
current_ts = 201.121445
current_received_ts = 201.120895
current_seq = 559
count = 525
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.104767/558, current 201.121445/559: elapsed=16678.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.121445
last_received_ts = 201.120895
last_seq = 559
current_ts = 201.138123
current_received_ts = 201.137695
current_seq = 560
count = 526
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.121445/559, current 201.138123/560: elapsed=16674.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.138123
last_received_ts = 201.137695
last_seq = 560
current_ts = 201.154800
current_received_ts = 201.154205
current_seq = 561
count = 527
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.138123/560, current 201.154800/561: elapsed=16681.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.154800
last_received_ts = 201.154205
last_seq = 561
current_ts = 201.171478
current_received_ts = 201.170914
current_seq = 562
count = 528
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.154800/561, current 201.171478/562: elapsed=16678.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.171478
last_received_ts = 201.170914
last_seq = 562
current_ts = 201.188156
current_received_ts = 201.187592
current_seq = 563
count = 529
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.171478/562, current 201.188156/563: elapsed=16675.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.188156
last_received_ts = 201.187592
last_seq = 563
current_ts = 201.204834
current_received_ts = 201.204269
current_seq = 564
count = 530
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.188156/563, current 201.204834/564: elapsed=16679.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.204834
last_received_ts = 201.204269
last_seq = 564
current_ts = 201.221512
current_received_ts = 201.220932
current_seq = 565
count = 531
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.204834/564, current 201.221512/565: elapsed=16669.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.221512
last_received_ts = 201.220932
last_seq = 565
current_ts = 201.238190
current_received_ts = 201.237747
current_seq = 566
count = 532
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.221512/565, current 201.238190/566: elapsed=16676.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.238190
last_received_ts = 201.237747
last_seq = 566
current_ts = 201.254868
current_received_ts = 201.254196
current_seq = 567
count = 533
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.238190/566, current 201.254868/567: elapsed=16680.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.254868
last_received_ts = 201.254196
last_seq = 567
current_ts = 201.271545
current_received_ts = 201.270966
current_seq = 568
count = 534
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.254868/567, current 201.271545/568: elapsed=16676.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.271545
last_received_ts = 201.270966
last_seq = 568
current_ts = 201.288208
current_received_ts = 201.287659
current_seq = 569
count = 535
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.271545/568, current 201.288208/569: elapsed=16674.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.288208
last_received_ts = 201.287659
last_seq = 569
current_ts = 201.304901
current_received_ts = 201.304306
current_seq = 570
count = 536
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.288208/569, current 201.304901/570: elapsed=16682.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.304901
last_received_ts = 201.304306
last_seq = 570
current_ts = 201.321564
current_received_ts = 201.321045
current_seq = 571
count = 537
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.304901/570, current 201.321564/571: elapsed=16673.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.321564
last_received_ts = 201.321045
last_seq = 571
current_ts = 201.338242
current_received_ts = 201.337662
current_seq = 572
count = 538
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.321564/571, current 201.338242/572: elapsed=16675.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.338242
last_received_ts = 201.337662
last_seq = 572
current_ts = 201.354919
current_received_ts = 201.354401
current_seq = 573
count = 539
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.338242/572, current 201.354919/573: elapsed=16680.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.354919
last_received_ts = 201.354401
last_seq = 573
current_ts = 201.371613
current_received_ts = 201.371063
current_seq = 574
count = 540
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.354919/573, current 201.371613/574: elapsed=16681.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.371613
last_received_ts = 201.371063
last_seq = 574
current_ts = 201.388275
current_received_ts = 201.387848
current_seq = 575
count = 541
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.371613/574, current 201.388275/575: elapsed=16670.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.388275
last_received_ts = 201.387848
last_seq = 575
current_ts = 201.404953
current_received_ts = 201.404343
current_seq = 576
count = 542
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.388275/575, current 201.404953/576: elapsed=16682.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.404953
last_received_ts = 201.404343
last_seq = 576
current_ts = 201.421631
current_received_ts = 201.421082
current_seq = 577
count = 543
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.404953/576, current 201.421631/577: elapsed=16668.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.421631
last_received_ts = 201.421082
last_seq = 577
current_ts = 201.438309
current_received_ts = 201.437714
current_seq = 578
count = 544
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.421631/577, current 201.438309/578: elapsed=16681.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.438309
last_received_ts = 201.437714
last_seq = 578
current_ts = 201.454971
current_received_ts = 201.454330
current_seq = 579
count = 545
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.438309/578, current 201.454971/579: elapsed=16671.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.454971
last_received_ts = 201.454330
last_seq = 579
current_ts = 201.471649
current_received_ts = 201.471100
current_seq = 580
count = 546
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.454971/579, current 201.471649/580: elapsed=16679.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.471649
last_received_ts = 201.471100
last_seq = 580
current_ts = 201.488327
current_received_ts = 201.487762
current_seq = 581
count = 547
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.471649/580, current 201.488327/581: elapsed=16678.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.488327
last_received_ts = 201.487762
last_seq = 581
current_ts = 201.505005
current_received_ts = 201.504364
current_seq = 582
count = 548
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.488327/581, current 201.505005/582: elapsed=16670.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.505005
last_received_ts = 201.504364
last_seq = 582
current_ts = 201.521683
current_received_ts = 201.521103
current_seq = 583
count = 549
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.505005/582, current 201.521683/583: elapsed=16679.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.521683
last_received_ts = 201.521103
last_seq = 583
current_ts = 201.538361
current_received_ts = 201.537766
current_seq = 584
count = 550
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.521683/583, current 201.538361/584: elapsed=16670.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.538361
last_received_ts = 201.537766
last_seq = 584
current_ts = 201.555023
current_received_ts = 201.554321
current_seq = 585
count = 551
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.538361/584, current 201.555023/585: elapsed=16675.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.555023
last_received_ts = 201.554321
last_seq = 585
current_ts = 201.571701
current_received_ts = 201.571152
current_seq = 586
count = 552
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.555023/585, current 201.571701/586: elapsed=16680.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.571701
last_received_ts = 201.571152
last_seq = 586
current_ts = 201.588379
current_received_ts = 201.587830
current_seq = 587
count = 553
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.571701/586, current 201.588379/587: elapsed=16671.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.588379
last_received_ts = 201.587830
last_seq = 587
current_ts = 201.605057
current_received_ts = 201.604401
current_seq = 588
count = 554
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.588379/587, current 201.605057/588: elapsed=16682.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.605057
last_received_ts = 201.604401
last_seq = 588
current_ts = 201.621735
current_received_ts = 201.621170
current_seq = 589
count = 555
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.605057/588, current 201.621735/589: elapsed=16673.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.621735
last_received_ts = 201.621170
last_seq = 589
current_ts = 201.638412
current_received_ts = 201.637817
current_seq = 590
count = 556
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.621735/589, current 201.638412/590: elapsed=16676.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.638412
last_received_ts = 201.637817
last_seq = 590
current_ts = 201.655075
current_received_ts = 201.654358
current_seq = 591
count = 557
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.638412/590, current 201.655075/591: elapsed=16672.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.655075
last_received_ts = 201.654358
last_seq = 591
current_ts = 201.671768
current_received_ts = 201.671219
current_seq = 592
count = 558
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.655075/591, current 201.671768/592: elapsed=16681.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.671768
last_received_ts = 201.671219
last_seq = 592
current_ts = 201.688431
current_received_ts = 201.687851
current_seq = 593
count = 559
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.671768/592, current 201.688431/593: elapsed=16671.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.688431
last_received_ts = 201.687851
last_seq = 593
current_ts = 201.705109
current_received_ts = 201.704514
current_seq = 594
count = 560
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.688431/593, current 201.705109/594: elapsed=16676.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.705109
last_received_ts = 201.704514
last_seq = 594
current_ts = 201.721786
current_received_ts = 201.721191
current_seq = 595
count = 561
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.705109/594, current 201.721786/595: elapsed=16678.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.721786
last_received_ts = 201.721191
last_seq = 595
current_ts = 201.738464
current_received_ts = 201.737885
current_seq = 596
count = 562
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.721786/595, current 201.738464/596: elapsed=16670.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.738464
last_received_ts = 201.737885
last_seq = 596
current_ts = 201.755142
current_received_ts = 201.754486
current_seq = 597
count = 563
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.738464/596, current 201.755142/597: elapsed=16677.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.755142
last_received_ts = 201.754486
last_seq = 597
current_ts = 201.771820
current_received_ts = 201.771240
current_seq = 598
count = 564
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.755142/597, current 201.771820/598: elapsed=16679.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.771820
last_received_ts = 201.771240
last_seq = 598
current_ts = 201.788483
current_received_ts = 201.787918
current_seq = 599
count = 565
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.771820/598, current 201.788483/599: elapsed=16671.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.788483
last_received_ts = 201.787918
last_seq = 599
current_ts = 201.805161
current_received_ts = 201.804565
current_seq = 600
count = 566
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.788483/599, current 201.805161/600: elapsed=16676.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.805161
last_received_ts = 201.804565
last_seq = 600
current_ts = 201.821838
current_received_ts = 201.821274
current_seq = 601
count = 567
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.805161/600, current 201.821838/601: elapsed=16672.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.821838
last_received_ts = 201.821274
last_seq = 601
current_ts = 201.838516
current_received_ts = 201.837936
current_seq = 602
count = 568
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.821838/601, current 201.838516/602: elapsed=16684.0us expected=16608.8us +- 83.0us, error 0.5%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.838516
last_received_ts = 201.837936
last_seq = 602
current_ts = 201.855194
current_received_ts = 201.854614
current_seq = 603
count = 569
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.838516/602, current 201.855194/603: elapsed=16670.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.855194
last_received_ts = 201.854614
last_seq = 603
current_ts = 201.871857
current_received_ts = 201.871307
current_seq = 604
count = 570
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.855194/603, current 201.871857/604: elapsed=16676.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.871857
last_received_ts = 201.871307
last_seq = 604
current_ts = 201.888535
current_received_ts = 201.887970
current_seq = 605
count = 571
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.871857/604, current 201.888535/605: elapsed=16677.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.888535
last_received_ts = 201.887970
last_seq = 605
current_ts = 201.905212
current_received_ts = 201.904648
current_seq = 606
count = 572
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.888535/605, current 201.905212/606: elapsed=16673.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.905212
last_received_ts = 201.904648
last_seq = 606
current_ts = 201.921890
current_received_ts = 201.921234
current_seq = 607
count = 573
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.905212/606, current 201.921890/607: elapsed=16675.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.921890
last_received_ts = 201.921234
last_seq = 607
current_ts = 201.938568
current_received_ts = 201.938004
current_seq = 608
count = 574
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.921890/607, current 201.938568/608: elapsed=16675.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.938568
last_received_ts = 201.938004
last_seq = 608
current_ts = 201.955231
current_received_ts = 201.954651
current_seq = 609
count = 575
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.938568/608, current 201.955231/609: elapsed=16674.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.955231
last_received_ts = 201.954651
last_seq = 609
current_ts = 201.971924
current_received_ts = 201.971344
current_seq = 610
count = 576
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.955231/609, current 201.971924/610: elapsed=16680.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.971924
last_received_ts = 201.971344
last_seq = 610
current_ts = 201.988586
current_received_ts = 201.988052
current_seq = 611
count = 577
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.971924/610, current 201.988586/611: elapsed=16677.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 201.988586
last_received_ts = 201.988052
last_seq = 611
current_ts = 202.005264
current_received_ts = 202.004700
current_seq = 612
count = 578
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 201.988586/611, current 202.005264/612: elapsed=16674.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.005264
last_received_ts = 202.004700
last_seq = 612
current_ts = 202.021942
current_received_ts = 202.021317
current_seq = 613
count = 579
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.005264/612, current 202.021942/613: elapsed=16673.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.021942
last_received_ts = 202.021317
last_seq = 613
current_ts = 202.038620
current_received_ts = 202.038071
current_seq = 614
count = 580
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.021942/613, current 202.038620/614: elapsed=16680.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.038620
last_received_ts = 202.038071
last_seq = 614
current_ts = 202.055298
current_received_ts = 202.054703
current_seq = 615
count = 581
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.038620/614, current 202.055298/615: elapsed=16674.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.055298
last_received_ts = 202.054703
last_seq = 615
current_ts = 202.071960
current_received_ts = 202.071396
current_seq = 616
count = 582
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.055298/615, current 202.071960/616: elapsed=16670.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.071960
last_received_ts = 202.071396
last_seq = 616
current_ts = 202.088654
current_received_ts = 202.088104
current_seq = 617
count = 583
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.071960/616, current 202.088654/617: elapsed=16682.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.088654
last_received_ts = 202.088104
last_seq = 617
current_ts = 202.105316
current_received_ts = 202.104752
current_seq = 618
count = 584
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.088654/617, current 202.105316/618: elapsed=16669.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.105316
last_received_ts = 202.104752
last_seq = 618
current_ts = 202.121994
current_received_ts = 202.121353
current_seq = 619
count = 585
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.105316/618, current 202.121994/619: elapsed=16678.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.121994
last_received_ts = 202.121353
last_seq = 619
current_ts = 202.138672
current_received_ts = 202.138107
current_seq = 620
count = 586
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.121994/619, current 202.138672/620: elapsed=16680.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.138672
last_received_ts = 202.138107
last_seq = 620
current_ts = 202.155350
current_received_ts = 202.154785
current_seq = 621
count = 587
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.138672/620, current 202.155350/621: elapsed=16671.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.155350
last_received_ts = 202.154785
last_seq = 621
current_ts = 202.172028
current_received_ts = 202.171402
current_seq = 622
count = 588
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.155350/621, current 202.172028/622: elapsed=16677.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.172028
last_received_ts = 202.171402
last_seq = 622
current_ts = 202.188690
current_received_ts = 202.188126
current_seq = 623
count = 589
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.172028/622, current 202.188690/623: elapsed=16675.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.188690
last_received_ts = 202.188126
last_seq = 623
current_ts = 202.205368
current_received_ts = 202.204803
current_seq = 624
count = 590
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.188690/623, current 202.205368/624: elapsed=16673.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.205368
last_received_ts = 202.204803
last_seq = 624
current_ts = 202.222046
current_received_ts = 202.221497
current_seq = 625
count = 591
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.205368/624, current 202.222046/625: elapsed=16677.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.222046
last_received_ts = 202.221497
last_seq = 625
current_ts = 202.238724
current_received_ts = 202.238190
current_seq = 626
count = 592
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.222046/625, current 202.238724/626: elapsed=16678.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.238724
last_received_ts = 202.238190
last_seq = 626
current_ts = 202.255402
current_received_ts = 202.254822
current_seq = 627
count = 593
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.238724/626, current 202.255402/627: elapsed=16670.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.255402
last_received_ts = 202.254822
last_seq = 627
current_ts = 202.272079
current_received_ts = 202.271454
current_seq = 628
count = 594
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.255402/627, current 202.272079/628: elapsed=16679.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.272079
last_received_ts = 202.271454
last_seq = 628
current_ts = 202.288742
current_received_ts = 202.288193
current_seq = 629
count = 595
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.272079/628, current 202.288742/629: elapsed=16674.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.288742
last_received_ts = 202.288193
last_seq = 629
current_ts = 202.305420
current_received_ts = 202.304855
current_seq = 630
count = 596
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.288742/629, current 202.305420/630: elapsed=16677.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.305420
last_received_ts = 202.304855
last_seq = 630
current_ts = 202.322098
current_received_ts = 202.321701
current_seq = 631
count = 597
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.305420/630, current 202.322098/631: elapsed=16678.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.322098
last_received_ts = 202.321701
last_seq = 631
current_ts = 202.338776
current_received_ts = 202.338196
current_seq = 632
count = 598
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.322098/631, current 202.338776/632: elapsed=16669.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.338776
last_received_ts = 202.338196
last_seq = 632
current_ts = 202.355453
current_received_ts = 202.355072
current_seq = 633
count = 599
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.338776/632, current 202.355453/633: elapsed=16678.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.355453
last_received_ts = 202.355072
last_seq = 633
current_ts = 202.372131
current_received_ts = 202.371521
current_seq = 634
count = 600
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.355453/633, current 202.372131/634: elapsed=16675.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: name = flip
last_ts = 202.372131
last_received_ts = 202.371521
last_seq = 634
current_ts = 202.388809
current_received_ts = 202.388214
current_seq = 635
count = 601
seq_step = 1
(kms_flip:6382) DEBUG: flip ts/seq: last 202.372131/634, current 202.388809/635: elapsed=16678.0us expected=16608.8us +- 83.0us, error 0.4%
(kms_flip:6382) DEBUG: expected 603, counted 602, encoder type 2
(kms_flip:6382) DEBUG: dropped frames, expected 603, counted 602, encoder type 2
(kms_flip:6382) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:6382) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:6382) igt_core-INFO: Stack trace:
(kms_flip:6382) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:6382) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:6382) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:6382) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:6382) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:6382) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:6382) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:6382) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-eDP1: FAIL (14.834s)
Subtest plain-flip-ts-check: FAIL (30.281s)
(kms_flip:6382) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2246:
(kms_flip:6382) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:6382) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:6382) igt_kms-CRITICAL: DPMS property not found on 189