| Summary: | [BDW] kms_flip / vblank-vs-suspend-interruptible is failing | ||||||
|---|---|---|---|---|---|---|---|
| Product: | DRI | Reporter: | cprigent <christophe.prigent> | ||||
| Component: | DRM/Intel | Assignee: | cprigent <christophe.prigent> | ||||
| Status: | CLOSED FIXED | QA Contact: | Intel GFX Bugs mailing list <intel-gfx-bugs> | ||||
| Severity: | blocker | ||||||
| Priority: | highest | CC: | dorota.czaplejewicz, intel-gfx-bugs, nutello, tomeu | ||||
| Version: | unspecified | Keywords: | bisect_pending, regression | ||||
| Hardware: | Other | ||||||
| OS: | All | ||||||
| Whiteboard: | |||||||
| i915 platform: | BDW | i915 features: | display/Other | ||||
| Attachments: |
|
||||||
|
Description
cprigent
2016-10-17 11:31:53 UTC
Assigned to Humberto to provide logs and bisect result I'm not able to find a good commit for this test. This is my config: Software Config: =============================================== Component : drm tag : libdrm-2.4.70-14-g0659558 commit : 0659558 Component : cairo tag : 1.15.2 commit : db8a7f1 Component : intel-gpu-tools tag : intel-gpu-tools-1.16-30-g32b2021 commit : 32b2021 Kernel: 4.8.0-rc8 aab15c2 from http://cgit.freedesktop.org/drm-intel/ commit aab15c274da587bcab19376d2caa9d6626440335 Author: Jani Nikula <jani.nikula@intel.com> Date: Mon Sep 26 15:11:53 2016 +0300 drm-intel-nightly: 2016y-09m-26d-12h-11m-33s UTC integration manifest libdrm-2.4.70-14 0659558 from git://anongit.freedesktop.org/mesa/drm mesa: mesa-12.0.0 8b06176 from git://anongit.freedesktop.org/mesa/mesa cairo 1.15.2 db8a7f1 from git://anongit.freedesktop.org/cairo xorg-server-1.18.99.901-14 ba199cb from git://git.freedesktop.org/git/xorg/xserver xf86-video-intel 2.99.917-708 8f33f80 from git://git.freedesktop.org/git/xorg/driver/xf86-video-intel libva-1.7.2-38 3b7e499 from git://git.freedesktop.org/git/vaapi/libva vaapi-intel-driver: 1.7.2-101 302cf63 from git://git.freedesktop.org/git/vaapi/intel-driver IGT: intel-gpu-tools-1.16-30 32b2021 from Hardware information : ============================================ Platform : BDW Motherboard type : NUC5i5MYBE Desktop CPU family : Core i5 CPU information : Intel(R) Core(TM) i5-5300U CPU @ 2.30GHz GPU Card : Intel Corporation Broadwell-U Integrated Graphics (rev 09) (prog-if 00 [VGA controller]) Memory ram : 16 GB Maximum memory ram allowed : 16 GB CPU thread : 4 CPU core : 2 Socket : Socket BGA1168 Signature : Type 0, Family 6, Model 61, Stepping 4 Hard drive capacity : 111GiB (120GB) I also tried a couple of commits: ============================================== commit de934d54f765dcfa82c018ea5d256801cffee7af Author: Jani Nikula <jani.nikula@intel.com> Date: Tue Sep 20 12:14:12 2016 +0300 commit f1a9622037cd370460fd06bb7e28d0f01ceb8ef1 Author: Oleg Nesterov <oleg@redhat.com> Date: Mon Sep 26 18:55:25 2016 +0200 Assigned to me. $ git bisect bad 3ec92362cda4c4a2c1ba699b6e8f2cc2e3b4306a The merge base 3ec92362cda4c4a2c1ba699b6e8f2cc2e3b4306a is bad. This means the bug has been fixed between 3ec92362cda4c4a2c1ba699b6e8f2cc2e3b4306a and [aab15c274da587bcab19376d2caa9d6626440335]. $ git bisect log git bisect start # bad: [71d126590e2fa6d65d93fe3586d55ddf9f6c39a6] drm-intel-nightly: 2016y-10m-03d-13h-22m-56s UTC integration manifest git bisect bad 71d126590e2fa6d65d93fe3586d55ddf9f6c39a6 # good: [aab15c274da587bcab19376d2caa9d6626440335] drm-intel-nightly: 2016y-09m-26d-12h-11m-33s UTC integration manifest git bisect good aab15c274da587bcab19376d2caa9d6626440335 # bad: [3ec92362cda4c4a2c1ba699b6e8f2cc2e3b4306a] drm/i915/skl: drop workarounds for F0 revision git bisect bad 3ec92362cda4c4a2c1ba699b6e8f2cc2e3b4306a I am seeing this when it fails:
csanta@csanta-bdw:~$ sudo ./kms_flip --r vblank-vs-suspend-interruptible
[sudo] password for csanta:
IGT-Version: 1.16-gcb214ef (x86_64) (Linux: 4.9.0-rc6+ x86_64)
Using monotonic timestamps
Beginning vblank-vs-suspend-interruptible on pipe A, connector HDMI-A-1
1920x1080 60 1920 1968 2000 2080 1080 1083 1088 1112 0x9 0x48 138780
.rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "mem" using /dev/rtc0 at Thu Dec 1 01:01:31 2016
.rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "mem" using /dev/rtc0 at Thu Dec 1 01:01:49 2016
vblank-vs-suspend-interruptible on pipe A, connector HDMI-A-1: PASSED
Beginning vblank-vs-suspend-interruptible on pipe B, connector HDMI-A-1
1920x1080 60 1920 1968 2000 2080 1080 1083 1088 1112 0x9 0x48 138780
.rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "mem" using /dev/rtc0 at Thu Dec 1 01:02:07 2016
.rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "mem" using /dev/rtc0 at Thu Dec 1 01:02:25 2016
vblank-vs-suspend-interruptible on pipe B, connector HDMI-A-1: PASSED
Beginning vblank-vs-suspend-interruptible on pipe C, connector HDMI-A-1
1920x1080 60 1920 1968 2000 2080 1080 1083 1088 1112 0x9 0x48 138780
.rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "mem" using /dev/rtc0 at Thu Dec 1 01:03:16 2016
.rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "mem" using /dev/rtc0 at Thu Dec 1 01:03:33 2016
(kms_flip:1128) CRITICAL: Test assertion failure function check_state, file kms_flip.c:510:
(kms_flip:1128) CRITICAL: Failed assertion: es->current_seq - es->last_seq <= 150
(kms_flip:1128) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:1128) CRITICAL: unexpected vblank seq 2022, should be < 164
Stack trace:
#0 [__igt_fail_assert+0x101]
#1 [check_state+0x331]
#2 [<unknown>+0x331]
Subtest vblank-vs-suspend-interruptible failed.
**** DEBUG ****
(kms_flip:1128) DEBUG: Test requirement passed: (flags & TEST_HANG) == 0 || !is_wedged(drm_fd)
(kms_flip:1128) DEBUG: Test requirement passed: modes
(kms_flip:1128) INFO: Beginning vblank-vs-suspend-interruptible on pipe A, connector HDMI-A-1
(kms_flip:1128) igt-fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=0x34325258, tiling=0x0, size=0)
(kms_flip:1128) igt-fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:1128) igt-fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=0x34325258, tiling=0x0, size=0)
(kms_flip:1128) igt-fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:1128) igt-kms-INFO: 1920x1080 60 1920 1968 2000 2080 1080 1083 1088 1112 0x9 0x48 138780
(kms_flip:1128) igt-core-DEBUG: Test requirement passed: !igt_run_in_simulation()
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: (power_dir = open("/sys/power", O_RDONLY)) >= 0
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: get_supported_suspend_states(power_dir) & (1 << state)
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: test == SUSPEND_TEST_NONE || faccessat(power_dir, "pm_test", R_OK | W_OK, 0) == 0
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: system(cmd) == 0
(kms_flip:1128) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 73.711808
current_received_ts = 75.530334
current_seq = 4357
count = 0
seq_step = 10
(kms_flip:1128) igt-core-DEBUG: Test requirement passed: !igt_run_in_simulation()
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: (power_dir = open("/sys/power", O_RDONLY)) >= 0
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: get_supported_suspend_states(power_dir) & (1 << state)
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: test == SUSPEND_TEST_NONE || faccessat(power_dir, "pm_test", R_OK | W_OK, 0) == 0
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: system(cmd) == 0
(kms_flip:1128) DEBUG: name = vblank
last_ts = 73.711808
last_received_ts = 75.530334
last_seq = 4357
current_ts = 75.682263
current_received_ts = 78.011187
current_seq = 4461
count = 1
seq_step = 10
(kms_flip:1128) DEBUG: testing ts continuity: Current frame 4461, old frame 4357
(kms_flip:1128) INFO:
vblank-vs-suspend-interruptible on pipe A, connector HDMI-A-1: PASSED
(kms_flip:1128) INFO: Beginning vblank-vs-suspend-interruptible on pipe B, connector HDMI-A-1
(kms_flip:1128) igt-fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=0x34325258, tiling=0x0, size=0)
(kms_flip:1128) igt-fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:1128) igt-fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=0x34325258, tiling=0x0, size=0)
(kms_flip:1128) igt-fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:1128) igt-kms-INFO: 1920x1080 60 1920 1968 2000 2080 1080 1083 1088 1112 0x9 0x48 138780
(kms_flip:1128) igt-core-DEBUG: Test requirement passed: !igt_run_in_simulation()
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: (power_dir = open("/sys/power", O_RDONLY)) >= 0
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: get_supported_suspend_states(power_dir) & (1 << state)
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: test == SUSPEND_TEST_NONE || faccessat(power_dir, "pm_test", R_OK | W_OK, 0) == 0
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: system(cmd) == 0
(kms_flip:1128) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 78.252519
current_received_ts = 80.494014
current_seq = 14
count = 0
seq_step = 10
(kms_flip:1128) igt-core-DEBUG: Test requirement passed: !igt_run_in_simulation()
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: (power_dir = open("/sys/power", O_RDONLY)) >= 0
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: get_supported_suspend_states(power_dir) & (1 << state)
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: test == SUSPEND_TEST_NONE || faccessat(power_dir, "pm_test", R_OK | W_OK, 0) == 0
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: system(cmd) == 0
(kms_flip:1128) DEBUG: name = vblank
last_ts = 78.252519
last_received_ts = 80.494014
last_seq = 14
current_ts = 80.660646
current_received_ts = 82.974470
current_seq = 142
count = 1
seq_step = 10
(kms_flip:1128) DEBUG: testing ts continuity: Current frame 142, old frame 14
(kms_flip:1128) INFO:
vblank-vs-suspend-interruptible on pipe B, connector HDMI-A-1: PASSED
(kms_flip:1128) INFO: Beginning vblank-vs-suspend-interruptible on pipe C, connector HDMI-A-1
(kms_flip:1128) igt-fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=0x34325258, tiling=0x0, size=0)
(kms_flip:1128) igt-fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:1128) igt-fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=0x34325258, tiling=0x0, size=0)
(kms_flip:1128) igt-fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:1128) igt-kms-INFO: 1920x1080 60 1920 1968 2000 2080 1080 1083 1088 1112 0x9 0x48 138780
(kms_flip:1128) igt-core-DEBUG: Test requirement passed: !igt_run_in_simulation()
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: (power_dir = open("/sys/power", O_RDONLY)) >= 0
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: get_supported_suspend_states(power_dir) & (1 << state)
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: test == SUSPEND_TEST_NONE || faccessat(power_dir, "pm_test", R_OK | W_OK, 0) == 0
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: system(cmd) == 0
(kms_flip:1128) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 83.203833
current_received_ts = 116.777497
current_seq = 14
count = 0
seq_step = 10
(kms_flip:1128) igt-core-DEBUG: Test requirement passed: !igt_run_in_simulation()
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: (power_dir = open("/sys/power", O_RDONLY)) >= 0
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: get_supported_suspend_states(power_dir) & (1 << state)
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: test == SUSPEND_TEST_NONE || faccessat(power_dir, "pm_test", R_OK | W_OK, 0) == 0
(kms_flip:1128) igt-aux-DEBUG: Test requirement passed: system(cmd) == 0
(kms_flip:1128) DEBUG: name = vblank
last_ts = 83.203833
last_received_ts = 116.777497
last_seq = 14
current_ts = 116.935350
current_received_ts = 118.224287
current_seq = 2022
count = 1
seq_step = 10
(kms_flip:1128) CRITICAL: Test assertion failure function check_state, file kms_flip.c:510:
(kms_flip:1128) CRITICAL: Failed assertion: es->current_seq - es->last_seq <= 150
(kms_flip:1128) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:1128) CRITICAL: unexpected vblank seq 2022, should be < 164
**** END ****
Subtest vblank-vs-suspend-interruptible: FAIL (44.647s)
Running this test on an APL machine here, I see this in dmesg: [10968.960490] [drm:drm_handle_vblank] vblank event on 58648, current 58648 [10968.960502] [drm:vblank_disable_fn] disabling vblank on crtc 0 [10971.312512] [drm:edp_panel_vdd_off_sync] Turning eDP port A VDD off [10971.312529] [drm:edp_panel_vdd_off_sync] PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067 [11031.602616] perf: interrupt took too long (3200 > 3178), lowering kernel.perf_event_max_sample_rate to 62000 [11121.589837] perf: interrupt took too long (4038 > 4000), lowering kernel.perf_event_max_sample_rate to 49000 [11211.908147] PM: Syncing filesystems ... done. ... [11212.918426] [drm:drm_handle_vblank] vblank event on 73245, current 73246 So after getting the vblank 58648 and right before suspending there's a big delay of 244 seconds (11212 − 10968) that is accompanied of complaints by perf. After resuming, we get a vblank of 73245 which roughly matches the previous vblank count plus 244 * 60. Created attachment 129385 [details]
dmesg
(In reply to Tomeu Vizoso from comment #7) > Running this test on an APL machine here, I see this in dmesg: > > [10968.960490] [drm:drm_handle_vblank] vblank event on 58648, current 58648 > [10968.960502] [drm:vblank_disable_fn] disabling vblank on crtc 0 > [10971.312512] [drm:edp_panel_vdd_off_sync] Turning eDP port A VDD off > [10971.312529] [drm:edp_panel_vdd_off_sync] PP_STATUS: 0x80000008 > PP_CONTROL: 0x00000067 > [11031.602616] perf: interrupt took too long (3200 > 3178), lowering > kernel.perf_event_max_sample_rate to 62000 > [11121.589837] perf: interrupt took too long (4038 > 4000), lowering > kernel.perf_event_max_sample_rate to 49000 > [11211.908147] PM: Syncing filesystems ... done. > ... > [11212.918426] [drm:drm_handle_vblank] vblank event on 73245, current 73246 > > > So after getting the vblank 58648 and right before suspending there's a big > delay of 244 seconds (11212 − 10968) that is accompanied of complaints by > perf. > > After resuming, we get a vblank of 73245 which roughly matches the previous > vblank count plus 244 * 60. The delay seems to be caused by receiving RTC interrupts at a rate of 8kHz from the moment the alarm is programmed. (In reply to Carlos Santa from comment #6) > > (kms_flip:1128) CRITICAL: Failed assertion: es->current_seq - es->last_seq > <= 150 > (kms_flip:1128) CRITICAL: Last errno: 4, Interrupted system call > (kms_flip:1128) CRITICAL: unexpected vblank seq 2022, should be < 164 > **** END **** > Subtest vblank-vs-suspend-interruptible: FAIL (44.647s) Can you try running this? sudo sh -c "echo `date '+%s' -d '+ 60 seconds'` > /sys/class/rtc/rtc0/wakealarm" And immediately after, check any of: * You get several "hpet1: lost 7161 rtc interrupts" messages in the kernel log * top shows that one core is busy dealing with interrupts ("hi" field) * perf top shows that rtc_cmos_read takes about 70% of the total CPU time, followed by hpet_rtc_interrupt. This is what I'm seeing in one of the machines I have here and would be useful to know if it's the same you are observing. Have sent a patch for IGT that should make it able to cope with faulty RTCs. Christophe, can you retest using the IGT patch mentioned in Comment 11 to see if it fixes the problem? Test is now Pass. Tested with: Platform BDW: NUC5i7RYB CPU: Intel(R) Core(TM) i7-5557U CPU @ 3.10GHz (Family 6, Model 61, Stepping 4) Motherboard version: H73774-102 GPU: Intel® Iris™ Graphics 6100 - Intel Corporation Broadwell-U Integrated Graphics (rev 09) Memory: two 4GB card Kingston 99U5469-045.A00LF SSD: INTEL SSDSC2KW24 Software Bios: RYBDWi35.86A.0358.2016.0606.1423 from https://downloadcenter.intel.com/downloads/eula/26081/BIOS-Update-RYBDWi35-86A-?httpDown=https%3A%2F%2Fdownloadmirror.intel.com%2F26081%2Feng%2FRY0358.bio Linux distribution: Ubuntu 16.04 64 bits Kernel: 4.10.0 f76e5ec branch drm-tip from https://cgit.freedesktop.org/drm-tip commit: f76e5eca8c2a46cbd0203d32842bca6ce0ec16ef committed_date: Mon Feb 27 13:20:52 2017 +0000 author: Mika Kuoppala <mika.kuoppala@intel.com> summary: 'drm-tip: 2017y-02m-27d-13h-20m-25s UTC integration manifest' libdrm-2.4.75-10 f6499b1 from git://anongit.freedesktop.org/mesa/drm mesa: mesa-17.0.0 683462e from git://anongit.freedesktop.org/mesa/mesa cairo 1.15.4 9fe6683 from git://anongit.freedesktop.org/cairo xorg-server-1.19.0-125 7d7788e from git://git.freedesktop.org/git/xorg/xserver xf86-video-intel 2.99.917-758 860c366 from git://git.freedesktop.org/git/xorg/driver/xf86-video-intel libva-1.7.3.pre1-84 e613327 from git://git.freedesktop.org/git/vaapi/libva vaapi-intel-driver: 1.7.3-325 03a86fc from git://git.freedesktop.org/git/vaapi/intel-driver intel-gpu-tools-1.17-261 8f3164f from http://anongit.freedesktop.org/git/xorg/app/intel-gpu-tools.git So closed |
Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.