Item7537: Severe performance issue with LdapContrib version 2014-06-06 (v4.38)

I am about to enhance the LdapContrib. As a start I installed it on a test installation. I found that the performance of the latest version is very bad, so bad that it can't be used in production.

I used the Monitor module to measure the performance. To enable:

• In twiki/bin/LocalLib.cfg set this:
  $ENV{TWIKI_MONITOR} = 10;
• In twiki/lib/TWiki/Contrib/LdapContrib.pm add this before use TWiki::Func (); :
  use Monitor;
Monitor::MonitorMethod('TWiki::Contrib::LdapContrib');

Result of an old LdapContrib version 2012-08-07 (v4.35):

==> Total time: 0.925428 wallclock secs ( 0.80 usr +  0.11 sys =  0.91 CPU)

| Count  |  Time (Min/Max) | Memory(Min/Max) | Total      | Method        |
|      1 |  0.000 /  0.000 |      0 /      0 | 2.90871e-05 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU) | TWiki::Contrib::LdapContrib::disconnect |
|      2 |  0.000 /  0.001 | 18446744073709551440 /      0 | 0.000762224 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU) | TWiki::Contrib::LdapContrib::finish |
[Fri Aug 01 21:36:42 2014] [error] [client 12.219.158.226] 
|      2 |  0.000 /  0.005 |      0 /    824 | 0.0051899 wallclock secs ( 0.01 usr +  0.00 sys =  0.01 CPU) | TWiki::Contrib::LdapContrib::getLdapContrib |
|     32 |  0.000 /  0.000 |      0 /    264 | 0.00115132 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU) | TWiki::Contrib::LdapContrib::getLoginOfWikiName |
|     41 |  0.000 /  0.000 |      0 /      0 | 0.00156307 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU) | TWiki::Contrib::LdapContrib::getWikiNameOfLogin |
|      1 |  0.005 /  0.005 |    824 /    824 | 0.00450587 wallclock secs ( 0.01 usr +  0.00 sys =  0.01 CPU) | TWiki::Contrib::LdapContrib::initCache |
|      1 |  0.000 /  0.000 |      0 /      0 | 0.000222921 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU) | TWiki::Contrib::LdapContrib::new |
|      1 |  0.000 /  0.000 |      0 /      0 | 1.19209e-05 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU) | TWiki::Contrib::LdapContrib::refreshCache |
|      1 |  0.000 /  0.000 |      0 /      0 | 1.40667e-05 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU) | TWiki::Contrib::LdapContrib::writeDebug |

Result of LdapContrib version 2014-06-06 (v4.38) from latest package:

==> Total time: 16.7232 wallclock secs ( 8.88 usr  5.48 sys +  0.02 cusr  0.61 csys = 14.99 CPU)

| Count  |  Time (Min/Max) | Memory(Min/Max) | Total      | Method        |
|   3508 |  0.001 /  0.003 |      0 /    264 | 4.454 wallclock secs ( 3.23 usr +  1.35 sys =  4.58 CPU) | TWiki::Contrib::LdapContrib::cacheUserFromEntry |
|      9 |  0.000 /  0.000 |      0 /      0 | 0.000214338 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU) | TWiki::Contrib::LdapContrib::checkError |
|      1 |  0.474 /  0.474 |   4116 /   4116 | 0.474017 wallclock secs ( 0.04 usr +  0.01 sys =  0.05 CPU) | TWiki::Contrib::LdapContrib::connect |
|      2 |  0.000 /  0.002 |      0 /     24 | 0.00225496 wallclock secs ( 0.00 usr +  0.01 sys =  0.01 CPU) | TWiki::Contrib::LdapContrib::disconnect |
|      2 |  0.001 /  0.006 |      0 /     24 | 0.006953 wallclock secs ( 0.00 usr +  0.01 sys =  0.01 CPU) | TWiki::Contrib::LdapContrib::finish |
|   3508 |  0.000 /  0.000 |      0 /    264 | 0.320298 wallclock secs ( 0.26 usr +  0.13 sys =  0.39 CPU) | TWiki::Contrib::LdapContrib::fromUtf8 |
|      1 |  0.000 /  0.000 |      0 /      0 | 0.000301123 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU) | TWiki::Contrib::LdapContrib::getAllIgnoredUsers |
|      1 |  0.006 /  0.006 |      0 /      0 | 0.00569606 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU) | TWiki::Contrib::LdapContrib::getAllLoginNames |
|   7028 |  0.000 /  0.001 |      0 /    524 | 0.11432 wallclock secs ( 0.16 usr +  0.00 sys =  0.16 CPU) | TWiki::Contrib::LdapContrib::getCacheTie |
|      2 |  0.000 / 11.939 |      0 /  83512 | 11.939 wallclock secs ( 7.84 usr +  2.38 sys = 10.22 CPU) | TWiki::Contrib::LdapContrib::getLdapContrib |
|      1 |  0.000 /  0.000 |      0 /      0 | 0.000494003 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU) | TWiki::Contrib::LdapContrib::getLoginOfWikiName |
|      1 |  0.003 /  0.003 |    348 /    348 | 0.00338101 wallclock secs ( 0.00 usr +  0.01 sys =  0.01 CPU) | TWiki::Contrib::LdapContrib::getRefreshMode |
|   7019 |  0.000 /  0.002 |      0 /    352 | 3.20766 wallclock secs ( 2.52 usr +  0.89 sys =  3.41 CPU) | TWiki::Contrib::LdapContrib::getWikiNameOfLogin |
|  14036 |  0.000 /  0.000 |      0 /    264 | 0.251607 wallclock secs ( 0.18 usr +  0.08 sys =  0.26 CPU) | TWiki::Contrib::LdapContrib::isValidCacheLoginName |
|      1 |  0.000 /  0.000 |      0 /      0 | 0.000246048 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU) | TWiki::Contrib::LdapContrib::new |
|      1 | 11.934 / 11.934 |  83164 /  83164 | 11.9341 wallclock secs ( 7.84 usr +  2.37 sys = 10.21 CPU) | TWiki::Contrib::LdapContrib::refreshCache |
|      1 |  0.011 /  0.011 |      0 /      0 | 0.0109229 wallclock secs ( 0.01 usr +  0.00 sys =  0.01 CPU) | TWiki::Contrib::LdapContrib::refreshIgnoredCache |
|      1 | 11.201 / 11.201 |  82180 /  82180 | 11.2006 wallclock secs ( 7.27 usr +  2.29 sys =  9.56 CPU) | TWiki::Contrib::LdapContrib::refreshUsersCache |
|      1 |  0.000 /  0.000 |      0 /      0 | 1.50204e-05 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU) | TWiki::Contrib::LdapContrib::resolveWikiNameClashes |
|      8 |  0.093 /  0.947 |      0 /   5700 | 2.78993 wallclock secs ( 1.12 usr +  0.02 sys =  1.14 CPU) | TWiki::Contrib::LdapContrib::search |
|      8 |  0.000 /  0.000 |      0 /      0 | 0.000889063 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU) | TWiki::Contrib::LdapContrib::toUtf8 |
|      9 |  0.000 /  0.069 |      0 /    196 | 0.0740871 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU) | TWiki::Contrib::LdapContrib::untieCache |
|     21 |  0.000 /  0.000 |      0 /      0 | 0.000392914 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU) | TWiki::Contrib::LdapContrib::writeDebug |

I use the same TWiki core code for both LdapContrib versions, and the same LDAP configuration, except for {Ldap}{UserBase} and {Ldap}{GroupBase}, which changed from a string to an array of strings.

-- TWiki:Main/PeterThoeny - 2014-08-01

Topic used for test: TWiki.LdapContrib.

-- TWiki:Main.PeterThoeny - 2014-08-01

I did one more change in configure of the new LdapContrib:

$TWiki::cfg{Ldap}{Precache} = 'existing';

No difference, still 16 - 17 sec for page load.

-- TWiki:Main.PeterThoeny - 2014-08-01

I notice that the cache is refreshed with each page load on the new LdapContrib, not sure why.

-- TWiki:Main.PeterThoeny - 2014-08-01

Here is the diff of the old and new config, with obfuscated dc:

2a3,4
> $TWiki::cfg{Ldap}{BackupCacheFile} = 0;
> $TWiki::cfg{Ldap}{BackupFileAge} = 0;
5a8
> $TWiki::cfg{Ldap}{CaseSensitiveGroup} = 0;
6a10
> $TWiki::cfg{Ldap}{CLIOnlyRefresh} = 0;
11c15
< $TWiki::cfg{Ldap}{GroupBase} = 'ou=group,dc=sub,dc=example,dc=com';
---
> $TWiki::cfg{Ldap}{GroupBase} = [ 'ou=group,dc=sub,dc=example,dc=com' ];
12a17
> $TWiki::cfg{Ldap}{GroupPattern} = '^.+$';
19a25
> $TWiki::cfg{Ldap}{LoginPattern} = '^.+$';
32c38,40
< $TWiki::cfg{Ldap}{Precache} = 1;
---
> $TWiki::cfg{Ldap}{Precache} = 'existing';
> $TWiki::cfg{Ldap}{PreserveTWikiUserMapping} = 0;
> $TWiki::cfg{Ldap}{PreserveWikiNames} = 0;
44c52
< $TWiki::cfg{Ldap}{UserBase} = 'dc=sub,dc=example,dc=com';
---
> $TWiki::cfg{Ldap}{UserBase} = [ 'dc=sub,dc=example,dc=com', ];

For reference, here are all configure values of new LdapContrib:

$TWiki::cfg{Ldap}{AllowChangePassword} = 0;
$TWiki::cfg{Ldap}{BackupCacheFile} = 0;
$TWiki::cfg{Ldap}{BackupFileAge} = 0;
$TWiki::cfg{Ldap}{Base} = 'dc=sub,dc=example,dc=com';
$TWiki::cfg{Ldap}{BindDN} = 'CN=Twiki Ldap,OU=Main Accounts,OU=Exchange Users,DC=sub,DC=example,DC=com';
$TWiki::cfg{Ldap}{BindPassword} = 'Password1';
$TWiki::cfg{Ldap}{CaseSensitiveGroup} = 0;
$TWiki::cfg{Ldap}{CaseSensitiveLogin} = 0;
$TWiki::cfg{Ldap}{CLIOnlyRefresh} = 0;
$TWiki::cfg{Ldap}{Debug} = 0;
#$TWiki::cfg{Ldap}{Debug} = 0;
$TWiki::cfg{Ldap}{Exclude} = 'TWikiGuest, TWikiContributor, RegistrationAgent, UnknownUser, AdminGroup, NobodyGroup, AdminUser, admin, guest';
$TWiki::cfg{Ldap}{GroupAttribute} = 'cn';
$TWiki::cfg{Ldap}{GroupBase} = [ 'ou=group,dc=sub,dc=example,dc=com' ];
$TWiki::cfg{Ldap}{GroupFilter} = 'objectClass=group';
$TWiki::cfg{Ldap}{GroupPattern} = '^.+$';
$TWiki::cfg{Ldap}{GroupScope} = 'sub';
$TWiki::cfg{Ldap}{GSSAPIuser} = '';
$TWiki::cfg{Ldap}{Host} = 'ldaps://1.2.3.4';
$TWiki::cfg{Ldap}{InnerGroupAttribute} = 'memberUid';
$TWiki::cfg{Ldap}{LoginAttribute} = 'sAMAccountName';
$TWiki::cfg{Ldap}{LoginFilter} = 'objectClass=user';
$TWiki::cfg{Ldap}{LoginPattern} = '^.+$';
$TWiki::cfg{Ldap}{MailAttribute} = 'mail';
$TWiki::cfg{Ldap}{MapGroups} = 0;
$TWiki::cfg{Ldap}{MaxCacheAge} = 86400;
$TWiki::cfg{Ldap}{MemberAttribute} = 'memberUid';
$TWiki::cfg{Ldap}{MemberIndirection} = 0;
$TWiki::cfg{Ldap}{MergeGroups} = 0;
$TWiki::cfg{Ldap}{NormalizeGroupNames} = 0;
$TWiki::cfg{Ldap}{NormalizeLoginNames} = 0;
$TWiki::cfg{Ldap}{NormalizeWikiNames} = 1;
$TWiki::cfg{Ldap}{PageSize} = 500;
$TWiki::cfg{Ldap}{Port} = 636;
$TWiki::cfg{Ldap}{Precache} = 'existing';
$TWiki::cfg{Ldap}{PreserveTWikiUserMapping} = 0;
$TWiki::cfg{Ldap}{PreserveWikiNames} = 0;
$TWiki::cfg{Ldap}{PrimaryGroupAttribute} = 'gidNumber';
$TWiki::cfg{Ldap}{RewriteGroups} = {};
$TWiki::cfg{Ldap}{RewriteWikiNames} = {
$TWiki::cfg{Ldap}{SASLMechanism} = 'PLAIN CRAM-MD5 EXTERNAL ANONYMOUS';
$TWiki::cfg{Ldap}{SecondaryPasswordManager} = 'none';
$TWiki::cfg{Ldap}{TLSCAFile} = '/root/certs/example.com.internal.crt';
$TWiki::cfg{Ldap}{TLSCAPath} = '';
$TWiki::cfg{Ldap}{TLSClientCert} = '/root/certs/example.com.crt';
$TWiki::cfg{Ldap}{TLSClientKey} = '/root/certs/example.com.key';
$TWiki::cfg{Ldap}{TLSSSLVersion} = 'tlsv1';
$TWiki::cfg{Ldap}{TLSVerify} = 'required';
$TWiki::cfg{Ldap}{UserBase} = [ 'dc=sub,dc=example,dc=com', ];
$TWiki::cfg{Ldap}{UserScope} = 'sub';
$TWiki::cfg{Ldap}{UseSASL} = 0;
$TWiki::cfg{Ldap}{UseTLS} = 1;
$TWiki::cfg{Ldap}{Version} = '3';
$TWiki::cfg{Ldap}{WikiGroupsBackoff} = 1;
$TWiki::cfg{Ldap}{WikiNameAliases} = '';
$TWiki::cfg{Ldap}{WikiNameAttributes} = 'cn';
$TWiki::cfg{PasswordManager} = 'TWiki::Users::LdapPasswdUser';
$TWiki::cfg{Plugins}{LdapNgPlugin}{Enabled} = 1;
$TWiki::cfg{UserMappingManager} = 'TWiki::Users::LdapUserMapping';

-- TWiki:Main.PeterThoeny - 2014-08-01

Update: Cache is no longer refreshed if I set $TWiki::cfg{Ldap}{Precache} = 'off';, and performance is better. However, at 2.6 wallclock secs still much longer than 0.9 wallclock secs on old LdapContrib.

-- TWiki:Main.PeterThoeny - 2014-08-01

Between the two initial tests, did you remove the database file in /working/work_areas/LdapContrib/cache.db ?

This is the desired behaviour:

• If {Precache} is either all or existing, all possible LDAP values will be retrieved and iterated over when the database is non-existing.
• After this, the database should only be refreshed whenever ?refreshldap=on is appended to the URL, or the database is over {MaxCacheAge} seconds.

I will set up a fresh 5.1.4 installation and the tests myself, hopefully I can replicate the problem and shed some light on what is wrong.

One thing is sure, the database should not be refreshed on every page load! If that were the case, our CERN TWiki would kneel a long time ago

-- TWiki:Main.TerjeAndersen - 2014-08-02

I'm working on reproducing this, and have installed two instances of TWiki 5.1.4, one running 4.35 and one running 4.38:

1. I ran /bin/configure on both, setting the minimum necessities for LdapContrib (registering Managers, setting paths etc.)
2. After adding the Monitor stuff to lib/LocalSite.cfg and LdapContrib.pm, I visited Main.WebHome.
3. I did a db_dump -p working/work_areas/LdapContrib/cache.db, and confirmed that the LdapContrib database indeed had been created.

1. Then I checked the apache error log, but could not see any debug info, just the header of the Monitoring:

   [root@farris LdapContrib]# tail -f /var/log/httpd/error_log
   [Sun Aug 03 19:28:43 2014] [error] [client 137.138.245.90]
   [Sun Aug 03 19:28:43 2014] [error] [client 137.138.245.90] | Count  |  Min   |  Max   | Total      | Method |
   

1. I took a look at http://twiki.org/cgi-bin/view/TWiki05x00/MonitorDotPm and tried it from the command line:

   [root@farris bin]# ./view -topic Main/WebHome
    topic text...
   | Count  |  Min   |  Max   | Total      | Method |
   

So I am currently stuck with getting the Monitor module to work. It doesn't report anything, any advice?

-- TWiki:Main.TerjeAndersen - 2014-08-03

Update: I managed got it to work by setting an exported environment variable in addition to the lib/LocalSite.cfg entry:

[root@farris bin]# export TWIKI_MONITOR=1
[root@farris bin]# ./view
topic text ....
| Count  |  Min   |  Max   | Total      | Method |
|      1 |  0.000 |  0.000 | 0.000405073 wallclock secs ( 0.00 usr +  0.00 sys =  0.00 CPU) | TWiki::Contrib::LdapContrib::addIgnoredUser |
|      1 |  0.014 |  0.014 | 0.0135438 wallclock secs ( 0.01 usr +  0.00 sys =  0.01 CPU) | TWiki::Contrib::LdapContrib::checkCacheForLoginName |
...

Will analyze and come back with the results.

-- TWiki:Main.TerjeAndersen - 2014-08-03 $TWiki::cfg{Ldap}{Precache}

Allright, I found the fault.

TWiki::Contrib::LdapContrib::getRefreshMode() is run at every page load in order to determine if the LdapContrib database should be refreshed or not.

If the {Ldap}{MaxCacheAge} preference has a above-zero value, the LASTUPDATED key in the LdapContrib is checked. If time() - LASTUPDATED is over {MaxCacheAge}, the database is due for a refresh.

After I implemented locks in LdapContrib, a database tie has to be done every time one reads from or writes to the database, like the following pseudo-code shows:

$this->getCacheTie('read');
# do read stuff ....
$this->untieCache();

The problem

When reading the LASTUPDATED key of the LdapContrib database in TWiki::Contrib::LdapContrib::getRefreshMode(), no tie was present.

The solution

Adding a read lock when the LASTUPDATED key of the LdapContrib is read:

    my $now = time();
+  $this->getCacheTie('read');
    my $lastUpdate = $this->{data}{LASTUPDATED} || 0;
+   $this->untieCache();
    $cacheAge = $now - $lastUpdate if $lastUpdate;

Why didn't I see this earlier?

Because in CERN's case, the {MaxCacheAge} is set to 0, which leads to the LASTUPDATED flag never being checked. Database refreshes have to be invoked manually.

Conclusion

I'll fix the bug and push it to SVN ASAP.

-- TWiki:Main.TerjeAndersen - 2014-08-03

LdapContrib updated.

-- TWiki:Main.TerjeAndersen - 2014-08-03

Thank you Terje for the very fast turnaround! I'll test it out.

-- TWiki:Main.PeterThoeny - 2014-08-04

I can confirm that the fix fixes the performance issue. Thank you Terje!

-- TWiki:Main.PeterThoeny - 2014-08-04