Re: [PATCH] ring-buffer: Fix polling on trace_pipe

From: Martin Lau
Date: Wed Jun 11 2014 - 01:58:29 EST


Hi Steve,

Attached is the modified test program. Here is the sample output:

localhost ~ # ./ftrace-test-epoll-kafai
<...>-1857 [000] ...1 720.174295: tracing_mark_write: some data
1857: waitting for more data......
1858: written more data
<block here>

Thanks,
--Martin

On Tue, Jun 10, 2014 at 11:49:15AM -0400, Steven Rostedt wrote:
> On Mon, 9 Jun 2014 23:06:42 -0700
> Martin Lau <kafai@xxxxxx> wrote:
>
> > ring_buffer_poll_wait() should always put the poll_table to its wait_queue
> > even there is immediate data available. Otherwise, the following epoll and
> > read sequence will eventually hang forever:
> >
> > 1. Put some data to make the trace_pipe ring_buffer read ready first
> > 2. epoll_ctl(efd, EPOLL_CTL_ADD, trace_pipe_fd, ee)
> > 3. epoll_wait()
> > 4. read(trace_pipe_fd) till EAGAIN
> > 5. Add some more data to the trace_pipe ring_buffer
> > 6. epoll_wait() -> this epoll_wait() will block forever
> >
> > ~ During the epoll_ctl(efd, EPOLL_CTL_ADD,...) call in step 2,
> > ring_buffer_poll_wait() returns immediately without adding poll_table,
> > which has poll_table->_qproc pointing to ep_poll_callback(), to its
> > wait_queue.
> > ~ During the epoll_wait() call in step 3 and step 6,
> > ring_buffer_poll_wait() cannot add ep_poll_callback() to its wait_queue
> > because the poll_table->_qproc is NULL and it is how epoll works.
> > ~ When there is new data available in step 6, ring_buffer does not know
> > it has to call ep_poll_callback() because it is not in its wait queue.
> > Hence, block forever.
> >
> > Other poll implementation seems to call poll_wait() unconditionally as the very
> > first thing to do. For example, tcp_poll() in tcp.c.
>
> I'm trying to see the effect of this bug, but can't seem to reproduce
> it. Maybe I did something wrong. Attached is a test program I wrote
> trying to follow your instructions. I don't use epoll, so perhaps I
> didn't use it correctly.
>
> Can you modify it to show me the problem this is trying to fix. That
> is, without this patch it hangs, but with the patch it does not.
>
> Thanks!
>
> -- Steve
>
> >
> > Signed-off-by: Martin Lau <kafai@xxxxxx>
> > ---
> > kernel/trace/ring_buffer.c | 4 ----
> > 1 file changed, 4 deletions(-)
> >
> > diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> > index fd12cc5..a6e64e8 100644
> > --- a/kernel/trace/ring_buffer.c
> > +++ b/kernel/trace/ring_buffer.c
> > @@ -613,10 +613,6 @@ int ring_buffer_poll_wait(struct ring_buffer *buffer, int cpu,
> > struct ring_buffer_per_cpu *cpu_buffer;
> > struct rb_irq_work *work;
> >
> > - if ((cpu == RING_BUFFER_ALL_CPUS && !ring_buffer_empty(buffer)) ||
> > - (cpu != RING_BUFFER_ALL_CPUS && !ring_buffer_empty_cpu(buffer, cpu)))
> > - return POLLIN | POLLRDNORM;
> > -
> > if (cpu == RING_BUFFER_ALL_CPUS)
> > work = &buffer->irq_work;
> > else {
>

#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <sys/epoll.h>
#include <fcntl.h>
#include <unistd.h>
#include <assert.h>

static const char * debugfs_list[] = {
"/debug/tracing",
"/sys/kernel/debug/tracing",
"/d/tracing",
NULL,
};

static const char *debugfs;
static int markfd;
static int trace_pipe_fd;

static const char *find_debugfs(void)
{
struct stat st;
int i;
int r;

for (i = 0; debugfs_list[i]; i++) {
r = stat(debugfs_list[i], &st);
if (r < 0)
continue;
if (S_ISDIR(st.st_mode))
return debugfs_list[i];
}
return NULL;
}

static char * make_path(const char *file)
{
char *path;
int size;

size = strlen(debugfs) + strlen(file) + 2;
path = malloc(size);
if (!path) {
perror("malloc");
exit(-1);
}
sprintf(path, "%s/%s", debugfs, file);
return path;
}

static void mark_write(const char *str)
{
write(markfd, str, strlen(str));
}

static void read_trace_pipe(void)
{
char buf[1024];
int r;

while ((r = read(trace_pipe_fd, buf, 1024)) > 0)
printf("%.*s", r, buf);
}

int main (int argc, char **argv)
{
struct epoll_event ee;
char *marker;
char *pipe;
int efd;
int ret;
pid_t dwrt_pid;

debugfs = find_debugfs();
if (!debugfs) {
fprintf(stderr, "Could not find debugfs\n");
exit(-1);
}

marker = make_path("trace_marker");
pipe = make_path("trace_pipe");

markfd = open(marker, O_WRONLY);
if (markfd < 0) {
perror("marker");
exit(-1);
}
trace_pipe_fd = open(pipe, O_RDONLY|O_NONBLOCK);
if (trace_pipe_fd < 0) {
perror("trace_pipe");
exit(-1);
}

efd = epoll_create(1);
if (efd < 0) {
perror("epoll_create");
exit(-1);
}

mark_write("some data");
ret = epoll_ctl(efd, EPOLL_CTL_ADD, trace_pipe_fd, &ee);
if (ret < 0) {
perror("epoll_ctl");
exit(-1);
}
epoll_wait(efd, &ee, 1, -1);
read_trace_pipe();
dwrt_pid = fork();
assert(dwrt_pid != -1);
if (dwrt_pid == 0) {
sleep(10);
mark_write("more data");
printf("%d: written more data\n", getpid());
} else {
printf("%d: waitting for more data......\n", getpid());
epoll_wait(efd, &ee, 1, -1);
printf("%d: got more data\n", getpid());
read_trace_pipe();
}
return 0;
}