[prev in list] [next in list] [prev in thread] [next in thread]
List: openldap-technical
Subject: OpenLDAP stats logging performance degradation
From: Christopher Paul <chris.paul () rexconsulting ! net>
Date: 2022-12-30 23:35:40
Message-ID: PH7PR12MB571022A0A3EA320F926EA69C9DF09 () PH7PR12MB5710 ! namprd12 ! prod ! outlook ! com
[Download RAW message or body]
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
[Attachment #3 (text/html)]
<html xmlns:v="urn:schemas-microsoft-com:vml" \
xmlns:o="urn:schemas-microsoft-com:office:office" \
xmlns:w="urn:schemas-microsoft-com:office:word" \
xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" \
xmlns="http://www.w3.org/TR/REC-html40"> <head>
<meta http-equiv="Content-Type" content="text/html; charset=us-ascii">
<meta name="Generator" content="Microsoft Word 15 (filtered medium)">
<style><!--
/* Font Definitions */
@font-face
{font-family:"Cambria Math";
panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0in;
font-size:11.0pt;
font-family:"Calibri",sans-serif;}
a:link, span.MsoHyperlink
{mso-style-priority:99;
color:#0563C1;
text-decoration:underline;}
p.MsoPlainText, li.MsoPlainText, div.MsoPlainText
{mso-style-priority:99;
mso-style-link:"Plain Text Char";
margin:0in;
font-size:11.0pt;
font-family:"Calibri",sans-serif;}
span.EmailStyle17
{mso-style-type:personal-compose;
font-family:"Calibri",sans-serif;
color:windowtext;}
span.PlainTextChar
{mso-style-name:"Plain Text Char";
mso-style-priority:99;
mso-style-link:"Plain Text";
font-family:"Calibri",sans-serif;}
span.machine-info-content
{mso-style-name:machine-info-content;}
.MsoChpDefault
{mso-style-type:export-only;
font-family:"Calibri",sans-serif;}
@page WordSection1
{size:8.5in 11.0in;
margin:1.0in 1.0in 1.0in 1.0in;}
div.WordSection1
{page:WordSection1;}
--></style><!--[if gte mso 9]><xml>
<o:shapedefaults v:ext="edit" spidmax="1026" />
</xml><![endif]--><!--[if gte mso 9]><xml>
<o:shapelayout v:ext="edit">
<o:idmap v:ext="edit" data="1" />
</o:shapelayout></xml><![endif]-->
</head>
<body lang="EN-US" link="#0563C1" vlink="#954F72" style="word-wrap:break-word">
<div class="WordSection1">
<p class="MsoPlainText">Hello OpenLDAP-Technical,<o:p></o:p></p>
<p class="MsoPlainText"><o:p> </o:p></p>
<p class="MsoPlainText">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.<o:p></o:p></p> <p \
class="MsoPlainText"><o:p> </o:p></p> <p class="MsoPlainText">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.<o:p></o:p></p> <p \
class="MsoPlainText"><o:p> </o:p></p> <p class="MsoPlainText">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.<o:p></o:p></p> <p \
class="MsoPlainText"><o:p> </o:p></p> <p class="MsoPlainText">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).<o:p></o:p></p> <p class="MsoPlainText"><o:p> </o:p></p>
<p class="MsoPlainText">Using LogLevel 256, the Asynchronous Search Rate test with 3 \
clients, 2 connection threads each (from laptop <span \
class="machine-info-content">i7-1280P vPro Processor)</span>, OpenLDAP returned an \
average 10,932 results completed per second with err=0 and average 21ms response \
time.<o:p></o:p></p> <p class="MsoPlainText"><o:p> </o:p></p>
<p class="MsoPlainText">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.<o:p></o:p></p> <p class="MsoPlainText"><o:p> </o:p></p>
<p class="MsoPlainText">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.<o:p></o:p></p>
<p class="MsoPlainText"><o:p> </o:p></p>
<p class="MsoPlainText">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.<o:p></o:p></p>
<p class="MsoPlainText"><o:p> </o:p></p>
<p class="MsoPlainText">Thanks,<o:p></o:p></p>
<p class="MsoPlainText"><o:p> </o:p></p>
<p class="MsoPlainText">Chris Paul | Rex Consulting | <a \
href="https://www.rexconsulting.net"> \
https://www.rexconsulting.net</a><o:p></o:p></p> <p \
class="MsoNormal"><o:p> </o:p></p> </div>
</body>
</html>
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic