Results for igt@kms_flip@2x-flip-vs-blocking-wf-vblank

shard-bmg-6

IGT-Version: 2.4-g2d1f7b290 (x86_64) (Linux: 7.0.0-rc7-lgci-xe-xe-pw-164412v2-debug+ x86_64)

Using IGT_SRANDOM=1775783885 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: 2x-flip-vs-blocking-wf-vblank
Starting dynamic subtest: AB-DP2-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16667.9us +- 5.994us accuracy 0.11%
Event flip: expected 304, counted 260, passrate = 84.62%, encoder type 2
Event vblank: expected 304, counted 260, passrate = 80.77%, encoder type 2
Expected frametime: 16667us; measured 16667.3us +- 6.107us accuracy 0.11%
Event flip: expected 303, counted 190, passrate = 73.68%, encoder type 2
Event vblank: expected 303, counted 190, passrate = 63.16%, encoder type 2
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:1443 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:2028 run_pair()
  #3 ../tests/kms_flip.c:2192 __igt_unique____real_main2104()
  #4 ../tests/kms_flip.c:2104 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest AB-DP2-HDMI-A3: FAIL (13.390s)
Starting dynamic subtest: AC-DP2-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16667.6us +- 4.334us accuracy 0.08%
Event flip: expected 309, counted 240, passrate = 79.17%, encoder type 2
Event vblank: expected 309, counted 240, passrate = 75.00%, encoder type 2
Expected frametime: 16667us; measured 16667.1us +- 6.692us accuracy 0.12%
Event flip: expected 307, counted 230, passrate = 78.26%, encoder type 2
Event vblank: expected 307, counted 230, passrate = 65.22%, encoder type 2
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:1443 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:2028 run_pair()
  #3 ../tests/kms_flip.c:2192 __igt_unique____real_main2104()
  #4 ../tests/kms_flip.c:2104 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest AC-DP2-HDMI-A3: FAIL (14.169s)
Starting dynamic subtest: AD-DP2-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16667.9us +- 3.243us accuracy 0.06%
Event flip: expected 305, counted 240, passrate = 87.50%, encoder type 2
Event vblank: expected 305, counted 240, passrate = 83.33%, encoder type 2
Expected frametime: 16667us; measured 16667.9us +- 6.797us accuracy 0.12%
Event flip: expected 306, counted 280, passrate = 85.71%, encoder type 2
Event vblank: expected 306, counted 280, passrate = 71.43%, encoder type 2
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:1443 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:2028 run_pair()
  #3 ../tests/kms_flip.c:2192 __igt_unique____real_main2104()
  #4 ../tests/kms_flip.c:2104 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest AD-DP2-HDMI-A3: FAIL (12.916s)
Starting dynamic subtest: BC-DP2-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16667.8us +- 6.434us accuracy 0.12%
Event flip: expected 307, counted 220, passrate = 72.73%, encoder type 2
Event vblank: expected 307, counted 220, passrate = 59.09%, encoder type 2
Expected frametime: 16667us; measured 16667.4us +- 5.123us accuracy 0.09%
Event flip: expected 302, counted 290, passrate = 89.66%, encoder type 2
Event vblank: expected 302, counted 290, passrate = 86.21%, encoder type 2
Dynamic subtest BC-DP2-HDMI-A3: SUCCESS (11.976s)
Starting dynamic subtest: BD-DP2-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16667.7us +- 4.868us accuracy 0.09%
Event flip: expected 309, counted 300, passrate = 90.00%, encoder type 2
Event vblank: expected 309, counted 300, passrate = 86.67%, encoder type 2
Dynamic subtest BD-DP2-HDMI-A3: SUCCESS (9.585s)
Starting dynamic subtest: CD-DP2-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16667.9us +- 6.952us accuracy 0.13%
Event flip: expected 305, counted 250, passrate = 88.00%, encoder type 2
Event vblank: expected 305, counted 250, passrate = 84.00%, encoder type 2
Expected frametime: 16667us; measured 16668.4us +- 5.365us accuracy 0.10%
Event flip: expected 303, counted 170, passrate = 70.59%, encoder type 2
Event vblank: expected 303, counted 170, passrate = 52.94%, encoder type 2
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:1443 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:2028 run_pair()
  #3 ../tests/kms_flip.c:2192 __igt_unique____real_main2104()
  #4 ../tests/kms_flip.c:2104 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest CD-DP2-HDMI-A3: FAIL (12.820s)
Subtest 2x-flip-vs-blocking-wf-vblank: FAIL (74.906s)
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2352 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2961 igt_atexit_handler()
  #3 [erand48_r+0x1d6]
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2416 igt_exit()
  #6 [main+0x3f]
  #7 [__libc_init_first+0x8a]
  #8 [__libc_start_main+0x8b]
  #9 [_start+0x25]

Starting subtest: 2x-flip-vs-blocking-wf-vblank
Starting dynamic subtest: AB-DP2-HDMI-A3
(kms_flip:3685) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1721:
(kms_flip:3685) CRITICAL: Failed assertion: !retried
Dynamic subtest AB-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:3685) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000009, size=0)
(kms_flip:3685) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:3685) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:3685) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:3685) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3685) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000009, size=0)
(kms_flip:3685) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:3685) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:3685) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:3685) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3685) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e554156e0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e554156e0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e554247f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e554247f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e554165a0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e554165a0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e55423de0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e55423de0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3685) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3685) DEBUG: No stale events found
(kms_flip:3685) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3685) INFO: Expected frametime: 16667us; measured 16667.9us +- 5.994us accuracy 0.11%
(kms_flip:3685) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 228.289856
current_received_ts = 228.439377
current_seq = 1399
count = 0
seq_step = 1
(kms_flip:3685) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 228.439880
current_received_ts = 228.439362
current_seq = 1408
count = 0
seq_step = 10
(kms_flip:3685) DEBUG: name = flip
last_ts = 228.289856
last_received_ts = 228.439377
last_seq = 1399
current_ts = 228.456543
current_received_ts = 228.606689
current_seq = 1409
count = 1
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 228.289856/1399, current 228.456543/1409: elapsed=166684.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 228.439880
last_received_ts = 228.439362
last_seq = 1408
current_ts = 228.606552
current_received_ts = 228.606598
current_seq = 1418
count = 1
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 228.439880/1408, current 228.606552/1418: elapsed=166679.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 228.456543
last_received_ts = 228.606689
last_seq = 1409
current_ts = 228.623215
current_received_ts = 228.773331
current_seq = 1419
count = 2
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 228.456543/1409, current 228.623215/1419: elapsed=166671.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 228.606552
last_received_ts = 228.606598
last_seq = 1418
current_ts = 228.773224
current_received_ts = 228.773254
current_seq = 1428
count = 2
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 228.606552/1418, current 228.773224/1428: elapsed=166672.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 228.623215
last_received_ts = 228.773331
last_seq = 1419
current_ts = 228.789902
current_received_ts = 228.939682
current_seq = 1429
count = 3
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 228.623215/1419, current 228.789902/1429: elapsed=166681.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 228.773224
last_received_ts = 228.773254
last_seq = 1428
current_ts = 228.939911
current_received_ts = 228.939606
current_seq = 1438
count = 3
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 228.773224/1428, current 228.939911/1438: elapsed=166681.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 228.789902
last_received_ts = 228.939682
last_seq = 1429
current_ts = 228.956589
current_received_ts = 229.106339
current_seq = 1439
count = 4
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 228.789902/1429, current 228.956589/1439: elapsed=166683.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 228.939911
last_received_ts = 228.939606
last_seq = 1438
current_ts = 229.106583
current_received_ts = 229.106247
current_seq = 1448
count = 4
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 228.939911/1438, current 229.106583/1448: elapsed=166673.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 228.956589
last_received_ts = 229.106339
last_seq = 1439
current_ts = 229.123245
current_received_ts = 229.240204
current_seq = 1449
count = 5
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 228.956589/1439, current 229.123245/1449: elapsed=166665.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 229.106583
last_received_ts = 229.106247
last_seq = 1448
current_ts = 229.239929
current_received_ts = 229.240143
current_seq = 1456
count = 5
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 1456, should be >= 1458
(kms_flip:3685) DEBUG: name = flip
last_ts = 229.123245
last_received_ts = 229.240204
last_seq = 1449
current_ts = 229.356491
current_received_ts = 229.506104
current_seq = 1460
count = 6
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 229.123245/1449, current 229.356491/1460: elapsed=233250.0us expected=183347.3us +- 916.7us, error 27.2%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 229.123245/1449, current 229.356491/1460: elapsed=233250.0us expected=183347.3us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 229.239929
last_received_ts = 229.240143
last_seq = 1456
current_ts = 229.506516
current_received_ts = 229.506088
current_seq = 1469
count = 6
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 229.239929/1456, current 229.506516/1469: elapsed=266580.0us expected=216683.2us +- 1083.4us, error 23.0%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 229.239929/1456, current 229.506516/1469: elapsed=266580.0us expected=216683.2us
(kms_flip:3685) DEBUG: name = flip
last_ts = 229.356491
last_received_ts = 229.506104
last_seq = 1460
current_ts = 229.523178
current_received_ts = 229.672943
current_seq = 1470
count = 7
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 229.356491/1460, current 229.523178/1470: elapsed=166682.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 229.506516
last_received_ts = 229.506088
last_seq = 1469
current_ts = 229.673187
current_received_ts = 229.672852
current_seq = 1479
count = 7
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 229.506516/1469, current 229.673187/1479: elapsed=166681.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 229.523178
last_received_ts = 229.672943
last_seq = 1470
current_ts = 229.689850
current_received_ts = 229.839905
current_seq = 1480
count = 8
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 229.523178/1470, current 229.689850/1480: elapsed=166668.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 229.673187
last_received_ts = 229.672852
last_seq = 1479
current_ts = 229.839859
current_received_ts = 229.839813
current_seq = 1489
count = 8
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 229.673187/1479, current 229.839859/1489: elapsed=166674.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 229.689850
last_received_ts = 229.839905
last_seq = 1480
current_ts = 229.856522
current_received_ts = 230.006378
current_seq = 1490
count = 9
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 229.689850/1480, current 229.856522/1490: elapsed=166679.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 229.839859
last_received_ts = 229.839813
last_seq = 1489
current_ts = 230.006546
current_received_ts = 230.006302
current_seq = 1499
count = 9
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 229.839859/1489, current 230.006546/1499: elapsed=166682.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 229.856522
last_received_ts = 230.006378
last_seq = 1490
current_ts = 230.023209
current_received_ts = 230.173370
current_seq = 1500
count = 10
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 229.856522/1490, current 230.023209/1500: elapsed=166686.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 230.006546
last_received_ts = 230.006302
last_seq = 1499
current_ts = 230.173218
current_received_ts = 230.173279
current_seq = 1509
count = 10
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 230.006546/1499, current 230.173218/1509: elapsed=166677.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 230.023209
last_received_ts = 230.173370
last_seq = 1500
current_ts = 230.189880
current_received_ts = 230.340118
current_seq = 1510
count = 11
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 230.023209/1500, current 230.189880/1510: elapsed=166668.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 230.173218
last_received_ts = 230.173279
last_seq = 1509
current_ts = 230.339890
current_received_ts = 230.339996
current_seq = 1519
count = 11
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 230.173218/1509, current 230.339890/1519: elapsed=166669.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 230.189880
last_received_ts = 230.340118
last_seq = 1510
current_ts = 230.356567
current_received_ts = 230.506165
current_seq = 1520
count = 12
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 230.189880/1510, current 230.356567/1520: elapsed=166686.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 230.339890
last_received_ts = 230.339996
last_seq = 1519
current_ts = 230.506561
current_received_ts = 230.506149
current_seq = 1529
count = 12
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 230.339890/1519, current 230.506561/1529: elapsed=166673.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 230.356567
last_received_ts = 230.506165
last_seq = 1520
current_ts = 230.637451
current_received_ts = 230.786972
current_seq = 1534
count = 13
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 230.356567/1520, current 230.637451/1534: elapsed=280879.0us expected=233351.1us +- 1166.8us, error 20.4%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 230.356567/1520, current 230.637451/1534: elapsed=280879.0us expected=233351.1us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 230.506561
last_received_ts = 230.506149
last_seq = 1529
current_ts = 230.787445
current_received_ts = 230.786957
current_seq = 1543
count = 13
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 230.506561/1529, current 230.787445/1543: elapsed=280887.0us expected=233351.1us +- 1166.8us, error 20.4%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 230.506561/1529, current 230.787445/1543: elapsed=280887.0us expected=233351.1us
(kms_flip:3685) DEBUG: name = flip
last_ts = 230.637451
last_received_ts = 230.786972
last_seq = 1534
current_ts = 230.804108
current_received_ts = 230.954239
current_seq = 1544
count = 14
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 230.637451/1534, current 230.804108/1544: elapsed=166665.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 230.787445
last_received_ts = 230.786957
last_seq = 1543
current_ts = 230.954117
current_received_ts = 230.954163
current_seq = 1553
count = 14
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 230.787445/1543, current 230.954117/1553: elapsed=166672.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 230.804108
last_received_ts = 230.954239
last_seq = 1544
current_ts = 230.970795
current_received_ts = 231.120911
current_seq = 1554
count = 15
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 230.804108/1544, current 230.970795/1554: elapsed=166686.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 230.954117
last_received_ts = 230.954163
last_seq = 1553
current_ts = 231.120804
current_received_ts = 231.120834
current_seq = 1563
count = 15
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 230.954117/1553, current 231.120804/1563: elapsed=166678.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 230.970795
last_received_ts = 231.120911
last_seq = 1554
current_ts = 231.137466
current_received_ts = 231.287384
current_seq = 1564
count = 16
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 230.970795/1554, current 231.137466/1564: elapsed=166670.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 231.120804
last_received_ts = 231.120834
last_seq = 1563
current_ts = 231.287476
current_received_ts = 231.287308
current_seq = 1573
count = 16
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 231.120804/1563, current 231.287476/1573: elapsed=166673.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 231.137466
last_received_ts = 231.287384
last_seq = 1564
current_ts = 231.304153
current_received_ts = 231.454269
current_seq = 1574
count = 17
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 231.137466/1564, current 231.304153/1574: elapsed=166682.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 231.287476
last_received_ts = 231.287308
last_seq = 1573
current_ts = 231.454163
current_received_ts = 231.454193
current_seq = 1583
count = 17
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 231.287476/1573, current 231.454163/1583: elapsed=166683.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 231.304153
last_received_ts = 231.454269
last_seq = 1574
current_ts = 231.470825
current_received_ts = 231.620941
current_seq = 1584
count = 18
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 231.304153/1574, current 231.470825/1584: elapsed=166671.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 231.454163
last_received_ts = 231.454193
last_seq = 1583
current_ts = 231.620834
current_received_ts = 231.620865
current_seq = 1593
count = 18
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 231.454163/1583, current 231.620834/1593: elapsed=166672.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 231.470825
last_received_ts = 231.620941
last_seq = 1584
current_ts = 231.637512
current_received_ts = 231.787170
current_seq = 1594
count = 19
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 231.470825/1584, current 231.637512/1594: elapsed=166690.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 231.620834
last_received_ts = 231.620865
last_seq = 1593
current_ts = 231.787506
current_received_ts = 231.787125
current_seq = 1603
count = 19
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 231.620834/1593, current 231.787506/1603: elapsed=166684.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 231.637512
last_received_ts = 231.787170
last_seq = 1594
current_ts = 232.214645
current_received_ts = 232.364227
current_seq = 1607
count = 20
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 231.637512/1594, current 232.214645/1607: elapsed=577132.0us expected=216683.2us +- 1083.4us, error 166.3%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 231.637512/1594, current 232.214645/1607: elapsed=577132.0us expected=216683.2us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 231.787506
last_received_ts = 231.787125
last_seq = 1603
current_ts = 232.364655
current_received_ts = 232.364212
current_seq = 1616
count = 20
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 231.787506/1603, current 232.364655/1616: elapsed=577137.0us expected=216683.2us +- 1083.4us, error 166.4%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 231.787506/1603, current 232.364655/1616: elapsed=577137.0us expected=216683.2us
(kms_flip:3685) DEBUG: name = flip
last_ts = 232.214645
last_received_ts = 232.364227
last_seq = 1607
current_ts = 232.526352
current_received_ts = 232.676468
current_seq = 1622
count = 21
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 232.214645/1607, current 232.526352/1622: elapsed=311715.0us expected=250019.1us +- 1250.1us, error 24.7%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 232.214645/1607, current 232.526352/1622: elapsed=311715.0us expected=250019.1us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 232.364655
last_received_ts = 232.364212
last_seq = 1616
current_ts = 232.676376
current_received_ts = 232.676392
current_seq = 1631
count = 21
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 232.364655/1616, current 232.676376/1631: elapsed=311723.0us expected=250019.1us +- 1250.1us, error 24.7%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 232.364655/1616, current 232.676376/1631: elapsed=311723.0us expected=250019.1us
(kms_flip:3685) DEBUG: name = flip
last_ts = 232.526352
last_received_ts = 232.676468
last_seq = 1622
current_ts = 232.693039
current_received_ts = 232.842850
current_seq = 1632
count = 22
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 232.526352/1622, current 232.693039/1632: elapsed=166684.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 232.676376
last_received_ts = 232.676392
last_seq = 1631
current_ts = 232.843048
current_received_ts = 232.842773
current_seq = 1641
count = 22
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 232.676376/1631, current 232.843048/1641: elapsed=166672.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 232.693039
last_received_ts = 232.842850
last_seq = 1632
current_ts = 232.859726
current_received_ts = 233.009842
current_seq = 1642
count = 23
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 232.693039/1632, current 232.859726/1642: elapsed=166680.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 232.843048
last_received_ts = 232.842773
last_seq = 1641
current_ts = 233.009735
current_received_ts = 233.009766
current_seq = 1651
count = 23
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 232.843048/1641, current 233.009735/1651: elapsed=166684.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 232.859726
last_received_ts = 233.009842
last_seq = 1642
current_ts = 233.026398
current_received_ts = 233.176529
current_seq = 1652
count = 24
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 232.859726/1642, current 233.026398/1652: elapsed=166671.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 233.009735
last_received_ts = 233.009766
last_seq = 1651
current_ts = 233.176407
current_received_ts = 233.176453
current_seq = 1661
count = 24
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 233.009735/1651, current 233.176407/1661: elapsed=166671.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 233.026398
last_received_ts = 233.176529
last_seq = 1652
current_ts = 233.193069
current_received_ts = 233.343201
current_seq = 1662
count = 25
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 233.026398/1652, current 233.193069/1662: elapsed=166681.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 233.176407
last_received_ts = 233.176453
last_seq = 1661
current_ts = 233.343079
current_received_ts = 233.343124
current_seq = 1671
count = 25
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 233.176407/1661, current 233.343079/1671: elapsed=166673.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) INFO: Event flip: expected 304, counted 260, passrate = 84.62%, encoder type 2
(kms_flip:3685) DEBUG: dropped frames, expected 304, counted 260, passrate = 84.62%, encoder type 2
(kms_flip:3685) INFO: Event vblank: expected 304, counted 260, passrate = 80.77%, encoder type 2
(kms_flip:3685) DEBUG: dropped frames, expected 304, counted 260, passrate = 80.77%, encoder type 2
(kms_flip:3685) DEBUG: Retrying after a hotplug event
(kms_flip:3685) DEBUG: No stale events found
(kms_flip:3685) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3685) INFO: Expected frametime: 16667us; measured 16667.3us +- 6.107us accuracy 0.11%
(kms_flip:3685) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 234.597565
current_received_ts = 234.747711
current_seq = 1731
count = 0
seq_step = 1
(kms_flip:3685) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 234.747574
current_received_ts = 234.747620
current_seq = 1740
count = 0
seq_step = 10
(kms_flip:3685) DEBUG: name = flip
last_ts = 234.597565
last_received_ts = 234.747711
last_seq = 1731
current_ts = 234.764252
current_received_ts = 234.914383
current_seq = 1741
count = 1
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 234.597565/1731, current 234.764252/1741: elapsed=166682.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 234.747574
last_received_ts = 234.747620
last_seq = 1740
current_ts = 234.914261
current_received_ts = 234.914307
current_seq = 1750
count = 1
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 234.747574/1740, current 234.914261/1750: elapsed=166679.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 234.764252
last_received_ts = 234.914383
last_seq = 1741
current_ts = 234.930923
current_received_ts = 235.080414
current_seq = 1751
count = 2
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 234.764252/1741, current 234.930923/1751: elapsed=166679.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 234.914261
last_received_ts = 234.914307
last_seq = 1750
current_ts = 235.080933
current_received_ts = 235.080338
current_seq = 1760
count = 2
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 234.914261/1750, current 235.080933/1760: elapsed=166677.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 234.930923
last_received_ts = 235.080414
last_seq = 1751
current_ts = 235.097595
current_received_ts = 235.197952
current_seq = 1761
count = 3
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 234.930923/1751, current 235.097595/1761: elapsed=166673.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 235.080933
last_received_ts = 235.080338
last_seq = 1760
current_ts = 235.197601
current_received_ts = 235.197906
current_seq = 1767
count = 3
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 1767, should be >= 1770
(kms_flip:3685) DEBUG: name = flip
last_ts = 235.097595
last_received_ts = 235.197952
last_seq = 1761
current_ts = 235.622803
current_received_ts = 235.772278
current_seq = 1771
count = 4
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 235.097595/1761, current 235.622803/1771: elapsed=525206.0us expected=166673.1us +- 833.4us, error 215.1%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 235.097595/1761, current 235.622803/1771: elapsed=525206.0us expected=166673.1us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 235.197601
last_received_ts = 235.197906
last_seq = 1767
current_ts = 235.772812
current_received_ts = 235.772202
current_seq = 1780
count = 4
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 235.197601/1767, current 235.772812/1780: elapsed=575201.0us expected=216675.1us +- 1083.4us, error 165.5%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 235.197601/1767, current 235.772812/1780: elapsed=575201.0us expected=216675.1us
(kms_flip:3685) DEBUG: name = flip
last_ts = 235.622803
last_received_ts = 235.772278
last_seq = 1771
current_ts = 235.789474
current_received_ts = 235.906906
current_seq = 1781
count = 5
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 235.622803/1771, current 235.789474/1781: elapsed=166669.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 235.772812
last_received_ts = 235.772202
last_seq = 1780
current_ts = 235.906158
current_received_ts = 235.906830
current_seq = 1788
count = 5
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 1788, should be >= 1790
(kms_flip:3685) DEBUG: name = flip
last_ts = 235.789474
last_received_ts = 235.906906
last_seq = 1781
current_ts = 236.462524
current_received_ts = 236.512970
current_seq = 1792
count = 6
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 235.789474/1781, current 236.462524/1792: elapsed=673056.0us expected=183340.4us +- 916.7us, error 267.1%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 235.789474/1781, current 236.462524/1792: elapsed=673056.0us expected=183340.4us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 235.906158
last_received_ts = 235.906830
last_seq = 1788
current_ts = 236.512527
current_received_ts = 236.512909
current_seq = 1795
count = 6
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 1795, should be >= 1798
(kms_flip:3685) DEBUG: name = flip
last_ts = 236.462524
last_received_ts = 236.512970
last_seq = 1792
current_ts = 237.083389
current_received_ts = 237.233582
current_seq = 1799
count = 7
seq_step = 1
(kms_flip:3685) DEBUG: unexpected flip seq 1799, should be >= 1802
(kms_flip:3685) DEBUG: name = vblank
last_ts = 236.512527
last_received_ts = 236.512909
last_seq = 1795
current_ts = 237.233398
current_received_ts = 237.233490
current_seq = 1808
count = 7
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 236.512527/1795, current 237.233398/1808: elapsed=720873.0us expected=216675.1us +- 1083.4us, error 232.7%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 236.512527/1795, current 237.233398/1808: elapsed=720873.0us expected=216675.1us
(kms_flip:3685) DEBUG: name = flip
last_ts = 237.083389
last_received_ts = 237.233582
last_seq = 1799
current_ts = 237.250076
current_received_ts = 237.400208
current_seq = 1809
count = 8
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 237.083389/1799, current 237.250076/1809: elapsed=166682.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 237.233398
last_received_ts = 237.233490
last_seq = 1808
current_ts = 237.400085
current_received_ts = 237.400131
current_seq = 1818
count = 8
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 237.233398/1808, current 237.400085/1818: elapsed=166678.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 237.250076
last_received_ts = 237.400208
last_seq = 1809
current_ts = 237.416748
current_received_ts = 237.566895
current_seq = 1819
count = 9
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 237.250076/1809, current 237.416748/1819: elapsed=166672.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 237.400085
last_received_ts = 237.400131
last_seq = 1818
current_ts = 237.566757
current_received_ts = 237.566818
current_seq = 1828
count = 9
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 237.400085/1818, current 237.566757/1828: elapsed=166672.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 237.416748
last_received_ts = 237.566895
last_seq = 1819
current_ts = 237.583435
current_received_ts = 237.733429
current_seq = 1829
count = 10
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 237.416748/1819, current 237.583435/1829: elapsed=166680.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 237.566757
last_received_ts = 237.566818
last_seq = 1828
current_ts = 237.733429
current_received_ts = 237.733353
current_seq = 1838
count = 10
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 237.566757/1828, current 237.733429/1838: elapsed=166682.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 237.583435
last_received_ts = 237.733429
last_seq = 1829
current_ts = 237.750107
current_received_ts = 237.900269
current_seq = 1839
count = 11
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 237.583435/1829, current 237.750107/1839: elapsed=166680.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 237.733429
last_received_ts = 237.733353
last_seq = 1838
current_ts = 237.900116
current_received_ts = 237.900192
current_seq = 1848
count = 11
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 237.733429/1838, current 237.900116/1848: elapsed=166676.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 237.750107
last_received_ts = 237.900269
last_seq = 1839
current_ts = 237.916779
current_received_ts = 238.066971
current_seq = 1849
count = 12
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 237.750107/1839, current 237.916779/1849: elapsed=166675.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 237.900116
last_received_ts = 237.900192
last_seq = 1848
current_ts = 238.066788
current_received_ts = 238.066895
current_seq = 1858
count = 12
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 237.900116/1848, current 238.066788/1858: elapsed=166679.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 237.916779
last_received_ts = 238.066971
last_seq = 1849
current_ts = 238.083450
current_received_ts = 238.232956
current_seq = 1859
count = 13
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 237.916779/1849, current 238.083450/1859: elapsed=166667.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 238.066788
last_received_ts = 238.066895
last_seq = 1858
current_ts = 238.233459
current_received_ts = 238.232925
current_seq = 1868
count = 13
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 238.066788/1858, current 238.233459/1868: elapsed=166673.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 238.083450
last_received_ts = 238.232956
last_seq = 1859
current_ts = 238.819534
current_received_ts = 238.869858
current_seq = 1874
count = 14
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 238.083450/1859, current 238.819534/1874: elapsed=736088.0us expected=250009.7us +- 1250.0us, error 194.4%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 238.083450/1859, current 238.819534/1874: elapsed=736088.0us expected=250009.7us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 238.233459
last_received_ts = 238.232925
last_seq = 1868
current_ts = 238.869537
current_received_ts = 238.869797
current_seq = 1877
count = 14
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 1877, should be >= 1878
(kms_flip:3685) DEBUG: name = flip
last_ts = 238.819534
last_received_ts = 238.869858
last_seq = 1874
current_ts = 238.998108
current_received_ts = 239.147675
current_seq = 1881
count = 15
seq_step = 1
(kms_flip:3685) DEBUG: unexpected flip seq 1881, should be >= 1884
(kms_flip:3685) DEBUG: name = vblank
last_ts = 238.869537
last_received_ts = 238.869797
last_seq = 1877
current_ts = 239.148117
current_received_ts = 239.147629
current_seq = 1890
count = 15
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 238.869537/1877, current 239.148117/1890: elapsed=278587.0us expected=216675.1us +- 1083.4us, error 28.6%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 238.869537/1877, current 239.148117/1890: elapsed=278587.0us expected=216675.1us
(kms_flip:3685) DEBUG: name = flip
last_ts = 238.998108
last_received_ts = 239.147675
last_seq = 1881
current_ts = 239.164780
current_received_ts = 239.314316
current_seq = 1891
count = 16
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 238.998108/1881, current 239.164780/1891: elapsed=166673.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 239.148117
last_received_ts = 239.147629
last_seq = 1890
current_ts = 239.314789
current_received_ts = 239.314285
current_seq = 1900
count = 16
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 239.148117/1890, current 239.314789/1900: elapsed=166676.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 239.164780
last_received_ts = 239.314316
last_seq = 1891
current_ts = 239.331467
current_received_ts = 239.481018
current_seq = 1901
count = 17
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 239.164780/1891, current 239.331467/1901: elapsed=166684.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 239.314789
last_received_ts = 239.314285
last_seq = 1900
current_ts = 239.481461
current_received_ts = 239.480988
current_seq = 1910
count = 17
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 239.314789/1900, current 239.481461/1910: elapsed=166672.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 239.331467
last_received_ts = 239.481018
last_seq = 1901
current_ts = 239.498138
current_received_ts = 239.647537
current_seq = 1911
count = 18
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 239.331467/1901, current 239.498138/1911: elapsed=166670.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 239.481461
last_received_ts = 239.480988
last_seq = 1910
current_ts = 239.648148
current_received_ts = 239.647507
current_seq = 1920
count = 18
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 239.481461/1910, current 239.648148/1920: elapsed=166673.0us expected=166673.1us +- 833.4us, error 0.0%
(kms_flip:3685) INFO: Event flip: expected 303, counted 190, passrate = 73.68%, encoder type 2
(kms_flip:3685) DEBUG: dropped frames, expected 303, counted 190, passrate = 73.68%, encoder type 2
(kms_flip:3685) INFO: Event vblank: expected 303, counted 190, passrate = 63.16%, encoder type 2
(kms_flip:3685) DEBUG: dropped frames, expected 303, counted 190, passrate = 63.16%, encoder type 2
(kms_flip:3685) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1721:
(kms_flip:3685) CRITICAL: Failed assertion: !retried
(kms_flip:3685) igt_core-INFO: Stack trace:
(kms_flip:3685) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:3685) igt_core-INFO:   #1 ../tests/kms_flip.c:1443 run_test_on_crtc_set()
(kms_flip:3685) igt_core-INFO:   #2 ../tests/kms_flip.c:2028 run_pair()
(kms_flip:3685) igt_core-INFO:   #3 ../tests/kms_flip.c:2192 __igt_unique____real_main2104()
(kms_flip:3685) igt_core-INFO:   #4 ../tests/kms_flip.c:2104 main()
(kms_flip:3685) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3685) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3685) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AB-DP2-HDMI-A3: FAIL (13.390s)
Starting dynamic subtest: AC-DP2-HDMI-A3
(kms_flip:3685) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1721:
(kms_flip:3685) CRITICAL: Failed assertion: !retried
Dynamic subtest AC-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:3685) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000009, size=0)
(kms_flip:3685) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:3685) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:3685) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:3685) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3685) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000009, size=0)
(kms_flip:3685) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:3685) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:3685) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=4, pitch=7680)
(kms_flip:3685) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3685) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e55481c50, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e55481c50, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e554a7460, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e554a7460, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e554a76a0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e554a76a0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e554c9220, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e554c9220, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3685) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3685) DEBUG: No stale events found
(kms_flip:3685) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3685) INFO: Expected frametime: 16667us; measured 16667.6us +- 4.334us accuracy 0.08%
(kms_flip:3685) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 242.028046
current_received_ts = 242.178162
current_seq = 2040
count = 0
seq_step = 1
(kms_flip:3685) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 242.178040
current_received_ts = 242.178070
current_seq = 2049
count = 0
seq_step = 10
(kms_flip:3685) DEBUG: name = flip
last_ts = 242.028046
last_received_ts = 242.178162
last_seq = 2040
current_ts = 242.194717
current_received_ts = 242.344833
current_seq = 2050
count = 1
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 242.028046/2040, current 242.194717/2050: elapsed=166670.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 242.178040
last_received_ts = 242.178070
last_seq = 2049
current_ts = 242.344727
current_received_ts = 242.344757
current_seq = 2059
count = 1
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 242.178040/2049, current 242.344727/2059: elapsed=166681.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 242.194717
last_received_ts = 242.344833
last_seq = 2050
current_ts = 242.361389
current_received_ts = 242.511505
current_seq = 2060
count = 2
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 242.194717/2050, current 242.361389/2060: elapsed=166678.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 242.344727
last_received_ts = 242.344757
last_seq = 2059
current_ts = 242.511398
current_received_ts = 242.511429
current_seq = 2069
count = 2
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 242.344727/2059, current 242.511398/2069: elapsed=166677.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 242.361389
last_received_ts = 242.511505
last_seq = 2060
current_ts = 242.528076
current_received_ts = 242.677551
current_seq = 2070
count = 3
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 242.361389/2060, current 242.528076/2070: elapsed=166685.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 242.511398
last_received_ts = 242.511429
last_seq = 2069
current_ts = 242.678085
current_received_ts = 242.677536
current_seq = 2079
count = 3
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 242.511398/2069, current 242.678085/2079: elapsed=166683.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 242.528076
last_received_ts = 242.677551
last_seq = 2070
current_ts = 242.694748
current_received_ts = 242.844208
current_seq = 2080
count = 4
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 242.528076/2070, current 242.694748/2080: elapsed=166669.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 242.678085
last_received_ts = 242.677536
last_seq = 2079
current_ts = 242.844757
current_received_ts = 242.844193
current_seq = 2089
count = 4
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 242.678085/2079, current 242.844757/2089: elapsed=166677.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 242.694748
last_received_ts = 242.844208
last_seq = 2080
current_ts = 242.861435
current_received_ts = 243.010864
current_seq = 2090
count = 5
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 242.694748/2080, current 242.861435/2090: elapsed=166683.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 242.844757
last_received_ts = 242.844193
last_seq = 2089
current_ts = 243.011444
current_received_ts = 243.010849
current_seq = 2099
count = 5
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 242.844757/2089, current 243.011444/2099: elapsed=166677.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 242.861435
last_received_ts = 243.010864
last_seq = 2090
current_ts = 243.028107
current_received_ts = 243.177704
current_seq = 2100
count = 6
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 242.861435/2090, current 243.028107/2100: elapsed=166671.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 243.011444
last_received_ts = 243.010849
last_seq = 2099
current_ts = 243.178116
current_received_ts = 243.177658
current_seq = 2109
count = 6
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 243.011444/2099, current 243.178116/2109: elapsed=166675.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 243.028107
last_received_ts = 243.177704
last_seq = 2100
current_ts = 243.307220
current_received_ts = 243.456787
current_seq = 2114
count = 7
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 243.028107/2100, current 243.307220/2114: elapsed=279127.0us expected=233346.8us +- 1166.7us, error 19.6%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 243.028107/2100, current 243.307220/2114: elapsed=279127.0us expected=233346.8us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 243.178116
last_received_ts = 243.177658
last_seq = 2109
current_ts = 243.457245
current_received_ts = 243.456772
current_seq = 2123
count = 7
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 243.178116/2109, current 243.457245/2123: elapsed=279131.0us expected=233346.8us +- 1166.7us, error 19.6%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 243.178116/2109, current 243.457245/2123: elapsed=279131.0us expected=233346.8us
(kms_flip:3685) DEBUG: name = flip
last_ts = 243.307220
last_received_ts = 243.456787
last_seq = 2114
current_ts = 243.473907
current_received_ts = 243.623718
current_seq = 2124
count = 8
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 243.307220/2114, current 243.473907/2124: elapsed=166674.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 243.457245
last_received_ts = 243.456772
last_seq = 2123
current_ts = 243.623917
current_received_ts = 243.623703
current_seq = 2133
count = 8
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 243.457245/2123, current 243.623917/2133: elapsed=166678.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 243.473907
last_received_ts = 243.623718
last_seq = 2124
current_ts = 243.640594
current_received_ts = 243.790146
current_seq = 2134
count = 9
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 243.473907/2124, current 243.640594/2134: elapsed=166691.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 243.623917
last_received_ts = 243.623703
last_seq = 2133
current_ts = 243.790588
current_received_ts = 243.790146
current_seq = 2143
count = 9
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 243.623917/2133, current 243.790588/2143: elapsed=166665.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 243.640594
last_received_ts = 243.790146
last_seq = 2134
current_ts = 243.807266
current_received_ts = 243.956955
current_seq = 2144
count = 10
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 243.640594/2134, current 243.807266/2144: elapsed=166674.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 243.790588
last_received_ts = 243.790146
last_seq = 2143
current_ts = 243.957275
current_received_ts = 243.956909
current_seq = 2153
count = 10
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 243.790588/2143, current 243.957275/2153: elapsed=166687.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 243.807266
last_received_ts = 243.956955
last_seq = 2144
current_ts = 244.381409
current_received_ts = 244.530945
current_seq = 2158
count = 11
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 243.807266/2144, current 244.381409/2158: elapsed=574141.0us expected=233346.8us +- 1166.7us, error 146.0%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 243.807266/2144, current 244.381409/2158: elapsed=574141.0us expected=233346.8us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 243.957275
last_received_ts = 243.956909
last_seq = 2153
current_ts = 244.531418
current_received_ts = 244.530930
current_seq = 2167
count = 11
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 243.957275/2153, current 244.531418/2167: elapsed=574150.0us expected=233346.8us +- 1166.7us, error 146.1%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 243.957275/2153, current 244.531418/2167: elapsed=574150.0us expected=233346.8us
(kms_flip:3685) DEBUG: name = flip
last_ts = 244.381409
last_received_ts = 244.530945
last_seq = 2158
current_ts = 244.548096
current_received_ts = 244.664963
current_seq = 2168
count = 12
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 244.381409/2158, current 244.548096/2168: elapsed=166685.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 244.531418
last_received_ts = 244.530930
last_seq = 2167
current_ts = 244.664764
current_received_ts = 244.664917
current_seq = 2175
count = 12
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 2175, should be >= 2177
(kms_flip:3685) DEBUG: name = flip
last_ts = 244.548096
last_received_ts = 244.664963
last_seq = 2168
current_ts = 245.222687
current_received_ts = 245.273026
current_seq = 2179
count = 13
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 244.548096/2168, current 245.222687/2179: elapsed=674601.0us expected=183343.9us +- 916.7us, error 267.9%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 244.548096/2168, current 245.222687/2179: elapsed=674601.0us expected=183343.9us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 244.664764
last_received_ts = 244.664917
last_seq = 2175
current_ts = 245.272690
current_received_ts = 245.272964
current_seq = 2182
count = 13
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 2182, should be >= 2185
(kms_flip:3685) DEBUG: name = flip
last_ts = 245.222687
last_received_ts = 245.273026
last_seq = 2179
current_ts = 245.398193
current_received_ts = 245.548248
current_seq = 2186
count = 14
seq_step = 1
(kms_flip:3685) DEBUG: unexpected flip seq 2186, should be >= 2189
(kms_flip:3685) DEBUG: name = vblank
last_ts = 245.272690
last_received_ts = 245.272964
last_seq = 2182
current_ts = 245.548203
current_received_ts = 245.548172
current_seq = 2195
count = 14
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 245.272690/2182, current 245.548203/2195: elapsed=275514.0us expected=216679.1us +- 1083.4us, error 27.2%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 245.272690/2182, current 245.548203/2195: elapsed=275514.0us expected=216679.1us
(kms_flip:3685) DEBUG: name = flip
last_ts = 245.398193
last_received_ts = 245.548248
last_seq = 2186
current_ts = 245.564880
current_received_ts = 245.714874
current_seq = 2196
count = 15
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 245.398193/2186, current 245.564880/2196: elapsed=166683.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 245.548203
last_received_ts = 245.548172
last_seq = 2195
current_ts = 245.714890
current_received_ts = 245.714798
current_seq = 2205
count = 15
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 245.548203/2195, current 245.714890/2205: elapsed=166679.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 245.564880
last_received_ts = 245.714874
last_seq = 2196
current_ts = 245.731537
current_received_ts = 245.881561
current_seq = 2206
count = 16
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 245.564880/2196, current 245.731537/2206: elapsed=166668.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 245.714890
last_received_ts = 245.714798
last_seq = 2205
current_ts = 245.881546
current_received_ts = 245.881485
current_seq = 2215
count = 16
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 245.714890/2205, current 245.881546/2215: elapsed=166666.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 245.731537
last_received_ts = 245.881561
last_seq = 2206
current_ts = 245.898224
current_received_ts = 246.048233
current_seq = 2216
count = 17
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 245.731537/2206, current 245.898224/2216: elapsed=166679.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 245.881546
last_received_ts = 245.881485
last_seq = 2215
current_ts = 246.048248
current_received_ts = 246.048157
current_seq = 2225
count = 17
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 245.881546/2215, current 246.048248/2225: elapsed=166691.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 245.898224
last_received_ts = 246.048233
last_seq = 2216
current_ts = 246.064911
current_received_ts = 246.214890
current_seq = 2226
count = 18
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 245.898224/2216, current 246.064911/2226: elapsed=166686.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 246.048248
last_received_ts = 246.048157
last_seq = 2225
current_ts = 246.214920
current_received_ts = 246.214813
current_seq = 2235
count = 18
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 246.048248/2225, current 246.214920/2235: elapsed=166674.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 246.064911
last_received_ts = 246.214890
last_seq = 2226
current_ts = 246.231583
current_received_ts = 246.381119
current_seq = 2236
count = 19
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 246.064911/2226, current 246.231583/2236: elapsed=166671.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 246.214920
last_received_ts = 246.214813
last_seq = 2235
current_ts = 246.381577
current_received_ts = 246.381104
current_seq = 2245
count = 19
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 246.214920/2235, current 246.381577/2245: elapsed=166666.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 246.231583
last_received_ts = 246.381119
last_seq = 2236
current_ts = 246.398254
current_received_ts = 246.547729
current_seq = 2246
count = 20
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 246.231583/2236, current 246.398254/2246: elapsed=166670.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 246.381577
last_received_ts = 246.381104
last_seq = 2245
current_ts = 246.548264
current_received_ts = 246.547714
current_seq = 2255
count = 20
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 246.381577/2245, current 246.548264/2255: elapsed=166688.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 246.398254
last_received_ts = 246.547729
last_seq = 2246
current_ts = 246.564941
current_received_ts = 246.714340
current_seq = 2256
count = 21
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 246.398254/2246, current 246.564941/2256: elapsed=166690.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 246.548264
last_received_ts = 246.547714
last_seq = 2255
current_ts = 246.714951
current_received_ts = 246.714310
current_seq = 2265
count = 21
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 246.548264/2255, current 246.714951/2265: elapsed=166678.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 246.564941
last_received_ts = 246.714340
last_seq = 2256
current_ts = 246.731613
current_received_ts = 246.881027
current_seq = 2266
count = 22
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 246.564941/2256, current 246.731613/2266: elapsed=166670.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 246.714951
last_received_ts = 246.714310
last_seq = 2265
current_ts = 246.881622
current_received_ts = 246.880981
current_seq = 2275
count = 22
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 246.714951/2265, current 246.881622/2275: elapsed=166678.0us expected=166676.3us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 246.731613
last_received_ts = 246.881027
last_seq = 2266
current_ts = 247.012619
current_received_ts = 247.162796
current_seq = 2280
count = 23
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 246.731613/2266, current 247.012619/2280: elapsed=281017.0us expected=233346.8us +- 1166.7us, error 20.4%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 246.731613/2266, current 247.012619/2280: elapsed=281017.0us expected=233346.8us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 246.881622
last_received_ts = 246.880981
last_seq = 2275
current_ts = 247.162628
current_received_ts = 247.162720
current_seq = 2289
count = 23
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 246.881622/2275, current 247.162628/2289: elapsed=281005.0us expected=233346.8us +- 1166.7us, error 20.4%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 246.881622/2275, current 247.162628/2289: elapsed=281005.0us expected=233346.8us
(kms_flip:3685) INFO: Event flip: expected 309, counted 240, passrate = 79.17%, encoder type 2
(kms_flip:3685) DEBUG: dropped frames, expected 309, counted 240, passrate = 79.17%, encoder type 2
(kms_flip:3685) INFO: Event vblank: expected 309, counted 240, passrate = 75.00%, encoder type 2
(kms_flip:3685) DEBUG: dropped frames, expected 309, counted 240, passrate = 75.00%, encoder type 2
(kms_flip:3685) DEBUG: Retrying after a hotplug event
(kms_flip:3685) DEBUG: No stale events found
(kms_flip:3685) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3685) INFO: Expected frametime: 16667us; measured 16667.1us +- 6.692us accuracy 0.12%
(kms_flip:3685) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 248.078308
current_received_ts = 248.227753
current_seq = 2311
count = 0
seq_step = 1
(kms_flip:3685) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 248.228317
current_received_ts = 248.227737
current_seq = 2320
count = 0
seq_step = 10
(kms_flip:3685) DEBUG: name = flip
last_ts = 248.078308
last_received_ts = 248.227753
last_seq = 2311
current_ts = 248.244980
current_received_ts = 248.394440
current_seq = 2321
count = 1
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 248.078308/2311, current 248.244980/2321: elapsed=166670.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 248.228317
last_received_ts = 248.227737
last_seq = 2320
current_ts = 248.394989
current_received_ts = 248.394379
current_seq = 2330
count = 1
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 248.228317/2320, current 248.394989/2330: elapsed=166671.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 248.244980
last_received_ts = 248.394440
last_seq = 2321
current_ts = 248.411652
current_received_ts = 248.487823
current_seq = 2331
count = 2
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 248.244980/2321, current 248.411652/2331: elapsed=166673.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 248.394989
last_received_ts = 248.394379
last_seq = 2330
current_ts = 248.478333
current_received_ts = 248.487808
current_seq = 2335
count = 2
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 2335, should be >= 2340
(kms_flip:3685) DEBUG: name = flip
last_ts = 248.411652
last_received_ts = 248.487823
last_seq = 2331
current_ts = 248.892380
current_received_ts = 249.041992
current_seq = 2339
count = 3
seq_step = 1
(kms_flip:3685) DEBUG: unexpected flip seq 2339, should be >= 2341
(kms_flip:3685) DEBUG: name = vblank
last_ts = 248.478333
last_received_ts = 248.487808
last_seq = 2335
current_ts = 249.042389
current_received_ts = 249.041977
current_seq = 2348
count = 3
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 248.478333/2335, current 249.042389/2348: elapsed=564057.0us expected=216672.6us +- 1083.4us, error 160.3%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 248.478333/2335, current 249.042389/2348: elapsed=564057.0us expected=216672.6us
(kms_flip:3685) DEBUG: name = flip
last_ts = 248.892380
last_received_ts = 249.041992
last_seq = 2339
current_ts = 249.660553
current_received_ts = 249.777695
current_seq = 2354
count = 4
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 248.892380/2339, current 249.660553/2354: elapsed=768176.0us expected=250006.9us +- 1250.0us, error 207.3%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 248.892380/2339, current 249.660553/2354: elapsed=768176.0us expected=250006.9us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 249.042389
last_received_ts = 249.041977
last_seq = 2348
current_ts = 249.777222
current_received_ts = 249.777634
current_seq = 2361
count = 4
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 249.042389/2348, current 249.777222/2361: elapsed=734833.0us expected=216672.6us +- 1083.4us, error 239.1%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 249.042389/2348, current 249.777222/2361: elapsed=734833.0us expected=216672.6us
(kms_flip:3685) DEBUG: name = flip
last_ts = 249.660553
last_received_ts = 249.777695
last_seq = 2354
current_ts = 249.892609
current_received_ts = 250.042786
current_seq = 2365
count = 5
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 249.660553/2354, current 249.892609/2365: elapsed=232045.0us expected=183338.4us +- 916.7us, error 26.6%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 249.660553/2354, current 249.892609/2365: elapsed=232045.0us expected=183338.4us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 249.777222
last_received_ts = 249.777634
last_seq = 2361
current_ts = 250.042618
current_received_ts = 250.042709
current_seq = 2374
count = 5
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 249.777222/2361, current 250.042618/2374: elapsed=265396.0us expected=216672.6us +- 1083.4us, error 22.5%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 249.777222/2361, current 250.042618/2374: elapsed=265396.0us expected=216672.6us
(kms_flip:3685) DEBUG: name = flip
last_ts = 249.892609
last_received_ts = 250.042786
last_seq = 2365
current_ts = 250.059280
current_received_ts = 250.209457
current_seq = 2375
count = 6
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 249.892609/2365, current 250.059280/2375: elapsed=166676.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 250.042618
last_received_ts = 250.042709
last_seq = 2374
current_ts = 250.209290
current_received_ts = 250.209366
current_seq = 2384
count = 6
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 250.042618/2374, current 250.209290/2384: elapsed=166667.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 250.059280
last_received_ts = 250.209457
last_seq = 2375
current_ts = 250.225967
current_received_ts = 250.376175
current_seq = 2385
count = 7
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 250.059280/2375, current 250.225967/2385: elapsed=166684.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 250.209290
last_received_ts = 250.209366
last_seq = 2384
current_ts = 250.375977
current_received_ts = 250.376099
current_seq = 2394
count = 7
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 250.209290/2384, current 250.375977/2394: elapsed=166686.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 250.225967
last_received_ts = 250.376175
last_seq = 2385
current_ts = 250.392639
current_received_ts = 250.542526
current_seq = 2395
count = 8
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 250.225967/2385, current 250.392639/2395: elapsed=166679.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 250.375977
last_received_ts = 250.376099
last_seq = 2394
current_ts = 250.542648
current_received_ts = 250.542450
current_seq = 2404
count = 8
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 250.375977/2394, current 250.542648/2404: elapsed=166680.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 250.392639
last_received_ts = 250.542526
last_seq = 2395
current_ts = 250.559311
current_received_ts = 250.709473
current_seq = 2405
count = 9
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 250.392639/2395, current 250.559311/2405: elapsed=166667.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 250.542648
last_received_ts = 250.542450
last_seq = 2404
current_ts = 250.709320
current_received_ts = 250.709381
current_seq = 2414
count = 9
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 250.542648/2404, current 250.709320/2414: elapsed=166664.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 250.559311
last_received_ts = 250.709473
last_seq = 2405
current_ts = 250.725983
current_received_ts = 250.875763
current_seq = 2415
count = 10
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 250.559311/2405, current 250.725983/2415: elapsed=166674.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 250.709320
last_received_ts = 250.709381
last_seq = 2414
current_ts = 250.875992
current_received_ts = 250.875702
current_seq = 2424
count = 10
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 250.709320/2414, current 250.875992/2424: elapsed=166676.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 250.725983
last_received_ts = 250.875763
last_seq = 2415
current_ts = 250.892670
current_received_ts = 251.042252
current_seq = 2425
count = 11
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 250.725983/2415, current 250.892670/2425: elapsed=166681.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 250.875992
last_received_ts = 250.875702
last_seq = 2424
current_ts = 251.042664
current_received_ts = 251.042236
current_seq = 2434
count = 11
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 250.875992/2424, current 251.042664/2434: elapsed=166677.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 250.892670
last_received_ts = 251.042252
last_seq = 2425
current_ts = 251.059341
current_received_ts = 251.209488
current_seq = 2435
count = 12
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 250.892670/2425, current 251.059341/2435: elapsed=166673.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 251.042664
last_received_ts = 251.042236
last_seq = 2434
current_ts = 251.209351
current_received_ts = 251.209412
current_seq = 2444
count = 12
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 251.042664/2434, current 251.209351/2444: elapsed=166679.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 251.059341
last_received_ts = 251.209488
last_seq = 2435
current_ts = 251.226013
current_received_ts = 251.376312
current_seq = 2445
count = 13
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 251.059341/2435, current 251.226013/2445: elapsed=166680.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 251.209351
last_received_ts = 251.209412
last_seq = 2444
current_ts = 251.376022
current_received_ts = 251.375977
current_seq = 2454
count = 13
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 251.209351/2444, current 251.376022/2454: elapsed=166677.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 251.226013
last_received_ts = 251.376312
last_seq = 2445
current_ts = 251.392700
current_received_ts = 251.542862
current_seq = 2455
count = 14
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 251.226013/2445, current 251.392700/2455: elapsed=166675.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 251.376022
last_received_ts = 251.375977
last_seq = 2454
current_ts = 251.542694
current_received_ts = 251.542786
current_seq = 2464
count = 14
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 251.376022/2454, current 251.542694/2464: elapsed=166677.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 251.392700
last_received_ts = 251.542862
last_seq = 2455
current_ts = 251.559372
current_received_ts = 251.709167
current_seq = 2465
count = 15
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 251.392700/2455, current 251.559372/2465: elapsed=166684.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 251.542694
last_received_ts = 251.542786
last_seq = 2464
current_ts = 251.709381
current_received_ts = 251.709091
current_seq = 2474
count = 15
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 251.542694/2464, current 251.709381/2474: elapsed=166682.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 251.559372
last_received_ts = 251.709167
last_seq = 2465
current_ts = 251.726044
current_received_ts = 251.875458
current_seq = 2475
count = 16
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 251.559372/2465, current 251.726044/2475: elapsed=166673.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 251.709381
last_received_ts = 251.709091
last_seq = 2474
current_ts = 251.876053
current_received_ts = 251.875412
current_seq = 2484
count = 16
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 251.709381/2474, current 251.876053/2484: elapsed=166669.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 251.726044
last_received_ts = 251.875458
last_seq = 2475
current_ts = 251.892715
current_received_ts = 251.942871
current_seq = 2485
count = 17
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 251.726044/2475, current 251.892715/2485: elapsed=166672.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 251.876053
last_received_ts = 251.875412
last_seq = 2484
current_ts = 251.942734
current_received_ts = 251.942841
current_seq = 2488
count = 17
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 2488, should be >= 2494
(kms_flip:3685) DEBUG: name = flip
last_ts = 251.892715
last_received_ts = 251.942871
last_seq = 2485
current_ts = 252.368729
current_received_ts = 252.518127
current_seq = 2492
count = 18
seq_step = 1
(kms_flip:3685) DEBUG: unexpected flip seq 2492, should be >= 2495
(kms_flip:3685) DEBUG: name = vblank
last_ts = 251.942734
last_received_ts = 251.942841
last_seq = 2488
current_ts = 252.518738
current_received_ts = 252.518112
current_seq = 2501
count = 18
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 251.942734/2488, current 252.518738/2501: elapsed=576007.0us expected=216672.6us +- 1083.4us, error 165.8%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 251.942734/2488, current 252.518738/2501: elapsed=576007.0us expected=216672.6us
(kms_flip:3685) DEBUG: name = flip
last_ts = 252.368729
last_received_ts = 252.518127
last_seq = 2492
current_ts = 252.535416
current_received_ts = 252.569336
current_seq = 2502
count = 19
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 252.368729/2492, current 252.535416/2502: elapsed=166682.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 252.518738
last_received_ts = 252.518112
last_seq = 2501
current_ts = 252.568741
current_received_ts = 252.569275
current_seq = 2504
count = 19
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 2504, should be >= 2511
(kms_flip:3685) DEBUG: name = flip
last_ts = 252.535416
last_received_ts = 252.569336
last_seq = 2502
current_ts = 252.696182
current_received_ts = 252.845947
current_seq = 2508
count = 20
seq_step = 1
(kms_flip:3685) DEBUG: unexpected flip seq 2508, should be >= 2512
(kms_flip:3685) DEBUG: name = vblank
last_ts = 252.568741
last_received_ts = 252.569275
last_seq = 2504
current_ts = 252.846207
current_received_ts = 252.845886
current_seq = 2517
count = 20
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 252.568741/2504, current 252.846207/2517: elapsed=277463.0us expected=216672.6us +- 1083.4us, error 28.1%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 252.568741/2504, current 252.846207/2517: elapsed=277463.0us expected=216672.6us
(kms_flip:3685) DEBUG: name = flip
last_ts = 252.696182
last_received_ts = 252.845947
last_seq = 2508
current_ts = 252.862869
current_received_ts = 253.012955
current_seq = 2518
count = 21
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 252.696182/2508, current 252.862869/2518: elapsed=166686.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 252.846207
last_received_ts = 252.845886
last_seq = 2517
current_ts = 253.012878
current_received_ts = 253.012878
current_seq = 2527
count = 21
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 252.846207/2517, current 253.012878/2527: elapsed=166676.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 252.862869
last_received_ts = 253.012955
last_seq = 2518
current_ts = 253.029541
current_received_ts = 253.179367
current_seq = 2528
count = 22
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 252.862869/2518, current 253.029541/2528: elapsed=166672.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 253.012878
last_received_ts = 253.012878
last_seq = 2527
current_ts = 253.179550
current_received_ts = 253.179306
current_seq = 2537
count = 22
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 253.012878/2527, current 253.179550/2537: elapsed=166666.0us expected=166671.2us +- 833.4us, error 0.0%
(kms_flip:3685) INFO: Event flip: expected 307, counted 230, passrate = 78.26%, encoder type 2
(kms_flip:3685) DEBUG: dropped frames, expected 307, counted 230, passrate = 78.26%, encoder type 2
(kms_flip:3685) INFO: Event vblank: expected 307, counted 230, passrate = 65.22%, encoder type 2
(kms_flip:3685) DEBUG: dropped frames, expected 307, counted 230, passrate = 65.22%, encoder type 2
(kms_flip:3685) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1721:
(kms_flip:3685) CRITICAL: Failed assertion: !retried
(kms_flip:3685) igt_core-INFO: Stack trace:
(kms_flip:3685) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:3685) igt_core-INFO:   #1 ../tests/kms_flip.c:1443 run_test_on_crtc_set()
(kms_flip:3685) igt_core-INFO:   #2 ../tests/kms_flip.c:2028 run_pair()
(kms_flip:3685) igt_core-INFO:   #3 ../tests/kms_flip.c:2192 __igt_unique____real_main2104()
(kms_flip:3685) igt_core-INFO:   #4 ../tests/kms_flip.c:2104 main()
(kms_flip:3685) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3685) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3685) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AC-DP2-HDMI-A3: FAIL (14.169s)
Starting dynamic subtest: AD-DP2-HDMI-A3
(kms_flip:3685) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1721:
(kms_flip:3685) CRITICAL: Failed assertion: !retried
Dynamic subtest AD-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:3685) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e553c99d0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e553c99d0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e553c99d0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e553c99d0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e553c99d0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e553c99d0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3685) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3685) DEBUG: No stale events found
(kms_flip:3685) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3685) INFO: Expected frametime: 16667us; measured 16667.9us +- 3.243us accuracy 0.06%
(kms_flip:3685) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 255.792923
current_received_ts = 255.942551
current_seq = 2679
count = 0
seq_step = 1
(kms_flip:3685) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 255.942932
current_received_ts = 255.942490
current_seq = 2688
count = 0
seq_step = 10
(kms_flip:3685) DEBUG: name = flip
last_ts = 255.792923
last_received_ts = 255.942551
last_seq = 2679
current_ts = 255.959595
current_received_ts = 256.109222
current_seq = 2689
count = 1
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 255.792923/2679, current 255.959595/2689: elapsed=166679.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 255.942932
last_received_ts = 255.942490
last_seq = 2688
current_ts = 256.109619
current_received_ts = 256.109161
current_seq = 2698
count = 1
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 255.942932/2688, current 256.109619/2698: elapsed=166676.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 255.959595
last_received_ts = 256.109222
last_seq = 2689
current_ts = 256.126282
current_received_ts = 256.275909
current_seq = 2699
count = 2
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 255.959595/2689, current 256.126282/2699: elapsed=166686.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 256.109619
last_received_ts = 256.109161
last_seq = 2698
current_ts = 256.276276
current_received_ts = 256.275818
current_seq = 2708
count = 2
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 256.109619/2698, current 256.276276/2708: elapsed=166672.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 256.126282
last_received_ts = 256.275909
last_seq = 2699
current_ts = 256.292969
current_received_ts = 256.442963
current_seq = 2709
count = 3
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 256.126282/2699, current 256.292969/2709: elapsed=166673.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 256.276276
last_received_ts = 256.275818
last_seq = 2708
current_ts = 256.442963
current_received_ts = 256.442871
current_seq = 2718
count = 3
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 256.276276/2708, current 256.442963/2718: elapsed=166682.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 256.292969
last_received_ts = 256.442963
last_seq = 2709
current_ts = 256.459625
current_received_ts = 256.609711
current_seq = 2719
count = 4
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 256.292969/2709, current 256.459625/2719: elapsed=166671.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 256.442963
last_received_ts = 256.442871
last_seq = 2718
current_ts = 256.609650
current_received_ts = 256.609619
current_seq = 2728
count = 4
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 256.442963/2718, current 256.609650/2728: elapsed=166678.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 256.459625
last_received_ts = 256.609711
last_seq = 2719
current_ts = 256.626312
current_received_ts = 256.776367
current_seq = 2729
count = 5
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 256.459625/2719, current 256.626312/2729: elapsed=166679.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 256.609650
last_received_ts = 256.609619
last_seq = 2728
current_ts = 256.776337
current_received_ts = 256.776306
current_seq = 2738
count = 5
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 256.609650/2728, current 256.776337/2738: elapsed=166679.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 256.626312
last_received_ts = 256.776367
last_seq = 2729
current_ts = 256.792999
current_received_ts = 256.943085
current_seq = 2739
count = 6
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 256.626312/2729, current 256.792999/2739: elapsed=166680.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 256.776337
last_received_ts = 256.776306
last_seq = 2738
current_ts = 256.942993
current_received_ts = 256.942963
current_seq = 2748
count = 6
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 256.776337/2738, current 256.942993/2748: elapsed=166676.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 256.792999
last_received_ts = 256.943085
last_seq = 2739
current_ts = 256.959656
current_received_ts = 257.109772
current_seq = 2749
count = 7
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 256.792999/2739, current 256.959656/2749: elapsed=166670.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 256.942993
last_received_ts = 256.942963
last_seq = 2748
current_ts = 257.109680
current_received_ts = 257.109711
current_seq = 2758
count = 7
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 256.942993/2748, current 257.109680/2758: elapsed=166680.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 256.959656
last_received_ts = 257.109772
last_seq = 2749
current_ts = 257.126343
current_received_ts = 257.275879
current_seq = 2759
count = 8
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 256.959656/2749, current 257.126343/2759: elapsed=166687.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 257.109680
last_received_ts = 257.109711
last_seq = 2758
current_ts = 257.276367
current_received_ts = 257.275848
current_seq = 2768
count = 8
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 257.109680/2758, current 257.276367/2768: elapsed=166677.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 257.126343
last_received_ts = 257.275879
last_seq = 2759
current_ts = 257.292999
current_received_ts = 257.442535
current_seq = 2769
count = 9
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 257.126343/2759, current 257.292999/2769: elapsed=166666.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 257.276367
last_received_ts = 257.275848
last_seq = 2768
current_ts = 257.443024
current_received_ts = 257.442535
current_seq = 2778
count = 9
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 257.276367/2768, current 257.443024/2778: elapsed=166664.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 257.292999
last_received_ts = 257.442535
last_seq = 2769
current_ts = 257.459686
current_received_ts = 257.609375
current_seq = 2779
count = 10
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 257.292999/2769, current 257.459686/2779: elapsed=166678.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 257.443024
last_received_ts = 257.442535
last_seq = 2778
current_ts = 257.609711
current_received_ts = 257.609375
current_seq = 2788
count = 10
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 257.443024/2778, current 257.609711/2788: elapsed=166685.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 257.459686
last_received_ts = 257.609375
last_seq = 2779
current_ts = 257.626373
current_received_ts = 257.760101
current_seq = 2789
count = 11
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 257.459686/2779, current 257.626373/2789: elapsed=166686.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 257.609711
last_received_ts = 257.609375
last_seq = 2788
current_ts = 257.759705
current_received_ts = 257.760010
current_seq = 2797
count = 11
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 2797, should be >= 2798
(kms_flip:3685) DEBUG: name = flip
last_ts = 257.626373
last_received_ts = 257.760101
last_seq = 2789
current_ts = 258.332886
current_received_ts = 258.482605
current_seq = 2801
count = 12
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 257.626373/2789, current 258.332886/2801: elapsed=706507.0us expected=200014.5us +- 1000.1us, error 253.2%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 257.626373/2789, current 258.332886/2801: elapsed=706507.0us expected=200014.5us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 257.759705
last_received_ts = 257.760010
last_seq = 2797
current_ts = 258.482910
current_received_ts = 258.482513
current_seq = 2810
count = 12
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 257.759705/2797, current 258.482910/2810: elapsed=723191.0us expected=216682.4us +- 1083.4us, error 233.8%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 257.759705/2797, current 258.482910/2810: elapsed=723191.0us expected=216682.4us
(kms_flip:3685) DEBUG: name = flip
last_ts = 258.332886
last_received_ts = 258.482605
last_seq = 2801
current_ts = 258.499573
current_received_ts = 258.649597
current_seq = 2811
count = 13
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 258.332886/2801, current 258.499573/2811: elapsed=166678.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 258.482910
last_received_ts = 258.482513
last_seq = 2810
current_ts = 258.649567
current_received_ts = 258.649536
current_seq = 2820
count = 13
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 258.482910/2810, current 258.649567/2820: elapsed=166666.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 258.499573
last_received_ts = 258.649597
last_seq = 2811
current_ts = 258.666260
current_received_ts = 258.816284
current_seq = 2821
count = 14
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 258.499573/2811, current 258.666260/2821: elapsed=166684.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 258.649567
last_received_ts = 258.649536
last_seq = 2820
current_ts = 258.816254
current_received_ts = 258.816223
current_seq = 2830
count = 14
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 258.649567/2820, current 258.816254/2830: elapsed=166678.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 258.666260
last_received_ts = 258.816284
last_seq = 2821
current_ts = 258.832916
current_received_ts = 258.982941
current_seq = 2831
count = 15
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 258.666260/2821, current 258.832916/2831: elapsed=166666.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 258.816254
last_received_ts = 258.816223
last_seq = 2830
current_ts = 258.982941
current_received_ts = 258.982880
current_seq = 2840
count = 15
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 258.816254/2830, current 258.982941/2840: elapsed=166681.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 258.832916
last_received_ts = 258.982941
last_seq = 2831
current_ts = 258.999603
current_received_ts = 259.149628
current_seq = 2841
count = 16
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 258.832916/2831, current 258.999603/2841: elapsed=166686.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 258.982941
last_received_ts = 258.982880
last_seq = 2840
current_ts = 259.149597
current_received_ts = 259.149567
current_seq = 2850
count = 16
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 258.982941/2840, current 259.149597/2850: elapsed=166674.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 258.999603
last_received_ts = 259.149628
last_seq = 2841
current_ts = 259.166290
current_received_ts = 259.316284
current_seq = 2851
count = 17
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 258.999603/2841, current 259.166290/2851: elapsed=166679.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 259.149597
last_received_ts = 259.149567
last_seq = 2850
current_ts = 259.316284
current_received_ts = 259.316223
current_seq = 2860
count = 17
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 259.149597/2850, current 259.316284/2860: elapsed=166672.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 259.166290
last_received_ts = 259.316284
last_seq = 2851
current_ts = 259.332947
current_received_ts = 259.482635
current_seq = 2861
count = 18
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 259.166290/2851, current 259.332947/2861: elapsed=166668.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 259.316284
last_received_ts = 259.316223
last_seq = 2860
current_ts = 259.482971
current_received_ts = 259.482605
current_seq = 2870
count = 18
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 259.316284/2860, current 259.482971/2870: elapsed=166685.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 259.332947
last_received_ts = 259.482635
last_seq = 2861
current_ts = 260.051727
current_received_ts = 260.101929
current_seq = 2875
count = 19
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 259.332947/2861, current 260.051727/2875: elapsed=718774.0us expected=233350.2us +- 1166.8us, error 208.0%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 259.332947/2861, current 260.051727/2875: elapsed=718774.0us expected=233350.2us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 259.482971
last_received_ts = 259.482605
last_seq = 2870
current_ts = 260.101746
current_received_ts = 260.101868
current_seq = 2878
count = 19
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 2878, should be >= 2880
(kms_flip:3685) DEBUG: name = flip
last_ts = 260.051727
last_received_ts = 260.101929
last_seq = 2875
current_ts = 260.227081
current_received_ts = 260.377167
current_seq = 2882
count = 20
seq_step = 1
(kms_flip:3685) DEBUG: unexpected flip seq 2882, should be >= 2885
(kms_flip:3685) DEBUG: name = vblank
last_ts = 260.101746
last_received_ts = 260.101868
last_seq = 2878
current_ts = 260.377106
current_received_ts = 260.377075
current_seq = 2891
count = 20
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 260.101746/2878, current 260.377106/2891: elapsed=275364.0us expected=216682.4us +- 1083.4us, error 27.1%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 260.101746/2878, current 260.377106/2891: elapsed=275364.0us expected=216682.4us
(kms_flip:3685) DEBUG: name = flip
last_ts = 260.227081
last_received_ts = 260.377167
last_seq = 2882
current_ts = 260.393768
current_received_ts = 260.543854
current_seq = 2892
count = 21
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 260.227081/2882, current 260.393768/2892: elapsed=166673.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 260.377106
last_received_ts = 260.377075
last_seq = 2891
current_ts = 260.543762
current_received_ts = 260.543762
current_seq = 2901
count = 21
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 260.377106/2891, current 260.543762/2901: elapsed=166673.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 260.393768
last_received_ts = 260.543854
last_seq = 2892
current_ts = 260.560425
current_received_ts = 260.710632
current_seq = 2902
count = 22
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 260.393768/2892, current 260.560425/2902: elapsed=166682.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 260.543762
last_received_ts = 260.543762
last_seq = 2901
current_ts = 260.710449
current_received_ts = 260.710541
current_seq = 2911
count = 22
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 260.543762/2901, current 260.710449/2911: elapsed=166684.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 260.560425
last_received_ts = 260.710632
last_seq = 2902
current_ts = 260.727112
current_received_ts = 260.877167
current_seq = 2912
count = 23
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 260.560425/2902, current 260.727112/2912: elapsed=166674.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 260.710449
last_received_ts = 260.710541
last_seq = 2911
current_ts = 260.877136
current_received_ts = 260.877106
current_seq = 2921
count = 23
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 260.710449/2911, current 260.877136/2921: elapsed=166678.0us expected=166678.8us +- 833.4us, error 0.0%
(kms_flip:3685) INFO: Event flip: expected 305, counted 240, passrate = 87.50%, encoder type 2
(kms_flip:3685) INFO: Event vblank: expected 305, counted 240, passrate = 83.33%, encoder type 2
(kms_flip:3685) DEBUG: dropped frames, expected 305, counted 240, passrate = 83.33%, encoder type 2
(kms_flip:3685) DEBUG: Retrying after a hotplug event
(kms_flip:3685) DEBUG: No stale events found
(kms_flip:3685) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3685) INFO: Expected frametime: 16667us; measured 16667.9us +- 6.797us accuracy 0.12%
(kms_flip:3685) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 261.496979
current_received_ts = 261.646667
current_seq = 2946
count = 0
seq_step = 1
(kms_flip:3685) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 261.646973
current_received_ts = 261.646606
current_seq = 2955
count = 0
seq_step = 10
(kms_flip:3685) DEBUG: name = flip
last_ts = 261.496979
last_received_ts = 261.646667
last_seq = 2946
current_ts = 261.663635
current_received_ts = 261.813232
current_seq = 2956
count = 1
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 261.496979/2946, current 261.663635/2956: elapsed=166674.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 261.646973
last_received_ts = 261.646606
last_seq = 2955
current_ts = 261.813660
current_received_ts = 261.813202
current_seq = 2965
count = 1
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 261.646973/2955, current 261.813660/2965: elapsed=166676.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 261.663635
last_received_ts = 261.813232
last_seq = 2956
current_ts = 261.830322
current_received_ts = 261.980286
current_seq = 2966
count = 2
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 261.663635/2956, current 261.830322/2966: elapsed=166670.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 261.813660
last_received_ts = 261.813202
last_seq = 2965
current_ts = 261.980316
current_received_ts = 261.980225
current_seq = 2975
count = 2
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 261.813660/2965, current 261.980316/2975: elapsed=166669.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 261.830322
last_received_ts = 261.980286
last_seq = 2966
current_ts = 261.997009
current_received_ts = 262.147064
current_seq = 2976
count = 3
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 261.830322/2966, current 261.997009/2976: elapsed=166680.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 261.980316
last_received_ts = 261.980225
last_seq = 2975
current_ts = 262.147003
current_received_ts = 262.146912
current_seq = 2985
count = 3
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 261.980316/2975, current 262.147003/2985: elapsed=166681.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 261.997009
last_received_ts = 262.147064
last_seq = 2976
current_ts = 262.163696
current_received_ts = 262.313690
current_seq = 2986
count = 4
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 261.997009/2976, current 262.163696/2986: elapsed=166684.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 262.147003
last_received_ts = 262.146912
last_seq = 2985
current_ts = 262.313690
current_received_ts = 262.313629
current_seq = 2995
count = 4
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 262.147003/2985, current 262.313690/2995: elapsed=166682.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 262.163696
last_received_ts = 262.313690
last_seq = 2986
current_ts = 262.330353
current_received_ts = 262.480316
current_seq = 2996
count = 5
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 262.163696/2986, current 262.330353/2996: elapsed=166677.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 262.313690
last_received_ts = 262.313629
last_seq = 2995
current_ts = 262.480377
current_received_ts = 262.480225
current_seq = 3005
count = 5
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 262.313690/2995, current 262.480377/3005: elapsed=166678.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 262.330353
last_received_ts = 262.480316
last_seq = 2996
current_ts = 262.497040
current_received_ts = 262.647003
current_seq = 3006
count = 6
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 262.330353/2996, current 262.497040/3006: elapsed=166668.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 262.480377
last_received_ts = 262.480225
last_seq = 3005
current_ts = 262.647034
current_received_ts = 262.646912
current_seq = 3015
count = 6
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 262.480377/3005, current 262.647034/3015: elapsed=166672.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 262.497040
last_received_ts = 262.647003
last_seq = 3006
current_ts = 262.663696
current_received_ts = 262.813751
current_seq = 3016
count = 7
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 262.497040/3006, current 262.663696/3016: elapsed=166675.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 262.647034
last_received_ts = 262.646912
last_seq = 3015
current_ts = 262.813721
current_received_ts = 262.813690
current_seq = 3025
count = 7
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 262.647034/3015, current 262.813721/3025: elapsed=166676.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 262.663696
last_received_ts = 262.813751
last_seq = 3016
current_ts = 262.830383
current_received_ts = 262.979828
current_seq = 3026
count = 8
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 262.663696/3016, current 262.830383/3026: elapsed=166683.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 262.813721
last_received_ts = 262.813690
last_seq = 3025
current_ts = 262.980377
current_received_ts = 262.979828
current_seq = 3035
count = 8
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 262.813721/3025, current 262.980377/3035: elapsed=166670.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 262.830383
last_received_ts = 262.979828
last_seq = 3026
current_ts = 262.997070
current_received_ts = 263.146545
current_seq = 3036
count = 9
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 262.830383/3026, current 262.997070/3036: elapsed=166679.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 262.980377
last_received_ts = 262.979828
last_seq = 3035
current_ts = 263.147064
current_received_ts = 263.146515
current_seq = 3045
count = 9
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 262.980377/3035, current 263.147064/3045: elapsed=166684.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 262.997070
last_received_ts = 263.146545
last_seq = 3036
current_ts = 263.163727
current_received_ts = 263.313324
current_seq = 3046
count = 10
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 262.997070/3036, current 263.163727/3046: elapsed=166670.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 263.147064
last_received_ts = 263.146515
last_seq = 3045
current_ts = 263.313751
current_received_ts = 263.313293
current_seq = 3055
count = 10
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 263.147064/3045, current 263.313751/3055: elapsed=166680.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 263.163727
last_received_ts = 263.313324
last_seq = 3046
current_ts = 263.330414
current_received_ts = 263.430634
current_seq = 3056
count = 11
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 263.163727/3046, current 263.330414/3056: elapsed=166673.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 263.313751
last_received_ts = 263.313293
last_seq = 3055
current_ts = 263.430420
current_received_ts = 263.430573
current_seq = 3062
count = 11
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 3062, should be >= 3065
(kms_flip:3685) DEBUG: name = flip
last_ts = 263.330414
last_received_ts = 263.430634
last_seq = 3056
current_ts = 263.556213
current_received_ts = 263.705750
current_seq = 3066
count = 12
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 263.330414/3056, current 263.556213/3066: elapsed=225792.0us expected=166679.4us +- 833.4us, error 35.5%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 263.330414/3056, current 263.556213/3066: elapsed=225792.0us expected=166679.4us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 263.430420
last_received_ts = 263.430573
last_seq = 3062
current_ts = 263.706207
current_received_ts = 263.705688
current_seq = 3075
count = 12
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 263.430420/3062, current 263.706207/3075: elapsed=275787.0us expected=216683.2us +- 1083.4us, error 27.3%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 263.430420/3062, current 263.706207/3075: elapsed=275787.0us expected=216683.2us
(kms_flip:3685) DEBUG: name = flip
last_ts = 263.556213
last_received_ts = 263.705750
last_seq = 3066
current_ts = 263.722900
current_received_ts = 263.872314
current_seq = 3076
count = 13
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 263.556213/3066, current 263.722900/3076: elapsed=166685.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 263.706207
last_received_ts = 263.705688
last_seq = 3075
current_ts = 263.872894
current_received_ts = 263.872314
current_seq = 3085
count = 13
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 263.706207/3075, current 263.872894/3085: elapsed=166684.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 263.722900
last_received_ts = 263.872314
last_seq = 3076
current_ts = 263.889557
current_received_ts = 264.039062
current_seq = 3086
count = 14
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 263.722900/3076, current 263.889557/3086: elapsed=166665.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 263.872894
last_received_ts = 263.872314
last_seq = 3085
current_ts = 264.039551
current_received_ts = 264.039062
current_seq = 3095
count = 14
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 263.872894/3085, current 264.039551/3095: elapsed=166670.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 263.889557
last_received_ts = 264.039062
last_seq = 3086
current_ts = 264.056213
current_received_ts = 264.205627
current_seq = 3096
count = 15
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 263.889557/3086, current 264.056213/3096: elapsed=166677.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 264.039551
last_received_ts = 264.039062
last_seq = 3095
current_ts = 264.206238
current_received_ts = 264.205597
current_seq = 3105
count = 15
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 264.039551/3095, current 264.206238/3105: elapsed=166682.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 264.056213
last_received_ts = 264.205627
last_seq = 3096
current_ts = 264.222900
current_received_ts = 264.306458
current_seq = 3106
count = 16
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 264.056213/3096, current 264.222900/3106: elapsed=166687.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 264.206238
last_received_ts = 264.205597
last_seq = 3105
current_ts = 264.306244
current_received_ts = 264.306427
current_seq = 3111
count = 16
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 3111, should be >= 3115
(kms_flip:3685) DEBUG: name = flip
last_ts = 264.222900
last_received_ts = 264.306458
last_seq = 3106
current_ts = 264.419739
current_received_ts = 264.569275
current_seq = 3115
count = 17
seq_step = 1
(kms_flip:3685) DEBUG: unexpected flip seq 3115, should be >= 3116
(kms_flip:3685) DEBUG: name = vblank
last_ts = 264.306244
last_received_ts = 264.306427
last_seq = 3111
current_ts = 264.569733
current_received_ts = 264.569244
current_seq = 3124
count = 17
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 264.306244/3111, current 264.569733/3124: elapsed=263486.0us expected=216683.2us +- 1083.4us, error 21.6%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 264.306244/3111, current 264.569733/3124: elapsed=263486.0us expected=216683.2us
(kms_flip:3685) DEBUG: name = flip
last_ts = 264.419739
last_received_ts = 264.569275
last_seq = 3115
current_ts = 264.586395
current_received_ts = 264.735901
current_seq = 3125
count = 18
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 264.419739/3115, current 264.586395/3125: elapsed=166678.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 264.569733
last_received_ts = 264.569244
last_seq = 3124
current_ts = 264.736420
current_received_ts = 264.735901
current_seq = 3134
count = 18
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 264.569733/3124, current 264.736420/3134: elapsed=166685.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 264.586395
last_received_ts = 264.735901
last_seq = 3125
current_ts = 264.753082
current_received_ts = 264.902527
current_seq = 3135
count = 19
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 264.586395/3125, current 264.753082/3135: elapsed=166683.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 264.736420
last_received_ts = 264.735901
last_seq = 3134
current_ts = 264.903107
current_received_ts = 264.902496
current_seq = 3144
count = 19
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 264.736420/3134, current 264.903107/3144: elapsed=166681.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 264.753082
last_received_ts = 264.902527
last_seq = 3135
current_ts = 264.919769
current_received_ts = 265.069305
current_seq = 3145
count = 20
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 264.753082/3135, current 264.919769/3145: elapsed=166669.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 264.903107
last_received_ts = 264.902496
last_seq = 3144
current_ts = 265.069763
current_received_ts = 265.069275
current_seq = 3154
count = 20
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 264.903107/3144, current 265.069763/3154: elapsed=166665.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 264.919769
last_received_ts = 265.069305
last_seq = 3145
current_ts = 265.086426
current_received_ts = 265.120087
current_seq = 3155
count = 21
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 264.919769/3145, current 265.086426/3155: elapsed=166676.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 265.069763
last_received_ts = 265.069275
last_seq = 3154
current_ts = 265.119781
current_received_ts = 265.120026
current_seq = 3157
count = 21
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 3157, should be >= 3164
(kms_flip:3685) DEBUG: name = flip
last_ts = 265.086426
last_received_ts = 265.120087
last_seq = 3155
current_ts = 265.545105
current_received_ts = 265.694641
current_seq = 3161
count = 22
seq_step = 1
(kms_flip:3685) DEBUG: unexpected flip seq 3161, should be >= 3165
(kms_flip:3685) DEBUG: name = vblank
last_ts = 265.119781
last_received_ts = 265.120026
last_seq = 3157
current_ts = 265.695129
current_received_ts = 265.694580
current_seq = 3170
count = 22
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 265.119781/3157, current 265.695129/3170: elapsed=575354.0us expected=216683.2us +- 1083.4us, error 165.5%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 265.119781/3157, current 265.695129/3170: elapsed=575354.0us expected=216683.2us
(kms_flip:3685) DEBUG: name = flip
last_ts = 265.545105
last_received_ts = 265.694641
last_seq = 3161
current_ts = 265.711792
current_received_ts = 265.828674
current_seq = 3171
count = 23
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 265.545105/3161, current 265.711792/3171: elapsed=166680.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 265.695129
last_received_ts = 265.694580
last_seq = 3170
current_ts = 265.828461
current_received_ts = 265.828613
current_seq = 3178
count = 23
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 3178, should be >= 3180
(kms_flip:3685) DEBUG: name = flip
last_ts = 265.711792
last_received_ts = 265.828674
last_seq = 3171
current_ts = 265.946320
current_received_ts = 266.095856
current_seq = 3182
count = 24
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 265.711792/3171, current 265.946320/3182: elapsed=234532.0us expected=183347.3us +- 916.7us, error 27.9%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 265.711792/3171, current 265.946320/3182: elapsed=234532.0us expected=183347.3us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 265.828461
last_received_ts = 265.828613
last_seq = 3178
current_ts = 266.096344
current_received_ts = 266.095825
current_seq = 3191
count = 24
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 265.828461/3178, current 266.096344/3191: elapsed=267862.0us expected=216683.2us +- 1083.4us, error 23.6%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 265.828461/3178, current 266.096344/3191: elapsed=267862.0us expected=216683.2us
(kms_flip:3685) DEBUG: name = flip
last_ts = 265.946320
last_received_ts = 266.095856
last_seq = 3182
current_ts = 266.113007
current_received_ts = 266.263123
current_seq = 3192
count = 25
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 265.946320/3182, current 266.113007/3192: elapsed=166667.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 266.096344
last_received_ts = 266.095825
last_seq = 3191
current_ts = 266.263000
current_received_ts = 266.263000
current_seq = 3201
count = 25
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 266.096344/3191, current 266.263000/3201: elapsed=166677.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 266.113007
last_received_ts = 266.263123
last_seq = 3192
current_ts = 266.279694
current_received_ts = 266.429749
current_seq = 3202
count = 26
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 266.113007/3192, current 266.279694/3202: elapsed=166690.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 266.263000
last_received_ts = 266.263000
last_seq = 3201
current_ts = 266.429688
current_received_ts = 266.429657
current_seq = 3211
count = 26
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 266.263000/3201, current 266.429688/3211: elapsed=166681.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 266.279694
last_received_ts = 266.429749
last_seq = 3202
current_ts = 266.446350
current_received_ts = 266.596344
current_seq = 3212
count = 27
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 266.279694/3202, current 266.446350/3212: elapsed=166673.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 266.429688
last_received_ts = 266.429657
last_seq = 3211
current_ts = 266.596375
current_received_ts = 266.596252
current_seq = 3221
count = 27
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 266.429688/3211, current 266.596375/3221: elapsed=166677.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) INFO: Event flip: expected 306, counted 280, passrate = 85.71%, encoder type 2
(kms_flip:3685) INFO: Event vblank: expected 306, counted 280, passrate = 71.43%, encoder type 2
(kms_flip:3685) DEBUG: dropped frames, expected 306, counted 280, passrate = 71.43%, encoder type 2
(kms_flip:3685) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1721:
(kms_flip:3685) CRITICAL: Failed assertion: !retried
(kms_flip:3685) igt_core-INFO: Stack trace:
(kms_flip:3685) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:3685) igt_core-INFO:   #1 ../tests/kms_flip.c:1443 run_test_on_crtc_set()
(kms_flip:3685) igt_core-INFO:   #2 ../tests/kms_flip.c:2028 run_pair()
(kms_flip:3685) igt_core-INFO:   #3 ../tests/kms_flip.c:2192 __igt_unique____real_main2104()
(kms_flip:3685) igt_core-INFO:   #4 ../tests/kms_flip.c:2104 main()
(kms_flip:3685) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3685) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3685) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AD-DP2-HDMI-A3: FAIL (12.916s)
Starting dynamic subtest: BC-DP2-HDMI-A3
Dynamic subtest BC-DP2-HDMI-A3: SUCCESS (11.976s)
Starting dynamic subtest: BD-DP2-HDMI-A3
Dynamic subtest BD-DP2-HDMI-A3: SUCCESS (9.585s)
Starting dynamic subtest: CD-DP2-HDMI-A3
(kms_flip:3685) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1721:
(kms_flip:3685) CRITICAL: Failed assertion: !retried
Dynamic subtest CD-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:3685) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000009, size=0)
(kms_flip:3685) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:3685) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:3685) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=7, pitch=7680)
(kms_flip:3685) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3685) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x100000000000009, size=0)
(kms_flip:3685) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:3685) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
(kms_flip:3685) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=8, pitch=7680)
(kms_flip:3685) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3685) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e55465c50, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e55465c50, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e55472d00, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e55472d00, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e5545aac0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e5545aac0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e55472d00, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) intel_allocator_simple-DEBUG: <ial: 0x563e55472d00, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3685) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3685) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3685) DEBUG: No stale events found
(kms_flip:3685) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3685) INFO: Expected frametime: 16667us; measured 16667.9us +- 6.952us accuracy 0.13%
(kms_flip:3685) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 290.289032
current_received_ts = 290.439148
current_seq = 1610
count = 0
seq_step = 1
(kms_flip:3685) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 290.439026
current_received_ts = 290.439087
current_seq = 1619
count = 0
seq_step = 10
(kms_flip:3685) DEBUG: name = flip
last_ts = 290.289032
last_received_ts = 290.439148
last_seq = 1610
current_ts = 290.455688
current_received_ts = 290.605499
current_seq = 1620
count = 1
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 290.289032/1610, current 290.455688/1620: elapsed=166672.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 290.439026
last_received_ts = 290.439087
last_seq = 1619
current_ts = 290.605713
current_received_ts = 290.605408
current_seq = 1629
count = 1
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 290.439026/1619, current 290.605713/1629: elapsed=166674.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 290.455688
last_received_ts = 290.605499
last_seq = 1620
current_ts = 290.622375
current_received_ts = 290.772491
current_seq = 1630
count = 2
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 290.455688/1620, current 290.622375/1630: elapsed=166680.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 290.605713
last_received_ts = 290.605408
last_seq = 1629
current_ts = 290.772369
current_received_ts = 290.772400
current_seq = 1639
count = 2
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 290.605713/1629, current 290.772369/1639: elapsed=166678.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 290.622375
last_received_ts = 290.772491
last_seq = 1630
current_ts = 290.789062
current_received_ts = 290.938751
current_seq = 1640
count = 3
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 290.622375/1630, current 290.789062/1640: elapsed=166681.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 290.772369
last_received_ts = 290.772400
last_seq = 1639
current_ts = 290.939056
current_received_ts = 290.938690
current_seq = 1649
count = 3
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 290.772369/1639, current 290.939056/1649: elapsed=166685.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 290.789062
last_received_ts = 290.938751
last_seq = 1640
current_ts = 290.955719
current_received_ts = 291.105865
current_seq = 1650
count = 4
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 290.789062/1640, current 290.955719/1650: elapsed=166667.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 290.939056
last_received_ts = 290.938690
last_seq = 1649
current_ts = 291.105743
current_received_ts = 291.105774
current_seq = 1659
count = 4
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 290.939056/1649, current 291.105743/1659: elapsed=166670.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 290.955719
last_received_ts = 291.105865
last_seq = 1650
current_ts = 291.122406
current_received_ts = 291.272156
current_seq = 1660
count = 5
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 290.955719/1650, current 291.122406/1660: elapsed=166686.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 291.105743
last_received_ts = 291.105774
last_seq = 1659
current_ts = 291.272400
current_received_ts = 291.272095
current_seq = 1669
count = 5
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 291.105743/1659, current 291.272400/1669: elapsed=166675.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 291.122406
last_received_ts = 291.272156
last_seq = 1660
current_ts = 291.289062
current_received_ts = 291.439178
current_seq = 1670
count = 6
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 291.122406/1660, current 291.289062/1670: elapsed=166669.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 291.272400
last_received_ts = 291.272095
last_seq = 1669
current_ts = 291.439087
current_received_ts = 291.439087
current_seq = 1679
count = 6
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 291.272400/1669, current 291.439087/1679: elapsed=166679.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 291.289062
last_received_ts = 291.439178
last_seq = 1670
current_ts = 291.455750
current_received_ts = 291.605774
current_seq = 1680
count = 7
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 291.289062/1670, current 291.455750/1680: elapsed=166682.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 291.439087
last_received_ts = 291.439087
last_seq = 1679
current_ts = 291.605774
current_received_ts = 291.605682
current_seq = 1689
count = 7
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 291.439087/1679, current 291.605774/1689: elapsed=166682.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 291.455750
last_received_ts = 291.605774
last_seq = 1680
current_ts = 291.622437
current_received_ts = 291.772156
current_seq = 1690
count = 8
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 291.455750/1680, current 291.622437/1690: elapsed=166669.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 291.605774
last_received_ts = 291.605682
last_seq = 1689
current_ts = 291.772430
current_received_ts = 291.772034
current_seq = 1699
count = 8
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 291.605774/1689, current 291.772430/1699: elapsed=166667.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 291.622437
last_received_ts = 291.772156
last_seq = 1690
current_ts = 291.789093
current_received_ts = 291.938721
current_seq = 1700
count = 9
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 291.622437/1690, current 291.789093/1700: elapsed=166683.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 291.772430
last_received_ts = 291.772034
last_seq = 1699
current_ts = 291.939117
current_received_ts = 291.938660
current_seq = 1709
count = 9
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 291.772430/1699, current 291.939117/1709: elapsed=166677.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 291.789093
last_received_ts = 291.938721
last_seq = 1700
current_ts = 291.955780
current_received_ts = 292.105804
current_seq = 1710
count = 10
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 291.789093/1700, current 291.955780/1710: elapsed=166679.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 291.939117
last_received_ts = 291.938660
last_seq = 1709
current_ts = 292.105804
current_received_ts = 292.105743
current_seq = 1719
count = 10
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 291.939117/1709, current 292.105804/1719: elapsed=166683.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 291.955780
last_received_ts = 292.105804
last_seq = 1710
current_ts = 292.122467
current_received_ts = 292.272461
current_seq = 1720
count = 11
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 291.955780/1710, current 292.122467/1720: elapsed=166676.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 292.105804
last_received_ts = 292.105743
last_seq = 1719
current_ts = 292.272461
current_received_ts = 292.272369
current_seq = 1729
count = 11
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 292.105804/1719, current 292.272461/1729: elapsed=166672.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 292.122467
last_received_ts = 292.272461
last_seq = 1720
current_ts = 292.289124
current_received_ts = 292.438507
current_seq = 1730
count = 12
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 292.122467/1720, current 292.289124/1730: elapsed=166674.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 292.272461
last_received_ts = 292.272369
last_seq = 1729
current_ts = 292.439148
current_received_ts = 292.438507
current_seq = 1739
count = 12
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 292.272461/1729, current 292.439148/1739: elapsed=166681.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 292.289124
last_received_ts = 292.438507
last_seq = 1730
current_ts = 292.455811
current_received_ts = 292.605347
current_seq = 1740
count = 13
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 292.289124/1730, current 292.455811/1740: elapsed=166677.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 292.439148
last_received_ts = 292.438507
last_seq = 1739
current_ts = 292.605804
current_received_ts = 292.605316
current_seq = 1749
count = 13
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 292.439148/1739, current 292.605804/1749: elapsed=166666.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 292.455811
last_received_ts = 292.605347
last_seq = 1740
current_ts = 292.622498
current_received_ts = 292.771973
current_seq = 1750
count = 14
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 292.455811/1740, current 292.622498/1750: elapsed=166672.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 292.605804
last_received_ts = 292.605316
last_seq = 1749
current_ts = 292.772491
current_received_ts = 292.771942
current_seq = 1759
count = 14
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 292.605804/1749, current 292.772491/1759: elapsed=166687.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 292.622498
last_received_ts = 292.771973
last_seq = 1750
current_ts = 292.789185
current_received_ts = 292.938751
current_seq = 1760
count = 15
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 292.622498/1750, current 292.789185/1760: elapsed=166686.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 292.772491
last_received_ts = 292.771942
last_seq = 1759
current_ts = 292.939178
current_received_ts = 292.938690
current_seq = 1769
count = 15
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 292.772491/1759, current 292.939178/1769: elapsed=166670.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 292.789185
last_received_ts = 292.938751
last_seq = 1760
current_ts = 293.376373
current_received_ts = 293.525940
current_seq = 1774
count = 16
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 292.789185/1760, current 293.376373/1774: elapsed=587194.0us expected=233351.1us +- 1166.8us, error 151.6%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 292.789185/1760, current 293.376373/1774: elapsed=587194.0us expected=233351.1us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 292.939178
last_received_ts = 292.938690
last_seq = 1769
current_ts = 293.526367
current_received_ts = 293.525909
current_seq = 1783
count = 16
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 292.939178/1769, current 293.526367/1783: elapsed=587196.0us expected=233351.1us +- 1166.8us, error 151.6%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 292.939178/1769, current 293.526367/1783: elapsed=587196.0us expected=233351.1us
(kms_flip:3685) DEBUG: name = flip
last_ts = 293.376373
last_received_ts = 293.525940
last_seq = 1774
current_ts = 293.543030
current_received_ts = 293.643341
current_seq = 1784
count = 17
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 293.376373/1774, current 293.543030/1784: elapsed=166666.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 293.526367
last_received_ts = 293.525909
last_seq = 1783
current_ts = 293.643036
current_received_ts = 293.643311
current_seq = 1790
count = 17
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 1790, should be >= 1793
(kms_flip:3685) DEBUG: name = flip
last_ts = 293.543030
last_received_ts = 293.643341
last_seq = 1784
current_ts = 294.067169
current_received_ts = 294.216797
current_seq = 1794
count = 18
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 293.543030/1784, current 294.067169/1794: elapsed=524144.0us expected=166679.4us +- 833.4us, error 214.5%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 293.543030/1784, current 294.067169/1794: elapsed=524144.0us expected=166679.4us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 293.643036
last_received_ts = 293.643311
last_seq = 1790
current_ts = 294.217194
current_received_ts = 294.216766
current_seq = 1803
count = 18
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 293.643036/1790, current 294.217194/1803: elapsed=574134.0us expected=216683.2us +- 1083.4us, error 165.0%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 293.643036/1790, current 294.217194/1803: elapsed=574134.0us expected=216683.2us
(kms_flip:3685) DEBUG: name = flip
last_ts = 294.067169
last_received_ts = 294.216797
last_seq = 1794
current_ts = 294.378174
current_received_ts = 294.527832
current_seq = 1809
count = 19
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 294.067169/1794, current 294.378174/1809: elapsed=310983.0us expected=250019.1us +- 1250.1us, error 24.4%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 294.067169/1794, current 294.378174/1809: elapsed=310983.0us expected=250019.1us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 294.217194
last_received_ts = 294.216766
last_seq = 1803
current_ts = 294.528168
current_received_ts = 294.527771
current_seq = 1818
count = 19
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 294.217194/1803, current 294.528168/1818: elapsed=310992.0us expected=250019.1us +- 1250.1us, error 24.4%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 294.217194/1803, current 294.528168/1818: elapsed=310992.0us expected=250019.1us
(kms_flip:3685) DEBUG: name = flip
last_ts = 294.378174
last_received_ts = 294.527832
last_seq = 1809
current_ts = 294.544830
current_received_ts = 294.694550
current_seq = 1819
count = 20
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 294.378174/1809, current 294.544830/1819: elapsed=166677.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 294.528168
last_received_ts = 294.527771
last_seq = 1818
current_ts = 294.694855
current_received_ts = 294.694489
current_seq = 1828
count = 20
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 294.528168/1818, current 294.694855/1828: elapsed=166677.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 294.544830
last_received_ts = 294.694550
last_seq = 1819
current_ts = 294.711517
current_received_ts = 294.861572
current_seq = 1829
count = 21
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 294.544830/1819, current 294.711517/1829: elapsed=166681.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 294.694855
last_received_ts = 294.694489
last_seq = 1828
current_ts = 294.861511
current_received_ts = 294.861511
current_seq = 1838
count = 21
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 294.694855/1828, current 294.861511/1838: elapsed=166674.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 294.711517
last_received_ts = 294.861572
last_seq = 1829
current_ts = 294.878204
current_received_ts = 295.027924
current_seq = 1839
count = 22
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 294.711517/1829, current 294.878204/1839: elapsed=166683.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 294.861511
last_received_ts = 294.861511
last_seq = 1838
current_ts = 295.028198
current_received_ts = 295.027863
current_seq = 1848
count = 22
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 294.861511/1838, current 295.028198/1848: elapsed=166677.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 294.878204
last_received_ts = 295.027924
last_seq = 1839
current_ts = 295.044861
current_received_ts = 295.194611
current_seq = 1849
count = 23
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 294.878204/1839, current 295.044861/1849: elapsed=166675.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 295.028198
last_received_ts = 295.027863
last_seq = 1848
current_ts = 295.194885
current_received_ts = 295.194550
current_seq = 1858
count = 23
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 295.028198/1848, current 295.194885/1858: elapsed=166676.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 295.044861
last_received_ts = 295.194611
last_seq = 1849
current_ts = 295.211548
current_received_ts = 295.361633
current_seq = 1859
count = 24
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 295.044861/1849, current 295.211548/1859: elapsed=166665.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 295.194885
last_received_ts = 295.194550
last_seq = 1858
current_ts = 295.361542
current_received_ts = 295.361542
current_seq = 1868
count = 24
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 295.194885/1858, current 295.361542/1868: elapsed=166677.0us expected=166679.4us +- 833.4us, error 0.0%
(kms_flip:3685) INFO: Event flip: expected 305, counted 250, passrate = 88.00%, encoder type 2
(kms_flip:3685) INFO: Event vblank: expected 305, counted 250, passrate = 84.00%, encoder type 2
(kms_flip:3685) DEBUG: dropped frames, expected 305, counted 250, passrate = 84.00%, encoder type 2
(kms_flip:3685) DEBUG: Retrying after a hotplug event
(kms_flip:3685) DEBUG: No stale events found
(kms_flip:3685) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3685) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3685) INFO: Expected frametime: 16667us; measured 16668.4us +- 5.365us accuracy 0.10%
(kms_flip:3685) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 296.060913
current_received_ts = 296.210693
current_seq = 1893
count = 0
seq_step = 1
(kms_flip:3685) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 296.210938
current_received_ts = 296.210632
current_seq = 1902
count = 0
seq_step = 10
(kms_flip:3685) DEBUG: name = flip
last_ts = 296.060913
last_received_ts = 296.210693
last_seq = 1893
current_ts = 296.227600
current_received_ts = 296.377441
current_seq = 1903
count = 1
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 296.060913/1893, current 296.227600/1903: elapsed=166671.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 296.210938
last_received_ts = 296.210632
last_seq = 1902
current_ts = 296.377594
current_received_ts = 296.377350
current_seq = 1912
count = 1
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 296.210938/1902, current 296.377594/1912: elapsed=166678.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 296.227600
last_received_ts = 296.377441
last_seq = 1903
current_ts = 296.394257
current_received_ts = 296.544098
current_seq = 1913
count = 2
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 296.227600/1903, current 296.394257/1913: elapsed=166677.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 296.377594
last_received_ts = 296.377350
last_seq = 1912
current_ts = 296.544281
current_received_ts = 296.543976
current_seq = 1922
count = 2
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 296.377594/1912, current 296.544281/1922: elapsed=166669.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 296.394257
last_received_ts = 296.544098
last_seq = 1913
current_ts = 296.560944
current_received_ts = 296.710419
current_seq = 1923
count = 3
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 296.394257/1913, current 296.560944/1923: elapsed=166682.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 296.544281
last_received_ts = 296.543976
last_seq = 1922
current_ts = 296.710938
current_received_ts = 296.710388
current_seq = 1932
count = 3
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 296.544281/1922, current 296.710938/1932: elapsed=166676.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 296.560944
last_received_ts = 296.710419
last_seq = 1923
current_ts = 296.727631
current_received_ts = 296.811493
current_seq = 1933
count = 4
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 296.560944/1923, current 296.727631/1933: elapsed=166669.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 296.710938
last_received_ts = 296.710388
last_seq = 1932
current_ts = 296.810944
current_received_ts = 296.811462
current_seq = 1938
count = 4
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 1938, should be >= 1942
(kms_flip:3685) DEBUG: name = flip
last_ts = 296.727631
last_received_ts = 296.811493
last_seq = 1933
current_ts = 297.367645
current_received_ts = 297.417999
current_seq = 1942
count = 5
seq_step = 1
(kms_flip:3685) DEBUG: unexpected flip seq 1942, should be >= 1943
(kms_flip:3685) DEBUG: name = vblank
last_ts = 296.810944
last_received_ts = 296.811462
last_seq = 1938
current_ts = 297.417633
current_received_ts = 297.417908
current_seq = 1945
count = 5
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 1945, should be >= 1948
(kms_flip:3685) DEBUG: name = flip
last_ts = 297.367645
last_received_ts = 297.417999
last_seq = 1942
current_ts = 297.989929
current_received_ts = 298.106873
current_seq = 1949
count = 6
seq_step = 1
(kms_flip:3685) DEBUG: unexpected flip seq 1949, should be >= 1952
(kms_flip:3685) DEBUG: name = vblank
last_ts = 297.417633
last_received_ts = 297.417908
last_seq = 1945
current_ts = 298.106598
current_received_ts = 298.106812
current_seq = 1956
count = 6
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 297.417633/1945, current 298.106598/1956: elapsed=688958.0us expected=183352.1us +- 916.8us, error 275.8%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 297.417633/1945, current 298.106598/1956: elapsed=688958.0us expected=183352.1us
(kms_flip:3685) DEBUG: name = flip
last_ts = 297.989929
last_received_ts = 298.106873
last_seq = 1949
current_ts = 298.516205
current_received_ts = 298.666168
current_seq = 1960
count = 7
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 297.989929/1949, current 298.516205/1960: elapsed=526290.0us expected=183352.1us +- 916.8us, error 187.0%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 297.989929/1949, current 298.516205/1960: elapsed=526290.0us expected=183352.1us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 298.106598
last_received_ts = 298.106812
last_seq = 1956
current_ts = 298.666229
current_received_ts = 298.666138
current_seq = 1969
count = 7
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 298.106598/1956, current 298.666229/1969: elapsed=559631.0us expected=216688.9us +- 1083.4us, error 158.3%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 298.106598/1956, current 298.666229/1969: elapsed=559631.0us expected=216688.9us
(kms_flip:3685) DEBUG: name = flip
last_ts = 298.516205
last_received_ts = 298.666168
last_seq = 1960
current_ts = 298.682892
current_received_ts = 298.799683
current_seq = 1970
count = 8
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 298.516205/1960, current 298.682892/1970: elapsed=166682.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 298.666229
last_received_ts = 298.666138
last_seq = 1969
current_ts = 298.799561
current_received_ts = 298.799622
current_seq = 1977
count = 8
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 1977, should be >= 1979
(kms_flip:3685) DEBUG: name = flip
last_ts = 298.682892
last_received_ts = 298.799683
last_seq = 1970
current_ts = 299.355652
current_received_ts = 299.406464
current_seq = 1981
count = 9
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 298.682892/1970, current 299.355652/1981: elapsed=672757.0us expected=183352.1us +- 916.8us, error 266.9%
(kms_flip:3685) DEBUG: inconsistent flip ts/seq: last 298.682892/1970, current 299.355652/1981: elapsed=672757.0us expected=183352.1us
(kms_flip:3685) DEBUG: name = vblank
last_ts = 298.799561
last_received_ts = 298.799622
last_seq = 1977
current_ts = 299.405640
current_received_ts = 299.406403
current_seq = 1984
count = 9
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 1984, should be >= 1987
(kms_flip:3685) DEBUG: name = flip
last_ts = 299.355652
last_received_ts = 299.406464
last_seq = 1981
current_ts = 299.976624
current_received_ts = 300.126770
current_seq = 1988
count = 10
seq_step = 1
(kms_flip:3685) DEBUG: unexpected flip seq 1988, should be >= 1991
(kms_flip:3685) DEBUG: name = vblank
last_ts = 299.405640
last_received_ts = 299.406403
last_seq = 1984
current_ts = 300.126648
current_received_ts = 300.126678
current_seq = 1997
count = 10
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 299.405640/1984, current 300.126648/1997: elapsed=720990.0us expected=216688.9us +- 1083.4us, error 232.7%
(kms_flip:3685) DEBUG: inconsistent vblank ts/seq: last 299.405640/1984, current 300.126648/1997: elapsed=720990.0us expected=216688.9us
(kms_flip:3685) DEBUG: name = flip
last_ts = 299.976624
last_received_ts = 300.126770
last_seq = 1988
current_ts = 300.143311
current_received_ts = 300.293396
current_seq = 1998
count = 11
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 299.976624/1988, current 300.143311/1998: elapsed=166670.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 300.126648
last_received_ts = 300.126678
last_seq = 1997
current_ts = 300.293304
current_received_ts = 300.293335
current_seq = 2007
count = 11
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 300.126648/1997, current 300.293304/2007: elapsed=166664.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 300.143311
last_received_ts = 300.293396
last_seq = 1998
current_ts = 300.309967
current_received_ts = 300.460144
current_seq = 2008
count = 12
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 300.143311/1998, current 300.309967/2008: elapsed=166681.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 300.293304
last_received_ts = 300.293335
last_seq = 2007
current_ts = 300.459991
current_received_ts = 300.460083
current_seq = 2017
count = 12
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 300.293304/2007, current 300.459991/2017: elapsed=166684.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 300.309967
last_received_ts = 300.460144
last_seq = 2008
current_ts = 300.476654
current_received_ts = 300.626770
current_seq = 2018
count = 13
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 300.309967/2008, current 300.476654/2018: elapsed=166675.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 300.459991
last_received_ts = 300.460083
last_seq = 2017
current_ts = 300.626678
current_received_ts = 300.626709
current_seq = 2027
count = 13
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 300.459991/2017, current 300.626678/2027: elapsed=166675.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 300.476654
last_received_ts = 300.626770
last_seq = 2018
current_ts = 300.643341
current_received_ts = 300.793457
current_seq = 2028
count = 14
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 300.476654/2018, current 300.643341/2028: elapsed=166677.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 300.626678
last_received_ts = 300.626709
last_seq = 2027
current_ts = 300.793335
current_received_ts = 300.793365
current_seq = 2037
count = 14
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 300.626678/2027, current 300.793335/2037: elapsed=166673.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 300.643341
last_received_ts = 300.793457
last_seq = 2028
current_ts = 300.810028
current_received_ts = 300.960144
current_seq = 2038
count = 15
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 300.643341/2028, current 300.810028/2038: elapsed=166683.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 300.793335
last_received_ts = 300.793365
last_seq = 2037
current_ts = 300.960022
current_received_ts = 300.960052
current_seq = 2047
count = 15
seq_step = 10
(kms_flip:3685) DEBUG: vblank ts/seq: last 300.793335/2037, current 300.960022/2047: elapsed=166679.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = flip
last_ts = 300.810028
last_received_ts = 300.960144
last_seq = 2038
current_ts = 300.976685
current_received_ts = 301.110626
current_seq = 2048
count = 16
seq_step = 1
(kms_flip:3685) DEBUG: flip ts/seq: last 300.810028/2038, current 300.976685/2048: elapsed=166675.0us expected=166683.8us +- 833.4us, error 0.0%
(kms_flip:3685) DEBUG: name = vblank
last_ts = 300.960022
last_received_ts = 300.960052
last_seq = 2047
current_ts = 301.110016
current_received_ts = 301.110046
current_seq = 2056
count = 16
seq_step = 10
(kms_flip:3685) DEBUG: unexpected vblank seq 2056, should be >= 2057
(kms_flip:3685) INFO: Event flip: expected 303, counted 170, passrate = 70.59%, encoder type 2
(kms_flip:3685) DEBUG: dropped frames, expected 303, counted 170, passrate = 70.59%, encoder type 2
(kms_flip:3685) INFO: Event vblank: expected 303, counted 170, passrate = 52.94%, encoder type 2
(kms_flip:3685) DEBUG: dropped frames, expected 303, counted 170, passrate = 52.94%, encoder type 2
(kms_flip:3685) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1721:
(kms_flip:3685) CRITICAL: Failed assertion: !retried
(kms_flip:3685) igt_core-INFO: Stack trace:
(kms_flip:3685) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:3685) igt_core-INFO:   #1 ../tests/kms_flip.c:1443 run_test_on_crtc_set()
(kms_flip:3685) igt_core-INFO:   #2 ../tests/kms_flip.c:2028 run_pair()
(kms_flip:3685) igt_core-INFO:   #3 ../tests/kms_flip.c:2192 __igt_unique____real_main2104()
(kms_flip:3685) igt_core-INFO:   #4 ../tests/kms_flip.c:2104 main()
(kms_flip:3685) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3685) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3685) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest CD-DP2-HDMI-A3: FAIL (12.820s)
Subtest 2x-flip-vs-blocking-wf-vblank: FAIL (74.906s)
(kms_flip:3685) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2352:
(kms_flip:3685) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:3685) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:3685) igt_kms-CRITICAL: DPMS property not found on 527