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

Liu Yuan namei.unix at gmail.com
Sat Aug 10 17:30:34 CEST 2013


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

$ collie trace graph stat
   Function Name                    | Call NR    | Total time(s)   | Time Per Call(us)
--------------------------------------------------------------------------------
eventfd_xread                       | 1964       | 110.817993      | 56424.640625
do_process_work                     | 1155       | 87.415054       | 75684.031250
do_push_object                      | 220        | 84.434906       | 383795.000000
push_cache_object                   | 220        | 84.426041       | 383754.718750
gateway_create_and_write_obj        | 403        | 82.382881       | 204424.015625
exec_local_req                      | 215        | 82.038292       | 381573.437500
gateway_forward_request             | 212        | 81.968315       | 386643.000000
event_loop                          | 5295       | 48.661499       | 9190.084961
do_event_loop                       | 5295       | 48.650993       | 9188.100586
xpwrite                             | 1012       | 38.091278       | 37639.601562
sheep_do_op_work                    | 77         | 36.608986       | 475441.375000
peer_create_and_write_obj           | 77         | 36.608803       | 475439.000000
default_create_and_write            | 77         | 36.607231       | 475418.562500
object_cache_push                   | 10         | 28.783995       | 2878399.500000
do_background_push                  | 9          | 27.332939       | 3036993.250000
local_release_vdi                   | 1          | 3.455209        | 3455209.000000
object_cache_flush_vdi              | 1          | 3.452806        | 3452806.000000
read_cache_object_noupdate          | 212        | 2.309551        | 10894.107422
xpread                              | 212        | 2.302798        | 10862.253906
object_cache_handle_request         | 935        | 1.942179        | 2077.196777
write_cache_object                  | 934        | 1.885499        | 2018.735229
write_cache_object_noupdate         | 934        | 1.613303        | 1727.305054
gateway_write_obj                   | 743        | 1.526443        | 2054.431641
client_handler                      | 2592       | 0.821204        | 316.822662
rx                                  | 2582       | 0.546757        | 211.757111
...

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

diff --git a/collie/trace.c b/collie/trace.c
index 18f062f..651fd6c 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,165 @@ 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;
+	uint32_t nr_calls;
+};
+
+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;
+			entry->nr_calls++;
+			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;
+	new->nr_calls = 1;
+	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) {
+		float f = (float)entry->duration / 1000000000;
+		float pf = (float)entry->duration / entry->nr_calls / 1000;
+
+		printf("%-*s| %-10"PRIu32" | %-16f| %-16f\n", TRACE_FNAME_LEN,
+		       entry->fname, entry->nr_calls, f, pf);
+	}
+}
+
+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                    | Call NR    | Total time(s)   | Time Per Call(us) \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 +363,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