igt@kms_flip@(2x-)flip-vs-expired-vblank(-interruptible) subtests - fail - Failed assertion: gettime_us() - start < 500|Failed assertion: end - start < 500
Submitted by Martin Peres @mupuf
Assigned to Intel GFX Bugs mailing list
Link to original bug (#105363)
Description
(kms_flip:7832) CRITICAL: Test assertion failure function run_test_step, file kms_flip.c:709:
(kms_flip:7832) CRITICAL: Failed assertion: gettime_us() - start < 500
(kms_flip:7832) CRITICAL: Last errno: 25, Inappropriate ioctl for device
Subtest flip-vs-expired-vblank failed.
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3874/shard-snb3/igt@kms_flip@flip-vs-expired-vblank.html
- Show closed items
Activity
-
Newest first Oldest first
-
Show all activity Show comments only Show history only
- Bugzilla Migration User added CI feature: display/Other platform: ALL priority::high severity::normal + 1 deleted label
added CI feature: display/Other platform: ALL priority::high severity::normal + 1 deleted label
LAKSHMINARAYANA VUDUM@l4kshmi
said:Platform is set as ALL as this failure occurs in ALL machines.
Martin Peres@mupuf
said:Also happening in shards, bumping the priority!
Mika Kahola said:It seems that we exceed the timeout when switching to test another pipe i.e. from pipe A to pipe B
flip-vs-expired-vblank-interruptible on pipe A, connector HDMI-A-1: PASSED
(kms_flip:7192) INFO: Beginning flip-vs-expired-vblank-interruptible on pipe B, connector HDMI-A-1
(kms_flip:7192) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:7192) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:7192) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:7192) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:7192) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:7192) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:7192) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_flip:7192) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_flip:7192) igt_kms-INFO: 1920x1080 60 1920 2008 2052 2200 1080 1083 1088 1125 0x9 0x48 148500
(kms_flip:7192) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 1611.736816
current_received_ts = 1611.736206
current_seq = 65053
count = 0
seq_step = 1
(kms_flip:7192) DEBUG: name = flip
The last_ts is initialized as 0. We grab the current_ts which is within normal range. However, the difference between these two values exceed the test limit of 500. Arkadiusz Hiler@ivyl
said:The test is making sure that blocking wait on a expired vblank (that has already
happened, so the current_seq == requested_seq) should be "immediate", i.e. taking
no longer than 500us.
This tests fails in all its variants, 2x, interruptible, non-interruptible.
500us seems like a plenty of time, but I have especially bad intuition when
it comes to time scales.
I would advise extending logging to that we igt_debug() the time it takes for a
successful and failed wait, so we can inspect the time scale, and confirm that
500us is good enough. Another culprit may be the method of getting the current
time and type casting done along the way.
Reading both the kernel handler for the IOCTL and libdrm wrapper I have no idea
where we could waste time other than some wonky OS scheduling / context
switching.
User impact: hard to tell, without more information on the failed waits, but
should be no more than "medium", assuming they are not taking forever. Simon Ser@emersion
said:Posted a patch to improve logging: https://patchwork.freedesktop.org/patch/313695/
CI Bug Log said:The CI Bug Log issue associated to this bug has been updated.
New filters associated
* all machines: igt@kms_flip@(2x-)flip-vs-expired-vblank(-interruptible) - Failed assertion: end - start < 500
(No new failures associated) Simon Ser@emersion
said:commit 15ad664534413628f06c0f172aac11598bfdb895
Author: Simon Ser simon.ser@intel.com
Date: Fri Jun 14 13:52:23 2019 +0300
tests/kms_flip: improve logging when timing out
Signed-off-by: Simon Ser simon.ser@intel.com
Bugzilla: https://bugs.freedesktop.org/show_bug.cgi?id=105363
Reviewed-by: Arkadiusz Hiler arkadiusz.hiler@intel.com Simon Ser@emersion
said:(kms_flip:1523) DEBUG: Vblank took 78us
(kms_flip:1523) DEBUG: Vblank took 225us
(kms_flip:1523) DEBUG: Vblank took 95us
(kms_flip:1523) DEBUG: Vblank took 202us
(kms_flip:1523) DEBUG: Vblank took 78us
(kms_flip:1523) DEBUG: Vblank took 77us
(kms_flip:1523) DEBUG: Vblank took 47us
(kms_flip:1523) DEBUG: Vblank took 78us
(kms_flip:1523) DEBUG: Vblank took 77us
(kms_flip:1523) DEBUG: Vblank took 80us
(kms_flip:1523) DEBUG: Vblank took 79us
(kms_flip:1523) DEBUG: Vblank took 78us
(kms_flip:1523) DEBUG: Vblank took 61us
(kms_flip:1523) DEBUG: Vblank took 78us
(kms_flip:1523) DEBUG: Vblank took 80us
(kms_flip:1523) DEBUG: Vblank took 525us
(kms_flip:1523) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:698:
(kms_flip:1523) CRITICAL: Failed assertion: end - start < 500 Arkadiusz Hiler@ivyl
said:Few notes:
- The message could be improved. It seems to suggest that this is interval between vblanks instead of the time it takes doing a wait on expired one
2. Going through recent logs the time is usually ~25us with occasional spikes to ~150us. And there are the outliers which we fail on:
(kms_flip:1816) DEBUG: Vblank took 1456us
(kms_flip:5124) DEBUG: Vblank took 1088us
(kms_flip:1373) DEBUG: Vblank took 501us
(kms_flip:2150) DEBUG: Vblank took 842us
(kms_flip:5198) DEBUG: Vblank took 3301us
Still no idea what may cause this. It seems to be too much of a lag even for very unfavourable scheduling. The only locking that happens on the call path is in drm_vblank_get() which takes on a few spinlocks. I believe it's worth investigating.
3ms of delay for 16ms frames (60fps) is a lot.- The message could be improved. It seems to suggest that this is interval between vblanks instead of the time it takes doing a wait on expired one
srinivasan.s@intel.com said:Based on my free time, would try to look into this issue
- Reporter
A CI Bug Log filter associated to this bug has been updated by Lakshmi Vudum:
Description: all machines: igt@kms_flip@(2x-)flip-vs-expired-vblank(-interruptible) - Failed assertion: end - start < 500
Equivalent query: runconfig_tag IS IN ["DRM-TIP"] AND ((testsuite_name = "IGT" AND test_name IS IN ["igt@kms_flip@2x-flip-vs-expired-vblank", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible", "igt@kms_flip@flip-vs-expired-vblank", "igt@kms_flip@flip-vs-expired-vblank-interruptible"])) AND ((testsuite_name = "IGT" AND status_name IS IN ["fail", "dmesg-fail"])) AND stderr ~= 'Failed assertion: end - start < 500'
New failures caught by the filter:
- Developer
Not seen on TGL lately. Removing TGL from Platforms.
- Ankit Nautiyal removed platform: TGL label
removed platform: TGL label
- Reporter
A CI Bug Log filter associated to this bug has been updated by Lakshmi Vudum:
Description: all machines: igt@kms_flip@(2x-)flip-vs-expired-vblank(-interruptible) - Failed assertion: end - start < 500
Equivalent query: runconfig_tag IS IN ["DRM-TIP"] AND ((testsuite_name = "IGT" AND test_name IS IN ["igt@kms_flip@2x-flip-vs-expired-vblank", "igt@kms_flip@2xflip-vs-expired-vblank-interruptible@a-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank-interruptible", "igt@kms_flip@flip-vs-expired-vblank", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible"])) AND ((testsuite_name = "IGT" AND status_name IS IN ["fail", "dmesg-fail"])) AND stderr ~= 'Failed assertion: end - start < 500'
New failures caught by the filter:
- Reporter
A CI Bug Log filter associated to this bug has been updated by Lakshmi Vudum:
Description: all machines: igt@kms_flip@(2x-)flip-vs-expired-vblank(-interruptible) - Failed assertion: end - start < 500
Equivalent query: runconfig_tag IS IN ["DRM-TIP"] AND ((testsuite_name = "IGT" AND test_name IS IN ["igt@kms_flip@2x-flip-vs-expired-vblank@ac-vga1-hdmi-a1", "igt@kms_flip@2x-flip-vs-expired-vblank@bc-hdmi-a1-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank@b-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank@a-hdmi-a2", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible@ab-vga1-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@c-vga1", "igt@kms_flip@flip-vs-expired-vblank-interruptible", "igt@kms_flip@flip-vs-expired-vblank@a-edp1", "igt@kms_flip@flip-vs-expired-vblank@c-vga1", "igt@kms_flip@flip-vs-expired-vblank@c-dp1", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible@bc-vga1-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@c-hdmi-a1", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible@ac-vga1-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@a-vga1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@a-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank-interruptible@b-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@d-edp1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@b-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank-interruptible@c-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank@b-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@a-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank@b-vga1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@a-dp1", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible", "igt@kms_flip@flip-vs-expired-vblank@a-vga1", "igt@kms_flip@2x-flip-vs-expired-vblank", "igt@kms_flip@flip-vs-expired-vblank-interruptible@b-vga1", "igt@kms_flip@flip-vs-expired-vblank@a-dp1", "igt@kms_flip@flip-vs-expired-vblank@b-dp1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@b-edp1", "igt@kms_flip@flip-vs-expired-vblank@c-hdmi-a2", "igt@kms_flip@2x-flip-vs-expired-vblank@ac-hdmi-a1-hdmi-a2", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible@ab-hdmi-a1-hdmi-a2", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible@ac-hdmi-a1-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank-interruptible@b-dp1", "igt@kms_flip@flip-vs-expired-vblank@b-edp1", "igt@kms_flip@2x-flip-vs-expired-vblank@bc-vga1-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@c-dp1", "igt@kms_flip@flip-vs-expired-vblank@d-edp1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@a-edp1", "igt@kms_flip@flip-vs-expired-vblank@c-hdmi-a1", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible@bc-hdmi-a1-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank", "igt@kms_flip@flip-vs-expired-vblank@c-edp1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@c-edp1", "igt@kms_flip@2x-flip-vs-expired-vblank@ab-hdmi-a1-hdmi-a2", "igt@kms_flip@2x-flip-vs-expired-vblank@ab-vga1-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank@a-hdmi-a1"])) AND ((testsuite_name = "IGT" AND status_name IS IN ["fail", "dmesg-fail"])) AND stderr ~= 'Failed assertion: end - start < 500'
New failures caught by the filter:
- Reporter
A CI Bug Log filter associated to this bug has been updated by Lakshmi Vudum:
Description: all machines: igt@kms_flip@(2x-)flip-vs-expired-vblank(-interruptible) - Failed assertion: end - start < 500
Equivalent query: runconfig_tag IS IN ["DRM-TIP"] AND ((testsuite_name = "IGT" AND test_name IS IN ["igt@kms_flip@2x-flip-vs-expired-vblank@ac-vga1-hdmi-a1", "igt@kms_flip@2x-flip-vs-expired-vblank@bc-hdmi-a1-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank@b-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank@a-hdmi-a2", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible@ab-vga1-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@c-vga1", "igt@kms_flip@flip-vs-expired-vblank-interruptible", "igt@kms_flip@flip-vs-expired-vblank@a-edp1", "igt@kms_flip@flip-vs-expired-vblank@c-vga1", "igt@kms_flip@flip-vs-expired-vblank@c-dp1", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible@bc-vga1-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@c-hdmi-a1", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible@ac-vga1-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@a-vga1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@a-dsi1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@a-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank-interruptible@b-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@d-edp1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@b-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank-interruptible@c-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank@b-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@a-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank@b-vga1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@a-dp1", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible", "igt@kms_flip@flip-vs-expired-vblank@a-vga1", "igt@kms_flip@2x-flip-vs-expired-vblank", "igt@kms_flip@flip-vs-expired-vblank-interruptible@b-vga1", "igt@kms_flip@flip-vs-expired-vblank@a-dp1", "igt@kms_flip@flip-vs-expired-vblank@b-dp1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@b-edp1", "igt@kms_flip@flip-vs-expired-vblank@c-hdmi-a2", "igt@kms_flip@2x-flip-vs-expired-vblank@ac-hdmi-a1-hdmi-a2", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible@ab-hdmi-a1-hdmi-a2", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible@ac-hdmi-a1-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank-interruptible@b-dp1", "igt@kms_flip@flip-vs-expired-vblank@b-edp1", "igt@kms_flip@2x-flip-vs-expired-vblank@bc-vga1-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@c-dp1", "igt@kms_flip@flip-vs-expired-vblank@d-edp1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@a-edp1", "igt@kms_flip@flip-vs-expired-vblank@c-hdmi-a1", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible@bc-hdmi-a1-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank", "igt@kms_flip@flip-vs-expired-vblank@c-edp1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@c-edp1", "igt@kms_flip@2x-flip-vs-expired-vblank@ab-hdmi-a1-hdmi-a2", "igt@kms_flip@2x-flip-vs-expired-vblank@ab-vga1-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank@a-hdmi-a1"])) AND ((testsuite_name = "IGT" AND status_name IS IN ["fail", "dmesg-fail"])) AND stderr ~= 'Failed assertion: end - start < 500'
New failures caught by the filter:
- Reporter
A CI Bug Log filter associated to this bug has been updated by Lakshmi Vudum:
Description: all machines: igt@kms_flip@(2x-)flip-vs-expired-vblank(-interruptible) - Failed assertion: end - start < 500
Equivalent query: runconfig_tag IS IN ["DRM-TIP"] AND ((testsuite_name = "IGT" AND test_name IS IN ["igt@kms_flip@2x-flip-vs-expired-vblank@ac-vga1-hdmi-a1", "igt@kms_flip@2x-flip-vs-expired-vblank@bc-hdmi-a1-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank@b-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank@a-hdmi-a2", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible@ab-vga1-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@c-vga1", "igt@kms_flip@flip-vs-expired-vblank-interruptible", "igt@kms_flip@flip-vs-expired-vblank@a-edp1", "igt@kms_flip@flip-vs-expired-vblank@c-vga1", "igt@kms_flip@flip-vs-expired-vblank@c-dp1", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible@bc-vga1-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@c-hdmi-a1", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible@ac-vga1-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@a-vga1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@a-dsi1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@a-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank-interruptible@b-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@d-edp1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@b-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank@b-dsi1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@c-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank@b-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@a-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank@b-vga1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@a-dp1", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible", "igt@kms_flip@flip-vs-expired-vblank@a-vga1", "igt@kms_flip@2x-flip-vs-expired-vblank", "igt@kms_flip@flip-vs-expired-vblank-interruptible@b-vga1", "igt@kms_flip@flip-vs-expired-vblank@a-dp1", "igt@kms_flip@flip-vs-expired-vblank@b-dp1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@b-edp1", "igt@kms_flip@flip-vs-expired-vblank@c-hdmi-a2", "igt@kms_flip@2x-flip-vs-expired-vblank@ac-hdmi-a1-hdmi-a2", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible@ab-hdmi-a1-hdmi-a2", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible@ac-hdmi-a1-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank-interruptible@b-dp1", "igt@kms_flip@flip-vs-expired-vblank@b-edp1", "igt@kms_flip@2x-flip-vs-expired-vblank@bc-vga1-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@c-dp1", "igt@kms_flip@flip-vs-expired-vblank@d-edp1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@a-edp1", "igt@kms_flip@flip-vs-expired-vblank@c-hdmi-a1", "igt@kms_flip@2x-flip-vs-expired-vblank-interruptible@bc-hdmi-a1-hdmi-a2", "igt@kms_flip@flip-vs-expired-vblank", "igt@kms_flip@flip-vs-expired-vblank@c-edp1", "igt@kms_flip@flip-vs-expired-vblank-interruptible@c-edp1", "igt@kms_flip@2x-flip-vs-expired-vblank@ab-hdmi-a1-hdmi-a2", "igt@kms_flip@2x-flip-vs-expired-vblank@ab-vga1-hdmi-a1", "igt@kms_flip@flip-vs-expired-vblank@a-hdmi-a1"])) AND ((testsuite_name = "IGT" AND status_name IS IN ["fail", "dmesg-fail"])) AND stderr ~= 'Failed assertion: end - start < 500'
New failures caught by the filter:
- Ankit Nautiyal added priority::low label and removed priority::high label
added priority::low label and removed priority::high label