Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
Date:   Mon, 28 Nov 2022 14:56:36 +0100
Message-ID: <87ilizyygb.wl-tiwai@suse.de>
From:   Takashi Iwai <tiwai@suse.de>
To:     John Keeping <john@metanate.com>
Cc:     alsa-devel@alsa-project.org, linux-kernel@vger.kernel.org,
        Takashi Iwai <tiwai@suse.com>
Subject: Re: [PATCH] ALSA: pcm: fix tracing reason in hw_ptr_error
In-Reply-To: <Y4SSjO8gnIz22vt3@donbot>
References: <20221125162327.297440-1-john@metanate.com>
        <Y4GNWYcQBUKn3KSa@workstation>
        <Y4SSjO8gnIz22vt3@donbot>
User-Agent: Wanderlust/2.15.9 (Almost Unreal) Emacs/27.2 Mule/6.0
MIME-Version: 1.0 (generated by SEMI-EPG 1.14.7 - "Harue")
Content-Type: text/plain; charset=US-ASCII
Precedence: bulk

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