subject:"\[PATCH v7 4\/4\] ftrace\: Add an option for tracing console latencies"

Re: [PATCH v7 4/4] ftrace: Add an option for tracing console latencies

2019-10-03 Thread Joel Fernandes

On Thu, Oct 03, 2019 at 12:44:09AM +0200, Viktor Rosendahl wrote:
> On 10/2/19 2:52 AM, Joel Fernandes wrote:
> > On Fri, Sep 20, 2019 at 05:22:19PM +0200, Viktor Rosendahl (BMW) wrote:
> > > This new trace option "console-latency" will enable the latency
> > > tracers to trace the console latencies. Previously this has always been
> > > implicitely disabled. I guess this is because they are considered
> > > to be well known and unavoidable.
> > > 
> > > However, for some organizations it may nevertheless be desirable to
> > > trace them. Basically, we want to be able to tell that there are
> > > latencies in the system under test because someone has incorrectly
> > > enabled the serial console.
> > > 
> > > Signed-off-by: Viktor Rosendahl (BMW) 
> > > ---
> > >   include/linux/irqflags.h | 22 ++
> > >   kernel/printk/printk.c   |  6 --
> > >   kernel/trace/trace.h |  1 +
> > >   kernel/trace/trace_irqsoff.c | 12 
> > >   4 files changed, 39 insertions(+), 2 deletions(-)
> > > 
> > > diff --git a/include/linux/irqflags.h b/include/linux/irqflags.h
> > > index 21619c92c377..3de891723331 100644
> > > --- a/include/linux/irqflags.h
> > > +++ b/include/linux/irqflags.h
> > > @@ -13,6 +13,7 @@
> > >   #define _LINUX_TRACE_IRQFLAGS_H
> > >   #include 
> > > +#include 
> > >   #include 
> > >   /* Currently trace_softirqs_on/off is used only by lockdep */
> > > @@ -68,9 +69,30 @@ do {   \
> > >   defined(CONFIG_PREEMPT_TRACER)
> > >extern void stop_critical_timings(void);
> > >extern void start_critical_timings(void);
> > > + extern bool console_tracing_disabled(void);
> > > +
> > > +# define console_stop_critical_timings(flag) \
> > > + do {\
> > > + typecheck(bool, flag);  \
> > > + flag = console_tracing_disabled();  \
> > > + if (flag)   \
> > > + stop_critical_timings();\
> > > + } while (0)
> > > +
> > > +# define console_start_critical_timings(flag) \
> > > + do { \
> > > + typecheck(bool, flag);   \
> > > + if (flag)\
> > > + start_critical_timings();\
> > > + } while (0)
> > > +
> > >   #else
> > >   # define stop_critical_timings() do { } while (0)
> > >   # define start_critical_timings() do { } while (0)
> > > +# define console_stop_critical_timings(flag) \
> > > + do { typecheck(bool, flag); } while (0)
> > > +# define console_start_critical_timings(flag)\
> > > + do { typecheck(bool, flag); } while (0)
> > >   #endif
> > >   /*
> > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > > index 1888f6a3b694..036460a7e4cd 100644
> > > --- a/kernel/printk/printk.c
> > > +++ b/kernel/printk/printk.c
> > > @@ -2359,6 +2359,7 @@ void console_unlock(void)
> > >   static char ext_text[CONSOLE_EXT_LOG_MAX];
> > >   static char text[LOG_LINE_MAX + PREFIX_MAX];
> > >   unsigned long flags;
> > > + bool cflag;
> > >   bool do_cond_resched, retry;
> > >   if (console_suspended) {
> > > @@ -2459,9 +2460,10 @@ void console_unlock(void)
> > >*/
> > >   console_lock_spinning_enable();
> > > - stop_critical_timings();/* don't trace print latency */
> > > + /* don't trace print latency if it's disabled */
> > > + console_stop_critical_timings(cflag);
> > >   call_console_drivers(ext_text, ext_len, text, len);
> > > - start_critical_timings();
> > > + console_start_critical_timings(cflag);
> > >   if (console_lock_spinning_disable_and_check()) {
> > >   printk_safe_exit_irqrestore(flags);
> > > diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> > > index 4913ed1138aa..93a8b82c27e4 100644
> > > --- a/kernel/trace/trace.h
> > > +++ b/kernel/trace/trace.h
> > > @@ -1262,6 +1262,7 @@ extern int trace_get_user(struct trace_parser 
> > > *parser, const char __user *ubuf,
> > >   C(PRINTK_MSGONLY,   "printk-msg-only"), \
> > >   C(CONTEXT_INFO, "context-info"),   /* Print 
> > > pid/cpu/time */ \
> > >   C(LATENCY_FMT,  "latency-format"),  \
> > > + C(CONSOLE_LATENCY,  "console-latency"), \
> > >   C(RECORD_CMD,   "record-cmd"),  \
> > >   C(RECORD_TGID,  "record-tgid"), \
> > >   C(OVERWRITE,"overwrite"),   \
> > > diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
> > > index a745b0cee5d3..bc02be207a7a 100644
> > > --- a/kernel/trace/trace_irqsoff.c
> > > +++ b/kernel/trace/trace_irqsoff.c
> > > @@ -456,6 +456,18

Re: [PATCH v7 4/4] ftrace: Add an option for tracing console latencies

2019-10-02 Thread Viktor Rosendahl


On 10/2/19 2:52 AM, Joel Fernandes wrote:

On Fri, Sep 20, 2019 at 05:22:19PM +0200, Viktor Rosendahl (BMW) wrote:

This new trace option "console-latency" will enable the latency
tracers to trace the console latencies. Previously this has always been
implicitely disabled. I guess this is because they are considered
to be well known and unavoidable.

However, for some organizations it may nevertheless be desirable to
trace them. Basically, we want to be able to tell that there are
latencies in the system under test because someone has incorrectly
enabled the serial console.

Signed-off-by: Viktor Rosendahl (BMW) 
---
  include/linux/irqflags.h | 22 ++
  kernel/printk/printk.c   |  6 --
  kernel/trace/trace.h |  1 +
  kernel/trace/trace_irqsoff.c | 12 
  4 files changed, 39 insertions(+), 2 deletions(-)

diff --git a/include/linux/irqflags.h b/include/linux/irqflags.h
index 21619c92c377..3de891723331 100644
--- a/include/linux/irqflags.h
+++ b/include/linux/irqflags.h
@@ -13,6 +13,7 @@
  #define _LINUX_TRACE_IRQFLAGS_H
  
  #include 

+#include 
  #include 
  
  /* Currently trace_softirqs_on/off is used only by lockdep */

@@ -68,9 +69,30 @@ do { \
defined(CONFIG_PREEMPT_TRACER)
   extern void stop_critical_timings(void);
   extern void start_critical_timings(void);
+ extern bool console_tracing_disabled(void);
+
+# define console_stop_critical_timings(flag)   \
+   do {\
+   typecheck(bool, flag);  \
+   flag = console_tracing_disabled();  \
+   if (flag)   \
+   stop_critical_timings();\
+   } while (0)
+
+# define console_start_critical_timings(flag)   \
+   do { \
+   typecheck(bool, flag);   \
+   if (flag)\
+   start_critical_timings();\
+   } while (0)
+
  #else
  # define stop_critical_timings() do { } while (0)
  # define start_critical_timings() do { } while (0)
+# define console_stop_critical_timings(flag)   \
+   do { typecheck(bool, flag); } while (0)
+# define console_start_critical_timings(flag)  \
+   do { typecheck(bool, flag); } while (0)
  #endif
  
  /*

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1888f6a3b694..036460a7e4cd 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2359,6 +2359,7 @@ void console_unlock(void)
static char ext_text[CONSOLE_EXT_LOG_MAX];
static char text[LOG_LINE_MAX + PREFIX_MAX];
unsigned long flags;
+   bool cflag;
bool do_cond_resched, retry;
  
  	if (console_suspended) {

@@ -2459,9 +2460,10 @@ void console_unlock(void)
 */
console_lock_spinning_enable();
  
-		stop_critical_timings();	/* don't trace print latency */

+   /* don't trace print latency if it's disabled */
+   console_stop_critical_timings(cflag);
call_console_drivers(ext_text, ext_len, text, len);
-   start_critical_timings();
+   console_start_critical_timings(cflag);
  
  		if (console_lock_spinning_disable_and_check()) {

printk_safe_exit_irqrestore(flags);
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 4913ed1138aa..93a8b82c27e4 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1262,6 +1262,7 @@ extern int trace_get_user(struct trace_parser *parser, 
const char __user *ubuf,
C(PRINTK_MSGONLY,   "printk-msg-only"),   \
C(CONTEXT_INFO, "context-info"),   /* Print 
pid/cpu/time */ \
C(LATENCY_FMT,  "latency-format"),\
+   C(CONSOLE_LATENCY,  "console-latency"),   \
C(RECORD_CMD,   "record-cmd"),\
C(RECORD_TGID,  "record-tgid"),   \
C(OVERWRITE,"overwrite"), \
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index a745b0cee5d3..bc02be207a7a 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -456,6 +456,18 @@ void stop_critical_timings(void)
  EXPORT_SYMBOL_GPL(stop_critical_timings);
  NOKPROBE_SYMBOL(stop_critical_timings);
  
+bool console_tracing_disabled(void)

+{
+   struct trace_array *tr = irqsoff_trace;
+   int pc = preempt_count();
+
+   if (!preempt_trace(pc) && !irq_trace())
+   return false;


Why this condition here? Why not just make the call to
stop_critical_timings() dependent on the new flag you are adding? Please
explain it more and add some comments.



It is a kind of optimization for the common case, i.e. that the tracer
is not enabled.

The

Re: [PATCH v7 4/4] ftrace: Add an option for tracing console latencies

2019-10-01 Thread Joel Fernandes

On Fri, Sep 20, 2019 at 05:22:19PM +0200, Viktor Rosendahl (BMW) wrote:
> This new trace option "console-latency" will enable the latency
> tracers to trace the console latencies. Previously this has always been
> implicitely disabled. I guess this is because they are considered
> to be well known and unavoidable.
> 
> However, for some organizations it may nevertheless be desirable to
> trace them. Basically, we want to be able to tell that there are
> latencies in the system under test because someone has incorrectly
> enabled the serial console.
> 
> Signed-off-by: Viktor Rosendahl (BMW) 
> ---
>  include/linux/irqflags.h | 22 ++
>  kernel/printk/printk.c   |  6 --
>  kernel/trace/trace.h |  1 +
>  kernel/trace/trace_irqsoff.c | 12 
>  4 files changed, 39 insertions(+), 2 deletions(-)
> 
> diff --git a/include/linux/irqflags.h b/include/linux/irqflags.h
> index 21619c92c377..3de891723331 100644
> --- a/include/linux/irqflags.h
> +++ b/include/linux/irqflags.h
> @@ -13,6 +13,7 @@
>  #define _LINUX_TRACE_IRQFLAGS_H
>  
>  #include 
> +#include 
>  #include 
>  
>  /* Currently trace_softirqs_on/off is used only by lockdep */
> @@ -68,9 +69,30 @@ do {   \
>   defined(CONFIG_PREEMPT_TRACER)
>   extern void stop_critical_timings(void);
>   extern void start_critical_timings(void);
> + extern bool console_tracing_disabled(void);
> +
> +# define console_stop_critical_timings(flag) \
> + do {\
> + typecheck(bool, flag);  \
> + flag = console_tracing_disabled();  \
> + if (flag)   \
> + stop_critical_timings();\
> + } while (0)
> +
> +# define console_start_critical_timings(flag) \
> + do { \
> + typecheck(bool, flag);   \
> + if (flag)\
> + start_critical_timings();\
> + } while (0)
> +
>  #else
>  # define stop_critical_timings() do { } while (0)
>  # define start_critical_timings() do { } while (0)
> +# define console_stop_critical_timings(flag) \
> + do { typecheck(bool, flag); } while (0)
> +# define console_start_critical_timings(flag)\
> + do { typecheck(bool, flag); } while (0)
>  #endif
>  
>  /*
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 1888f6a3b694..036460a7e4cd 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2359,6 +2359,7 @@ void console_unlock(void)
>   static char ext_text[CONSOLE_EXT_LOG_MAX];
>   static char text[LOG_LINE_MAX + PREFIX_MAX];
>   unsigned long flags;
> + bool cflag;
>   bool do_cond_resched, retry;
>  
>   if (console_suspended) {
> @@ -2459,9 +2460,10 @@ void console_unlock(void)
>*/
>   console_lock_spinning_enable();
>  
> - stop_critical_timings();/* don't trace print latency */
> + /* don't trace print latency if it's disabled */
> + console_stop_critical_timings(cflag);
>   call_console_drivers(ext_text, ext_len, text, len);
> - start_critical_timings();
> + console_start_critical_timings(cflag);
>  
>   if (console_lock_spinning_disable_and_check()) {
>   printk_safe_exit_irqrestore(flags);
> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index 4913ed1138aa..93a8b82c27e4 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -1262,6 +1262,7 @@ extern int trace_get_user(struct trace_parser *parser, 
> const char __user *ubuf,
>   C(PRINTK_MSGONLY,   "printk-msg-only"), \
>   C(CONTEXT_INFO, "context-info"),   /* Print 
> pid/cpu/time */ \
>   C(LATENCY_FMT,  "latency-format"),  \
> + C(CONSOLE_LATENCY,  "console-latency"), \
>   C(RECORD_CMD,   "record-cmd"),  \
>   C(RECORD_TGID,  "record-tgid"), \
>   C(OVERWRITE,"overwrite"),   \
> diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
> index a745b0cee5d3..bc02be207a7a 100644
> --- a/kernel/trace/trace_irqsoff.c
> +++ b/kernel/trace/trace_irqsoff.c
> @@ -456,6 +456,18 @@ void stop_critical_timings(void)
>  EXPORT_SYMBOL_GPL(stop_critical_timings);
>  NOKPROBE_SYMBOL(stop_critical_timings);
>  
> +bool console_tracing_disabled(void)
> +{
> + struct trace_array *tr = irqsoff_trace;
> + int pc = preempt_count();
> +
> + if (!preempt_trace(pc) && !irq_trace())
> + return false;

Why this condition here? Why not just make the call to
stop_critical_timings() dependent on the new flag you are adding? Please
explain it more and

[PATCH v7 4/4] ftrace: Add an option for tracing console latencies

2019-09-20 Thread Viktor Rosendahl (BMW)

This new trace option "console-latency" will enable the latency
tracers to trace the console latencies. Previously this has always been
implicitely disabled. I guess this is because they are considered
to be well known and unavoidable.

However, for some organizations it may nevertheless be desirable to
trace them. Basically, we want to be able to tell that there are
latencies in the system under test because someone has incorrectly
enabled the serial console.

Signed-off-by: Viktor Rosendahl (BMW) 
---
 include/linux/irqflags.h | 22 ++
 kernel/printk/printk.c   |  6 --
 kernel/trace/trace.h |  1 +
 kernel/trace/trace_irqsoff.c | 12 
 4 files changed, 39 insertions(+), 2 deletions(-)

diff --git a/include/linux/irqflags.h b/include/linux/irqflags.h
index 21619c92c377..3de891723331 100644
--- a/include/linux/irqflags.h
+++ b/include/linux/irqflags.h
@@ -13,6 +13,7 @@
 #define _LINUX_TRACE_IRQFLAGS_H
 
 #include 
+#include 
 #include 
 
 /* Currently trace_softirqs_on/off is used only by lockdep */
@@ -68,9 +69,30 @@ do { \
defined(CONFIG_PREEMPT_TRACER)
  extern void stop_critical_timings(void);
  extern void start_critical_timings(void);
+ extern bool console_tracing_disabled(void);
+
+# define console_stop_critical_timings(flag)   \
+   do {\
+   typecheck(bool, flag);  \
+   flag = console_tracing_disabled();  \
+   if (flag)   \
+   stop_critical_timings();\
+   } while (0)
+
+# define console_start_critical_timings(flag)   \
+   do { \
+   typecheck(bool, flag);   \
+   if (flag)\
+   start_critical_timings();\
+   } while (0)
+
 #else
 # define stop_critical_timings() do { } while (0)
 # define start_critical_timings() do { } while (0)
+# define console_stop_critical_timings(flag)   \
+   do { typecheck(bool, flag); } while (0)
+# define console_start_critical_timings(flag)  \
+   do { typecheck(bool, flag); } while (0)
 #endif
 
 /*
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1888f6a3b694..036460a7e4cd 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2359,6 +2359,7 @@ void console_unlock(void)
static char ext_text[CONSOLE_EXT_LOG_MAX];
static char text[LOG_LINE_MAX + PREFIX_MAX];
unsigned long flags;
+   bool cflag;
bool do_cond_resched, retry;
 
if (console_suspended) {
@@ -2459,9 +2460,10 @@ void console_unlock(void)
 */
console_lock_spinning_enable();
 
-   stop_critical_timings();/* don't trace print latency */
+   /* don't trace print latency if it's disabled */
+   console_stop_critical_timings(cflag);
call_console_drivers(ext_text, ext_len, text, len);
-   start_critical_timings();
+   console_start_critical_timings(cflag);
 
if (console_lock_spinning_disable_and_check()) {
printk_safe_exit_irqrestore(flags);
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 4913ed1138aa..93a8b82c27e4 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1262,6 +1262,7 @@ extern int trace_get_user(struct trace_parser *parser, 
const char __user *ubuf,
C(PRINTK_MSGONLY,   "printk-msg-only"), \
C(CONTEXT_INFO, "context-info"),   /* Print 
pid/cpu/time */ \
C(LATENCY_FMT,  "latency-format"),  \
+   C(CONSOLE_LATENCY,  "console-latency"), \
C(RECORD_CMD,   "record-cmd"),  \
C(RECORD_TGID,  "record-tgid"), \
C(OVERWRITE,"overwrite"),   \
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index a745b0cee5d3..bc02be207a7a 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -456,6 +456,18 @@ void stop_critical_timings(void)
 EXPORT_SYMBOL_GPL(stop_critical_timings);
 NOKPROBE_SYMBOL(stop_critical_timings);
 
+bool console_tracing_disabled(void)
+{
+   struct trace_array *tr = irqsoff_trace;
+   int pc = preempt_count();
+
+   if (!preempt_trace(pc) && !irq_trace())
+   return false;
+
+   return !(tr->trace_flags & TRACE_ITER_CONSOLE_LATENCY);
+}
+EXPORT_SYMBOL_GPL(console_tracing_disabled);
+
 #ifdef CONFIG_FUNCTION_TRACER
 static bool function_enabled;
 
-- 
2.17.1

Re: [PATCH v7 4/4] ftrace: Add an option for tracing console latencies

Re: [PATCH v7 4/4] ftrace: Add an option for tracing console latencies

Re: [PATCH v7 4/4] ftrace: Add an option for tracing console latencies

[PATCH v7 4/4] ftrace: Add an option for tracing console latencies

4 matches

Site Navigation

Mail list logo

Footer information