| Message ID | 20221125162327.297440-1-john@metanate.com |
|---|---|
| State | Accepted |
| Commit | e4baf845364637bfe56228b282b8795a77d0f8af |
| Headers | show |
| Series | ALSA: pcm: fix tracing reason in hw_ptr_error | expand |
On Mon, 28 Nov 2022 11:50:52 +0100, John Keeping wrote: > > On Sat, Nov 26, 2022 at 12:51:53PM +0900, Takashi Sakamoto wrote: > > Hi, > > > > On Fri, Nov 25, 2022 at 04:23:26PM +0000, John Keeping wrote: > > > Strings need to be specially marked in trace events to ensure the > > > content is captured, othewise the trace just shows the value of the > > > pointer. > > > > > > Signed-off-by: John Keeping <john@metanate.com> > > > --- > > > sound/core/pcm_trace.h | 6 +++--- > > > 1 file changed, 3 insertions(+), 3 deletions(-) > > > > Thanks for the patch, while I have a slight concern about the intension > > of change. > > > > Let's see message in below commit to add 'trace_safe_str()' in > > 'kernel/trace/trace.c': > > https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=9a6944fee68 > > > > "The proper way to handle displaying any string that is not guaranteed to be > > in the kernel core rodata section, is to copy it into the ring buffer via > > the __string(), __assign_str() and __get_str() helper macros." > > > > Additionally, the macros looks to be alias to __dynamic_array() or so. > > > > In our case, the pointer of 'why' argument should points to two > > hardcoded strings; "hw_ptr skipping" and "Unexpected hw_ptr". As long as > > I know, they are put into any of .rodata section. > > > > ``` > > $ objdump -s sound/core/snd-pcm.ko -j .rodata.str1.1 > > ``` > > 0830 74757265 20436861 6e6e656c 204d6170 ture Channel Map > > 0840 00585255 4e3a2025 730a0055 6e657870 .XRUN: %s..Unexp > > 0850 65637465 64206877 5f707472 0068775f ected hw_ptr.hw_ > > 0860 70747220 736b6970 70696e67 004c6f73 ptr skipping.Los > > 0870 7420696e 74657272 75707473 3f00756e t interrupts?.un > > ``` > > > > I think current implementation is enough safe. > > Thanks for this analysis - I hadn't looked into the history of this. > > It seems that trace-cmd's record/report functionality does not support > rodata strings in this way though. Without this patch, the trace log is > not very informative: > > $ trace-cmd record -e snd_pcm:hw_ptr_error > ^C > $ trace-cmd report > irq/49-ehci_hcd-111 [002] 65.785147: hw_ptr_error: pcmC1D0p/sub0: ERROR: c0b1b3c7 > > With this patch applied this becomes: > > irq/49-ehci_hcd-111 [002] 435.758754: hw_ptr_error: pcmC2D0p/sub0: ERROR: Lost interrupts? Fair enough, I applied now as is. Thanks! Takashi
diff --git a/sound/core/pcm_trace.h b/sound/core/pcm_trace.h index f18da2050772..350b40b906ca 100644 --- a/sound/core/pcm_trace.h +++ b/sound/core/pcm_trace.h @@ -88,19 +88,19 @@ TRACE_EVENT(hw_ptr_error, __field( unsigned int, device ) __field( unsigned int, number ) __field( unsigned int, stream ) - __field( const char *, reason ) + __string( reason, why ) ), TP_fast_assign( __entry->card = (substream)->pcm->card->number; __entry->device = (substream)->pcm->device; __entry->number = (substream)->number; __entry->stream = (substream)->stream; - __entry->reason = (why); + __assign_str(reason, why); ), TP_printk("pcmC%dD%d%s/sub%d: ERROR: %s", __entry->card, __entry->device, __entry->stream == SNDRV_PCM_STREAM_PLAYBACK ? "p" : "c", - __entry->number, __entry->reason) + __entry->number, __get_str(reason)) ); TRACE_EVENT(applptr,
Strings need to be specially marked in trace events to ensure the content is captured, othewise the trace just shows the value of the pointer. Signed-off-by: John Keeping <john@metanate.com> --- sound/core/pcm_trace.h | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-)