All of lore.kernel.org
 help / color / mirror / Atom feed
* [for-linus][PATCH 0/5] Tracing fixes for 5.12:
@ 2021-03-04 14:19 Steven Rostedt
  2021-03-04 14:19 ` [for-linus][PATCH 1/5] ftrace: Have recordmcount use w8 to read relp->r_info in arm64_is_fake_mcount Steven Rostedt
                   ` (4 more replies)
  0 siblings, 5 replies; 6+ messages in thread
From: Steven Rostedt @ 2021-03-04 14:19 UTC (permalink / raw)
  To: linux-kernel; +Cc: Ingo Molnar, Andrew Morton


Functional fixes:

 - Fix big endian conversion for arg64 in recordmcount processing

 - Fix timestamp corruption in ring buffer on discarding events

Non-functional fixes:

 - Fix help text working in Kconfig

 - Remove duplicate prototype for trace_empty()

Self test update:

 - Add more information to the validation output of when a
   corrupt timestamp is found in the ring buffer, and also
   trigger a warning to make sure that tests catch it.

Chen Jun (1):
      ftrace: Have recordmcount use w8 to read relp->r_info in arm64_is_fake_mcount

Rolf Eike Beer (1):
      tracing: Fix help text of TRACEPOINT_BENCHMARK in Kconfig

Steven Rostedt (VMware) (2):
      ring-buffer: Force before_stamp and write_stamp to be different on discard
      ring-buffer: Add a little more information and a WARN when time stamp going backwards is detected

Yordan Karadzhov (VMware) (1):
      tracing: Remove duplicate declaration from trace.h

----
 kernel/trace/Kconfig       |  2 +-
 kernel/trace/ring_buffer.c | 21 ++++++++++++++++++---
 kernel/trace/trace.h       |  1 -
 scripts/recordmcount.c     |  2 +-
 4 files changed, 20 insertions(+), 6 deletions(-)

^ permalink raw reply	[flat|nested] 6+ messages in thread

* [for-linus][PATCH 1/5] ftrace: Have recordmcount use w8 to read relp->r_info in arm64_is_fake_mcount
  2021-03-04 14:19 [for-linus][PATCH 0/5] Tracing fixes for 5.12: Steven Rostedt
@ 2021-03-04 14:19 ` Steven Rostedt
  2021-03-04 14:19 ` [for-linus][PATCH 2/5] tracing: Remove duplicate declaration from trace.h Steven Rostedt
                   ` (3 subsequent siblings)
  4 siblings, 0 replies; 6+ messages in thread
From: Steven Rostedt @ 2021-03-04 14:19 UTC (permalink / raw)
  To: linux-kernel; +Cc: Ingo Molnar, Andrew Morton, Will Deacon, Chen Jun

From: Chen Jun <chenjun102@huawei.com>

On little endian system, Use aarch64_be(gcc v7.3) downloaded from
linaro.org to build image with CONFIG_CPU_BIG_ENDIAN = y,
CONFIG_FTRACE = y, CONFIG_DYNAMIC_FTRACE = y.

gcc will create symbols of _mcount but recordmcount can not create
mcount_loc for *.o.
aarch64_be-linux-gnu-objdump -r fs/namei.o | grep mcount
00000000000000d0 R_AARCH64_CALL26  _mcount
...
0000000000007190 R_AARCH64_CALL26  _mcount

The reason is than funciton arm64_is_fake_mcount can not work correctly.
A symbol of _mcount in *.o compiled with big endian compiler likes:
00 00 00 2d 00 00 01 1b
w(rp->r_info) will return 0x2d instead of 0x011b. Because w() takes
uint32_t as parameter, which truncates rp->r_info.

Use w8() instead w() to read relp->r_info

Link: https://lkml.kernel.org/r/20210222135840.56250-1-chenjun102@huawei.com

Fixes: ea0eada45632 ("recordmcount: only record relocation of type R_AARCH64_CALL26 on arm64.")
Acked-by: Will Deacon <will@kernel.org>
Signed-off-by: Chen Jun <chenjun102@huawei.com>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 scripts/recordmcount.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/scripts/recordmcount.c b/scripts/recordmcount.c
index b9c2ee7ab43f..cce12e1971d8 100644
--- a/scripts/recordmcount.c
+++ b/scripts/recordmcount.c
@@ -438,7 +438,7 @@ static int arm_is_fake_mcount(Elf32_Rel const *rp)
 
 static int arm64_is_fake_mcount(Elf64_Rel const *rp)
 {
-	return ELF64_R_TYPE(w(rp->r_info)) != R_AARCH64_CALL26;
+	return ELF64_R_TYPE(w8(rp->r_info)) != R_AARCH64_CALL26;
 }
 
 /* 64-bit EM_MIPS has weird ELF64_Rela.r_info.
-- 
2.30.0



^ permalink raw reply related	[flat|nested] 6+ messages in thread

* [for-linus][PATCH 2/5] tracing: Remove duplicate declaration from trace.h
  2021-03-04 14:19 [for-linus][PATCH 0/5] Tracing fixes for 5.12: Steven Rostedt
  2021-03-04 14:19 ` [for-linus][PATCH 1/5] ftrace: Have recordmcount use w8 to read relp->r_info in arm64_is_fake_mcount Steven Rostedt
@ 2021-03-04 14:19 ` Steven Rostedt
  2021-03-04 14:19 ` [for-linus][PATCH 3/5] tracing: Fix help text of TRACEPOINT_BENCHMARK in Kconfig Steven Rostedt
                   ` (2 subsequent siblings)
  4 siblings, 0 replies; 6+ messages in thread
From: Steven Rostedt @ 2021-03-04 14:19 UTC (permalink / raw)
  To: linux-kernel; +Cc: Ingo Molnar, Andrew Morton, Yordan Karadzhov (VMware)

From: "Yordan Karadzhov (VMware)" <y.karadz@gmail.com>

A declaration of function "int trace_empty(struct trace_iterator *iter)"
shows up twice in the header file kernel/trace/trace.h

Signed-off-by: Yordan Karadzhov (VMware) <y.karadz@gmail.com>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 kernel/trace/trace.h | 1 -
 1 file changed, 1 deletion(-)

diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index dec13ff66077..a6446c03cfbc 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -605,7 +605,6 @@ void trace_graph_function(struct trace_array *tr,
 void trace_latency_header(struct seq_file *m);
 void trace_default_header(struct seq_file *m);
 void print_trace_header(struct seq_file *m, struct trace_iterator *iter);
-int trace_empty(struct trace_iterator *iter);
 
 void trace_graph_return(struct ftrace_graph_ret *trace);
 int trace_graph_entry(struct ftrace_graph_ent *trace);
-- 
2.30.0



^ permalink raw reply related	[flat|nested] 6+ messages in thread

* [for-linus][PATCH 3/5] tracing: Fix help text of TRACEPOINT_BENCHMARK in Kconfig
  2021-03-04 14:19 [for-linus][PATCH 0/5] Tracing fixes for 5.12: Steven Rostedt
  2021-03-04 14:19 ` [for-linus][PATCH 1/5] ftrace: Have recordmcount use w8 to read relp->r_info in arm64_is_fake_mcount Steven Rostedt
  2021-03-04 14:19 ` [for-linus][PATCH 2/5] tracing: Remove duplicate declaration from trace.h Steven Rostedt
@ 2021-03-04 14:19 ` Steven Rostedt
  2021-03-04 14:19 ` [for-linus][PATCH 4/5] ring-buffer: Force before_stamp and write_stamp to be different on discard Steven Rostedt
  2021-03-04 14:19 ` [for-linus][PATCH 5/5] ring-buffer: Add a little more information and a WARN when time stamp going backwards is detected Steven Rostedt
  4 siblings, 0 replies; 6+ messages in thread
From: Steven Rostedt @ 2021-03-04 14:19 UTC (permalink / raw)
  To: linux-kernel; +Cc: Ingo Molnar, Andrew Morton, Rolf Eike Beer

From: Rolf Eike Beer <eb@emlix.com>

It's "cond_resched()" not "cond_sched()".

Link: https://lkml.kernel.org/r/1863065.aFVDpXsuPd@devpool47

Signed-off-by: Rolf Eike Beer <eb@emlix.com>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 kernel/trace/Kconfig | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index 9c266b93cbc0..7fa82778c3e6 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -694,7 +694,7 @@ config TRACEPOINT_BENCHMARK
 	help
 	 This option creates the tracepoint "benchmark:benchmark_event".
 	 When the tracepoint is enabled, it kicks off a kernel thread that
-	 goes into an infinite loop (calling cond_sched() to let other tasks
+	 goes into an infinite loop (calling cond_resched() to let other tasks
 	 run), and calls the tracepoint. Each iteration will record the time
 	 it took to write to the tracepoint and the next iteration that
 	 data will be passed to the tracepoint itself. That is, the tracepoint
-- 
2.30.0



^ permalink raw reply related	[flat|nested] 6+ messages in thread

* [for-linus][PATCH 4/5] ring-buffer: Force before_stamp and write_stamp to be different on discard
  2021-03-04 14:19 [for-linus][PATCH 0/5] Tracing fixes for 5.12: Steven Rostedt
                   ` (2 preceding siblings ...)
  2021-03-04 14:19 ` [for-linus][PATCH 3/5] tracing: Fix help text of TRACEPOINT_BENCHMARK in Kconfig Steven Rostedt
@ 2021-03-04 14:19 ` Steven Rostedt
  2021-03-04 14:19 ` [for-linus][PATCH 5/5] ring-buffer: Add a little more information and a WARN when time stamp going backwards is detected Steven Rostedt
  4 siblings, 0 replies; 6+ messages in thread
From: Steven Rostedt @ 2021-03-04 14:19 UTC (permalink / raw)
  To: linux-kernel; +Cc: Ingo Molnar, Andrew Morton, stable

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Part of the logic of the new time stamp code depends on the before_stamp and
the write_stamp to be different if the write_stamp does not match the last
event on the buffer, as it will be used to calculate the delta of the next
event written on the buffer.

The discard logic depends on this, as the next event to come in needs to
inject a full timestamp as it can not rely on the last event timestamp in
the buffer because it is unknown due to events after it being discarded. But
by changing the write_stamp back to the time before it, it forces the next
event to use a full time stamp, instead of relying on it.

The issue came when a full time stamp was used for the event, and
rb_time_delta() returns zero in that case. The update to the write_stamp
(which subtracts delta) made it not change. Then when the event is removed
from the buffer, because the before_stamp and write_stamp still match, the
next event written would calculate its delta from the write_stamp, but that
would be wrong as the write_stamp is of the time of the event that was
discarded.

In the case that the delta change being made to write_stamp is zero, set the
before_stamp to zero as well, and this will force the next event to inject a
full timestamp and not use the current write_stamp.

Cc: stable@vger.kernel.org
Fixes: a389d86f7fd09 ("ring-buffer: Have nested events still record running time stamp")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 kernel/trace/ring_buffer.c | 11 +++++++++++
 1 file changed, 11 insertions(+)

diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index b9dad3500041..342f49c3ccc5 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -2814,6 +2814,17 @@ rb_try_to_discard(struct ring_buffer_per_cpu *cpu_buffer,
 				       write_stamp, write_stamp - delta))
 			return 0;
 
+		/*
+		 * It's possible that the event time delta is zero
+		 * (has the same time stamp as the previous event)
+		 * in which case write_stamp and before_stamp could
+		 * be the same. In such a case, force before_stamp
+		 * to be different than write_stamp. It doesn't
+		 * matter what it is, as long as its different.
+		 */
+		if (!delta)
+			rb_time_set(&cpu_buffer->before_stamp, 0);
+
 		/*
 		 * If an event were to come in now, it would see that the
 		 * write_stamp and the before_stamp are different, and assume
-- 
2.30.0



^ permalink raw reply related	[flat|nested] 6+ messages in thread

* [for-linus][PATCH 5/5] ring-buffer: Add a little more information and a WARN when time stamp going backwards is detected
  2021-03-04 14:19 [for-linus][PATCH 0/5] Tracing fixes for 5.12: Steven Rostedt
                   ` (3 preceding siblings ...)
  2021-03-04 14:19 ` [for-linus][PATCH 4/5] ring-buffer: Force before_stamp and write_stamp to be different on discard Steven Rostedt
@ 2021-03-04 14:19 ` Steven Rostedt
  4 siblings, 0 replies; 6+ messages in thread
From: Steven Rostedt @ 2021-03-04 14:19 UTC (permalink / raw)
  To: linux-kernel; +Cc: Ingo Molnar, Andrew Morton

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

When the CONFIG_RING_BUFFER_VALIDATE_TIME_DELTAS is enabled, and the time
stamps are detected as not being valid, it reports information about the
write stamp, but does not show the before_stamp which is still useful
information. Also, it should give a warning once, such that tests detect
this happening.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 kernel/trace/ring_buffer.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)

diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index 342f49c3ccc5..68744c51517e 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -3318,9 +3318,13 @@ static void check_buffer(struct ring_buffer_per_cpu *cpu_buffer,
 			goto out;
 		}
 		atomic_inc(&cpu_buffer->record_disabled);
-		pr_warn("[CPU: %d]TIME DOES NOT MATCH expected:%lld actual:%lld delta:%lld after:%lld\n",
-		       cpu_buffer->cpu,
-		       ts + info->delta, info->ts, info->delta, info->after);
+		/* There's some cases in boot up that this can happen */
+		WARN_ON_ONCE(system_state != SYSTEM_BOOTING);
+		pr_warn("[CPU: %d]TIME DOES NOT MATCH expected:%lld actual:%lld delta:%lld before:%lld after:%lld%s\n",
+			cpu_buffer->cpu,
+			ts + info->delta, info->ts, info->delta,
+			info->before, info->after,
+			full ? " (full)" : "");
 		dump_buffer_page(bpage, info, tail);
 		atomic_dec(&ts_dump);
 		/* Do not re-enable checking */
-- 
2.30.0



^ permalink raw reply related	[flat|nested] 6+ messages in thread

end of thread, other threads:[~2021-03-04 14:22 UTC | newest]

Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-03-04 14:19 [for-linus][PATCH 0/5] Tracing fixes for 5.12: Steven Rostedt
2021-03-04 14:19 ` [for-linus][PATCH 1/5] ftrace: Have recordmcount use w8 to read relp->r_info in arm64_is_fake_mcount Steven Rostedt
2021-03-04 14:19 ` [for-linus][PATCH 2/5] tracing: Remove duplicate declaration from trace.h Steven Rostedt
2021-03-04 14:19 ` [for-linus][PATCH 3/5] tracing: Fix help text of TRACEPOINT_BENCHMARK in Kconfig Steven Rostedt
2021-03-04 14:19 ` [for-linus][PATCH 4/5] ring-buffer: Force before_stamp and write_stamp to be different on discard Steven Rostedt
2021-03-04 14:19 ` [for-linus][PATCH 5/5] ring-buffer: Add a little more information and a WARN when time stamp going backwards is detected Steven Rostedt

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.