tracing: queued updates

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(-)

From: Steven Rostedt <[email protected]>

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.

---
 kernel/trace/ftrace.c |    8 ++++++++
 kernel/trace/trace.c  |   15 +++++++++++++++
 kernel/trace/trace.h  |    2 ++
 3 files changed, 25 insertions(+), 0 deletions(-)

index c3e4575..077d853 100644
@@ -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.
  *

index 4b8df0d..13f2b84 100644
@@ -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();
 

index 4c7540a..092e1f8 100644
@@ -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

From: Steven Rostedt <[email protected]>

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().

---
 kernel/trace/trace.c |  111 +++++++++++++++++++++++++++++++++++++-------------
 1 files changed, 83 insertions(+), 28 deletions(-)

index 13f2b84..f86efe9 100644
@@ -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

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

[ Added hpa ]

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	[email protected]:/pub/scm/linux/kernel/git/rostedt/linux-trace.git (fetch)
push	[email protected]:/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

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

Got it from there - thanks Steve!

Tests are also looking good so far.

Ingo

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 ;)

Great! Thanks,

-- Steve

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

[ Added Peter Zijlstra ]

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

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

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