Home | History | Annotate | Line # | Download | only in libperfuse
debug.c revision 1.11
      1 /*  $NetBSD: debug.c,v 1.11 2012/03/21 10:10:36 matt Exp $ */
      2 
      3 /*-
      4  *  Copyright (c) 2010 Emmanuel Dreyfus. All rights reserved.
      5  *
      6  *  Redistribution and use in source and binary forms, with or without
      7  *  modification, are permitted provided that the following conditions
      8  *  are met:
      9  *  1. Redistributions of source code must retain the above copyright
     10  *     notice, this list of conditions and the following disclaimer.
     11  *  2. Redistributions in binary form must reproduce the above copyright
     12  *     notice, this list of conditions and the following disclaimer in the
     13  *     documentation and/or other materials provided with the distribution.
     14  *
     15  *  THIS SOFTWARE IS PROVIDED BY THE NETBSD FOUNDATION, INC. AND CONTRIBUTORS
     16  *  ``AS IS'' AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED
     17  *  TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR
     18  *  PURPOSE ARE DISCLAIMED.  IN NO EVENT SHALL THE FOUNDATION OR CONTRIBUTORS
     19  *  BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR
     20  *  CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF
     21  *  SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS
     22  *  INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN
     23  *  CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE)
     24  *  ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
     25  *  POSSIBILITY OF SUCH DAMAGE.
     26  */
     27 
     28 #include <puffs.h>
     29 #include <stdio.h>
     30 #include <stdlib.h>
     31 #include <err.h>
     32 #include <errno.h>
     33 #include <sys/types.h>
     34 
     35 #include "perfuse_if.h"
     36 #include "perfuse_priv.h"
     37 #include "fuse.h"
     38 
     39 struct perfuse_opcode {
     40 	int  opcode;
     41 	const char *opname;
     42 };
     43 
     44 const struct perfuse_opcode perfuse_opcode[] = {
     45 	{ FUSE_LOOKUP, "LOOKUP" },
     46 	{ FUSE_FORGET, "FORGET" },
     47 	{ FUSE_GETATTR, "GETATTR" },
     48 	{ FUSE_SETATTR, "SETATTR" },
     49 	{ FUSE_READLINK, "READLINK" },
     50 	{ FUSE_SYMLINK, "SYMLINK" },
     51 	{ FUSE_MKNOD, "MKNOD" },
     52 	{ FUSE_MKDIR, "MKDIR" },
     53 	{ FUSE_UNLINK, "UNLINK" },
     54 	{ FUSE_RMDIR, "RMDIR" },
     55 	{ FUSE_RENAME, "RENAME" },
     56 	{ FUSE_LINK, "LINK" },
     57 	{ FUSE_OPEN, "OPEN" },
     58 	{ FUSE_READ, "READ" },
     59 	{ FUSE_WRITE, "WRITE" },
     60 	{ FUSE_STATFS, "STATFS" },
     61 	{ FUSE_RELEASE, "RELEASE" },
     62 	{ FUSE_FSYNC, "FSYNC" },
     63 	{ FUSE_SETXATTR, "SETXATTR" },
     64 	{ FUSE_GETXATTR, "GETXATTR" },
     65 	{ FUSE_LISTXATTR, "LISTXATTR" },
     66 	{ FUSE_REMOVEXATTR, "REMOVEXATTR" },
     67 	{ FUSE_FLUSH, "FLUSH" },
     68 	{ FUSE_INIT, "INIT" },
     69 	{ FUSE_OPENDIR, "OPENDIR" },
     70 	{ FUSE_READDIR, "READDIR" },
     71 	{ FUSE_RELEASEDIR, "RELEASEDIR" },
     72 	{ FUSE_FSYNCDIR, "FSYNCDIR" },
     73 	{ FUSE_GETLK, "GETLK" },
     74 	{ FUSE_SETLK, "SETLK" },
     75 	{ FUSE_SETLKW, "SETLKW" },
     76 	{ FUSE_ACCESS, "ACCESS" },
     77 	{ FUSE_CREATE, "CREATE" },
     78 	{ FUSE_INTERRUPT, "INTERRUPT" },
     79 	{ FUSE_BMAP, "BMAP" },
     80 	{ FUSE_DESTROY, "DESTROY" },
     81 	{ FUSE_IOCTL, "IOCTL" },
     82 	{ FUSE_POLL, "POLL" },
     83 	{ FUSE_CUSE_INIT, "CUSE_INIT" },
     84 	{ 0, "UNKNOWN" },
     85 };
     86 
     87 const char * const perfuse_qtypestr[] = {
     88 	"READDIR",
     89 	"READ",
     90 	"WRITE",
     91 	"AFTERWRITE",
     92 	"OPEN",
     93 	"AFTERXCHG"
     94 };
     95 
     96 const char *
     97 perfuse_opname(int opcode)
     98 {
     99 	const struct perfuse_opcode *po;
    100 
    101 	for (po = perfuse_opcode; po->opcode; po++) {
    102 		if (po->opcode == opcode)
    103 			return po->opname;
    104 	}
    105 
    106 	return po->opname; /* "UNKNOWN" */
    107 }
    108 
    109 char *
    110 perfuse_opdump_in(struct perfuse_state *ps, perfuse_msg_t *pm)
    111 {
    112 	struct fuse_in_header *fih;
    113 	static char buf[BUFSIZ] = "";
    114 
    115 	fih = GET_INHDR(ps, pm);
    116 
    117 	switch(fih->opcode) {
    118 	case FUSE_LOOKUP:
    119 		(void)snprintf(buf, sizeof(buf), "path = \"%s\"",
    120 			       _GET_INPAYLOAD(ps, pm, const char *));
    121 		break;
    122 	default:
    123 		buf[0] = '\0';
    124 		break;
    125 	}
    126 
    127 	return buf;
    128 }
    129 
    130 struct perfuse_trace *
    131 perfuse_trace_begin(struct perfuse_state *ps, puffs_cookie_t opc,
    132 	perfuse_msg_t *pm)
    133 {
    134 	struct perfuse_trace *pt;
    135 
    136 	if ((pt = malloc(sizeof(*pt))) == NULL)
    137 		DERR(EX_OSERR, "malloc failed");
    138 
    139 	pt->pt_opcode = ps->ps_get_inhdr(pm)->opcode;
    140 	pt->pt_status = inxchg;
    141 
    142 	if (clock_gettime(CLOCK_REALTIME, &pt->pt_start) != 0)
    143 		DERR(EX_OSERR, "clock_gettime failed");
    144 
    145 	if (opc == 0)
    146 		(void)strcpy(pt->pt_path, "");
    147 	else
    148 		(void)strlcpy(pt->pt_path,
    149 			      perfuse_node_path(opc),
    150 			      sizeof(pt->pt_path));
    151 
    152 	(void)strlcpy(pt->pt_extra,
    153 		      perfuse_opdump_in(ps, pm),
    154 		      sizeof(pt->pt_extra));
    155 
    156 	TAILQ_INSERT_TAIL(&ps->ps_trace, pt, pt_list);
    157 	ps->ps_tracecount++;
    158 
    159 	return pt;
    160 }
    161 
    162 void
    163 perfuse_trace_end(struct perfuse_state *ps, struct perfuse_trace *pt, int error)
    164 {
    165 	if (clock_gettime(CLOCK_REALTIME, &pt->pt_end) != 0)
    166 		DERR(EX_OSERR, "clock_gettime failed");
    167 
    168 	pt->pt_status = done;
    169 	pt->pt_error = error;
    170 
    171 	while (ps->ps_tracecount > PERFUSE_TRACECOUNT_MAX) {
    172 		struct perfuse_trace *fpt = TAILQ_FIRST(&ps->ps_trace);
    173 
    174 		if (fpt == NULL || fpt->pt_status != done)
    175 			break;
    176 
    177 		TAILQ_REMOVE(&ps->ps_trace, fpt, pt_list);
    178 		free(fpt);
    179 		ps->ps_tracecount--;
    180 	}
    181 }
    182 
    183 void
    184 perfuse_trace_dump(struct puffs_usermount *pu, FILE *fp)
    185 {
    186 	struct perfuse_state *ps;
    187 	struct perfuse_trace *pt;
    188 	struct timespec ts_min[FUSE_OPCODE_MAX];
    189 	struct timespec ts_max[FUSE_OPCODE_MAX];
    190 	struct timespec ts_total[FUSE_OPCODE_MAX];
    191 	int count[FUSE_OPCODE_MAX];
    192 	uint64_t avg;
    193 	int i;
    194 
    195 	if (!(perfuse_diagflags & PDF_TRACE))
    196 		return;
    197 
    198 	ps = puffs_getspecific(pu);
    199 
    200 	(void)ftruncate(fileno(fp), 0);
    201 	(void)fseek(fp, 0, SEEK_SET);
    202 
    203 	(void)memset(&ts_min, 0, sizeof(ts_min));
    204 	(void)memset(&ts_max, 0, sizeof(ts_max));
    205 	(void)memset(&ts_total, 0, sizeof(ts_total));
    206 	(void)memset(&count, 0, sizeof(count));
    207 
    208 	fprintf(fp, "Last %"PRId64" operations\n", ps->ps_tracecount);
    209 
    210 	TAILQ_FOREACH(pt, &ps->ps_trace, pt_list) {
    211 		const char *quote = pt->pt_path[0] != '\0' ? "\"" : "";
    212 
    213 		fprintf(fp, "%lld.%09ld %s %s%s%s %s ",
    214 			(long long)pt->pt_start.tv_sec, pt->pt_start.tv_nsec,
    215 			perfuse_opname(pt->pt_opcode),
    216 			quote, pt->pt_path, quote,
    217 			pt->pt_extra);
    218 
    219 		if (pt->pt_status == done) {
    220 			struct timespec ts;
    221 
    222 			ts.tv_sec = 0;	/* delint */
    223 			ts.tv_nsec = 0;	/* delint */
    224 			timespecsub(&pt->pt_end, &pt->pt_start, &ts);
    225 
    226 			fprintf(fp, "error = %d elapsed = %lld.%09lu ",
    227 				pt->pt_error, (long long)ts.tv_sec,
    228 				ts.tv_nsec);
    229 
    230 			count[pt->pt_opcode]++;
    231 			timespecadd(&ts_total[pt->pt_opcode],
    232 				    &ts,
    233 				    &ts_total[pt->pt_opcode]);
    234 
    235 			if (timespeccmp(&ts, &ts_min[pt->pt_opcode], <) ||
    236 			    (count[pt->pt_opcode] == 1))
    237 				ts_min[pt->pt_opcode] = ts;
    238 
    239 			if (timespeccmp(&ts, &ts_max[pt->pt_opcode], >))
    240 				ts_max[pt->pt_opcode] = ts;
    241 		} else {
    242 			fprintf(fp, "ongoing ");
    243 		}
    244 
    245 		fprintf(fp, "\n");
    246 	}
    247 
    248 	fprintf(fp, "\nStatistics by operation\n");
    249 	fprintf(fp, "operation\tcount\tmin\tavg\tmax\n");
    250 	for (i = 0; i < FUSE_OPCODE_MAX; i++) {
    251 		time_t min;
    252 
    253 		if (count[i] != 0) {
    254 			avg = timespec2ns(&ts_total[i]) / count[i];
    255 			min = ts_min[i].tv_sec;
    256 		} else {
    257 			avg = 0;
    258 			min = 0;
    259 		}
    260 
    261 		fprintf(fp, "%s\t%d\t%lld.%09ld\t%lld.%09ld\t%lld.%09ld\t\n",
    262 			perfuse_opname(i), count[i],
    263 			(long long)min, ts_min[i].tv_nsec,
    264 			(long long)(time_t)(avg / 1000000000L),
    265 			(long)(avg % 1000000000L),
    266 			(long long)ts_max[i].tv_sec, ts_max[i].tv_nsec);
    267 	}
    268 
    269 	(void)fflush(fp);
    270 	return;
    271 }
    272