RT wakeup woes in Linux 2.6.31.6 on Mac Mini

RT wakeup woes in Linux 2.6.31.6 on Mac Mini

[Greg Steuck]

Hello kernel gurus,

I would appreciate some ideas about reducing wakeup latency for our
real time application. The write up below identifies 3 seemingly
different cases of our task not getting to run long after it is woken
up.

We have a real-timish requirement for feeding a hardware device on
time. To achieve this goal we run a userspace program with SCHED_FIFO
at priority 99. We also set CPU affinity with sys_sched_setaffinity
inside our driver program (rxtest) to get a dedicated core (#1). We
change the affinity of all user processes (i.e. non-kernel threads) on
the system to stay on the other core (#0). Then we ran a bunch of
experiments with wakeup ftrace tracer enabled. Here is the script we
ran:

sudo mount -t debugfs nodev /sys/kernel/debug
cd /sys/kernel/debug/tracing

while : ; do
  sudo sh -c '
      echo wakeup > current_tracer
      echo 0 > tracing_max_latency
      echo 2 > tracing_cpumask
      echo 1 > tracing_enabled
      chrt -f 99 ~/rxtest -logtostderr 2>&1
      echo 0 > tracing_enabled
      cat trace > ~/trace.$$'
done | tee ~/tracing-wakeup-latency

There was some decent disk activity to keep the machine busy while the
script was running (rsync copying kernel source directory). We ran the
experiment some 15000 times and observed the average wakeup latency of
about 276 microseconds. There are however a few outliers that would be
nice to understand.

 Latency (us)	Trace log file
 612	trace.1029
 900	trace.13653
 922	trace.6039

The attachments at http://sites.google.com/a/nest.cx/public/rtwakeup
have machine configuration and full traces. Belows are excerpts from
the trace files:

% egrep '[+!]' trace.*
trace.1029:  <idle>-0       1d.s.    0us :      0:140:R   + [001]
1030:  0:S rxtest
trace.1029:  <idle>-0       1.Nh.   80us+: mii_rw <-nv_update_linkspeed
trace.1029:  <idle>-0       1.Nh.   85us+: delay_tsc <-__delay
trace.1029:  <idle>-0       1.Nh.   97us+: delay_tsc <-__delay
trace.1029:  <idle>-0       1.Nh.  109us+: delay_tsc <-__delay
trace.1029:  <idle>-0       1.Nh.  120us+: delay_tsc <-__delay
...
trace.13653:kblockd/-65      1d.s.    0us :     65:115:R   + [001]
13654:  0:S rxtest
trace.13653:kblockd/-65      1dN..  130us+: kmem_cache_alloc
<-mempool_alloc_slab
trace.13653:kblockd/-65      1dN..  132us+: blk_rq_map_sg <-scsi_init_sgtable
trace.13653:kblockd/-65      1dN..  200us+: blk_rq_map_sg <-scsi_init_sgtable
trace.13653:kblockd/-65      1dN..  264us+: ata_tf_to_fis <-ahci_qc_prep
trace.13653:kblockd/-65      1dN..  289us+: blk_rq_map_sg <-scsi_init_sgtable
trace.13653:kblockd/-65      1dN..  349us+: ata_tf_to_fis <-ahci_qc_prep
...
trace.6039: pdflush-5162    1d.s.    0us :   5162:120:R   + [001]
6040:  0:S rxtest
trace.6039: pdflush-5162    1dN..   61us+: idle_cpu <-irq_exit
trace.6039: pdflush-5162    1dN..  130us!: idle_cpu <-irq_exit
trace.6039: pdflush-5162    1dN..  273us!: idle_cpu <-irq_exit

Thanks
Greg
-- 
nest.cx is Gmail hosted, use PGP for anything private. Key:
http://tinyurl.com/ho8qg
Fingerprint: 5E2B 2D0E 1E03 2046 BEC3  4D50 0B15 42BD 8DF5 A1B0

Re: RT wakeup woes in Linux 2.6.31.6 on Mac Mini

[Steven Rostedt]

Have you tried the -rt kernel?

http://rt.wiki.kernel.org/index.php/Main_Page

On Thu, 2009-11-12 at 15:52 -0800, Greg Steuck wrote:
> Hello kernel gurus,
> 
> I would appreciate some ideas about reducing wakeup latency for our
> real time application. The write up below identifies 3 seemingly
> different cases of our task not getting to run long after it is woken
> up.
> 
> We have a real-timish requirement for feeding a hardware device on
> time. To achieve this goal we run a userspace program with SCHED_FIFO
> at priority 99. We also set CPU affinity with sys_sched_setaffinity
> inside our driver program (rxtest) to get a dedicated core (#1). We
> change the affinity of all user processes (i.e. non-kernel threads) on
> the system to stay on the other core (#0). Then we ran a bunch of
> experiments with wakeup ftrace tracer enabled. Here is the script we
> ran:
> 
> sudo mount -t debugfs nodev /sys/kernel/debug
> cd /sys/kernel/debug/tracing
> 
> while : ; do
>   sudo sh -c '
>       echo wakeup > current_tracer

I think you want "wakeup_rt", since that ignores SCHED_OTHER tasks.
SCHED_OTHER may wake up poorly, and hide the results of your RT task.

>       echo 0 > tracing_max_latency
>       echo 2 > tracing_cpumask
>       echo 1 > tracing_enabled
>       chrt -f 99 ~/rxtest -logtostderr 2>&1
>       echo 0 > tracing_enabled
>       cat trace > ~/trace.$$'
> done | tee ~/tracing-wakeup-latency
> 
> There was some decent disk activity to keep the machine busy while the
> script was running (rsync copying kernel source directory). We ran the
> experiment some 15000 times and observed the average wakeup latency of
> about 276 microseconds. There are however a few outliers that would be
> nice to understand.

If you are not running the -rt kernel, vanilla Linux will give lots of
outliers.

> 
>  Latency (us)	Trace log file
>  612	trace.1029
>  900	trace.13653
>  922	trace.6039
> 
> The attachments at http://sites.google.com/a/nest.cx/public/rtwakeup
> have machine configuration and full traces. Belows are excerpts from
> the trace files:
> 
> % egrep '[+!]' trace.*
> trace.1029:  <idle>-0       1d.s.    0us :      0:140:R   + [001]
> 1030:  0:S rxtest
> trace.1029:  <idle>-0       1.Nh.   80us+: mii_rw <-nv_update_linkspeed
> trace.1029:  <idle>-0       1.Nh.   85us+: delay_tsc <-__delay
> trace.1029:  <idle>-0       1.Nh.   97us+: delay_tsc <-__delay
> trace.1029:  <idle>-0       1.Nh.  109us+: delay_tsc <-__delay
> trace.1029:  <idle>-0       1.Nh.  120us+: delay_tsc <-__delay

Looks like NEED_RESCHED is set, but interrupts are disabled. This is
typical for vanilla linux. I really suggest trying out the latest -rt
patch.

You can get it here:

http://www.kernel.org/pub/linux/kernel/projects/rt/patch-2.6.31.6-rt19.bz2

You can also use my version of ketchup.

~$ wget http://people.redhat.com/srostedt/rt/tools/ketchup-0.9.8-rt3
~$ mv ketchup-0.9.8-rt3 ketchup
~$ chmod +x ketchup
~$ mkdir tmp
~$ cd tmp
tmp$ ../ketchup -r -G -f 2.6.31.6-rt19
tmp$ cd .
linux-2.6.31.6-rt19$ 

-- Steve

> ...
> trace.13653:kblockd/-65      1d.s.    0us :     65:115:R   + [001]
> 13654:  0:S rxtest
> trace.13653:kblockd/-65      1dN..  130us+: kmem_cache_alloc
> <-mempool_alloc_slab
> trace.13653:kblockd/-65      1dN..  132us+: blk_rq_map_sg <-scsi_init_sgtable
> trace.13653:kblockd/-65      1dN..  200us+: blk_rq_map_sg <-scsi_init_sgtable
> trace.13653:kblockd/-65      1dN..  264us+: ata_tf_to_fis <-ahci_qc_prep
> trace.13653:kblockd/-65      1dN..  289us+: blk_rq_map_sg <-scsi_init_sgtable
> trace.13653:kblockd/-65      1dN..  349us+: ata_tf_to_fis <-ahci_qc_prep
> ...
> trace.6039: pdflush-5162    1d.s.    0us :   5162:120:R   + [001]
> 6040:  0:S rxtest
> trace.6039: pdflush-5162    1dN..   61us+: idle_cpu <-irq_exit
> trace.6039: pdflush-5162    1dN..  130us!: idle_cpu <-irq_exit
> trace.6039: pdflush-5162    1dN..  273us!: idle_cpu <-irq_exit
> 
> Thanks
> Greg

Re: RT wakeup woes in Linux 2.6.31.6 on Mac Mini

[Greg Steuck]

Hi Steven,

Thanks for your reply. I believe the answer to my outliers question is
- that's normal. I am lucky enough that 1ms delay is acceptable for my
project and so I can stick with vanilla kernel for now.

On Thu, Nov 12, 2009 at 4:14 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> Have you tried the -rt kernel?

I have now.

> I think you want "wakeup_rt", since that ignores SCHED_OTHER tasks.
> SCHED_OTHER may wake up poorly, and hide the results of your RT task.

Yes, done that now.

> Looks like NEED_RESCHED is set, but interrupts are disabled. This is
> typical for vanilla linux. I really suggest trying out the latest -rt
> patch.

With -rt9 I see a different set of interesting behaviors. I should
mention that my task needs to send network packets. So, I end up
trying to juggle priorities of  irq/27-eth0, sirq-net-rx/1 and my
rxtest tasks. If I make my task higher priority than the other two, I
get interrupts delayed (because my task is being a hog sometimes). If
I go the other way and my task gets lower priority, I end up with my
task not getting to run when there is a lot of network activity which
ultimately kills it.

Thanks
Greg
-- 
nest.cx is Gmail hosted, use PGP for anything private. Key:
http://tinyurl.com/ho8qg
Fingerprint: 5E2B 2D0E 1E03 2046 BEC3  4D50 0B15 42BD 8DF5 A1B0

Re: RT wakeup woes in Linux 2.6.31.6 on Mac Mini

[Alan Cox]

> trace.13653:kblockd/-65      1dN..  132us+: blk_rq_map_sg <-scsi_init_sgtable
> trace.13653:kblockd/-65      1dN..  200us+: blk_rq_map_sg <-scsi_init_sgtable
> trace.13653:kblockd/-65      1dN..  264us+: ata_tf_to_fis <-ahci_qc_prep
> trace.13653:kblockd/-65      1dN..  289us+: blk_rq_map_sg <-scsi_init_sgtable
> trace.13653:kblockd/-65      1dN..  349us+: ata_tf_to_fis <-ahci_qc_prep

Something very weird with your tracing there ata_tf_to_fis simply moves
20 bytes of memory about. It could be you are hitting some kind of
caching effect with the AHCI controller I guess. Certainly looks odd of
itself.

> ...
> trace.6039: pdflush-5162    1d.s.    0us :   5162:120:R   + [001]
> 6040:  0:S rxtest
> trace.6039: pdflush-5162    1dN..   61us+: idle_cpu <-irq_exit
> trace.6039: pdflush-5162    1dN..  130us!: idle_cpu <-irq_exit
> trace.6039: pdflush-5162    1dN..  273us!: idle_cpu <-irq_exit

What power management do you have enabled ?