[sheepdog] [PATCH 4/5] collie/trace: add graph stat function

Liu Yuan namei.unix at gmail.com
Sat Aug 10 16:21:10 CEST 2013


This is useful to get how much time each function takes during the trace.

Usage:
$ collie trace graph stat
   Function Name                    |  Time(ms)
--------------------------------------------------
eventfd_xread                       | 110817.996257
do_process_work                     | 87415.051934
do_push_object                      | 84434.906931
push_cache_object                   | 84426.040582
gateway_create_and_write_obj        | 82382.884469
exec_local_req                      | 82038.293182
gateway_forward_request             | 81968.317720
event_loop                          | 48661.499542
do_event_loop                       | 48650.993934
xpwrite                             | 38091.275768
sheep_do_op_work                    | 36608.988329
peer_create_and_write_obj           | 36608.802587
default_create_and_write            | 36607.231493
object_cache_push                   | 28783.994126
do_background_push                  | 27332.938972
local_release_vdi                   | 3455.208848
object_cache_flush_vdi              | 3452.805846
read_cache_object_noupdate          | 2309.550495
...

Signed-off-by: Liu Yuan <namei.unix at gmail.com>
---
 collie/trace.c      |  152 +++++++++++++++++++++++++++++++++++++++++++++++----
 include/sheep.h     |    4 +-
 sheep/trace/graph.c |    1 +
 3 files changed, 143 insertions(+), 14 deletions(-)

diff --git a/collie/trace.c b/collie/trace.c
index 18f062f..7b09578 100644
--- a/collie/trace.c
+++ b/collie/trace.c
@@ -21,6 +21,8 @@
 #include <sys/mman.h>
 
 #include "collie.h"
+#include "rbtree.h"
+#include "list.h"
 
 static inline void print_thread_name(struct trace_graph_item *item)
 {
@@ -58,10 +60,10 @@ static void print_trace_item(struct trace_graph_item *item)
 	print_finale(item);
 }
 
-static void parse_trace_buffer(char *buf, int size)
+static void cat_trace_file(void *buf, size_t size)
 {
 	struct trace_graph_item *item = (struct trace_graph_item *)buf;
-	int sz = size / sizeof(struct trace_graph_item), i;
+	size_t sz = size / sizeof(struct trace_graph_item), i;
 
 	printf("   Thread Name      |  Time(us)  |  Function Graph\n");
 	printf("--------------------------------------------------\n");
@@ -194,38 +196,162 @@ static int trace_status(int argc, char **argv)
 	return EXIT_SUCCESS;
 }
 
-static int graph_cat(int argc, char **argv)
+static void *map_trace_file(struct stat *st)
 {
 	int fd = open(tracefile, O_RDONLY);
-	struct stat st;
 	void *map;
 
 	if (fd < 0) {
 		sd_err("%m");
-		return EXIT_SYSFAIL;
+		return NULL;
 	}
 
-	if (fstat(fd, &st) < 0) {
+	if (fstat(fd, st) < 0) {
 		sd_err("%m");
 		close(fd);
-		return EXIT_SYSFAIL;
+		return NULL;
 	}
 
-	if (st.st_size == 0)
-		return EXIT_SUCCESS;
+	if (st->st_size == 0) {
+		sd_err("trace file is empty");
+		return NULL;
+	}
 
-	map = mmap(NULL, st.st_size, PROT_READ, MAP_PRIVATE, fd, 0);
+	map = mmap(NULL, st->st_size, PROT_READ, MAP_PRIVATE, fd, 0);
 	close(fd);
 	if (map == MAP_FAILED) {
 		sd_err("%m");
-		return EXIT_SYSFAIL;
+		return NULL;
 	}
-	parse_trace_buffer(map, st.st_size);
+
+	return map;
+}
+
+static int graph_cat(int argc, char **argv)
+{
+	struct stat st;
+	void *map = map_trace_file(&st);
+
+	if (!map)
+		return EXIT_FAILURE;
+
+	cat_trace_file(map, st.st_size);
 	munmap(map, st.st_size);
 
 	return EXIT_SUCCESS;
 }
 
+struct graph_stat_entry {
+	struct rb_node rb;
+	struct list_head list;
+	char fname[TRACE_FNAME_LEN];
+	uint64_t duration;
+};
+
+static struct rb_root stat_tree_root;
+
+static LIST_HEAD(stat_list);
+
+static struct graph_stat_entry *
+stat_tree_insert(struct graph_stat_entry *new)
+{
+	struct rb_node **p = &stat_tree_root.rb_node;
+	struct rb_node *parent = NULL;
+	struct graph_stat_entry *entry;
+
+	while (*p) {
+		int cmp;
+
+		parent = *p;
+		entry = rb_entry(parent, struct graph_stat_entry, rb);
+		cmp = strcmp(new->fname, entry->fname);
+
+		if (cmp < 0)
+			p = &(*p)->rb_left;
+		else if (cmp > 0)
+			p = &(*p)->rb_right;
+		else {
+			entry->duration += new->duration;
+			return entry;
+		}
+	}
+	rb_link_node(&new->rb, parent, p);
+	rb_insert_color(&new->rb, &stat_tree_root);
+
+	return NULL; /* insert successfully */
+}
+
+static void prepare_stat_tree(struct trace_graph_item *item)
+{
+	struct graph_stat_entry *new;
+
+	if (item->type != TRACE_GRAPH_RETURN)
+		return;
+	new = xmalloc(sizeof(*new));
+	pstrcpy(new->fname, sizeof(new->fname), item->fname);
+	new->duration = item->return_time - item->entry_time;
+	INIT_LIST_HEAD(&new->list);
+	if (stat_tree_insert(new)) {
+		free(new);
+		return;
+	}
+	list_add(&new->list, &stat_list);
+}
+
+static void stat_list_print(void)
+{
+	struct graph_stat_entry *entry;
+
+	list_for_each_entry(entry, &stat_list, list) {
+		uint64_t quot = entry->duration / 1000000,
+			 rem = entry->duration % 1000000;
+
+		printf("%-*s| %"PRIu64".%06"PRIu64"\n", TRACE_FNAME_LEN,
+		       entry->fname, quot, rem);
+	}
+}
+
+static int stat_list_cmp(void *priv, struct list_head *a, struct list_head *b)
+{
+	struct graph_stat_entry *ga = container_of(a, struct graph_stat_entry,
+						   list);
+	struct graph_stat_entry *gb = container_of(b, struct graph_stat_entry,
+						   list);
+
+	if (ga->duration == gb->duration)
+		return 0;
+	else if (ga->duration > gb->duration)
+		return -1; /* This is for reverse sort, largest first */
+	else
+		return 1;
+}
+
+static void stat_trace_file(void *buf, size_t size)
+{
+	struct trace_graph_item *item = (struct trace_graph_item *)buf;
+	size_t sz = size / sizeof(struct trace_graph_item), i;
+
+	printf("   Function Name                    |  Time(ms)\n");
+	printf("--------------------------------------------------\n");
+	for (i = 0; i < sz; i++)
+		prepare_stat_tree(item++);
+	list_sort(NULL, &stat_list, stat_list_cmp);
+	stat_list_print();
+}
+
+static int graph_stat(int argc, char **argv)
+{
+	struct stat st;
+	void *map = map_trace_file(&st);
+
+	if (!map)
+		return EXIT_FAILURE;
+
+	stat_trace_file(map, st.st_size);
+	munmap(map, st.st_size);
+	return EXIT_SUCCESS;
+}
+
 static int trace_parser(int ch, char *opt)
 {
 	return 0;
@@ -234,6 +360,8 @@ static int trace_parser(int ch, char *opt)
 static struct subcommand graph_cmd[] = {
 	{"cat", NULL, NULL, "cat the output of graph tracer",
 	 NULL, 0, graph_cat},
+	{"stat", NULL, NULL, "get the stat of the graph calls",
+	 NULL, 0, graph_stat},
 	{NULL,},
 };
 
diff --git a/include/sheep.h b/include/sheep.h
index 295cb24..d6d57b6 100644
--- a/include/sheep.h
+++ b/include/sheep.h
@@ -47,8 +47,8 @@ struct trace_graph_item {
 	int type;
 	char fname[TRACE_FNAME_LEN];
 	int depth;
-	unsigned long long entry_time;
-	unsigned long long return_time;
+	uint64_t entry_time;
+	uint64_t return_time;
 };
 
 static inline void sd_init_req(struct sd_req *req, uint8_t opcode)
diff --git a/sheep/trace/graph.c b/sheep/trace/graph.c
index 33c6365..554668b 100644
--- a/sheep/trace/graph.c
+++ b/sheep/trace/graph.c
@@ -24,6 +24,7 @@ static void graph_tracer_exit(const struct caller *this_fn, int depth)
 		.return_time = clock_get_time(),
 	};
 
+	pstrcpy(trace.fname, sizeof(trace.fname), this_fn->name);
 	get_thread_name(trace.tname);
 
 	trace_buffer_push(sched_getcpu(), &trace);
-- 
1.7.9.5




More information about the sheepdog mailing list