On Tue, 9 Oct 2018 23:52:14 +0530 Sai Prakash Ranjan <saiprakash.ranjan@xxxxxxxxxxxxxx> wrote: > >>> Also regarding the warning on "event_call->event.funcs->trace()" call, > >>> I see it everytime without spinlock. Also we see output_printk using > >>> spinlock when making this call. I could not find a way to pass event > >>> buffer size and allocate in pstore. Steven can give some hints with this > >>> I guess. > > > > The spinlock warning you're talking about is this one correct? > > > > [ 1.389382] WARNING: CPU: 2 PID: 2 at kernel/trace/trace_output.c:289 trace_raw_output_prep+0x18/0xa0 > > [ 1.389416] Modules linked in: > > which you reported here: > > https://lkml.org/lkml/2018/9/22/319 > > > > This warning happens I think because you're trying to format the events while > > the trace events are being generated. You said you got this warning when you > > didn't use the spinlock. I believe the spinlocking prevents such races, but > > if you didn't need to format the events into text into text in the first > > place, then you wouldn't need such locking at all. > > > > I believe ftrace doesn't have such issues because such locking is taken care > > off when the trace events are formatted from the trace buffer and displayed, > > but I could be wrong about that.. I'll let Steven provide more inputs about > > how this warning can occur. > Yes Steven would have more insight on this warning. Correct. Formatting should not be done at the location of recording (it's way too much overhead). Even trace_printk() doesn't format string at the execution path, but does so at the presentation path (reading the buffer, via reads of the trace file, or in trace-cmd post processing of the trace.dat file). trace_printk() uses vbin_printf() which doesn't do printf() conversions, but instead only saves the format string and the raw values into the buffer. Then in uses bstr_printf() that takes the format string and raw values to produce the "printf()" output you know and love. -- Steve
