Re: [PATCH v5 0/3] iommu/arm-smmu-v3: Parse out event records

[Pranjal Shrivastava <praan@google.com>]

On Fri, Nov 22, 2024 at 03:33:42PM -0800, Daniel Mentz wrote:
> On Wed, Nov 20, 2024 at 3:43 AM Pranjal Shrivastava <praan@google.com> wrote:
> >
> > On Wed, Nov 20, 2024 at 12:24:43PM +0530, Pranjal Shrivastava wrote:
> > > Hi Daniel,
> > >
> > > On Wed, Nov 20, 2024 at 10:15 AM Daniel Mentz <danielmentz@google.com> wrote:
> > > >
> > > > On Tue, Nov 12, 2024 at 12:30 AM Pranjal Shrivastava <praan@google.com> wrote:
> > > > >
> > > > > Enhance the arm-smmu-v3 driver to parse out useful information from
> > > > > event records into a structure for better event handling & logging.
> > > >
> > > > Hi Pranjal,
> > > >
> > > > Thank you for putting this together.
> > > >
> > > > >
> > > > > Some sample events, powered by QEMU:
> > > >
> > > > > 4. Translation Fault:
> > > > >
> > > > > [    7.586428] arm-smmu-v3 arm-smmu-v3.0.auto: event 0x10 received:
> > > > > [    7.587012] arm-smmu-v3 arm-smmu-v3.0.auto:  0x0000000800000010
> > > > > [    7.587504] arm-smmu-v3 arm-smmu-v3.0.auto:  0x0000020000000000
> > > > > [    7.587986] arm-smmu-v3 arm-smmu-v3.0.auto:  0x00000000fffff040
> > > > > [    7.588745] arm-smmu-v3 arm-smmu-v3.0.auto:  0x0000000000000000
> > > > > [    7.589219] arm-smmu-v3 arm-smmu-v3.0.auto: Event 0x10 received: F_TRANSLATION
> > > > > [    7.589219]  client: 0000:00:01.0 sid: 0x8 ssid: 0x0
> > > > > [    7.589219]  iova 0xfffff040 ipa 0x0
> > > > > [    7.589219]  Unpriv | Data | Write | S1 | Input address caused fault
> > > > > [    7.589219]  STAG: 0x0
> > > >
> > > > I find that "Event 0x10" is redundant and recommend removing it. Maybe
> > > > print just "Event F_TRANSLATION"
> > >
> >
> > I agree, however, in the past reviews [1] we've been asked to keep the
> > existing log "as is" unless there's a particularly compelling reason.
> 
> I believe that feedback was about changing "event 0x%02x received:\n"
> to "event 0x%02x received: master %s:\n" on the line that immediately
> precedes the raw dump, but we're not changing that. What I am
> suggesting is to remove "Event 0x10 received:" from "Event 0x10
> received: F_TRANSLATION" and replace it with "event F_TRANSLATION"
> 

Ahh, apologies. I'll remove the event code from the pretty print.

> >
> > >
> > > >
> > > > Not printing the prefix "arm-smmu-v3 arm-smmu-v3.0.auto:" on
> > > > subsequent lines appears to be inconsistent with how the raw event
> > > > bits are dumped. Also, I typically run a command like "grep
> > > > 'arm-smmu-v3 arm-smmu-v3.0.auto' uart.log" while I'm developing smmu
> > > > driver code, and with the proposed change, the grep command wouldn't
> > > > print most of the event details, because they are not prefixed by
> > > > "arm-smmu-v3 arm-smmu-v3.0.auto"
> > >
> > > I see. The prefix isn't getting picked up because I'm trying to print
> > > all the lines in
> > > a single `dev_err` in order to avoid other logs inter-mingling with
> > > these ones. I can add
> > > that if we are okay with using multiple `dev_err` calls (i.e.
> > > potentially allowing other logs
> > > to mix-in).  Otherwise, let me see how we can manually add the dev_fmt
> > > string in the log.
> > >
> > > >
> > > > The words "client", "sid" and "ssid" are followed by a colon (":") but
> > > > iova and ipa are not.
> > > >
> > >
> > > Ack. Will fix that.
> > >
> > > > Can you put everything up to and including iova on the first line and
> > > > the rest on the second line?
> >
> > Finally my email client is fine.
> > Did you mean something like the following:
> > [    7.589219] arm-smmu-v3 arm-smmu-v3.0.auto: Event 0x10 received: F_TRANSLATION
> > [    7.589219] arm-smmu-v3 arm-smmu-v3.0.auto: client: 0000:00:01.0 sid: 0x8 ssid: 0x0 iova: 0xfffff040 ipa: 0x0
> > [    7.589219] arm-smmu-v3 arm-smmu-v3.0.auto: Unpriv | Data | Write | S1 | Input address caused fault | STAG: 0x0
> >
> 
> I was thinking about something like the following:
> 
> [    7.589219] arm-smmu-v3 arm-smmu-v3.0.auto: event F_TRANSLATION
> client: 0000:00:01.0 sid: 0x8 ssid: 0x0 iova: 0xfffff040 ipa: 0x0
> [    7.589219] arm-smmu-v3 arm-smmu-v3.0.auto: unpriv data write s1
> "Input address caused fault" stag: 0x0
> 

Ack. This might make the 1st line longer (the following is 133 columns):

[    7.589219] arm-smmu-v3 arm-smmu-v3.0.auto: event: F_TRANSLATION client: 0000:00:01.0 sid: 0x8 ssid: 0x0 iova: 0xfffff040 ipa: 0x0
[    7.589219] arm-smmu-v3 arm-smmu-v3.0.auto: unpriv data write s1 "Input address caused fault" stag: 0x0

Though, the worst case length would be something like:

[    7.589219] arm-smmu-v3 arm-smmu-v3.0.auto: event: F_TRANSLATION client: 0000:00:01.0 sid: 0x8 ssid: 0x0 iova: 0xfffff040 ipa: 0x0
[    7.589219] arm-smmu-v3 arm-smmu-v3.0.auto: unpriv data write s2 "Stage 1 translation table fetch" ttd_write stall stag: 0x0

I like this as well, provided the length would be fine?

> For sid, ssid, iova and ipa, you used all lowercase. I suggest
> extending this rule to Unpriv, Data, Write etc. and use lower case
> there as well. I'd remove the "|" characters to save space. I'm not
> sure how to represent the "Input address caused fault" part without
> the "|" characters to separate it from the rest. Maybe we can put it
> in double quotes.
> 

Also, if we wanna print everything in 2 lines along with the dev prefix,
I think we can do away with all the complex macro logic and have simply
two `dev_err`logs? Something like the attached below.

Thanks
Praan

------------------------------------------------->8------------------------------------------------

dev_err(smmu->dev, "Event received: %s client: %s sid: %#x ssid: %#x iova: %#x ipa: %#x",
	ARM_SMMU_EVT_NAME(evt), dev_name(evt->dev), evt->sid, evt->ssid, evt->iova, evt->ipa);

dev_err(smmu->dev, "%s %s %s %s %s %s %sSTAG: %#x",
	evt->privileged ? "priv" : "unpriv",
	evt->instruction ? "inst" : "data",
	evt->read ? "read" : "write",
	evt->s2 ? "s2" : "s1", event_class_str[evt->class],
	evt->class_tt ? (evt->ttrnw ? "ttd_read" : "ttd_write") : "",
	evt->stall ? "stall " : "", evt->stag);