TOFU very slow on Windows
Open, NormalPublic

Description

With an 18mb test keyring (which I can provide) the first issuing of:

gpg --trust-model tofu+pgp -k takes 2minutes 20seconds.

This blocks other gpg calls because it locks the db and so an encryption /
decryption appears to hang while this keylist is running.

Further calls to this command take 44 seconds. While a "normal" gpg
--trust-model pgp only takes 4 seconds on this system.

See: http://paste.debian.net/884541/ (expires 90 days from now)

Process Monitor shows that the time is consumed by reading the pubring.gpg again
and again. Probably for each key? (Offset starts from 0 moves up and then the
read starts again). Which is likely much faster on Linux with better File system
caching.

I think I have tested older versions with tofu before and didn't notice this so
it may be a regression, but I'm not sure. From a rough look at the code I think
the keybd_new in build_conflict_set might be the cause which is also fairly new.

Under GNU/Linux you can compare the strace output to see that there is a problem
even if it's quick because it is cached:

~> time strace gpg2 --no-auto-check-trustdb --trust-model pgp -k 2>&1 |wc -l
33383
strace gpg2 --no-auto-check-trustdb --trust-model pgp -k 2>&1 1.04s user 0.45s
system 104% cpu 1.433 total
wc -l 0.02s user 0.16s system 12% cpu 1.433 total

~> time strace gpg2 --no-auto-check-trustdb --trust-model tofu -k 2>&1 |wc -l
558528
strace gpg2 --no-auto-check-trustdb --trust-model tofu -k 2>&1 9.60s user 8.47s
system 106% cpu 17.022 total
wc -l 0.60s user 2.34s system 17% cpu 17.022 total

This is with my normal pubring that contains 790 public keys.

neal added a comment.Oct 30 2016, 5:21 PM

The first time a key is encountered, we need to do a number of checks that
require reading its keyblock. These include checking whether the key is signed
by an ultimately trusted key. So, this cost is pretty much unavoidable, but it
should be a one time thing.

That other gpg processes stall is surprising, and I will investigate this. I
went to a fair amount of trouble to make sure that that doesn't happen in practice.

That the cost is higher on subsequent runs is a bit disconcerting. I will also
investigate this.

neal added a comment.Oct 30 2016, 7:12 PM

eec365a & 614ca00 fixed the performance issue for me here.

us@chu:~/neal/work/gpg/test (GnuPGTest)$ rm tofu.db
us@chu:~/neal/work/gpg/test (GnuPGTest)$ time gpg --no-default-keyring --keyring
/usr/share/keyrings/debian-keyring.gpg -k >/dev/null
gpg: NOTE: THIS IS A DEVELOPMENT VERSION!
gpg: It is only intended for test purposes and should NOT be
gpg: used in a production environment or with production keys!
gpg: Note: signatures using the MD5 algorithm are rejected

real 0m45.569s
user 0m34.316s
sys 0m10.872s
us@chu:~/neal/work/gpg/test (GnuPGTest)$ time gpg --no-default-keyring --keyring
/usr/share/keyrings/debian-keyring.gpg -k >/dev/null
gpg: NOTE: THIS IS A DEVELOPMENT VERSION!
gpg: It is only intended for test purposes and should NOT be
gpg: used in a production environment or with production keys!
gpg: Note: signatures using the MD5 algorithm are rejected

real 0m2.306s
user 0m2.284s
sys 0m0.020s
us@chu:~/neal/work/gpg/test (GnuPGTest)$ time gpg --no-auto-check-trustdb
--trust-model pgp --no-default-keyring --keyring
/usr/share/keyrings/debian-keyring.gpg -k >/dev/null
gpg: NOTE: THIS IS A DEVELOPMENT VERSION!
gpg: It is only intended for test purposes and should NOT be
gpg: used in a production environment or with production keys!
gpg: please do a --check-trustdb
gpg: Note: signatures using the MD5 algorithm are rejected

real 0m2.261s
user 0m2.248s
sys 0m0.012s

neal added a comment.Oct 31 2016, 3:17 AM

7a634e48b13c5d5d295b8fed9b429e1b2109a333 should fix the contention issue.
Please let me know if you are still having issues.

Sry I accidentally posted an incomplete message with T2812 (aheinecke on Oct 31 2016, 05:08 PM / Roundup) (I used itsalltext
and postet a wrong version).

I wanted to write:

On the command line it's looking good. The second keylist is also down to 5
seconds on Windows.

But used from gpgme it still takes about a minute. If you add --with-colons and
slow down system calls by using strace you can also see this on GNU/Linux:

~> time strace gpg2 --no-default-keyring \

--keyring /usr/share/keyrings/debian-keyring.gpg \
--no-auto-check-trustdb --trust-model pgp \
--with-colons -k >/dev/null 2>&1

2.26s user 0.40s system 102% cpu 2.601 total
~> time strace gpg2 --no-default-keyring \

--keyring /usr/share/keyrings/debian-keyring.gpg \
--no-auto-check-trustdb --trust-model tofu \
--with-colons -k >/dev/null 2>&1

21.43s user 24.47s system 108% cpu 42.451 total

On Windows it's:

PS C:\Users\aheinecke> Measure-Command -Expression { gpg --no-auto-check-trustdb
--trust-model tofu --list-keys > $null
}
TotalSeconds : 7.0945596

PS C:\Users\aheinecke> Measure-Command -Expression { gpg --no-auto-check-trustdb
--with-colons --trust-model tofu --lis
t-keys > $null }
TotalSeconds : 56.0914993

PS C:\Users\aheinecke> Measure-Command -Expression { gpg --no-auto-check-trustdb
--with-colons --trust-model pgp --list
-keys > $null }
TotalSeconds : 1.4855689

I'm also still seeing decryption blocked on Windows while a keylist
--with-colons runs.

I wonder if we should generally check out performance of reading the keyring on
Windows
mabye we could genrally improve it so that it's better cached by Windows.

neal added a comment.Nov 1 2016, 4:48 PM

Hi Andre,

Thanks for following up. I seem to be able to reproduce the first part of your
issue here and I'm looking in to it.

Thanks,
Neal

Fixed in 03a65a5. The time for doing a tofu --with-tofu-info --with-colons
listing is now similar to doing a pgp listing.

Please reopen if there are still unresolved issues.

$ time gpg2 --with-tofu-info --with-colons --no-auto-check-trustdb
--no-default-keyring --keyring /usr/share/keyrings/debian-keyring.gpg
--trust-model pgp -k >/dev/null
gpg: Note: signatures using the MD5 algorithm are rejected

real 0m1.972s
user 0m1.940s
sys 0m0.028s
$ time gpg2 --with-tofu-info --with-colons --no-auto-check-trustdb
--no-default-keyring --keyring /usr/share/keyrings/debian-keyring.gpg
--trust-model tofu -k >/dev/null
gpg: Note: signatures using the MD5 algorithm are rejected

real 0m2.252s
user 0m2.172s
sys 0m0.020s

On Windows especially the initial keylist is very slow, subsequent keylists are
okish (less then 10 seconds) I don't think it's as big a problem anymore.
Listing a specific key is ~100ms. And that is with a large keyring (~18mb) on a
VM with a fairly slow harddisk.

For me this would be good enough to use tofu on windows. So it can be resolved
if you do not think the performance (especially of the initial listing) can be
improved or should have been better.

PS C:\Users\aheinecke> Measure-Command -Expression { gpg --no-auto-check-trustdb
--with-colons --trust-model tofu --list-keys --with-colons > $null }
gpg: NOTE: THIS IS A DEVELOPMENT VERSION!
gpg: It is only intended for test purposes and should NOT be
gpg: used in a production environment or with production keys!
gpg: please do a --check-trustdb
gpg: public key 60041E4EC03449C4 is 39 seconds newer than the signature
gpg: public key 60041E4EC03449C4 is 39 seconds newer than the signature

Days : 0
Hours : 0
Minutes : 1
Seconds : 14
Milliseconds : 785
Ticks : 747854659
TotalDays : 0.000865572521990741
TotalHours : 0.0207737405277778
TotalMinutes : 1.24642443166667
TotalSeconds : 74.7854659
TotalMilliseconds : 74785.4659

PS C:\Users\aheinecke> Measure-Command -Expression { gpg --no-auto-check-trustdb
--with-colons --trust-model tofu --list-keys --with-colons > $null }
gpg: NOTE: THIS IS A DEVELOPMENT VERSION!
gpg: It is only intended for test purposes and should NOT be
gpg: used in a production environment or with production keys!
gpg: please do a --check-trustdb
gpg: public key 60041E4EC03449C4 is 39 seconds newer than the signature

Days : 0
Hours : 0
Minutes : 0
Seconds : 7
Milliseconds : 812
Ticks : 78128420
TotalDays : 9.0426412037037E-05
TotalHours : 0.00217023388888889
TotalMinutes : 0.130214033333333
TotalSeconds : 7.812842
TotalMilliseconds : 7812.842

PS C:\Users\aheinecke> Measure-Command -Expression { gpg --no-auto-check-trustdb
--with-colons --trust-model pgp --list-keys --with-colons > $null }
gpg: NOTE: THIS IS A DEVELOPMENT VERSION!
gpg: It is only intended for test purposes and should NOT be
gpg: used in a production environment or with production keys!
gpg: public key 60041E4EC03449C4 is 39 seconds newer than the signature

Days : 0
Hours : 0
Minutes : 0
Seconds : 1
Milliseconds : 369
Ticks : 13697177
TotalDays : 1.58532141203704E-05
TotalHours : 0.000380477138888889
TotalMinutes : 0.0228286283333333
TotalSeconds : 1.3697177
TotalMilliseconds : 1369.7177

PS C:\Users\aheinecke> gpg --version
gpg (GnuPG) 2.1.17-beta30
libgcrypt 1.7.3

NOTE: THIS IS A DEVELOPMENT VERSION! It is only intended for test purposes and should NOT be used in a production environment or with production keys! Copyright (C) 2016 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later https://gnu.org/licenses/gpl.html This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law.

Home: C:/Users/aheinecke/AppData/Roaming/gnupg
Supported algorithms:
Pubkey: RSA, ELG, DSA, ECDH, ECDSA, EDDSA
Cipher: IDEA, 3DES, CAST5, BLOWFISH, AES, AES192, AES256, TWOFISH,

CAMELLIA128, CAMELLIA192, CAMELLIA256

Hash: SHA1, RIPEMD160, SHA256, SHA384, SHA512, SHA224
Compression: Uncompressed, ZIP, ZLIB, BZIP2

While testing with tofu enabled I sometimes see that some actions take very
long. (>1minute)

Like importing a key in Kleopatra where Kleopatra does an import and starts a
keylist afterwards / in parallel.

I'll try to reproduce this on the command line. Just doing a simple import on
the command line is quick.

Do you have any hint what can take so long?
Like a trigger that would cause a rechecks for cross signatures?

neal added a comment.Dec 2 2016, 11:22 AM

In general, parallel operations aren't great, but I find that such bad
performance surprising.

If you update a key, only that key's effective policy is rechecked, not all
keys. But, the effective policy of conflicting keys is always rechecked.

marcus removed neal as the assignee of this task.Aug 14 2017, 10:36 AM
marcus added a project: Stalled.