[PATCH v3 0/7] perf cs_etm: Basic support for virtual/kernel timestamps

[PATCH v3 0/7] perf cs_etm: Basic support for virtual/kernel timestamps

[James Clark]

Changes since v2:

  * Remove const to non-const change and copy strings where needed
    instead.
  * Use sizeof() instead of PATH_MAX
  * Append "will not be set accurately." to new error message
  * Remove unneeded stat() call
  * Rebase on perf/core
  
==========================

Changes since v1:

  * Add 3 refactor commits for sysfs reading around pmu.c as suggested
    by Arnaldo here [1]
  * The dependency on [2] has now reached mainline so is no longer
    blocking
  * Rebase on perf/core
  
[1]: https://lore.kernel.org/all/YnqVqq5QW%2Fb14oPZ@kernel.org/
[2]: https://lore.kernel.org/all/20220503123537.1003035-1-german.gomez@arm.com/

German Gomez (4):
  perf pmu: Add function to check if a pmu file exists
  perf cs_etm: Keep separate symbols for ETMv4 and ETE parameters
  perf cs_etm: Record ts_source in AUXTRACE_INFO for ETMv4 and ETE
  perf cs_etm: Set the time field in the synthetic samples

James Clark (3):
  perf: Remove duplication around EVENT_SOURCE_DEVICE_PATH
  perf: Use perf_pmu__open_file() and perf_pmu__scan_file()
  perf: Remove remaining duplication of bus/event_source/devices/...

 tools/perf/arch/arm/util/auxtrace.c |   5 +-
 tools/perf/arch/arm/util/cs-etm.c   |  91 ++++++++++++--
 tools/perf/arch/x86/util/pmu.c      |  12 +-
 tools/perf/util/cputopo.c           |   9 +-
 tools/perf/util/cs-etm-base.c       |  34 ++++--
 tools/perf/util/cs-etm.c            |  86 ++++++++++++--
 tools/perf/util/cs-etm.h            |  13 +-
 tools/perf/util/pmu-hybrid.c        |  27 +----
 tools/perf/util/pmu.c               | 177 +++++++++++-----------------
 tools/perf/util/pmu.h               |  10 +-
 10 files changed, 284 insertions(+), 180 deletions(-)


base-commit: 09e6f9f98370be9a9f8978139e0eb1be87d1125f
-- 
2.25.1

[PATCH v3 1/7] perf: Remove duplication around EVENT_SOURCE_DEVICE_PATH

[James Clark]

The pattern for accessing EVENT_SOURCE_DEVICE_PATH is duplicated in a
few places, so add two utility functions to cover it. Also just use
perf_pmu__scan_file() instead of pmu_type() which already does the same
thing.

No functional changes.

Reviewed-by: Leo Yan <leo.yan@linaro.org>
Signed-off-by: James Clark <james.clark@arm.com>
---
 tools/perf/arch/arm/util/auxtrace.c |   5 +-
 tools/perf/arch/x86/util/pmu.c      |  12 +--
 tools/perf/util/pmu.c               | 110 +++++++++++-----------------
 tools/perf/util/pmu.h               |   5 +-
 4 files changed, 49 insertions(+), 83 deletions(-)

diff --git a/tools/perf/arch/arm/util/auxtrace.c b/tools/perf/arch/arm/util/auxtrace.c
index deeb163999ce..adec6c9ee11d 100644
--- a/tools/perf/arch/arm/util/auxtrace.c
+++ b/tools/perf/arch/arm/util/auxtrace.c
@@ -55,17 +55,16 @@ static struct perf_pmu **find_all_arm_spe_pmus(int *nr_spes, int *err)
 
 static struct perf_pmu **find_all_hisi_ptt_pmus(int *nr_ptts, int *err)
 {
-	const char *sysfs = sysfs__mountpoint();
 	struct perf_pmu **hisi_ptt_pmus = NULL;
 	struct dirent *dent;
 	char path[PATH_MAX];
 	DIR *dir = NULL;
 	int idx = 0;
 
-	snprintf(path, PATH_MAX, "%s" EVENT_SOURCE_DEVICE_PATH, sysfs);
+	perf_pmu__event_source_devices_scnprintf(path, sizeof(path));
 	dir = opendir(path);
 	if (!dir) {
-		pr_err("can't read directory '%s'\n", EVENT_SOURCE_DEVICE_PATH);
+		pr_err("can't read directory '%s'\n", path);
 		*err = -EINVAL;
 		return NULL;
 	}
diff --git a/tools/perf/arch/x86/util/pmu.c b/tools/perf/arch/x86/util/pmu.c
index 74d69db1ea99..358340b34243 100644
--- a/tools/perf/arch/x86/util/pmu.c
+++ b/tools/perf/arch/x86/util/pmu.c
@@ -15,8 +15,6 @@
 #include "../../../util/pmu.h"
 #include "../../../util/fncache.h"
 
-#define TEMPLATE_ALIAS	"%s/bus/event_source/devices/%s/alias"
-
 struct pmu_alias {
 	char *name;
 	char *alias;
@@ -72,18 +70,14 @@ static int setup_pmu_alias_list(void)
 	char path[PATH_MAX];
 	DIR *dir;
 	struct dirent *dent;
-	const char *sysfs = sysfs__mountpoint();
 	struct pmu_alias *pmu_alias;
 	char buf[MAX_PMU_NAME_LEN];
 	FILE *file;
 	int ret = -ENOMEM;
 
-	if (!sysfs)
+	if (!perf_pmu__event_source_devices_scnprintf(path, sizeof(path)))
 		return -1;
 
-	snprintf(path, PATH_MAX,
-		 "%s" EVENT_SOURCE_DEVICE_PATH, sysfs);
-
 	dir = opendir(path);
 	if (!dir)
 		return -errno;
@@ -93,9 +87,7 @@ static int setup_pmu_alias_list(void)
 		    !strcmp(dent->d_name, ".."))
 			continue;
 
-		snprintf(path, PATH_MAX,
-			 TEMPLATE_ALIAS, sysfs, dent->d_name);
-
+		perf_pmu__pathname_scnprintf(path, sizeof(path), dent->d_name, "alias");
 		if (!file_available(path))
 			continue;
 
diff --git a/tools/perf/util/pmu.c b/tools/perf/util/pmu.c
index 2bdeb89352e7..0d9619dde3a8 100644
--- a/tools/perf/util/pmu.c
+++ b/tools/perf/util/pmu.c
@@ -107,14 +107,10 @@ int perf_pmu__format_parse(char *dir, struct list_head *head)
 static int pmu_format(const char *name, struct list_head *format)
 {
 	char path[PATH_MAX];
-	const char *sysfs = sysfs__mountpoint();
 
-	if (!sysfs)
+	if (!perf_pmu__pathname_scnprintf(path, sizeof(path), name, "format"))
 		return -1;
 
-	snprintf(path, PATH_MAX,
-		 "%s" EVENT_SOURCE_DEVICE_PATH "%s/format", sysfs, name);
-
 	if (!file_available(path))
 		return 0;
 
@@ -513,14 +509,10 @@ static int pmu_aliases_parse(char *dir, struct list_head *head)
 static int pmu_aliases(const char *name, struct list_head *head)
 {
 	char path[PATH_MAX];
-	const char *sysfs = sysfs__mountpoint();
 
-	if (!sysfs)
+	if (!perf_pmu__pathname_scnprintf(path, sizeof(path), name, "events"))
 		return -1;
 
-	snprintf(path, PATH_MAX,
-		 "%s/bus/event_source/devices/%s/events", sysfs, name);
-
 	if (!file_available(path))
 		return 0;
 
@@ -554,52 +546,16 @@ static int pmu_alias_terms(struct perf_pmu_alias *alias,
 	return 0;
 }
 
-/*
- * Reading/parsing the default pmu type value, which should be
- * located at:
- * /sys/bus/event_source/devices/<dev>/type as sysfs attribute.
- */
-static int pmu_type(const char *name, __u32 *type)
-{
-	char path[PATH_MAX];
-	FILE *file;
-	int ret = 0;
-	const char *sysfs = sysfs__mountpoint();
-
-	if (!sysfs)
-		return -1;
-
-	snprintf(path, PATH_MAX,
-		 "%s" EVENT_SOURCE_DEVICE_PATH "%s/type", sysfs, name);
-
-	if (access(path, R_OK) < 0)
-		return -1;
-
-	file = fopen(path, "r");
-	if (!file)
-		return -EINVAL;
-
-	if (1 != fscanf(file, "%u", type))
-		ret = -1;
-
-	fclose(file);
-	return ret;
-}
-
 /* Add all pmus in sysfs to pmu list: */
 static void pmu_read_sysfs(void)
 {
 	char path[PATH_MAX];
 	DIR *dir;
 	struct dirent *dent;
-	const char *sysfs = sysfs__mountpoint();
 
-	if (!sysfs)
+	if (!perf_pmu__event_source_devices_scnprintf(path, sizeof(path)))
 		return;
 
-	snprintf(path, PATH_MAX,
-		 "%s" EVENT_SOURCE_DEVICE_PATH, sysfs);
-
 	dir = opendir(path);
 	if (!dir)
 		return;
@@ -696,14 +652,9 @@ static char *pmu_id(const char *name)
 static int is_arm_pmu_core(const char *name)
 {
 	char path[PATH_MAX];
-	const char *sysfs = sysfs__mountpoint();
 
-	if (!sysfs)
+	if (!perf_pmu__pathname_scnprintf(path, sizeof(path), name, "cpus"))
 		return 0;
-
-	/* Look for cpu sysfs (specific to arm) */
-	scnprintf(path, PATH_MAX, "%s/bus/event_source/devices/%s/cpus",
-				sysfs, name);
 	return file_available(path);
 }
 
@@ -969,11 +920,8 @@ static struct perf_pmu *pmu_lookup(const char *lookup_name)
 		return NULL;
 
 	/*
-	 * Check the type first to avoid unnecessary work.
+	 * Check the aliases first to avoid unnecessary work.
 	 */
-	if (pmu_type(name, &type))
-		return NULL;
-
 	if (pmu_aliases(name, &aliases))
 		return NULL;
 
@@ -983,9 +931,14 @@ static struct perf_pmu *pmu_lookup(const char *lookup_name)
 
 	pmu->cpus = pmu_cpumask(name);
 	pmu->name = strdup(name);
+
 	if (!pmu->name)
 		goto err;
 
+	/* Read type, and ensure that type value is successfully assigned (return 1) */
+	if (perf_pmu__scan_file(pmu, "type", "%u", &type) != 1)
+		goto err;
+
 	alias_name = pmu_find_alias_name(name);
 	if (alias_name) {
 		pmu->alias_name = strdup(alias_name);
@@ -1786,16 +1739,11 @@ bool pmu_have_event(const char *pname, const char *name)
 static FILE *perf_pmu__open_file(struct perf_pmu *pmu, const char *name)
 {
 	char path[PATH_MAX];
-	const char *sysfs;
 
-	sysfs = sysfs__mountpoint();
-	if (!sysfs)
+	if (!perf_pmu__pathname_scnprintf(path, sizeof(path), pmu->name, name) ||
+	    !file_available(path))
 		return NULL;
 
-	snprintf(path, PATH_MAX,
-		 "%s" EVENT_SOURCE_DEVICE_PATH "%s/%s", sysfs, pmu->name, name);
-	if (!file_available(path))
-		return NULL;
 	return fopen(path, "r");
 }
 
@@ -1849,7 +1797,6 @@ int perf_pmu__caps_parse(struct perf_pmu *pmu)
 {
 	struct stat st;
 	char caps_path[PATH_MAX];
-	const char *sysfs = sysfs__mountpoint();
 	DIR *caps_dir;
 	struct dirent *evt_ent;
 
@@ -1858,12 +1805,9 @@ int perf_pmu__caps_parse(struct perf_pmu *pmu)
 
 	pmu->nr_caps = 0;
 
-	if (!sysfs)
+	if (!perf_pmu__pathname_scnprintf(caps_path, sizeof(caps_path), pmu->name, "caps"))
 		return -1;
 
-	snprintf(caps_path, PATH_MAX,
-		 "%s" EVENT_SOURCE_DEVICE_PATH "%s/caps", sysfs, pmu->name);
-
 	if (stat(caps_path, &st) < 0) {
 		pmu->caps_initialized = true;
 		return 0;	/* no error if caps does not exist */
@@ -1993,3 +1937,31 @@ int perf_pmu__cpus_match(struct perf_pmu *pmu, struct perf_cpu_map *cpus,
 	*ucpus_ptr = unmatched_cpus;
 	return 0;
 }
+
+int perf_pmu__event_source_devices_scnprintf(char *pathname, size_t size)
+{
+	const char *sysfs = sysfs__mountpoint();
+
+	if (!sysfs)
+		return 0;
+	return scnprintf(pathname, size, "%s/bus/event_source/devices/", sysfs);
+}
+
+/*
+ * Fill 'buf' with the path to a file or folder in 'pmu_name' in
+ * sysfs. For example if pmu_name = "cs_etm" and 'filename' = "format"
+ * then pathname will be filled with
+ * "/sys/bus/event_source/devices/cs_etm/format"
+ *
+ * Return 0 if the sysfs mountpoint couldn't be found or if no
+ * characters were written.
+ */
+int perf_pmu__pathname_scnprintf(char *buf, size_t size,
+				 const char *pmu_name, const char *filename)
+{
+	char base_path[PATH_MAX];
+
+	if (!perf_pmu__event_source_devices_scnprintf(base_path, sizeof(base_path)))
+		return 0;
+	return scnprintf(buf, size, "%s%s/%s", base_path, pmu_name, filename);
+}
diff --git a/tools/perf/util/pmu.h b/tools/perf/util/pmu.h
index 69ca0004f94f..2f2bb0286e2a 100644
--- a/tools/perf/util/pmu.h
+++ b/tools/perf/util/pmu.h
@@ -22,7 +22,6 @@ enum {
 };
 
 #define PERF_PMU_FORMAT_BITS 64
-#define EVENT_SOURCE_DEVICE_PATH "/bus/event_source/devices/"
 #define CPUS_TEMPLATE_CPU	"%s/bus/event_source/devices/%s/cpus"
 #define MAX_PMU_NAME_LEN 128
 
@@ -259,4 +258,8 @@ int perf_pmu__cpus_match(struct perf_pmu *pmu, struct perf_cpu_map *cpus,
 
 char *pmu_find_real_name(const char *name);
 char *pmu_find_alias_name(const char *name);
+int perf_pmu__event_source_devices_scnprintf(char *pathname, size_t size);
+int perf_pmu__pathname_scnprintf(char *buf, size_t size,
+				 const char *pmu_name, const char *filename);
+
 #endif /* __PMU_H */
-- 
2.25.1

[PATCH v3 2/7] perf: Use perf_pmu__open_file() and perf_pmu__scan_file()

[James Clark]

Remove some code that duplicates existing methods. This requires that
some consts are removed because one of the existing helper methods takes
a struct perf_pmu instead of a name which has a non const name field.
But except for the tests, the strings were already non const.

No functional changes.

Signed-off-by: James Clark <james.clark@arm.com>
---
 tools/perf/util/cputopo.c    |  9 +-------
 tools/perf/util/pmu-hybrid.c | 27 +++++-------------------
 tools/perf/util/pmu.c        | 40 +++++++++++-------------------------
 tools/perf/util/pmu.h        |  3 ++-
 4 files changed, 20 insertions(+), 59 deletions(-)

diff --git a/tools/perf/util/cputopo.c b/tools/perf/util/cputopo.c
index 1a3ff6449158..e08797c3cdbc 100644
--- a/tools/perf/util/cputopo.c
+++ b/tools/perf/util/cputopo.c
@@ -422,8 +422,6 @@ void numa_topology__delete(struct numa_topology *tp)
 static int load_hybrid_node(struct hybrid_topology_node *node,
 			    struct perf_pmu *pmu)
 {
-	const char *sysfs;
-	char path[PATH_MAX];
 	char *buf = NULL, *p;
 	FILE *fp;
 	size_t len = 0;
@@ -432,12 +430,7 @@ static int load_hybrid_node(struct hybrid_topology_node *node,
 	if (!node->pmu_name)
 		return -1;
 
-	sysfs = sysfs__mountpoint();
-	if (!sysfs)
-		goto err;
-
-	snprintf(path, PATH_MAX, CPUS_TEMPLATE_CPU, sysfs, pmu->name);
-	fp = fopen(path, "r");
+	fp = perf_pmu__open_file(pmu, "cpus");
 	if (!fp)
 		goto err;
 
diff --git a/tools/perf/util/pmu-hybrid.c b/tools/perf/util/pmu-hybrid.c
index f51ccaac60ee..38628805a952 100644
--- a/tools/perf/util/pmu-hybrid.c
+++ b/tools/perf/util/pmu-hybrid.c
@@ -20,32 +20,15 @@ LIST_HEAD(perf_pmu__hybrid_pmus);
 
 bool perf_pmu__hybrid_mounted(const char *name)
 {
-	char path[PATH_MAX];
-	const char *sysfs;
-	FILE *file;
-	int n, cpu;
+	int cpu;
+	char pmu_name[PATH_MAX];
+	struct perf_pmu pmu = {.name = pmu_name};
 
 	if (strncmp(name, "cpu_", 4))
 		return false;
 
-	sysfs = sysfs__mountpoint();
-	if (!sysfs)
-		return false;
-
-	snprintf(path, PATH_MAX, CPUS_TEMPLATE_CPU, sysfs, name);
-	if (!file_available(path))
-		return false;
-
-	file = fopen(path, "r");
-	if (!file)
-		return false;
-
-	n = fscanf(file, "%u", &cpu);
-	fclose(file);
-	if (n <= 0)
-		return false;
-
-	return true;
+	strlcpy(pmu_name, name, sizeof(pmu_name));
+	return perf_pmu__scan_file(&pmu, "cpus", "%u", &cpu) > 0;
 }
 
 struct perf_pmu *perf_pmu__find_hybrid_pmu(const char *name)
diff --git a/tools/perf/util/pmu.c b/tools/perf/util/pmu.c
index 0d9619dde3a8..683cc7953f11 100644
--- a/tools/perf/util/pmu.c
+++ b/tools/perf/util/pmu.c
@@ -570,45 +570,31 @@ static void pmu_read_sysfs(void)
 	closedir(dir);
 }
 
-static struct perf_cpu_map *__pmu_cpumask(const char *path)
-{
-	FILE *file;
-	struct perf_cpu_map *cpus;
-
-	file = fopen(path, "r");
-	if (!file)
-		return NULL;
-
-	cpus = perf_cpu_map__read(file);
-	fclose(file);
-	return cpus;
-}
-
 /*
  * Uncore PMUs have a "cpumask" file under sysfs. CPU PMUs (e.g. on arm/arm64)
  * may have a "cpus" file.
  */
 #define SYS_TEMPLATE_ID	"./bus/event_source/devices/%s/identifier"
-#define CPUS_TEMPLATE_UNCORE	"%s/bus/event_source/devices/%s/cpumask"
 
 static struct perf_cpu_map *pmu_cpumask(const char *name)
 {
-	char path[PATH_MAX];
 	struct perf_cpu_map *cpus;
-	const char *sysfs = sysfs__mountpoint();
 	const char *templates[] = {
-		CPUS_TEMPLATE_UNCORE,
-		CPUS_TEMPLATE_CPU,
+		"cpumask",
+		"cpus",
 		NULL
 	};
 	const char **template;
+	char pmu_name[PATH_MAX];
+	struct perf_pmu pmu = {.name = pmu_name};
+	FILE *file;
 
-	if (!sysfs)
-		return NULL;
-
+	strlcpy(pmu_name, name, sizeof(pmu_name));
 	for (template = templates; *template; template++) {
-		snprintf(path, PATH_MAX, *template, sysfs, name);
-		cpus = __pmu_cpumask(path);
+		file = perf_pmu__open_file(&pmu, *template);
+		if (!file)
+			continue;
+		cpus = perf_cpu_map__read(file);
 		if (cpus)
 			return cpus;
 	}
@@ -619,13 +605,11 @@ static struct perf_cpu_map *pmu_cpumask(const char *name)
 static bool pmu_is_uncore(const char *name)
 {
 	char path[PATH_MAX];
-	const char *sysfs;
 
 	if (perf_pmu__hybrid_mounted(name))
 		return false;
 
-	sysfs = sysfs__mountpoint();
-	snprintf(path, PATH_MAX, CPUS_TEMPLATE_UNCORE, sysfs, name);
+	perf_pmu__pathname_scnprintf(path, sizeof(path), name, "cpumask");
 	return file_available(path);
 }
 
@@ -1736,7 +1720,7 @@ bool pmu_have_event(const char *pname, const char *name)
 	return false;
 }
 
-static FILE *perf_pmu__open_file(struct perf_pmu *pmu, const char *name)
+FILE *perf_pmu__open_file(struct perf_pmu *pmu, const char *name)
 {
 	char path[PATH_MAX];
 
diff --git a/tools/perf/util/pmu.h b/tools/perf/util/pmu.h
index 2f2bb0286e2a..8f39e2d17fb1 100644
--- a/tools/perf/util/pmu.h
+++ b/tools/perf/util/pmu.h
@@ -2,6 +2,7 @@
 #ifndef __PMU_H
 #define __PMU_H
 
+#include <bits/types/FILE.h>
 #include <linux/bitmap.h>
 #include <linux/compiler.h>
 #include <linux/perf_event.h>
@@ -22,7 +23,6 @@ enum {
 };
 
 #define PERF_PMU_FORMAT_BITS 64
-#define CPUS_TEMPLATE_CPU	"%s/bus/event_source/devices/%s/cpus"
 #define MAX_PMU_NAME_LEN 128
 
 struct perf_event_attr;
@@ -261,5 +261,6 @@ char *pmu_find_alias_name(const char *name);
 int perf_pmu__event_source_devices_scnprintf(char *pathname, size_t size);
 int perf_pmu__pathname_scnprintf(char *buf, size_t size,
 				 const char *pmu_name, const char *filename);
+FILE *perf_pmu__open_file(struct perf_pmu *pmu, const char *name);
 
 #endif /* __PMU_H */
-- 
2.25.1

Re: [PATCH v3 2/7] perf: Use perf_pmu__open_file() and perf_pmu__scan_file()

[Leo Yan]

On Tue, Jan 03, 2023 at 04:20:36PM +0000, James Clark wrote:
> Remove some code that duplicates existing methods. This requires that
> some consts are removed because one of the existing helper methods takes
> a struct perf_pmu instead of a name which has a non const name field.
> But except for the tests, the strings were already non const.
> 
> No functional changes.

[...]

> diff --git a/tools/perf/util/pmu.h b/tools/perf/util/pmu.h
> index 2f2bb0286e2a..8f39e2d17fb1 100644
> --- a/tools/perf/util/pmu.h
> +++ b/tools/perf/util/pmu.h
> @@ -2,6 +2,7 @@
>  #ifndef __PMU_H
>  #define __PMU_H
>  
> +#include <bits/types/FILE.h>

Nitpick: it's good to use <stdio.h> to replace <bits/types/FILE.h>.

Either way, this patch looks good to me:

Reviewed-by: Leo Yan <leo.yan@linaro.org>

Re: [PATCH v3 2/7] perf: Use perf_pmu__open_file() and perf_pmu__scan_file()

[James Clark]

On 11/01/2023 07:09, Leo Yan wrote:
> On Tue, Jan 03, 2023 at 04:20:36PM +0000, James Clark wrote:
>> Remove some code that duplicates existing methods. This requires that
>> some consts are removed because one of the existing helper methods takes
>> a struct perf_pmu instead of a name which has a non const name field.
>> But except for the tests, the strings were already non const.
>>
>> No functional changes.
> 
> [...]
> 
>> diff --git a/tools/perf/util/pmu.h b/tools/perf/util/pmu.h
>> index 2f2bb0286e2a..8f39e2d17fb1 100644
>> --- a/tools/perf/util/pmu.h
>> +++ b/tools/perf/util/pmu.h
>> @@ -2,6 +2,7 @@
>>  #ifndef __PMU_H
>>  #define __PMU_H
>>  
>> +#include <bits/types/FILE.h>
> 
> Nitpick: it's good to use <stdio.h> to replace <bits/types/FILE.h>.
> 
> Either way, this patch looks good to me:

Looks like I also forgot to update the commit message about removing the
consts after the last change. Will update both in the next change.

Thanks for the review!

> 
> Reviewed-by: Leo Yan <leo.yan@linaro.org>

[PATCH v3 3/7] perf: Remove remaining duplication of bus/event_source/devices/...

[James Clark]

Use the new perf_pmu__pathname_scnprintf() instead. No functional
changes.

Reviewed-by: Leo Yan <leo.yan@linaro.org>
Signed-off-by: James Clark <james.clark@arm.com>
---
 tools/perf/util/pmu.c | 17 +++++------------
 1 file changed, 5 insertions(+), 12 deletions(-)

diff --git a/tools/perf/util/pmu.c b/tools/perf/util/pmu.c
index 683cc7953f11..7a4e243a370d 100644
--- a/tools/perf/util/pmu.c
+++ b/tools/perf/util/pmu.c
@@ -574,8 +574,6 @@ static void pmu_read_sysfs(void)
  * Uncore PMUs have a "cpumask" file under sysfs. CPU PMUs (e.g. on arm/arm64)
  * may have a "cpus" file.
  */
-#define SYS_TEMPLATE_ID	"./bus/event_source/devices/%s/identifier"
-
 static struct perf_cpu_map *pmu_cpumask(const char *name)
 {
 	struct perf_cpu_map *cpus;
@@ -618,9 +616,9 @@ static char *pmu_id(const char *name)
 	char path[PATH_MAX], *str;
 	size_t len;
 
-	snprintf(path, PATH_MAX, SYS_TEMPLATE_ID, name);
+	perf_pmu__pathname_scnprintf(path, sizeof(path), name, "identifier");
 
-	if (sysfs__read_str(path, &str, &len) < 0)
+	if (filename__read_str(path, &str, &len) < 0)
 		return NULL;
 
 	str[len - 1] = 0; /* remove line feed */
@@ -866,16 +864,11 @@ pmu_find_alias_name(const char *name __maybe_unused)
 	return NULL;
 }
 
-static int pmu_max_precise(const char *name)
+static int pmu_max_precise(struct perf_pmu *pmu)
 {
-	char path[PATH_MAX];
 	int max_precise = -1;
 
-	scnprintf(path, PATH_MAX,
-		 "bus/event_source/devices/%s/caps/max_precise",
-		 name);
-
-	sysfs__read_int(path, &max_precise);
+	perf_pmu__scan_file(pmu, "caps/max_precise", "%d", &max_precise);
 	return max_precise;
 }
 
@@ -934,7 +927,7 @@ static struct perf_pmu *pmu_lookup(const char *lookup_name)
 	pmu->is_uncore = pmu_is_uncore(name);
 	if (pmu->is_uncore)
 		pmu->id = pmu_id(name);
-	pmu->max_precise = pmu_max_precise(name);
+	pmu->max_precise = pmu_max_precise(pmu);
 	pmu_add_cpu_aliases(&aliases, pmu);
 	pmu_add_sys_aliases(&aliases, pmu);
 
-- 
2.25.1

[PATCH v3 4/7] perf pmu: Add function to check if a pmu file exists

[James Clark]

From: German Gomez <german.gomez@arm.com>

Add a utility function perf_pmu__file_exists() to check if a given pmu
file exists in the sysfs filesystem.

Signed-off-by: German Gomez <german.gomez@arm.com>
Signed-off-by: James Clark <james.clark@arm.com>
---
 tools/perf/util/pmu.c | 10 ++++++++++
 tools/perf/util/pmu.h |  2 ++
 2 files changed, 12 insertions(+)

diff --git a/tools/perf/util/pmu.c b/tools/perf/util/pmu.c
index 7a4e243a370d..3529556d57dc 100644
--- a/tools/perf/util/pmu.c
+++ b/tools/perf/util/pmu.c
@@ -1741,6 +1741,16 @@ int perf_pmu__scan_file(struct perf_pmu *pmu, const char *name, const char *fmt,
 	return ret;
 }
 
+bool perf_pmu__file_exists(struct perf_pmu *pmu, const char *name)
+{
+	char path[PATH_MAX];
+
+	if (!perf_pmu__pathname_scnprintf(path, sizeof(path), pmu->name, name))
+		return false;
+
+	return file_available(path);
+}
+
 static int perf_pmu__new_caps(struct list_head *list, char *name, char *value)
 {
 	struct perf_pmu_caps *caps = zalloc(sizeof(*caps));
diff --git a/tools/perf/util/pmu.h b/tools/perf/util/pmu.h
index 8f39e2d17fb1..c1d138fe9602 100644
--- a/tools/perf/util/pmu.h
+++ b/tools/perf/util/pmu.h
@@ -230,6 +230,8 @@ bool pmu_have_event(const char *pname, const char *name);
 
 int perf_pmu__scan_file(struct perf_pmu *pmu, const char *name, const char *fmt, ...) __scanf(3, 4);
 
+bool perf_pmu__file_exists(struct perf_pmu *pmu, const char *name);
+
 int perf_pmu__test(void);
 
 struct perf_event_attr *perf_pmu__get_default_config(struct perf_pmu *pmu);
-- 
2.25.1

[PATCH v3 5/7] perf cs_etm: Keep separate symbols for ETMv4 and ETE parameters

[James Clark]

From: German Gomez <german.gomez@arm.com>

Previously, adding a new parameter at the end of ETMv4 meant adding it
somewhere in the middle of ETE, which is not supported by the current
header version.

Reviewed-by: Mike Leach <mike.leach@linaro.org>
Signed-off-by: German Gomez <german.gomez@arm.com>
Signed-off-by: James Clark <james.clark@arm.com>
---
 tools/perf/arch/arm/util/cs-etm.c | 43 ++++++++++++++++++++++++++-----
 tools/perf/util/cs-etm-base.c     | 32 +++++++++++++++++------
 tools/perf/util/cs-etm.c          | 12 ++++-----
 tools/perf/util/cs-etm.h          | 11 +++++++-
 4 files changed, 76 insertions(+), 22 deletions(-)

diff --git a/tools/perf/arch/arm/util/cs-etm.c b/tools/perf/arch/arm/util/cs-etm.c
index a346d5f3dafa..b526ffe550a5 100644
--- a/tools/perf/arch/arm/util/cs-etm.c
+++ b/tools/perf/arch/arm/util/cs-etm.c
@@ -53,7 +53,15 @@ static const char * const metadata_etmv4_ro[] = {
 	[CS_ETMV4_TRCIDR2]		= "trcidr/trcidr2",
 	[CS_ETMV4_TRCIDR8]		= "trcidr/trcidr8",
 	[CS_ETMV4_TRCAUTHSTATUS]	= "mgmt/trcauthstatus",
-	[CS_ETE_TRCDEVARCH]		= "mgmt/trcdevarch"
+};
+
+static const char * const metadata_ete_ro[] = {
+	[CS_ETE_TRCIDR0]		= "trcidr/trcidr0",
+	[CS_ETE_TRCIDR1]		= "trcidr/trcidr1",
+	[CS_ETE_TRCIDR2]		= "trcidr/trcidr2",
+	[CS_ETE_TRCIDR8]		= "trcidr/trcidr8",
+	[CS_ETE_TRCAUTHSTATUS]		= "mgmt/trcauthstatus",
+	[CS_ETE_TRCDEVARCH]		= "mgmt/trcdevarch",
 };
 
 static bool cs_etm_is_etmv4(struct auxtrace_record *itr, int cpu);
@@ -617,7 +625,7 @@ static bool cs_etm_is_ete(struct auxtrace_record *itr, int cpu)
 {
 	struct cs_etm_recording *ptr = container_of(itr, struct cs_etm_recording, itr);
 	struct perf_pmu *cs_etm_pmu = ptr->cs_etm_pmu;
-	int trcdevarch = cs_etm_get_ro(cs_etm_pmu, cpu, metadata_etmv4_ro[CS_ETE_TRCDEVARCH]);
+	int trcdevarch = cs_etm_get_ro(cs_etm_pmu, cpu, metadata_ete_ro[CS_ETE_TRCDEVARCH]);
 
 	/*
 	 * ETE if ARCHVER is 5 (ARCHVER is 4 for ETM) and ARCHPART is 0xA13.
@@ -648,6 +656,31 @@ static void cs_etm_save_etmv4_header(__u64 data[], struct auxtrace_record *itr,
 						     metadata_etmv4_ro[CS_ETMV4_TRCAUTHSTATUS]);
 }
 
+static void cs_etm_save_ete_header(__u64 data[], struct auxtrace_record *itr, int cpu)
+{
+	struct cs_etm_recording *ptr = container_of(itr, struct cs_etm_recording, itr);
+	struct perf_pmu *cs_etm_pmu = ptr->cs_etm_pmu;
+
+	/* Get trace configuration register */
+	data[CS_ETE_TRCCONFIGR] = cs_etmv4_get_config(itr);
+	/* Get traceID from the framework */
+	data[CS_ETE_TRCTRACEIDR] = coresight_get_trace_id(cpu);
+	/* Get read-only information from sysFS */
+	data[CS_ETE_TRCIDR0] = cs_etm_get_ro(cs_etm_pmu, cpu,
+					     metadata_ete_ro[CS_ETE_TRCIDR0]);
+	data[CS_ETE_TRCIDR1] = cs_etm_get_ro(cs_etm_pmu, cpu,
+					     metadata_ete_ro[CS_ETE_TRCIDR1]);
+	data[CS_ETE_TRCIDR2] = cs_etm_get_ro(cs_etm_pmu, cpu,
+					     metadata_ete_ro[CS_ETE_TRCIDR2]);
+	data[CS_ETE_TRCIDR8] = cs_etm_get_ro(cs_etm_pmu, cpu,
+					     metadata_ete_ro[CS_ETE_TRCIDR8]);
+	data[CS_ETE_TRCAUTHSTATUS] = cs_etm_get_ro(cs_etm_pmu, cpu,
+						   metadata_ete_ro[CS_ETE_TRCAUTHSTATUS]);
+	/* ETE uses the same registers as ETMv4 plus TRCDEVARCH */
+	data[CS_ETE_TRCDEVARCH] = cs_etm_get_ro(cs_etm_pmu, cpu,
+						metadata_ete_ro[CS_ETE_TRCDEVARCH]);
+}
+
 static void cs_etm_get_metadata(int cpu, u32 *offset,
 				struct auxtrace_record *itr,
 				struct perf_record_auxtrace_info *info)
@@ -661,11 +694,7 @@ static void cs_etm_get_metadata(int cpu, u32 *offset,
 	/* first see what kind of tracer this cpu is affined to */
 	if (cs_etm_is_ete(itr, cpu)) {
 		magic = __perf_cs_ete_magic;
-		/* ETE uses the same registers as ETMv4 plus TRCDEVARCH */
-		cs_etm_save_etmv4_header(&info->priv[*offset], itr, cpu);
-		info->priv[*offset + CS_ETE_TRCDEVARCH] =
-			cs_etm_get_ro(cs_etm_pmu, cpu,
-				      metadata_etmv4_ro[CS_ETE_TRCDEVARCH]);
+		cs_etm_save_ete_header(&info->priv[*offset], itr, cpu);
 
 		/* How much space was used */
 		increment = CS_ETE_PRIV_MAX;
diff --git a/tools/perf/util/cs-etm-base.c b/tools/perf/util/cs-etm-base.c
index 597542410854..282042c6e944 100644
--- a/tools/perf/util/cs-etm-base.c
+++ b/tools/perf/util/cs-etm-base.c
@@ -36,7 +36,20 @@ static const char * const cs_etmv4_priv_fmts[] = {
 	[CS_ETMV4_TRCIDR2]	= "	TRCIDR2			       %llx\n",
 	[CS_ETMV4_TRCIDR8]	= "	TRCIDR8			       %llx\n",
 	[CS_ETMV4_TRCAUTHSTATUS] = "	TRCAUTHSTATUS		       %llx\n",
-	[CS_ETE_TRCDEVARCH]	= "	TRCDEVARCH                     %llx\n"
+};
+
+static const char * const cs_ete_priv_fmts[] = {
+	[CS_ETM_MAGIC]		= "	Magic number		       %llx\n",
+	[CS_ETM_CPU]		= "	CPU			       %lld\n",
+	[CS_ETM_NR_TRC_PARAMS]	= "	NR_TRC_PARAMS		       %llx\n",
+	[CS_ETE_TRCCONFIGR]	= "	TRCCONFIGR		       %llx\n",
+	[CS_ETE_TRCTRACEIDR]	= "	TRCTRACEIDR		       %llx\n",
+	[CS_ETE_TRCIDR0]	= "	TRCIDR0			       %llx\n",
+	[CS_ETE_TRCIDR1]	= "	TRCIDR1			       %llx\n",
+	[CS_ETE_TRCIDR2]	= "	TRCIDR2			       %llx\n",
+	[CS_ETE_TRCIDR8]	= "	TRCIDR8			       %llx\n",
+	[CS_ETE_TRCAUTHSTATUS]	= "	TRCAUTHSTATUS		       %llx\n",
+	[CS_ETE_TRCDEVARCH]	= "	TRCDEVARCH                     %llx\n",
 };
 
 static const char * const param_unk_fmt =
@@ -96,19 +109,22 @@ static int cs_etm__print_cpu_metadata_v1(u64 *val, int *offset)
 			else
 				fprintf(stdout, cs_etm_priv_fmts[j], val[i]);
 		}
-	} else if (magic == __perf_cs_etmv4_magic || magic == __perf_cs_ete_magic) {
-		/*
-		 * ETE and ETMv4 can be printed in the same block because the number of parameters
-		 * is saved and they share the list of parameter names. ETE is also only supported
-		 * in V1 files.
-		 */
+	} else if (magic == __perf_cs_etmv4_magic) {
 		for (j = 0; j < total_params; j++, i++) {
 			/* if newer record - could be excess params */
-			if (j >= CS_ETE_PRIV_MAX)
+			if (j >= CS_ETMV4_PRIV_MAX)
 				fprintf(stdout, param_unk_fmt, j, val[i]);
 			else
 				fprintf(stdout, cs_etmv4_priv_fmts[j], val[i]);
 		}
+	} else if (magic == __perf_cs_ete_magic) {
+		for (j = 0; j < total_params; j++, i++) {
+			/* if newer record - could be excess params */
+			if (j >= CS_ETE_PRIV_MAX)
+				fprintf(stdout, param_unk_fmt, j, val[i]);
+			else
+				fprintf(stdout, cs_ete_priv_fmts[j], val[i]);
+		}
 	} else {
 		/* failure - note bad magic value and error out */
 		fprintf(stdout, magic_unk_fmt, magic);
diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c
index 33303d03c2fa..879576d5f899 100644
--- a/tools/perf/util/cs-etm.c
+++ b/tools/perf/util/cs-etm.c
@@ -464,12 +464,12 @@ static void cs_etm__set_trace_param_ete(struct cs_etm_trace_params *t_params,
 	u64 **metadata = etm->metadata;
 
 	t_params[idx].protocol = CS_ETM_PROTO_ETE;
-	t_params[idx].ete.reg_idr0 = metadata[idx][CS_ETMV4_TRCIDR0];
-	t_params[idx].ete.reg_idr1 = metadata[idx][CS_ETMV4_TRCIDR1];
-	t_params[idx].ete.reg_idr2 = metadata[idx][CS_ETMV4_TRCIDR2];
-	t_params[idx].ete.reg_idr8 = metadata[idx][CS_ETMV4_TRCIDR8];
-	t_params[idx].ete.reg_configr = metadata[idx][CS_ETMV4_TRCCONFIGR];
-	t_params[idx].ete.reg_traceidr = metadata[idx][CS_ETMV4_TRCTRACEIDR];
+	t_params[idx].ete.reg_idr0 = metadata[idx][CS_ETE_TRCIDR0];
+	t_params[idx].ete.reg_idr1 = metadata[idx][CS_ETE_TRCIDR1];
+	t_params[idx].ete.reg_idr2 = metadata[idx][CS_ETE_TRCIDR2];
+	t_params[idx].ete.reg_idr8 = metadata[idx][CS_ETE_TRCIDR8];
+	t_params[idx].ete.reg_configr = metadata[idx][CS_ETE_TRCCONFIGR];
+	t_params[idx].ete.reg_traceidr = metadata[idx][CS_ETE_TRCTRACEIDR];
 	t_params[idx].ete.reg_devarch = metadata[idx][CS_ETE_TRCDEVARCH];
 }
 
diff --git a/tools/perf/util/cs-etm.h b/tools/perf/util/cs-etm.h
index 5da50d5dae6b..c5925428afa9 100644
--- a/tools/perf/util/cs-etm.h
+++ b/tools/perf/util/cs-etm.h
@@ -82,7 +82,16 @@ enum {
  * added in header V1
  */
 enum {
-	CS_ETE_TRCDEVARCH = CS_ETMV4_PRIV_MAX,
+	/* Dynamic, configurable parameters */
+	CS_ETE_TRCCONFIGR = CS_ETM_COMMON_BLK_MAX_V1,
+	CS_ETE_TRCTRACEIDR,
+	/* RO, taken from sysFS */
+	CS_ETE_TRCIDR0,
+	CS_ETE_TRCIDR1,
+	CS_ETE_TRCIDR2,
+	CS_ETE_TRCIDR8,
+	CS_ETE_TRCAUTHSTATUS,
+	CS_ETE_TRCDEVARCH,
 	CS_ETE_PRIV_MAX
 };
 
-- 
2.25.1

[PATCH v3 6/7] perf cs_etm: Record ts_source in AUXTRACE_INFO for ETMv4 and ETE

[James Clark]

From: German Gomez <german.gomez@arm.com>

Read the value of ts_source exposed by the driver and store it in the
ETMv4 and ETE header. If the interface doesn't exist (such as in older
Kernels), defaults to a safe value of -1.

Signed-off-by: German Gomez <german.gomez@arm.com>
Signed-off-by: James Clark <james.clark@arm.com>
---
 tools/perf/arch/arm/util/cs-etm.c | 48 +++++++++++++++++++++++++++++++
 tools/perf/util/cs-etm-base.c     |  2 ++
 tools/perf/util/cs-etm.h          |  2 ++
 3 files changed, 52 insertions(+)

diff --git a/tools/perf/arch/arm/util/cs-etm.c b/tools/perf/arch/arm/util/cs-etm.c
index b526ffe550a5..481e170cd3f1 100644
--- a/tools/perf/arch/arm/util/cs-etm.c
+++ b/tools/perf/arch/arm/util/cs-etm.c
@@ -53,6 +53,7 @@ static const char * const metadata_etmv4_ro[] = {
 	[CS_ETMV4_TRCIDR2]		= "trcidr/trcidr2",
 	[CS_ETMV4_TRCIDR8]		= "trcidr/trcidr8",
 	[CS_ETMV4_TRCAUTHSTATUS]	= "mgmt/trcauthstatus",
+	[CS_ETMV4_TS_SOURCE]		= "ts_source",
 };
 
 static const char * const metadata_ete_ro[] = {
@@ -62,6 +63,7 @@ static const char * const metadata_ete_ro[] = {
 	[CS_ETE_TRCIDR8]		= "trcidr/trcidr8",
 	[CS_ETE_TRCAUTHSTATUS]		= "mgmt/trcauthstatus",
 	[CS_ETE_TRCDEVARCH]		= "mgmt/trcdevarch",
+	[CS_ETE_TS_SOURCE]		= "ts_source",
 };
 
 static bool cs_etm_is_etmv4(struct auxtrace_record *itr, int cpu);
@@ -613,6 +615,32 @@ static int cs_etm_get_ro(struct perf_pmu *pmu, int cpu, const char *path)
 	return val;
 }
 
+static int cs_etm_get_ro_signed(struct perf_pmu *pmu, int cpu, const char *path)
+{
+	char pmu_path[PATH_MAX];
+	int scan;
+	int val = 0;
+
+	/* Get RO metadata from sysfs */
+	snprintf(pmu_path, PATH_MAX, "cpu%d/%s", cpu, path);
+
+	scan = perf_pmu__scan_file(pmu, pmu_path, "%d", &val);
+	if (scan != 1)
+		pr_err("%s: error reading: %s\n", __func__, pmu_path);
+
+	return val;
+}
+
+static bool cs_etm_pmu_path_exists(struct perf_pmu *pmu, int cpu, const char *path)
+{
+	char pmu_path[PATH_MAX];
+
+	/* Get RO metadata from sysfs */
+	snprintf(pmu_path, PATH_MAX, "cpu%d/%s", cpu, path);
+
+	return perf_pmu__file_exists(pmu, pmu_path);
+}
+
 #define TRCDEVARCH_ARCHPART_SHIFT 0
 #define TRCDEVARCH_ARCHPART_MASK  GENMASK(11, 0)
 #define TRCDEVARCH_ARCHPART(x)    (((x) & TRCDEVARCH_ARCHPART_MASK) >> TRCDEVARCH_ARCHPART_SHIFT)
@@ -654,6 +682,16 @@ static void cs_etm_save_etmv4_header(__u64 data[], struct auxtrace_record *itr,
 					       metadata_etmv4_ro[CS_ETMV4_TRCIDR8]);
 	data[CS_ETMV4_TRCAUTHSTATUS] = cs_etm_get_ro(cs_etm_pmu, cpu,
 						     metadata_etmv4_ro[CS_ETMV4_TRCAUTHSTATUS]);
+
+	/* Kernels older than 5.19 may not expose ts_source */
+	if (cs_etm_pmu_path_exists(cs_etm_pmu, cpu, metadata_etmv4_ro[CS_ETMV4_TS_SOURCE]))
+		data[CS_ETMV4_TS_SOURCE] = (__u64) cs_etm_get_ro_signed(cs_etm_pmu, cpu,
+				metadata_etmv4_ro[CS_ETMV4_TS_SOURCE]);
+	else {
+		pr_warning("[%03d] pmu file 'ts_source' not found. Fallback to safe value (-1)\n",
+			   cpu);
+		data[CS_ETMV4_TS_SOURCE] = (__u64) -1;
+	}
 }
 
 static void cs_etm_save_ete_header(__u64 data[], struct auxtrace_record *itr, int cpu)
@@ -679,6 +717,16 @@ static void cs_etm_save_ete_header(__u64 data[], struct auxtrace_record *itr, in
 	/* ETE uses the same registers as ETMv4 plus TRCDEVARCH */
 	data[CS_ETE_TRCDEVARCH] = cs_etm_get_ro(cs_etm_pmu, cpu,
 						metadata_ete_ro[CS_ETE_TRCDEVARCH]);
+
+	/* Kernels older than 5.19 may not expose ts_source */
+	if (cs_etm_pmu_path_exists(cs_etm_pmu, cpu, metadata_ete_ro[CS_ETE_TS_SOURCE]))
+		data[CS_ETE_TS_SOURCE] = (__u64) cs_etm_get_ro_signed(cs_etm_pmu, cpu,
+				metadata_ete_ro[CS_ETE_TS_SOURCE]);
+	else {
+		pr_warning("[%03d] pmu file 'ts_source' not found. Fallback to safe value (-1)\n",
+			   cpu);
+		data[CS_ETE_TS_SOURCE] = (__u64) -1;
+	}
 }
 
 static void cs_etm_get_metadata(int cpu, u32 *offset,
diff --git a/tools/perf/util/cs-etm-base.c b/tools/perf/util/cs-etm-base.c
index 282042c6e944..5f48b756c4cf 100644
--- a/tools/perf/util/cs-etm-base.c
+++ b/tools/perf/util/cs-etm-base.c
@@ -36,6 +36,7 @@ static const char * const cs_etmv4_priv_fmts[] = {
 	[CS_ETMV4_TRCIDR2]	= "	TRCIDR2			       %llx\n",
 	[CS_ETMV4_TRCIDR8]	= "	TRCIDR8			       %llx\n",
 	[CS_ETMV4_TRCAUTHSTATUS] = "	TRCAUTHSTATUS		       %llx\n",
+	[CS_ETMV4_TS_SOURCE]	= "	TS_SOURCE		       %lld\n",
 };
 
 static const char * const cs_ete_priv_fmts[] = {
@@ -50,6 +51,7 @@ static const char * const cs_ete_priv_fmts[] = {
 	[CS_ETE_TRCIDR8]	= "	TRCIDR8			       %llx\n",
 	[CS_ETE_TRCAUTHSTATUS]	= "	TRCAUTHSTATUS		       %llx\n",
 	[CS_ETE_TRCDEVARCH]	= "	TRCDEVARCH                     %llx\n",
+	[CS_ETE_TS_SOURCE]	= "	TS_SOURCE                      %lld\n",
 };
 
 static const char * const param_unk_fmt =
diff --git a/tools/perf/util/cs-etm.h b/tools/perf/util/cs-etm.h
index c5925428afa9..ad790930bcbc 100644
--- a/tools/perf/util/cs-etm.h
+++ b/tools/perf/util/cs-etm.h
@@ -71,6 +71,7 @@ enum {
 	CS_ETMV4_TRCIDR2,
 	CS_ETMV4_TRCIDR8,
 	CS_ETMV4_TRCAUTHSTATUS,
+	CS_ETMV4_TS_SOURCE,
 	CS_ETMV4_PRIV_MAX,
 };
 
@@ -92,6 +93,7 @@ enum {
 	CS_ETE_TRCIDR8,
 	CS_ETE_TRCAUTHSTATUS,
 	CS_ETE_TRCDEVARCH,
+	CS_ETE_TS_SOURCE,
 	CS_ETE_PRIV_MAX
 };
 
-- 
2.25.1

[PATCH v3 7/7] perf cs_etm: Set the time field in the synthetic samples

[James Clark]

From: German Gomez <german.gomez@arm.com>

If virtual timestamps are detected, set sample time field accordingly,
otherwise warn the user that the samples will not include the time data.

 | Test notes (FEAT_TRF platform)
 |
 | $ ./perf record -e cs_etm//u -a -- sleep 4
 | $ ./perf script --fields +time
 | 	    perf   422 [000]   163.375100:          1 branches:uH:                 0 [unknown] ([unknown])
 | 	    perf   422 [000]   163.375100:          1 branches:uH:      ffffb8009544 ioctl+0x14 (/lib/aarch64-linux-gnu/libc-2.27.so)
 | 	    perf   422 [000]   163.375100:          1 branches:uH:      aaaaab6bebf4 perf_evsel__run_ioctl+0x90 (/home/german/linux/tools/perf/perf)
 | [...]
 | 	    perf   422 [000]   167.393100:          1 branches:uH:      aaaaab6bda00 __xyarray__entry+0x74 (/home/german/linux/tools/perf/perf)
 | 	    perf   422 [000]   167.393099:          1 branches:uH:      aaaaab6bda0c __xyarray__entry+0x80 (/home/german/linux/tools/perf/perf)
 | 	    perf   422 [000]   167.393099:          1 branches:uH:      ffffb8009538 ioctl+0x8 (/lib/aarch64-linux-gnu/libc-2.27.so)
 |
 | The time from the first sample to the last sample is 4 seconds

Signed-off-by: German Gomez <german.gomez@arm.com>
Signed-off-by: James Clark <james.clark@arm.com>
---
 tools/perf/util/cs-etm.c | 74 +++++++++++++++++++++++++++++++++++++---
 1 file changed, 70 insertions(+), 4 deletions(-)

diff --git a/tools/perf/util/cs-etm.c b/tools/perf/util/cs-etm.c
index 879576d5f899..19784baef5b8 100644
--- a/tools/perf/util/cs-etm.c
+++ b/tools/perf/util/cs-etm.c
@@ -35,6 +35,7 @@
 #include "tool.h"
 #include "thread.h"
 #include "thread-stack.h"
+#include "tsc.h"
 #include <tools/libc_compat.h>
 #include "util/synthetic-events.h"
 
@@ -46,10 +47,12 @@ struct cs_etm_auxtrace {
 	struct perf_session *session;
 	struct machine *machine;
 	struct thread *unknown_thread;
+	struct perf_tsc_conversion tc;
 
 	u8 timeless_decoding;
 	u8 snapshot_mode;
 	u8 data_queued;
+	u8 has_virtual_ts; /* Virtual/Kernel timestamps in the trace. */
 
 	int num_cpu;
 	u64 latest_kernel_timestamp;
@@ -1161,6 +1164,22 @@ static void cs_etm__copy_insn(struct cs_etm_queue *etmq,
 			   sample->insn_len, (void *)sample->insn);
 }
 
+static inline void cs_etm__resolve_sample_time(struct cs_etm_queue *etmq,
+					       struct cs_etm_traceid_queue *tidq,
+					       u64 *time)
+{
+	struct cs_etm_auxtrace *etm = etmq->etm;
+	struct cs_etm_packet_queue *packet_queue = &tidq->packet_queue;
+
+	if (etm->timeless_decoding)
+		*time = 0;
+	else if (etm->has_virtual_ts)
+		*time = tsc_to_perf_time(packet_queue->cs_timestamp, &etm->tc);
+	else
+		*time = etm->latest_kernel_timestamp;
+
+}
+
 static int cs_etm__synth_instruction_sample(struct cs_etm_queue *etmq,
 					    struct cs_etm_traceid_queue *tidq,
 					    u64 addr, u64 period)
@@ -1174,8 +1193,9 @@ static int cs_etm__synth_instruction_sample(struct cs_etm_queue *etmq,
 	event->sample.header.misc = cs_etm__cpu_mode(etmq, addr);
 	event->sample.header.size = sizeof(struct perf_event_header);
 
-	if (!etm->timeless_decoding)
-		sample.time = etm->latest_kernel_timestamp;
+	/* Set time field based con etm auxtrace config. */
+	cs_etm__resolve_sample_time(etmq, tidq, &sample.time);
+
 	sample.ip = addr;
 	sample.pid = tidq->pid;
 	sample.tid = tidq->tid;
@@ -1232,8 +1252,9 @@ static int cs_etm__synth_branch_sample(struct cs_etm_queue *etmq,
 	event->sample.header.misc = cs_etm__cpu_mode(etmq, ip);
 	event->sample.header.size = sizeof(struct perf_event_header);
 
-	if (!etm->timeless_decoding)
-		sample.time = etm->latest_kernel_timestamp;
+	/* Set time field based con etm auxtrace config. */
+	cs_etm__resolve_sample_time(etmq, tidq, &sample.time);
+
 	sample.ip = ip;
 	sample.pid = tidq->pid;
 	sample.tid = tidq->tid;
@@ -2746,12 +2767,42 @@ static int cs_etm__queue_aux_records(struct perf_session *session)
 	return 0;
 }
 
+#define HAS_PARAM(j, type, param) (metadata[(j)][CS_ETM_NR_TRC_PARAMS] <= \
+				  (CS_##type##_##param - CS_ETM_COMMON_BLK_MAX_V1))
+
+/*
+ * Loop through the ETMs and complain if we find at least one where ts_source != 1 (virtual
+ * timestamps).
+ */
+static bool cs_etm__has_virtual_ts(u64 **metadata, int num_cpu)
+{
+	int j;
+
+	for (j = 0; j < num_cpu; j++) {
+		switch (metadata[j][CS_ETM_MAGIC]) {
+		case __perf_cs_etmv4_magic:
+			if (HAS_PARAM(j, ETMV4, TS_SOURCE) || metadata[j][CS_ETMV4_TS_SOURCE] != 1)
+				return false;
+			break;
+		case __perf_cs_ete_magic:
+			if (HAS_PARAM(j, ETE, TS_SOURCE) || metadata[j][CS_ETE_TS_SOURCE] != 1)
+				return false;
+			break;
+		default:
+			/* Unknown / unsupported magic number. */
+			return false;
+		}
+	}
+	return true;
+}
+
 int cs_etm__process_auxtrace_info_full(union perf_event *event,
 				       struct perf_session *session)
 {
 	struct perf_record_auxtrace_info *auxtrace_info = &event->auxtrace_info;
 	struct cs_etm_auxtrace *etm = NULL;
 	struct int_node *inode;
+	struct perf_record_time_conv *tc = &session->time_conv;
 	int event_header_size = sizeof(struct perf_event_header);
 	int total_size = auxtrace_info->header.size;
 	int priv_size = 0;
@@ -2886,6 +2937,12 @@ int cs_etm__process_auxtrace_info_full(union perf_event *event,
 	etm->auxtrace_type = auxtrace_info->type;
 	etm->timeless_decoding = cs_etm__is_timeless_decoding(etm);
 
+	/* Use virtual timestamps if all ETMs report ts_source = 1 */
+	etm->has_virtual_ts = cs_etm__has_virtual_ts(metadata, num_cpu);
+
+	if (!etm->has_virtual_ts)
+		ui__warning("Virtual timestamps are not enabled, or not supported by the traced system.\n\nThe time field of the samples will not be set accurately.\n\n");
+
 	etm->auxtrace.process_event = cs_etm__process_event;
 	etm->auxtrace.process_auxtrace_event = cs_etm__process_auxtrace_event;
 	etm->auxtrace.flush_events = cs_etm__flush_events;
@@ -2915,6 +2972,15 @@ int cs_etm__process_auxtrace_info_full(union perf_event *event,
 		goto err_delete_thread;
 	}
 
+	etm->tc.time_shift = tc->time_shift;
+	etm->tc.time_mult = tc->time_mult;
+	etm->tc.time_zero = tc->time_zero;
+	if (event_contains(*tc, time_cycles)) {
+		etm->tc.time_cycles = tc->time_cycles;
+		etm->tc.time_mask = tc->time_mask;
+		etm->tc.cap_user_time_zero = tc->cap_user_time_zero;
+		etm->tc.cap_user_time_short = tc->cap_user_time_short;
+	}
 	err = cs_etm__synth_events(etm, session);
 	if (err)
 		goto err_delete_thread;
-- 
2.25.1

Re: [PATCH v3 0/7] perf cs_etm: Basic support for virtual/kernel timestamps

[Tanmay Jagdale]

Hi James,

> Changes since v2:
> 
>   * Remove const to non-const change and copy strings where needed
>     instead.
>   * Use sizeof() instead of PATH_MAX
>   * Append "will not be set accurately." to new error message
>   * Remove unneeded stat() call
>   * Rebase on perf/core
> 
> ==========================
> 
> Changes since v1:
> 
>   * Add 3 refactor commits for sysfs reading around pmu.c as suggested
>     by Arnaldo here [1]
>   * The dependency on [2] has now reached mainline so is no longer
>     blocking
>   * Rebase on perf/core
> 
> [1]: https://lore.kernel.org/all/YnqVqq5QW%2Fb14oPZ@kernel.org/
> [2]: https://lore.kernel.org/all/20220503123537.1003035-1-german.gomez@arm.com/
> 
> German Gomez (4):
>   perf pmu: Add function to check if a pmu file exists
>   perf cs_etm: Keep separate symbols for ETMv4 and ETE parameters
>   perf cs_etm: Record ts_source in AUXTRACE_INFO for ETMv4 and ETE
>   perf cs_etm: Set the time field in the synthetic samples
> 
> James Clark (3):
>   perf: Remove duplication around EVENT_SOURCE_DEVICE_PATH
>   perf: Use perf_pmu__open_file() and perf_pmu__scan_file()
>   perf: Remove remaining duplication of bus/event_source/devices/...
> 
>  tools/perf/arch/arm/util/auxtrace.c |   5 +-
>  tools/perf/arch/arm/util/cs-etm.c   |  91 ++++++++++++--
>  tools/perf/arch/x86/util/pmu.c      |  12 +-
>  tools/perf/util/cputopo.c           |   9 +-
>  tools/perf/util/cs-etm-base.c       |  34 ++++--
>  tools/perf/util/cs-etm.c            |  86 ++++++++++++--
>  tools/perf/util/cs-etm.h            |  13 +-
>  tools/perf/util/pmu-hybrid.c        |  27 +----
>  tools/perf/util/pmu.c               | 177 +++++++++++-----------------
>  tools/perf/util/pmu.h               |  10 +-
>  10 files changed, 284 insertions(+), 180 deletions(-)
> 
> 
> base-commit: 09e6f9f98370be9a9f8978139e0eb1be87d1125f
I have tested this patch set on our platform and able to see updated
timestamp values in perf script's output.

$ perf record -e cs_etm/cycacc,@tmc_etr0/k -C 9 taskset -c 9 sleep 2
$ perf script --itrace=i1ns --ns -Fcomm,tid,pid,time,cpu,event,ip,sym,addr,symoff,flags,callindent

At certain points noticed that hardware emits same timestamp packets
but with updated cycle count (CC) values. A small snippet of the log:

Idx:100; ID:12; I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFF8000086A761C ~[0x761C]
Idx:103; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x3d
Idx:107; ID:12; I_ATOM_F2 : Atom format 2.; EN
Idx:108; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x3f
Idx:112; ID:12; I_ATOM_F1 : Atom format 1.; N
Idx:113; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x45
Idx:116; ID:12; I_ATOM_F1 : Atom format 1.; E
Idx:117; ID:12; I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFF8000086B52D4 ~[0x152D4]

Since the source of timestamp is the Generic Timer block and the CPUs
run at higher frequencies, this behaviour could be possible on high
performance ARM cores.

Having consecutive timestamps with same value is resulting in a
slightly jumbled order (in nanosecs) in perf script's time column.
A snippet corresponding to the Coresight trace data mentioned above:
...
perf   965/965   [001]  3182.286629044:            instructions:k:   return                               0 ffff8000086a761c coresight_timeout+0xc8
perf   965/965   [001]  3182.286629044:            instructions:k:   return                               0 ffff8000086a7620 coresight_timeout+0xcc
perf   965/965   [001]  3182.286629046:            instructions:k:   jmp                                  0 ffff8000086a75c8 coresight_timeout+0x74
perf   965/965   [001]  3182.286629046:            instructions:k:   jmp                                  0 ffff8000086a75cc coresight_timeout+0x78
perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75d0 coresight_timeout+0x7c
perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75d4 coresight_timeout+0x80
perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75d8 coresight_timeout+0x84
perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75dc coresight_timeout+0x88
perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75e0 coresight_timeout+0x8c
perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75e4 coresight_timeout+0x90
perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75e8 coresight_timeout+0x94
perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75ec coresight_timeout+0x98

Perf's do_soft_timestamp() logic in cs_etm_decoder.c file is incrementing
the HW timestamp based on instruction count. Since the next timestamp
also has the same value, it could be leading to this jumbled order.

We would like to know if this has been observed on other platforms ?
And what could be a solution in SW for this ?

With Regards,
Tanmay

Re: [PATCH v3 0/7] perf cs_etm: Basic support for virtual/kernel timestamps

[James Clark]

On 10/01/2023 16:42, Tanmay Jagdale wrote:
[...]
>>
>> base-commit: 09e6f9f98370be9a9f8978139e0eb1be87d1125f
> I have tested this patch set on our platform and able to see updated
> timestamp values in perf script's output.
> 
> $ perf record -e cs_etm/cycacc,@tmc_etr0/k -C 9 taskset -c 9 sleep 2
> $ perf script --itrace=i1ns --ns -Fcomm,tid,pid,time,cpu,event,ip,sym,addr,symoff,flags,callindent
> 
> At certain points noticed that hardware emits same timestamp packets
> but with updated cycle count (CC) values. A small snippet of the log:
> 
> Idx:100; ID:12; I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFF8000086A761C ~[0x761C]
> Idx:103; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x3d
> Idx:107; ID:12; I_ATOM_F2 : Atom format 2.; EN
> Idx:108; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x3f
> Idx:112; ID:12; I_ATOM_F1 : Atom format 1.; N
> Idx:113; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x45
> Idx:116; ID:12; I_ATOM_F1 : Atom format 1.; E
> Idx:117; ID:12; I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFF8000086B52D4 ~[0x152D4]
> 
> Since the source of timestamp is the Generic Timer block and the CPUs
> run at higher frequencies, this behaviour could be possible on high
> performance ARM cores.
> 
> Having consecutive timestamps with same value is resulting in a
> slightly jumbled order (in nanosecs) in perf script's time column.
> A snippet corresponding to the Coresight trace data mentioned above:
> ...
> perf   965/965   [001]  3182.286629044:            instructions:k:   return                               0 ffff8000086a761c coresight_timeout+0xc8
> perf   965/965   [001]  3182.286629044:            instructions:k:   return                               0 ffff8000086a7620 coresight_timeout+0xcc
> perf   965/965   [001]  3182.286629046:            instructions:k:   jmp                                  0 ffff8000086a75c8 coresight_timeout+0x74
> perf   965/965   [001]  3182.286629046:            instructions:k:   jmp                                  0 ffff8000086a75cc coresight_timeout+0x78
> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75d0 coresight_timeout+0x7c
> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75d4 coresight_timeout+0x80
> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75d8 coresight_timeout+0x84
> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75dc coresight_timeout+0x88
> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75e0 coresight_timeout+0x8c
> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75e4 coresight_timeout+0x90
> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75e8 coresight_timeout+0x94
> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75ec coresight_timeout+0x98
> 
> Perf's do_soft_timestamp() logic in cs_etm_decoder.c file is incrementing
> the HW timestamp based on instruction count. Since the next timestamp
> also has the same value, it could be leading to this jumbled order.
> 
> We would like to know if this has been observed on other platforms ?
> And what could be a solution in SW for this ?

Nice catch. If I'm understanding this correctly it looks like the issue
is a combination of the cycle count in the packet being ignored by Perf,
and the instruction count being reset to 0 when a new timestamp is received.

It looks like it can be fixed by some combination of combining the cycle
count and instruction count and maybe not resetting instruction count if
the newly received timestamp is the same as the last one. I will look
into this.

We haven't noticed it on any other platforms, but we haven't been
looking too closely at the timestamps until now. Perhaps I can add a
test that checks if the trace in a known function goes in the correct
time order.

Thanks
James

Re: [PATCH v3 0/7] perf cs_etm: Basic support for virtual/kernel timestamps

[James Clark]

On 11/01/2023 10:56, James Clark wrote:
> 
> 
> On 10/01/2023 16:42, Tanmay Jagdale wrote:
> [...]
>>>
>>> base-commit: 09e6f9f98370be9a9f8978139e0eb1be87d1125f
>> I have tested this patch set on our platform and able to see updated
>> timestamp values in perf script's output.
>>
>> $ perf record -e cs_etm/cycacc,@tmc_etr0/k -C 9 taskset -c 9 sleep 2
>> $ perf script --itrace=i1ns --ns -Fcomm,tid,pid,time,cpu,event,ip,sym,addr,symoff,flags,callindent
>>
>> At certain points noticed that hardware emits same timestamp packets
>> but with updated cycle count (CC) values. A small snippet of the log:
>>
>> Idx:100; ID:12; I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFF8000086A761C ~[0x761C]
>> Idx:103; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x3d
>> Idx:107; ID:12; I_ATOM_F2 : Atom format 2.; EN
>> Idx:108; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x3f
>> Idx:112; ID:12; I_ATOM_F1 : Atom format 1.; N
>> Idx:113; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x45
>> Idx:116; ID:12; I_ATOM_F1 : Atom format 1.; E
>> Idx:117; ID:12; I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFF8000086B52D4 ~[0x152D4]
>>
>> Since the source of timestamp is the Generic Timer block and the CPUs
>> run at higher frequencies, this behaviour could be possible on high
>> performance ARM cores.
>>
>> Having consecutive timestamps with same value is resulting in a
>> slightly jumbled order (in nanosecs) in perf script's time column.
>> A snippet corresponding to the Coresight trace data mentioned above:
>> ...
>> perf   965/965   [001]  3182.286629044:            instructions:k:   return                               0 ffff8000086a761c coresight_timeout+0xc8
>> perf   965/965   [001]  3182.286629044:            instructions:k:   return                               0 ffff8000086a7620 coresight_timeout+0xcc
>> perf   965/965   [001]  3182.286629046:            instructions:k:   jmp                                  0 ffff8000086a75c8 coresight_timeout+0x74
>> perf   965/965   [001]  3182.286629046:            instructions:k:   jmp                                  0 ffff8000086a75cc coresight_timeout+0x78
>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75d0 coresight_timeout+0x7c
>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75d4 coresight_timeout+0x80
>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75d8 coresight_timeout+0x84
>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75dc coresight_timeout+0x88
>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75e0 coresight_timeout+0x8c
>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75e4 coresight_timeout+0x90
>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75e8 coresight_timeout+0x94
>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75ec coresight_timeout+0x98
>>
>> Perf's do_soft_timestamp() logic in cs_etm_decoder.c file is incrementing
>> the HW timestamp based on instruction count. Since the next timestamp
>> also has the same value, it could be leading to this jumbled order.
>>
>> We would like to know if this has been observed on other platforms ?
>> And what could be a solution in SW for this ?
> 
> Nice catch. If I'm understanding this correctly it looks like the issue
> is a combination of the cycle count in the packet being ignored by Perf,
> and the instruction count being reset to 0 when a new timestamp is received.
> 
> It looks like it can be fixed by some combination of combining the cycle
> count and instruction count and maybe not resetting instruction count if
> the newly received timestamp is the same as the last one. I will look
> into this.
> 
> We haven't noticed it on any other platforms, but we haven't been
> looking too closely at the timestamps until now. Perhaps I can add a
> test that checks if the trace in a known function goes in the correct
> time order.
> 

I'm thinking of something like the following patch to fix the ordering.
It doesn't use the cycle count, but I'm not sure if that would be
worthwhile in the end, considering that it would have sub nanosecond
resolution so wouldn't affect the Perf timestamps:


diff --git a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
index 31fa3b45134a..08a028e3e87a 100644
--- a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
+++ b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
@@ -112,6 +112,19 @@ int cs_etm_decoder__get_packet(struct cs_etm_packet_queue *packet_queue,
 	return 1;
 }
 
+static u64 cs_etm_decoder__instr_count_to_ns(u64 instr_count)
+{
+	/*
+	 * Assume a maximum of 0.1ns elapsed per instruction. This would be the
+	 * case with a theoretical 10GHz core executing 1 instruction per cycle.
+	 * Used to estimate the sample time for synthesized instructions because
+	 * Coresight only emits a timestamp for a range of instructions rather
+	 * than per instruction.
+	 */
+	const int INSTR_PER_NS = 10;
+
+	return instr_count / INSTR_PER_NS;
+}
 static int cs_etm_decoder__gen_etmv3_config(struct cs_etm_trace_params *params,
 					    ocsd_etmv3_cfg *config)
 {
@@ -267,7 +280,7 @@ cs_etm_decoder__do_soft_timestamp(struct cs_etm_queue *etmq,
 	packet_queue->cs_timestamp = packet_queue->next_cs_timestamp;
 
 	/* Estimate the timestamp for the next range packet */
-	packet_queue->next_cs_timestamp += packet_queue->instr_count;
+	packet_queue->next_cs_timestamp += cs_etm_decoder__instr_count_to_ns(packet_queue->instr_count);
 	packet_queue->instr_count = 0;
 
 	/* Tell the front end which traceid_queue needs attention */
@@ -295,11 +308,17 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
 	 * hence asking the decoder to keep decoding rather than stopping.
 	 */
 	if (packet_queue->cs_timestamp) {
-		packet_queue->next_cs_timestamp = elem->timestamp;
+		/*
+		 * Don't allow next_cs_timestamp to be less than the last one estimated by
+		 * cs_etm_decoder__do_soft_timestamp() otherwise new instructions would
+		 * appear to go back in time. In theory this should never happen, but if
+		 * it did, then next_cs_timestamp should eventually catch up to real time
+		 * unless every single range was predicted to be too long for some reason.
+		 */
+		packet_queue->next_cs_timestamp = max(elem->timestamp, packet_queue->next_cs_timestamp);
 		return OCSD_RESP_CONT;
 	}
 
-
 	if (!elem->timestamp) {
 		/*
 		 * Zero timestamps can be seen due to misconfiguration or hardware bugs.
@@ -312,7 +331,7 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
 					". Decoding may be improved by prepending 'Z' to your current --itrace arguments.\n",
 					indx);
 
-	} else if (packet_queue->instr_count > elem->timestamp) {
+	} else if (cs_etm_decoder__instr_count_to_ns(packet_queue->instr_count) > elem->timestamp) {
 		/*
 		 * Sanity check that the elem->timestamp - packet_queue->instr_count would not
 		 * result in an underflow. Warn and clamp at 0 if it would.
@@ -327,7 +346,8 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
 		 * which instructions started by subtracting the number of instructions
 		 * executed to the timestamp.
 		 */
-		packet_queue->cs_timestamp = elem->timestamp - packet_queue->instr_count;
+		packet_queue->cs_timestamp = elem->timestamp -
+			cs_etm_decoder__instr_count_to_ns(packet_queue->instr_count);
 	}
 	packet_queue->next_cs_timestamp = elem->timestamp;
 	packet_queue->instr_count = 0;

Re: [PATCH v3 0/7] perf cs_etm: Basic support for virtual/kernel timestamps

[Tanmay Jagdale]

Hi James

> >>> base-commit: 09e6f9f98370be9a9f8978139e0eb1be87d1125f
> >> I have tested this patch set on our platform and able to see updated
> >> timestamp values in perf script's output.
> >>
> >> $ perf record -e cs_etm/cycacc,@tmc_etr0/k -C 9 taskset -c 9 sleep 2
> >> $ perf script --itrace=i1ns --ns -Fcomm,tid,pid,time,cpu,event,ip,sym,addr,symoff,flags,callindent
> >>
> >> At certain points noticed that hardware emits same timestamp packets
> >> but with updated cycle count (CC) values. A small snippet of the log:
> >>
> >> Idx:100; ID:12; I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFF8000086A761C ~[0x761C]
> >> Idx:103; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x3d
> >> Idx:107; ID:12; I_ATOM_F2 : Atom format 2.; EN
> >> Idx:108; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x3f
> >> Idx:112; ID:12; I_ATOM_F1 : Atom format 1.; N
> >> Idx:113; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x45
> >> Idx:116; ID:12; I_ATOM_F1 : Atom format 1.; E
> >> Idx:117; ID:12; I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFF8000086B52D4 ~[0x152D4]
> >>
> >> Since the source of timestamp is the Generic Timer block and the CPUs
> >> run at higher frequencies, this behaviour could be possible on high
> >> performance ARM cores.
> >>
> >> Having consecutive timestamps with same value is resulting in a
> >> slightly jumbled order (in nanosecs) in perf script's time column.
> >> A snippet corresponding to the Coresight trace data mentioned above:
> >> ...
> >> perf   965/965   [001]  3182.286629044:            instructions:k:   return                               0 ffff8000086a761c coresight_timeout+0xc8
> >> perf   965/965   [001]  3182.286629044:            instructions:k:   return                               0 ffff8000086a7620 coresight_timeout+0xcc
> >> perf   965/965   [001]  3182.286629046:            instructions:k:   jmp                                  0 ffff8000086a75c8 coresight_timeout+0x74
> >> perf   965/965   [001]  3182.286629046:            instructions:k:   jmp                                  0 ffff8000086a75cc coresight_timeout+0x78
> >> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75d0 coresight_timeout+0x7c
> >> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75d4 coresight_timeout+0x80
> >> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75d8 coresight_timeout+0x84
> >> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75dc coresight_timeout+0x88
> >> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75e0 coresight_timeout+0x8c
> >> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75e4 coresight_timeout+0x90
> >> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75e8 coresight_timeout+0x94
> >> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75ec coresight_timeout+0x98
> >>
> >> Perf's do_soft_timestamp() logic in cs_etm_decoder.c file is incrementing
> >> the HW timestamp based on instruction count. Since the next timestamp
> >> also has the same value, it could be leading to this jumbled order.
> >>
> >> We would like to know if this has been observed on other platforms ?
> >> And what could be a solution in SW for this ?
> >
> > Nice catch. If I'm understanding this correctly it looks like the issue
> > is a combination of the cycle count in the packet being ignored by Perf,
> > and the instruction count being reset to 0 when a new timestamp is received.
> >
> > It looks like it can be fixed by some combination of combining the cycle
> > count and instruction count and maybe not resetting instruction count if
> > the newly received timestamp is the same as the last one. I will look
> > into this.
> >
> > We haven't noticed it on any other platforms, but we haven't been
> > looking too closely at the timestamps until now. Perhaps I can add a
> > test that checks if the trace in a known function goes in the correct
> > time order.
> >
> 
> I'm thinking of something like the following patch to fix the ordering.
> It doesn't use the cycle count, but I'm not sure if that would be
> worthwhile in the end, considering that it would have sub nanosecond
> resolution so wouldn't affect the Perf timestamps:
Thanks for coming up with a quick solution for this issue !

> 
> 
> diff --git a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
> index 31fa3b45134a..08a028e3e87a 100644
> --- a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
> +++ b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
> @@ -112,6 +112,19 @@ int cs_etm_decoder__get_packet(struct cs_etm_packet_queue *packet_queue,
>  	return 1;
>  }
> 
> +static u64 cs_etm_decoder__instr_count_to_ns(u64 instr_count)
> +{
> +	/*
> +	 * Assume a maximum of 0.1ns elapsed per instruction. This would be the
> +	 * case with a theoretical 10GHz core executing 1 instruction per cycle.
> +	 * Used to estimate the sample time for synthesized instructions because
> +	 * Coresight only emits a timestamp for a range of instructions rather
> +	 * than per instruction.
> +	 */
> +	const int INSTR_PER_NS = 10;
> +
> +	return instr_count / INSTR_PER_NS;
> +}
>  static int cs_etm_decoder__gen_etmv3_config(struct cs_etm_trace_params *params,
>  					    ocsd_etmv3_cfg *config)
>  {
> @@ -267,7 +280,7 @@ cs_etm_decoder__do_soft_timestamp(struct cs_etm_queue *etmq,
>  	packet_queue->cs_timestamp = packet_queue->next_cs_timestamp;
> 
>  	/* Estimate the timestamp for the next range packet */
> -	packet_queue->next_cs_timestamp += packet_queue->instr_count;
> +	packet_queue->next_cs_timestamp += cs_etm_decoder__instr_count_to_ns(packet_queue->instr_count);
>  	packet_queue->instr_count = 0;
> 
>  	/* Tell the front end which traceid_queue needs attention */
> @@ -295,11 +308,17 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
>  	 * hence asking the decoder to keep decoding rather than stopping.
>  	 */
>  	if (packet_queue->cs_timestamp) {
> -		packet_queue->next_cs_timestamp = elem->timestamp;
> +		/*
> +		 * Don't allow next_cs_timestamp to be less than the last one estimated by
> +		 * cs_etm_decoder__do_soft_timestamp() otherwise new instructions would
> +		 * appear to go back in time. In theory this should never happen, but if
> +		 * it did, then next_cs_timestamp should eventually catch up to real time
> +		 * unless every single range was predicted to be too long for some reason.
> +		 */
> +		packet_queue->next_cs_timestamp = max(elem->timestamp, packet_queue->next_cs_timestamp);
>  		return OCSD_RESP_CONT;
>  	}
> 
> -
>  	if (!elem->timestamp) {
>  		/*
>  		 * Zero timestamps can be seen due to misconfiguration or hardware bugs.
> @@ -312,7 +331,7 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
>  					". Decoding may be improved by prepending 'Z' to your current --itrace
> arguments.\n",
>  					indx);
> 
> -	} else if (packet_queue->instr_count > elem->timestamp) {
> +	} else if (cs_etm_decoder__instr_count_to_ns(packet_queue->instr_count) > elem->timestamp) {
>  		/*
>  		 * Sanity check that the elem->timestamp - packet_queue->instr_count would not
>  		 * result in an underflow. Warn and clamp at 0 if it would.
> @@ -327,7 +346,8 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
>  		 * which instructions started by subtracting the number of instructions
>  		 * executed to the timestamp.
>  		 */
> -		packet_queue->cs_timestamp = elem->timestamp - packet_queue->instr_count;
> +		packet_queue->cs_timestamp = elem->timestamp -
> +			cs_etm_decoder__instr_count_to_ns(packet_queue->instr_count);
>  	}
>  	packet_queue->next_cs_timestamp = elem->timestamp;
>  	packet_queue->instr_count = 0;
I have tested this diff along with the patchset and found that
timestamps are generated/estimated in an increasing order.

However, found few corner cases where they weren't in order.
I'm currently gathering more information on these corner cases.

Used the following steps to find inconsistencies:
$ perf record -e cs_etm/@tmc_etr0/k -C 4 taskset -c 4 sleep 1
$ perf script --itrace=i1ns --ns -Fcomm,tid,pid,time,cpu,event,ip,sym,addr,symoff,flags,callindent > itrace
$ sed 's/://g' itrace | awk -F '.' ' { print $2 } ' | awk '{ if ($1 < prev) { print "line:" NR " " $0 } {prev=$1}}'

Setting INSTR_PER_NS to higher values (14,16,20 etc) results in
lower inconsistencies but it would defeat the purpose of
estimating values in software since we could be returning 0
from __instr_count_to_ns() in many cases.

Please share your thoughts.

Thanks,
Tanmay

Re: [PATCH v3 0/7] perf cs_etm: Basic support for virtual/kernel timestamps

[James Clark]

On 12/01/2023 15:33, Tanmay Jagdale wrote:
> Hi James
> 
>>>>> base-commit: 09e6f9f98370be9a9f8978139e0eb1be87d1125f
>>>> I have tested this patch set on our platform and able to see updated
>>>> timestamp values in perf script's output.
>>>>
>>>> $ perf record -e cs_etm/cycacc,@tmc_etr0/k -C 9 taskset -c 9 sleep 2
>>>> $ perf script --itrace=i1ns --ns -Fcomm,tid,pid,time,cpu,event,ip,sym,addr,symoff,flags,callindent
>>>>
>>>> At certain points noticed that hardware emits same timestamp packets
>>>> but with updated cycle count (CC) values. A small snippet of the log:
>>>>
>>>> Idx:100; ID:12; I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFF8000086A761C ~[0x761C]
>>>> Idx:103; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x3d
>>>> Idx:107; ID:12; I_ATOM_F2 : Atom format 2.; EN
>>>> Idx:108; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x3f
>>>> Idx:112; ID:12; I_ATOM_F1 : Atom format 1.; N
>>>> Idx:113; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x45
>>>> Idx:116; ID:12; I_ATOM_F1 : Atom format 1.; E
>>>> Idx:117; ID:12; I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFF8000086B52D4 ~[0x152D4]
>>>>
>>>> Since the source of timestamp is the Generic Timer block and the CPUs
>>>> run at higher frequencies, this behaviour could be possible on high
>>>> performance ARM cores.
>>>>
>>>> Having consecutive timestamps with same value is resulting in a
>>>> slightly jumbled order (in nanosecs) in perf script's time column.
>>>> A snippet corresponding to the Coresight trace data mentioned above:
>>>> ...
>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   return                               0 ffff8000086a761c coresight_timeout+0xc8
>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   return                               0 ffff8000086a7620 coresight_timeout+0xcc
>>>> perf   965/965   [001]  3182.286629046:            instructions:k:   jmp                                  0 ffff8000086a75c8 coresight_timeout+0x74
>>>> perf   965/965   [001]  3182.286629046:            instructions:k:   jmp                                  0 ffff8000086a75cc coresight_timeout+0x78
>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75d0 coresight_timeout+0x7c
>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75d4 coresight_timeout+0x80
>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75d8 coresight_timeout+0x84
>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75dc coresight_timeout+0x88
>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75e0 coresight_timeout+0x8c
>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75e4 coresight_timeout+0x90
>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75e8 coresight_timeout+0x94
>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75ec coresight_timeout+0x98
>>>>
>>>> Perf's do_soft_timestamp() logic in cs_etm_decoder.c file is incrementing
>>>> the HW timestamp based on instruction count. Since the next timestamp
>>>> also has the same value, it could be leading to this jumbled order.
>>>>
>>>> We would like to know if this has been observed on other platforms ?
>>>> And what could be a solution in SW for this ?
>>>
>>> Nice catch. If I'm understanding this correctly it looks like the issue
>>> is a combination of the cycle count in the packet being ignored by Perf,
>>> and the instruction count being reset to 0 when a new timestamp is received.
>>>
>>> It looks like it can be fixed by some combination of combining the cycle
>>> count and instruction count and maybe not resetting instruction count if
>>> the newly received timestamp is the same as the last one. I will look
>>> into this.
>>>
>>> We haven't noticed it on any other platforms, but we haven't been
>>> looking too closely at the timestamps until now. Perhaps I can add a
>>> test that checks if the trace in a known function goes in the correct
>>> time order.
>>>
>>
>> I'm thinking of something like the following patch to fix the ordering.
>> It doesn't use the cycle count, but I'm not sure if that would be
>> worthwhile in the end, considering that it would have sub nanosecond
>> resolution so wouldn't affect the Perf timestamps:
> Thanks for coming up with a quick solution for this issue !
> 
>>
>>
>> diff --git a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
>> index 31fa3b45134a..08a028e3e87a 100644
>> --- a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
>> +++ b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
>> @@ -112,6 +112,19 @@ int cs_etm_decoder__get_packet(struct cs_etm_packet_queue *packet_queue,
>>  	return 1;
>>  }
>>
>> +static u64 cs_etm_decoder__instr_count_to_ns(u64 instr_count)
>> +{
>> +	/*
>> +	 * Assume a maximum of 0.1ns elapsed per instruction. This would be the
>> +	 * case with a theoretical 10GHz core executing 1 instruction per cycle.
>> +	 * Used to estimate the sample time for synthesized instructions because
>> +	 * Coresight only emits a timestamp for a range of instructions rather
>> +	 * than per instruction.
>> +	 */
>> +	const int INSTR_PER_NS = 10;
>> +
>> +	return instr_count / INSTR_PER_NS;
>> +}
>>  static int cs_etm_decoder__gen_etmv3_config(struct cs_etm_trace_params *params,
>>  					    ocsd_etmv3_cfg *config)
>>  {
>> @@ -267,7 +280,7 @@ cs_etm_decoder__do_soft_timestamp(struct cs_etm_queue *etmq,
>>  	packet_queue->cs_timestamp = packet_queue->next_cs_timestamp;
>>
>>  	/* Estimate the timestamp for the next range packet */
>> -	packet_queue->next_cs_timestamp += packet_queue->instr_count;
>> +	packet_queue->next_cs_timestamp += cs_etm_decoder__instr_count_to_ns(packet_queue->instr_count);
>>  	packet_queue->instr_count = 0;
>>
>>  	/* Tell the front end which traceid_queue needs attention */
>> @@ -295,11 +308,17 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
>>  	 * hence asking the decoder to keep decoding rather than stopping.
>>  	 */
>>  	if (packet_queue->cs_timestamp) {
>> -		packet_queue->next_cs_timestamp = elem->timestamp;
>> +		/*
>> +		 * Don't allow next_cs_timestamp to be less than the last one estimated by
>> +		 * cs_etm_decoder__do_soft_timestamp() otherwise new instructions would
>> +		 * appear to go back in time. In theory this should never happen, but if
>> +		 * it did, then next_cs_timestamp should eventually catch up to real time
>> +		 * unless every single range was predicted to be too long for some reason.
>> +		 */
>> +		packet_queue->next_cs_timestamp = max(elem->timestamp, packet_queue->next_cs_timestamp);
>>  		return OCSD_RESP_CONT;
>>  	}
>>
>> -
>>  	if (!elem->timestamp) {
>>  		/*
>>  		 * Zero timestamps can be seen due to misconfiguration or hardware bugs.
>> @@ -312,7 +331,7 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
>>  					". Decoding may be improved by prepending 'Z' to your current --itrace
>> arguments.\n",
>>  					indx);
>>
>> -	} else if (packet_queue->instr_count > elem->timestamp) {
>> +	} else if (cs_etm_decoder__instr_count_to_ns(packet_queue->instr_count) > elem->timestamp) {
>>  		/*
>>  		 * Sanity check that the elem->timestamp - packet_queue->instr_count would not
>>  		 * result in an underflow. Warn and clamp at 0 if it would.
>> @@ -327,7 +346,8 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
>>  		 * which instructions started by subtracting the number of instructions
>>  		 * executed to the timestamp.
>>  		 */
>> -		packet_queue->cs_timestamp = elem->timestamp - packet_queue->instr_count;
>> +		packet_queue->cs_timestamp = elem->timestamp -
>> +			cs_etm_decoder__instr_count_to_ns(packet_queue->instr_count);
>>  	}
>>  	packet_queue->next_cs_timestamp = elem->timestamp;
>>  	packet_queue->instr_count = 0;
> I have tested this diff along with the patchset and found that
> timestamps are generated/estimated in an increasing order.
> 
> However, found few corner cases where they weren't in order.
> I'm currently gathering more information on these corner cases.
> 
> Used the following steps to find inconsistencies:
> $ perf record -e cs_etm/@tmc_etr0/k -C 4 taskset -c 4 sleep 1
> $ perf script --itrace=i1ns --ns -Fcomm,tid,pid,time,cpu,event,ip,sym,addr,symoff,flags,callindent > itrace
> $ sed 's/://g' itrace | awk -F '.' ' { print $2 } ' | awk '{ if ($1 < prev) { print "line:" NR " " $0 } {prev=$1}}'
> 
> Setting INSTR_PER_NS to higher values (14,16,20 etc) results in
> lower inconsistencies but it would defeat the purpose of
> estimating values in software since we could be returning 0
> from __instr_count_to_ns() in many cases.
> 
> Please share your thoughts.

I believe this could be because I was adding nanosecond values
to the raw coresight counter before it was converted which was
a mistake. I have made another change to move the conversion
as early as possible to avoid mistakes like this.

Increasing the INSTR_PER_NS shouldn't be required because of
the max() call, in fact INSTR_PER_NS isn't necessarily
needed at all, I just thought it would make it more accurate.

I'll test the new version on the file that you sent before
pasting it here. If you have another recording that has more
of the edge cases then please also upload that one too.

James

Re: [PATCH v3 0/7] perf cs_etm: Basic support for virtual/kernel timestamps

[James Clark]

On 13/01/2023 11:12, James Clark wrote:
> 
> 
> On 12/01/2023 15:33, Tanmay Jagdale wrote:
>> Hi James
>>
>>>>>> base-commit: 09e6f9f98370be9a9f8978139e0eb1be87d1125f
>>>>> I have tested this patch set on our platform and able to see updated
>>>>> timestamp values in perf script's output.
>>>>>
>>>>> $ perf record -e cs_etm/cycacc,@tmc_etr0/k -C 9 taskset -c 9 sleep 2
>>>>> $ perf script --itrace=i1ns --ns -Fcomm,tid,pid,time,cpu,event,ip,sym,addr,symoff,flags,callindent
>>>>>
>>>>> At certain points noticed that hardware emits same timestamp packets
>>>>> but with updated cycle count (CC) values. A small snippet of the log:
>>>>>
>>>>> Idx:100; ID:12; I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFF8000086A761C ~[0x761C]
>>>>> Idx:103; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x3d
>>>>> Idx:107; ID:12; I_ATOM_F2 : Atom format 2.; EN
>>>>> Idx:108; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x3f
>>>>> Idx:112; ID:12; I_ATOM_F1 : Atom format 1.; N
>>>>> Idx:113; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x45
>>>>> Idx:116; ID:12; I_ATOM_F1 : Atom format 1.; E
>>>>> Idx:117; ID:12; I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFF8000086B52D4 ~[0x152D4]
>>>>>
>>>>> Since the source of timestamp is the Generic Timer block and the CPUs
>>>>> run at higher frequencies, this behaviour could be possible on high
>>>>> performance ARM cores.
>>>>>
>>>>> Having consecutive timestamps with same value is resulting in a
>>>>> slightly jumbled order (in nanosecs) in perf script's time column.
>>>>> A snippet corresponding to the Coresight trace data mentioned above:
>>>>> ...
>>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   return                               0 ffff8000086a761c coresight_timeout+0xc8
>>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   return                               0 ffff8000086a7620 coresight_timeout+0xcc
>>>>> perf   965/965   [001]  3182.286629046:            instructions:k:   jmp                                  0 ffff8000086a75c8 coresight_timeout+0x74
>>>>> perf   965/965   [001]  3182.286629046:            instructions:k:   jmp                                  0 ffff8000086a75cc coresight_timeout+0x78
>>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75d0 coresight_timeout+0x7c
>>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75d4 coresight_timeout+0x80
>>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75d8 coresight_timeout+0x84
>>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75dc coresight_timeout+0x88
>>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75e0 coresight_timeout+0x8c
>>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75e4 coresight_timeout+0x90
>>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75e8 coresight_timeout+0x94
>>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0 ffff8000086a75ec coresight_timeout+0x98
>>>>>
>>>>> Perf's do_soft_timestamp() logic in cs_etm_decoder.c file is incrementing
>>>>> the HW timestamp based on instruction count. Since the next timestamp
>>>>> also has the same value, it could be leading to this jumbled order.
>>>>>
>>>>> We would like to know if this has been observed on other platforms ?
>>>>> And what could be a solution in SW for this ?
>>>>
>>>> Nice catch. If I'm understanding this correctly it looks like the issue
>>>> is a combination of the cycle count in the packet being ignored by Perf,
>>>> and the instruction count being reset to 0 when a new timestamp is received.
>>>>
>>>> It looks like it can be fixed by some combination of combining the cycle
>>>> count and instruction count and maybe not resetting instruction count if
>>>> the newly received timestamp is the same as the last one. I will look
>>>> into this.
>>>>
>>>> We haven't noticed it on any other platforms, but we haven't been
>>>> looking too closely at the timestamps until now. Perhaps I can add a
>>>> test that checks if the trace in a known function goes in the correct
>>>> time order.
>>>>
>>>
>>> I'm thinking of something like the following patch to fix the ordering.
>>> It doesn't use the cycle count, but I'm not sure if that would be
>>> worthwhile in the end, considering that it would have sub nanosecond
>>> resolution so wouldn't affect the Perf timestamps:
>> Thanks for coming up with a quick solution for this issue !
>>
>>>
>>>
>>> diff --git a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
>>> index 31fa3b45134a..08a028e3e87a 100644
>>> --- a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
>>> +++ b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
>>> @@ -112,6 +112,19 @@ int cs_etm_decoder__get_packet(struct cs_etm_packet_queue *packet_queue,
>>>  	return 1;
>>>  }
>>>
>>> +static u64 cs_etm_decoder__instr_count_to_ns(u64 instr_count)
>>> +{
>>> +	/*
>>> +	 * Assume a maximum of 0.1ns elapsed per instruction. This would be the
>>> +	 * case with a theoretical 10GHz core executing 1 instruction per cycle.
>>> +	 * Used to estimate the sample time for synthesized instructions because
>>> +	 * Coresight only emits a timestamp for a range of instructions rather
>>> +	 * than per instruction.
>>> +	 */
>>> +	const int INSTR_PER_NS = 10;
>>> +
>>> +	return instr_count / INSTR_PER_NS;
>>> +}
>>>  static int cs_etm_decoder__gen_etmv3_config(struct cs_etm_trace_params *params,
>>>  					    ocsd_etmv3_cfg *config)
>>>  {
>>> @@ -267,7 +280,7 @@ cs_etm_decoder__do_soft_timestamp(struct cs_etm_queue *etmq,
>>>  	packet_queue->cs_timestamp = packet_queue->next_cs_timestamp;
>>>
>>>  	/* Estimate the timestamp for the next range packet */
>>> -	packet_queue->next_cs_timestamp += packet_queue->instr_count;
>>> +	packet_queue->next_cs_timestamp += cs_etm_decoder__instr_count_to_ns(packet_queue->instr_count);
>>>  	packet_queue->instr_count = 0;
>>>
>>>  	/* Tell the front end which traceid_queue needs attention */
>>> @@ -295,11 +308,17 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
>>>  	 * hence asking the decoder to keep decoding rather than stopping.
>>>  	 */
>>>  	if (packet_queue->cs_timestamp) {
>>> -		packet_queue->next_cs_timestamp = elem->timestamp;
>>> +		/*
>>> +		 * Don't allow next_cs_timestamp to be less than the last one estimated by
>>> +		 * cs_etm_decoder__do_soft_timestamp() otherwise new instructions would
>>> +		 * appear to go back in time. In theory this should never happen, but if
>>> +		 * it did, then next_cs_timestamp should eventually catch up to real time
>>> +		 * unless every single range was predicted to be too long for some reason.
>>> +		 */
>>> +		packet_queue->next_cs_timestamp = max(elem->timestamp, packet_queue->next_cs_timestamp);
>>>  		return OCSD_RESP_CONT;
>>>  	}
>>>
>>> -
>>>  	if (!elem->timestamp) {
>>>  		/*
>>>  		 * Zero timestamps can be seen due to misconfiguration or hardware bugs.
>>> @@ -312,7 +331,7 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
>>>  					". Decoding may be improved by prepending 'Z' to your current --itrace
>>> arguments.\n",
>>>  					indx);
>>>
>>> -	} else if (packet_queue->instr_count > elem->timestamp) {
>>> +	} else if (cs_etm_decoder__instr_count_to_ns(packet_queue->instr_count) > elem->timestamp) {
>>>  		/*
>>>  		 * Sanity check that the elem->timestamp - packet_queue->instr_count would not
>>>  		 * result in an underflow. Warn and clamp at 0 if it would.
>>> @@ -327,7 +346,8 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
>>>  		 * which instructions started by subtracting the number of instructions
>>>  		 * executed to the timestamp.
>>>  		 */
>>> -		packet_queue->cs_timestamp = elem->timestamp - packet_queue->instr_count;
>>> +		packet_queue->cs_timestamp = elem->timestamp -
>>> +			cs_etm_decoder__instr_count_to_ns(packet_queue->instr_count);
>>>  	}
>>>  	packet_queue->next_cs_timestamp = elem->timestamp;
>>>  	packet_queue->instr_count = 0;
>> I have tested this diff along with the patchset and found that
>> timestamps are generated/estimated in an increasing order.
>>
>> However, found few corner cases where they weren't in order.
>> I'm currently gathering more information on these corner cases.
>>
>> Used the following steps to find inconsistencies:
>> $ perf record -e cs_etm/@tmc_etr0/k -C 4 taskset -c 4 sleep 1
>> $ perf script --itrace=i1ns --ns -Fcomm,tid,pid,time,cpu,event,ip,sym,addr,symoff,flags,callindent > itrace
>> $ sed 's/://g' itrace | awk -F '.' ' { print $2 } ' | awk '{ if ($1 < prev) { print "line:" NR " " $0 } {prev=$1}}'
>>
>> Setting INSTR_PER_NS to higher values (14,16,20 etc) results in
>> lower inconsistencies but it would defeat the purpose of
>> estimating values in software since we could be returning 0
>> from __instr_count_to_ns() in many cases.
>>
>> Please share your thoughts.
> 
> I believe this could be because I was adding nanosecond values
> to the raw coresight counter before it was converted which was
> a mistake. I have made another change to move the conversion
> as early as possible to avoid mistakes like this.
> 
> Increasing the INSTR_PER_NS shouldn't be required because of
> the max() call, in fact INSTR_PER_NS isn't necessarily
> needed at all, I just thought it would make it more accurate.
> 
> I'll test the new version on the file that you sent before
> pasting it here. If you have another recording that has more
> of the edge cases then please also upload that one too.

Hi Tanmay,

I've sent v4 and I don't see any issues now with the files that you
sent. There were a couple of different edge cases that I listed in the
last commit message. Let me know if you find any more, otherwise if you
leave your review or tested-by tag that would be great.

Thanks
James

Re: [PATCH v3 0/7] perf cs_etm: Basic support for virtual/kernel timestamps

[Tanmay Jagdale]

Hi James,

> On 13/01/2023 11:12, James Clark wrote:
> > On 12/01/2023 15:33, Tanmay Jagdale wrote:
> >> Hi James
> >>
> >>>>>> base-commit: 09e6f9f98370be9a9f8978139e0eb1be87d1125f
> >>>>> I have tested this patch set on our platform and able to see updated
> >>>>> timestamp values in perf script's output.
> >>>>>
> >>>>> $ perf record -e cs_etm/cycacc,@tmc_etr0/k -C 9 taskset -c 9 sleep 2
> >>>>> $ perf script --itrace=i1ns --ns -Fcomm,tid,pid,time,cpu,event,ip,sym,addr,symoff,flags,callindent
> >>>>>
> >>>>> At certain points noticed that hardware emits same timestamp packets
> >>>>> but with updated cycle count (CC) values. A small snippet of the log:
> >>>>>
> >>>>> Idx:100; ID:12; I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFF8000086A761C ~[0x761C]
> >>>>> Idx:103; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x3d
> >>>>> Idx:107; ID:12; I_ATOM_F2 : Atom format 2.; EN
> >>>>> Idx:108; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x3f
> >>>>> Idx:112; ID:12; I_ATOM_F1 : Atom format 1.; N
> >>>>> Idx:113; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x45
> >>>>> Idx:116; ID:12; I_ATOM_F1 : Atom format 1.; E
> >>>>> Idx:117; ID:12; I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFF8000086B52D4 ~[0x152D4]
> >>>>>
> >>>>> Since the source of timestamp is the Generic Timer block and the CPUs
> >>>>> run at higher frequencies, this behaviour could be possible on high
> >>>>> performance ARM cores.
> >>>>>
> >>>>> Having consecutive timestamps with same value is resulting in a
> >>>>> slightly jumbled order (in nanosecs) in perf script's time column.
> >>>>> A snippet corresponding to the Coresight trace data mentioned above:
> >>>>> ...
> >>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   return                               0
> ffff8000086a761c coresight_timeout+0xc8
> >>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   return                               0
> ffff8000086a7620 coresight_timeout+0xcc
> >>>>> perf   965/965   [001]  3182.286629046:            instructions:k:   jmp                                  0
> ffff8000086a75c8 coresight_timeout+0x74
> >>>>> perf   965/965   [001]  3182.286629046:            instructions:k:   jmp                                  0
> ffff8000086a75cc coresight_timeout+0x78
> >>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0
> ffff8000086a75d0 coresight_timeout+0x7c
> >>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0
> ffff8000086a75d4 coresight_timeout+0x80
> >>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0
> ffff8000086a75d8 coresight_timeout+0x84
> >>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0
> ffff8000086a75dc coresight_timeout+0x88
> >>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0
> ffff8000086a75e0 coresight_timeout+0x8c
> >>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0
> ffff8000086a75e4 coresight_timeout+0x90
> >>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0
> ffff8000086a75e8 coresight_timeout+0x94
> >>>>> perf   965/965   [001]  3182.286629044:            instructions:k:   jcc                                  0
> ffff8000086a75ec coresight_timeout+0x98
> >>>>>
> >>>>> Perf's do_soft_timestamp() logic in cs_etm_decoder.c file is incrementing
> >>>>> the HW timestamp based on instruction count. Since the next timestamp
> >>>>> also has the same value, it could be leading to this jumbled order.
> >>>>>
> >>>>> We would like to know if this has been observed on other platforms ?
> >>>>> And what could be a solution in SW for this ?
> >>>>
> >>>> Nice catch. If I'm understanding this correctly it looks like the issue
> >>>> is a combination of the cycle count in the packet being ignored by Perf,
> >>>> and the instruction count being reset to 0 when a new timestamp is received.
> >>>>
> >>>> It looks like it can be fixed by some combination of combining the cycle
> >>>> count and instruction count and maybe not resetting instruction count if
> >>>> the newly received timestamp is the same as the last one. I will look
> >>>> into this.
> >>>>
> >>>> We haven't noticed it on any other platforms, but we haven't been
> >>>> looking too closely at the timestamps until now. Perhaps I can add a
> >>>> test that checks if the trace in a known function goes in the correct
> >>>> time order.
> >>>>
> >>>
> >>> I'm thinking of something like the following patch to fix the ordering.
> >>> It doesn't use the cycle count, but I'm not sure if that would be
> >>> worthwhile in the end, considering that it would have sub nanosecond
> >>> resolution so wouldn't affect the Perf timestamps:
> >> Thanks for coming up with a quick solution for this issue !
> >>
> >>>
> >>>
> >>> diff --git a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
> >>> index 31fa3b45134a..08a028e3e87a 100644
> >>> --- a/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
> >>> +++ b/tools/perf/util/cs-etm-decoder/cs-etm-decoder.c
> >>> @@ -112,6 +112,19 @@ int cs_etm_decoder__get_packet(struct cs_etm_packet_queue *packet_queue,
> >>>  	return 1;
> >>>  }
> >>>
> >>> +static u64 cs_etm_decoder__instr_count_to_ns(u64 instr_count)
> >>> +{
> >>> +	/*
> >>> +	 * Assume a maximum of 0.1ns elapsed per instruction. This would be the
> >>> +	 * case with a theoretical 10GHz core executing 1 instruction per cycle.
> >>> +	 * Used to estimate the sample time for synthesized instructions because
> >>> +	 * Coresight only emits a timestamp for a range of instructions rather
> >>> +	 * than per instruction.
> >>> +	 */
> >>> +	const int INSTR_PER_NS = 10;
> >>> +
> >>> +	return instr_count / INSTR_PER_NS;
> >>> +}
> >>>  static int cs_etm_decoder__gen_etmv3_config(struct cs_etm_trace_params *params,
> >>>  					    ocsd_etmv3_cfg *config)
> >>>  {
> >>> @@ -267,7 +280,7 @@ cs_etm_decoder__do_soft_timestamp(struct cs_etm_queue *etmq,
> >>>  	packet_queue->cs_timestamp = packet_queue->next_cs_timestamp;
> >>>
> >>>  	/* Estimate the timestamp for the next range packet */
> >>> -	packet_queue->next_cs_timestamp += packet_queue->instr_count;
> >>> +	packet_queue->next_cs_timestamp += cs_etm_decoder__instr_count_to_ns(packet_queue->instr_count);
> >>>  	packet_queue->instr_count = 0;
> >>>
> >>>  	/* Tell the front end which traceid_queue needs attention */
> >>> @@ -295,11 +308,17 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
> >>>  	 * hence asking the decoder to keep decoding rather than stopping.
> >>>  	 */
> >>>  	if (packet_queue->cs_timestamp) {
> >>> -		packet_queue->next_cs_timestamp = elem->timestamp;
> >>> +		/*
> >>> +		 * Don't allow next_cs_timestamp to be less than the last one estimated by
> >>> +		 * cs_etm_decoder__do_soft_timestamp() otherwise new instructions would
> >>> +		 * appear to go back in time. In theory this should never happen, but if
> >>> +		 * it did, then next_cs_timestamp should eventually catch up to real time
> >>> +		 * unless every single range was predicted to be too long for some reason.
> >>> +		 */
> >>> +		packet_queue->next_cs_timestamp = max(elem->timestamp, packet_queue->next_cs_timestamp);
> >>>  		return OCSD_RESP_CONT;
> >>>  	}
> >>>
> >>> -
> >>>  	if (!elem->timestamp) {
> >>>  		/*
> >>>  		 * Zero timestamps can be seen due to misconfiguration or hardware bugs.
> >>> @@ -312,7 +331,7 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
> >>>  					". Decoding may be improved by prepending 'Z' to your current --itrace
> >>> arguments.\n",
> >>>  					indx);
> >>>
> >>> -	} else if (packet_queue->instr_count > elem->timestamp) {
> >>> +	} else if (cs_etm_decoder__instr_count_to_ns(packet_queue->instr_count) > elem->timestamp) {
> >>>  		/*
> >>>  		 * Sanity check that the elem->timestamp - packet_queue->instr_count would not
> >>>  		 * result in an underflow. Warn and clamp at 0 if it would.
> >>> @@ -327,7 +346,8 @@ cs_etm_decoder__do_hard_timestamp(struct cs_etm_queue *etmq,
> >>>  		 * which instructions started by subtracting the number of instructions
> >>>  		 * executed to the timestamp.
> >>>  		 */
> >>> -		packet_queue->cs_timestamp = elem->timestamp - packet_queue->instr_count;
> >>> +		packet_queue->cs_timestamp = elem->timestamp -
> >>> +			cs_etm_decoder__instr_count_to_ns(packet_queue->instr_count);
> >>>  	}
> >>>  	packet_queue->next_cs_timestamp = elem->timestamp;
> >>>  	packet_queue->instr_count = 0;
> >> I have tested this diff along with the patchset and found that
> >> timestamps are generated/estimated in an increasing order.
> >>
> >> However, found few corner cases where they weren't in order.
> >> I'm currently gathering more information on these corner cases.
> >>
> >> Used the following steps to find inconsistencies:
> >> $ perf record -e cs_etm/@tmc_etr0/k -C 4 taskset -c 4 sleep 1
> >> $ perf script --itrace=i1ns --ns -Fcomm,tid,pid,time,cpu,event,ip,sym,addr,symoff,flags,callindent > itrace
> >> $ sed 's/://g' itrace | awk -F '.' ' { print $2 } ' | awk '{ if ($1 < prev) { print "line:" NR " " $0 }
> {prev=$1}}'
> >>
> >> Setting INSTR_PER_NS to higher values (14,16,20 etc) results in
> >> lower inconsistencies but it would defeat the purpose of
> >> estimating values in software since we could be returning 0
> >> from __instr_count_to_ns() in many cases.
> >>
> >> Please share your thoughts.
> >
> > I believe this could be because I was adding nanosecond values
> > to the raw coresight counter before it was converted which was
> > a mistake. I have made another change to move the conversion
> > as early as possible to avoid mistakes like this.
> >
> > Increasing the INSTR_PER_NS shouldn't be required because of
> > the max() call, in fact INSTR_PER_NS isn't necessarily
> > needed at all, I just thought it would make it more accurate.
> >
> > I'll test the new version on the file that you sent before
> > pasting it here. If you have another recording that has more
> > of the edge cases then please also upload that one too.
> 
> Hi Tanmay,
> 
> I've sent v4 and I don't see any issues now with the files that you
> sent. There were a couple of different edge cases that I listed in the
> last commit message. Let me know if you find any more, otherwise if you
> leave your review or tested-by tag that would be great.
I have tested the latest v5 version on our platform with test
cases that run with and without filters for kernel/user space.
The timestamps look good on all of them.

Thanks for the effort !

Thanks and regards,
Tanmay
> 
> Thanks
> James

Re: [PATCH v3 0/7] perf cs_etm: Basic support for virtual/kernel timestamps

[Arnaldo Carvalho de Melo]

Em Fri, Jan 20, 2023 at 05:30:30PM +0000, Tanmay Jagdale escreveu:
> > On 13/01/2023 11:12, James Clark wrote:
> > > On 12/01/2023 15:33, Tanmay Jagdale wrote:
> > I've sent v4 and I don't see any issues now with the files that you
> > sent. There were a couple of different edge cases that I listed in the
> > last commit message. Let me know if you find any more, otherwise if you
> > leave your review or tested-by tag that would be great.
> I have tested the latest v5 version on our platform with test
> cases that run with and without filters for kernel/user space.
> The timestamps look good on all of them.
> 
> Thanks for the effort !

Can I take that as an:

Tested-by: Tanmay Jagdale <tanmay@marvell.com>

For all the patches in this v5 series?

- Arnaldo

Re: [PATCH v3 0/7] perf cs_etm: Basic support for virtual/kernel timestamps

[Tanmay Jagdale]

Hi Arnaldo,

> Em Fri, Jan 20, 2023 at 05:30:30PM +0000, Tanmay Jagdale escreveu:
> > > On 13/01/2023 11:12, James Clark wrote:
> > > > On 12/01/2023 15:33, Tanmay Jagdale wrote:
> > > I've sent v4 and I don't see any issues now with the files that you
> > > sent. There were a couple of different edge cases that I listed in the
> > > last commit message. Let me know if you find any more, otherwise if you
> > > leave your review or tested-by tag that would be great.
> > I have tested the latest v5 version on our platform with test
> > cases that run with and without filters for kernel/user space.
> > The timestamps look good on all of them.
> >
> > Thanks for the effort !
> 
> Can I take that as an:
> 
> Tested-by: Tanmay Jagdale <tanmay@marvell.com>
> 
> For all the patches in this v5 series?
Yes sure. I tested the patch series on our platform
and able to see the correct timestamps.

Thanks,
Tanmay
> 
> - Arnaldo

Re: [PATCH v3 0/7] perf cs_etm: Basic support for virtual/kernel timestamps

[James Clark]

On 10/01/2023 16:42, Tanmay Jagdale wrote:
> Hi James,
> 
[...]

>> base-commit: 09e6f9f98370be9a9f8978139e0eb1be87d1125f
> I have tested this patch set on our platform and able to see updated
> timestamp values in perf script's output.
> 
> $ perf record -e cs_etm/cycacc,@tmc_etr0/k -C 9 taskset -c 9 sleep 2
> $ perf script --itrace=i1ns --ns -Fcomm,tid,pid,time,cpu,event,ip,sym,addr,symoff,flags,callindent
> 
> At certain points noticed that hardware emits same timestamp packets
> but with updated cycle count (CC) values. A small snippet of the log:
> 
> Idx:100; ID:12; I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFF8000086A761C ~[0x761C]
> Idx:103; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x3d
> Idx:107; ID:12; I_ATOM_F2 : Atom format 2.; EN
> Idx:108; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x3f
> Idx:112; ID:12; I_ATOM_F1 : Atom format 1.; N
> Idx:113; ID:12; I_TIMESTAMP : Timestamp.; Updated val = 0x2f373e37e02; CC=0x45
> Idx:116; ID:12; I_ATOM_F1 : Atom format 1.; E
> Idx:117; ID:12; I_ADDR_S_IS0 : Address, Short, IS0.; Addr=0xFFFF8000086B52D4 ~[0x152D4]

Hi Tanmay,

Are you able to email or send a download link with the perf archive and
perf.data file of this recording please?

Thanks
James