Re: Realtime Preemption, 2.6.12, Beginners Guide?

[Alistair John Strachan <s0348365@sms.ed.ac.uk>]

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

On Wednesday 06 Jul 2005 22:02, Ingo Molnar wrote:
> * Alistair John Strachan <s0348365@sms.ed.ac.uk> wrote:
> > This is a completely unrelated question, but now we've got everything
> > under control.. how do I make "quiet" actually do something on the RT
> > patchset?
> >
> > Currently I flag it on the kernel cmdline, but I still get everything
> > spewed to my primary VT.
>
> do you have CONFIG_PRINTK_IGNORE_LOGLEVEL enabled perhaps?

Good idea, but nope. Find attached the config I'm using, and here's the output 
from /proc/cmdline:

[alistair] 23:07 [~] cat /proc/cmdline
BOOT_IMAGE=2.6.12rt ro root=301 acpi_sleep=s3_bios lapic quiet

[alistair] 23:07 [~] uname -r
2.6.12-RT-V0.7.51-06

What I see are the kernel messages pre-init not suppressed (like I think they 
should be with quiet) and spurious noise from usb, etc. as the system boots 
up. sysklogd starts up but the messages are still duplicated on the console.

Maybe my configuration is subtlely broken. Is anybody else experiencing this?

By the way, I've been hammering the machine with the RT fixups and so far I've 
only been able to get a ~50us maximum; everything seems to be working fine. 
Find attached a final trace with the minimum kernel options enabled to get 
it.

-- 
Cheers,
Alistair.

personal:   alistair()devzero!co!uk
university: s0348365()sms!ed!ac!uk
student:    CS/CSim Undergraduate
contact:    1F2 55 South Clerk Street,
            Edinburgh. EH8 9PP.

[-- Attachment #2: trace --]
[-- Type: text/plain, Size: 6384 bytes --]

preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.51-06
--------------------------------------------------------------------
 latency: 54 us, #93/93, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:1)
    -----------------
    | task: softirq-net-rx/-5 (uid:0 nice:-10 policy:0 rt_prio:0)
    -----------------

                 _------=> CPU#            
                / _-----=> irqs-off        
               | / _----=> need-resched    
               || / _---=> hardirq/softirq 
               ||| / _--=> preempt-depth   
               |||| /                      
               |||||     delay             
   cmd     pid ||||| time  |   caller      
      \   /    |||||   \   |   /           
   <...>-3142  0dnh2    0us!: <5f6f696b> (<70747468>)
   <...>-3142  0dnh2    0us : __trace_start_sched_wakeup (try_to_wake_up)
   <...>-3142  0dnh2    0us : __trace_start_sched_wakeup <softirq--5> (69 0)
   <...>-3142  0dnh1    1us+: try_to_wake_up <softirq--5> (69 76)
   <...>-3142  0dnh.    4us : do_IRQ (c0117743 0 0)
   <...>-3142  0dnh.    5us : __local_irq_save (__do_IRQ)
   <...>-3142  0dnh1    5us+: mask_and_ack_8259A (__do_IRQ)
   <...>-3142  0dnh1   12us : preempt_schedule (__do_IRQ)
   <...>-3142  0dnh1   12us : redirect_hardirq (__do_IRQ)
   <...>-3142  0dnh.   13us : preempt_schedule (__do_IRQ)
   <...>-3142  0dnh.   13us : handle_IRQ_event (__do_IRQ)
   <...>-3142  0dnh.   14us : timer_interrupt (handle_IRQ_event)
   <...>-3142  0dnh1   14us : mark_offset_tsc (timer_interrupt)
   <...>-3142  0dnh1   16us : preempt_schedule (mark_offset_tsc)
   <...>-3142  0dnh1   16us : preempt_schedule (mark_offset_tsc)
   <...>-3142  0dnh1   16us : do_timer (timer_interrupt)
   <...>-3142  0dnh1   17us : update_process_times (timer_interrupt)
   <...>-3142  0dnh1   17us : account_system_time (update_process_times)
   <...>-3142  0dnh1   18us : update_mem_hiwater (update_process_times)
   <...>-3142  0dnh1   19us : run_local_timers (update_process_times)
   <...>-3142  0dnh1   19us : raise_softirq (update_process_times)
   <...>-3142  0dnh1   20us : rcu_check_callbacks (update_process_times)
   <...>-3142  0dnh1   21us : idle_cpu (rcu_check_callbacks)
   <...>-3142  0dnh1   21us : __tasklet_schedule (update_process_times)
   <...>-3142  0dnh1   21us : scheduler_tick (update_process_times)
   <...>-3142  0dnh1   22us : sched_clock (scheduler_tick)
   <...>-3142  0dnh1   22us : preempt_schedule (scheduler_tick)
   <...>-3142  0dnh1   23us : softlockup_tick (timer_interrupt)
   <...>-3142  0dnh.   23us : preempt_schedule (timer_interrupt)
   <...>-3142  0dnh1   24us : note_interrupt (__do_IRQ)
   <...>-3142  0dnh1   24us : end_8259A_irq (__do_IRQ)
   <...>-3142  0dnh1   25us+: enable_8259A_irq (__do_IRQ)
   <...>-3142  0dnh1   28us : preempt_schedule (__do_IRQ)
   <...>-3142  0dnh.   28us : preempt_schedule (__do_IRQ)
   <...>-3142  0dnh.   28us : local_irq_restore (__do_IRQ)
   <...>-3142  0dnh.   29us : irq_exit (do_IRQ)
   <...>-3142  0dnh1   29us : do_softirq (irq_exit)
   <...>-3142  0dnh1   29us : __local_irq_save (do_softirq)
   <...>-3142  0dnh1   30us : __do_softirq (do_softirq)
   <...>-3142  0dnh1   30us : trigger_softirqs (do_softirq)
   <...>-3142  0dnh1   30us : wakeup_softirqd (trigger_softirqs)
   <...>-3142  0dnh1   31us : wake_up_process (trigger_softirqs)
   <...>-3142  0dnh1   31us : try_to_wake_up (wake_up_process)
   <...>-3142  0dnh1   31us : activate_task (try_to_wake_up)
   <...>-3142  0dnh1   32us : sched_clock (activate_task)
   <...>-3142  0dnh1   32us : recalc_task_prio (activate_task)
   <...>-3142  0dnh1   33us : effective_prio (recalc_task_prio)
   <...>-3142  0dnh1   33us : activate_task <<...>-3> (69 4)
   <...>-3142  0dnh1   33us : enqueue_task (activate_task)
   <...>-3142  0dnh1   34us : __trace_start_sched_wakeup (try_to_wake_up)
   <...>-3142  0dnh1   34us : preempt_schedule (try_to_wake_up)
   <...>-3142  0dnh1   34us : try_to_wake_up <<...>-3> (69 76)
   <...>-3142  0dnh1   35us : preempt_schedule (try_to_wake_up)
   <...>-3142  0dnh1   35us : wake_up_process (trigger_softirqs)
   <...>-3142  0dnh1   36us : wakeup_softirqd (trigger_softirqs)
   <...>-3142  0dnh1   36us : wakeup_softirqd (trigger_softirqs)
   <...>-3142  0dnh1   36us : wake_up_process (trigger_softirqs)
   <...>-3142  0dnh1   36us : try_to_wake_up (wake_up_process)
   <...>-3142  0dnh1   37us : activate_task (try_to_wake_up)
   <...>-3142  0dnh1   37us : sched_clock (activate_task)
   <...>-3142  0dnh1   38us : recalc_task_prio (activate_task)
   <...>-3142  0dnh1   38us : effective_prio (recalc_task_prio)
   <...>-3142  0dnh1   38us : activate_task <<...>-7> (69 5)
   <...>-3142  0dnh1   38us : enqueue_task (activate_task)
   <...>-3142  0dnh1   39us : __trace_start_sched_wakeup (try_to_wake_up)
   <...>-3142  0dnh1   39us : preempt_schedule (try_to_wake_up)
   <...>-3142  0dnh1   39us : try_to_wake_up <<...>-7> (69 76)
   <...>-3142  0dnh1   40us : preempt_schedule (try_to_wake_up)
   <...>-3142  0dnh1   40us : wake_up_process (trigger_softirqs)
   <...>-3142  0dnh1   40us : local_irq_restore (do_softirq)
   <...>-3142  0dnh.   41us < (2097760)
   <...>-3142  0dn..   42us : preempt_schedule (try_to_wake_up)
   <...>-3142  0dn..   42us : wake_up_process (trigger_softirqs)
   <...>-3142  0dn..   43us : local_irq_restore (netif_rx)
   <...>-3142  0dn..   43us : get_sample_stats (netif_rx)
   <...>-3142  0dn..   43us : local_irq_restore (netif_rx)
   <...>-3142  0Dn..   44us : preempt_schedule (netif_rx)
   <...>-3142  0Dn..   44us : irqs_disabled (preempt_schedule)
   <...>-3142  0Dnh.   44us : __schedule (preempt_schedule)
   <...>-3142  0Dnh.   45us : profile_hit (__schedule)
   <...>-3142  0Dnh1   45us : sched_clock (__schedule)
   <...>-3142  0Dnh2   46us : dequeue_task (__schedule)
   <...>-3142  0Dnh2   46us : recalc_task_prio (__schedule)
   <...>-3142  0Dnh2   47us : effective_prio (recalc_task_prio)
   <...>-3142  0Dnh2   47us : enqueue_task (__schedule)
softirq--5     0Dnh2   49us : __switch_to (__schedule)
softirq--5     0Dnh2   50us : __schedule <<...>-3142> (76 69)
softirq--5     0Dnh2   50us : finish_task_switch (__schedule)
softirq--5     0Dnh1   51us : trace_stop_sched_switched (finish_task_switch)
softirq--5     0Dnh2   51us : trace_stop_sched_switched <softirq--5> (69 0)
softirq--5     0Dnh2   52us : trace_stop_sched_switched (finish_task_switch)


vim:ft=help

[-- Attachment #3: config.gz --]
[-- Type: application/x-gzip, Size: 8557 bytes --]