Impact: fix time output bug in 32bits system
ns2usecs() returns 'long', it's incorrect.
(In i386)
# cat trace
...
<idle>-0 [000] 521.442100: _spin_lock <-tick_do_update_jiffies64
<idle>-0 [000] 521.442101: do_timer <-tick_do_update_jiffies64
<idle>-0 [000] 521.442102: update_wall_time <-do_timer
<idle>-0 [000] 521.442102: update_xtime_cache <-update_wall_time
....
(It always print the time less than 2200 seconds besides ...)
Because 'long' is 32bits in i386. ( (1<<31) useconds is about 2200 seconds)
# cat trace
...
<idle>-0 [001] 4154502640.134759: rcu_bh_qsctr_inc <-__do_softirq
<idle>-0 [001] 4154502640.134760: _local_bh_enable <-__do_softirq
<idle>-0 [001] 4154502640.134761: idle_cpu <-irq_exit
...
(very large value)
Because 'long' is a signed type and is 32bits in i386.
Signed-off-by: Lai Jiangshan <[email protected]>
Reported-by: Li Zefan <[email protected]>
Tested-by: Lai Jiangshan <[email protected]>
---
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 2a81dec..c048243 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -147,8 +147,7 @@ static int __init set_ftrace_dump_on_oops(char *str)
}
__setup("ftrace_dump_on_oops", set_ftrace_dump_on_oops);
-long
-ns2usecs(cycle_t nsec)
+cycle_t ns2usecs(cycle_t nsec)
{
nsec += 500;
do_div(nsec, 1000);
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index fec6521..ed78278 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -602,7 +602,7 @@ extern int trace_selftest_startup_branch(struct tracer *trace,
#endif /* CONFIG_FTRACE_STARTUP_TEST */
extern void *head_page(struct trace_array_cpu *data);
-extern long ns2usecs(cycle_t nsec);
+extern cycle_t ns2usecs(cycle_t nsec);
extern int
trace_vbprintk(unsigned long ip, const char *fmt, va_list args);
extern int
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index aeac358..0e70fb0 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -433,7 +433,7 @@ int trace_print_lat_context(struct trace_iterator *iter)
trace_find_cmdline(entry->pid, comm);
- ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08lx]"
+ ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08llx]"
" %ld.%03ldms (+%ld.%03ldms): ", comm,
entry->pid, iter->cpu, entry->flags,
entry->preempt_count, iter->idx,
Impact: fix time output bug in 32bits system
ns2usecs() returns 'long', it's incorrect.
(In i386)
# cat trace
...
<idle>-0 [000] 521.442100: _spin_lock <-tick_do_update_jiffies64
<idle>-0 [000] 521.442101: do_timer <-tick_do_update_jiffies64
<idle>-0 [000] 521.442102: update_wall_time <-do_timer
<idle>-0 [000] 521.442102: update_xtime_cache <-update_wall_time
....
(It always print the time less than 2200 seconds besides ...)
Because 'long' is 32bits in i386. ( (1<<31) useconds is about 2200 seconds)
# cat trace
...
<idle>-0 [001] 4154502640.134759: rcu_bh_qsctr_inc <-__do_softirq
<idle>-0 [001] 4154502640.134760: _local_bh_enable <-__do_softirq
<idle>-0 [001] 4154502640.134761: idle_cpu <-irq_exit
...
(very large value)
Because 'long' is a signed type and it is 32bits in i386.
Changed from V1:
return 'unsigned long long' instead of 'cycle_t'
Signed-off-by: Lai Jiangshan <[email protected]>
Reported-by: Li Zefan <[email protected]>
---
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 2a81dec..5232201 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -147,8 +147,7 @@ static int __init set_ftrace_dump_on_oops(char *str)
}
__setup("ftrace_dump_on_oops", set_ftrace_dump_on_oops);
-long
-ns2usecs(cycle_t nsec)
+unsigned long long ns2usecs(cycle_t nsec)
{
nsec += 500;
do_div(nsec, 1000);
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index fec6521..47aa6d0 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -602,7 +602,7 @@ extern int trace_selftest_startup_branch(struct tracer *trace,
#endif /* CONFIG_FTRACE_STARTUP_TEST */
extern void *head_page(struct trace_array_cpu *data);
-extern long ns2usecs(cycle_t nsec);
+extern unsigned long long ns2usecs(cycle_t nsec);
extern int
trace_vbprintk(unsigned long ip, const char *fmt, va_list args);
extern int
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index aeac358..0e70fb0 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -433,7 +433,7 @@ int trace_print_lat_context(struct trace_iterator *iter)
trace_find_cmdline(entry->pid, comm);
- ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08lx]"
+ ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08llx]"
" %ld.%03ldms (+%ld.%03ldms): ", comm,
entry->pid, iter->cpu, entry->flags,
entry->preempt_count, iter->idx,
On Mon, Mar 30, 2009 at 11:52:13AM +0800, Lai Jiangshan wrote:
>
> Impact: fix time output bug in 32bits system
>
> ns2usecs() returns 'long', it's incorrect.
>
> (In i386)
> # cat trace
> ...
> <idle>-0 [000] 521.442100: _spin_lock <-tick_do_update_jiffies64
> <idle>-0 [000] 521.442101: do_timer <-tick_do_update_jiffies64
> <idle>-0 [000] 521.442102: update_wall_time <-do_timer
> <idle>-0 [000] 521.442102: update_xtime_cache <-update_wall_time
> ....
> (It always print the time less than 2200 seconds besides ...)
> Because 'long' is 32bits in i386. ( (1<<31) useconds is about 2200 seconds)
>
> # cat trace
> ...
> <idle>-0 [001] 4154502640.134759: rcu_bh_qsctr_inc <-__do_softirq
> <idle>-0 [001] 4154502640.134760: _local_bh_enable <-__do_softirq
> <idle>-0 [001] 4154502640.134761: idle_cpu <-irq_exit
> ...
> (very large value)
> Because 'long' is a signed type and is 32bits in i386.
>
> Signed-off-by: Lai Jiangshan <[email protected]>
> Reported-by: Li Zefan <[email protected]>
> Tested-by: Lai Jiangshan <[email protected]>
Acked-by: Frederic Weisbecker <[email protected]>
On Mon, 2009-03-30 at 13:48 +0800, Lai Jiangshan wrote:
> Impact: fix time output bug in 32bits system
>
> ns2usecs() returns 'long', it's incorrect.
>
> (In i386)
> # cat trace
> ...
> <idle>-0 [000] 521.442100: _spin_lock <-tick_do_update_jiffies64
> <idle>-0 [000] 521.442101: do_timer <-tick_do_update_jiffies64
> <idle>-0 [000] 521.442102: update_wall_time <-do_timer
> <idle>-0 [000] 521.442102: update_xtime_cache <-update_wall_time
> ....
> (It always print the time less than 2200 seconds besides ...)
> Because 'long' is 32bits in i386. ( (1<<31) useconds is about 2200 seconds)
>
> # cat trace
> ...
> <idle>-0 [001] 4154502640.134759: rcu_bh_qsctr_inc <-__do_softirq
> <idle>-0 [001] 4154502640.134760: _local_bh_enable <-__do_softirq
> <idle>-0 [001] 4154502640.134761: idle_cpu <-irq_exit
> ...
> (very large value)
> Because 'long' is a signed type and it is 32bits in i386.
>
> Changed from V1:
> return 'unsigned long long' instead of 'cycle_t'
>
> Signed-off-by: Lai Jiangshan <[email protected]>
> Reported-by: Li Zefan <[email protected]>
Thanks, applied.
-- Steve
Commit-ID: cf8e3474654f20433aab9aa35826d43b5f245008
Gitweb: http://git.kernel.org/tip/cf8e3474654f20433aab9aa35826d43b5f245008
Author: Lai Jiangshan <[email protected]>
AuthorDate: Mon, 30 Mar 2009 13:48:00 +0800
Committer: Ingo Molnar <[email protected]>
CommitDate: Tue, 7 Apr 2009 13:59:23 +0200
tracing: fix incorrect return type of ns2usecs()
Impact: fix time output bug in 32bits system
ns2usecs() returns 'long', it's incorrect.
(In i386)
..
<idle>-0 [000] 521.442100: _spin_lock <-tick_do_update_jiffies64
<idle>-0 [000] 521.442101: do_timer <-tick_do_update_jiffies64
<idle>-0 [000] 521.442102: update_wall_time <-do_timer
<idle>-0 [000] 521.442102: update_xtime_cache <-update_wall_time
...
(It always print the time less than 2200 seconds besides ...)
Because 'long' is 32bits in i386. ( (1<<31) useconds is about 2200 seconds)
..
<idle>-0 [001] 4154502640.134759: rcu_bh_qsctr_inc <-__do_softirq
<idle>-0 [001] 4154502640.134760: _local_bh_enable <-__do_softirq
<idle>-0 [001] 4154502640.134761: idle_cpu <-irq_exit
..
(very large value)
Because 'long' is a signed type and it is 32bits in i386.
Changes in v2:
return 'unsigned long long' instead of 'cycle_t'
Signed-off-by: Lai Jiangshan <[email protected]>
LKML-Reference: <[email protected]>
Reported-by: Li Zefan <[email protected]>
Acked-by: Frederic Weisbecker <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Signed-off-by: Ingo Molnar <[email protected]>
---
kernel/trace/trace.c | 3 +--
kernel/trace/trace.h | 2 +-
kernel/trace/trace_output.c | 2 +-
3 files changed, 3 insertions(+), 4 deletions(-)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index a0174a4..457dd8c 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -147,8 +147,7 @@ static int __init set_ftrace_dump_on_oops(char *str)
}
__setup("ftrace_dump_on_oops", set_ftrace_dump_on_oops);
-long
-ns2usecs(cycle_t nsec)
+unsigned long long ns2usecs(cycle_t nsec)
{
nsec += 500;
do_div(nsec, 1000);
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index cb0ce3f..0d81a4a 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -596,7 +596,7 @@ extern int trace_selftest_startup_branch(struct tracer *trace,
#endif /* CONFIG_FTRACE_STARTUP_TEST */
extern void *head_page(struct trace_array_cpu *data);
-extern long ns2usecs(cycle_t nsec);
+extern unsigned long long ns2usecs(cycle_t nsec);
extern int
trace_vbprintk(unsigned long ip, const char *fmt, va_list args);
extern int
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index d72b9a6..64b54a5 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -423,7 +423,7 @@ int trace_print_lat_context(struct trace_iterator *iter)
trace_find_cmdline(entry->pid, comm);
- ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08lx]"
+ ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08llx]"
" %ld.%03ldms (+%ld.%03ldms): ", comm,
entry->pid, iter->cpu, entry->flags,
entry->preempt_count, iter->idx,