[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