[dm-crypt] Computer locking up on heavy disk IO

[dm-crypt] Computer locking up on heavy disk IO

[heinrich5991]

Hi,

I've noticed that my computer performs worse than optimal in cases of
much disk IO. Now that I tried to use dd to securely erase a large disk
(as in 2.19 of the FAQ at
https://gitlab.com/cryptsetup/cryptsetup/wikis/FrequentlyAskedQuestions#2-setup),
the computer completely locked up after half a minute or so. Before
locking up one completely, it showed high load (>80) and high io wait. I
was able to reboot the computer using Magic SysRq sequences, although
they had a big delay.

Previously, I tried to see how fast the drive can go and just dd'ed
/dev/zero directly onto it. The computer handled that one fine, disk
transfer averaged out at ~150MiB/s.

    # Tests are approximate using memory only (no storage IO).
    PBKDF2-sha1      1016062 iterations per second for 256-bit key
    PBKDF2-sha256    1432480 iterations per second for 256-bit key
    PBKDF2-sha512     976327 iterations per second for 256-bit key
    PBKDF2-ripemd160  815377 iterations per second for 256-bit key
    PBKDF2-whirlpool  580606 iterations per second for 256-bit key
    #     Algorithm | Key |  Encryption |  Decryption
            aes-cbc   128b   655.6 MiB/s  2261.2 MiB/s
        serpent-cbc   128b    80.7 MiB/s   323.3 MiB/s
        twofish-cbc   128b   186.4 MiB/s   352.1 MiB/s
            aes-cbc   256b   481.6 MiB/s  1724.6 MiB/s
        serpent-cbc   256b    80.7 MiB/s   323.2 MiB/s
        twofish-cbc   256b   186.4 MiB/s   351.9 MiB/s
            aes-xts   256b  1956.1 MiB/s  1965.6 MiB/s
        serpent-xts   256b   332.8 MiB/s   316.9 MiB/s
        twofish-xts   256b   345.8 MiB/s   347.2 MiB/s
            aes-xts   512b  1526.4 MiB/s  1522.7 MiB/s
        serpent-xts   512b   333.4 MiB/s   316.8 MiB/s
        twofish-xts   512b   345.5 MiB/s   346.7 MiB/s

Thanks

Re: [dm-crypt] Computer locking up on heavy disk IO

[Arno Wagner]

Maybe your disk is dying or your CPU is inadequately cooled?
Or there is something else putting high load on your machine?

Regards,
Arno

On Tue, Aug 01, 2017 at 10:52:48 CEST, heinrich5991@gmail.com wrote:
> Hi,
> 
> I've noticed that my computer performs worse than optimal in cases of
> much disk IO. Now that I tried to use dd to securely erase a large disk
> (as in 2.19 of the FAQ at
> https://gitlab.com/cryptsetup/cryptsetup/wikis/FrequentlyAskedQuestions#2-setup),
> the computer completely locked up after half a minute or so. Before
> locking up one completely, it showed high load (>80) and high io wait. I
> was able to reboot the computer using Magic SysRq sequences, although
> they had a big delay.
> 
> Previously, I tried to see how fast the drive can go and just dd'ed
> /dev/zero directly onto it. The computer handled that one fine, disk
> transfer averaged out at ~150MiB/s.
> 
>     # Tests are approximate using memory only (no storage IO).
>     PBKDF2-sha1      1016062 iterations per second for 256-bit key
>     PBKDF2-sha256    1432480 iterations per second for 256-bit key
>     PBKDF2-sha512     976327 iterations per second for 256-bit key
>     PBKDF2-ripemd160  815377 iterations per second for 256-bit key
>     PBKDF2-whirlpool  580606 iterations per second for 256-bit key
>     #     Algorithm | Key |  Encryption |  Decryption
>             aes-cbc   128b   655.6 MiB/s  2261.2 MiB/s
>         serpent-cbc   128b    80.7 MiB/s   323.3 MiB/s
>         twofish-cbc   128b   186.4 MiB/s   352.1 MiB/s
>             aes-cbc   256b   481.6 MiB/s  1724.6 MiB/s
>         serpent-cbc   256b    80.7 MiB/s   323.2 MiB/s
>         twofish-cbc   256b   186.4 MiB/s   351.9 MiB/s
>             aes-xts   256b  1956.1 MiB/s  1965.6 MiB/s
>         serpent-xts   256b   332.8 MiB/s   316.9 MiB/s
>         twofish-xts   256b   345.8 MiB/s   347.2 MiB/s
>             aes-xts   512b  1526.4 MiB/s  1522.7 MiB/s
>         serpent-xts   512b   333.4 MiB/s   316.8 MiB/s
>         twofish-xts   512b   345.5 MiB/s   346.7 MiB/s
> 
> Thanks
> _______________________________________________
> dm-crypt mailing list
> dm-crypt@saout.de
> http://www.saout.de/mailman/listinfo/dm-crypt

-- 
Arno Wagner,     Dr. sc. techn., Dipl. Inform.,    Email: arno@wagner.name
GnuPG: ID: CB5D9718  FP: 12D6 C03B 1B30 33BB 13CF  B774 E35C 5FA1 CB5D 9718
----
A good decision is based on knowledge and not on numbers. -- Plato

If it's in the news, don't worry about it.  The very definition of 
"news" is "something that hardly ever happens." -- Bruce Schneier

Re: [dm-crypt] Computer locking up on heavy disk IO

[heinrich5991]

On 08/01/17 11:57, Arno Wagner wrote:
> Maybe your disk is dying or your CPU is inadequately cooled?
> Or there is something else putting high load on your machine?
> 
> Regards,
> Arno

Disk dying is unlikely, the disk is new. Also the following command
works fine for clearing the the disk with random data, it averages out
at ~130MiB/s:

openssl enc -aes-256-ctr -pass pass:"$(dd if=/dev/urandom bs=128 count=1
2>/dev/null | base64)" -nosalt < /dev/zero | pv -s "$(blockdev
--getsize64 /dev/sdX)" > /dev/sdX

(with sdX replaced by the correct device).

I don't know how to determine whether the CPU is inadequately cooled.

Thanks for your answer.

Re: [dm-crypt] Computer locking up on heavy disk IO

[heinrich5991]

On 08/01/17 11:57, Arno Wagner wrote:
> Maybe your disk is dying or your CPU is inadequately cooled?
> Or there is something else putting high load on your machine?

It really doesn't seem that one of these is the case, I performed these
steps without any other open programs: After completely wiping the hard
disk with the other method, I retried opening it with a random key in
cryptsetup

  cryptsetup open --type plain -d /dev/urandom /dev/sdX sdX_wipe

and then overwriting it again

  pv /dev/zero > /dev/mapper/sdX_wipe

and after a couple of seconds, the computer locked up again. Does
someone know how to debug this?

These dmesg entries look suspicious:

Aug 01 22:05:27 kernel: ata_piix 0000:00:1f.2: swiotlb buffer is full
(sz: 61440 bytes)
Aug 01 22:05:27 kernel: ata_piix 0000:00:1f.2: DMA: Out of SW-IOMMU
space for 61440 bytes
Aug 01 22:05:27 kernel: ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0
action 0x0
Aug 01 22:05:27 kernel: ata1.00: failed command: READ DMA EXT
Aug 01 22:05:27 kernel: ata1.00: cmd 25/00:00:50:f5:53/00:01:bd:00:00/e0
tag 0 dma 131072 in
                                 res 50/00:00:4f:c1:3b/00:00:b8:00:00/e0
Emask 0x40 (internal error)
Aug 01 22:05:27 kernel: ata1.00: status: { DRDY }
Aug 01 22:05:27 kernel: ata1.00: configured for UDMA/133
Aug 01 22:05:27 kernel: ata1: EH complete
Aug 01 22:05:27 kernel: ata_piix 0000:00:1f.2: swiotlb buffer is full
(sz: 61440 bytes)
Aug 01 22:05:27 kernel: ata_piix 0000:00:1f.2: DMA: Out of SW-IOMMU
space for 61440 bytes
Aug 01 22:05:27 kernel: ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0
action 0x0
Aug 01 22:05:27 kernel: ata1.00: failed command: READ DMA EXT
Aug 01 22:05:27 kernel: ata1.00: cmd 25/00:00:50:f5:53/00:01:bd:00:00/e0
tag 0 dma 131072 in
                                 res 50/00:00:af:88:e0/00:00:e8:00:00/e0
Emask 0x40 (internal error)
Aug 01 22:05:27 kernel: ata1.00: status: { DRDY }
[... a lot of repetitions of this]

Thanks

Re: [dm-crypt] Computer locking up on heavy disk IO

[Arno Wagner]

Hi,

while I am really not an expert on ATA commands, this
looks like a dying disk, a dying disk controller or
bad cabeling to me. What happens is that your disk access 
fails and then it seems to go through a reset.  That pretty 
much kills performance.

I have no idea why this does not happen on normal access.
Is this perhaps on an old OCZ SSD? These use compression
and perform much worse with incompressible data.

Regards,
Arno

On Tue, Aug 01, 2017 at 22:22:11 CEST, heinrich5991@gmail.com wrote:
> On 08/01/17 11:57, Arno Wagner wrote:
> > Maybe your disk is dying or your CPU is inadequately cooled?
> > Or there is something else putting high load on your machine?
> 
> It really doesn't seem that one of these is the case, I performed these
> steps without any other open programs: After completely wiping the hard
> disk with the other method, I retried opening it with a random key in
> cryptsetup
> 
>   cryptsetup open --type plain -d /dev/urandom /dev/sdX sdX_wipe
> 
> and then overwriting it again
> 
>   pv /dev/zero > /dev/mapper/sdX_wipe
> 
> and after a couple of seconds, the computer locked up again. Does
> someone know how to debug this?
> 
> These dmesg entries look suspicious:
> 
> Aug 01 22:05:27 kernel: ata_piix 0000:00:1f.2: swiotlb buffer is full
> (sz: 61440 bytes)
> Aug 01 22:05:27 kernel: ata_piix 0000:00:1f.2: DMA: Out of SW-IOMMU
> space for 61440 bytes
> Aug 01 22:05:27 kernel: ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0
> action 0x0
> Aug 01 22:05:27 kernel: ata1.00: failed command: READ DMA EXT
> Aug 01 22:05:27 kernel: ata1.00: cmd 25/00:00:50:f5:53/00:01:bd:00:00/e0
> tag 0 dma 131072 in
>                                  res 50/00:00:4f:c1:3b/00:00:b8:00:00/e0
> Emask 0x40 (internal error)
> Aug 01 22:05:27 kernel: ata1.00: status: { DRDY }
> Aug 01 22:05:27 kernel: ata1.00: configured for UDMA/133
> Aug 01 22:05:27 kernel: ata1: EH complete
> Aug 01 22:05:27 kernel: ata_piix 0000:00:1f.2: swiotlb buffer is full
> (sz: 61440 bytes)
> Aug 01 22:05:27 kernel: ata_piix 0000:00:1f.2: DMA: Out of SW-IOMMU
> space for 61440 bytes
> Aug 01 22:05:27 kernel: ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0
> action 0x0
> Aug 01 22:05:27 kernel: ata1.00: failed command: READ DMA EXT
> Aug 01 22:05:27 kernel: ata1.00: cmd 25/00:00:50:f5:53/00:01:bd:00:00/e0
> tag 0 dma 131072 in
>                                  res 50/00:00:af:88:e0/00:00:e8:00:00/e0
> Emask 0x40 (internal error)
> Aug 01 22:05:27 kernel: ata1.00: status: { DRDY }
> [... a lot of repetitions of this]
> 
> Thanks
> _______________________________________________
> dm-crypt mailing list
> dm-crypt@saout.de
> http://www.saout.de/mailman/listinfo/dm-crypt

-- 
Arno Wagner,     Dr. sc. techn., Dipl. Inform.,    Email: arno@wagner.name
GnuPG: ID: CB5D9718  FP: 12D6 C03B 1B30 33BB 13CF  B774 E35C 5FA1 CB5D 9718
----
A good decision is based on knowledge and not on numbers. -- Plato

If it's in the news, don't worry about it.  The very definition of 
"news" is "something that hardly ever happens." -- Bruce Schneier

Re: [dm-crypt] Computer locking up on heavy disk IO

[heinrich5991]

On 08/01/17 22:40, Arno Wagner wrote:
> while I am really not an expert on ATA commands, this
> looks like a dying disk, a dying disk controller or
> bad cabeling to me. What happens is that your disk access 
> fails and then it seems to go through a reset.  That pretty 
> much kills performance.
> 
> I have no idea why this does not happen on normal access.
> Is this perhaps on an old OCZ SSD? These use compression
> and perform much worse with incompressible data.
These are two different 4TB USB 3 hard drives (not SSDs). Since it's two
different (from different vendors) and new disks, I assume they're not
dying just now.

Re: [dm-crypt] Computer locking up on heavy disk IO

[Michael Kjörling]

On 1 Aug 2017 22:22 +0200, from heinrich5991@gmail.com:
> Aug 01 22:05:27 kernel: ata_piix 0000:00:1f.2: swiotlb buffer is full (sz: 61440 bytes)
> Aug 01 22:05:27 kernel: ata_piix 0000:00:1f.2: DMA: Out of SW-IOMMU space for 61440 bytes

I think that's the key. Don't know why it'd only affect usage through
dm-crypt, though.

[1] isn't about the exact same issue (that's someone getting very
similar errors with a network card) but suggests booting with
iommu=force or even iommu=off causes the errors to go away. It'll
likely kill performance, but it seems like a good test. If the system
is stable with such a configuration, one might expect that the drive
itself doesn't have any problems with the usage.

Also, there seem to be lots of reports that this happens with kernels
3.8.0 and newer, but that 3.7.x and earlier don't exhibit the same
problem and [2] says a fix for another similar issue may be in 3.8.3
or possibly (as per [3]) 3.8.4. Which of course prompts the question:
what kernel version are you running? And while you're at it, you might
also tell us which cryptsetup version you're running; while I really
doubt this is cryptsetup related, that piece of information can hardly
hurt.

And [4] suggests increasing the swiotlb size using the swiotlb=N
kernel parameter, where N apparently is the number of 2 KiB blocks to
allocate (65536 for 128 MB, 131072 for 256 MB). That feels like a
stopgap measure, though, even more so than disabling IOMMU, but if all
else fails...


 [1]: https://bbs.archlinux.org/viewtopic.php?pid=650269#p650269

 [2]: https://forum.siduction.org/index.php?topic=3272.msg27986#msg27986

 [3]: https://forum.siduction.org/index.php?topic=3272.msg28451#msg28451

 [4]: https://www.spinics.net/lists/linux-ide/msg25119.html

-- 
Michael Kjörling • https://michael.kjorling.se • michael@kjorling.se
                 “People who think they know everything really annoy
                 those of us who know we don’t.” (Bjarne Stroustrup)

Re: [dm-crypt] Computer locking up on heavy disk IO

[heinrich5991]

On 08/01/17 22:47, Michael Kjörling wrote:
> On 1 Aug 2017 22:22 +0200, from heinrich5991@gmail.com:
>> Aug 01 22:05:27 kernel: ata_piix 0000:00:1f.2: swiotlb buffer is full (sz: 61440 bytes)
>> Aug 01 22:05:27 kernel: ata_piix 0000:00:1f.2: DMA: Out of SW-IOMMU space for 61440 bytes
> 
> I think that's the key. Don't know why it'd only affect usage through
> dm-crypt, though.
> 
> [1] isn't about the exact same issue (that's someone getting very
> similar errors with a network card) but suggests booting with
> iommu=force or even iommu=off causes the errors to go away. It'll
> likely kill performance, but it seems like a good test. If the system
> is stable with such a configuration, one might expect that the drive
> itself doesn't have any problems with the usage.

iommu=force seems to keep similar issues, i.e. I still see error
messages like that in dmesg when performing a lot of disk IO through a
device mounted by cryptsetup. iommu=off stops the computer from booting,
displaying a lot of disk errors instead.

> Also, there seem to be lots of reports that this happens with kernels
> 3.8.0 and newer, but that 3.7.x and earlier don't exhibit the same
> problem and [2] says a fix for another similar issue may be in 3.8.3
> or possibly (as per [3]) 3.8.4. Which of course prompts the question:
> what kernel version are you running? And while you're at it, you might
> also tell us which cryptsetup version you're running; while I really
> doubt this is cryptsetup related, that piece of information can hardly
> hurt.

$ uname -a
Linux <hostname> 4.11.9-1-ARCH #1 SMP PREEMPT Wed Jul 5 18:23:08 CEST
2017 x86_64 GNU/Linux
$ cryptsetup --version
cryptsetup 1.7.5

> And [4] suggests increasing the swiotlb size using the swiotlb=N
> kernel parameter, where N apparently is the number of 2 KiB blocks to
> allocate (65536 for 128 MB, 131072 for 256 MB). That feels like a
> stopgap measure, though, even more so than disabling IOMMU, but if all
> else fails...

Unfortunately, it's exactly this "stopgap measure" that apparantly makes
the issue go away completely. I set swiotlb=131072 and afterwards, the
pv /dev/zero > /dev/mapper/dbX_wipe worked without problems.

>  [1]: https://bbs.archlinux.org/viewtopic.php?pid=650269#p650269
> 
>  [2]: https://forum.siduction.org/index.php?topic=3272.msg27986#msg27986
> 
>  [3]: https://forum.siduction.org/index.php?topic=3272.msg28451#msg28451
> 
>  [4]: https://www.spinics.net/lists/linux-ide/msg25119.html
> 
Thank you for your help so far! :)

[dm-crypt] Fwd: Re: Computer locking up on heavy disk IO

[heinrich5991]

Okay, maybe a little less strange: Only one of the two disks seems to be
affected, and swiotlb=131072 does not actually help.

Summarized:
There's two USB 3 disks with same size, swapping cables does not do
anything, plugging the bad disk into a USB 2 port does not help. Writing
much data through cryptsetup onto the bad disk locks up the computer,
all other combinations do not, in particular:
1) Writing much data to the bad disk without cryptsetup.
2) Writing much data to the other disk, with or without cryptsetup.

Sorry for the wrong conclusions in the last email.


-------- Forwarded Message --------
Subject: Re: [dm-crypt] Computer locking up on heavy disk IO
Date: Wed, 2 Aug 2017 00:19:38 +0200
From: heinrich5991@gmail.com
To: dm-crypt@saout.de

On 08/01/17 22:47, Michael Kjörling wrote:
> On 1 Aug 2017 22:22 +0200, from heinrich5991@gmail.com:
>> Aug 01 22:05:27 kernel: ata_piix 0000:00:1f.2: swiotlb buffer is full (sz: 61440 bytes)
>> Aug 01 22:05:27 kernel: ata_piix 0000:00:1f.2: DMA: Out of SW-IOMMU space for 61440 bytes
> 
> I think that's the key. Don't know why it'd only affect usage through
> dm-crypt, though.
> 
> [1] isn't about the exact same issue (that's someone getting very
> similar errors with a network card) but suggests booting with
> iommu=force or even iommu=off causes the errors to go away. It'll
> likely kill performance, but it seems like a good test. If the system
> is stable with such a configuration, one might expect that the drive
> itself doesn't have any problems with the usage.

iommu=force seems to keep similar issues, i.e. I still see error
messages like that in dmesg when performing a lot of disk IO through a
device mounted by cryptsetup. iommu=off stops the computer from booting,
displaying a lot of disk errors instead.

> Also, there seem to be lots of reports that this happens with kernels
> 3.8.0 and newer, but that 3.7.x and earlier don't exhibit the same
> problem and [2] says a fix for another similar issue may be in 3.8.3
> or possibly (as per [3]) 3.8.4. Which of course prompts the question:
> what kernel version are you running? And while you're at it, you might
> also tell us which cryptsetup version you're running; while I really
> doubt this is cryptsetup related, that piece of information can hardly
> hurt.

$ uname -a
Linux <hostname> 4.11.9-1-ARCH #1 SMP PREEMPT Wed Jul 5 18:23:08 CEST
2017 x86_64 GNU/Linux
$ cryptsetup --version
cryptsetup 1.7.5

> And [4] suggests increasing the swiotlb size using the swiotlb=N
> kernel parameter, where N apparently is the number of 2 KiB blocks to
> allocate (65536 for 128 MB, 131072 for 256 MB). That feels like a
> stopgap measure, though, even more so than disabling IOMMU, but if all
> else fails...

Unfortunately, it's exactly this "stopgap measure" that apparantly makes
the issue go away completely. I set swiotlb=131072 and afterwards, the
pv /dev/zero > /dev/mapper/dbX_wipe worked without problems.

>  [1]: https://bbs.archlinux.org/viewtopic.php?pid=650269#p650269
> 
>  [2]: https://forum.siduction.org/index.php?topic=3272.msg27986#msg27986
> 
>  [3]: https://forum.siduction.org/index.php?topic=3272.msg28451#msg28451
> 
>  [4]: https://www.spinics.net/lists/linux-ide/msg25119.html
> 
Thank you for your help so far! :)