Re: [PATCH v2 1/2] iommu/arm-smmu-v3: Print better events records

[Pranjal Shrivastava <praan@google.com>]

On Thu, Aug 29, 2024 at 06:45:53PM -0700, Nicolin Chen wrote:
> On Thu, Aug 29, 2024 at 11:54:26PM +0000, Pranjal Shrivastava wrote:
> 
> > > > +static const char * const class_str[] = {
> > > > +       [0] = "CD",
> > > > +       [1] = "TTD",
> > > > +       [2] = "IN",
> > > > +       [3] = "RES",
> > > > +};
> > >
> > > Unlike the event IDs, these class code names are still uneasy to
> > > read. Though it'd result in a print-format change, yet could we
> > > simply dump full strings instead?
> > >
> > 
> > By "full strings" do you mean "CD => CD Fetch" as mentioned in the spec?
> 
> Yes.

Ack. So, just for confirmation we want the following 4 class strings:
"CD Fetch"
"Stage 1 translation table fetch"
"Input address caused fault"
"Reserved"

Right?

> 
> > > > +static void arm_smmu_get_evt_info(struct arm_smmu_device *smmu, u64 *evt,
> > > > +                                 struct arm_smmu_event *event)
> > > > +{
> > > > +       /* Pick out the good stuff */
> > > > +       event->id = FIELD_GET(EVTQ_0_ID, evt[0]);
> > > > +       event->sid = FIELD_GET(EVTQ_0_SID, evt[0]);
> > > > +       event->ssid_valid = evt[0] & EVTQ_0_SSV;
> > > > +       event->ssid = event->ssid_valid ? FIELD_GET(EVTQ_0_SSID, evt[0]) : IOMMU_NO_PASID;
> > > > +       event->class = FIELD_GET(EVTQ_1_CLASS, evt[1]);
> > > > +       event->iova = FIELD_GET(EVTQ_2_ADDR, evt[2]);
> > > > +       event->ipa = FIELD_GET(EVTQ_3_IPA, evt[3]);
> > > > +       event->privileged = FIELD_GET(EVTQ_1_PnU, evt[1]);
> > > > +       event->instruction = FIELD_GET(EVTQ_1_InD, evt[1]);
> > > > +       event->stage = FIELD_GET(EVTQ_1_S2, evt[1]);
> > > > +       event->read = FIELD_GET(EVTQ_1_RnW, evt[1]);
> > > > +       event->raw = evt;
> > >
> > > Maybe we could define struct arm_smmu_event in this way:
> > >
> > > +struct arm_smmu_event {
> > > +     union {
> > > +             u64 evt[4];
> > > +             struct {
> > > +                     /* Bit 0:63 */
> > > +                     u64 id : 8;
> > > +                     u64 _res0 : 3;
> > > +                     u64 ssv : 1;
> > > +                     u64 ssid : 20;
> > > +                     u64 sid : 32;
> > > +                     /* Bit 64:127 */
> > > +                     u64 stag : 16;
> > > +                     u64 _res1 : 15;
> > > +                     u64 stall : 1;
> > > +                     u64 _res2 : 1;
> > > +                     u64 pnu : 1;
> > > +                     u64 ind : 1;
> > > +                     u64 rnw : 1;
> > > +                     u64 _res3 : 2;
> > > +                     u64 nsipa : 1;
> > > +                     u64 s2 : 1;
> > > +                     u64 class : 2;
> > > +                     u64 _res4 : 6;
> > > +                     u64 impl_def : 16;
> > > +                     /* Bit 128:191 */
> > > +                     u64 inputaddr;
> > > +                     /* Bit 192:255 */
> > > +                     u64 _res5 : 12;
> > > +                     u64 ipa : 40;
> > > +                     u64 _res6 : 12;
> > > +             } f_trans;
> > > +             /* FIXME Add other event structs */
> > > +     };
> > > +};
> > >
> > > Then, event would be just:
> > > +             struct arm_smmu_event *event = (struct arm_smmu_event *)evt;
> > >
> > > Not sure if Will would like this though...
> > 
> > Yea, I thought about this too but I felt that it'd bloat up the code
> > for every new event that's introduced.
> 
> That'd be in the header. The IRQ Handler would be always clean
> and fast.
> 
> > Also, the printing would become
> > more complicated as we'd have to log different fields for different
> > events. Additionally, I don't see that many unions being defined
> > elsewhere in the kernel.
> 
> OK. That's a fair point. I think we could have just one common
> union for the "good stuff" fields. Then, if something isn't in
> the common union, do a FIELD_GET(raw)?
> 

I'm not sure if I get this right, but are you suggesting something like:

+struct arm_smmu_event {
+	union {
+	u64 raw_evt[4];
+	struct {
+		/* "Good stuff" fields */
+	};
+};

and then based on the fault type we can use the "good stuff" or raw_evt?
So, basically just add a union between raw_evt and the other fields to
improve struct arm_smmu_event present in v2?

> > > > +       mutex_lock(&smmu->streams_mutex);
> > > > +       event->master = arm_smmu_find_master(smmu, event->sid);
> > > > +       mutex_unlock(&smmu->streams_mutex);
> > >
> > > Same as I pointed out at the other patch, "master" is unprotected
> > > after the unlock. It can unlikely-yet-still-possibly race against
> > > arm_smmu_release_device.
> > >
> > 
> > Hmm.. are you suggesting that the `master` could've been removed by the
> > arm_smmu_release_device while we access it in an event handler?
> > 
> > As in, something like the following situation:
> > 
> > 1. The evtq_thread gets scheduled
> > 2. arm_smmu_release_device removes the `master` & its streams
> > 3. In the `handle_evt` we dereference `master` which has been `kfree`ed
> >    (also, we don't return -EINVAL like we ideally should)
> > 
> > In that case, I think I should add back the `arm_smmu_find_master` to
> > the `arm_smmu_handle_evt` along with the locks. Nice catch! :)
> 
> Probably could lock the entire iteration, master pointer could
> be then passed in safely between the helper functions.

I'm just wondering if that'd be too much to print the "master_name", I
mean what if we simply save the master_name in `struct arm_smmu_event`?
That way, we can keep the locking as is in `arm_smmu_handle_evt` and
simply print the stored "master_name".

Note: I'm suggesting to store the entire string and not just the ptr
returned by dev_name(master->dev)), something like: 

`strcpy(event->master_name, dev_name(master->dev))`

> 
> > > And it'd feel clearer to have an "ssid". And perhaps adding commas
> > > to separate them too.
> > 
> > I referred to the log in `arm_smmu_handle_ppr` for the sid.ssid format.
> > If we'd prefer a separate "ssid", should we change the one in ppr too?
> > LMK, what you and Will think about that?
> 
> Didn't realize arm_smmu_handle_ppr does that. It's fine to keep
> the format in that way then.

Ack.

> 
> > > > +                       evts[event->id], event->master_name, event->sid, event->ssid);
> > > > +       dev_err(smmu->dev, "\tiova = %#llx ipa = %#llx (%s%s%s%s%s%s)\n", event->iova, event->ipa,
> > > > +                   event->privileged ? "Priv " : "Unpriv ",
> > > > +                   event->instruction ? "Inst " : "Data ",
> > > > +                   event->read ? "Read " : "Write ",
> > > > +                   event->stage ? "S2 " : "S1 ", class_str[event->class],
> > > > +                   ((event->id == EVT_ID_PERMISSION_FAULT) && (event->class == EVTQ_1_CLASS_TT)) ?
> > > > +                   (FIELD_GET(EVTQ_1_TT_READ, event->raw[1]) ? " TTD Read" : " TTD Write")
> > > > +                   : "");
> > >
> > > Indentation should follow the existing printk() in this driver. And
> > 
> > I'm sorry but I'm not sure if I understand what is meant by "the
> > existing printk indentation in this driver", do you mean aligning the
> > next line with the opening brace? For example:
> > 
> >         dev_err(smmu->dev,
> >                 "failed to allocate queue (0x%zx
> >                 bytes) for %s\n",
> >                 qsz, name);
> 
> Yea, just to keep the same coding style, line wrapping can still
> happen to 80 characters in general though.
> 

Ack.

> > > those ternary operators at the last field(s?) are hard to ready..
> > >
> > 
> > Hmm, I wanted the last fields to be printed only when the fault was
> > F_PERMISSION, in the same log. Any suggestions on what might make it
> > easier to read? Some helpful comments around it? Something else?
> 
> With an "other" string, we could sprintf on conditions inside the
> "case F_PERMISSION:".
> 

Ohh alright, basically we append something extra in the "other" string
for `F_PERMISSION`. Got it.

> > > > +static void arm_smmu_dump_fetch_fault(struct arm_smmu_device *smmu,
> > > > +                                     struct arm_smmu_event *event)
> > > > +{
> > > > +       dev_err(smmu->dev, "Bad fetch: %s client %s sid 0x%08x.0x%05x: fetch addr = %#llx\n",
> > > > +                       evts[event->id], event->master_name, event->sid, event->ssid, event->ipa);
> > >
> > > Actually, the "Fault", "Bad fetch", and "Bad smmu config" doesn't
> > > feel very necessary, since we prints the event string already.
> > >
> > 
> > That makes sense, I'll remove those in a follow up patch.
> > Although, I guess we should still say "fault" somewhere to hint folks
> > without arm-smmu-v3 knowledge that the event wasn't normal operation.
> > 
> > LMK what you think? I've had a few interactions where clients tend to
> > ignore the current "event received" dump considering that to be a part
> > of normal SMMU operation.
> 
> Well, we could improve the event_str with human-readable ones:
> 	s/F_TRANSLATION/Translation\ Fault
> 

Yea, but I'd still want to see a "spec searchable" name for the fault.
Maybe we can have "Unexpected event recieved:<spec_fault_name>" in the
"title" string?

> > > > +}
> > > > +
> > > > +static void arm_smmu_dump_raw_event(struct arm_smmu_device *smmu,
> > > > +                                   struct arm_smmu_event *event)
> > > > +{
> > > > +       int i;
> > > > +
> > > > +       dev_err(smmu->dev, "event 0x%02x received: client %s:\n", event->id, event->master_name);
> > >
> > > Looks like it would print another title that's sorta duplicated to
> > > other dump functions yet less informative?
> > >
> > 
> > Yea, I didn't wanna break backward compatibility, people might have
> > tools to parse out the existing dump, lol!
> >
> > On a serious note, I believe it'd be better to print this as some
> > implmentations might have some "IMPLEMENTATION DEFINED" fields which
> > people might be interested to look at.
> > 
> > Although, we can dump the raw event only in the `default` case, i.e.
> > when we don't have a dumper function for that particular event ID but
> > that might still avoid printing the IMPL_DEFINED fields in fetch faults
> 
> Makes sense to me by having a different title for the default case.
> 

Ack, we can have a different title for the default case. However, on a
second thought, I believe we should log the "raw" event in all cases,
since we aren't printing all the fields anyway. For example, for
F_TRANSLATION we don't print IMPL_DEF fields, NSIPA etc. It might be 
helpful to see the raw event even for the "non-default" cases.

> > > > +       for (i = 0; i < EVTQ_ENT_DWORDS; ++i)
> > > > +               dev_err(smmu->dev, "\t0x%016llx\n",
> > > > +                        (unsigned long long)event->raw[i]);
> > > > +}
> > > > +
> > > > +static void arm_smmu_dump_event(struct arm_smmu_device *smmu,
> > > > +    
> > 
> > I thought about something similar as well, but then referred to Robin's
> > comments on [1]. Also, printing strings in 3 different `dev_err` logs
> > could result in interruptions from other logs in dmesg, I'd prefer to
> 
> Ack.
> 
> > see the entire log in a single `dev_err` for ease. Although, I think we
> > should be able to do something like the following to achieve that:
> >         ...
> > 
> >         dev_err(%s %s %s, strlen(title) ? title : ""
> >                 strlen(addrs) ? addrs : ""
> >                 strlen(other) ? other : ""
> 
> That is fine, though should break the lines too. Maybe:
> 	dev_err(smmu->dev, "%s%s%s%s%s\n", title,
> 		strlen(addrs) ? "\n" : "", addrs,
> 		strlen(other) ? "\n" : "", other);
> ?
> 

I'd like line-feeds too, but I'm unsure if that could cause dmesg log
interruptions? I assume adding a "\n" flushes the console buffer, i.e.
we might get interrupted logs (I maybe wrong here).

> > 
> >         for (i = 0; i < EVTQ_ENT_DWORDS; ++i)
> >                 dev_err(smmu->dev, "\t0x%016llx\n", event->evt[i]);
> 
> Maybe merge the four dev_err iterations too?

Ack.

> 
> Nicolin

Thanks,
Pranjal