All of lore.kernel.org
 help / color / mirror / Atom feed
From: Thomas Gleixner <tglx@linutronix.de>
To: LKML <linux-kernel@vger.kernel.org>
Cc: Steven Rostedt <rostedt@goodmis.org>,
	RT-users <linux-rt-users@vger.kernel.org>,
	Carsten Emde <cbe@osadl.org>
Subject: [patch RT 1/7] Latency histogramms: Cope with backwards running local trace clock
Date: Wed, 11 Jul 2012 22:05:17 -0000	[thread overview]
Message-ID: <20120711215611.623007012@linutronix.de> (raw)
In-Reply-To: 20120711214552.036760674@linutronix.de

[-- Attachment #1: latency-histogramms-cope-with-backwards-running-local-trace-clock.patch --]
[-- Type: text/plain, Size: 9180 bytes --]

Thanks to the wonders of modern technology, the local trace clock can
now run backwards. Since this never happened before, the time difference
between now and somewhat earlier was expected to never become negative
and, thus, stored in an unsigned integer variable. Nowadays, we need a
signed integer to ensure that the value is stored as underflow in the
related histogram. (In cases where this is not a misfunction, bipolar
histograms can be used.)

This patch takes care that all latency variables are represented as
signed integers and negative numbers are considered as histogram
underflows.

In one of the misbehaving processors switching to global clock solved
the problem:
  echo global >/sys/kernel/debug/tracing/trace_clock

Signed-off-by: Carsten Emde <C.Emde@osadl.org>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>

---
 include/linux/sched.h       |    2 +-
 kernel/trace/latency_hist.c |   30 +++++++++++++++---------------
 2 files changed, 16 insertions(+), 16 deletions(-)

Index: linux-3.4.4-rt13/include/linux/sched.h
===================================================================
--- linux-3.4.4-rt13.orig/include/linux/sched.h
+++ linux-3.4.4-rt13/include/linux/sched.h
@@ -1629,7 +1629,7 @@ struct task_struct {
 #ifdef CONFIG_WAKEUP_LATENCY_HIST
 	u64 preempt_timestamp_hist;
 #ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
-	unsigned long timer_offset;
+	long timer_offset;
 #endif
 #endif
 #endif /* CONFIG_TRACING */
Index: linux-3.4.4-rt13/kernel/trace/latency_hist.c
===================================================================
--- linux-3.4.4-rt13.orig/kernel/trace/latency_hist.c
+++ linux-3.4.4-rt13/kernel/trace/latency_hist.c
@@ -27,6 +27,8 @@
 #include "trace.h"
 #include <trace/events/sched.h>
 
+#define NSECS_PER_USECS 1000L
+
 #define CREATE_TRACE_POINTS
 #include <trace/events/hist.h>
 
@@ -46,11 +48,11 @@ enum {
 struct hist_data {
 	atomic_t hist_mode; /* 0 log, 1 don't log */
 	long offset; /* set it to MAX_ENTRY_NUM/2 for a bipolar scale */
-	unsigned long min_lat;
-	unsigned long max_lat;
+	long min_lat;
+	long max_lat;
 	unsigned long long below_hist_bound_samples;
 	unsigned long long above_hist_bound_samples;
-	unsigned long long accumulate_lat;
+	long long accumulate_lat;
 	unsigned long long total_samples;
 	unsigned long long hist_array[MAX_ENTRY_NUM];
 };
@@ -152,8 +154,8 @@ static struct enable_data timerandwakeup
 static DEFINE_PER_CPU(struct maxlatproc_data, timerandwakeup_maxlatproc);
 #endif
 
-void notrace latency_hist(int latency_type, int cpu, unsigned long latency,
-			  unsigned long timeroffset, cycle_t stop,
+void notrace latency_hist(int latency_type, int cpu, long latency,
+			  long timeroffset, cycle_t stop,
 			  struct task_struct *p)
 {
 	struct hist_data *my_hist;
@@ -224,7 +226,7 @@ void notrace latency_hist(int latency_ty
 		my_hist->hist_array[latency]++;
 
 	if (unlikely(latency > my_hist->max_lat ||
-	    my_hist->min_lat == ULONG_MAX)) {
+	    my_hist->min_lat == LONG_MAX)) {
 #if defined(CONFIG_WAKEUP_LATENCY_HIST) || \
     defined(CONFIG_MISSED_TIMER_OFFSETS_HIST)
 		if (latency_type == WAKEUP_LATENCY ||
@@ -263,15 +265,14 @@ static void *l_start(struct seq_file *m,
 		atomic_dec(&my_hist->hist_mode);
 
 		if (likely(my_hist->total_samples)) {
-			unsigned long avg = (unsigned long)
-			    div64_u64(my_hist->accumulate_lat,
+			long avg = (long) div64_s64(my_hist->accumulate_lat,
 			    my_hist->total_samples);
 			snprintf(minstr, sizeof(minstr), "%ld",
-			    (long) my_hist->min_lat - my_hist->offset);
+			    my_hist->min_lat - my_hist->offset);
 			snprintf(avgstr, sizeof(avgstr), "%ld",
-			    (long) avg - my_hist->offset);
+			    avg - my_hist->offset);
 			snprintf(maxstr, sizeof(maxstr), "%ld",
-			    (long) my_hist->max_lat - my_hist->offset);
+			    my_hist->max_lat - my_hist->offset);
 		} else {
 			strcpy(minstr, "<undef>");
 			strcpy(avgstr, minstr);
@@ -376,10 +377,10 @@ static void hist_reset(struct hist_data 
 	memset(hist->hist_array, 0, sizeof(hist->hist_array));
 	hist->below_hist_bound_samples = 0ULL;
 	hist->above_hist_bound_samples = 0ULL;
-	hist->min_lat = ULONG_MAX;
-	hist->max_lat = 0UL;
+	hist->min_lat = LONG_MAX;
+	hist->max_lat = LONG_MIN;
 	hist->total_samples = 0ULL;
-	hist->accumulate_lat = 0ULL;
+	hist->accumulate_lat = 0LL;
 
 	atomic_inc(&hist->hist_mode);
 }
@@ -790,9 +791,9 @@ static notrace void probe_preemptirqsoff
 
 			stop = ftrace_now(cpu);
 			time_set++;
-			if (start && stop >= start) {
-				unsigned long latency =
-				    nsecs_to_usecs(stop - start);
+			if (start) {
+				long latency = ((long) (stop - start)) /
+				    NSECS_PER_USECS;
 
 				latency_hist(IRQSOFF_LATENCY, cpu, latency, 0,
 				    stop, NULL);
@@ -808,9 +809,9 @@ static notrace void probe_preemptirqsoff
 
 			if (!(time_set++))
 				stop = ftrace_now(cpu);
-			if (start && stop >= start) {
-				unsigned long latency =
-				    nsecs_to_usecs(stop - start);
+			if (start) {
+				long latency = ((long) (stop - start)) /
+				    NSECS_PER_USECS;
 
 				latency_hist(PREEMPTOFF_LATENCY, cpu, latency,
 				    0, stop, NULL);
@@ -827,9 +828,10 @@ static notrace void probe_preemptirqsoff
 
 			if (!time_set)
 				stop = ftrace_now(cpu);
-			if (start && stop >= start) {
-				unsigned long latency =
-				    nsecs_to_usecs(stop - start);
+			if (start) {
+				long latency = ((long) (stop - start)) /
+				    NSECS_PER_USECS;
+
 				latency_hist(PREEMPTIRQSOFF_LATENCY, cpu,
 				    latency, 0, stop, NULL);
 			}
@@ -908,7 +910,7 @@ static notrace void probe_wakeup_latency
 {
 	unsigned long flags;
 	int cpu = task_cpu(next);
-	unsigned long latency;
+	long latency;
 	cycle_t stop;
 	struct task_struct *cpu_wakeup_task;
 
@@ -939,7 +941,8 @@ static notrace void probe_wakeup_latency
 	 */
 	stop = ftrace_now(raw_smp_processor_id());
 
-	latency = nsecs_to_usecs(stop - next->preempt_timestamp_hist);
+	latency = ((long) (stop - next->preempt_timestamp_hist)) /
+	    NSECS_PER_USECS;
 
 	if (per_cpu(wakeup_sharedprio, cpu)) {
 		latency_hist(WAKEUP_LATENCY_SHAREDPRIO, cpu, latency, 0, stop,
@@ -975,7 +978,7 @@ static notrace void probe_hrtimer_interr
 	    (task->prio < curr->prio ||
 	    (task->prio == curr->prio &&
 	    !cpumask_test_cpu(cpu, &task->cpus_allowed)))) {
-		unsigned long latency;
+		long latency;
 		cycle_t now;
 
 		if (missed_timer_offsets_pid) {
@@ -985,7 +988,7 @@ static notrace void probe_hrtimer_interr
 		}
 
 		now = ftrace_now(cpu);
-		latency = (unsigned long) div_s64(-latency_ns, 1000);
+		latency = (long) div_s64(-latency_ns, NSECS_PER_USECS);
 		latency_hist(MISSED_TIMER_OFFSETS, cpu, latency, latency, now,
 		    task);
 #ifdef CONFIG_WAKEUP_LATENCY_HIST
@@ -1026,7 +1029,7 @@ static __init int latency_hist_init(void
 		    &per_cpu(irqsoff_hist, i), &latency_hist_fops);
 		my_hist = &per_cpu(irqsoff_hist, i);
 		atomic_set(&my_hist->hist_mode, 1);
-		my_hist->min_lat = 0xFFFFFFFFUL;
+		my_hist->min_lat = LONG_MAX;
 	}
 	entry = debugfs_create_file("reset", 0644, dentry,
 	    (void *)IRQSOFF_LATENCY, &latency_hist_reset_fops);
@@ -1041,7 +1044,7 @@ static __init int latency_hist_init(void
 		    &per_cpu(preemptoff_hist, i), &latency_hist_fops);
 		my_hist = &per_cpu(preemptoff_hist, i);
 		atomic_set(&my_hist->hist_mode, 1);
-		my_hist->min_lat = 0xFFFFFFFFUL;
+		my_hist->min_lat = LONG_MAX;
 	}
 	entry = debugfs_create_file("reset", 0644, dentry,
 	    (void *)PREEMPTOFF_LATENCY, &latency_hist_reset_fops);
@@ -1056,7 +1059,7 @@ static __init int latency_hist_init(void
 		    &per_cpu(preemptirqsoff_hist, i), &latency_hist_fops);
 		my_hist = &per_cpu(preemptirqsoff_hist, i);
 		atomic_set(&my_hist->hist_mode, 1);
-		my_hist->min_lat = 0xFFFFFFFFUL;
+		my_hist->min_lat = LONG_MAX;
 	}
 	entry = debugfs_create_file("reset", 0644, dentry,
 	    (void *)PREEMPTIRQSOFF_LATENCY, &latency_hist_reset_fops);
@@ -1081,14 +1084,14 @@ static __init int latency_hist_init(void
 		    &latency_hist_fops);
 		my_hist = &per_cpu(wakeup_latency_hist, i);
 		atomic_set(&my_hist->hist_mode, 1);
-		my_hist->min_lat = 0xFFFFFFFFUL;
+		my_hist->min_lat = LONG_MAX;
 
 		entry = debugfs_create_file(name, 0444, dentry_sharedprio,
 		    &per_cpu(wakeup_latency_hist_sharedprio, i),
 		    &latency_hist_fops);
 		my_hist = &per_cpu(wakeup_latency_hist_sharedprio, i);
 		atomic_set(&my_hist->hist_mode, 1);
-		my_hist->min_lat = 0xFFFFFFFFUL;
+		my_hist->min_lat = LONG_MAX;
 
 		sprintf(name, cpufmt_maxlatproc, i);
 
@@ -1122,7 +1125,7 @@ static __init int latency_hist_init(void
 		    &per_cpu(missed_timer_offsets, i), &latency_hist_fops);
 		my_hist = &per_cpu(missed_timer_offsets, i);
 		atomic_set(&my_hist->hist_mode, 1);
-		my_hist->min_lat = 0xFFFFFFFFUL;
+		my_hist->min_lat = LONG_MAX;
 
 		sprintf(name, cpufmt_maxlatproc, i);
 		mp = &per_cpu(missed_timer_offsets_maxlatproc, i);
@@ -1150,7 +1153,7 @@ static __init int latency_hist_init(void
 		    &latency_hist_fops);
 		my_hist = &per_cpu(timerandwakeup_latency_hist, i);
 		atomic_set(&my_hist->hist_mode, 1);
-		my_hist->min_lat = 0xFFFFFFFFUL;
+		my_hist->min_lat = LONG_MAX;
 
 		sprintf(name, cpufmt_maxlatproc, i);
 		mp = &per_cpu(timerandwakeup_maxlatproc, i);






  reply	other threads:[~2012-07-11 22:07 UTC|newest]

Thread overview: 11+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2012-07-11 22:05 [patch RT 0/7] Various fixes for the stable RT series - part I Thomas Gleixner
2012-07-11 22:05 ` Thomas Gleixner [this message]
2012-07-11 22:05 ` [patch RT 3/7] Disable RT_GROUP_SCHED in PREEMPT_RT_FULL Thomas Gleixner
2012-07-12  2:36   ` Mike Galbraith
2012-07-11 22:05 ` [patch RT 2/7] Latency histograms: Adjust timer, if already elapsed when programmed Thomas Gleixner
2012-07-11 22:05 ` [patch RT 5/7] slab: Prevent local lock deadlock Thomas Gleixner
2012-07-11 22:05 ` [patch RT 4/7] Latency histograms: Detect another yet overlooked sharedprio condition Thomas Gleixner
2012-07-11 22:05 ` [patch RT 6/7] fs, jbd: pull your plug when waiting for space Thomas Gleixner
2012-07-11 22:05 ` [patch RT 7/7] perf: Make swevent hrtimer run in irq instead of softirq Thomas Gleixner
2012-07-11 23:31 ` [patch RT 0/7] Various fixes for the stable RT series - part I Steven Rostedt
2012-07-12  8:49   ` Thomas Gleixner

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=20120711215611.623007012@linutronix.de \
    --to=tglx@linutronix.de \
    --cc=cbe@osadl.org \
    --cc=linux-kernel@vger.kernel.org \
    --cc=linux-rt-users@vger.kernel.org \
    --cc=rostedt@goodmis.org \
    /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.