Messages in this thread | | | From | Mark_H_Johnson@raytheon ... | Subject | Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15 | Date | Fri, 10 Dec 2004 15:06:43 -0600 |
| |
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@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
| |