Module Name: src
Committed By: manu
Date: Wed Dec 28 17:33:53 UTC 2011
Modified Files:
src/lib/libperfuse: debug.c fuse.h ops.c perfuse.c perfuse_if.h
perfuse_priv.h
src/usr.sbin/perfused: perfused.8 perfused.c perfused.h
Log Message:
Add a FUSE trace facility, with statistics collection. This should help
tracking bugs and performance issues
To generate a diff of this commit:
cvs rdiff -u -r1.5 -r1.6 src/lib/libperfuse/debug.c
cvs rdiff -u -r1.4 -r1.5 src/lib/libperfuse/fuse.h
cvs rdiff -u -r1.48 -r1.49 src/lib/libperfuse/ops.c
cvs rdiff -u -r1.23 -r1.24 src/lib/libperfuse/perfuse.c \
src/lib/libperfuse/perfuse_priv.h
cvs rdiff -u -r1.17 -r1.18 src/lib/libperfuse/perfuse_if.h
cvs rdiff -u -r1.7 -r1.8 src/usr.sbin/perfused/perfused.8
cvs rdiff -u -r1.16 -r1.17 src/usr.sbin/perfused/perfused.c
cvs rdiff -u -r1.5 -r1.6 src/usr.sbin/perfused/perfused.h
Please note that diffs are not public domain; they are subject to the
copyright notices on the relevant files.
Modified files:
Index: src/lib/libperfuse/debug.c
diff -u src/lib/libperfuse/debug.c:1.5 src/lib/libperfuse/debug.c:1.6
--- src/lib/libperfuse/debug.c:1.5 Sun Oct 3 05:46:47 2010
+++ src/lib/libperfuse/debug.c Wed Dec 28 17:33:52 2011
@@ -1,4 +1,4 @@
-/* $NetBSD: debug.c,v 1.5 2010/10/03 05:46:47 manu Exp $ */
+/* $NetBSD: debug.c,v 1.6 2011/12/28 17:33:52 manu Exp $ */
/*-
* Copyright (c) 2010 Emmanuel Dreyfus. All rights reserved.
@@ -26,9 +26,11 @@
*/
#include <puffs.h>
+#include <stdio.h>
#include <sys/types.h>
#include "perfuse_if.h"
+#include "perfuse_priv.h"
#include "fuse.h"
struct perfuse_opcode {
@@ -101,3 +103,116 @@ perfuse_opname(opcode)
return po->opname; /* "UNKNOWN" */
}
+
+char *
+perfuse_opdump_in(ps, pm)
+ struct perfuse_state *ps;
+ perfuse_msg_t *pm;
+{
+ struct fuse_in_header *fih;
+ static char buf[BUFSIZ] = "";
+
+ fih = GET_INHDR(ps, pm);
+
+ switch(fih->opcode) {
+ case FUSE_LOOKUP:
+ (void)snprintf(buf, sizeof(buf), "path = \"%s\"",
+ _GET_INPAYLOAD(ps, pm, const char *));
+ break;
+ default:
+ buf[0] = '\0';
+ break;
+ }
+
+ return buf;
+}
+
+void
+perfuse_trace_dump(pu, fp)
+ struct puffs_usermount *pu;
+ FILE *fp;
+{
+ struct perfuse_state *ps;
+ struct perfuse_trace *pt;
+ struct timespec ts_min[FUSE_OPCODE_MAX];
+ struct timespec ts_max[FUSE_OPCODE_MAX];
+ struct timespec ts_total[FUSE_OPCODE_MAX];
+ int count[FUSE_OPCODE_MAX];
+ uint64_t avg;
+ int i;
+
+ if (!(perfuse_diagflags & PDF_TRACE))
+ return;
+
+ ps = puffs_getspecific(pu);
+
+ (void)ftruncate(fileno(fp), 0);
+ (void)fseek(fp, 0, SEEK_SET);
+
+ (void)memset(&ts_min, 0, sizeof(ts_min));
+ (void)memset(&ts_max, 0, sizeof(ts_max));
+ (void)memset(&ts_total, 0, sizeof(ts_total));
+ (void)memset(&count, 0, sizeof(count));
+
+ fprintf(fp, "Last %"PRId64" operations\n", ps->ps_tracecount);
+
+ TAILQ_FOREACH(pt, &ps->ps_trace, pt_list) {
+ const char *quote = pt->pt_path[0] != '\0' ? "\"" : "";
+
+ fprintf(fp, "%lu.%09ld %s %s%s%s %s ",
+ pt->pt_start.tv_sec, pt->pt_start.tv_nsec,
+ perfuse_opname(pt->pt_opcode),
+ quote, pt->pt_path, quote,
+ pt->pt_extra);
+
+ if (pt->pt_status == done) {
+ struct timespec ts;
+
+ ts.tv_sec = 0; /* delint */
+ ts.tv_nsec = 0; /* delint */
+ timespecsub(&pt->pt_end, &pt->pt_start, &ts);
+
+ fprintf(fp, "error = %d elapsed = %lu.%09lu ",
+ pt->pt_error, ts.tv_sec, ts.tv_nsec);
+
+ count[pt->pt_opcode]++;
+ timespecadd(&ts_total[pt->pt_opcode],
+ &ts,
+ &ts_total[pt->pt_opcode]);
+
+ if (timespeccmp(&ts, &ts_min[pt->pt_opcode], <) ||
+ (count[pt->pt_opcode] == 1))
+ ts_min[pt->pt_opcode] = ts;
+
+ if (timespeccmp(&ts, &ts_max[pt->pt_opcode], >))
+ ts_max[pt->pt_opcode] = ts;
+ } else {
+ fprintf(fp, "ongoing ");
+ }
+
+ fprintf(fp, "\n");
+ }
+
+ fprintf(fp, "\nStatistics by operation\n");
+ fprintf(fp, "operation\tcount\tmin\tavg\tmax\n");
+ for (i = 0; i < FUSE_OPCODE_MAX; i++) {
+ time_t min;
+
+ if (count[i] != 0) {
+ avg = timespec2ns(&ts_total[i]) / count[i];
+ min = ts_min[i].tv_sec;
+ } else {
+ avg = 0;
+ min = 0;
+ }
+
+ fprintf(fp, "%s\t%d\t%ld.%09ld\t%ld.%09ld\t%ld.%09ld\t\n",
+ perfuse_opname(i), count[i],
+ min, ts_min[i].tv_nsec,
+ (time_t)(avg / 1000000000L), (long)(avg % 1000000000L),
+ ts_max[i].tv_sec, ts_max[i].tv_nsec);
+ }
+
+ (void)fflush(fp);
+ return;
+}
Index: src/lib/libperfuse/fuse.h
diff -u src/lib/libperfuse/fuse.h:1.4 src/lib/libperfuse/fuse.h:1.5
--- src/lib/libperfuse/fuse.h:1.4 Tue Jun 28 16:19:16 2011
+++ src/lib/libperfuse/fuse.h Wed Dec 28 17:33:53 2011
@@ -1,4 +1,4 @@
-/* $NetBSD: fuse.h,v 1.4 2011/06/28 16:19:16 manu Exp $ */
+/* $NetBSD: fuse.h,v 1.5 2011/12/28 17:33:53 manu Exp $ */
/*-
* Copyright (c) 2010 Emmanuel Dreyfus. All rights reserved.
@@ -169,6 +169,7 @@ enum fuse_opcode {
FUSE_DESTROY = 38,
FUSE_IOCTL = 39,
FUSE_POLL = 40,
+ FUSE_OPCODE_MAX,
FUSE_CUSE_INIT = 4096
};
Index: src/lib/libperfuse/ops.c
diff -u src/lib/libperfuse/ops.c:1.48 src/lib/libperfuse/ops.c:1.49
--- src/lib/libperfuse/ops.c:1.48 Fri Dec 16 05:34:54 2011
+++ src/lib/libperfuse/ops.c Wed Dec 28 17:33:53 2011
@@ -1,4 +1,4 @@
-/* $NetBSD: ops.c,v 1.48 2011/12/16 05:34:54 manu Exp $ */
+/* $NetBSD: ops.c,v 1.49 2011/12/28 17:33:53 manu Exp $ */
/*-
* Copyright (c) 2010-2011 Emmanuel Dreyfus. All rights reserved.
@@ -37,6 +37,7 @@
#include <sys/socket.h>
#include <sys/socket.h>
#include <sys/extattr.h>
+#include <sys/time.h>
#include <machine/vmparam.h>
#include "perfuse_priv.h"
@@ -205,6 +206,8 @@ xchg_msg(pu, opc, pm, len, wait)
{
struct perfuse_state *ps;
struct perfuse_node_data *pnd;
+ struct perfuse_trace *pt = NULL;
+ int opcode;
int error;
ps = puffs_getspecific(pu);
@@ -222,9 +225,62 @@ xchg_msg(pu, opc, pm, len, wait)
if (pnd)
pnd->pnd_flags |= PND_INXCHG;
+ /*
+ * Record FUSE call start if requested
+ */
+ opcode = ps->ps_get_inhdr(pm)->opcode;
+ if (perfuse_diagflags & PDF_TRACE) {
+ if ((pt = malloc(sizeof(*pt))) == NULL)
+ DERR(EX_OSERR, "malloc failed");
+
+ pt->pt_opcode = opcode;
+ pt->pt_status = inxchg;
+
+ if (opc == 0)
+ (void)strcpy(pt->pt_path, "");
+ else
+ (void)strlcpy(pt->pt_path,
+ perfuse_node_path(opc),
+ sizeof(pt->pt_path));
+
+ (void)strlcpy(pt->pt_extra,
+ perfuse_opdump_in(ps, pm),
+ sizeof(pt->pt_extra));
+
+ if (clock_gettime(CLOCK_REALTIME, &pt->pt_start) != 0)
+ DERR(EX_OSERR, "clock_gettime failed");
+
+ TAILQ_INSERT_TAIL(&ps->ps_trace, pt, pt_list);
+ ps->ps_tracecount++;
+ }
+
+ /*
+ * Do actual FUSE exchange
+ */
if ((error = ps->ps_xchg_msg(pu, pm, len, wait)) != 0)
ps->ps_destroy_msg(pm);
+ /*
+ * Record FUSE call end if requested
+ */
+ if (perfuse_diagflags & PDF_TRACE) {
+ if (clock_gettime(CLOCK_REALTIME, &pt->pt_end) != 0)
+ DERR(EX_OSERR, "clock_gettime failed");
+
+ pt->pt_status = done;
+ pt->pt_error = error;
+ while (ps->ps_tracecount > PERFUSE_TRACECOUNT_MAX) {
+ struct perfuse_trace *fpt = TAILQ_FIRST(&ps->ps_trace);
+
+ if (fpt->pt_status != done)
+ break;
+
+ TAILQ_REMOVE(&ps->ps_trace, fpt, pt_list);
+ ps->ps_tracecount--;
+ free(fpt);
+ }
+ }
+
if (pnd) {
pnd->pnd_flags &= ~PND_INXCHG;
(void)dequeue_requests(ps, opc, PCQ_AFTERXCHG, DEQUEUE_ALL);
Index: src/lib/libperfuse/perfuse.c
diff -u src/lib/libperfuse/perfuse.c:1.23 src/lib/libperfuse/perfuse.c:1.24
--- src/lib/libperfuse/perfuse.c:1.23 Sun Oct 30 05:11:37 2011
+++ src/lib/libperfuse/perfuse.c Wed Dec 28 17:33:53 2011
@@ -1,4 +1,4 @@
-/* $NetBSD: perfuse.c,v 1.23 2011/10/30 05:11:37 manu Exp $ */
+/* $NetBSD: perfuse.c,v 1.24 2011/12/28 17:33:53 manu Exp $ */
/*-
* Copyright (c) 2010-2011 Emmanuel Dreyfus. All rights reserved.
@@ -64,6 +64,7 @@ init_state(void)
(void)memset(ps, 0, sizeof(*ps));
ps->ps_max_write = UINT_MAX;
ps->ps_max_readahead = UINT_MAX;
+ TAILQ_INIT(&ps->ps_trace);
/*
* Most of the time, access() is broken because the filesystem
Index: src/lib/libperfuse/perfuse_priv.h
diff -u src/lib/libperfuse/perfuse_priv.h:1.23 src/lib/libperfuse/perfuse_priv.h:1.24
--- src/lib/libperfuse/perfuse_priv.h:1.23 Sun Oct 30 05:11:37 2011
+++ src/lib/libperfuse/perfuse_priv.h Wed Dec 28 17:33:53 2011
@@ -1,4 +1,4 @@
-/* $NetBSD: perfuse_priv.h,v 1.23 2011/10/30 05:11:37 manu Exp $ */
+/* $NetBSD: perfuse_priv.h,v 1.24 2011/12/28 17:33:53 manu Exp $ */
/*-
* Copyright (c) 2010-2011 Emmanuel Dreyfus. All rights reserved.
@@ -37,6 +37,19 @@
#include "perfuse_if.h"
#include "fuse.h"
+#define PERFUSE_TRACECOUNT_MAX 4096
+#define PERFUSE_TRACEPATH_MAX 256
+struct perfuse_trace {
+ int pt_opcode;
+ char pt_path[PERFUSE_TRACEPATH_MAX];
+ char pt_extra[BUFSIZ];
+ int pt_error;
+ enum { inxchg, done } pt_status;
+ struct timespec pt_start;
+ struct timespec pt_end;
+ TAILQ_ENTRY(perfuse_trace) pt_list;
+};
+
struct perfuse_state {
void *ps_private; /* Private field for libperfuse user */
struct puffs_usermount *ps_pu;
@@ -66,6 +79,8 @@ struct perfuse_state {
perfuse_get_outhdr_fn ps_get_outhdr;
perfuse_get_outpayload_fn ps_get_outpayload;
perfuse_umount_fn ps_umount;
+ TAILQ_HEAD(,perfuse_trace) ps_trace;
+ uint64_t ps_tracecount;
};
@@ -237,6 +252,8 @@ int perfuse_node_listextattr(struct puff
int perfuse_node_deleteextattr(struct puffs_usermount *, puffs_cookie_t,
int, const char *, const struct puffs_cred *);
+char *perfuse_opdump_in(struct perfuse_state *, perfuse_msg_t *);
+
__END_DECLS
#endif /* _PERFUSE_PRIV_H_ */
Index: src/lib/libperfuse/perfuse_if.h
diff -u src/lib/libperfuse/perfuse_if.h:1.17 src/lib/libperfuse/perfuse_if.h:1.18
--- src/lib/libperfuse/perfuse_if.h:1.17 Sun Oct 30 05:11:37 2011
+++ src/lib/libperfuse/perfuse_if.h Wed Dec 28 17:33:53 2011
@@ -1,4 +1,4 @@
-/* $NetBSD: perfuse_if.h,v 1.17 2011/10/30 05:11:37 manu Exp $ */
+/* $NetBSD: perfuse_if.h,v 1.18 2011/12/28 17:33:53 manu Exp $ */
/*-
* Copyright (c) 2010-2011 Emmanuel Dreyfus. All rights reserved.
@@ -54,6 +54,7 @@ extern int perfuse_diagflags;
#define PDF_SYSLOG 0x0400 /* use syslog */
#define PDF_FILENAME 0x0800 /* File names */
#define PDF_RESIZE 0x1000 /* Resize operations */
+#define PDF_TRACE 0x2000 /* Trace FUSE calls */
/*
* Diagnostic functions
@@ -206,5 +207,6 @@ const char *perfuse_opname(int);
void perfuse_fs_init(struct puffs_usermount *);
int perfuse_mainloop(struct puffs_usermount *);
int perfuse_unmount(struct puffs_usermount *);
+void perfuse_trace_dump(struct puffs_usermount *, FILE *);
#endif /* _PERFUSE_IF_H */
Index: src/usr.sbin/perfused/perfused.8
diff -u src/usr.sbin/perfused/perfused.8:1.7 src/usr.sbin/perfused/perfused.8:1.8
--- src/usr.sbin/perfused/perfused.8:1.7 Fri Dec 16 12:51:43 2011
+++ src/usr.sbin/perfused/perfused.8 Wed Dec 28 17:33:53 2011
@@ -1,4 +1,4 @@
-.\" $NetBSD: perfused.8,v 1.7 2011/12/16 12:51:43 wiz Exp $
+.\" $NetBSD: perfused.8,v 1.8 2011/12/28 17:33:53 manu Exp $
.\"
.\" Copyright (c) 2010 Emmanuel Dreyfus. All rights reserved.
.\"
@@ -118,12 +118,30 @@ is started from
Enable debug output only when receiving
.Li SIGINFO .
.El
+.Sh SIGNALS
+.Bl -tag -width indent
+.It SIGINFO
+If the
+.Fl s
+flag was used, toggle debug output. Do nothing otherwise.
+.It SIGUSR1
+Dump FUSE operation trace to
+.Pa /var/run/perfuse.trace .
+.El
.Sh ERRORS
The program logs to the syslog daemon as facility
.Dq daemon .
For detailed debugging use the
.Fl d
(debug) option.
+.Sh BUGS
+When
+.Nm
+runs in the foreground (using the
+.Fl f
+flag), some processes using the FUSE filesystem will
+sometime hang on
+.Sq uvn_fp2 .
.Sh SEE ALSO
.Xr mount 2 ,
.Xr perfuse_mount 3 ,
Index: src/usr.sbin/perfused/perfused.c
diff -u src/usr.sbin/perfused/perfused.c:1.16 src/usr.sbin/perfused/perfused.c:1.17
--- src/usr.sbin/perfused/perfused.c:1.16 Sun Oct 23 05:03:37 2011
+++ src/usr.sbin/perfused/perfused.c Wed Dec 28 17:33:53 2011
@@ -1,4 +1,4 @@
-/* $NetBSD: perfused.c,v 1.16 2011/10/23 05:03:37 manu Exp $ */
+/* $NetBSD: perfused.c,v 1.17 2011/12/28 17:33:53 manu Exp $ */
/*-
* Copyright (c) 2010 Emmanuel Dreyfus. All rights reserved.
@@ -50,10 +50,19 @@
#include "../../lib/libperfuse/perfuse_if.h"
#include "perfused.h"
+/*
+ * This is used for trace file. of course it will not work if
+ * we ever mount multiple filesystems in a single perfused,
+ * but it is not sure we will ever want to do that.
+ */
+struct puffs_usermount *perfuse_mount = NULL;
+FILE *perfuse_trace = NULL;
+
static int access_mount(const char *, uid_t, int);
static void new_mount(int, int);
static int parse_debug(char *);
static void siginfo_handler(int);
+static void sigusr1_handler(int);
static int parse_options(int, char **);
static void get_mount_info(int, struct perfuse_mount_info *, int);
@@ -267,6 +276,19 @@ new_mount(int fd, int pmnt_flags)
DERR(EX_OSERR, "fcntl failed");
/*
+ * Setup trace file facility
+ */
+ perfuse_mount = pu;
+
+ if ((perfuse_trace = fopen(_PATH_VAR_RUN_PERFUSE_TRACE, "w")) == NULL)
+ DERR(EX_OSFILE,
+ "could not open \"%s\"",
+ _PATH_VAR_RUN_PERFUSE_TRACE);
+
+ if (signal(SIGUSR1, sigusr1_handler) != 0)
+ DERR(EX_OSERR, "signal failed");
+
+ /*
* Hand over control to puffs main loop.
*/
if (perfuse_mainloop(pu) != 0)
@@ -333,6 +355,13 @@ siginfo_handler(int sig)
return;
}
+/* ARGSUSED0 */
+static void
+sigusr1_handler(int sig)
+{
+ return perfuse_trace_dump(perfuse_mount, perfuse_trace);
+}
+
static int
parse_options(int argc, char **argv)
{
@@ -341,6 +370,9 @@ parse_options(int argc, char **argv)
int retval = -1;
perfuse_diagflags = PDF_FOREGROUND | PDF_SYSLOG;
+#ifdef PERFUSE_DEBUG
+ perfuse_diagflags |= PDF_TRACE;
+#endif
while ((ch = getopt(argc, argv, "d:fsi:")) != -1) {
switch (ch) {
Index: src/usr.sbin/perfused/perfused.h
diff -u src/usr.sbin/perfused/perfused.h:1.5 src/usr.sbin/perfused/perfused.h:1.6
--- src/usr.sbin/perfused/perfused.h:1.5 Tue Aug 30 20:17:01 2011
+++ src/usr.sbin/perfused/perfused.h Wed Dec 28 17:33:53 2011
@@ -1,4 +1,4 @@
-/* $NetBSD: perfused.h,v 1.5 2011/08/30 20:17:01 joerg Exp $ */
+/* $NetBSD: perfused.h,v 1.6 2011/12/28 17:33:53 manu Exp $ */
/*-
* Copyright (c) 2010 Emmanuel Dreyfus. All rights reserved.
@@ -34,6 +34,8 @@
#define PERFUSE_MSG_T struct puffs_framebuf
+#define _PATH_VAR_RUN_PERFUSE_TRACE "/var/run/perfuse.trace"
+
__BEGIN_DECLS
#ifdef PERFUSE_DEBUG
