[PATCH] 2.6.18-rt7: fix more issues with 32-bit cycles_t in latency_trace.c (take 3)

[PATCH] 2.6.18-rt7: fix more issues with 32-bit cycles_t in latency_trace.c (take 3)

[Sergei Shtylyov]

In addition to the clock jump-back check being falsely triggered by clock wrap
with 32-bit cycles_t, as noticed by Kevin Hilman, there's another issue: using
%Lx format to print 32-bit values warrants erroneous values on 32-bit machines
like ARM and PPC32...

Signed-off-by: Sergei Shtylyov <sshtylyov@ru.mvista.com>

---
There's a lot more of this cr*p with CONFIG_LATENCY_TRACE enabled, hence is
take 3 on this patch...

 kernel/latency_trace.c |   42 +++++++++++++++++++++---------------------
 1 files changed, 21 insertions(+), 21 deletions(-)

Index: linux-2.6/kernel/latency_trace.c
===================================================================
--- linux-2.6.orig/kernel/latency_trace.c
+++ linux-2.6/kernel/latency_trace.c
@@ -989,30 +989,30 @@ static void update_out_trace(void)
 			tmp_max = max_tr.traces + cpu;
 			entries = min(tmp_max->trace_idx, MAX_TRACE-1);
 			printk("CPU%d: %016Lx (%016Lx) ... #%d (%016Lx) %016Lx\n", cpu,
-				tmp_max->trace[0].timestamp,
-				tmp_max->trace[1].timestamp,
+				(u64)tmp_max->trace[0].timestamp,
+				(u64)tmp_max->trace[1].timestamp,
 				entries,
-				tmp_max->trace[entries-2].timestamp,
-				tmp_max->trace[entries-1].timestamp);
+				(u64)tmp_max->trace[entries-2].timestamp,
+				(u64)tmp_max->trace[entries-1].timestamp);
 		}
 		tmp_max = max_tr.traces + max_tr.cpu;
 		entries = min(tmp_max->trace_idx, MAX_TRACE-1);
 
 		printk("CPU%d entries: %d\n", max_tr.cpu, entries);
-		printk("first stamp: %016Lx\n", first_stamp);
-		printk(" last stamp: %016Lx\n", first_stamp);
+		printk("first stamp: %016Lx\n", (u64)first_stamp);
+		printk(" last stamp: %016Lx\n", (u64)first_stamp);
 	}
 
 #if 0
-	printk("first_stamp: %Ld [%016Lx]\n", first_stamp, first_stamp);
-	printk(" last_stamp: %Ld [%016Lx]\n", last_stamp, last_stamp);
+	printk("first_stamp: %Ld [%016Lx]\n", (u64)first_stamp, (u64)first_stamp);
+	printk(" last_stamp: %Ld [%016Lx]\n", (u64)last_stamp, (u64)last_stamp);
 	printk("   +1 stamp: %Ld [%016Lx]\n",
-		tmp_max->trace[entries].timestamp,
-		tmp_max->trace[entries].timestamp);
+		(u64)tmp_max->trace[entries].timestamp,
+		(u64)tmp_max->trace[entries].timestamp);
 	printk("   +2 stamp: %Ld [%016Lx]\n",
-		tmp_max->trace[entries+1].timestamp,
-		tmp_max->trace[entries+1].timestamp);
-	printk("      delta: %Ld\n", last_stamp-first_stamp);
+		(u64)tmp_max->trace[entries+1].timestamp,
+		(u64)tmp_max->trace[entries+1].timestamp);
+	printk("      delta: %Ld\n", (u64)(last_stamp-first_stamp));
 	printk("    entries: %d\n", entries);
 #endif
 
@@ -1240,7 +1240,7 @@ static int notrace l_show_fn(struct seq_
 			pid_to_cmdline(entry->pid),
 			entry->pid, entry->cpu, entry->flags,
 			entry->preempt_count, trace_idx,
-			entry->timestamp, abs_usecs/1000,
+			(u64)entry->timestamp, abs_usecs/1000,
 			abs_usecs % 1000, rel_usecs/1000, rel_usecs % 1000);
 		print_name_offset(m, entry->u.fn.eip);
 		seq_puts(m, " (");
@@ -1623,8 +1623,8 @@ check_critical_timing(int cpu, struct cp
 #ifndef CONFIG_CRITICAL_LATENCY_HIST
 	if (!preempt_thresh && preempt_max_latency > delta) {
 		printk("bug: updating %016Lx > %016Lx?\n",
-			preempt_max_latency, delta);
-		printk("  [%016Lx %016Lx %016Lx]\n", T0, T1, T2);
+			(u64)preempt_max_latency, (u64)delta);
+		printk("  [%016Lx %016Lx %016Lx]\n", (u64)T0, (u64)T1, (u64)T2);
 	}
 #endif
 
@@ -2006,7 +2006,7 @@ check_wakeup_timing(struct cpu_trace *tr
 	____trace(smp_processor_id(), TRACE_FN, tr, CALLER_ADDR0, parent_eip, 0, 0, 0, *flags);
 	T2 = get_cycles();
 	if (T2 < T1)
-		printk("bug2: %016Lx < %016Lx!\n", T2, T1);
+		printk("bug2: %016Lx < %016Lx!\n", (u64)T2, (u64)T1);
 	delta = T2-T0;
 
 	latency = cycles_to_usecs(delta);
@@ -2023,8 +2023,8 @@ check_wakeup_timing(struct cpu_trace *tr
 #ifndef CONFIG_WAKEUP_LATENCY_HIST
 	if (!preempt_thresh && preempt_max_latency > delta) {
 		printk("bug2: updating %016Lx > %016Lx?\n",
-			preempt_max_latency, delta);
-		printk("  [%016Lx %016Lx %016Lx]\n", T0, T1, T2);
+			(u64)preempt_max_latency, (u64)delta);
+		printk("  [%016Lx %016Lx %016Lx]\n", (u64)T0, (u64)T1, (u64)T2);
 	}
 #endif
 
@@ -2273,8 +2273,8 @@ long user_trace_stop(void)
 		if (!preempt_thresh && preempt_max_latency > delta) {
 			local_irq_restore(flags);
 			printk("bug3: updating %016Lx > %016Lx [%016Lx]?\n",
-				preempt_max_latency, delta, tmp0);
-			printk("  [%016Lx %016Lx]\n", T0, T1);
+				(u64)preempt_max_latency, (u64)delta, tmp0);
+			printk("  [%016Lx %016Lx]\n", (u64)T0, (u64)T1);
 			local_irq_save(flags);
 		}
 

Re: [PATCH] 2.6.18-rt7: fix more issues with 32-bit cycles_t in latency_trace.c (take 3)

[Sergei Shtylyov]

Hello, I wrote:

> In addition to the clock jump-back check being falsely triggered by clock wrap
> with 32-bit cycles_t, as noticed by Kevin Hilman, there's another issue: using
> %Lx format to print 32-bit values warrants erroneous values on 32-bit machines
> like ARM and PPC32...

> Signed-off-by: Sergei Shtylyov <sshtylyov@ru.mvista.com>

    What was the destiny of that patch? I haven't seen it accepted, haven't 
seen any comments... while this is not a mere warning fix. What am I expected 
to do to get it accepted -- recast it against 2.6.19-rt1?

>  kernel/latency_trace.c |   42 +++++++++++++++++++++---------------------
>  1 files changed, 21 insertions(+), 21 deletions(-)

WBR, Sergei

Re: [PATCH] 2.6.18-rt7: fix more issues with 32-bit cycles_t in latency_trace.c (take 3)

[Ingo Molnar]

* Sergei Shtylyov <sshtylyov@ru.mvista.com> wrote:

>    What was the destiny of that patch? I haven't seen it accepted, 
> haven't seen any comments... while this is not a mere warning fix. 
> What am I expected to do to get it accepted -- recast it against 
> 2.6.19-rt1?

i'd suggest to redo it - but please keep it simple and clean. Those 
dozens of casts to u64 are quite ugly. Why is cycles_t 32-bits on some 
of the arches to begin with?

	Ingo

Re: [PATCH] 2.6.18-rt7: fix more issues with 32-bit cycles_t in latency_trace.c (take 3)

[Sergei Shtylyov]

Hello.

Ingo Molnar wrote:

>>   What was the destiny of that patch? I haven't seen it accepted, 
>>haven't seen any comments... while this is not a mere warning fix. 
>>What am I expected to do to get it accepted -- recast it against 
>>2.6.19-rt1?

> i'd suggest to redo it - but please keep it simple and clean. Those 
> dozens of casts to u64 are quite ugly.

    Alas, there's *nothing* I can do about it with 32-bit cycles_t. And if you 
look at the kernel, this is not the only case of such "ugliness", look at this 
commit for example:

http://www.kernel.org/git/?p=linux/kernel/git/paulus/powerpc.git;a=commit;h=685143ac1f7a579a3fac9c7f2ac8f82e95af6864

> Why is cycles_t 32-bits on some 
> of the arches to begin with?

    I guess this was done for speed reasons. That's not a qustion for me 
although...

> 	Ingo

WBR, Sergei

Re: [PATCH] 2.6.18-rt7: fix more issues with 32-bit cycles_t in latency_trace.c (take 3)

[Ingo Molnar]

* Sergei Shtylyov <sshtylyov@ru.mvista.com> wrote:

> >i'd suggest to redo it - but please keep it simple and clean. Those 
> >dozens of casts to u64 are quite ugly.
> 
>    Alas, there's *nothing* I can do about it with 32-bit cycles_t. 
> [...]

there's *always* a way to do such things more cleanly - such as the 
patch below. Could you try to fix it up for 32-bit cycles_t platforms? I 
bet the hackery will be limited to now() and maybe the conversion 
routines, instead of spreading all around latency_trace.c.

	Ingo

Index: linux/kernel/latency_trace.c
===================================================================
--- linux.orig/kernel/latency_trace.c
+++ linux/kernel/latency_trace.c
@@ -18,6 +18,7 @@
 #include <linux/kallsyms.h>
 #include <linux/seq_file.h>
 #include <linux/interrupt.h>
+#include <linux/clocksource.h>
 #include <linux/proc_fs.h>
 #include <linux/latency_hist.h>
 #include <linux/utsrelease.h>
@@ -43,7 +44,7 @@ int trace_use_raw_cycles = 1;
  * points, but the trace entries inbetween are timestamped with
  * get_cycles().
  */
-static unsigned long notrace cycles_to_us(cycles_t delta)
+static unsigned long notrace cycles_to_us(cycle_t delta)
 {
 	if (!trace_use_raw_cycles)
 		return cycles_to_usecs(delta);
@@ -60,7 +61,7 @@ static unsigned long notrace cycles_to_u
 	return (unsigned long) delta;
 }
 
-static notrace inline cycles_t now(void)
+static notrace inline cycle_t now(void)
 {
 	if (trace_use_raw_cycles)
 		return get_cycles();
@@ -150,17 +151,17 @@ enum trace_flag_type
  * we clear it after bootup.
  */
 #ifdef CONFIG_LATENCY_HIST
-static cycles_t preempt_max_latency = (cycles_t)0UL;
+static cycle_t preempt_max_latency = (cycle_t)0UL;
 #else
-static cycles_t preempt_max_latency = (cycles_t)ULONG_MAX;
+static cycle_t preempt_max_latency = (cycle_t)ULONG_MAX;
 #endif
 
-static cycles_t preempt_thresh;
+static cycle_t preempt_thresh;
 
 /*
  * Should this new latency be reported/recorded?
  */
-static int report_latency(cycles_t delta)
+static int report_latency(cycle_t delta)
 {
 	if (latency_hist_flag && !trace_user_triggered)
 		return 1;
@@ -193,7 +194,7 @@ struct trace_entry {
 	char flags;
 	char preempt_count; // assumes PREEMPT_MASK is 8 bits or less
 	int pid;
-	cycles_t timestamp;
+	cycle_t timestamp;
 	union {
 		struct {
 			unsigned long eip;
@@ -224,7 +225,7 @@ struct trace_entry {
 struct cpu_trace {
 	atomic_t disabled;
 	unsigned long trace_idx;
-	cycles_t preempt_timestamp;
+	cycle_t preempt_timestamp;
 	unsigned long critical_start, critical_end;
 	unsigned long critical_sequence;
 	atomic_t overrun;
@@ -274,7 +275,7 @@ int trace_user_trigger_irq = -1;
 
 struct saved_trace_struct {
 	int cpu;
-	cycles_t first_timestamp, last_timestamp;
+	cycle_t first_timestamp, last_timestamp;
 	struct cpu_trace traces[NR_CPUS];
 } ____cacheline_aligned_in_smp;
 
@@ -586,7 +587,7 @@ ____trace(int cpu, enum trace_type type,
 {
 	struct trace_entry *entry;
 	unsigned long idx, idx_next;
-	cycles_t timestamp;
+	cycle_t timestamp;
 	u32 pc;
 
 #ifdef CONFIG_DEBUG_PREEMPT
@@ -972,7 +973,7 @@ struct block_idx {
  */
 static int min_idx(struct block_idx *bidx)
 {
-	cycles_t min_stamp = (cycles_t) -1;
+	cycle_t min_stamp = (cycle_t) -1;
 	struct trace_entry *entry;
 	int cpu, min_cpu = -1, idx;
 
@@ -1006,7 +1007,7 @@ static int min_idx(struct block_idx *bid
 static void update_out_trace(void)
 {
 	struct trace_entry *out_entry, *entry, *tmp;
-	cycles_t stamp, first_stamp, last_stamp;
+	cycle_t stamp, first_stamp, last_stamp;
 	struct block_idx bidx = { { 0, }, };
 	struct cpu_trace *tmp_max, *tmp_out;
 	int cpu, sum, entries, overrun_sum;
@@ -1694,7 +1695,7 @@ static void notrace
 check_critical_timing(int cpu, struct cpu_trace *tr, unsigned long parent_eip)
 {
 	unsigned long latency, t0, t1;
-	cycles_t T0, T1, T2, delta;
+	cycle_t T0, T1, T2, delta;
 	unsigned long flags;
 
 	if (trace_user_triggered)
@@ -1721,7 +1722,7 @@ check_critical_timing(int cpu, struct cp
 	T2 = get_monotonic_cycles();
 
 	/* check for buggy clocks, handling wrap for 32-bit clocks */
-	if (TYPE_EQUAL(cycles_t, unsigned long)) {
+	if (TYPE_EQUAL(cycle_t, unsigned long)) {
 		if (time_after((unsigned long)T1, (unsigned long)T2))
 			printk("bug: %08lx < %08lx!\n",
 				(unsigned long)T2, (unsigned long)T1);
@@ -2100,7 +2101,7 @@ check_wakeup_timing(struct cpu_trace *tr
 {
 	int cpu = raw_smp_processor_id();
 	unsigned long latency, t0, t1;
-	cycles_t T0, T1, delta;
+	cycle_t T0, T1, delta;
 
 	if (trace_user_triggered)
 		return;
@@ -2293,7 +2294,7 @@ long user_trace_start(void)
 	 * bootup then we assume that this was the intention
 	 * (we wont get any tracing done otherwise):
 	 */
-	if (preempt_max_latency == (cycles_t)ULONG_MAX)
+	if (preempt_max_latency == (cycle_t)ULONG_MAX)
 		preempt_max_latency = 0;
 
 	/*
@@ -2343,7 +2344,7 @@ long user_trace_stop(void)
 {
 	unsigned long latency, flags;
 	struct cpu_trace *tr;
-	cycles_t delta;
+	cycle_t delta;
 
 	if (!trace_user_triggered || trace_print_at_crash || print_functions)
 		return -EINVAL;
@@ -2371,7 +2372,7 @@ long user_trace_stop(void)
 
 	atomic_inc(&tr->disabled);
 	if (tr->preempt_timestamp) {
-		cycles_t T0, T1;
+		cycle_t T0, T1;
 		unsigned long long tmp0;
 
 		T0 = tr->preempt_timestamp;
@@ -2633,7 +2634,7 @@ void print_traces(struct task_struct *ta
 static int preempt_read_proc(char *page, char **start, off_t off,
 			     int count, int *eof, void *data)
 {
-	cycles_t *max = data;
+	cycle_t *max = data;
 
 	return sprintf(page, "%ld\n", cycles_to_usecs(*max));
 }
@@ -2642,7 +2643,7 @@ static int preempt_write_proc(struct fil
 			      unsigned long count, void *data)
 {
 	unsigned int c, done = 0, val, sum = 0;
-	cycles_t *max = data;
+	cycle_t *max = data;
 
 	while (count) {
 		if (get_user(c, buffer))
Index: linux/kernel/timer.c
===================================================================
--- linux.orig/kernel/timer.c
+++ linux/kernel/timer.c
@@ -889,7 +889,7 @@ static inline s64 __get_nsec_offset(void
 	return ns_offset;
 }
 
-cycles_t notrace get_monotonic_cycles(void)
+cycle_t notrace get_monotonic_cycles(void)
 {
 	cycle_t cycle_now, cycle_delta;
 
@@ -902,7 +902,7 @@ cycles_t notrace get_monotonic_cycles(vo
 	return clock->cycle_last + cycle_delta;
 }
 
-unsigned long notrace cycles_to_usecs(cycles_t cycles)
+unsigned long notrace cycles_to_usecs(cycle_t cycles)
 {
 	u64 ret = cyc2ns(clock, cycles);
 
@@ -911,7 +911,7 @@ unsigned long notrace cycles_to_usecs(cy
 	return ret;
 }
 
-cycles_t notrace usecs_to_cycles(unsigned long usecs)
+cycle_t notrace usecs_to_cycles(unsigned long usecs)
 {
 	return ns2cyc(clock, (u64)usecs * 1000);
 }

Re: [PATCH] 2.6.18-rt7: fix more issues with 32-bit cycles_t in latency_trace.c (take 3)

[Sergei Shtylyov]

Hello.

Ingo Molnar wrote:

>>>i'd suggest to redo it - but please keep it simple and clean. Those 
>>>dozens of casts to u64 are quite ugly.

>>   Alas, there's *nothing* I can do about it with 32-bit cycles_t. 
>>[...]

> there's *always* a way to do such things more cleanly - such as the 
> patch below. Could you try to fix it up for 32-bit cycles_t platforms? I 
> bet the hackery will be limited to now() and maybe the conversion 
> routines, instead of spreading all around latency_trace.c.

    I'm not sure what you want me to do... You've switched to clocksource 
specific cycle_t (which is u64), do you want me to use the clocksource 
interface to get the cycles from now on?

> Index: linux/kernel/latency_trace.c
> ===================================================================
> --- linux.orig/kernel/latency_trace.c
> +++ linux/kernel/latency_trace.c
[...]
> @@ -1721,7 +1722,7 @@ check_critical_timing(int cpu, struct cp
>  	T2 = get_monotonic_cycles();
>  
>  	/* check for buggy clocks, handling wrap for 32-bit clocks */
> -	if (TYPE_EQUAL(cycles_t, unsigned long)) {
> +	if (TYPE_EQUAL(cycle_t, unsigned long)) {
>  		if (time_after((unsigned long)T1, (unsigned long)T2))
>  			printk("bug: %08lx < %08lx!\n",
>  				(unsigned long)T2, (unsigned long)T1);

    This earlier fix by Kevin woulnd't have sense anymore with cycle_t...

WBR, Sergei

Re: [PATCH] 2.6.18-rt7: fix more issues with 32-bit cycles_t in latency_trace.c (take 3)

[Ingo Molnar]

* Sergei Shtylyov <sshtylyov@ru.mvista.com> wrote:

> > 	/* check for buggy clocks, handling wrap for 32-bit clocks */
> >-	if (TYPE_EQUAL(cycles_t, unsigned long)) {
> >+	if (TYPE_EQUAL(cycle_t, unsigned long)) {
> > 		if (time_after((unsigned long)T1, (unsigned long)T2))
> > 			printk("bug: %08lx < %08lx!\n",
> > 				(unsigned long)T2, (unsigned long)T1);
> 
>    This earlier fix by Kevin woulnd't have sense anymore with cycle_t...

yeah, indeed - i've zapped this one too.

basically, what i'd like is the 32-bit clocks/cycles be handled 
intelligently, and not adding to the cruft that already is in 
kernel/latency_tracing.c.

	Ingo

Re: [PATCH] 2.6.18-rt7: fix more issues with 32-bit cycles_t in latency_trace.c (take 3)

[Sergei Shtylyov]

Hello.

Ingo Molnar wrote:

>>>	/* check for buggy clocks, handling wrap for 32-bit clocks */
>>>-	if (TYPE_EQUAL(cycles_t, unsigned long)) {
>>>+	if (TYPE_EQUAL(cycle_t, unsigned long)) {
>>>		if (time_after((unsigned long)T1, (unsigned long)T2))
>>>			printk("bug: %08lx < %08lx!\n",
>>>				(unsigned long)T2, (unsigned long)T1);

>>   This earlier fix by Kevin woulnd't have sense anymore with cycle_t...

> yeah, indeed - i've zapped this one too.

    Moreover, it was somewhat incorrect from the very start since 'unsigned 
long' is 64-bit on 64-bit machines, and cycles_t is 'unsigned long' on both 
PPC32 and PPC64, so else branch would've *never* be executed...

> basically, what i'd like is the 32-bit clocks/cycles be handled 
> intelligently, and not adding to the cruft that already is in 
> kernel/latency_tracing.c.

    Yeah, I've looked at 2.6.19-rt2 and saw the new approach. But what's left 
to fix there, only the case of using PPC32 raw cycles? I guess you only need 
to cast a result of get_cycles() to cycle_t... wait, it'll be explicitly cast 
in the return stmt, won't it?

> 	Ingo

WBR, Sergei

Re: [PATCH] 2.6.18-rt7: fix more issues with 32-bit cycles_t in latency_trace.c (take 3)

[Sergei Shtylyov]

Hello.

Sergei Shtylyov wrote:

>>Why is cycles_t 32-bits on some 
>>of the arches to begin with?

>     I guess this was done for speed reasons.

    The whole 64-bit timebase can't be rad atomically on PPC32. ARM probably 
has stricter limitations...

>>	Ingo

WBR, Sergei

Re: [PATCH] 2.6.18-rt7: fix more issues with 32-bit cycles_t in latency_trace.c (take 3)

[Roman Zippel]

Hi,

On Monday 04 December 2006 16:39, Ingo Molnar wrote:

> there's *always* a way to do such things more cleanly - such as the
> patch below. Could you try to fix it up for 32-bit cycles_t platforms? I
> bet the hackery will be limited to now() and maybe the conversion
> routines, instead of spreading all around latency_trace.c.

While I'm not against this patch, but on m68k I prefer a 32bit cycle type 
(however it's called), so it doesn't solve the original problem.

bye, Roman

Re: [PATCH] 2.6.18-rt7: fix more issues with 32-bit cycles_t in latency_trace.c (take 3)

[Ingo Molnar]

* Roman Zippel <zippel@linux-m68k.org> wrote:

> While I'm not against this patch, but on m68k I prefer a 32bit cycle 
> type (however it's called), so it doesn't solve the original problem.

i havent changed the cycles_t type - it's still 32-bit. I agree with you 
that we dont want to bloat 32-bit arch-level code by artificially 
forcing everyone to a 64-bit cycles_t.

	Ingo