relay: Fix 4 off-by-one errors occuring when writing to a CPU buffer.

Semantically, start + offset is always lower than the total size in bytes, so the code should check against equality to size, not size + 1. When userspace did read() (but not necessarily restricted to this), this resulted in all-zeros data at the end of the buffer.

---
 include/linux/relay.h |    4 ++--
 kernel/relay.c        |    4 ++--
 2 files changed, 4 insertions(+), 4 deletions(-)

index 6cd8c44..8593ca1 100644
@@ -202,7 +202,7 @@ static inline void relay_write(struct rchan *chan,
 
 	local_irq_save(flags);
 	buf = chan->buf[smp_processor_id()];
-	if (unlikely(buf->offset + length > chan->subbuf_size))
+	if (unlikely(buf->offset + length >= chan->subbuf_size))
 		length = relay_switch_subbuf(buf, length);
 	memcpy(buf->data + buf->offset, data, length);
 	buf->offset += length;

@@ -228,7 +228,7 @@ static inline void __relay_write(struct rchan *chan,
 	struct rchan_buf *buf;
 
 	buf = chan->buf[get_cpu()];
-	if (unlikely(buf->offset + length > buf->chan->subbuf_size))
+	if (unlikely(buf->offset + length >= buf->chan->subbuf_size))
 		length = relay_switch_subbuf(buf, length);
 	memcpy(buf->data + buf->offset, data, length);
 	buf->offset += length;

index 7de644c..07f25e7 100644
@@ -622,7 +622,7 @@ size_t relay_switch_subbuf(struct rchan_buf *buf, size_t length)
 	if (unlikely(length > buf->chan->subbuf_size))
 		goto toobig;
 
-	if (buf->offset != buf->chan->subbuf_size + 1) {
+	if (buf->offset != buf->chan->subbuf_size) {
 		buf->prev_padding = buf->chan->subbuf_size - buf->offset;
 		old_subbuf = buf->subbufs_produced % buf->chan->n_subbufs;
 		buf->padding[old_subbuf] = buf->prev_padding;

@@ -645,7 +645,7 @@ size_t relay_switch_subbuf(struct rchan_buf *buf, size_t length)
 	new = buf->start + new_subbuf * buf->chan->subbuf_size;
 	buf->offset = 0;
 	if (!buf->chan->cb->subbuf_start(buf, new, old, buf->prev_padding)) {
-		buf->offset = buf->chan->subbuf_size + 1;
+		buf->offset = buf->chan->subbuf_size;
 		return 0;
 	}
 	buf->data = new;

1.5.5.4

Hi,

I'm wondering if the all-zeroes at the end of the buffer might be another case of the all-zeroes you were seeing due to cross-cpu reading you decribed in the other patch. In any case, I'm pretty sure this patch isn't doing what you think it is, and don't see how it could have fixed the problem (see below). There may still be a bug somewhere, but it would be good to be able to reproduce it. Does it happen even when running on a single cpu?

Hi,

I noticed this problem after adding those spinlocks. As far as I can tell, having (offset == subbuf_size + 1) at any given moment allows the read() handler to see inconsistent offsets:
1. writer sets offset = subbuf_size + 1
2. writer releases spinlock
3. read() acquires spinlock and reads the wrong offset
4. read() releases spinlock
5. next writer corrects the offset at the next write

No, it won't. Maximum length messages result in the following condition:
start + offset == subbuf_size
This happens because a buffer of length subbuf_size actually ranges from zero to (subbuf_size - 1) in regard to how it is addressed. Then, subbuf_size + 1 isn't just outside the bounds, but one more byte off. "Visual" example:
subbuf_size = 4

|[ ][ ][ ][ ]|[ ]
  0  1  2  3   subbuf_size

So, a full subbufer means offset equals subbuf_size, that is, the next empty slot is just outside the subbuffer.

Eduard

Yes, I understand that - what I meant was that the subbuf_size + 1 condition happens only in the buffer-full case (i.e. no reader or lagging reader), but not during the normal filling of a subbuffer, which you describe correctly.

So apparently what you're seeing is zeroes being read when there's a buffer-full condition? If so, we need to figure out exactly why that's happening to see whether your fix is really what's needed; I haven't seen problems in the buffer-full case before and I think your fix would break it even if it fixed your read problem. So it would be good to be able to reproduce it first.

Tom

Hi,

Sorry for being so late, there were some exams I had to cope with.

Although I couldn't reproduce zeros, I've come up with something I'd say is equally good. This has been done on a vanilla 2.6.26-rc6.

Please look at the testcase below and tell me what you think.

And yes, the changes in relay_write() and __relay_write() are inappropriate.

Cheers,
Eduard

---

index 1c9938a..5e1a32b 100644
@@ -9,7 +9,7 @@ obj-y     = sched.o fork.o exec_domain.o panic.o printk.o profile.o \
 	    rcupdate.o extable.o params.o posix-timers.o \
 	    kthread.o wait.o kfifo.o sys_ni.o posix-cpu-timers.o mutex.o \
 	    hrtimer.o rwsem.o nsproxy.o srcu.o semaphore.o \
-	    notifier.o ksysfs.o pm_qos_params.o sched_clock.o
+	    notifier.o ksysfs.o pm_qos_params.o sched_clock.o relay_test.o
 
 obj-$(CONFIG_SYSCTL_SYSCALL_CHECK) += sysctl_check.o
 obj-$(CONFIG_STACKTRACE) += stacktrace.o

---

Results, first run:

Test 0:
0000000 1616
0000002
---
Test 1:
0000000 3232 3232
0000004
---
Test 2:
0000000 1616
0000002
---
Test 3:
0000000 3232 3232 3232 3232
0000008
---
Test 0, 0:
---
Test 0, 0, 0, 0:
0000000 1616 1616 1616 1616
0000008
---
What the kernel said:
relay_test: Doing test 0 on CPU 1.
relay_test: Doing test 1 on CPU 1.
relay_test: Doing test 2 on CPU 1.
relay_test: Doing test 3 on CPU 0.
relay_test: Doing test 0 on CPU 0.
relay_test: Doing test 0 on CPU 0.
relay_test: Doing test 0 on CPU 0.
relay_test: Doing test 0 on CPU 0.
relay_test: Doing test 0 on CPU 0.
relay_test: Doing test 0 on CPU 0.

Results, second run, without rebooting in between:

Test 0:
0000000 1616
0000002
---
Test 1:
0000000 3232 3232
0000004
---
Test 2:
0000000 1616
0000002
---
Test 3:
---
Test 0, 0:
0000000 3232 3232 3232 3232
0000008
---
Test 0, 0, 0, 0:
---
What the kernel said:
relay_test: Doing test 0 on CPU 0.
relay_test: Doing test 1 on CPU 1.
relay_test: Doing test 2 on CPU 1.
relay_test: Doing test 3 on CPU 1.
relay_test: Doing test 0 on CPU 1.
relay_test: Doing test 0 on CPU 1.
relay_test: Doing test 0 on CPU 1.
relay_test: Doing test 0 on CPU 1.
relay_test: Doing test 0 on CPU 1.
relay_test: Doing test 0 on CPU 1.

The ugly script used to do this (on the second run I edited the file to remove previous dmesg stuff):

#!/bin/bash
echo "Test 0:" > /output.vanilla
echo "0" > /debug/relay_test_trigger sleep 1
hexdump /debug/relay_test_cpu* >> /output.vanilla sleep 1
echo "---" >> /output.vanilla

echo "Test 1:" >> /output.vanilla
echo "1" > /debug/relay_test_trigger sleep 1
hexdump /debug/relay_test_cpu* >> /output.vanilla sleep 1
echo "---" >> /output.vanilla

echo "Test 2:" >> /output.vanilla
echo "2" > /debug/relay_test_trigger sleep 1
hexdump /debug/relay_test_cpu* >> /output.vanilla sleep 1
echo "---" >> /output.vanilla

echo "Test 3:" >> /output.vanilla
echo "3" > /debug/relay_test_trigger sleep 1
hexdump /debug/relay_test_cpu* >> /output.vanilla sleep 1
echo "---" >> /output.vanilla

echo "Test 0, 0:" >> /output.vanilla
echo "0" > /debug/relay_test_trigger
echo "0" > /debug/relay_test_trigger sleep 1
hexdump /debug/relay_test_cpu* >> /output.vanilla sleep 1
echo "---" >> /output.vanilla

echo "Test 0, 0, 0, 0:" >> /output.vanilla echo "0" > /debug/relay_test_trigger
echo "0" > /debug/relay_test_trigger
echo "0" > /debug/relay_test_trigger
echo "0" > /debug/relay_test_trigger sleep 1
hexdump /debug/relay_test_cpu* >> /output.vanilla sleep 1
echo "---" >> /output.vanilla

echo "What the kernel said:" >> /output.vanilla dmesg | grep relay_test >> /output.vanilla

Hi,

Yes, this is a bug - thanks for sending the nice test case. This patch should fix it. BTW, if the output still looks a little different from what you were expecting, it might make more sense after adding a relay_test printk for each dropped event, something like this:

index 38c2755..2d4ecb1 100644
@@ -64,8 +64,23 @@ relay_test_create_buf_file(const char *filename, struct dentry *parent,
 				   buf, &relay_file_operations);
 }
 
+static int relay_test_subbuf_start(struct rchan_buf *buf,
+				   void *subbuf,
+				   void *prev_subbuf,
+				   size_t prev_padding)
+{
+	if (relay_buf_full(buf)) {
+		printk(KERN_INFO "relay_test: Dropped event on CPU %lu.\n",
+		       smp_processor_id());
+		return 0;
+	}
+
+	return 1;
+}
+
 static struct rchan_callbacks relay_test_callbacks = {
 	.create_buf_file = relay_test_create_buf_file,
+	.subbuf_start = relay_test_subbuf_start,
 };
 
 static int relay_test_init(void)

Thanks,

Tom

---

In relay's current read implementation, if the buffer is completely full but hasn't triggered the buffer-full condition (i.e. the last write didn't cross the subbuffer boundary) and the last subbuffer is exactly full, the subbuffer accounting code erroneously finds nothing available. This patch fixes the problem.

index 7de644c..f5a5a96 100644
@@ -832,6 +832,10 @@ static void relay_file_read_consume(struct rchan_buf *buf,
 	size_t n_subbufs = buf->chan->n_subbufs;
 	size_t read_subbuf;
 
+	if (buf->subbufs_produced == buf->subbufs_consumed &&
+	    buf->offset == buf->bytes_consumed)
+		return;
+
 	if (buf->bytes_consumed + bytes_consumed > subbuf_size) {
 		relay_subbufs_consumed(buf->chan, buf->cpu, 1);
 		buf->bytes_consumed = 0;

@@ -863,6 +867,8 @@ static int relay_file_read_avail(struct rchan_buf *buf, size_t read_pos)
 
 	relay_file_read_consume(buf, read_pos, 0);
 
+	consumed = buf->subbufs_consumed;
+
 	if (unlikely(buf->offset > subbuf_size)) {
 		if (produced == consumed)
 			return 0;

@@ -881,8 +887,12 @@ static int relay_file_read_avail(struct rchan_buf *buf, size_t read_pos)
 	if (consumed > produced)
 		produced += n_subbufs * subbuf_size;
 
-	if (consumed == produced)
+	if (consumed == produced) {
+		if (buf->offset == subbuf_size &&
+		    buf->subbufs_produced > buf->subbufs_consumed)
+			return 1;
 		return 0;
+	}
 
 	return 1;
 }

The all-zeros problem happened when poll() with infinite timeout is not used before reading. I fixed the user app I was writing, but the docs should really reflect this. Relay has a kinda strange interface.

Cheers,
Eduard

Hi,

You shouldn't have to use poll() with infinite timeout - see for example the blktrace user code. I'm not sure why you're seeing these problems, but if you're interested, even if only for comparison, you can try using the blktrace user code for kmemtrace too - I recently turned the blktrace userspace code into a generic tracing library called libutt, which you can get here:

http://utt.sourceforge.net

Here are some patches to your code that take a first stab at kmemtrace using utt:

http://utt.sourceforge.net/kmemtrace-utt-kernel.patch
http://utt.sourceforge.net/kmemtrace-utt-user.patch

Most of the kernel patch just adds tracing controls for the purpose of controlling the trace:

root@positron:/home/trz/kmemtrace-user# ls -al /sys/kernel/debug/kmem/trace
total 0
drwxr-xr-x 2 root root       0 2008-08-12 22:48 .
drwxr-xr-x 3 root root       0 2008-08-12 22:48 ..
-r-------- 1 root root       0 2008-08-12 22:48 abi_version
---------- 1 root root       0 2008-08-12 22:48 buf_nr
---------- 1 root root       0 2008-08-12 22:48 buf_size
---------- 1 root root       0 2008-08-12 22:48 create
---------- 1 root root       0 2008-08-12 22:48 destroy
-r--r--r-- 1 root root       0 2008-08-12 22:48 dropped
---------- 1 root root       0 2008-08-12 22:48 event_mask
---------- 1 root root       0 2008-08-12 22:48 start
---------- 1 root root       0 2008-08-12 22:48 stop
-r-------- 1 root root 9175040 2008-08-12 22:48 trace0
-r-------- 1 root root 1543192 2008-08-12 22:48 trace1

You'll also notice that the directory structure is a little different (/sys/kernel/debug/kmem/trace instead of /sys/kernel/debug/kmemtrace) and that the per-cpu files are named traceX instead of cpuX - this is just because it follows the blktrace conventions.

The other change to the kernel code is that it allows the buffers (and buffer sizes) to be created on demand instead of always allocated at boot time. The boot-time buffer and tracing still works as before, but it actually turns tracing off in kmem_setup_late(), since there's really no point in continuing logging and overrunning the buffers until kmemtraced is started up to read it. Having the buffers allocated and tracing started by kmemtraced also makes more sense to me, rather than the current behavior of continually logging and overrunning the buffers forever regardless of whether something is reading them. Maybe that's not exactly what you'd want, but it made more sense to me, so that's what I did for this.

So anyway, to use it, after you boot up, you can do:

root@positron:/home/trz/kmemtrace-user# ./kmemtraced-utt -t
^CChannel: trace
  CPU  0:                    0 events,     8960 KiB data
  CPU  1:                    0 events,     1508 KiB data
  Total:                     0 events (dropped 3124),    10468 KiB data
You have dropped events, consider using a larger buffer size (-b)

(yeah, I know, it shouldn't say 0 events, there were plenty!)

This will read the contents of the per-cpu relay files containing what you logged during boot into trace.kmem.0 and trace.kmem.1 - you'll have to rename them to cpu0.out,etc to use them with your analysis tools. The ctrl-c does the same thing as a normal trace i.e. stops the trace, reads the files and destroys the buffers.

You can start a new trace at any time using:

root@positron:/home/trz/kmemtrace-user# ./kmemtraced-utt
^CChannel: trace
  CPU  0:                    0 events,      316 KiB data
  CPU  1:                    0 events,      223 KiB data
  Total:                     0 events (dropped 0),      538 KiB data

Again, ctrl-c to stop the trace and clean up.

Also, because you're using part of the blktrace code, you get some other capabilities for free, such as tracing over the network. This starts the trace server, which will receive the trace data:

root@positron:/home/trz/kmemtrace-user# ./kmemtraced-utt -l
server: waiting for connections...
server: connection from 127.0.0.1

Now run the trace on the client, and ctrl-c to stop it:

root@positron:/home/trz/kmemtrace-user# ./kmemtraced-utt -h localhost
kmem: connecting to localhost
kmem: connected!
^CChannel: trace
  CPU  0:                    0 events,      581 KiB data
  CPU  1:                    0 events,      399 KiB data
  Total:                     0 events (dropped 0),      980 KiB data

And you should see something like this on the server as well:

server: end of run for trace
Channel: trace

  CPU  0:                    0 events,      581 KiB data
  CPU  1:                    0 events,      399 KiB data
  Total:                     0 events (dropped 0),      980 KiB data

The trace files will be in a directory named using the IP address and time:

root@positron:/home/trz/kmemtrace-user# ls -al 127.0.0.1-2008-08-13-04:12:39
total 1000
drwxr-xr-x 2 root root   4096 2008-08-12 23:12 .
drwxr-xr-x 6 trz  trz    4096 2008-08-12 23:12 ..
-rw-r--r-- 1 root root 594944 2008-08-12 23:13 trace.kmem.0
-rw-r--r-- 1 root root 408352 2008-08-12 23:13 trace.kmem.1

libutt isn't completely baked at this point, and the API will probably change depending on feedback, but still it seems to work pretty well at this point. If you decide to try it out, please let me know if you run into problems with it too.

Tom

Hi,

Thanks a lot, I'll have a look at them and try this instead.

Looks nice, as I had already implemented a way to turn off kmemtrace when logging. I'll get back to you in a few days, I'm not close to home right now.

BTW, did the kmemtrace user app work for you? Pekka seemed to have issues with compiling it.

Thanks,
Eduard

Hi,

Just a small problem compiling - there was no Makefile or configure, and the README doesn't say anything about autogen.sh, though I later saw something about it in the kernel documentation. Anyway, autogen.sh failed because I didn't have autoconf/automake installed; after doing that I didn't have a problem compiling. I did notice a couple printf format warnings, though.

I then ran kmemtraced and ran the check and report on the output. The check passed but the report tool just spewed a lot of error lines with the same caller. I looked a little closer and realized there was something really wrong with the reporting tool e.g. a tiny trace of about 10k, probably fewer than 200 events (a hexdump of the data looked ok to me), produced a report of about 800k. Remembering the printf format warnings, I realized it probably hadn't been run on a 32-bit system lately, so I tried it all again on a 64-bit system, and there it seemed to work ok, or at least the output looked reasonable, to my untrained eye.

Tom