[PATCH 0/6] perf tools: Add wallclock time conversion support

[PATCH 0/6] perf tools: Add wallclock time conversion support

[Jiri Olsa]

hi,
this patchset is based on changes made by David Ahern long time ago.
The perf code moved a lot since then, but the idea is the same.

The patchset is adding the ability to display TOD/wallclock timestamp
in 'perf script' output and in 'perf data convert --to-ctf' subcommand,
so the converted CTF data contain TOD/wallclock timestamps.

It's done by adding new header FEATURE 'CLOCK_DATA' to perf.data, that
stores reference times for both TOD/wallclock time and for the clock that
perf record is configured to use. These reference times are then used to
convert sample's timestamps to TOD/wallclock timestamps.

The feature is available only for recording with clockid specified,
because it's the only case where we can get reference time to TOD/wallclock
time. We can't do that with perf clock yet.

Also available in here:
  git://git.kernel.org/pub/scm/linux/kernel/git/jolsa/perf.git
  perf/abs_time

thanks,
jirka


---
Jiri Olsa (6):
      perf tools: Add clockid_name function
      perf tools: Store clock references for -k/--clockid option
      perf tools: Move clockid_res_ns under clock struct
      perf tools: Add support to store time of day in CTF data conversion
      perf script: Change enum perf_output_field values to be 64 bits
      perf script: Add tod field to display time of day

 tools/perf/Documentation/perf-data.txt             |   3 ++
 tools/perf/Documentation/perf.data-file-format.txt |  13 +++++++
 tools/perf/builtin-data.c                          |   1 +
 tools/perf/builtin-record.c                        |  58 ++++++++++++++++++++++++++++--
 tools/perf/builtin-script.c                        | 195 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++----------------------------------
 tools/perf/util/data-convert-bt.c                  |  56 ++++++++++++++++++-----------
 tools/perf/util/data-convert.h                     |   1 +
 tools/perf/util/env.h                              |  14 +++++++-
 tools/perf/util/header.c                           | 120 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++---
 tools/perf/util/header.h                           |   1 +
 tools/perf/util/util.h                             |   2 ++
 11 files changed, 371 insertions(+), 93 deletions(-)

[PATCH 1/6] perf tools: Add clockid_name function

[Jiri Olsa]

Adding clockid_name function to get the clock name based
on its clockid. It will be used in following changes.

Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/builtin-record.c | 11 +++++++++++
 tools/perf/util/util.h      |  2 ++
 2 files changed, 13 insertions(+)

diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
index b6bdccd875bc..468c669519a6 100644
--- a/tools/perf/builtin-record.c
+++ b/tools/perf/builtin-record.c
@@ -2121,6 +2121,17 @@ static const struct clockid_map clockids[] = {
 	CLOCKID_END,
 };
 
+const char *clockid_name(clockid_t clk_id)
+{
+	const struct clockid_map *cm;
+
+	for (cm = clockids; cm->name; cm++) {
+		if (cm->clockid == clk_id)
+			return cm->name;
+	}
+	return "(not found)";
+}
+
 static int get_clockid_res(clockid_t clk_id, u64 *res_ns)
 {
 	struct timespec res;
diff --git a/tools/perf/util/util.h b/tools/perf/util/util.h
index f486fdd3a538..126dad238ee3 100644
--- a/tools/perf/util/util.h
+++ b/tools/perf/util/util.h
@@ -62,4 +62,6 @@ char *perf_exe(char *buf, int len);
 #endif
 #endif
 
+const char *clockid_name(clockid_t clk_id);
+
 #endif /* GIT_COMPAT_UTIL_H */
-- 
2.25.4

Re: [PATCH 1/6] perf tools: Add clockid_name function

[Andi Kleen]

> diff --git a/tools/perf/util/util.h b/tools/perf/util/util.h
> index f486fdd3a538..126dad238ee3 100644
> --- a/tools/perf/util/util.h
> +++ b/tools/perf/util/util.h
> @@ -62,4 +62,6 @@ char *perf_exe(char *buf, int len);
>  #endif
>  #endif
>  
> +const char *clockid_name(clockid_t clk_id);

If it's a generic "util" it probably shouldn't live in builtin-record.c

-Andi

Re: [PATCH 1/6] perf tools: Add clockid_name function

[Jiri Olsa]

On Fri, Jul 31, 2020 at 08:33:37AM -0700, Andi Kleen wrote:
> > diff --git a/tools/perf/util/util.h b/tools/perf/util/util.h
> > index f486fdd3a538..126dad238ee3 100644
> > --- a/tools/perf/util/util.h
> > +++ b/tools/perf/util/util.h
> > @@ -62,4 +62,6 @@ char *perf_exe(char *buf, int len);
> >  #endif
> >  #endif
> >  
> > +const char *clockid_name(clockid_t clk_id);
> 
> If it's a generic "util" it probably shouldn't live in builtin-record.c

true, but it's where all the clockid data is,
I'd need to move parse_clockid as well, I'll check

thanks,
jirka

[PATCH 2/6] perf tools: Store clock references for -k/--clockid option

[Jiri Olsa]

Adding new CLOCK_DATA feature that stores reference times
when -k/--clockid option is specified.

It contains clock id and its reference time together with
wall clock time taken at the 'same time', both values are
in nanoseconds.

The format of data is as below:

  struct {
       u32 version;  /* version = 1 */
       u32 clockid;
       u64 clockid_time_ns;
       u64 wall_clock_ns;
  };

This clock reference times will be used in following changes
to display wall clock for perf events.

It's available only for recording with clockid specified,
because it's the only case where we can get reference time
to wallclock time. It's can't do that with perf clock yet.

Original-patch-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 .../Documentation/perf.data-file-format.txt   |  13 ++
 tools/perf/builtin-record.c                   |  41 +++++++
 tools/perf/util/env.h                         |  12 ++
 tools/perf/util/header.c                      | 112 ++++++++++++++++++
 tools/perf/util/header.h                      |   1 +
 5 files changed, 179 insertions(+)

diff --git a/tools/perf/Documentation/perf.data-file-format.txt b/tools/perf/Documentation/perf.data-file-format.txt
index b6472e463284..c484e81987c7 100644
--- a/tools/perf/Documentation/perf.data-file-format.txt
+++ b/tools/perf/Documentation/perf.data-file-format.txt
@@ -389,6 +389,19 @@ struct {
 Example:
  cpu pmu capabilities: branches=32, max_precise=3, pmu_name=icelake
 
+	HEADER_CLOCK_DATA = 29,
+
+	Contains clock id and its reference time together with wall clock
+	time taken at the 'same time', both values are in nanoseconds.
+	The format of data is as below.
+
+struct {
+	u32 version;  /* version = 1 */
+	u32 clockid;
+	u64 clockid_time_ns;
+	u64 wall_clock_ns;
+};
+
 	other bits are reserved and should ignored for now
 	HEADER_FEAT_BITS	= 256,
 
diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
index 468c669519a6..f8280e721e1a 100644
--- a/tools/perf/builtin-record.c
+++ b/tools/perf/builtin-record.c
@@ -70,6 +70,7 @@
 #include <linux/time64.h>
 #include <linux/zalloc.h>
 #include <linux/bitmap.h>
+#include <sys/time.h>
 
 struct switch_output {
 	bool		 enabled;
@@ -1203,6 +1204,9 @@ static void record__init_features(struct record *rec)
 	if (!(rec->opts.use_clockid && rec->opts.clockid_res_ns))
 		perf_header__clear_feat(&session->header, HEADER_CLOCKID);
 
+	if (!rec->opts.use_clockid)
+		perf_header__clear_feat(&session->header, HEADER_CLOCK_DATA);
+
 	perf_header__clear_feat(&session->header, HEADER_DIR_FORMAT);
 	if (!record__comp_enabled(rec))
 		perf_header__clear_feat(&session->header, HEADER_COMPRESSED);
@@ -1551,6 +1555,40 @@ static int record__setup_sb_evlist(struct record *rec)
 	return 0;
 }
 
+static int record__init_clock(struct record *rec)
+{
+	struct perf_session *session = rec->session;
+	struct timespec ref_clockid;
+	struct timeval ref_tod;
+	u64 ref;
+
+	if (!rec->opts.use_clockid)
+		return 0;
+
+	session->header.env.clock.clockid = rec->opts.clockid;
+
+	if (gettimeofday(&ref_tod, NULL) != 0) {
+		pr_err("gettimeofday failed, cannot set reference time.\n");
+		return -1;
+	}
+
+	if (clock_gettime(rec->opts.clockid, &ref_clockid)) {
+		pr_err("clock_gettime failed, cannot set reference time.\n");
+		return -1;
+	}
+
+	ref = (u64) ref_tod.tv_sec * NSEC_PER_SEC +
+	      (u64) ref_tod.tv_usec * NSEC_PER_USEC;
+
+	session->header.env.clock.clockid_ns = ref;
+
+	ref = (u64) ref_clockid.tv_sec * NSEC_PER_SEC +
+	      (u64) ref_clockid.tv_nsec;
+
+	session->header.env.clock.tod_ns = ref;
+	return 0;
+}
+
 static int __cmd_record(struct record *rec, int argc, const char **argv)
 {
 	int err;
@@ -1630,6 +1668,9 @@ static int __cmd_record(struct record *rec, int argc, const char **argv)
 		return -1;
 	}
 
+	if (record__init_clock(rec))
+		return -1;
+
 	record__init_features(rec);
 
 	if (rec->opts.use_clockid && rec->opts.clockid_res_ns)
diff --git a/tools/perf/util/env.h b/tools/perf/util/env.h
index 1ab2682d5d2b..4098a63d5e64 100644
--- a/tools/perf/util/env.h
+++ b/tools/perf/util/env.h
@@ -100,6 +100,18 @@ struct perf_env {
 	/* For fast cpu to numa node lookup via perf_env__numa_node */
 	int			*numa_map;
 	int			 nr_numa_map;
+
+	/* For real clock time refference. */
+	struct {
+		u64	tod_ns;
+		u64	clockid_ns;
+		int	clockid;
+		/*
+		 * enabled is valid for report mode, and is true if above
+		 * values are set, it's set in process_clock_data
+		 */
+		bool	enabled;
+	} clock;
 };
 
 enum perf_compress_type {
diff --git a/tools/perf/util/header.c b/tools/perf/util/header.c
index 7a67d017d72c..ffe10d8fd5fa 100644
--- a/tools/perf/util/header.c
+++ b/tools/perf/util/header.c
@@ -895,6 +895,40 @@ static int write_clockid(struct feat_fd *ff,
 			sizeof(ff->ph->env.clockid_res_ns));
 }
 
+static int write_clock_data(struct feat_fd *ff,
+			    struct evlist *evlist __maybe_unused)
+{
+	u64 *data64;
+	u32 data32;
+	int ret;
+
+	/* version */
+	data32 = 1;
+
+	ret = do_write(ff, &data32, sizeof(data32));
+	if (ret < 0)
+		return ret;
+
+	/* clockid */
+	data32 = ff->ph->env.clock.clockid;
+
+	ret = do_write(ff, &data32, sizeof(data32));
+	if (ret < 0)
+		return ret;
+
+	/* TOD ref time */
+	data64 = &ff->ph->env.clock.clockid_ns;
+
+	ret = do_write(ff, data64, sizeof(*data64));
+	if (ret < 0)
+		return ret;
+
+	/* clockid ref time */
+	data64 = &ff->ph->env.clock.tod_ns;
+
+	return do_write(ff, data64, sizeof(*data64));
+}
+
 static int write_dir_format(struct feat_fd *ff,
 			    struct evlist *evlist __maybe_unused)
 {
@@ -1549,6 +1583,49 @@ static void print_clockid(struct feat_fd *ff, FILE *fp)
 		ff->ph->env.clockid_res_ns * 1000);
 }
 
+static void print_clock_data(struct feat_fd *ff, FILE *fp)
+{
+	struct timespec clockid_ns;
+	char tstr[64], date[64];
+	struct timeval tod_ns;
+	clockid_t clockid;
+	struct tm ltime;
+	u64 ref;
+
+	if (!ff->ph->env.clock.enabled) {
+		fprintf(fp, "# reference time disabled\n");
+		return;
+	}
+
+	/* Compute TOD time. */
+	ref = ff->ph->env.clock.tod_ns;
+	tod_ns.tv_sec = ref / NSEC_PER_SEC;
+	ref -= tod_ns.tv_sec * NSEC_PER_SEC;
+	tod_ns.tv_usec = ref / NSEC_PER_USEC;
+
+	/* Compute clockid time. */
+	ref = ff->ph->env.clock.clockid_ns;
+	clockid_ns.tv_sec = ref / NSEC_PER_SEC;
+	ref -= clockid_ns.tv_sec * NSEC_PER_SEC;
+	clockid_ns.tv_nsec = ref;
+
+	clockid = ff->ph->env.clock.clockid;
+
+	if (localtime_r(&tod_ns.tv_sec, &ltime) == NULL)
+		snprintf(tstr, sizeof(tstr), "<error>");
+	else {
+		strftime(date, sizeof(date), "%F %T", &ltime);
+		scnprintf(tstr, sizeof(tstr), "%s.%06d",
+			  date, (int) tod_ns.tv_usec);
+	}
+
+	fprintf(fp, "# clockid: %s (%u)\n", clockid_name(clockid), clockid);
+	fprintf(fp, "# reference time: %s = %ld.%06d (TOD) = %ld.%ld (%s)\n",
+		    tstr, tod_ns.tv_sec, (int) tod_ns.tv_usec,
+		    clockid_ns.tv_sec, clockid_ns.tv_nsec,
+		    clockid_name(clockid));
+}
+
 static void print_dir_format(struct feat_fd *ff, FILE *fp)
 {
 	struct perf_session *session;
@@ -2738,6 +2815,40 @@ static int process_clockid(struct feat_fd *ff,
 	return 0;
 }
 
+static int process_clock_data(struct feat_fd *ff,
+			      void *_data __maybe_unused)
+{
+	u32 data32;
+	u64 data64;
+
+	/* version */
+	if (do_read_u32(ff, &data32))
+		return -1;
+
+	if (data32 != 1)
+		return -1;
+
+	/* clockid */
+	if (do_read_u32(ff, &data32))
+		return -1;
+
+	ff->ph->env.clock.clockid = data32;
+
+	/* TOD ref time */
+	if (do_read_u64(ff, &data64))
+		return -1;
+
+	ff->ph->env.clock.tod_ns = data64;
+
+	/* clockid ref time */
+	if (do_read_u64(ff, &data64))
+		return -1;
+
+	ff->ph->env.clock.clockid_ns = data64;
+	ff->ph->env.clock.enabled = true;
+	return 0;
+}
+
 static int process_dir_format(struct feat_fd *ff,
 			      void *_data __maybe_unused)
 {
@@ -3008,6 +3119,7 @@ const struct perf_header_feature_ops feat_ops[HEADER_LAST_FEATURE] = {
 	FEAT_OPR(BPF_BTF,       bpf_btf,        false),
 	FEAT_OPR(COMPRESSED,	compressed,	false),
 	FEAT_OPR(CPU_PMU_CAPS,	cpu_pmu_caps,	false),
+	FEAT_OPR(CLOCK_DATA,	clock_data,	false),
 };
 
 struct header_print_data {
diff --git a/tools/perf/util/header.h b/tools/perf/util/header.h
index 650bd1c7a99b..2aca71763ecf 100644
--- a/tools/perf/util/header.h
+++ b/tools/perf/util/header.h
@@ -44,6 +44,7 @@ enum {
 	HEADER_BPF_BTF,
 	HEADER_COMPRESSED,
 	HEADER_CPU_PMU_CAPS,
+	HEADER_CLOCK_DATA,
 	HEADER_LAST_FEATURE,
 	HEADER_FEAT_BITS	= 256,
 };
-- 
2.25.4

Re: [PATCH 2/6] perf tools: Store clock references for -k/--clockid option

[Alexey Budankov]

On 31.07.2020 0:39, Jiri Olsa wrote:
> Adding new CLOCK_DATA feature that stores reference times
> when -k/--clockid option is specified.
> 
> It contains clock id and its reference time together with
> wall clock time taken at the 'same time', both values are
> in nanoseconds.
> 
> The format of data is as below:
> 
>   struct {
>        u32 version;  /* version = 1 */
>        u32 clockid;
>        u64 clockid_time_ns;
>        u64 wall_clock_ns;
>   };
> 
> This clock reference times will be used in following changes
> to display wall clock for perf events.
> 
> It's available only for recording with clockid specified,
> because it's the only case where we can get reference time
> to wallclock time. It's can't do that with perf clock yet.
> 
> Original-patch-by: David Ahern <dsahern@gmail.com>
> Signed-off-by: Jiri Olsa <jolsa@kernel.org>
> ---
>  .../Documentation/perf.data-file-format.txt   |  13 ++
>  tools/perf/builtin-record.c                   |  41 +++++++
>  tools/perf/util/env.h                         |  12 ++
>  tools/perf/util/header.c                      | 112 ++++++++++++++++++
>  tools/perf/util/header.h                      |   1 +
>  5 files changed, 179 insertions(+)
> 
> diff --git a/tools/perf/Documentation/perf.data-file-format.txt b/tools/perf/Documentation/perf.data-file-format.txt
> index b6472e463284..c484e81987c7 100644
> --- a/tools/perf/Documentation/perf.data-file-format.txt
> +++ b/tools/perf/Documentation/perf.data-file-format.txt
> @@ -389,6 +389,19 @@ struct {
>  Example:
>   cpu pmu capabilities: branches=32, max_precise=3, pmu_name=icelake
>  
> +	HEADER_CLOCK_DATA = 29,
> +
> +	Contains clock id and its reference time together with wall clock
> +	time taken at the 'same time', both values are in nanoseconds.
> +	The format of data is as below.
> +
> +struct {
> +	u32 version;  /* version = 1 */
> +	u32 clockid;
> +	u64 clockid_time_ns;
> +	u64 wall_clock_ns;
> +};
> +
>  	other bits are reserved and should ignored for now
>  	HEADER_FEAT_BITS	= 256,
>  
> diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
> index 468c669519a6..f8280e721e1a 100644
> --- a/tools/perf/builtin-record.c
> +++ b/tools/perf/builtin-record.c
> @@ -70,6 +70,7 @@
>  #include <linux/time64.h>
>  #include <linux/zalloc.h>
>  #include <linux/bitmap.h>
> +#include <sys/time.h>
>  
>  struct switch_output {
>  	bool		 enabled;
> @@ -1203,6 +1204,9 @@ static void record__init_features(struct record *rec)
>  	if (!(rec->opts.use_clockid && rec->opts.clockid_res_ns))
>  		perf_header__clear_feat(&session->header, HEADER_CLOCKID);
>  
> +	if (!rec->opts.use_clockid)
> +		perf_header__clear_feat(&session->header, HEADER_CLOCK_DATA);
> +
>  	perf_header__clear_feat(&session->header, HEADER_DIR_FORMAT);
>  	if (!record__comp_enabled(rec))
>  		perf_header__clear_feat(&session->header, HEADER_COMPRESSED);
> @@ -1551,6 +1555,40 @@ static int record__setup_sb_evlist(struct record *rec)
>  	return 0;
>  }
>  
> +static int record__init_clock(struct record *rec)
> +{
> +	struct perf_session *session = rec->session;
> +	struct timespec ref_clockid;
> +	struct timeval ref_tod;
> +	u64 ref;
> +
> +	if (!rec->opts.use_clockid)
> +		return 0;
> +
> +	session->header.env.clock.clockid = rec->opts.clockid;
> +
> +	if (gettimeofday(&ref_tod, NULL) != 0) {
> +		pr_err("gettimeofday failed, cannot set reference time.\n");
> +		return -1;
> +	}
> +
> +	if (clock_gettime(rec->opts.clockid, &ref_clockid)) {
> +		pr_err("clock_gettime failed, cannot set reference time.\n");
> +		return -1;
> +	}

It might also want to be implemented in a loop and iteration with minimal
time delta is chosen to improve synchronization accuracy and also mitigate
possible context switches between gettimeofday() and clock_gettime() calls.

Alexei

Re: [PATCH 2/6] perf tools: Store clock references for -k/--clockid option

[Jiri Olsa]

On Fri, Jul 31, 2020 at 06:52:36PM +0300, Alexey Budankov wrote:
> 
> On 31.07.2020 0:39, Jiri Olsa wrote:
> > Adding new CLOCK_DATA feature that stores reference times
> > when -k/--clockid option is specified.
> > 
> > It contains clock id and its reference time together with
> > wall clock time taken at the 'same time', both values are
> > in nanoseconds.
> > 
> > The format of data is as below:
> > 
> >   struct {
> >        u32 version;  /* version = 1 */
> >        u32 clockid;
> >        u64 clockid_time_ns;
> >        u64 wall_clock_ns;
> >   };
> > 
> > This clock reference times will be used in following changes
> > to display wall clock for perf events.
> > 
> > It's available only for recording with clockid specified,
> > because it's the only case where we can get reference time
> > to wallclock time. It's can't do that with perf clock yet.
> > 
> > Original-patch-by: David Ahern <dsahern@gmail.com>
> > Signed-off-by: Jiri Olsa <jolsa@kernel.org>
> > ---
> >  .../Documentation/perf.data-file-format.txt   |  13 ++
> >  tools/perf/builtin-record.c                   |  41 +++++++
> >  tools/perf/util/env.h                         |  12 ++
> >  tools/perf/util/header.c                      | 112 ++++++++++++++++++
> >  tools/perf/util/header.h                      |   1 +
> >  5 files changed, 179 insertions(+)
> > 
> > diff --git a/tools/perf/Documentation/perf.data-file-format.txt b/tools/perf/Documentation/perf.data-file-format.txt
> > index b6472e463284..c484e81987c7 100644
> > --- a/tools/perf/Documentation/perf.data-file-format.txt
> > +++ b/tools/perf/Documentation/perf.data-file-format.txt
> > @@ -389,6 +389,19 @@ struct {
> >  Example:
> >   cpu pmu capabilities: branches=32, max_precise=3, pmu_name=icelake
> >  
> > +	HEADER_CLOCK_DATA = 29,
> > +
> > +	Contains clock id and its reference time together with wall clock
> > +	time taken at the 'same time', both values are in nanoseconds.
> > +	The format of data is as below.
> > +
> > +struct {
> > +	u32 version;  /* version = 1 */
> > +	u32 clockid;
> > +	u64 clockid_time_ns;
> > +	u64 wall_clock_ns;
> > +};
> > +
> >  	other bits are reserved and should ignored for now
> >  	HEADER_FEAT_BITS	= 256,
> >  
> > diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
> > index 468c669519a6..f8280e721e1a 100644
> > --- a/tools/perf/builtin-record.c
> > +++ b/tools/perf/builtin-record.c
> > @@ -70,6 +70,7 @@
> >  #include <linux/time64.h>
> >  #include <linux/zalloc.h>
> >  #include <linux/bitmap.h>
> > +#include <sys/time.h>
> >  
> >  struct switch_output {
> >  	bool		 enabled;
> > @@ -1203,6 +1204,9 @@ static void record__init_features(struct record *rec)
> >  	if (!(rec->opts.use_clockid && rec->opts.clockid_res_ns))
> >  		perf_header__clear_feat(&session->header, HEADER_CLOCKID);
> >  
> > +	if (!rec->opts.use_clockid)
> > +		perf_header__clear_feat(&session->header, HEADER_CLOCK_DATA);
> > +
> >  	perf_header__clear_feat(&session->header, HEADER_DIR_FORMAT);
> >  	if (!record__comp_enabled(rec))
> >  		perf_header__clear_feat(&session->header, HEADER_COMPRESSED);
> > @@ -1551,6 +1555,40 @@ static int record__setup_sb_evlist(struct record *rec)
> >  	return 0;
> >  }
> >  
> > +static int record__init_clock(struct record *rec)
> > +{
> > +	struct perf_session *session = rec->session;
> > +	struct timespec ref_clockid;
> > +	struct timeval ref_tod;
> > +	u64 ref;
> > +
> > +	if (!rec->opts.use_clockid)
> > +		return 0;
> > +
> > +	session->header.env.clock.clockid = rec->opts.clockid;
> > +
> > +	if (gettimeofday(&ref_tod, NULL) != 0) {
> > +		pr_err("gettimeofday failed, cannot set reference time.\n");
> > +		return -1;
> > +	}
> > +
> > +	if (clock_gettime(rec->opts.clockid, &ref_clockid)) {
> > +		pr_err("clock_gettime failed, cannot set reference time.\n");
> > +		return -1;
> > +	}
> 
> It might also want to be implemented in a loop and iteration with minimal
> time delta is chosen to improve synchronization accuracy and also mitigate
> possible context switches between gettimeofday() and clock_gettime() calls.

right, we could make this more accurate.. I'll post some follow up
change with that

thanks,
jirka

Re: [PATCH 2/6] perf tools: Store clock references for -k/--clockid option

[David Ahern]

On 7/31/20 10:15 AM, Jiri Olsa wrote:
>> It might also want to be implemented in a loop and iteration with minimal
>> time delta is chosen to improve synchronization accuracy and also mitigate
>> possible context switches between gettimeofday() and clock_gettime() calls.
> right, we could make this more accurate.. I'll post some follow up
> change with that

If it is handled through vdso (e.g., x86) both calls should be very fast
with no context switches and the margin of error is well less than the
usec resolution in the output.

Re: [PATCH 2/6] perf tools: Store clock references for -k/--clockid option

[Namhyung Kim]

On Thu, Jul 30, 2020 at 11:39:46PM +0200, Jiri Olsa wrote:
> Adding new CLOCK_DATA feature that stores reference times
> when -k/--clockid option is specified.
> 
> It contains clock id and its reference time together with
> wall clock time taken at the 'same time', both values are
> in nanoseconds.
> 
> The format of data is as below:
> 
>   struct {
>        u32 version;  /* version = 1 */
>        u32 clockid;
>        u64 clockid_time_ns;
>        u64 wall_clock_ns;
>   };
> 
> This clock reference times will be used in following changes
> to display wall clock for perf events.
> 
> It's available only for recording with clockid specified,
> because it's the only case where we can get reference time
> to wallclock time. It's can't do that with perf clock yet.
> 
> Original-patch-by: David Ahern <dsahern@gmail.com>
> Signed-off-by: Jiri Olsa <jolsa@kernel.org>
> ---
>  .../Documentation/perf.data-file-format.txt   |  13 ++
>  tools/perf/builtin-record.c                   |  41 +++++++
>  tools/perf/util/env.h                         |  12 ++
>  tools/perf/util/header.c                      | 112 ++++++++++++++++++
>  tools/perf/util/header.h                      |   1 +
>  5 files changed, 179 insertions(+)
> 
> diff --git a/tools/perf/Documentation/perf.data-file-format.txt b/tools/perf/Documentation/perf.data-file-format.txt
> index b6472e463284..c484e81987c7 100644
> --- a/tools/perf/Documentation/perf.data-file-format.txt
> +++ b/tools/perf/Documentation/perf.data-file-format.txt
> @@ -389,6 +389,19 @@ struct {
>  Example:
>   cpu pmu capabilities: branches=32, max_precise=3, pmu_name=icelake
>  
> +	HEADER_CLOCK_DATA = 29,
> +
> +	Contains clock id and its reference time together with wall clock
> +	time taken at the 'same time', both values are in nanoseconds.
> +	The format of data is as below.
> +
> +struct {
> +	u32 version;  /* version = 1 */
> +	u32 clockid;
> +	u64 clockid_time_ns;
> +	u64 wall_clock_ns;
> +};
> +

It seems that it's slightly different than what it actually write to a file.
Specifically the last two fields should be reversed IMHO.


>  	other bits are reserved and should ignored for now
>  	HEADER_FEAT_BITS	= 256,
>
[SNIP]

> diff --git a/tools/perf/util/env.h b/tools/perf/util/env.h
> index 1ab2682d5d2b..4098a63d5e64 100644
> --- a/tools/perf/util/env.h
> +++ b/tools/perf/util/env.h
> @@ -100,6 +100,18 @@ struct perf_env {
>  	/* For fast cpu to numa node lookup via perf_env__numa_node */
>  	int			*numa_map;
>  	int			 nr_numa_map;
> +
> +	/* For real clock time refference. */

typo: reference

> +	struct {
> +		u64	tod_ns;
> +		u64	clockid_ns;
> +		int	clockid;
> +		/*
> +		 * enabled is valid for report mode, and is true if above
> +		 * values are set, it's set in process_clock_data
> +		 */
> +		bool	enabled;
> +	} clock;
>  };
>  
>  enum perf_compress_type {

[SNIP]
> +static void print_clock_data(struct feat_fd *ff, FILE *fp)
> +{
> +	struct timespec clockid_ns;
> +	char tstr[64], date[64];
> +	struct timeval tod_ns;
> +	clockid_t clockid;
> +	struct tm ltime;
> +	u64 ref;
> +
> +	if (!ff->ph->env.clock.enabled) {
> +		fprintf(fp, "# reference time disabled\n");
> +		return;
> +	}
> +
> +	/* Compute TOD time. */
> +	ref = ff->ph->env.clock.tod_ns;
> +	tod_ns.tv_sec = ref / NSEC_PER_SEC;
> +	ref -= tod_ns.tv_sec * NSEC_PER_SEC;
> +	tod_ns.tv_usec = ref / NSEC_PER_USEC;
> +
> +	/* Compute clockid time. */
> +	ref = ff->ph->env.clock.clockid_ns;
> +	clockid_ns.tv_sec = ref / NSEC_PER_SEC;
> +	ref -= clockid_ns.tv_sec * NSEC_PER_SEC;
> +	clockid_ns.tv_nsec = ref;
> +
> +	clockid = ff->ph->env.clock.clockid;
> +
> +	if (localtime_r(&tod_ns.tv_sec, &ltime) == NULL)
> +		snprintf(tstr, sizeof(tstr), "<error>");
> +	else {
> +		strftime(date, sizeof(date), "%F %T", &ltime);
> +		scnprintf(tstr, sizeof(tstr), "%s.%06d",
> +			  date, (int) tod_ns.tv_usec);
> +	}
> +
> +	fprintf(fp, "# clockid: %s (%u)\n", clockid_name(clockid), clockid);
> +	fprintf(fp, "# reference time: %s = %ld.%06d (TOD) = %ld.%ld (%s)\n",

Shouldn't the last one be %ld.%09ld?

Thanks
Namhyung


> +		    tstr, tod_ns.tv_sec, (int) tod_ns.tv_usec,
> +		    clockid_ns.tv_sec, clockid_ns.tv_nsec,
> +		    clockid_name(clockid));
> +}
> +
>  static void print_dir_format(struct feat_fd *ff, FILE *fp)
>  {
>  	struct perf_session *session;
> @@ -2738,6 +2815,40 @@ static int process_clockid(struct feat_fd *ff,
>  	return 0;
>  }
>  
> +static int process_clock_data(struct feat_fd *ff,
> +			      void *_data __maybe_unused)
> +{
> +	u32 data32;
> +	u64 data64;
> +
> +	/* version */
> +	if (do_read_u32(ff, &data32))
> +		return -1;
> +
> +	if (data32 != 1)
> +		return -1;
> +
> +	/* clockid */
> +	if (do_read_u32(ff, &data32))
> +		return -1;
> +
> +	ff->ph->env.clock.clockid = data32;
> +
> +	/* TOD ref time */
> +	if (do_read_u64(ff, &data64))
> +		return -1;
> +
> +	ff->ph->env.clock.tod_ns = data64;
> +
> +	/* clockid ref time */
> +	if (do_read_u64(ff, &data64))
> +		return -1;
> +
> +	ff->ph->env.clock.clockid_ns = data64;
> +	ff->ph->env.clock.enabled = true;
> +	return 0;
> +}
> +
>  static int process_dir_format(struct feat_fd *ff,
>  			      void *_data __maybe_unused)
>  {
> @@ -3008,6 +3119,7 @@ const struct perf_header_feature_ops feat_ops[HEADER_LAST_FEATURE] = {
>  	FEAT_OPR(BPF_BTF,       bpf_btf,        false),
>  	FEAT_OPR(COMPRESSED,	compressed,	false),
>  	FEAT_OPR(CPU_PMU_CAPS,	cpu_pmu_caps,	false),
> +	FEAT_OPR(CLOCK_DATA,	clock_data,	false),
>  };
>  
>  struct header_print_data {
> diff --git a/tools/perf/util/header.h b/tools/perf/util/header.h
> index 650bd1c7a99b..2aca71763ecf 100644
> --- a/tools/perf/util/header.h
> +++ b/tools/perf/util/header.h
> @@ -44,6 +44,7 @@ enum {
>  	HEADER_BPF_BTF,
>  	HEADER_COMPRESSED,
>  	HEADER_CPU_PMU_CAPS,
> +	HEADER_CLOCK_DATA,
>  	HEADER_LAST_FEATURE,
>  	HEADER_FEAT_BITS	= 256,
>  };
> -- 
> 2.25.4

Re: [PATCH 2/6] perf tools: Store clock references for -k/--clockid option

[Jiri Olsa]

On Mon, Aug 03, 2020 at 12:55:50PM +0900, Namhyung Kim wrote:

SNIP

> > diff --git a/tools/perf/Documentation/perf.data-file-format.txt b/tools/perf/Documentation/perf.data-file-format.txt
> > index b6472e463284..c484e81987c7 100644
> > --- a/tools/perf/Documentation/perf.data-file-format.txt
> > +++ b/tools/perf/Documentation/perf.data-file-format.txt
> > @@ -389,6 +389,19 @@ struct {
> >  Example:
> >   cpu pmu capabilities: branches=32, max_precise=3, pmu_name=icelake
> >  
> > +	HEADER_CLOCK_DATA = 29,
> > +
> > +	Contains clock id and its reference time together with wall clock
> > +	time taken at the 'same time', both values are in nanoseconds.
> > +	The format of data is as below.
> > +
> > +struct {
> > +	u32 version;  /* version = 1 */
> > +	u32 clockid;
> > +	u64 clockid_time_ns;
> > +	u64 wall_clock_ns;
> > +};
> > +
> 
> It seems that it's slightly different than what it actually write to a file.
> Specifically the last two fields should be reversed IMHO.

oops, you're right.. wil fix in new version

> 
> 
> >  	other bits are reserved and should ignored for now
> >  	HEADER_FEAT_BITS	= 256,
> >
> [SNIP]
> 
> > diff --git a/tools/perf/util/env.h b/tools/perf/util/env.h
> > index 1ab2682d5d2b..4098a63d5e64 100644
> > --- a/tools/perf/util/env.h
> > +++ b/tools/perf/util/env.h
> > @@ -100,6 +100,18 @@ struct perf_env {
> >  	/* For fast cpu to numa node lookup via perf_env__numa_node */
> >  	int			*numa_map;
> >  	int			 nr_numa_map;
> > +
> > +	/* For real clock time refference. */
> 
> typo: reference

ok

SNIP

> > +	else {
> > +		strftime(date, sizeof(date), "%F %T", &ltime);
> > +		scnprintf(tstr, sizeof(tstr), "%s.%06d",
> > +			  date, (int) tod_ns.tv_usec);
> > +	}
> > +
> > +	fprintf(fp, "# clockid: %s (%u)\n", clockid_name(clockid), clockid);
> > +	fprintf(fp, "# reference time: %s = %ld.%06d (TOD) = %ld.%ld (%s)\n",
> 
> Shouldn't the last one be %ld.%09ld?

sure, why not

thanks,
jirka

[PATCH 3/6] perf tools: Move clockid_res_ns under clock struct

[Jiri Olsa]

Moving clockid_res_ns under clock struct, so we have
clock related stuff in one place.

Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/builtin-record.c | 6 +++---
 tools/perf/util/env.h       | 2 +-
 tools/perf/util/header.c    | 8 ++++----
 3 files changed, 8 insertions(+), 8 deletions(-)

diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
index f8280e721e1a..955c621b0ff7 100644
--- a/tools/perf/builtin-record.c
+++ b/tools/perf/builtin-record.c
@@ -1565,6 +1565,9 @@ static int record__init_clock(struct record *rec)
 	if (!rec->opts.use_clockid)
 		return 0;
 
+	if (rec->opts.use_clockid && rec->opts.clockid_res_ns)
+		session->header.env.clock.clockid_res_ns = rec->opts.clockid_res_ns;
+
 	session->header.env.clock.clockid = rec->opts.clockid;
 
 	if (gettimeofday(&ref_tod, NULL) != 0) {
@@ -1673,9 +1676,6 @@ static int __cmd_record(struct record *rec, int argc, const char **argv)
 
 	record__init_features(rec);
 
-	if (rec->opts.use_clockid && rec->opts.clockid_res_ns)
-		session->header.env.clockid_res_ns = rec->opts.clockid_res_ns;
-
 	if (forks) {
 		err = perf_evlist__prepare_workload(rec->evlist, &opts->target,
 						    argv, data->is_pipe,
diff --git a/tools/perf/util/env.h b/tools/perf/util/env.h
index 4098a63d5e64..d50c0a3354e3 100644
--- a/tools/perf/util/env.h
+++ b/tools/perf/util/env.h
@@ -77,7 +77,6 @@ struct perf_env {
 	struct numa_node	*numa_nodes;
 	struct memory_node	*memory_nodes;
 	unsigned long long	 memory_bsize;
-	u64                     clockid_res_ns;
 
 	/*
 	 * bpf_info_lock protects bpf rbtrees. This is needed because the
@@ -105,6 +104,7 @@ struct perf_env {
 	struct {
 		u64	tod_ns;
 		u64	clockid_ns;
+		u64     clockid_res_ns;
 		int	clockid;
 		/*
 		 * enabled is valid for report mode, and is true if above
diff --git a/tools/perf/util/header.c b/tools/perf/util/header.c
index ffe10d8fd5fa..88151c5cf286 100644
--- a/tools/perf/util/header.c
+++ b/tools/perf/util/header.c
@@ -891,8 +891,8 @@ static int write_auxtrace(struct feat_fd *ff,
 static int write_clockid(struct feat_fd *ff,
 			 struct evlist *evlist __maybe_unused)
 {
-	return do_write(ff, &ff->ph->env.clockid_res_ns,
-			sizeof(ff->ph->env.clockid_res_ns));
+	return do_write(ff, &ff->ph->env.clock.clockid_res_ns,
+			sizeof(ff->ph->env.clock.clockid_res_ns));
 }
 
 static int write_clock_data(struct feat_fd *ff,
@@ -1580,7 +1580,7 @@ static void print_cpu_topology(struct feat_fd *ff, FILE *fp)
 static void print_clockid(struct feat_fd *ff, FILE *fp)
 {
 	fprintf(fp, "# clockid frequency: %"PRIu64" MHz\n",
-		ff->ph->env.clockid_res_ns * 1000);
+		ff->ph->env.clock.clockid_res_ns * 1000);
 }
 
 static void print_clock_data(struct feat_fd *ff, FILE *fp)
@@ -2809,7 +2809,7 @@ static int process_mem_topology(struct feat_fd *ff,
 static int process_clockid(struct feat_fd *ff,
 			   void *data __maybe_unused)
 {
-	if (do_read_u64(ff, &ff->ph->env.clockid_res_ns))
+	if (do_read_u64(ff, &ff->ph->env.clock.clockid_res_ns))
 		return -1;
 
 	return 0;
-- 
2.25.4

[PATCH 4/6] perf tools: Add support to store time of day in CTF data conversion

[Jiri Olsa]

Adding support to convert and store time of day in CTF
data conversion for 'perf data convert' subcommand.

The perf.data used for conversion needs to have clock data
information - must be recorded with -k/--clockid option).

New --tod option is added to 'perf data convert' subcommand
to convert data with timestamps converted to wall clock time.

Record data with clockid set:
  # perf record -k CLOCK_MONOTONIC kill
  kill: not enough arguments
  [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 0.033 MB perf.data (8 samples) ]

Convert data with TOD timestamps:
  # perf data convert --tod --to-ctf ./ctf
  [ perf data convert: Converted 'perf.data' into CTF data './ctf' ]
  [ perf data convert: Converted and wrote 0.000 MB (8 samples) ]

Display data in perf script:
  # perf script -F+tod --ns
            perf 262150 2020-07-13 18:38:50.097678523 153633.958246159:          1 cycles: ...
            perf 262150 2020-07-13 18:38:50.097682941 153633.958250577:          1 cycles: ...
            perf 262150 2020-07-13 18:38:50.097684997 153633.958252633:          7 cycles: ...
  ...

Display data in babeltrace:
  # babeltrace --clock-date  ./ctf
  [2020-07-13 18:38:50.097678523] (+?.?????????) cycles: { cpu_id = 0 }, { perf_ip = 0xFFF ...
  [2020-07-13 18:38:50.097682941] (+0.000004418) cycles: { cpu_id = 0 }, { perf_ip = 0xFFF ...
  [2020-07-13 18:38:50.097684997] (+0.000002056) cycles: { cpu_id = 0 }, { perf_ip = 0xFFF ...
  ...

It's available only for recording with clockid specified,
because it's the only case where we can get reference time
to wallclock time. It's can't do that with perf clock yet.

Error is display if you want to use --tod on data without
clockid specified:

  # perf data convert --tod --to-ctf ./ctf
  Can't provide --tod time, missing clock data. Please record with -k/--clockid option.
  Failed to setup CTF writer.
  Error during conversion setup.

Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/Documentation/perf-data.txt |  3 ++
 tools/perf/builtin-data.c              |  1 +
 tools/perf/util/data-convert-bt.c      | 56 +++++++++++++++++---------
 tools/perf/util/data-convert.h         |  1 +
 4 files changed, 41 insertions(+), 20 deletions(-)

diff --git a/tools/perf/Documentation/perf-data.txt b/tools/perf/Documentation/perf-data.txt
index c87180764829..726b9bc9e1a7 100644
--- a/tools/perf/Documentation/perf-data.txt
+++ b/tools/perf/Documentation/perf-data.txt
@@ -27,6 +27,9 @@ OPTIONS for 'convert'
 --to-ctf::
 	Triggers the CTF conversion, specify the path of CTF data directory.
 
+--tod::
+	Convert time to wall clock time.
+
 -i::
 	Specify input perf data file path.
 
diff --git a/tools/perf/builtin-data.c b/tools/perf/builtin-data.c
index ca2fb44874e4..8d23b8d6ee8e 100644
--- a/tools/perf/builtin-data.c
+++ b/tools/perf/builtin-data.c
@@ -65,6 +65,7 @@ static int cmd_data_convert(int argc, const char **argv)
 		OPT_STRING('i', "input", &input_name, "file", "input file name"),
 #ifdef HAVE_LIBBABELTRACE_SUPPORT
 		OPT_STRING(0, "to-ctf", &to_ctf, NULL, "Convert to CTF format"),
+		OPT_BOOLEAN(0, "tod", &opts.tod, "Convert time to wall clock time"),
 #endif
 		OPT_BOOLEAN('f', "force", &opts.force, "don't complain, do it"),
 		OPT_BOOLEAN(0, "all", &opts.all, "Convert all events"),
diff --git a/tools/perf/util/data-convert-bt.c b/tools/perf/util/data-convert-bt.c
index 5f36fc6a5578..ded8a9da0fe8 100644
--- a/tools/perf/util/data-convert-bt.c
+++ b/tools/perf/util/data-convert-bt.c
@@ -31,6 +31,8 @@
 #include "config.h"
 #include <linux/ctype.h>
 #include <linux/err.h>
+#include <linux/time64.h>
+#include "util.h"
 
 #define pr_N(n, fmt, ...) \
 	eprintf(n, debug_data_convert, fmt, ##__VA_ARGS__)
@@ -1381,11 +1383,26 @@ do {									\
 	return 0;
 }
 
-static int ctf_writer__setup_clock(struct ctf_writer *cw)
+static int ctf_writer__setup_clock(struct ctf_writer *cw,
+				   struct perf_session *session,
+				   bool tod)
 {
 	struct bt_ctf_clock *clock = cw->clock;
+	const char *desc = "perf clock";
+	int64_t offset = 0;
 
-	bt_ctf_clock_set_description(clock, "perf clock");
+	if (tod) {
+		struct perf_env *env = &session->header.env;
+
+		if (!env->clock.enabled) {
+			pr_err("Can't provide --tod time, missing clock data. "
+			       "Please record with -k/--clockid option.\n");
+			return -1;
+		}
+
+		desc   = clockid_name(env->clock.clockid);
+		offset = env->clock.tod_ns - env->clock.clockid_ns;
+	}
 
 #define SET(__n, __v)				\
 do {						\
@@ -1394,8 +1411,8 @@ do {						\
 } while (0)
 
 	SET(frequency,   1000000000);
-	SET(offset_s,    0);
-	SET(offset,      0);
+	SET(offset,      offset);
+	SET(description, desc);
 	SET(precision,   10);
 	SET(is_absolute, 0);
 
@@ -1481,7 +1498,8 @@ static void ctf_writer__cleanup(struct ctf_writer *cw)
 	memset(cw, 0, sizeof(*cw));
 }
 
-static int ctf_writer__init(struct ctf_writer *cw, const char *path)
+static int ctf_writer__init(struct ctf_writer *cw, const char *path,
+			    struct perf_session *session, bool tod)
 {
 	struct bt_ctf_writer		*writer;
 	struct bt_ctf_stream_class	*stream_class;
@@ -1505,7 +1523,7 @@ static int ctf_writer__init(struct ctf_writer *cw, const char *path)
 
 	cw->clock = clock;
 
-	if (ctf_writer__setup_clock(cw)) {
+	if (ctf_writer__setup_clock(cw, session, tod)) {
 		pr("Failed to setup CTF clock.\n");
 		goto err_cleanup;
 	}
@@ -1613,17 +1631,15 @@ int bt_convert__perf2ctf(const char *input, const char *path,
 	if (err)
 		return err;
 
-	/* CTF writer */
-	if (ctf_writer__init(cw, path))
-		return -1;
-
 	err = -1;
 	/* perf.data session */
 	session = perf_session__new(&data, 0, &c.tool);
-	if (IS_ERR(session)) {
-		err = PTR_ERR(session);
-		goto free_writer;
-	}
+	if (IS_ERR(session))
+		return PTR_ERR(session);
+
+	/* CTF writer */
+	if (ctf_writer__init(cw, path, session, opts->tod))
+		goto free_session;
 
 	if (c.queue_size) {
 		ordered_events__set_alloc_size(&session->ordered_events,
@@ -1632,17 +1648,17 @@ int bt_convert__perf2ctf(const char *input, const char *path,
 
 	/* CTF writer env/clock setup  */
 	if (ctf_writer__setup_env(cw, session))
-		goto free_session;
+		goto free_writer;
 
 	/* CTF events setup */
 	if (setup_events(cw, session))
-		goto free_session;
+		goto free_writer;
 
 	if (opts->all && setup_non_sample_events(cw, session))
-		goto free_session;
+		goto free_writer;
 
 	if (setup_streams(cw, session))
-		goto free_session;
+		goto free_writer;
 
 	err = perf_session__process_events(session);
 	if (!err)
@@ -1670,10 +1686,10 @@ int bt_convert__perf2ctf(const char *input, const char *path,
 
 	return err;
 
-free_session:
-	perf_session__delete(session);
 free_writer:
 	ctf_writer__cleanup(cw);
+free_session:
+	perf_session__delete(session);
 	pr_err("Error during conversion setup.\n");
 	return err;
 }
diff --git a/tools/perf/util/data-convert.h b/tools/perf/util/data-convert.h
index af90b6076c06..feab5f114e37 100644
--- a/tools/perf/util/data-convert.h
+++ b/tools/perf/util/data-convert.h
@@ -5,6 +5,7 @@
 struct perf_data_convert_opts {
 	bool force;
 	bool all;
+	bool tod;
 };
 
 #endif /* __DATA_CONVERT_H */
-- 
2.25.4

Re: [PATCH 4/6] perf tools: Add support to store time of day in CTF data conversion

[Namhyung Kim]

On Thu, Jul 30, 2020 at 11:39:48PM +0200, Jiri Olsa wrote:
> Adding support to convert and store time of day in CTF
> data conversion for 'perf data convert' subcommand.
> 
> The perf.data used for conversion needs to have clock data
> information - must be recorded with -k/--clockid option).
> 
> New --tod option is added to 'perf data convert' subcommand
> to convert data with timestamps converted to wall clock time.
> 
> Record data with clockid set:
>   # perf record -k CLOCK_MONOTONIC kill
>   kill: not enough arguments
>   [ perf record: Woken up 1 times to write data ]
>   [ perf record: Captured and wrote 0.033 MB perf.data (8 samples) ]
> 
> Convert data with TOD timestamps:
>   # perf data convert --tod --to-ctf ./ctf
>   [ perf data convert: Converted 'perf.data' into CTF data './ctf' ]
>   [ perf data convert: Converted and wrote 0.000 MB (8 samples) ]
> 
> Display data in perf script:
>   # perf script -F+tod --ns
>             perf 262150 2020-07-13 18:38:50.097678523 153633.958246159:          1 cycles: ...
>             perf 262150 2020-07-13 18:38:50.097682941 153633.958250577:          1 cycles: ...
>             perf 262150 2020-07-13 18:38:50.097684997 153633.958252633:          7 cycles: ...
>   ...

I believe this belongs to a later patch.

Thanks
Namhyung

> 
> Display data in babeltrace:
>   # babeltrace --clock-date  ./ctf
>   [2020-07-13 18:38:50.097678523] (+?.?????????) cycles: { cpu_id = 0 }, { perf_ip = 0xFFF ...
>   [2020-07-13 18:38:50.097682941] (+0.000004418) cycles: { cpu_id = 0 }, { perf_ip = 0xFFF ...
>   [2020-07-13 18:38:50.097684997] (+0.000002056) cycles: { cpu_id = 0 }, { perf_ip = 0xFFF ...
>   ...
> 
> It's available only for recording with clockid specified,
> because it's the only case where we can get reference time
> to wallclock time. It's can't do that with perf clock yet.
> 
> Error is display if you want to use --tod on data without
> clockid specified:
> 
>   # perf data convert --tod --to-ctf ./ctf
>   Can't provide --tod time, missing clock data. Please record with -k/--clockid option.
>   Failed to setup CTF writer.
>   Error during conversion setup.
> 
> Signed-off-by: Jiri Olsa <jolsa@kernel.org>
> ---
>  tools/perf/Documentation/perf-data.txt |  3 ++
>  tools/perf/builtin-data.c              |  1 +
>  tools/perf/util/data-convert-bt.c      | 56 +++++++++++++++++---------
>  tools/perf/util/data-convert.h         |  1 +
>  4 files changed, 41 insertions(+), 20 deletions(-)

Re: [PATCH 4/6] perf tools: Add support to store time of day in CTF data conversion

[Jiri Olsa]

On Mon, Aug 03, 2020 at 01:00:12PM +0900, Namhyung Kim wrote:
> On Thu, Jul 30, 2020 at 11:39:48PM +0200, Jiri Olsa wrote:
> > Adding support to convert and store time of day in CTF
> > data conversion for 'perf data convert' subcommand.
> > 
> > The perf.data used for conversion needs to have clock data
> > information - must be recorded with -k/--clockid option).
> > 
> > New --tod option is added to 'perf data convert' subcommand
> > to convert data with timestamps converted to wall clock time.
> > 
> > Record data with clockid set:
> >   # perf record -k CLOCK_MONOTONIC kill
> >   kill: not enough arguments
> >   [ perf record: Woken up 1 times to write data ]
> >   [ perf record: Captured and wrote 0.033 MB perf.data (8 samples) ]
> > 
> > Convert data with TOD timestamps:
> >   # perf data convert --tod --to-ctf ./ctf
> >   [ perf data convert: Converted 'perf.data' into CTF data './ctf' ]
> >   [ perf data convert: Converted and wrote 0.000 MB (8 samples) ]
> > 
> > Display data in perf script:
> >   # perf script -F+tod --ns
> >             perf 262150 2020-07-13 18:38:50.097678523 153633.958246159:          1 cycles: ...
> >             perf 262150 2020-07-13 18:38:50.097682941 153633.958250577:          1 cycles: ...
> >             perf 262150 2020-07-13 18:38:50.097684997 153633.958252633:          7 cycles: ...
> >   ...
> 
> I believe this belongs to a later patch.

I wanted to show in changelog that the timestamps match
for both script and data convert tools

jirka

> 
> Thanks
> Namhyung
> 
> > 
> > Display data in babeltrace:
> >   # babeltrace --clock-date  ./ctf
> >   [2020-07-13 18:38:50.097678523] (+?.?????????) cycles: { cpu_id = 0 }, { perf_ip = 0xFFF ...
> >   [2020-07-13 18:38:50.097682941] (+0.000004418) cycles: { cpu_id = 0 }, { perf_ip = 0xFFF ...
> >   [2020-07-13 18:38:50.097684997] (+0.000002056) cycles: { cpu_id = 0 }, { perf_ip = 0xFFF ...
> >   ...
> > 
> > It's available only for recording with clockid specified,
> > because it's the only case where we can get reference time
> > to wallclock time. It's can't do that with perf clock yet.
> > 
> > Error is display if you want to use --tod on data without
> > clockid specified:
> > 
> >   # perf data convert --tod --to-ctf ./ctf
> >   Can't provide --tod time, missing clock data. Please record with -k/--clockid option.
> >   Failed to setup CTF writer.
> >   Error during conversion setup.
> > 
> > Signed-off-by: Jiri Olsa <jolsa@kernel.org>
> > ---
> >  tools/perf/Documentation/perf-data.txt |  3 ++
> >  tools/perf/builtin-data.c              |  1 +
> >  tools/perf/util/data-convert-bt.c      | 56 +++++++++++++++++---------
> >  tools/perf/util/data-convert.h         |  1 +
> >  4 files changed, 41 insertions(+), 20 deletions(-)
> 

[PATCH 5/6] perf script: Change enum perf_output_field values to be 64 bits

[Jiri Olsa]

So it's possible to add new values. I did not find any place
where the enum values are passed through some number type,
so it's safe to make this change.

Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/builtin-script.c | 64 ++++++++++++++++++-------------------
 1 file changed, 32 insertions(+), 32 deletions(-)

diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c
index 0dfc38fb6d35..eb45f678dc2f 100644
--- a/tools/perf/builtin-script.c
+++ b/tools/perf/builtin-script.c
@@ -82,38 +82,38 @@ static bool			native_arch;
 unsigned int scripting_max_stack = PERF_MAX_STACK_DEPTH;
 
 enum perf_output_field {
-	PERF_OUTPUT_COMM            = 1U << 0,
-	PERF_OUTPUT_TID             = 1U << 1,
-	PERF_OUTPUT_PID             = 1U << 2,
-	PERF_OUTPUT_TIME            = 1U << 3,
-	PERF_OUTPUT_CPU             = 1U << 4,
-	PERF_OUTPUT_EVNAME          = 1U << 5,
-	PERF_OUTPUT_TRACE           = 1U << 6,
-	PERF_OUTPUT_IP              = 1U << 7,
-	PERF_OUTPUT_SYM             = 1U << 8,
-	PERF_OUTPUT_DSO             = 1U << 9,
-	PERF_OUTPUT_ADDR            = 1U << 10,
-	PERF_OUTPUT_SYMOFFSET       = 1U << 11,
-	PERF_OUTPUT_SRCLINE         = 1U << 12,
-	PERF_OUTPUT_PERIOD          = 1U << 13,
-	PERF_OUTPUT_IREGS	    = 1U << 14,
-	PERF_OUTPUT_BRSTACK	    = 1U << 15,
-	PERF_OUTPUT_BRSTACKSYM	    = 1U << 16,
-	PERF_OUTPUT_DATA_SRC	    = 1U << 17,
-	PERF_OUTPUT_WEIGHT	    = 1U << 18,
-	PERF_OUTPUT_BPF_OUTPUT	    = 1U << 19,
-	PERF_OUTPUT_CALLINDENT	    = 1U << 20,
-	PERF_OUTPUT_INSN	    = 1U << 21,
-	PERF_OUTPUT_INSNLEN	    = 1U << 22,
-	PERF_OUTPUT_BRSTACKINSN	    = 1U << 23,
-	PERF_OUTPUT_BRSTACKOFF	    = 1U << 24,
-	PERF_OUTPUT_SYNTH           = 1U << 25,
-	PERF_OUTPUT_PHYS_ADDR       = 1U << 26,
-	PERF_OUTPUT_UREGS	    = 1U << 27,
-	PERF_OUTPUT_METRIC	    = 1U << 28,
-	PERF_OUTPUT_MISC            = 1U << 29,
-	PERF_OUTPUT_SRCCODE	    = 1U << 30,
-	PERF_OUTPUT_IPC             = 1U << 31,
+	PERF_OUTPUT_COMM            = 1ULL << 0,
+	PERF_OUTPUT_TID             = 1ULL << 1,
+	PERF_OUTPUT_PID             = 1ULL << 2,
+	PERF_OUTPUT_TIME            = 1ULL << 3,
+	PERF_OUTPUT_CPU             = 1ULL << 4,
+	PERF_OUTPUT_EVNAME          = 1ULL << 5,
+	PERF_OUTPUT_TRACE           = 1ULL << 6,
+	PERF_OUTPUT_IP              = 1ULL << 7,
+	PERF_OUTPUT_SYM             = 1ULL << 8,
+	PERF_OUTPUT_DSO             = 1ULL << 9,
+	PERF_OUTPUT_ADDR            = 1ULL << 10,
+	PERF_OUTPUT_SYMOFFSET       = 1ULL << 11,
+	PERF_OUTPUT_SRCLINE         = 1ULL << 12,
+	PERF_OUTPUT_PERIOD          = 1ULL << 13,
+	PERF_OUTPUT_IREGS	    = 1ULL << 14,
+	PERF_OUTPUT_BRSTACK	    = 1ULL << 15,
+	PERF_OUTPUT_BRSTACKSYM	    = 1ULL << 16,
+	PERF_OUTPUT_DATA_SRC	    = 1ULL << 17,
+	PERF_OUTPUT_WEIGHT	    = 1ULL << 18,
+	PERF_OUTPUT_BPF_OUTPUT	    = 1ULL << 19,
+	PERF_OUTPUT_CALLINDENT	    = 1ULL << 20,
+	PERF_OUTPUT_INSN	    = 1ULL << 21,
+	PERF_OUTPUT_INSNLEN	    = 1ULL << 22,
+	PERF_OUTPUT_BRSTACKINSN	    = 1ULL << 23,
+	PERF_OUTPUT_BRSTACKOFF	    = 1ULL << 24,
+	PERF_OUTPUT_SYNTH           = 1ULL << 25,
+	PERF_OUTPUT_PHYS_ADDR       = 1ULL << 26,
+	PERF_OUTPUT_UREGS	    = 1ULL << 27,
+	PERF_OUTPUT_METRIC	    = 1ULL << 28,
+	PERF_OUTPUT_MISC            = 1ULL << 29,
+	PERF_OUTPUT_SRCCODE	    = 1ULL << 30,
+	PERF_OUTPUT_IPC             = 1ULL << 31,
 };
 
 struct output_option {
-- 
2.25.4

[PATCH 6/6] perf script: Add tod field to display time of day

[Jiri Olsa]

Adding tod field to display time of day column with
time of date (wallclock) time.

  # perf record -k CLOCK_MONOTONIC kill
  kill: not enough arguments
  [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 0.033 MB perf.data (8 samples) ]

  # perf script
            perf 261340 152919.481538:          1 cycles:  ffffffff8106d104 ...
            perf 261340 152919.481543:          1 cycles:  ffffffff8106d104 ...
            perf 261340 152919.481545:          7 cycles:  ffffffff8106d104 ...
  ...

  # perf script --ns
            perf 261340 152919.481538922:          1 cycles:  ffffffff8106d ...
            perf 261340 152919.481543286:          1 cycles:  ffffffff8106d ...
            perf 261340 152919.481545397:          7 cycles:  ffffffff8106d ...
  ...

  # perf script -F+tod
            perf 261340 2020-07-13 18:26:55.620971 152919.481538:           ...
            perf 261340 2020-07-13 18:26:55.620975 152919.481543:           ...
            perf 261340 2020-07-13 18:26:55.620978 152919.481545:           ...
  ...

  # perf script -F+tod --ns
            perf 261340 2020-07-13 18:26:55.620971621 152919.481538922:     ...
            perf 261340 2020-07-13 18:26:55.620975985 152919.481543286:     ...
            perf 261340 2020-07-13 18:26:55.620978096 152919.481545397:     ...
  ...

It's available only for recording with clockid specified,
because it's the only case where we can get reference time
to wallclock time. It's can't do that with perf clock yet.

Error is display if you want to use --tod on data without
clockid specified:

  # perf script -F+tod
  Can't provide 'tod' time, missing clock data. Please record with -k/--clockid option.

Original-patch-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/builtin-script.c | 131 +++++++++++++++++++++++++++---------
 1 file changed, 98 insertions(+), 33 deletions(-)

diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c
index eb45f678dc2f..484ce6067d23 100644
--- a/tools/perf/builtin-script.c
+++ b/tools/perf/builtin-script.c
@@ -114,6 +114,32 @@ enum perf_output_field {
 	PERF_OUTPUT_MISC            = 1ULL << 29,
 	PERF_OUTPUT_SRCCODE	    = 1ULL << 30,
 	PERF_OUTPUT_IPC             = 1ULL << 31,
+	PERF_OUTPUT_TOD             = 1ULL << 32,
+};
+
+struct perf_script {
+	struct perf_tool	tool;
+	struct perf_session	*session;
+	bool			show_task_events;
+	bool			show_mmap_events;
+	bool			show_switch_events;
+	bool			show_namespace_events;
+	bool			show_lost_events;
+	bool			show_round_events;
+	bool			show_bpf_events;
+	bool			show_cgroup_events;
+	bool			show_text_poke_events;
+	bool			allocated;
+	bool			per_event_dump;
+	bool			stitch_lbr;
+	struct evswitch		evswitch;
+	struct perf_cpu_map	*cpus;
+	struct perf_thread_map *threads;
+	int			name_width;
+	const char              *time_str;
+	struct perf_time_interval *ptime_range;
+	int			range_size;
+	int			range_num;
 };
 
 struct output_option {
@@ -152,6 +178,7 @@ struct output_option {
 	{.str = "misc", .field = PERF_OUTPUT_MISC},
 	{.str = "srccode", .field = PERF_OUTPUT_SRCCODE},
 	{.str = "ipc", .field = PERF_OUTPUT_IPC},
+	{.str = "tod", .field = PERF_OUTPUT_TOD},
 };
 
 enum {
@@ -502,6 +529,7 @@ static void set_print_ip_opts(struct perf_event_attr *attr)
  */
 static int perf_session__check_output_opt(struct perf_session *session)
 {
+	bool tod = false;
 	unsigned int j;
 	struct evsel *evsel;
 
@@ -528,6 +556,7 @@ static int perf_session__check_output_opt(struct perf_session *session)
 			continue;
 
 		set_print_ip_opts(&evsel->core.attr);
+		tod |= output[j].fields & PERF_OUTPUT_TOD;
 	}
 
 	if (!no_callchain) {
@@ -568,13 +597,17 @@ static int perf_session__check_output_opt(struct perf_session *session)
 		}
 	}
 
+	if (tod && !session->header.env.clock.enabled) {
+		pr_err("Can't provide 'tod' time, missing clock data. "
+		       "Please record with -k/--clockid option.\n");
+		return -1;
+	}
 out:
 	return 0;
 }
 
 static int perf_sample__fprintf_regs(struct regs_dump *regs, uint64_t mask,
-				     FILE *fp
-)
+				     FILE *fp)
 {
 	unsigned i = 0, r;
 	int printed = 0;
@@ -592,6 +625,56 @@ static int perf_sample__fprintf_regs(struct regs_dump *regs, uint64_t mask,
 	return printed;
 }
 
+#define DEFAULT_TOD_FMT "%F %H:%M:%S"
+
+static char*
+tod_scnprintf(struct perf_script *script, char *buf, int buflen,
+	     u64 timestamp)
+{
+	u64 tod_ns, clockid_ns;
+	struct perf_env *env;
+	unsigned long nsec;
+	struct tm ltime;
+	char date[64];
+	time_t sec;
+
+	buf[0] = '\0';
+	if (buflen < 64 || !script)
+		return buf;
+
+	env = &script->session->header.env;
+	if (!env->clock.enabled) {
+		scnprintf(buf, buflen, "disabled");
+		return buf;
+	}
+
+	clockid_ns = env->clock.clockid_ns;
+	tod_ns     = env->clock.tod_ns;
+
+	if (timestamp > clockid_ns)
+		tod_ns += timestamp - clockid_ns;
+	else
+		tod_ns -= clockid_ns - timestamp;
+
+	sec  = (time_t) (tod_ns / NSEC_PER_SEC);
+	nsec = tod_ns - sec * NSEC_PER_SEC;
+
+	if (localtime_r(&sec, &ltime) == NULL) {
+		scnprintf(buf, buflen, "failed");
+	} else {
+		strftime(date, sizeof(date), DEFAULT_TOD_FMT, &ltime);
+
+		if (symbol_conf.nanosecs) {
+			snprintf(buf, buflen, "%s.%09lu", date, nsec);
+		} else {
+			snprintf(buf, buflen, "%s.%06lu",
+				 date, nsec / NSEC_PER_USEC);
+		}
+	}
+
+	return buf;
+}
+
 static int perf_sample__fprintf_iregs(struct perf_sample *sample,
 				      struct perf_event_attr *attr, FILE *fp)
 {
@@ -606,7 +689,8 @@ static int perf_sample__fprintf_uregs(struct perf_sample *sample,
 					 attr->sample_regs_user, fp);
 }
 
-static int perf_sample__fprintf_start(struct perf_sample *sample,
+static int perf_sample__fprintf_start(struct perf_script *script,
+				      struct perf_sample *sample,
 				      struct thread *thread,
 				      struct evsel *evsel,
 				      u32 type, FILE *fp)
@@ -615,6 +699,7 @@ static int perf_sample__fprintf_start(struct perf_sample *sample,
 	unsigned long secs;
 	unsigned long long nsecs;
 	int printed = 0;
+	char tstr[128];
 
 	if (PRINT_FIELD(COMM)) {
 		if (latency_format)
@@ -683,6 +768,11 @@ static int perf_sample__fprintf_start(struct perf_sample *sample,
 		printed += ret;
 	}
 
+	if (PRINT_FIELD(TOD)) {
+		tod_scnprintf(script, tstr, sizeof(tstr), sample->time);
+		printed += fprintf(fp, "%s ", tstr);
+	}
+
 	if (PRINT_FIELD(TIME)) {
 		u64 t = sample->time;
 		if (reltime) {
@@ -1667,31 +1757,6 @@ static int perf_sample__fprintf_synth(struct perf_sample *sample,
 	return 0;
 }
 
-struct perf_script {
-	struct perf_tool	tool;
-	struct perf_session	*session;
-	bool			show_task_events;
-	bool			show_mmap_events;
-	bool			show_switch_events;
-	bool			show_namespace_events;
-	bool			show_lost_events;
-	bool			show_round_events;
-	bool			show_bpf_events;
-	bool			show_cgroup_events;
-	bool			show_text_poke_events;
-	bool			allocated;
-	bool			per_event_dump;
-	bool			stitch_lbr;
-	struct evswitch		evswitch;
-	struct perf_cpu_map	*cpus;
-	struct perf_thread_map *threads;
-	int			name_width;
-	const char              *time_str;
-	struct perf_time_interval *ptime_range;
-	int			range_size;
-	int			range_num;
-};
-
 static int evlist__max_name_len(struct evlist *evlist)
 {
 	struct evsel *evsel;
@@ -1739,7 +1804,7 @@ static void script_print_metric(struct perf_stat_config *config __maybe_unused,
 
 	if (!fmt)
 		return;
-	perf_sample__fprintf_start(mctx->sample, mctx->thread, mctx->evsel,
+	perf_sample__fprintf_start(NULL, mctx->sample, mctx->thread, mctx->evsel,
 				   PERF_RECORD_SAMPLE, mctx->fp);
 	fputs("\tmetric: ", mctx->fp);
 	if (color)
@@ -1754,7 +1819,7 @@ static void script_new_line(struct perf_stat_config *config __maybe_unused,
 {
 	struct metric_ctx *mctx = ctx;
 
-	perf_sample__fprintf_start(mctx->sample, mctx->thread, mctx->evsel,
+	perf_sample__fprintf_start(NULL, mctx->sample, mctx->thread, mctx->evsel,
 				   PERF_RECORD_SAMPLE, mctx->fp);
 	fputs("\tmetric: ", mctx->fp);
 }
@@ -1865,7 +1930,7 @@ static void process_event(struct perf_script *script,
 
 	++es->samples;
 
-	perf_sample__fprintf_start(sample, thread, evsel,
+	perf_sample__fprintf_start(script, sample, thread, evsel,
 				   PERF_RECORD_SAMPLE, fp);
 
 	if (PRINT_FIELD(PERIOD))
@@ -2174,7 +2239,7 @@ static int print_event_with_time(struct perf_tool *tool,
 		thread = machine__findnew_thread(machine, pid, tid);
 
 	if (thread && evsel) {
-		perf_sample__fprintf_start(sample, thread, evsel,
+		perf_sample__fprintf_start(script, sample, thread, evsel,
 					   event->header.type, stdout);
 	}
 
@@ -3439,7 +3504,7 @@ int cmd_script(int argc, const char **argv)
 		     "Fields: comm,tid,pid,time,cpu,event,trace,ip,sym,dso,"
 		     "addr,symoff,srcline,period,iregs,uregs,brstack,"
 		     "brstacksym,flags,bpf-output,brstackinsn,brstackoff,"
-		     "callindent,insn,insnlen,synth,phys_addr,metric,misc,ipc",
+		     "callindent,insn,insnlen,synth,phys_addr,metric,misc,ipc,tod",
 		     parse_output_fields),
 	OPT_BOOLEAN('a', "all-cpus", &system_wide,
 		    "system-wide collection from all CPUs"),
-- 
2.25.4

Re: [PATCH 0/6] perf tools: Add wallclock time conversion support

[peterz]

On Thu, Jul 30, 2020 at 11:39:44PM +0200, Jiri Olsa wrote:

> The patchset is adding the ability to display TOD/wallclock timestamp
> in 'perf script' output and in 'perf data convert --to-ctf' subcommand,
> so the converted CTF data contain TOD/wallclock timestamps.

But why? Wallclock is a horrible piece of crap. Why would you want to do
this?

Re: [PATCH 0/6] perf tools: Add wallclock time conversion support

[David Ahern]

On 7/30/20 4:14 PM, peterz@infradead.org wrote:
> On Thu, Jul 30, 2020 at 11:39:44PM +0200, Jiri Olsa wrote:
> 
>> The patchset is adding the ability to display TOD/wallclock timestamp
>> in 'perf script' output and in 'perf data convert --to-ctf' subcommand,
>> so the converted CTF data contain TOD/wallclock timestamps.
> 
> But why? Wallclock is a horrible piece of crap. Why would you want to do
> this?
> 

Same reason I brought this up 9+ years ago: userspace lives on
time-of-day, and troubleshooting is based on correlating timestamps from
multiple sources. To correlate a perf event to syslog or an application
log, we need time-of-day.

Re: [PATCH 0/6] perf tools: Add wallclock time conversion support

[Jiri Olsa]

On Thu, Jul 30, 2020 at 07:21:54PM -0600, David Ahern wrote:
> On 7/30/20 4:14 PM, peterz@infradead.org wrote:
> > On Thu, Jul 30, 2020 at 11:39:44PM +0200, Jiri Olsa wrote:
> > 
> >> The patchset is adding the ability to display TOD/wallclock timestamp
> >> in 'perf script' output and in 'perf data convert --to-ctf' subcommand,
> >> so the converted CTF data contain TOD/wallclock timestamps.
> > 
> > But why? Wallclock is a horrible piece of crap. Why would you want to do
> > this?
> > 
> 
> Same reason I brought this up 9+ years ago: userspace lives on
> time-of-day, and troubleshooting is based on correlating timestamps from
> multiple sources. To correlate a perf event to syslog or an application
> log, we need time-of-day.

yep, we have a customer that needs to compare data from multiple servers

jirka

Re: [PATCH 0/6] perf tools: Add wallclock time conversion support

[Andi Kleen]

> yep, we have a customer that needs to compare data from multiple servers

It's also needed to correlate over different guests on the same machine.
This is an important use case.

It would be nice if we could find a way to export the per guest 
TSC offset from KVM, then we could use the more reliable TSC for this,
at least as long as no TSC scaling is used.

But failing that wall clock is probably the best you can do.

-Andi

Re: [PATCH 0/6] perf tools: Add wallclock time conversion support

[peterz]

On Fri, Jul 31, 2020 at 08:36:12AM -0700, Andi Kleen wrote:
> > yep, we have a customer that needs to compare data from multiple servers
> 
> It's also needed to correlate over different guests on the same machine.
> This is an important use case.

Both these cases you want to sync up CLOCK_MONOTONIC, using walltime is
just utterly misguided.

What happens if the servers have (per accident or otherwise) different
DST settings, or someone does a clock_setttime() for giggles.

All you really want is a clock that runs at the same rate but is not
subject to random jumps and user foibles.

Re: [PATCH 0/6] perf tools: Add wallclock time conversion support

[David Ahern]

On 7/31/20 12:05 PM, peterz@infradead.org wrote:
> On Fri, Jul 31, 2020 at 08:36:12AM -0700, Andi Kleen wrote:
>>> yep, we have a customer that needs to compare data from multiple servers
>>
>> It's also needed to correlate over different guests on the same machine.
>> This is an important use case.
> 
> Both these cases you want to sync up CLOCK_MONOTONIC, using walltime is
> just utterly misguided.

Every userspace component logs in walltime. You can say that is
misguided, but that is the way it is. The missing piece is the ability
to correlate kernel events to userspace logs.

> 
> What happens if the servers have (per accident or otherwise) different
> DST settings, or someone does a clock_setttime() for giggles.

Yes, someone *could* change the time. Someone *could* start ntpd or
other time server in the middle of a session. While technically such
things can happen, that is not real life in most environments (e.g.,
Data center servers). ntpd (or other) is started at boot, and it is just
the little misc adjustments that happen over time.

We could add tracepoints and detect the changes and invalidate the
reference time. We could add tracepoints to track the adjustments and
update the reference time. In my experience over 9+ years using this
tool (out of tree patches) that has never been the problem.

> 
> All you really want is a clock that runs at the same rate but is not
> subject to random jumps and user foibles.
> 

All I want is to compare user logs to a kernel event via timestamps.

Re: [PATCH 0/6] perf tools: Add wallclock time conversion support

[Arnaldo Carvalho de Melo]

Em Fri, Jul 31, 2020 at 06:46:21PM -0600, David Ahern escreveu:
> On 7/31/20 12:05 PM, peterz@infradead.org wrote:
> > On Fri, Jul 31, 2020 at 08:36:12AM -0700, Andi Kleen wrote:
> >>> yep, we have a customer that needs to compare data from multiple servers

> >> It's also needed to correlate over different guests on the same machine.
> >> This is an important use case.

> > Both these cases you want to sync up CLOCK_MONOTONIC, using walltime is
> > just utterly misguided.

> Every userspace component logs in walltime. You can say that is
> misguided, but that is the way it is. The missing piece is the ability
> to correlate kernel events to userspace logs.

> > What happens if the servers have (per accident or otherwise) different
> > DST settings, or someone does a clock_setttime() for giggles.
 
> Yes, someone *could* change the time. Someone *could* start ntpd or
> other time server in the middle of a session. While technically such
> things can happen, that is not real life in most environments (e.g.,
> Data center servers). ntpd (or other) is started at boot, and it is just
> the little misc adjustments that happen over time.
 
> We could add tracepoints and detect the changes and invalidate the
> reference time. We could add tracepoints to track the adjustments and
> update the reference time. In my experience over 9+ years using this
> tool (out of tree patches) that has never been the problem.
 
> > All you really want is a clock that runs at the same rate but is not
> > subject to random jumps and user foibles.

> All I want is to compare user logs to a kernel event via timestamps.

Can we have both possibilities and leave the decision on which one to
use in the hands of those who have a gun to shoot wherever they want,
maybe in the foot?

- Arnaldo

Re: [PATCH 0/6] perf tools: Add wallclock time conversion support

[peterz]

On Thu, Jul 30, 2020 at 07:21:54PM -0600, David Ahern wrote:
> On 7/30/20 4:14 PM, peterz@infradead.org wrote:
> > On Thu, Jul 30, 2020 at 11:39:44PM +0200, Jiri Olsa wrote:
> > 
> >> The patchset is adding the ability to display TOD/wallclock timestamp
> >> in 'perf script' output and in 'perf data convert --to-ctf' subcommand,
> >> so the converted CTF data contain TOD/wallclock timestamps.
> > 
> > But why? Wallclock is a horrible piece of crap. Why would you want to do
> > this?
> > 
> 
> Same reason I brought this up 9+ years ago: userspace lives on
> time-of-day, and troubleshooting is based on correlating timestamps from
> multiple sources. To correlate a perf event to syslog or an application
> log, we need time-of-day.

You need a sync'ed CLOCK_MONOTONIC for that, CLOCK_REALTIME 'aka'
wallclock is a trainwreck, you don't ever want that.