utt tutorial

For the tracer, there's actually very little code to write; most of it can be lifted as-is from the vfstrace.c code, but we'll go over most of that code to show the API functions used and how the tracing code basically works. We'll first go over the tracer code that you'll need to write for any application, assuming that that's what someone writing a new application would be interested in right away. After that, we'll cover how the rest of the API is used in the boilerplate code, for those interested.

An utt tracer can operate in different modes e.g. disk mode, where the incoming data is saved directly to disk, network client mode where the data is sent to the destination using sendfile, non-sendfile network mode, and 'live mode', where the data is sent to stdout and the other end of the pipe is a parser or other post-processing utility interpreting the trace stream in real time.

For 'live mode' and non-sendfile network mode, in order to make it easy for the post-processing utilities to make sense of the incoming data, the tracer only sends data when it knows it has complete events to hand over. To make this possible, the tracing engine requires the application to define a callback function called verify_event() (if the application isn't interested in supporting live/non-sendfile network mode, it isn't necessary to implement verify_event() and this section can be skipped). The tracer passes this function a pointer to the start of the buffer containing the data and the end of the buffer containing the data. The application's implementation of this function should verify that the buffer contains a valid event and if it does, return the length of the event for the next time around the loop.

The application's implementation of verify_event() is passed to the tracer when the tracer is created using utt_alloc_trace() (see below) via a set of user-defined callbacks contained in an utt_ops struct. Currently verify_event() is the only callback defined for tracing, and it's only used for pipe mode.

So here's basically all the code you need to write to get a functional tracer, when combined with the boilerplate code in the example:

/*
 * vfstrace_verify_event - utt userspace API callback verify implementation
 */
static int vfstrace_verify_event(struct trace_info *ti,
				 const void *event, const void *buf_end)
{
	const struct vfs_common_trace_rec *t = event;
	int len;

	if (event + sizeof(*t) > buf_end)
		return 0;
	
	if (verify_trace(&ti->di, t->magic))
		return -1;
	
	switch (t->id) {
	case __TRACE_OPEN:
		len = sizeof(struct vfs_open_trace_rec) + t->pdu_len;
		break;
	case __TRACE_CLOSE:
		len = sizeof(struct vfs_close_trace_rec);
		break;
	case __TRACE_READ:
	case __TRACE_WRITE:
		len = sizeof(struct vfs_readwrite_trace_rec);
		break;
	case __TRACE_SENDFILE:
		len = sizeof(struct vfs_sendfile_trace_rec);
		break;
	default:
		return -1;
		break;
	}

	if (event + len > buf_end)
		return 0;
	
	return len;
}

static struct utt_ops ops =
{
	.verify_event = vfstrace_verify_event,
};

The parser requires more application-specific information than the tracer does in order to make sense of the data, so the parser code is by necessity somewhat more involved. It is however pretty straightforward - the parts that can't be lifted as-is from the vfsparse.c code can be easily adapted from the application-specific parts.

As with the tracer, we'll go over most of the parser code to show the API functions used and how the parsing engine basically works, but first we'll go over the parser code that you'll need to write for any application, assuming that that's what someone writing a new application would be interested in right away.

But first, an overview of the parsing process:

The parser basically reads the per-cpu trace files for all the channels generated by the tracer (or the trace data piped from the tracer in live mode) into sorted batches of event objects which are later passed back in the correct order to the application for display. Both the reading of event data into event objects and the their sorting and display are implemented or helped out by application-specific callbacks defined in an utt_ops struct object.

For a particular per-cpu file or pipe, while data remain in the trace stream, utp_do_parse() calls the utp_ops read_event() callback function whose responsibility it is to capture the next event's data in a dynamically allocated event object of the client's choosing. The parser saves up batches of these events and sometime later invokes client callbacks and display the data using the utp_ops print_event() callback.

The client's read_event() implementation uses its knowledge of the application's events to allocate event objects that hold the event data and uses the utp_read_data() API function to read the correct amount of data into the allocated object. Its also responsible for checking the integrity of the retrieved data (by checking the magic value in the event using the bad_magic() helper function) and that the version number contained in the magic value is supported by the parser (by using the verify_trace() helper function). Finally, if the trace data is being read on a system with a different endianness from the system it was generated on, read_event() also needs to implement and call a function that will switch the endianness of the data contained in the event object it passes back. As you can see, the client's read_event() needs to do quite a lot, but it's all pretty straightforward and can be easily adapted from existing examples such as the vfstrace example parser, vfsparse.c.

When the parser receives an event from read_event(), it puts it into an internal list or tree data structure along with the other currently outstanding events, which it will later process and send to the application in the proper order. In order to determine the correct order for an event, the parser will or may invoke other utp_ops callbacks such as get_event_time() (always required), get_event_cpu() (always required), get_event_sequence() (optional), get_channel_id() (optional) in order to determine the event's position relative to other events. It may also call set_event_time() callback (required) to adjust the time contained within an event. These callbacks are very simple to implement - basically they return the address of the respective field within the event struct, and are documented elsewhere.

To display the data, the parser calls the client's utp_ops print_event() implementation for each event in the batch of events it's ready to display. The processing print_event does should be relatively simple e.g. cast the void * passed in to the proper event type and print the fields to the output file (in the parse_info.ofp member). One callback of interest related to printing is print_channel_id(). This is optional for the client to implement and normally does nothing, but some apps may wish to specially encode a channel id and print it in a special way e.g. the blktrace implementation encodes device major and minor numbers in the channel id.

Here's the vfsparse application's implementation of read_event(). Basically, when the parsing engine calls this, it's asking for the next event in the given event stream in the form of an opaque user-allocated data object. This object will at later times in the parse be passed back to the application for it to print or satisfy queries about the data contained within it.

The read_event() implementation is passed the file descriptor to read from and at this point knows how much to read to determine the size of the object and in turn create the object. To actually read the data from the current stream, the implementation should use the utp_read_data() API function. For the vfstrace application, every event starts with a common header, decribed by vfs_common_trace_rec. Our implementation first attempts to read that amount of data; if it's not yet available, it just returns and tries again next time. If it's successful, it casts the buffer into a vfs_common_trace_rec and checks the endianness of the data. If necessary, it later converts it to the local system's endianness (note that the parser has to also implement that conversion, but it's simple and will be covered shortly). It then checks the magic number to make sure we have valid data at this point, and the goes on to determine the exact length of the event the data corresponds to. It does this by checking the id field in the common header, which is unique to each event. Given the event type, it can then determine the length of the event. If the event doesn't have any variable-length data in it, it's simply the length of the corresponding event struct. If it does have variable-length data, the application should read the variable data as well so that it can be included in the returned event object. In the case of vfstrace, the __TRACE_OPEN event contains a variable length filename whose length is contained in the pdu_len field of the common record. We use this length to make another utp_read_data() call to retrieve the rest of the data for the event. Now that we know the length of the event, we allocate an object to give to the parser, fill it in with the data we've read, do the endianness conversion and integrity check, and hand it over to the parse engine.

Here's the vfsparse read_event() implementation in its entirety:

void *vfsparse_read_event(struct parse_info *pi,
			  int fd, int should_block, int *fdblock)
{
	int pdu_len, ret;
	int len, var_len, common_len = sizeof(struct vfs_common_trace_rec);
	struct vfs_common_trace_rec *r;
	void *event;
	struct data_info *di = &pi->di;

	ret = utp_read_data(fd, recbuf, common_len, should_block, fdblock);
	if (ret)
		return NULL;

	r = (struct vfs_common_trace_rec *)recbuf;

	/*
	* look at first trace to check whether we need to convert
	* data in the future
	*/
	if (di->data_is_native == -1 && check_data_endianness(di, r->magic))
		return NULL;

	if (bad_magic(di, r->magic))
		return NULL;

	switch (r->id) {
	case __TRACE_OPEN:
		pdu_len = get_pdulen(pi, r);
		len = sizeof(struct vfs_open_trace_rec) + pdu_len;
		break;
	case __TRACE_CLOSE:
		len = sizeof(struct vfs_close_trace_rec);
		break;
	case __TRACE_READ:
	case __TRACE_WRITE:
		len = sizeof(struct vfs_readwrite_trace_rec);
		break;
	case __TRACE_SENDFILE:
		len = sizeof(struct vfs_sendfile_trace_rec);
		break;
	default:
		return NULL;
		break;
	}

	event = malloc(len);
	memcpy(event, r, common_len);
	var_len = len - common_len;
	if (utp_read_data(fd, event + common_len, var_len, 1, fdblock)) {
		free(event);
		return NULL;
	}

	trace_to_cpu(di->data_is_native, event);

	if (verify_trace(di, r->magic)) {
		free(event);
		return NULL;
	}

	return event;
}

void vfsparse_free_event(void *event)
{
	free(event);
}

If the event data is the same as the system the parser is running on, there's nothing to do and it returns. If however the receiving system is little-endian, it needs to convert it. Basically this means converting each field that needs it using the endian macros defined in utt-common.h. They take the form beXX_to_cpu and convert network byte-order data to little-endian if necessary. The vfstrace conversion helper function is shown below; other applications can easily follow the same pattern for their own event types.

static char recbuf[1024];

static void trace_to_cpu(int data_is_native, void *rec)
{
	struct vfs_common_trace_rec *t = rec;

	if (data_is_native)
		return;

	t->magic	= be32_to_cpu(t->magic);
	t->id		= be16_to_cpu(t->id);
	t->cpu		= be16_to_cpu(t->cpu);
	t->sequence	= be32_to_cpu(t->sequence);
	t->time		= be64_to_cpu(t->time);
	t->pid		= be32_to_cpu(t->pid);
	t->pdu_len	= be16_to_cpu(t->pdu_len);

	switch (t->id) {
	case __TRACE_OPEN: {
		struct vfs_open_trace_rec *r = rec;
		r->fd = be32_to_cpu(r->fd);
		break;
	}
	case __TRACE_CLOSE: {
		struct vfs_close_trace_rec *r = rec;
		r->fd = be32_to_cpu(r->fd);
		break;
	}
	case __TRACE_READ:
	case __TRACE_WRITE: {
		struct vfs_readwrite_trace_rec *r = rec;
		r->fd = be32_to_cpu(r->fd);
		r->count = be32_to_cpu(r->count);
		r->ret = be32_to_cpu(r->ret);
		break;
	}
	case __TRACE_SENDFILE: {
		struct vfs_sendfile_trace_rec *r = rec;
		r->out_fd = be32_to_cpu(r->out_fd);
		r->in_fd = be32_to_cpu(r->in_fd);
		r->start_ppos = be64_to_cpu(r->start_ppos);
		r->start_count = be32_to_cpu(r->start_count);
		r->start_max = be64_to_cpu(r->start_max);
		r->end_ppos = be64_to_cpu(r->end_ppos);
		r->end_count = be32_to_cpu(r->end_count);
		r->end_max = be64_to_cpu(r->end_max);
		r->ret = be32_to_cpu(r->ret);
		break;
	}
	default:
		return;
		break;
	}
}

static int vfsparse_print_event(struct parse_info *pi,
				void *parse_private __attribute ((unused)),
				void *channel_private __attribute ((unused)),
				void *cpu_private __attribute ((unused)),
				void *event,
				int text_output)
{
	struct vfs_common_trace_rec *common = event;

	if (!text_output)
		return 0;

	vfsparse_print_common(pi, common);

	switch (common->id) {
	case __TRACE_OPEN: {
		struct vfs_open_trace_rec *r = event;
		fprintf(pi->ofp, "fd: %8d fname: %s\n", r->fd,
			(char *)r + sizeof(*r));
		break;
	}
	case __TRACE_CLOSE: {
		struct vfs_close_trace_rec *r = event;
		fprintf(pi->ofp, "fd: %8d\n", r->fd);
		break;
	}
	case __TRACE_READ:
	case __TRACE_WRITE: {
		struct vfs_readwrite_trace_rec *r = event;
		fprintf(pi->ofp, "fd: %8d cnt: %8d ret: %8d\n",
			r->fd, r->count, r->ret);
		break;
	}
	case __TRACE_SENDFILE: {
		struct vfs_sendfile_trace_rec *r = event;
		fprintf(pi->ofp, "out_fd: %8d in_fd: %8d start_ppos: %8llu" \
			" start_cnt: %8d start_max: %8llu end_ppos: %8llu" \
			" end_cnt: %8d end_max: %8llu ret: %8d\n",
			r->out_fd, r->in_fd,
			r->start_ppos, r->start_count, r->start_max,
			r->end_ppos, r->end_count, r->end_max,
			r->ret);
		break;
	}
	default:
		break;
	}
	
	return 0;
}

static void vfsparse_print_common(struct parse_info *pi,
				  struct vfs_common_trace_rec *r)
{
	fprintf(pi->ofp, "%7s %2d %8d %5d.%09lu %5u %15s ",
		event_name(r->id), r->cpu, r->sequence,
		(int) SECONDS(r->time), (unsigned long) NANO_SECONDS(r->time),
		r->pid, r->comm);
}

static char *event_name(int id)
{
	char *name;

	switch (id) {
	case __TRACE_OPEN:
		name = "OPEN";
		break;
	case __TRACE_CLOSE:
		name = "CLOSE";
		break;
	case __TRACE_READ:
		name = "READ";
		break;
	case __TRACE_WRITE:
		name = "WRITE";
		break;
	case __TRACE_SENDFILE:
		name = "SENDFIL";
		break;
	default:
		name = "UNKNOWN";
		break;
	}

	return name;
}

That's basically it - at this point we've achieved what we set out to do - display the binary trace stream in a human-readable form.

There are a few more minor application-specific things the parser needs to do to be complete - we'll take a moment to describe those before we move on to a description of the rest of the utp API by looking at the boilerplatecode.

To support the binary option, which instead of, or in addition to displaying the human-readable form results in the event data being saved to disk as binary data, the application should provide an implementation of the output_binary() utp_ops callback function, which basically does nothing more than reter the length of the data in the event its passed. This code also can be easily adapted by a new parser to dump the application's events.

static void vfsparse_output_binary(struct parse_info *pi, void *event)
{
	struct vfs_common_trace_rec *r = event;
	int pdu_len, len = 0;

	switch (r->id) {
	case __TRACE_OPEN:
		pdu_len = get_pdulen(pi, r);
		len = sizeof(struct vfs_open_trace_rec) + pdu_len;
		break;
	case __TRACE_CLOSE:
		len = sizeof(struct vfs_close_trace_rec);
		break;
	case __TRACE_READ:
	case __TRACE_WRITE:
		len = sizeof(struct vfs_readwrite_trace_rec);
		break;
	case __TRACE_SENDFILE:
		len = sizeof(struct vfs_sendfile_trace_rec);
		break;
	default:
		break;
	}

	if (len)
		utp_output_binary(pi, r, len);
}

static inline __u32 vfsparse_get_event_cpu(void *event)
{
	struct vfs_common_trace_rec *r = event;
	return r->cpu;
}

static inline __u64 vfsparse_get_event_time(void *event)
{
	struct vfs_common_trace_rec *r = event;
	return r->time;
}
  
static inline void vfsparse_set_event_time(void *event,
					   __u64 time)
{
	struct vfs_common_trace_rec *r = event;
	r->time = time;
}

static inline __u32 vfsparse_get_event_seq(void *event)
{
	struct vfs_common_trace_rec *r = event;
	return r->sequence;
}

static struct utp_ops ops =
{
	.alloc_channel_private = NULL,
	.alloc_cpu_private = NULL,
	.free_event = vfsparse_free_event,
	.get_channel_id = NULL,
	.print_channel_id = NULL,
	.get_event_cpu = vfsparse_get_event_cpu,
	.get_event_time = vfsparse_get_event_time,
	.set_event_time = vfsparse_set_event_time,
	.get_event_seq = vfsparse_get_event_seq,
	.read_event = vfsparse_read_event,
	.print_event = vfsparse_print_event,
	.output_binary = vfsparse_output_binary,
	.show_channel_stats = NULL,
	.show_cpu_stats = NULL,
};

The only other thing an application would need to do outside of the boilerplate code of this example would be to change the call to utp_alloc_parse(), described below.

We'll now go over main(), where most of the API calls happen, but where basically only one line of code needs to be changed for a new application (it isn't necessary to understand how all the other utp_ API functions are used here in order to write a parse using the boilerplace code - this section is for anyone interested in the complete API:

int main(int argc, char *argv[])
{
	int c, ret;
	
	/* New apps should change this line. */
	pi = utp_alloc_parse("vfs", VFS_TRACE_MAGIC, VFS_TRACE_VERSION,
			     NULL, &ops);

The first thing we'd normally do is instrument the kernel code to log the data we're interested in. I'll describe how the vfstrace example kernel code does that, but since there are many ways of skinning this cat, it shouldn't be taken as the only or even best way to write kernel instrumentation to be consumed by utt-based applications.

As mentioned, we'll be tracing 5 vfs 'events'; we'll show a couple of them here - see the code itself for the others.

linux-2.6/fs/read_write.c:

asmlinkage ssize_t sys_read(unsigned int fd, char __user * buf, size_t count)
{
	struct file *file;
	ssize_t ret = -EBADF;
	int fput_needed;

	file = fget_light(fd, &fput_needed);
	if (file) {
		loff_t pos = file_pos_read(file);
		ret = vfs_read(file, buf, count, &pos);
		file_pos_write(file, pos);
		fput_light(file, fput_needed);
	}


	if (fd > 2)
		vfs_read_trace(fd, count, ret);

	return ret;
}

The code we're adding is shown in red. We're interested in tracing all read system calls, but to avoid being overwhelmed by the standard file streams, we'll say we're only interested in fd's greater than 2. For any read we're interested in, we call a function called vfs_read_trace() and pass it the variables we're interested in logging: fd, count, and ret. vfstrace_trace_read is a macro defined in our own header file in include/linux:

linux-2.6/include/linux/vfstrace_api.h:

#define vfs_read_trace(fd, count, ret) \
	trace_mark(vfs_readwrite, "%u %u %u %d", __TRACE_READ, fd, count, ret);

As another example, we'll show the instrumentation for the open syscall, which logs the fd and the filename of the file being opened:

linux-2.6/fs/open.c:

long do_sys_open(int dfd, const char __user *filename, int flags, int mode)
{
	char *tmp = getname(filename);
	int fd = PTR_ERR(tmp);

	if (!IS_ERR(tmp)) {
		fd = get_unused_fd_flags(flags);
		if (fd >= 0) {
			struct file *f = do_filp_open(dfd, tmp, flags, mode);
			if (IS_ERR(f)) {
				put_unused_fd(fd);
				fd = PTR_ERR(f);
			} else {
				fsnotify_open(f->f_path.dentry);
				fd_install(fd, f);
			}
		}

		vfs_open_trace(tmp, fd);

		putname(tmp);
	}

	return fd;
}

linux-2.6/include/linux/vfstrace_api.h:

#define vfs_open_trace(filename, fd) \
	trace_mark(vfs_open, "%s %u", filename, fd);

vfstrace-utt-example/vfstrace-mod.c:

static int __init probe_init(void)
{
	int ret;

	ret = create_trace_controls();
	if (ret) {
		printk("Unable to create trace controls\n");
		goto err;
	}

	ret = marker_probe_register("vfs_open", "%s %u", vfs_open_probe, NULL);
	if (ret) {
		printk("Unable to register vfstrace probe vfs_open\n");
		goto err;
	}

	ret = marker_probe_register("vfs_readwrite", "%u %u %u %d",
				    vfs_readwrite_probe, NULL);
	if (ret) {
		printk("Unable to register vfstrace probe vfs_readwrite\n");
		goto err;
	}

        .
        .
        .
}

void vfs_readwrite_probe(void *probe_data, void *call_data,
			 const char *format, va_list *args)
{
	unsigned int id = va_arg(*args, typeof(id));
	unsigned int fd = va_arg(*args, typeof(fd));
	unsigned int count = va_arg(*args, typeof(count));
	int ret = va_arg(*args, typeof(ret));

	if (unlikely(!(tracing & id)))
		return;

	__vfs_readwrite_trace(channel, id, fd, count, ret);
}

static void __vfs_readwrite_trace(struct rchan *channel, u16 id,
				  u32 fd, u32 count, s32 ret)
{
	struct vfs_readwrite_trace_rec *t;
	unsigned long flags;

	local_irq_save(flags);
	t = relay_reserve(channel, sizeof(*t));
	if (t) {
		__vfs_common_trace(&t->common, id, 0, 0, NULL);
		/* event-specific fields */
		t->fd = fd;
		t->count = count;
		t->ret = ret;
	}
	local_irq_restore(flags);
}

struct vfs_readwrite_trace_rec {
	struct vfs_common_trace_rec common;

	__u32 fd;		/* file descriptor to read/write */
	__u32 count;		/* count of bytes to read/write */
	__s32 ret;		/* count of bytes read/written, or err */
};

/*
 * VFS trace, common part of each trace record
 */
struct vfs_common_trace_rec {
	__u32 magic;		/* MAGIC << 8 | version */
	__u16 id;		/* event id */
	__u32 cpu;		/* on what cpu did it happen */
	__u32 sequence;		/* event number */
	__u64 time;		/* in microseconds */
	__u32 pid;		/* who did it */
	char comm[TASK_COMM_LEN]; /* who did it (executable) */
	__u16 pdu_len;		/* length of variable data at end */
};

static inline void __vfs_common_trace(struct vfs_common_trace_rec *t, u16 id,
				      u16 pdu_off, u16 pdu_len, void *pdu_data)
{
	struct task_struct *tsk = current;
	unsigned long *sequence;
	pid_t pid = tsk->pid;
	int cpu;

	cpu = smp_processor_id();
	sequence = per_cpu_ptr(trace_sequence, cpu);

	t->magic = VFS_TRACE_MAGIC | VFS_TRACE_VERSION;
	t->id = id;
	t->cpu = cpu;
	t->sequence = ++(*sequence);
	t->time = ktime_to_ns(ktime_get());
	t->pid = pid;
	memcpy(t->comm, tsk->comm, sizeof(tsk->comm));
	t->pdu_len = pdu_len;

	if (pdu_len)
		memcpy((void *)t + pdu_off, pdu_data, pdu_len);
}

static void __vfs_readwrite_trace(struct rchan *channel, u16 id,
				  u32 fd, u32 count, s32 ret)
{
	struct vfs_readwrite_trace_rec *t;
	unsigned long flags;

	local_irq_save(flags);
	t = relay_reserve(channel, sizeof(*t));
	if (t) {
		__vfs_common_trace(&t->common, id, 0, 0, NULL);
		/* event-specific fields */
		t->fd = fd;
		t->count = count;
		t->ret = ret;
	}
	local_irq_restore(flags);
}

struct vfs_open_trace_rec {
	struct vfs_common_trace_rec common;

	__u32 fd;		/* file descriptor opened, or err */
};

void vfs_open_probe(void *probe_data, void *call_data,
		    const char *format, va_list *args)
{
	unsigned int id = __TRACE_OPEN;
	char *filename = va_arg(*args, typeof(filename));
	unsigned int fd = va_arg(*args, typeof(fd));

	if (unlikely(!(tracing & id)))
		return;

	__vfs_open_trace(channel, id, fd, strlen(filename) + 1, filename);
}

static void __vfs_open_trace(struct rchan *channel, u16 id, u32 fd,
			     u16 pdu_len, void *pdu_data)
{
	struct vfs_open_trace_rec *t;
	unsigned long flags;
	u16 pdu_off = sizeof(*t);

	local_irq_save(flags);
	t = relay_reserve(channel, sizeof(*t) + pdu_len);
	if (t) {
		__vfs_common_trace(&t->common, id,
				   pdu_off, pdu_len, pdu_data);
		/* event-specific fields */
		t->fd = fd;
	}
	local_irq_restore(flags);
}