* Re: Losing interrupts
@ 2004-07-16 9:16 Remon Sijrier
2004-07-16 21:00 ` Lee Revell
0 siblings, 1 reply; 7+ messages in thread
From: Remon Sijrier @ 2004-07-16 9:16 UTC (permalink / raw)
To: linux-kernel
[-- Attachment #1: Type: text/plain, Size: 10830 bytes --]
Hello,
First, thanks a lot for the work done and still done for tackling the latency
issues in the kernel.
I'm interested in this area, and want to do some testing as well.
Lee Revel, could you please sent me the changes you made for measuring
interrupt times to me?
I've collected as well some preempt stuff, here it goes: (I've send them also
to Andrew)
While compiling a program:
9ms non-preemptible critical section violated 2 ms preempt threshold starting
at __find_get_block+0x2a/0x110 and ending at __find_get_block+0x4f/0x110
[<c0158f2f>] __find_get_block+0x4f/0x110
[<c011a9f8>] dec_preempt_count+0x118/0x120
[<c0158f2f>] __find_get_block+0x4f/0x110
[<c0158f2f>] __find_get_block+0x4f/0x110
[<c013a6b7>] mempool_alloc+0x87/0x190
[<c0159027>] __getblk+0x37/0x80
[<c01590f7>] __bread+0x27/0x50
[<c01c65d2>] ext3_get_branch+0x72/0xf0
[<c01c6cdb>] ext3_get_block_handle+0xbb/0x390
[<c011ae30>] autoremove_wake_function+0x0/0x60
[<c01c7015>] ext3_get_block+0x65/0xc0
[<c01790a8>] do_mpage_readpage+0x148/0x4a0
[<c0284d02>] pci_bus_write_config_byte+0x52/0x80
[<c013714e>] add_to_page_cache+0x9e/0xc0
[<c011a932>] dec_preempt_count+0x52/0x120
[<c027e949>] radix_tree_preload+0x19/0xb0
[<c027ebad>] radix_tree_insert+0xed/0x110
[<c013714e>] add_to_page_cache+0x9e/0xc0
[<c017954b>] mpage_readpages+0x14b/0x180
[<c01c6fb0>] ext3_get_block+0x0/0xc0
[<c02f88a6>] lba_28_rw_disk+0x86/0x90
[<c013b9bb>] buffered_rmqueue+0x14b/0x1a0
[<c011a932>] dec_preempt_count+0x52/0x120
[<c013ea88>] read_pages+0x138/0x150
[<c01c6fb0>] ext3_get_block+0x0/0xc0
[<c013bd30>] __alloc_pages+0x320/0x390
[<c013ed7c>] do_page_cache_readahead+0xcc/0x1c0
[<c011a932>] dec_preempt_count+0x52/0x120
[<c013edcf>] do_page_cache_readahead+0x11f/0x1c0
[<c013f010>] page_cache_readahead+0x1a0/0x200
[<c0137a74>] do_generic_mapping_read+0x104/0x4f0
[<c0138175>] __generic_file_aio_read+0x205/0x240
[<c0137e60>] file_read_actor+0x0/0x110
[<c013820b>] generic_file_aio_read+0x5b/0x80
[<c0155e80>] do_sync_read+0x80/0xb0
[<c0172bfa>] __inode_dir_notify+0x4a/0xc0
[<c0155f9d>] vfs_read+0xed/0x160
[<c037cd05>] schedule+0x255/0x4a0
[<c0156262>] sys_read+0x42/0x70
[<c0106167>] syscall_call+0x7/0xb
printk: 1 messages suppressed.
7ms non-preemptible critical section violated 2 ms preempt threshold starting
at drain_cpu_caches+0x21/0x70 and ending at drain_cpu_caches+0x2e/0x70
[<c013fc6e>] drain_cpu_caches+0x2e/0x70
[<c011a9f8>] dec_preempt_count+0x118/0x120
[<c013fc6e>] drain_cpu_caches+0x2e/0x70
[<c013fc6e>] drain_cpu_caches+0x2e/0x70
[<c013fcc3>] __cache_shrink+0x13/0xc0
[<c026f9a4>] xfs_inode_shake+0x14/0x30
[<c0142728>] shrink_slab+0x78/0x190
[<c0143cd4>] balance_pgdat+0x1c4/0x210
[<c0143df2>] kswapd+0xd2/0xf0
[<c011ae30>] autoremove_wake_function+0x0/0x60
[<c0106032>] ret_from_fork+0x6/0x14
[<c011ae30>] autoremove_wake_function+0x0/0x60
[<c0143d20>] kswapd+0x0/0xf0
[<c01042ad>] kernel_thread_helper+0x5/0x18
printk: 2 messages suppressed.
8ms non-preemptible critical section violated 2 ms preempt threshold starting
at sys_ioctl+0x61/0x2c0 and ending at sys_ioctl+0xed/0x2c0
[<c016953d>] sys_ioctl+0xed/0x2c0
[<c011a9f8>] dec_preempt_count+0x118/0x120
[<c016953d>] sys_ioctl+0xed/0x2c0
[<c016953d>] sys_ioctl+0xed/0x2c0
[<c0106167>] syscall_call+0x7/0xb
printk: 5 messages suppressed.
9ms non-preemptible critical section violated 2 ms preempt threshold starting
at schedule+0x65/0x4a0 and ending at schedule+0x255/0x4a0
[<c037cd05>] schedule+0x255/0x4a0
[<c011a9f8>] dec_preempt_count+0x118/0x120
[<c037cd05>] schedule+0x255/0x4a0
[<c037cd05>] schedule+0x255/0x4a0
[<d0b42adb>] snd_pcm_playback_poll+0xdb/0x140 [snd_pcm]
[<c011a932>] dec_preempt_count+0x52/0x120
[<c037d4a5>] schedule_timeout+0xb5/0xc0
[<c016a76b>] do_pollfd+0x5b/0xa0
[<c016a858>] do_poll+0xa8/0xd0
[<c016a9e1>] sys_poll+0x161/0x240
[<c0169d10>] __pollwait+0x0/0xd0
[<c0106167>] syscall_call+0x7/0xb
While starting openoffice.org:
8ms non-preemptible critical section violated 2 ms preempt threshold starting
at __find_get_block+0x2a/0x110 and ending at __find_get_block+0x4f/0x110
[<c0158f2f>] __find_get_block+0x4f/0x110
[<c011a9f8>] dec_preempt_count+0x118/0x120
[<c0158f2f>] __find_get_block+0x4f/0x110
[<c0158f2f>] __find_get_block+0x4f/0x110
[<c0157450>] bh_wake_function+0x0/0x40
[<c0159027>] __getblk+0x37/0x80
[<c01c94c0>] ext3_get_inode_loc+0x60/0x270
[<c01c9765>] ext3_read_inode+0x35/0x300
[<c0171272>] iget_locked+0xa2/0xe0
[<c01cb9aa>] ext3_lookup+0x9a/0xd0
[<c01642b5>] real_lookup+0xd5/0x100
[<c0164566>] do_lookup+0x96/0xb0
[<c0164b03>] link_path_walk+0x583/0xb00
[<c0165320>] path_lookup+0x80/0x150
[<c011a932>] dec_preempt_count+0x52/0x120
[<c0161300>] open_exec+0x30/0x100
[<c013b914>] buffered_rmqueue+0xa4/0x1a0
[<c0137523>] find_get_page+0x33/0x60
[<c0162360>] do_execve+0x20/0x290
[<c0137523>] find_get_page+0x33/0x60
[<c01387e7>] filemap_nopage+0x217/0x3b0
[<c0147470>] do_no_page+0x190/0x350
[<c011a932>] dec_preempt_count+0x52/0x120
[<c0147470>] do_no_page+0x190/0x350
[<c0147830>] handle_mm_fault+0xe0/0x190
[<c0117f0c>] do_page_fault+0x36c/0x55e
[<c0281ac8>] copy_to_user+0x48/0x60
[<c012933a>] sys_rt_sigaction+0xaa/0xc0
[<c0281703>] strncpy_from_user+0x43/0x70
[<c0163e28>] getname+0x98/0xd0
[<c0104c52>] sys_execve+0x42/0x80
[<c0106167>] syscall_call+0x7/0xb
With xrun_debug = 2
XRUN: pcmC0D0p
[<d0b458a7>] snd_pcm_period_elapsed+0x2d7/0x430 [snd_pcm]
[<c0124444>] update_process_times+0x44/0x50
[<d0b557ca>] snd_ice1712_interrupt+0x1da/0x270 [snd_ice1712]
[<c0108419>] handle_IRQ_event+0x49/0x80
[<c01087c3>] do_IRQ+0x93/0x130
[<c0106a78>] common_interrupt+0x18/0x20
[<c0111e84>] delay_pmtmr+0x14/0x20
[<c027ef32>] __delay+0x12/0x20
[<c030abbc>] atkbd_sendbyte+0x4c/0x90
[<c030add9>] atkbd_command+0x1d9/0x1f0
[<c030b051>] atkbd_event+0x261/0x2f0
[<c0308bed>] input_event+0x14d/0x410
[<c02bbbb8>] kbd_bh+0xa8/0x190
[<c01207d0>] ksoftirqd+0x0/0xe0
[<c01206a6>] tasklet_action+0x46/0x70
[<c012048b>] __do_softirq+0x7b/0x80
[<c01204b7>] do_softirq+0x27/0x30
[<c012084a>] ksoftirqd+0x7a/0xe0
[<c012f22a>] kthread+0xaa/0xb0
[<c012f180>] kthread+0x0/0xb0
[<c01042ad>] kernel_thread_helper+0x5/0x18
39ms non-preemptible critical section violated 2 ms preempt threshold starting
at ksoftirqd+0x75/0xe0 and ending at ksoftirqd+0x7f/0xe0
[<c012084f>] ksoftirqd+0x7f/0xe0
[<c0119b09>] dec_preempt_count+0x119/0x120
[<c012084f>] ksoftirqd+0x7f/0xe0
[<c01207d0>] ksoftirqd+0x0/0xe0
[<c012084f>] ksoftirqd+0x7f/0xe0
[<c012f22a>] kthread+0xaa/0xb0
[<c012f180>] kthread+0x0/0xb0
[<c01042ad>] kernel_thread_helper+0x5/0x18
XRUN: pcmC0D0p
[<d0b458a7>] snd_pcm_period_elapsed+0x2d7/0x430 [snd_pcm]
[<c0124444>] update_process_times+0x44/0x50
[<d0b557ca>] snd_ice1712_interrupt+0x1da/0x270 [snd_ice1712]
[<c0108419>] handle_IRQ_event+0x49/0x80
[<c01087c3>] do_IRQ+0x93/0x130
[<c0106a78>] common_interrupt+0x18/0x20
[<c0111e84>] delay_pmtmr+0x14/0x20
[<c027ef32>] __delay+0x12/0x20
[<c030abbc>] atkbd_sendbyte+0x4c/0x90
[<c030add9>] atkbd_command+0x1d9/0x1f0
[<c030b051>] atkbd_event+0x261/0x2f0
[<c0308bed>] input_event+0x14d/0x410
[<c02bbbb8>] kbd_bh+0xa8/0x190
[<c01207d0>] ksoftirqd+0x0/0xe0
[<c01206a6>] tasklet_action+0x46/0x70
[<c012048b>] __do_softirq+0x7b/0x80
[<c01204b7>] do_softirq+0x27/0x30
[<c012084a>] ksoftirqd+0x7a/0xe0
[<c012f22a>] kthread+0xaa/0xb0
[<c012f180>] kthread+0x0/0xb0
[<c01042ad>] kernel_thread_helper+0x5/0x18
39ms non-preemptible critical section violated 2 ms preempt threshold starting
at ksoftirqd+0x75/0xe0 and ending at ksoftirqd+0x7f/0xe0
[<c012084f>] ksoftirqd+0x7f/0xe0
[<c0119b09>] dec_preempt_count+0x119/0x120
[<c012084f>] ksoftirqd+0x7f/0xe0
[<c01207d0>] ksoftirqd+0x0/0xe0
[<c012084f>] ksoftirqd+0x7f/0xe0
[<c012f22a>] kthread+0xaa/0xb0
[<c012f180>] kthread+0x0/0xb0
[<c01042ad>] kernel_thread_helper+0x5/0x18
XRUN: pcmC0D0p
[<d0b458a7>] snd_pcm_period_elapsed+0x2d7/0x430 [snd_pcm]
[<c0124444>] update_process_times+0x44/0x50
[<d0b557ca>] snd_ice1712_interrupt+0x1da/0x270 [snd_ice1712]
[<c0108419>] handle_IRQ_event+0x49/0x80
[<c01087c3>] do_IRQ+0x93/0x130
[<c0106a78>] common_interrupt+0x18/0x20
[<c0111e86>] delay_pmtmr+0x16/0x20
[<c027ef32>] __delay+0x12/0x20
[<c030abbc>] atkbd_sendbyte+0x4c/0x90
[<c030add9>] atkbd_command+0x1d9/0x1f0
[<c030b051>] atkbd_event+0x261/0x2f0
[<c0308bed>] input_event+0x14d/0x410
[<c02bbbb8>] kbd_bh+0xa8/0x190
[<c01207d0>] ksoftirqd+0x0/0xe0
[<c01206a6>] tasklet_action+0x46/0x70
[<c012048b>] __do_softirq+0x7b/0x80
[<c01204b7>] do_softirq+0x27/0x30
[<c012084a>] ksoftirqd+0x7a/0xe0
[<c012f22a>] kthread+0xaa/0xb0
[<c012f180>] kthread+0x0/0xb0
[<c01042ad>] kernel_thread_helper+0x5/0x18
40ms non-preemptible critical section violated 2 ms preempt threshold starting
at ksoftirqd+0x75/0xe0 and ending at ksoftirqd+0x7f/0xe0
[<c012084f>] ksoftirqd+0x7f/0xe0
[<c0119b09>] dec_preempt_count+0x119/0x120
[<c012084f>] ksoftirqd+0x7f/0xe0
[<c01207d0>] ksoftirqd+0x0/0xe0
[<c012084f>] ksoftirqd+0x7f/0xe0
[<c012f22a>] kthread+0xaa/0xb0
[<c012f180>] kthread+0x0/0xb0
[<c01042ad>] kernel_thread_helper+0x5/0x18
XRUN: pcmC0D0p
[<d0b458a7>] snd_pcm_period_elapsed+0x2d7/0x430 [snd_pcm]
[<c0124444>] update_process_times+0x44/0x50
[<d0b557ca>] snd_ice1712_interrupt+0x1da/0x270 [snd_ice1712]
[<c0108419>] handle_IRQ_event+0x49/0x80
[<c01087c3>] do_IRQ+0x93/0x130
[<c0106a78>] common_interrupt+0x18/0x20
[<c037007b>] xfrm_state_find+0x56b/0xad0
[<c0111e86>] delay_pmtmr+0x16/0x20
[<c027ef32>] __delay+0x12/0x20
[<c030abbc>] atkbd_sendbyte+0x4c/0x90
[<c030add9>] atkbd_command+0x1d9/0x1f0
[<c030b051>] atkbd_event+0x261/0x2f0
[<c0308bed>] input_event+0x14d/0x410
[<c02bbbb8>] kbd_bh+0xa8/0x190
[<c01206a6>] tasklet_action+0x46/0x70
[<c012048b>] __do_softirq+0x7b/0x80
[<c01204b7>] do_softirq+0x27/0x30
[<c0114955>] smp_apic_timer_interrupt+0xc5/0x100
[<c0106a9a>] apic_timer_interrupt+0x1a/0x20
And these I'm getting the most frequently and most often:
7ms non-preemptible critical section violated 2 ms preempt threshold starting
at ksoftirqd+0x75/0xe0 and ending at ksoftirqd+0x7f/0xe0
[<c01217af>] ksoftirqd+0x7f/0xe0
[<c011a9f8>] dec_preempt_count+0x118/0x120
[<c01217af>] ksoftirqd+0x7f/0xe0
[<c0121730>] ksoftirqd+0x0/0xe0
[<c01217af>] ksoftirqd+0x7f/0xe0
[<c013022a>] kthread+0xaa/0xb0
[<c0130180>] kthread+0x0/0xb0
[<c01042ad>] kernel_thread_helper+0x5/0x18
I've used the voluntary_preempt patch, but it looks like there's no
difference. Both with/without kernel preempt and with/without
voluntary_preempt I'm getting the same results.
I used ck6 which includes all patches from Andrew as well.
I don't know if it is usefull, but I attached the startup dmesg log.
Thanks a lot, and hopefully you can do something with this information.
Remon
[-- Attachment #2: dmesg_startup.log --]
[-- Type: text/x-log, Size: 12947 bytes --]
Linux version 2.6.8-rc1-ck6 (root@lute) (gcc versie 3.3.4 (Debian)) #1 Thu Jul 15 19:41:59 CEST 2004
BIOS-provided physical RAM map:
BIOS-e820: 0000000000000000 - 000000000009f800 (usable)
BIOS-e820: 000000000009f800 - 00000000000a0000 (reserved)
BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
BIOS-e820: 0000000000100000 - 000000000ffeb000 (usable)
BIOS-e820: 000000000ffeb000 - 000000000ffef000 (ACPI data)
BIOS-e820: 000000000ffef000 - 000000000ffff000 (reserved)
BIOS-e820: 000000000ffff000 - 0000000010000000 (ACPI NVS)
BIOS-e820: 00000000fff80000 - 0000000100000000 (reserved)
0MB HIGHMEM available.
255MB LOWMEM available.
On node 0 totalpages: 65515
DMA zone: 4096 pages, LIFO batch:1
Normal zone: 61419 pages, LIFO batch:14
HighMem zone: 0 pages, LIFO batch:1
DMI 2.3 present.
ACPI: RSDP (v000 ASUS ) @ 0x000f7b10
ACPI: RSDT (v001 ASUS CUSL2 0x30303031 MSFT 0x31313031) @ 0x0ffeb000
ACPI: FADT (v001 ASUS CUSL2 0x30303031 MSFT 0x31313031) @ 0x0ffeb080
ACPI: BOOT (v001 ASUS CUSL2 0x30303031 MSFT 0x31313031) @ 0x0ffeb040
ACPI: DSDT (v001 ASUS CUSL2 0x00001000 MSFT 0x0100000b) @ 0x00000000
ACPI: PM-Timer IO Port: 0xe408
Built 1 zonelists
Kernel command line: BOOT_IMAGE=Linux root=210c preempt_threshold=1 elevator=cfq
Local APIC disabled by BIOS -- reenabling.
Found and enabled local APIC!
Initializing CPU#0
PID hash table entries: 1024 (order 10: 8192 bytes)
Detected 808.139 MHz processor.
Using pmtmr for high-res timesource
Console: colour VGA+ 80x25
Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
Memory: 254996k/262060k available (2554k kernel code, 6332k reserved, 868k data, 172k init, 0k highmem, 0k BadRAM)
Checking if this processor honours the WP bit even in supervisor mode... Ok.
Calibrating delay loop... 1601.53 BogoMIPS
Security Scaffold v1.0.0 initialized
Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
CPU: After generic identify, caps: 0383fbff 00000000 00000000 00000000
CPU: After vendor identify, caps: 0383fbff 00000000 00000000 00000000
CPU: L1 I cache: 16K, L1 D cache: 16K
CPU: L2 cache: 128K
CPU: After all inits, caps: 0383fbff 00000000 00000000 00000040
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#0.
CPU: Intel Celeron (Coppermine) stepping 0a
Enabling fast FPU save and restore... done.
Enabling unmasked SIMD FPU exception support... done.
Checking 'hlt' instruction... OK.
Generic cache decay timeout: 2 msecs.
enabled ExtINT on CPU#0
ESR value before enabling vector: 00000000
ESR value after enabling vector: 00000000
Using local APIC timer interrupts.
calibrating APIC timer ...
..... CPU clock speed is 807.0799 MHz.
..... host bus clock speed is 100.0974 MHz.
NET: Registered protocol family 16
PCI: PCI BIOS revision 2.10 entry at 0xf0df0, last bus=2
PCI: Using configuration type 1
mtrr: v2.0 (20020519)
ACPI: Subsystem revision 20040326
ACPI: IRQ9 SCI: Level Trigger.
ACPI-0165: *** Error: No object was returned from [\_SB_.PCI0.PX40.UAR2._STA] (Node cff46220), AE_NOT_EXIST
ACPI: Interpreter enabled
ACPI: Using PIC for interrupt routing
ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 6 7 9 10 *11 12 14 15)
ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 5 6 7 9 *10 11 12 14 15)
ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 *5 6 7 9 10 11 12 14 15)
ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 6 7 *9 10 11 12 14 15)
ACPI: PCI Interrupt Link [LNKE] (IRQs 3 4 5 6 7 *9 10 11 12 14 15)
ACPI: PCI Interrupt Link [LNKF] (IRQs 3 4 5 6 7 9 10 11 12 14 15) *0, disabled.
ACPI: PCI Interrupt Link [LNKG] (IRQs 3 4 5 6 7 *9 10 11 12 14 15)
ACPI: PCI Interrupt Link [LNKH] (IRQs 3 4 5 6 7 *9 10 11 12 14 15)
ACPI: PCI Root Bridge [PCI0] (00:00)
PCI: Probing PCI hardware (bus 00)
PCI: Transparent bridge - 0000:00:1e.0
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PCI1._PRT]
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PCI2._PRT]
Linux Plug and Play Support v0.97 (c) Adam Belay
PnPBIOS: Scanning system for PnP BIOS support...
PnPBIOS: Found PnP BIOS installation structure at 0xc00fbe20
PnPBIOS: PnP BIOS version 1.0, entry 0xf0000:0xbe50, dseg 0xf0000
pnp: 00:12: ioport range 0x3f0-0x3f1 has been reserved
pnp: 00:12: ioport range 0xe400-0xe47f has been reserved
pnp: 00:12: ioport range 0xec00-0xec3f has been reserved
PnPBIOS: 16 nodes reported by PnP BIOS; 16 recorded by driver
PCI: Using ACPI for IRQ routing
ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 9
ACPI: PCI interrupt 0000:00:1f.2[D] -> GSI 9 (level, low) -> IRQ 9
ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 10
ACPI: PCI interrupt 0000:00:1f.3[B] -> GSI 10 (level, low) -> IRQ 10
ACPI: PCI Interrupt Link [LNKH] enabled at IRQ 9
ACPI: PCI interrupt 0000:00:1f.4[C] -> GSI 9 (level, low) -> IRQ 9
ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 11
ACPI: PCI interrupt 0000:01:00.0[A] -> GSI 11 (level, low) -> IRQ 11
ACPI: PCI Interrupt Link [LNKG] enabled at IRQ 9
ACPI: PCI interrupt 0000:02:0a.0[A] -> GSI 9 (level, low) -> IRQ 9
ACPI: PCI Interrupt Link [LNKE] enabled at IRQ 9
ACPI: PCI interrupt 0000:02:0c.0[A] -> GSI 9 (level, low) -> IRQ 9
ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 5
ACPI: PCI interrupt 0000:02:0e.0[A] -> GSI 5 (level, low) -> IRQ 5
Simple Boot Flag at 0x3a set to 0x1
VFS: Disk quotas dquot_6.5.1
Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
devfs: 2004-01-31 Richard Gooch (rgooch@atnf.csiro.au)
devfs: boot_options: 0x0
SGI XFS with ACLs, security attributes, realtime, large block numbers, no debug enabled
SGI XFS Quota Management subsystem
Initializing Cryptographic API
isapnp: Scanning for PnP cards...
isapnp: No Plug & Play device found
Serial: 8250/16550 driver $Revision: 1.90 $ 48 ports, IRQ sharing enabled
ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
Using cfq io scheduler
Floppy drive(s): fd0 is 1.44M
FDC 0 is a post-1991 82077
RAMDISK driver initialized: 16 RAM disks of 8192K size 1024 blocksize
Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
ICH2: IDE controller at PCI slot 0000:00:1f.1
ICH2: chipset revision 1
ICH2: not 100% native mode: will probe irqs later
ide0: BM-DMA at 0x7800-0x7807, BIOS settings: hda:DMA, hdb:pio
ide1: BM-DMA at 0x7808-0x780f, BIOS settings: hdc:DMA, hdd:pio
hda: Hewlett-Packard CD-Writer Plus 8200a, ATAPI CD/DVD-ROM drive
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
hdc: LITEON DVD-ROM LTD-165H, ATAPI CD/DVD-ROM drive
ide1 at 0x170-0x177,0x376 on irq 15
HPT370: IDE controller at PCI slot 0000:02:0a.0
ACPI: PCI interrupt 0000:02:0a.0[A] -> GSI 9 (level, low) -> IRQ 9
HPT370: chipset revision 3
HPT37X: using 33MHz PCI clock
HPT370: 100% native mode on irq 9
ide2: BM-DMA at 0xa400-0xa407, BIOS settings: hde:DMA, hdf:pio
ide3: BM-DMA at 0xa408-0xa40f, BIOS settings: hdg:pio, hdh:pio
hde: ST380023A, ATA DISK drive
ide2 at 0xb800-0xb807,0xb402 on irq 9
hde: max request size: 128KiB
hde: 156301488 sectors (80026 MB) w/2048KiB Cache, CHS=65535/16/63, UDMA(100)
/dev/ide/host2/bus0/target0/lun0: p1 p2 < p5 p6 p7 p8 p9 p10 p11 p12 >
hda: ATAPI 32X CD-ROM CD-R/RW drive, 4096kB Cache, UDMA(33)
Uniform CD-ROM driver Revision: 3.20
hdc: ATAPI 48X DVD-ROM drive, 256kB Cache, UDMA(33)
serio: i8042 AUX port at 0x60,0x64 irq 12
serio: i8042 KBD port at 0x60,0x64 irq 1
input: AT Translated Set 2 keyboard on isa0060/serio0
NET: Registered protocol family 2
IP: routing cache hash table of 2048 buckets, 16Kbytes
TCP: Hash tables configured (established 16384 bind 32768)
NET: Registered protocol family 8
NET: Registered protocol family 20
ACPI: (supports S0 S1 S4 S5)
kjournald starting. Commit interval 5 seconds
EXT3-fs: mounted filesystem with ordered data mode.
VFS: Mounted root (ext3 filesystem) readonly.
Freeing unused kernel memory: 172k freed
NET: Registered protocol family 1
Adding 497972k swap on /dev/hde8. Priority:-1 extents:1
EXT3 FS on hde12, internal journal
Real Time Clock Driver v1.12
input: PS2++ Logitech Wheel Mouse on isa0060/serio1
mice: PS/2 mouse device common for all mice
ts: Compaq touchscreen protocol output
ReiserFS: hde10: found reiserfs format "3.6" with standard journal
ReiserFS: hde10: using ordered data mode
ReiserFS: hde10: journal params: device hde10, size 8192, journal first block 18, max trans len 1024, max batch 900, max commit age 30, max trans age 30
ReiserFS: hde10: checking transaction log (hde10)
ReiserFS: hde10: Using r5 hash to sort names
ReiserFS: hde5: found reiserfs format "3.6" with standard journal
ReiserFS: hde5: using ordered data mode
ReiserFS: hde5: journal params: device hde5, size 8192, journal first block 18, max trans len 1024, max batch 900, max commit age 30, max trans age 30
ReiserFS: hde5: checking transaction log (hde5)
ReiserFS: hde5: Using r5 hash to sort names
XFS mounting filesystem hde9
Ending clean XFS mount for filesystem: hde9
end_request: I/O error, dev fd0, sector 0
parport: PnPBIOS parport detected.
parport0: PC-style at 0x378 (0x778), irq 7, dma 3 [PCSPP,TRISTATE,COMPAT,ECP,DMA]
lp0: using parport0 (interrupt-driven).
via-rhine.c:v1.10-LK1.1.20-2.6 May-23-2004 Written by Donald Becker
ACPI: PCI interrupt 0000:02:0c.0[A] -> GSI 9 (level, low) -> IRQ 9
eth0: VIA Rhine II at 0xa000, 00:05:5d:de:e4:9d, IRQ 9.
eth0: MII PHY found at address 8, status 0x782d advertising 01e1 Link 45e1.
SCSI subsystem initialized
Linux agpgart interface v0.100 (c) Dave Jones
agpgart: Detected an Intel i815 Chipset, but could not find the secondary device.
agpgart: Detected an Intel i815 Chipset.
agpgart: Maximum main memory to use for agp memory: 203M
agpgart: AGP aperture is 64M @ 0xf8000000
cpci_hotplug: CompactPCI Hot Plug Core version: 0.2
pci_hotplug: PCI Hot Plug PCI Core version: 0.5
pciehp: acpi_pciehprm:\_SB_.PCI0 evaluate _BBN fail=0x5
pciehp: acpi_pciehprm:get_device PCI ROOT HID fail=0x5
shpchp: acpi_shpchprm:\_SB_.PCI0 evaluate _BBN fail=0x5
shpchp: acpi_shpchprm:get_device PCI ROOT HID fail=0x5
hw_random hardware driver 1.0.0 loaded
pciehp: acpi_pciehprm:\_SB_.PCI0 evaluate _BBN fail=0x5
pciehp: acpi_pciehprm:get_device PCI ROOT HID fail=0x5
shpchp: acpi_shpchprm:\_SB_.PCI0 evaluate _BBN fail=0x5
shpchp: acpi_shpchprm:get_device PCI ROOT HID fail=0x5
usbcore: registered new driver usbfs
usbcore: registered new driver hub
USB Universal Host Controller Interface driver v2.2
ACPI: PCI interrupt 0000:00:1f.2[D] -> GSI 9 (level, low) -> IRQ 9
uhci_hcd 0000:00:1f.2: Intel Corp. 82801BA/BAM USB (Hub #1)
PCI: Setting latency timer of device 0000:00:1f.2 to 64
uhci_hcd 0000:00:1f.2: irq 9, io base 00007400
uhci_hcd 0000:00:1f.2: new USB bus registered, assigned bus number 1
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 2 ports detected
ACPI: PCI interrupt 0000:00:1f.4[C] -> GSI 9 (level, low) -> IRQ 9
uhci_hcd 0000:00:1f.4: Intel Corp. 82801BA/BAM USB (Hub #2)
PCI: Setting latency timer of device 0000:00:1f.4 to 64
uhci_hcd 0000:00:1f.4: irq 9, io base 00007000
uhci_hcd 0000:00:1f.4: new USB bus registered, assigned bus number 2
hub 2-0:1.0: USB hub found
hub 2-0:1.0: 2 ports detected
usb 2-2: new full speed USB device using address 2
hub 2-2:1.0: USB hub found
hub 2-2:1.0: 4 ports detected
ACPI: PCI interrupt 0000:02:0e.0[A] -> GSI 5 (level, low) -> IRQ 5
eth0: Setting full-duplex based on MII #8 link partner capability of 45e1.
Linux Kernel Card Services
options: [pci] [cardbus] [pm]
Intel ISA PCIC probe: not found.
Device 'i823650' does not have a release() function, it is broken and must be fixed.
Badness in device_release at drivers/base/core.c:85
[<c027e168>] kobject_cleanup+0x98/0xa0
[<c02cfeeb>] platform_device_unregister+0x1b/0x60
[<d0aa53d3>] init_i82365+0x1c3/0x1d9 [i82365]
[<c0134619>] sys_init_module+0x109/0x230
[<c0106167>] syscall_call+0x7/0xb
NET: Registered protocol family 10
Disabled Privacy Extensions on device c0419120(lo)
IPv6 over IPv4 tunneling driver
apm: BIOS version 1.2 Flags 0x03 (Driver version 1.16ac)
apm: overridden by ACPI.
[drm] Initialized radeon 1.11.0 20020828 on minor 0: ATI Technologies Inc Radeon R200 QL [Radeon 8500 LE]
agpgart: Found an AGP 2.0 compliant device at 0000:00:00.0.
agpgart: Putting AGP V2 device at 0000:00:00.0 into 4x mode
agpgart: Putting AGP V2 device at 0000:01:00.0 into 4x mode
[drm] Loading R200 Microcode
eth0: no IPv6 routers present
hde: dma_intr: status=0x51 { DriveReady SeekComplete Error }
hde: dma_intr: error=0x84 { DriveStatusError BadCRC }
hde: dma_intr: status=0x51 { DriveReady SeekComplete Error }
hde: dma_intr: error=0x84 { DriveStatusError BadCRC }
hde: dma_intr: status=0x51 { DriveReady SeekComplete Error }
hde: dma_intr: error=0x84 { DriveStatusError BadCRC }
hde: dma_intr: status=0x51 { DriveReady SeekComplete Error }
hde: dma_intr: error=0x84 { DriveStatusError BadCRC }
ide2: reset: success
^ permalink raw reply [flat|nested] 7+ messages in thread* Re: Losing interrupts
2004-07-16 9:16 Losing interrupts Remon Sijrier
@ 2004-07-16 21:00 ` Lee Revell
2004-07-17 13:29 ` Remon Sijrier
0 siblings, 1 reply; 7+ messages in thread
From: Lee Revell @ 2004-07-16 21:00 UTC (permalink / raw)
To: Remon Sijrier; +Cc: linux-kernel
On Fri, 2004-07-16 at 05:16, Remon Sijrier wrote:
> Hello,
>
> First, thanks a lot for the work done and still done for tackling the latency
> issues in the kernel.
>
> I'm interested in this area, and want to do some testing as well.
> Lee Revel, could you please sent me the changes you made for measuring
> interrupt times to me?
>
It's pretty sloppy, but it is just debugging code. This patch is for
emu10k1, you will have to adapt this to your driver (ice1712).
Basically you just add a couple of fields to the card record to track
the time the last interrupt occurred, and the time elapsed between the
previous two interrupts. Then, if you launch a program like JACK that
should cause the soundcard interrupts to happen at a fixed interval, you
can use some heuristics to figure out whether you have lost an
interrupt.
Also the fscking tabs below have been mangled to spaces, I am not sure
if this is caused by copying from xterm, or pasting into Evolution, but
I am not too happy about it.
Index: include/emu10k1.h
===================================================================
RCS file: /cvsroot/alsa/alsa-kernel/include/emu10k1.h,v
retrieving revision 1.43
diff -u -r1.43 emu10k1.h
--- include/emu10k1.h 1 Jul 2004 09:22:16 -0000 1.43
+++ include/emu10k1.h 16 Jul 2004 20:54:16 -0000
@@ -1003,6 +1003,9 @@
emu10k1_midi_t midi2; /* for audigy */
unsigned int efx_voices_mask[2];
+
+ cycles_t last_interrupt_time;
+ int last_delay;
};
int snd_emu10k1_create(snd_card_t * card,
Index: pci/emu10k1/emupcm.c
===================================================================
RCS file: /cvsroot/alsa/alsa-kernel/pci/emu10k1/emupcm.c,v
retrieving revision 1.29
diff -u -r1.29 emupcm.c
--- pci/emu10k1/emupcm.c 1 Jul 2004 09:22:16 -0000 1.29
+++ pci/emu10k1/emupcm.c 16 Jul 2004 20:51:02 -0000
@@ -37,6 +37,26 @@
static void snd_emu10k1_pcm_interrupt(emu10k1_t *emu, emu10k1_voice_t *voice)
{
emu10k1_pcm_t *epcm;
+ cycles_t then;
+ cycles_t now;
+ int delay;
+ int jitter;
+
+ then = emu->last_interrupt_time;
+ now = get_cycles ();
+ emu->last_interrupt_time = now;
+
+ delay = now - then;
+ jitter = abs( delay - emu->last_delay );
+
+ if (jitter > 50000) {
+ printk("IRQ: delay = %i cycles, jitter = %i\n", delay, jitter);
+ }
+ if (jitter * 2 > emu->last_delay ) {
+ printk("IRQ: delay = %i cycles, jitter = %i - missed an interrupt?\n", delay, jitter);
+ }
+
+ emu->last_delay = delay;
if ((epcm = voice->epcm) == NULL)
return;
@@ -816,6 +836,8 @@
mix->send_volume[1][0] = mix->send_volume[2][1] = 255;
mix->attn[0] = mix->attn[1] = mix->attn[2] = 0xffff;
mix->epcm = epcm;
+ emu->last_interrupt_time = 0;
+ emu->last_delay = 0;
snd_emu10k1_pcm_mixer_notify(emu, substream->number, 1);
return 0;
}
Lee
^ permalink raw reply [flat|nested] 7+ messages in thread* Re: Losing interrupts
2004-07-16 21:00 ` Lee Revell
@ 2004-07-17 13:29 ` Remon Sijrier
0 siblings, 0 replies; 7+ messages in thread
From: Remon Sijrier @ 2004-07-17 13:29 UTC (permalink / raw)
To: Lee Revell; +Cc: linux-kernel
Thanks!
I'm unfortunately not able to work on this for some weeks, I'm not at home.
As soon as I have some results I'll post them here.
Remon
> On Fri, 2004-07-16 at 05:16, Remon Sijrier wrote:
>> Hello,
>>
>> First, thanks a lot for the work done and still done for tackling the
>> latency
>> issues in the kernel.
>>
>> I'm interested in this area, and want to do some testing as well.
>> Lee Revel, could you please sent me the changes you made for measuring
>> interrupt times to me?
>>
>
> It's pretty sloppy, but it is just debugging code. This patch is for
> emu10k1, you will have to adapt this to your driver (ice1712).
> Basically you just add a couple of fields to the card record to track
> the time the last interrupt occurred, and the time elapsed between the
> previous two interrupts. Then, if you launch a program like JACK that
> should cause the soundcard interrupts to happen at a fixed interval, you
> can use some heuristics to figure out whether you have lost an
> interrupt.
>
> Also the fscking tabs below have been mangled to spaces, I am not sure
> if this is caused by copying from xterm, or pasting into Evolution, but
> I am not too happy about it.
>
> Index: include/emu10k1.h
> ===================================================================
> RCS file: /cvsroot/alsa/alsa-kernel/include/emu10k1.h,v
> retrieving revision 1.43
> diff -u -r1.43 emu10k1.h
> --- include/emu10k1.h 1 Jul 2004 09:22:16 -0000 1.43
> +++ include/emu10k1.h 16 Jul 2004 20:54:16 -0000
> @@ -1003,6 +1003,9 @@
> emu10k1_midi_t midi2; /* for audigy */
>
> unsigned int efx_voices_mask[2];
> +
> + cycles_t last_interrupt_time;
> + int last_delay;
> };
>
> int snd_emu10k1_create(snd_card_t * card,
> Index: pci/emu10k1/emupcm.c
> ===================================================================
> RCS file: /cvsroot/alsa/alsa-kernel/pci/emu10k1/emupcm.c,v
> retrieving revision 1.29
> diff -u -r1.29 emupcm.c
> --- pci/emu10k1/emupcm.c 1 Jul 2004 09:22:16 -0000 1.29
> +++ pci/emu10k1/emupcm.c 16 Jul 2004 20:51:02 -0000
> @@ -37,6 +37,26 @@
> static void snd_emu10k1_pcm_interrupt(emu10k1_t *emu, emu10k1_voice_t
> *voice)
> {
> emu10k1_pcm_t *epcm;
> + cycles_t then;
> + cycles_t now;
> + int delay;
> + int jitter;
> +
> + then = emu->last_interrupt_time;
> + now = get_cycles ();
> + emu->last_interrupt_time = now;
> +
> + delay = now - then;
> + jitter = abs( delay - emu->last_delay );
> +
> + if (jitter > 50000) {
> + printk("IRQ: delay = %i cycles, jitter = %i\n", delay,
> jitter);
> + }
> + if (jitter * 2 > emu->last_delay ) {
> + printk("IRQ: delay = %i cycles, jitter = %i - missed an
> interrupt?\n", delay, jitter);
> + }
> +
> + emu->last_delay = delay;
>
> if ((epcm = voice->epcm) == NULL)
> return;
> @@ -816,6 +836,8 @@
> mix->send_volume[1][0] = mix->send_volume[2][1] = 255;
> mix->attn[0] = mix->attn[1] = mix->attn[2] = 0xffff;
> mix->epcm = epcm;
> + emu->last_interrupt_time = 0;
> + emu->last_delay = 0;
> snd_emu10k1_pcm_mixer_notify(emu, substream->number, 1);
> return 0;
> }
>
> Lee
>
>
^ permalink raw reply [flat|nested] 7+ messages in thread
* Losing interrupts
@ 2004-07-14 22:19 Lee Revell
2004-07-15 21:36 ` Lee Revell
2004-07-16 3:24 ` Lee Revell
0 siblings, 2 replies; 7+ messages in thread
From: Lee Revell @ 2004-07-14 22:19 UTC (permalink / raw)
To: linux-kernel; +Cc: alsa-devel
It seems that interrupts are being disabled for long periods, resulting
in the soundcard interrupt being lost. I hacked the ALSA emu10k1 driver
to keep track in the interrupt handler of the number of CPU cycles
elapsed since the last time it ran. I am using a period that
corresponds to 666 microseconds between interrupts, or ~400000 cycles on
my 600Mhz CPU. As you can see the average jitter is *extremely* low -
50-400 CPU cycles of per interrupt. I hardcoded it to printk if the
jitter is more than 15000 (only happens every 5-10 seconds), and error
if it's really big. As you can see, something is disabling interrupts
for a long time. This is a completely different issue from an XRUN,
improving the scheduler latency will not solve this.
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 392256 cycles, jitter = 15387
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 392353 cycles, jitter = 15603
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 391461 cycles, jitter = 16916
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 818180 cycles, jitter = 418547
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 818180 cycles, jitter = 418547 - missed an interrupt?
Jul 14 18:06:08 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa-driver/alsa-kernel/core/pcm_lib.c:199: Unexpected hw_pointer value [1] (stream = 0, delta: -26, max jitter = 32): wrong interrupt
acknowledge?
Jul 14 18:06:08 mindpipe kernel: [dump_stack+23/32] dump_stack+0x17/0x20
Jul 14 18:06:08 mindpipe kernel: [__crc_totalram_pages+664125/3558647] snd_pcm_period_elapsed+0x1a7/0x400 [snd_pcm]
Jul 14 18:06:08 mindpipe kernel: [__crc_totalram_pages+729917/3558647] snd_emu10k1_interrupt+0x337/0x3c0 [snd_emu10k1]
Jul 14 18:06:08 mindpipe kernel: [handle_IRQ_event+51/96] handle_IRQ_event+0x33/0x60
Jul 14 18:06:08 mindpipe kernel: [do_IRQ+165/368] do_IRQ+0xa5/0x170
Jul 14 18:06:08 mindpipe kernel: [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 14 18:06:08 mindpipe kernel: [do_softirq+53/64] do_softirq+0x35/0x40
Jul 14 18:06:08 mindpipe kernel: [do_IRQ+277/368] do_IRQ+0x115/0x170
Jul 14 18:06:08 mindpipe kernel: [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 14 18:06:08 mindpipe kernel:
Jul 14 18:06:08 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa-driver/alsa-kernel/core/pcm_lib.c:199: Unexpected hw_pointer value [1] (stream = 1, delta: -4, max jitter = 32): wrong interrupt
acknowledge?
Jul 14 18:06:08 mindpipe kernel: [dump_stack+23/32] dump_stack+0x17/0x20
Jul 14 18:06:08 mindpipe kernel: [__crc_totalram_pages+664125/3558647] snd_pcm_period_elapsed+0x1a7/0x400 [snd_pcm]
Jul 14 18:06:08 mindpipe kernel: [__crc_totalram_pages+729303/3558647] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
Jul 14 18:06:08 mindpipe kernel: [handle_IRQ_event+51/96] handle_IRQ_event+0x33/0x60
Jul 14 18:06:08 mindpipe kernel: [do_IRQ+165/368] do_IRQ+0xa5/0x170
Jul 14 18:06:08 mindpipe kernel: [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 14 18:06:08 mindpipe kernel: [do_softirq+53/64] do_softirq+0x35/0x40
Jul 14 18:06:08 mindpipe kernel: [do_IRQ+277/368] do_IRQ+0x115/0x170
Jul 14 18:06:08 mindpipe kernel: [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 14 18:06:08 mindpipe kernel:
Jul 14 18:06:08 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D2c
Jul 14 18:06:08 mindpipe kernel: [dump_stack+23/32] dump_stack+0x17/0x20
Jul 14 18:06:08 mindpipe kernel: [__crc_totalram_pages+664413/3558647] snd_pcm_period_elapsed+0x2c7/0x400 [snd_pcm]
Jul 14 18:06:08 mindpipe kernel: [__crc_totalram_pages+729303/3558647] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
Jul 14 18:06:08 mindpipe kernel: [handle_IRQ_event+51/96] handle_IRQ_event+0x33/0x60
Jul 14 18:06:08 mindpipe kernel: [do_IRQ+165/368] do_IRQ+0xa5/0x170
Jul 14 18:06:08 mindpipe kernel: [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 14 18:06:08 mindpipe kernel:
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 4964265 cycles, jitter = 4146085
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 4964265 cycles, jitter = 4146085 - missed an interrupt?
Jul 14 18:06:08 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa-driver/alsa-kernel/core/pcm_lib.c:199: Unexpected hw_pointer value [1] (stream = 0, delta: -14, max jitter = 32): wrong interrupt
acknowledge?
Jul 14 18:06:08 mindpipe kernel: [dump_stack+23/32] dump_stack+0x17/0x20
Jul 14 18:06:08 mindpipe kernel: [__crc_totalram_pages+664125/3558647] snd_pcm_period_elapsed+0x1a7/0x400 [snd_pcm]
Jul 14 18:06:08 mindpipe kernel: [__crc_totalram_pages+729917/3558647] snd_emu10k1_interrupt+0x337/0x3c0 [snd_emu10k1]
Jul 14 18:06:08 mindpipe kernel: [handle_IRQ_event+51/96] handle_IRQ_event+0x33/0x60
Jul 14 18:06:08 mindpipe kernel: [do_IRQ+165/368] do_IRQ+0xa5/0x170
Jul 14 18:06:08 mindpipe kernel: [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 14 18:06:08 mindpipe kernel:
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 1055689 cycles, jitter = 3908576
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 1055689 cycles, jitter = 3908576 - missed an interrupt?
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 362752 cycles, jitter = 692937
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 362752 cycles, jitter = 692937 - missed an interrupt?
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 399829 cycles, jitter = 37077
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 413648 cycles, jitter = 15319
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 387686 cycles, jitter = 25962
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 450250 cycles, jitter = 51838
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 349918 cycles, jitter = 100332
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 400891 cycles, jitter = 50973
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 386404 cycles, jitter = 26320
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 453172 cycles, jitter = 54183
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 347573 cycles, jitter = 105599
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 401149 cycles, jitter = 53576
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 386633 cycles, jitter = 26209
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 449097 cycles, jitter = 49093
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 351560 cycles, jitter = 97537
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 397671 cycles, jitter = 46111
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 389595 cycles, jitter = 21606
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 451106 cycles, jitter = 51236
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 350349 cycles, jitter = 100757
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 400588 cycles, jitter = 50239
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 386300 cycles, jitter = 25946
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 448680 cycles, jitter = 49155
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 351876 cycles, jitter = 96804
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 400708 cycles, jitter = 48832
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 385443 cycles, jitter = 28488
Jul 14 18:06:08 mindpipe kernel: IRQ: delay = 400482 cycles, jitter = 15039
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 387947 cycles, jitter = 23589
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 391951 cycles, jitter = 16855
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 388987 cycles, jitter = 21825
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 392021 cycles, jitter = 16017
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 390522 cycles, jitter = 20142
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 391896 cycles, jitter = 17595
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 388017 cycles, jitter = 23648
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 391085 cycles, jitter = 18631
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 390518 cycles, jitter = 17585
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 390227 cycles, jitter = 18928
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 389163 cycles, jitter = 20901
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 389526 cycles, jitter = 19946
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 389876 cycles, jitter = 19494
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 391128 cycles, jitter = 17707
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 391987 cycles, jitter = 16681
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 390271 cycles, jitter = 18691
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 388294 cycles, jitter = 21678
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 389929 cycles, jitter = 19020
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 390888 cycles, jitter = 18574
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 387801 cycles, jitter = 22866
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 390384 cycles, jitter = 20683
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 391604 cycles, jitter = 17213
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 392076 cycles, jitter = 15074
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 392304 cycles, jitter = 15524
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 388990 cycles, jitter = 20218
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 391993 cycles, jitter = 16200
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 391055 cycles, jitter = 17245
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 391652 cycles, jitter = 15653
Jul 14 18:06:09 mindpipe kernel: IRQ: delay = 391095 cycles, jitter = 17794
Jul 14 18:06:10 mindpipe kernel: IRQ: delay = 392424 cycles, jitter = 15108
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Losing interrupts
2004-07-14 22:19 Lee Revell
@ 2004-07-15 21:36 ` Lee Revell
2004-07-15 21:04 ` Andrew Morton
2004-07-16 3:24 ` Lee Revell
1 sibling, 1 reply; 7+ messages in thread
From: Lee Revell @ 2004-07-15 21:36 UTC (permalink / raw)
To: linux-kernel, Andrew Morton
On Wed, 2004-07-14 at 18:19, Lee Revell wrote:
> It seems that interrupts are being disabled for long periods, resulting
> in the soundcard interrupt being lost. I hacked the ALSA emu10k1 driver
> to keep track in the interrupt handler of the number of CPU cycles
> elapsed since the last time it ran. I am using a period that
> corresponds to 666 microseconds between interrupts, or ~400000 cycles on
> my 600Mhz CPU. As you can see the average jitter is *extremely* low -
> 50-400 CPU cycles of per interrupt. I hardcoded it to printk if the
> jitter is more than 15000 (only happens every 5-10 seconds), and error
> if it's really big. As you can see, something is disabling interrupts
> for a long time. This is a completely different issue from an XRUN,
> improving the scheduler latency will not solve this.
>
The problem is with the video driver (Via CastleRock integrated,
AGP4x). By dragging certain windows around slowly in X, I can reliably
cause interrupts to be completely disabled for tens of milliseconds.
There was an issue several years ago where Matrox figured out they could
get slightly better benchmark scores by not checking whether a FIFO on
the video card was full before writing to it, which would cause the PCI
bus to completely freeze until the FIFO had drained. Lots of vendors
followed suit until one of the audio software vendors figred it out and
called them on it, at which point they fixed their drivers. The effects
(massive audio drouputs) and the steps to reproduce (drag a window
around the screen slowly) were identical.
I will contact the maintainer.
Lee
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Losing interrupts
2004-07-15 21:36 ` Lee Revell
@ 2004-07-15 21:04 ` Andrew Morton
0 siblings, 0 replies; 7+ messages in thread
From: Andrew Morton @ 2004-07-15 21:04 UTC (permalink / raw)
To: Lee Revell; +Cc: linux-kernel
Lee Revell <rlrevell@joe-job.com> wrote:
>
> There was an issue several years ago where Matrox figured out they could
> get slightly better benchmark scores by not checking whether a FIFO on
> the video card was full before writing to it, which would cause the PCI
> bus to completely freeze until the FIFO had drained. Lots of vendors
> followed suit until one of the audio software vendors figred it out and
> called them on it, at which point they fixed their drivers. The effects
> (massive audio drouputs) and the steps to reproduce (drag a window
> around the screen slowly) were identical.
There's an XF86Config incantation which is supposed to prevent this: if you
set it, the driver will poll the FIFO-full bit before actually reading the
FIFO.
hm, according to http://www.xfree86.org/3.3.6/3DLabs3.html, the pci_retry
option _causes_ the bad behaviour, rather than avoiding it.
Oh, well. Have a play with that.
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Losing interrupts
2004-07-14 22:19 Lee Revell
2004-07-15 21:36 ` Lee Revell
@ 2004-07-16 3:24 ` Lee Revell
1 sibling, 0 replies; 7+ messages in thread
From: Lee Revell @ 2004-07-16 3:24 UTC (permalink / raw)
To: linux-kernel; +Cc: alsa-devel, sbenno
On Wed, 2004-07-14 at 18:19, Lee Revell wrote:
> It seems that interrupts are being disabled for long periods, resulting
> in the soundcard interrupt being lost. I hacked the ALSA emu10k1 driver
> to keep track in the interrupt handler of the number of CPU cycles
> elapsed since the last time it ran. I am using a period that
> corresponds to 666 microseconds between interrupts, or ~400000 cycles on
> my 600Mhz CPU. As you can see the average jitter is *extremely* low -
> 50-400 CPU cycles of per interrupt. I hardcoded it to printk if the
> jitter is more than 15000 (only happens every 5-10 seconds), and error
> if it's really big. As you can see, something is disabling interrupts
> for a long time. This is a completely different issue from an XRUN,
> improving the scheduler latency will not solve this.
The problem is with the video driver (Via CastleRock integrated,
AGP4x). By dragging a window in X more quickly than the machine can
keep up with, I can reliably cause interrupts to be completely disabled
for tens or hundreds of milliseconds.
There was an issue several years ago where Matrox figured out they could
get slightly better benchmark scores by not checking whether a FIFO on
the video card was full before writing to it, which would cause the PCI
bus to completely freeze until the FIFO had drained. Lots of vendors
followed suit until one of the audio software vendors figred it out and
called them on it, at which point they fixed their drivers. The effects
(massive audio drouputs) and the steps to reproduce (drag a window
around the screen) were identical.
Is it possible for the XFree86 DRI module to cause this, or would it
have to be in the kernel?
Here is the lspci output:
0000:01:00.0 VGA compatible controller: VIA Technologies, Inc. VT8623 [Apollo CLE266] integrated CastleRock graphics (rev 03) (prog-if 00 [VGA])
Subsystem: VIA Technologies, Inc. VT8623 [Apollo CLE266] integrated CastleRock graphics
Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B-
Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR-
Latency: 32 (500ns min)
Interrupt: pin A routed to IRQ 11
Region 0: Memory at e4000000 (32-bit, prefetchable) [size=64M]
Region 1: Memory at e8000000 (32-bit, non-prefetchable) [size=16M]
Capabilities: [60] Power Management version 2
Flags: PMEClk- DSI+ D1+ D2+ AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
Status: D0 PME-Enable- DSel=0 DScale=0 PME-
Capabilities: [70] AGP version 2.0
Status: RQ=32 Iso- ArqSz=0 Cal=0 SBA+ ITACoh- GART64- HTrans- 64bit- FW- AGP3- Rate=x1,x2,x4
Command: RQ=1 ArqSz=0 Cal=0 SBA- AGP- GART64- 64bit- FW- Rate=<none>
Lee
^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2004-07-17 13:39 UTC | newest]
Thread overview: 7+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2004-07-16 9:16 Losing interrupts Remon Sijrier
2004-07-16 21:00 ` Lee Revell
2004-07-17 13:29 ` Remon Sijrier
-- strict thread matches above, loose matches on Subject: below --
2004-07-14 22:19 Lee Revell
2004-07-15 21:36 ` Lee Revell
2004-07-15 21:04 ` Andrew Morton
2004-07-16 3:24 ` Lee Revell
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox