--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