diff mbox series

[v4,09/10] trace: platform/x86/intel/ifs: Add trace point to track Intel IFS operations

Message ID 20220422200219.2843823-10-tony.luck@intel.com (mailing list archive)
State Changes Requested, archived
Headers show
Series Introduce In Field Scan driver | expand

Commit Message

Luck, Tony April 22, 2022, 8:02 p.m. UTC 
Add tracing support which may be useful for debugging systems that fail to complete
In Field Scan tests.

Reviewed-by: Dan Williams <dan.j.williams@intel.com>
Signed-off-by: Tony Luck <tony.luck@intel.com>
---
 MAINTAINERS                              |  1 +
 drivers/platform/x86/intel/ifs/runtest.c |  5 ++++
 include/trace/events/intel_ifs.h         | 38 ++++++++++++++++++++++++
 3 files changed, 44 insertions(+)
 create mode 100644 include/trace/events/intel_ifs.h

Comments

Steven Rostedt April 25, 2022, 2:52 p.m. UTC | #1 
On Fri, 22 Apr 2022 13:02:18 -0700
Tony Luck <tony.luck@intel.com> wrote:

> Add tracing support which may be useful for debugging systems that fail to complete
> In Field Scan tests.
> 
> Reviewed-by: Dan Williams <dan.j.williams@intel.com>
> Signed-off-by: Tony Luck <tony.luck@intel.com>
> ---
>  MAINTAINERS                              |  1 +
>  drivers/platform/x86/intel/ifs/runtest.c |  5 ++++
>  include/trace/events/intel_ifs.h         | 38 ++++++++++++++++++++++++

From the tracing POV:

Acked-by: Steven Rostedt (Google) <rostedt@goodmis.org>

-- Steve
Luck, Tony April 25, 2022, 4:49 p.m. UTC | #2 
> > Add tracing support which may be useful for debugging systems that fail to complete
> > In Field Scan tests.
> >
> > Reviewed-by: Dan Williams <dan.j.williams@intel.com>
> > Signed-off-by: Tony Luck <tony.luck@intel.com>
> > ---
> >  MAINTAINERS                              |  1 +
> >  drivers/platform/x86/intel/ifs/runtest.c |  5 ++++
> >  include/trace/events/intel_ifs.h         | 38 ++++++++++++++++++++++++
>
> From the tracing POV:
>
> Acked-by: Steven Rostedt (Google) <rostedt@goodmis.org>

Question for the future of this driver.  There are a couple more scan tools coming
in the future. The interface is similar:

	WRMSR to start a scan
	RDMSR to get the results

For this first one, I made the trace code do some user friendly decoding of the
WRMSR value to just show the two interesting fields (start & stop).

The future scan modes will have different fields.

I see two paths:

1) Create a new user friendly trace point for each new scan mode.
2) Just provide a generic one that dumps both the 64-bit WRMSR and RDMSR values.

Q: Are trace points "expensive" in some way ... so better to just have one than three?
     Or are the cheap enough that decoding for the user is an OK thing?

Thanks

-Tony
Steven Rostedt April 26, 2022, 1:49 a.m. UTC | #3 
On Mon, 25 Apr 2022 16:49:35 +0000
"Luck, Tony" <tony.luck@intel.com> wrote:

> I see two paths:
> 
> 1) Create a new user friendly trace point for each new scan mode.
> 2) Just provide a generic one that dumps both the 64-bit WRMSR and RDMSR values.
> 
> Q: Are trace points "expensive" in some way ... so better to just have one than three?
>      Or are the cheap enough that decoding for the user is an OK thing?

Yes, they are expensive as each TRACE_EVENT() can add a few KB of text and
data. But you can add a DECLARE_EVENT_CLASS() and then add "printk"
differences that are less memory heavy.

See DEFINE_EVENT_PRINT().

-- Steve
Luck, Tony April 26, 2022, 11:53 p.m. UTC | #4 
On Mon, Apr 25, 2022 at 09:49:28PM -0400, Steven Rostedt wrote:
> On Mon, 25 Apr 2022 16:49:35 +0000
> "Luck, Tony" <tony.luck@intel.com> wrote:
> 
> > I see two paths:
> > 
> > 1) Create a new user friendly trace point for each new scan mode.
> > 2) Just provide a generic one that dumps both the 64-bit WRMSR and RDMSR values.
> > 
> > Q: Are trace points "expensive" in some way ... so better to just have one than three?
> >      Or are the cheap enough that decoding for the user is an OK thing?
> 
> Yes, they are expensive as each TRACE_EVENT() can add a few KB of text and
> data. But you can add a DECLARE_EVENT_CLASS() and then add "printk"
> differences that are less memory heavy.
> 
> See DEFINE_EVENT_PRINT().

I looked at the examples in samples/trace_events/trace-events-sample.h
and tried to use this. But I'm doing something wrong because the
compiler barfs on something defined but not used.

Maybe my problem is the TP_printk() in the DECLARE_EVENT_CLASS() that
is over-ridden by DEFINE_EVENT_PRINT(). I wasn't at all sure what to
put here ... or how to use the base tracepoint that doesn't have the
printk() over-ridden.

I think I need my class to just save both the u64 values to the trace
buffer. Then the different trace points will extract the bits they want
and print in a user friendly way. While this increases space used in
the trace buffer, these events are not crazy high frequency. Usually 
one or two events per core with a gap 30 minutes or more between tests.

In my ".c" file the tracepoint looks like this using the name from
DEFINE_EVENT_PRINT(), and now passing the full u64 values:

	trace_ifs_status_saf(activate.data, status.data);

and my #include file looks like this:

----------------------------------------------
/* SPDX-License-Identifier: GPL-2.0 */
#undef TRACE_SYSTEM
#define TRACE_SYSTEM intel_ifs

#if !defined(_TRACE_IFS_H) || defined(TRACE_HEADER_MULTI_READ)
#define _TRACE_IFS_H

#include <linux/ktime.h>
#include <linux/tracepoint.h>

DECLARE_EVENT_CLASS(ifs_status,

	TP_PROTO(u64 activate, u64 status),

	TP_ARGS(activate, status),

	TP_STRUCT__entry(
		__field(	u64,	activate	)
		__field(	u64,	status		)
	),

	TP_fast_assign(
		__entry->activate = activate;
		__entry->status	= status;
	),

	TP_printk("activate: %llx status: %llx",
		__entry->activate,
		__entry->status)
);

DEFINE_EVENT_PRINT(ifs_status, ifs_status_saf,
	TP_PROTO(u64 activate, u64 status),
	TP_ARGS(activate, status),
	TP_printk("start: %.2x, stop: %.2x, status: %llx",
		((union ifs_scan *)&(__entry->activate))->start,
		((union ifs_scan *)&(__entry->activate))->stop,
		__entry->status)
);

#endif /* _TRACE_IFS_H */

/* This part must be outside protection */
#include <trace/define_trace.h>
-----------------------------------------------------

GCC messages:


  CC [M]  drivers/platform/x86/intel/ifs/runtest.o
In file included from /home/agluck/GIT/mywork/include/trace/define_trace.h:102,
                 from /home/agluck/GIT/mywork/include/trace/events/intel_ifs.h:44,
                 from /home/agluck/GIT/mywork/drivers/platform/x86/intel/ifs/runtest.c:27:
/home/agluck/GIT/mywork/include/trace/trace_events.h:426:13: warning: ‘print_fmt_ifs_status’ defined but not used [-Wunused-variable]
  426 | static char print_fmt_##call[] = print;                                 \
      |             ^~~~~~~~~~
/home/agluck/GIT/mywork/include/trace/events/intel_ifs.h:11:1: note: in expansion of macro ‘DECLARE_EVENT_CLASS’
   11 | DECLARE_EVENT_CLASS(ifs_status,
      | ^~~~~~~~~~~~~~~~~~~
In file included from /home/agluck/GIT/mywork/include/trace/define_trace.h:102,
                 from /home/agluck/GIT/mywork/include/trace/events/intel_ifs.h:44,
                 from /home/agluck/GIT/mywork/drivers/platform/x86/intel/ifs/runtest.c:27:
/home/agluck/GIT/mywork/include/trace/trace_events.h:207:37: warning: ‘trace_event_type_funcs_ifs_status’ defined but not used [-Wunused-variable]
  207 | static struct trace_event_functions trace_event_type_funcs_##call = {   \
      |                                     ^~~~~~~~~~~~~~~~~~~~~~~
/home/agluck/GIT/mywork/include/trace/events/intel_ifs.h:11:1: note: in expansion of macro ‘DECLARE_EVENT_CLASS’
   11 | DECLARE_EVENT_CLASS(ifs_status,
      | ^~~~~~~~~~~~~~~~~~~
make[1]: Leaving directory '/home/agluck/GIT/mywork/build/ifsv5-rc1'

-Tony
Steven Rostedt April 27, 2022, 2:42 a.m. UTC | #5 
On Tue, 26 Apr 2022 16:53:13 -0700
"Luck, Tony" <tony.luck@intel.com> wrote:
> 
> I looked at the examples in samples/trace_events/trace-events-sample.h
> and tried to use this. But I'm doing something wrong because the
> compiler barfs on something defined but not used.
> 
> Maybe my problem is the TP_printk() in the DECLARE_EVENT_CLASS() that
> is over-ridden by DEFINE_EVENT_PRINT(). I wasn't at all sure what to
> put here ... or how to use the base tracepoint that doesn't have the
> printk() over-ridden.

Yeah, that could be confusing.

Basically, TRACE_EVENT() is simply defined as:

DECLARE_EVENT_CLASS()
DEFINE_EVENT();

So technically you could create the class and event with the same name,
and then you could create a second event on top of that. But I usually
suggest people explicitly specify the DECLARE_EVENT_CLASS() and
DEFINE_EVENT().

I would not do this until you have more than one event. The what you
would do is create one event where the print matches the
DECLARE_EVENT_CLASS() TP_printk(), and have that event defined with
just DEFINE_EVENT(). Then create other events with the
DEFINE_EVENT_PRINT().

> 
> I think I need my class to just save both the u64 values to the trace
> buffer. Then the different trace points will extract the bits they want
> and print in a user friendly way. While this increases space used in
> the trace buffer, these events are not crazy high frequency. Usually 
> one or two events per core with a gap 30 minutes or more between tests.
> 
> In my ".c" file the tracepoint looks like this using the name from
> DEFINE_EVENT_PRINT(), and now passing the full u64 values:
> 
> 	trace_ifs_status_saf(activate.data, status.data);
> 
> and my #include file looks like this:
> 
> ----------------------------------------------
> /* SPDX-License-Identifier: GPL-2.0 */
> #undef TRACE_SYSTEM
> #define TRACE_SYSTEM intel_ifs
> 
> #if !defined(_TRACE_IFS_H) || defined(TRACE_HEADER_MULTI_READ)
> #define _TRACE_IFS_H
> 
> #include <linux/ktime.h>
> #include <linux/tracepoint.h>
> 
> DECLARE_EVENT_CLASS(ifs_status,
> 
> 	TP_PROTO(u64 activate, u64 status),
> 
> 	TP_ARGS(activate, status),
> 
> 	TP_STRUCT__entry(
> 		__field(	u64,	activate	)
> 		__field(	u64,	status		)
> 	),
> 
> 	TP_fast_assign(
> 		__entry->activate = activate;
> 		__entry->status	= status;
> 	),
> 
> 	TP_printk("activate: %llx status: %llx",
> 		__entry->activate,
> 		__entry->status)
> );
> 
> DEFINE_EVENT_PRINT(ifs_status, ifs_status_saf,
> 	TP_PROTO(u64 activate, u64 status),
> 	TP_ARGS(activate, status),
> 	TP_printk("start: %.2x, stop: %.2x, status: %llx",
> 		((union ifs_scan *)&(__entry->activate))->start,
> 		((union ifs_scan *)&(__entry->activate))->stop,
> 		__entry->status)
> );
> 
> #endif /* _TRACE_IFS_H */
> 
> /* This part must be outside protection */
> #include <trace/define_trace.h>
> -----------------------------------------------------
> 
> GCC messages:
> 
> 
>   CC [M]  drivers/platform/x86/intel/ifs/runtest.o
> In file included from /home/agluck/GIT/mywork/include/trace/define_trace.h:102,
>                  from /home/agluck/GIT/mywork/include/trace/events/intel_ifs.h:44,
>                  from /home/agluck/GIT/mywork/drivers/platform/x86/intel/ifs/runtest.c:27:
> /home/agluck/GIT/mywork/include/trace/trace_events.h:426:13: warning: ‘print_fmt_ifs_status’ defined but not used [-Wunused-variable]
>   426 | static char print_fmt_##call[] = print;                                 \
>       |             ^~~~~~~~~~
> /home/agluck/GIT/mywork/include/trace/events/intel_ifs.h:11:1: note: in expansion of macro ‘DECLARE_EVENT_CLASS’
>    11 | DECLARE_EVENT_CLASS(ifs_status,
>       | ^~~~~~~~~~~~~~~~~~~
> In file included from /home/agluck/GIT/mywork/include/trace/define_trace.h:102,
>                  from /home/agluck/GIT/mywork/include/trace/events/intel_ifs.h:44,
>                  from /home/agluck/GIT/mywork/drivers/platform/x86/intel/ifs/runtest.c:27:
> /home/agluck/GIT/mywork/include/trace/trace_events.h:207:37: warning: ‘trace_event_type_funcs_ifs_status’ defined but not used [-Wunused-variable]
>   207 | static struct trace_event_functions trace_event_type_funcs_##call = {   \
>       |                                     ^~~~~~~~~~~~~~~~~~~~~~~
> /home/agluck/GIT/mywork/include/trace/events/intel_ifs.h:11:1: note: in expansion of macro ‘DECLARE_EVENT_CLASS’
>    11 | DECLARE_EVENT_CLASS(ifs_status,
>       | ^~~~~~~~~~~~~~~~~~~
> make[1]: Leaving directory '/home/agluck/GIT/mywork/build/ifsv5-rc1'
> 

Yeah, because you don't have more than one event, so the
DEFINE_EVENT_PRINT() does not make sense.  You still need one
DEFINE_EVENT() otherwise, you will get that static function not used
warning.

-- Steve
diff mbox series

Patch

diff --git a/MAINTAINERS b/MAINTAINERS
index d2ee63193ab3..abcf9b895ea8 100644
--- a/MAINTAINERS
+++ b/MAINTAINERS
@@ -9867,6 +9867,7 @@  R:	Ashok Raj <ashok.raj@intel.com>
 R:	Tony Luck <tony.luck@intel.com>
 S:	Maintained
 F:	drivers/platform/x86/intel/ifs
+F:	include/trace/events/intel_ifs.h
 
 INTEL INTEGRATED SENSOR HUB DRIVER
 M:	Srinivas Pandruvada <srinivas.pandruvada@linux.intel.com>
diff --git a/drivers/platform/x86/intel/ifs/runtest.c b/drivers/platform/x86/intel/ifs/runtest.c
index c30cc9c95b4f..d6cb5d9e44c2 100644
--- a/drivers/platform/x86/intel/ifs/runtest.c
+++ b/drivers/platform/x86/intel/ifs/runtest.c
@@ -23,6 +23,9 @@  static atomic_t siblings_out;
 static int cpu_sibl_ct;
 static bool scan_enabled = true;
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/intel_ifs.h>
+
 struct ifs_work {
 	struct work_struct w;
 	struct device *dev;
@@ -216,6 +219,8 @@  static void ifs_work_func(struct work_struct *work)
 
 		rdmsrl(MSR_SCAN_STATUS, status.data);
 
+		trace_ifs_status(activate, status);
+
 		/* Some cases can be retried, give up for others */
 		if (!can_restart(status))
 			break;
diff --git a/include/trace/events/intel_ifs.h b/include/trace/events/intel_ifs.h
new file mode 100644
index 000000000000..0611f370cb37
--- /dev/null
+++ b/include/trace/events/intel_ifs.h
@@ -0,0 +1,38 @@ 
+/* SPDX-License-Identifier: GPL-2.0 */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM intel_ifs
+
+#if !defined(_TRACE_IFS_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_IFS_H
+
+#include <linux/ktime.h>
+#include <linux/tracepoint.h>
+
+TRACE_EVENT(ifs_status,
+
+	TP_PROTO(union ifs_scan activate, union ifs_status status),
+
+	TP_ARGS(activate, status),
+
+	TP_STRUCT__entry(
+		__field(	u64,	status	)
+		__field(	u8,	start	)
+		__field(	u8,	stop	)
+	),
+
+	TP_fast_assign(
+		__entry->start	= activate.start;
+		__entry->stop	= activate.stop;
+		__entry->status	= status.data;
+	),
+
+	TP_printk("start: %.2x, stop: %.2x, status: %llx",
+		__entry->start,
+		__entry->stop,
+		__entry->status)
+);
+
+#endif /* _TRACE_IFS_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>