Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar <mingo@elte.hu>]

[-- Attachment #1: Type: text/plain, Size: 2144 bytes --]


* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> VARYING SYSTEM CALL TIMES
> =========================
> 
> In 2.4, it appears that the duration of the write system call is
> basically fixed and dependent on the duration of the audio fragment.
> In 2.6, this behavior is now different. If I look at the chart in
> detail, it appears the system is queueing up several write operations
> during the first few seconds of testing. You can see this by
> consistently low elapsed times for the write system call. Then the
> elapsed time for the write bounces up / down in a sawtooth pattern
> over a 1 msec range. Could someone explain the cause of this new
> behavior and if there is a setting to restore the old behavior? I am
> concerned that this queueing adds latency to audio operations (when
> trying to synchronize audio with other real time behavior).

since the latency tracer does not trigger, we need a modified tracer to
find out what's happening during such long delays. I've attached the
'user-latency-tracer' patch ontop of -Q5, which is a modification of the
latency tracer. This patch enables free-running tracing which includes
all kernel functions not just critical sections. To activate this, two
things have to be done. Firstly:

	echo 2 > /proc/sys/kernel/trace_enabled

this turns off the normal latency tracer and turns on the 'user tracer'. 
Traces can be generated by userspace via a hack done to
sys_gettimeofday():

	gettimeofday(0,1); // enable the tracer
	gettimeofday(0,0); // save current trace and disable the tracer

this way the tracing can be limited to the suspected codepaths only.

could you try to insert gettimeofday(0,1) into your testsuite just
before the write() call is done, and right after the write() call, and
save a couple of representative traces? The patch also ups the # of
latency entries to 8000 - if that is still insufficient then please
increase it as needed.

NOTE: on SMP the tracing on/off is strictly per-CPU. So do the enabling
and disabling of the trace on the same CPU. (doing otherwise wont cause
problems, but the generated traces will be less useful.)

	Ingo

[-- Attachment #2: user-latency-2.6.9-rc1-bk4-Q5-A0 --]
[-- Type: text/plain, Size: 3598 bytes --]

--- linux/kernel/latency.c.orig
+++ linux/kernel/latency.c
@@ -27,7 +27,7 @@ static DECLARE_MUTEX(max_mutex);
 
 #ifdef CONFIG_LATENCY_TRACE
 
-#define MAX_TRACE 4000UL
+#define MAX_TRACE 8000UL
 
 struct trace_entry {
 	unsigned long preempt_count;
@@ -63,14 +63,13 @@ static unsigned long max_nice;
 static unsigned long max_policy;
 static unsigned long max_rt_priority;
 
-inline void notrace
+static inline void notrace
 ____trace(struct cpu_trace *tr, unsigned long eip, unsigned long parent_eip)
 {
 	struct trace_entry *entry;
 
-	BUG_ON(!irqs_disabled());
-
-	if (tr->trace_idx < MAX_TRACE) {
+	if ((tr->critical_start || (trace_enabled == 2)) &&
+			(tr->trace_idx < MAX_TRACE)) {
 		entry = tr->trace + tr->trace_idx;
 		entry->eip = eip;
 		entry->parent_eip = parent_eip;
@@ -80,7 +79,7 @@ ____trace(struct cpu_trace *tr, unsigned
 	tr->trace_idx++;
 }
 
-inline void notrace
+static inline void notrace
 ___trace(unsigned long eip, unsigned long parent_eip)
 {
 	unsigned long flags;
@@ -266,6 +265,18 @@ static int setup_preempt_thresh(char *s)
 }
 __setup("preempt_thresh=", setup_preempt_thresh);
 
+static void update_max_trace(struct cpu_trace *tr)
+{
+	memcpy(&max_trace, tr, sizeof (max_trace));
+
+	memcpy(max_comm, current->comm, 16);
+	max_pid = current->pid;
+	max_uid = current->uid;
+	max_nice = current->static_prio - 20 - MAX_RT_PRIO;
+	max_policy = current->policy;
+	max_rt_priority = current->rt_priority;
+}
+
 static void notrace check_preempt_timing(struct cpu_trace *tr)
 {
 #ifdef CONFIG_LATENCY_TRACE
@@ -274,6 +285,10 @@ static void notrace check_preempt_timing
 	unsigned long parent_eip = (unsigned long)__builtin_return_address(1);
 	unsigned long latency;
 
+#ifdef CONFIG_LATENCY_TRACE
+	if (trace_enabled == 2)
+		return;
+#endif
 	atomic_inc(&tr->disabled);
 	latency = cycles_to_usecs(get_cycles() - tr->preempt_timestamp);
 
@@ -293,14 +308,7 @@ static void notrace check_preempt_timing
 
 #ifdef CONFIG_LATENCY_TRACE
 	____trace(tr, eip, parent_eip);
-	memcpy(&max_trace, tr, sizeof (max_trace));
-
-	memcpy(max_comm, current->comm, 16);
-	max_pid = current->pid;
-	max_uid = current->uid;
-	max_nice = current->static_prio - 20 - MAX_RT_PRIO;
-	max_policy = current->policy;
-	max_rt_priority = current->rt_priority;
+	update_max_trace(tr);
 #endif
 
 	if (preempt_thresh)
@@ -354,6 +362,10 @@ void notrace add_preempt_count(int val)
 #endif
 
 	preempt_count() += val;
+#ifdef CONFIG_LATENCY_TRACE
+	if (trace_enabled == 2)
+		return;
+#endif
 	if (preempt_count() == val) {
 		struct cpu_trace *tr = &__get_cpu_var(trace);
 
@@ -383,3 +395,27 @@ void notrace sub_preempt_count(int val)
 	preempt_count() -= val;
 }
 EXPORT_SYMBOL(sub_preempt_count);
+
+void user_trace_start(void)
+{
+	struct cpu_trace *tr;
+
+	if (trace_enabled != 2)
+		return;
+	tr = &get_cpu_var(trace);
+	tr->trace_idx = 0;
+	mcount();
+	put_cpu_var(trace);
+}
+
+void user_trace_stop(void)
+{
+	struct cpu_trace *tr;
+
+	if (trace_enabled != 2)
+		return;
+	tr = &get_cpu_var(trace);
+	mcount();
+	update_max_trace(tr);
+	put_cpu_var(trace);
+}
--- linux/kernel/time.c.orig2	
+++ linux/kernel/time.c	
@@ -90,8 +90,17 @@ asmlinkage long sys_stime(time_t __user 
 
 #endif /* __ARCH_WANT_SYS_TIME */
 
+extern void user_trace_start(void);
+extern void user_trace_stop(void);
+
 asmlinkage long sys_gettimeofday(struct timeval __user *tv, struct timezone __user *tz)
 {
+#ifdef CONFIG_LATENCY_TRACE
+	if (!tv && ((int)tz == 1))
+		user_trace_start();
+	if (!tv && !tz)
+		user_trace_stop();
+#endif
 	if (likely(tv != NULL)) {
 		struct timeval ktv;
 		do_gettimeofday(&ktv);