root/lib/libperfuse/debug.c
/*  $NetBSD: debug.c,v 1.13 2018/11/16 02:39:02 manu Exp $ */

/*-
 *  Copyright (c) 2010 Emmanuel Dreyfus. All rights reserved.
 * 
 *  Redistribution and use in source and binary forms, with or without
 *  modification, are permitted provided that the following conditions
 *  are met:
 *  1. Redistributions of source code must retain the above copyright
 *     notice, this list of conditions and the following disclaimer.
 *  2. Redistributions in binary form must reproduce the above copyright
 *     notice, this list of conditions and the following disclaimer in the
 *     documentation and/or other materials provided with the distribution.
 * 
 *  THIS SOFTWARE IS PROVIDED BY THE NETBSD FOUNDATION, INC. AND CONTRIBUTORS
 *  ``AS IS'' AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED
 *  TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR
 *  PURPOSE ARE DISCLAIMED.  IN NO EVENT SHALL THE FOUNDATION OR CONTRIBUTORS
 *  BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR
 *  CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF
 *  SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS
 *  INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN
 *  CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE)
 *  ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
 *  POSSIBILITY OF SUCH DAMAGE.
 */ 

#include <puffs.h>
#include <stdio.h>
#include <stdlib.h>
#include <err.h>
#include <errno.h>
#include <sys/types.h>

#include "perfuse_if.h"
#include "perfuse_priv.h"
#include "fuse.h"

struct perfuse_opcode {
        int  opcode;
        const char *opname;
};

const struct perfuse_opcode perfuse_opcode[] = {
        { FUSE_LOOKUP, "LOOKUP" },
        { FUSE_FORGET, "FORGET" },
        { FUSE_GETATTR, "GETATTR" },
        { FUSE_SETATTR, "SETATTR" },
        { FUSE_READLINK, "READLINK" },
        { FUSE_SYMLINK, "SYMLINK" },
        { FUSE_MKNOD, "MKNOD" },
        { FUSE_MKDIR, "MKDIR" },
        { FUSE_UNLINK, "UNLINK" },
        { FUSE_RMDIR, "RMDIR" },
        { FUSE_RENAME, "RENAME" },
        { FUSE_LINK, "LINK" },
        { FUSE_OPEN, "OPEN" },
        { FUSE_READ, "READ" },
        { FUSE_WRITE, "WRITE" },
        { FUSE_STATFS, "STATFS" },
        { FUSE_RELEASE, "RELEASE" },
        { FUSE_FSYNC, "FSYNC" },
        { FUSE_SETXATTR, "SETXATTR" },
        { FUSE_GETXATTR, "GETXATTR" },
        { FUSE_LISTXATTR, "LISTXATTR" },
        { FUSE_REMOVEXATTR, "REMOVEXATTR" },
        { FUSE_FLUSH, "FLUSH" },
        { FUSE_INIT, "INIT" },
        { FUSE_OPENDIR, "OPENDIR" },
        { FUSE_READDIR, "READDIR" },
        { FUSE_RELEASEDIR, "RELEASEDIR" },
        { FUSE_FSYNCDIR, "FSYNCDIR" },
        { FUSE_GETLK, "GETLK" },
        { FUSE_SETLK, "SETLK" },
        { FUSE_SETLKW, "SETLKW" },
        { FUSE_ACCESS, "ACCESS" },
        { FUSE_CREATE, "CREATE" },
        { FUSE_INTERRUPT, "INTERRUPT" },
        { FUSE_BMAP, "BMAP" },
        { FUSE_DESTROY, "DESTROY" },
        { FUSE_IOCTL, "IOCTL" },
        { FUSE_POLL, "POLL" },
        { FUSE_CUSE_INIT, "CUSE_INIT" },
        { 0, "UNKNOWN" },
};

const char * const perfuse_qtypestr[] = { 
        "READDIR",
        "READ",
        "WRITE",
        "AFTERWRITE",
        "OPEN",
        "AFTERXCHG",
        "REF"
};

const char *
perfuse_opname(int opcode)
{
        const struct perfuse_opcode *po;

        for (po = perfuse_opcode; po->opcode; po++) {
                if (po->opcode == opcode)
                        return po->opname;
        }

        return po->opname; /* "UNKNOWN" */
}

char *
perfuse_opdump_in(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;
}

struct perfuse_trace *
perfuse_trace_begin(struct perfuse_state *ps, puffs_cookie_t opc,
        perfuse_msg_t *pm)
{
        struct perfuse_trace *pt;

        if ((pt = malloc(sizeof(*pt))) == NULL)
                DERR(EX_OSERR, "malloc failed");

        pt->pt_opcode = ps->ps_get_inhdr(pm)->opcode;
        pt->pt_status = inxchg;

        if (clock_gettime(CLOCK_REALTIME, &pt->pt_start) != 0)
                DERR(EX_OSERR, "clock_gettime failed");

        if (opc == 0)
                (void)strcpy(pt->pt_path, "");
        else
                (void)strlcpy(pt->pt_path, 
                              perfuse_node_path(ps, opc),
                              sizeof(pt->pt_path));

        (void)strlcpy(pt->pt_extra,
                      perfuse_opdump_in(ps, pm),
                      sizeof(pt->pt_extra));

        TAILQ_INSERT_TAIL(&ps->ps_trace, pt, pt_list);
        ps->ps_tracecount++;

        return pt;
}

void
perfuse_trace_end(struct perfuse_state *ps, struct perfuse_trace *pt, int error)
{
        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 == NULL || fpt->pt_status != done)
                        break;

                TAILQ_REMOVE(&ps->ps_trace, fpt, pt_list);
                free(fpt);
                ps->ps_tracecount--;
        }
}

void
perfuse_trace_dump(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, 0UL, 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, "%lld.%09ld %s %s%s%s %s ",  
                        (long long)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 = %lld.%09lu ",
                                pt->pt_error, (long long)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%lld.%09ld\t%lld.%09ld\t%lld.%09ld\t\n",
                        perfuse_opname(i), count[i],
                        (long long)min, ts_min[i].tv_nsec,
                        (long long)(time_t)(avg / 1000000000L),
                        (long)(avg % 1000000000L),
                        (long long)ts_max[i].tv_sec, ts_max[i].tv_nsec);
        }       

        fprintf(fp, "\n\nGlobal statistics\n");
        fprintf(fp, "Nodes: %d\n", ps->ps_nodecount);
        fprintf(fp, "Exchanges: %d\n", ps->ps_xchgcount);
        
        (void)fflush(fp);
        return;
}