Query: rcu_sched detected stalls with function_graph tracer

From: Pratyush Anand
Date: Wed Aug 02 2017 - 02:32:32 EST

Hi Steve,

I am using a 3.10 based kernel, and when I enable function_graph with one particular x86_64 machine, I encounter rcu_sched stall.

echo function_graph > /sys/kernel/debug/tracing/current_tracer
echo 1 > /sys/kernel/debug/tracing/tracing_on

If I use 4.13-rc2, then its better, but still goes for it after a bit of stressing with stressng.

It looks like that this behavior should be expected with a loaded system (like that of ftrace-graph tracing for all available function) which can cause RCU stall warning. But,I am not an expert. So, whats your opinion on it?

I tried to bisect and there was no particular function which can cause this. It looked like that when we had more than 5000 functions in set_ftrace_filter, we start getting such warnings. Tried by putting some most hit functions like spin_lock* etc in set_ftrace_notrace. Still, no help. Do you have some suggestion for further debugging pointers?

log with 3.10 based kernel
===============================
[ 358.764071] perf: interrupt took too long (4503 > 4488), lowering kernel.perf_event_max_sample_rate to 44000
[ 408.705034] INFO: rcu_sched detected stalls on CPUs/tasks: { 0} (detected by 7, t=60036 jiffies, g=21144, c=21143, q=21651)
[ 408.706011] Task dump for CPU 0:
[ 408.706011] swapper/0 R running task 0 0 0 0x00000008
[ 408.706011] 0000000000000003 0000000000000003 ffffffff81aaf920 ffffffff819e4000
[ 408.706011] ffffffff819e7ed0 ffffffff816b6ef5 0000000000000000 ffffffff81b1c820
[ 408.706011] ffffffff819e4000 ffffffff819e4000 ffffffff819e4000 ffffffff819e4000
[ 408.706011] Call Trace:
[ 408.706011] [<ffffffff816b6ef5>] ? ftrace_graph_caller+0x85/0x85
[ 408.706011] [<ffffffff81130c05>] handle_irq_event_percpu+0x55/0x80
[ 408.706011] [<ffffffff816b6ef5>] ? ftrace_graph_caller+0x85/0x85
[ 408.706011] [<ffffffff81130c6c>] handle_irq_event+0x3c/0x60
[ 408.706011] [<ffffffff816b6ef5>] ? ftrace_graph_caller+0x85/0x85
[ 408.706011] [<ffffffff8135e466>] pci_bus_read_config_dword+0x86/0xb0
[ 408.706011] [<ffffffff81692c57>] ? rest_init+0x77/0x80
[ 408.706011] [<ffffffff81b45060>] ? start_kernel+0x439/0x45a
[ 408.706011] [<ffffffff81b44a30>] ? repair_env_string+0x5c/0x5c
[ 408.706011] [<ffffffff81b44120>] ? early_idt_handler_array+0x120/0x120
[ 408.706011] [<ffffffff81b445ef>] ? x86_64_start_reservations+0x24/0x26
[ 408.706011] [<ffffffff81b44740>] ? x86_64_start_kernel+0x14f/0x172
[ 377.243167] perf: interrupt took too long (5741 > 5628), lowering kernel.perf_event_max_sample_rate to 34000
[ 437.522697] perf: interrupt took too long (8551 > 7176), lowering kernel.perf_event_max_sample_rate to 23000
[ 463.908115] perf: interrupt took too long (11374 > 10688), lowering kernel.perf_event_max_sample_rate to 17000
[ 480.954277] INFO: task yum:6726 blocked for more than 120 seconds.
[ 480.991431] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 481.038470] yum D ffff880467bebf40 0 6726 6714 0x00000080
[ 481.081174] ffff88006489b850 0000000000000082 ffff880467bebf40 ffff88006489bfd8
[ 481.126085] ffff88006489bfd8 ffff88006489bfd8 ffff880467bebf40 ffff8802772656b0
[ 481.171087] 7fffffffffffffff 0000000000000002 0000000000000000 ffff880467bebf40
[ 481.216034] Call Trace:
[ 481.230832] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 481.266435] [<ffffffff816a94c9>] schedule+0x29/0x70
[ 481.296290] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 481.331966] [<ffffffff816a6fd9>] schedule_timeout+0x239/0x2c0
[ 481.367082] [<ffffffff8105bdd6>] ? prepare_ftrace_return+0xb6/0xe0
[ 481.404850] [<ffffffff816a88c1>] ? __down_common+0x104/0x104
[ 481.439492] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 481.475091] [<ffffffff816a8867>] __down_common+0xaa/0x104
[ 481.508098] [<ffffffff816b6ef5>] ? ftrace_graph_caller+0x85/0x85
[ 481.544778] [<ffffffff810b6691>] down+0x41/0x50
[ 481.577943] [<ffffffff816a88de>] __down+0x1d/0x1f
[ 481.611734] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 481.652576] [<ffffffffc02c421c>] xfs_buf_lock+0x3c/0xd0 [xfs]
[ 481.693178] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 481.734216] [<ffffffffc02c4420>] _xfs_buf_find+0x170/0x330 [xfs]
[ 481.775910] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 481.816266] [<ffffffffc02c460a>] xfs_buf_get_map+0x2a/0x240 [xfs]
[ 481.859119] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 481.899431] [<ffffffffc02c5180>] xfs_buf_read_map+0x30/0x160 [xfs]
[ 481.941875] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 481.982192] [<ffffffffc02f4ea1>] xfs_trans_read_buf_map+0x211/0x400 [xfs]
[ 482.027938] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 482.068655] [<ffffffffc02b8d6e>] xfs_imap_to_bp+0x6e/0xf0 [xfs]
[ 482.109275] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 482.149375] [<ffffffffc02d5aa5>] xfs_iunlink_remove+0x295/0x3c0 [xfs]
[ 482.193561] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 482.233577] [<ffffffffc02d9157>] xfs_ifree+0x47/0x100 [xfs]
[ 482.272198] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 482.312544] [<ffffffffc02d92e1>] xfs_inactive_ifree+0xd1/0x230 [xfs]
[ 482.355816] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 482.395936] [<ffffffffc02d94cb>] xfs_inactive+0x8b/0x130 [xfs]
[ 482.436204] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 482.477110] [<ffffffffc02dff65>] xfs_fs_destroy_inode+0x95/0x180 [xfs]
[ 482.521397] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 482.562184] [<ffffffff8121d548>] destroy_inode+0x38/0x60
[ 482.599372] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 482.639831] [<ffffffff8121d67a>] evict+0x10a/0x180
[ 482.673827] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 482.714694] [<ffffffff8121df29>] iput+0xf9/0x190
[ 482.748414] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 482.789294] [<ffffffff812186c8>] dentry_kill+0x168/0x1b0
[ 482.827374] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 482.868003] [<ffffffff81212a68>] SYSC_renameat2+0x518/0x5a0
[ 482.906672] [<ffffffff8121876e>] dput+0x5e/0xd0
[ 482.938986] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 482.979490] [<ffffffff8121397e>] SyS_rename+0x1e/0x20
[ 483.016292] [<ffffffff81158fcf>] ? ftrace_push_return_trace+0x4f/0xe0
[ 483.060909] [<ffffffff81213930>] ? SyS_link+0x20/0x20
[ 483.096075] [<ffffffff8121397e>] ? SyS_rename+0x1e/0x20
[ 483.132925] [<ffffffff8105bdd6>] ? prepare_ftrace_return+0xb6/0xe0
[ 483.174945] [<ffffffff81213930>] ? SyS_link+0x20/0x20
[ 483.210469] [<ffffffff8115947b>] ? __trace_graph_return+0x9b/0xb0
[ 483.252601] [<ffffffff8121393e>] SyS_renameat2+0xe/0x10
[ 483.288881] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 483.328689] [<ffffffff816b4fc9>] system_call_fastpath+0x16/0x1b
[ 483.369480] [<ffffffff816b6ef5>] ftrace_graph_caller+0x85/0x85
[ 507.786060] perf: interrupt took too long (14339 > 14217), lowering kernel.perf_event_max_sample_rate to 13000
[ 546.740390] perf: interrupt took too long (18151 > 17923), lowering kernel.perf_event_max_sample_rate to 11000
[ 588.710897] INFO: rcu_sched detected stalls on CPUs/tasks: { 0} (detected by 7, t=240042 jiffies, g=21144, c=21143, q=23204)
[ 588.711872] Task dump for CPU 0:
[ 588.711872] swapper/0 R running task 0 0 0 0x00000008
[ 588.711872] 0000000000000003 0000000000000003 ffffffff81aaf920 ffffffff819e4000
[ 588.711872] ffffffff819e7ed0 ffffffff816b6ef5 0000000000000000 ffffffff81b1c820
[ 588.711872] ffffffff819e4000 ffffffff819e4000 ffffffff819e4000 ffffffff819e4000
[ 588.711872] Call Trace:
[ 588.711872] [<ffffffff816b6ef5>] ? ftrace_graph_caller+0x85/0x85
[ 588.711872] [<ffffffff81130c05>] handle_irq_event_percpu+0x55/0x80
[ 588.711872] [<ffffffff816b6ef5>] ? ftrace_graph_caller+0x85/0x85
[ 588.711872] [<ffffffff81130c6c>] handle_irq_event+0x3c/0x60
[ 588.711872] [<ffffffff816b6ef5>] ? ftrace_graph_caller+0x85/0x85
[ 588.711872] [<ffffffff81130c6c>] handle_irq_event+0x3c/0x60
[ 588.711872] [<ffffffff81692c57>] ? rest_init+0x77/0x80
[ 588.711872] [<ffffffff81b45060>] ? start_kernel+0x439/0x45a
[ 588.711872] [<ffffffff81b44a30>] ? repair_env_string+0x5c/0x5c
[ 588.711872] [<ffffffff81b44120>] ? early_idt_handler_array+0x120/0x120
[ 588.711872] [<ffffffff81b445ef>] ? x86_64_start_reservations+0x24/0x26
[ 588.711872] [<ffffffff81b44740>] ? x86_64_start_kernel+0x14f/0x172
[-- MARK -- Wed Jul 12 02:45:00 2017]

log with 4.13-rc2 kernel
=============================

[ 876.272025] INFO: rcu_sched detected stalls on CPUs/tasks:
[ 876.272027] 0-...: (1 GPs behind) idle=992/140000000000000/0 softirq=66236/66237 fqs=11905
[ 876.272027] (detected by 12, t=60002 jiffies, g=20604, c=20603, q=23819)
[ 876.272027] Sending NMI from CPU 12 to CPUs 0:
[ 876.272027] NMI backtrace for cpu 0
[ 876.272027] CPU: 0 PID: 2106 Comm: stress Not tainted 4.13.0-rc2 #1
[ 876.272027] Hardware name: XXXXXXXXXXXXXXXXX
[ 876.272027] task: ffff9484e3a52c00 task.stack: ffffaa1c08888000
[ 876.272027] RIP: 0010:delay_tsc+0x23/0x60
[ 876.272027] RSP: 0000:ffffaa1c0888b768 EFLAGS: 00000083
[ 876.272027] RAX: 00000000000007a4 RBX: ffffffffb9f48d40 RCX: 000001eec7b47589
[ 876.272027] RDX: 000001eec7b47d2d RSI: 0000000000000000 RDI: 00000000000007d1
[ 876.272027] RBP: ffffaa1c0888b768 R08: ffff94820fc08890 R09: 000000002ce120d1
[ 876.272027] R10: 0000000497700000 R11: ffff9482f6c7c580 R12: 00000000000026f2
[ 876.272027] R13: 0000000000000020 R14: ffffffffb9ce4ad1 R15: ffffffffb9f48d40
[ 876.272027] FS: 00007fdb22cf9740(0000) GS:ffff9482f6200000(0000) knlGS:0000000000000000
[ 876.272027] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 876.272027] CR2: 00007f4dfe401010 CR3: 00000004656ef000 CR4: 00000000000006f0
[ 876.272027] Call Trace:
[ 876.272027] ? ftrace_graph_caller+0xa8/0xa8
[ 876.272027] __const_udelay+0x32/0x40
[ 876.272027] wait_for_xmitr+0x2c/0xa0
[ 876.272027] ? ftrace_graph_caller+0xa8/0xa8
[ 876.272027] serial8250_console_putchar+0x1c/0x30
[ 876.272027] ? wait_for_xmitr+0xa0/0xa0
[ 876.272027] ? ftrace_graph_caller+0xa8/0xa8
[ 876.272027] uart_console_write+0x31/0x70
[ 876.272027] ? ftrace_graph_caller+0xa8/0xa8
[ 876.272027] serial8250_console_write+0xd7/0x290
[ 876.272027] ? serial8250_console_write+0x5/0x290
[ 876.272027] ? ftrace_return_to_handler+0x9d/0xf0
[ 876.272027] ? univ8250_console_write+0x5/0x30
[ 876.272027] ? ftrace_graph_caller+0xa8/0xa8
[ 876.272027] univ8250_console_write+0x26/0x30
[ 876.272027] ? ftrace_graph_caller+0xa8/0xa8
[ 876.272027] console_unlock+0x3e6/0x4c0
[ 876.272027] ? ftrace_graph_caller+0xa8/0xa8
[ 876.272027] vprintk_emit+0x2f5/0x3a0
[ 876.272027] ? vprintk_emit+0x5/0x3a0
[ 876.272027] ? ftrace_graph_caller+0xa8/0xa8
[ 876.272027] vprintk_default+0x29/0x50
[ 876.272027] ? ftrace_graph_caller+0xa8/0xa8
[ 876.272027] vprintk_func+0x27/0x60
[ 876.272027] ? ftrace_graph_caller+0xa8/0xa8
[ 876.272027] printk+0x58/0x6f
[ 876.272027] ? ftrace_graph_caller+0xa8/0xa8
[ 876.272027] show_free_areas+0x255/0xa40
[ 876.272027] ? ftrace_graph_caller+0x78/0xa8
[ 876.272027] ? __trace_graph_return+0x88/0x90
[ 876.272027] ? ftrace_return_to_handler+0x9d/0xf0
[ 876.272027] ? show_free_areas+0x5/0xa40
[ 876.272027] ? ftrace_graph_caller+0xa8/0xa8
[ 876.272027] show_mem+0x2b/0xf0
[ 876.272027] warn_alloc+0x198/0x1c0
[ 876.272027] ? ftrace_graph_caller+0xa8/0xa8
[ 876.272027] __alloc_pages_slowpath+0x353/0xb90
[ 876.272027] ? __trace_graph_return+0x88/0x90
[ 876.272027] ? __alloc_pages_nodemask+0x102/0x290
[ 876.272027] ? ftrace_return_to_handler+0x9d/0xf0
[ 876.272027] __alloc_pages_nodemask+0x267/0x290
[ 876.272027] ? ftrace_graph_caller+0xa8/0xa8
[ 876.272027] alloc_pages_vma+0x7f/0x180
[ 876.272027] ? ftrace_graph_caller+0xa8/0xa8
[ 876.272027] __handle_mm_fault+0xbeb/0x1150
[ 876.272027] ? __trace_graph_return+0x88/0x90
[ 876.272027] ? ftrace_graph_caller+0xa8/0xa8
[ 876.272027] handle_mm_fault+0xd1/0x230
[ 876.272027] ? ftrace_graph_caller+0xa8/0xa8
[ 876.272027] __do_page_fault+0x22a/0x4a0
[ 876.272027] ? ftrace_graph_caller+0xa8/0xa8
[ 876.272027] do_page_fault+0x30/0x80
[ 876.272027] ? return_to_handler+0x15/0x27
[ 876.272027] page_fault+0x28/0x30
[ 876.272027] RIP: 0033:0x403072
[ 876.272027] RSP: 002b:00007fff358a2590 EFLAGS: 00010202
[ 876.272027] RAX: 00007fdb19e8e010 RBX: 0000000000000000 RCX: 00007fdb12420010
[ 876.272027] RDX: 0000000007a6e000 RSI: 0000000010001000 RDI: 0000000000000000
[ 876.272027] RBP: 00007fff358a25d0 R08: ffffffffffffffff R09: 0000000010000000
[ 876.272027] R10: 0000000000000022 R11: 0000000000001000 R12: 0000000000400dc0
[ 876.272027] R13: 00007fff358a27e0 R14: 0000000000000000 R15: 0000000000000000
[ 876.272027] Code: c3 0f 1f 80 00 00 00 00 e8 7b 1c 01 00 55 48 89 e5 65 8b 35 d0 be ca 46 0f ae e8 0f 31 48 89 d1 48 c1 e1 20 48 09 c1 eb 0d f3 90 <65> 8b 05 b6 be ca 46 39 c6 75 19 0f ae e8 0f 31 48 c1 e2 20 48
[ 876.319103] INFO: NMI handler (nmi_cpu_backtrace_handler) took too long to run: 1.808 msecs
[ 877.920915] stress: page allocation stalls for 11490ms, order:0, mode:0x14280ca(GFP_HIGHUSER_MOVABLE|__GFP_ZERO), nodemask=(null)
[ 877.920971] stress cpuset=/ mems_allowed=0-1
[ 877.921094] CPU: 18 PID: 2085 Comm: stress Not tainted 4.13.0-rc2 #1
[ 877.921108] Hardware name: XXXXXXXXXX
[ 877.921122] Call Trace:
[ 877.921170] ? ftrace_graph_caller+0xa8/0xa8
[ 877.921193] dump_stack+0x63/0x89
[ 877.921237] warn_alloc+0x114/0x1c0
[ 877.921352] ? ftrace_graph_caller+0xa8/0xa8
[ 877.921372] __alloc_pages_slowpath+0x353/0xb90
[ 877.921444] ? __trace_graph_return+0x88/0x90
[ 877.921489] ? __alloc_pages_nodemask+0x102/0x290
[ 877.921520] ? ftrace_return_to_handler+0x9d/0xf0
[ 877.921599] __alloc_pages_nodemask+0x267/0x290
[ 877.921701] ? ftrace_graph_caller+0xa8/0xa8
[ 877.921726] alloc_pages_vma+0x7f/0x180
[ 877.921790] ? ftrace_graph_caller+0xa8/0xa8
[ 877.921812] __handle_mm_fault+0xbeb/0x1150
[ 877.921839] ? __trace_graph_return+0x88/0x90
[ 877.921968] ? ftrace_graph_caller+0xa8/0xa8
[ 877.921986] handle_mm_fault+0xd1/0x230
[ 877.922028] ? ftrace_graph_caller+0xa8/0xa8
[ 877.922028] __do_page_fault+0x22a/0x4a0
[ 877.922028] ? ftrace_graph_caller+0xa8/0xa8
[ 877.922028] do_page_fault+0x30/0x80
[ 877.922028] ? return_to_handler+0x15/0x27
[ 877.922028] page_fault+0x28/0x30
[ 877.922028] RIP: 0033:0x403072
[ 877.922028] RSP: 002b:00007fff358a2590 EFLAGS: 00010202
[ 877.922028] RAX: 00007fdb1f99a010 RBX: 0000000000000000 RCX: 00007fdb12420010
[ 877.922028] RDX: 000000000d57a000 RSI: 0000000010001000 RDI: 0000000000000000
[ 877.922028] RBP: 00007fff358a25d0 R08: ffffffffffffffff R09: 0000000010000000
[ 877.922028] R10: 0000000000000022 R11: 0000000000001000 R12: 0000000000400dc0
[ 877.922028] R13: 00007fff358a27e0 R14: 0000000000000000 R15: 0000000000000000
[ 877.922541] warn_alloc_show_mem: 1 callbacks suppressed
[ 877.922554] Mem-Info:
[ 877.922594] active_anon:3380619 inactive_anon:424654 isolated_anon:27399

--
Regards
Pratyush