From mboxrd@z Thu Jan 1 00:00:00 1970 From: Sai Prakash Ranjan Subject: Re: [PATCH 2/6] pstore: Add event tracing support Date: Tue, 11 Sep 2018 16:16:01 +0530 Message-ID: <444d7b13-2653-ba0e-e9e6-a448fded2a77@codeaurora.org> References: Mime-Version: 1.0 Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 7bit Return-path: In-Reply-To: Content-Language: en-US Sender: linux-kernel-owner@vger.kernel.org To: Steven Rostedt , Ingo Molnar , Laura Abbott , Kees Cook , Anton Vorontsov , Rob Herring , devicetree@vger.kernel.org, Colin Cross , Jason Baron , Tony Luck , Arnd Bergmann , Catalin Marinas , Will Deacon , Joel Fernandes , Masami Hiramatsu , Joe Perches , Jim Cromie Cc: Rajendra Nayak , Vivek Gautam , Sibi Sankar , linux-arm-kernel@lists.infradead.org, linux-kernel@vger.kernel.org, linux-arm-msm@vger.kernel.org, Greg Kroah-Hartman , Ingo Molnar , Tom Zanussi , Prasad Sodagudi , tsoni@codeaurora.org, Bryan Huntsman , Tingwei Zhang List-Id: linux-arm-msm@vger.kernel.org On 9/9/2018 1:57 AM, Sai Prakash Ranjan wrote: > +void notrace pstore_event_call(struct trace_event_buffer *fbuffer) > +{ > + struct trace_iterator *iter; > + struct trace_seq *s; > + struct trace_event_call *event_call; > + struct pstore_record record; > + struct trace_event *event; > + struct seq_buf *seq; > + unsigned long flags; > + > + if (!psinfo) > + return; > + > + if (unlikely(oops_in_progress)) > + return; > + > + pstore_record_init(&record, psinfo); > + record.type = PSTORE_TYPE_EVENT; > + > + iter = kmalloc(sizeof(*iter), GFP_KERNEL); > + if (!iter) > + return; > + > + event_call = fbuffer->trace_file->event_call; > + if (!event_call || !event_call->event.funcs || > + !event_call->event.funcs->trace) > + goto fail_event; > + > + event = &fbuffer->trace_file->event_call->event; > + > + spin_lock_irqsave(&psinfo->buf_lock, flags); > + > + trace_seq_init(&iter->seq); > + iter->ent = fbuffer->entry; > + event_call->event.funcs->trace(iter, 0, event); > + trace_seq_putc(&iter->seq, 0); > + > + if (seq->size > psinfo->bufsize) > + seq->size = psinfo->bufsize; > + > + s = &iter->seq; > + seq = &s->seq; > + > + record.buf = (char *)(seq->buffer); > + record.size = seq->len; > + psinfo->write(&record); > + > + spin_unlock_irqrestore(&psinfo->buf_lock, flags); > + > +fail_event: > + kfree(iter); > +} > + > When tracing sched events on sdm845 mtp, I hit below bug repeatedly. Seems like pstore_event_call can be called in atomic context. I will respin the below fix in next version of the patch. Reviews on other parts would be appreciated, thanks. diff --git a/fs/pstore/ftrace.c b/fs/pstore/ftrace.c index d47dc93ac098..a497cf782ee8 100644 --- a/fs/pstore/ftrace.c +++ b/fs/pstore/ftrace.c @@ -73,6 +73,7 @@ void notrace pstore_event_call(struct trace_event_buffer *fbuffer) struct trace_event *event; struct seq_buf *seq; unsigned long flags; + gfp_t gfpflags; if (!psinfo) return; @@ -83,7 +84,9 @@ void notrace pstore_event_call(struct trace_event_buffer *fbuffer) pstore_record_init(&record, psinfo); record.type = PSTORE_TYPE_EVENT; - iter = kmalloc(sizeof(*iter), GFP_KERNEL); + gfpflags = (in_atomic() || irqs_disabled()) ? GFP_ATOMIC : GFP_KERNEL; + + iter = kmalloc(sizeof(*iter), gfpflags); if (!iter) return; Backtrace: [ 0.433204] clocksource: Switched to clocksource arch_sys_counter [ 0.440035] pstore: using zlib compression [ 0.444265] BUG: sleeping function called from invalid context at /mnt/host/source/src/third_party/kernel/v4.14/mm/page_alloc.c:4134 [ 0.444268] in_atomic(): 1, irqs_disabled(): 128, pid: 1, name: swapper/0 [ 0.444277] CPU: 2 PID: 1 Comm: swapper/0 Not tainted 4.14.65 #19 [ 0.444286] Call trace: [ 0.444303] [] dump_backtrace+0x0/0x254 [ 0.444309] [] show_stack+0x20/0x28 [ 0.444320] [] dump_stack+0x90/0xb0 [ 0.444329] [] ___might_sleep+0x110/0x128 [ 0.444332] [] __might_sleep+0x78/0x88 [ 0.444343] [] __alloc_pages_nodemask+0xe4/0xef4 [ 0.444351] [] kmalloc_order+0x34/0x5c [ 0.444355] [] kmalloc_order_trace+0x3c/0x10c [ 0.444366] [] pstore_event_call+0x64/0x148 [ 0.444374] [] trace_event_buffer_commit+0x230/0x25c [ 0.444379] [] trace_event_raw_event_sched_stat_runtime+0x78/0xc8 [ 0.444385] [] update_curr+0x184/0x208 [ 0.444388] [] task_tick_fair+0x58/0x478 [ 0.444394] [] scheduler_tick+0x78/0xb4 [ 0.444404] [] update_process_times+0x48/0x5c [ 0.444411] [] tick_sched_handle.isra.9+0x58/0x6c [ 0.444415] [] tick_sched_timer+0x48/0x84 [ 0.444420] [] __hrtimer_run_queues+0x1f0/0x31c [ 0.444423] [] hrtimer_interrupt+0xa8/0x1c8 [ 0.444435] [] arch_timer_handler_phys+0x3c/0x48 [ 0.444443] [] handle_percpu_devid_irq+0x124/0x27c [ 0.444448] [] generic_handle_irq+0x30/0x44 [ 0.444452] [] __handle_domain_irq+0x90/0xbc [ 0.444457] [] gic_handle_irq+0x144/0x1ac [ 0.444460] Exception stack(0xffffff800805b5f0 to 0xffffff800805b730) [ 0.444465] b5e0: 0000000000000040 ffffffc0fb2d8000 [ 0.444468] b600: 00000040f7046000 ffffffffffffffff 0000000000000000 0000000000000000 [ 0.444472] b620: ffffffc0fb288f00 0720072007200720 0720072007200720 0720072007200720 [ 0.444475] b640: 0720072007200720 0720072007200720 0720072007200720 0720072007200720 [ 0.444479] b660: 0720072007200720 0000000000000010 0000000000000003 0000000000004600 [ 0.444482] b680: 000000000000000c ffffff8009152000 ffffff8009192000 000000000000002e [ 0.444485] b6a0: ffffff8009192458 0000000000000000 0000000000000000 ffffff8009031410 [ 0.444490] b6c0: ffffff8008ec7018 ffffff8009031410 ffffff8009031000 ffffff800805b730 [ 0.444495] b6e0: ffffff80081030d4 ffffff800805b730 ffffff80081030dc 0000000060c00049 [ 0.444498] b700: 0000000000000000 ffffff80090916a0 ffffffffffffffff ffffff8008ec7018 [ 0.444502] b720: ffffff800805b730 ffffff80081030dc [ 0.444506] [] el1_irq+0xb0/0x124 [ 0.444510] [] console_unlock+0x27c/0x4e0 [ 0.444512] [] vprintk_emit+0x270/0x290 [ 0.444515] [] vprintk_default+0x7c/0x84 [ 0.444518] [] vprintk_func+0x154/0x180 [ 0.444522] [] printk+0x80/0xa0 [ 0.444525] [] pstore_register+0x148/0x1f8 [ 0.444529] [] ramoops_probe+0x56c/0x6e8 [ 0.444537] [] platform_drv_probe+0x58/0xa4 [ 0.444544] [] driver_probe_device+0x204/0x438 [ 0.444547] [] __device_attach_driver+0xf8/0x110 [ 0.444552] [] bus_for_each_drv+0x98/0xc8 [ 0.444556] [] __device_attach+0xac/0x150 [ 0.444559] [] device_initial_probe+0x24/0x30 [ 0.444563] [] bus_probe_device+0x38/0x98 [ 0.444567] [] device_add+0x318/0x560 [ 0.444575] [] of_device_add+0x44/0x50 [ 0.444579] [] of_platform_device_create_pdata+0x8c/0xc4 [ 0.444582] [] of_platform_device_create+0x34/0x40 [ 0.444593] [] of_platform_default_populate_init+0x58/0xa8 [ 0.444596] [] do_one_initcall+0xa0/0x138 [ 0.444605] [] kernel_init_freeable+0x198/0x24c [ 0.444610] [] kernel_init+0x18/0x108 [ 0.444616] [] ret_from_fork+0x10/0x18 [ 0.856135] console [pstore-1] enabled From mboxrd@z Thu Jan 1 00:00:00 1970 From: saiprakash.ranjan@codeaurora.org (Sai Prakash Ranjan) Date: Tue, 11 Sep 2018 16:16:01 +0530 Subject: [PATCH 2/6] pstore: Add event tracing support In-Reply-To: References: Message-ID: <444d7b13-2653-ba0e-e9e6-a448fded2a77@codeaurora.org> To: linux-arm-kernel@lists.infradead.org List-Id: linux-arm-kernel.lists.infradead.org On 9/9/2018 1:57 AM, Sai Prakash Ranjan wrote: > +void notrace pstore_event_call(struct trace_event_buffer *fbuffer) > +{ > + struct trace_iterator *iter; > + struct trace_seq *s; > + struct trace_event_call *event_call; > + struct pstore_record record; > + struct trace_event *event; > + struct seq_buf *seq; > + unsigned long flags; > + > + if (!psinfo) > + return; > + > + if (unlikely(oops_in_progress)) > + return; > + > + pstore_record_init(&record, psinfo); > + record.type = PSTORE_TYPE_EVENT; > + > + iter = kmalloc(sizeof(*iter), GFP_KERNEL); > + if (!iter) > + return; > + > + event_call = fbuffer->trace_file->event_call; > + if (!event_call || !event_call->event.funcs || > + !event_call->event.funcs->trace) > + goto fail_event; > + > + event = &fbuffer->trace_file->event_call->event; > + > + spin_lock_irqsave(&psinfo->buf_lock, flags); > + > + trace_seq_init(&iter->seq); > + iter->ent = fbuffer->entry; > + event_call->event.funcs->trace(iter, 0, event); > + trace_seq_putc(&iter->seq, 0); > + > + if (seq->size > psinfo->bufsize) > + seq->size = psinfo->bufsize; > + > + s = &iter->seq; > + seq = &s->seq; > + > + record.buf = (char *)(seq->buffer); > + record.size = seq->len; > + psinfo->write(&record); > + > + spin_unlock_irqrestore(&psinfo->buf_lock, flags); > + > +fail_event: > + kfree(iter); > +} > + > When tracing sched events on sdm845 mtp, I hit below bug repeatedly. Seems like pstore_event_call can be called in atomic context. I will respin the below fix in next version of the patch. Reviews on other parts would be appreciated, thanks. diff --git a/fs/pstore/ftrace.c b/fs/pstore/ftrace.c index d47dc93ac098..a497cf782ee8 100644 --- a/fs/pstore/ftrace.c +++ b/fs/pstore/ftrace.c @@ -73,6 +73,7 @@ void notrace pstore_event_call(struct trace_event_buffer *fbuffer) struct trace_event *event; struct seq_buf *seq; unsigned long flags; + gfp_t gfpflags; if (!psinfo) return; @@ -83,7 +84,9 @@ void notrace pstore_event_call(struct trace_event_buffer *fbuffer) pstore_record_init(&record, psinfo); record.type = PSTORE_TYPE_EVENT; - iter = kmalloc(sizeof(*iter), GFP_KERNEL); + gfpflags = (in_atomic() || irqs_disabled()) ? GFP_ATOMIC : GFP_KERNEL; + + iter = kmalloc(sizeof(*iter), gfpflags); if (!iter) return; Backtrace: [ 0.433204] clocksource: Switched to clocksource arch_sys_counter [ 0.440035] pstore: using zlib compression [ 0.444265] BUG: sleeping function called from invalid context at /mnt/host/source/src/third_party/kernel/v4.14/mm/page_alloc.c:4134 [ 0.444268] in_atomic(): 1, irqs_disabled(): 128, pid: 1, name: swapper/0 [ 0.444277] CPU: 2 PID: 1 Comm: swapper/0 Not tainted 4.14.65 #19 [ 0.444286] Call trace: [ 0.444303] [] dump_backtrace+0x0/0x254 [ 0.444309] [] show_stack+0x20/0x28 [ 0.444320] [] dump_stack+0x90/0xb0 [ 0.444329] [] ___might_sleep+0x110/0x128 [ 0.444332] [] __might_sleep+0x78/0x88 [ 0.444343] [] __alloc_pages_nodemask+0xe4/0xef4 [ 0.444351] [] kmalloc_order+0x34/0x5c [ 0.444355] [] kmalloc_order_trace+0x3c/0x10c [ 0.444366] [] pstore_event_call+0x64/0x148 [ 0.444374] [] trace_event_buffer_commit+0x230/0x25c [ 0.444379] [] trace_event_raw_event_sched_stat_runtime+0x78/0xc8 [ 0.444385] [] update_curr+0x184/0x208 [ 0.444388] [] task_tick_fair+0x58/0x478 [ 0.444394] [] scheduler_tick+0x78/0xb4 [ 0.444404] [] update_process_times+0x48/0x5c [ 0.444411] [] tick_sched_handle.isra.9+0x58/0x6c [ 0.444415] [] tick_sched_timer+0x48/0x84 [ 0.444420] [] __hrtimer_run_queues+0x1f0/0x31c [ 0.444423] [] hrtimer_interrupt+0xa8/0x1c8 [ 0.444435] [] arch_timer_handler_phys+0x3c/0x48 [ 0.444443] [] handle_percpu_devid_irq+0x124/0x27c [ 0.444448] [] generic_handle_irq+0x30/0x44 [ 0.444452] [] __handle_domain_irq+0x90/0xbc [ 0.444457] [] gic_handle_irq+0x144/0x1ac [ 0.444460] Exception stack(0xffffff800805b5f0 to 0xffffff800805b730) [ 0.444465] b5e0: 0000000000000040 ffffffc0fb2d8000 [ 0.444468] b600: 00000040f7046000 ffffffffffffffff 0000000000000000 0000000000000000 [ 0.444472] b620: ffffffc0fb288f00 0720072007200720 0720072007200720 0720072007200720 [ 0.444475] b640: 0720072007200720 0720072007200720 0720072007200720 0720072007200720 [ 0.444479] b660: 0720072007200720 0000000000000010 0000000000000003 0000000000004600 [ 0.444482] b680: 000000000000000c ffffff8009152000 ffffff8009192000 000000000000002e [ 0.444485] b6a0: ffffff8009192458 0000000000000000 0000000000000000 ffffff8009031410 [ 0.444490] b6c0: ffffff8008ec7018 ffffff8009031410 ffffff8009031000 ffffff800805b730 [ 0.444495] b6e0: ffffff80081030d4 ffffff800805b730 ffffff80081030dc 0000000060c00049 [ 0.444498] b700: 0000000000000000 ffffff80090916a0 ffffffffffffffff ffffff8008ec7018 [ 0.444502] b720: ffffff800805b730 ffffff80081030dc [ 0.444506] [] el1_irq+0xb0/0x124 [ 0.444510] [] console_unlock+0x27c/0x4e0 [ 0.444512] [] vprintk_emit+0x270/0x290 [ 0.444515] [] vprintk_default+0x7c/0x84 [ 0.444518] [] vprintk_func+0x154/0x180 [ 0.444522] [] printk+0x80/0xa0 [ 0.444525] [] pstore_register+0x148/0x1f8 [ 0.444529] [] ramoops_probe+0x56c/0x6e8 [ 0.444537] [] platform_drv_probe+0x58/0xa4 [ 0.444544] [] driver_probe_device+0x204/0x438 [ 0.444547] [] __device_attach_driver+0xf8/0x110 [ 0.444552] [] bus_for_each_drv+0x98/0xc8 [ 0.444556] [] __device_attach+0xac/0x150 [ 0.444559] [] device_initial_probe+0x24/0x30 [ 0.444563] [] bus_probe_device+0x38/0x98 [ 0.444567] [] device_add+0x318/0x560 [ 0.444575] [] of_device_add+0x44/0x50 [ 0.444579] [] of_platform_device_create_pdata+0x8c/0xc4 [ 0.444582] [] of_platform_device_create+0x34/0x40 [ 0.444593] [] of_platform_default_populate_init+0x58/0xa8 [ 0.444596] [] do_one_initcall+0xa0/0x138 [ 0.444605] [] kernel_init_freeable+0x198/0x24c [ 0.444610] [] kernel_init+0x18/0x108 [ 0.444616] [] ret_from_fork+0x10/0x18 [ 0.856135] console [pstore-1] enabled