Re: [PATCH 2/6] pstore: Add event tracing support

[Sai Prakash Ranjan <saiprakash.ranjan@codeaurora.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] [<ffffff800808a91c>] dump_backtrace+0x0/0x254
[    0.444309] [<ffffff800808ab90>] show_stack+0x20/0x28
[    0.444320] [<ffffff8008913794>] dump_stack+0x90/0xb0
[    0.444329] [<ffffff80080d9080>] ___might_sleep+0x110/0x128
[    0.444332] [<ffffff80080d9110>] __might_sleep+0x78/0x88
[    0.444343] [<ffffff80081b83c4>] __alloc_pages_nodemask+0xe4/0xef4
[    0.444351] [<ffffff80081da1ac>] kmalloc_order+0x34/0x5c
[    0.444355] [<ffffff80081da210>] kmalloc_order_trace+0x3c/0x10c
[    0.444366] [<ffffff800832b5fc>] pstore_event_call+0x64/0x148
[    0.444374] [<ffffff800817b754>] trace_event_buffer_commit+0x230/0x25c
[    0.444379] [<ffffff80080d774c>] 
trace_event_raw_event_sched_stat_runtime+0x78/0xc8
[    0.444385] [<ffffff80080e4d5c>] update_curr+0x184/0x208
[    0.444388] [<ffffff80080e5fc0>] task_tick_fair+0x58/0x478
[    0.444394] [<ffffff80080dd834>] scheduler_tick+0x78/0xb4
[    0.444404] [<ffffff800811d714>] update_process_times+0x48/0x5c
[    0.444411] [<ffffff800812e198>] tick_sched_handle.isra.9+0x58/0x6c
[    0.444415] [<ffffff800812e1f4>] tick_sched_timer+0x48/0x84
[    0.444420] [<ffffff800811e218>] __hrtimer_run_queues+0x1f0/0x31c
[    0.444423] [<ffffff800811eb78>] hrtimer_interrupt+0xa8/0x1c8
[    0.444435] [<ffffff8008720bc8>] arch_timer_handler_phys+0x3c/0x48
[    0.444443] [<ffffff800810a750>] handle_percpu_devid_irq+0x124/0x27c
[    0.444448] [<ffffff8008104e48>] generic_handle_irq+0x30/0x44
[    0.444452] [<ffffff80081054dc>] __handle_domain_irq+0x90/0xbc
[    0.444457] [<ffffff8008081250>] 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] [<ffffff8008082a30>] el1_irq+0xb0/0x124
[    0.444510] [<ffffff80081030dc>] console_unlock+0x27c/0x4e0
[    0.444512] [<ffffff80081035b0>] vprintk_emit+0x270/0x290
[    0.444515] [<ffffff80081037c0>] vprintk_default+0x7c/0x84
[    0.444518] [<ffffff8008104db8>] vprintk_func+0x154/0x180
[    0.444522] [<ffffff8008104448>] printk+0x80/0xa0
[    0.444525] [<ffffff800832a944>] pstore_register+0x148/0x1f8
[    0.444529] [<ffffff800832cb5c>] ramoops_probe+0x56c/0x6e8
[    0.444537] [<ffffff8008551d64>] platform_drv_probe+0x58/0xa4
[    0.444544] [<ffffff800854f9c4>] driver_probe_device+0x204/0x438
[    0.444547] [<ffffff800854fe44>] __device_attach_driver+0xf8/0x110
[    0.444552] [<ffffff800854d6dc>] bus_for_each_drv+0x98/0xc8
[    0.444556] [<ffffff800854f6ec>] __device_attach+0xac/0x150
[    0.444559] [<ffffff800854fe80>] device_initial_probe+0x24/0x30
[    0.444563] [<ffffff800854e96c>] bus_probe_device+0x38/0x98
[    0.444567] [<ffffff800854c478>] device_add+0x318/0x560
[    0.444575] [<ffffff8008737440>] of_device_add+0x44/0x50
[    0.444579] [<ffffff80087379f8>] 
of_platform_device_create_pdata+0x8c/0xc4
[    0.444582] [<ffffff8008737a64>] of_platform_device_create+0x34/0x40
[    0.444593] [<ffffff8008e3e9e8>] 
of_platform_default_populate_init+0x58/0xa8
[    0.444596] [<ffffff8008083558>] do_one_initcall+0xa0/0x138
[    0.444605] [<ffffff8008e00f10>] kernel_init_freeable+0x198/0x24c
[    0.444610] [<ffffff8008925a7c>] kernel_init+0x18/0x108
[    0.444616] [<ffffff800808477c>] ret_from_fork+0x10/0x18
[    0.856135] console [pstore-1] enabled