2021-04-12 08:37:35

by Leo Yan

[permalink] [raw]
Subject: [PATCH v1 3/3] perf session: Dump PERF_RECORD_TIME_CONV event

Now perf tool uses the common stub function process_event_op2_stub() for
dumping TIME_CONV event, thus it doesn't output the clock parameters
contained in the event.

This patch adds the callback function for dumping the hardware clock
parameters in TIME_CONV event.

Before:

# perf report -D

0x978 [0x38]: event: 79
.
. ... raw event: size 56 bytes
. 0000: 4f 00 00 00 00 00 38 00 15 00 00 00 00 00 00 00 O.....8.........
. 0010: 00 00 40 01 00 00 00 00 86 89 0b bf df ff ff ff ..@........<BF><DF><FF><FF><FF>
. 0020: d1 c1 b2 39 03 00 00 00 ff ff ff ff ff ff ff 00 <D1><C1><B2>9....<FF><FF><FF><FF><FF><FF><FF>.
. 0030: 01 01 00 00 00 00 00 00 ........

0 0 0x978 [0x38]: PERF_RECORD_TIME_CONV
: unhandled!

[...]

After:

# perf report -D

0x978 [0x38]: event: 79
.
. ... raw event: size 56 bytes
. 0000: 4f 00 00 00 00 00 38 00 15 00 00 00 00 00 00 00 O.....8.........
. 0010: 00 00 40 01 00 00 00 00 86 89 0b bf df ff ff ff ..@........<BF><DF><FF><FF><FF>
. 0020: d1 c1 b2 39 03 00 00 00 ff ff ff ff ff ff ff 00 <D1><C1><B2>9....<FF><FF><FF><FF><FF><FF><FF>.
. 0030: 01 01 00 00 00 00 00 00 ........

0 0 0x978 [0x38]: PERF_RECORD_TIME_CONV
... Time Shift 21
... Time Muliplier 20971520
... Time Zero 18446743935180835206
... Time Cycles 13852918225
... Time Mask 0xffffffffffffff
... Cap Time Zero 1
... Cap Time Short 1
: unhandled!

[...]

Signed-off-by: Leo Yan <[email protected]>
---
tools/perf/util/session.c | 13 ++++++++++++-
tools/perf/util/tsc.c | 31 +++++++++++++++++++++++++++++++
tools/perf/util/tsc.h | 4 ++++
3 files changed, 47 insertions(+), 1 deletion(-)

diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index afca3d5fc851..19a0b2bc5f33 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -29,6 +29,7 @@
#include "thread-stack.h"
#include "sample-raw.h"
#include "stat.h"
+#include "tsc.h"
#include "ui/progress.h"
#include "../perf.h"
#include "arch/common.h"
@@ -451,6 +452,16 @@ static int process_stat_round_stub(struct perf_session *perf_session __maybe_unu
return 0;
}

+static int process_event_time_conv_stub(struct perf_session *perf_session __maybe_unused,
+ union perf_event *event)
+{
+ if (dump_trace)
+ perf_event__fprintf_time_conv(event, stdout);
+
+ dump_printf(": unhandled!\n");
+ return 0;
+}
+
static int perf_session__process_compressed_event_stub(struct perf_session *session __maybe_unused,
union perf_event *event __maybe_unused,
u64 file_offset __maybe_unused)
@@ -532,7 +543,7 @@ void perf_tool__fill_defaults(struct perf_tool *tool)
if (tool->stat_round == NULL)
tool->stat_round = process_stat_round_stub;
if (tool->time_conv == NULL)
- tool->time_conv = process_event_op2_stub;
+ tool->time_conv = process_event_time_conv_stub;
if (tool->feature == NULL)
tool->feature = process_event_op2_stub;
if (tool->compressed == NULL)
diff --git a/tools/perf/util/tsc.c b/tools/perf/util/tsc.c
index 62b4c75c966c..e2a2c63e5189 100644
--- a/tools/perf/util/tsc.c
+++ b/tools/perf/util/tsc.c
@@ -1,5 +1,7 @@
// SPDX-License-Identifier: GPL-2.0
#include <errno.h>
+#include <inttypes.h>
+#include <string.h>

#include <linux/compiler.h>
#include <linux/perf_event.h>
@@ -110,3 +112,32 @@ u64 __weak rdtsc(void)
{
return 0;
}
+
+size_t perf_event__fprintf_time_conv(union perf_event *event, FILE *fp)
+{
+ struct perf_record_time_conv *tc = (struct perf_record_time_conv *)event;
+ size_t ret;
+
+ ret = fprintf(fp, "\n... Time Shift %" PRI_lu64 "\n", tc->time_shift);
+ ret += fprintf(fp, "... Time Muliplier %" PRI_lu64 "\n", tc->time_mult);
+ ret += fprintf(fp, "... Time Zero %" PRI_lu64 "\n", tc->time_zero);
+
+ /*
+ * The event TIME_CONV was extended for the fields from "time_cycles"
+ * when supported cap_user_time_short, for backward compatibility,
+ * checks the event size and prints these extended fields if these
+ * fields are contained in the perf data file.
+ */
+ if (tc->header.size > ((void *)&tc->time_cycles - (void *)tc)) {
+ ret += fprintf(fp, "... Time Cycles %" PRI_lu64 "\n",
+ tc->time_cycles);
+ ret += fprintf(fp, "... Time Mask %#" PRI_lx64 "\n",
+ tc->time_mask);
+ ret += fprintf(fp, "... Cap Time Zero %" PRId32 "\n",
+ tc->cap_user_time_zero);
+ ret += fprintf(fp, "... Cap Time Short %" PRId32 "\n",
+ tc->cap_user_time_short);
+ }
+
+ return ret;
+}
diff --git a/tools/perf/util/tsc.h b/tools/perf/util/tsc.h
index 72a15419f3b3..7d83a31732a7 100644
--- a/tools/perf/util/tsc.h
+++ b/tools/perf/util/tsc.h
@@ -4,6 +4,8 @@

#include <linux/types.h>

+#include "event.h"
+
struct perf_tsc_conversion {
u16 time_shift;
u32 time_mult;
@@ -24,4 +26,6 @@ u64 perf_time_to_tsc(u64 ns, struct perf_tsc_conversion *tc);
u64 tsc_to_perf_time(u64 cyc, struct perf_tsc_conversion *tc);
u64 rdtsc(void);

+size_t perf_event__fprintf_time_conv(union perf_event *event, FILE *fp);
+
#endif // __PERF_TSC_H
--
2.25.1


2021-04-26 06:11:06

by Adrian Hunter

[permalink] [raw]
Subject: Re: [PATCH v1 3/3] perf session: Dump PERF_RECORD_TIME_CONV event

On 12/04/21 11:34 am, Leo Yan wrote:
> Now perf tool uses the common stub function process_event_op2_stub() for
> dumping TIME_CONV event, thus it doesn't output the clock parameters
> contained in the event.
>
> This patch adds the callback function for dumping the hardware clock
> parameters in TIME_CONV event.
>
> Before:
>
> # perf report -D
>
> 0x978 [0x38]: event: 79
> .
> . ... raw event: size 56 bytes
> . 0000: 4f 00 00 00 00 00 38 00 15 00 00 00 00 00 00 00 O.....8.........
> . 0010: 00 00 40 01 00 00 00 00 86 89 0b bf df ff ff ff ..@........<BF><DF><FF><FF><FF>
> . 0020: d1 c1 b2 39 03 00 00 00 ff ff ff ff ff ff ff 00 <D1><C1><B2>9....<FF><FF><FF><FF><FF><FF><FF>.
> . 0030: 01 01 00 00 00 00 00 00 ........
>
> 0 0 0x978 [0x38]: PERF_RECORD_TIME_CONV
> : unhandled!
>
> [...]
>
> After:
>
> # perf report -D
>
> 0x978 [0x38]: event: 79
> .
> . ... raw event: size 56 bytes
> . 0000: 4f 00 00 00 00 00 38 00 15 00 00 00 00 00 00 00 O.....8.........
> . 0010: 00 00 40 01 00 00 00 00 86 89 0b bf df ff ff ff ..@........<BF><DF><FF><FF><FF>
> . 0020: d1 c1 b2 39 03 00 00 00 ff ff ff ff ff ff ff 00 <D1><C1><B2>9....<FF><FF><FF><FF><FF><FF><FF>.
> . 0030: 01 01 00 00 00 00 00 00 ........
>
> 0 0 0x978 [0x38]: PERF_RECORD_TIME_CONV
> ... Time Shift 21
> ... Time Muliplier 20971520
> ... Time Zero 18446743935180835206
> ... Time Cycles 13852918225
> ... Time Mask 0xffffffffffffff
> ... Cap Time Zero 1
> ... Cap Time Short 1
> : unhandled!
>
> [...]
>
> Signed-off-by: Leo Yan <[email protected]>

Perhaps could make use of a helper like the one described in my comments for patch 2.
Nevertheless:

Acked-by: Adrian Hunter <[email protected]>


> ---
> tools/perf/util/session.c | 13 ++++++++++++-
> tools/perf/util/tsc.c | 31 +++++++++++++++++++++++++++++++
> tools/perf/util/tsc.h | 4 ++++
> 3 files changed, 47 insertions(+), 1 deletion(-)
>
> diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
> index afca3d5fc851..19a0b2bc5f33 100644
> --- a/tools/perf/util/session.c
> +++ b/tools/perf/util/session.c
> @@ -29,6 +29,7 @@
> #include "thread-stack.h"
> #include "sample-raw.h"
> #include "stat.h"
> +#include "tsc.h"
> #include "ui/progress.h"
> #include "../perf.h"
> #include "arch/common.h"
> @@ -451,6 +452,16 @@ static int process_stat_round_stub(struct perf_session *perf_session __maybe_unu
> return 0;
> }
>
> +static int process_event_time_conv_stub(struct perf_session *perf_session __maybe_unused,
> + union perf_event *event)
> +{
> + if (dump_trace)
> + perf_event__fprintf_time_conv(event, stdout);
> +
> + dump_printf(": unhandled!\n");
> + return 0;
> +}
> +
> static int perf_session__process_compressed_event_stub(struct perf_session *session __maybe_unused,
> union perf_event *event __maybe_unused,
> u64 file_offset __maybe_unused)
> @@ -532,7 +543,7 @@ void perf_tool__fill_defaults(struct perf_tool *tool)
> if (tool->stat_round == NULL)
> tool->stat_round = process_stat_round_stub;
> if (tool->time_conv == NULL)
> - tool->time_conv = process_event_op2_stub;
> + tool->time_conv = process_event_time_conv_stub;
> if (tool->feature == NULL)
> tool->feature = process_event_op2_stub;
> if (tool->compressed == NULL)
> diff --git a/tools/perf/util/tsc.c b/tools/perf/util/tsc.c
> index 62b4c75c966c..e2a2c63e5189 100644
> --- a/tools/perf/util/tsc.c
> +++ b/tools/perf/util/tsc.c
> @@ -1,5 +1,7 @@
> // SPDX-License-Identifier: GPL-2.0
> #include <errno.h>
> +#include <inttypes.h>
> +#include <string.h>
>
> #include <linux/compiler.h>
> #include <linux/perf_event.h>
> @@ -110,3 +112,32 @@ u64 __weak rdtsc(void)
> {
> return 0;
> }
> +
> +size_t perf_event__fprintf_time_conv(union perf_event *event, FILE *fp)
> +{
> + struct perf_record_time_conv *tc = (struct perf_record_time_conv *)event;
> + size_t ret;
> +
> + ret = fprintf(fp, "\n... Time Shift %" PRI_lu64 "\n", tc->time_shift);
> + ret += fprintf(fp, "... Time Muliplier %" PRI_lu64 "\n", tc->time_mult);
> + ret += fprintf(fp, "... Time Zero %" PRI_lu64 "\n", tc->time_zero);
> +
> + /*
> + * The event TIME_CONV was extended for the fields from "time_cycles"
> + * when supported cap_user_time_short, for backward compatibility,
> + * checks the event size and prints these extended fields if these
> + * fields are contained in the perf data file.
> + */
> + if (tc->header.size > ((void *)&tc->time_cycles - (void *)tc)) {
> + ret += fprintf(fp, "... Time Cycles %" PRI_lu64 "\n",
> + tc->time_cycles);
> + ret += fprintf(fp, "... Time Mask %#" PRI_lx64 "\n",
> + tc->time_mask);
> + ret += fprintf(fp, "... Cap Time Zero %" PRId32 "\n",
> + tc->cap_user_time_zero);
> + ret += fprintf(fp, "... Cap Time Short %" PRId32 "\n",
> + tc->cap_user_time_short);
> + }
> +
> + return ret;
> +}
> diff --git a/tools/perf/util/tsc.h b/tools/perf/util/tsc.h
> index 72a15419f3b3..7d83a31732a7 100644
> --- a/tools/perf/util/tsc.h
> +++ b/tools/perf/util/tsc.h
> @@ -4,6 +4,8 @@
>
> #include <linux/types.h>
>
> +#include "event.h"
> +
> struct perf_tsc_conversion {
> u16 time_shift;
> u32 time_mult;
> @@ -24,4 +26,6 @@ u64 perf_time_to_tsc(u64 ns, struct perf_tsc_conversion *tc);
> u64 tsc_to_perf_time(u64 cyc, struct perf_tsc_conversion *tc);
> u64 rdtsc(void);
>
> +size_t perf_event__fprintf_time_conv(union perf_event *event, FILE *fp);
> +
> #endif // __PERF_TSC_H
>