Bug 108673

Summary:	[CI][BAT] igt@gem_exec_create@madvise - dmesg-warn - ODEBUG: active_state not available
Product:	DRI	Reporter:	Martin Peres <martin.peres>
Component:	DRM/Intel	Assignee:	Intel GFX Bugs mailing list <intel-gfx-bugs>
Status:	CLOSED DUPLICATE	QA Contact:	Intel GFX Bugs mailing list <intel-gfx-bugs>
Severity:	normal
Priority:	highest	CC:	intel-gfx-bugs
Version:	XOrg git
Hardware:	Other
OS:	All
Whiteboard:	ReadyForDev
i915 platform:	BXT	i915 features:	GEM/Other

Description Martin Peres 2018-11-06 08:29:55 UTC

https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4709/shard-apl3/igt@gem_exec_create@madvise.html

<6> [552.678352] [IGT] gem_exec_create: executing
<5> [552.718634] Setting dangerous option reset - tainting kernel
<6> [552.723148] [IGT] gem_exec_create: starting subtest madvise
<4> [573.806157] ------------[ cut here ]------------
<3> [573.806180] ODEBUG: active_state not available (active state 0) object type: rcu_head hint:           (null)
<4> [573.806225] WARNING: CPU: 3 PID: 26 at lib/debugobjects.c:329 debug_print_object+0x67/0x90
<4> [573.806242] Modules linked in: vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic x86_pkg_temp_thermal coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel lpc_ich i915 r8169 snd_hda_intel snd_hda_codec snd_hwdep snd_hda_core mei_me snd_pcm pinctrl_broxton pinctrl_intel mei prime_numbers
<4> [573.806310] CPU: 3 PID: 26 Comm: ksoftirqd/3 Tainted: G     U  W         4.20.0-rc1-CI-CI_DRM_5085+ #1
<4> [573.806329] Hardware name:  /NUC6CAYB, BIOS AYAPLCEL.86A.0049.2018.0508.1356 05/08/2018
<4> [573.806348] RIP: 0010:debug_print_object+0x67/0x90
<4> [573.806360] Code: 83 c2 01 8b 4b 14 4c 8b 45 00 89 15 cb 7d 22 02 8b 53 10 4c 89 e6 48 c7 c7 e0 6e 0d 82 48 8b 14 d5 c0 d8 e6 81 e8 a9 7c be ff <0f> 0b 5b 83 05 73 ab e9 00 01 5d 41 5c c3 83 05 68 ab e9 00 01 c3
<4> [573.806394] RSP: 0018:ffffc90000107d50 EFLAGS: 00010086
<4> [573.806406] RAX: 0000000000000000 RBX: ffffc90000107d80 RCX: 0000000000000000
<4> [573.806421] RDX: 0000000000000007 RSI: ffffffff820c6428 RDI: 00000000ffffffff
<4> [573.806436] RBP: ffffffff822478a0 R08: 0000000000000000 R09: 0000000000000000
<4> [573.806451] R10: ffffc90000107ce8 R11: ffffffff822459f8 R12: ffffffff820d70ce
<4> [573.806465] R13: ffffffff8374c688 R14: 0000000000000206 R15: ffffffff8110d8fe
<4> [573.806480] FS:  0000000000000000(0000) GS:ffff880277b80000(0000) knlGS:0000000000000000
<4> [573.806497] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4> [573.806510] CR2: 00007fa1d8321100 CR3: 000000025cada000 CR4: 00000000003406e0
<4> [573.806524] Call Trace:
<4> [573.806536]  debug_object_active_state+0x12c/0x160
<4> [573.806629]  ? i915_gem_free_object+0x110/0x110 [i915]
<4> [573.806644]  ? rcu_process_callbacks+0x3c0/0x850
<4> [573.806656]  rcu_process_callbacks+0x3c0/0x850
<4> [573.806672]  __do_softirq+0xd8/0x4b9
<4> [573.806686]  ? smpboot_thread_fn+0x23/0x280
<4> [573.806697]  ? smpboot_thread_fn+0x6b/0x280
<4> [573.806710]  run_ksoftirqd+0x2b/0x50
<4> [573.806720]  smpboot_thread_fn+0x1d3/0x280
<4> [573.806733]  ? sort_range+0x20/0x20
<4> [573.806743]  kthread+0x119/0x130
<4> [573.806753]  ? kthread_park+0x80/0x80
<4> [573.806766]  ret_from_fork+0x3a/0x50
<4> [573.806781] irq event stamp: 38562
<4> [573.806792] hardirqs last  enabled at (38561): [<ffffffff8108ddc0>] run_ksoftirqd+0x30/0x50
<4> [573.806810] hardirqs last disabled at (38562): [<ffffffff8194c99a>] __schedule+0xaa/0xb50
<4> [573.806828] softirqs last  enabled at (38560): [<ffffffff81c0033a>] __do_softirq+0x33a/0x4b9
<4> [573.806846] softirqs last disabled at (38347): [<ffffffff8108ddbb>] run_ksoftirqd+0x2b/0x50
<4> [573.806865] WARNING: CPU: 3 PID: 26 at lib/debugobjects.c:329 debug_print_object+0x67/0x90
<4> [573.806882] ---[ end trace 5c1fc586ecb7a0a0 ]---
<4> [573.806927] ------------[ cut here ]------------
<3> [573.806942] ODEBUG: deactivate not available (active state 0) object type: rcu_head hint:           (null)
<4> [573.806977] WARNING: CPU: 3 PID: 26 at lib/debugobjects.c:329 debug_print_object+0x67/0x90
<4> [573.806995] Modules linked in: vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic x86_pkg_temp_thermal coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel lpc_ich i915 r8169 snd_hda_intel snd_hda_codec snd_hwdep snd_hda_core mei_me snd_pcm pinctrl_broxton pinctrl_intel mei prime_numbers
<4> [573.807056] CPU: 3 PID: 26 Comm: ksoftirqd/3 Tainted: G     U  W         4.20.0-rc1-CI-CI_DRM_5085+ #1
<4> [573.807074] Hardware name:  /NUC6CAYB, BIOS AYAPLCEL.86A.0049.2018.0508.1356 05/08/2018
<4> [573.807092] RIP: 0010:debug_print_object+0x67/0x90
<4> [573.807104] Code: 83 c2 01 8b 4b 14 4c 8b 45 00 89 15 cb 7d 22 02 8b 53 10 4c 89 e6 48 c7 c7 e0 6e 0d 82 48 8b 14 d5 c0 d8 e6 81 e8 a9 7c be ff <0f> 0b 5b 83 05 73 ab e9 00 01 5d 41 5c c3 83 05 68 ab e9 00 01 c3
<4> [573.807138] RSP: 0018:ffffc90000107d50 EFLAGS: 00010086
<4> [573.807150] RAX: 0000000000000000 RBX: ffffc90000107d80 RCX: 0000000000000000
<4> [573.807165] RDX: 0000000000000000 RSI: 0000000000000001 RDI: 00000000ffffffff
<4> [573.807180] RBP: ffffffff822478a0 R08: 0000000000000000 R09: 0000000000000000
<4> [573.807194] R10: ffffc90000107ce8 R11: ffffffff822459f8 R12: ffffffff8209f1f9
<4> [573.807209] R13: ffffffff8374c688 R14: 0000000000000206 R15: ffffffff8110d8fe
<4> [573.807224] FS:  0000000000000000(0000) GS:ffff880277b80000(0000) knlGS:0000000000000000
<4> [573.807243] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4> [573.807260] CR2: 00007fa1d8321100 CR3: 000000025cada000 CR4: 00000000003406e0
<4> [573.807278] Call Trace:
<4> [573.807292]  debug_object_deactivate+0x12c/0x160
<4> [573.807389]  ? i915_gem_free_object+0x110/0x110 [i915]
<4> [573.807408]  ? rcu_process_callbacks+0x3cb/0x850
<4> [573.807423]  rcu_process_callbacks+0x3cb/0x850
<4> [573.807439]  __do_softirq+0xd8/0x4b9
<4> [573.807452]  ? smpboot_thread_fn+0x23/0x280
<4> [573.807463]  ? smpboot_thread_fn+0x6b/0x280
<4> [573.807475]  run_ksoftirqd+0x2b/0x50
<4> [573.807485]  smpboot_thread_fn+0x1d3/0x280
<4> [573.807500]  ? sort_range+0x20/0x20
<4> [573.807510]  kthread+0x119/0x130
<4> [573.807520]  ? kthread_park+0x80/0x80
<4> [573.807535]  ret_from_fork+0x3a/0x50
<4> [573.807552] irq event stamp: 38562
<4> [573.807562] hardirqs last  enabled at (38561): [<ffffffff8108ddc0>] run_ksoftirqd+0x30/0x50
<4> [573.807581] hardirqs last disabled at (38562): [<ffffffff8194c99a>] __schedule+0xaa/0xb50
<4> [573.807599] softirqs last  enabled at (38560): [<ffffffff81c0033a>] __do_softirq+0x33a/0x4b9
<4> [573.807618] softirqs last disabled at (38347): [<ffffffff8108ddbb>] run_ksoftirqd+0x2b/0x50
<4> [573.807637] WARNING: CPU: 3 PID: 26 at lib/debugobjects.c:329 debug_print_object+0x67/0x90
<4> [573.807654] ---[ end trace 5c1fc586ecb7a0a1 ]---
<4> [573.807733] ODEBUG: Out of memory. ODEBUG disabled
<6> [574.489083] [IGT] gem_exec_create: exiting, ret=0
<6> [575.808197] Console: switching to colour frame buffer device 240x67

Comment 1 Chris Wilson 2018-11-06 08:40:38 UTC

debugobjects hit a malloc error and got all confused.

Comment 2 Martin Peres 2018-11-06 13:15:20 UTC

(In reply to Chris Wilson from comment #1)
> debugobjects hit a malloc error and got all confused.

Is it a NOTABUG, or NOTOURBUG?

I would say that if it is not a bug, then it should not spew up a warning. Thoughts?

Comment 3 Francesco Balestrieri 2018-11-09 09:04:40 UTC

Ping Chris?

Comment 4 Chris Wilson 2018-11-09 09:30:05 UTC

There isn't that much we can do about the warn; the debugobjects code is written to be usable from atomic context, that is allocation failures are a reality and its way to deal with them is to turn off. The warn makes sense, you were using debugobjects, an error occurred and it can no longer use debugobjects.

That being said we are missing a init_rcu_head() which means a lack of opportunity for debugobjects to preallocate. What really threw me here is that we should have seen this error from the get go, the only saving grace would be the late initialisation that failed here due to the allocation failure.

*** This bug has been marked as a duplicate of bug 108691 ***

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.