[PATCH 0/3] tracing: make tp_printk work on syscall tracepoints

[PATCH 0/3] tracing: make tp_printk work on syscall tracepoints

[Jeff Xie]

Currently the tp_printk option has no effect on syscall tracepoint.
When adding the kernel option parameter tp_printk, then:

echo 1 > /sys/kernel/debug/tracing/events/syscalls/enable

When running any application, no trace information is printed on the
terminal.

Now added printk for syscall tracepoints.

Jeff Xie (3):
  tracing: make tracepoint_iter_lock public
  tracing: make tracepoint_printk_key public
  tracing: make tp_printk work on syscall tracepoints

 kernel/trace/trace.c          |  4 ++--
 kernel/trace/trace.h          |  2 ++
 kernel/trace/trace_syscalls.c | 25 +++++++++++++++++++++++++
 3 files changed, 29 insertions(+), 2 deletions(-)

-- 
2.25.1

[PATCH 1/3] tracing: make tracepoint_iter_lock public

[Jeff Xie]

The syscall tracepoints need tracepoint_iter_lock for the tp_printk work.

Signed-off-by: Jeff Xie <xiehuan09@gmail.com>
---
 kernel/trace/trace.c | 2 +-
 kernel/trace/trace.h | 1 +
 2 files changed, 2 insertions(+), 1 deletion(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index eaf7d30ca6f1..867f00473f9f 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2833,7 +2833,7 @@ trace_event_buffer_lock_reserve(struct trace_buffer **current_rb,
 }
 EXPORT_SYMBOL_GPL(trace_event_buffer_lock_reserve);
 
-static DEFINE_SPINLOCK(tracepoint_iter_lock);
+DEFINE_SPINLOCK(tracepoint_iter_lock);
 static DEFINE_MUTEX(tracepoint_printk_mutex);
 
 static void output_printk(struct trace_event_buffer *fbuffer)
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 0f5e22238cd2..7ce345699ac2 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1523,6 +1523,7 @@ static inline void *event_file_data(struct file *filp)
 
 extern struct mutex event_mutex;
 extern struct list_head ftrace_events;
+extern spinlock_t tracepoint_iter_lock;
 
 extern const struct file_operations event_trigger_fops;
 extern const struct file_operations event_hist_fops;
-- 
2.25.1

[PATCH 2/3] tracing: make tracepoint_printk_key public

[Jeff Xie]

The syscall tracepoints need tracepoint_printk_key for the tp_printk work.

Signed-off-by: Jeff Xie <xiehuan09@gmail.com>
---
 kernel/trace/trace.c | 2 +-
 kernel/trace/trace.h | 1 +
 2 files changed, 2 insertions(+), 1 deletion(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 867f00473f9f..8efee5d339b9 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -88,7 +88,7 @@ void __init disable_tracing_selftest(const char *reason)
 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);
+DEFINE_STATIC_KEY_FALSE(tracepoint_printk_key);
 
 /* For tracers that don't implement custom flags */
 static struct tracer_opt dummy_tracer_opt[] = {
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 7ce345699ac2..f44a9510209c 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1524,6 +1524,7 @@ static inline void *event_file_data(struct file *filp)
 extern struct mutex event_mutex;
 extern struct list_head ftrace_events;
 extern spinlock_t tracepoint_iter_lock;
+DECLARE_STATIC_KEY_FALSE(tracepoint_printk_key);
 
 extern const struct file_operations event_trigger_fops;
 extern const struct file_operations event_hist_fops;
-- 
2.25.1

[PATCH 3/3] tracing: make tp_printk work on syscall tracepoints

[Jeff Xie]

Adding printk for syscall tracepoints for the tp_printk work.

Signed-off-by: Jeff Xie <xiehuan09@gmail.com>
---
 kernel/trace/trace_syscalls.c | 25 +++++++++++++++++++++++++
 1 file changed, 25 insertions(+)

diff --git a/kernel/trace/trace_syscalls.c b/kernel/trace/trace_syscalls.c
index f755bde42fd0..9798122166d3 100644
--- a/kernel/trace/trace_syscalls.c
+++ b/kernel/trace/trace_syscalls.c
@@ -290,6 +290,25 @@ static int __init syscall_enter_define_fields(struct trace_event_call *call)
 	return ret;
 }
 
+static void syscall_output_printk(struct trace_entry *ent,
+		struct trace_event_file *trace_file, struct trace_array *tr)
+{
+	unsigned long flags;
+	struct trace_iterator *iter = tracepoint_print_iter;
+	struct trace_event *event = &trace_file->event_call->event;
+
+	spin_lock_irqsave(&tracepoint_iter_lock, flags);
+
+	trace_seq_init(&iter->seq);
+	iter->ent = ent;
+	iter->tr = tr;
+	event->funcs->trace(iter, 0, event);
+	trace_seq_putc(&iter->seq, 0);
+	pr_info("%s", iter->seq.buffer);
+
+	spin_unlock_irqrestore(&tracepoint_iter_lock, flags);
+}
+
 static void ftrace_syscall_enter(void *data, struct pt_regs *regs, long id)
 {
 	struct trace_array *tr = data;
@@ -333,6 +352,9 @@ static void ftrace_syscall_enter(void *data, struct pt_regs *regs, long id)
 	syscall_get_arguments(current, regs, args);
 	memcpy(entry->args, args, sizeof(unsigned long) * sys_data->nb_args);
 
+	if (static_key_false(&tracepoint_printk_key.key))
+		syscall_output_printk(&entry->ent, trace_file, tr);
+
 	event_trigger_unlock_commit(trace_file, buffer, event, entry,
 				    trace_ctx);
 }
@@ -376,6 +398,9 @@ static void ftrace_syscall_exit(void *data, struct pt_regs *regs, long ret)
 	entry->nr = syscall_nr;
 	entry->ret = syscall_get_return_value(current, regs);
 
+	if (static_key_false(&tracepoint_printk_key.key))
+		syscall_output_printk(&entry->ent, trace_file, tr);
+
 	event_trigger_unlock_commit(trace_file, buffer, event, entry,
 				    trace_ctx);
 }
-- 
2.25.1

Re: [PATCH 3/3] tracing: make tp_printk work on syscall tracepoints

[Steven Rostedt]

On Wed, 30 Mar 2022 00:39:31 +0800
Jeff Xie <xiehuan09@gmail.com> wrote:

First, patch 1 and 2 can be folded into this patch. Making something
"available for future use" is not a reason to break up patches. It will not
help in bisecting, and its not something to be backported.

Next, the tracing subsystem follows the "Capitalize first letter" for
subjects:

 "tracing: Make tp_printk work on syscall tracepoints"

> Adding printk for syscall tracepoints for the tp_printk work.

Need to add much more content to the above. Your cover letter would work.

    Currently the tp_printk option has no effect on syscall tracepoint.
    When adding the kernel option parameter tp_printk, then:

    echo 1 > /sys/kernel/debug/tracing/events/syscalls/enable

    When running any application, no trace information is printed on the
    terminal.

    Now added printk for syscall tracepoints.

As commit logs should be self explanatory per commit. The cover letter was,
but this patch was lacking.


> 
> Signed-off-by: Jeff Xie <xiehuan09@gmail.com>
> ---
>  kernel/trace/trace_syscalls.c | 25 +++++++++++++++++++++++++
>  1 file changed, 25 insertions(+)
> 
> diff --git a/kernel/trace/trace_syscalls.c b/kernel/trace/trace_syscalls.c
> index f755bde42fd0..9798122166d3 100644
> --- a/kernel/trace/trace_syscalls.c
> +++ b/kernel/trace/trace_syscalls.c
> @@ -290,6 +290,25 @@ static int __init syscall_enter_define_fields(struct trace_event_call *call)
>  	return ret;
>  }
>  
> +static void syscall_output_printk(struct trace_entry *ent,
> +		struct trace_event_file *trace_file, struct trace_array *tr)
> +{
> +	unsigned long flags;
> +	struct trace_iterator *iter = tracepoint_print_iter;
> +	struct trace_event *event = &trace_file->event_call->event;
> +
> +	spin_lock_irqsave(&tracepoint_iter_lock, flags);
> +
> +	trace_seq_init(&iter->seq);
> +	iter->ent = ent;
> +	iter->tr = tr;
> +	event->funcs->trace(iter, 0, event);
> +	trace_seq_putc(&iter->seq, 0);
> +	pr_info("%s", iter->seq.buffer);
> +
> +	spin_unlock_irqrestore(&tracepoint_iter_lock, flags);
> +}
> +
>  static void ftrace_syscall_enter(void *data, struct pt_regs *regs, long id)
>  {
>  	struct trace_array *tr = data;
> @@ -333,6 +352,9 @@ static void ftrace_syscall_enter(void *data, struct pt_regs *regs, long id)
>  	syscall_get_arguments(current, regs, args);
>  	memcpy(entry->args, args, sizeof(unsigned long) * sys_data->nb_args);
>  
> +	if (static_key_false(&tracepoint_printk_key.key))
> +		syscall_output_printk(&entry->ent, trace_file, tr);
> +
>  	event_trigger_unlock_commit(trace_file, buffer, event, entry,
>  				    trace_ctx);


>  }
> @@ -376,6 +398,9 @@ static void ftrace_syscall_exit(void *data, struct pt_regs *regs, long ret)
>  	entry->nr = syscall_nr;
>  	entry->ret = syscall_get_return_value(current, regs);
>  
> +	if (static_key_false(&tracepoint_printk_key.key))
> +		syscall_output_printk(&entry->ent, trace_file, tr);
> +

Instead of reimplementing the logic, just convert the syscall code to use,
trace_event_buffer_reserve() and trace_event_buffer_commit(), and then you
not only get tp_printk() for syscalls, but also other features as well.

-- Steve


>  	event_trigger_unlock_commit(trace_file, buffer, event, entry,
>  				    trace_ctx);
>  }

Re: [PATCH 3/3] tracing: make tp_printk work on syscall tracepoints

[Jeff Xie]

Hi steve,

On Sat, Apr 9, 2022 at 5:18 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Wed, 30 Mar 2022 00:39:31 +0800
> Jeff Xie <xiehuan09@gmail.com> wrote:
>
> First, patch 1 and 2 can be folded into this patch. Making something
> "available for future use" is not a reason to break up patches. It will not
> help in bisecting, and its not something to be backported.
>
> Next, the tracing subsystem follows the "Capitalize first letter" for
> subjects:
>
>  "tracing: Make tp_printk work on syscall tracepoints"
>
> > Adding printk for syscall tracepoints for the tp_printk work.
>
> Need to add much more content to the above. Your cover letter would work.
>
>     Currently the tp_printk option has no effect on syscall tracepoint.
>     When adding the kernel option parameter tp_printk, then:
>
>     echo 1 > /sys/kernel/debug/tracing/events/syscalls/enable
>
>     When running any application, no trace information is printed on the
>     terminal.
>
>     Now added printk for syscall tracepoints.
>
> As commit logs should be self explanatory per commit. The cover letter was,
> but this patch was lacking.

Thanks a lot for these detailed suggestions.

>
> >
> > Signed-off-by: Jeff Xie <xiehuan09@gmail.com>
> > ---
> >  kernel/trace/trace_syscalls.c | 25 +++++++++++++++++++++++++
> >  1 file changed, 25 insertions(+)
> >
> > diff --git a/kernel/trace/trace_syscalls.c b/kernel/trace/trace_syscalls.c
> > index f755bde42fd0..9798122166d3 100644
> > --- a/kernel/trace/trace_syscalls.c
> > +++ b/kernel/trace/trace_syscalls.c
> > @@ -290,6 +290,25 @@ static int __init syscall_enter_define_fields(struct trace_event_call *call)
> >       return ret;
> >  }
> >
> > +static void syscall_output_printk(struct trace_entry *ent,
> > +             struct trace_event_file *trace_file, struct trace_array *tr)
> > +{
> > +     unsigned long flags;
> > +     struct trace_iterator *iter = tracepoint_print_iter;
> > +     struct trace_event *event = &trace_file->event_call->event;
> > +
> > +     spin_lock_irqsave(&tracepoint_iter_lock, flags);
> > +
> > +     trace_seq_init(&iter->seq);
> > +     iter->ent = ent;
> > +     iter->tr = tr;
> > +     event->funcs->trace(iter, 0, event);
> > +     trace_seq_putc(&iter->seq, 0);
> > +     pr_info("%s", iter->seq.buffer);
> > +
> > +     spin_unlock_irqrestore(&tracepoint_iter_lock, flags);
> > +}
> > +
> >  static void ftrace_syscall_enter(void *data, struct pt_regs *regs, long id)
> >  {
> >       struct trace_array *tr = data;
> > @@ -333,6 +352,9 @@ static void ftrace_syscall_enter(void *data, struct pt_regs *regs, long id)
> >       syscall_get_arguments(current, regs, args);
> >       memcpy(entry->args, args, sizeof(unsigned long) * sys_data->nb_args);
> >
> > +     if (static_key_false(&tracepoint_printk_key.key))
> > +             syscall_output_printk(&entry->ent, trace_file, tr);
> > +
> >       event_trigger_unlock_commit(trace_file, buffer, event, entry,
> >                                   trace_ctx);
>
>
> >  }
> > @@ -376,6 +398,9 @@ static void ftrace_syscall_exit(void *data, struct pt_regs *regs, long ret)
> >       entry->nr = syscall_nr;
> >       entry->ret = syscall_get_return_value(current, regs);
> >
> > +     if (static_key_false(&tracepoint_printk_key.key))
> > +             syscall_output_printk(&entry->ent, trace_file, tr);
> > +
>
> Instead of reimplementing the logic, just convert the syscall code to use,
> trace_event_buffer_reserve() and trace_event_buffer_commit(), and then you
> not only get tp_printk() for syscalls, but also other features as well.

Thanks, I will prepare the V2.

> -- Steve
>
>
> >       event_trigger_unlock_commit(trace_file, buffer, event, entry,
> >                                   trace_ctx);
> >  }
>
---
JeffXie

Re: [PATCH 0/3] tracing: make tp_printk work on syscall tracepoints

[Jeff Xie]

Hi,

Anyone have any suggestions for this patch series? ;-)

On Wed, Mar 30, 2022 at 12:39 AM Jeff Xie <xiehuan09@gmail.com> wrote:
>
> Currently the tp_printk option has no effect on syscall tracepoint.
> When adding the kernel option parameter tp_printk, then:
>
> echo 1 > /sys/kernel/debug/tracing/events/syscalls/enable
>
> When running any application, no trace information is printed on the
> terminal.
>
> Now added printk for syscall tracepoints.
>
> Jeff Xie (3):
>   tracing: make tracepoint_iter_lock public
>   tracing: make tracepoint_printk_key public
>   tracing: make tp_printk work on syscall tracepoints
>
>  kernel/trace/trace.c          |  4 ++--
>  kernel/trace/trace.h          |  2 ++
>  kernel/trace/trace_syscalls.c | 25 +++++++++++++++++++++++++
>  3 files changed, 29 insertions(+), 2 deletions(-)
>
> --
> 2.25.1
>
---
JeffXie

Re: [PATCH 0/3] tracing: make tp_printk work on syscall tracepoints

[Steven Rostedt]

On Fri, 8 Apr 2022 22:21:18 +0800
Jeff Xie <xiehuan09@gmail.com> wrote:

> Anyone have any suggestions for this patch series? ;-)

Thanks for the reminder. I'll look at them now.

-- Steve