Messages in this thread Patch in this message | | | Date | Tue, 31 Aug 2004 10:49:28 +0200 | From | Ingo Molnar <> | Subject | Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5 |
| |
* 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 --- 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);
| |