* [PATCH] ALSA: pcm: fix tracing reason in hw_ptr_error
@ 2022-11-25 16:23 John Keeping
2022-11-26 3:51 ` Takashi Sakamoto
0 siblings, 1 reply; 4+ messages in thread
From: John Keeping @ 2022-11-25 16:23 UTC (permalink / raw)
To: alsa-devel; +Cc: John Keeping, Jaroslav Kysela, Takashi Iwai, linux-kernel
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(-)
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,
--
2.38.1
^ permalink raw reply related [flat|nested] 4+ messages in thread
* Re: [PATCH] ALSA: pcm: fix tracing reason in hw_ptr_error
2022-11-25 16:23 [PATCH] ALSA: pcm: fix tracing reason in hw_ptr_error John Keeping
@ 2022-11-26 3:51 ` Takashi Sakamoto
2022-11-28 10:50 ` John Keeping
0 siblings, 1 reply; 4+ messages in thread
From: Takashi Sakamoto @ 2022-11-26 3:51 UTC (permalink / raw)
To: John Keeping; +Cc: alsa-devel, linux-kernel, Takashi Iwai
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.
Nevertheless, explicit usage of the macros are developer friendly in my
opinion since string buffer in C language tends to bring problems and
the usage of macro would reduce careless future mistakes. In the case,
when probing the event, the string is copied to memory for event
structure, thus it adds slight overhead than current implementation. I
leave the decision to maintainer.
To maintainer, if you apply the patch to your tree, feel free to add my
review tag.
Reviewed-by: Takashi Sakamoto <o-takashi@sakamocchi.jp>
> 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,
> --
> 2.38.1
Regards
Takashi Sakamoto
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [PATCH] ALSA: pcm: fix tracing reason in hw_ptr_error
2022-11-26 3:51 ` Takashi Sakamoto
@ 2022-11-28 10:50 ` John Keeping
2022-11-28 13:56 ` Takashi Iwai
0 siblings, 1 reply; 4+ messages in thread
From: John Keeping @ 2022-11-28 10:50 UTC (permalink / raw)
To: alsa-devel, linux-kernel, Takashi Iwai
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?
> Nevertheless, explicit usage of the macros are developer friendly in my
> opinion since string buffer in C language tends to bring problems and
> the usage of macro would reduce careless future mistakes. In the case,
> when probing the event, the string is copied to memory for event
> structure, thus it adds slight overhead than current implementation. I
> leave the decision to maintainer.
>
> To maintainer, if you apply the patch to your tree, feel free to add my
> review tag.
>
> Reviewed-by: Takashi Sakamoto <o-takashi@sakamocchi.jp>
>
> > 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,
> > --
> > 2.38.1
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [PATCH] ALSA: pcm: fix tracing reason in hw_ptr_error
2022-11-28 10:50 ` John Keeping
@ 2022-11-28 13:56 ` Takashi Iwai
0 siblings, 0 replies; 4+ messages in thread
From: Takashi Iwai @ 2022-11-28 13:56 UTC (permalink / raw)
To: John Keeping; +Cc: alsa-devel, linux-kernel, Takashi Iwai
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
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2022-11-28 13:57 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-11-25 16:23 [PATCH] ALSA: pcm: fix tracing reason in hw_ptr_error John Keeping
2022-11-26 3:51 ` Takashi Sakamoto
2022-11-28 10:50 ` John Keeping
2022-11-28 13:56 ` Takashi Iwai
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).