>From 63c1b869d94eb31a98015af09fb24e22151f2f00 Mon Sep 17 00:00:00 2001
From: Arjan van de Ven <[email protected]>
Date: Tue, 4 Nov 2008 21:08:11 -0800
Subject: [PATCH] ftrace: add an fsync tracer
fsync() (and its cousin, fdatasync()) are important chokepoints in the
kernel as they imply very expensive operations, both in terms of filesystem
operations (ext3 writes back its entire journal) as well as the block layer
(fsync() implies sending a cache flushing barrier to the SATA/SCSI disk).
This tracer makes a log of which application calls fsync() on which file,
so that developers and others interested in finding these choke points
can locate them and fix them in the apps that call this function.
Signed-off-by: Arjan van de Ven <[email protected]>
---
fs/sync.c | 4 +
include/trace/fs.h | 11 +++
kernel/trace/Kconfig | 9 +++
kernel/trace/Makefile | 1 +
kernel/trace/trace.h | 1 +
kernel/trace/trace_fsync.c | 165 ++++++++++++++++++++++++++++++++++++++++++++
6 files changed, 191 insertions(+), 0 deletions(-)
create mode 100644 include/trace/fs.h
create mode 100644 kernel/trace/trace_fsync.c
diff --git a/fs/sync.c b/fs/sync.c
index 2967562..dd5641b 100644
--- a/fs/sync.c
+++ b/fs/sync.c
@@ -14,6 +14,8 @@
#include <linux/quotaops.h>
#include <linux/buffer_head.h>
+#include <trace/fs.h>
+
#define VALID_FLAGS (SYNC_FILE_RANGE_WAIT_BEFORE|SYNC_FILE_RANGE_WRITE| \
SYNC_FILE_RANGE_WAIT_AFTER)
@@ -81,6 +83,8 @@ long do_fsync(struct file *file, int datasync)
int err;
struct address_space *mapping = file->f_mapping;
+ trace_do_fsync(file, datasync);
+
if (!file->f_op || !file->f_op->fsync) {
/* Why? We can still call filemap_fdatawrite */
ret = -EINVAL;
diff --git a/include/trace/fs.h b/include/trace/fs.h
new file mode 100644
index 0000000..9d964f1
--- /dev/null
+++ b/include/trace/fs.h
@@ -0,0 +1,11 @@
+#ifndef _TRACE_FS_H
+#define _TRACE_FS_H
+
+#include <linux/fs.h>
+#include <linux/tracepoint.h>
+
+DEFINE_TRACE(do_fsync,
+ TPPROTO(struct file *file, int datasync),
+ TPARGS(file, datasync));
+
+#endif
diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index 33dbefd..42d60c5 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -119,6 +119,15 @@ config CONTEXT_SWITCH_TRACER
This tracer gets called from the context switch and records
all switching of tasks.
+config FSYNC_TRACER
+ bool "Trace fsync() calls"
+ depends on DEBUG_KERNEL
+ select TRACING
+ select MARKERS
+ help
+ This tracer records fsync() and fdatasync() calls. These calls
+ are key reasons for IO related system latency.
+
config BOOT_TRACER
bool "Trace boot initcalls"
depends on DEBUG_KERNEL
diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index c8228b1..292f39d 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -15,6 +15,7 @@ obj-$(CONFIG_RING_BUFFER) += ring_buffer.o
obj-$(CONFIG_TRACING) += trace.o
obj-$(CONFIG_CONTEXT_SWITCH_TRACER) += trace_sched_switch.o
+obj-$(CONFIG_FSYNC_TRACER) += trace_fsync.o
obj-$(CONFIG_SYSPROF_TRACER) += trace_sysprof.o
obj-$(CONFIG_FUNCTION_TRACER) += trace_functions.o
obj-$(CONFIG_IRQSOFF_TRACER) += trace_irqsoff.o
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 8465ad0..dd0fef4 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -22,6 +22,7 @@ enum trace_type {
TRACE_MMIO_RW,
TRACE_MMIO_MAP,
TRACE_BOOT,
+ TRACE_FSYNC,
__TRACE_LAST_TYPE
};
diff --git a/kernel/trace/trace_fsync.c b/kernel/trace/trace_fsync.c
new file mode 100644
index 0000000..9cfb9d0
--- /dev/null
+++ b/kernel/trace/trace_fsync.c
@@ -0,0 +1,165 @@
+/*
+ * trace fsync calls
+ * Copyright (C) 2008 Intel Corporation
+ *
+ * Based extensively on trace_sched_switch.c
+ * Copyright (C) 2007 Steven Rostedt <[email protected]>
+ *
+ */
+#include <linux/module.h>
+#include <linux/fs.h>
+#include <linux/debugfs.h>
+#include <linux/kallsyms.h>
+#include <linux/uaccess.h>
+#include <linux/ftrace.h>
+#include <trace/fs.h>
+
+#include "trace.h"
+
+static struct trace_array *ctx_trace;
+static int __read_mostly tracer_enabled;
+static atomic_t fsync_ref;
+
+static void
+probe_do_fsync(struct file *file, int datasync)
+{
+ char *buffer;
+ char *err;
+
+ if (!atomic_read(&fsync_ref))
+ return;
+
+ if (!tracer_enabled)
+ return;
+
+ buffer = kmalloc(4096, GFP_KERNEL);
+ if (!buffer)
+ return;
+
+ memset(buffer, 0, 4096);
+ err = d_path(&file->f_path, buffer, 4096);
+
+ if (IS_ERR(err))
+ goto out;
+
+ ftrace_printk("Process %s is calling fsync on %s\n",
+ current->comm, err);
+
+out:
+ kfree(buffer);
+}
+
+static void fsync_reset(struct trace_array *tr)
+{
+ int cpu;
+
+ tr->time_start = ftrace_now(tr->cpu);
+
+ for_each_online_cpu(cpu)
+ tracing_reset(tr, cpu);
+}
+
+static int tracing_fsync_register(void)
+{
+ int ret;
+
+ ret = register_trace_do_fsync(probe_do_fsync);
+ if (ret) {
+ pr_info("wakeup trace: Couldn't activate tracepoint"
+ " probe to do_fsync\n");
+ return ret;
+ }
+
+ return ret;
+}
+
+static void tracing_fsync_unregister(void)
+{
+ unregister_trace_do_fsync(probe_do_fsync);
+}
+
+static void tracing_start_fsync(void)
+{
+ long ref;
+
+ ref = atomic_inc_return(&fsync_ref);
+ if (ref == 1)
+ tracing_fsync_register();
+}
+
+static void tracing_stop_fsync(void)
+{
+ long ref;
+
+ ref = atomic_dec_and_test(&fsync_ref);
+ if (ref)
+ tracing_fsync_unregister();
+}
+
+void tracing_start_cmdline_record(void)
+{
+ tracing_start_fsync();
+}
+
+void tracing_stop_cmdline_record(void)
+{
+ tracing_stop_fsync();
+}
+
+static void start_fsync_trace(struct trace_array *tr)
+{
+ fsync_reset(tr);
+ tracing_start_cmdline_record();
+ tracer_enabled = 1;
+}
+
+static void stop_fsync_trace(struct trace_array *tr)
+{
+ tracer_enabled = 0;
+ tracing_stop_cmdline_record();
+}
+
+static void fsync_trace_init(struct trace_array *tr)
+{
+ ctx_trace = tr;
+
+ if (tr->ctrl)
+ start_fsync_trace(tr);
+}
+
+static void fsync_trace_reset(struct trace_array *tr)
+{
+ if (tr->ctrl)
+ stop_fsync_trace(tr);
+}
+
+static void fsync_trace_ctrl_update(struct trace_array *tr)
+{
+ /* When starting a new trace, reset the buffers */
+ if (tr->ctrl)
+ start_fsync_trace(tr);
+ else
+ stop_fsync_trace(tr);
+}
+
+static struct tracer fsync_trace __read_mostly =
+{
+ .name = "fsync",
+ .init = fsync_trace_init,
+ .reset = fsync_trace_reset,
+ .ctrl_update = fsync_trace_ctrl_update,
+};
+
+__init static int init_fsync_trace(void)
+{
+ int ret = 0;
+
+ if (atomic_read(&fsync_ref))
+ ret = tracing_fsync_register();
+ if (ret) {
+ pr_info("error registering fsync trace\n");
+ return ret;
+ }
+ return register_tracer(&fsync_trace);
+}
+device_initcall(init_fsync_trace);
--
1.6.0.3
--
Arjan van de Ven Intel Open Source Technology Centre
For development, discussion and tips for power savings,
visit http://www.lesswatts.org
On Wed, Nov 05, 2008 at 09:49:02AM -0800, Arjan van de Ven wrote:
> --- /dev/null
> +++ b/kernel/trace/trace_fsync.c
> @@ -0,0 +1,165 @@
> +/*
> + * trace fsync calls
> + * Copyright (C) 2008 Intel Corporation
> + *
> + * Based extensively on trace_sched_switch.c
> + * Copyright (C) 2007 Steven Rostedt <[email protected]>
> + *
> + */
> +#include <linux/module.h>
> +#include <linux/fs.h>
> +#include <linux/debugfs.h>
> +#include <linux/kallsyms.h>
> +#include <linux/uaccess.h>
> +#include <linux/ftrace.h>
> +#include <trace/fs.h>
> +
> +#include "trace.h"
> +
> +static struct trace_array *ctx_trace;
> +static int __read_mostly tracer_enabled;
> +static atomic_t fsync_ref;
> +
> +static void
> +probe_do_fsync(struct file *file, int datasync)
> +{
> + char *buffer;
> + char *err;
> +
> + if (!atomic_read(&fsync_ref))
> + return;
> +
> + if (!tracer_enabled)
> + return;
> +
> + buffer = kmalloc(4096, GFP_KERNEL);
> + if (!buffer)
> + return;
> +
> + memset(buffer, 0, 4096);
kzalloc?
> + err = d_path(&file->f_path, buffer, 4096);
> +
> + if (IS_ERR(err))
> + goto out;
> +
> + ftrace_printk("Process %s is calling fsync on %s\n",
> + current->comm, err);
err? not buffer?
> +
> +out:
> + kfree(buffer);
> +}
> +
> (...)
On Wed, 5 Nov 2008 20:43:31 +0100
Marcin Slusarz <[email protected]> wrote:
> On Wed, Nov 05, 2008 at 09:49:02AM -0800, Arjan van de Ven wrote:
> > --- /dev/null
> > +++ b/kernel/trace/trace_fsync.c
> > @@ -0,0 +1,165 @@
> > +/*
> > + * trace fsync calls
> > + * Copyright (C) 2008 Intel Corporation
> > + *
> > + * Based extensively on trace_sched_switch.c
> > + * Copyright (C) 2007 Steven Rostedt <[email protected]>
> > + *
> > + */
> > +#include <linux/module.h>
> > +#include <linux/fs.h>
> > +#include <linux/debugfs.h>
> > +#include <linux/kallsyms.h>
> > +#include <linux/uaccess.h>
> > +#include <linux/ftrace.h>
> > +#include <trace/fs.h>
> > +
> > +#include "trace.h"
> > +
> > +static struct trace_array *ctx_trace;
> > +static int __read_mostly tracer_enabled;
> > +static atomic_t fsync_ref;
> > +
> > +static void
> > +probe_do_fsync(struct file *file, int datasync)
> > +{
> > + char *buffer;
> > + char *err;
> > +
> > + if (!atomic_read(&fsync_ref))
> > + return;
> > +
> > + if (!tracer_enabled)
> > + return;
> > +
> > + buffer = kmalloc(4096, GFP_KERNEL);
> > + if (!buffer)
> > + return;
> > +
> > + memset(buffer, 0, 4096);
>
> kzalloc?
could do I suppose
>
> > + err = d_path(&file->f_path, buffer, 4096);
> > +
> > + if (IS_ERR(err))
> > + goto out;
> > +
> > + ftrace_printk("Process %s is calling fsync on %s\n",
> > + current->comm, err);
>
> err? not buffer?
correct, not buffer
it won't work if you use buffer.
--
Arjan van de Ven Intel Open Source Technology Centre
For development, discussion and tips for power savings,
visit http://www.lesswatts.org
* Arjan van de Ven <[email protected]> wrote:
> > > + buffer = kmalloc(4096, GFP_KERNEL);
> > > + err = d_path(&file->f_path, buffer, 4096);
hm, magic constants.
> > > + if (IS_ERR(err))
> > > + goto out;
> > > +
> > > + ftrace_printk("Process %s is calling fsync on %s\n",
> > > + current->comm, err);
> >
> > err? not buffer?
>
> correct, not buffer
>
> it won't work if you use buffer.
please use some other name than 'err' - since "error" is just a
property of the path string pointer you get back from do_path().
Ingo
On Wed, 2008-11-05 at 09:49 -0800, Arjan van de Ven wrote:
> From 63c1b869d94eb31a98015af09fb24e22151f2f00 Mon Sep 17 00:00:00 2001
> From: Arjan van de Ven <[email protected]>
> Date: Tue, 4 Nov 2008 21:08:11 -0800
> Subject: [PATCH] ftrace: add an fsync tracer
>
> fsync() (and its cousin, fdatasync()) are important chokepoints in the
> kernel as they imply very expensive operations, both in terms of filesystem
> operations (ext3 writes back its entire journal) as well as the block layer
> (fsync() implies sending a cache flushing barrier to the SATA/SCSI disk).
>
> This tracer makes a log of which application calls fsync() on which file,
> so that developers and others interested in finding these choke points
> can locate them and fix them in the apps that call this function.
Sorry, but I have to object to such single purpose tracers..
If we go this way we'll end up with a gazillion little tracers, non of
which are really useful.
Please work on getting something like a syscall tracer, or lttng like
event tracer.
Both of those should be able to find such badness, but are also able to
diagnose many more issues.
Also, sure fsync() is expensive, but you make it sound like its a bad
thing. Lets not teach people to ignore data integrity just because ext3
is such a massive piece of shit.
2008/11/6 Peter Zijlstra <[email protected]>:
> Please work on getting something like a syscall tracer, or lttng like
> event tracer.
>
> Both of those should be able to find such badness, but are also able to
> diagnose many more issues.
BTW. Why not adding a kind of tracer_ctrl callback on the
struct_tracer? This way we could add some custom
options on the iter_ctrl file that could be transmitted to the current_tracer.
For example considering a syscall tracer.
By default if we don't write anything on iter_ctrl, it traces all
syscalls. But if we do:
echo fsync > iter_ctrl
Only the fsync call will be traced (unused tracepoint would be disabled).
A tracer just have to implement this new callback and transmit the
options it support.
On Thu, 06 Nov 2008 13:55:38 +0100
Peter Zijlstra <[email protected]> wrote:
> On Wed, 2008-11-05 at 09:49 -0800, Arjan van de Ven wrote:
> > From 63c1b869d94eb31a98015af09fb24e22151f2f00 Mon Sep 17 00:00:00
> > 2001 From: Arjan van de Ven <[email protected]>
> > Date: Tue, 4 Nov 2008 21:08:11 -0800
> > Subject: [PATCH] ftrace: add an fsync tracer
> >
> > fsync() (and its cousin, fdatasync()) are important chokepoints in
> > the kernel as they imply very expensive operations, both in terms
> > of filesystem operations (ext3 writes back its entire journal) as
> > well as the block layer (fsync() implies sending a cache flushing
> > barrier to the SATA/SCSI disk).
> >
> > This tracer makes a log of which application calls fsync() on which
> > file, so that developers and others interested in finding these
> > choke points can locate them and fix them in the apps that call
> > this function.
>
> Sorry, but I have to object to such single purpose tracers..
>
> If we go this way we'll end up with a gazillion little tracers, non of
> which are really useful.
If we go this way we'll end up with a bunch of little tracers, all of
which will be useful in their area, and people can also make "super
tracers" out of the useful trace points.
>
> Please work on getting something like a syscall tracer,
a syscall tracer will exactly not tell you which file(name) was being
fsync()'d which was the whole point.
LatencyTOP already KNOWS that fsync is the problem. What it doesn't
know is which file is being fsync()d.
fsync is a problem when used incorrectly, not just for ext3 but also
due to barriers. That's why it's important to be able to find who calls
it when it impacts interactive performance.
--
Arjan van de Ven Intel Open Source Technology Centre
For development, discussion and tips for power savings,
visit http://www.lesswatts.org
On Thu, 06 Nov 2008 13:55:38 +0100
Peter Zijlstra <[email protected]> wrote:
> On Wed, 2008-11-05 at 09:49 -0800, Arjan van de Ven wrote:
> > From 63c1b869d94eb31a98015af09fb24e22151f2f00 Mon Sep 17 00:00:00
> > 2001 From: Arjan van de Ven <[email protected]>
> > Date: Tue, 4 Nov 2008 21:08:11 -0800
> > Subject: [PATCH] ftrace: add an fsync tracer
> >
> > fsync() (and its cousin, fdatasync()) are important chokepoints in
> > the kernel as they imply very expensive operations, both in terms
> > of filesystem operations (ext3 writes back its entire journal) as
> > well as the block layer (fsync() implies sending a cache flushing
> > barrier to the SATA/SCSI disk).
> >
> > This tracer makes a log of which application calls fsync() on which
> > file, so that developers and others interested in finding these
> > choke points can locate them and fix them in the apps that call
> > this function.
>
> Sorry, but I have to object to such single purpose tracers..
>
> If we go this way we'll end up with a gazillion little tracers, non of
> which are really useful.
>
> Please work on getting something like a syscall tracer, or lttng like
> event tracer.
>
btw a syscall tracer is not long term right, just like system call
level auditing was the wrong thing: you don't have the real information
of what's being worked on. having the trace points on the do_FOO()
level is the right thing, and that's exactly what my patch does.
On Thu, 2008-11-06 at 06:06 -0800, Arjan van de Ven wrote:
> On Thu, 06 Nov 2008 13:55:38 +0100
> Peter Zijlstra <[email protected]> wrote:
>
> > On Wed, 2008-11-05 at 09:49 -0800, Arjan van de Ven wrote:
> > > From 63c1b869d94eb31a98015af09fb24e22151f2f00 Mon Sep 17 00:00:00
> > > 2001 From: Arjan van de Ven <[email protected]>
> > > Date: Tue, 4 Nov 2008 21:08:11 -0800
> > > Subject: [PATCH] ftrace: add an fsync tracer
> > >
> > > fsync() (and its cousin, fdatasync()) are important chokepoints in
> > > the kernel as they imply very expensive operations, both in terms
> > > of filesystem operations (ext3 writes back its entire journal) as
> > > well as the block layer (fsync() implies sending a cache flushing
> > > barrier to the SATA/SCSI disk).
> > >
> > > This tracer makes a log of which application calls fsync() on which
> > > file, so that developers and others interested in finding these
> > > choke points can locate them and fix them in the apps that call
> > > this function.
> >
> > Sorry, but I have to object to such single purpose tracers..
> >
> > If we go this way we'll end up with a gazillion little tracers, non of
> > which are really useful.
>
> If we go this way we'll end up with a bunch of little tracers, all of
> which will be useful in their area, and people can also make "super
> tracers" out of the useful trace points.
I don't think:
# cat available_tracers | wc -l
500
will do much good for people.
Also, I don't think do_fsync() is the right place to catch what you're
trying to catch.
> >
> > Please work on getting something like a syscall tracer,
>
> a syscall tracer will exactly not tell you which file(name) was being
> fsync()'d which was the whole point.
It will tell you the process and the fd, and when you have those two its
a simple step to find the actual file.
> LatencyTOP already KNOWS that fsync is the problem. What it doesn't
> know is which file is being fsync()d.
>
> fsync is a problem when used incorrectly, not just for ext3 but also
> due to barriers. That's why it's important to be able to find who calls
> it when it impacts interactive performance.
Which suggests you want a tracer that gives more information about who
generates barriers, not specifically fsync().
On Thu, 06 Nov 2008 15:19:01 +0100
Peter Zijlstra <[email protected]> wrote:
> > a syscall tracer will exactly not tell you which file(name) was
> > being fsync()'d which was the whole point.
>
> It will tell you the process and the fd, and when you have those two
> its a simple step to find the actual file.
actually process+fd is absolutely useless; the typical useage is
fd = open(file)
write(fd, <> )
fsync(fd);
close(fd);
by the time userland gets the data the fd is closed. And heck, even the
program may have exited.
Really, the fd number is only useful for the program itself, not for
any outside part, and especially, later in time.
>
> > LatencyTOP already KNOWS that fsync is the problem. What it doesn't
> > know is which file is being fsync()d.
> >
> > fsync is a problem when used incorrectly, not just for ext3 but also
> > due to barriers. That's why it's important to be able to find who
> > calls it when it impacts interactive performance.
>
> Which suggests you want a tracer that gives more information about who
> generates barriers, not specifically fsync().
that would be a fine second tracer. because the filesystem part of it
is also expensive, and you can diss ext3 all you want, it is reality
for 99% of the people...
(and I suspect that at the barrier level it'll be really hard to get to
a filename)
--
Arjan van de Ven Intel Open Source Technology Centre
For development, discussion and tips for power savings,
visit http://www.lesswatts.org
On Thu, 2008-11-06 at 06:31 -0800, Arjan van de Ven wrote:
> On Thu, 06 Nov 2008 15:19:01 +0100
> Peter Zijlstra <[email protected]> wrote:
>
> > > a syscall tracer will exactly not tell you which file(name) was
> > > being fsync()'d which was the whole point.
> >
> > It will tell you the process and the fd, and when you have those two
> > its a simple step to find the actual file.
>
> actually process+fd is absolutely useless; the typical useage is
>
> fd = open(file)
> write(fd, <> )
> fsync(fd);
> close(fd);
>
> by the time userland gets the data the fd is closed. And heck, even the
> program may have exited.
> Really, the fd number is only useful for the program itself, not for
> any outside part, and especially, later in time.
The syscall tracer will also have told you about that open.
Anyway, do_fsync() doesn't catch all sync actions (although I suspect it
catches most). We still have the mythical sync_file_range() that Andrew
still wants a real program to use.
And then there are things like sync and umount that do syncs too. But I
suspect you might not be interested in those.
> >
> > > LatencyTOP already KNOWS that fsync is the problem. What it doesn't
> > > know is which file is being fsync()d.
> > >
> > > fsync is a problem when used incorrectly, not just for ext3 but also
> > > due to barriers. That's why it's important to be able to find who
> > > calls it when it impacts interactive performance.
> >
> > Which suggests you want a tracer that gives more information about who
> > generates barriers, not specifically fsync().
>
> that would be a fine second tracer. because the filesystem part of it
> is also expensive, and you can diss ext3 all you want, it is reality
> for 99% of the people...
Lets hope btrfs will fix that quickly. fsync() causing latencies for
anyone else besides tasks interested in that file is utterly
unacceptable.
> (and I suspect that at the barrier level it'll be really hard to get to
> a filename)
I suspect you might be right, but that's not a reason not to try ;-)
On Thu, 06 Nov 2008 15:50:52 +0100
Peter Zijlstra <[email protected]> wrote:
> On Thu, 2008-11-06 at 06:31 -0800, Arjan van de Ven wrote:
> > On Thu, 06 Nov 2008 15:19:01 +0100
> > Peter Zijlstra <[email protected]> wrote:
> >
> > > > a syscall tracer will exactly not tell you which file(name) was
> > > > being fsync()'d which was the whole point.
> > >
> > > It will tell you the process and the fd, and when you have those
> > > two its a simple step to find the actual file.
> >
> > actually process+fd is absolutely useless; the typical useage is
> >
> > fd = open(file)
> > write(fd, <> )
> > fsync(fd);
> > close(fd);
> >
> > by the time userland gets the data the fd is closed. And heck, even
> > the program may have exited.
> > Really, the fd number is only useful for the program itself, not for
> > any outside part, and especially, later in time.
>
> The syscall tracer will also have told you about that open.
ok so now you're turning a simple problem into "also track all open,
openat, dup, dup2, close, unix domain fs passing etc". That doesn't
sound like an improvement to me.
And even the "open/fd" family isn't enough, because the open will be
relative pathnames, so I now also need to second guess the PWD, and
then follow a chain of "chdir" calls as well and then resolve the
".."'s in the path. And follow symlinks that may no longer be the same
symlink it used to be. Etc. Etc.
No sorry, this really is not a viable approach.
And that goes beyond the fsync tracer. Anybody who thinks that syscall
tracing is the right approach needs to seriously think about it; it
really looks like the same problem as with audit... it started out with
a bad hack that did it at the syscall level but it was likewise shown
to just not be the right level. I am rather certain that the same will
be shown for tracing.
>
> Anyway, do_fsync() doesn't catch all sync actions (although I suspect
> it catches most). We still have the mythical sync_file_range() that
> Andrew still wants a real program to use.
a normal sync() I don't need any help for.. it has no filename and I
already know who's calling it with what latency.
>
> And then there are things like sync and umount that do syncs too. But
> I suspect you might not be interested in those.
I already know all I need about those.... again it's the fsync() that
is specific, and I need to know the specifics to help the user figure
out what is going on.
(and in case you worry that there's not going to be a user for this
tracer, I already wrote the latencytop side of the code for this one,
so I know I can use the current format)
--
Arjan van de Ven Intel Open Source Technology Centre
For development, discussion and tips for power savings,
visit http://www.lesswatts.org
On Thu, 6 Nov 2008, Arjan van de Ven wrote:
> >
> > The syscall tracer will also have told you about that open.
>
> ok so now you're turning a simple problem into "also track all open,
> openat, dup, dup2, close, unix domain fs passing etc". That doesn't
> sound like an improvement to me.
> And even the "open/fd" family isn't enough, because the open will be
> relative pathnames, so I now also need to second guess the PWD, and
> then follow a chain of "chdir" calls as well and then resolve the
> ".."'s in the path. And follow symlinks that may no longer be the same
> symlink it used to be. Etc. Etc.
>
> No sorry, this really is not a viable approach.
>
> And that goes beyond the fsync tracer. Anybody who thinks that syscall
> tracing is the right approach needs to seriously think about it; it
> really looks like the same problem as with audit... it started out with
> a bad hack that did it at the syscall level but it was likewise shown
> to just not be the right level. I am rather certain that the same will
> be shown for tracing.
What I would like is a single "event tracer" that does all of this.
But add the ability to start and stop different events. We could start
with this tracer, and then add more events to this tracer. Have a
separate file to show which events are available.
This will keep the 'available_tracers' file small, but it would be fine
if the 'events' file grew large.
-- Steve
On Thu, 6 Nov 2008 10:34:50 -0500 (EST)
Steven Rostedt <[email protected]> wrote:
>
> What I would like is a single "event tracer" that does all of this.
> But add the ability to start and stop different events. We could start
> with this tracer, and then add more events to this tracer. Have a
> separate file to show which events are available.
>
> This will keep the 'available_tracers' file small, but it would be
> fine if the 'events' file grew large.
well 2 ounces versus one liter ;)
what is the real need is
1) Have a trace point in the source
2) Associate a "formatting function" with that point
(which basically transforms the trace parameters to, say, a string)
3) A way to turn the trace point on/off.
right now this is what the fsync tracer does, because it's the only way
to do such a thing.
I don't care how to otherwise do it ....
--
Arjan van de Ven Intel Open Source Technology Centre
For development, discussion and tips for power savings,
visit http://www.lesswatts.org
Arjan van de Ven <[email protected]> writes:
> [...]
> what is the real need is
> 1) Have a trace point in the source
> 2) Associate a "formatting function" with that point
> (which basically transforms the trace parameters to, say, a string)
> 3) A way to turn the trace point on/off.
For 1 and 2, it may be worth considering a plain trace_mark() in
do_sync(). The complication that makes this uglier than a one-liner
is d_path()'s buffer and error handling.
{
char *buffer = kzalloc (4096, GFP_KERNEL);
trace_mark(fsync, "Process %s is calling fsync on %s\n",
current->comm,
({char *err = d_path (...);
IS_ERR(err) ? "?" : err;}));
kfree (buffer);
}
With a bit of extension on the marker front, the allocation could be
made conditional on the marker being enabled.
For 3, the kernel could merge a backend that connects arbitrary
markers to an ftrace (or whatever) buffer. Several compact prototypes
for the latter exist.
- FChE
On Thu, 2008-11-06 at 15:19 -0500, Frank Ch. Eigler wrote:
> Arjan van de Ven <[email protected]> writes:
>
> > [...]
> > what is the real need is
> > 1) Have a trace point in the source
> > 2) Associate a "formatting function" with that point
> > (which basically transforms the trace parameters to, say, a string)
> > 3) A way to turn the trace point on/off.
>
> For 1 and 2, it may be worth considering a plain trace_mark() in
> do_sync(). The complication that makes this uglier than a one-liner
> is d_path()'s buffer and error handling.
>
> {
> char *buffer = kzalloc (4096, GFP_KERNEL);
> trace_mark(fsync, "Process %s is calling fsync on %s\n",
> current->comm,
> ({char *err = d_path (...);
> IS_ERR(err) ? "?" : err;}));
> kfree (buffer);
> }
>
> With a bit of extension on the marker front, the allocation could be
> made conditional on the marker being enabled.
>
>
> For 3, the kernel could merge a backend that connects arbitrary
> markers to an ftrace (or whatever) buffer. Several compact prototypes
> for the latter exist.
I prefer we keep using trace points but do what jason has been proposing
for a while, which is add a format and arg list to the trace point
definition.
Something like
DEFINE_TRACE_FMT(sched_switch,
TPPROTO(struct rq *rq, struct task_struct *prev,
struct task_struct *next),
TPARGS(rq, prev, next),
TPFMT("%d to %d\n", prev->pid, next->pid));
Which would be similar to attaching a trace_mark() to the trace point
and can in these cases save a lot of lines of code.
Both lttng and the ftrace event tracer can use these default text
strings.
Hi -
On Thu, Nov 06, 2008 at 09:29:03PM +0100, Peter Zijlstra wrote:
> [...]
> I prefer we keep using trace points but do what jason has been proposing
> for a while, which is add a format and arg list to the trace point
> definition.
>
> Something like
>
> DEFINE_TRACE_FMT(sched_switch,
> TPPROTO(struct rq *rq, struct task_struct *prev,
> struct task_struct *next),
> TPARGS(rq, prev, next),
> TPFMT("%d to %d\n", prev->pid, next->pid));
>
> Which would be similar to attaching a trace_mark() to the trace point
> and can in these cases save a lot of lines of code.
Can you explain how this would save any lines of code at all compared
to the trace_mark() example? Both cases still need a bit of
~identical additional code to couple the markers (specified whichever
way) to a trace buffer. Your version has the tracepoint machinery
too, which is strictly additional. Where's the savings?
- FChE
On Thu, 06 Nov 2008 15:19:48 -0500
[email protected] (Frank Ch. Eigler) wrote:
> Arjan van de Ven <[email protected]> writes:
>
> > [...]
> > what is the real need is
> > 1) Have a trace point in the source
> > 2) Associate a "formatting function" with that point
> > (which basically transforms the trace parameters to, say, a
> > string) 3) A way to turn the trace point on/off.
>
> For 1 and 2, it may be worth considering a plain trace_mark() in
> do_sync(). The complication that makes this uglier than a one-liner
no why is that?
what you really need is to be able to provide a callback function
pointer that will do the formatting,
or as Peter wants it, a format string.
(and we can easily make a format string that knows how to print a
struct file, no big deal, I suspect that is a common thing actually)
Doing this like you propose is just too complex and too specialistic;
the reality is that merely formatting the arguments of a trace point is
the common case, and I suspect for 99.9% of the cases we can get away
with a standard default formatting.
We should make THAT easy. Not complex or ugly. But easy.
And then if I or some tool wants to see a tracepoint, we have some
standard way to enumerate them and turn individual ones on with their
standard formatting ... and that's it.
no iffs or buts
--
Arjan van de Ven Intel Open Source Technology Centre
For development, discussion and tips for power savings,
visit http://www.lesswatts.org
On Thu, Nov 06, 2008 at 09:29:03PM +0100, Peter Zijlstra wrote:
> On Thu, 2008-11-06 at 15:19 -0500, Frank Ch. Eigler wrote:
> > Arjan van de Ven <[email protected]> writes:
> >
> > > [...]
> > > what is the real need is
> > > 1) Have a trace point in the source
> > > 2) Associate a "formatting function" with that point
> > > (which basically transforms the trace parameters to, say, a string)
> > > 3) A way to turn the trace point on/off.
> >
> > For 1 and 2, it may be worth considering a plain trace_mark() in
> > do_sync(). The complication that makes this uglier than a one-liner
> > is d_path()'s buffer and error handling.
> >
> > {
> > char *buffer = kzalloc (4096, GFP_KERNEL);
> > trace_mark(fsync, "Process %s is calling fsync on %s\n",
> > current->comm,
> > ({char *err = d_path (...);
> > IS_ERR(err) ? "?" : err;}));
> > kfree (buffer);
> > }
> >
> > With a bit of extension on the marker front, the allocation could be
> > made conditional on the marker being enabled.
> >
> >
> > For 3, the kernel could merge a backend that connects arbitrary
> > markers to an ftrace (or whatever) buffer. Several compact prototypes
> > for the latter exist.
>
>
> I prefer we keep using trace points but do what jason has been proposing
> for a while, which is add a format and arg list to the trace point
> definition.
>
> Something like
>
> DEFINE_TRACE_FMT(sched_switch,
> TPPROTO(struct rq *rq, struct task_struct *prev,
> struct task_struct *next),
> TPARGS(rq, prev, next),
> TPFMT("%d to %d\n", prev->pid, next->pid));
>
> Which would be similar to attaching a trace_mark() to the trace point
> and can in these cases save a lot of lines of code.
>
> Both lttng and the ftrace event tracer can use these default text
> strings.
>
indeed...done this way I believe marker registration could then be
done directly with the tracepoint itself. That is, callers that
want the tracepoint interface register directly with the tracepoint and get
called as before. However, callers that want the marker interface register
directly with the tracepoint and get passed the associated marker string and
arguments. Then, we could consolidate kernel/marker.c into kernel/tracepoint.c,
which would simlify things, and reduce code duplication.
thanks,
-Jason
Hi -
On Thu, Nov 06, 2008 at 01:13:48PM -0800, Arjan van de Ven wrote:
> [...]
> [email protected] (Frank Ch. Eigler) wrote:
>
> > Arjan van de Ven <[email protected]> writes:
> >
> > > [...]
> > > what is the real need is
> > > 1) Have a trace point in the source
> > > 2) Associate a "formatting function" with that point
> > > (which basically transforms the trace parameters to, say, a
> > > string) 3) A way to turn the trace point on/off.
> >
> > For 1 and 2, it may be worth considering a plain trace_mark() in
> > do_sync(). The complication that makes this uglier than a one-liner
>
> no why is that?
>
> what you really need is to be able to provide a callback function
> pointer that will do the formatting, or as Peter wants it, a format string.
> [...]
> Doing this like you propose is just too complex and too specialistic;
> the reality is that merely formatting the arguments of a trace point is
> the common case, and I suspect for 99.9% of the cases we can get away
> with a standard default formatting.
I don't understand what you're arguing against. If formatting strings
learn to deal with struct files, then the marker approach would be
even simpler, and the fsync "tracer" would consist of this single line:
trace_mark (fsync, "process %s fsyncd file %pF\n", comm->execname, file);
Via some simple additional generic code (the generic marker->ftrace
backend), that would turn into exactly the "merely formatting the
arguments ... 99.9% of the cases" you're talking about.
- FChE
* Peter Zijlstra ([email protected]) wrote:
> On Thu, 2008-11-06 at 15:19 -0500, Frank Ch. Eigler wrote:
> > Arjan van de Ven <[email protected]> writes:
> >
> > > [...]
> > > what is the real need is
> > > 1) Have a trace point in the source
> > > 2) Associate a "formatting function" with that point
> > > (which basically transforms the trace parameters to, say, a string)
> > > 3) A way to turn the trace point on/off.
> >
> > For 1 and 2, it may be worth considering a plain trace_mark() in
> > do_sync(). The complication that makes this uglier than a one-liner
> > is d_path()'s buffer and error handling.
> >
> > {
> > char *buffer = kzalloc (4096, GFP_KERNEL);
> > trace_mark(fsync, "Process %s is calling fsync on %s\n",
> > current->comm,
> > ({char *err = d_path (...);
> > IS_ERR(err) ? "?" : err;}));
> > kfree (buffer);
> > }
> >
> > With a bit of extension on the marker front, the allocation could be
> > made conditional on the marker being enabled.
> >
> >
> > For 3, the kernel could merge a backend that connects arbitrary
> > markers to an ftrace (or whatever) buffer. Several compact prototypes
> > for the latter exist.
>
>
> I prefer we keep using trace points but do what jason has been proposing
> for a while, which is add a format and arg list to the trace point
> definition.
>
> Something like
>
> DEFINE_TRACE_FMT(sched_switch,
> TPPROTO(struct rq *rq, struct task_struct *prev,
> struct task_struct *next),
> TPARGS(rq, prev, next),
> TPFMT("%d to %d\n", prev->pid, next->pid));
>
> Which would be similar to attaching a trace_mark() to the trace point
> and can in these cases save a lot of lines of code.
>
> Both lttng and the ftrace event tracer can use these default text
> strings.
>
>
Argh. No, please. Doing this would end up exposing the inner kernel API
(the tracepoints) directly to userspace.
I've done an addition to the markers which does approximately the same.
It's in the -lttng tree now, I should post it soon.
A new marker type, trace_mark_tp() also takes a tracepoint name as
parameter. When the tracepoint is enabled, it also enables the
associated tracepoint. And it makes sure tracepoints are not exposed to
userspace.
Mathieu
--
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68
Hi -
On Thu, Nov 06, 2008 at 04:53:11PM -0500, Mathieu Desnoyers wrote:
> [...]
> > Something like
> >
> > DEFINE_TRACE_FMT(sched_switch,
> > TPPROTO(struct rq *rq, struct task_struct *prev,
> > struct task_struct *next),
> > TPARGS(rq, prev, next),
> > TPFMT("%d to %d\n", prev->pid, next->pid));
> >
> > Which would be similar to attaching a trace_mark() to the trace point
> > and can in these cases save a lot of lines of code.
> >
> > Both lttng and the ftrace event tracer can use these default text
> > strings.
>
> Argh. No, please. Doing this would end up exposing the inner kernel API
> (the tracepoints) directly to userspace. [...]
Arjan asked for something to send formatted strings to tracing buffers
that are consumed by user space. Whether internally that is done by
markers, or by tracepoints converted to markers, or by tracepoints
with custom ftrace_printf-y code, is indistinguishable to the user.
Can you be specific in what way any of that is exposing an "API
directly to userspace"?
- FChE
* Frank Ch. Eigler ([email protected]) wrote:
> Hi -
>
> On Thu, Nov 06, 2008 at 04:53:11PM -0500, Mathieu Desnoyers wrote:
> > [...]
> > > Something like
> > >
> > > DEFINE_TRACE_FMT(sched_switch,
> > > TPPROTO(struct rq *rq, struct task_struct *prev,
> > > struct task_struct *next),
> > > TPARGS(rq, prev, next),
> > > TPFMT("%d to %d\n", prev->pid, next->pid));
> > >
> > > Which would be similar to attaching a trace_mark() to the trace point
> > > and can in these cases save a lot of lines of code.
> > >
> > > Both lttng and the ftrace event tracer can use these default text
> > > strings.
> >
> > Argh. No, please. Doing this would end up exposing the inner kernel API
> > (the tracepoints) directly to userspace. [...]
>
>
> Arjan asked for something to send formatted strings to tracing buffers
> that are consumed by user space. Whether internally that is done by
> markers, or by tracepoints converted to markers, or by tracepoints
> with custom ftrace_printf-y code, is indistinguishable to the user.
>
> Can you be specific in what way any of that is exposing an "API
> directly to userspace"?
>
> - FChE
The tracepoint declaration is linked to the kernel code that is meant to
be traced. Given this code will change over time, it will be more
difficult to perform those changes if it is in any way coupled with
format strings exported to userspace via traced.
This is where using the markers as an indirection layer plays its role.
I also have a patch with "redux" markers, where I separate the marker
"declaration" from the marker "call". By doing this, I remove the need
for cascading function calls, which is more efficient.
Mathieu
--
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68
Hi -
On Thu, Nov 06, 2008 at 05:25:29PM -0500, Mathieu Desnoyers wrote:
> [...]
> > Arjan asked for something to send formatted strings to tracing buffers
> > that are consumed by user space. Whether internally that is done by
> > markers, or by tracepoints converted to markers, or by tracepoints
> > with custom ftrace_printf-y code, is indistinguishable to the user.
> >
> > Can you be specific in what way any of that is exposing an "API
> > directly to userspace"?
>
> The tracepoint declaration is linked to the kernel code that is meant to
> be traced. Given this code will change over time, it will be more
> difficult to perform those changes if it is in any way coupled with
> format strings exported to userspace via traced. [...]
The userspace interface to all the various tracing widgets consists of
the textual formatted trace data stream. ** IF ** these streams are
to represent a long-term interface, can you elaborate why you believe
it would be harder to generate identical text in the future with
markers rather than another technique with more internal layers? Can
you work out an example?
(BTW, is "traced" a typo?)
And as to that ** IF **: is there actually consensus that the format
of tracing data generated by e.g. ftrace engines are supposed to be
preserved into the future versions, just as if they were a user-space
interface like /proc files? (That's certainly not my impression.)
- FChE
On Thu, 6 Nov 2008 18:25:06 -0500
"Frank Ch. Eigler" <[email protected]> wrote:
> Hi -
>
> On Thu, Nov 06, 2008 at 05:25:29PM -0500, Mathieu Desnoyers wrote:
> > [...]
> > > Arjan asked for something to send formatted strings to tracing
> > > buffers that are consumed by user space. Whether internally that
> > > is done by markers, or by tracepoints converted to markers, or by
> > > tracepoints with custom ftrace_printf-y code, is
> > > indistinguishable to the user.
> > >
> > > Can you be specific in what way any of that is exposing an "API
> > > directly to userspace"?
> >
> > The tracepoint declaration is linked to the kernel code that is
> > meant to be traced. Given this code will change over time, it will
> > be more difficult to perform those changes if it is in any way
> > coupled with format strings exported to userspace via traced. [...]
>
> The userspace interface to all the various tracing widgets consists of
> the textual formatted trace data stream. ** IF ** these streams are
> to represent a long-term interface, can you elaborate why you believe
tracepoints are not and cannot be a stable interface, and users of
these points, preferably scripts that are part of the kernel source,
need to learn to adapt to a changing environment.
At least if we make the formatting function a *function*, we can even do
very minor things to deal with some changes, but even then.
And this is ok. You're talking about deep internals, and for
tracepoints to be useful they HAVE to be about these internals.
--
Arjan van de Ven Intel Open Source Technology Centre
For development, discussion and tips for power savings,
visit http://www.lesswatts.org
Hi Frank,
* Frank Ch. Eigler ([email protected]) wrote:
> Hi -
>
> On Thu, Nov 06, 2008 at 05:25:29PM -0500, Mathieu Desnoyers wrote:
> > [...]
> > > Arjan asked for something to send formatted strings to tracing buffers
> > > that are consumed by user space. Whether internally that is done by
> > > markers, or by tracepoints converted to markers, or by tracepoints
> > > with custom ftrace_printf-y code, is indistinguishable to the user.
> > >
> > > Can you be specific in what way any of that is exposing an "API
> > > directly to userspace"?
> >
> > The tracepoint declaration is linked to the kernel code that is meant to
> > be traced. Given this code will change over time, it will be more
> > difficult to perform those changes if it is in any way coupled with
> > format strings exported to userspace via traced. [...]
>
> The userspace interface to all the various tracing widgets consists of
> the textual formatted trace data stream.
Oh ? Really ? I thought a binary data stream wasn't out of the question ?
Actually, having both ascii and binary output seems like a good way to
do it.
> ** IF ** these streams are
> to represent a long-term interface, can you elaborate why you believe
> it would be harder to generate identical text in the future with
> markers rather than another technique with more internal layers? Can
> you work out an example?
>
Hum.. I never said it would be harder to generate the trace data. I said
it would be harder for kernel developers to change kernel code because
they would have to change (and understand the usefulness down to the
analysis tools) all the subtile tracepoint fields exported to userspace
tools. I am not willing to push tracepoints in the kernel as a
supplementary maintainance burden for kernel developers. With the format
string identifying subfield, this burden will fall on the kernel
developers. If we put the field selection in a callback sitting in a
different module, well, it won't compile for as long as nobody think
it's important enough to be fixed according to new in-kernel APIs, but
it won't break the standard kernel build, and this is a _must_.
> (BTW, is "traced" a typo?)
>
Yep, I should have written "via a tracer".
> And as to that ** IF **: is there actually consensus that the format
> of tracing data generated by e.g. ftrace engines are supposed to be
> preserved into the future versions, just as if they were a user-space
> interface like /proc files? (That's certainly not my impression.)
>
We aim at having a standardized buffer format at some point, and expect
the consumer tools to be shipped with the kernel tree for most part.
We also plan to put a version number on the trace buffer. I am merely
relating the discussions that led to Steven Rostedt unified trace buffer
mechanism. (I do not say it actually does everything that was agreed on,
but we have to start somewhere)
If I can get my head out of the sand and start posting the
implementations I have, we'll have more concrete stuff to discuss about
:) Only two things left on my 30-ish things long todo list.. almost
there ;)
Mathieu
--
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68