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