Skip to contentSkip to conversation

tracing: Last minute updates for 5.14

PATCH In review Steven Rostedt 2 participants 26 messages Jun 26, 2021 – Jul 20, 2021

Subsystems (9)
lore
Share & tools
lore

Steven Rostedt

author maintainer
#0 lore raw

cover tracing: Last minute updates for 5.14

Changes for 5.14.

git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
for-next

Head SHA1: 1f1b9e5899a2c96b354cac917f532c1917990ab6

Daniel Bristot de Oliveira (12):
trace/hwlat: Fix Clark's email
trace/hwlat: Implement the mode config option trace/hwlat: Switch disable_migrate to mode none trace/hwlat: Implement the per-cpu mode
trace: Add a generic function to read/write u64 values from tracefs trace/hwlat: Use trace_min_max_param for width and window params trace/hwlat: Remove printk from sampling loop
trace: Add osnoise tracer
trace: Add timerlat tracer
trace/hwlat: Protect kdata->kthread with get/put_online_cpus trace/hwlat: Support hotplug operations
trace/osnoise: Support hotplug operations

Masami Hiramatsu (5):
bootconfig: Change array value to use child node
bootconfig: Support mixing a value and subkeys under a key tools/bootconfig: Support mixed value and subkey test cases
docs: bootconfig: Update for mixing value and subkeys
bootconfig: Share the checksum function with tools

Steven Rostedt (1):
trace: Add __print_ns_to_secs() and __print_ns_without_secs() helpers

Steven Rostedt (VMware) (7):
tracing: Simplify the max length test when using the filtering temp buffer
tracing: Add better comments for the filtering temp buffer use case
tracing: Add tp_printk_stop_on_boot option
tracing: Have ftrace_dump_on_oops kernel parameter take numbers bootconfig/tracing/ktest: Add ktest examples of testing bootconfig
tracing: Add LATENCY_FS_NOTIFY to define if latency_fsnotify() is defined Merge branch 'trace/ftrace/core' into trace/for-next

----

 Documentation/admin-guide/bootconfig.rst           |   30 +-
 Documentation/admin-guide/kernel-parameters.txt    |   13 +
 Documentation/trace/hwlat_detector.rst             |   13 +-
 Documentation/trace/index.rst                      |    2 +
 Documentation/trace/osnoise-tracer.rst             |  152 ++
 Documentation/trace/timerlat-tracer.rst            |  181 ++
 arch/x86/kernel/Makefile                           |    1 +
 arch/x86/kernel/trace.c                            |  237 +++
 fs/proc/bootconfig.c                               |    2 +-
 include/linux/bootconfig.h                         |   58 +-
 include/linux/ftrace_irq.h                         |   13 +
 include/linux/trace.h                              |    5 +
 include/trace/events/osnoise.h                     |  142 ++
 include/trace/trace_events.h                       |   25 +
 init/main.c                                        |   12 +-
 kernel/trace/Kconfig                               |   62 +
 kernel/trace/Makefile                              |    1 +
 kernel/trace/trace.c                               |  172 +-
 kernel/trace/trace.h                               |   35 +-
 kernel/trace/trace_entries.h                       |   41 +
 kernel/trace/trace_hwlat.c                         |  534 +++--
 kernel/trace/trace_osnoise.c                       | 2053 ++++++++++++++++++++
 kernel/trace/trace_output.c                        |  119 +-
 lib/bootconfig.c                                   |   76 +-
 tools/bootconfig/main.c                            |   62 +-
 tools/bootconfig/samples/bad-override.bconf        |    3 -
 tools/bootconfig/samples/bad-override2.bconf       |    3 -
 tools/bootconfig/samples/good-mixed-append.bconf   |    4 +
 .../{bad-mixed-kv1.bconf => good-mixed-kv1.bconf}  |    0
 .../{bad-mixed-kv2.bconf => good-mixed-kv2.bconf}  |    0
 tools/bootconfig/samples/good-mixed-kv3.bconf      |    6 +
 tools/bootconfig/samples/good-mixed-override.bconf |    4 +
 .../ktest/examples/bootconfigs/boottrace.bconf     |   49 +
 .../ktest/examples/bootconfigs/config-bootconfig   |    1 +
 .../ktest/examples/bootconfigs/functiongraph.bconf |   15 +
 .../ktest/examples/bootconfigs/tracing.bconf       |   33 +
 .../ktest/examples/bootconfigs/verify-boottrace.sh |   84 +
 .../examples/bootconfigs/verify-functiongraph.sh   |   61 +
 .../ktest/examples/bootconfigs/verify-tracing.sh   |   72 +
 .../testing/ktest/examples/include/bootconfig.conf |   69 +
 tools/testing/ktest/examples/kvm.conf              |    1 +
 41 files changed, 4211 insertions(+), 235 deletions(-)
 create mode 100644 Documentation/trace/osnoise-tracer.rst
 create mode 100644 Documentation/trace/timerlat-tracer.rst
 create mode 100644 arch/x86/kernel/trace.c
 create mode 100644 include/trace/events/osnoise.h
 create mode 100644 kernel/trace/trace_osnoise.c
 delete mode 100644 tools/bootconfig/samples/bad-override.bconf
 delete mode 100644 tools/bootconfig/samples/bad-override2.bconf
 create mode 100644 tools/bootconfig/samples/good-mixed-append.bconf
 rename tools/bootconfig/samples/{bad-mixed-kv1.bconf => good-mixed-kv1.bconf} (100%)
 rename tools/bootconfig/samples/{bad-mixed-kv2.bconf => good-mixed-kv2.bconf} (100%)
 create mode 100644 tools/bootconfig/samples/good-mixed-kv3.bconf
 create mode 100644 tools/bootconfig/samples/good-mixed-override.bconf
 create mode 100644 tools/testing/ktest/examples/bootconfigs/boottrace.bconf
 create mode 100644 tools/testing/ktest/examples/bootconfigs/config-bootconfig
 create mode 100644 tools/testing/ktest/examples/bootconfigs/functiongraph.bconf
 create mode 100644 tools/testing/ktest/examples/bootconfigs/tracing.bconf
 create mode 100755 tools/testing/ktest/examples/bootconfigs/verify-boottrace.sh
 create mode 100755 tools/testing/ktest/examples/bootconfigs/verify-functiongraph.sh
 create mode 100755 tools/testing/ktest/examples/bootconfigs/verify-tracing.sh
 create mode 100644 tools/testing/ktest/examples/include/bootconfig.conf
author maintainer
#1 lore raw

PATCH 1/24 bootconfig: Change array value to use child node

From: Masami Hiramatsu <[email protected]>

It is not possible to put an array value with subkeys under a key node, because both of subkeys and the array elements are using "next" field of the xbc_node.

Thus this changes the array values to use "child" field in the array case. The reason why split this change is to test it easily.

---
 fs/proc/bootconfig.c       |  2 +-
 include/linux/bootconfig.h |  6 +++---
 lib/bootconfig.c           | 23 +++++++++++++++++++----
 tools/bootconfig/main.c    |  2 +-
 4 files changed, 24 insertions(+), 9 deletions(-)
fs/proc/bootconfig.c +1 -1
index ad31ec4ad627..6d8d4bf20837 100644
@@ -49,7 +49,7 @@ static int __init copy_xbc_key_value_list(char *dst, size_t size)
 				else
 					q = '"';
 				ret = snprintf(dst, rest(dst, end), "%c%s%c%s",
-					q, val, q, vnode->next ? ", " : "\n");
+					q, val, q, xbc_node_is_array(vnode) ? ", " : "\n");
 				if (ret < 0)
 					goto out;
 				dst += ret;
include/linux/bootconfig.h +3 -3
index 2696eb0fc149..3178a31fdabc 100644
@@ -71,7 +71,7 @@ static inline __init bool xbc_node_is_key(struct xbc_node *node)
  */
 static inline __init bool xbc_node_is_array(struct xbc_node *node)
 {
-	return xbc_node_is_value(node) && node->next != 0;
+	return xbc_node_is_value(node) && node->child != 0;
 }
 
 /**
@@ -140,7 +140,7 @@ static inline struct xbc_node * __init xbc_find_node(const char *key)
  */
 #define xbc_array_for_each_value(anode, value)				\
 	for (value = xbc_node_get_data(anode); anode != NULL ;		\
-	     anode = xbc_node_get_next(anode),				\
+	     anode = xbc_node_get_child(anode),				\
 	     value = anode ? xbc_node_get_data(anode) : NULL)
 
 /**
@@ -171,7 +171,7 @@ static inline struct xbc_node * __init xbc_find_node(const char *key)
  */
 #define xbc_node_for_each_array_value(node, key, anode, value)		\
 	for (value = xbc_node_find_value(node, key, &anode); value != NULL; \
-	     anode = xbc_node_get_next(anode),				\
+	     anode = xbc_node_get_child(anode),				\
 	     value = anode ? xbc_node_get_data(anode) : NULL)
 
 /**
lib/bootconfig.c +19 -4
index 9f8c70a98fcf..44dcdcbd746a 100644
@@ -367,6 +367,14 @@ static inline __init struct xbc_node *xbc_last_sibling(struct xbc_node *node)
 	return node;
 }
 
+static inline __init struct xbc_node *xbc_last_child(struct xbc_node *node)
+{
+	while (node->child)
+		node = xbc_node_get_child(node);
+
+	return node;
+}
+
 static struct xbc_node * __init xbc_add_sibling(char *data, u32 flag)
 {
 	struct xbc_node *sib, *node = xbc_add_node(data, flag);
@@ -517,17 +525,20 @@ static int __init xbc_parse_array(char **__v)
 	char *next;
 	int c = 0;
 
+	if (last_parent->child)
+		last_parent = xbc_node_get_child(last_parent);
+
 	do {
 		c = __xbc_parse_value(__v, &next);
 		if (c < 0)
 			return c;
 
-		node = xbc_add_sibling(*__v, XBC_VALUE);
+		node = xbc_add_child(*__v, XBC_VALUE);
 		if (!node)
 			return -ENOMEM;
 		*__v = next;
 	} while (c == ',');
-	node->next = 0;
+	node->child = 0;
 
 	return c;
 }
@@ -615,8 +626,12 @@ static int __init xbc_parse_kv(char **k, char *v, int op)
 
 	if (op == ':' && child) {
 		xbc_init_node(child, v, XBC_VALUE);
-	} else if (!xbc_add_sibling(v, XBC_VALUE))
-		return -ENOMEM;
+	} else {
+		if (op == '+' && child)
+			last_parent = xbc_last_child(child);
+		if (!xbc_add_sibling(v, XBC_VALUE))
+			return -ENOMEM;
+	}
 
 	if (c == ',') {	/* Array */
 		c = xbc_parse_array(&next);
tools/bootconfig/main.c +1 -1
index 268b72f4cc92..23569fb634f1 100644
@@ -27,7 +27,7 @@ static int xbc_show_value(struct xbc_node *node, bool semicolon)
 			q = '\'';
 		else
 			q = '"';
-		printf("%c%s%c%s", q, val, q, node->next ? ", " : eol);
+		printf("%c%s%c%s", q, val, q, xbc_node_is_array(node) ? ", " : eol);
 		i++;
 	}
 	return i;
Signature · 1 line
2.30.2
author maintainer
#2 lore raw

PATCH 2/24 bootconfig: Support mixing a value and subkeys under a key

In reply to Steven Rostedt

From: Masami Hiramatsu <[email protected]>

Support mixing a value and subkeys under a key. Since kernel cmdline options will support "aaa.bbb=value1 aaa.bbb.ccc=value2", it is better that the bootconfig supports such configuration too.

Note that this does not change syntax itself but just accepts mixed value and subkeys e.g.

key = value1
key.subkey = value2

But this is not accepted;

key {
value1
subkey = value2
}

That will make value1 as a subkey.

Also, the order of the value node under a key is fixed. If there are a value and subkeys, the value is always the first child node of the key. Thus if user specifies subkeys first, e.g.

key.subkey = value1
key = value2

In the program (and /proc/bootconfig), it will be shown as below

key = value2
key.subkey = value1

---
 include/linux/bootconfig.h | 32 +++++++++++++++++++
 lib/bootconfig.c           | 65 ++++++++++++++++++++++++++------------
 tools/bootconfig/main.c    | 45 +++++++++++++++++++++-----
 3 files changed, 114 insertions(+), 28 deletions(-)
include/linux/bootconfig.h +32 -0
index 3178a31fdabc..e49043ac77c9 100644
@@ -80,6 +80,8 @@ static inline __init bool xbc_node_is_array(struct xbc_node *node)
  *
  * Test the @node is a leaf key node which is a key node and has a value node
  * or no child. Returns true if it is a leaf node, or false if not.
+ * Note that the leaf node can have subkey nodes in addition to the
+ * value node.
  */
 static inline __init bool xbc_node_is_leaf(struct xbc_node *node)
 {
@@ -129,6 +131,23 @@ static inline struct xbc_node * __init xbc_find_node(const char *key)
 	return xbc_node_find_child(NULL, key);
 }
 
+/**
+ * xbc_node_get_subkey() - Return the first subkey node if exists
+ * @node: Parent node
+ *
+ * Return the first subkey node of the @node. If the @node has no child
+ * or only value node, this will return NULL.
+ */
+static inline struct xbc_node * __init xbc_node_get_subkey(struct xbc_node *node)
+{
+	struct xbc_node *child = xbc_node_get_child(node);
+
+	if (child && xbc_node_is_value(child))
+		return xbc_node_get_next(child);
+	else
+		return child;
+}
+
 /**
  * xbc_array_for_each_value() - Iterate value nodes on an array
  * @anode: An XBC arraied value node
@@ -149,11 +168,24 @@ static inline struct xbc_node * __init xbc_find_node(const char *key)
  * @child: Iterated XBC node.
  *
  * Iterate child nodes of @parent. Each child nodes are stored to @child.
+ * The @child can be mixture of a value node and subkey nodes.
  */
 #define xbc_node_for_each_child(parent, child)				\
 	for (child = xbc_node_get_child(parent); child != NULL ;	\
 	     child = xbc_node_get_next(child))
 
+/**
+ * xbc_node_for_each_subkey() - Iterate child subkey nodes
+ * @parent: An XBC node.
+ * @child: Iterated XBC node.
+ *
+ * Iterate subkey nodes of @parent. Each child nodes are stored to @child.
+ * The @child is only the subkey node.
+ */
+#define xbc_node_for_each_subkey(parent, child)				\
+	for (child = xbc_node_get_subkey(parent); child != NULL ;	\
+	     child = xbc_node_get_next(child))
+
 /**
  * xbc_node_for_each_array_value() - Iterate array entries of geven key
  * @node: An XBC node.
lib/bootconfig.c +45 -20

136 lines not on this page · raw message

tools/bootconfig/main.c +37 -8

85 lines not on this page · raw message

Signature · 1 line
2.30.2
author maintainer
#3 lore raw

PATCH 3/24 tools/bootconfig: Support mixed value and subkey test cases

In reply to Steven Rostedt

From: Masami Hiramatsu <[email protected]>

Update test case to support mixed value and subkey on a key.

---
 tools/bootconfig/samples/bad-override.bconf                 | 3 ---
 tools/bootconfig/samples/bad-override2.bconf                | 3 ---
 tools/bootconfig/samples/good-mixed-append.bconf            | 4 ++++
 .../samples/{bad-mixed-kv1.bconf => good-mixed-kv1.bconf}   | 0
 .../samples/{bad-mixed-kv2.bconf => good-mixed-kv2.bconf}   | 0
 tools/bootconfig/samples/good-mixed-kv3.bconf               | 6 ++++++
 tools/bootconfig/samples/good-mixed-override.bconf          | 4 ++++
 7 files changed, 14 insertions(+), 6 deletions(-)
 delete mode 100644 tools/bootconfig/samples/bad-override.bconf
 delete mode 100644 tools/bootconfig/samples/bad-override2.bconf
 create mode 100644 tools/bootconfig/samples/good-mixed-append.bconf
 rename tools/bootconfig/samples/{bad-mixed-kv1.bconf => good-mixed-kv1.bconf} (100%)
 rename tools/bootconfig/samples/{bad-mixed-kv2.bconf => good-mixed-kv2.bconf} (100%)
 create mode 100644 tools/bootconfig/samples/good-mixed-kv3.bconf
 create mode 100644 tools/bootconfig/samples/good-mixed-override.bconf
tools/bootconfig/samples/bad-override.bconf deleted +0 -3
deleted file mode 100644
index fde6c561512e..000000000000
@@ -1,3 +0,0 @@
-key.subkey = value
-# We can not override pre-defined subkeys with value
-key := value
tools/bootconfig/samples/bad-override2.bconf deleted +0 -3
deleted file mode 100644
index 688587cb023c..000000000000
@@ -1,3 +0,0 @@
-key = value
-# We can not override pre-defined value with subkey
-key.subkey := value
tools/bootconfig/samples/good-mixed-append.bconf new file +4 -0
new file mode 100644
index 000000000000..b99a089a05f5
@@ -0,0 +1,4 @@
+key = foo
+keyx.subkey = value
+key += bar
+
tools/bootconfig/samples/good-mixed-kv1.bconf renamed from tools/bootconfig/samples/bad-mixed-kv1.bconf +0 -0
similarity index 100%
rename from tools/bootconfig/samples/bad-mixed-kv1.bconf
rename to tools/bootconfig/samples/good-mixed-kv1.bconf
tools/bootconfig/samples/good-mixed-kv2.bconf renamed from tools/bootconfig/samples/bad-mixed-kv2.bconf +0 -0
similarity index 100%
rename from tools/bootconfig/samples/bad-mixed-kv2.bconf
rename to tools/bootconfig/samples/good-mixed-kv2.bconf
tools/bootconfig/samples/good-mixed-kv3.bconf new file +6 -0
new file mode 100644
index 000000000000..2ce2b02224b8
@@ -0,0 +1,6 @@
+# mixed key and subkeys with braces
+key = value
+key {
+	subkey1
+	subkey2 = foo
+}
tools/bootconfig/samples/good-mixed-override.bconf new file +4 -0
new file mode 100644
index 000000000000..18195b2873b6
@@ -0,0 +1,4 @@
+key.foo = bar
+key = value
+# mixed key value can be overridden
+key := value2
Signature · 1 line
2.30.2
author maintainer
#4 lore raw

PATCH 4/24 docs: bootconfig: Update for mixing value and subkeys

In reply to Steven Rostedt

From: Masami Hiramatsu <[email protected]>

Update document for the mixing value and subkeys on a key.

---
 Documentation/admin-guide/bootconfig.rst | 30 ++++++++++++++++++++----
 1 file changed, 26 insertions(+), 4 deletions(-)
Documentation/admin-guide/bootconfig.rst +26 -4
index 452b7dcd7f6b..6a79f2e59396 100644
@@ -89,13 +89,35 @@ you can use ``+=`` operator. For example::
 
 In this case, the key ``foo`` has ``bar``, ``baz`` and ``qux``.
 
-However, a sub-key and a value can not co-exist under a parent key.
-For example, following config is NOT allowed.::
+Moreover, sub-keys and a value can coexist under a parent key.
+For example, following config is allowed.::
 
  foo = value1
- foo.bar = value2 # !ERROR! subkey "bar" and value "value1" can NOT co-exist
- foo.bar := value2 # !ERROR! even with the override operator, this is NOT allowed.
+ foo.bar = value2
+ foo := value3 # This will update foo's value.
+
+Note, since there is no syntax to put a raw value directly under a
+structured key, you have to define it outside of the brace. For example::
+
+ foo {
+     bar = value1
+     bar {
+         baz = value2
+         qux = value3
+     }
+ }
+
+Also, the order of the value node under a key is fixed. If there
+are a value and subkeys, the value is always the first child node
+of the key. Thus if user specifies subkeys first, e.g.::
+
+ foo.bar = value1
+ foo = value2
+
+In the program (and /proc/bootconfig), it will be shown as below::
 
+ foo = value2
+ foo.bar = value1
 
 Comments
 --------
Signature · 1 line
2.30.2
author maintainer
#5 lore raw

PATCH 5/24 bootconfig: Share the checksum function with tools

In reply to Steven Rostedt

From: Masami Hiramatsu <[email protected]>

Move the checksum calculation function into the header for sharing it with tools/bootconfig.

---
 include/linux/bootconfig.h | 20 ++++++++++++++++++++
 init/main.c                | 12 +-----------
 tools/bootconfig/main.c    | 15 ++-------------
 3 files changed, 23 insertions(+), 24 deletions(-)
include/linux/bootconfig.h +20 -0
index e49043ac77c9..6bdd94cff4e2 100644
@@ -16,6 +16,26 @@
 #define BOOTCONFIG_ALIGN	(1 << BOOTCONFIG_ALIGN_SHIFT)
 #define BOOTCONFIG_ALIGN_MASK	(BOOTCONFIG_ALIGN - 1)
 
+/**
+ * xbc_calc_checksum() - Calculate checksum of bootconfig
+ * @data: Bootconfig data.
+ * @size: The size of the bootconfig data.
+ *
+ * Calculate the checksum value of the bootconfig data.
+ * The checksum will be used with the BOOTCONFIG_MAGIC and the size for
+ * embedding the bootconfig in the initrd image.
+ */
+static inline __init u32 xbc_calc_checksum(void *data, u32 size)
+{
+	unsigned char *p = data;
+	u32 ret = 0;
+
+	while (size--)
+		ret += *p++;
+
+	return ret;
+}
+
 /* XBC tree node */
 struct xbc_node {
 	u16 next;
init/main.c +1 -11
index e9c42a183e33..7b150f0501e2 100644
@@ -386,16 +386,6 @@ static char * __init xbc_make_cmdline(const char *key)
 	return new_cmdline;
 }
 
-static u32 boot_config_checksum(unsigned char *p, u32 size)
-{
-	u32 ret = 0;
-
-	while (size--)
-		ret += *p++;
-
-	return ret;
-}
-
 static int __init bootconfig_params(char *param, char *val,
 				    const char *unused, void *arg)
 {
@@ -439,7 +429,7 @@ static void __init setup_boot_config(void)
 		return;
 	}
 
-	if (boot_config_checksum((unsigned char *)data, size) != csum) {
+	if (xbc_calc_checksum(data, size) != csum) {
 		pr_err("bootconfig checksum failed\n");
 		return;
 	}
tools/bootconfig/main.c +2 -13
index 62a3b5064b17..f45fa992e01d 100644
@@ -126,17 +126,6 @@ static void xbc_show_list(void)
 	}
 }
 
-/* Simple real checksum */
-static int checksum(unsigned char *buf, int len)
-{
-	int i, sum = 0;
-
-	for (i = 0; i < len; i++)
-		sum += buf[i];
-
-	return sum;
-}
-
 #define PAGE_SIZE	4096
 
 static int load_xbc_fd(int fd, char **buf, int size)
@@ -232,7 +221,7 @@ static int load_xbc_from_initrd(int fd, char **buf)
 		return ret;
 
 	/* Wrong Checksum */
-	rcsum = checksum((unsigned char *)*buf, size);
+	rcsum = xbc_calc_checksum(*buf, size);
 	if (csum != rcsum) {
 		pr_err("checksum error: %d != %d\n", csum, rcsum);
 		return -EINVAL;
@@ -381,7 +370,7 @@ static int apply_xbc(const char *path, const char *xbc_path)
 		return ret;
 	}
 	size = strlen(buf) + 1;
-	csum = checksum((unsigned char *)buf, size);
+	csum = xbc_calc_checksum(buf, size);
 
 	/* Backup the bootconfig data */
 	data = calloc(size + BOOTCONFIG_ALIGN +
Signature · 1 line
2.30.2
author maintainer
#6 lore raw

PATCH 6/24 tracing: Simplify the max length test when using the filtering temp buffer

In reply to Steven Rostedt

From: "Steven Rostedt (VMware)" <[email protected]>

When filtering trace events, a temp buffer is used because the extra copy from the temp buffer into the ring buffer is still faster than the direct write into the ring buffer followed by a discard if the filter does not match.

But the data that can be stored in the temp buffer is a PAGE_SIZE minus the ring buffer event header. The calculation of that header size is complex, but using the helper macro "struct_size()" can simplify it.

---
 kernel/trace/trace.c | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)
kernel/trace/trace.c +3 -1
index 2e592885a167..a0a84ff46ecd 100644
@@ -2735,8 +2735,10 @@ trace_event_buffer_lock_reserve(struct trace_buffer **current_rb,
 	    (trace_file->flags & (EVENT_FILE_FL_SOFT_DISABLED | EVENT_FILE_FL_FILTERED)) &&
 	    (entry = this_cpu_read(trace_buffered_event))) {
 		/* Try to use the per cpu buffer first */
+		int max_len = PAGE_SIZE - struct_size(entry, array, 1);
+
 		val = this_cpu_inc_return(trace_buffered_event_cnt);
-		if ((len < (PAGE_SIZE - sizeof(*entry) - sizeof(entry->array[0]))) && val == 1) {
+		if (val == 1 && likely(len <= max_len)) {
 			trace_event_setup(entry, type, trace_ctx);
 			entry->array[0] = len;
 			return entry;
Signature · 1 line
2.30.2
author maintainer
#7 lore raw

PATCH 7/24 tracing: Add better comments for the filtering temp buffer use case

In reply to Steven Rostedt

From: "Steven Rostedt (VMware)" <[email protected]>

When filtering is enabled, the event is copied into a temp buffer instead of being written into the ring buffer directly, because the discarding of events from the ring buffer is very expensive, and doing the extra copy is much faster than having to discard most of the time.

As that logic is subtle, add comments to explain in more detail to what is going on and how it works.

---
 kernel/trace/trace.c | 36 +++++++++++++++++++++++++++++++++++-
 1 file changed, 35 insertions(+), 1 deletion(-)
kernel/trace/trace.c +35 -1
index a0a84ff46ecd..a0d66a056e59 100644
@@ -2734,10 +2734,44 @@ trace_event_buffer_lock_reserve(struct trace_buffer **current_rb,
 	if (!tr->no_filter_buffering_ref &&
 	    (trace_file->flags & (EVENT_FILE_FL_SOFT_DISABLED | EVENT_FILE_FL_FILTERED)) &&
 	    (entry = this_cpu_read(trace_buffered_event))) {
-		/* Try to use the per cpu buffer first */
+		/*
+		 * Filtering is on, so try to use the per cpu buffer first.
+		 * This buffer will simulate a ring_buffer_event,
+		 * where the type_len is zero and the array[0] will
+		 * hold the full length.
+		 * (see include/linux/ring-buffer.h for details on
+		 *  how the ring_buffer_event is structured).
+		 *
+		 * Using a temp buffer during filtering and copying it
+		 * on a matched filter is quicker than writing directly
+		 * into the ring buffer and then discarding it when
+		 * it doesn't match. That is because the discard
+		 * requires several atomic operations to get right.
+		 * Copying on match and doing nothing on a failed match
+		 * is still quicker than no copy on match, but having
+		 * to discard out of the ring buffer on a failed match.
+		 */
 		int max_len = PAGE_SIZE - struct_size(entry, array, 1);
 
 		val = this_cpu_inc_return(trace_buffered_event_cnt);
+
+		/*
+		 * Preemption is disabled, but interrupts and NMIs
+		 * can still come in now. If that happens after
+		 * the above increment, then it will have to go
+		 * back to the old method of allocating the event
+		 * on the ring buffer, and if the filter fails, it
+		 * will have to call ring_buffer_discard_commit()
+		 * to remove it.
+		 *
+		 * Need to also check the unlikely case that the
+		 * length is bigger than the temp buffer size.
+		 * If that happens, then the reserve is pretty much
+		 * guaranteed to fail, as the ring buffer currently
+		 * only allows events less than a page. But that may
+		 * change in the future, so let the ring buffer reserve
+		 * handle the failure in that case.
+		 */
 		if (val == 1 && likely(len <= max_len)) {
 			trace_event_setup(entry, type, trace_ctx);
 			entry->array[0] = len;
Signature · 1 line
2.30.2
author maintainer
#8 lore raw

PATCH 8/24 tracing: Add tp_printk_stop_on_boot option

In reply to Steven Rostedt

From: "Steven Rostedt (VMware)" <[email protected]>

Add a kernel command line option that disables printing of events to console at late_initcall_sync(). This is useful when needing to see specific events written to console on boot up, but not wanting it when user space starts, as user space may make the console so noisy that the system becomes inoperable.

---
 .../admin-guide/kernel-parameters.txt         | 13 ++++++
 kernel/trace/trace.c                          | 40 ++++++++++++++-----
 2 files changed, 42 insertions(+), 11 deletions(-)
Documentation/admin-guide/kernel-parameters.txt +13 -0
index cb89dbdedc46..0fcc725105cd 100644
@@ -5605,12 +5605,25 @@
 			Note, echoing 1 into this file without the
 			tracepoint_printk kernel cmdline option has no effect.
 
+			The tp_printk_stop_on_boot (see below) can also be used
+			to stop the printing of events to console at
+			late_initcall_sync.
+
 			** CAUTION **
 
 			Having tracepoints sent to printk() and activating high
 			frequency tracepoints such as irq or sched, can cause
 			the system to live lock.
 
+	tp_printk_stop_on_boot[FTRACE]
+			When tp_printk (above) is set, it can cause a lot of noise
+			on the console. It may be useful to only include the
+			printing of events during boot up, as user space may
+			make the system inoperable.
+
+			This command line option will stop the printing of events
+			to console at the late_initcall_sync() time frame.
+
 	traceoff_on_warning
 			[FTRACE] enable this option to disable tracing when a
 			warning is hit. This turns off "tracing_on". Tracing can
kernel/trace/trace.c +29 -11
index a0d66a056e59..bbc63ac5b47f 100644
@@ -86,6 +86,7 @@ void __init disable_tracing_selftest(const char *reason)
 /* Pipe tracepoints to printk */
 struct trace_iterator *tracepoint_print_iter;
 int tracepoint_printk;
+static bool tracepoint_printk_stop_on_boot __initdata;
 static DEFINE_STATIC_KEY_FALSE(tracepoint_printk_key);
 
 /* For tracers that don't implement custom flags */
@@ -256,6 +257,13 @@ static int __init set_tracepoint_printk(char *str)
 }
 __setup("tp_printk", set_tracepoint_printk);
 
+static int __init set_tracepoint_printk_stop(char *str)
+{
+	tracepoint_printk_stop_on_boot = true;
+	return 1;
+}
+__setup("tp_printk_stop_on_boot", set_tracepoint_printk_stop);
+
 unsigned long long ns2usecs(u64 nsec)
 {
 	nsec += 500;
@@ -9578,6 +9586,8 @@ static __init int tracer_init_tracefs(void)
 	return 0;
 }
 
+fs_initcall(tracer_init_tracefs);
+
 static int trace_panic_handler(struct notifier_block *this,
 			       unsigned long event, void *unused)
 {
@@ -9998,7 +10008,7 @@ void __init trace_init(void)
 	trace_event_init();
 }
 
-__init static int clear_boot_tracer(void)
+__init static void clear_boot_tracer(void)
 {
 	/*
 	 * The default tracer at boot buffer is an init section.
@@ -10008,26 +10018,21 @@ __init static int clear_boot_tracer(void)
 	 * about to be freed.
 	 */
 	if (!default_bootup_tracer)
-		return 0;
+		return;
 
 	printk(KERN_INFO "ftrace bootup tracer '%s' not registered.\n",
 	       default_bootup_tracer);
 	default_bootup_tracer = NULL;
-
-	return 0;
 }
 
-fs_initcall(tracer_init_tracefs);
-late_initcall_sync(clear_boot_tracer);
-
 #ifdef CONFIG_HAVE_UNSTABLE_SCHED_CLOCK
-__init static int tracing_set_default_clock(void)
+__init static void tracing_set_default_clock(void)
 {
 	/* sched_clock_stable() is determined in late_initcall */
 	if (!trace_boot_clock && !sched_clock_stable()) {
 		if (security_locked_down(LOCKDOWN_TRACEFS)) {
 			pr_warn("Can not set tracing clock due to lockdown\n");
-			return -EPERM;
+			return;
 		}
 
 		printk(KERN_WARNING
@@ -10037,8 +10042,21 @@ __init static int tracing_set_default_clock(void)
 		       "on the kernel command line\n");
 		tracing_set_clock(&global_trace, "global");
 	}
+}
+#else
+static inline void tracing_set_default_clock(void) { }
+#endif
 
+__init static int late_trace_init(void)
+{
+	if (tracepoint_printk && tracepoint_printk_stop_on_boot) {
+		static_key_disable(&tracepoint_printk_key.key);
+		tracepoint_printk = 0;
+	}
+
+	tracing_set_default_clock();
+	clear_boot_tracer();
 	return 0;
 }
-late_initcall_sync(tracing_set_default_clock);
-#endif
+
+late_initcall_sync(late_trace_init);
Signature · 1 line
2.30.2
author maintainer
#9 lore raw

PATCH 9/24 tracing: Have ftrace_dump_on_oops kernel parameter take numbers

In reply to Steven Rostedt

From: "Steven Rostedt (VMware)" <[email protected]>

The kernel parameter for ftrace_dump_on_oops can take a single assignment. That is, it can be:

ftrace_dump_on_oops or ftrace_dump_on_oops=orig_cpu

But the content in the sysctl file is a number.

0 for disabled
1 for ftrace_dump_on_oops (all CPUs)
2 for ftrace_dump_on_oops (orig CPU)

Allow the kernel command line to take a number as well to match the sysctl numbers.

That is:

ftrace_dump_on_oops=1 is the same as ftrace_dump_on_oops

and

ftrace_dump_on_oops=2 is the same as ftrace_dump_on_oops=orig_cpu

---
 kernel/trace/trace.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)
kernel/trace/trace.c +2 -2
index bbc63ac5b47f..d352fb4b7709 100644
@@ -197,12 +197,12 @@ __setup("ftrace=", set_cmdline_ftrace);
 
 static int __init set_ftrace_dump_on_oops(char *str)
 {
-	if (*str++ != '=' || !*str) {
+	if (*str++ != '=' || !*str || !strcmp("1", str)) {
 		ftrace_dump_on_oops = DUMP_ALL;
 		return 1;
 	}
 
-	if (!strcmp("orig_cpu", str)) {
+	if (!strcmp("orig_cpu", str) || !strcmp("2", str)) {
 		ftrace_dump_on_oops = DUMP_ORIG;
                 return 1;
         }
Signature · 1 line
2.30.2
author maintainer
#10 lore raw

PATCH 10/24 bootconfig/tracing/ktest: Add ktest examples of testing bootconfig

In reply to Steven Rostedt

From: "Steven Rostedt (VMware)" <[email protected]>

bootconfig is a new feature that appends scripts onto the initrd, and the kernel executes the scripts as an extended kernel command line.

Need to add tests to test that the happened. To test the bootconfig properly, the initrd needs to be updated and the kernel rebooted. ktest is the perfect solution to perform these tests.

Add a example bootconfig.conf in the tools/testing/ktest/examples/include and example bootconfig scripts in tools/testing/ktest/examples/bootconfig and also include verifier scripts that ktest will install on the target and run to make sure that the bootconfig options in the scripts took place after the target rebooted with the new initrd update.

---
 .../examples/bootconfigs/boottrace.bconf      | 49 +++++++++++
 .../examples/bootconfigs/config-bootconfig    |  1 +
 .../examples/bootconfigs/functiongraph.bconf  | 15 ++++
 .../ktest/examples/bootconfigs/tracing.bconf  | 33 ++++++++
 .../examples/bootconfigs/verify-boottrace.sh  | 84 +++++++++++++++++++
 .../bootconfigs/verify-functiongraph.sh       | 61 ++++++++++++++
 .../examples/bootconfigs/verify-tracing.sh    | 72 ++++++++++++++++
 .../ktest/examples/include/bootconfig.conf    | 69 +++++++++++++++
 tools/testing/ktest/examples/kvm.conf         |  1 +
 9 files changed, 385 insertions(+)
 create mode 100644 tools/testing/ktest/examples/bootconfigs/boottrace.bconf
 create mode 100644 tools/testing/ktest/examples/bootconfigs/config-bootconfig
 create mode 100644 tools/testing/ktest/examples/bootconfigs/functiongraph.bconf
 create mode 100644 tools/testing/ktest/examples/bootconfigs/tracing.bconf
 create mode 100755 tools/testing/ktest/examples/bootconfigs/verify-boottrace.sh
 create mode 100755 tools/testing/ktest/examples/bootconfigs/verify-functiongraph.sh
 create mode 100755 tools/testing/ktest/examples/bootconfigs/verify-tracing.sh
 create mode 100644 tools/testing/ktest/examples/include/bootconfig.conf
tools/testing/ktest/examples/bootconfigs/boottrace.bconf new file +49 -0
new file mode 100644
index 000000000000..9db64ec589d5
@@ -0,0 +1,49 @@
+ftrace.event {
+	task.task_newtask {
+		filter = "pid < 128"
+		enable
+	}
+	kprobes.vfs_read {
+		probes = "vfs_read $arg1 $arg2"
+		filter = "common_pid < 200"
+		enable
+	}
+	synthetic.initcall_latency {
+		fields = "unsigned long func", "u64 lat"
+		actions = "hist:keys=func.sym,lat:vals=lat:sort=lat"
+	}
+	initcall.initcall_start {
+		actions = "hist:keys=func:ts0=common_timestamp.usecs"
+	}
+	initcall.initcall_finish {
+		actions = "hist:keys=func:lat=common_timestamp.usecs-$ts0:onmatch(initcall.initcall_start).initcall_latency(func,$lat)"
+	}
+}
+
+ftrace.instance {
+	foo {
+		tracer = "function"
+		ftrace.filters = "user_*"
+		cpumask = 1
+		options = nosym-addr
+		buffer_size = 512KB
+		trace_clock = mono
+		event.signal.signal_deliver.actions=snapshot
+	}
+	bar {
+		tracer = "function"
+		ftrace.filters = "kernel_*"
+		cpumask = 2
+		trace_clock = x86-tsc
+	}
+}
+
+ftrace.alloc_snapshot
+
+kernel {
+	trace_options = sym-addr
+	trace_event = "initcall:*"
+	trace_buf_size = 1M
+	ftrace = function
+	ftrace_filter = "vfs*"
+}
tools/testing/ktest/examples/bootconfigs/config-bootconfig new file +1 -0
new file mode 100644
index 000000000000..0685b6811388
@@ -0,0 +1 @@
+CONFIG_CMDLINE="bootconfig"
tools/testing/ktest/examples/bootconfigs/functiongraph.bconf new file +15 -0
new file mode 100644
index 000000000000..68debfcbda76
@@ -0,0 +1,15 @@
+ftrace {
+	tracing_on = 0  # off by default
+	tracer = function_graph
+	event.kprobes {
+		start_event {
+			probes = "pci_proc_init"
+			actions = "traceon"
+		}
+		end_event {
+			probes = "pci_proc_init%return"
+			actions = "traceoff"
+		}
+	}
+}
+
tools/testing/ktest/examples/bootconfigs/tracing.bconf new file +33 -0
new file mode 100644
index 000000000000..bf117c78115a
@@ -0,0 +1,33 @@
+ftrace {
+	tracer = function_graph;
+	options = event-fork, sym-addr, stacktrace;
+	buffer_size = 1M;
+	alloc_snapshot;
+	trace_clock = global;
+	events = "task:task_newtask", "initcall:*";
+	event.sched.sched_process_exec {
+		filter = "pid < 128";
+	}
+	instance.bar {
+		event.kprobes {
+			myevent {
+				probes = "vfs_read $arg2 $arg3";
+			}
+			myevent2 {
+				probes = "vfs_write $arg2 +0($arg2):ustring $arg3";
+			}
+			myevent3 {
+				probes = "initrd_load";
+			}
+			enable
+		}
+	}
+	instance.foo {
+		tracer = function;
+		tracing_on = false;
+	};
+}
+kernel {
+	ftrace_dump_on_oops = "orig_cpu"
+	traceoff_on_warning
+}
tools/testing/ktest/examples/bootconfigs/verify-boottrace.sh new file +84 -0

84 lines not on this page · raw message

tools/testing/ktest/examples/bootconfigs/verify-functiongraph.sh new file +61 -0

61 lines not on this page · raw message

tools/testing/ktest/examples/bootconfigs/verify-tracing.sh new file +72 -0

72 lines not on this page · raw message

tools/testing/ktest/examples/include/bootconfig.conf new file +69 -0

69 lines not on this page · raw message

tools/testing/ktest/examples/kvm.conf +1 -0
index fbc134f9ac6e..c700e8bb7fde 100644
@@ -90,3 +90,4 @@ INCLUDE include/patchcheck.conf
 INCLUDE include/tests.conf
 INCLUDE include/bisect.conf
 INCLUDE include/min-config.conf
+INCLUDE include/bootconfig.conf
\ No newline at end of file
Signature · 1 line
2.30.2
author maintainer
#11 lore raw

PATCH 11/24 trace/hwlat: Fix Clarks email

In reply to Steven Rostedt

From: Daniel Bristot de Oliveira <[email protected]>

Clark's email is [email protected].

No functional change.

Cc Phil Auld <[email protected]>
Cc Sebastian Andrzej Siewior <[email protected]>
Cc Kate Carcia <[email protected]>
Cc Jonathan Corbet <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Alexandre Chartre <[email protected]>
Cc Clark Willaims <[email protected]>
Cc John Kacur <[email protected]>
Cc Juri Lelli <[email protected]>
Cc Borislav Petkov <[email protected]>
Cc "H. Peter Anvin" <[email protected]>
---
 kernel/trace/trace_hwlat.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)
kernel/trace/trace_hwlat.c +1 -1
index 632ef88131a9..0a5635401125 100644
@@ -34,7 +34,7 @@
  * Copyright (C) 2008-2009 Jon Masters, Red Hat, Inc. <[email protected]>
  * Copyright (C) 2013-2016 Steven Rostedt, Red Hat, Inc. <[email protected]>
  *
- * Includes useful feedback from Clark Williams <[email protected]>
+ * Includes useful feedback from Clark Williams <[email protected]>
  *
  */
 #include <linux/kthread.h>
Signature · 1 line
2.30.2
author maintainer
#12 lore raw

PATCH 12/24 trace/hwlat: Implement the mode config option

In reply to Steven Rostedt

From: Daniel Bristot de Oliveira <[email protected]>

Provides the "mode" config to the hardware latency detector. hwlatd has two different operation modes. The default mode is the "round-robin" one, in which a single hwlatd thread runs, migrating among the allowed CPUs in a "round-robin" fashion. This is the current behavior.

The "none" sets the allowed cpumask for a single hwlatd thread at the startup, but skips the round-robin, letting the scheduler handle the migration.

In preparation to the per-cpu mode.

Cc Phil Auld <[email protected]>
Cc Sebastian Andrzej Siewior <[email protected]>
Cc Kate Carcia <[email protected]>
Cc Jonathan Corbet <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Alexandre Chartre <[email protected]>
Cc Clark Willaims <[email protected]>
Cc John Kacur <[email protected]>
Cc Juri Lelli <[email protected]>
Cc Borislav Petkov <[email protected]>
Cc "H. Peter Anvin" <[email protected]>
---
 Documentation/trace/hwlat_detector.rst |  12 +-
 kernel/trace/trace_hwlat.c             | 179 +++++++++++++++++++++++--
 2 files changed, 175 insertions(+), 16 deletions(-)
Documentation/trace/hwlat_detector.rst +8 -4
index 5739349649c8..4d952df0586a 100644
@@ -76,8 +76,12 @@ in /sys/kernel/tracing:
  - tracing_cpumask	- the CPUs to move the hwlat thread across
  - hwlat_detector/width	- specified amount of time to spin within window (usecs)
  - hwlat_detector/window	- amount of time between (width) runs (usecs)
+ - hwlat_detector/mode	- the thread mode
 
-The hwlat detector's kernel thread will migrate across each CPU specified in
-tracing_cpumask between each window. To limit the migration, either modify
-tracing_cpumask, or modify the hwlat kernel thread (named [hwlatd]) CPU
-affinity directly, and the migration will stop.
+By default, the hwlat detector's kernel thread will migrate across each CPU
+specified in cpumask at the beginning of a new window, in a round-robin
+fashion. This behavior can be changed by changing the thread mode,
+the available options are:
+
+ - none:        do not force migration
+ - round-robin: migrate across each CPU specified in cpumask [default]
kernel/trace/trace_hwlat.c +167 -12

250 lines not on this page · raw message

Signature · 1 line
2.30.2
author maintainer
#13 lore raw

PATCH 13/24 trace/hwlat: Switch disable_migrate to mode none

In reply to Steven Rostedt

From: Daniel Bristot de Oliveira <[email protected]>

When in the round-robin mode, if the tracer detects a change in the hwlatd thread affinity by an external tool, e.g., taskset, the round-robin logic is disabled. The disable_migrate variable currently tracks this.

With the addition of the "mode" config and the mode "none," the disable_migrate logic is equivalent to switch to the "none" mode.

Hence, instead of using a hidden variable to track this behavior, switch the mode to none, informing the user about this change.

Cc Phil Auld <[email protected]>
Cc Sebastian Andrzej Siewior <[email protected]>
Cc Kate Carcia <[email protected]>
Cc Jonathan Corbet <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Alexandre Chartre <[email protected]>
Cc Clark Willaims <[email protected]>
Cc John Kacur <[email protected]>
Cc Juri Lelli <[email protected]>
Cc Borislav Petkov <[email protected]>
Cc "H. Peter Anvin" <[email protected]>
---
 kernel/trace/trace_hwlat.c | 13 +++++--------
 1 file changed, 5 insertions(+), 8 deletions(-)
kernel/trace/trace_hwlat.c +5 -8
index 43a436d85a01..bae74b95cf55 100644
@@ -286,7 +286,6 @@ static int get_sample(void)
 }
 
 static struct cpumask save_cpumask;
-static bool disable_migrate;
 
 static void move_to_next_cpu(void)
 {
@@ -294,15 +293,13 @@ static void move_to_next_cpu(void)
 	struct trace_array *tr = hwlat_trace;
 	int next_cpu;
 
-	if (disable_migrate)
-		return;
 	/*
 	 * If for some reason the user modifies the CPU affinity
 	 * of this thread, then stop migrating for the duration
 	 * of the current test.
 	 */
 	if (!cpumask_equal(current_mask, current->cpus_ptr))
-		goto disable;
+		goto change_mode;
 
 	get_online_cpus();
 	cpumask_and(current_mask, cpu_online_mask, tr->tracing_cpumask);
@@ -313,7 +310,7 @@ static void move_to_next_cpu(void)
 		next_cpu = cpumask_first(current_mask);
 
 	if (next_cpu >= nr_cpu_ids) /* Shouldn't happen! */
-		goto disable;
+		goto change_mode;
 
 	cpumask_clear(current_mask);
 	cpumask_set_cpu(next_cpu, current_mask);
@@ -321,8 +318,9 @@ static void move_to_next_cpu(void)
 	sched_setaffinity(0, current_mask);
 	return;
 
- disable:
-	disable_migrate = true;
+ change_mode:
+	hwlat_data.thread_mode = MODE_NONE;
+	pr_info(BANNER "cpumask changed while in round-robin mode, switching to mode none\n");
 }
 
 /*
@@ -744,7 +742,6 @@ static int hwlat_tracer_init(struct trace_array *tr)
 
 	hwlat_trace = tr;
 
-	disable_migrate = false;
 	hwlat_data.count = 0;
 	tr->max_latency = 0;
 	save_tracing_thresh = tracing_thresh;
Signature · 1 line
2.30.2
author maintainer
#14 lore raw

PATCH 14/24 trace/hwlat: Implement the per-cpu mode

In reply to Steven Rostedt

From: Daniel Bristot de Oliveira <[email protected]>

Implements the per-cpu mode in which a sampling thread is created for each cpu in the "cpus" (and tracing_mask).

The per-cpu mode has the potention to speed up the hwlat detection by running on multiple CPUs at the same time, at the cost of higher cpu usage with irqs disabled. Use with care.

[
Changed get_cpu_data() to static.

]

Cc Phil Auld <[email protected]>
Cc Sebastian Andrzej Siewior <[email protected]>
Cc Kate Carcia <[email protected]>
Cc Jonathan Corbet <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Alexandre Chartre <[email protected]>
Cc Clark Willaims <[email protected]>
Cc John Kacur <[email protected]>
Cc Juri Lelli <[email protected]>
Cc Borislav Petkov <[email protected]>
Cc "H. Peter Anvin" <[email protected]>
---
 Documentation/trace/hwlat_detector.rst |   3 +-
 kernel/trace/trace_hwlat.c             | 186 ++++++++++++++++++++-----
 2 files changed, 152 insertions(+), 37 deletions(-)
Documentation/trace/hwlat_detector.rst +2 -1
index 4d952df0586a..de94b499b0bc 100644
@@ -78,10 +78,11 @@ in /sys/kernel/tracing:
  - hwlat_detector/window	- amount of time between (width) runs (usecs)
  - hwlat_detector/mode	- the thread mode
 
-By default, the hwlat detector's kernel thread will migrate across each CPU
+By default, one hwlat detector's kernel thread will migrate across each CPU
 specified in cpumask at the beginning of a new window, in a round-robin
 fashion. This behavior can be changed by changing the thread mode,
 the available options are:
 
  - none:        do not force migration
  - round-robin: migrate across each CPU specified in cpumask [default]
+ - per-cpu:     create one thread for each cpu in tracing_cpumask
kernel/trace/trace_hwlat.c +150 -36

306 lines not on this page · raw message

Signature · 1 line
2.30.2
author maintainer
#15 lore raw

PATCH 15/24 trace: Add a generic function to read/write u64 values from tracefs

In reply to Steven Rostedt

From: Daniel Bristot de Oliveira <[email protected]>

The hwlat detector and (in preparation for) the osnoise/timerlat tracers have a set of u64 parameters that the user can read/write via tracefs. For instance, we have hwlat_detector's window and width.

To reduce the code duplication, hwlat's window and width share the same read function. However, they do not share the write functions because they do different parameter checks. For instance, the width needs to be smaller than the window, while the window needs to be larger than the window. The same pattern repeats on osnoise/timerlat, and a large portion of the code was devoted to the write function.

Despite having different checks, the write functions have the same structure:

read a user-space buffer
take the lock that protects the value check for minimum and maximum acceptable values
save the value
release the lock
return success or error

To reduce the code duplication also in the write functions, this patch provides a generic read and write implementation for u64 values that need to be within some minimum and/or maximum parameters, while (potentially) being protected by a lock.

To use this interface, the structure trace_min_max_param needs to be filled:

 struct trace_min_max_param {
         struct mutex    *lock;
         u64             *val;
         u64             *min;
         u64             *max;

};

The desired value is stored on the variable pointed by *val. If *min points to a minimum acceptable value, it will be checked during the write operation. Likewise, if *max points to a maximum allowable value, it will be checked during the write operation. Finally, if *lock points to a mutex, it will be taken at the beginning of the operation and released at the end.

The definition of a trace_min_max_param needs to passed as the (private) *data for tracefs_create_file(), and the trace_min_max_fops (added by this patch) as the *fops file_operations.

Cc Phil Auld <[email protected]>
Cc Sebastian Andrzej Siewior <[email protected]>
Cc Kate Carcia <[email protected]>
Cc Jonathan Corbet <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Alexandre Chartre <[email protected]>
Cc Clark Willaims <[email protected]>
Cc John Kacur <[email protected]>
Cc Juri Lelli <[email protected]>
Cc Borislav Petkov <[email protected]>
Cc "H. Peter Anvin" <[email protected]>
---
 kernel/trace/trace.c | 85 ++++++++++++++++++++++++++++++++++++++++++++
 kernel/trace/trace.h | 18 ++++++++++
 2 files changed, 103 insertions(+)
kernel/trace/trace.c +85 -0
index d352fb4b7709..27bf203ef05a 100644
@@ -7583,6 +7583,91 @@ static const struct file_operations snapshot_raw_fops = {
 
 #endif /* CONFIG_TRACER_SNAPSHOT */
 
+/*
+ * trace_min_max_write - Write a u64 value to a trace_min_max_param struct
+ * @filp: The active open file structure
+ * @ubuf: The userspace provided buffer to read value into
+ * @cnt: The maximum number of bytes to read
+ * @ppos: The current "file" position
+ *
+ * This function implements the write interface for a struct trace_min_max_param.
+ * The filp->private_data must point to a trace_min_max_param structure that
+ * defines where to write the value, the min and the max acceptable values,
+ * and a lock to protect the write.
+ */
+static ssize_t
+trace_min_max_write(struct file *filp, const char __user *ubuf, size_t cnt, loff_t *ppos)
+{
+	struct trace_min_max_param *param = filp->private_data;
+	u64 val;
+	int err;
+
+	if (!param)
+		return -EFAULT;
+
+	err = kstrtoull_from_user(ubuf, cnt, 10, &val);
+	if (err)
+		return err;
+
+	if (param->lock)
+		mutex_lock(param->lock);
+
+	if (param->min && val < *param->min)
+		err = -EINVAL;
+
+	if (param->max && val > *param->max)
+		err = -EINVAL;
+
+	if (!err)
+		*param->val = val;
+
+	if (param->lock)
+		mutex_unlock(param->lock);
+
+	if (err)
+		return err;
+
+	return cnt;
+}
+
+/*
+ * trace_min_max_read - Read a u64 value from a trace_min_max_param struct
+ * @filp: The active open file structure
+ * @ubuf: The userspace provided buffer to read value into
+ * @cnt: The maximum number of bytes to read
+ * @ppos: The current "file" position
+ *
+ * This function implements the read interface for a struct trace_min_max_param.
+ * The filp->private_data must point to a trace_min_max_param struct with valid
+ * data.
+ */
+static ssize_t
+trace_min_max_read(struct file *filp, char __user *ubuf, size_t cnt, loff_t *ppos)
+{
+	struct trace_min_max_param *param = filp->private_data;
+	char buf[U64_STR_SIZE];
+	int len;
+	u64 val;
+
+	if (!param)
+		return -EFAULT;
+
+	val = *param->val;
+
+	if (cnt > sizeof(buf))
+		cnt = sizeof(buf);
+
+	len = snprintf(buf, sizeof(buf), "%llu\n", val);
+
+	return simple_read_from_buffer(ubuf, cnt, ppos, buf, len);
+}
+
+const struct file_operations trace_min_max_fops = {
+	.open		= tracing_open_generic,
+	.read		= trace_min_max_read,
+	.write		= trace_min_max_write,
+};
+
 #define TRACING_LOG_ERRS_MAX	8
 #define TRACING_LOG_LOC_MAX	128
 
kernel/trace/trace.h +18 -0
index cd80d046c7a5..22f8c652ef8b 100644
@@ -1952,4 +1952,22 @@ static inline bool is_good_name(const char *name)
 	return true;
 }
 
+/*
+ * This is a generic way to read and write a u64 value from a file in tracefs.
+ *
+ * The value is stored on the variable pointed by *val. The value needs
+ * to be at least *min and at most *max. The write is protected by an
+ * existing *lock.
+ */
+struct trace_min_max_param {
+	struct mutex	*lock;
+	u64		*val;
+	u64		*min;
+	u64		*max;
+};
+
+#define U64_STR_SIZE		24	/* 20 digits max */
+
+extern const struct file_operations trace_min_max_fops;
+
 #endif /* _LINUX_KERNEL_TRACE_H */
Signature · 1 line
2.30.2
author maintainer
#16 lore raw

PATCH 16/24 trace/hwlat: Use trace_min_max_param for width and window params

In reply to Steven Rostedt

From: Daniel Bristot de Oliveira <[email protected]>

Use the trace_min_max_param to reduce code duplication.

No functional change.

Cc Phil Auld <[email protected]>
Cc Sebastian Andrzej Siewior <[email protected]>
Cc Kate Carcia <[email protected]>
Cc Jonathan Corbet <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Alexandre Chartre <[email protected]>
Cc Clark Willaims <[email protected]>
Cc John Kacur <[email protected]>
Cc Juri Lelli <[email protected]>
Cc Borislav Petkov <[email protected]>
Cc "H. Peter Anvin" <[email protected]>
---
 kernel/trace/trace_hwlat.c | 145 ++++++-------------------------------
 1 file changed, 24 insertions(+), 121 deletions(-)
kernel/trace/trace_hwlat.c +24 -121
index 3957b36826e2..44f46bc1140f 100644
@@ -527,115 +527,6 @@ static int start_per_cpu_kthreads(struct trace_array *tr)
 	return retval;
 }
 
-/*
- * hwlat_read - Wrapper read function for reading both window and width
- * @filp: The active open file structure
- * @ubuf: The userspace provided buffer to read value into
- * @cnt: The maximum number of bytes to read
- * @ppos: The current "file" position
- *
- * This function provides a generic read implementation for the global state
- * "hwlat_data" structure filesystem entries.
- */
-static ssize_t hwlat_read(struct file *filp, char __user *ubuf,
-			  size_t cnt, loff_t *ppos)
-{
-	char buf[U64STR_SIZE];
-	u64 *entry = filp->private_data;
-	u64 val;
-	int len;
-
-	if (!entry)
-		return -EFAULT;
-
-	if (cnt > sizeof(buf))
-		cnt = sizeof(buf);
-
-	val = *entry;
-
-	len = snprintf(buf, sizeof(buf), "%llu\n", val);
-
-	return simple_read_from_buffer(ubuf, cnt, ppos, buf, len);
-}
-
-/**
- * hwlat_width_write - Write function for "width" entry
- * @filp: The active open file structure
- * @ubuf: The user buffer that contains the value to write
- * @cnt: The maximum number of bytes to write to "file"
- * @ppos: The current position in @file
- *
- * This function provides a write implementation for the "width" interface
- * to the hardware latency detector. It can be used to configure
- * for how many us of the total window us we will actively sample for any
- * hardware-induced latency periods. Obviously, it is not possible to
- * sample constantly and have the system respond to a sample reader, or,
- * worse, without having the system appear to have gone out to lunch. It
- * is enforced that width is less that the total window size.
- */
-static ssize_t
-hwlat_width_write(struct file *filp, const char __user *ubuf,
-		  size_t cnt, loff_t *ppos)
-{
-	u64 val;
-	int err;
-
-	err = kstrtoull_from_user(ubuf, cnt, 10, &val);
-	if (err)
-		return err;
-
-	mutex_lock(&hwlat_data.lock);
-	if (val < hwlat_data.sample_window)
-		hwlat_data.sample_width = val;
-	else
-		err = -EINVAL;
-	mutex_unlock(&hwlat_data.lock);
-
-	if (err)
-		return err;
-
-	return cnt;
-}
-
-/**
- * hwlat_window_write - Write function for "window" entry
- * @filp: The active open file structure
- * @ubuf: The user buffer that contains the value to write
- * @cnt: The maximum number of bytes to write to "file"
- * @ppos: The current position in @file
- *
- * This function provides a write implementation for the "window" interface
- * to the hardware latency detector. The window is the total time
- * in us that will be considered one sample period. Conceptually, windows
- * occur back-to-back and contain a sample width period during which
- * actual sampling occurs. Can be used to write a new total window size. It
- * is enforced that any value written must be greater than the sample width
- * size, or an error results.
- */
-static ssize_t
-hwlat_window_write(struct file *filp, const char __user *ubuf,
-		   size_t cnt, loff_t *ppos)
-{
-	u64 val;
-	int err;
-
-	err = kstrtoull_from_user(ubuf, cnt, 10, &val);
-	if (err)
-		return err;
-
-	mutex_lock(&hwlat_data.lock);
-	if (hwlat_data.sample_width < val)
-		hwlat_data.sample_window = val;
-	else
-		err = -EINVAL;
-	mutex_unlock(&hwlat_data.lock);
-
-	if (err)
-		return err;
-
-	return cnt;
-}
-
 static void *s_mode_start(struct seq_file *s, loff_t *pos)
 {
 	int mode = *pos;
@@ -760,16 +651,28 @@ static ssize_t hwlat_mode_write(struct file *filp, const char __user *ubuf,
 	return ret;
 }
 
-static const struct file_operations width_fops = {
-	.open		= tracing_open_generic,
-	.read		= hwlat_read,
-	.write		= hwlat_width_write,
+/*
+ * The width parameter is read/write using the generic trace_min_max_param
+ * method. The *val is protected by the hwlat_data lock and is upper
+ * bounded by the window parameter.
+ */
+static struct trace_min_max_param hwlat_width = {
+	.lock		= &hwlat_data.lock,
+	.val		= &hwlat_data.sample_width,
+	.max		= &hwlat_data.sample_window,
+	.min		= NULL,
 };
 
-static const struct file_operations window_fops = {
-	.open		= tracing_open_generic,
-	.read		= hwlat_read,
-	.write		= hwlat_window_write,
+/*
+ * The window parameter is read/write using the generic trace_min_max_param
+ * method. The *val is protected by the hwlat_data lock and is lower
+ * bounded by the width parameter.
+ */
+static struct trace_min_max_param hwlat_window = {
+	.lock		= &hwlat_data.lock,
+	.val		= &hwlat_data.sample_window,
+	.max		= NULL,
+	.min		= &hwlat_data.sample_width,
 };
 
 static const struct file_operations thread_mode_fops = {
@@ -802,15 +705,15 @@ static int init_tracefs(void)
 
 	hwlat_sample_window = tracefs_create_file("window", 0640,
 						  top_dir,
-						  &hwlat_data.sample_window,
-						  &window_fops);
+						  &hwlat_window,
+						  &trace_min_max_fops);
 	if (!hwlat_sample_window)
 		goto err;
 
 	hwlat_sample_width = tracefs_create_file("width", 0644,
 						 top_dir,
-						 &hwlat_data.sample_width,
-						 &width_fops);
+						 &hwlat_width,
+						 &trace_min_max_fops);
 	if (!hwlat_sample_width)
 		goto err;
 
Signature · 1 line
2.30.2
author maintainer
#17 lore raw

PATCH 17/24 trace/hwlat: Remove printk from sampling loop

In reply to Steven Rostedt

From: Daniel Bristot de Oliveira <[email protected]>

hwlat has some time operation checks on the sample loop, and it is currently using pr_err (printk) to report them. The problem is that this can lead the system to an unresponsible state due to an overflow of printk messages. This problem can be mitigated by writing the error message to the trace buffer.

Remove the printk messages from the sampling loop, switching the to messages in the trace buffer.

No functional change.

Cc Phil Auld <[email protected]>
Cc Sebastian Andrzej Siewior <[email protected]>
Cc Kate Carcia <[email protected]>
Cc Jonathan Corbet <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Alexandre Chartre <[email protected]>
Cc Clark Willaims <[email protected]>
Cc John Kacur <[email protected]>
Cc Juri Lelli <[email protected]>
Cc Borislav Petkov <[email protected]>
Cc "H. Peter Anvin" <[email protected]>
---
 kernel/trace/trace_hwlat.c | 15 ++++++++++++---
 1 file changed, 12 insertions(+), 3 deletions(-)
kernel/trace/trace_hwlat.c +12 -3
index 44f46bc1140f..a625bfdb844e 100644
@@ -182,6 +182,15 @@ void trace_hwlat_callback(bool enter)
 		kdata->nmi_count++;
 }
 
+/*
+ * hwlat_err - report a hwlat error.
+ */
+#define hwlat_err(msg) ({							\
+	struct trace_array *tr = hwlat_trace;					\
+										\
+	trace_array_printk_buf(tr->array_buffer.buffer, _THIS_IP_, msg);	\
+})
+
 /**
  * get_sample - sample the CPU TSC and look for likely hardware latencies
  *
@@ -225,7 +234,7 @@ static int get_sample(void)
 			outer_diff = time_to_us(time_sub(t1, last_t2));
 			/* This shouldn't happen */
 			if (outer_diff < 0) {
-				pr_err(BANNER "time running backwards\n");
+				hwlat_err(BANNER "time running backwards\n");
 				goto out;
 			}
 			if (outer_diff > outer_sample)
@@ -237,7 +246,7 @@ static int get_sample(void)
 
 		/* Check for possible overflows */
 		if (total < last_total) {
-			pr_err("Time total overflowed\n");
+			hwlat_err("Time total overflowed\n");
 			break;
 		}
 		last_total = total;
@@ -253,7 +262,7 @@ static int get_sample(void)
 
 		/* This shouldn't happen */
 		if (diff < 0) {
-			pr_err(BANNER "time running backwards\n");
+			hwlat_err(BANNER "time running backwards\n");
 			goto out;
 		}
 
Signature · 1 line
2.30.2
author maintainer
#18 lore raw

PATCH 18/24 trace: Add __print_ns_to_secs() and __print_ns_without_secs() helpers

In reply to Steven Rostedt

From: Steven Rostedt <[email protected]>

To have nanosecond output displayed in a more human readable format, its nicer to convert it to a seconds format (XXX.YYYYYYYYY). The problem is that to do so, the numbers must be divided by NSEC_PER_SEC, and moded too. But as these numbers are 64 bit, this can not be done simply with '/' and '%' operators, but must use do_div() instead.

Instead of performing the expensive do_div() in the hot path of the tracepoint, it is more efficient to perform it during the output phase. But passing in do_div() can confuse the parser, and do_div() doesn't work exactly like a normal C function. It modifies the number in place, and we don't want to modify the actual values in the ring buffer.

Two helper functions are now created:

__print_ns_to_secs() and __print_ns_without_secs()

They both take a value of nanoseconds, and the former will return that number divided by NSEC_PER_SEC, and the latter will mod it with NSEC_PER_SEC giving a way to print a nice human readable format:

__print_fmt("time=%llu.%09u",

	__print_ns_to_secs(REC->nsec_val),
	__print_ns_without_secs(REC->nsec_val))
Cc Phil Auld <[email protected]>
Cc Sebastian Andrzej Siewior <[email protected]>
Cc Kate Carcia <[email protected]>
Cc Jonathan Corbet <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Alexandre Chartre <[email protected]>
Cc Clark Willaims <[email protected]>
Cc John Kacur <[email protected]>
Cc Juri Lelli <[email protected]>
Cc Borislav Petkov <[email protected]>
Cc "H. Peter Anvin" <[email protected]>
---
 include/trace/trace_events.h | 25 +++++++++++++++++++++++++
 1 file changed, 25 insertions(+)
include/trace/trace_events.h +25 -0
index 8268bf747d6f..acc17194c160 100644
@@ -358,6 +358,21 @@ TRACE_MAKE_SYSTEM_STR();
 	trace_print_hex_dump_seq(p, prefix_str, prefix_type,		\
 				 rowsize, groupsize, buf, len, ascii)
 
+#undef __print_ns_to_secs
+#define __print_ns_to_secs(value)			\
+	({						\
+		u64 ____val = (u64)(value);		\
+		do_div(____val, NSEC_PER_SEC);		\
+		____val;				\
+	})
+
+#undef __print_ns_without_secs
+#define __print_ns_without_secs(value)			\
+	({						\
+		u64 ____val = (u64)(value);		\
+		(u32) do_div(____val, NSEC_PER_SEC);	\
+	})
+
 #undef DECLARE_EVENT_CLASS
 #define DECLARE_EVENT_CLASS(call, proto, args, tstruct, assign, print)	\
 static notrace enum print_line_t					\
@@ -736,6 +751,16 @@ static inline void ftrace_test_probe_##call(void)			\
 #undef __print_array
 #undef __print_hex_dump
 
+/*
+ * The below is not executed in the kernel. It is only what is
+ * displayed in the print format for userspace to parse.
+ */
+#undef __print_ns_to_secs
+#define __print_ns_to_secs(val) (val) / 1000000000UL
+
+#undef __print_ns_without_secs
+#define __print_ns_without_secs(val) (val) % 1000000000UL
+
 #undef TP_printk
 #define TP_printk(fmt, args...) "\"" fmt "\", "  __stringify(args)
 
Signature · 1 line
2.30.2
author maintainer
#19 lore raw

PATCH 19/24 tracing: Add LATENCY_FS_NOTIFY to define if latency_fsnotify() is defined

In reply to Steven Rostedt

From: "Steven Rostedt (VMware)" <[email protected]>

With the coming addition of the osnoise tracer, the configs needed to include the latency_fsnotify() has become more complex, and to keep the declaration in the header file the same as in the C file, just have the logic needed to define it in one place, and that defines LATENCY_FS_NOTIFY which will be used in the C code.

---
 kernel/trace/trace.c | 3 +--
 kernel/trace/trace.h | 6 +++---
 2 files changed, 4 insertions(+), 5 deletions(-)
kernel/trace/trace.c +1 -2
index 27bf203ef05a..60492464281e 100644
@@ -1690,8 +1690,7 @@ static ssize_t trace_seq_to_buffer(struct trace_seq *s, void *buf, size_t cnt)
 unsigned long __read_mostly	tracing_thresh;
 static const struct file_operations tracing_max_lat_fops;
 
-#if (defined(CONFIG_TRACER_MAX_TRACE) || defined(CONFIG_HWLAT_TRACER)) && \
-	defined(CONFIG_FSNOTIFY)
+#ifdef LATENCY_FS_NOTIFY
 
 static struct workqueue_struct *fsnotify_wq;
 
kernel/trace/trace.h +3 -3
index 22f8c652ef8b..87588d1e24ca 100644
@@ -677,13 +677,13 @@ void update_max_tr_single(struct trace_array *tr,
 
 #if (defined(CONFIG_TRACER_MAX_TRACE) || defined(CONFIG_HWLAT_TRACER)) && \
 	defined(CONFIG_FSNOTIFY)
+#define LATENCY_FS_NOTIFY
+#endif
 
+#ifdef LATENCY_FS_NOTIFY
 void latency_fsnotify(struct trace_array *tr);
-
 #else
-
 static inline void latency_fsnotify(struct trace_array *tr) { }
-
 #endif
 
 #ifdef CONFIG_STACKTRACE
Signature · 1 line
2.30.2
#20 lore raw

Re: [for-next][PATCH 19/24] tracing: Add LATENCY_FS_NOTIFY to define if latency_fsnotify() is defined

Quoted 11 lines · Steven Rostedt

From: "Steven Rostedt (VMware)" <[email protected]>

With the coming addition of the osnoise tracer, the configs needed to include the latency_fsnotify() has become more complex, and to keep the declaration in the header file the same as in the C file, just have the logic needed to define it in one place, and that defines LATENCY_FS_NOTIFY which will be used in the C code.

This still doesn't seem quite right. I just came across this randconfig build warning on 5.14-rc2:

kernel/trace/trace.c:1712:13: error: 'trace_create_maxlat_file' defined but not used [-Werror=unused-function]
1712 | static void trace_create_maxlat_file(struct trace_array *tr,

See https://pastebin.com/raw/b3DH7hWg for the .config that triggered it.

Arnd

author maintainer
#21 lore raw

PATCH 20/24 trace: Add osnoise tracer

In reply to Steven Rostedt

From: Daniel Bristot de Oliveira <[email protected]>

In the context of high-performance computing (HPC), the Operating System Noise (*osnoise*) refers to the interference experienced by an application due to activities inside the operating system. In the context of Linux, NMIs, IRQs, SoftIRQs, and any other system thread can cause noise to the system. Moreover, hardware-related jobs can also cause noise, for example, via SMIs.

The osnoise tracer leverages the hwlat_detector by running a similar loop with preemption, SoftIRQs and IRQs enabled, thus allowing all the sources of *osnoise* during its execution. Using the same approach of hwlat, osnoise takes note of the entry and exit point of any source of interferences, increasing a per-cpu interference counter. The osnoise tracer also saves an interference counter for each source of interference. The interference counter for NMI, IRQs, SoftIRQs, and threads is increased anytime the tool observes these interferences' entry events. When a noise happens without any interference from the operating system level, the hardware noise counter increases, pointing to a hardware-related noise. In this way, osnoise can account for any source of interference. At the end of the period, the osnoise tracer prints the sum of all noise, the max single noise, the percentage of CPU available for the thread, and the counters for the noise sources.

Usage

Write the ASCII text "osnoise" into the current_tracer file of the tracing system (generally mounted at /sys/kernel/tracing).

For example::

[root@f32 ~]# cd /sys/kernel/tracing/ [root@f32 tracing]# echo osnoise > current_tracer

It is possible to follow the trace by reading the trace trace file::

        [root@f32 tracing]# cat trace
        # tracer: osnoise
        #
        #                                _-----=> irqs-off
        #                               / _----=> need-resched
        #                              | / _---=> hardirq/softirq
        #                              || / _--=> preempt-depth                            MAX
        #                              || /                                             SINGLE     Interference counters:
        #                              ||||               RUNTIME      NOISE   % OF CPU  NOISE    +-----------------------------+
        #           TASK-PID      CPU# ||||   TIMESTAMP    IN US       IN US  AVAILABLE  IN US     HW    NMI    IRQ   SIRQ THREAD
        #              | |         |   ||||      |           |             |    |            |      |      |      |      |      |
                   <...>-859     [000] ....    81.637220: 1000000        190  99.98100       9     18      0   1007     18      1
                   <...>-860     [001] ....    81.638154: 1000000        656  99.93440      74     23      0   1006     16      3
                   <...>-861     [002] ....    81.638193: 1000000       5675  99.43250     202      6      0   1013     25     21
                   <...>-862     [003] ....    81.638242: 1000000        125  99.98750      45      1      0   1011     23      0
                   <...>-863     [004] ....    81.638260: 1000000       1721  99.82790     168      7      0   1002     49     41
                   <...>-864     [005] ....    81.638286: 1000000        263  99.97370      57      6      0   1006     26      2
                   <...>-865     [006] ....    81.638302: 1000000        109  99.98910      21      3      0   1006     18      1
                   <...>-866     [007] ....    81.638326: 1000000       7816  99.21840     107      8      0   1016     39     19

In addition to the regular trace fields (from TASK-PID to TIMESTAMP), the tracer prints a message at the end of each period for each CPU that is running an osnoise/CPU thread. The osnoise specific fields report:

- The RUNTIME IN USE reports the amount of time in microseconds that the osnoise thread kept looping reading the time.
- The NOISE IN US reports the sum of noise in microseconds observed by the osnoise tracer during the associated runtime.
- The % OF CPU AVAILABLE reports the percentage of CPU available for the osnoise thread during the runtime window.
- The MAX SINGLE NOISE IN US reports the maximum single noise observed during the runtime window.
- The Interference counters display how many each of the respective interference happened during the runtime window.

Note that the example above shows a high number of HW noise samples. The reason being is that this sample was taken on a virtual machine, and the host interference is detected as a hardware interference.

Tracer options

The tracer has a set of options inside the osnoise directory, they are:

- osnoise/cpus: CPUs at which a osnoise thread will execute.
- osnoise/period_us: the period of the osnoise thread.
- osnoise/runtime_us: how long an osnoise thread will look for noise.
- osnoise/stop_tracing_us: stop the system tracing if a single noise higher than the configured value happens. Writing 0 disables this option.
- osnoise/stop_tracing_total_us: stop the system tracing if total noise higher than the configured value happens. Writing 0 disables this option.
- tracing_threshold: the minimum delta between two time() reads to be considered as noise, in us. When set to 0, the default value will be used, which is currently 5 us.

Additional Tracing

In addition to the tracer, a set of tracepoints were added to facilitate the identification of the osnoise source.

- osnoise:sample_threshold: printed anytime a noise is higher than the configurable tolerance_ns.
- osnoise:nmi_noise: noise from NMI, including the duration.
- osnoise:irq_noise: noise from an IRQ, including the duration.
- osnoise:softirq_noise: noise from a SoftIRQ, including the duration.
- osnoise:thread_noise: noise from a thread, including the duration.

Note that all the values are *net values*. For example, if while osnoise is running, another thread preempts the osnoise thread, it will start a thread_noise duration at the start. Then, an IRQ takes place, preempting the thread_noise, starting a irq_noise. When the IRQ ends its execution, it will compute its duration, and this duration will be subtracted from the thread_noise, in such a way as to avoid the double accounting of the IRQ execution. This logic is valid for all sources of noise.

Here is one example of the usage of these tracepoints::

       osnoise/8-961     [008] d.h.  5789.857532: irq_noise: local_timer:236 start 5789.857529929 duration 1845 ns
       osnoise/8-961     [008] dNh.  5789.858408: irq_noise: local_timer:236 start 5789.858404871 duration 2848 ns
     migration/8-54      [008] d...  5789.858413: thread_noise: migration/8:54 start 5789.858409300 duration 3068 ns
       osnoise/8-961     [008] ....  5789.858413: sample_threshold: start 5789.858404555 duration 8723 ns interferences 2

In this example, a noise sample of 8 microseconds was reported in the last line, pointing to two interferences. Looking backward in the trace, the two previous entries were about the migration thread running after a timer IRQ execution. The first event is not part of the noise because it took place one millisecond before.

It is worth noticing that the sum of the duration reported in the tracepoints is smaller than eight us reported in the sample_threshold. The reason roots in the overhead of the entry and exit code that happens before and after any interference execution. This justifies the dual
approach: measuring thread and tracing.

Cc Phil Auld <[email protected]>
Cc Sebastian Andrzej Siewior <[email protected]>
Cc Kate Carcia <[email protected]>
Cc Jonathan Corbet <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Alexandre Chartre <[email protected]>
Cc Clark Willaims <[email protected]>
Cc John Kacur <[email protected]>
Cc Juri Lelli <[email protected]>
Cc Borislav Petkov <[email protected]>
Cc "H. Peter Anvin" <[email protected]>

[
Made the following functions static:
trace_irqentry_callback()
trace_irqexit_callback()
trace_intel_irqentry_callback()
trace_intel_irqexit_callback()

Added to include/trace.h:
osnoise_arch_register()
osnoise_arch_unregister()

Fixed define logic for LATENCY_FS_NOTIFY

]

---
 Documentation/trace/index.rst          |    1 +
 Documentation/trace/osnoise-tracer.rst |  152 +++
 arch/x86/kernel/Makefile               |    1 +
 arch/x86/kernel/trace.c                |  237 ++++
 include/linux/ftrace_irq.h             |   13 +
 include/linux/trace.h                  |    5 +
 include/trace/events/osnoise.h         |  142 +++
 kernel/trace/Kconfig                   |   34 +
 kernel/trace/Makefile                  |    1 +
 kernel/trace/trace.h                   |    9 +-
 kernel/trace/trace_entries.h           |   25 +
 kernel/trace/trace_osnoise.c           | 1384 ++++++++++++++++++++++++
 kernel/trace/trace_output.c            |   72 +-
 13 files changed, 2072 insertions(+), 4 deletions(-)
 create mode 100644 Documentation/trace/osnoise-tracer.rst
 create mode 100644 arch/x86/kernel/trace.c
 create mode 100644 include/trace/events/osnoise.h
 create mode 100644 kernel/trace/trace_osnoise.c
Documentation/trace/index.rst +1 -0
index f634b36fd3aa..608107b27cc0 100644
@@ -23,6 +23,7 @@ Linux Tracing Technologies
    histogram-design
    boottime-trace
    hwlat_detector
+   osnoise-tracer
    intel_th
    ring-buffer-design
    stm
Documentation/trace/osnoise-tracer.rst new file +152 -0

152 lines not on this page · raw message

arch/x86/kernel/Makefile +1 -0
index 0f66682ac02a..3e625c61f008 100644
@@ -102,6 +102,7 @@ obj-$(CONFIG_FUNCTION_TRACER)	+= ftrace_$(BITS).o
 obj-$(CONFIG_FUNCTION_GRAPH_TRACER) += ftrace.o
 obj-$(CONFIG_FTRACE_SYSCALLS)	+= ftrace.o
 obj-$(CONFIG_X86_TSC)		+= trace_clock.o
+obj-$(CONFIG_TRACING)		+= trace.o
 obj-$(CONFIG_CRASH_CORE)	+= crash_core_$(BITS).o
 obj-$(CONFIG_KEXEC_CORE)	+= machine_kexec_$(BITS).o
 obj-$(CONFIG_KEXEC_CORE)	+= relocate_kernel_$(BITS).o crash.o
arch/x86/kernel/trace.c new file +237 -0

237 lines not on this page · raw message

include/linux/ftrace_irq.h +13 -0
index 0abd9a1d2852..f6faa31289ba 100644
@@ -7,12 +7,21 @@ extern bool trace_hwlat_callback_enabled;
 extern void trace_hwlat_callback(bool enter);
 #endif
 
+#ifdef CONFIG_OSNOISE_TRACER
+extern bool trace_osnoise_callback_enabled;
+extern void trace_osnoise_callback(bool enter);
+#endif
+
 static inline void ftrace_nmi_enter(void)
 {
 #ifdef CONFIG_HWLAT_TRACER
 	if (trace_hwlat_callback_enabled)
 		trace_hwlat_callback(true);
 #endif
+#ifdef CONFIG_OSNOISE_TRACER
+	if (trace_osnoise_callback_enabled)
+		trace_osnoise_callback(true);
+#endif
 }
 
 static inline void ftrace_nmi_exit(void)
@@ -21,6 +30,10 @@ static inline void ftrace_nmi_exit(void)
 	if (trace_hwlat_callback_enabled)
 		trace_hwlat_callback(false);
 #endif
+#ifdef CONFIG_OSNOISE_TRACER
+	if (trace_osnoise_callback_enabled)
+		trace_osnoise_callback(false);
+#endif
 }
 
 #endif /* _LINUX_FTRACE_IRQ_H */
include/linux/trace.h +5 -0
index be1e130ed87c..4e3858640c47 100644
@@ -41,6 +41,11 @@ int trace_array_init_printk(struct trace_array *tr);
 void trace_array_put(struct trace_array *tr);
 struct trace_array *trace_array_get_by_name(const char *name);
 int trace_array_destroy(struct trace_array *tr);
+
+/* For osnoise tracer */
+int osnoise_arch_register(void);
+void osnoise_arch_unregister(void);
+
 #endif	/* CONFIG_TRACING */
 
 #endif	/* _LINUX_TRACE_H */
include/trace/events/osnoise.h new file +142 -0

142 lines not on this page · raw message

kernel/trace/Kconfig +34 -0
index 7fa82778c3e6..41582ae4682b 100644
@@ -356,6 +356,40 @@ config HWLAT_TRACER
 	 file. Every time a latency is greater than tracing_thresh, it will
 	 be recorded into the ring buffer.
 
+config OSNOISE_TRACER
+	bool "OS Noise tracer"
+	select GENERIC_TRACER
+	help
+	  In the context of high-performance computing (HPC), the Operating
+	  System Noise (osnoise) refers to the interference experienced by an
+	  application due to activities inside the operating system. In the
+	  context of Linux, NMIs, IRQs, SoftIRQs, and any other system thread
+	  can cause noise to the system. Moreover, hardware-related jobs can
+	  also cause noise, for example, via SMIs.
+
+	  The osnoise tracer leverages the hwlat_detector by running a similar
+	  loop with preemption, SoftIRQs and IRQs enabled, thus allowing all
+	  the sources of osnoise during its execution. The osnoise tracer takes
+	  note of the entry and exit point of any source of interferences,
+	  increasing a per-cpu interference counter. It saves an interference
+	  counter for each source of interference. The interference counter for
+	  NMI, IRQs, SoftIRQs, and threads is increased anytime the tool
+	  observes these interferences' entry events. When a noise happens
+	  without any interference from the operating system level, the
+	  hardware noise counter increases, pointing to a hardware-related
+	  noise. In this way, osnoise can account for any source of
+	  interference. At the end of the period, the osnoise tracer prints
+	  the sum of all noise, the max single noise, the percentage of CPU
+	  available for the thread, and the counters for the noise sources.
+
+	  In addition to the tracer, a set of tracepoints were added to
+	  facilitate the identification of the osnoise source.
+
+	  The output will appear in the trace and trace_pipe files.
+
+	  To enable this tracer, echo in "osnoise" into the current_tracer
+          file.
+
 config MMIOTRACE
 	bool "Memory mapped IO tracing"
 	depends on HAVE_MMIOTRACE_SUPPORT && PCI
kernel/trace/Makefile +1 -0
index b28d3e5013cd..b1c47ccf4f73 100644
@@ -58,6 +58,7 @@ obj-$(CONFIG_IRQSOFF_TRACER) += trace_irqsoff.o
 obj-$(CONFIG_PREEMPT_TRACER) += trace_irqsoff.o
 obj-$(CONFIG_SCHED_TRACER) += trace_sched_wakeup.o
 obj-$(CONFIG_HWLAT_TRACER) += trace_hwlat.o
+obj-$(CONFIG_OSNOISE_TRACER) += trace_osnoise.o
 obj-$(CONFIG_NOP_TRACER) += trace_nop.o
 obj-$(CONFIG_STACK_TRACER) += trace_stack.o
 obj-$(CONFIG_MMIOTRACE) += trace_mmiotrace.o
kernel/trace/trace.h +6 -3
index 87588d1e24ca..b959c9ec9711 100644
@@ -44,6 +44,7 @@ enum trace_type {
 	TRACE_BLK,
 	TRACE_BPUTS,
 	TRACE_HWLAT,
+	TRACE_OSNOISE,
 	TRACE_RAW_DATA,
 	TRACE_FUNC_REPEATS,
 
@@ -297,7 +298,8 @@ struct trace_array {
 	struct array_buffer	max_buffer;
 	bool			allocated_snapshot;
 #endif
-#if defined(CONFIG_TRACER_MAX_TRACE) || defined(CONFIG_HWLAT_TRACER)
+#if defined(CONFIG_TRACER_MAX_TRACE) || defined(CONFIG_HWLAT_TRACER) \
+	|| defined(CONFIG_OSNOISE_TRACER)
 	unsigned long		max_latency;
 #ifdef CONFIG_FSNOTIFY
 	struct dentry		*d_max_latency;
@@ -445,6 +447,7 @@ extern void __ftrace_bad_type(void);
 		IF_ASSIGN(var, ent, struct bprint_entry, TRACE_BPRINT);	\
 		IF_ASSIGN(var, ent, struct bputs_entry, TRACE_BPUTS);	\
 		IF_ASSIGN(var, ent, struct hwlat_entry, TRACE_HWLAT);	\
+		IF_ASSIGN(var, ent, struct osnoise_entry, TRACE_OSNOISE);\
 		IF_ASSIGN(var, ent, struct raw_data_entry, TRACE_RAW_DATA);\
 		IF_ASSIGN(var, ent, struct trace_mmiotrace_rw,		\
 			  TRACE_MMIO_RW);				\
@@ -675,8 +678,8 @@ void update_max_tr_single(struct trace_array *tr,
 			  struct task_struct *tsk, int cpu);
 #endif /* CONFIG_TRACER_MAX_TRACE */
 
-#if (defined(CONFIG_TRACER_MAX_TRACE) || defined(CONFIG_HWLAT_TRACER)) && \
-	defined(CONFIG_FSNOTIFY)
+#if (defined(CONFIG_TRACER_MAX_TRACE) || defined(CONFIG_HWLAT_TRACER) \
+	|| defined(CONFIG_OSNOISE_TRACER)) && defined(CONFIG_FSNOTIFY)
 #define LATENCY_FS_NOTIFY
 #endif
 
kernel/trace/trace_entries.h +25 -0
index 251c819cf0c5..158c0984b59b 100644
@@ -360,3 +360,28 @@ FTRACE_ENTRY(func_repeats, func_repeats_entry,
 		 __entry->count,
 		 FUNC_REPEATS_GET_DELTA_TS(__entry))
 );
+
+FTRACE_ENTRY(osnoise, osnoise_entry,
+
+	TRACE_OSNOISE,
+
+	F_STRUCT(
+		__field(	u64,			noise		)
+		__field(	u64,			runtime		)
+		__field(	u64,			max_sample	)
+		__field(	unsigned int,		hw_count	)
+		__field(	unsigned int,		nmi_count	)
+		__field(	unsigned int,		irq_count	)
+		__field(	unsigned int,		softirq_count	)
+		__field(	unsigned int,		thread_count	)
+	),
+
+	F_printk("noise:%llu\tmax_sample:%llu\thw:%u\tnmi:%u\tirq:%u\tsoftirq:%u\tthread:%u\n",
+		 __entry->noise,
+		 __entry->max_sample,
+		 __entry->hw_count,
+		 __entry->nmi_count,
+		 __entry->irq_count,
+		 __entry->softirq_count,
+		 __entry->thread_count)
+);
kernel/trace/trace_osnoise.c new file +1384 -0

1,384 lines not on this page · raw message

kernel/trace/trace_output.c +71 -1

90 lines not on this page · raw message

Signature · 1 line
2.30.2
author maintainer
#22 lore raw

PATCH 21/24 trace: Add timerlat tracer

In reply to Steven Rostedt

From: Daniel Bristot de Oliveira <[email protected]>

The timerlat tracer aims to help the preemptive kernel developers to found souces of wakeup latencies of real-time threads. Like cyclictest, the tracer sets a periodic timer that wakes up a thread. The thread then computes a *wakeup latency* value as the difference between the *current time* and the *absolute time* that the timer was set to expire. The main goal of timerlat is tracing in such a way to help kernel developers.

Usage

Write the ASCII text "timerlat" into the current_tracer file of the tracing system (generally mounted at /sys/kernel/tracing).

For example:

[root@f32 ~]# cd /sys/kernel/tracing/ [root@f32 tracing]# echo timerlat > current_tracer

It is possible to follow the trace by reading the trace trace file:

[root@f32 tracing]# cat trace
# tracer: timerlat
#
# _-----=> irqs-off
# / _----=> need-resched

  #                            | / _---=> hardirq/softirq
  #                            || / _--=> preempt-depth
  #                            || /
  #                            ||||             ACTIVATION
  #         TASK-PID      CPU# ||||   TIMESTAMP    ID            CONTEXT                LATENCY
  #            | |         |   ||||      |         |                  |                       |
          <idle>-0       [000] d.h1    54.029328: #1     context    irq timer_latency       932 ns
           <...>-867     [000] ....    54.029339: #1     context thread timer_latency     11700 ns
          <idle>-0       [001] dNh1    54.029346: #1     context    irq timer_latency      2833 ns
           <...>-868     [001] ....    54.029353: #1     context thread timer_latency      9820 ns
          <idle>-0       [000] d.h1    54.030328: #2     context    irq timer_latency       769 ns
           <...>-867     [000] ....    54.030330: #2     context thread timer_latency      3070 ns
          <idle>-0       [001] d.h1    54.030344: #2     context    irq timer_latency       935 ns
           <...>-868     [001] ....    54.030347: #2     context thread timer_latency      4351 ns

The tracer creates a per-cpu kernel thread with real-time priority that prints two lines at every activation. The first is the *timer latency* observed at the *hardirq* context before the activation of the thread. The second is the *timer latency* observed by the thread, which is the same level that cyclictest reports. The ACTIVATION ID field serves to relate the *irq* execution to its respective *thread* execution.

The irq/thread splitting is important to clarify at which context the unexpected high value is coming from. The *irq* context can be delayed by hardware related actions, such as SMIs, NMIs, IRQs or by a thread masking interrupts. Once the timer happens, the delay can also be influenced by blocking caused by threads. For example, by postponing the scheduler execution via preempt_disable(), by the scheduler execution, or by masking interrupts. Threads can also be delayed by the interference from other threads and IRQs.

The timerlat can also take advantage of the osnoise: traceevents. For example:

        [root@f32 ~]# cd /sys/kernel/tracing/
        [root@f32 tracing]# echo timerlat > current_tracer
        [root@f32 tracing]# echo osnoise > set_event
        [root@f32 tracing]# echo 25 > osnoise/stop_tracing_total_us
        [root@f32 tracing]# tail -10 trace
             cc1-87882   [005] d..h...   548.771078: #402268 context    irq timer_latency      1585 ns
             cc1-87882   [005] dNLh1..   548.771082: irq_noise: local_timer:236 start 548.771077442 duration 4597 ns
             cc1-87882   [005] dNLh2..   548.771083: irq_noise: reschedule:253 start 548.771083017 duration 56 ns
             cc1-87882   [005] dNLh2..   548.771086: irq_noise: call_function_single:251 start 548.771083811 duration 2048 ns
             cc1-87882   [005] dNLh2..   548.771088: irq_noise: call_function_single:251 start 548.771086814 duration 1495 ns
             cc1-87882   [005] dNLh2..   548.771091: irq_noise: call_function_single:251 start 548.771089194 duration 1558 ns
             cc1-87882   [005] dNLh2..   548.771094: irq_noise: call_function_single:251 start 548.771091719 duration 1932 ns
             cc1-87882   [005] dNLh2..   548.771096: irq_noise: call_function_single:251 start 548.771094696 duration 1050 ns
             cc1-87882   [005] d...3..   548.771101: thread_noise:      cc1:87882 start 548.771078243 duration 10909 ns
      timerlat/5-1035    [005] .......   548.771103: #402268 context thread timer_latency     25960 ns

For further information see: Documentation/trace/timerlat-tracer.rst

Cc Phil Auld <[email protected]>
Cc Sebastian Andrzej Siewior <[email protected]>
Cc Kate Carcia <[email protected]>
Cc Jonathan Corbet <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Alexandre Chartre <[email protected]>
Cc Clark Willaims <[email protected]>
Cc John Kacur <[email protected]>
Cc Juri Lelli <[email protected]>
Cc Borislav Petkov <[email protected]>
Cc "H. Peter Anvin" <[email protected]>
---
 Documentation/trace/index.rst           |   1 +
 Documentation/trace/timerlat-tracer.rst | 181 +++++++
 kernel/trace/Kconfig                    |  28 ++
 kernel/trace/trace.h                    |   2 +
 kernel/trace/trace_entries.h            |  16 +
 kernel/trace/trace_osnoise.c            | 626 ++++++++++++++++++++++--
 kernel/trace/trace_output.c             |  47 ++
 7 files changed, 870 insertions(+), 31 deletions(-)
 create mode 100644 Documentation/trace/timerlat-tracer.rst
Documentation/trace/index.rst +1 -0
index 608107b27cc0..3769b9b7aed8 100644
@@ -24,6 +24,7 @@ Linux Tracing Technologies
    boottime-trace
    hwlat_detector
    osnoise-tracer
+   timerlat-tracer
    intel_th
    ring-buffer-design
    stm
Documentation/trace/timerlat-tracer.rst new file +181 -0

181 lines not on this page · raw message

kernel/trace/Kconfig +28 -0
index 41582ae4682b..d567b1717c4c 100644
@@ -390,6 +390,34 @@ config OSNOISE_TRACER
 	  To enable this tracer, echo in "osnoise" into the current_tracer
           file.
 
+config TIMERLAT_TRACER
+	bool "Timerlat tracer"
+	select OSNOISE_TRACER
+	select GENERIC_TRACER
+	help
+	  The timerlat tracer aims to help the preemptive kernel developers
+	  to find sources of wakeup latencies of real-time threads.
+
+	  The tracer creates a per-cpu kernel thread with real-time priority.
+	  The tracer thread sets a periodic timer to wakeup itself, and goes
+	  to sleep waiting for the timer to fire. At the wakeup, the thread
+	  then computes a wakeup latency value as the difference between
+	  the current time and the absolute time that the timer was set
+	  to expire.
+
+	  The tracer prints two lines at every activation. The first is the
+	  timer latency observed at the hardirq context before the
+	  activation of the thread. The second is the timer latency observed
+	  by the thread, which is the same level that cyclictest reports. The
+	  ACTIVATION ID field serves to relate the irq execution to its
+	  respective thread execution.
+
+	  The tracer is build on top of osnoise tracer, and the osnoise:
+	  events can be used to trace the source of interference from NMI,
+	  IRQs and other threads. It also enables the capture of the
+	  stacktrace at the IRQ context, which helps to identify the code
+	  path that can cause thread delay.
+
 config MMIOTRACE
 	bool "Memory mapped IO tracing"
 	depends on HAVE_MMIOTRACE_SUPPORT && PCI
kernel/trace/trace.h +2 -0
index b959c9ec9711..d83bbb6859b4 100644
@@ -45,6 +45,7 @@ enum trace_type {
 	TRACE_BPUTS,
 	TRACE_HWLAT,
 	TRACE_OSNOISE,
+	TRACE_TIMERLAT,
 	TRACE_RAW_DATA,
 	TRACE_FUNC_REPEATS,
 
@@ -448,6 +449,7 @@ extern void __ftrace_bad_type(void);
 		IF_ASSIGN(var, ent, struct bputs_entry, TRACE_BPUTS);	\
 		IF_ASSIGN(var, ent, struct hwlat_entry, TRACE_HWLAT);	\
 		IF_ASSIGN(var, ent, struct osnoise_entry, TRACE_OSNOISE);\
+		IF_ASSIGN(var, ent, struct timerlat_entry, TRACE_TIMERLAT);\
 		IF_ASSIGN(var, ent, struct raw_data_entry, TRACE_RAW_DATA);\
 		IF_ASSIGN(var, ent, struct trace_mmiotrace_rw,		\
 			  TRACE_MMIO_RW);				\
kernel/trace/trace_entries.h +16 -0
index 158c0984b59b..cd41e863b51c 100644
@@ -385,3 +385,19 @@ FTRACE_ENTRY(osnoise, osnoise_entry,
 		 __entry->softirq_count,
 		 __entry->thread_count)
 );
+
+FTRACE_ENTRY(timerlat, timerlat_entry,
+
+	TRACE_TIMERLAT,
+
+	F_STRUCT(
+		__field(	unsigned int,		seqnum		)
+		__field(	int,			context		)
+		__field(	u64,			timer_latency	)
+	),
+
+	F_printk("seq:%u\tcontext:%d\ttimer_latency:%llu\n",
+		 __entry->seqnum,
+		 __entry->context,
+		 __entry->timer_latency)
+);
kernel/trace/trace_osnoise.c +595 -31

810 lines not on this page · raw message

kernel/trace/trace_output.c +47 -0

59 lines not on this page · raw message

Signature · 1 line
2.30.2
author maintainer
#23 lore raw

PATCH 22/24 trace/hwlat: Protect kdata->kthread with get/put_online_cpus

In reply to Steven Rostedt

From: Daniel Bristot de Oliveira <[email protected]>

In preparation to the hotplug support, protect kdata->kthread with get/put_online_cpus() to avoid concurrency with hotplug operations.

Cc Phil Auld <[email protected]>
Cc Sebastian Andrzej Siewior <[email protected]>
Cc Kate Carcia <[email protected]>
Cc Jonathan Corbet <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Alexandre Chartre <[email protected]>
Cc Clark Willaims <[email protected]>
Cc John Kacur <[email protected]>
Cc Juri Lelli <[email protected]>
Cc Borislav Petkov <[email protected]>
Cc "H. Peter Anvin" <[email protected]>
---
 kernel/trace/trace_hwlat.c | 19 +++++++++++++------
 1 file changed, 13 insertions(+), 6 deletions(-)
kernel/trace/trace_hwlat.c +13 -6
index a625bfdb844e..20e31f79ebd9 100644
@@ -396,13 +396,19 @@ static int kthread_fn(void *data)
 static void stop_single_kthread(void)
 {
 	struct hwlat_kthread_data *kdata = get_cpu_data();
-	struct task_struct *kthread = kdata->kthread;
+	struct task_struct *kthread;
+
+	get_online_cpus();
+	kthread = kdata->kthread;
 
 	if (!kthread)
-		return;
+		goto out_put_cpus;
 
 	kthread_stop(kthread);
 	kdata->kthread = NULL;
+
+out_put_cpus:
+	put_online_cpus();
 }
 
 
@@ -419,20 +425,19 @@ static int start_single_kthread(struct trace_array *tr)
 	struct task_struct *kthread;
 	int next_cpu;
 
+	get_online_cpus();
 	if (kdata->kthread)
-		return 0;
+		goto out_put_cpus;
 
 	kthread = kthread_create(kthread_fn, NULL, "hwlatd");
 	if (IS_ERR(kthread)) {
 		pr_err(BANNER "could not start sampling thread\n");
+		put_online_cpus();
 		return -ENOMEM;
 	}
 
-
 	/* Just pick the first CPU on first iteration */
-	get_online_cpus();
 	cpumask_and(current_mask, cpu_online_mask, tr->tracing_cpumask);
-	put_online_cpus();
 
 	if (hwlat_data.thread_mode == MODE_ROUND_ROBIN) {
 		next_cpu = cpumask_first(current_mask);
@@ -446,6 +451,8 @@ static int start_single_kthread(struct trace_array *tr)
 	kdata->kthread = kthread;
 	wake_up_process(kthread);
 
+out_put_cpus:
+	put_online_cpus();
 	return 0;
 }
 
Signature · 1 line
2.30.2
author maintainer
#24 lore raw

PATCH 23/24 trace/hwlat: Support hotplug operations

In reply to Steven Rostedt

From: Daniel Bristot de Oliveira <[email protected]>

Enable and disable hwlat thread during cpu hotplug online and offline operations, respectivelly.

Cc Phil Auld <[email protected]>
Cc Sebastian Andrzej Siewior <[email protected]>
Cc Kate Carcia <[email protected]>
Cc Jonathan Corbet <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Alexandre Chartre <[email protected]>
Cc Clark Willaims <[email protected]>
Cc John Kacur <[email protected]>
Cc Juri Lelli <[email protected]>
Cc Borislav Petkov <[email protected]>
Cc "H. Peter Anvin" <[email protected]>
---
 kernel/trace/trace_hwlat.c | 65 ++++++++++++++++++++++++++++++++++++++
 1 file changed, 65 insertions(+)
kernel/trace/trace_hwlat.c +65 -0
index 20e31f79ebd9..a6c0cdaf4b87 100644
@@ -466,6 +466,7 @@ static void stop_cpu_kthread(unsigned int cpu)
 	kthread = per_cpu(hwlat_per_cpu_data, cpu).kthread;
 	if (kthread)
 		kthread_stop(kthread);
+	per_cpu(hwlat_per_cpu_data, cpu).kthread = NULL;
 }
 
 /*
@@ -506,6 +507,68 @@ static int start_cpu_kthread(unsigned int cpu)
 	return 0;
 }
 
+#ifdef CONFIG_HOTPLUG_CPU
+static void hwlat_hotplug_workfn(struct work_struct *dummy)
+{
+	struct trace_array *tr = hwlat_trace;
+	unsigned int cpu = smp_processor_id();
+
+	mutex_lock(&trace_types_lock);
+	mutex_lock(&hwlat_data.lock);
+	get_online_cpus();
+
+	if (!hwlat_busy || hwlat_data.thread_mode != MODE_PER_CPU)
+		goto out_unlock;
+
+	if (!cpumask_test_cpu(cpu, tr->tracing_cpumask))
+		goto out_unlock;
+
+	start_cpu_kthread(cpu);
+
+out_unlock:
+	put_online_cpus();
+	mutex_unlock(&hwlat_data.lock);
+	mutex_unlock(&trace_types_lock);
+}
+
+static DECLARE_WORK(hwlat_hotplug_work, hwlat_hotplug_workfn);
+
+/*
+ * hwlat_cpu_init - CPU hotplug online callback function
+ */
+static int hwlat_cpu_init(unsigned int cpu)
+{
+	schedule_work_on(cpu, &hwlat_hotplug_work);
+	return 0;
+}
+
+/*
+ * hwlat_cpu_die - CPU hotplug offline callback function
+ */
+static int hwlat_cpu_die(unsigned int cpu)
+{
+	stop_cpu_kthread(cpu);
+	return 0;
+}
+
+static void hwlat_init_hotplug_support(void)
+{
+	int ret;
+
+	ret = cpuhp_setup_state(CPUHP_AP_ONLINE_DYN, "trace/hwlat:online",
+				hwlat_cpu_init, hwlat_cpu_die);
+	if (ret < 0)
+		pr_warn(BANNER "Error to init cpu hotplug support\n");
+
+	return;
+}
+#else /* CONFIG_HOTPLUG_CPU */
+static void hwlat_init_hotplug_support(void)
+{
+	return;
+}
+#endif /* CONFIG_HOTPLUG_CPU */
+
 /*
  * start_per_cpu_kthreads - Kick off the hardware latency sampling/detector kthreads
  *
@@ -822,6 +885,8 @@ __init static int init_hwlat_tracer(void)
 	if (ret)
 		return ret;
 
+	hwlat_init_hotplug_support();
+
 	init_tracefs();
 
 	return 0;
Signature · 1 line
2.30.2
author maintainer
#25 lore raw

PATCH 24/24 trace/osnoise: Support hotplug operations

In reply to Steven Rostedt

From: Daniel Bristot de Oliveira <[email protected]>

Enable and disable osnoise/timerlat thread during on CPU hotplug online and offline operations respectivelly.

Cc Phil Auld <[email protected]>
Cc Sebastian Andrzej Siewior <[email protected]>
Cc Kate Carcia <[email protected]>
Cc Jonathan Corbet <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Alexandre Chartre <[email protected]>
Cc Clark Willaims <[email protected]>
Cc John Kacur <[email protected]>
Cc Juri Lelli <[email protected]>
Cc Borislav Petkov <[email protected]>
Cc "H. Peter Anvin" <[email protected]>
---
 kernel/trace/trace_osnoise.c | 165 ++++++++++++++++++++++++++++-------
 1 file changed, 135 insertions(+), 30 deletions(-)
kernel/trace/trace_osnoise.c +135 -30
index 8546e66bafcb..38aa5e208ffd 100644
@@ -1416,22 +1416,67 @@ static int timerlat_main(void *data)
 #endif /* CONFIG_TIMERLAT_TRACER */
 
 /*
- * stop_per_cpu_kthread - stop per-cpu threads
+ * stop_kthread - stop a workload thread
+ */
+static void stop_kthread(unsigned int cpu)
+{
+	struct task_struct *kthread;
+
+	kthread = per_cpu(per_cpu_osnoise_var, cpu).kthread;
+	if (kthread)
+		kthread_stop(kthread);
+	per_cpu(per_cpu_osnoise_var, cpu).kthread = NULL;
+}
+
+/*
+ * stop_per_cpu_kthread - Stop per-cpu threads
  *
  * Stop the osnoise sampling htread. Use this on unload and at system
  * shutdown.
  */
 static void stop_per_cpu_kthreads(void)
 {
-	struct task_struct *kthread;
 	int cpu;
 
-	for_each_online_cpu(cpu) {
-		kthread = per_cpu(per_cpu_osnoise_var, cpu).kthread;
-		if (kthread)
-			kthread_stop(kthread);
-		per_cpu(per_cpu_osnoise_var, cpu).kthread = NULL;
+	get_online_cpus();
+
+	for_each_online_cpu(cpu)
+		stop_kthread(cpu);
+
+	put_online_cpus();
+}
+
+/*
+ * start_kthread - Start a workload tread
+ */
+static int start_kthread(unsigned int cpu)
+{
+	struct task_struct *kthread;
+	void *main = osnoise_main;
+	char comm[24];
+
+#ifdef CONFIG_TIMERLAT_TRACER
+	if (osnoise_data.timerlat_tracer) {
+		snprintf(comm, 24, "timerlat/%d", cpu);
+		main = timerlat_main;
+	} else {
+		snprintf(comm, 24, "osnoise/%d", cpu);
 	}
+#else
+	snprintf(comm, 24, "osnoise/%d", cpu);
+#endif
+	kthread = kthread_create_on_cpu(main, NULL, cpu, comm);
+
+	if (IS_ERR(kthread)) {
+		pr_err(BANNER "could not start sampling thread\n");
+		stop_per_cpu_kthreads();
+		return -ENOMEM;
+	}
+
+	per_cpu(per_cpu_osnoise_var, cpu).kthread = kthread;
+	wake_up_process(kthread);
+
+	return 0;
 }
 
 /*
@@ -1443,9 +1488,7 @@ static void stop_per_cpu_kthreads(void)
 static int start_per_cpu_kthreads(struct trace_array *tr)
 {
 	struct cpumask *current_mask = &save_cpumask;
-	struct task_struct *kthread;
-	char comm[24];
-	void *main = osnoise_main;
+	int retval;
 	int cpu;
 
 	get_online_cpus();
@@ -1457,37 +1500,91 @@ static int start_per_cpu_kthreads(struct trace_array *tr)
 	 * And the CPU is online.
 	 */
 	cpumask_and(current_mask, cpu_online_mask, current_mask);
-	put_online_cpus();
 
-	for_each_online_cpu(cpu)
+	for_each_possible_cpu(cpu)
 		per_cpu(per_cpu_osnoise_var, cpu).kthread = NULL;
 
 	for_each_cpu(cpu, current_mask) {
-#ifdef CONFIG_TIMERLAT_TRACER
-		if (osnoise_data.timerlat_tracer) {
-			snprintf(comm, 24, "timerlat/%d", cpu);
-			main = timerlat_main;
-		} else {
-			snprintf(comm, 24, "osnoise/%d", cpu);
-		}
-#else
-		snprintf(comm, 24, "osnoise/%d", cpu);
-#endif
-		kthread = kthread_create_on_cpu(main, NULL, cpu, comm);
-
-		if (IS_ERR(kthread)) {
-			pr_err(BANNER "could not start sampling thread\n");
+		retval = start_kthread(cpu);
+		if (retval) {
 			stop_per_cpu_kthreads();
-			return -ENOMEM;
+			return retval;
 		}
-
-		per_cpu(per_cpu_osnoise_var, cpu).kthread = kthread;
-		wake_up_process(kthread);
 	}
 
+	put_online_cpus();
+
 	return 0;
 }
 
+#ifdef CONFIG_HOTPLUG_CPU
+static void osnoise_hotplug_workfn(struct work_struct *dummy)
+{
+	struct trace_array *tr = osnoise_trace;
+	unsigned int cpu = smp_processor_id();
+
+
+	mutex_lock(&trace_types_lock);
+
+	if (!osnoise_busy)
+		goto out_unlock_trace;
+
+	mutex_lock(&interface_lock);
+	get_online_cpus();
+
+	if (!cpumask_test_cpu(cpu, &osnoise_cpumask))
+		goto out_unlock;
+
+	if (!cpumask_test_cpu(cpu, tr->tracing_cpumask))
+		goto out_unlock;
+
+	start_kthread(cpu);
+
+out_unlock:
+	put_online_cpus();
+	mutex_unlock(&interface_lock);
+out_unlock_trace:
+	mutex_unlock(&trace_types_lock);
+}
+
+static DECLARE_WORK(osnoise_hotplug_work, osnoise_hotplug_workfn);
+
+/*
+ * osnoise_cpu_init - CPU hotplug online callback function
+ */
+static int osnoise_cpu_init(unsigned int cpu)
+{
+	schedule_work_on(cpu, &osnoise_hotplug_work);
+	return 0;
+}
+
+/*
+ * osnoise_cpu_die - CPU hotplug offline callback function
+ */
+static int osnoise_cpu_die(unsigned int cpu)
+{
+	stop_kthread(cpu);
+	return 0;
+}
+
+static void osnoise_init_hotplug_support(void)
+{
+	int ret;
+
+	ret = cpuhp_setup_state(CPUHP_AP_ONLINE_DYN, "trace/osnoise:online",
+				osnoise_cpu_init, osnoise_cpu_die);
+	if (ret < 0)
+		pr_warn(BANNER "Error to init cpu hotplug support\n");
+
+	return;
+}
+#else /* CONFIG_HOTPLUG_CPU */
+static void osnoise_init_hotplug_support(void)
+{
+	return 0;
+}
+#endif /* CONFIG_HOTPLUG_CPU */
+
 /*
  * osnoise_cpus_read - Read function for reading the "cpus" file
  * @filp: The active open file structure
@@ -1583,7 +1680,14 @@ osnoise_cpus_write(struct file *filp, const char __user *ubuf, size_t count,
 		osnoise_tracer_stop(tr);
 
 	mutex_lock(&interface_lock);
+	/*
+	 * osnoise_cpumask is read by CPU hotplug operations.
+	 */
+	get_online_cpus();
+
 	cpumask_copy(&osnoise_cpumask, osnoise_cpumask_new);
+
+	put_online_cpus();
 	mutex_unlock(&interface_lock);
 
 	if (running)
@@ -1940,6 +2044,7 @@ __init static int init_osnoise_tracer(void)
 		return ret;
 	}
 #endif
+	osnoise_init_hotplug_support();
 
 	init_tracefs();
 
Signature · 1 line
2.30.2