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

[Nicolin Chen <nicolinc@nvidia.com>]

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.

> > > +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)?

> > > +       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.

> > 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.

> > > +                       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.

> > 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:".

> > > +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

> > > +}
> > > +
> > > +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.

> > > +       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);
?

> 
>         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?

Nicolin