Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Mark_H_Johnson]

Comparison of .32-18RT and .32-18PK results
RT has PREEMPT_RT,
PK has PREEMPT_DESKTOP and no threaded IRQ's.
2.4 has lowlat + preempt patches applied

      within 100 usec
       CPU loop (%)   Elapsed Time (sec)    2.4
Test   RT     PK        RT      PK   |   CPU  Elapsed
X     90.40 100.00&     73 *    64+  |  97.20   70
top   78.56 100.00&     39 *    31+  |  97.48   29
neto  92.82 100.00&    350 *   184+  |  96.23   36
neti  90.69 100.00&    350 *   170+  |  95.86   41
diskw 82.96  99.99     360 *    61+  |  77.64   29
diskc 91.41  99.34     350 *   310+  |  84.12   77
diskr 88.41  99.96     360 *   310+  |  90.66   86
total                 1881    1130   |         368
 [higher is better]  [lower is better]
* wide variation in audio duration
+ long stretch of audio duration "too fast"
& 100% to digits shown, had a FEW samples > 100 usec.

WOW! Look at the 100% values measured on -18PK. The performance
of 2.6 with PREEMPT_DESKTOP is far better than 2.4 preempt+lowlat
in every way except the non RT starvation problem. Something
fixed between -12 and -18 really made a big improvement.

It is still disturbing to see the worse results for -18RT
and I wish I knew what the cause was. Perhaps the traces I sent
earlier can provide a clue.

Other notes:

[1] -PK has many more latency traces > 250 usec [some MUCH longer]
than -RT. I ended up collecting more traces for -RT since I set
the limit to 100 usec, but only got about 8 > 250 usec traces
compared to 40 for -PK.

[2] Some of the traces in -PK are extremely long (up to 2 msec) and
I guess I'm glad I have an SMP system to run the RT application on
the other CPU. Here's an extract of one example:

reemption latency trace v1.1.4 on 2.6.10-rc2-mm3-V0.7.32-18PK
--------------------------------------------------------------------
 latency: 1698 us, #3137/3137, CPU#0 | (M:preempt VP:0, KP:1, SP:0 HP:0
#P:2)
    -----------------
    | task: kjournald-1203 (uid:0 nice:0 policy:0 rt_prio:0)
    -----------------

                 _------=> CPU#
                / _-----=> irqs-off
               | / _----=> need-resched
               || / _---=> hardirq/softirq
               ||| / _--=> preempt-depth
               |||| /
               |||||     delay
   cmd     pid ||||| time  |   caller
      \   /    |||||   \   |   /
<unknown-1203  0d..1    0µs < (54)
<unknown-1203  0...1    0µs : journal_remove_journal_head
(journal_commit_transaction)
<unknown-1203  0...1    1µs : __journal_remove_journal_head
(journal_remove_journal_head)
<unknown-1203  0...1    1µs : __brelse (__journal_remove_journal_head)
<unknown-1203  0...1    1µs : journal_free_journal_head
(journal_remove_journal_head)
<unknown-1203  0...1    1µs : kmem_cache_free (journal_free_journal_head)
<unknown-1203  0d..1    2µs : cache_flusharray (kmem_cache_free)
<unknown-1203  0d..1    2µs : _raw_spin_lock (cache_flusharray)
<unknown-1203  0d..2    2µs+: free_block (cache_flusharray)
<unknown-1203  0d..2    5µs : _raw_spin_unlock (cache_flusharray)
<unknown-1203  0d..1    5µs : memmove (cache_flusharray)
<unknown-1203  0d..1    5µs : memcpy (memmove)
<unknown-1203  0...1    6µs : inverted_lock (journal_commit_transaction)
<unknown-1203  0...1    6µs : __journal_unfile_buffer
(journal_commit_transaction)
<unknown-1203  0...1    7µs : journal_remove_journal_head
(journal_commit_transaction)
<unknown-1203  0...1    7µs : __journal_remove_journal_head
(journal_remove_journal_head)
<unknown-1203  0...1    8µs : __brelse (__journal_remove_journal_head)
<unknown-1203  0...1    8µs : journal_free_journal_head
(journal_remove_journal_head)
<unknown-1203  0...1    8µs : kmem_cache_free (journal_free_journal_head)
<unknown-1203  0...1    9µs : inverted_lock (journal_commit_transaction)
<unknown-1203  0...1    9µs : __journal_unfile_buffer
(journal_commit_transaction)
...
<unknown-1203  0...1  835µs : journal_remove_journal_head
(journal_commit_transaction)
<unknown-1203  0...1  835µs : __journal_remove_journal_head
(journal_remove_journal_head)
<unknown-1203  0...1  836µs : __brelse (__journal_remove_journal_head)
<unknown-1203  0...1  836µs : journal_free_journal_head
(journal_remove_journal_head)
<unknown-1203  0...1  837µs : kmem_cache_free (journal_free_journal_head)
<unknown-1203  0d..1  837µs : cache_flusharray (kmem_cache_free)
<unknown-1203  0d..1  837µs : _raw_spin_lock (cache_flusharray)
<unknown-1203  0d..2  838µs : free_block (cache_flusharray)
<unknown-1203  0d.h2  839µs : do_nmi (__mcount)
<unknown-1203  0d.h2  840µs : do_nmi (<08048340>)
<unknown-1203  0d.h2  840µs+: do_nmi (<00200282>)
<unknown-1203  0d..2  843µs : _raw_spin_unlock (cache_flusharray)
<unknown-1203  0d..1  844µs : memmove (cache_flusharray)
<unknown-1203  0d..1  844µs : memcpy (memmove)
<unknown-1203  0...1  844µs : inverted_lock (journal_commit_transaction)
...
<unknown-1203  0d.h2 1686µs : __mod_timer (ide_execute_command)
<unknown-1203  0d.h2 1686µs : _raw_spin_lock_irqsave (__mod_timer)
<unknown-1203  0d.h3 1687µs : _raw_spin_lock (__mod_timer)
<unknown-1203  0d.h4 1687µs : internal_add_timer (__mod_timer)
<unknown-1203  0d.h4 1687µs : _raw_spin_unlock (__mod_timer)
<unknown-1203  0d.h3 1688µs : _raw_spin_unlock_irqrestore (__mod_timer)
<unknown-1203  0d.h2 1688µs : ide_outbsync (ide_execute_command)
<unknown-1203  0d.h2 1689µs : __const_udelay (ide_execute_command)
<unknown-1203  0d.h2 1690µs : __delay (ide_execute_command)
<unknown-1203  0d.h2 1690µs : delay_tsc (__delay)
<unknown-1203  0d.h2 1691µs : _raw_spin_unlock_irqrestore
(ide_dma_exec_cmd)
<unknown-1203  0..h1 1691µs : ide_dma_start (__ide_do_rw_disk)
<unknown-1203  0..h1 1692µs : ide_inb (ide_dma_start)
<unknown-1203  0..h1 1692µs : ide_outb (ide_dma_start)
<unknown-1203  0..h1 1693µs : _raw_spin_lock_irq (ide_do_request)
<unknown-1203  0..h1 1693µs : _raw_spin_lock_irqsave (ide_do_request)
<unknown-1203  0d.h2 1694µs : _raw_spin_unlock_irqrestore (ide_intr)
<unknown-1203  0d.h1 1695µs : _raw_spin_lock (__do_IRQ)
<unknown-1203  0d.h2 1695µs : note_interrupt (__do_IRQ)
<unknown-1203  0d.h2 1696µs : end_edge_ioapic_irq (__do_IRQ)
<unknown-1203  0d.h2 1696µs : _raw_spin_unlock (__do_IRQ)
<unknown-1203  0d.h1 1696µs : irq_exit (do_IRQ)

[3] The charts are very smooth on -PK, very similar to those on
2.4 other than the "too fast" symptom for the audio duration.
[the white line is shifted down when compared to the nominal
duration yellow line]

[4] -PK also had two of the non RT starvation periods. Each was
almost 3 minutes long (should be a 5 second sleep). -RT had
none.

Will send the traces separately.
  --Mark

-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/