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