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

[Nicolin Chen <nicolinc@nvidia.com>]

On Mon, Sep 02, 2024 at 08:23:20AM +0000, Pranjal Shrivastava wrote:

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

Yes. I know they are longer, but more readable. So, you might want
to arrange the output format to present them nicely.

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

Yea, I attached a test code at the EOM for your reference. Please
feel free to drop fields if they aren't common enough, and confirm
those bits are correctly written too.

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

I'd probably move the dump() call inside arm_smmu_handle_evt(), and
within the lock to avoid strcpy. And eventually it would be located
at "else { /* Unhandled events should be pinned */ ret = -EFAULT; }:
https://lore.kernel.org/linux-iommu/8b93be1d913f9e227748de2d07e8540ddc2372ab.1724777091.git.nicolinc@nvidia.com/

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

That looks good to me.

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

That makes sense. I'd dump the raw dwords outside the switch-case,
i.e. in the common path.

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

I think the console_lock is grabbed per printk call, not per "\n".

Thanks
Nicolin

-------------------------------------------------------------------------------
diff --git a/drivers/iommu/arm/arm-smmu-v3/arm-smmu-v3.c b/drivers/iommu/arm/arm-smmu-v3/arm-smmu-v3.c
index 6c48b53fc2b8..6b1ca9379999 100644
--- a/drivers/iommu/arm/arm-smmu-v3/arm-smmu-v3.c
+++ b/drivers/iommu/arm/arm-smmu-v3/arm-smmu-v3.c
@@ -1894,6 +1894,37 @@ static int arm_smmu_handle_evt(struct arm_smmu_device *smmu, u64 *evt)
 	return ret;
 }
 
+union arm_smmu_event {
+	u64 evt[EVTQ_ENT_DWORDS];
+	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 addr1;
+	/* Bit 192:255 */
+	u64 addr2: 56;
+	u64 _res5: 8;
+	};
+};
+
 static irqreturn_t arm_smmu_evtq_thread(int irq, void *dev)
 {
 	int i, ret;
@@ -1902,20 +1933,27 @@ static irqreturn_t arm_smmu_evtq_thread(int irq, void *dev)
 	struct arm_smmu_ll_queue *llq = &q->llq;
 	static DEFINE_RATELIMIT_STATE(rs, DEFAULT_RATELIMIT_INTERVAL,
 				      DEFAULT_RATELIMIT_BURST);
-	u64 evt[EVTQ_ENT_DWORDS];
+	union arm_smmu_event event;
 
 	do {
-		while (!queue_remove_raw(q, evt)) {
-			u8 id = FIELD_GET(EVTQ_0_ID, evt[0]);
+		while (!queue_remove_raw(q, event.evt)) {
+			u8 id = FIELD_GET(EVTQ_0_ID, event.evt[0]);
 
-			ret = arm_smmu_handle_evt(smmu, evt);
+			ret = arm_smmu_handle_evt(smmu, event.evt);
 			if (!ret || !__ratelimit(&rs))
 				continue;
 
 			dev_info(smmu->dev, "event 0x%02x received:\n", id);
-			for (i = 0; i < ARRAY_SIZE(evt); ++i)
+			for (i = 0; i < ARRAY_SIZE(event.evt); ++i)
 				dev_info(smmu->dev, "\t0x%016llx\n",
-					 (unsigned long long)evt[i]);
+					 event.evt[i]);
+			dev_info(smmu->dev, "id=%d\n", event.id);
+			dev_info(smmu->dev, "sid=%x\n", event.sid);
+			dev_info(smmu->dev, "class=%d\n", event.class);
+			dev_info(smmu->dev, "s2=%d\n", event.s2);
+			dev_info(smmu->dev, "inputaddr=%llx\n", event.addr1);
+			dev_info(smmu->dev, "ipa=%llx\n",
+					(u64)event.addr2 & GENMASK(55, 12));
 
 			cond_resched();
 		}