Associated bug: bug 79052

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