Aquaris-M10-4G/fs/fuse/mt_fuse.c

/*
  FUSE: file io log
  Copyright (C) 2015 Perry Hsu <perry.hsu@mediatek.com>

  This program can be distributed under the terms of the GNU GPL.
  See the file COPYING.
*/

#define DEBUG 1

#include "fuse_i.h"
#include "mt_fuse.h"
#include <linux/debugfs.h>
#include <linux/slab.h>
#include <linux/time.h>

/* kerel log buffer and ring buffer for debugfs */
struct fuse_proc_info *fuse_iolog = NULL;
struct fuse_proc_log *fuse_ringbuf = NULL;
int fuse_ringbuf_index = 0;

/* kernel print buffer */
static char *fuse_iolog_buf;

/* mutex used to protect the buffers */
struct mutex fuse_iolog_lock;

/* kernel log thread */
struct task_struct *fuse_iolog_thread = NULL;

/* debugfs dentries */
struct dentry *fuseio_droot = NULL;
struct dentry *fuseio_dklog = NULL;
struct dentry *fuseio_dlog = NULL;

/* kernel log enable */
unsigned int fuseio_klog_enable = 0;

void fuse_time_diff(struct timespec *start, struct timespec *end, struct timespec *diff)
{
	if ((end->tv_nsec-start->tv_nsec) < 0) {
		diff->tv_sec = end->tv_sec-start->tv_sec-1;
		diff->tv_nsec = 1000000000+end->tv_nsec-start->tv_nsec;
	} else {
		diff->tv_sec = end->tv_sec-start->tv_sec;
		diff->tv_nsec = end->tv_nsec-start->tv_nsec;
	}
}

/* type code translation table */
struct fuse_ioiog_type_map {
	int type;
	const char *str;
};

#define FUSE_IOLOG_TYPE_MAX 46

static const char *fuse_iolog_type[FUSE_IOLOG_TYPE_MAX] = {
	"unknown",	/*0*/
	"lookup",	/*1*/
	"forget",	/*2*/
	"getattr",	/*3*/
	"setattr",	/*4*/
	"readlink",	/*5*/
	"symlink",	/*6*/
	"",	/*7*/
	"mknod",	/*8*/
	"mkdir",	/*9*/
	"unlink",	/*10*/
	"rmdir",	/*11*/
	"rename",	/*12*/
	"link",	/*13*/
	"open",	/*14*/
	"read",	/*15*/
	"write",	/*16*/
	"statfs",	/*17*/
	"release",	/*18*/
	"",	/*19*/
	"fsync",	/*20*/
	"setxattr",	/*21*/
	"getxattr",	/*22*/
	"listxattr",	/*23*/
	"removexattr",	/*24*/
	"flush",	/*25*/
	"init",	/*26*/
	"opendir",	/*27*/
	"readdir",	/*28*/
	"releasedir",	/*29*/
	"fsyncdir",	/*30*/
	"getlk",	/*31*/
	"setlk",	/*32*/
	"setlkw",	/*33*/
	"access",	/*34*/
	"create",	/*35*/
	"interrupt",	/*36*/
	"bmap",	/*37*/
	"destroy",	/*38*/
	"ioctl",	/*39*/
	"poll",	/*40*/
	"notify_reply",	/*41*/
	"batch_forget",	/*42*/
	"fallocate", /*43*/
	"readdirplus", /*44*/
	"cuse"
};

/* convert type code to string */
static const char *fuse_iolog_type2str(int type)
{
	if (type >= 0 && type < FUSE_IOLOG_TYPE_MAX)
		goto out;
	else if (type == CUSE_INIT)
		type = FUSE_IOLOG_TYPE_MAX-1;
	else
		type = 0;
out:
	return fuse_iolog_type[type];
}



int fuse_iolog_print(void)
{
	int i, len, n;
	char *ptr;

	len = FUSE_IOLOG_BUFLEN-1;
	ptr = &fuse_iolog_buf[0];

	for (i = 0; i < FUSE_IOLOG_MAX && fuse_iolog[i].valid; i++) {

		if (fuse_iolog[i].read.count || fuse_iolog[i].write.count) {
			n = snprintf(ptr, len, "{%d:R(%d,%d,%d),W(%d,%d,%d)}",
				fuse_iolog[i].pid,
				fuse_iolog[i].read.bytes,
				fuse_iolog[i].read.count,
				fuse_iolog[i].read.us,
				fuse_iolog[i].write.bytes,
				fuse_iolog[i].write.count,
				fuse_iolog[i].write.us);

			len -= n;
			ptr += n;

			if (len < 0)
				goto overflow;
		}

		if (fuse_iolog[i].misc_type) {
			n = snprintf(ptr, len, "{%d:%s(%d,%d,%d)}",
				fuse_iolog[i].pid,
				fuse_iolog_type2str(fuse_iolog[i].misc_type),
				fuse_iolog[i].misc.bytes,
				fuse_iolog[i].misc.count,
				fuse_iolog[i].misc.us);
			len -= n;
			ptr += n;

			if (len < 0)
				goto overflow;
		}
	}

	if (i > 0) {
		if (fuseio_klog_enable)
			pr_debug("[BLOCK_TAG] FUSEIO %s\n", &fuse_iolog_buf[0]);

		memcpy(fuse_ringbuf[fuse_ringbuf_index].info, fuse_iolog, FUSE_IOLOG_MAX*sizeof(struct fuse_proc_info));
		fuse_ringbuf[fuse_ringbuf_index].time = sched_clock();
		fuse_ringbuf_index++;
		if (fuse_ringbuf_index >= FUSE_IOLOG_RINGBUF_MAX)
			fuse_ringbuf_index = 0;
	}

	return ptr - &fuse_iolog_buf[0];

overflow:
	pr_debug("[BLOCK_TAG] FUSEIO log buffer overflow\n");

	return -1;
}

static void fuse_iolog_seq_entry_time(struct seq_file *seq, uint64_t time)
{
	uint32_t nsec;

	if (time > 0) {
		nsec = do_div(time, 1000000000);
		seq_printf(seq, "[%5lu.%06lu] FUSEIO ", (unsigned long)time, (unsigned long)nsec/1000);
	}
}

static int fuse_iolog_seq_entry(struct seq_file *seq, int index)
{
	int i;

	if (index < 0 || index >= FUSE_IOLOG_RINGBUF_MAX)
		pr_warn("fuseio: fuse_iolog_seq_entry, index %d out of range (0-%d).\n",
			index, FUSE_IOLOG_RINGBUF_MAX-1);

	fuse_iolog_seq_entry_time(seq, fuse_ringbuf[index].time);

	for (i = 0; i < FUSE_IOLOG_MAX && fuse_ringbuf[index].info[i].valid; i++) {
		struct fuse_proc_info *info =  &fuse_ringbuf[index].info[i];

		if (info->read.count || info->write.count) {
			seq_printf(seq, "{%d:R(%d,%d,%d),W(%d,%d,%d)}",
				info->pid,
				info->read.bytes,
				info->read.count,
				info->read.us,
				info->write.bytes,
				info->write.count,
				info->write.us);
		}

		if (info->misc_type) {
			seq_printf(seq, "{%d:%s(%d,%d,%d)}",
				info->pid,
				fuse_iolog_type2str(info->misc_type),
				info->misc.bytes,
				info->misc.count,
				info->misc.us);
		}
	}
	if (i > 0)
		seq_puts(seq, "\n");

	return i;
}

static void fuse_iolog_clear(void)
{
	memset(&fuse_iolog[0], 0, sizeof(struct fuse_proc_info)*FUSE_IOLOG_MAX);
}

static void fuse_ringbuf_clear(void)
{
	memset(&fuse_ringbuf[0], 0, sizeof(struct fuse_proc_log)*FUSE_IOLOG_RINGBUF_MAX);
}

inline __u32 fuse_iolog_timeus(struct timespec *t)
{
	__u32 _t;
	long us;

	us = t->tv_nsec;
	do_div(us, 1000);

	if (t->tv_sec > 3600)
		return 0xD693A400; /* 3600000000 */

	_t = t->tv_sec * 1000000 + us;

	if (_t)
		return _t;

	return 1;
}

__u32 fuse_iolog_timeus_diff(struct timespec *start, struct timespec *end)
{
	struct timespec diff;

	fuse_time_diff(start, end, &diff);
	return fuse_iolog_timeus(&diff);
}


inline int fuse_iolog_proc_update(struct fuse_proc_info *info,
	__u32 io_bytes, int type, struct timespec *diff)
{
	struct fuse_rw_info *rwi;
	__u32 _t;

	_t = fuse_iolog_timeus(diff);

	if (type == FUSE_READ)
		rwi = &info->read;
	else if (type == FUSE_WRITE)
		rwi = &info->write;
	else {
		if (info->misc_type == 0)
			info->misc_type = type;
		else if (info->misc_type != type) /* misc type mismatch => continue */
			return -1;
		rwi = &info->misc;
	}

	rwi->bytes += io_bytes;
	rwi->us += _t;
	rwi->count++;

	return 0;
}

static int fuse_iolog_watch(void *arg)
{
	unsigned int timeout;
	int n;
	int empty = 0;  /* how many seconds that log is empty */

	while (1) {
		if (kthread_should_stop())
			break;

		/* log is empty for last 1 seconds => sleep till next io coming */
		if (empty > 1) {
				set_current_state(TASK_INTERRUPTIBLE);
				schedule();
		} else { /* otherwise, check 1 seconds later */
			do {
				set_current_state(TASK_INTERRUPTIBLE);
				timeout = schedule_timeout(FUSE_IOLOG_LATENCY*HZ);
			 } while (timeout);
		}

		mutex_lock(&fuse_iolog_lock);

		n = fuse_iolog_print();

		if (n > 0) {
			fuse_iolog_clear();
			empty = 0;
		} else {
			empty++;
		}

		mutex_unlock(&fuse_iolog_lock);
	}

	return 0;
}


static ssize_t fuseio_debug_write(struct file *file, const char __user *ubuf, size_t count, loff_t *ppos)
{
	return count;
}

/* seq file operations */
static void *fuseio_seq_debug_start(struct seq_file *seq, loff_t *pos)
{
	unsigned int idx;

	if (*pos < 0 || *pos >= 1)
		return NULL;

	idx = *pos + 1;
	return (void *) ((unsigned long) idx);
}

static void *fuseio_seq_debug_next(struct seq_file *seq, void *v, loff_t *pos)
{
	unsigned int idx;

	++*pos;
	if (*pos < 0 || *pos >= 1)
		return NULL;

	idx = *pos + 1;
	return (void *) ((unsigned long) idx);
}

static int fuseio_seq_debug_show(struct seq_file *seq, void *v)
{
	int i, end;

	mutex_lock(&fuse_iolog_lock);
	end = (fuse_ringbuf_index > 0) ? fuse_ringbuf_index-1 : FUSE_IOLOG_RINGBUF_MAX-1;
	for (i = fuse_ringbuf_index; ;) {
		fuse_iolog_seq_entry(seq, i);
		if (i == end)
			break;
		i = (i == FUSE_IOLOG_RINGBUF_MAX-1) ? 0 : i+1;
	};

	mutex_unlock(&fuse_iolog_lock);

	return 0;
}

static void fuseio_seq_debug_stop(struct seq_file *seq, void *v)
{
}

static const struct seq_operations fuseio_seq_debug_ops = {
	.start  = fuseio_seq_debug_start,
	.next   = fuseio_seq_debug_next,
	.stop   = fuseio_seq_debug_stop,
	.show   = fuseio_seq_debug_show,
};

static int fuseio_seq_debug_open(struct inode *inode, struct file *file)
{
	int rc;

	rc = seq_open(file, &fuseio_seq_debug_ops);
	if (rc == 0) {
		struct seq_file *m = file->private_data;

		m->private = &fuse_ringbuf_index;
	}
	return rc;

}

static const struct file_operations fuseio_seq_debug_fops = {
	.owner		= THIS_MODULE,
	.open		= fuseio_seq_debug_open,
	.read		= seq_read,
	.llseek		= seq_lseek,
	.release	= seq_release,
	.write		= fuseio_debug_write,
};

void fuse_iolog_init(void)
{
	int ret;

	fuse_iolog_buf = kmalloc(FUSE_IOLOG_BUFLEN, GFP_NOFS);
	fuse_iolog = kmalloc_array(FUSE_IOLOG_MAX, sizeof(struct fuse_proc_info), GFP_NOFS);
	fuse_ringbuf = kmalloc_array(FUSE_IOLOG_RINGBUF_MAX, sizeof(struct fuse_proc_log), GFP_NOFS);

	if (!fuse_iolog_buf || !fuse_iolog || !fuse_ringbuf)
		goto error_out;

	mutex_init(&fuse_iolog_lock);
	mutex_lock(&fuse_iolog_lock);
	fuse_iolog_clear();
	fuse_ringbuf_clear();
	mutex_unlock(&fuse_iolog_lock);

	fuse_iolog_thread = kthread_create(fuse_iolog_watch, NULL, "fuse_log");
	if (IS_ERR(fuse_iolog_thread)) {
		ret = PTR_ERR(fuse_iolog_thread);
		pr_warn("[BLOCK_TAG] fuse: fail to create fuse_log thread %d\n", ret);
		fuse_iolog_thread = NULL;
		goto error_out;
	}

	fuseio_droot = debugfs_create_dir("fuseio", NULL);

	if (IS_ERR(fuseio_droot)) {
		pr_warn("[BLOCK_TAG] fuse: fail to create debugfs root\n");
		goto out;
	}

	fuseio_dklog = debugfs_create_u32("klog_enable", 0660, fuseio_droot, &fuseio_klog_enable);

	if (IS_ERR(fuseio_dklog)) {
		pr_warn("[BLOCK_TAG] fuse: fail to create klog_enable at debugfs\n");
		goto out;
	}

	fuseio_dlog = debugfs_create_file("log", S_IFREG | S_IRUGO, fuseio_droot, (void *)0, &fuseio_seq_debug_fops);

	if (IS_ERR(fuseio_dlog)) {
		pr_warn("[BLOCK_TAG] fuse: fail to create log at debugfs\n");
		goto out;
	}

out:
	return;

error_out:
	kfree(fuse_iolog_buf);
	kfree(fuse_iolog);
	kfree(fuse_ringbuf);
}

void fuse_iolog_exit(void)
{
	kthread_stop(fuse_iolog_thread);
	kfree(fuse_iolog_buf);
	kfree(fuse_iolog);
	kfree(fuse_ringbuf);
}

void fuse_iolog_add(__u32 io_bytes, int type,
	struct timespec *start,
	struct timespec *end)
{
	struct fuse_proc_info *info;
	struct timespec diff;
	pid_t pid;
	int i;

	pid = task_pid_nr(current);
	fuse_time_diff(start, end, &diff);

	mutex_lock(&fuse_iolog_lock);

	for (i = 0; i < FUSE_IOLOG_MAX; i++)   {
		info = &fuse_iolog[i];
		if (info->valid) {
			if (info->pid == pid) {
				if (fuse_iolog_proc_update(info, io_bytes, type, &diff))
					continue; /* ops mismatch */
				else
					goto out;
			} else {
				continue;
			}
		} else {
			info->valid = 1;
			info->pid = pid;
			fuse_iolog_proc_update(info, io_bytes, type, &diff);
			if (i == 0) {  /* this is the first entry, wake up the handler */
				if (fuse_iolog_thread)
					wake_up_process(fuse_iolog_thread);
			}
			goto out;
		}
	}

	if (i == FUSE_IOLOG_MAX) {
		fuse_iolog_print();
		fuse_iolog_clear();
		info = &fuse_iolog[0];
		info->valid = 1;
		info->pid = pid;
		fuse_iolog_proc_update(info, io_bytes, type, &diff);
	}
out:
	mutex_unlock(&fuse_iolog_lock);
}