Re: iommu_iova leak [inside 3w-9xxx]

Re: iommu_iova leak [inside 3w-9xxx]

[Chris Boot]

On 17 Sep 2011, at 12:57, Chris Boot wrote:
> On 17 Sep 2011, at 11:45, Woodhouse, David wrote:
>> On Fri, 2011-09-16 at 13:43 +0100, Chris Boot wrote:
>>> In the very short term the number is up and down by a few hundred 
>>> objects but the general trend is constantly upwards. After about 5 days' 
>>> uptime I have some very serious IO slowdowns (narrowed down by a friend 
>>> to SCSI command queueing) with a lot of time spent in
>>> alloc_iova() and rb_prev() according to 'perf top'. Eventually these 
>>> translate into softlockups and the machine becomes almost unusable.
>> 
>> If you're seeing it spend ages in rb_prev() that implies that the
>> mappings are still *active* and in the rbtree, rather than just the the
>> iommu_iova data structure has been leaked.
>> 
>> I suppose it's vaguely possible that we're leaking them in such a way
>> that they remain on the rbtree, perhaps if the deferred unmap is never
>> actually happening... but I think it's a whole lot more likely that the
>> PCI driver is just never bothering to unmap the pages it maps.
>> 
>> If you boot with 'intel_iommu=strict' that will avoid the deferred unmap
>> which is the only likely culprit in the IOMMU code...
> 
> 
> Booting with intel_iommu=on,strict still shows the iommu_iova on a constant increase, so I don't think it's that.
> 
> I've bodged the following patch to see if it catches anything obvious. We'll see if anything useful comes of it. Sorry, my mail client kills whitespace.


[patch snipped, it's at http://lkml.org/lkml/2011/9/17/23]

David,

With a modified version of the patch (as discussed on IRC) which also takes into account mapping of sg lists, I see that the cause of the spurious mappings is the 3ware-9xxx driver (CCs added). The raw WARNING is below. I get a very large number of these one after the other as well, all nearly identical and within the 3w-9xxx driver.

twa_scsiop_execute_scsi+0x141 is actually twa_map_scsi_sg_data() which has been inlined.

Sep 17 13:40:30 tarquin kernel: [ 1447.334024] ------------[ cut here ]------------
Sep 17 13:40:30 tarquin kernel: [ 1447.347585] WARNING: at drivers/iommu/intel-iommu.c:3088 intel_map_sg+0x1db/0x221()
Sep 17 13:40:30 tarquin kernel: [ 1447.364894] Hardware name: S1200BTL
Sep 17 13:40:30 tarquin kernel: [ 1447.377545] Modules linked in: tun ip6table_mangle iptable_mangle xt_DSCP xt_owner iscsi_target_mod target_core_pscsi target_core_file target_core_iblock target_core_mod configfs ip6table_filter ip6_tables iptable_filter ip_tables ebtable_nat ebtables x_tables cpufreq_stats cpufreq_userspace cpufreq_conservative cpufreq_powersave ipmi_watchdog microcode nfsd nfs lockd fscache auth_rpcgss nfs_acl sunrpc bridge stp ext4 jbd2 crc16 dm_snapshot ipmi_si ipmi_devintf ipmi_msghandler acpi_cpufreq mperf coretemp fuse crc32c_intel aesni_intel cryptd aes_x86_64 aes_generic dm_crypt kvm_intel kvm i2c_i801 snd_pcm snd_timer snd soundcore i2c_core snd_page_alloc joydev ftdi_sio usbserial evdev pcspkr processor video button ext3 jbd mbcache btrfs zlib_deflate crc32c li
 bcrc32c dm_mod sg sd_mod crc_t10dif usbhid hid ahci libahci 3w_9xxx thermal libata ehci_hcd fan thermal_sys scsi_mod usbcore e1000e [last unloaded: scsi_wait_scan]
Sep 17 13:40:30 tarquin kernel: [ 1447.552657] Pid: 0, comm: swapper Not tainted 3.1.0-rc6+ #3
Sep 17 13:40:30 tarquin kernel: [ 1447.569884] Call Trace:
Sep 17 13:40:30 tarquin kernel: [ 1447.583468]  <IRQ>  [<ffffffff81047f62>] warn_slowpath_common+0x7e/0x96
Sep 17 13:40:30 tarquin kernel: [ 1447.602095]  [<ffffffff81047f8f>] warn_slowpath_null+0x15/0x17
Sep 17 13:40:30 tarquin kernel: [ 1447.619837]  [<ffffffff812756cb>] intel_map_sg+0x1db/0x221
Sep 17 13:40:30 tarquin kernel: [ 1447.637110]  [<ffffffffa00650c0>] scsi_dma_map+0x80/0x99 [scsi_mod]
Sep 17 13:40:30 tarquin kernel: [ 1447.655291]  [<ffffffffa00e4675>] twa_scsiop_execute_scsi+0x141/0x3a5 [3w_9xxx]
Sep 17 13:40:30 tarquin kernel: [ 1447.674875]  [<ffffffffa00e4ded>] twa_scsi_queue+0xd6/0x16a [3w_9xxx]
Sep 17 13:40:30 tarquin kernel: [ 1447.693424]  [<ffffffffa005d488>] ? scsi_finish_command+0xe8/0xe8 [scsi_mod]
Sep 17 13:40:30 tarquin kernel: [ 1447.712660]  [<ffffffffa005e620>] scsi_dispatch_cmd+0x192/0x236 [scsi_mod]
Sep 17 13:40:30 tarquin kernel: [ 1447.731711]  [<ffffffffa0064235>] scsi_request_fn+0x3f5/0x421 [scsi_mod]
Sep 17 13:40:30 tarquin kernel: [ 1447.750511]  [<ffffffff81194a3f>] __blk_run_queue+0x16/0x18
Sep 17 13:40:30 tarquin kernel: [ 1447.767974]  [<ffffffffa006388a>] scsi_run_queue+0x1b5/0x21e [scsi_mod]
Sep 17 13:40:30 tarquin kernel: [ 1447.786632]  [<ffffffffa006494e>] scsi_next_command+0x34/0x45 [scsi_mod]
Sep 17 13:40:30 tarquin kernel: [ 1447.805337]  [<ffffffffa0064e01>] scsi_io_completion+0x458/0x4d2 [scsi_mod]
Sep 17 13:40:30 tarquin kernel: [ 1447.824467]  [<ffffffff8127248f>] ? __free_iova+0x71/0x79
Sep 17 13:40:30 tarquin kernel: [ 1447.841928]  [<ffffffff8134f36b>] ? _raw_spin_unlock_irqrestore+0x12/0x14
Sep 17 13:40:30 tarquin kernel: [ 1447.860901]  [<ffffffffa005d47f>] scsi_finish_command+0xdf/0xe8 [scsi_mod]
Sep 17 13:40:30 tarquin kernel: [ 1447.879789]  [<ffffffffa00648ff>] scsi_softirq_done+0x104/0x10d [scsi_mod]
Sep 17 13:40:30 tarquin kernel: [ 1447.898445]  [<ffffffff8119d5a7>] blk_done_softirq+0x69/0x79
Sep 17 13:40:30 tarquin kernel: [ 1447.915703]  [<ffffffff810748d7>] ? arch_local_irq_save+0x15/0x1b
Sep 17 13:40:30 tarquin kernel: [ 1447.933430]  [<ffffffff8104d877>] __do_softirq+0xc2/0x182
Sep 17 13:40:30 tarquin kernel: [ 1447.950234]  [<ffffffff8134f36b>] ? _raw_spin_unlock_irqrestore+0x12/0x14
Sep 17 13:40:30 tarquin kernel: [ 1447.968574]  [<ffffffff813568ec>] call_softirq+0x1c/0x30
Sep 17 13:40:30 tarquin kernel: [ 1447.985226]  [<ffffffff8100fa12>] do_softirq+0x41/0x7f
Sep 17 13:40:30 tarquin kernel: [ 1448.001673]  [<ffffffff8104dae3>] irq_exit+0x3f/0x9c
Sep 17 13:40:30 tarquin kernel: [ 1448.017782]  [<ffffffff8100f720>] do_IRQ+0x89/0xa0
Sep 17 13:40:30 tarquin kernel: [ 1448.033770]  [<ffffffff8134f6ae>] common_interrupt+0x6e/0x6e
Sep 17 13:40:30 tarquin kernel: [ 1448.050658]  <EOI>  [<ffffffff8100d03a>] ? load_TLS+0xb/0xf
Sep 17 13:40:30 tarquin kernel: [ 1448.067500]  [<ffffffffa01f6426>] ? arch_local_irq_enable+0x8/0xd [processor]
Sep 17 13:40:30 tarquin kernel: [ 1448.086229]  [<ffffffffa01f6dad>] acpi_idle_enter_c1+0x88/0xa6 [processor]
Sep 17 13:40:30 tarquin kernel: [ 1448.104583]  [<ffffffff8126b6c9>] cpuidle_idle_call+0xf9/0x185
Sep 17 13:40:30 tarquin kernel: [ 1448.121632]  [<ffffffff8100d29d>] cpu_idle+0x9f/0xe3
Sep 17 13:40:30 tarquin kernel: [ 1448.137603]  [<ffffffff8133255e>] rest_init+0x72/0x74
Sep 17 13:40:30 tarquin kernel: [ 1448.153605]  [<ffffffff816a5b81>] start_kernel+0x3c0/0x3cb
Sep 17 13:40:30 tarquin kernel: [ 1448.170074]  [<ffffffff816a52c4>] x86_64_start_reservations+0xaf/0xb3
Sep 17 13:40:30 tarquin kernel: [ 1448.187796]  [<ffffffff816a5140>] ? early_idt_handlers+0x140/0x140
Sep 17 13:40:30 tarquin kernel: [ 1448.205156]  [<ffffffff816a53ca>] x86_64_start_kernel+0x102/0x111
Sep 17 13:40:30 tarquin kernel: [ 1448.222302] ---[ end trace a812f71b71702674 ]---

-- 
Chris Boot
bootc@bootc.net

Re: iommu_iova leak [inside 3w-9xxx]

[adam radford]

On Sat, Sep 17, 2011 at 7:29 AM, Chris Boot <bootc@bootc.net> wrote:
> On 17 Sep 2011, at 12:57, Chris Boot wrote:
>> On 17 Sep 2011, at 11:45, Woodhouse, David wrote:
>>> I suppose it's vaguely possible that we're leaking them in such a way
>>> that they remain on the rbtree, perhaps if the deferred unmap is never
>>> actually happening... but I think it's a whole lot more likely that the
>>> PCI driver is just never bothering to unmap the pages it maps.

If you think 3w-9xxx is not unmapping pages it maps, please re-run with
CONFIG_PCI_DMA_DEBUG=y

-Adam

Re: iommu_iova leak [inside 3w-9xxx]

[Woodhouse, David]

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

On Sat, 2011-09-17 at 12:22 -0700, adam radford wrote:
> If you think 3w-9xxx is not unmapping pages it maps, please re-run
> with CONFIG_PCI_DMA_DEBUG=y 

Good point; thanks. I'd forgotten about PCI_DMA_DEBUG. Is there a way to
trigger it other than unloading the module? Doing that may require
nfsroot...

-- 
                   Sent with MeeGo's ActiveSync support.

David Woodhouse                            Open Source Technology Centre
David.Woodhouse@intel.com                              Intel Corporation



[-- Attachment #2: smime.p7s --]
[-- Type: application/x-pkcs7-signature, Size: 4370 bytes --]

Re: iommu_iova leak [inside 3w-9xxx]

[Chris Boot]

On 17/09/2011 20:22, adam radford wrote:
> On Sat, Sep 17, 2011 at 7:29 AM, Chris Boot<bootc@bootc.net>  wrote:
>> On 17 Sep 2011, at 12:57, Chris Boot wrote:
>>> On 17 Sep 2011, at 11:45, Woodhouse, David wrote:
>>>> I suppose it's vaguely possible that we're leaking them in such a way
>>>> that they remain on the rbtree, perhaps if the deferred unmap is never
>>>> actually happening... but I think it's a whole lot more likely that the
>>>> PCI driver is just never bothering to unmap the pages it maps.
> If you think 3w-9xxx is not unmapping pages it maps, please re-run with
> CONFIG_PCI_DMA_DEBUG=y

I can't find a CONFIG_PCI_DMA_DEBUG to enable in 3.1-rc6. Did you mean 
CONFIG_DMA_API_DEBUG?

And as David Woodhouse mentions, the 3ware card houses my root 
filesystem - is there a way I can debug without unloading the module? If 
not I guess I can try to work around it but it would be difficult.

Cheers,
Chris

-- 
Chris Boot
bootc@bootc.net

Re: iommu_iova leak [inside 3w-9xxx]

[Chris Boot]

On 17 Sep 2011, at 20:22, adam radford wrote:
> On Sat, Sep 17, 2011 at 7:29 AM, Chris Boot <bootc@bootc.net> wrote:
>> On 17 Sep 2011, at 12:57, Chris Boot wrote:
>>> On 17 Sep 2011, at 11:45, Woodhouse, David wrote:
>>>> I suppose it's vaguely possible that we're leaking them in such a way
>>>> that they remain on the rbtree, perhaps if the deferred unmap is never
>>>> actually happening... but I think it's a whole lot more likely that the
>>>> PCI driver is just never bothering to unmap the pages it maps.
> 
> If you think 3w-9xxx is not unmapping pages it maps, please re-run with
> CONFIG_PCI_DMA_DEBUG=y

Adam,

I installed a fresh Debian system on a SATA disk connected to the built-in SATA controller, then played with loading/unloading the 3w-9xxx module and doing a few basic things. Without even prodding very much, I got this result:

[ 1142.363173] ------------[ cut here ]------------
[ 1142.368507] WARNING: at lib/dma-debug.c:697 dma_debug_device_change+0x172/0x1a6()
[ 1142.377162] Hardware name: S1200BTL
[ 1142.381193] pci 0000:01:00.0: DMA-API: device driver has pending DMA allocations while released from device [count=37]
[ 1142.381194] One of leaked entries details: [device address=0x00000000fff9a000] [size=4096 bytes] [mapped with DMA_TO_DEVICE] [mapped as scather-gather]
[ 1142.381195] Modules linked in: ext3 jbd nfsd nfs lockd fscache auth_rpcgss nfs_acl sunrpc loop snd_pcm snd_timer i2c_i801 ftdi_sio i2c_core snd soundcore snd_page_alloc usbserial joydev pcspkr evdev video button processor ext4 mbcache jbd2 crc16 dm_mod usbhid sg hid sd_mod crc_t10dif 3w_9xxx(-) ahci libahci libata scsi_mod ehci_hcd e1000e usbcore thermal fan thermal_sys [last unloaded: scsi_wait_scan]
[ 1142.381209] Pid: 4532, comm: rmmod Not tainted 3.1.0-rc6+ #1
[ 1142.381210] Call Trace:
[ 1142.381214]  [<ffffffff81047fe2>] warn_slowpath_common+0x7e/0x96
[ 1142.381216]  [<ffffffff8104808e>] warn_slowpath_fmt+0x41/0x43
[ 1142.381219]  [<ffffffff810407b9>] ? try_to_wake_up+0x195/0x1a7
[ 1142.381221]  [<ffffffff811c3470>] dma_debug_device_change+0x172/0x1a6
[ 1142.381225]  [<ffffffff81359db1>] notifier_call_chain.isra.0+0x33/0x60
[ 1142.381228]  [<ffffffff81066819>] __blocking_notifier_call_chain+0x46/0x5b
[ 1142.381230]  [<ffffffff8106683d>] blocking_notifier_call_chain+0xf/0x11
[ 1142.381232]  [<ffffffff812530df>] __device_release_driver+0xc5/0xca
[ 1142.381234]  [<ffffffff81253738>] driver_detach+0x7d/0xa5
[ 1142.381236]  [<ffffffff81252f75>] bus_remove_driver+0xb2/0xd5
[ 1142.381238]  [<ffffffff81253dae>] driver_unregister+0x65/0x6f
[ 1142.381241]  [<ffffffff811cb6f8>] pci_unregister_driver+0x3e/0x9f
[ 1142.381245]  [<ffffffffa012f811>] ? twa_probe+0x725/0x725 [3w_9xxx]
[ 1142.381247]  [<ffffffffa012f821>] twa_exit+0x10/0x7ef [3w_9xxx]
[ 1142.381250]  [<ffffffff81077a79>] sys_delete_module+0x1d4/0x248
[ 1142.381252]  [<ffffffff8135bf52>] system_call_fastpath+0x16/0x1b
[ 1142.381253] ---[ end trace 1b2f66e73df1e7d3 ]---
[ 1142.381254] Mapped at:
[ 1142.381255]  [<ffffffff811c35b1>] debug_dma_map_sg+0x3b/0x140
[ 1142.381256]  [<ffffffffa00cb0db>] scsi_dma_map+0x9b/0xb7 [scsi_mod]
[ 1142.381260]  [<ffffffffa012c675>] twa_scsiop_execute_scsi+0x141/0x3a5 [3w_9xxx]
[ 1142.381263]  [<ffffffffa012ce3b>] twa_scsi_queue+0xd6/0x16a [3w_9xxx]
[ 1142.381265]  [<ffffffffa00c4620>] scsi_dispatch_cmd+0x192/0x236 [scsi_mod]

HTH,
Chris

-- 
Chris Boot
bootc@bootc.net

Re: iommu_iova leak [inside 3w-9xxx]

[Woodhouse, David]

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

On Sun, 2011-09-18 at 13:06 +0100, Chris Boot wrote:
> On 17 Sep 2011, at 20:22, adam radford wrote:
> > On Sat, Sep 17, 2011 at 7:29 AM, Chris Boot <bootc@bootc.net> wrote:
> >> On 17 Sep 2011, at 12:57, Chris Boot wrote:
> >>> On 17 Sep 2011, at 11:45, Woodhouse, David wrote:
> >>>> I suppose it's vaguely possible that we're leaking them in such a way
> >>>> that they remain on the rbtree, perhaps if the deferred unmap is never
> >>>> actually happening... but I think it's a whole lot more likely that the
> >>>> PCI driver is just never bothering to unmap the pages it maps.
> > 
> > If you think 3w-9xxx is not unmapping pages it maps, please re-run with
> > CONFIG_PCI_DMA_DEBUG=y
> 
> Adam,
> 
> I installed a fresh Debian system on a SATA disk connected to the built-in SATA controller, then played with loading/unloading the 3w-9xxx module and doing a few basic things. Without even prodding very much, I got this result:
> 
> [ 1142.363173] ------------[ cut here ]------------
> [ 1142.368507] WARNING: at lib/dma-debug.c:697 dma_debug_device_change+0x172/0x1a6()
> [ 1142.377162] Hardware name: S1200BTL
> [ 1142.381193] pci 0000:01:00.0: DMA-API: device driver has pending DMA allocations while released from device [count=37]
> [ 1142.381194] One of leaked entries details: [device address=0x00000000fff9a000] [size=4096 bytes] [mapped with DMA_TO_DEVICE] [mapped as scather-gather]
 ...
> [ 1142.381254] Mapped at:
> [ 1142.381255]  [<ffffffff811c35b1>] debug_dma_map_sg+0x3b/0x140
> [ 1142.381256]  [<ffffffffa00cb0db>] scsi_dma_map+0x9b/0xb7 [scsi_mod]
> [ 1142.381260]  [<ffffffffa012c675>] twa_scsiop_execute_scsi+0x141/0x3a5 [3w_9xxx]
> [ 1142.381263]  [<ffffffffa012ce3b>] twa_scsi_queue+0xd6/0x16a [3w_9xxx]
> [ 1142.381265]  [<ffffffffa00c4620>] scsi_dispatch_cmd+0x192/0x236 [scsi_mod]

Seems like a smoking gun to me, although at first glance I can't see an
*obvious* leak in the 3w-9xxx code. Adam?

-- 
                   Sent with MeeGo's ActiveSync support.

David Woodhouse                            Open Source Technology Centre
David.Woodhouse@intel.com                              Intel Corporation



[-- Attachment #2: smime.p7s --]
[-- Type: application/x-pkcs7-signature, Size: 4370 bytes --]

Re: iommu_iova leak [inside 3w-9xxx]

[James Bottomley]

On Sun, 2011-09-18 at 13:39 +0000, Woodhouse, David wrote:
> On Sun, 2011-09-18 at 13:06 +0100, Chris Boot wrote:
> > On 17 Sep 2011, at 20:22, adam radford wrote:
> > > On Sat, Sep 17, 2011 at 7:29 AM, Chris Boot <bootc@bootc.net> wrote:
> > >> On 17 Sep 2011, at 12:57, Chris Boot wrote:
> > >>> On 17 Sep 2011, at 11:45, Woodhouse, David wrote:
> > >>>> I suppose it's vaguely possible that we're leaking them in such a way
> > >>>> that they remain on the rbtree, perhaps if the deferred unmap is never
> > >>>> actually happening... but I think it's a whole lot more likely that the
> > >>>> PCI driver is just never bothering to unmap the pages it maps.
> > > 
> > > If you think 3w-9xxx is not unmapping pages it maps, please re-run with
> > > CONFIG_PCI_DMA_DEBUG=y
> > 
> > Adam,
> > 
> > I installed a fresh Debian system on a SATA disk connected to the built-in SATA controller, then played with loading/unloading the 3w-9xxx module and doing a few basic things. Without even prodding very much, I got this result:
> > 
> > [ 1142.363173] ------------[ cut here ]------------
> > [ 1142.368507] WARNING: at lib/dma-debug.c:697 dma_debug_device_change+0x172/0x1a6()
> > [ 1142.377162] Hardware name: S1200BTL
> > [ 1142.381193] pci 0000:01:00.0: DMA-API: device driver has pending DMA allocations while released from device [count=37]
> > [ 1142.381194] One of leaked entries details: [device address=0x00000000fff9a000] [size=4096 bytes] [mapped with DMA_TO_DEVICE] [mapped as scather-gather]
>  ...
> > [ 1142.381254] Mapped at:
> > [ 1142.381255]  [<ffffffff811c35b1>] debug_dma_map_sg+0x3b/0x140
> > [ 1142.381256]  [<ffffffffa00cb0db>] scsi_dma_map+0x9b/0xb7 [scsi_mod]
> > [ 1142.381260]  [<ffffffffa012c675>] twa_scsiop_execute_scsi+0x141/0x3a5 [3w_9xxx]
> > [ 1142.381263]  [<ffffffffa012ce3b>] twa_scsi_queue+0xd6/0x16a [3w_9xxx]
> > [ 1142.381265]  [<ffffffffa00c4620>] scsi_dispatch_cmd+0x192/0x236 [scsi_mod]
> 
> Seems like a smoking gun to me, although at first glance I can't see an
> *obvious* leak in the 3w-9xxx code. Adam?

Hardly ... all it's saying is that twa_exit doesn't wait for pending I/O
to complete, so when you remove the module it tears down in the middle
of an I/O.  A bug, yes, but it's not indicative of any sort of leak in
the maps/unmaps.

James

Re: iommu_iova leak [inside 3w-9xxx]

[Chris Boot]

On 18 Sep 2011, at 15:01, James Bottomley wrote:
> On Sun, 2011-09-18 at 13:39 +0000, Woodhouse, David wrote:
>> On Sun, 2011-09-18 at 13:06 +0100, Chris Boot wrote:
>>> On 17 Sep 2011, at 20:22, adam radford wrote:
>>>> On Sat, Sep 17, 2011 at 7:29 AM, Chris Boot <bootc@bootc.net> wrote:
>>>>> On 17 Sep 2011, at 12:57, Chris Boot wrote:
>>>>>> On 17 Sep 2011, at 11:45, Woodhouse, David wrote:
>>>>>>> I suppose it's vaguely possible that we're leaking them in such a way
>>>>>>> that they remain on the rbtree, perhaps if the deferred unmap is never
>>>>>>> actually happening... but I think it's a whole lot more likely that the
>>>>>>> PCI driver is just never bothering to unmap the pages it maps.
>>>> 
>>>> If you think 3w-9xxx is not unmapping pages it maps, please re-run with
>>>> CONFIG_PCI_DMA_DEBUG=y
>>> 
>>> Adam,
>>> 
>>> I installed a fresh Debian system on a SATA disk connected to the built-in SATA controller, then played with loading/unloading the 3w-9xxx module and doing a few basic things. Without even prodding very much, I got this result:
>>> 
>>> [ 1142.363173] ------------[ cut here ]------------
>>> [ 1142.368507] WARNING: at lib/dma-debug.c:697 dma_debug_device_change+0x172/0x1a6()
>>> [ 1142.377162] Hardware name: S1200BTL
>>> [ 1142.381193] pci 0000:01:00.0: DMA-API: device driver has pending DMA allocations while released from device [count=37]
>>> [ 1142.381194] One of leaked entries details: [device address=0x00000000fff9a000] [size=4096 bytes] [mapped with DMA_TO_DEVICE] [mapped as scather-gather]
>> ...
>>> [ 1142.381254] Mapped at:
>>> [ 1142.381255]  [<ffffffff811c35b1>] debug_dma_map_sg+0x3b/0x140
>>> [ 1142.381256]  [<ffffffffa00cb0db>] scsi_dma_map+0x9b/0xb7 [scsi_mod]
>>> [ 1142.381260]  [<ffffffffa012c675>] twa_scsiop_execute_scsi+0x141/0x3a5 [3w_9xxx]
>>> [ 1142.381263]  [<ffffffffa012ce3b>] twa_scsi_queue+0xd6/0x16a [3w_9xxx]
>>> [ 1142.381265]  [<ffffffffa00c4620>] scsi_dispatch_cmd+0x192/0x236 [scsi_mod]
>> 
>> Seems like a smoking gun to me, although at first glance I can't see an
>> *obvious* leak in the 3w-9xxx code. Adam?
> 
> Hardly ... all it's saying is that twa_exit doesn't wait for pending I/O
> to complete, so when you remove the module it tears down in the middle
> of an I/O.  A bug, yes, but it's not indicative of any sort of leak in
> the maps/unmaps.


James,

I don't think that's the case - I had unmounted all filesystems, deactivated all volume groups, and performed a sync before waiting a few seconds and running rmmod. Next time I'll also 'echo 1 > /sys/block/sdX/device/delete' if that's helpful.

Chris

-- 
Chris Boot
bootc@bootc.net

Re: iommu_iova leak [inside 3w-9xxx]

[James Bottomley]

On Sun, 2011-09-18 at 15:05 +0100, Chris Boot wrote: 
> > Hardly ... all it's saying is that twa_exit doesn't wait for pending I/O
> > to complete, so when you remove the module it tears down in the middle
> > of an I/O.  A bug, yes, but it's not indicative of any sort of leak in
> > the maps/unmaps.
> 
> 
> James,
> 
> I don't think that's the case - I had unmounted all filesystems, deactivated all volume groups, and performed a sync before waiting a few seconds and running rmmod. Next time I'll also 'echo 1 > /sys/block/sdX/device/delete' if that's helpful.

Actually, I take all that back: the driver has a bug in QUEUE_FULL
handling: twa_scsi_queue() calls twa_scsiop_execute_scsi(), which maps
the dma buffer, but if the card responds QUEUE_FULL it just returns
SCSI_MLQUEUE_HOST_BUSY without ever unmapping.  That leg in the code
frees the request but also doesn't unmap it.  In fact any error return
from twa_scsiop_execute_scsi() seems to have the same problem (but
QUEUE_FULL is the only silent one).

I trust Adam will fix this.

James

Re: iommu_iova leak [inside 3w-9xxx]

[James Bottomley]

On Sun, 2011-09-18 at 18:25 +0400, James Bottomley wrote:
> On Sun, 2011-09-18 at 15:05 +0100, Chris Boot wrote: 
> > > Hardly ... all it's saying is that twa_exit doesn't wait for pending I/O
> > > to complete, so when you remove the module it tears down in the middle
> > > of an I/O.  A bug, yes, but it's not indicative of any sort of leak in
> > > the maps/unmaps.
> > 
> > 
> > James,
> > 
> > I don't think that's the case - I had unmounted all filesystems, deactivated all volume groups, and performed a sync before waiting a few seconds and running rmmod. Next time I'll also 'echo 1 > /sys/block/sdX/device/delete' if that's helpful.
> 
> Actually, I take all that back: the driver has a bug in QUEUE_FULL
> handling: twa_scsi_queue() calls twa_scsiop_execute_scsi(), which maps
> the dma buffer, but if the card responds QUEUE_FULL it just returns
> SCSI_MLQUEUE_HOST_BUSY without ever unmapping.  That leg in the code
> frees the request but also doesn't unmap it.  In fact any error return
> from twa_scsiop_execute_scsi() seems to have the same problem (but
> QUEUE_FULL is the only silent one).
> 
> I trust Adam will fix this.

Actually, while Adam's mulling this, try the following.  It should at
least confirm we're on the right track.

James

---

diff --git a/drivers/scsi/3w-9xxx.c b/drivers/scsi/3w-9xxx.c
index b7bd5b0..3868ab2 100644
--- a/drivers/scsi/3w-9xxx.c
+++ b/drivers/scsi/3w-9xxx.c
@@ -1800,10 +1800,12 @@ static int twa_scsi_queue_lck(struct scsi_cmnd *SCpnt, void (*done)(struct scsi_
 	switch (retval) {
 	case SCSI_MLQUEUE_HOST_BUSY:
 		twa_free_request_id(tw_dev, request_id);
+		twa_unmap_scsi_data(tw_dev, request_id);
 		break;
 	case 1:
 		tw_dev->state[request_id] = TW_S_COMPLETED;
 		twa_free_request_id(tw_dev, request_id);
+		twa_unmap_scsi_data(tw_dev, request_id);
 		SCpnt->result = (DID_ERROR << 16);
 		done(SCpnt);
 		retval = 0;

Re: iommu_iova leak [inside 3w-9xxx]

[Chris Boot]

On 18/09/2011 15:56, James Bottomley wrote:
> On Sun, 2011-09-18 at 18:25 +0400, James Bottomley wrote:
>> On Sun, 2011-09-18 at 15:05 +0100, Chris Boot wrote:
>>>> Hardly ... all it's saying is that twa_exit doesn't wait for pending I/O
>>>> to complete, so when you remove the module it tears down in the middle
>>>> of an I/O.  A bug, yes, but it's not indicative of any sort of leak in
>>>> the maps/unmaps.
>>>
>>> James,
>>>
>>> I don't think that's the case - I had unmounted all filesystems, deactivated all volume groups, and performed a sync before waiting a few seconds and running rmmod. Next time I'll also 'echo 1>  /sys/block/sdX/device/delete' if that's helpful.
>> Actually, I take all that back: the driver has a bug in QUEUE_FULL
>> handling: twa_scsi_queue() calls twa_scsiop_execute_scsi(), which maps
>> the dma buffer, but if the card responds QUEUE_FULL it just returns
>> SCSI_MLQUEUE_HOST_BUSY without ever unmapping.  That leg in the code
>> frees the request but also doesn't unmap it.  In fact any error return
>> from twa_scsiop_execute_scsi() seems to have the same problem (but
>> QUEUE_FULL is the only silent one).
>>
>> I trust Adam will fix this.
> Actually, while Adam's mulling this, try the following.  It should at
> least confirm we're on the right track.
>
> James
>
> ---
>
> diff --git a/drivers/scsi/3w-9xxx.c b/drivers/scsi/3w-9xxx.c
> index b7bd5b0..3868ab2 100644
> --- a/drivers/scsi/3w-9xxx.c
> +++ b/drivers/scsi/3w-9xxx.c
> @@ -1800,10 +1800,12 @@ static int twa_scsi_queue_lck(struct scsi_cmnd *SCpnt, void (*done)(struct scsi_
>   	switch (retval) {
>   	case SCSI_MLQUEUE_HOST_BUSY:
>   		twa_free_request_id(tw_dev, request_id);
> +		twa_unmap_scsi_data(tw_dev, request_id);
>   		break;
>   	case 1:
>   		tw_dev->state[request_id] = TW_S_COMPLETED;
>   		twa_free_request_id(tw_dev, request_id);
> +		twa_unmap_scsi_data(tw_dev, request_id);
>   		SCpnt->result = (DID_ERROR<<  16);
>   		done(SCpnt);
>   		retval = 0;

James,

After testing quite thoroughly on my test install (lots of parallel 
e2fsck and an rsync from one LV to another) I couldn't trigger the 
warning. It's probably too early to tell for sure if this fixes things 
on my normal workload (I'll be able to tell definitely tomorrow), but it 
certainly seems much better right now. I'll keep you posted.

Thanks,
Chris

-- 
Chris Boot
bootc@bootc.net

Re: iommu_iova leak [inside 3w-9xxx]

[Chris Boot]

On 18/09/2011 17:19, Chris Boot wrote:
> On 18/09/2011 15:56, James Bottomley wrote:
>> On Sun, 2011-09-18 at 18:25 +0400, James Bottomley wrote:
>>> On Sun, 2011-09-18 at 15:05 +0100, Chris Boot wrote:
>>>>> Hardly ... all it's saying is that twa_exit doesn't wait for 
>>>>> pending I/O
>>>>> to complete, so when you remove the module it tears down in the 
>>>>> middle
>>>>> of an I/O.  A bug, yes, but it's not indicative of any sort of 
>>>>> leak in
>>>>> the maps/unmaps.
>>>>
>>>> James,
>>>>
>>>> I don't think that's the case - I had unmounted all filesystems, 
>>>> deactivated all volume groups, and performed a sync before waiting 
>>>> a few seconds and running rmmod. Next time I'll also 'echo 1>  
>>>> /sys/block/sdX/device/delete' if that's helpful.
>>> Actually, I take all that back: the driver has a bug in QUEUE_FULL
>>> handling: twa_scsi_queue() calls twa_scsiop_execute_scsi(), which maps
>>> the dma buffer, but if the card responds QUEUE_FULL it just returns
>>> SCSI_MLQUEUE_HOST_BUSY without ever unmapping.  That leg in the code
>>> frees the request but also doesn't unmap it.  In fact any error return
>>> from twa_scsiop_execute_scsi() seems to have the same problem (but
>>> QUEUE_FULL is the only silent one).
>>>
>>> I trust Adam will fix this.
>> Actually, while Adam's mulling this, try the following.  It should at
>> least confirm we're on the right track.
>>
>> James
>>
>> ---
>>
>> diff --git a/drivers/scsi/3w-9xxx.c b/drivers/scsi/3w-9xxx.c
>> index b7bd5b0..3868ab2 100644
>> --- a/drivers/scsi/3w-9xxx.c
>> +++ b/drivers/scsi/3w-9xxx.c
>> @@ -1800,10 +1800,12 @@ static int twa_scsi_queue_lck(struct 
>> scsi_cmnd *SCpnt, void (*done)(struct scsi_
>>       switch (retval) {
>>       case SCSI_MLQUEUE_HOST_BUSY:
>>           twa_free_request_id(tw_dev, request_id);
>> +        twa_unmap_scsi_data(tw_dev, request_id);
>>           break;
>>       case 1:
>>           tw_dev->state[request_id] = TW_S_COMPLETED;
>>           twa_free_request_id(tw_dev, request_id);
>> +        twa_unmap_scsi_data(tw_dev, request_id);
>>           SCpnt->result = (DID_ERROR<<  16);
>>           done(SCpnt);
>>           retval = 0;
>
> James,
>
> After testing quite thoroughly on my test install (lots of parallel 
> e2fsck and an rsync from one LV to another) I couldn't trigger the 
> warning. It's probably too early to tell for sure if this fixes things 
> on my normal workload (I'll be able to tell definitely tomorrow), but 
> it certainly seems much better right now. I'll keep you posted.

The patch above certainly seems to fix things for me. After almost 24 
hours uptime my iommu_iova looks entirely reasonable:

iommu_iova           592    885     64   59    1 : tunables  120   60    
8 : slabdata     15     15     60

We'll see in a few days' time if this resolves my entire performance 
problem, but I'm nearly 100% confident it does.

Thanks.

Chris

-- 
Chris Boot
bootc@bootc.net

Re: iommu_iova leak [inside 3w-9xxx]

[adam radford]

On Sun, Sep 18, 2011 at 7:56 AM, James Bottomley
<James.Bottomley@hansenpartnership.com> wrote:
> On Sun, 2011-09-18 at 18:25 +0400, James Bottomley wrote:
>> On Sun, 2011-09-18 at 15:05 +0100, Chris Boot wrote:
>> > > Hardly ... all it's saying is that twa_exit doesn't wait for pending I/O
>> > > to complete, so when you remove the module it tears down in the middle
>> > > of an I/O.  A bug, yes, but it's not indicative of any sort of leak in
>> > > the maps/unmaps.
>> >
>> >
>> > James,
>> >
>> > I don't think that's the case - I had unmounted all filesystems, deactivated all volume groups, and performed a sync before waiting a few seconds and running rmmod. Next time I'll also 'echo 1 > /sys/block/sdX/device/delete' if that's helpful.
>>
>> Actually, I take all that back: the driver has a bug in QUEUE_FULL
>> handling: twa_scsi_queue() calls twa_scsiop_execute_scsi(), which maps
>> the dma buffer, but if the card responds QUEUE_FULL it just returns
>> SCSI_MLQUEUE_HOST_BUSY without ever unmapping.  That leg in the code
>> frees the request but also doesn't unmap it.  In fact any error return
>> from twa_scsiop_execute_scsi() seems to have the same problem (but
>> QUEUE_FULL is the only silent one).
>>
>> I trust Adam will fix this.
>
> Actually, while Adam's mulling this, try the following.  It should at
> least confirm we're on the right track.
>
> James
>
> ---
>
> diff --git a/drivers/scsi/3w-9xxx.c b/drivers/scsi/3w-9xxx.c
> index b7bd5b0..3868ab2 100644
> --- a/drivers/scsi/3w-9xxx.c
> +++ b/drivers/scsi/3w-9xxx.c
> @@ -1800,10 +1800,12 @@ static int twa_scsi_queue_lck(struct scsi_cmnd *SCpnt, void (*done)(struct scsi_
>        switch (retval) {
>        case SCSI_MLQUEUE_HOST_BUSY:
>                twa_free_request_id(tw_dev, request_id);
> +               twa_unmap_scsi_data(tw_dev, request_id);
>                break;
>        case 1:
>                tw_dev->state[request_id] = TW_S_COMPLETED;
>                twa_free_request_id(tw_dev, request_id);
> +               twa_unmap_scsi_data(tw_dev, request_id);
>                SCpnt->result = (DID_ERROR << 16);
>                done(SCpnt);
>                retval = 0;
>
>
>

James,

Your patch looks correct.

Acked-by: Adam Radford <aradford@gmail.com>

-Adam

Re: iommu_iova leak [inside 3w-9xxx]

[Chris Boot]

On 19/09/2011 20:26, adam radford wrote:
> On Sun, Sep 18, 2011 at 7:56 AM, James Bottomley
> <James.Bottomley@hansenpartnership.com>  wrote:
>> On Sun, 2011-09-18 at 18:25 +0400, James Bottomley wrote:
>>> On Sun, 2011-09-18 at 15:05 +0100, Chris Boot wrote:
>>>>> Hardly ... all it's saying is that twa_exit doesn't wait for pending I/O
>>>>> to complete, so when you remove the module it tears down in the middle
>>>>> of an I/O.  A bug, yes, but it's not indicative of any sort of leak in
>>>>> the maps/unmaps.
>>>>
>>>> James,
>>>>
>>>> I don't think that's the case - I had unmounted all filesystems, deactivated all volume groups, and performed a sync before waiting a few seconds and running rmmod. Next time I'll also 'echo 1>  /sys/block/sdX/device/delete' if that's helpful.
>>> Actually, I take all that back: the driver has a bug in QUEUE_FULL
>>> handling: twa_scsi_queue() calls twa_scsiop_execute_scsi(), which maps
>>> the dma buffer, but if the card responds QUEUE_FULL it just returns
>>> SCSI_MLQUEUE_HOST_BUSY without ever unmapping.  That leg in the code
>>> frees the request but also doesn't unmap it.  In fact any error return
>>> from twa_scsiop_execute_scsi() seems to have the same problem (but
>>> QUEUE_FULL is the only silent one).
>>>
>>> I trust Adam will fix this.
>> Actually, while Adam's mulling this, try the following.  It should at
>> least confirm we're on the right track.
>>
>> James
>>
>> ---
>>
>> diff --git a/drivers/scsi/3w-9xxx.c b/drivers/scsi/3w-9xxx.c
>> index b7bd5b0..3868ab2 100644
>> --- a/drivers/scsi/3w-9xxx.c
>> +++ b/drivers/scsi/3w-9xxx.c
>> @@ -1800,10 +1800,12 @@ static int twa_scsi_queue_lck(struct scsi_cmnd *SCpnt, void (*done)(struct scsi_
>>         switch (retval) {
>>         case SCSI_MLQUEUE_HOST_BUSY:
>>                 twa_free_request_id(tw_dev, request_id);
>> +               twa_unmap_scsi_data(tw_dev, request_id);
>>                 break;
>>         case 1:
>>                 tw_dev->state[request_id] = TW_S_COMPLETED;
>>                 twa_free_request_id(tw_dev, request_id);
>> +               twa_unmap_scsi_data(tw_dev, request_id);
>>                 SCpnt->result = (DID_ERROR<<  16);
>>                 done(SCpnt);
>>                 retval = 0;
>>
>>
>>
> James,
>
> Your patch looks correct.
>
> Acked-by: Adam Radford<aradford@gmail.com>
>
> -Adam

Reported-by: Chris Boot <bootc@bootc.net>
Tested-by: Chris Boot <bootc@bootc.net>

-- 
Chris Boot
bootc@bootc.net