--weak-digest SHA1 causes significant slowdown in --check-trustdb (2.1.10)
Daniel Kahn Gillmor
dkg at fifthhorseman.net
Tue Jan 5 05:20:25 CET 2016
Hi folks--
i'm running gnupg 2.1.10 with a large keybox (a couple thousand
certificates).
With a hot filesystem cache, "gpg2 --check-trustdb" on its own takes
about 17 seconds to run.
real 0m17.160s
user 0m15.852s
sys 0m1.308s
If i add --weak-digest RIPEMD160, it's still about 17 seconds.
if i add --weak-digest RIPEMD160 --weak-digest SHA224 --weak-digest
SHA384, it is still about 17 seconds.
(note: i don't actually think sha224 and sha384 should be discarded,
this is just for demonstration)
But if i add --weak-digest SHA1, then check-trustdb runs for about 22
*minutes*, and nearly half of that is in the kernel:
real 22m9.765s
user 9m48.464s
sys 12m21.464s
To try to get a better sense of what's going on here. I've tried
running with profiling (gprof), and the difference in the gprof
summaries look like this:
==> with-weak-sha1 <==
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls s/call s/call name
40.48 86.29 86.29 264440430 0.00 0.00 unknown_pubkey_warning
14.53 117.26 30.97 70214 0.00 0.00 iobuf_temp_with_content
8.90 136.24 18.98 2151046702 0.00 0.00 enum_sig_subpkt
5.64 148.27 12.03 169702791 0.00 0.00 new_kbnode
5.37 159.71 11.44 169205168 0.00 0.00 parse_signature
5.07 170.52 10.81 169772114 0.00 0.00 free_packet
4.15 179.36 8.84 70144 0.00 0.00 release_kbnode
3.10 185.97 6.61 88068 0.00 0.00 find_prev_kbnode
2.06 190.36 4.39 80306 0.00 0.00 keybox_search
1.51 193.58 3.22 169772114 0.00 0.00 dbg_parse_packet
1.37 196.50 2.92 124607778 0.00 0.00 _keybox_read_blob2
1.24 199.15 2.65 346174508 0.00 0.00 parse_one_sig_subpkt
1.14 201.59 2.44 69323 0.00 0.00 parse_keyblock_image
0.91 203.53 1.94 330484896 0.00 0.00 iobuf_read
0.52 204.64 1.11 330484916 0.00 0.00 parse_sig_subpkt2
==> without-weak-sha1 <==
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ms/call ms/call name
28.99 0.40 0.40 1348642 0.00 0.00 unknown_pubkey_warning
18.12 0.65 0.25 13853 0.02 0.03 mark_usable_uid_certs
10.15 0.79 0.14 23060 0.01 0.01 find_prev_kbnode
8.70 0.91 0.12 10690983 0.00 0.00 enum_sig_subpkt
7.97 1.02 0.11 6639 0.02 0.02 iobuf_temp_with_content
5.07 1.09 0.07 5498 0.01 0.02 get_pubkey_fast
4.35 1.15 0.06 814348 0.00 0.00 parse_signature
3.62 1.20 0.05 138747 0.00 0.00 tdbio_read_record
2.90 1.24 0.04 validate_keys.constprop.5
2.17 1.27 0.03 65352 0.00 0.00 transform
1.45 1.29 0.02 850030 0.00 0.00 dbg_parse_packet
1.45 1.31 0.02 850030 0.00 0.00 free_packet
0.72 1.32 0.01 1825225 0.00 0.00 parse_one_sig_subpkt
0.72 1.33 0.01 827276 0.00 0.00 iobuf_skip_rest
0.72 1.34 0.01 24280 0.00 0.00 check_signature_end
note that that's 2G calls to enum_sig_subpkt with --weak-digest SHA1 and
only 10M invocations without!
The top 3 items in the gprof callgraph summary are:
==> with-weak-sha1 <==
index % time self children called name
<spontaneous>
[1] 99.4 0.04 211.85 validate_keys.constprop.5 [1]
0.02 211.57 2/2 validate_key_list [2]
0.09 0.11 727/70144 release_kbnode [14]
0.00 0.03 1729/1729 update_validity [65]
0.00 0.02 1/1 get_pubkeyblock [76]
0.00 0.01 1/1 reset_trust_records [90]
0.00 0.00 382/22568 tdbio_search_trust_bypk [42]
0.00 0.00 5215/174077 keyid_from_pk [63]
0.00 0.00 1/1 tdbio_update_version_record [102]
0.00 0.00 1/1 tdbio_write_nextcheck [106]
0.00 0.00 1/198670 keydb_release [62]
0.00 0.00 1/198670 keydb_new [75]
0.00 0.00 728/728 tdbio_sync [131]
0.00 0.00 382/31371 init_trustdb [115]
0.00 0.00 4/8 log_info [143]
0.00 0.00 1/10544660 make_timestamp [111]
0.00 0.00 1/1 keydb_rebuild_caches [160]
0.00 0.00 1/1 strtimestamp [170]
-----------------------------------------------
0.02 211.57 2/2 validate_keys.constprop.5 [1]
[2] 99.3 0.02 211.57 2 validate_key_list [2]
0.48 110.46 14630/14630 mark_usable_uid_certs [9]
0.20 84.45 5452/12567 get_pubkey_fast <cycle 1> [4]
0.00 13.59 5452/69323 keydb_get_keyblock [5]
0.69 0.86 5452/70144 release_kbnode [14]
0.00 0.69 5454/5549 keydb_search [30]
0.00 0.10 14630/22568 tdbio_search_trust_bypk [42]
0.02 0.00 5452/5452 clear_kbnode_flags [71]
0.00 0.02 14630/16359 namehash_from_uid [69]
0.01 0.00 19544/171718 tdbio_read_record [45]
0.00 0.00 6491/174077 keyid_from_pk [63]
0.00 0.00 2/2 keydb_search_reset [108]
0.00 0.00 29260/31371 init_trustdb [115]
0.00 0.00 5452/5452 merge_keys_and_selfsig [127]
-----------------------------------------------
[3] 91.5 0.46 194.67 12567+180615 <cycle 1 as a whole> [3]
0.43 187.68 5547+199354 get_pubkey_fast <cycle 1> [4]
0.03 6.67 119456 check_key_signature2 <cycle 1> [20]
0.00 0.28 95 lookup.constprop.11 <cycle 1> [35]
0.00 0.03 6591 get_pubkey <cycle 1> [60]
0.00 0.00 6591 check_signature2 <cycle 1> [99]
0.00 0.00 2 check_revocation_keys <cycle 1> [107]
0.00 0.00 54900 check_key_signature <cycle 1> [114]
-----------------------------------------------
==> without-weak-sha1 <==
index % time self children called name
<spontaneous>
[1] 99.9 0.04 1.34 validate_keys.constprop.5 [1]
0.01 1.31 2/2 validate_key_list [2]
0.00 0.01 1993/1993 update_validity [26]
0.00 0.00 823/6423 release_kbnode [22]
0.00 0.00 1/1 reset_trust_records [32]
0.00 0.00 408/16254 tdbio_search_trust_bypk [18]
0.00 0.00 1/1 get_pubkeyblock [38]
0.00 0.00 408/16254 tdbio_search_trust_bypk [18]
0.00 0.00 1/1 get_pubkeyblock [38]
0.00 0.00 1/1 tdbio_update_version_record [39]
0.00 0.00 1/1 tdbio_write_nextcheck [45]
0.00 0.00 5896/45984 keyid_from_pk [55]
0.00 0.00 824/824 tdbio_sync [81]
0.00 0.00 408/30107 init_trustdb [58]
0.00 0.00 4/7 log_info [104]
0.00 0.00 1/146691 make_timestamp [51]
0.00 0.00 1/1 keydb_rebuild_caches [123]
0.00 0.00 1/104 keydb_new [89]
0.00 0.00 1/104 keydb_release [90]
0.00 0.00 1/1 strtimestamp [134]
-----------------------------------------------
0.01 1.31 2/2 validate_keys.constprop.5 [1]
[2] 95.6 0.01 1.31 2 validate_key_list [2]
0.00 0.70 5395/5498 keydb_get_keyblock [3]
0.25 0.15 13853/13853 mark_usable_uid_certs [7]
0.03 0.08 5395/12407 get_pubkey_fast <cycle 1> [14]
0.00 0.03 13853/16254 tdbio_search_trust_bypk [18]
0.00 0.03 13853/15846 namehash_from_uid [20]
0.01 0.02 5395/6423 release_kbnode [22]
0.01 0.00 17549/138747 tdbio_read_record [16]
0.00 0.00 27706/30107 init_trustdb [58]
0.00 0.00 6517/45984 keyid_from_pk [55]
0.00 0.00 5397/5500 keydb_search [73]
0.00 0.00 5395/5395 merge_keys_and_selfsig [76]
0.00 0.00 5395/5395 clear_kbnode_flags [75]
0.00 0.00 2/2 keydb_search_reset [115]
-----------------------------------------------
0.00 0.01 103/5498 lookup.constprop.11 <cycle 1> [25]
0.00 0.70 5395/5498 validate_key_list [2]
[3] 52.1 0.00 0.72 5498 keydb_get_keyblock [3]
0.01 0.62 5498/5498 parse_keyblock_image [4]
0.00 0.09 5498/5498 keybox_get_keyblock [15]
0.00 0.00 10996/17639 iobuf_close [63]
-----------------------------------------------
I can provide more info or do more debugging if it would be useful to
track this down?
Regards,
--dkg
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 948 bytes
Desc: not available
URL: </pipermail/attachments/20160104/087263a1/attachment.sig>
More information about the Gnupg-devel
mailing list