When profiling large applications that have multiple children we really want to
see the profile of the app all together. Add a --by-comm option to accomplish
this for profile. This merges all the events for like comms into one big chunk
so we can easily see what a giant app is doing, such as HHVM. Thanks,
Signed-off-by: Josef Bacik <[email protected]>
---
V1->V2:
-renamed the option to --by-comm, added it to trace-cmd report --profile as well
-fixed up the string hash
-changed it to merge all events after the fact so it's less error prone
trace-hash-local.h | 9 ++
trace-local.h | 1 +
trace-profile.c | 302 ++++++++++++++++++++++++++++++++++++++++++++++++++++-
trace-read.c | 5 +
trace-record.c | 5 +
trace-usage.c | 3 +-
6 files changed, 319 insertions(+), 6 deletions(-)
diff --git a/trace-hash-local.h b/trace-hash-local.h
index 997b11c..eaeeaaf 100644
--- a/trace-hash-local.h
+++ b/trace-hash-local.h
@@ -48,4 +48,13 @@ static inline unsigned int trace_hash(int val)
return hash;
}
+static inline unsigned int trace_hash_str(char *str)
+{
+ int val = 0;
+ int i;
+
+ for (i = 0; str[i]; i++)
+ val += ((int)str[i]) << (i & 0xffffff);
+ return trace_hash(val);
+}
#endif /* _TRACE_HASH_LOCAL_H */
diff --git a/trace-local.h b/trace-local.h
index ab2bd34..d9a4fac 100644
--- a/trace-local.h
+++ b/trace-local.h
@@ -81,6 +81,7 @@ int trace_profile_record(struct tracecmd_input *handle,
void trace_init_profile(struct tracecmd_input *handle, struct hook_list *hooks,
int global);
int trace_profile(void);
+void trace_profile_set_merge_like_comms(void);
struct tracecmd_input *
trace_stream_init(struct buffer_instance *instance, int cpu, int fd, int cpus,
diff --git a/trace-profile.c b/trace-profile.c
index f71a7c6..74d6253 100644
--- a/trace-profile.c
+++ b/trace-profile.c
@@ -34,6 +34,7 @@
#define start_from_item(item) container_of(item, struct start_data, hash)
#define event_from_item(item) container_of(item, struct event_hash, hash)
#define stack_from_item(item) container_of(item, struct stack_data, hash)
+#define group_from_item(item) container_of(item, struct group_data, hash)
#define event_data_from_item(item) container_of(item, struct event_data, hash)
static unsigned long long nsecs_per_sec(unsigned long long ts)
@@ -141,6 +142,12 @@ struct event_hash {
struct trace_hash stacks;
};
+struct group_data {
+ struct trace_hash_item hash;
+ char *comm;
+ struct trace_hash event_hash;
+};
+
struct task_data {
struct trace_hash_item hash;
int pid;
@@ -156,6 +163,7 @@ struct task_data {
struct event_hash *last_event;
struct pevent_record *last_stack;
struct handle_data *handle;
+ struct group_data *group;
};
struct cpu_info {
@@ -173,6 +181,7 @@ struct handle_data {
struct pevent *pevent;
struct trace_hash events;
+ struct trace_hash group_hash;
struct cpu_info **cpu_data;
@@ -196,6 +205,12 @@ struct handle_data {
static struct handle_data *handles;
static struct event_data *stacktrace_event;
+static bool merge_like_comms = false;
+
+void trace_profile_set_merge_like_comms(void)
+{
+ merge_like_comms = true;
+}
static struct start_data *
add_start(struct task_data *task,
@@ -496,6 +511,14 @@ find_task(struct handle_data *h, int pid)
return last_task;
}
+static int match_group(struct trace_hash_item *item, void *data)
+{
+ struct group_data *group = group_from_item(item);
+
+ return strcmp(group->comm, (char *)data) == 0;
+}
+
+
static void
add_task_comm(struct task_data *task, struct format_field *field,
struct pevent_record *record)
@@ -1196,6 +1219,7 @@ void trace_init_profile(struct tracecmd_input *handle, struct hook_list *hook,
trace_hash_init(&h->task_hash, 1024);
trace_hash_init(&h->events, 1024);
+ trace_hash_init(&h->group_hash, 512);
h->handle = handle;
h->pevent = pevent;
@@ -1874,6 +1898,9 @@ static void output_task(struct handle_data *h, struct task_data *task)
int nr_events = 0;
int i;
+ if (task->group)
+ return;
+
if (task->comm)
comm = task->comm;
else
@@ -1907,6 +1934,39 @@ static void output_task(struct handle_data *h, struct task_data *task)
free(events);
}
+static void output_group(struct handle_data *h, struct group_data *group)
+{
+ struct trace_hash_item **bucket;
+ struct trace_hash_item *item;
+ struct event_hash **events;
+ int nr_events = 0;
+ int i;
+
+ printf("\ngroup: %s\n", group->comm);
+
+ trace_hash_for_each_bucket(bucket, &group->event_hash) {
+ trace_hash_for_each_item(item, bucket) {
+ nr_events++;
+ }
+ }
+
+ events = malloc_or_die(sizeof(*events) * nr_events);
+
+ i = 0;
+ trace_hash_for_each_bucket(bucket, &group->event_hash) {
+ trace_hash_for_each_item(item, bucket) {
+ events[i++] = event_from_item(item);
+ }
+ }
+
+ qsort(events, nr_events, sizeof(*events), compare_events);
+
+ for (i = 0; i < nr_events; i++)
+ output_event(events[i]);
+
+ free(events);
+}
+
static int compare_tasks(const void *a, const void *b)
{
struct task_data * const *A = a;
@@ -1919,6 +1979,14 @@ static int compare_tasks(const void *a, const void *b)
return 0;
}
+static int compare_groups(const void *a, const void *b)
+{
+ const char *A = a;
+ const char *B = b;
+
+ return strcmp(A, B);
+}
+
static void free_event_hash(struct event_hash *event_hash)
{
struct trace_hash_item **bucket;
@@ -1976,6 +2044,25 @@ static void free_task(struct task_data *task)
free(task);
}
+static void free_group(struct group_data *group)
+{
+ struct trace_hash_item **bucket;
+ struct trace_hash_item *item;
+ struct event_hash *event_hash;
+
+ free(group->comm);
+
+ trace_hash_for_each_bucket(bucket, &group->event_hash) {
+ trace_hash_while_item(item, bucket) {
+ event_hash = event_from_item(item);
+ trace_hash_del(item);
+ free_event_hash(event_hash);
+ }
+ }
+ trace_hash_free(&group->event_hash);
+ free(group);
+}
+
static void show_global_task(struct handle_data *h,
struct task_data *task)
{
@@ -1985,7 +2072,7 @@ static void show_global_task(struct handle_data *h,
output_task(h, task);
}
-static void output_handle(struct handle_data *h)
+static void output_tasks(struct handle_data *h)
{
struct trace_hash_item **bucket;
struct trace_hash_item *item;
@@ -1993,10 +2080,6 @@ static void output_handle(struct handle_data *h)
int nr_tasks = 0;
int i;
- show_global_task(h, h->global_task);
- for (i = 0; i < h->cpus; i++)
- show_global_task(h, &h->global_percpu_tasks[i]);
-
trace_hash_for_each_bucket(bucket, &h->task_hash) {
trace_hash_for_each_item(item, bucket) {
nr_tasks++;
@@ -2024,11 +2107,220 @@ static void output_handle(struct handle_data *h)
free(tasks);
}
+static void output_groups(struct handle_data *h)
+{
+ struct trace_hash_item **bucket;
+ struct trace_hash_item *item;
+ struct group_data **groups;
+ int nr_groups = 0;
+ int i;
+
+ trace_hash_for_each_bucket(bucket, &h->group_hash) {
+ trace_hash_for_each_item(item, bucket) {
+ nr_groups++;
+ }
+ }
+
+ if (nr_groups == 0)
+ return;
+
+ groups = malloc_or_die(sizeof(*groups) * nr_groups);
+
+ nr_groups = 0;
+
+ trace_hash_for_each_bucket(bucket, &h->group_hash) {
+ trace_hash_while_item(item, bucket) {
+ groups[nr_groups++] = group_from_item(item);
+ trace_hash_del(item);
+ }
+ }
+
+ qsort(groups, nr_groups, sizeof(*groups), compare_groups);
+
+ for (i = 0; i < nr_groups; i++) {
+ output_group(h, groups[i]);
+ free_group(groups[i]);
+ }
+
+ free(groups);
+}
+
+static void output_handle(struct handle_data *h)
+{
+ int i;
+
+ show_global_task(h, h->global_task);
+ for (i = 0; i < h->cpus; i++)
+ show_global_task(h, &h->global_percpu_tasks[i]);
+
+ output_groups(h);
+ output_tasks(h);
+}
+
+static void merge_event_stack(struct event_hash *event,
+ struct stack_data *stack)
+{
+ struct stack_data *exist;
+ struct trace_hash_item *item;
+ struct stack_match match;
+
+ match.caller = stack->caller;
+ match.size = stack->size;
+ item = trace_hash_find(&event->stacks, stack->hash.key, match_stack,
+ &match);
+ if (!item) {
+ trace_hash_add(&event->stacks, &stack->hash);
+ return;
+ }
+ exist = stack_from_item(item);
+ exist->count += stack->count;
+ exist->time += stack->time;
+
+ if (exist->time_max < stack->time_max) {
+ exist->time_max = stack->time_max;
+ exist->ts_max = stack->ts_max;
+ }
+ if (exist->time_min > stack->time_min) {
+ exist->time_min = stack->time_min;
+ exist->ts_min = stack->ts_min;
+ }
+ free(stack);
+}
+
+static void merge_stacks(struct event_hash *exist, struct event_hash *event)
+{
+ struct stack_data *stack;
+ struct trace_hash_item *item;
+ struct trace_hash_item **bucket;
+
+ trace_hash_for_each_bucket(bucket, &event->stacks) {
+ trace_hash_while_item(item, bucket) {
+ stack = stack_from_item(item);
+ trace_hash_del(&stack->hash);
+ merge_event_stack(exist, stack);
+ }
+ }
+}
+
+/*
+ * We use the pid in some of the fields in the event data which isn't helpful
+ * when we're trying to merge things, so just pay attention to the event_data
+ * field.
+ */
+static int match_event_for_merge(struct trace_hash_item *item, void *data)
+{
+ struct event_data_match *edata = data;
+ struct event_hash *event = event_from_item(item);
+
+ return event->event_data == edata->event_data;
+}
+
+static void merge_event_into_group(struct group_data *group,
+ struct event_hash *event)
+{
+ struct event_hash *exist;
+ struct trace_hash_item *item;
+ struct event_data_match edata;
+ trace_hash_func match;
+ unsigned long long key;
+
+ if (event->event_data->type == EVENT_TYPE_WAKEUP) {
+ edata.event_data = event->event_data;
+ match = match_event_for_merge;
+ key = trace_hash((unsigned long)event->event_data);
+ } else {
+ edata.event_data = event->event_data;
+ edata.search_val = event->search_val;
+ edata.val = event->val;
+ key = event->hash.key;
+ match = match_event;
+ }
+
+ item = trace_hash_find(&group->event_hash, key, match, &edata);
+ if (!item) {
+ event->hash.key = key;
+ trace_hash_add(&group->event_hash, &event->hash);
+ return;
+ }
+
+ exist = event_from_item(item);
+ exist->count += event->count;
+ exist->time_total += event->time_total;
+
+ if (exist->time_max < event->time_max) {
+ exist->time_max = event->time_max;
+ exist->ts_max = event->ts_max;
+ }
+ if (exist->time_min > event->time_min) {
+ exist->time_min = event->time_min;
+ exist->ts_min = event->ts_min;
+ }
+
+ merge_stacks(exist, event);
+ free_event_hash(event);
+}
+
+static void add_group(struct handle_data *h, struct task_data *task)
+{
+ unsigned long long key;
+ struct trace_hash_item *item;
+ struct group_data *grp;
+ struct trace_hash_item **bucket;
+ void *data = task->comm;
+
+ if (!task->comm)
+ return;
+
+ key = trace_hash_str(task->comm);
+
+ item = trace_hash_find(&h->group_hash, key, match_group, data);
+ if (item) {
+ grp = group_from_item(item);
+ } else {
+ grp = malloc_or_die(sizeof(*grp));
+ memset(grp, 0, sizeof(*grp));
+
+ grp->comm = strdup(task->comm);
+ if (!grp->comm)
+ die("strdup");
+ grp->hash.key = key;
+ trace_hash_add(&h->group_hash, &grp->hash);
+ trace_hash_init(&grp->event_hash, 32);
+ }
+ task->group = grp;
+
+ trace_hash_for_each_bucket(bucket, &task->event_hash) {
+ trace_hash_while_item(item, bucket) {
+ struct event_hash *event_hash;
+
+ event_hash = event_from_item(item);
+ trace_hash_del(&event_hash->hash);
+ merge_event_into_group(grp, event_hash);
+ }
+ }
+}
+
+static void merge_tasks(struct handle_data *h)
+{
+ struct trace_hash_item **bucket;
+ struct trace_hash_item *item;
+
+ if (!merge_like_comms)
+ return;
+
+ trace_hash_for_each_bucket(bucket, &h->task_hash) {
+ trace_hash_for_each_item(item, bucket)
+ add_group(h, task_from_item(item));
+ }
+}
+
int trace_profile(void)
{
struct handle_data *h;
for (h = handles; h; h = h->next) {
+ if (merge_like_comms)
+ merge_tasks(h);
output_handle(h);
trace_hash_free(&h->task_hash);
}
diff --git a/trace-read.c b/trace-read.c
index 17636a7..f4dffd6 100644
--- a/trace-read.c
+++ b/trace-read.c
@@ -1274,6 +1274,7 @@ static void add_hook(const char *arg)
}
enum {
+ OPT_bycomm = 243,
OPT_uname = 244,
OPT_profile = 245,
OPT_event = 246,
@@ -1348,6 +1349,7 @@ void trace_report (int argc, char **argv)
{"boundary", no_argument, NULL, OPT_boundary},
{"profile", no_argument, NULL, OPT_profile},
{"uname", no_argument, NULL, OPT_uname},
+ {"by-comm", no_argument, NULL, OPT_bycomm},
{"help", no_argument, NULL, '?'},
{NULL, 0, NULL, 0}
};
@@ -1477,6 +1479,9 @@ void trace_report (int argc, char **argv)
case OPT_uname:
show_uname = 1;
break;
+ case OPT_bycomm:
+ trace_profile_set_merge_like_comms();
+ break;
default:
usage(argv);
}
diff --git a/trace-record.c b/trace-record.c
index 9874a12..102bfe1 100644
--- a/trace-record.c
+++ b/trace-record.c
@@ -3703,6 +3703,7 @@ static void add_hook(struct buffer_instance *instance, const char *arg)
}
enum {
+ OPT_bycomm = 250,
OPT_stderr = 251,
OPT_profile = 252,
OPT_nosplice = 253,
@@ -3871,6 +3872,7 @@ void trace_record (int argc, char **argv)
{"nosplice", no_argument, NULL, OPT_nosplice},
{"profile", no_argument, NULL, OPT_profile},
{"stderr", no_argument, NULL, OPT_stderr},
+ {"by-comm", no_argument, NULL, OPT_bycomm},
{"help", no_argument, NULL, '?'},
{NULL, 0, NULL, 0}
};
@@ -4102,6 +4104,9 @@ void trace_record (int argc, char **argv)
close(1);
dup2(2, 1);
break;
+ case OPT_bycomm:
+ trace_profile_set_merge_like_comms();
+ break;
default:
usage(argv);
}
diff --git a/trace-usage.c b/trace-usage.c
index 520b14b..bdd5727 100644
--- a/trace-usage.c
+++ b/trace-usage.c
@@ -48,6 +48,7 @@ static struct usage_help usage_help[] = {
" -B create sub buffer and folling events will be enabled here\n"
" -k do not reset the buffers after tracing.\n"
" -i do not fail if an event is not found\n"
+ " --by-comm used with --profile, merge events for related comms\n"
" --profile enable tracing options needed for report --profile\n"
" --func-stack perform a stack trace for function tracer\n"
" (use with caution)\n"
@@ -151,7 +152,7 @@ static struct usage_help usage_help[] = {
" -G when profiling, set soft and hard irqs as global\n"
" -H Allows users to hook two events together for timings\n"
" (used with --profile)\n"
-
+ " --by-comm used with --profile, merge events for related comms\n"
},
{
"stream",
--
2.1.0
On Thu, 21 May 2015 13:30:08 -0400
Josef Bacik <[email protected]> wrote:
> V1->V2:
> -renamed the option to --by-comm, added it to trace-cmd report --profile as well
> -fixed up the string hash
Or break it ;-)
> -changed it to merge all events after the fact so it's less error prone
> diff --git a/trace-hash-local.h b/trace-hash-local.h
> index 997b11c..eaeeaaf 100644
> --- a/trace-hash-local.h
> +++ b/trace-hash-local.h
> @@ -48,4 +48,13 @@ static inline unsigned int trace_hash(int val)
> return hash;
> }
>
> +static inline unsigned int trace_hash_str(char *str)
> +{
> + int val = 0;
> + int i;
> +
> + for (i = 0; str[i]; i++)
> + val += ((int)str[i]) << (i & 0xffffff);
> + return trace_hash(val);
> +}
>
I need to clean out my medicine cabinet and remove all the expired
meds. Because I was definitely taking something nasty when I
recommended (i & 0xffffff)!
When i is greater than 32 (which is less than 0xffffff) it will
overflow the addition. What I wanted was that we don't shift more than
24 bits. Where 2 ** 24 - 1 == 0xffffff.
That should be:
val += ((int)str[i]) << (i % 25);
my bad :-/
To avoid the slow '%', I'll just use '& 0xf', as shifting it 16 times is
enough for this algorithm.
No need to send a new patch, I'll fix it, as it was my brain
fart. I'll review the rest of this patch too and apply it if nothing
sticks out.
Thanks!
-- Steve
On Thu, 21 May 2015 13:30:08 -0400
Josef Bacik <[email protected]> wrote:
> +static int compare_groups(const void *a, const void *b)
> +{
> + const char *A = a;
> + const char *B = b;
> +
> + return strcmp(A, B);
a and b are not strings here. They are group_data pointers.
I think what you want is this:
static int compare_groups(const void *a, const void *b)
{
struct group_data * const *A = a;
struct group_data * const *B = b;
return strcmp((*A)->comm, (*B)->comm);
}
-- Steve
> +}
> +
>
> +static void output_groups(struct handle_data *h)
> +{
> + struct trace_hash_item **bucket;
> + struct trace_hash_item *item;
> + struct group_data **groups;
> + int nr_groups = 0;
> + int i;
> +
> + trace_hash_for_each_bucket(bucket, &h->group_hash) {
> + trace_hash_for_each_item(item, bucket) {
> + nr_groups++;
> + }
> + }
> +
> + if (nr_groups == 0)
> + return;
> +
> + groups = malloc_or_die(sizeof(*groups) * nr_groups);
> +
> + nr_groups = 0;
> +
> + trace_hash_for_each_bucket(bucket, &h->group_hash) {
> + trace_hash_while_item(item, bucket) {
> + groups[nr_groups++] = group_from_item(item);
> + trace_hash_del(item);
> + }
> + }
> +
> + qsort(groups, nr_groups, sizeof(*groups), compare_groups);
> +
> + for (i = 0; i < nr_groups; i++) {
> + output_group(h, groups[i]);
> + free_group(groups[i]);
> + }
> +
> + free(groups);
> +}
> +
>
On Thu, 21 May 2015 13:30:08 -0400
Josef Bacik <[email protected]> wrote:
> +static void merge_tasks(struct handle_data *h)
> +{
> + struct trace_hash_item **bucket;
> + struct trace_hash_item *item;
> +
> + if (!merge_like_comms)
> + return;
> +
> + trace_hash_for_each_bucket(bucket, &h->task_hash) {
> + trace_hash_for_each_item(item, bucket)
> + add_group(h, task_from_item(item));
> + }
> +}
> +
> int trace_profile(void)
> {
> struct handle_data *h;
>
> for (h = handles; h; h = h->next) {
> + if (merge_like_comms)
> + merge_tasks(h);
I don't think we need the double check. Here you only call
merge_tasks() if merge_like_comms is set, but then the first thing you
do in merge_tasks() is to return if merge_like_comms is not set. One
check is enough.
-- Steve
> output_handle(h);
> trace_hash_free(&h->task_hash);
> }