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

[Pranjal Shrivastava <praan@google.com>]

On Wed, Aug 28, 2024 at 11:36:02PM -0700, Nicolin Chen wrote:
Hi Nicolin,
> Hi Pranjal,
> 
> The prints would be very helpful for debugging. Thanks for the
> patch!
> 
> I have some personally thoughts here, so hopefully we can make
> it cleaner and more readable.
> 
> On Tue, Aug 27, 2024 at 12:30:25PM -0700, Pranjal Shrivastava wrote:
> 
> > +static const char * const evts[] = {
> 
> s/evts/event_str
> 

Ack, would change that in the follow up patch.

> > +       /* Bad config events */
> > +       [EVT_ID_BAD_SID_CONFIG] = "C_BAD_STREAMID",
> > +       [EVT_ID_BAD_STE_CONFIG] = "C_BAD_STE",
> > +       [EVT_ID_BAD_CD_CONFIG] = "C_BAD_CD",
> > +       [EVT_ID_BAD_SSID_CONFIG] = "C_BAD_SUBSTREAMID",
> > +       [EVT_ID_STREAM_DISABLED] = "F_STREAM_DISABLED",
> > +
> > +       /* Bad translation events */
> > +       [EVT_ID_TRANSLATION_FAULT] = "F_TRANSLATION",
> > +       [EVT_ID_ADDR_SIZE_FAULT] = "F_ADDR_SIZE",
> > +       [EVT_ID_ACCESS_FAULT] = "F_ACCESS",
> > +       [EVT_ID_PERMISSION_FAULT] = "F_PERMISSION",
> > +
> > +       /* Bad fetch events */
> > +       [EVT_ID_STE_FETCH_FAULT] = "F_STE_FETCH",
> > +       [EVT_ID_CD_FETCH_FAULT] = "F_CD_FETCH",
> > +       [EVT_ID_VMS_FETCH_FAULT] = "F_VMS_FAULT"
> > +};
> > +
> > +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?
Or do you mean "Context Descriptor", "Translation Table Desc" etc.? I'm
afraid that the latter would make the printed string much longer.
Although, I wouldn't mind doing that if we have consensus.

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

...and, I'm not a fan of too many unions (personally) :) 

> 
> > +
> > +       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! :)


> > +static void arm_smmu_dump_xlation_fault(struct arm_smmu_device *smmu,
> > +                                       struct arm_smmu_event *event)
> > +{
> > +       dev_err(smmu->dev, "Fault: %s client %s sid 0x%08x.0x%05x:\n",
> 
> "client" doesn't seem to be used anywhere in this driver, I would:
> s/client/master
> 

Ack, would change this to "master".

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

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

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

I just noticed that I've missed the `STAG` field in the in xlation_fault
dump, would add that too in the next version of this patch.

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

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

> > +       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,
> > +                                struct arm_smmu_event *event)
> > +{
> > +       switch (event->id) {
> > +       case EVT_ID_BAD_SID_CONFIG:
> > +       case EVT_ID_BAD_STE_CONFIG:
> > +       case EVT_ID_BAD_SSID_CONFIG:
> > +       case EVT_ID_BAD_CD_CONFIG:
> > +       case EVT_ID_STREAM_DISABLED:
> > +               dev_err(smmu->dev, "Bad smmu config - %s client %s sid 0x%08x.0x%05x\n",
> > +                               evts[event->id], event->master_name, event->sid, event->ssid);
> > +               break;
> > +
> > +       case EVT_ID_TRANSLATION_FAULT:
> > +       case EVT_ID_ADDR_SIZE_FAULT:
> > +       case EVT_ID_ACCESS_FAULT:
> > +       case EVT_ID_PERMISSION_FAULT:
> > +               arm_smmu_dump_xlation_fault(smmu, event);
> > +               break;
> > +
> > +       case EVT_ID_STE_FETCH_FAULT:
> > +       case EVT_ID_CD_FETCH_FAULT:
> > +       case EVT_ID_VMS_FETCH_FAULT:
> > +               arm_smmu_dump_fetch_fault(smmu, event);
> > +               break;
> > +       }
> > +
> > +       arm_smmu_dump_raw_event(smmu, event);
> 
> I wonder if something like this would be cleaner:
> 
> 	...
> 	char title[256];
> 	char addrs[256];
> 	char other[256];
> 	int i;
> 
> 	switch () {
> 	case xxxx:
> 		/* If duplicated between cases, put them into helpers */
> 		snprintf(title, 256, "%s: Master %s, sid 0x%08x, ssid 0x%05x\n",
> 			 event_str(event->id], dev_name(master->dev),
> 			 event->sid, event->ssid);
> 		snprintf(addrs, 256, .....);
> 		snprintf(other, 256, .....);
> 		break;
> 	...
> 	default:
> 		/* snprintf raw title */
> 		break;
> 	}
> 	if (strlen(title))
> 		dev_err(smmu->dev, "%s", title);
> 	if (strlen(addrs))
> 		dev_err(smmu->dev, "%s", addrs);
> 	if (strlen(other))
> 		dev_err(smmu->dev, "%s", other);
> 	for (i = 0; i < EVTQ_ENT_DWORDS; ++i)
> 		dev_err(smmu->dev, "\t0x%016llx\n", event->evt[i]);
> 	...
> 

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

	for (i = 0; i < EVTQ_ENT_DWORDS; ++i)
		dev_err(smmu->dev, "\t0x%016llx\n", event->evt[i]);

	...

It does look cleaner to me as well. I'd wait for what other have to say.

> Thanks
> Nicolin

[1]
https://lore.kernel.org/linux-arm-kernel/07c7426c-7d01-4160-a344-1857b738e9c4@arm.com/T/#m9c38920897999c56f0b135556133cae38f40b754a

Thanks,
Pranjal