I have found out a space to improve a delay feature of trace output
format as playing with function_graph. This patchset deals with delay
of 7-digit number and introduction of two additional delay marks.
All works are based on the following repository with ARM64 platform.
git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git perf/core
Any feedbacks are always welcome. Thanks in advance!
Best Regards
Jungseok Lee
Jungseok Lee (2):
tracing: Fix function graph duration format for 7-digit number
tracing: Introduce two additional marks for delay
Documentation/trace/ftrace.txt | 51 ++++++++++++----
kernel/trace/trace_functions_graph.c | 2 +
kernel/trace/trace_output.c | 4 +-
3 files changed, 43 insertions(+), 14 deletions(-)
--
1.9.1
Currently, row's width of 7-digit duration numbers not aligned with
other cases like the following example.
3) $ 3999884 us | }
3) | finish_task_switch() {
3) 0.365 us | _raw_spin_unlock_irq();
3) 3.333 us | }
3) $ 3999976 us | }
3) $ 3999979 us | } /* schedule */
As adding a single white space in case of 7-digit numbers, the format
could be unified easily as follows.
3) $ 2237472 us | }
3) | finish_task_switch() {
3) 0.364 us | _raw_spin_unlock_irq();
3) 3.125 us | }
3) $ 2237556 us | }
3) $ 2237559 us | } /* schedule */
Signed-off-by: Jungseok Lee <[email protected]>
---
kernel/trace/trace_functions_graph.c | 2 ++
1 file changed, 2 insertions(+)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 8968bf7..0bc16c4 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -716,6 +716,8 @@ trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
snprintf(nsecs_str, slen, "%03lu", nsecs_rem);
trace_seq_printf(s, ".%s", nsecs_str);
len += strlen(nsecs_str);
+ } else if (len == 7) {
+ len -= 1;
}
trace_seq_puts(s, " us ");
--
1.9.1
A fine granulity support for delay would be very useful when profiling
VM logics, such as page allocation including page reclaim and memory
compaction with function graph.
Thus, this patch adds two additional marks with two changes.
- An equal sign in mark selection function is removed to align code
behavior with comments and documentation.
- The function graph example related to delay in ftrace.txt is updated
to cover all supported marks.
Cc: Byungchul Park <[email protected]>
Signed-off-by: Jungseok Lee <[email protected]>
---
Documentation/trace/ftrace.txt | 51 ++++++++++++++++------
kernel/trace/trace_output.c | 4 +-
2 files changed, 41 insertions(+), 14 deletions(-)
diff --git a/Documentation/trace/ftrace.txt b/Documentation/trace/ftrace.txt
index 7ddb1e3..072d3c4 100644
--- a/Documentation/trace/ftrace.txt
+++ b/Documentation/trace/ftrace.txt
@@ -686,6 +686,8 @@ The above is mostly meaningful for kernel developers.
The marks are determined by the difference between this
current trace and the next trace.
'$' - greater than 1 second
+ '@' - greater than 100 milisecond
+ '*' - greater than 10 milisecond
'#' - greater than 1000 microsecond
'!' - greater than 100 microsecond
'+' - greater than 10 microsecond
@@ -1939,26 +1941,49 @@ want, depending on your needs.
ie:
- 0) | up_write() {
- 0) 0.646 us | _spin_lock_irqsave();
- 0) 0.684 us | _spin_unlock_irqrestore();
- 0) 3.123 us | }
- 0) 0.548 us | fput();
- 0) + 58.628 us | }
+ 3) # 1837.709 us | } /* __switch_to */
+ 3) | finish_task_switch() {
+ 3) 0.313 us | _raw_spin_unlock_irq();
+ 3) 3.177 us | }
+ 3) # 1889.063 us | } /* __schedule */
+ 3) ! 140.417 us | } /* __schedule */
+ 3) # 2034.948 us | } /* schedule */
+ 3) * 33998.59 us | } /* schedule_preempt_disabled */
[...]
- 0) | putname() {
- 0) | kmem_cache_free() {
- 0) 0.518 us | __phys_addr();
- 0) 1.757 us | }
- 0) 2.861 us | }
- 0) ! 115.305 us | }
- 0) ! 116.402 us | }
+ 1) 0.260 us | msecs_to_jiffies();
+ 1) 0.313 us | __rcu_read_unlock();
+ 1) + 61.770 us | }
+ 1) + 64.479 us | }
+ 1) 0.313 us | rcu_bh_qs();
+ 1) 0.313 us | __local_bh_enable();
+ 1) ! 217.240 us | }
+ 1) 0.365 us | idle_cpu();
+ 1) | rcu_irq_exit() {
+ 1) 0.417 us | rcu_eqs_enter_common.isra.47();
+ 1) 3.125 us | }
+ 1) ! 227.812 us | }
+ 1) ! 457.395 us | }
+ 1) @ 119760.2 us | }
+
+ [...]
+
+ 2) | handle_IPI() {
+ 1) 6.979 us | }
+ 2) 0.417 us | scheduler_ipi();
+ 1) 9.791 us | }
+ 1) + 12.917 us | }
+ 2) 3.490 us | }
+ 1) + 15.729 us | }
+ 1) + 18.542 us | }
+ 2) $ 3594274 us | }
+ means that the function exceeded 10 usecs.
! means that the function exceeded 100 usecs.
# means that the function exceeded 1000 usecs.
+ * means that the function exceeded 10 msecs.
+ @ means that the function exceeded 100 msecs.
$ means that the function exceeded 1 sec.
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index dfab253..8e481a8 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -496,6 +496,8 @@ static const struct trace_mark {
char sym;
} mark[] = {
MARK(1000000000ULL , '$'), /* 1 sec */
+ MARK(100000000ULL , '@'), /* 100 msec */
+ MARK(10000000ULL , '*'), /* 10 msec */
MARK(1000000ULL , '#'), /* 1000 usecs */
MARK(100000ULL , '!'), /* 100 usecs */
MARK(10000ULL , '+'), /* 10 usecs */
@@ -508,7 +510,7 @@ char trace_find_mark(unsigned long long d)
int size = ARRAY_SIZE(mark);
for (i = 0; i < size; i++) {
- if (d >= mark[i].val)
+ if (d > mark[i].val)
break;
}
--
1.9.1
On Sat, 11 Jul 2015 14:51:39 +0000
Jungseok Lee <[email protected]> wrote:
> diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> index 8968bf7..0bc16c4 100644
> --- a/kernel/trace/trace_functions_graph.c
> +++ b/kernel/trace/trace_functions_graph.c
> @@ -716,6 +716,8 @@ trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
> snprintf(nsecs_str, slen, "%03lu", nsecs_rem);
> trace_seq_printf(s, ".%s", nsecs_str);
> len += strlen(nsecs_str);
> + } else if (len == 7) {
> + len -= 1;
Don't you mean len--;
> }
>
> trace_seq_puts(s, " us ");
I don't care much for an extra branch here. I'm going to go with the
following patch:
-- Steve
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 8968bf720c12..ca98445782ac 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -715,13 +715,13 @@ trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
snprintf(nsecs_str, slen, "%03lu", nsecs_rem);
trace_seq_printf(s, ".%s", nsecs_str);
- len += strlen(nsecs_str);
+ len += strlen(nsecs_str) + 1;
}
trace_seq_puts(s, " us ");
/* Print remaining spaces to fit the row's width */
- for (i = len; i < 7; i++)
+ for (i = len; i < 8; i++)
trace_seq_putc(s, ' ');
}
On Jul 17, 2015, at 10:44 AM, Steven Rostedt wrote:
Hi, Steve
Thanks for caring about this!
> On Sat, 11 Jul 2015 14:51:39 +0000
> Jungseok Lee <[email protected]> wrote:
>
>> diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
>> index 8968bf7..0bc16c4 100644
>> --- a/kernel/trace/trace_functions_graph.c
>> +++ b/kernel/trace/trace_functions_graph.c
>> @@ -716,6 +716,8 @@ trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
>> snprintf(nsecs_str, slen, "%03lu", nsecs_rem);
>> trace_seq_printf(s, ".%s", nsecs_str);
>> len += strlen(nsecs_str);
>> + } else if (len == 7) {
>> + len -= 1;
>
> Don't you mean len--;
You're right.
>> }
>>
>> trace_seq_puts(s, " us ");
>
> I don't care much for an extra branch here. I'm going to go with the
> following patch:
>
> -- Steve
>
> diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> index 8968bf720c12..ca98445782ac 100644
> --- a/kernel/trace/trace_functions_graph.c
> +++ b/kernel/trace/trace_functions_graph.c
> @@ -715,13 +715,13 @@ trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
>
> snprintf(nsecs_str, slen, "%03lu", nsecs_rem);
> trace_seq_printf(s, ".%s", nsecs_str);
> - len += strlen(nsecs_str);
> + len += strlen(nsecs_str) + 1;
> }
>
> trace_seq_puts(s, " us ");
>
> /* Print remaining spaces to fit the row's width */
> - for (i = len; i < 7; i++)
> + for (i = len; i < 8; i++)
> trace_seq_putc(s, ' ');
> }
This change is better than my approach. As expected, it works well.
Best Regards
Jungseok Lee-
On Jul 11, 2015, at 11:51 PM, Jungseok Lee wrote:
> A fine granulity support for delay would be very useful when profiling
> VM logics, such as page allocation including page reclaim and memory
> compaction with function graph.
>
> Thus, this patch adds two additional marks with two changes.
>
> - An equal sign in mark selection function is removed to align code
> behavior with comments and documentation.
>
> - The function graph example related to delay in ftrace.txt is updated
> to cover all supported marks.
>
> Cc: Byungchul Park <[email protected]>
> Signed-off-by: Jungseok Lee <[email protected]>
> ---
> Documentation/trace/ftrace.txt | 51 ++++++++++++++++------
> kernel/trace/trace_output.c | 4 +-
> 2 files changed, 41 insertions(+), 14 deletions(-)
>
> diff --git a/Documentation/trace/ftrace.txt b/Documentation/trace/ftrace.txt
> index 7ddb1e3..072d3c4 100644
> --- a/Documentation/trace/ftrace.txt
> +++ b/Documentation/trace/ftrace.txt
> @@ -686,6 +686,8 @@ The above is mostly meaningful for kernel developers.
> The marks are determined by the difference between this
> current trace and the next trace.
> '$' - greater than 1 second
> + '@' - greater than 100 milisecond
> + '*' - greater than 10 milisecond
> '#' - greater than 1000 microsecond
> '!' - greater than 100 microsecond
> '+' - greater than 10 microsecond
> @@ -1939,26 +1941,49 @@ want, depending on your needs.
>
> ie:
>
> - 0) | up_write() {
> - 0) 0.646 us | _spin_lock_irqsave();
> - 0) 0.684 us | _spin_unlock_irqrestore();
> - 0) 3.123 us | }
> - 0) 0.548 us | fput();
> - 0) + 58.628 us | }
> + 3) # 1837.709 us | } /* __switch_to */
> + 3) | finish_task_switch() {
> + 3) 0.313 us | _raw_spin_unlock_irq();
> + 3) 3.177 us | }
> + 3) # 1889.063 us | } /* __schedule */
> + 3) ! 140.417 us | } /* __schedule */
> + 3) # 2034.948 us | } /* schedule */
> + 3) * 33998.59 us | } /* schedule_preempt_disabled */
>
> [...]
>
> - 0) | putname() {
> - 0) | kmem_cache_free() {
> - 0) 0.518 us | __phys_addr();
> - 0) 1.757 us | }
> - 0) 2.861 us | }
> - 0) ! 115.305 us | }
> - 0) ! 116.402 us | }
> + 1) 0.260 us | msecs_to_jiffies();
> + 1) 0.313 us | __rcu_read_unlock();
> + 1) + 61.770 us | }
> + 1) + 64.479 us | }
> + 1) 0.313 us | rcu_bh_qs();
> + 1) 0.313 us | __local_bh_enable();
> + 1) ! 217.240 us | }
> + 1) 0.365 us | idle_cpu();
> + 1) | rcu_irq_exit() {
> + 1) 0.417 us | rcu_eqs_enter_common.isra.47();
> + 1) 3.125 us | }
> + 1) ! 227.812 us | }
> + 1) ! 457.395 us | }
> + 1) @ 119760.2 us | }
> +
> + [...]
> +
> + 2) | handle_IPI() {
> + 1) 6.979 us | }
> + 2) 0.417 us | scheduler_ipi();
> + 1) 9.791 us | }
> + 1) + 12.917 us | }
> + 2) 3.490 us | }
> + 1) + 15.729 us | }
> + 1) + 18.542 us | }
> + 2) $ 3594274 us | }
>
> + means that the function exceeded 10 usecs.
> ! means that the function exceeded 100 usecs.
> # means that the function exceeded 1000 usecs.
> + * means that the function exceeded 10 msecs.
> + @ means that the function exceeded 100 msecs.
> $ means that the function exceeded 1 sec.
>
>
> diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
> index dfab253..8e481a8 100644
> --- a/kernel/trace/trace_output.c
> +++ b/kernel/trace/trace_output.c
> @@ -496,6 +496,8 @@ static const struct trace_mark {
> char sym;
> } mark[] = {
> MARK(1000000000ULL , '$'), /* 1 sec */
> + MARK(100000000ULL , '@'), /* 100 msec */
> + MARK(10000000ULL , '*'), /* 10 msec */
Hi, Steve,
Recently, I've noticed that there is a minor, not logical, flaw in the
above hunk as reviewing patches which do not get any signals yet. It is
a lack of 's' in msec in comment. That is, my latest one is as follows.
+ MARK(100000000ULL , '@'), /* 100 msecs */
+ MARK(10000000ULL , '*'), /* 10 msecs */
I know it's definitely trivial, but I've updated it to align with other
comments and planned to resend the patch. Surprisingly, this patch
has been already staged on your repo. So, I leave a whole patch again
including your SOB since I don't know how to handle this.
Thanks you for reviewing my patch!
Best Regards
Jungseok Lee
----8<-----
>From b431680d4c94a8b54db8b297f8e93329857dc191 Mon Sep 17 00:00:00 2001
From: Jungseok Lee <[email protected]>
Date: Sat, 11 Jul 2015 14:51:40 +0000
Subject: [PATCH] tracing: Introduce two additional marks for delay
A fine granulity support for delay would be very useful when profiling
VM logics, such as page allocation including page reclaim and memory
compaction, with function graph.
Thus, this patch adds two additional marks with two changes.
- An equal sign in mark selection function is removed to align code
behavior with comments and documentation.
- The function graph example related to delay in ftrace.txt is updated
to cover all supported marks.
Link: http://lkml.kernel.org/r/[email protected]
Cc: Byungchul Park <[email protected]>
Signed-off-by: Jungseok Lee <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
---
Documentation/trace/ftrace.txt | 51 +++++++++++++++++++++++++++++++-----------
kernel/trace/trace_output.c | 4 +++-
2 files changed, 41 insertions(+), 14 deletions(-)
diff --git a/Documentation/trace/ftrace.txt b/Documentation/trace/ftrace.txt
index 572ca92..eaa8473 100644
--- a/Documentation/trace/ftrace.txt
+++ b/Documentation/trace/ftrace.txt
@@ -686,6 +686,8 @@ The above is mostly meaningful for kernel developers.
The marks are determined by the difference between this
current trace and the next trace.
'$' - greater than 1 second
+ '@' - greater than 100 milisecond
+ '*' - greater than 10 milisecond
'#' - greater than 1000 microsecond
'!' - greater than 100 microsecond
'+' - greater than 10 microsecond
@@ -1939,26 +1941,49 @@ want, depending on your needs.
ie:
- 0) | up_write() {
- 0) 0.646 us | _spin_lock_irqsave();
- 0) 0.684 us | _spin_unlock_irqrestore();
- 0) 3.123 us | }
- 0) 0.548 us | fput();
- 0) + 58.628 us | }
+ 3) # 1837.709 us | } /* __switch_to */
+ 3) | finish_task_switch() {
+ 3) 0.313 us | _raw_spin_unlock_irq();
+ 3) 3.177 us | }
+ 3) # 1889.063 us | } /* __schedule */
+ 3) ! 140.417 us | } /* __schedule */
+ 3) # 2034.948 us | } /* schedule */
+ 3) * 33998.59 us | } /* schedule_preempt_disabled */
[...]
- 0) | putname() {
- 0) | kmem_cache_free() {
- 0) 0.518 us | __phys_addr();
- 0) 1.757 us | }
- 0) 2.861 us | }
- 0) ! 115.305 us | }
- 0) ! 116.402 us | }
+ 1) 0.260 us | msecs_to_jiffies();
+ 1) 0.313 us | __rcu_read_unlock();
+ 1) + 61.770 us | }
+ 1) + 64.479 us | }
+ 1) 0.313 us | rcu_bh_qs();
+ 1) 0.313 us | __local_bh_enable();
+ 1) ! 217.240 us | }
+ 1) 0.365 us | idle_cpu();
+ 1) | rcu_irq_exit() {
+ 1) 0.417 us | rcu_eqs_enter_common.isra.47();
+ 1) 3.125 us | }
+ 1) ! 227.812 us | }
+ 1) ! 457.395 us | }
+ 1) @ 119760.2 us | }
+
+ [...]
+
+ 2) | handle_IPI() {
+ 1) 6.979 us | }
+ 2) 0.417 us | scheduler_ipi();
+ 1) 9.791 us | }
+ 1) + 12.917 us | }
+ 2) 3.490 us | }
+ 1) + 15.729 us | }
+ 1) + 18.542 us | }
+ 2) $ 3594274 us | }
+ means that the function exceeded 10 usecs.
! means that the function exceeded 100 usecs.
# means that the function exceeded 1000 usecs.
+ * means that the function exceeded 10 msecs.
+ @ means that the function exceeded 100 msecs.
$ means that the function exceeded 1 sec.
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index 25a086b..46ce046 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -496,6 +496,8 @@ static const struct trace_mark {
char sym;
} mark[] = {
MARK(1000000000ULL , '$'), /* 1 sec */
+ MARK(100000000ULL , '@'), /* 100 msecs */
+ MARK(10000000ULL , '*'), /* 10 msecs */
MARK(1000000ULL , '#'), /* 1000 usecs */
MARK(100000ULL , '!'), /* 100 usecs */
MARK(10000ULL , '+'), /* 10 usecs */
@@ -508,7 +510,7 @@ char trace_find_mark(unsigned long long d)
int size = ARRAY_SIZE(mark);
for (i = 0; i < size; i++) {
- if (d >= mark[i].val)
+ if (d > mark[i].val)
break;
}
--
1.9.1
On Tue, 21 Jul 2015 23:56:31 +0900
Jungseok Lee <[email protected]> wrote:
> Recently, I've noticed that there is a minor, not logical, flaw in the
> above hunk as reviewing patches which do not get any signals yet. It is
> a lack of 's' in msec in comment. That is, my latest one is as follows.
>
> + MARK(100000000ULL , '@'), /* 100 msecs */
> + MARK(10000000ULL , '*'), /* 10 msecs */
>
> I know it's definitely trivial, but I've updated it to align with other
> comments and planned to resend the patch. Surprisingly, this patch
> has been already staged on your repo. So, I leave a whole patch again
> including your SOB since I don't know how to handle this.
>
> Thanks you for reviewing my patch!
The original is in the process of going through my tests. I waited till
rc3 to come out to rebase all my work on it (including this patch) and
restated testing again. I tripped on some things that are still buggy
in -rc3 (which delays the finishing of my testing).
As it is in the testing phase, I wont be modifying it. If you want,
just send another patch on top of my ftrace/core branch, and I can add
that to my queue too.
-- Steve
On Jul 22, 2015, at 12:09 AM, Steven Rostedt wrote:
> On Tue, 21 Jul 2015 23:56:31 +0900
> Jungseok Lee <[email protected]> wrote:
>
>
>
>> Recently, I've noticed that there is a minor, not logical, flaw in the
>> above hunk as reviewing patches which do not get any signals yet. It is
>> a lack of 's' in msec in comment. That is, my latest one is as follows.
>>
>> + MARK(100000000ULL , '@'), /* 100 msecs */
>> + MARK(10000000ULL , '*'), /* 10 msecs */
>>
>> I know it's definitely trivial, but I've updated it to align with other
>> comments and planned to resend the patch. Surprisingly, this patch
>> has been already staged on your repo. So, I leave a whole patch again
>> including your SOB since I don't know how to handle this.
>>
>> Thanks you for reviewing my patch!
>
> The original is in the process of going through my tests. I waited till
> rc3 to come out to rebase all my work on it (including this patch) and
> restated testing again. I tripped on some things that are still buggy
> in -rc3 (which delays the finishing of my testing).
>
> As it is in the testing phase, I wont be modifying it. If you want,
> just send another patch on top of my ftrace/core branch, and I can add
> that to my queue too.
Thanks for a kind explanation.
I think it is not needed to create another patch for only this change.
Best Regards
Jungseok Lee