From 0766ce61fd7dd3ac61b6daca0df194285c6ba891 Mon Sep 17 00:00:00 2001 From: Dmitry Vyukov Date: Wed, 24 Apr 2019 00:02:57 +0300 Subject: pkg/report: fix stalls in RIP frame Even though we extract an anchor frame which usually higher up the stack, the anchor frame can be on RIP: line too. Account for that. --- pkg/report/linux.go | 6 +++ pkg/report/testdata/linux/report/373 | 73 ++++++++++++++++++++++++++++++++++++ 2 files changed, 79 insertions(+) create mode 100644 pkg/report/testdata/linux/report/373 (limited to 'pkg') diff --git a/pkg/report/linux.go b/pkg/report/linux.go index c63b5bfd8..b498dd503 100644 --- a/pkg/report/linux.go +++ b/pkg/report/linux.go @@ -870,6 +870,7 @@ var linuxOopses = []*oops{ fmt: "BUG: soft lockup in %[1]v", stack: &stackFmt{ parts: []*regexp.Regexp{ + linuxRipFrame, compile("Call Trace:"), parseStackTrace, }, @@ -1134,6 +1135,11 @@ var linuxOopses = []*oops{ fmt: "INFO: rcu detected stall in %[1]v", stack: &stackFmt{ parts: []*regexp.Regexp{ + compile("apic_timer_interrupt"), + linuxRipFrame, + parseStackTrace, + }, + parts2: []*regexp.Regexp{ compile("apic_timer_interrupt"), parseStackTrace, }, diff --git a/pkg/report/testdata/linux/report/373 b/pkg/report/testdata/linux/report/373 new file mode 100644 index 000000000..c355af9ee --- /dev/null +++ b/pkg/report/testdata/linux/report/373 @@ -0,0 +1,73 @@ +TITLE: INFO: rcu detected stall in rtc_timer_do_work + +[ 249.033000] INFO: rcu_sched self-detected stall on CPU +[ 249.038403] 1-....: (10499 ticks this GP) idle=35e/140000000000001/0 softirq=17797/17797 fqs=5227 +[ 249.047693] (t=10500 jiffies g=2803 c=2802 q=3452) +[ 249.052792] NMI backtrace for cpu 1 +[ 249.056404] CPU: 1 PID: 17 Comm: kworker/1:0 Not tainted 4.15.0 #10 +[ 249.062875] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011 +[ 249.072229] Workqueue: events rtc_timer_do_work +[ 249.076884] Call Trace: +[ 249.079451] +[ 249.081604] [] dump_stack+0x14d/0x20b +[ 249.087048] [] ? x86_vector_activate.cold+0xb8/0xb8 +[ 249.093726] [] nmi_cpu_backtrace.cold+0x19/0x98 +[ 249.100055] [] ? lapic_can_unplug_cpu.cold+0x38/0x38 +[ 249.106804] [] nmi_trigger_cpumask_backtrace+0x16a/0x17e +[ 249.113916] [] arch_trigger_cpumask_backtrace+0x14/0x20 +[ 249.120980] [] rcu_dump_cpu_stacks+0x189/0x1d5 +[ 249.127214] [] rcu_check_callbacks.cold+0x51c/0xc29 +[ 249.133888] [] ? irqtime_account_process_tick.isra.0+0x2cc/0x470 +[ 249.141773] [] update_process_times+0x32/0x80 +[ 249.147916] [] tick_sched_handle+0xa0/0x180 +[ 249.153888] [] tick_sched_timer+0x44/0x130 +[ 249.159768] [] __hrtimer_run_queues+0x307/0xd90 +[ 249.166111] [] ? tick_sched_do_timer+0x110/0x110 +[ 249.172529] [] ? hrtimer_start_range_ns+0xc20/0xc20 +[ 249.179213] [] hrtimer_interrupt+0x2ea/0x730 +[ 249.185287] [] smp_apic_timer_interrupt+0x144/0x5e0 +[ 249.191970] [] apic_timer_interrupt+0x8e/0xa0 +[ 249.198108] +[ 249.200451] RIP: 0010:rtc_timer_do_work+0x21a/0x650 +[ 249.205465] RSP: 0018:ffff8801d930bb70 EFLAGS: 00000a02 ORIG_RAX: ffffffffffffff12 +[ 249.213175] RAX: ffffffff83456f90 RBX: dffffc0000000000 RCX: 1ffff1003a100b1c +[ 249.220455] RDX: 1ffff1003a100b26 RSI: ffffffff834572d7 RDI: ffff8801d0805930 +[ 249.228144] RBP: ffff8801d930bd00 R08: ffff8801d92fe100 R09: 0000000000000000 +[ 249.235407] R10: 0000000000000000 R11: 0000000000000000 R12: ffff8801d0805938 +[ 249.242751] R13: 2b64ae95de020000 R14: ffff8801d0805950 R15: ffff8801d0805960 +[ 249.250020] [] ? rtc_aie_update_irq+0x30/0x30 +[ 249.256172] [] ? rtc_timer_do_work+0x207/0x650 +[ 249.262392] [] ? retint_kernel+0x10/0x10 +[ 249.268094] [] ? rtc_aie_update_irq+0x30/0x30 +[ 249.274227] [] ? rtc_pie_update_irq+0x110/0x110 +[ 249.280536] [] ? __lock_is_held+0xba/0x140 +[ 249.286497] [] process_one_work+0x886/0x1650 +[ 249.292543] [] ? rtc_pie_update_irq+0x110/0x110 +[ 249.298850] [] ? process_one_work+0x886/0x1650 +[ 249.305280] [] ? __schedule+0x59b/0x1d40 +[ 249.310981] [] ? pwq_dec_nr_in_flight+0x310/0x310 +[ 249.317483] [] ? lock_acquire+0x10c/0x330 +[ 249.323298] [] ? _raw_spin_unlock_irq+0x28/0x40 +[ 249.329617] [] worker_thread+0x653/0x1150 +[ 249.335431] [] kthread+0x348/0x420 +[ 249.340610] [] ? process_one_work+0x1650/0x1650 +[ 249.346921] [] ? kthread_create_worker_on_cpu+0xf0/0xf0 +[ 249.353923] [] ret_from_fork+0x61/0x70 +[ 255.918447] INFO: rcu_sched detected expedited stalls on CPUs/tasks: { 1-... } 10879 jiffies s: 529 root: 0x2/. +[ 255.929073] blocking rcu_node structures: +[ 255.933240] Task dump for CPU 1: +[ 255.936606] kworker/1:0 R running task on cpu 1 11096 17 2 0x80000008 144014221083 +[ 255.945801] Workqueue: events rtc_timer_do_work +[ 255.950691] Call Trace: +[ 255.953500] [] ? process_one_work+0x886/0x1650 +[ 255.959955] [] ? rtc_pie_update_irq+0x110/0x110 +[ 255.966286] [] ? process_one_work+0x886/0x1650 +[ 255.972682] [] ? __schedule+0x59b/0x1d40 +[ 255.978449] [] ? pwq_dec_nr_in_flight+0x310/0x310 +[ 255.984954] [] ? lock_acquire+0x10c/0x330 +[ 255.990805] [] ? _raw_spin_unlock_irq+0x28/0x40 +[ 255.997150] [] ? worker_thread+0x653/0x1150 +[ 256.003229] [] ? kthread+0x348/0x420 +[ 256.008664] [] ? process_one_work+0x1650/0x1650 +[ 256.015102] [] ? kthread_create_worker_on_cpu+0xf0/0xf0 +[ 256.022185] [] ? ret_from_fork+0x61/0x70 -- cgit mrf-deployment