389-ds-base

#49873 Contention on virtual attribute lookup
Closed: wontfix by tbordaz. Opened by tbordaz.

Closed: wontfix
Reopen Issue

Issue Description

virtual attribute lookup can be slow because of slowness of RW lock acquisition when there are many threads competing for the lock.
This was reported in https://pagure.io/389-ds-base/issue/511. The fix was to disable virtual attribute checking when evaluating a filter.

The RC of the slowness is https://bugzilla.redhat.com/show_bug.cgi?id=200247, but this bug is not a priority.

Rather than disabling vattr lookup, this ticket is to evaluate the possibility to acquire the RW lock once during the operation. vattr are rarely updated so an option would be to acquire the lock in SRCH op (from pre-to-post op) and set a flag in percpu.

Package Version and Platform

All version

Steps to reproduce

Using IPA deployement, many groups, users/hosts and do a sssd fetch (no cache)

Actual results

Many threads contention

Expected results

No threads in contention

Contention threads are looking like

Thread 30
#0  0x00007f54e5f444cd in __lll_lock_wait ()
#1  0x00007f54e5f410c2 in pthread_rwlock_rdlock ()
#2  0x00007f54e8801fca in slapi_rwlock_rdlock ()
#3  0x00007f54e881a2d1 in vattr_map_lookup ()
#4  0x00007f54e881b294 in vattr_map_namespace_sp_getlist ()
#5  0x00007f54e881b3be in vattr_test_filter ()
#6  0x00007f54e87a9a54 in slapi_vattr_filter_test_ext_internal ()
#7  0x00007f54e87aa736 in slapi_vattr_filter_test_ext ()
#8  0x00007f54e87aa788 in slapi_vattr_filter_test ()
#9  0x00007f54dd7b7df2 in acl__resource_match_aci ()
#10 0x00007f54dd7b9270 in acl__scan_for_acis ()
#11 0x00007f54dd7b9270 in acl_access_allowed ()
#12 0x00007f54dd7cc987 in acl_access_allowed_main ()
#13 0x00007f54e87e2ecc in plugin_call_acl_plugin ()
#14 0x00007f54e87e3397 in slapi_access_allowed ()
#15 0x00007f54dcb3317b in deref_check_access ()
#16 0x00007f54dcb337d3 in deref_do_deref_attr ()
#17 0x00007f54dcb337d3 in deref_pre_entry ()
#18 0x00007f54e87df548 in plugin_call_func ()
#19 0x00007f54e87df803 in plugin_call_list ()
#20 0x00007f54e87df803 in plugin_call_plugins ()
#21 0x00007f54e87f546f in send_ldap_search_entry_ext ()
#22 0x00007f54e87f5e5c in send_ldap_search_entry ()
#23 0x00007f54e87d0cf4 in send_entry ()
#24 0x00007f54e87d1258 in iterate ()
#25 0x00007f54e87d1258 in send_results_ext ()
#26 0x00007f54e87d3121 in op_shared_search ()
#27 0x0000556814ef366e in do_search ()
#28 0x0000556814ee15aa in connection_dispatch_operation ()
#29 0x0000556814ee15aa in connection_threadmain ()
#30 0x00007f54e659dbab in _pt_root ()
#31 0x00007f54e5f3ddd5 in start_thread ()
#32 0x00007f54e55eab3d in clone ()

Metadata Update from @tbordaz:
- Custom field component adjusted to None
- Custom field origin adjusted to None
- Custom field reviewstatus adjusted to None
- Custom field type adjusted to None
- Custom field version adjusted to None

yes, I think it would be acceptable to take the read lock for a longer time, updates are rare, and if they happen could wait.
It could even be mor logical not to allow changes of vattr in the middle of a search evaluation.

Metadata Update from @mreynolds:
- Issue set to the milestone: 1.4.0

https://pagure.io/389-ds-base/pull-request/50163

Metadata Update from @tbordaz:
- Issue assigned to tbordaz

Metadata Update from @tbordaz:
- Custom field rhbz adjusted to https://bugzilla.redhat.com/show_bug.cgi?id=1627846

Something we should consider is that the default linux RWlock policy is write-favouring, which will cause reader starvation. If we change the rwlock policy to a balanced one, this may already help with the issue we are having.

http://man7.org/linux/man-pages/man3/pthread_rwlockattr_setkind_np.3.html

More details here. I think perhaps I was wrong and the rwlock is reader favouring on linux by default, which is possible that it's not what we want depending on workload ....

@firstyear thank you for the pointer. 389-ds initialize rwlock with reader favoring so I think we are good here.

The concern is not favoring readers vs writers as most of time there will never be writers (except at DS startup). First slapi_rwlock_rdlock is expensive even if there is only readers (kind of contention to test if reader is allowed to proceed), then the concern is that to process an operation it may acquire multiple times the expensive lock.
The fix to reduce the cost of rwlock was delayed but it looks it landed in glibc-2.28-1.el8+7 (https://bugzilla.redhat.com/show_bug.cgi?id=1512010)

If #1512010 works as expected, it will improve DS situation. However we still have the possible improvement to acquire the lock only once (it is what the current patch does) rather than multiple time.

Yes, acquiring once and holding the read lock for longer is a better solution. Sorry if I misunderstood the comments previous to this.

I'm surprised read locks are so expensive to acquire, they should be low-cost? But maybe I am thinking of something else ... anyway. It sounds like a good answer to have the read-lock last for longer.

That was also a surprise for me. The reason was identified but the fix was complex and missed RHEL7 (hopefully is in RHEL8). The problem is that acquiring a rdlock requires some checks that are done while holding an internal lock. If several threads do pthread_rwlock_rdlock at once, it can create contention on that internal lock.

ff94e562a...e580506d5 master
70cac1b11..6f87fab42 389-ds-base-1.4.0

Metadata Update from @tbordaz:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)

This change introduced a regression and broke nightly tests. Test suites/config/config_test.py::test_ignore_virtual_attrs fails and then hangs in the next one.
To reproduce run suites/config/config_test.py on latest master.

Thread 6 (Thread 0x7fdb463e0700 (LWP 23097)):
#0  0x00007fdb59eb283f in futex_abstimed_wait (private=0, abstime=0x0, expected=2, futex_word=0x5593f53bb0a8) at ../sysdeps/unix/sysv/linux/futex-internal.h:172
#1  0x00007fdb59eb283f in __pthread_rwlock_wrlock_full (abstime=0x0, rwlock=0x5593f53bb0a0) at pthread_rwlock_common.c:803
#2  0x00007fdb59eb283f in __GI___pthread_rwlock_wrlock (rwlock=0x5593f53bb0a0) at pthread_rwlock_wrlock.c:27
#3  0x00007fdb5a3e8a77 in vattr_map_insert () at /usr/lib64/dirsrv/libslapd.so.0
#4  0x00007fdb5a3ea66f in vattr_map_sp_insert () at /usr/lib64/dirsrv/libslapd.so.0
#5  0x00007fdb5a3ea753 in slapi_vattrspi_regattr () at /usr/lib64/dirsrv/libslapd.so.0
#6  0x00007fdb5674833c in cos_dn_defs_cb (e=0x7fdb24011020, callback_data=0x7fdb463dfc80) at ldap/servers/plugins/cos/cos_cache.c:859
#7  0x00007fdb5a3c1b0e in send_ldap_search_entry_ext () at /usr/lib64/dirsrv/libslapd.so.0
#8  0x00007fdb5a3c1e74 in send_ldap_search_entry () at /usr/lib64/dirsrv/libslapd.so.0
#9  0x00007fdb5a39b204 in None () at /usr/lib64/dirsrv/libslapd.so.0
#10 0x00007fdb5a39b786 in None () at /usr/lib64/dirsrv/libslapd.so.0
#11 0x00007fdb5a39d42e in op_shared_search () at /usr/lib64/dirsrv/libslapd.so.0
#12 0x00007fdb5a3aef2c in None () at /usr/lib64/dirsrv/libslapd.so.0
#13 0x00007fdb56749a47 in cos_cache_add_dn_defs (pDefs=0x7fdb40014e90, dn=0x7fdb400017b0 "dc=example,dc=com") at ldap/servers/plugins/cos/cos_cache.c:1051
#14 0x00007fdb56749a47 in cos_cache_build_definition_list (vattr_cacheable=0x7fdb40014eb8, pDefs=0x7fdb40014e90) at ldap/servers/plugins/cos/cos_cache.c:666
#15 0x00007fdb56749a47 in cos_cache_create_unlock () at ldap/servers/plugins/cos/cos_cache.c:458
#16 0x00007fdb56749a47 in cos_cache_creation_lock () at ldap/servers/plugins/cos/cos_cache.c:586
#17 0x00007fdb5674a3dd in cos_cache_wait_on_change (arg=<optimized out>) at ldap/servers/plugins/cos/cos_cache.c:419
#18 0x00007fdb59f12b08 in _pt_root (arg=0x5593f53cec00) at ../../.././nspr/pr/src/pthreads/ptthread.c:201
#19 0x00007fdb59ead58e in start_thread (arg=<optimized out>) at pthread_create.c:486
#20 0x00007fdb59cdc6a3 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
Thread 5 (Thread 0x7fdb46be1700 (LWP 23096)):
#0  0x00007fdb59cd3d0f in __GI___select (nfds=0, readfds=0x0, writefds=0x0, exceptfds=0x0, timeout=0x7fdb46be0cc0) at ../sysdeps/unix/sysv/linux/select.c:41
#1  0x00007fdb5a3e2df4 in DS_Sleep () at /usr/lib64/dirsrv/libslapd.so.0
#2  0x00007fdb566e4608 in perfctrs_wait (milliseconds=<optimized out>, priv=<optimized out>, db_env=<optimized out>) at ldap/servers/slapd/back-ldbm/perfctrs.c:80
#3  0x00007fdb56689c3f in perf_threadmain (param=<optimized out>) at ldap/servers/slapd/back-ldbm/dblayer.c:3600
#4  0x00007fdb59f12b08 in _pt_root (arg=0x5593f56ffee0) at ../../.././nspr/pr/src/pthreads/ptthread.c:201
#5  0x00007fdb59ead58e in start_thread (arg=<optimized out>) at pthread_create.c:486
#6  0x00007fdb59cdc6a3 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
Thread 4 (Thread 0x7fdb473e2700 (LWP 23095)):
#0  0x00007fdb59cd3d0f in __GI___select (nfds=0, readfds=0x0, writefds=0x0, exceptfds=0x0, timeout=0x7fdb473e1c90) at ../sysdeps/unix/sysv/linux/select.c:41
#1  0x00007fdb5a3e2df4 in DS_Sleep () at /usr/lib64/dirsrv/libslapd.so.0
#2  0x00007fdb5668f4a7 in trickle_threadmain (param=<optimized out>) at ldap/servers/slapd/back-ldbm/dblayer.c:4539
#3  0x00007fdb59f12b08 in _pt_root (arg=0x5593f56fd500) at ../../.././nspr/pr/src/pthreads/ptthread.c:201
#4  0x00007fdb59ead58e in start_thread (arg=<optimized out>) at pthread_create.c:486
#5  0x00007fdb59cdc6a3 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
Thread 3 (Thread 0x7fdb47be3700 (LWP 23094)):
#0  0x00007fdb59cd3d0f in __GI___select (nfds=0, readfds=0x0, writefds=0x0, exceptfds=0x0, timeout=0x7fdb47be1bc0) at ../sysdeps/unix/sysv/linux/select.c:41
#1  0x00007fdb5a3e2df4 in DS_Sleep () at /usr/lib64/dirsrv/libslapd.so.0
#2  0x00007fdb56693018 in checkpoint_threadmain (param=<optimized out>) at ldap/servers/slapd/back-ldbm/dblayer.c:4324
#3  0x00007fdb59f12b08 in _pt_root (arg=0x5593f56fdd90) at ../../.././nspr/pr/src/pthreads/ptthread.c:201
#4  0x00007fdb59ead58e in start_thread (arg=<optimized out>) at pthread_create.c:486
#5  0x00007fdb59cdc6a3 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
Thread 2 (Thread 0x7fdb483e4700 (LWP 23093)):
#0  0x00007fdb59cd3d0f in __GI___select (nfds=0, readfds=0x0, writefds=0x0, exceptfds=0x0, timeout=0x7fdb483e3c90) at ../sysdeps/unix/sysv/linux/select.c:41
#1  0x00007fdb5a3e2df4 in DS_Sleep () at /usr/lib64/dirsrv/libslapd.so.0
#2  0x00007fdb5668f24f in deadlock_threadmain (param=<optimized out>) at ldap/servers/slapd/back-ldbm/dblayer.c:4102
#3  0x00007fdb59f12b08 in _pt_root (arg=0x5593f5702220) at ../../.././nspr/pr/src/pthreads/ptthread.c:201
#4  0x00007fdb59ead58e in start_thread (arg=<optimized out>) at pthread_create.c:486
#5  0x00007fdb59cdc6a3 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
Thread 1 (Thread 0x7fdb59432900 (LWP 23092)):
#0  0x00007fdb59eb6b4d in __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:103
#1  0x00007fdb59eaff7d in __GI___pthread_mutex_lock (mutex=mutex@entry=0x5593f6afc0e0) at ../nptl/pthread_mutex_lock.c:135
#2  0x00007fdb59f0ca6d in PR_Lock (lock=0x5593f6afc0e0) at ../../.././nspr/pr/src/pthreads/ptsynch.c:171
#3  0x00007fdb5674ac7d in cos_cache_stop () at ldap/servers/plugins/cos/cos_cache.c:3275
#4  0x00007fdb56745d07 in cos_close (pb=<optimized out>) at ldap/servers/plugins/cos/cos.c:224
#5  0x00007fdb5a3a9eb7 in None () at /usr/lib64/dirsrv/libslapd.so.0
#6  0x00007fdb5a3ad492 in plugin_dependency_closeall () at /usr/lib64/dirsrv/libslapd.so.0
#7  0x00005593f3b15169 in slapd_daemon (ports=<optimized out>, tp=0x0) at ldap/servers/slapd/daemon.c:1279
#8  0x00005593f3b05c17 in main (argc=5, argv=0x7ffd9b09e1d8) at ldap/servers/slapd/main.c:1213
Edited by vashirov

Metadata Update from @vashirov:
- Issue status updated to: Open (was: Closed)

To bad I did not run those tests !!

The problem is possibly (likely ?) a race condition, because the server is shutting down while trying to add a new virtual attribute definition in the map.
Addition of virtual attribute SP is usually done at startup but here we shutdown soon after startup

[15/Feb/2019:04:55:01.870021773 -0500] - INFO - slapd_daemon - slapd started.  Listening on All Interfaces port 38901 for LDAP requests
[15/Feb/2019:04:55:02.421438432 -0500] - INFO - slapd_daemon - slapd shutting down - closing down internal subsystems and plugins

This means there is some kind of shutdown ordering issue?

This is a self deadlock:

2 0x00007fdb59eb283f in __GI___pthread_rwlock_wrlock (rwlock=0x5593f53bb0a0) at pthread_rwlock_wrlock.c:27

3 0x00007fdb5a3e8a77 in vattr_map_insert () at /usr/lib64/dirsrv/libslapd.so.0

4 0x00007fdb5a3ea66f in vattr_map_sp_insert () at /usr/lib64/dirsrv/libslapd.so.0

5 0x00007fdb5a3ea753 in slapi_vattrspi_regattr () at /usr/lib64/dirsrv/libslapd.so.0

6 0x00007fdb5674833c in cos_dn_defs_cb (e=0x7fdb24011020, callback_data=0x7fdb463dfc80) at ldap/servers/plugins/cos/cos_cache.c:859

7 0x00007fdb5a3c1b0e in send_ldap_search_entry_ext () at /usr/lib64/dirsrv/libslapd.so.0

8 0x00007fdb5a3c1e74 in send_ldap_search_entry () at /usr/lib64/dirsrv/libslapd.so.0

9 0x00007fdb5a39b204 in None () at /usr/lib64/dirsrv/libslapd.so.0

10 0x00007fdb5a39b786 in None () at /usr/lib64/dirsrv/libslapd.so.0

11 0x00007fdb5a39d42e in op_shared_search () at /usr/lib64/dirsrv/libslapd.so.0

12 0x00007fdb5a3aef2c in None () at /usr/lib64/dirsrv/libslapd.so.0

13 0x00007fdb56749a47 in cos_cache_add_dn_defs (pDefs=0x7fdb40014e90, dn=0x7fdb400017b0 "dc=example,dc=com") at ldap/servers/plugins/cos/cos_cache.c:1051

14 0x00007fdb56749a47 in cos_cache_build_definition_list (vattr_cacheable=0x7fdb40014eb8, pDefs=0x7fdb40014e90) at ldap/servers/plugins/cos/cos_cache.c:666

15 0x00007fdb56749a47 in cos_cache_create_unlock () at ldap/servers/plugins/cos/cos_cache.c:458

16 0x00007fdb56749a47 in cos_cache_creation_lock () at ldap/servers/plugins/cos/cos_cache.c:586

17 0x00007fdb5674a3dd in cos_cache_wait_on_change (arg=) at ldap/servers/plugins/cos/cos_cache.c:419

18 0x00007fdb59f12b08 in _pt_root (arg=0x5593f53cec00) at ../../.././nspr/pr/src/p

We take the read lock in opshared, then we try to take the write lock ---> deadlock Basically need a monitor style RW lock. :-/

Also, when I step through the code we never enter your new thread data code. thread_private_global_vattr_lock is always zero, and it's skipped over.

rwlocks are super prone to recursive deadlocks like this. I think a monitor RW is even more dangerous, an we should not use it.

Just in my mind, I can think of so many ways this could go wrong. I wonder if we need to rethink our approach to this problem some how.

Cos plugin registers callback to detect cos definition/template change. When it detects a change (for example when adding a cos), it rebuilds the cos cache. To do so it triggers an internal search looking for cos definitions and for each of them update the cos cache.

The internal search acquire the vattr rlock. When updating the cos cache it registers the new virtual attribute (cos)... acquiring the vattr wrlock. :(

Investigating a fix

THere are also issues with how you are using the thread data. There are compiler warnings. These diffs should correct the behavior:

@@ -143,17 +143,22 @@ void
 vattr_rdlock()
 {
     if (thread_private_global_vattr_lock) {
-        int nb_acquire = (int) PR_GetThreadPrivate(thread_private_global_vattr_lock);
+        int *nb_acquire = (int *)PR_GetThreadPrivate(thread_private_global_vattr_lock);
-        if (nb_acquire == 0) {
+        if (*nb_acquire == 0) {
             /* The lock was not held just acquire it */
             slapi_rwlock_rdlock(the_map->lock);
        }
-        nb_acquire++;
+        (*nb_acquire)++;
         PR_SetThreadPrivate(thread_private_global_vattr_lock, (void *) nb_acquire);
     } else {
@@ -164,22 +169,27 @@ void
 vattr_unlock()
 {
     if (thread_private_global_vattr_lock) {
-        int nb_acquire = (int) PR_GetThreadPrivate(thread_private_global_vattr_lock);
+        int *nb_acquire = (int *)PR_GetThreadPrivate(thread_private_global_vattr_lock);
-        if (nb_acquire >= 1) {
-            nb_acquire--;
-            if (nb_acquire == 0) {
+        if (*nb_acquire >= 1) {
+            (*nb_acquire)--;
+            if (*nb_acquire == 0) {
                 slapi_rwlock_unlock(the_map->lock);
            } 
             PR_SetThreadPrivate(thread_private_global_vattr_lock, (void *) nb_acquire);
         } else {
-            PR_ASSERT(nb_acquire >= 1);
+            PR_ASSERT(*nb_acquire >= 1);
         }

Probably worth doing int32_t too here. But certainly incorrect pointers isn't good. Can we test this with ASAN, it would really quickly show some of these errors I think.

A second fix to address the hang is https://pagure.io/389-ds-base/pull-request/50268

This is to fix the deadlocks introduced by https://pagure.io/389-ds-base/issue/49873#comment-552412
7ba8a80cf..6d0ba294b master
09b5a2c32..b998fed9c 389-ds-base-1.4.0

Metadata Update from @tbordaz:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)

A third fix to address crash condition (when main initialize ssl) and leak https://pagure.io/389-ds-base/pull-request/50296

Metadata Update from @tbordaz:
- Issue status updated to: Open (was: Closed)

Third patch
09965c45e..38d4e5231 master
2b689f8b1..74490fb28 389-ds-base-1.4.0

Metadata Update from @tbordaz:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)

Fourth patch (cleanup debug log)
38d4e5231..235bde930 master
74490fb28..f7d717909 389-ds-base-1.4.0

Fourth patch (cleanup debug log)
38d4e5231..235bde930 master
74490fb28..f7d717909 389-ds-base-1.4.0

backport in 1.3.9
502281ff6..f6c0c84e2 389-ds-base-1.3.9

Metadata Update from @tbordaz:
- Issue set to the milestone: 1.3.9 (was: 1.4.0)

Another deadlock in suites/replication/acceptance_test.py::test_password_repl_error:

Thread 10 (Thread 0x7f5532167700 (LWP 22434)):
#0  0x00007f5547432a8a in pthread_cond_timedwait@@GLIBC_2.3.2 () at /lib64/libpthread.so.0
#1  0x00007f554748f8e3 in None () at /lib64/libnspr4.so
#2  0x00007f554748fdae in PR_WaitCondVar () at /lib64/libnspr4.so
#3  0x00007f5543b68f86 in protocol_sleep (prp=0x55aadb6fbb40, duration=300000) at ldap/servers/plugins/replication/repl5_inc_protocol.c:1222
#4  0x00007f5543b6d09c in repl5_inc_run (prp=0x55aadb6fbb40) at ldap/servers/plugins/replication/repl5_inc_protocol.c:782
#5  0x00007f5543b71661 in prot_thread_main (arg=0x55aadb76a5f0) at ldap/servers/plugins/replication/repl5_protocol.c:255
#6  0x00007f5547495b98 in None () at /lib64/libnspr4.so
#7  0x00007f554742c58e in start_thread () at /lib64/libpthread.so.0
#8  0x00007f55472596a3 in clone () at /lib64/libc.so.6
Thread 9 (Thread 0x7f5532968700 (LWP 22433)):
#0  0x00007f5547432a8a in pthread_cond_timedwait@@GLIBC_2.3.2 () at /lib64/libpthread.so.0
#1  0x00007f554748f8e3 in None () at /lib64/libnspr4.so
#2  0x00007f554748fdae in PR_WaitCondVar () at /lib64/libnspr4.so
#3  0x00007f5543b68f86 in protocol_sleep (prp=0x55aada2a9d40, duration=300000) at ldap/servers/plugins/replication/repl5_inc_protocol.c:1222
#4  0x00007f5543b6d09c in repl5_inc_run (prp=0x55aada2a9d40) at ldap/servers/plugins/replication/repl5_inc_protocol.c:782
#5  0x00007f5543b71661 in prot_thread_main (arg=0x55aadb76d6a0) at ldap/servers/plugins/replication/repl5_protocol.c:255
#6  0x00007f5547495b98 in None () at /lib64/libnspr4.so
#7  0x00007f554742c58e in start_thread () at /lib64/libpthread.so.0
#8  0x00007f55472596a3 in clone () at /lib64/libc.so.6
Thread 8 (Thread 0x7f5533169700 (LWP 22432)):
#0  0x00007f5547432a8a in pthread_cond_timedwait@@GLIBC_2.3.2 () at /lib64/libpthread.so.0
#1  0x00007f554748f8e3 in None () at /lib64/libnspr4.so
#2  0x00007f554748fdae in PR_WaitCondVar () at /lib64/libnspr4.so
#3  0x00007f5543b68f86 in protocol_sleep (prp=0x55aadb7727f0, duration=300000) at ldap/servers/plugins/replication/repl5_inc_protocol.c:1222
#4  0x00007f5543b6d09c in repl5_inc_run (prp=0x55aadb7727f0) at ldap/servers/plugins/replication/repl5_inc_protocol.c:782
#5  0x00007f5543b71661 in prot_thread_main (arg=0x55aadb742480) at ldap/servers/plugins/replication/repl5_protocol.c:255
#6  0x00007f5547495b98 in None () at /lib64/libnspr4.so
#7  0x00007f554742c58e in start_thread () at /lib64/libpthread.so.0
#8  0x00007f55472596a3 in clone () at /lib64/libc.so.6
Thread 7 (Thread 0x7f553318a700 (LWP 22431)):
#0  0x00007f5547432a8a in pthread_cond_timedwait@@GLIBC_2.3.2 () at /lib64/libpthread.so.0
#1  0x00007f554748f8e3 in None () at /lib64/libnspr4.so
#2  0x00007f554748fdae in PR_WaitCondVar () at /lib64/libnspr4.so
#3  0x00007f5543b529ac in _cl5TrimMain (param=<optimized out>) at ldap/servers/plugins/replication/cl5_api.c:3287
#4  0x00007f5547495b98 in None () at /lib64/libnspr4.so
#5  0x00007f554742c58e in start_thread () at /lib64/libpthread.so.0
#6  0x00007f55472596a3 in clone () at /lib64/libc.so.6
Thread 6 (Thread 0x7f553398b700 (LWP 22430)):
#0  0x00007f554743273c in pthread_cond_wait@@GLIBC_2.3.2 () at /lib64/libpthread.so.0
#1  0x00007f554748fe18 in PR_WaitCondVar () at /lib64/libnspr4.so
#2  0x00007f55479afded in slapi_wait_condvar () at /usr/lib64/dirsrv/libslapd.so.0
#3  0x00007f5543cf33ce in cos_cache_wait_on_change (arg=<optimized out>) at ldap/servers/plugins/cos/cos_cache.c:404
#4  0x00007f5547495b98 in None () at /lib64/libnspr4.so
#5  0x00007f554742c58e in start_thread () at /lib64/libpthread.so.0
#6  0x00007f55472596a3 in clone () at /lib64/libc.so.6
Thread 5 (Thread 0x7f553418c700 (LWP 22429)):
#0  0x00007f5547250d0f in select () at /lib64/libc.so.6
#1  0x00007f55479c3fa4 in DS_Sleep () at /usr/lib64/dirsrv/libslapd.so.0
#2  0x00007f5543c8d0c8 in perfctrs_wait (milliseconds=<optimized out>, priv=<optimized out>, db_env=<optimized out>) at ldap/servers/slapd/back-ldbm/perfctrs.c:80
#3  0x00007f5543c321df in perf_threadmain (param=<optimized out>) at ldap/servers/slapd/back-ldbm/dblayer.c:3600
#4  0x00007f5547495b98 in None () at /lib64/libnspr4.so
#5  0x00007f554742c58e in start_thread () at /lib64/libpthread.so.0
#6  0x00007f55472596a3 in clone () at /lib64/libc.so.6
Thread 4 (Thread 0x7f553498d700 (LWP 22428)):
#0  0x00007f5547250d0f in select () at /lib64/libc.so.6
#1  0x00007f55479c3fa4 in DS_Sleep () at /usr/lib64/dirsrv/libslapd.so.0
#2  0x00007f5543c37a47 in trickle_threadmain (param=<optimized out>) at ldap/servers/slapd/back-ldbm/dblayer.c:4539
#3  0x00007f5547495b98 in None () at /lib64/libnspr4.so
#4  0x00007f554742c58e in start_thread () at /lib64/libpthread.so.0
#5  0x00007f55472596a3 in clone () at /lib64/libc.so.6
Thread 3 (Thread 0x7f553518e700 (LWP 22427)):
#0  0x00007f5547250d0f in select () at /lib64/libc.so.6
#1  0x00007f55479c3fa4 in DS_Sleep () at /usr/lib64/dirsrv/libslapd.so.0
#2  0x00007f5543c3b5b8 in checkpoint_threadmain (param=<optimized out>) at ldap/servers/slapd/back-ldbm/dblayer.c:4324
#3  0x00007f5547495b98 in None () at /lib64/libnspr4.so
#4  0x00007f554742c58e in start_thread () at /lib64/libpthread.so.0
#5  0x00007f55472596a3 in clone () at /lib64/libc.so.6
Thread 2 (Thread 0x7f553598f700 (LWP 22426)):
#0  0x00007f5547250d0f in select () at /lib64/libc.so.6
#1  0x00007f55479c3fa4 in DS_Sleep () at /usr/lib64/dirsrv/libslapd.so.0
#2  0x00007f5543c377ef in deadlock_threadmain (param=<optimized out>) at ldap/servers/slapd/back-ldbm/dblayer.c:4102
#3  0x00007f5547495b98 in None () at /lib64/libnspr4.so
#4  0x00007f554742c58e in start_thread () at /lib64/libpthread.so.0
#5  0x00007f55472596a3 in clone () at /lib64/libc.so.6
Thread 1 (Thread 0x7f55469dd900 (LWP 22425)):
#0  0x00007f554743273c in pthread_cond_wait@@GLIBC_2.3.2 () at /lib64/libpthread.so.0
#1  0x00007f5543df0523 in __db_pthread_mutex_condwait (env=0x55aada15ec50, mutex=0, timespec=0x0, mutexp=<optimized out>) at ../../src/mutex/mut_pthread.c:321
#2  0x00007f5543df0523 in __db_hybrid_mutex_suspend (env=env@entry=0x55aada15ec50, mutex=mutex@entry=33037, timespec=timespec@entry=0x0, exclusive=exclusive@entry=1) at ../../src/mutex/mut_pthread.c:577
#3  0x00007f5543def91f in __db_tas_mutex_lock_int (nowait=0, timeout=0, mutex=33037, env=0x55aada15ec50) at ../../src/mutex/mut_tas.c:255
#4  0x00007f5543def91f in __db_tas_mutex_lock (env=env@entry=0x55aada15ec50, mutex=33037, timeout=timeout@entry=0) at ../../src/mutex/mut_tas.c:286
#5  0x00007f5543e9b2f7 in __lock_get_internal (lt=lt@entry=0x55aada308a70, sh_locker=sh_locker@entry=0x7f5542fc3cf8, flags=flags@entry=0, obj=<optimized out>, lock_mode=DB_LOCK_WRITE, timeout=0, lock=0x7ffe34d0e928) at ../../src/lock/lock.c:989
#6  0x00007f5543e9c004 in __lock_vec (env=0x55aada15ec50, sh_locker=sh_locker@entry=0x7f5542fc3cf8, flags=<optimized out>, list=list@entry=0x7ffe34d0e8e0, nlist=nlist@entry=2, elistp=elistp@entry=0x7ffe34d0e888) at ../../src/lock/lock.c:140
#7  0x00007f5543ef6016 in __fop_lock_handle (env=<optimized out>, dbp=0x55aadb7145c0, locker=0x7f5542fc3cf8, mode=<optimized out>, elockp=0x7ffe34d0e9b0, flags=<optimized out>) at ../../src/fileops/fop_util.c:144
#8  0x00007f5543ef7f58 in __fop_remove_setup (dbp=dbp@entry=0x55aadb7145c0, txn=txn@entry=0x55aada0343c0, name=0x55aadb739cf0 "/var/lib/dirsrv/slapd-master2/changelogdb/74e82583-552611e9-85f9cafb-36f6ee82_5ca325df000000010000.db", flags=flags@entry=0) at ../../src/fileops/fop_util.c:1079
#9  0x00007f5543edbf91 in __db_rename_int (dbp=dbp@entry=0x55aadb7145c0, ip=0x0, txn=txn@entry=0x55aada0343c0, name=name@entry=0x55aadb75d220 "/var/lib/dirsrv/slapd-master2/changelogdb/74e82583-552611e9-85f9cafb-36f6ee82_5ca325df000000010000.db", subdb=subdb@entry=0x0, newname=0x55aadb76bb70 "/var/lib/dirsrv/slapd-master2/changelogdb/800001e6.7f65ab62", flags=1) at ../../src/db/db_rename.c:272
#10 0x00007f5543edb320 in __db_dbtxn_remove (subdb=0x0, name=0x55aadb75d220 "/var/lib/dirsrv/slapd-master2/changelogdb/74e82583-552611e9-85f9cafb-36f6ee82_5ca325df000000010000.db", txn=0x55aada0343c0, ip=0x0, dbp=0x55aadb7145c0) at ../../src/db/db_remove.c:490
#11 0x00007f5543edb320 in __db_remove_int (dbp=0x55aadb7145c0, ip=0x0, txn=0x55aada0343c0, name=name@entry=0x55aadb75d220 "/var/lib/dirsrv/slapd-master2/changelogdb/74e82583-552611e9-85f9cafb-36f6ee82_5ca325df000000010000.db", subdb=subdb@entry=0x0, flags=flags@entry=0) at ../../src/db/db_remove.c:267
#12 0x00007f5543edbbbf in __env_dbremove_pp (dbenv=<optimized out>, txn=<optimized out>, name=0x55aadb75d220 "/var/lib/dirsrv/slapd-master2/changelogdb/74e82583-552611e9-85f9cafb-36f6ee82_5ca325df000000010000.db", subdb=0x0, flags=0) at ../../src/db/db_remove.c:99
#13 0x00007f5543b4cc35 in _cl5DBCloseFile (data=<optimized out>) at ldap/servers/plugins/replication/cl5_api.c:5936
#14 0x00007f554797b0ff in object_release () at /usr/lib64/dirsrv/libslapd.so.0
#15 0x00007f5543b4e38a in _cl5DBDeleteFile (obj=<optimized out>) at ldap/servers/plugins/replication/cl5_api.c:6031
#16 0x00007f5543b4e38a in cl5DeleteDBSync (replica=<optimized out>) at ldap/servers/plugins/replication/cl5_api.c:588
#17 0x00007f5543b764e9 in replica_check_for_data_reload (r=0x55aada1443c0, arg=<optimized out>) at ldap/servers/plugins/replication/repl5_replica.c:1688
#18 0x00007f5543b81ccb in replica_enumerate (he=<optimized out>, index=<optimized out>, hash_data=0x7ffe34d0ef20) at ldap/servers/plugins/replication/repl5_replica_hash.c:244
#19 0x00007f55474b7e20 in PL_HashTableEnumerateEntries () at /lib64/libplds4.so
#20 0x00007f5543b82133 in replica_enumerate_replicas (fn=<optimized out>, arg=arg@entry=0x0) at ldap/servers/plugins/replication/repl5_replica_hash.c:200
#21 0x00007f5543b6e520 in multimaster_start (pb=0x55aada310710) at ldap/servers/plugins/replication/repl5_init.c:819
#22 0x00007f5543b6e520 in multimaster_start (pb=0x55aada310710) at ldap/servers/plugins/replication/repl5_init.c:757
#23 0x00007f554798aed7 in None () at /usr/lib64/dirsrv/libslapd.so.0
#24 0x00007f554798b65e in plugin_startall () at /usr/lib64/dirsrv/libslapd.so.0
#25 0x000055aad9ed6b8e in main (argc=5, argv=0x7ffe34d0f568) at ldap/servers/slapd/main.c:1150

in the error logs:

[02/Apr/2019:05:08:03.574988752 -0400] - WARN - NSMMReplicationPlugin - acquire_replica - agmt="cn=002" (server:39002): Unable to receive the response for a startReplication extended operation to consumer (Can't contact LDAP server). Will retry later.
[02/Apr/2019:05:08:06.580207875 -0400] - ERR - slapi_ldap_bind - Could not send bind request for id [cn=server.example.com:63704,ou=Services,dc=example,dc=com] authentication mechanism [SIMPLE]: error -1 (Can't contact LDAP server), system error -5987 (Invalid function argument.), network error 107 (Transport endpoint is not connected, host "server.example.com:39002")

and the last message is repeated many times.

@vashirov Could help, but if you source the ns-slapd-gdb.py (it could auto-load in RHEL), then try ds-backtrace instead? It de-dupes idle threads to help show deadlocks easier.

@lkrispen, the hang was reproducible only with this: 

mkdir -p /etc/systemd/system/dirsrv\@.service.d
cat > /etc/systemd/system/dirsrv\@.service.d/override.conf << EOF
[Service]
KillSignal=9
TimeoutStopSec=10
EOF
systemctl daemon-reload

Change 9 to 11 if you want to get a core generated.

this is really brute force, you replace the kill signal, which is SIGTERM by default with SIGKILL or SIGSEGV - and the timeout is irrelevant, the process is killed.

I was surprised that I didn't see any shutdown logs, but there was no normal shutdown.

Anyway, I can imagine that killing a server can leave a db page locked, but why it would only happen with this vattr patch in place is still a mystery to me

Here is a summary of what I understand and what I don't understand.

I understand

  • that we can have this hang:

      #0  0x00007fab69ca273c in pthread_cond_wait@@GLIBC_2.3.2 () at /lib64/libpthread.so.0
  #1  0x00007fab66660523 in __db_hybrid_mutex_suspend () at /lib64/libdb-5.3.so
  #2  0x00007fab6665f91f in __db_tas_mutex_lock () at /lib64/libdb-5.3.so
  #3  0x00007fab6670b2f7 in __lock_get_internal () at /lib64/libdb-5.3.so
  #4  0x00007fab6670c004 in __lock_vec () at /lib64/libdb-5.3.so
  #5  0x00007fab66766016 in __fop_lock_handle () at /lib64/libdb-5.3.so
  #6  0x00007fab66767f58 in __fop_remove_setup () at /lib64/libdb-5.3.so
  #7  0x00007fab6674bf91 in __db_rename_int () at /lib64/libdb-5.3.so
  #8  0x00007fab6674b320 in __db_remove_int () at /lib64/libdb-5.3.so
  #9  0x00007fab6674bbbf in __env_dbremove_pp () at /lib64/libdb-5.3.so
  #10 0x00007fab663bcc35 in _cl5DBCloseFile (data=<optimized out>) at ldap/servers/plugins/replication/cl5_api.c:5936

  • it is trying to lock the db handle for the changelog, but this is locked by another process:

       2b dd=29 locks held 1    write locks 0    pid/thread 27295/139638295484160 flags 10   priority 100       
   2b READ          1 HELD    /var/lib/dirsrv/slapd-master2/changelogdb/62a46203-5b8c11e9-b1cba87f-bd3ae6e1_5cade1e1000000010000.db handle        0
 800001f8 dd= 0 locks held 0    write locks 0    pid/thread 28044/140374180157696 flags 0    priority 100       
 800001f8 WRITE         1 WAIT    /var/lib/dirsrv/slapd-master2/changelogdb/62a46203-5b8c11e9-b1cba87f-bd3ae6e1_5cade1e1000000010000.db handle        0

  • the handle should be free at shutdown, in a normal shutdown with repl logging we have:

      [10/Apr/2019:09:39:15.332095729 +0200] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5DBCloseFile - Closing database /home/lkrispen/TEST/cz/install/var/lib/dirsrv/slapd-master2/changelogdb/9dde6b03-5b6311e9-ad16b06f-34f70f28_5cad9d7a000000010000.db
  [10/Apr/2019:09:39:15.357930758 +0200] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5DBCloseFile - Closed the changelog database handle for /home/lkrispen/TEST/cz/install/var/lib/dirsrv/slapd-master2/changelogdb/9dde6b03-5b6311e9-ad16b06f-34f70f28_5cad9d7a000000010000.db (rc: 0)

  • the modification in the systemd override replaces sigterm with sigkill or sigsegv, so we do not have a normal shutdown, so this hang seems to be "understandable"

But, what I do not understand is:
- why is it hangig in that specific test case as part of the suite
- why is it sometimes hanging if the test is run as single test, but not always
- why did this start with this specific commit ? The commit for this ticket does not touch replication or the shutdown code. With the override we should see this hang with other builds
Edited by lkrispen

Sorry no answer to your questions :(

Just a new question. If vattr patch slows down the server (I know it was expected to improve pref :( ) this patch can trigger the timeout and then the hang. Did you get a core dumped using SIGSEGV ? the core could show if DS was impacted by vattr patch during the timeout.

Sorry no answer to your questions :(
Just a new question. If vattr patch slows down the server (I know it was expected to improve pref :( ) this patch can trigger the timeout and then the hang. Did you get a core dumped using SIGSEGV ? the core could show if DS was impacted by vattr patch during the timeout.

you missed one point, the change in override changes the timeout AND killsignal, so it immediately kills the server, the timeout is not effective.

I did rerun the test with
PYTEST_TEST=suites/replication/acceptance_test.py BUILDRPM=1 COMMIT=09965c45ed718595ecbd5804d00648b53123014c

and did get the same hang, so it is iondependent of the latest vattr patch

just reproduced the hang with commit ff94e562a0c3e10c05fbead70e27215ace47b1d2 which was before the first vattr commit.

I think we see an effect of killing servers instead of stopping them

This might need to be backported to 1.3.8 (RHEL 7.6)

389-ds-base is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in 389-ds-base's github repository.

This issue has been cloned to Github and is available here:
- https://github.com/389ds/389-ds-base/issues/2932

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.

Metadata Update from @spichugi:
- Issue close_status updated to: wontfix (was: fixed)
Metadata
None
None
None
None
None
None
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.