[PATCH 0/2 v2] [GIT PULL][v3.2] tracing: queued updates

[PATCH 0/2 v2] [GIT PULL][v3.2] tracing: queued updates

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 1447 bytes --]


Ingo,

I found the build bug with ftrace disabled. It was in the second to last
patch of the series. It was a cut and paste error where the ftrace_is_dead()
stub had "extern static inline" which caused the error.

I rebased and pushed to my git tree. Please check the SHA1, even though
the mirrors should be updated by now.

I tested this branch with the following:

 allnoconfig + minconfig to boot

 full ftrace enabled to boot and test

 ftrace without function tracing to boot and test

 no tracing enabled to boot and test

 allmodconfig to boot and test - a call trace dumped from a non
  related bug (in slub). I will investigate this later.

 allyesconfig to build - just made sure it builds.

I'm only sending out the last two patches as the other patches are
still the same. The rebase started from the second patch.

-- Steve

Please pull the latest tip/perf/core tree, which can be found at:

  git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
tip/perf/core

Head SHA1: d696b58ca2c3ca76e784ef89a7e0453d9b7ab187


Steven Rostedt (2):
      tracing: Warn on output if the function tracer was found corrupted
      tracing: Do not allocate buffer for trace_marker

----
 kernel/trace/ftrace.c |    8 +++
 kernel/trace/trace.c  |  126 ++++++++++++++++++++++++++++++++++++++-----------
 kernel/trace/trace.h  |    2 +
 3 files changed, 108 insertions(+), 28 deletions(-)

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

[PATCH 1/2 v2] tracing: Warn on output if the function tracer was found corrupted

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 3168 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

As the function tracer is very intrusive, lots of self checks are
performed on the tracer and if something is found to be strange
it will shut itself down keeping it from corrupting the rest of the
kernel. This shutdown may still allow functions to be traced, as the
tracing only stops new modifications from happening. Trying to stop
the function tracer itself can cause more harm as it requires code
modification.

Although a WARN_ON() is executed, a user may not notice it. To help
the user see that something isn't right with the tracing of the system
a big warning is added to the output of the tracer that lets the user
know that their data may be incomplete.

Reported-by: Thomas Gleixner <tglx@linutronix.de>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/ftrace.c |    8 ++++++++
 kernel/trace/trace.c  |   15 +++++++++++++++
 kernel/trace/trace.h  |    2 ++
 3 files changed, 25 insertions(+), 0 deletions(-)

diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index c3e4575..077d853 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -3863,6 +3863,14 @@ void ftrace_kill(void)
 }
 
 /**
+ * Test if ftrace is dead or not.
+ */
+int ftrace_is_dead(void)
+{
+	return ftrace_disabled;
+}
+
+/**
  * register_ftrace_function - register a function for profiling
  * @ops - ops structure that holds the function for profiling.
  *
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 4b8df0d..13f2b84 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2160,6 +2160,14 @@ void trace_default_header(struct seq_file *m)
 	}
 }
 
+static void test_ftrace_alive(struct seq_file *m)
+{
+	if (!ftrace_is_dead())
+		return;
+	seq_printf(m, "# WARNING: FUNCTION TRACING IS CORRUPTED\n");
+	seq_printf(m, "#          MAY BE MISSING FUNCTION EVENTS\n");
+}
+
 static int s_show(struct seq_file *m, void *v)
 {
 	struct trace_iterator *iter = v;
@@ -2169,6 +2177,7 @@ static int s_show(struct seq_file *m, void *v)
 		if (iter->tr) {
 			seq_printf(m, "# tracer: %s\n", iter->trace->name);
 			seq_puts(m, "#\n");
+			test_ftrace_alive(m);
 		}
 		if (iter->trace && iter->trace->print_header)
 			iter->trace->print_header(m);
@@ -4613,6 +4622,12 @@ __ftrace_dump(bool disable_tracing, enum ftrace_dump_mode oops_dump_mode)
 
 	tracing_off();
 
+	/* Did function tracer already get disabled? */
+	if (ftrace_is_dead()) {
+		printk("# WARNING: FUNCTION TRACING IS CORRUPTED\n");
+		printk("#          MAY BE MISSING FUNCTION EVENTS\n");
+	}
+
 	if (disable_tracing)
 		ftrace_kill();
 
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 4c7540a..092e1f8 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -579,11 +579,13 @@ static inline int ftrace_trace_task(struct task_struct *task)
 
 	return test_tsk_trace_trace(task);
 }
+extern int ftrace_is_dead(void);
 #else
 static inline int ftrace_trace_task(struct task_struct *task)
 {
 	return 1;
 }
+static inline int ftrace_is_dead(void) { return 0; }
 #endif
 
 /*
-- 
1.7.6.3



[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

[PATCH 2/2 v2] tracing: Do not allocate buffer for trace_marker

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 4873 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

When doing intense tracing, the kmalloc inside trace_marker can
introduce side effects to what is being traced.

As trace_marker() is used by userspace to inject data into the
kernel ring buffer, it needs to do so with the least amount
of intrusion to the operations of the kernel or the user space
application.

As the ring buffer is designed to write directly into the buffer
without the need to make a temporary buffer, and userspace already
went through the hassle of knowing how big the write will be,
we can simply pin the userspace pages and write the data directly
into the buffer. This improves the impact of tracing via trace_marker
tremendously!

Thanks to Peter Zijlstra and Thomas Gleixner for pointing out the
use of get_user_pages_fast() and kmap_atomic().

Suggested-by: Thomas Gleixner <tglx@linutronix.de>
Suggested-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/trace.c |  111 +++++++++++++++++++++++++++++++++++++-------------
 1 files changed, 83 insertions(+), 28 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 13f2b84..f86efe9 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3628,22 +3628,24 @@ tracing_free_buffer_release(struct inode *inode, struct file *filp)
 	return 0;
 }
 
-static int mark_printk(const char *fmt, ...)
-{
-	int ret;
-	va_list args;
-	va_start(args, fmt);
-	ret = trace_vprintk(0, fmt, args);
-	va_end(args);
-	return ret;
-}
-
 static ssize_t
 tracing_mark_write(struct file *filp, const char __user *ubuf,
 					size_t cnt, loff_t *fpos)
 {
-	char *buf;
-	size_t written;
+	unsigned long addr = (unsigned long)ubuf;
+	struct ring_buffer_event *event;
+	struct ring_buffer *buffer;
+	struct print_entry *entry;
+	unsigned long irq_flags;
+	struct page *pages[2];
+	int nr_pages = 1;
+	ssize_t written;
+	void *page1;
+	void *page2;
+	int offset;
+	int size;
+	int len;
+	int ret;
 
 	if (tracing_disabled)
 		return -EINVAL;
@@ -3651,28 +3653,81 @@ tracing_mark_write(struct file *filp, const char __user *ubuf,
 	if (cnt > TRACE_BUF_SIZE)
 		cnt = TRACE_BUF_SIZE;
 
-	buf = kmalloc(cnt + 2, GFP_KERNEL);
-	if (buf == NULL)
-		return -ENOMEM;
+	/*
+	 * Userspace is injecting traces into the kernel trace buffer.
+	 * We want to be as non intrusive as possible.
+	 * To do so, we do not want to allocate any special buffers
+	 * or take any locks, but instead write the userspace data
+	 * straight into the ring buffer.
+	 *
+	 * First we need to pin the userspace buffer into memory,
+	 * which, most likely it is, because it just referenced it.
+	 * But there's no guarantee that it is. By using get_user_pages_fast()
+	 * and kmap_atomic/kunmap_atomic() we can get access to the
+	 * pages directly. We then write the data directly into the
+	 * ring buffer.
+	 */
+	BUILD_BUG_ON(TRACE_BUF_SIZE >= PAGE_SIZE);
 
-	if (copy_from_user(buf, ubuf, cnt)) {
-		kfree(buf);
-		return -EFAULT;
+	/* check if we cross pages */
+	if ((addr & PAGE_MASK) != ((addr + cnt) & PAGE_MASK))
+		nr_pages = 2;
+
+	offset = addr & (PAGE_SIZE - 1);
+	addr &= PAGE_MASK;
+
+	ret = get_user_pages_fast(addr, nr_pages, 0, pages);
+	if (ret < nr_pages) {
+		while (--ret >= 0)
+			put_page(pages[ret]);
+		written = -EFAULT;
+		goto out;
 	}
-	if (buf[cnt-1] != '\n') {
-		buf[cnt] = '\n';
-		buf[cnt+1] = '\0';
+
+	page1 = kmap_atomic(pages[0]);
+	if (nr_pages == 2)
+		page2 = kmap_atomic(pages[1]);
+
+	local_save_flags(irq_flags);
+	size = sizeof(*entry) + cnt + 2; /* possible \n added */
+	buffer = global_trace.buffer;
+	event = trace_buffer_lock_reserve(buffer, TRACE_PRINT, size,
+					  irq_flags, preempt_count());
+	if (!event) {
+		/* Ring buffer disabled, return as if not open for write */
+		written = -EBADF;
+		goto out_unlock;
+	}
+
+	entry = ring_buffer_event_data(event);
+	entry->ip = _THIS_IP_;
+
+	if (nr_pages == 2) {
+		len = PAGE_SIZE - offset;
+		memcpy(&entry->buf, page1 + offset, len);
+		memcpy(&entry->buf[len], page2, cnt - len);
 	} else
-		buf[cnt] = '\0';
+		memcpy(&entry->buf, page1 + offset, cnt);
 
-	written = mark_printk("%s", buf);
-	kfree(buf);
-	*fpos += written;
+	if (entry->buf[cnt - 1] != '\n') {
+		entry->buf[cnt] = '\n';
+		entry->buf[cnt + 1] = '\0';
+	} else
+		entry->buf[cnt] = '\0';
+
+	ring_buffer_unlock_commit(buffer, event);
 
-	/* don't tell userspace we wrote more - it might confuse them */
-	if (written > cnt)
-		written = cnt;
+	written = cnt;
 
+	*fpos += written;
+
+ out_unlock:
+	if (nr_pages == 2)
+		kunmap_atomic(page2);
+	kunmap_atomic(page1);
+	while (nr_pages > 0)
+		put_page(pages[--nr_pages]);
+ out:
 	return written;
 }
 
-- 
1.7.6.3



[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: [PATCH 0/2 v2] [GIT PULL][v3.2] tracing: queued updates

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> Ingo,
> 
> I found the build bug with ftrace disabled. It was in the second to last
> patch of the series. It was a cut and paste error where the ftrace_is_dead()
> stub had "extern static inline" which caused the error.
> 
> I rebased and pushed to my git tree. Please check the SHA1, even though
> the mirrors should be updated by now.
> 
> I tested this branch with the following:
> 
>  allnoconfig + minconfig to boot
> 
>  full ftrace enabled to boot and test
> 
>  ftrace without function tracing to boot and test
> 
>  no tracing enabled to boot and test
> 
>  allmodconfig to boot and test - a call trace dumped from a non
>   related bug (in slub). I will investigate this later.
> 
>  allyesconfig to build - just made sure it builds.
> 
> I'm only sending out the last two patches as the other patches are
> still the same. The rebase started from the second patch.
> 
> -- Steve
> 
> Please pull the latest tip/perf/core tree, which can be found at:
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
> tip/perf/core
> 
> Head SHA1: d696b58ca2c3ca76e784ef89a7e0453d9b7ab187

Hm, even after 12+ hours of wait i can only pull 177e216 from your 
tip/perf/core. Is this a korg delay, or did you forget to push? The 
perf/urgent branch was there, so i don't think it's korg delay.

Thanks,

	Ingo

Re: [PATCH 0/2 v2] [GIT PULL][v3.2] tracing: queued updates

[Steven Rostedt]

[ Added hpa ]

On Wed, 2011-10-12 at 10:16 +0200, Ingo Molnar wrote:
>  
> > Please pull the latest tip/perf/core tree, which can be found at:
> > 
> >   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
> > tip/perf/core
> > 
> > Head SHA1: d696b58ca2c3ca76e784ef89a7e0453d9b7ab187
> 
> Hm, even after 12+ hours of wait i can only pull 177e216 from your 
> tip/perf/core. Is this a korg delay, or did you forget to push? The 
> perf/urgent branch was there, so i don't think it's korg delay.

I just tried again, and got:

$ git push push trace/tip/perf/core:tip/perf/core
Enter passphrase for key '/home/rostedt/.ssh/id_rsa_korg': 
Everything up-to-date

$ git log -1 --pretty=oneline trace/tip/perf/core
d696b58ca2c3ca76e784ef89a7e0453d9b7ab187 tracing: Do not allocate buffer for tra

But if I refresh from git itself

$ git remote -v 
ftrace	git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git (fetch)
ftrace	git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git (push)
push	gitolite@ra.kernel.org:/pub/scm/linux/kernel/git/rostedt/linux-trace.git (fetch)
push	gitolite@ra.kernel.org:/pub/scm/linux/kernel/git/rostedt/linux-trace.git (push)

$ git remote update ftrace
Fetching ftrace

$ git log -1 --pretty=oneline ftrace/tip/perf/core
87912fdfc1378a7e7e54a169ef9eebeafa1af04f tracing: Do not allocate buffer for tra

It seems that gitolite isn't refreshing rebases?

I just pushed it to tip/perf/core-2. I waited about 5 minutes, and I
still do not see it.

The urgent branch I pushed the same time as I did the first version of
this branch.

-- Steve

Re: [PATCH 0/2 v2] [GIT PULL][v3.2] tracing: queued updates

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 1091 bytes --]

On Wed, 2011-10-12 at 07:21 -0400, Steven Rostedt wrote:
> [ Added hpa ]
> 
> On Wed, 2011-10-12 at 10:16 +0200, Ingo Molnar wrote:
> >  
> > > Please pull the latest tip/perf/core tree, which can be found at:
> > > 
> > >   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
> > > tip/perf/core
> > > 
> > > Head SHA1: d696b58ca2c3ca76e784ef89a7e0453d9b7ab187
> > 
> > Hm, even after 12+ hours of wait i can only pull 177e216 from your 
> > tip/perf/core. Is this a korg delay, or did you forget to push? The 
> > perf/urgent branch was there, so i don't think it's korg delay.
> 
> I just tried again, and got:
> 
> $ git push push trace/tip/perf/core:tip/perf/core
> Enter passphrase for key '/home/rostedt/.ssh/id_rsa_korg': 
> Everything up-to-date

> It seems that gitolite isn't refreshing rebases?


There seems to be issues with kernel.org refreshing. You can get the
same branch at my github repo:

  git://github.com/rostedt/linux.git
tip/perf/core


It has the same SHA1: d696b58ca2c3ca76e784ef89a7e0453d9b7ab187

-- Steve


[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

Re: [PATCH 0/2 v2] [GIT PULL][v3.2] tracing: queued updates

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> On Wed, 2011-10-12 at 07:21 -0400, Steven Rostedt wrote:
> > [ Added hpa ]
> > 
> > On Wed, 2011-10-12 at 10:16 +0200, Ingo Molnar wrote:
> > >  
> > > > Please pull the latest tip/perf/core tree, which can be found at:
> > > > 
> > > >   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
> > > > tip/perf/core
> > > > 
> > > > Head SHA1: d696b58ca2c3ca76e784ef89a7e0453d9b7ab187
> > > 
> > > Hm, even after 12+ hours of wait i can only pull 177e216 from your 
> > > tip/perf/core. Is this a korg delay, or did you forget to push? The 
> > > perf/urgent branch was there, so i don't think it's korg delay.
> > 
> > I just tried again, and got:
> > 
> > $ git push push trace/tip/perf/core:tip/perf/core
> > Enter passphrase for key '/home/rostedt/.ssh/id_rsa_korg': 
> > Everything up-to-date
> 
> > It seems that gitolite isn't refreshing rebases?
> 
> There seems to be issues with kernel.org refreshing. You can get the
> same branch at my github repo:
> 
>   git://github.com/rostedt/linux.git
> tip/perf/core
> 
> 
> It has the same SHA1: d696b58ca2c3ca76e784ef89a7e0453d9b7ab187

Got it from there - thanks Steve!

Tests are also looking good so far.

	Ingo

Re: [PATCH 0/2 v2] [GIT PULL][v3.2] tracing: queued updates

[Steven Rostedt]

On Wed, 2011-10-12 at 18:23 +0200, Ingo Molnar wrote:
> * Steven Rostedt <rostedt@goodmis.org> wrote:

> > It has the same SHA1: d696b58ca2c3ca76e784ef89a7e0453d9b7ab187
> 
> Got it from there - thanks Steve!

kernel.org should be back again. I'm talking with John about it, and he
said he did some things that caused severe strain on the hard drives.
The refreshes were happening, just verrrrry sloowly ;)

> 
> Tests are also looking good so far.

Great! Thanks,

-- Steve

Re: [PATCH 0/2 v2] [GIT PULL][v3.2] tracing: queued updates

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

> Tests are also looking good so far.

there's a cross-build failure on the m32r architecture:

/home/mingo/tip/kernel/trace/trace_clock.c:117: error: expected '=', ',', ';', 'asm' or '__attribute__' before 'trace_counter'
/home/mingo/tip/kernel/trace/trace_clock.c: In function 'trace_clock_counter':
/home/mingo/tip/kernel/trace/trace_clock.c:126: error: implicit declaration of function 'atomic64_add_return'
/home/mingo/tip/kernel/trace/trace_clock.c:126: error: 'trace_counter' undeclared (first use in this function)
/home/mingo/tip/kernel/trace/trace_clock.c:126: error: (Each undeclared identifier is reported only once
/home/mingo/tip/kernel/trace/trace_clock.c:126: error: for each function it appears in.)

Thanks,

	Ingo

Re: [PATCH 0/2 v2] [GIT PULL][v3.2] tracing: queued updates

[Steven Rostedt]

[ Added Peter Zijlstra ]

On Thu, 2011-10-13 at 10:59 +0200, Ingo Molnar wrote:
> * Ingo Molnar <mingo@elte.hu> wrote:
> 
> > Tests are also looking good so far.
> 
> there's a cross-build failure on the m32r architecture:

Hmm, I don't have a m32r cross compiler in my arsenal.

 
> 
> /home/mingo/tip/kernel/trace/trace_clock.c:117: error: expected '=', ',', ';', 'asm' or '__attribute__' before 'trace_counter'
> /home/mingo/tip/kernel/trace/trace_clock.c: In function 'trace_clock_counter':
> /home/mingo/tip/kernel/trace/trace_clock.c:126: error: implicit declaration of function 'atomic64_add_return'
> /home/mingo/tip/kernel/trace/trace_clock.c:126: error: 'trace_counter' undeclared (first use in this function)
> /home/mingo/tip/kernel/trace/trace_clock.c:126: error: (Each undeclared identifier is reported only once
> /home/mingo/tip/kernel/trace/trace_clock.c:126: error: for each function it appears in.)

At that line there's:

static atomic64_t trace_counter;

I take it that m32r does not define an atomic64_t. Does this mean that
we can not use it? This code was taken from Peter, as it stated in the
commit log:

commit 6249687f76b69cc0b2ad34636f4a18d693ef3262
tracing: Add a counter clock for those that do not trust clocks

[...]

    The trace_clock_counter() is added from the attempt by Peter Zijlstra
    trying to convert the trace_clock_global() to it. I took Peter's counter
    code and made trace_clock_counter() instead, and added it to the choice
    of clocks. Just echo counter > /debug/tracing/trace_clock to activate
    it.

I think the fix to this is to add:

CONFIG_GENERIC_ATOMIC64 to m32r.

-- Steve

Re: [PATCH 0/2 v2] [GIT PULL][v3.2] tracing: queued updates

[Steven Rostedt]

On Thu, 2011-10-13 at 09:55 -0400, Steven Rostedt wrote:

> > there's a cross-build failure on the m32r architecture:
> 
> Hmm, I don't have a m32r cross compiler in my arsenal.

Ah, I didn't see a 4.5.2 m32r binary cross compiler, but there is a
4.5.1. I'll add this to my tool chain.

Thanks!

-- Steve