Bug 102899

Summary: [IGT] gem_ringfill some subtests failing with rtcwake failed with 256
Product: DRI Reporter: Hector Velazquez <hector.franciscox.velazquez.suriano>
Component: DRM/IntelAssignee: Intel GFX Bugs mailing list <intel-gfx-bugs>
Status: CLOSED FIXED QA Contact: Intel GFX Bugs mailing list <intel-gfx-bugs>
Severity: normal    
Priority: medium CC: intel-gfx-bugs
Version: DRI git   
Hardware: x86-64 (AMD64)   
OS: Linux (All)   
See Also: https://bugs.freedesktop.org/show_bug.cgi?id=102261
Whiteboard:
i915 platform: GLK i915 features: GEM/Other
Attachments:
Description Flags
Output log
none
Dmesg none

Description Hector Velazquez 2017-09-20 13:31:14 UTC 
Created attachment 134360 [details]
Output log
Comment 1 Hector Velazquez 2017-09-20 13:31:53 UTC 
This test also fail on GLK QA

Tests List:

igt@gem_ringfill@bsd-S4


====================================================
Output
====================================================
. . .
**** DEBUG ****
(gem_ringfill:12874) DEBUG: Test requirement passed: !(m->flags & NEWFD && master)
(gem_ringfill:12874) ioctl-wrappers-DEBUG: Test requirement passed: gem_has_ring(fd, ring)
(gem_ringfill:12874) DEBUG: Test requirement passed: gem_can_store_dword(fd, ring)
(gem_ringfill:12874) ioctl-wrappers-DEBUG: Test requirement passed: gem_has_ring(fd, ring)
(gem_ringfill:12874) DEBUG: Test requirement passed: gem_can_store_dword(fd, ring)
(gem_ringfill:12874) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'
(gem_ringfill:12874) DEBUG: Verifying result
(gem_ringfill:12874) DEBUG: Test requirement passed: setup_execbuf(fd, &execbuf, obj, reloc, ring) == 0
(gem_ringfill:12874) DEBUG: Executing execbuf 4096 times
(gem_ringfill:12874) DEBUG: Verifying result
(gem_ringfill:12874) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'
(gem_ringfill:12874) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'
(gem_ringfill:12874) DEBUG: Verifying result
(gem_ringfill:12874) DEBUG: Test requirement passed: setup_execbuf(fd, &execbuf, obj, reloc, ring) == 0
(gem_ringfill:12874) DEBUG: Forking 32 children
(gem_ringfill:12874) igt-core-DEBUG: Test requirement passed: !igt_run_in_simulation()
(gem_ringfill:12874) igt-aux-DEBUG: Test requirement passed: (power_dir = open("/sys/power", O_RDONLY)) >= 0
(gem_ringfill:12874) igt-aux-DEBUG: Test requirement passed: get_supported_suspend_states(power_dir) & (1 << state)
(gem_ringfill:12874) igt-aux-DEBUG: Test requirement passed: test == SUSPEND_TEST_NONE || faccessat(power_dir, "pm_test", R_OK | W_OK, 0) == 0
(gem_ringfill:12874) igt-aux-DEBUG: Test requirement passed: ret == 0
(gem_ringfill:12874) igt-aux-CRITICAL: Test assertion failure function suspend_via_rtcwake, file igt_aux.c:769:
(gem_ringfill:12874) igt-aux-CRITICAL: Failed assertion: ret == 0
(gem_ringfill:12874) igt-aux-CRITICAL: rtcwake failed with 256
Check dmesg for further details.
(gem_ringfill:12874) igt-core-INFO: Stack trace:
(gem_ringfill:12874) igt-core-INFO:   #0 [__igt_fail_assert+0x101]
(gem_ringfill:12874) igt-core-INFO:   #1 [igt_system_suspend_autoresume+0x5ae]
(gem_ringfill:12874) igt-core-INFO:   #2 [<unknown>+0x5ae]
****  END  ****
. . .

This is my configuration:

====================================================
Graphic Stack
====================================================
Component: drm
    tag: libdrm-2.4.81-55-g76418c2
    commit: 76418c244d4c52a8dd20809e3e8b4e70501fc76f

Component: cairo
    tag: 1.15.6-38-g1220e3c
    commit: 1220e3c6b8f94a00ac7afee15f21e6782655d97c

Component: intel-gpu-tools
    tag: intel-gpu-tools-1.19-312-gda197b5
    commit: da197b5f3cb516aaaea72d0d60b0f5c1c81081dd

Component: piglit
    tag: piglit-v1
    commit: 2753955998d7deb90f681cf4cb1253c4519dfd1d

======================================
	     Software
======================================
kernel version              : 4.14.0-rc1-drm-tip-ww38-commit-ab2e3a0+
hostname                    : gfx-desktop
architecture                : x86_64
os version                  : Ubuntu 16.10
os codename                 : yakkety
kernel driver               : i915
bios revision               : 62.30
bios release date           : 08/22/2017
ksc                         : 1.48
hardware acceleration       : disabled
swap partition              : enabled on (/dev/sda3)

======================================
	Graphic drivers
======================================
libdrm                      : 2.4.83
cairo                       : 1.15.9
intel-gpu-tools (tag)       : intel-gpu-tools-1.19-312-gda197b5
intel-gpu-tools (commit)    : da197b5

======================================
	     Hardware
======================================
platform                   : Geminilake
motherboard model          : Geminilake
motherboard id             : GLKRVP1DDR4(05)
form factor                : Hand Held
manufacturer               : IntelCorp.
cpu family                 : Pentium
cpu family id              : 6
cpu information            : Intel(R) Pentium(R) Silver J5005 CPU @ 1.50GHz
gpu card                   : Intel Corporation Device 3184 (rev 03) (prog-if 00 [VGA controller])
memory ram                 : 7.6 GB
max memory ram             : 16 GB
cpu thread                 : 4
cpu core                   : 4
cpu model                  : 122
cpu stepping               : 1
socket                     : Other
signature                  : Type 0, Family 6, Model 122, Stepping 1
hard drive                 : 111GiB (120GB)
current cd clock frequency : 316800 kHz
maximum cd clock frequency : 316800 kHz
displays connected         : eDP-1 DP-1 HDMI-A-2

======================================
	     Firmware
======================================
dmc fw loaded             : yes
dmc version               : 1.4
guc fw loaded             : SUCCESS
guc version wanted        : 10.56
guc version found         : 10.56
huc fw loaded             : yes

======================================
	     kernel parameters
======================================
quiet splash drm.debug=0xe i915.enable_guc_submission=2 i915.enable_guc_loading=2 i915.alpha_support=1 resume=/dev/sda3
Comment 2 Hector Velazquez 2017-09-20 13:33:14 UTC 
Created attachment 134361 [details]
Dmesg
Comment 3 Elizabeth 2017-09-25 21:19:15 UTC 
From dmesg:
[ 1913.747680] [drm:intel_enable_pipe [i915]] enabling pipe C
[ 1913.747729] [drm:intel_hdmi_handle_sink_scrambling [i915]] Setting sink scrambling for enc:DDI C connector:HDMI-A-2
[ 1913.749337] [drm:gmbus_xfer [i915]] GMBUS [i915 gmbus dpc] NAK for addr: 0054 w(1)
[ 1913.749386] [drm:gmbus_xfer [i915]] GMBUS [i915 gmbus dpc] NAK on first message, retry
[ 1913.751332] [drm:gmbus_xfer [i915]] GMBUS [i915 gmbus dpc] NAK for addr: 0054 w(1)
[ 1913.751361] [drm:drm_scdc_set_high_tmds_clock_ratio] *ERROR* Failed to read TMDS config: -6
[ 1913.751404] [drm:intel_hdmi_handle_sink_scrambling [i915]] *ERROR* Set TMDS ratio failed
[ 1913.751451] [drm:intel_audio_codec_enable [i915]] ELD on [CONNECTOR:91:HDMI-A-2], [ENCODER:90:DDI C]
[ 1913.751496] [drm:hsw_audio_codec_enable [i915]] Enable audio codec on pipe C, 32 bytes ELD
[ 1913.751544] [drm:audio_config_hdmi_pixel_clock.isra.3 [i915]] HDMI audio pixel clock setting for 533250 not found, falling back to defaults
[ 1913.751591] [drm:audio_config_hdmi_pixel_clock.isra.3 [i915]] Configuring HDMI audio for pixel clock 25200 (0x00010000)
[ 1913.751636] [drm:hsw_audio_config_update [i915]] using automatic N

It repeats for pipe A, B and C. And then there is the hang:

[ 3232.953345] [drm] GPU HANG: ecode 9:0:0xfffffffe, reason: Manually setting wedged to 18446744073709551615, action: reset
[ 3232.953383] [drm] GPU hangs can indicate a bug anywhere in the entire gfx stack, including userspace.
[ 3232.953585] [drm] Please file a _new_ bug report on bugs.freedesktop.org against DRI -> DRM/Intel
[ 3232.953614] [drm] drm/i915 developers can then reassign to the right component if it's not a kernel issue.
[ 3232.953643] [drm] The gpu crash dump is required to analyze gpu hangs, so please always attach it.
[ 3232.953670] [drm] GPU crash dump saved to /sys/class/drm/card0/error
[ 3232.953849] [drm:i915_reset_device [i915]] resetting chip
[ 3232.953926] i915 0000:00:02.0: Resetting chip after gpu hang
[ 3232.956285] [drm:gen8_init_common_ring [i915]] Execlists enabled for rcs0
[ 3232.956387] [drm:init_workarounds_ring [i915]] rcs0: Number of context specific w/a: 12
[ 3232.956540] [drm:gen8_init_common_ring [i915]] Execlists enabled for bcs0
[ 3232.956688] [drm:gen8_init_common_ring [i915]] Execlists enabled for vcs0
[ 3232.956832] [drm:gen8_init_common_ring [i915]] Execlists enabled for vecs0
[ 3232.957916] [IGT] gem_eio: starting subtest in-flight
[ 3232.958163] Setting dangerous option reset - tainting kernel
[ 3232.958973] [drm] RC6 on
[ 3234.720287] [drm:missed_breadcrumb [i915]] rcs0 missed breadcrumb at intel_breadcrumbs_hangcheck+0x5c/0x80 [i915], irq posted? yes, current seqno=0, last=41
[ 3234.720708] [drm:i915_reset_device [i915]] resetting chip
[ 3234.720758] i915 0000:00:02.0: Resetting chip after gpu hang
[ 3234.721198] [drm:i915_reset [i915]] GPU reset disabled
[ 3234.722765] Setting dangerous option reset - tainting kernel
[ 3234.722947] [drm:i915_reset_device [i915]] resetting chip
[ 3234.723039] i915 0000:00:02.0: Resetting chip after gpu hang

Would the file /sys/class/drm/card0/error be useful?
Comment 4 Chris Wilson 2017-09-25 22:08:31 UTC 
The hangs are intentional and unrelated. What actually caused rtcwake is not known; it did not leave a dmesg telltale.
Comment 5 Hector Velazquez 2017-10-03 15:00:40 UTC 
This tests are failing on GLK QA

Tests List:

igt@gem_ringfill@blt-S4
igt@gem_ringfill@bsd-S4
igt@gem_ringfill@vebox-S4


====================================================
Output 
====================================================
. . .
	

This is my configuration:

======================================
        Graphic stack
======================================
Component: drm
    tag: libdrm-2.4.81-57-g1dd84e0
    commit: 1dd84e01a972b1759839a7326009be24ab3e6de2

Component: cairo
    tag: 1.15.6-42-gdccbed7
    commit: dccbed7d78d32bd3b912e8810379451dd94e6a1f

Component: intel-gpu-tools
    tag: intel-gpu-tools-1.19-357-g1e99f8b
    commit: 1e99f8b8d2563d7f5c4e82932bab15abc5eacaef

Component: piglit
    tag: piglit-v1
    commit: 5aa6eea37f44f818632a3dad4c1a7478085bd56d

	
======================================
	     Software
======================================
kernel version              : 4.14.0-rc3-drm-tip-ww40-commit-2f14e31+
hostname                    : GLK-1-GLKRVP1DDR405
architecture                : x86_64
os version                  : Ubuntu 16.10
os codename                 : yakkety
kernel driver               : i915
bios revision               : 62.30
bios release date           : 08/22/2017
ksc                         : 1.41
hardware acceleration       : disabled
swap partition              : enabled on (/dev/sda3)

======================================
	Graphic drivers
======================================
libdrm                      : 2.4.83
cairo                       : 1.15.9
intel-gpu-tools (tag)       : intel-gpu-tools-1.19-357-g1e99f8b
intel-gpu-tools (commit)    : 1e99f8b

======================================
	     Hardware
======================================
. . .
======================================
	     Firmware
======================================
dmc fw loaded             : yes
dmc version               : 1.4
guc fw loaded             : SUCCESS
guc version wanted        : 10.56
guc version found         : 10.56

======================================
	     kernel parameters
======================================
quiet drm.debug=0x1e pci=pcie_bus_safe intel_iommu=igfx_off auto panic=1 nmi_watchdog=panic i915.alpha_support=1 i915.enable_guc_loading=2 i915.enable_guc_submission=2 resume=/dev/sda3 fastboot
Comment 6 Imre Deak 2017-10-05 09:05:09 UTC 
Could you make sure that your time is accurate using ntp or setting it locally and then:

# hwclock --systohc

Also could you please paste the output of

# cat /sys/power/state

?
Comment 7 Hector Velazquez 2017-10-05 14:56:48 UTC 
for the comment 6:

# hwclock --systohc
# cat /sys/power/state
freeze mem disk
# timedatectl
      Local time: Thu 2017-10-05 09:33:15 CDT
  Universal time: Thu 2017-10-05 14:33:15 UTC
        RTC time: Thu 2017-10-05 14:33:15
       Time zone: America/Mexico_City (CDT, -0500)
 Network time on: yes
NTP synchronized: no
 RTC in local TZ: no
Comment 8 Hector Velazquez 2017-12-22 16:12:41 UTC 
This test has passing on GLK QA...

igt@gem_ringfill@blt-S4

This tests continue failing on GLK QA...

igt@gem_ringfill@bsd-S4
igt@gem_ringfill@vebox-S4

IGT-Version: 1.20-gc0be331 (x86_64) (Linux: 4.15.0-rc3-drm-intel-qa-ww50-commit-ad43db1+ x86_64)

====================================================
output sample
====================================================
[**** DEBUG Subtest vebox-S4****
(gem_ringfill:2651) DEBUG: Test requirement passed: !(m->flags & NEWFD && master)
(gem_ringfill:2651) igt-core-DEBUG: Test requirement passed: !igt_run_in_simulation()
(gem_ringfill:2651) ioctl-wrappers-DEBUG: Test requirement passed: gem_has_ring(fd, ring)
(gem_ringfill:2651) DEBUG: Test requirement passed: gem_can_store_dword(fd, ring)
(gem_ringfill:2651) ioctl-wrappers-DEBUG: Test requirement passed: gem_has_ring(fd, ring)
(gem_ringfill:2651) DEBUG: Test requirement passed: gem_can_store_dword(fd, ring)
(gem_ringfill:2651) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'
(gem_ringfill:2651) DEBUG: Verifying result
(gem_ringfill:2651) DEBUG: Test requirement passed: setup_execbuf(fd, &execbuf, obj, reloc, ring) == 0
(gem_ringfill:2651) DEBUG: Executing execbuf 4096 times
(gem_ringfill:2651) DEBUG: Verifying result
(gem_ringfill:2651) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'
(gem_ringfill:2651) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'
(gem_ringfill:2651) DEBUG: Verifying result
(gem_ringfill:2651) DEBUG: Test requirement passed: setup_execbuf(fd, &execbuf, obj, reloc, ring) == 0
(gem_ringfill:2651) DEBUG: Forking 16 children
(gem_ringfill:2651) igt-core-DEBUG: Test requirement passed: !igt_run_in_simulation()
(gem_ringfill:2651) igt-aux-DEBUG: Test requirement passed: (power_dir = open("/sys/power", O_RDONLY)) >= 0
(gem_ringfill:2651) igt-aux-DEBUG: Test requirement passed: get_supported_suspend_states(power_dir) & (1 << state)
(gem_ringfill:2651) igt-aux-DEBUG: Test requirement passed: test == SUSPEND_TEST_NONE || faccessat(power_dir, "pm_test", R_OK | W_OK, 0) == 0
(gem_ringfill:2651) igt-aux-DEBUG: Test requirement passed: ret == 0
(gem_ringfill:2651) igt-core-INFO: [cmd] rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "disk" using /dev/rtc0 at Thu May 26 00:08:49 2016
(gem_ringfill:2651) igt-core-WARNING: [cmd] rtcwake: write error
(gem_ringfill:2651) igt-aux-WARNING: rtcwake failed with 1
Check dmesg for further details.
(gem_ringfill:2651) igt-aux-DEBUG: suspend_stats:
success: 8
fail: 0
failed_freeze: 0
failed_prepare: 0
failed_suspend: 0
failed_suspend_late: 0
failed_suspend_noirq: 0
failed_resume: 0
failed_resume_early: 0
failed_resume_noirq: 0
failures:
  last_failed_dev:	
			
  last_failed_errno:	0
			0
  last_failed_step:	
			
(gem_ringfill:2651) igt-aux-CRITICAL: Test assertion failure function suspend_via_rtcwake, file igt_aux.c:821:
(gem_ringfill:2651) igt-aux-CRITICAL: Failed assertion: ret == 0
(gem_ringfill:2651) igt-aux-CRITICAL: error: 1 != 0
(gem_ringfill:2651) igt-core-INFO: Stack trace:
(gem_ringfill:2651) igt-core-INFO:   #0 [__igt_fail_assert+0x101]
(gem_ringfill:2651) igt-core-INFO:   #1 [igt_system_suspend_autoresume+0x52b]
(gem_ringfill:2651) igt-core-INFO:   #2 [<unknown>+0x52b]
****  END  ****

**** DEBUG bsd-S4****
(gem_ringfill:2592) DEBUG: Test requirement passed: !(m->flags & NEWFD && master)
(gem_ringfill:2592) igt-core-DEBUG: Test requirement passed: !igt_run_in_simulation()
(gem_ringfill:2592) ioctl-wrappers-DEBUG: Test requirement passed: gem_has_ring(fd, ring)
(gem_ringfill:2592) DEBUG: Test requirement passed: gem_can_store_dword(fd, ring)
(gem_ringfill:2592) ioctl-wrappers-DEBUG: Test requirement passed: gem_has_ring(fd, ring)
(gem_ringfill:2592) DEBUG: Test requirement passed: gem_can_store_dword(fd, ring)
(gem_ringfill:2592) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'
(gem_ringfill:2592) DEBUG: Verifying result
(gem_ringfill:2592) DEBUG: Test requirement passed: setup_execbuf(fd, &execbuf, obj, reloc, ring) == 0
(gem_ringfill:2592) DEBUG: Executing execbuf 4096 times
(gem_ringfill:2592) DEBUG: Verifying result
(gem_ringfill:2592) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'
(gem_ringfill:2592) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'
(gem_ringfill:2592) DEBUG: Verifying result
(gem_ringfill:2592) DEBUG: Test requirement passed: setup_execbuf(fd, &execbuf, obj, reloc, ring) == 0
(gem_ringfill:2592) DEBUG: Forking 16 children
(gem_ringfill:2592) igt-core-DEBUG: Test requirement passed: !igt_run_in_simulation()
(gem_ringfill:2592) igt-aux-DEBUG: Test requirement passed: (power_dir = open("/sys/power", O_RDONLY)) >= 0
(gem_ringfill:2592) igt-aux-DEBUG: Test requirement passed: get_supported_suspend_states(power_dir) & (1 << state)
(gem_ringfill:2592) igt-aux-DEBUG: Test requirement passed: test == SUSPEND_TEST_NONE || faccessat(power_dir, "pm_test", R_OK | W_OK, 0) == 0
(gem_ringfill:2592) igt-aux-DEBUG: Test requirement passed: ret == 0
(gem_ringfill:2592) igt-core-INFO: [cmd] rtcwake: assuming RTC uses UTC ...
rtcwake: wakeup from "disk" using /dev/rtc0 at Thu May 26 00:08:28 2016
(gem_ringfill:2592) igt-core-WARNING: [cmd] rtcwake: write error
(gem_ringfill:2592) igt-aux-WARNING: rtcwake failed with 1
Check dmesg for further details.
(gem_ringfill:2592) igt-aux-DEBUG: suspend_stats:
success: 8
fail: 0
failed_freeze: 0
failed_prepare: 0
failed_suspend: 0
failed_suspend_late: 0
failed_suspend_noirq: 0
failed_resume: 0
failed_resume_early: 0
failed_resume_noirq: 0
failures:
  last_failed_dev:	
			
  last_failed_errno:	0
			0
  last_failed_step:	
			
(gem_ringfill:2592) igt-aux-CRITICAL: Test assertion failure function suspend_via_rtcwake, file igt_aux.c:821:
(gem_ringfill:2592) igt-aux-CRITICAL: Failed assertion: ret == 0
(gem_ringfill:2592) igt-aux-CRITICAL: error: 1 != 0
(gem_ringfill:2592) igt-core-INFO: Stack trace:
(gem_ringfill:2592) igt-core-INFO:   #0 [__igt_fail_assert+0x101]
(gem_ringfill:2592) igt-core-INFO:   #1 [igt_system_suspend_autoresume+0x52b]
(gem_ringfill:2592) igt-core-INFO:   #2 [<unknown>+0x52b]
****  END  ****
Comment 9 Hector Velazquez 2018-02-15 21:28:33 UTC 
This test has passing on GLK QA

Test List
igt@gem_ringfill@bsd-S4
igt@gem_ringfill@vebox-S4
igt@gem_ringfill@blt-S4


Software:
IGT-Version: 1.21-g37bd27f (x86_64) (Linux: 4.16.0-rc1-drm-intel-qa-ww7-commit-28dc2a5+ x86_64)
Comment 10 Elizabeth 2018-02-19 18:57:45 UTC 
Besides one recurrence with test igt@gem_ringfill@bsd-S4 last week, previous and actual week results doesn't show the issue anymore, so closing. Thanks for your time.

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.