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

RESOLVED FIXED in 3.16

Status

NSS
Libraries
RESOLVED FIXED
4 years ago
6 months ago

People

(Reporter: Peter (Stig) Edwards, Assigned: kaie)

Tracking

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment, 2 obsolete attachments)

(Reporter)

Description

4 years ago
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

4 years ago
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
(Reporter)

Comment 2

4 years ago
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

4 years ago
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
(Reporter)

Comment 4

4 years ago
Created attachment 8361069 [details] [diff] [review]
bug956082_avoid_sdb_measureAccess_calls.patch

Comment 5

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

r+ rrelyea
Attachment #8361069 - Flags: review+

Comment 6

4 years ago
Thanks Peter!
Keywords: checkin-needed

Comment 7

4 years ago
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.
(Reporter)

Comment 8

4 years ago
Created attachment 8361329 [details] [diff] [review]
bug956082_avoid_sdb_measureAccess_calls_deloused.patch

Thanks bob and wtc.
Attachment #8361069 - Attachment is obsolete: true
(Assignee)

Updated

4 years ago
Target Milestone: --- → 3.16
(Assignee)

Comment 9

4 years ago
Created attachment 8364551 [details] [diff] [review]
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.
Attachment #8361329 - Attachment is obsolete: true
(Assignee)

Comment 10

4 years ago
https://hg.mozilla.org/projects/nss/rev/9934c8faef29
Status: ASSIGNED → RESOLVED
Last Resolved: 4 years ago
Keywords: checkin-needed
Resolution: --- → FIXED
(Assignee)

Comment 11

4 years ago
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
(Reporter)

Comment 12

4 years ago
Thank you Kai.

Comment 13

6 months ago
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
(Reporter)

Comment 14

6 months ago
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.