2015-11-05 14:43:52

by Namhyung Kim

[permalink] [raw]
Subject: Re: [PATCH 00/28] tracing: 'hist' triggers

Hi Tom,

I implemented 'log2' modifier on top of your v11 patchset. Could you
please take a look at this?



>From 5fc74778b9af5e4e121a0563fb8e54e8f495ca29 Mon Sep 17 00:00:00 2001
From: Namhyung Kim <[email protected]>
Date: Thu, 5 Nov 2015 23:34:05 +0900
Subject: [PATCH] tracing: Add hist trigger 'log2' modifier

Allow users to have numeric fields displayed as log2 values in case
value range is very wide by appending '.log2' to field names.

For example,

# echo 'hist:key=bytes_req' > kmalloc/trigger
# cat kmalloc/hist

{ bytes_req: 504 } hitcount: 1
{ bytes_req: 11 } hitcount: 1
{ bytes_req: 104 } hitcount: 1
{ bytes_req: 48 } hitcount: 1
{ bytes_req: 2048 } hitcount: 1
{ bytes_req: 4096 } hitcount: 1
{ bytes_req: 240 } hitcount: 1
{ bytes_req: 392 } hitcount: 1
{ bytes_req: 13 } hitcount: 1
{ bytes_req: 28 } hitcount: 1
{ bytes_req: 12 } hitcount: 1
{ bytes_req: 64 } hitcount: 2
{ bytes_req: 128 } hitcount: 2
{ bytes_req: 32 } hitcount: 2
{ bytes_req: 8 } hitcount: 11
{ bytes_req: 10 } hitcount: 13
{ bytes_req: 24 } hitcount: 25
{ bytes_req: 160 } hitcount: 29
{ bytes_req: 16 } hitcount: 33
{ bytes_req: 80 } hitcount: 36

When using '.log2' modifier, the output looks like:

# echo 'hist:key=bytes_req.log2' > kmalloc/trigger
# cat kmalloc/hist

{ bytes_req: ~ 2^12 } hitcount: 1
{ bytes_req: ~ 2^11 } hitcount: 1
{ bytes_req: ~ 2^9 } hitcount: 2
{ bytes_req: ~ 2^6 } hitcount: 3
{ bytes_req: ~ 2^3 } hitcount: 13
{ bytes_req: ~ 2^5 } hitcount: 19
{ bytes_req: ~ 2^8 } hitcount: 49
{ bytes_req: ~ 2^7 } hitcount: 57
{ bytes_req: ~ 2^4 } hitcount: 74

Cc: Tom Zanussi <[email protected]>
Cc: Masami Hiramatsu <[email protected]>
Signed-off-by: Namhyung Kim <[email protected]>
---
kernel/trace/trace.c | 1 +
kernel/trace/trace_events_hist.c | 18 ++++++++++++++++++
2 files changed, 19 insertions(+)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 74f95745acbc..542486468707 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3837,6 +3837,7 @@ static const char readme_msg[] =
"\t .sym-offset display an address as a symbol and offset\n"
"\t .execname display a common_pid as a program name\n"
"\t .syscall display a syscall id as a syscall name\n\n"
+ "\t .log2 display log2 value rather than raw number\n\n"
"\t The 'pause' parameter can be used to pause an existing hist\n"
"\t trigger or to start a hist trigger but not log any events\n"
"\t until told to do so. 'continue' can be used to start or\n"
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index b040ebefcd64..20a17fdb3fe6 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -68,6 +68,13 @@ static u64 hist_field_pstring(struct hist_field *hist_field, void *event)
return (u64)(unsigned long)*addr;
}

+static u64 hist_field_log2(struct hist_field *hist_field, void *event)
+{
+ u64 val = *(u64 *)(event + hist_field->field->offset);
+
+ return (u64) ilog2(roundup_pow_of_two(val));
+}
+
#define DEFINE_HIST_FIELD_FN(type) \
static u64 hist_field_##type(struct hist_field *hist_field, void *event)\
{ \
@@ -103,6 +110,7 @@ enum hist_field_flags {
HIST_FIELD_EXECNAME = 64,
HIST_FIELD_SYSCALL = 128,
HIST_FIELD_STACKTRACE = 256,
+ HIST_FIELD_LOG2 = 512,
};

struct hist_trigger_attrs {
@@ -349,6 +357,11 @@ static struct hist_field *create_hist_field(struct ftrace_event_field *field,
goto out;
}

+ if (flags & HIST_FIELD_LOG2) {
+ hist_field->fn = hist_field_log2;
+ goto out;
+ }
+
if (is_string_field(field)) {
flags |= HIST_FIELD_STRING;

@@ -500,6 +513,8 @@ static int create_key_field(struct hist_trigger_data *hist_data,
flags |= HIST_FIELD_EXECNAME;
else if (!strcmp(field_str, "syscall"))
flags |= HIST_FIELD_SYSCALL;
+ else if (!strcmp(field_str, "log2"))
+ flags |= HIST_FIELD_LOG2;
else {
ret = -EINVAL;
goto out;
@@ -942,6 +957,9 @@ hist_trigger_entry_print(struct seq_file *m,
key + key_field->offset,
HIST_STACKTRACE_DEPTH);
multiline = true;
+ } else if (key_field->flags & HIST_FIELD_LOG2) {
+ seq_printf(m, "%s: ~ 2^%-2llu", key_field->field->name,
+ *(u64 *)(key + key_field->offset));
} else if (key_field->flags & HIST_FIELD_STRING) {
seq_printf(m, "%s: %-50s", key_field->field->name,
(char *)(key + key_field->offset));
--
2.6.2


Subject: RE: [PATCH 00/28] tracing: 'hist' triggers

From: Namhyung Kim [mailto:[email protected]] On Behalf Of Namhyung Kim
>
>Hi Tom,
>
>I implemented 'log2' modifier on top of your v11 patchset. Could you
>please take a look at this?

Ah, this seems very useful :)

Reviewed-by: Masami Hiramatsu <[email protected]>

--
Masami

>
>
>
>From 5fc74778b9af5e4e121a0563fb8e54e8f495ca29 Mon Sep 17 00:00:00 2001
>From: Namhyung Kim <[email protected]>
>Date: Thu, 5 Nov 2015 23:34:05 +0900
>Subject: [PATCH] tracing: Add hist trigger 'log2' modifier
>
>Allow users to have numeric fields displayed as log2 values in case
>value range is very wide by appending '.log2' to field names.
>
>For example,
>
> # echo 'hist:key=bytes_req' > kmalloc/trigger
> # cat kmalloc/hist
>
> { bytes_req: 504 } hitcount: 1
> { bytes_req: 11 } hitcount: 1
> { bytes_req: 104 } hitcount: 1
> { bytes_req: 48 } hitcount: 1
> { bytes_req: 2048 } hitcount: 1
> { bytes_req: 4096 } hitcount: 1
> { bytes_req: 240 } hitcount: 1
> { bytes_req: 392 } hitcount: 1
> { bytes_req: 13 } hitcount: 1
> { bytes_req: 28 } hitcount: 1
> { bytes_req: 12 } hitcount: 1
> { bytes_req: 64 } hitcount: 2
> { bytes_req: 128 } hitcount: 2
> { bytes_req: 32 } hitcount: 2
> { bytes_req: 8 } hitcount: 11
> { bytes_req: 10 } hitcount: 13
> { bytes_req: 24 } hitcount: 25
> { bytes_req: 160 } hitcount: 29
> { bytes_req: 16 } hitcount: 33
> { bytes_req: 80 } hitcount: 36
>
>When using '.log2' modifier, the output looks like:
>
> # echo 'hist:key=bytes_req.log2' > kmalloc/trigger
> # cat kmalloc/hist
>
> { bytes_req: ~ 2^12 } hitcount: 1
> { bytes_req: ~ 2^11 } hitcount: 1
> { bytes_req: ~ 2^9 } hitcount: 2
> { bytes_req: ~ 2^6 } hitcount: 3
> { bytes_req: ~ 2^3 } hitcount: 13
> { bytes_req: ~ 2^5 } hitcount: 19
> { bytes_req: ~ 2^8 } hitcount: 49
> { bytes_req: ~ 2^7 } hitcount: 57
> { bytes_req: ~ 2^4 } hitcount: 74
>
>Cc: Tom Zanussi <[email protected]>
>Cc: Masami Hiramatsu <[email protected]>
>Signed-off-by: Namhyung Kim <[email protected]>
>---
> kernel/trace/trace.c | 1 +
> kernel/trace/trace_events_hist.c | 18 ++++++++++++++++++
> 2 files changed, 19 insertions(+)
>
>diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
>index 74f95745acbc..542486468707 100644
>--- a/kernel/trace/trace.c
>+++ b/kernel/trace/trace.c
>@@ -3837,6 +3837,7 @@ static const char readme_msg[] =
> "\t .sym-offset display an address as a symbol and offset\n"
> "\t .execname display a common_pid as a program name\n"
> "\t .syscall display a syscall id as a syscall name\n\n"
>+ "\t .log2 display log2 value rather than raw number\n\n"
> "\t The 'pause' parameter can be used to pause an existing hist\n"
> "\t trigger or to start a hist trigger but not log any events\n"
> "\t until told to do so. 'continue' can be used to start or\n"
>diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
>index b040ebefcd64..20a17fdb3fe6 100644
>--- a/kernel/trace/trace_events_hist.c
>+++ b/kernel/trace/trace_events_hist.c
>@@ -68,6 +68,13 @@ static u64 hist_field_pstring(struct hist_field *hist_field, void *event)
> return (u64)(unsigned long)*addr;
> }
>
>+static u64 hist_field_log2(struct hist_field *hist_field, void *event)
>+{
>+ u64 val = *(u64 *)(event + hist_field->field->offset);
>+
>+ return (u64) ilog2(roundup_pow_of_two(val));
>+}
>+
> #define DEFINE_HIST_FIELD_FN(type) \
> static u64 hist_field_##type(struct hist_field *hist_field, void *event)\
> { \
>@@ -103,6 +110,7 @@ enum hist_field_flags {
> HIST_FIELD_EXECNAME = 64,
> HIST_FIELD_SYSCALL = 128,
> HIST_FIELD_STACKTRACE = 256,
>+ HIST_FIELD_LOG2 = 512,
> };
>
> struct hist_trigger_attrs {
>@@ -349,6 +357,11 @@ static struct hist_field *create_hist_field(struct ftrace_event_field *field,
> goto out;
> }
>
>+ if (flags & HIST_FIELD_LOG2) {
>+ hist_field->fn = hist_field_log2;
>+ goto out;
>+ }
>+
> if (is_string_field(field)) {
> flags |= HIST_FIELD_STRING;
>
>@@ -500,6 +513,8 @@ static int create_key_field(struct hist_trigger_data *hist_data,
> flags |= HIST_FIELD_EXECNAME;
> else if (!strcmp(field_str, "syscall"))
> flags |= HIST_FIELD_SYSCALL;
>+ else if (!strcmp(field_str, "log2"))
>+ flags |= HIST_FIELD_LOG2;
> else {
> ret = -EINVAL;
> goto out;
>@@ -942,6 +957,9 @@ hist_trigger_entry_print(struct seq_file *m,
> key + key_field->offset,
> HIST_STACKTRACE_DEPTH);
> multiline = true;
>+ } else if (key_field->flags & HIST_FIELD_LOG2) {
>+ seq_printf(m, "%s: ~ 2^%-2llu", key_field->field->name,
>+ *(u64 *)(key + key_field->offset));
> } else if (key_field->flags & HIST_FIELD_STRING) {
> seq_printf(m, "%s: %-50s", key_field->field->name,
> (char *)(key + key_field->offset));
>--
>2.6.2

????{.n?+???????+%?????ݶ??w??{.n?+????{??G?????{ay?ʇڙ?,j??f???h?????????z_??(?階?ݢj"???m??????G????????????&???~???iO???z??v?^?m???? ????????I?

2015-11-05 22:13:06

by Tom Zanussi

[permalink] [raw]
Subject: Re: [PATCH 00/28] tracing: 'hist' triggers

Hi Namhyung,

On Thu, 2015-11-05 at 23:43 +0900, Namhyung Kim wrote:
> Hi Tom,
>
> I implemented 'log2' modifier on top of your v11 patchset. Could you
> please take a look at this?
>

Very nice, thanks for doing this.

I just noticed one small problem in that the modifier doesn't get
printed in the output. The below patch fixes that.

I can just merge that change into your patch and add it to my series,
otherwise please let me know what you'd like me to do..

Tom

Signed-off-by: Tom Zanussi <[email protected]>
---
kernel/trace/trace_events_hist.c | 2 ++
1 file changed, 2 insertions(+)

diff --git a/kernel/trace/trace_events_hist.c
b/kernel/trace/trace_events_hist.c
index 20a17fd..7621748 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -1092,6 +1092,8 @@ static const char *get_hist_field_flags(struct
hist_field *hist_field)
flags_str = "execname";
else if (hist_field->flags & HIST_FIELD_SYSCALL)
flags_str = "syscall";
+ else if (hist_field->flags & HIST_FIELD_LOG2)
+ flags_str = "log2";

return flags_str;
}


2015-11-05 23:18:08

by Namhyung Kim

[permalink] [raw]
Subject: Re: [PATCH 00/28] tracing: 'hist' triggers

On Thu, Nov 05, 2015 at 04:13:02PM -0600, Tom Zanussi wrote:
> Hi Namhyung,
>
> On Thu, 2015-11-05 at 23:43 +0900, Namhyung Kim wrote:
> > Hi Tom,
> >
> > I implemented 'log2' modifier on top of your v11 patchset. Could you
> > please take a look at this?
> >
>
> Very nice, thanks for doing this.
>
> I just noticed one small problem in that the modifier doesn't get
> printed in the output. The below patch fixes that.

Ah, thanks!

>
> I can just merge that change into your patch and add it to my series,
> otherwise please let me know what you'd like me to do..

It'd be great if you take this (with the fix) into your series.

Thanks,
Namhyung


>
> Signed-off-by: Tom Zanussi <[email protected]>
> ---
> kernel/trace/trace_events_hist.c | 2 ++
> 1 file changed, 2 insertions(+)
>
> diff --git a/kernel/trace/trace_events_hist.c
> b/kernel/trace/trace_events_hist.c
> index 20a17fd..7621748 100644
> --- a/kernel/trace/trace_events_hist.c
> +++ b/kernel/trace/trace_events_hist.c
> @@ -1092,6 +1092,8 @@ static const char *get_hist_field_flags(struct
> hist_field *hist_field)
> flags_str = "execname";
> else if (hist_field->flags & HIST_FIELD_SYSCALL)
> flags_str = "syscall";
> + else if (hist_field->flags & HIST_FIELD_LOG2)
> + flags_str = "log2";
>
> return flags_str;
> }
>
>
>