----- On Apr 30, 2020, at 10:11 AM, Joerg Roedel jroe...@suse.de wrote:
> Hi,
>
> On Wed, Apr 29, 2020 at 10:07:31AM -0400, Steven Rostedt wrote:
>> Talking with Mathieu about this on IRC, he pointed out that my code does
>> have a vzalloc() that is called:
>>
>> in trace_pid_write()
>>
>> pid_list->pids = vzalloc((pid_list->pid_max + 7) >> 3);
>>
>> This is done when -P1,2 is on the trace-cmd command line.
>
> Okay, tracked it down, some instrumentation in the page-fault and
> double-fault handler gave me the stack-traces. Here is what happens:
>
> As already pointed out, it all happens because of page-faults on the
> vzalloc'ed pid bitmap. It starts with this stack-trace:
>
> RIP: 0010:trace_event_ignore_this_pid+0x23/0x30
> Code: e9 c2 4b 6b 00 cc cc 48 8b 57 28 48 8b 8a b8 00 00 00 48 8b 82 c0 00 00
> 00
> 48 85 c0 74 11 48 8b 42 28 65 48 03 05 5d 9c e6 7e <0f> b6 40 7c c3 48 85 c9
> 75
> ea f3 c3 90 48 8b 4f 70 48 83 02 01 48
> RSP: 0018:ffffc90000673bd8 EFLAGS: 00010082
> RAX: ffffe8ffffd8c870 RBX: 0000000000000203 RCX: ffff88810734ca90
> RDX: ffff888451578000 RSI: ffffffff820f3d2a RDI: ffff888453594d68
> RBP: ffff888453594d68 R08: 000000000001845e R09: ffffffff81114ba0
> R10: 0000000000000000 R11: 000000000000000e R12: 4000000000000000
> R13: ffffffff820f3d2a R14: 000000000001845e R15: 4000000000000002
> ? trace_event_raw_event_rcu_fqs+0xa0/0xa0
> trace_event_raw_event_rcu_dyntick+0x89/0xa0
> ? trace_event_raw_event_rcu_dyntick+0x89/0xa0
> ? trace_event_raw_event_rcu_dyntick+0x89/0xa0
> ? insn_get_prefixes.part.2+0x174/0x2d0
> rcu_irq_enter+0xf0/0x1d0
> rcu_irq_enter_irqson+0x21/0x50
> switch_mm_irqs_off+0x43c/0x570
> ? do_one_initcall+0x51/0x210
> __text_poke+0x1a9/0x470
> text_poke_bp_batch+0x73/0x180
> text_poke_flush+0x43/0x50
> arch_jump_label_transform_apply+0x16/0x30
> __static_key_slow_dec_cpuslocked+0x42/0x50
> static_key_slow_dec+0x1f/0x50
> tracepoint_probe_unregister+0x1e2/0x220
> trace_event_reg+0x6a/0x80
> __ftrace_event_enable_disable+0x1ca/0x240
> __ftrace_set_clr_event_nolock+0xe1/0x140
> __ftrace_set_clr_event+0x3d/0x60
> system_enable_write+0x76/0xa0
> vfs_write+0xad/0x1a0
> ? rcu_irq_exit+0xb8/0x170
> ksys_write+0x48/0xb0
> do_syscall_64+0x60/0x200
> entry_SYSCALL_64_after_hwframe+0x49/0xb3
> RIP: 0033:0x7f875b0ecdb0
> Code: Bad RIP value.
> RSP: 002b:00007ffc746be918 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
> RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f875b0ecdb0
> RDX: 0000000000000001 RSI: 00007ffc746be93f RDI: 0000000000000004
> RBP: 00007ffc746be9a0 R08: 636172742f6c6500 R09: 0000000002242ee0
> R10: 6f662f7365636e61 R11: 0000000000000246 R12: 000000000040a4b0
> R13: 00007ffc746bebd0 R14: 0000000000000000 R15: 0000000000000000
>
> I havn't figured out how rcu_irq_enter() calls down into
> trace_event_raw_event_rcu_dyntick() and further into
> trace_event_ignore_this_pid(), but the stacktrace shows it does.
>
> So trace_event_ignore_this_pid() faults on the vzalloc()'ed memory, calling
> into the page-fault handler. What happens there is:
>
> RIP: 0010:trace_event_ignore_this_pid+0x23/0x30
> Code: e9 c2 4b 6b 00 cc cc 48 8b 57 28 48 8b 8a b8 00 00 00 48 8b 82 c0 00 00
> 00
> 48 85 c0 74 11 48 8b 42 28 65 48 03 05 5d 9c e6 7e <0f> b6 40 7c c3 48 85 c9
> 75
> ea f3 c3 90 48 8b 4f 70 48 83 02 01 48
> RSP: 0018:ffffc90000673a50 EFLAGS: 00010082
> RAX: ffffe8ffffd8c870 RBX: 0000000000000203 RCX: ffff88810734ca90
> RDX: ffff888451578000 RSI: ffffe8ffffd8c8ec RDI: ffff88844fd98478
> RBP: ffff88844fd98478 R08: 0000000000000000 R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000000 R12: ffffe8ffffd8c8ec
> R13: 0000000000000000 R14: ffffc90000673b28 R15: 0000000000000000
> trace_event_raw_event_x86_exceptions+0x87/0xa0
> ? trace_event_buffer_lock_reserve+0x6e/0x110
> do_page_fault+0x45e/0x630
> ? trace_hardirqs_off_thunk+0x1a/0x37
> page_fault+0x43/0x50
>
> The page-fault handler calls a tracing function which again ends up in
> trace_event_ignore_this_pid(), where it faults again. From here on the CPU is
> in
> a page-fault loop, which continues until the stack overflows (with
> CONFIG_VMAP_STACK).
>
> Then there is no mapped stack anymore, so the page-fault results in a
> double-fault, which uses an IST stack. The double-fault handler does
> ist_enter(), which calls into rcu_nmi_enter(), which also has trace-events
> down
> its call-path. I have no stack-trace for this, but what likely happens
> now is that it page-faults again while on the IST stack and the
> page-fault loops until the #DF IST stack overflows. Then the next #DF
> happens and the stack pointer is reset to the top of the #DF IST stack,
> starting the loop over again. This loops forever, causing the hang.
I suspect it's called by:
include/linux/trace_event.h:trace_trigger_soft_disabled():
static inline bool
trace_trigger_soft_disabled(struct trace_event_file *file)
{
unsigned long eflags = file->flags;
if (!(eflags & EVENT_FILE_FL_TRIGGER_COND)) {
if (eflags & EVENT_FILE_FL_TRIGGER_MODE)
event_triggers_call(file, NULL, NULL);
if (eflags & EVENT_FILE_FL_SOFT_DISABLED)
return true;
if (eflags & EVENT_FILE_FL_PID_FILTER)
return trace_event_ignore_this_pid(file);
}
return false;
}
Thanks,
Mathieu
>
> Regards,
>
> Joerg
--
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com
