On Mon, Feb 14, 2022 at 09:57:06AM -0800, Quanah Gibson-Mount wrote:

How large is the total size of all mdb databases?

According to mdb_stat the primary db is:

Page size: 4096 Number of pages used: 500651

4k * 500651 = 2002604

which lines up with du:

# du -k data.mdb 2002604 data.mdb

Then the accesslog db is:

Page size: 4096 Number of pages used: 74753

# du -k data.mdb 299016 data.mdb

So a total of a bit over 2GB.

How much RAM do you have on the system?

2GB. I don't think I'm running low on memory, there's usually a bit free:

# free -m total used free shared buff/cache available Mem: 1949 423 79 0 1446 1372 Swap: 1023 291 732

And when it's being really slow for memberOf there's no swapping or other signs of low memory. Other queries are still very responsive, it's just memberOf that gets slow. The only metric that seems ramped when it occurs is high read IO.

Is it possible that you've exceeded the index slot size?

I'm not sure. How would I check that? The issue only happens occasionally though, with generally the same load and query set. If it was a problem like that I would think it would happen all the time.

Is there anything I could poke with mdb_stat or the slapd monitor interface the next time it happens to try and narrow down the root cause?

Thanks much...

On 2/14/2022 11:55 PM, Ulrich Windl wrote:

Independent of LDAP my guess is that 2GB is somewhat tight these days, and my guess is that it's virtual machine.

It is a virtual machine indeed. I generally try to minimize the memory allocated to my linux instances to make up for the bloated Windows instances that are sucking up 32-64GB on the same virtualization infrastructure 8-/.

I can certainly just throw memory at it and hope the problem goes away, but I will discuss a bit more why I don't think it is memory in my reply to Ondřej.

Thanks…

On 2/15/2022 1:57 AM, Ondřej Kuzník wrote:

• your DB is just over the size of available RAM by itself

Yes, but that size includes not just the data itself, but all of the indexes as well, right?

• after a while using the system, other processes (and slapd) will carve out a fair amount of it that the system will be unwilling/unable to page out

Yes. But that is not currently the case. Here is a slapd process on one of our nodes that has been up about a week and a half:

ldap 1207 1 9 Feb04 ? 1-01:46:47 /opt/symas/lib/slapd -d 0 -h ldap:/// ldaps:/// ldapi:/// -u ldap -g ldap

It's resident set is a bit less than a gigabyte:

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1207 ldap 20 0 8530708 954688 829836 S 28.1 47.8 1546:40 slapd

While unused (ie wasted) memory is only 82M, the amount of memory in use by buffer/cache that the system would be willing to give up at any time is more than a gigabyte:

total used free shared buff/cache available Mem: 1949 413 82 0 1453 1382 Swap: 1023 295 728

When the problem occurs, there isn't a memory shortage. There is still free memory. Nothing is getting paged in or out, the only IO is application read, not system swap.

• if, to answer that query, you need to crawl a large part of the DB, the OS will have to page that part into memory, at the beginning, there is enough RAM to do it all just once, later, you've reached a threshold and it needs to page bits in and then drop them again to fetch others you develop these symptoms - lots or read I/O and a delay in processing

Intuitively that does sound like a good description of the problem I'm having. But the only thing that takes a long time is returning the memberOf attribute. When queries requesting that are taking more than 30 seconds or even minutes to respond, all other queries remain instantaneous. It seems unlikely that under memory pressure the only queries that would end up having to page out stuff and be degraded would be those? Every other query just happens to have what it needs still in memory?

Figure out what is involved in that search and see if you can tweak

It's not a very complicated query:

# ldapsearch -x -H ldapi:/// uid=henson memberOf [...] dn: uid=henson,ou=user,dc=cpp,dc=edu

memberOf: uid=idm,ou=group,dc=cpp,dc=edu

memberOf: uid=iit,ou=group,dc=cpp,dc=edu

If I understand correctly, this just needs to access the index on uid to find my entry, and then the dynlist module presumably does something like this:

# ldapsearch -x -H ldapi:/// member=uid=henson,ou=user,dc=cpp,dc=edu dn [...] # cppnet, group, cpp.edu dn: uid=cppnet,ou=group,dc=cpp,dc=edu # cppnet-admin, group, cpp.edu dn: uid=cppnet-admin,ou=group,dc=cpp,dc=edu

this just needs to access the index on member to find all of the group objects, which in my case is 36.

So it only needs to have two indexes and 37 objects in memory to perform quickly, right?

When performance on memberOf queries is degraded, this takes more than 30 seconds to run. Every single time. I could run it 20 times in a row and it always takes more than 30 seconds. If it was a memory issue, you would think that at least some of the queries would get lucky and the pages needed would be in memory, given they had just been accessed moments before?

I can certainly just throw memory at it and hope the problem goes away. But based on the observations when it occurs it does not feel like just a memory problem. The last time it happened I pulled the node out of the load balancer so nothing else was poking at it and the test query was still taking more than 30 seconds.

I'm going to bump the production nodes up to 4G, which should be more than enough to run the OS and always have the entire database plus all indexes in memory. I will keep my fingers crossed this problem just goes away, but if it doesn't, what else can I do when it occurs to help track it down?

Thanks much…

On 2/16/2022 3:08 AM, Ulrich Windl wrote:

Remember there are some classic tools like sar, vmstat, iostat, etc. to display or store some interesting information about what the OS is

Like I mentioned, the OS doesn't appear to be doing anything interesting when this has occurred. There's plenty of free memory, there is no swap paging, and CPU utilization isn't particularly high.

iotop is another nice utility.

Yes, I was using that; the only abnormal behavior when the problem occurred was extremely high read IO by the slapd process. Normally, read IO is virtually nil, jumping up to a MB/s or two occasionally. When the memberOf query is taking excessive time, there is like continuous 200-400 MB/s read IO being performed by slapd. Despite the high read IO, all queries that don't involve memberOf continue to operate with usual speed. Just the queries that return memberOf are degraded.

That's why it feels to me like an issue somehow with slapd, not the OS.

You didn't tell what hypervisor you are using, bu tdid you know that Xen PVMs support "memory hotplugging"?

We are using VMware ESXi, which also supports memory hot plugging. Although they do something weird where if you have less than 3G of RAM allocated they only let you hot plug up to 3G. If you have more than 3G allocated, you can hot plug up to the max. There is some knowledge base article about it, ah, here it is:

https://kb.vmware.com/s/article/2008405

It claims that linux "freezes" if you increase from less than 3G to more than 3G? I can believe that maybe that occurred once upon a time due to a bug, but find it hard to believe that it still does. It seems like VMware implemented a kludge workaround and has never removed it...

Yup. I just bumped the memory from 2GB to 8GB on an instance running under kvm, no problem. Stupid vmware. Hmm, nifty, kvm even lets you dynamically remove memory, another thing VMware doesn't let you do.

Thanks…

On 2/16/2022 11:25 AM, Howard Chu wrote:

Use perf (formerly oprofile) and get a trace of slapd's execution during one of these searches. Also get a trace when it is performing normally, for comparison.

Cool, thanks much. Now I've just got to wait until it happens again; which given I'm ready this time to investigate it better means it probably will work fine for a while :).

...

...

"Paul B. Henson" henson@acm.org schrieb am 16.02.2022 um 06:13 in

Nachricht 5f015d2d-8965-6c70-0c6d-7a96e9ec290c@acm.org:

On 2/15/2022 1:57 AM, Ondřej Kuzník wrote:

...

• if, to answer that query, you need to crawl a large part of the DB, the OS will have to page that part into memory

Do you know if there's any way to tell which pages of a memory mapped file are actually in memory at any given time? The process map just shows 5G (the max size I currently have configured for the database):

00007fece8cfb000 5242880K rw-s- data.mdb

"man pmap", maybe?

# pmap $$ 21561: -bash Address Kbytes RSS PSS Dirty Swap Mode Mapping 0000558d2476d000 964 904 904 0 0 r-xp- /usr/bin/bash 0000558d24a5e000 8 8 8 8 0 r--p- /usr/bin/bash 0000558d24a60000 16 16 16 16 0 rw-p- /usr/bin/bash 0000558d24a64000 56 44 44 44 0 rw-p- [ anon ] 0000558d25ff7000 4464 4384 4384 4384 0 rw-p- [ anon ] 00007f1ca39a8000 2528 192 35 0 0 r--p- /usr/lib/locale/en_US.utf8/LC_COLLATE 00007f1ca3c20000 28 28 0 0 0 r-xp- /lib64/libnss_compat-2.31.so 00007f1ca3c27000 2048 0 0 0 0 ---p- /lib64/libnss_compat-2.31.so 00007f1ca3e27000 4 4 4 4 0 r--p- /lib64/libnss_compat-2.31.so 00007f1ca3e28000 4 4 4 4 0 rw-p- /lib64/libnss_compat-2.31.so 00007f1ca3e29000 152 152 38 0 0 r-xp- /lib64/libtinfo.so.6.1 00007f1ca3e4f000 2044 0 0 0 0 ---p- /lib64/libtinfo.so.6.1 [...]

Thanks…

On Mon, May 30, 2022 at 02:38:11PM +0100, Howard Chu wrote:

Let us know how things go.

Arg. Seems to have been a red herring. Blew up again with swappiness set to 1, and then again with swap completely disabled :(. Usual symptoms of crazy high disk reads:

Total DISK READ : 389.05 M/s | Total DISK WRITE : 3.93 K/s Actual DISK READ: 391.50 M/s | Actual DISK WRITE: 0.00 B/s TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND 577547 be/4 ldap 36.88 M/s 0.00 B/s 0.00 % 97.92 % slapd -d 0 -h ldap:/// ~dapi:/// -u ldap -g ldap 577546 be/4 ldap 32.27 M/s 0.00 B/s 0.00 % 97.88 % slapd -d 0 -h ldap:/// ~dapi:/// -u ldap -g ldap 575034 be/4 ldap 29.47 M/s 0.00 B/s 0.00 % 97.72 % slapd -d 0 -h ldap:/// ~dapi:/// -u ldap -g ldap 572838 be/4 ldap 27.38 M/s 0.00 B/s 0.00 % 97.66 % slapd -d 0 -h ldap:/// ~dapi:/// -u ldap -g ldap 575308 be/4 ldap 24.47 M/s 0.00 B/s 0.00 % 97.50 % slapd -d 0 -h ldap:/// ~dapi:/// -u ldap -g ldap 572866 be/4 ldap 91.55 M/s 0.00 B/s 0.00 % 97.33 % slapd -d 0 -h ldap:/// ~dapi:/// -u ldap -g ldap 572841 be/4 ldap 26.96 M/s 0.00 B/s 0.00 % 96.87 % slapd -d 0 -h ldap:/// ~dapi:/// -u ldap -g ldap 572836 be/4 ldap 43.90 M/s 0.00 B/s 0.00 % 96.84 % slapd -d 0 -h ldap:/// ~dapi:/// -u ldap -g ldap 577508 be/4 ldap 76.17 M/s 0.00 B/s 0.00 % 95.96 % slapd -d 0 -h ldap:/// ~dapi:/// -u ldap -g ldap

Even though there's plenty of memory:

total used free shared buff/cache available Mem: 3901 944 109 1 2847 2715 Swap: 0 0 0

Looking at the lmdb mapping:

00007f662ea25000 5242880 325560 0 rw-s- data.mdb 00007f676ec26000 2097152 0 0 rw-s- data.mdb

There seems to be fewer pages mapped in than on one that isn't blowing up:

00007f6ab1606000 5242880 560712 0 rw-s- data.mdb 00007f6bf1807000 2097152 120772 0 rw-s- data.mdb

Memory use is similar:

total used free shared buff/cache available Mem: 3896 725 156 0 3014 2893 Swap: 2047 127 1920

The one that's unhappy is generating a lot of page faults:

ldap-02 ~ # ps -o min_flt,maj_flt 572833; sleep 10; ps -o min_flt,maj_flt 572833 MINFL MAJFL 11924597 3715970 MINFL MAJFL 11931358 3718833 ldap-02 ~ # ps -o min_flt,maj_flt 572833; sleep 10; ps -o min_flt,maj_flt 572833 MINFL MAJFL 11949883 3726966 MINFL MAJFL 11957081 3730080

Compared to the one that's working properly, which has none:

ldap-01 ~ # ps -o min_flt,maj_flt 1227; sleep 10; ps -o min_flt,maj_flt 1227 MINFL MAJFL 1282224 221928 MINFL MAJFL 1282224 221928 ldap-01 ~ # ps -o min_flt,maj_flt 1227; sleep 10; ps -o min_flt,maj_flt 1227 MINFL MAJFL 1282225 221928 MINFL MAJFL 1282225 221928

But why? Arg. All the slow queries are asking for memberOf:

May 30 21:54:25 ldap-02 slapd[572833]: conn=120576 op=1 SRCH base="ou=user,dc=cpp,dc=edu" scope=2 deref=3 filter="(&(objectClass=person)(calstateEduPersonEmplID=014994057))" May 30 21:54:25 ldap-02 slapd[572833]: conn=120576 op=1 SRCH attr=memberOf May 30 21:56:59 ldap-02 slapd[572833]: conn=120576 op=1 SEARCH RESULT tag=101 err=0 qtime=0.000016 etime=154.273556 nentries=1 text=

There's something going on with the dynlist overlay and memberof queries, but I still can't figure out what <sigh>. It's not a low on memory issue, there's plenty of free memory. But for some reason the read IO goes through the roof. I'm pretty sure it has the same query load while it's freaking as it did when it was running fine.