PREEMPT_RT and latency_trace

PREEMPT_RT and latency_trace

[Serge Noiraud]

Hi,

I have a big dilemna on one machine :
I run a task with RT priority which make a loop to mesure the system
perturbation.
It works well except on  one machine.
On a multi-cpu, If I run the program on cpu 1, I get 23us. It's OK.
If I run the same program on cpu 0, I get 17373us !
If I do :
# echo 0 >/proc/sys/kernel/preempt_max_latency
# ./tsc 0
 temps deb 60229d5e6ee 
cptr mlockall 0
 temps fin 6c386df6612 
 temps max 1  6472c52d682 
 temps max 2  6472fa35c26 
duree du test 259.450819 s max detecte 17373 µs
#cat /proc/latency_trace 
preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.51-13-DAV06
--------------------------------------------------------------------
 latency: 33 us, #48/48, CPU#1 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:2)
   -----------------
   | task: softirq-timer/1-12 (uid:0 nice:-10 policy:0 rt_prio:0)
   -----------------

                _------=> CPU#            
               / _-----=> irqs-off        
              | / _----=> need-resched    
              || / _---=> hardirq/softirq 
              ||| / _--=> preempt-depth
              |||| /                      
              |||||     delay             
  cmd     pid ||||| time  |   caller      
     \   /    |||||   \   |   /           
 <idle>-0     1Dnh3    0us!: <70617773> (<00726570>)
 <idle>-0     1Dnh3    0us : __trace_start_sched_wakeup (try_to_wake_up)
 <idle>-0     1Dnh3    0us : __trace_start_sched_wakeup <<...>-12>(69 1)
 <idle>-0     1Dnh3    0us : _raw_spin_unlock (try_to_wake_up)
 <idle>-0     1Dnh2    0us : resched_task (try_to_wake_up)
 <idle>-0     1Dnh2    0us+: try_to_wake_up <<...>-12> (69 8c)
 <idle>-0     1Dnh2   22us : _raw_spin_unlock_irqrestore
(try_to_wake_up)
 <idle>-0     1Dnh1   22us : preempt_schedule (try_to_wake_up)
 <idle>-0     1Dnh1   22us : wake_up_process (trigger_softirqs)
 <idle>-0     1Dnh.   23us : preempt_schedule_irq (need_resched)
 <idle>-0     1Dnh.   23us : __schedule (preempt_schedule_irq)
 <idle>-0     1Dnh.   23us : profile_hit (__schedule)
 <idle>-0     1Dnh1   23us : sched_clock (__schedule)
 <idle>-0     1Dnh1   23us : _raw_spin_lock_irq (__schedule)
 <idle>-0     1Dnh1   24us : _raw_spin_lock_irqsave (__schedule)
 <idle>-0     1Dnh2   24us : pull_rt_tasks (__schedule)
 <idle>-0     1Dnh2   24us : double_lock_balance (pull_rt_tasks)
 <idle>-0     1Dnh2   24us : _raw_spin_trylock (double_lock_balance)
 <idle>-0     1Dnh3   25us : pick_rt_task (pull_rt_tasks)
 <idle>-0     1Dnh3   25us : find_next_bit (pick_rt_task)
 <idle>-0     1Dnh3   25us : find_next_bit (pick_rt_task)
 <idle>-0     1Dnh3   25us : find_next_bit (pick_rt_task)
 <idle>-0     1Dnh3   25us : _raw_spin_unlock (pull_rt_tasks)
 <idle>-0     1Dnh2   26us : preempt_schedule (pull_rt_tasks)
 <idle>-0     1Dnh2   26us : find_next_bit (pull_rt_tasks)
 <idle>-0     1Dnh2   26us : find_next_bit (pull_rt_tasks)
 <idle>-0     1Dnh2   26us : dependent_sleeper (__schedule)
 <idle>-0     1Dnh2   26us : _raw_spin_unlock (dependent_sleeper)
 <idle>-0     1Dnh1   27us : preempt_schedule (dependent_sleeper)
 <idle>-0     1Dnh1   27us : _raw_spin_lock (dependent_sleeper)
 <idle>-0     1Dnh2   27us : find_next_bit (dependent_sleeper)
 <idle>-0     1Dnh2   27us : dequeue_task (__schedule)
 <idle>-0     1Dnh2   27us : recalc_task_prio (__schedule)
 <idle>-0     1Dnh2   28us : effective_prio (recalc_task_prio)
 <idle>-0     1Dnh2   28us : enqueue_task (__schedule)
 <idle>-0     1Dnh2   28us : trace_array (__schedule)
 <idle>-0     1Dnh2   29us : trace_array <<...>-12> (69 6e)
 <idle>-0     1Dnh2   29us : trace_array (__schedule)
  <...>-12    1Dnh2   31us : __switch_to (__schedule)
  <...>-12    1Dnh2   31us : __schedule <<idle>-0> (8c 69)
  <...>-12    1Dnh2   31us : finish_task_switch (__schedule)
  <...>-12    1Dnh2   31us : _raw_spin_unlock (finish_task_switch)
  <...>-12    1Dnh1   32us : trace_stop_sched_switched
(finish_task_switch)
  <...>-12    1Dnh1   32us : _raw_spin_lock (trace_stop_sched_switched)
  <...>-12    1Dnh2   32us : trace_stop_sched_switched <<...>-12>(69 1)
  <...>-12    1Dnh2   32us : trace_stop_sched_switched
(finish_task_switch)


vim:ft=help


My Question is : where is the time missing ?

Re: PREEMPT_RT and latency_trace

[Daniel Walker]

On Fri, 2005-07-08 at 14:49 +0200, Serge Noiraud wrote:
> Hi,
> 
> I have a big dilemna on one machine :
> I run a task with RT priority which make a loop to mesure the system
> perturbation.
> It works well except on  one machine.
> On a multi-cpu, If I run the program on cpu 1, I get 23us. It's OK.
> If I run the same program on cpu 0, I get 17373us !

If it's not at RT priority 99 , then your application could be held off
until higher priority applications have run. 17373us is a pretty long
hold off time though .

Daniel

Re: PREEMPT_RT and latency_trace

[Ingo Molnar]

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


* Serge Noiraud <serge.noiraud@bull.net> wrote:

> Hi,
> 
> I have a big dilemna on one machine :
> I run a task with RT priority which make a loop to mesure the system
> perturbation.
> It works well except on  one machine.
> On a multi-cpu, If I run the program on cpu 1, I get 23us. It's OK.
> If I run the same program on cpu 0, I get 17373us !
> If I do :
> # echo 0 >/proc/sys/kernel/preempt_max_latency

you can start/stop tracing from userspace too. Then you'll see what 
happens. See the attached trace-it.c code. After having activated 
user-triggered tracing, do something like this in your testcode:

	for (;;) {
	        gettimeofday(0, 1);
        	gettimeofday(0, 0);
	}

this should measure the maximum userspace delay on that CPU. You can 
also read the TSC in the inner loop to validate the kernel tracer:

	for (;;) {
	        gettimeofday(0, 1);
		t0 = rdtsc();
		t1 = rdtsc();
        	gettimeofday(0, 0);
		if (t1-t0 > max)
			print_max();
	}

(you should not measure the trace start/stop functions themselves, they 
can take alot of time when a maximum-latency event happens.)

	Ingo

[-- Attachment #2: trace-it.c --]
[-- Type: text/plain, Size: 1183 bytes --]


/*
 * Copyright (C) 1999, Ingo Molnar <mingo@redhat.com>
 */

#include <unistd.h>
#include <stdio.h>
#include <stdlib.h>
#include <signal.h>
#include <sys/wait.h>
#include <linux/unistd.h>

int main (int argc, char **argv)
{
	int ret;

	if (getuid() != 0) {
		fprintf(stderr, "needs to run as root.\n");
		exit(1);
	}
	ret = system("cat /proc/sys/kernel/mcount_enabled >/dev/null 2>/dev/null");
	if (ret) {
		fprintf(stderr, "CONFIG_LATENCY_TRACING not enabled?\n");
		exit(1);
	}
	system("echo 1 > /proc/sys/kernel/trace_all_cpus");
	system("echo 1 > /proc/sys/kernel/trace_enabled");
	system("echo 0 > /proc/sys/kernel/trace_freerunning");
	system("echo 0 > /proc/sys/kernel/trace_print_at_crash");
	system("echo 1 > /proc/sys/kernel/trace_user_triggered");
	system("echo 0 > /proc/sys/kernel/trace_verbose");
	system("echo 0 > /proc/sys/kernel/preempt_max_latency");
	system("echo 0 > /proc/sys/kernel/preempt_thresh");
	system("[ -e /proc/sys/kernel/wakeup_timing ] && echo 0 > /proc/sys/kernel/wakeup_timing");
	system("echo 1 > /proc/sys/kernel/mcount_enabled");

	gettimeofday(0, 1);
	usleep(100000);
	gettimeofday(0, 0);

	system("cat /proc/latency_trace");

	return 0;
}

Re: PREEMPT_RT and latency_trace

[Ingo Molnar]

* Serge Noiraud <serge.noiraud@bull.net> wrote:

> Hi,
> 
> I have a big dilemna on one machine :
> I run a task with RT priority which make a loop to mesure the system
> perturbation.
> It works well except on  one machine.
> On a multi-cpu, If I run the program on cpu 1, I get 23us. It's OK.
> If I run the same program on cpu 0, I get 17373us !

could you try the -51-24 (or later) kernel, does it have any better 
latencies? It has a PI fix that fixes the recent priority leakage 
observed on SMP systems. The priority leakage can lead to excessive 
delays in RT apps.

	Ingo