[PATCH] trace: Add migrate-disabled counter to tracing output.

[PATCH] trace: Add migrate-disabled counter to tracing output.

[Sebastian Andrzej Siewior]

From: Thomas Gleixner <tglx@linutronix.de>

migrate_disable() forbids task migration to another CPU. It is available
since v5.11 and has already users such as highmem or BPF. It is useful
to observe this task state in tracing which already has other states
like the preemption counter.

Add the migrate-disable counter to the trace entry so it shows up in the
trace. Due to the users mentioned above, it is already possible to
observe it:

|  bash-1108    [000] ...21    73.950578: rss_stat: mm_id=2213312838 curr=0 type=MM_ANONPAGES size=8192B
|  bash-1108    [000] d..31    73.951222: irq_disable: caller=flush_tlb_mm_range+0x115/0x130 parent=ptep_clear_flush+0x42/0x50
|  bash-1108    [000] d..31    73.951222: tlb_flush: pages:1 reason:local mm shootdown (3)

The last value is the migrate-disable counter.

Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
[bigeasy: patch description.]
Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
---
 include/linux/trace_events.h |  2 ++
 kernel/trace/trace.c         | 26 +++++++++++++++++++-------
 kernel/trace/trace_events.c  |  1 +
 kernel/trace/trace_output.c  |  5 +++++
 4 files changed, 27 insertions(+), 7 deletions(-)

diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
index ad413b382a3ca..7c4280b4c6be7 100644
--- a/include/linux/trace_events.h
+++ b/include/linux/trace_events.h
@@ -69,6 +69,7 @@ struct trace_entry {
 	unsigned char		flags;
 	unsigned char		preempt_count;
 	int			pid;
+	unsigned char		migrate_disable;
 };
 
 #define TRACE_EVENT_TYPE_MAX						\
@@ -157,6 +158,7 @@ static inline void tracing_generic_entry_update(struct trace_entry *entry,
 						unsigned int trace_ctx)
 {
 	entry->preempt_count		= trace_ctx & 0xff;
+	entry->migrate_disable		= (trace_ctx >> 8) & 0xff;
 	entry->pid			= current->pid;
 	entry->type			= type;
 	entry->flags =			trace_ctx >> 16;
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index c59dd35a6da5c..936b683c81c7a 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2603,6 +2603,15 @@ enum print_line_t trace_handle_return(struct trace_seq *s)
 }
 EXPORT_SYMBOL_GPL(trace_handle_return);
 
+static unsigned short migration_disable_value(void)
+{
+#if defined(CONFIG_SMP)
+	return current->migration_disabled;
+#else
+	return 0;
+#endif
+}
+
 unsigned int tracing_gen_ctx_irq_test(unsigned int irqs_status)
 {
 	unsigned int trace_flags = irqs_status;
@@ -2621,7 +2630,8 @@ unsigned int tracing_gen_ctx_irq_test(unsigned int irqs_status)
 		trace_flags |= TRACE_FLAG_NEED_RESCHED;
 	if (test_preempt_need_resched())
 		trace_flags |= TRACE_FLAG_PREEMPT_RESCHED;
-	return (trace_flags << 16) | (pc & 0xff);
+	return (trace_flags << 16) | (pc & 0xff) |
+		(migration_disable_value() & 0xff) << 8;
 }
 
 struct ring_buffer_event *
@@ -4177,9 +4187,10 @@ static void print_lat_help_header(struct seq_file *m)
 		    "#                  | / _----=> need-resched    \n"
 		    "#                  || / _---=> hardirq/softirq \n"
 		    "#                  ||| / _--=> preempt-depth   \n"
-		    "#                  |||| /     delay            \n"
-		    "#  cmd     pid     ||||| time  |   caller      \n"
-		    "#     \\   /        |||||  \\    |   /         \n");
+		    "#                  |||| / _-=> migrate-disable \n"
+		    "#                  ||||| /     delay           \n"
+		    "#  cmd     pid     |||||| time  |   caller     \n"
+		    "#     \\   /        ||||||  \\    |    /       \n");
 }
 
 static void print_event_info(struct array_buffer *buf, struct seq_file *m)
@@ -4217,9 +4228,10 @@ static void print_func_help_header_irq(struct array_buffer *buf, struct seq_file
 	seq_printf(m, "#                            %.*s / _----=> need-resched\n", prec, space);
 	seq_printf(m, "#                            %.*s| / _---=> hardirq/softirq\n", prec, space);
 	seq_printf(m, "#                            %.*s|| / _--=> preempt-depth\n", prec, space);
-	seq_printf(m, "#                            %.*s||| /     delay\n", prec, space);
-	seq_printf(m, "#           TASK-PID  %.*s CPU#  ||||   TIMESTAMP  FUNCTION\n", prec, "     TGID   ");
-	seq_printf(m, "#              | |    %.*s   |   ||||      |         |\n", prec, "       |    ");
+	seq_printf(m, "#                            %.*s||| / _-=> migrate-disable\n", prec, space);
+	seq_printf(m, "#                            %.*s|||| /     delay\n", prec, space);
+	seq_printf(m, "#           TASK-PID  %.*s CPU#  |||||  TIMESTAMP  FUNCTION\n", prec, "     TGID   ");
+	seq_printf(m, "#              | |    %.*s   |   |||||     |         |\n", prec, "       |    ");
 }
 
 void
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 80e96989770ed..80b09956d5a0f 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -183,6 +183,7 @@ static int trace_define_common_fields(void)
 	__common_field(unsigned char, flags);
 	__common_field(unsigned char, preempt_count);
 	__common_field(int, pid);
+	__common_field(unsigned char, migrate_disable);
 
 	return ret;
 }
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index a0bf446bb0348..5b642b502b00f 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -497,6 +497,11 @@ int trace_print_lat_fmt(struct trace_seq *s, struct trace_entry *entry)
 	else
 		trace_seq_putc(s, '.');
 
+	if (entry->migrate_disable)
+		trace_seq_printf(s, "%x", entry->migrate_disable);
+	else
+		trace_seq_putc(s, '.');
+
 	return !trace_seq_has_overflowed(s);
 }
 
-- 
2.32.0

Re: [PATCH] trace: Add migrate-disabled counter to tracing output.

[Steven Rostedt]

On Fri, 6 Aug 2021 18:49:07 +0200
Sebastian Andrzej Siewior <bigeasy@linutronix.de> wrote:

> From: Thomas Gleixner <tglx@linutronix.de>
> 
> migrate_disable() forbids task migration to another CPU. It is available
> since v5.11 and has already users such as highmem or BPF. It is useful
> to observe this task state in tracing which already has other states
> like the preemption counter.
> 
> Add the migrate-disable counter to the trace entry so it shows up in the
> trace. Due to the users mentioned above, it is already possible to
> observe it:
> 
> |  bash-1108    [000] ...21    73.950578: rss_stat: mm_id=2213312838 curr=0 type=MM_ANONPAGES size=8192B
> |  bash-1108    [000] d..31    73.951222: irq_disable: caller=flush_tlb_mm_range+0x115/0x130 parent=ptep_clear_flush+0x42/0x50
> |  bash-1108    [000] d..31    73.951222: tlb_flush: pages:1 reason:local mm shootdown (3)
> 
> The last value is the migrate-disable counter.
> 
> Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
> [bigeasy: patch description.]
> Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
> ---
>  include/linux/trace_events.h |  2 ++
>  kernel/trace/trace.c         | 26 +++++++++++++++++++-------
>  kernel/trace/trace_events.c  |  1 +
>  kernel/trace/trace_output.c  |  5 +++++
>  4 files changed, 27 insertions(+), 7 deletions(-)
> 
> diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
> index ad413b382a3ca..7c4280b4c6be7 100644
> --- a/include/linux/trace_events.h
> +++ b/include/linux/trace_events.h
> @@ -69,6 +69,7 @@ struct trace_entry {
>  	unsigned char		flags;
>  	unsigned char		preempt_count;
>  	int			pid;
> +	unsigned char		migrate_disable;

The only issue I have with this patch is this part. It extends the
header of all events beyond 8 bytes, and actually adds another 4 or 8
bytes despite being just a char in size. That's because this is a
header of a structure, which depending on the first field of an event,
padding may be added to have 4 or 8 byte alignment.

I'll be fine with merging this counter with either flags or
preempt_count (neither needs all 8 bits). I can figure out how to
update libtraceevent to handle this case.

-- Steve


>  };
>  
>  #define TRACE_EVENT_TYPE_MAX						\
> @@ -157,6 +158,7 @@ static inline void tracing_generic_entry_update(struct trace_entry *entry,
>  						unsigned int trace_ctx)

Re: [PATCH] trace: Add migrate-disabled counter to tracing output.

[Sebastian Andrzej Siewior]

On 2021-08-06 13:51:24 [-0400], Steven Rostedt wrote:
> > diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
> > index ad413b382a3ca..7c4280b4c6be7 100644
> > --- a/include/linux/trace_events.h
> > +++ b/include/linux/trace_events.h
> > @@ -69,6 +69,7 @@ struct trace_entry {
> >  	unsigned char		flags;
> >  	unsigned char		preempt_count;
> >  	int			pid;
> > +	unsigned char		migrate_disable;
> 
> The only issue I have with this patch is this part. It extends the
> header of all events beyond 8 bytes, and actually adds another 4 or 8
> bytes despite being just a char in size. That's because this is a
> header of a structure, which depending on the first field of an event,
> padding may be added to have 4 or 8 byte alignment.
> 
> I'll be fine with merging this counter with either flags or
> preempt_count (neither needs all 8 bits). I can figure out how to
> update libtraceevent to handle this case.

I was kind of expecting that. Let me try 4 bits for the preempt counter
and 4 bits for the migrate counter.

> -- Steve
> 

Sebastian

[PATCH v2] trace: Add migrate-disabled counter to tracing output.

[Sebastian Andrzej Siewior]

From: Thomas Gleixner <tglx@linutronix.de>

migrate_disable() forbids task migration to another CPU. It is available
since v5.11 and has already users such as highmem or BPF. It is useful
to observe this task state in tracing which already has other states
like the preemption counter.

Instead of adding the migrate disable counter as a new entry to struct
trace_entry, which would extend the whole struct by four bytes, it is
squashed into the preempt-disable counter. The lower four bits represent
the preemption counter, the upper four bits represent the migrate
disable counter. Both counter shouldn't exceed 15 but if they do, there
is a safety net which caps the value at 15.

Add the migrate-disable counter to the trace entry so it shows up in the
trace. Due to the users mentioned above, it is already possible to
observe it:

|  bash-1108    [000] ...21    73.950578: rss_stat: mm_id=2213312838 curr=0 type=MM_ANONPAGES size=8192B
|  bash-1108    [000] d..31    73.951222: irq_disable: caller=flush_tlb_mm_range+0x115/0x130 parent=ptep_clear_flush+0x42/0x50
|  bash-1108    [000] d..31    73.951222: tlb_flush: pages:1 reason:local mm shootdown (3)

The last value is the migrate-disable counter.

Things that popped up:
- trace_print_lat_context() does not print the migrate counter. Not sure
  if it should. It is used in "verbose" mode and uses 8 digits and I'm
  not sure ther is something processing the value.

- trace_define_common_fields() now defines a different variable. This
  probably breaks things. No ide what to do in order to preserve the old
  behaviour. Since this is used as a filter it should be split somehow
  to be able to match both nibbles here.

Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
[bigeasy: patch description.]
Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
---
v1…v2:
  - use the upper nibble of the preemption counter for the migrate
    disable counter and the lower for the preemption counter. This
    avoids extending the struct by four bytes due to alignment /
    padding.

 include/linux/trace_events.h |  4 ++--
 kernel/trace/trace.c         | 26 +++++++++++++++++++-------
 kernel/trace/trace_events.c  |  3 ++-
 kernel/trace/trace_output.c  | 11 ++++++++---
 4 files changed, 31 insertions(+), 13 deletions(-)

diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
index ad413b382a3ca..92680a59740e4 100644
--- a/include/linux/trace_events.h
+++ b/include/linux/trace_events.h
@@ -67,7 +67,7 @@ void trace_event_printf(struct trace_iterator *iter, const char *fmt, ...);
 struct trace_entry {
 	unsigned short		type;
 	unsigned char		flags;
-	unsigned char		preempt_count;
+	unsigned char		preempt_mg_count;
 	int			pid;
 };
 
@@ -156,7 +156,7 @@ static inline void tracing_generic_entry_update(struct trace_entry *entry,
 						unsigned short type,
 						unsigned int trace_ctx)
 {
-	entry->preempt_count		= trace_ctx & 0xff;
+	entry->preempt_mg_count		= trace_ctx & 0xff;
 	entry->pid			= current->pid;
 	entry->type			= type;
 	entry->flags =			trace_ctx >> 16;
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index c59dd35a6da5c..ea9082fdcc69a 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2603,6 +2603,15 @@ enum print_line_t trace_handle_return(struct trace_seq *s)
 }
 EXPORT_SYMBOL_GPL(trace_handle_return);
 
+static unsigned short migration_disable_value(void)
+{
+#if defined(CONFIG_SMP)
+	return current->migration_disabled;
+#else
+	return 0;
+#endif
+}
+
 unsigned int tracing_gen_ctx_irq_test(unsigned int irqs_status)
 {
 	unsigned int trace_flags = irqs_status;
@@ -2621,7 +2630,8 @@ unsigned int tracing_gen_ctx_irq_test(unsigned int irqs_status)
 		trace_flags |= TRACE_FLAG_NEED_RESCHED;
 	if (test_preempt_need_resched())
 		trace_flags |= TRACE_FLAG_PREEMPT_RESCHED;
-	return (trace_flags << 16) | (pc & 0xff);
+	return (trace_flags << 16) | (min_t(unsigned int, pc & 0xff, 0xf)) |
+		(min_t(unsigned int, migration_disable_value(), 0xf)) << 4;
 }
 
 struct ring_buffer_event *
@@ -4177,9 +4187,10 @@ static void print_lat_help_header(struct seq_file *m)
 		    "#                  | / _----=> need-resched    \n"
 		    "#                  || / _---=> hardirq/softirq \n"
 		    "#                  ||| / _--=> preempt-depth   \n"
-		    "#                  |||| /     delay            \n"
-		    "#  cmd     pid     ||||| time  |   caller      \n"
-		    "#     \\   /        |||||  \\    |   /         \n");
+		    "#                  |||| / _-=> migrate-disable \n"
+		    "#                  ||||| /     delay           \n"
+		    "#  cmd     pid     |||||| time  |   caller     \n"
+		    "#     \\   /        ||||||  \\    |    /       \n");
 }
 
 static void print_event_info(struct array_buffer *buf, struct seq_file *m)
@@ -4217,9 +4228,10 @@ static void print_func_help_header_irq(struct array_buffer *buf, struct seq_file
 	seq_printf(m, "#                            %.*s / _----=> need-resched\n", prec, space);
 	seq_printf(m, "#                            %.*s| / _---=> hardirq/softirq\n", prec, space);
 	seq_printf(m, "#                            %.*s|| / _--=> preempt-depth\n", prec, space);
-	seq_printf(m, "#                            %.*s||| /     delay\n", prec, space);
-	seq_printf(m, "#           TASK-PID  %.*s CPU#  ||||   TIMESTAMP  FUNCTION\n", prec, "     TGID   ");
-	seq_printf(m, "#              | |    %.*s   |   ||||      |         |\n", prec, "       |    ");
+	seq_printf(m, "#                            %.*s||| / _-=> migrate-disable\n", prec, space);
+	seq_printf(m, "#                            %.*s|||| /     delay\n", prec, space);
+	seq_printf(m, "#           TASK-PID  %.*s CPU#  |||||  TIMESTAMP  FUNCTION\n", prec, "     TGID   ");
+	seq_printf(m, "#              | |    %.*s   |   |||||     |         |\n", prec, "       |    ");
 }
 
 void
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 80e96989770ed..5817d14e8095f 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -181,7 +181,8 @@ static int trace_define_common_fields(void)
 
 	__common_field(unsigned short, type);
 	__common_field(unsigned char, flags);
-	__common_field(unsigned char, preempt_count);
+	/* XXX */
+	__common_field(unsigned char, preempt_mg_count);
 	__common_field(int, pid);
 
 	return ret;
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index a0bf446bb0348..def0d8de2df6f 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -492,8 +492,13 @@ int trace_print_lat_fmt(struct trace_seq *s, struct trace_entry *entry)
 	trace_seq_printf(s, "%c%c%c",
 			 irqs_off, need_resched, hardsoft_irq);
 
-	if (entry->preempt_count)
-		trace_seq_printf(s, "%x", entry->preempt_count);
+	if (entry->preempt_mg_count & 0xf)
+		trace_seq_printf(s, "%x", entry->preempt_mg_count & 0xf);
+	else
+		trace_seq_putc(s, '.');
+
+	if (entry->preempt_mg_count & 0xf0)
+		trace_seq_printf(s, "%x", entry->preempt_mg_count >> 4);
 	else
 		trace_seq_putc(s, '.');
 
@@ -656,7 +661,7 @@ int trace_print_lat_context(struct trace_iterator *iter)
 		trace_seq_printf(
 			s, "%16s %7d %3d %d %08x %08lx ",
 			comm, entry->pid, iter->cpu, entry->flags,
-			entry->preempt_count, iter->idx);
+			entry->preempt_mg_count & 0xf, iter->idx);
 	} else {
 		lat_print_generic(s, entry, iter->cpu);
 	}
-- 
2.32.0

Re: [PATCH v2] trace: Add migrate-disabled counter to tracing output.

[Sebastian Andrzej Siewior]

On 2021-08-10 15:26:26 [+0200], To Steven Rostedt wrote:
> From: Thomas Gleixner <tglx@linutronix.de>
> 
> migrate_disable() forbids task migration to another CPU. It is available
> since v5.11 and has already users such as highmem or BPF. It is useful
> to observe this task state in tracing which already has other states
> like the preemption counter.
> 
> Instead of adding the migrate disable counter as a new entry to struct
> trace_entry, which would extend the whole struct by four bytes, it is
> squashed into the preempt-disable counter. The lower four bits represent
> the preemption counter, the upper four bits represent the migrate
> disable counter. Both counter shouldn't exceed 15 but if they do, there
> is a safety net which caps the value at 15.
> 
> Add the migrate-disable counter to the trace entry so it shows up in the
> trace. Due to the users mentioned above, it is already possible to
> observe it:
> 
> |  bash-1108    [000] ...21    73.950578: rss_stat: mm_id=2213312838 curr=0 type=MM_ANONPAGES size=8192B
> |  bash-1108    [000] d..31    73.951222: irq_disable: caller=flush_tlb_mm_range+0x115/0x130 parent=ptep_clear_flush+0x42/0x50
> |  bash-1108    [000] d..31    73.951222: tlb_flush: pages:1 reason:local mm shootdown (3)
> 
> The last value is the migrate-disable counter.
> 
> Things that popped up:
> - trace_print_lat_context() does not print the migrate counter. Not sure
>   if it should. It is used in "verbose" mode and uses 8 digits and I'm
>   not sure ther is something processing the value.
> 
> - trace_define_common_fields() now defines a different variable. This
>   probably breaks things. No ide what to do in order to preserve the old
>   behaviour. Since this is used as a filter it should be split somehow
>   to be able to match both nibbles here.
> 
> Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
> [bigeasy: patch description.]
> Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
> ---
> v1…v2:
>   - use the upper nibble of the preemption counter for the migrate
>     disable counter and the lower for the preemption counter. This
>     avoids extending the struct by four bytes due to alignment /
>     padding.
 
 Ping.

Sebastian

Re: [PATCH v2] trace: Add migrate-disabled counter to tracing output.

[Steven Rostedt]

On Thu, 2 Sep 2021 09:16:50 +0200
Sebastian Andrzej Siewior <bigeasy@linutronix.de> wrote:

>  
>  Ping.

Crap, this fell through the cracks.

Let me pull it in and start testing it.

We still have another week of the merge window, luckily.

-- Steve

Re: [PATCH v2] trace: Add migrate-disabled counter to tracing output.

[Steven Rostedt]

BTW,

When doing a v2, always create a new thread. Never send it as a reply to
the previous patch. The reason I missed this is because replies to previous
patches do not end up in my internal patchwork. And I only look at that for
patches. Not my INBOX.


On Tue, 10 Aug 2021 15:26:25 +0200
Sebastian Andrzej Siewior <bigeasy@linutronix.de> wrote:

> --- a/kernel/trace/trace_events.c
> +++ b/kernel/trace/trace_events.c
> @@ -181,7 +181,8 @@ static int trace_define_common_fields(void)
>  
>  	__common_field(unsigned short, type);
>  	__common_field(unsigned char, flags);
> -	__common_field(unsigned char, preempt_count);
> +	/* XXX */
> +	__common_field(unsigned char, preempt_mg_count);
>  	__common_field(int, pid);
>  
>  	return ret;

I'm going to have to nuke this hunk of the patch, and update all the other
locations that have preempt_mg_count in it. Because I just tested it, and
this breaks user space.

 # trace-cmd record -e all sleep 1
 # trace-cmd report -l

   sleep-1903    2...ffffffff   743.721748: lock_release:         0xffffffffb1a2f428 trace_types_lock
   sleep-1903    2...ffffffff   743.721749: lock_release:         0xffff89b981318430 sb_writers
   sleep-1903    2d..ffffffff   743.721749: irq_disable:          caller=rcu_irq_enter_irqson+0x25 parent=0x0
   sleep-1903    2d..ffffffff   743.721749: irq_enable:           caller=rcu_irq_enter_irqson+0x2f parent=0x0
   sleep-1903    2...ffffffff   743.721750: preempt_disable:      caller=vfs_write+0x13a parent=vfs_write+0x13a
   sleep-1903    2d..ffffffff   743.721750: irq_disable:          caller=rcu_irq_exit_irqson+0x25 parent=0x0
   sleep-1903    2d..ffffffff   743.721750: irq_enable:           caller=rcu_irq_exit_irqson+0x2f parent=0x0
   sleep-1903    2d..ffffffff   743.721750: irq_disable:          caller=rcu_irq_enter_irqson+0x25 parent=0x0
   sleep-1903    2d..ffffffff   743.721750: irq_enable:           caller=rcu_irq_enter_irqson+0x2f parent=0x0
   sleep-1903    2...ffffffff   743.721750: preempt_enable:       caller=vfs_write+0x15c parent=vfs_write+0x15c
   sleep-1903    2d..ffffffff   743.721751: irq_disable:          caller=rcu_irq_exit_irqson+0x25 parent=0x0
   sleep-1903    2d..ffffffff   743.721751: irq_enable:           caller=rcu_irq_exit_irqson+0x2f parent=0x0
   sleep-1903    2...ffffffff   743.721751: lock_release:         0xffff89b8a144e4f0 &f->f_pos_lock
   sleep-1903    2...ffffffff   743.721751: sys_exit:             NR 1 = 1
   sleep-1903    2...ffffffff   743.721751: sys_exit_write:       0x1
   sleep-1903    2d..ffffffff   743.721752: irq_disable:          caller=syscall_exit_to_user_mode+0xe parent=0x0
   sleep-1903    2d..ffffffff   743.721752: irq_enable:           caller=syscall_exit_to_user_mode+0x1b parent=0x0

Because to parse the preempt portion, libtraceevent searches for
"common_preempt_count". When it's not found, -1 is used.

As the migrate disable is an offset, we can at least filter that.

And if and old libtraceevent is used, the preempt counts will be the
combination of both, and although it may be a little confusing, at least,
it can be figured out.

I'm going to fold the below patch into this patch if that's OK with you?

-- Steve

diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
index 5a679315fbed..0a0144580bbd 100644
--- a/include/linux/trace_events.h
+++ b/include/linux/trace_events.h
@@ -67,7 +67,7 @@ void trace_event_printf(struct trace_iterator *iter, const char *fmt, ...);
 struct trace_entry {
 	unsigned short		type;
 	unsigned char		flags;
-	unsigned char		preempt_mg_count;
+	unsigned char		preempt_count;
 	int			pid;
 };
 
@@ -156,7 +156,7 @@ static inline void tracing_generic_entry_update(struct trace_entry *entry,
 						unsigned short type,
 						unsigned int trace_ctx)
 {
-	entry->preempt_mg_count		= trace_ctx & 0xff;
+	entry->preempt_count		= trace_ctx & 0xff;
 	entry->pid			= current->pid;
 	entry->type			= type;
 	entry->flags =			trace_ctx >> 16;
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index d3715e2f6707..830b3b9940f4 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -181,8 +181,8 @@ static int trace_define_common_fields(void)
 
 	__common_field(unsigned short, type);
 	__common_field(unsigned char, flags);
-	/* XXX */
-	__common_field(unsigned char, preempt_mg_count);
+	/* Holds both preempt_count and migrate_disable */
+	__common_field(unsigned char, preempt_count);
 	__common_field(int, pid);
 
 	return ret;
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index def0d8de2df6..c2ca40e8595b 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -492,13 +492,13 @@ int trace_print_lat_fmt(struct trace_seq *s, struct trace_entry *entry)
 	trace_seq_printf(s, "%c%c%c",
 			 irqs_off, need_resched, hardsoft_irq);
 
-	if (entry->preempt_mg_count & 0xf)
-		trace_seq_printf(s, "%x", entry->preempt_mg_count & 0xf);
+	if (entry->preempt_count & 0xf)
+		trace_seq_printf(s, "%x", entry->preempt_count & 0xf);
 	else
 		trace_seq_putc(s, '.');
 
-	if (entry->preempt_mg_count & 0xf0)
-		trace_seq_printf(s, "%x", entry->preempt_mg_count >> 4);
+	if (entry->preempt_count & 0xf0)
+		trace_seq_printf(s, "%x", entry->preempt_count >> 4);
 	else
 		trace_seq_putc(s, '.');
 
@@ -661,7 +661,7 @@ int trace_print_lat_context(struct trace_iterator *iter)
 		trace_seq_printf(
 			s, "%16s %7d %3d %d %08x %08lx ",
 			comm, entry->pid, iter->cpu, entry->flags,
-			entry->preempt_mg_count & 0xf, iter->idx);
+			entry->preempt_count & 0xf, iter->idx);
 	} else {
 		lat_print_generic(s, entry, iter->cpu);
 	}

Re: [PATCH v2] trace: Add migrate-disabled counter to tracing output.

[Sebastian Andrzej Siewior]

On 2021-09-03 19:42:16 [-0400], Steven Rostedt wrote:
Hi Steven,

> BTW,
> 
> When doing a v2, always create a new thread. Never send it as a reply to
> the previous patch. The reason I missed this is because replies to previous
> patches do not end up in my internal patchwork. And I only look at that for
> patches. Not my INBOX.

oki.

> 
> > --- a/kernel/trace/trace_events.c
> > +++ b/kernel/trace/trace_events.c
> > @@ -181,7 +181,8 @@ static int trace_define_common_fields(void)
> >  
> >  	__common_field(unsigned short, type);
> >  	__common_field(unsigned char, flags);
> > -	__common_field(unsigned char, preempt_count);
> > +	/* XXX */
> > +	__common_field(unsigned char, preempt_mg_count);
> >  	__common_field(int, pid);
> >  
> >  	return ret;
> 
> I'm going to have to nuke this hunk of the patch, and update all the other
> locations that have preempt_mg_count in it. Because I just tested it, and
> this breaks user space.

I left that with that XXX on purpose so you can look and comment and say
how to fix it. The problem I had with preempt_count was that only the
lower nibble contains the preemption counter. So I thought you could
easily came up with something how this can be split or taught to only
expose the lower nibble. I didn't after a few attempts.
My understanding is that this `preempt_count' is also used in the filter
tracefs file so something like "preempt_count > 1" > filter would also
match for migrate_count = 2, preempt_count = 1. You seem to be happy to
filter in user space.

Sebastian

Re: [PATCH v2] trace: Add migrate-disabled counter to tracing output.

[Steven Rostedt]

On Mon, 6 Sep 2021 10:13:43 +0200
Sebastian Andrzej Siewior <bigeasy@linutronix.de> wrote:

> I left that with that XXX on purpose so you can look and comment and say
> how to fix it. The problem I had with preempt_count was that only the
> lower nibble contains the preemption counter. So I thought you could
> easily came up with something how this can be split or taught to only
> expose the lower nibble. I didn't after a few attempts.
> My understanding is that this `preempt_count' is also used in the filter
> tracefs file so something like "preempt_count > 1" > filter would also
> match for migrate_count = 2, preempt_count = 1. You seem to be happy to
> filter in user space.

Right. It will break filtering, and I don't see a good way to handle that.

That said, I'll update the code to handle comparing fields with a mask.
I'll need to do this with the kernel as well.

I'm fine with breaking the filtering on preempt_count over having it just
fail to print it at all.

-- Steve

Re: [PATCH v2] trace: Add migrate-disabled counter to tracing output.

[Sebastian Andrzej Siewior]

On 2021-09-07 11:21:28 [-0400], Steven Rostedt wrote:
> Right. It will break filtering, and I don't see a good way to handle that.
> 
> That said, I'll update the code to handle comparing fields with a mask.
> I'll need to do this with the kernel as well.
> 
> I'm fine with breaking the filtering on preempt_count over having it just
> fail to print it at all.

This was my only concern and if it does not matter even better ;)
Thank you.

> -- Steve

Sebastian