[PATCH 1/2] cxl: Move command enumeration from dev_dbg() to traceevent

[PATCH 1/2] cxl: Move command enumeration from dev_dbg() to traceevent

[Dave Jiang]

Given that event logs outputs are all emitted to traceevent, move the
enumeration of log types to traceevent as well in order to keep all the
outputs at the same location.

Suggested-by: Alison Schofield <alison.schofield@intel.com>
Signed-off-by: Dave Jiang <dave.jiang@intel.com>
---
 drivers/cxl/core/mbox.c  |    3 +--
 drivers/cxl/core/trace.h |   31 +++++++++++++++++++++++++++++++
 2 files changed, 32 insertions(+), 2 deletions(-)

diff --git a/drivers/cxl/core/mbox.c b/drivers/cxl/core/mbox.c
index ca60bb8114f2..ab6b6c4d7a48 100644
--- a/drivers/cxl/core/mbox.c
+++ b/drivers/cxl/core/mbox.c
@@ -787,7 +787,6 @@ static const uuid_t log_uuid[] = {
 int cxl_enumerate_cmds(struct cxl_memdev_state *mds)
 {
 	struct cxl_mbox_get_supported_logs *gsl;
-	struct device *dev = mds->cxlds.dev;
 	struct cxl_mem_command *cmd;
 	int i, rc;
 
@@ -801,7 +800,7 @@ int cxl_enumerate_cmds(struct cxl_memdev_state *mds)
 		uuid_t uuid = gsl->entry[i].uuid;
 		u8 *log;
 
-		dev_dbg(dev, "Found LOG type %pU of size %d", &uuid, size);
+		trace_cxl_log_type(mds->cxlds.cxlmd, &uuid, size);
 
 		if (!uuid_equal(&uuid, &log_uuid[CEL_UUID]))
 			continue;
diff --git a/drivers/cxl/core/trace.h b/drivers/cxl/core/trace.h
index a0b5819bc70b..817c5377eca2 100644
--- a/drivers/cxl/core/trace.h
+++ b/drivers/cxl/core/trace.h
@@ -703,6 +703,37 @@ TRACE_EVENT(cxl_poison,
 	)
 );
 
+TRACE_EVENT(cxl_log_type,
+
+	TP_PROTO(const struct cxl_memdev *cxlmd, uuid_t *uuid, int size),
+
+	TP_ARGS(cxlmd, uuid, size),
+
+	TP_STRUCT__entry(
+		__string(memdev, dev_name(&cxlmd->dev))
+		__string(host, dev_name(cxlmd->dev.parent))
+		__array(char, uuid, 16)
+		__field(u64, serial)
+		__field(int, size)
+	),
+
+	TP_fast_assign(
+		__assign_str(memdev, dev_name(&cxlmd->dev));
+		__assign_str(host, dev_name(cxlmd->dev.parent));
+		__entry->serial = cxlmd->cxlds->serial;
+		memcpy(__entry->uuid, uuid, 16);
+		__entry->size = size;
+	),
+
+	TP_printk("memdev=%s host=%s serial=%lld log_type=%pU size=%d",
+		  __get_str(memdev),
+		  __get_str(host),
+		  __entry->serial,
+		  __entry->uuid,
+		  __entry->size
+	)
+);
+
 #endif /* _CXL_EVENTS_H */
 
 #define TRACE_INCLUDE_FILE trace

[PATCH 2/2] cxl: Move opcode reporting from dev_dbg() to traceevent

[Dave Jiang]

Alison has reported that against certain hardware devices the opcode
discovery dev_dbg() can emit several hundred "unsupported by driver"
messages while parsing the CEL. Move the emission to traceevent to reduce
dmesg spamming and let software parse the output if there are interested
parties.

Reported-by: Alison Schofield <alison.schofield@intel.com>
Suggested-by: Alison Schofield <alison.schofield@intel.com>
Signed-off-by: Dave Jiang <dave.jiang@intel.com>
---
 drivers/cxl/core/mbox.c  |    7 +++----
 drivers/cxl/core/trace.h |   30 ++++++++++++++++++++++++++++++
 2 files changed, 33 insertions(+), 4 deletions(-)

diff --git a/drivers/cxl/core/mbox.c b/drivers/cxl/core/mbox.c
index ab6b6c4d7a48..59089b540add 100644
--- a/drivers/cxl/core/mbox.c
+++ b/drivers/cxl/core/mbox.c
@@ -707,7 +707,7 @@ static void cxl_walk_cel(struct cxl_memdev_state *mds, size_t size, u8 *cel)
 {
 	struct cxl_cel_entry *cel_entry;
 	const int cel_entries = size / sizeof(*cel_entry);
-	struct device *dev = mds->cxlds.dev;
+	struct cxl_memdev *cxlmd = mds->cxlds.cxlmd;
 	int i;
 
 	cel_entry = (struct cxl_cel_entry *) cel;
@@ -718,8 +718,7 @@ static void cxl_walk_cel(struct cxl_memdev_state *mds, size_t size, u8 *cel)
 
 		if (!cmd && (!cxl_is_poison_command(opcode) ||
 			     !cxl_is_security_command(opcode))) {
-			dev_dbg(dev,
-				"Opcode 0x%04x unsupported by driver\n", opcode);
+			trace_cxl_opcode(cxlmd, opcode, false);
 			continue;
 		}
 
@@ -732,7 +731,7 @@ static void cxl_walk_cel(struct cxl_memdev_state *mds, size_t size, u8 *cel)
 		if (cxl_is_security_command(opcode))
 			cxl_set_security_cmd_enabled(&mds->security, opcode);
 
-		dev_dbg(dev, "Opcode 0x%04x enabled\n", opcode);
+		trace_cxl_opcode(cxlmd, opcode, true);
 	}
 }
 
diff --git a/drivers/cxl/core/trace.h b/drivers/cxl/core/trace.h
index 817c5377eca2..c48e4c836d77 100644
--- a/drivers/cxl/core/trace.h
+++ b/drivers/cxl/core/trace.h
@@ -734,6 +734,36 @@ TRACE_EVENT(cxl_log_type,
 	)
 );
 
+TRACE_EVENT(cxl_opcode,
+
+	TP_PROTO(const struct cxl_memdev *cxlmd, u16 opcode, bool enabled),
+
+	TP_ARGS(cxlmd, opcode, enabled),
+
+	TP_STRUCT__entry(
+		__string(memdev, dev_name(&cxlmd->dev))
+		__string(host, dev_name(cxlmd->dev.parent))
+		__field(u64, serial)
+		__field(u16, opcode)
+		__field(bool, enabled)
+	),
+
+	TP_fast_assign(
+		__assign_str(memdev, dev_name(&cxlmd->dev));
+		__assign_str(host, dev_name(cxlmd->dev.parent));
+		__entry->serial = cxlmd->cxlds->serial;
+		__entry->opcode = opcode;
+		__entry->enabled = enabled;
+	),
+
+	TP_printk("memdev=%s host=%s serial=%lld opcode=%d state=%s",
+		  __get_str(memdev),
+		  __get_str(host),
+		  __entry->serial,
+		  __entry->opcode,
+		  __entry->enabled ? "enabled" : "unsupported"
+	)
+);
 #endif /* _CXL_EVENTS_H */
 
 #define TRACE_INCLUDE_FILE trace

Re: [PATCH 2/2] cxl: Move opcode reporting from dev_dbg() to traceevent

[Alison Schofield]

On Fri, Sep 15, 2023 at 01:13:55PM -0700, Dave Jiang wrote:
> Alison has reported that against certain hardware devices the opcode
> discovery dev_dbg() can emit several hundred "unsupported by driver"
> messages while parsing the CEL. Move the emission to traceevent to reduce
> dmesg spamming and let software parse the output if there are interested
> parties.

Thanks for reducing the spew Dave.

Considering that tracing may or may not be 'on' can we just not
spew anything at this point - no dev_dbg(), no trace. Let the user
ask for the opcode list at their leisure, at which time we'd dump
it to trace log.

Is there a mechanism in place for user to ask for logs?
(cxl list -m mem1 'show me my opcodes')
Barring that, I'm assuming users can do a pass thru of this cmd
and get whatever they want.

Counterpoint - is there a subset of opcodes that we'd really like
to dev_dbg() about at this point in time?  ie missing opcodes that
are going to make the device useless.

Alison

> 
> Reported-by: Alison Schofield <alison.schofield@intel.com>
> Suggested-by: Alison Schofield <alison.schofield@intel.com>
> Signed-off-by: Dave Jiang <dave.jiang@intel.com>
> ---
>  drivers/cxl/core/mbox.c  |    7 +++----
>  drivers/cxl/core/trace.h |   30 ++++++++++++++++++++++++++++++
>  2 files changed, 33 insertions(+), 4 deletions(-)
> 
> diff --git a/drivers/cxl/core/mbox.c b/drivers/cxl/core/mbox.c
> index ab6b6c4d7a48..59089b540add 100644
> --- a/drivers/cxl/core/mbox.c
> +++ b/drivers/cxl/core/mbox.c
> @@ -707,7 +707,7 @@ static void cxl_walk_cel(struct cxl_memdev_state *mds, size_t size, u8 *cel)
>  {
>  	struct cxl_cel_entry *cel_entry;
>  	const int cel_entries = size / sizeof(*cel_entry);
> -	struct device *dev = mds->cxlds.dev;
> +	struct cxl_memdev *cxlmd = mds->cxlds.cxlmd;
>  	int i;
>  
>  	cel_entry = (struct cxl_cel_entry *) cel;
> @@ -718,8 +718,7 @@ static void cxl_walk_cel(struct cxl_memdev_state *mds, size_t size, u8 *cel)
>  
>  		if (!cmd && (!cxl_is_poison_command(opcode) ||
>  			     !cxl_is_security_command(opcode))) {
> -			dev_dbg(dev,
> -				"Opcode 0x%04x unsupported by driver\n", opcode);
> +			trace_cxl_opcode(cxlmd, opcode, false);
>  			continue;
>  		}
>  
> @@ -732,7 +731,7 @@ static void cxl_walk_cel(struct cxl_memdev_state *mds, size_t size, u8 *cel)
>  		if (cxl_is_security_command(opcode))
>  			cxl_set_security_cmd_enabled(&mds->security, opcode);
>  
> -		dev_dbg(dev, "Opcode 0x%04x enabled\n", opcode);
> +		trace_cxl_opcode(cxlmd, opcode, true);
>  	}
>  }
>  
> diff --git a/drivers/cxl/core/trace.h b/drivers/cxl/core/trace.h
> index 817c5377eca2..c48e4c836d77 100644
> --- a/drivers/cxl/core/trace.h
> +++ b/drivers/cxl/core/trace.h
> @@ -734,6 +734,36 @@ TRACE_EVENT(cxl_log_type,
>  	)
>  );
>  
> +TRACE_EVENT(cxl_opcode,
> +
> +	TP_PROTO(const struct cxl_memdev *cxlmd, u16 opcode, bool enabled),
> +
> +	TP_ARGS(cxlmd, opcode, enabled),
> +
> +	TP_STRUCT__entry(
> +		__string(memdev, dev_name(&cxlmd->dev))
> +		__string(host, dev_name(cxlmd->dev.parent))
> +		__field(u64, serial)
> +		__field(u16, opcode)
> +		__field(bool, enabled)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(memdev, dev_name(&cxlmd->dev));
> +		__assign_str(host, dev_name(cxlmd->dev.parent));
> +		__entry->serial = cxlmd->cxlds->serial;
> +		__entry->opcode = opcode;
> +		__entry->enabled = enabled;
> +	),
> +
> +	TP_printk("memdev=%s host=%s serial=%lld opcode=%d state=%s",
> +		  __get_str(memdev),
> +		  __get_str(host),
> +		  __entry->serial,
> +		  __entry->opcode,
> +		  __entry->enabled ? "enabled" : "unsupported"
> +	)
> +);
>  #endif /* _CXL_EVENTS_H */
>  
>  #define TRACE_INCLUDE_FILE trace
> 
> 

Re: [PATCH 2/2] cxl: Move opcode reporting from dev_dbg() to traceevent

[Ira Weiny]

Alison Schofield wrote:
> On Fri, Sep 15, 2023 at 01:13:55PM -0700, Dave Jiang wrote:
> > Alison has reported that against certain hardware devices the opcode
> > discovery dev_dbg() can emit several hundred "unsupported by driver"
> > messages while parsing the CEL. Move the emission to traceevent to reduce
> > dmesg spamming and let software parse the output if there are interested
> > parties.
> 
> Thanks for reducing the spew Dave.
> 
> Considering that tracing may or may not be 'on' can we just not
> spew anything at this point - no dev_dbg(), no trace. Let the user
> ask for the opcode list at their leisure, at which time we'd dump
> it to trace log.
> 
> Is there a mechanism in place for user to ask for logs?
> (cxl list -m mem1 'show me my opcodes')
> Barring that, I'm assuming users can do a pass thru of this cmd
> and get whatever they want.
> 
> Counterpoint - is there a subset of opcodes that we'd really like
> to dev_dbg() about at this point in time?  ie missing opcodes that
> are going to make the device useless.

IMO any command which fails and is fatal to the device coming up should
trigger a dev_err() somewhere.

I don't think that is a guarantee currently though.  Even something which
we expect but does not fail the device is IMO a candidate for dev_err()
because it is unexpected behavior.

Does anyone oppose removing the dev_dbg()'s in this series?  Is anyone
looking at the list of opcodes this way?

Ira

Re: [PATCH 1/2] cxl: Move command enumeration from dev_dbg() to traceevent

[Ira Weiny]

Dave Jiang wrote:
> Given that event logs outputs are all emitted to traceevent, move the
> enumeration of log types to traceevent as well in order to keep all the
> outputs at the same location.
> 
> Suggested-by: Alison Schofield <alison.schofield@intel.com>
> Signed-off-by: Dave Jiang <dave.jiang@intel.com>

My gut reaction was to nak this patch because I'm not sure how to enable
trace events prior to module load.  Then I realized that this is in the
cxl_core and is only triggered by driver loads.  So I've not tested this
patch but I think the following sequence will work for these 2 patches.

$ modprobe cxl_core
$ echo 1 > /sys/kernel/tracing/events/cxl/cxl_log_type/enable
$ modprobe cxl_pci

Is that how you tested this?  It seems like a pain.  But perhaps that pain
is fine because these debug messages are not as useful as others?
Especially for all the unsupported messages mentioned in patch 2?

Ira

Re: [PATCH 1/2] cxl: Move command enumeration from dev_dbg() to traceevent

[Dave Jiang]

On 9/15/23 15:11, Ira Weiny wrote:
> Dave Jiang wrote:
>> Given that event logs outputs are all emitted to traceevent, move the
>> enumeration of log types to traceevent as well in order to keep all the
>> outputs at the same location.
>>
>> Suggested-by: Alison Schofield <alison.schofield@intel.com>
>> Signed-off-by: Dave Jiang <dave.jiang@intel.com>
> 
> My gut reaction was to nak this patch because I'm not sure how to enable
> trace events prior to module load.  Then I realized that this is in the
> cxl_core and is only triggered by driver loads.  So I've not tested this
> patch but I think the following sequence will work for these 2 patches.
> 
> $ modprobe cxl_core
> $ echo 1 > /sys/kernel/tracing/events/cxl/cxl_log_type/enable
> $ modprobe cxl_pci

I don't see any other way to do this. I saw this [1] but it doesn't appeared to be upstream.

[1]: https://lwn.net/Articles/432186/

> 
> Is that how you tested this?  It seems like a pain.  But perhaps that pain
> is fine because these debug messages are not as useful as others?
> Especially for all the unsupported messages mentioned in patch 2?

Yes. Alison mentioned seeing maybe 500+ of those.

> 
> Ira

Re: [PATCH 1/2] cxl: Move command enumeration from dev_dbg() to traceevent

[Ira Weiny]

Dave Jiang wrote:
> 
> 
> On 9/15/23 15:11, Ira Weiny wrote:
> > Dave Jiang wrote:
> > 

[snip]

> > My gut reaction was to nak this patch because I'm not sure how to enable
> > trace events prior to module load.  Then I realized that this is in the
> > cxl_core and is only triggered by driver loads.  So I've not tested this
> > patch but I think the following sequence will work for these 2 patches.
> > 
> > $ modprobe cxl_core
> > $ echo 1 > /sys/kernel/tracing/events/cxl/cxl_log_type/enable
> > $ modprobe cxl_pci
> 
> I don't see any other way to do this. I saw this [1] but it doesn't appeared to be upstream.
> 
> [1]: https://lwn.net/Articles/432186/
> 
> > 
> > Is that how you tested this?  It seems like a pain.  But perhaps that pain
> > is fine because these debug messages are not as useful as others?
> > Especially for all the unsupported messages mentioned in patch 2?
> 
> Yes. Alison mentioned seeing maybe 500+ of those.

Ok it seems reasonable to me.  But perhaps we can document the above method
somewhere?  Not sure if the commit message is the best place but it is better
than nothing.

Thanks,
Ira

Re: [PATCH 1/2] cxl: Move command enumeration from dev_dbg() to traceevent

[Dave Jiang]

On 9/18/23 10:49, Ira Weiny wrote:
> Dave Jiang wrote:
>>
>>
>> On 9/15/23 15:11, Ira Weiny wrote:
>>> Dave Jiang wrote:
>>>
> 
> [snip]
> 
>>> My gut reaction was to nak this patch because I'm not sure how to enable
>>> trace events prior to module load.  Then I realized that this is in the
>>> cxl_core and is only triggered by driver loads.  So I've not tested this
>>> patch but I think the following sequence will work for these 2 patches.
>>>
>>> $ modprobe cxl_core
>>> $ echo 1 > /sys/kernel/tracing/events/cxl/cxl_log_type/enable
>>> $ modprobe cxl_pci
>>
>> I don't see any other way to do this. I saw this [1] but it doesn't appeared to be upstream.
>>
>> [1]: https://lwn.net/Articles/432186/
>>
>>>
>>> Is that how you tested this?  It seems like a pain.  But perhaps that pain
>>> is fine because these debug messages are not as useful as others?
>>> Especially for all the unsupported messages mentioned in patch 2?
>>
>> Yes. Alison mentioned seeing maybe 500+ of those.
> 
> Ok it seems reasonable to me.  But perhaps we can document the above method
> somewhere?  Not sure if the commit message is the best place but it is better
> than nothing.

I can add it to the commit log. Maybe I'll send out v2 of this independent of the other patch given there may be some differing opinions on what to do about that.

> 
> Thanks,
> Ira