956082 - Avoid call to sdb_measureAccess in lib/softoken/sdb.c s_open if NSS_SDB_USE_CACHE is "yes" or "no"

Status: RESOLVED FIXED

(NSS :: Libraries, defect)

Description

[Peter (Stig) Edwards]

User Agent: Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/31.0.1650.63 Safari/537.36

Steps to reproduce:

Hello and thank you for nss,

With a version of curl built with NSS on RHEL6 and with the environment variable NSS_SDB_USE_CACHE set to "yes" or "no", strace "access" calls from the command line curl making a HTTPS request:

export NSS_SDB_USE_CACHE=yes
strace -f -e trace=access curl 'https://bugzilla.mozilla.org'
 
also see https://bugzilla.redhat.com/show_bug.cgi?id=1044666#c7 for a reproducer that does not use curl, essentially just a mainprog including nss.h and calling NSS_InitContext("sql:/etc/pki/nssdb", "", "", "", &initparams, NSS_INIT_READONLY | NSS_INIT_PK11RELOAD), initparams being memset to \0.

I can also reproduce using multinit from RH src RPM for nss-3.15.1

strace -f -e trace=access bin/multinit --lib1_db sql:/etc/pki/nssdb --lib1_readonly


Actual results:

There are many access system calls to paths ending in _dOeSnotExist_.db that do not exist, with fast "disks" and many processes calling NSS_InitContext frequently the dentry cache can grow very quickly.


Expected results:

When the environment variable NSS_SDB_USE_CACHE is set to "yes" or "no" I think the call in s_open in lib/softoken/sdb.c to sdb_measureAccess can be avoided, saving up to 33ms of time and up to 10000 access system calls and corresponding dentry cache entries.

The patch in https://bugzilla.redhat.com/show_bug.cgi?id=1044666#c8 guards the call to sdb_measureAccess with a check against the environment variable NSS_SDB_USE_CACHE, it would be better if the environment variable check was not performed in more than one place.

nss/lib/softoken/sdb.c

     /* how long does it take to test for a non-existant file in our working
      * directory? Allows us to test if we may be on a network file system */
-    accessOps = sdb_measureAccess(directory);
+    accessOps = 1;
+    {
+       char *env;
+       env = PR_GetEnv("NSS_SDB_USE_CACHE");
+       if ( !(env) || ( (PORT_Strcasecmp(env,"no") != 0) && (PORT_Strcasecmp(env,"yes") != 0) ) ){
+         accessOps = sdb_measureAccess(directory);
+       }
+    }

     /*
      * open the cert data base

Comment 1

[Wan-Teh Chang]

Kai: you last worked on this code. Could you take a look at the
patch that Peter (Stig) Edwards included in comment 0? Thanks.

Please assign the bug to me if you don't have time to work on this.

Comment 2

[Peter (Stig) Edwards]

Previously I had only tested with RedHat src RPM nss-3.15.1-15.el6.
Building ftp://ftp.mozilla.org/pub/mozilla.org/security/nss/releases/NSS_3_15_3_1_RTM/src/nss-3.15.3.1-with-nspr-4.10.2.tar.gz on RHEL6.5 2.6.32-431.el6.x86_64 with:
 
cd nss
USE_64=1 gmake nss_build_all
export LD_LIBRARY_PATH=dist/Linux2.6_x86_64_glibc_PTH_64_DBG.OBJ/lib
 
export NSS_SDB_USE_CACHE=yes
strace -fc -e trace=access dist/Linux2.6_x86_64_glibc_PTH_64_DBG.OBJ/bin/multinit --lib1_db sql:/etc/pki/nssdb --lib1_readonly
>> No main_db has been specified
usage: multinit [--order initOrder] --main_db nss_db [--lib1_db nss_db]
      [--lib2_db nss_db] [--main_readonly] [--lib1_readonly] [--lib2_readonly]
      [--main_command nss_command] [--lib1_command nss_command] [--lib2_command nss_command]
      [--main_token_name token_name] [--lib1_token_name token_name] [--lib2_token_name token_name]
      [--oldStype] [--verbose] [--summary] [--help]
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.000138           0       825       821 access
------ ----------- ----------- --------- --------- ----------------
100.00    0.000138                   825       821 total
 
I see the same behaviour as seen when using the RedHat src RPM nss-3.15.1-15.el6.
After applying the patch and rebuilding, sdb_measureAccess is not called when NSS_SDB_USE_CACHE is set to "yes" or "no".
The 30 access calls are to cert9 and key4 .db[-(journal|wal)] files in the system and local db locations.
 
strace -fc -e trace=access dist/Linux2.6_x86_64_glibc_PTH_64_DBG.OBJ/bin/multinit --lib1_db sql:/etc/pki/nssdb --lib1_readonly
>> No main_db has been specified
usage: multinit [--order initOrder] --main_db nss_db [--lib1_db nss_db]
      [--lib2_db nss_db] [--main_readonly] [--lib1_readonly] [--lib2_readonly]
      [--main_command nss_command] [--lib1_command nss_command] [--lib2_command nss_command]
      [--main_token_name token_name] [--lib1_token_name token_name] [--lib2_token_name token_name]
      [--oldStype] [--verbose] [--summary] [--help]
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  -nan    0.000000           0        34        30 access
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                    34        30 total
 
Example using curl:
 
export NSS_SDB_USE_CACHE=yes
strace -fc -e trace=access curl 'https://google.com'
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  -nan    0.000000           0        35        31 access
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                    35        31 total
 
export NSS_SDB_USE_CACHE=auto
strace -fc -e trace=access curl 'https://google.com'
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.001412           0      4505      4497 access
------ ----------- ----------- --------- --------- ----------------
100.00    0.001412                  4505      4497 total
 
Thanks.

Comment 3

[Robert Relyea]

wtc, peter's patch looks good, Peter if you attach the patch to the bug I can give it an r+ and we can check it in.

bob

Comment 4

[Peter (Stig) Edwards]

Attachment: bug956082_avoid_sdb_measureAccess_calls.patch

Comment 5

[Robert Relyea]

Comment on attachment 8361069 [details] [diff] [review]
bug956082_avoid_sdb_measureAccess_calls.patch

r+ rrelyea

Comment 6

[Robert Relyea]

Thanks Peter!

Comment 7

[Wan-Teh Chang]

Comment on attachment 8361069 [details] [diff] [review]
bug956082_avoid_sdb_measureAccess_calls.patch

Review of attachment 8361069 [details] [diff] [review]:
-----------------------------------------------------------------

::: lib/softoken/sdb.c
@@ +2014,5 @@
> +    accessOps = 1;
> +    {
> +        char *env;
> +        env = PR_GetEnv("NSS_SDB_USE_CACHE");
> +        if ( !(env) || ( (PORT_Strcasecmp(env,"no") != 0) && (PORT_Strcasecmp(env,"yes") != 0) ) ){

Nit: change "!(env)" to "!env". The parentheses are not necessary.

Please also add a space before the commas in the two PORT_Strcasecmp calls.

Comment 8

[Peter (Stig) Edwards]

Attachment: bug956082_avoid_sdb_measureAccess_calls_deloused.patch

Thanks bob and wtc.

Comment 9

[Kai Engert [:KaiE:]]

Attachment: p3-956082

I've fixed the whitespace to our usual style, wrapped the long line, and added a comment that describes the intention of the expression.

Comment 10

[Kai Engert [:KaiE:]]

https://hg.mozilla.org/projects/nss/rev/9934c8faef29

Comment 11

[Kai Engert [:KaiE:]]

Sorry, I forgot to include bug number and reviewer in the commit message.
I've commited an additional whitespace change to add that information.
https://hg.mozilla.org/projects/nss/rev/5a67f6beee9a

Comment 12

[Peter (Stig) Edwards]

Thank you Kai.

Comment 13

[hamiltont]

Apologies for commenting on fixed bug, but it's still present (in late 2016) on AWS EC2 images. Hopefully this post saves someone else from repeating my mistake of spending 4 hours tracking this down. Setting export NSS_SDB_USE_CACHE=yes fixes the issue for me. Here's what I know: 

[ec2-user@ip-10-0-233-18 splits]$ strace -fc -e trace=access curl 'https://www.google.com' > /dev/null
Process 122792 attached
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 10039    0 10039    0     0  40688      0 --:--:-- --:--:-- --:--:-- 40643
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.000017           0      4149      4145 access
------ ----------- ----------- --------- --------- ----------------
100.00    0.000017                  4149      4145 total
[ec2-user@ip-10-0-233-18 splits]$ yum info curl nss-softokn
Loaded plugins: priorities, update-motd, upgrade-helper
Installed Packages
Name        : curl
Arch        : x86_64
Version     : 7.47.1
Release     : 9.68.amzn1
Size        : 543 k
Repo        : installed
Summary     : A utility for getting files from remote servers (FTP, HTTP, and others)
URL         : http://curl.haxx.se/
License     : MIT
Description : curl is a command line tool for transferring data with URL syntax, supporting
            : FTP, FTPS, HTTP, HTTPS, SCP, SFTP, TFTP, TELNET, DICT, LDAP, LDAPS, FILE, IMAP,
            : SMTP, POP3 and RTSP.  curl supports SSL certificates, HTTP POST, HTTP PUT, FTP
            : uploading, HTTP form based upload, proxies, cookies, user+password
            : authentication (Basic, Digest, NTLM, Negotiate, kerberos...), file transfer
            : resume, proxy tunneling and a busload of other useful tricks.

Name        : nss-softokn
Arch        : x86_64
Version     : 3.16.2.3
Release     : 14.4.39.amzn1
Size        : 1.0 M
Repo        : installed
Summary     : Network Security Services Softoken Module
URL         : http://www.mozilla.org/projects/security/pki/nss/
License     : MPLv2.0
Description : Network Security Services Softoken Cryptographic Module

Available Packages
Name        : nss-softokn
Arch        : i686
Version     : 3.16.2.3
Release     : 14.4.39.amzn1
Size        : 440 k
Repo        : amzn-updates/latest
Summary     : Network Security Services Softoken Module
URL         : http://www.mozilla.org/projects/security/pki/nss/
License     : MPLv2.0
Description : Network Security Services Softoken Cryptographic Module

[ec2-user@ip-10-0-233-18 splits]$ cat /etc/*rel*
NAME="Amazon Linux AMI"
VERSION="2016.09"
ID="amzn"
ID_LIKE="rhel fedora"
VERSION_ID="2016.09"
PRETTY_NAME="Amazon Linux AMI 2016.09"
ANSI_COLOR="0;33"
CPE_NAME="cpe:/o:amazon:linux:2016.09:ga"
HOME_URL="http://aws.amazon.com/amazon-linux-ami/"
cat: /etc/prelink.conf.d: Is a directory
Amazon Linux AMI release 2016.09
cpe:/o:amazon:linux:2016.09:ga
[ec2-user@ip-10-0-233-18 splits]$ export NSS_SDB_USE_CACHE=yes
[ec2-user@ip-10-0-233-18 splits]$ strace -fc -e trace=access curl 'https://www.google.com' > /dev/null
Process 15387 attached
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 10049    0 10049    0     0   109k      0 --:--:-- --:--:-- --:--:--  111k
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0        32        30 access
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                    32        30 total

Comment 14

[Peter (Stig) Edwards]

Hamilton T, this bug was to avoid calls to sdb_measureAccess in lib/softoken/sdb.c s_open if NSS_SDB_USE_CACHE is "yes" or "no".

Prior to the fix, if you set NSS_SDB_USE_CACHE=yes (or no) then the calls were still made.