3:35 p.m.
Hello OpenLDAP-Technical,
Using the oldie but goodie LDAP performance testing tool, SLAMD, I've been doing
performance tests. What I found was that stats logging (olcLogLevel: 256) degrades
performance significantly. A pity, because it is recommended in the manual. Also, it
considered very useful by those of us who've been running OpenLDAP for a while.
The test was performed on Dell Workstation Intel Xeon E-2630 v3 @ 2.40Ghz Xen 4.6.5
hypervisor running Linux 4.4.0 Ubuntu 16.04, 4 vcpus pinned to the hypervisor and the
other 12 pinned to the OpenLDAP VM. The OpenLDAP VM was allocated 8GB RAM and runs
OpenLDAP 2.5.13 (Symas RPM build) on RedHat 8.7. Ten thousand fake users were created in
an OU=FakePeople for testing.
I am aware that contention with disk I/O can cause problems, so I tried eliminating
systemd-journald and rsyslogd in order to test "pure OpenLDAP" response times
but was not perfectly successful. I ran slapd in the foreground using "slapd -d 256
... 2>/dev/null". But then I noticed that systemd-journald still was logging to
"session-4.scope". I tried "systemctl stop systemd-journald" and
"systemctl stop systemd-journald.socket" and "systemctl stop
systemd-journald-dev-log.socket" but was not able to stop systemd-journald from
showing up using CPU in "htop". I tried limiting it also by setting
RateLimitIntervalSec=1s and RateLimitBurst=1 in /etc/system/journald.conf. This reduced
the logging but I still saw "/usr/lib/system/systemd-journald" taking 100% of
one vcpu during the performance tests whenever olcLogLevel was set to 256.
The test results I will include with this post are from the Asynchronous Search Rate SLAMD
job class using LDAPSearch filters of valid random values for indexed attributeTypes
"uid" and "mail" matching exact filters (equality match).
Using LogLevel 256, the Asynchronous Search Rate test with 3 clients, 2 connection threads
each (from laptop i7-1280P vPro Processor), OpenLDAP returned an average 10,932 results
completed per second with err=0 and average 21ms response time.
Then I ran ldapmodify to changetype: replace olcLogLevel to 0, reran the same test, and
saw OpenLDAP perform much better. The same test with olcLogLevel=0 returned 84,286 results
per second with err=0 (671% increase) and average response time of 2.6 ms (88% decrease).
Watching "htop" during this test showed all vcpus firing a lot more evenly and
hotter than the test with olcLogLevel=256; it was very clear how efficient slapd can be
without having to do any logging.
I ran several samples of each test and picked the best for each of olcLogLevels I tested.
I ran other tests like 3 and 4 clients times 50 connections each, also ran Basic Bind Rate
and saw similar patterns there. I don't mind sharing my configs or the test data if
anyone is interested.
And so naturally, I am wondering if this is a known limitation and also whether it is
something that can be addressed or is a hard constraint. I guess I had expected some
impact as a result of logging (nothing comes for free...) but not this much.
Thanks,
Chris Paul | Rex Consulting | https://www.rexconsulting.net
9:12 a.m.
New subject: Antw: [EXT] OpenLDAP stats logging performance degradation
On Jan 2, 2023, at 1:21 AM, Ulrich Windl
<Ulrich.Windl(a)rz.uni-regensburg.de> wrote:
>
> I am aware that contention with disk I/O can cause problems, so I tried
> eliminating systemd-journald and rsyslogd in order to test "pure OpenLDAP"
> response times but was not perfectly successful. I ran slapd in the
> foreground using "slapd -d 256 ... 2>/dev/null". But then I noticed that
> systemd-journald still was logging to "session-4.scope". I tried
"systemctl
> stop systemd-journald" and "systemctl stop systemd-journald.socket"
and
> "systemctl stop systemd-journald-dev-log.socket" but was not able to stop
> systemd-journald from showing up using CPU in "htop". I tried limiting it
> also by setting RateLimitIntervalSec=1s and RateLimitBurst=1 in
> /etc/system/journald.conf. This reduced the logging but I still saw
> "/usr/lib/system/systemd-journald" taking 100% of one vcpu during the
> performance tests whenever olcLogLevel was set to 256.
Did you try to revert systemd logging to ramdisk only (/run/log/journal/ (or so)) instead
of /var/log/journal/?
Apologize for missing this before my earlier response. Looks like Chris tried the debug
route. I’m guessing there must be a way to detach the system logging facility completely
from the daemon?
If someone has suggestions I’ll run some tests to verify.
Thanks
—
Shawn
9:04 a.m.
On Jan 3, 2023, at 5:17 AM, Quanah Gibson-Mount
<quanah(a)fast-mail.org> wrote:
--On Friday, December 30, 2022 11:35 PM +0000 Christopher Paul
<chris.paul(a)rexconsulting.net> wrote:
> Using the oldie but goodie LDAP performance testing tool, SLAMD, I've
> been doing performance tests. What I found was that stats logging
> (olcLogLevel: 256) degrades performance significantly. A pity, because it
> is recommended in the manual. Also, it considered very useful by those of
> us who've been running OpenLDAP for a while.
Yes, this is a well known, documented, and discussed issue. It makes logical sense if
you think of the massive overhead incurred with logging lots of information vs logging
nothing at all. I would note that the amount of perf hit taken depends on the system
setup. For example, if systemd is doing logging along with syslog, which is often the
case these days, then that's your worst case scenario, followed by just direct logging
to syslog being the next worst.
You might want to play with OpenLDAP 2.6 which allows direct logging to a logfile on
disk, completely bypassing systemd and/or syslog, this is your best case scenario
currently for when logging is necessary.
It gets worse on RHEL systems due to rate limiting, where large swaths of statements are
skipped entirely.
I concur with Quanah. Use the 2.6 logger. My tests w/ a log level of sync (which includes
stats), showed a perf boost of approximately a factor or 2.
I suppose one could achieve the same on earlier releases by disabling syslog and enabling
the debug logger instead?
—
Shawn
3:17 a.m.
--On Friday, December 30, 2022 11:35 PM +0000 Christopher Paul
<chris.paul(a)rexconsulting.net> wrote:
Using the oldie but goodie LDAP performance testing tool, SLAMD,
I've
been doing performance tests. What I found was that stats logging
(olcLogLevel: 256) degrades performance significantly. A pity, because it
is recommended in the manual. Also, it considered very useful by those of
us who've been running OpenLDAP for a while.
Yes, this is a well known, documented, and discussed issue. It makes
logical sense if you think of the massive overhead incurred with logging
lots of information vs logging nothing at all. I would note that the
amount of perf hit taken depends on the system setup. For example, if
systemd is doing logging along with syslog, which is often the case these
days, then that's your worst case scenario, followed by just direct logging
to syslog being the next worst.
You might want to play with OpenLDAP 2.6 which allows direct logging to a
logfile on disk, completely bypassing systemd and/or syslog, this is your
best case scenario currently for when logging is necessary.
Regards,
Quanah
11:21 p.m.
New subject: Antw: [EXT] OpenLDAP stats logging performance degradation
>> Christopher Paul <chris.paul(a)rexconsulting.net> schrieb
am 31.12.2022 um 00:35
in Nachricht
<PH7PR12MB571022A0A3EA320F926EA69C9DF09(a)PH7PR12MB5710.namprd12.prod.outlook.com>
Hello OpenLDAP-Technical,
Using the oldie but goodie LDAP performance testing tool, SLAMD, I've been
doing performance tests. What I found was that stats logging (olcLogLevel:
256) degrades performance significantly. A pity, because it is recommended in
the manual. Also, it considered very useful by those of us who've been
running OpenLDAP for a while.
The test was performed on Dell Workstation Intel Xeon E-2630 v3 @ 2.40Ghz
Xen 4.6.5 hypervisor running Linux 4.4.0 Ubuntu 16.04, 4 vcpus pinned to the
hypervisor and the other 12 pinned to the OpenLDAP VM. The OpenLDAP VM was
allocated 8GB RAM and runs OpenLDAP 2.5.13 (Symas RPM build) on RedHat 8.7.
Ten thousand fake users were created in an OU=FakePeople for testing.
I am aware that contention with disk I/O can cause problems, so I tried
eliminating systemd-journald and rsyslogd in order to test "pure OpenLDAP"
response times but was not perfectly successful. I ran slapd in the
foreground using "slapd -d 256 ... 2>/dev/null". But then I noticed that
systemd-journald still was logging to "session-4.scope". I tried
"systemctl
stop systemd-journald" and "systemctl stop systemd-journald.socket" and
"systemctl stop systemd-journald-dev-log.socket" but was not able to stop
systemd-journald from showing up using CPU in "htop". I tried limiting it
also by setting RateLimitIntervalSec=1s and RateLimitBurst=1 in
/etc/system/journald.conf. This reduced the logging but I still saw
"/usr/lib/system/systemd-journald" taking 100% of one vcpu during the
performance tests whenever olcLogLevel was set to 256.
Did you try to revert systemd logging to ramdisk only (/run/log/journal/ (or so)) instead
of /var/log/journal/?
The test results I will include with this post are from the Asynchronous
Search Rate SLAMD job class using LDAPSearch filters of valid random values
for indexed attributeTypes "uid" and "mail" matching exact filters
(equality
match).
Using LogLevel 256, the Asynchronous Search Rate test with 3 clients, 2
connection threads each (from laptop i7-1280P vPro Processor), OpenLDAP
returned an average 10,932 results completed per second with err=0 and
average 21ms response time.
Then I ran ldapmodify to changetype: replace olcLogLevel to 0, reran the
same test, and saw OpenLDAP perform much better. The same test with
olcLogLevel=0 returned 84,286 results per second with err=0 (671% increase)
and average response time of 2.6 ms (88% decrease). Watching "htop" during
this test showed all vcpus firing a lot more evenly and hotter than the test
with olcLogLevel=256; it was very clear how efficient slapd can be without
having to do any logging.
Maybe try each single bit of olcLogLevel to make a histogram which logging bit consumes
most time.
That would be 8 tests (for 8 bits).
I ran several samples of each test and picked the best for each of
olcLogLevels I tested. I ran other tests like 3 and 4 clients times 50
connections each, also ran Basic Bind Rate and saw similar patterns there. I
don't mind sharing my configs or the test data if anyone is interested.
And so naturally, I am wondering if this is a known limitation and also
whether it is something that can be addressed or is a hard constraint. I
guess I had expected some impact as a result of logging (nothing comes for
free...) but not this much.
Well, in general extra logging does not only mean some extra log output, but also
formatting (like using printf()) or other conversions that may cost extra time. There are
also profiling tools (like gprof) that might allow you some deeper insights, but that
would require a rebuild of the software.
Regards,
Ulrich
337
days inactive
342
days old
openldap-technical@openldap.org
5 comments
4 participants
participants (4)
-
Christopher Paul -
Quanah Gibson-Mount -
Shawn McKinney -
Ulrich Windl