Closed Bug 956082 Opened 7 years ago Closed 7 years ago

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

Categories

(NSS :: Libraries, defect)

defect
Not set
normal

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: thatsafunnyname, Assigned: KaiE)

Details

Attachments

(1 file, 2 obsolete files)

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
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.
Assignee: nobody → kaie
Status: UNCONFIRMED → ASSIGNED
Ever confirmed: true
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.
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 on attachment 8361069 [details] [diff] [review]
bug956082_avoid_sdb_measureAccess_calls.patch

r+ rrelyea
Attachment #8361069 - Flags: review+
Thanks Peter!
Keywords: checkin-needed
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.
Thanks bob and wtc.
Attachment #8361069 - Attachment is obsolete: true
Target Milestone: --- → 3.16
Attached patch p3-956082Splinter Review
I've fixed the whitespace to our usual style, wrapped the long line, and added a comment that describes the intention of the expression.
Attachment #8361329 - Attachment is obsolete: true
https://hg.mozilla.org/projects/nss/rev/9934c8faef29
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
Keywords: checkin-needed
Resolution: --- → FIXED
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
Thank you Kai.
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
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.
You need to log in before you can comment on or make changes to this bug.