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 |