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 |