All of lore.kernel.org
 help / color / mirror / Atom feed
From: Sergei Shtylyov <sshtylyov@ru.mvista.com>
To: mingo@elte.hu
Cc: linuxppc-dev@ozlabs.org, khilman@mvista.com,
	linux-kernel@vger.kernel.org, dwalker@mvista.com
Subject: [PATCH] 2.6.18-rt7: fix more issues with 32-bit cycles_t in latency_trace.c (take 3)
Date: Mon, 13 Nov 2006 22:52:58 +0300	[thread overview]
Message-ID: <200611132252.58818.sshtylyov@ru.mvista.com> (raw)

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);
 		}
 

WARNING: multiple messages have this Message-ID (diff)
From: Sergei Shtylyov <sshtylyov@ru.mvista.com>
To: mingo@elte.hu
Cc: linux-kernel@vger.kernel.org, linuxppc-dev@ozlabs.org,
	dwalker@mvista.com, khilman@mvista.com
Subject: [PATCH] 2.6.18-rt7: fix more issues with 32-bit cycles_t in latency_trace.c (take 3)
Date: Mon, 13 Nov 2006 22:52:58 +0300	[thread overview]
Message-ID: <200611132252.58818.sshtylyov@ru.mvista.com> (raw)

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);
 		}
 


             reply	other threads:[~2006-11-13 19:51 UTC|newest]

Thread overview: 15+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2006-11-13 19:52 Sergei Shtylyov [this message]
2006-11-13 19:52 ` [PATCH] 2.6.18-rt7: fix more issues with 32-bit cycles_t in latency_trace.c (take 3) Sergei Shtylyov
2006-12-03 19:33 ` Sergei Shtylyov
2006-12-04  9:51   ` Ingo Molnar
2006-12-04 12:29     ` Sergei Shtylyov
2006-12-04 15:39       ` Ingo Molnar
2006-12-04 16:21         ` Sergei Shtylyov
2006-12-04 16:23           ` Ingo Molnar
2006-12-04 17:09             ` Sergei Shtylyov
2006-12-04 17:09               ` Sergei Shtylyov
2006-12-04 21:56         ` Roman Zippel
2006-12-04 21:56           ` Roman Zippel
2006-12-04 21:58           ` Ingo Molnar
2006-12-04 21:58             ` Ingo Molnar
2006-12-04 18:04       ` Sergei Shtylyov

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=200611132252.58818.sshtylyov@ru.mvista.com \
    --to=sshtylyov@ru.mvista.com \
    --cc=dwalker@mvista.com \
    --cc=khilman@mvista.com \
    --cc=linux-kernel@vger.kernel.org \
    --cc=linuxppc-dev@ozlabs.org \
    --cc=mingo@elte.hu \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.