Home | History | Annotate | Line # | Download | only in libperfuse 
      1 /*  $NetBSD: debug.c,v 1.13 2018/11/16 02:39:02 manu 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 	"REF"
     95 };
     96 
     97 const char *
     98 perfuse_opname(int opcode)
     99 {
    100 	const struct perfuse_opcode *po;
    101 
    102 	for (po = perfuse_opcode; po->opcode; po++) {
    103 		if (po->opcode == opcode)
    104 			return po->opname;
    105 	}
    106 
    107 	return po->opname; /* "UNKNOWN" */
    108 }
    109 
    110 char *
    111 perfuse_opdump_in(struct perfuse_state *ps, perfuse_msg_t *pm)
    112 {
    113 	struct fuse_in_header *fih;
    114 	static char buf[BUFSIZ] = "";
    115 
    116 	fih = GET_INHDR(ps, pm);
    117 
    118 	switch(fih->opcode) {
    119 	case FUSE_LOOKUP:
    120 		(void)snprintf(buf, sizeof(buf), "path = \"%s\"",
    121 			       _GET_INPAYLOAD(ps, pm, const char *));
    122 		break;
    123 	default:
    124 		buf[0] = '\0';
    125 		break;
    126 	}
    127 
    128 	return buf;
    129 }
    130 
    131 struct perfuse_trace *
    132 perfuse_trace_begin(struct perfuse_state *ps, puffs_cookie_t opc,
    133 	perfuse_msg_t *pm)
    134 {
    135 	struct perfuse_trace *pt;
    136 
    137 	if ((pt = malloc(sizeof(*pt))) == NULL)
    138 		DERR(EX_OSERR, "malloc failed");
    139 
    140 	pt->pt_opcode = ps->ps_get_inhdr(pm)->opcode;
    141 	pt->pt_status = inxchg;
    142 
    143 	if (clock_gettime(CLOCK_REALTIME, &pt->pt_start) != 0)
    144 		DERR(EX_OSERR, "clock_gettime failed");
    145 
    146 	if (opc == 0)
    147 		(void)strcpy(pt->pt_path, "");
    148 	else
    149 		(void)strlcpy(pt->pt_path,
    150 			      perfuse_node_path(ps, opc),
    151 			      sizeof(pt->pt_path));
    152 
    153 	(void)strlcpy(pt->pt_extra,
    154 		      perfuse_opdump_in(ps, pm),
    155 		      sizeof(pt->pt_extra));
    156 
    157 	TAILQ_INSERT_TAIL(&ps->ps_trace, pt, pt_list);
    158 	ps->ps_tracecount++;
    159 
    160 	return pt;
    161 }
    162 
    163 void
    164 perfuse_trace_end(struct perfuse_state *ps, struct perfuse_trace *pt, int error)
    165 {
    166 	if (clock_gettime(CLOCK_REALTIME, &pt->pt_end) != 0)
    167 		DERR(EX_OSERR, "clock_gettime failed");
    168 
    169 	pt->pt_status = done;
    170 	pt->pt_error = error;
    171 
    172 	while (ps->ps_tracecount > PERFUSE_TRACECOUNT_MAX) {
    173 		struct perfuse_trace *fpt = TAILQ_FIRST(&ps->ps_trace);
    174 
    175 		if (fpt == NULL || fpt->pt_status != done)
    176 			break;
    177 
    178 		TAILQ_REMOVE(&ps->ps_trace, fpt, pt_list);
    179 		free(fpt);
    180 		ps->ps_tracecount--;
    181 	}
    182 }
    183 
    184 void
    185 perfuse_trace_dump(struct puffs_usermount *pu, FILE *fp)
    186 {
    187 	struct perfuse_state *ps;
    188 	struct perfuse_trace *pt;
    189 	struct timespec ts_min[FUSE_OPCODE_MAX];
    190 	struct timespec ts_max[FUSE_OPCODE_MAX];
    191 	struct timespec ts_total[FUSE_OPCODE_MAX];
    192 	int count[FUSE_OPCODE_MAX];
    193 	uint64_t avg;
    194 	int i;
    195 
    196 	if (!(perfuse_diagflags & PDF_TRACE))
    197 		return;
    198 
    199 	ps = puffs_getspecific(pu);
    200 
    201 	(void)ftruncate(fileno(fp), 0);
    202 	(void)fseek(fp, 0UL, SEEK_SET);
    203 
    204 	(void)memset(&ts_min, 0, sizeof(ts_min));
    205 	(void)memset(&ts_max, 0, sizeof(ts_max));
    206 	(void)memset(&ts_total, 0, sizeof(ts_total));
    207 	(void)memset(&count, 0, sizeof(count));
    208 
    209 	fprintf(fp, "Last %"PRId64" operations\n", ps->ps_tracecount);
    210 
    211 	TAILQ_FOREACH(pt, &ps->ps_trace, pt_list) {
    212 		const char *quote = pt->pt_path[0] != '\0' ? "\"" : "";
    213 
    214 		fprintf(fp, "%lld.%09ld %s %s%s%s %s ",
    215 			(long long)pt->pt_start.tv_sec, pt->pt_start.tv_nsec,
    216 			perfuse_opname(pt->pt_opcode),
    217 			quote, pt->pt_path, quote,
    218 			pt->pt_extra);
    219 
    220 		if (pt->pt_status == done) {
    221 			struct timespec ts;
    222 
    223 			ts.tv_sec = 0;	/* delint */
    224 			ts.tv_nsec = 0;	/* delint */
    225 			timespecsub(&pt->pt_end, &pt->pt_start, &ts);
    226 
    227 			fprintf(fp, "error = %d elapsed = %lld.%09lu ",
    228 				pt->pt_error, (long long)ts.tv_sec,
    229 				ts.tv_nsec);
    230 
    231 			count[pt->pt_opcode]++;
    232 			timespecadd(&ts_total[pt->pt_opcode],
    233 				    &ts,
    234 				    &ts_total[pt->pt_opcode]);
    235 
    236 			if (timespeccmp(&ts, &ts_min[pt->pt_opcode], <) ||
    237 			    (count[pt->pt_opcode] == 1))
    238 				ts_min[pt->pt_opcode] = ts;
    239 
    240 			if (timespeccmp(&ts, &ts_max[pt->pt_opcode], >))
    241 				ts_max[pt->pt_opcode] = ts;
    242 		} else {
    243 			fprintf(fp, "ongoing ");
    244 		}
    245 
    246 		fprintf(fp, "\n");
    247 	}
    248 
    249 	fprintf(fp, "\nStatistics by operation\n");
    250 	fprintf(fp, "operation\tcount\tmin\tavg\tmax\n");
    251 	for (i = 0; i < FUSE_OPCODE_MAX; i++) {
    252 		time_t min;
    253 
    254 		if (count[i] != 0) {
    255 			avg = timespec2ns(&ts_total[i]) / count[i];
    256 			min = ts_min[i].tv_sec;
    257 		} else {
    258 			avg = 0;
    259 			min = 0;
    260 		}
    261 
    262 		fprintf(fp, "%s\t%d\t%lld.%09ld\t%lld.%09ld\t%lld.%09ld\t\n",
    263 			perfuse_opname(i), count[i],
    264 			(long long)min, ts_min[i].tv_nsec,
    265 			(long long)(time_t)(avg / 1000000000L),
    266 			(long)(avg % 1000000000L),
    267 			(long long)ts_max[i].tv_sec, ts_max[i].tv_nsec);
    268 	}
    269 
    270 	fprintf(fp, "\n\nGlobal statistics\n");
    271 	fprintf(fp, "Nodes: %d\n", ps->ps_nodecount);
    272 	fprintf(fp, "Exchanges: %d\n", ps->ps_xchgcount);
    273 
    274 	(void)fflush(fp);
    275 	return;
    276 }
    277