IOMMU - DMA debugging

IOMMU - DMA debugging

[Federico Vaga]

Hello,

kernel version 4.4.x

I'm facing an issue with the INTEL IOMMU driver and DMA mapping. I have an 
Ethernet driver that uses `dma_alloc_coherent()` to allocate and map some 
memory for DMA transfers.

The driver uses the DMA API as described in the documentation and I was 
expecting the IOMMU to be transparent, but apparently it is not. When the 
IOMMU is disabled the driver works fine, but when `intel_iommu=on|pt` then it 
does not work

I enabled the iommu events in ftrace at boot time; a weird thing that I 
noticed is that I do not see any map/unmap event in ftrace while I was 
expecting to have some of them.

How can be debugged this kind of issue? Where should I look for troubles 
(BIOS, Linux kernel, the ethernet driver, the ethernet device, PCI bridges)? 

Following the typical errors when `intel_iommu=on|pt`

Thank you



[...]
[ 1156.858606] DMAR: DRHD: handling fault status reg 302
[ 1156.864249] DMAR: DMAR:[DMA Read] Request device [02:00.0] fault addr 
3febf0
[ 1156.864249] DMAR:[fault reason 06] PTE Read access is not set
[ 1189.179531] DMAR: DRHD: handling fault status reg 402
[ 1189.185182] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr 
6d9c7
[ 1189.185182] DMAR:[fault reason 05] PTE Write access is not set
[ 1196.313544] DMAR: DRHD: handling fault status reg 502
[ 1196.319194] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr 
657bb
[ 1196.319194] DMAR:[fault reason 05] PTE Write access is not set
[ 1230.607870] DMAR: DRHD: handling fault status reg 602
[ 1230.613520] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr 
16cfe
[ 1230.613520] DMAR:[fault reason 05] PTE Write access is not set
[ 1236.314332] DMAR: DRHD: handling fault status reg 702
[ 1236.319983] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr 
6e59e
[ 1236.319983] DMAR:[fault reason 05] PTE Write access is not set
[ 1246.314521] DMAR: DRHD: handling fault status reg 2
[ 1246.319979] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr 
7e59f
[ 1246.319979] DMAR:[fault reason 05] PTE Write access is not set
[ 1261.169485] DMAR: DRHD: handling fault status reg 102
[ 1261.175135] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr 
7ddee
[ 1261.175135] DMAR:[fault reason 05] PTE Write access is not set
[ 1272.640611] DMAR: DRHD: handling fault status reg 202
[ 1272.646261] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr 
7bbee
[ 1272.646261] DMAR:[fault reason 05] PTE Write access is not set

-- 
Federico Vaga
http://www.federicovaga.it/

Re: IOMMU - DMA debugging

[Robin Murphy]

On 12/07/17 08:11, Federico Vaga wrote:
> Hello,
> 
> kernel version 4.4.x
> 
> I'm facing an issue with the INTEL IOMMU driver and DMA mapping. I have an 
> Ethernet driver that uses `dma_alloc_coherent()` to allocate and map some 
> memory for DMA transfers.

Assuming 02:00.0 is your actual endpoint and not some upstream aliasing
bridge, is your driver definitely using the correct struct device
pointer corresponding to that for its DMA API calls?

> The driver uses the DMA API as described in the documentation and I was 
> expecting the IOMMU to be transparent, but apparently it is not. When the 
> IOMMU is disabled the driver works fine, but when `intel_iommu=on|pt` then it 
> does not work
> 
> I enabled the iommu events in ftrace at boot time; a weird thing that I 
> noticed is that I do not see any map/unmap event in ftrace while I was 
> expecting to have some of them.

Note that intel-iommu implements its own DMA ops, so will not go via the
IOMMU API abstraction in the DMA path - you'd need to trace
intel_{alloc,free}_coherent() and intel_{map,unmap}_{page,sg}() to see
what's actually being called.

> How can be debugged this kind of issue? Where should I look for troubles 
> (BIOS, Linux kernel, the ethernet driver, the ethernet device, PCI bridges)? 

The faulting addresses below don't look like the kind of IOVAs that
iommu=on mode would map things to, which would usually imply the driver
calling the wrong DMA ops or erroneously bypassing the DMA API
somewhere, but the fact that it also doesn't work in passthrough
suggests something more fundamental, like the IOMMU being configured for
the wrong requester ID entirely.

Robin.

> Following the typical errors when `intel_iommu=on|pt`
> 
> Thank you
> 
> 
> 
> [...]
> [ 1156.858606] DMAR: DRHD: handling fault status reg 302
> [ 1156.864249] DMAR: DMAR:[DMA Read] Request device [02:00.0] fault addr 
> 3febf0
> [ 1156.864249] DMAR:[fault reason 06] PTE Read access is not set
> [ 1189.179531] DMAR: DRHD: handling fault status reg 402
> [ 1189.185182] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr 
> 6d9c7
> [ 1189.185182] DMAR:[fault reason 05] PTE Write access is not set
> [ 1196.313544] DMAR: DRHD: handling fault status reg 502
> [ 1196.319194] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr 
> 657bb
> [ 1196.319194] DMAR:[fault reason 05] PTE Write access is not set
> [ 1230.607870] DMAR: DRHD: handling fault status reg 602
> [ 1230.613520] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr 
> 16cfe
> [ 1230.613520] DMAR:[fault reason 05] PTE Write access is not set
> [ 1236.314332] DMAR: DRHD: handling fault status reg 702
> [ 1236.319983] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr 
> 6e59e
> [ 1236.319983] DMAR:[fault reason 05] PTE Write access is not set
> [ 1246.314521] DMAR: DRHD: handling fault status reg 2
> [ 1246.319979] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr 
> 7e59f
> [ 1246.319979] DMAR:[fault reason 05] PTE Write access is not set
> [ 1261.169485] DMAR: DRHD: handling fault status reg 102
> [ 1261.175135] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr 
> 7ddee
> [ 1261.175135] DMAR:[fault reason 05] PTE Write access is not set
> [ 1272.640611] DMAR: DRHD: handling fault status reg 202
> [ 1272.646261] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr 
> 7bbee
> [ 1272.646261] DMAR:[fault reason 05] PTE Write access is not set
> 

Re: IOMMU - DMA debugging

[Federico Vaga]

Thank you Robin

(inline comments)

On Wednesday, July 12, 2017 1:10:51 PM CEST Robin Murphy wrote:
> On 12/07/17 08:11, Federico Vaga wrote:
> > Hello,
> > 
> > kernel version 4.4.x
> > 
> > I'm facing an issue with the INTEL IOMMU driver and DMA mapping. I have an
> > Ethernet driver that uses `dma_alloc_coherent()` to allocate and map some
> > memory for DMA transfers.
> 
> Assuming 02:00.0 is your actual endpoint and not some upstream aliasing
> bridge, is your driver definitely using the correct struct device
> pointer corresponding to that for its DMA API calls?
> 
> > The driver uses the DMA API as described in the documentation and I was
> > expecting the IOMMU to be transparent, but apparently it is not. When the
> > IOMMU is disabled the driver works fine, but when `intel_iommu=on|pt` then
> > it does not work
> > 
> > I enabled the iommu events in ftrace at boot time; a weird thing that I
> > noticed is that I do not see any map/unmap event in ftrace while I was
> > expecting to have some of them.
> 
> Note that intel-iommu implements its own DMA ops, so will not go via the
> IOMMU API abstraction in the DMA path - you'd need to trace
> intel_{alloc,free}_coherent() and intel_{map,unmap}_{page,sg}() to see
> what's actually being called.

Yes I know. Perhaps I'm missing something in the IOMMU code but I was 
expecting to see the event in:

/sys/kernel/debug/tracing/events/iommu/

I can see the various intel_* function. With SystemTap I tracked variables and 
everything looks fine to me. Indeed, I trust the intel-iommu.c code. And I 
think that the problem is on our side (driver, motherboard, BIOS, ...)

> > How can be debugged this kind of issue? Where should I look for troubles
> > (BIOS, Linux kernel, the ethernet driver, the ethernet device, PCI
> > bridges)?
> The faulting addresses below don't look like the kind of IOVAs that
> iommu=on mode would map things to, which would usually imply the driver
> calling the wrong DMA ops or erroneously bypassing the DMA API
> somewhere, but the fact that it also doesn't work in passthrough
> suggests something more fundamental,

I missed to make explicit the fact that with intel_iommu=off, it works fine.

> like the IOMMU being configured for the wrong requester ID entirely.
>
> Robin.
> 
> > Following the typical errors when `intel_iommu=on|pt`
> > 
> > Thank you
> > 
> > 
> > 
> > [...]
> > [ 1156.858606] DMAR: DRHD: handling fault status reg 302
> > [ 1156.864249] DMAR: DMAR:[DMA Read] Request device [02:00.0] fault addr
> > 3febf0
> > [ 1156.864249] DMAR:[fault reason 06] PTE Read access is not set
> > [ 1189.179531] DMAR: DRHD: handling fault status reg 402
> > [ 1189.185182] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr
> > 6d9c7
> > [ 1189.185182] DMAR:[fault reason 05] PTE Write access is not set
> > [ 1196.313544] DMAR: DRHD: handling fault status reg 502
> > [ 1196.319194] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr
> > 657bb
> > [ 1196.319194] DMAR:[fault reason 05] PTE Write access is not set
> > [ 1230.607870] DMAR: DRHD: handling fault status reg 602
> > [ 1230.613520] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr
> > 16cfe
> > [ 1230.613520] DMAR:[fault reason 05] PTE Write access is not set
> > [ 1236.314332] DMAR: DRHD: handling fault status reg 702
> > [ 1236.319983] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr
> > 6e59e
> > [ 1236.319983] DMAR:[fault reason 05] PTE Write access is not set
> > [ 1246.314521] DMAR: DRHD: handling fault status reg 2
> > [ 1246.319979] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr
> > 7e59f
> > [ 1246.319979] DMAR:[fault reason 05] PTE Write access is not set
> > [ 1261.169485] DMAR: DRHD: handling fault status reg 102
> > [ 1261.175135] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr
> > 7ddee
> > [ 1261.175135] DMAR:[fault reason 05] PTE Write access is not set
> > [ 1272.640611] DMAR: DRHD: handling fault status reg 202
> > [ 1272.646261] DMAR: DMAR:[DMA Write] Request device [02:00.0] fault addr
> > 7bbee
> > [ 1272.646261] DMAR:[fault reason 05] PTE Write access is not set


-- 
Federico Vaga
http://www.federicovaga.it/

Re: IOMMU - DMA debugging

[Federico Vaga]

On Wednesday, July 12, 2017 2:15:34 PM CEST Federico Vaga wrote:
> Thank you Robin
> 
> (inline comments)
> 
> On Wednesday, July 12, 2017 1:10:51 PM CEST Robin Murphy wrote:
> > On 12/07/17 08:11, Federico Vaga wrote:
> > > Hello,
> > > 
> > > kernel version 4.4.x
> > > 
> > > I'm facing an issue with the INTEL IOMMU driver and DMA mapping. I have
> > > an
> > > Ethernet driver that uses `dma_alloc_coherent()` to allocate and map
> > > some
> > > memory for DMA transfers.
> > 
> > Assuming 02:00.0 is your actual endpoint and not some upstream aliasing
> > bridge, is your driver definitely using the correct struct device
> > pointer corresponding to that for its DMA API calls?

I had a look at this point. The driver is using the device 02:08.0 (which is 
the one that should use) but the errors refers to the 02:00.0. I have a rough 
idea about how the IOMMU works but I do not know the details involved in the 
process.

\-[0000:00]-+-00.0
             +-01.0-[01-02]----00.0-[02]----08.0      <<<<<<<<<<
             +-01.1-[03]----00.0

Then among all the other devices, I have this from `dmesg`

[...]
[    2.212107] DMAR: Hardware identity mapping for device 0000:00:1f.3
[    2.219113] DMAR: Hardware identity mapping for device 0000:03:00.0
[    2.226118] DMAR: Hardware identity mapping for device 0000:04:00.0
[    2.233123] DMAR: Hardware identity mapping for device 0000:04:00.1
[...]
[    2.693295] iommu: Adding device 0000:00:1f.3 to group 22
[    2.699350] iommu: Adding device 0000:01:00.0 to group 23
[    2.705389] iommu: Adding device 0000:02:08.0 to group 23
[    2.711444] iommu: Adding device 0000:03:00.0 to group 24
[    2.717552] iommu: Adding device 0000:04:00.0 to group 25
[...]


It misses the message "Hardware identity mapping for device 0000:02:08.0". Is 
it possible that there is not a valid DMAR table?

-- 
Federico Vaga
http://www.federicovaga.it/

Re: IOMMU - DMA debugging

[Robin Murphy]

On 12/07/17 18:20, Federico Vaga wrote:
> On Wednesday, July 12, 2017 2:15:34 PM CEST Federico Vaga wrote:
>> Thank you Robin
>>
>> (inline comments)
>>
>> On Wednesday, July 12, 2017 1:10:51 PM CEST Robin Murphy wrote:
>>> On 12/07/17 08:11, Federico Vaga wrote:
>>>> Hello,
>>>>
>>>> kernel version 4.4.x
>>>>
>>>> I'm facing an issue with the INTEL IOMMU driver and DMA mapping. I have
>>>> an
>>>> Ethernet driver that uses `dma_alloc_coherent()` to allocate and map
>>>> some
>>>> memory for DMA transfers.
>>>
>>> Assuming 02:00.0 is your actual endpoint and not some upstream aliasing
>>> bridge, is your driver definitely using the correct struct device
>>> pointer corresponding to that for its DMA API calls?
> 
> I had a look at this point. The driver is using the device 02:08.0 (which is 
> the one that should use) but the errors refers to the 02:00.0. I have a rough 
> idea about how the IOMMU works but I do not know the details involved in the 
> process.
> 
> \-[0000:00]-+-00.0
>              +-01.0-[01-02]----00.0-[02]----08.0      <<<<<<<<<<
>              +-01.1-[03]----00.0

OK, this is what I suspected might be happening, thanks for confirming.

> Then among all the other devices, I have this from `dmesg`
> 
> [...]
> [    2.212107] DMAR: Hardware identity mapping for device 0000:00:1f.3
> [    2.219113] DMAR: Hardware identity mapping for device 0000:03:00.0
> [    2.226118] DMAR: Hardware identity mapping for device 0000:04:00.0
> [    2.233123] DMAR: Hardware identity mapping for device 0000:04:00.1
> [...]
> [    2.693295] iommu: Adding device 0000:00:1f.3 to group 22
> [    2.699350] iommu: Adding device 0000:01:00.0 to group 23
> [    2.705389] iommu: Adding device 0000:02:08.0 to group 23
> [    2.711444] iommu: Adding device 0000:03:00.0 to group 24
> [    2.717552] iommu: Adding device 0000:04:00.0 to group 25
> [...]
> 
> 
> It misses the message "Hardware identity mapping for device 0000:02:08.0". Is 
> it possible that there is not a valid DMAR table?

I'm a bit sketchy on intel-iommu details as well, but based on a quick
scan through the code I'd assume your endpoint doesn't get an identity
mapping because it's a PCI device behind a PCIe-to-PCI bridge (which
ties in with the RID alias to DevFn 00.0). AFAICS that then means that
the DMA ops should always give back a remapped address (i.e. iommu=pt
ends up behaving the same as iommu=on), at which point it does start to
look like your device is simply making bogus accesses.

The IOVA allocator will allocate DMA addresses downwards from
0xfffff000, but your reported fault addresses don't look anything like
that, so I'd imagine that either some part of the driver is bypassing
the DMA API and erroneously passing physical addresses to the hardware,
or alternatively the hardware itself is going wrong somehow (e.g. trying
to read a buffer address from an in-memory descriptor, getting back
junk, and going downhill from there).

Hope that helps,
Robin.

Re: IOMMU - DMA debugging

[Federico Vaga]

On Wednesday, July 12, 2017 8:02:42 PM CEST Robin Murphy wrote:
> On 12/07/17 18:20, Federico Vaga wrote:
> > On Wednesday, July 12, 2017 2:15:34 PM CEST Federico Vaga wrote:
> >> Thank you Robin
> >> 
> >> (inline comments)
> >> 
> >> On Wednesday, July 12, 2017 1:10:51 PM CEST Robin Murphy wrote:
> >>> On 12/07/17 08:11, Federico Vaga wrote:
> >>>> Hello,
> >>>> 
> >>>> kernel version 4.4.x
> >>>> 
> >>>> I'm facing an issue with the INTEL IOMMU driver and DMA mapping. I have
> >>>> an
> >>>> Ethernet driver that uses `dma_alloc_coherent()` to allocate and map
> >>>> some
> >>>> memory for DMA transfers.
> >>> 
> >>> Assuming 02:00.0 is your actual endpoint and not some upstream aliasing
> >>> bridge, is your driver definitely using the correct struct device
> >>> pointer corresponding to that for its DMA API calls?
> > 
> > I had a look at this point. The driver is using the device 02:08.0 (which
> > is the one that should use) but the errors refers to the 02:00.0. I have
> > a rough idea about how the IOMMU works but I do not know the details
> > involved in the process.
> > 
> > \-[0000:00]-+-00.0
> > 
> >              +-01.0-[01-02]----00.0-[02]----08.0      <<<<<<<<<<
> >              +-01.1-[03]----00.0
> 
> OK, this is what I suspected might be happening, thanks for confirming.
> 
> > Then among all the other devices, I have this from `dmesg`
> > 
> > [...]
> > [    2.212107] DMAR: Hardware identity mapping for device 0000:00:1f.3
> > [    2.219113] DMAR: Hardware identity mapping for device 0000:03:00.0
> > [    2.226118] DMAR: Hardware identity mapping for device 0000:04:00.0
> > [    2.233123] DMAR: Hardware identity mapping for device 0000:04:00.1
> > [...]
> > [    2.693295] iommu: Adding device 0000:00:1f.3 to group 22
> > [    2.699350] iommu: Adding device 0000:01:00.0 to group 23
> > [    2.705389] iommu: Adding device 0000:02:08.0 to group 23
> > [    2.711444] iommu: Adding device 0000:03:00.0 to group 24
> > [    2.717552] iommu: Adding device 0000:04:00.0 to group 25
> > [...]
> > 
> > 
> > It misses the message "Hardware identity mapping for device 0000:02:08.0".
> > Is it possible that there is not a valid DMAR table?
> 
> I'm a bit sketchy on intel-iommu details as well, but based on a quick
> scan through the code I'd assume your endpoint doesn't get an identity
> mapping because it's a PCI device behind a PCIe-to-PCI bridge (which
> ties in with the RID alias to DevFn 00.0). AFAICS that then means that
> the DMA ops should always give back a remapped address (i.e. iommu=pt
> ends up behaving the same as iommu=on), at which point it does start to
> look like your device is simply making bogus accesses.
> 
> The IOVA allocator will allocate DMA addresses downwards from
> 0xfffff000, but your reported fault addresses don't look anything like
> that, so I'd imagine that either some part of the driver is bypassing
> the DMA API and erroneously passing physical addresses to the hardware,

I don't think that this is the case. The addresses returned by 
dma_alloc_coherent are consistent with the IOVA logic:

[...]
[67594.620282] DMA addr 0x00000000ffffd000
[67594.620294] DMA addr 0x00000000ffffc000
[67594.620305] DMA addr 0x00000000ffffb000
[67594.620314] DMA addr 0x00000000ffffa000
[...]

and this is the address that is going to be programmed in the hardware 
register.


> or alternatively the hardware itself is going wrong somehow (e.g. trying
> to read a buffer address from an in-memory descriptor, getting back
> junk, and going downhill from there).

Probably it worth to have a look there
 
> Hope that helps,

Thank you

-- 
Federico Vaga
http://www.federicovaga.it/

Re: IOMMU - DMA debugging

[Federico Vaga]

Hello,

just to conclude this issue

On Thursday, July 13, 2017 10:43:27 AM CEST Federico Vaga wrote:
> On Wednesday, July 12, 2017 8:02:42 PM CEST Robin Murphy wrote:
> [...]
> > or alternatively the hardware itself is going wrong somehow (e.g. trying
> > to read a buffer address from an in-memory descriptor, getting back
> > junk, and going downhill from there).
> 
> Probably it worth to have a look there

It was an hardware problem it has been fixed. Now the DMA works with and 
without IOMMU.

Thank you again

-- 
Federico Vaga
http://www.federicovaga.it/