Bug 75855 - [libc] getpwent(3) functions on 5.3 with large password file extremely slow
Summary: [libc] getpwent(3) functions on 5.3 with large password file extremely slow
Status: Open
Alias: None
Product: Base System
Classification: Unclassified
Component: kern (show other bugs)
Version: 5.3-RELEASE
Hardware: Any Any
: Normal Affects Only Me
Assignee: freebsd-bugs (Nobody)
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2005-01-05 15:50 UTC by bruce
Modified: 2015-11-10 12:19 UTC (History)
2 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description bruce 2005-01-05 15:50:46 UTC
      
getpwnam or getpwuid on our system with over 10,000 entries
in /etc/master.passwd is slow and uses alot of resources.

How-To-Repeat:       
Create an /etc/master.passwd with 10,000 entries.

Run this program:

#include <sys/types.h>
#include <pwd.h>

main( int argc, char *argv[] )
{
getpwnam( "someid" );
}

if run with truss, it can be seen doing 1,000 to 100,000
repetitions of 

lseek(3,0x5d3000,SEEK_SET)                       = 6107136 (0x5d3000)
read(0x3,0x8061000,0x1000)                       = 4096 (0x1000)
lseek(3,0x5d4000,SEEK_SET)                       = 6111232 (0x5d4000)
read(0x3,0x8062000,0x1000)                       = 4096 (0x1000)

where file handle 3 is /etc/spwd.db
Comment 1 bruce 2005-01-05 19:28:25 UTC
I have a workaround.

I copied /usr/src/lib/libc/gen/getpwent.c from a 4.7 system onto
the 5.3 system,  and then remade and installed libc.

Load average on our mail server went from 70 to 2.

-- 
Bruce Campbell
Engineering Computing
CPH-2374B
University of Waterloo
(519)888-4567 ext 5889

----------------------------------------
This mail sent through www.mywaterloo.ca
Comment 2 Kris Kennaway 2005-01-05 19:31:24 UTC
Adding relevant information to followup

----- Forwarded message from Bruce Campbell <bruce@engmail.uwaterloo.ca> -----

Date: Wed,  5 Jan 2005 11:08:22 -0500
From: Bruce Campbell <bruce@engmail.uwaterloo.ca>
To: freebsd-questions@freebsd.org
In-Reply-To: <1104932867.41dbf003405b1@www.nexusmail.uwaterloo.ca>
X-Originating-IP: 129.97.50.50
Subject: Re: New FreeBSD 5.3 e-mail server extremely slow - traced to
	getpwnam maybe ?

Quoting Bruce Campbell <bruce@engmail.uwaterloo.ca>:
> > On Tue, Jan 04, 2005 at 09:27:27PM -0500, Bruce Campbell wrote:
> > 
> > > I wrote a small program:
> > > 
> > >   #include <sys/types.h>
> > >   #include <pwd.h>
> > > 
> > >   main( int argc, char *argv[] )
> > >   {
> > >   getpwuid( 13076 );
> > >   }
> > > 
> > > and ran it under truss on 5.x and it generated 178,711 lines of output.
> > > (the bulk of which is those lseek/read calls as above)

It looks like the overhaul of getpwent Apr/2003 to make it thread safe:

  http://www.freebsd.org/cgi/cvsweb.cgi/src/lib/libc/gen/getpwent.c

may be the problem.

I've tested the dbm_fetch function independently on a large
file, and it is fine.

I've opened a bug report, and plan to build a replacement 4.x
mail server, as the most deterministic path to restoring
adequate e-mail service to our users.

Can anyone suggest a workaround ?

-- 
Bruce Campbell
Engineering Computing
CPH-2374B
University of Waterloo
(519)888-4567 ext 5889

----------------------------------------
This mail sent through www.mywaterloo.ca
_______________________________________________
freebsd-questions@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-questions
To unsubscribe, send any mail to "freebsd-questions-unsubscribe@freebsd.org"


----- End forwarded message -----
Comment 3 Kris Kennaway 2005-01-05 19:32:35 UTC
Adding relevant info to followup

----- Forwarded message from Bruce Campbell <bruce@engmail.uwaterloo.ca> -----

Date: Wed, 05 Jan 2005 08:47:47 -0500
From: Bruce Campbell <bruce@engmail.uwaterloo.ca>
Subject: Re: New FreeBSD 5.3 e-mail server extremely slow - traced to getpwnam
 maybe ?
To: Kris Kennaway <kris@obsecurity.org>
Cc: freebsd-questions@freebsd.org

Quoting Kris Kennaway <kris@obsecurity.org>:

> On Tue, Jan 04, 2005 at 09:27:27PM -0500, Bruce Campbell wrote:
> 
> > I wrote a small program:
> > 
> >   #include <sys/types.h>
> >   #include <pwd.h>
> > 
> >   main( int argc, char *argv[] )
> >   {
> >   getpwuid( 13076 );
> >   }
> > 
> > and ran it under truss on 5.x and it generated 178,711 lines of output.
> > (the bulk of which is those lseek/read calls as above)
> > ...
> 
> Try tuning the pwd_mkdb parameters (see hash(3)) in
> /usr/src/usr.sbin/pwd_mkdb/pwd_mkdb.c and recompile:
> 
> HASHINFO openinfo = {
>         4096,           /* bsize */
>         32,             /* ffactor */
>         256,            /* nelem */
>         2048 * 1024,    /* cachesize */
>         NULL,           /* hash() */
>         0               /* lorder */
> };
> 
> e.g. adjust nelem to 12000 to accomodate your
> significantly-larger-than-average password database.  If this helps,
> please submit a PR requesting that someone make an option to pwd_mkdb
> to tune this at runtime (or better yet, submit the patch to do this
> yourself - it's straightforward to modify the source to do this).

Thanks.  That had no effect on the large number of seeks/reads
to do a getpwuid of a specific uid.  I tried boosting that
number further, still no change.  I suspect the problem is related
to some change to the hash functions between 4.7 and 5.2.1 and I
hope to get to the bottom of it today.

I tried two getpwnam (as opposed to getpwuid) calls on 2 different userids, one
took 1000 seek/reads, the other 16,000, so it's all
pretty random, no doubt related to how stuff gets hashed.  On
4.7 it takes just one or two reads/seeks.

As each login via ipop, imap, and each sendmail, and just about everything
will be doing getpwnam's I think this is our problem.

-- 
Bruce Campbell
Engineering Computing
CPH-2374B
University of Waterloo
(519)888-4567 ext 5889

----------------------------------------
This mail sent through www.mywaterloo.ca


----- End forwarded message -----
Comment 4 bruce 2005-01-05 21:23:08 UTC
If anyone would like to investigate, I've just installed
a new 5.3 system and created a dummy 10,000 entry password file.

Please contact me for the password and hostname.

-- 
Bruce Campbell
Engineering Computing
CPH-2374B
University of Waterloo
(519)888-4567 ext 5889

----------------------------------------
This mail sent through www.mywaterloo.ca
Comment 5 bruce 2005-01-05 22:54:58 UTC
One of my co-workers appears to be on to something...


----- Forwarded message from Paul McKone <pdmckone at engmail uwaterloo ca> -----
    
After a bit of reading:

in /etc/nsswitch.conf

passwd: compat

produces lots and lots of lseek's

passwd: files

produces the expected number

"compat" is the compatibility database method for nis and stuff, or something
like that, called by nsdispatch, which is called by getpwent.c

"files" just looks at /etc/passwd and /etc/master.passwd

I've changed the entries for group and passwd in ecserv14's /etc/nsswitch.conf

group: files
passwd: files

and the output from "truss -f /root/a.out | & wc -l" has grone from 16341 to 119
lines.

We are onto something here. I don't know what's going on, but it's tied into
"nsdispatch" and "compat" somehow.

PDM

-- 
Paul McKone  Engineering Computing           Waterloo Unlimited
BASc         Systems Manager                 Development Team
===========  innovation through support      building a community of scholars
==== phone:  519-888-4567  ext 2757(am)      ext 5140(pm)
==== email:  pdmckone engmail.uwaterloo.ca   paul unlimited.uwaterloo.ca
==== https:  www.eng.uwaterloo.ca/~pdmckone  www.unlimited.uwaterloo.ca

----------------------------------------
This mail sent through www.mywaterloo.ca

----- End forwarded message -----


-- 
Bruce Campbell
Engineering Computing
CPH-2374B
University of Waterloo
(519)888-4567 ext 5889

----------------------------------------
This mail sent through www.mywaterloo.ca
Comment 6 pviersel 2007-12-07 08:03:08 UTC
This problem/bug still exists in 6.3-PRERELEASE (6.3-PRERELEASE FreeBSD
6.3-PRERELEASE #0: Wed Dec  5 13:35:05 CET 2007).
The more users there are in the password db, the bigger the impact on
performance (we had around 74000 entries and this renders the system
unusable).
The mentioned workaround (nsswitch.conf) does help a lot. Performance does
not match that of 4-stable, but it handles large(r) user bases well enough.
Comment 7 Adrian Chadd freebsd_committer 2008-01-25 10:05:28 UTC
Responsible Changed
From-To: freebsd-bugs->adrian

This tickles my fancy.
Comment 8 Philip M. Gollucci freebsd_committer 2010-06-11 00:18:43 UTC
Responsible Changed
From-To: krion->adrian

to committer
Comment 9 Scott Lambert 2010-12-17 00:42:01 UTC
We had someone run into this issue on the postfix mailing list
recently with FreeBSD 8.2-PRERELEASE.

Here is the link to the thread on the Postfix list:

http://tech.groups.yahoo.com/group/postfix-users/message/271899

I was about to open another PR for nsswitch.conf for lack of any
better idea on where to file this when someone mentioned this PR.

I have no idea what could be done to make for a better experience
out of the box.

Here is the thread where I first asked about this in 2007:
http://unix.derkeiler.com/Mailing-Lists/FreeBSD/stable/2007-04/msg00193.html

Here is some current testing from the same box 3+ years later with
a 90 line passwd file on the host and all the users in a jail on
the same machine:

$ uname -a          
FreeBSD web1.hosting.tcworks.net 7.4-PRERELEASE FreeBSD 7.4-PRERELEASE #0: Wed Dec  1 11:02:50 CST 2010     root@web1.hosting.tcworks.net:/usr/obj/usr/src/sys/GENERIC  i386

$ wc -l /etc/passwd 
      90 /etc/passwd

lambert@web1.hosting.tcworks.net /home/ezjails/users.tcworks.net/home
18:14:16 Thu Dec 16 $ egrep '^(group|passwd):' /etc/nsswitch.conf
group: files
passwd: files

lambert@web1.hosting.tcworks.net /home/ezjails/users.tcworks.net/home
18:14:31 Thu Dec 16 $ time ls -l | wc -l
    3917

real    0m0.124s
user    0m0.095s
sys     0m0.040s

lambert@web1.hosting.tcworks.net /home/ezjails/users.tcworks.net/home
18:14:34 Thu Dec 16 $ time ls -l | wc -l
    3917

real    0m0.113s
user    0m0.053s
sys     0m0.071s

lambert@web1.hosting.tcworks.net /home/ezjails/users.tcworks.net/home
18:14:35 Thu Dec 16 $ time ls -l | wc -l
    3917

real    0m0.124s
user    0m0.078s
sys     0m0.056s

$ sudo vi /etc/nsswitch.conf

lambert@web1.hosting.tcworks.net /home/ezjails/users.tcworks.net/home
18:15:37 Thu Dec 16 $ egrep '^(group|passwd):' /etc/nsswitch.conf
group: compat
passwd: compat

lambert@web1.hosting.tcworks.net /home/ezjails/users.tcworks.net/home
18:15:47 Thu Dec 16 $ time ls -l | wc -l
    3917

real    0m0.748s
user    0m0.384s
sys     0m0.355s

lambert@web1.hosting.tcworks.net /home/ezjails/users.tcworks.net/home
18:15:51 Thu Dec 16 $ time ls -l | wc -l
    3917

real    0m0.743s
user    0m0.425s
sys     0m0.317s

lambert@web1.hosting.tcworks.net /home/ezjails/users.tcworks.net/home
18:15:54 Thu Dec 16 $ time ls -l | wc -l
    3917

real    0m0.734s
user    0m0.381s
sys     0m0.351s


Then from inside the jail:

$ wc -l /etc/passwd 
    3935 /etc/passwd

lambert@users.tcworks.net /home
18:04:11 Thu Dec 16 $ egrep '^(group|passwd):' /etc/nsswitch.conf
group: compat
passwd: compat

lambert@users.tcworks.net /home
18:16:32 Thu Dec 16 $ time ls -l | wc -l
    3917

real    1m0.092s
user    0m11.030s
sys     0m47.301s

I ran top outside the jail while running ls the first time and got:

68759    997           1 116    0  4492K  2140K CPU0    0   0:25 88.96% ls
later during the same run ...
68759    997           1 118    0  4492K  2240K CPU0    0   0:57 98.29% ls

lambert@users.tcworks.net /home
18:17:35 Thu Dec 16 $ time ls -l | wc -l
    3917

real    1m1.616s
user    0m11.464s
sys     0m48.228s

lambert@users.tcworks.net /home
18:18:57 Thu Dec 16 $ time ls -l | wc -l
    3917

real    1m0.295s
user    0m12.076s
sys     0m46.384s

lambert@users.tcworks.net /home
18:20:08 Thu Dec 16 $ 

$ sudo vi /etc/nsswitch.conf

lambert@users.tcworks.net /home
18:20:49 Thu Dec 16 $ egrep '^(group|passwd):' /etc/nsswitch.conf
group: files
passwd: files

lambert@users.tcworks.net /home
18:20:53 Thu Dec 16 $ time ls -l | wc -l
    3917

real    0m0.148s
user    0m0.086s
sys     0m0.074s

lambert@users.tcworks.net /home
18:20:59 Thu Dec 16 $ time ls -l | wc -l
    3917

real    0m0.158s
user    0m0.078s
sys     0m0.089s

lambert@users.tcworks.net /home
18:21:00 Thu Dec 16 $ time ls -l | wc -l
    3917

real    0m0.157s
user    0m0.035s
sys     0m0.134s

-- 
Scott Lambert                    KC5MLE                       Unix SysAdmin
lambert@lambertfam.org
Comment 10 Scott Lambert 2010-12-17 00:42:01 UTC
We had someone run into this issue on the postfix mailing list
recently with FreeBSD 8.2-PRERELEASE.

Here is the link to the thread on the Postfix list:

http://tech.groups.yahoo.com/group/postfix-users/message/271899

I was about to open another PR for nsswitch.conf for lack of any
better idea on where to file this when someone mentioned this PR.

I have no idea what could be done to make for a better experience
out of the box.

Here is the thread where I first asked about this in 2007:
http://unix.derkeiler.com/Mailing-Lists/FreeBSD/stable/2007-04/msg00193.html

Here is some current testing from the same box 3+ years later with
a 90 line passwd file on the host and all the users in a jail on
the same machine:

$ uname -a          
FreeBSD web1.hosting.tcworks.net 7.4-PRERELEASE FreeBSD 7.4-PRERELEASE #0: Wed Dec  1 11:02:50 CST 2010     root@web1.hosting.tcworks.net:/usr/obj/usr/src/sys/GENERIC  i386

$ wc -l /etc/passwd 
      90 /etc/passwd

lambert@web1.hosting.tcworks.net /home/ezjails/users.tcworks.net/home
18:14:16 Thu Dec 16 $ egrep '^(group|passwd):' /etc/nsswitch.conf
group: files
passwd: files

lambert@web1.hosting.tcworks.net /home/ezjails/users.tcworks.net/home
18:14:31 Thu Dec 16 $ time ls -l | wc -l
    3917

real    0m0.124s
user    0m0.095s
sys     0m0.040s

lambert@web1.hosting.tcworks.net /home/ezjails/users.tcworks.net/home
18:14:34 Thu Dec 16 $ time ls -l | wc -l
    3917

real    0m0.113s
user    0m0.053s
sys     0m0.071s

lambert@web1.hosting.tcworks.net /home/ezjails/users.tcworks.net/home
18:14:35 Thu Dec 16 $ time ls -l | wc -l
    3917

real    0m0.124s
user    0m0.078s
sys     0m0.056s

$ sudo vi /etc/nsswitch.conf

lambert@web1.hosting.tcworks.net /home/ezjails/users.tcworks.net/home
18:15:37 Thu Dec 16 $ egrep '^(group|passwd):' /etc/nsswitch.conf
group: compat
passwd: compat

lambert@web1.hosting.tcworks.net /home/ezjails/users.tcworks.net/home
18:15:47 Thu Dec 16 $ time ls -l | wc -l
    3917

real    0m0.748s
user    0m0.384s
sys     0m0.355s

lambert@web1.hosting.tcworks.net /home/ezjails/users.tcworks.net/home
18:15:51 Thu Dec 16 $ time ls -l | wc -l
    3917

real    0m0.743s
user    0m0.425s
sys     0m0.317s

lambert@web1.hosting.tcworks.net /home/ezjails/users.tcworks.net/home
18:15:54 Thu Dec 16 $ time ls -l | wc -l
    3917

real    0m0.734s
user    0m0.381s
sys     0m0.351s


Then from inside the jail:

$ wc -l /etc/passwd 
    3935 /etc/passwd

lambert@users.tcworks.net /home
18:04:11 Thu Dec 16 $ egrep '^(group|passwd):' /etc/nsswitch.conf
group: compat
passwd: compat

lambert@users.tcworks.net /home
18:16:32 Thu Dec 16 $ time ls -l | wc -l
    3917

real    1m0.092s
user    0m11.030s
sys     0m47.301s

I ran top outside the jail while running ls the first time and got:

68759    997           1 116    0  4492K  2140K CPU0    0   0:25 88.96% ls
later during the same run ...
68759    997           1 118    0  4492K  2240K CPU0    0   0:57 98.29% ls

lambert@users.tcworks.net /home
18:17:35 Thu Dec 16 $ time ls -l | wc -l
    3917

real    1m1.616s
user    0m11.464s
sys     0m48.228s

lambert@users.tcworks.net /home
18:18:57 Thu Dec 16 $ time ls -l | wc -l
    3917

real    1m0.295s
user    0m12.076s
sys     0m46.384s

lambert@users.tcworks.net /home
18:20:08 Thu Dec 16 $ 

$ sudo vi /etc/nsswitch.conf

lambert@users.tcworks.net /home
18:20:49 Thu Dec 16 $ egrep '^(group|passwd):' /etc/nsswitch.conf
group: files
passwd: files

lambert@users.tcworks.net /home
18:20:53 Thu Dec 16 $ time ls -l | wc -l
    3917

real    0m0.148s
user    0m0.086s
sys     0m0.074s

lambert@users.tcworks.net /home
18:20:59 Thu Dec 16 $ time ls -l | wc -l
    3917

real    0m0.158s
user    0m0.078s
sys     0m0.089s

lambert@users.tcworks.net /home
18:21:00 Thu Dec 16 $ time ls -l | wc -l
    3917

real    0m0.157s
user    0m0.035s
sys     0m0.134s

-- 
Scott Lambert                    KC5MLE                       Unix SysAdmin
lambert@lambertfam.org
Comment 11 Mark Linimon freebsd_committer freebsd_triage 2011-01-03 21:02:27 UTC
Responsible Changed
From-To: adrian->freebsd-bugs

with bugmeister hat on, reassign back to mailing list.  (adrian did 
not respond to a request for status).
Comment 12 Gordon Tetlow 2011-05-07 09:59:52 UTC
The reason for this is how the compat code scans the password table
looking for compat entries. The algorithm is O(m * n) where m is the
number of entries to lookup (in the case of the ls -l /home) and n is
the number of lines in the password database. This is clearly
pessimized and should be able to be better optimized.

The current logic is something like:

scan each entry in the passwd db:
  if it starts with '+/-' do compat checking
  if the key matches, return

The logic for files is something like:
Lookup exact entry in db, return if found.

The process could probably do some amount of intelligence to avoid
rescanning the password database on every lookup, but I can't think of
anything off the top of my head (it's late). I'll think about it some
more.
Comment 13 Enji Cooper freebsd_committer 2015-11-10 12:19:40 UTC
This seems like something we might want to fix, benno?