tracepipe -- event streams, debugfs, and pipe_buffers

This quick tracepipe patch is an attempt to make it trivial for a developer to generate debugging traces in the kernel and get them to mass storage without having the tracing enormously skew behaviour. It is built off of Greg's debugfs and Linus' advocacy of efficient buffer transit with pipes and pipe_buffers.

A kernel subsystem registers a file in debugfs and gets a struct cookie in return. The file that is created uses fs/pipe's file_operations but wraps its own open and release tracking around it.

While it's running the kernel subsystem can send binary blobs, less than the length of a page, down this channel. The blobs are copied into per-cpu lists of pages. Cutesy little headers with get_cycles() and the cpu id are prepended to each blob. The traces are only recorded if user space has open references to the file.

As the pages fill they're kicked off to a work_struct worker who puts them in the bufs[] array in the debugfs pipe file. Userspace can then do whatever it wants with the data via the pipe. One can imagine it wanting to splice() these pages to disk in huge batches, or perhaps some zero-copy network card, etc. I've only tested this so far as verifying that 'cat' is able to push data into a regular file.

I didn't aim for for optimal behaviour before sending this patch out. I'm looking for comments. There's lots of room for improvement, particularly in reducing synchronization between cpus (not as it fills each dinky page) and in more flexible buffering semantics. As written there is no support for cyclic lists of pages rather than streaming nor are a huge amount of pending pages allowed. debugfs masks the mode of the file so it appears to be a regular file, but that'd be trivial to fix if this is methodology is useful.

Thoughts? I, for one, am tired of writing throw-away per-cpu tracing patches ;)

Index: 2.6-mm-tracepipe/fs/Makefile
===================================================================
@@ -45,6 +45,8 @@
 obj-y				+= devpts/
 
 obj-$(CONFIG_PROFILING)		+= dcookies.o
+
+obj-$(CONFIG_DEBUG_TRACEPIPE)	+= tracepipe.o
  
 # Do not add any filesystems before this line
 obj-$(CONFIG_FSCACHE)		+= fscache/

Index: 2.6-mm-tracepipe/fs/pipe.c
===================================================================
@@ -107,7 +107,7 @@
 	kunmap(buf->page);
 }
 
-static struct pipe_buf_operations anon_pipe_buf_ops = {
+struct pipe_buf_operations anon_pipe_buf_ops = {
 	.can_merge = 1,
 	.map = anon_pipe_buf_map,
 	.unmap = anon_pipe_buf_unmap,

@@ -486,7 +486,7 @@
 }
 
 
-static int
+int
 pipe_read_release(struct inode *inode, struct file *filp)
 {
 	pipe_read_fasync(-1, filp, 0);

@@ -511,7 +511,7 @@
 	return pipe_release(inode, decr, decw);
 }
 
-static int
+int
 pipe_read_open(struct inode *inode, struct file *filp)
 {
 	/* We could have perhaps used atomic_t, but this and friends

Index: 2.6-mm-tracepipe/include/linux/pipe_fs_i.h
===================================================================
@@ -56,4 +56,8 @@
 struct inode* pipe_new(struct inode* inode);
 void free_pipe_info(struct inode* inode);
 
+extern struct pipe_buf_operations anon_pipe_buf_ops;
+int pipe_read_open(struct inode *inode, struct file *filp);
+int pipe_read_release(struct inode *inode, struct file *filp);
+
 #endif

Index: 2.6-mm-tracepipe/include/linux/tracepipe.h
===================================================================
@@ -0,0 +1,39 @@
+/*
+ *  Copyright (C) 2004 Oracle Inc.
+ *
+ *	This program is free software; you can redistribute it and/or
+ *	modify it under the terms of the GNU General Public License version
+ *	2 as published by the Free Software Foundation.
+ */
+
+#ifndef _TRACEPIPE_H_
+#define _TRACEPIPE_H_
+
+struct trace_channel;
+
+#if defined(CONFIG_DEBUG_TRACEPIPE)
+
+struct trace_channel *tracepipe_create_channel(char *name);
+int tracepipe_remove_channel(struct trace_channel *chan);
+void tracepipe_event(struct trace_channel *chan, void *data, unsigned int len);
+
+#else
+
+static inline struct trace_channel *tracepipe_create_channel(char *name)
+{
+	return ERR_PTR(-ENODEV);
+}
+
+static inline int tracepipe_remove_channel(struct trace_channel *chan)
+{
+	return -ENODEV;
+}
+
+static inline void tracepipe_event(struct trace_channel *chan, void *data,
+				   unsigned int len)
+{
+}
+
+#endif
+
+#endif

Index: 2.6-mm-tracepipe/lib/Kconfig.debug
===================================================================
@@ -140,6 +140,17 @@
 
 	  If unsure, say N.
 
+config DEBUG_TRACEPIPE
+	bool "Provide debugfs named pipes with tracing events"
+	depends on DEBUG_FS
+	help
+	  tracepipe is a facility that lets kernel developers expose streams
+	  of debugging events as named pipes in the debugfs file system.
+	  Enable this option to give kernel subsytems the ability to register
+	  these kinds of named pipes.
+
+	  If unsure, say N.
+
 if !X86_64
 config FRAME_POINTER
 	bool "Compile the kernel with frame pointers"

Have you taken a look at relayfs and ltt?

Karim

Author, Speaker, Developer, Consultant
Pushing Embedded and Real-Time Linux Systems Beyond the Limits
http://www.opersys.com || [email protected] || 1-866-677-4546

Only briefly. They've always seemed more involved than the sort of thing I was after. I'll try and sit down and investigate in more detail.

There's definitely an opportunity for interfacing here. If nothing else, this clearly shows the interest for the kind of things both relayfs and ltt attempt to achieve.

So here are a few comments regading the implementation and how this relates to the stuff I'm working on.

In the case of LTT, we just open one relay channel per cpu. This avoids having to write the CPUID to the trace, that's 2 bytes less per event, and also avoids any need for synchronization.

As for get_cycles(), some architectures don't have anything useful to give. Here's for ARM (include/asm-arm/timex.h):
static inline cycles_t get_cycles (void)

{
	return 0;
}

In the case of LTT, we just use the, albeit expensive, do_gettimeofday when hardware counters aren't there (currently all non-x86 tracing does this, but this should be fixed.) Also, in the case of the x86 at least, we just write the lower 32-bits of the TSC, so that's 4 bytes less per event. Instead, we use the buffer_start and buffer_end callbacks provided by relayfs to write a header and footer containing full do_gettimeofday value and TSC value.

It seems to me that while this is a nice use of pipes, it isn't as fast as ram-locked pages. Basically relayfs does the bttv driver magic (or what used to be done in there, I haven't checked what they do lately.) Basically, we allocate pages, lock them into ram and remap them for use as a single memory area. No caching necessary. It goes from the buffer to whatever media you want (disk, network, etc.) IOW, user-space does a open(), mmap(), write(). Also, the channels exist whether user-space has done an open or not. That's good for flight-recording.

Looking at the code:

- tracepipe_event() does a get_cpu()/put_cpu() for protecting the writing to the buffer. What about tracing within an interrupt? local_irq_save()?

- I hadn't thought of doing something like this to write the header:
+ hdr = tcpu->next_region;
+ hdr->cycles = get_cycles();
+ hdr->cpu = cpu;
I will replace some of the memcpy() code in LTT with something like this.

- From what I assume is a "whishlist":
+ * - actually communicate missed to userspace

Already done in LTT.

+ * - how to specify wrapping or dropping

relayfs provides RELAY_MODE_CONTINUOUS and RELAY_MODE_NO_OVERWRITE.

+ * - non-temporal stores into bufs

The latest relayfs code doesn't care about timestamps. It's its clients job to do that (ex. ltt).

+ * - let caller reserve space and get a pointer into buf

This is the relevant relayfs function:
char* relay_reserve(struct rchan *rchan, u32 len, int *err, int *interrupting)

Karim

Author, Speaker, Developer, Consultant
Pushing Embedded and Real-Time Linux Systems Beyond the Limits
http://www.opersys.com || [email protected] || 1-866-677-4546