This is useful to get how much time each function takes during the trace.
$ collie trace graph stat
Total (s) Per Call (ms) Calls Name
100.659 51.356 1960 eventfd_xread
79.315 68.790 1153 do_process_work
76.645 348.388 220 do_push_object
76.637 348.349 220 push_cache_object
74.611 185.139 403 gateway_create_and_write_obj
74.338 345.757 215 exec_local_req
74.276 350.361 212 gateway_forward_request
35.555 34.722 1024 xpwrite
35.547 7.119 4993 event_loop
35.538 7.118 4993 do_event_loop
34.299 385.380 89 sheep_do_op_work
33.778 427.565 79 peer_create_and_write_obj
33.776 427.547 79 default_create_and_write
26.324 2632.399 10 object_cache_push
26.259 2917.706 9 do_background_push
2.525 2.701 935 object_cache_handle_request
...
Signed-off-by: Liu Yuan <namei.unix at gmail.com>
---
collie/trace.c | 153 ++++++++++++++++++++++++++++++++++++++++++++++-----
include/sheep.h | 4 +-
sheep/trace/graph.c | 1 +
3 files changed, 142 insertions(+), 16 deletions(-)
diff --git a/collie/trace.c b/collie/trace.c
index 18f062f..5e8fd59 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,159 @@ 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;
+ uint16_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 total = (float)entry->duration / 1000000000;
+ float per = (float)entry->duration / entry->nr_calls / 1000000;
+
+ printf("%10.3f %10.3f %5"PRIu16" %-*s\n", total, per,
+ entry->nr_calls, TRACE_FNAME_LEN, entry->fname);
+ }
+}
+
+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);
+ /* '-' is for reverse sort, largest first */
+ return -intcmp(ga->duration, gb->duration);
+}
+
+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(" Total (s) Per Call (ms) Calls Name\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 +357,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,},
};
@@ -250,8 +375,8 @@ static struct subcommand trace_cmd[] = {
CMD_NEED_ARG, trace_disable},
{"status", NULL, "aph", "show tracer statuses", NULL,
0, trace_status},
- {"graph", NULL, "aph", "cat the output of tracers if any", graph_cmd,
- CMD_NEED_ARG, trace_graph},
+ {"graph", NULL, "aph", "run collie trace graph for more information",
+ graph_cmd, CMD_NEED_ARG, trace_graph},
{NULL},
};
diff --git a/include/sheep.h b/include/sheep.h
index 7a98ce7..1d146bd 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
|
|