1:40 p.m.
I'm trying to track down a problem we are seeing on two relatively
lightly used instances on CentOS 7 (and previously on CentOS 6, which is
no longer in use). Our servers have 3624 entries according to last
night's export (we export userRoot daily). There are currently just
over 400 connections established to each server.
We have a local cron job that runs every 5 minutes that performs a
simple query. If it takes more than 7 seconds to get an answer, the
attempt is aborted and another query issued. If three consecutive test
fail, the directory server is restarted.
The issue we're seeing is that the longer the system is up, the more
often checks will fail. Restarting the directory does not resolve the
problem. Our servers have currently been up for 108 days, and are
restarting the service several times a day, as a result of the checks.
Only if we reboot the systems does the problem subside.
CPU utilization seems relatively high for such a small directory, but
it's not constant. I tried to manually capture a bit of data with
strace during a period when CPU use was bursting high. During a capture
of maybe two seconds, I saw most of the CPU time was spent in futex.
usecs/call was fairly high for calls to futex and select, as detailed below.
Since restarting the service doesn't fix the problem, it seems most
likely that this is an OS bug, but I'm hoping that the list can help me
identify other useful data to track down the problem. Does anyone have
any suggestions for what I can capture now, while I can sometimes
observe the problem? If I reboot, it'll take months before I can get
any new data.
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
74.61 4.505251 3590 1255 340 futex
17.65 1.065548 6660 160 select
4.41 0.266344 88781 3 2 restart_syscall
3.07 0.185566 50 3718 poll
0.10 0.006185 2 3610 sendto
0.09 0.005189 5189 1 fsync
0.04 0.002134 37 58 write
0.03 0.001618 27 61 setsockopt
0.00 0.000111 3 36 recvfrom
0.00 0.000078 1 57 read
0.00 0.000014 14 1 fstat
0.00 0.000003 2 2 accept
0.00 0.000003 1 6 fcntl
0.00 0.000002 1 2 getsockname
0.00 0.000001 1 2 close
------ ----------- ----------- --------- --------- ----------------
100.00 6.038047 8972 342 total
1:58 p.m.
What is the test filter like?
Can we see a sanitized sample of the access log with the SRCH and RESULT?
If using SSL, review the output of
cat /proc/sys/kernel/random/entropy_avail
Do we have replication? (and large attribute values?)
You may want to run the "dbmon.sh" script to monitor cache usage for db
cache and entry cache, try to capture a few samples of line about
dbcachefree and userroot:ent (if the db with the problems is
userroot), when the searches are becoming too long, like this example:
INCR=1 HOST=m2.example.com BINDDN="cn=directory manager"
BINDPW="password"
VERBOSE=2 /usr/sbin/dbmon.sh
and review the ns-slapd errors and system messages log files for any
unusual activity.
what is the ns-slapd memory foot print from restart to slow responses?
any "too high" disk i/o? (or "bad" ssd?)
Thanks,
M.
On Tue, Nov 15, 2016 at 11:40 AM, Gordon Messmer <gordon.messmer(a)gmail.com>
wrote:
I'm trying to track down a problem we are seeing on two
relatively lightly
used instances on CentOS 7 (and previously on CentOS 6, which is no longer
in use). Our servers have 3624 entries according to last night's export
(we export userRoot daily). There are currently just over 400 connections
established to each server.
We have a local cron job that runs every 5 minutes that performs a simple
query. If it takes more than 7 seconds to get an answer, the attempt is
aborted and another query issued. If three consecutive test fail, the
directory server is restarted.
The issue we're seeing is that the longer the system is up, the more often
checks will fail. Restarting the directory does not resolve the problem.
Our servers have currently been up for 108 days, and are restarting the
service several times a day, as a result of the checks. Only if we reboot
the systems does the problem subside.
CPU utilization seems relatively high for such a small directory, but it's
not constant. I tried to manually capture a bit of data with strace during
a period when CPU use was bursting high. During a capture of maybe two
seconds, I saw most of the CPU time was spent in futex. usecs/call was
fairly high for calls to futex and select, as detailed below.
Since restarting the service doesn't fix the problem, it seems most likely
that this is an OS bug, but I'm hoping that the list can help me identify
other useful data to track down the problem. Does anyone have any
suggestions for what I can capture now, while I can sometimes observe the
problem? If I reboot, it'll take months before I can get any new data.
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
74.61 4.505251 3590 1255 340 futex
17.65 1.065548 6660 160 select
4.41 0.266344 88781 3 2 restart_syscall
3.07 0.185566 50 3718 poll
0.10 0.006185 2 3610 sendto
0.09 0.005189 5189 1 fsync
0.04 0.002134 37 58 write
0.03 0.001618 27 61 setsockopt
0.00 0.000111 3 36 recvfrom
0.00 0.000078 1 57 read
0.00 0.000014 14 1 fstat
0.00 0.000003 2 2 accept
0.00 0.000003 1 6 fcntl
0.00 0.000002 1 2 getsockname
0.00 0.000001 1 2 close
------ ----------- ----------- --------- --------- ----------------
100.00 6.038047 8972 342 total
_______________________________________________
389-users mailing list -- 389-users(a)lists.fedoraproject.org
To unsubscribe send an email to 389-users-leave(a)lists.fedoraproject.org
2:08 p.m.
On 11/15/2016 12:58 PM, Marc Sauton wrote:
What is the test filter like?
Can we see a sanitized sample of the access log with the SRCH and RESULT?
If using SSL, review the output of
cat /proc/sys/kernel/random/entropy_avail
Do we have replication? (and large attribute values?)
You may want to run the "dbmon.sh" script to monitor cache usage for
db cache and entry cache, try to capture a few samples of line about
dbcachefree and userroot:ent (if the db with the problems is
userroot), when the searches are becoming too long, like this example:
INCR=1 HOST=m2.example.com <http://m2.example.com>
BINDDN="cn=directory manager" BINDPW="password" VERBOSE=2
/usr/sbin/dbmon.sh
and review the ns-slapd errors and system messages log files for any
unusual activity.
what is the ns-slapd memory foot print from restart to slow responses?
any "too high" disk i/o? (or "bad" ssd?)
It is also useful to get a few stacktraces which will give us detailed
information about what the server is doing. For example, if you can
"catch" the server while it is misbehaving, and get stacktraces every
second for 10 seconds.
http://www.port389.org/docs/389ds/FAQ/faq.html#debugging-hangs
Thanks,
M.
On Tue, Nov 15, 2016 at 11:40 AM, Gordon Messmer
<gordon.messmer(a)gmail.com <mailto:gordon.messmer@gmail.com>> wrote:
I'm trying to track down a problem we are seeing on two relatively
lightly used instances on CentOS 7 (and previously on CentOS 6,
which is no longer in use). Our servers have 3624 entries
according to last night's export (we export userRoot daily).
There are currently just over 400 connections established to each
server.
We have a local cron job that runs every 5 minutes that performs a
simple query. If it takes more than 7 seconds to get an answer,
the attempt is aborted and another query issued. If three
consecutive test fail, the directory server is restarted.
The issue we're seeing is that the longer the system is up, the
more often checks will fail. Restarting the directory does not
resolve the problem. Our servers have currently been up for 108
days, and are restarting the service several times a day, as a
result of the checks. Only if we reboot the systems does the
problem subside.
CPU utilization seems relatively high for such a small directory,
but it's not constant. I tried to manually capture a bit of data
with strace during a period when CPU use was bursting high.
During a capture of maybe two seconds, I saw most of the CPU time
was spent in futex. usecs/call was fairly high for calls to futex
and select, as detailed below.
Since restarting the service doesn't fix the problem, it seems
most likely that this is an OS bug, but I'm hoping that the list
can help me identify other useful data to track down the problem.
Does anyone have any suggestions for what I can capture now, while
I can sometimes observe the problem? If I reboot, it'll take
months before I can get any new data.
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
74.61 4.505251 3590 1255 340 futex
17.65 1.065548 6660 160 select
4.41 0.266344 88781 3 2 restart_syscall
3.07 0.185566 50 3718 poll
0.10 0.006185 2 3610 sendto
0.09 0.005189 5189 1 fsync
0.04 0.002134 37 58 write
0.03 0.001618 27 61 setsockopt
0.00 0.000111 3 36 recvfrom
0.00 0.000078 1 57 read
0.00 0.000014 14 1 fstat
0.00 0.000003 2 2 accept
0.00 0.000003 1 6 fcntl
0.00 0.000002 1 2 getsockname
0.00 0.000001 1 2 close
------ ----------- ----------- --------- --------- ----------------
100.00 6.038047 8972 342 total
_______________________________________________
389-users mailing list -- 389-users(a)lists.fedoraproject.org
<mailto:389-users@lists.fedoraproject.org>
To unsubscribe send an email to
389-users-leave(a)lists.fedoraproject.org
<mailto:389-users-leave@lists.fedoraproject.org>
_______________________________________________
389-users mailing list -- 389-users(a)lists.fedoraproject.org
To unsubscribe send an email to 389-users-leave(a)lists.fedoraproject.org
6:51 p.m.
On 11/15/2016 12:08 PM, Rich Megginson wrote:
It is also useful to get a few stacktraces which will give us
detailed
information about what the server is doing. For example, if you can
"catch" the server while it is misbehaving, and get stacktraces every
second for 10 seconds.
http://www.port389.org/docs/389ds/FAQ/faq.html#debugging-hangs
This might be really good news: In addition to oddly high CPU
utilization, we sometimes see slapd lock up completely. I managed to
catch the server in such a state and get a backtrace. Can you let me
know if this clarifies the problem at all?
When the server wedged, an ldap client would complete a connect() call
to establish the connection, write some data, and then hang indefinitely:
connect(3, {sa_family=AF_INET6, sin6_port=htons(389),
inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0,
sin6_scope_id=0}, 28) = 0
write(3,
"0>\2\1\1c9\4\0\n\1\0\n\1\0\2\1\0\2\1\0\1\1\0\207\vobjectclass0\31\4\27supportedSASLMechanisms",
64) = 64
poll([{fd=3, events=POLLIN|POLLPRI}], 1, 4294967295) = ?
ERESTART_RESTARTBLOCK (Interrupted by signal)
I'd been running dbmon.sh in a terminal, and it had hung with no output
for several minutes. The last thing it printed was rather normal:
dbname count free free% size
userroot:ent 3607 78692851 75.0 7253.9
userroot:dn 3607 10162827 96.9 89.5
7:16 p.m.
rpm -q 389-ds-base?
I wonder you are running the latest version?
https://git.centos.org/summary/rpms!!389-ds-base
2016-11-03 *imports/c7/389-ds-base-1.3.5.10-11.el7
<https://git.centos.org/commit/rpms%21%21389-ds-base/7c7f2927f715ce0e96e4d...
* import 389-ds-base-1.3.5.10-11.el7
<https://git.centos.org/tag/rpms%21%21389-ds-base/a01dffe770540fbb0a42c3b7...
tag
<https://git.centos.org/tag/rpms%21%21389-ds-base/a01dffe770540fbb0a42c3b7...
| commit
<https://git.centos.org/commit/rpms%21%21389-ds-base/7c7f2927f715ce0e96e4d...
| log
<https://git.centos.org/log/rpms%21%21389-ds-base/refs%21tags%21imports%21...
On 11/15/2016 04:51 PM, Gordon Messmer wrote:
On 11/15/2016 12:08 PM, Rich Megginson wrote:
> It is also useful to get a few stacktraces which will give us
> detailed information about what the server is doing. For example, if
> you can "catch" the server while it is misbehaving, and get
> stacktraces every second for 10 seconds.
> http://www.port389.org/docs/389ds/FAQ/faq.html#debugging-hangs
This might be really good news: In addition to oddly high CPU
utilization, we sometimes see slapd lock up completely. I managed to
catch the server in such a state and get a backtrace. Can you let me
know if this clarifies the problem at all?
When the server wedged, an ldap client would complete a connect() call
to establish the connection, write some data, and then hang indefinitely:
connect(3, {sa_family=AF_INET6, sin6_port=htons(389),
inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0,
sin6_scope_id=0}, 28) = 0
write(3,
"0>\2\1\1c9\4\0\n\1\0\n\1\0\2\1\0\2\1\0\1\1\0\207\vobjectclass0\31\4\27supportedSASLMechanisms",
64) = 64
poll([{fd=3, events=POLLIN|POLLPRI}], 1, 4294967295) = ?
ERESTART_RESTARTBLOCK (Interrupted by signal)
I'd been running dbmon.sh in a terminal, and it had hung with no
output for several minutes. The last thing it printed was rather normal:
dbname count free free% size
userroot:ent 3607 78692851 75.0 7253.9
userroot:dn 3607 10162827 96.9 89.5
_______________________________________________
389-users mailing list -- 389-users(a)lists.fedoraproject.org
To unsubscribe send an email to 389-users-leave(a)lists.fedoraproject.org
1:06 a.m.
On 11/15/2016 05:16 PM, Noriko Hosoi wrote:
rpm -q 389-ds-base?
# rpm -q 389-ds-base
389-ds-base-1.3.4.0-33.el7_2.x86_64
I wonder you are running the latest version?
https://git.centos.org/summary/rpms!!389-ds-base
2016-11-03 *imports/c7/389-ds-base-1.3.5.10-11.el7
<https://git.centos.org/commit/rpms%21%21389-ds-base/7c7f2927f715ce0e96e4d...
* import 389-ds-base-1.3.5.10-11.el7
<https://git.centos.org/tag/rpms%21%21389-ds-base/a01dffe770540fbb0a42c3b7...
tag
<https://git.centos.org/tag/rpms%21%21389-ds-base/a01dffe770540fbb0a42c3b7...
| commit
<https://git.centos.org/commit/rpms%21%21389-ds-base/7c7f2927f715ce0e96e4d...
| log
<https://git.centos.org/log/rpms%21%21389-ds-base/refs%21tags%21imports%21...
That's not generally available yet. I'll see if I can get it tomorrow
and update. If so, I should be able to verify the problem still exists.
11:21 a.m.
On 11/15/2016 05:51 PM, Gordon Messmer wrote:
On 11/15/2016 12:08 PM, Rich Megginson wrote:
> It is also useful to get a few stacktraces which will give us
> detailed information about what the server is doing. For example, if
> you can "catch" the server while it is misbehaving, and get
> stacktraces every second for 10 seconds.
> http://www.port389.org/docs/389ds/FAQ/faq.html#debugging-hangs
This might be really good news: In addition to oddly high CPU
utilization, we sometimes see slapd lock up completely. I managed to
catch the server in such a state and get a backtrace. Can you let me
know if this clarifies the problem at all?
When the server wedged, an ldap client would complete a connect() call
to establish the connection, write some data, and then hang indefinitely:
connect(3, {sa_family=AF_INET6, sin6_port=htons(389),
inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0,
sin6_scope_id=0}, 28) = 0
write(3,
"0>\2\1\1c9\4\0\n\1\0\n\1\0\2\1\0\2\1\0\1\1\0\207\vobjectclass0\31\4\27supportedSASLMechanisms",
64) = 64
poll([{fd=3, events=POLLIN|POLLPRI}], 1, 4294967295) = ?
ERESTART_RESTARTBLOCK (Interrupted by signal)
I'd been running dbmon.sh in a terminal, and it had hung with no
output for several minutes. The last thing it printed was rather normal:
dbname count free free% size
userroot:ent 3607 78692851 75.0 7253.9
userroot:dn 3607 10162827 96.9 89.5
I suggest you file a ticket at https://fedorahosted.org/389/newticket
and attach this and the other information for tracking. This doesn't
seem like an issue that will be easily resolved . . .
_______________________________________________
389-users mailing list -- 389-users(a)lists.fedoraproject.org
To unsubscribe send an email to 389-users-leave(a)lists.fedoraproject.org
12:24 p.m.
On 11/16/2016 09:21 AM, Rich Megginson wrote:
I suggest you file a ticket at https://fedorahosted.org/389/newticket
and attach this and the other information for tracking. This doesn't
seem like an issue that will be easily resolved . . .
OK. Is there any other data I can gather right now? The problem takes
a few months to manifest, but once it does it gets pretty bad. That
gives us narrow, rare windows to get useful data.
12:47 p.m.
Am 11/16/2016 um 7:24 PM schrieb Gordon Messmer:
On 11/16/2016 09:21 AM, Rich Megginson wrote:
> I suggest you file a ticket at https://fedorahosted.org/389/newticket
> and attach this and the other information for tracking. This doesn't
> seem like an issue that will be easily resolved . . .
OK. Is there any other data I can gather right now? The problem
takes a few months to manifest, but once it does it gets pretty bad.
That gives us narrow, rare windows to get useful data.
I would monitor the system(s) OS behavior with (example) collectd at
least cpu, memory, load, iowait. Additional any either query/behavior
specific monitoring can be implemented using collectd plugins like
perl/python
and additional the generic available stats like provided through
cn=snmp,cn=monitor
regards
mIke
example collectd plugin
/usr/share/collectd/python-plugins/389_monitorstats.py
import collectd
import ldap
instances = {}
config = None
monitorattrs = ['anonymousbinds', 'unauthbinds',
'simpleauthbinds',
'strongauthbinds', 'bindsecurityerrors', 'inops',
'readops',
'compareops', 'addentryops', 'removeentryops',
'modifyentryops',
'modifyrdnops', 'listops', 'searchops',
'onelevelsearchops',
'wholesubtreesearchops', 'referrals',
'chainings',
'securityerrors',
'errors', 'connections', 'connectionseq',
'bytesrecv',
'bytessent', 'entriesreturned',
'referralsreturned',
'masterentries',
'copyentries', 'cacheentries', 'cachehits',
'slavehits']
class LDAPStats(object):
def __init__(self, hostname=None, port=389, binddn=None, bindpw=None):
self.hostname = hostname
self.binddn = binddn
self.bindpw = bindpw
self.port = int(port)
if self.hostname != None:
self.__get_stats__()
def __get_stats__(self):
self.srv = ldap.open(self.hostname, self.port)
if self.binddn != None:
self.srv.simple_bind_s(self.binddn, self.bindpw)
dn, attrs = self.srv.search_s('cn=snmp,cn=monitor',
ldap.SCOPE_BASE, attrlist=monitorattrs)[0]
for a in monitorattrs:
if int(attrs[a][0]) < 0:
attrs[a][0] = int(attrs[a][0]) * -1
setattr(self, a, int(attrs[a][0]))
del self.srv
def get_stats(self, hr=False):
stats = []
for a in monitorattrs:
stats.append(int(getattr(self, a)))
if hr == False:
return stats
else:
return zip(monitorattrs, stats)
def configer(config):
global instances
collectd.debug('Configuring Stuff')
# children', 'key', 'parent', 'values'
for c in config.children:
if c.key == 'server':
for srv in c.children:
if srv.key == 'hostname':
hostname = '.'.join(srv.values)
elif srv.key == 'port':
port = int(srv.values[0])
instances[hostname] = port
def initer():
collectd.debug('initing stuff')
def reader(input_data=None):
global instances
for h in instances:
srv = LDAPStats(hostname=h, port=instances[h])
metric = collectd.Values(host=h,
type='389monitorstats', plugin='389monitorstats', type_instance=h)
metric.values = srv.get_stats()
metric.dispatch()
collectd.register_config(configer)
collectd.register_init(initer)
collectd.register_read(reader)
the corresponding /usr/share/collectd/types.db entry looks as follows
389monitorstats anonymousbinds:COUNTER:0:U, unauthbinds:COUNTER:0:U,
simpleauthbinds:COUNTER:0:U, strongauthbinds:COUNTER:0:U,
bindsecurityerrors:COUNTER:0:U, inops:COUNTER:0:U, readops:COUNTER:0:U,
compareops:COUNTER:0:U, addentryops:COUNTER:0:U,
removeentryops:COUNTER:0:U, modifyentryops:COUNTER:0:U,
modifyrdnops:COUNTER:0:U, listops:COUNTER:0:U, searchops:COUNTER:0:U,
onelevelsearchops:COUNTER:0:U, wholesubtrsearchops:COUNTER:0:U,
referrals:COUNTER:0:U, chainings:COUNTER:0:U,
securityerrors:COUNTER:0:U, errors:COUNTER:0:U, connections:DERIVE:U:U,
connectionseq:COUNTER:0:U, bytesrecv:COUNTER:0:U, bytessent:COUNTER:0:U,
entriesreturned:COUNTER:0:U, referralsreturned:COUNTER:0:U,
masterentries:COUNTER:0:U, copyentries:COUNTER:0:U,
cacheentries:COUNTER:0:U, cachehits:COUNTER:0:U, slavehits:COUNTER:0:U
and collectd configuration /etc/collectd.d/python.conf
LoadPlugin python
<Plugin python>
ModulePath "/usr/share/collectd/python-plugins"
LogTraces true
Interactive false
Import "389_monitorstats"
<Module 389_monitorstats>
<server>
hostname localhost
port 389
</server>
</Module>
</Plugin>
_______________________________________________
389-users mailing list -- 389-users(a)lists.fedoraproject.org
To unsubscribe send an email to 389-users-leave(a)lists.fedoraproject.org
3:23 p.m.
On Wed, 2016-11-16 at 10:24 -0800, Gordon Messmer wrote:
On 11/16/2016 09:21 AM, Rich Megginson wrote:
> I suggest you file a ticket at https://fedorahosted.org/389/newticket
> and attach this and the other information for tracking. This doesn't
> seem like an issue that will be easily resolved . . .
OK. Is there any other data I can gather right now? The problem takes
a few months to manifest, but once it does it gets pretty bad. That
gives us narrow, rare windows to get useful data.
What's your ioblocktimeout set to?
How many connections are idle on the server?
Are you seeing OOM behaviour or memory not being released to the OS?
What specs are your servers ie cpu and memory, is it ecc memory?
What kind of disk are they on? Are there issues in dmesg?
Have you configured system activity reporter (sar), and have out from
the same time of disk io, memory usage, cpu etc?
What's your sysctl setup like?
Have you increased file descriptors for Directory Server?
Have you lowered the TCP close wait timeout?
When I hear of problems like this, I'm always inclined to investigate
the host first, as there is a surprising amount that can affect DS from
the host.
--
Sincerely,
William Brown
Software Engineer
Red Hat, Brisbane
6 p.m.
On 11/16/2016 01:23 PM, William Brown wrote:
What's your ioblocktimeout set to?
nsslapd-ioblocktimeout: 1800000
How many connections are idle on the server?
How would I check?
Are you seeing OOM behaviour or memory not being released to the OS?
No, the systems use very little memory:
# free
total used free shared buff/cache
available
Mem: 1883872 148932 72752 97156 1662188 1429468
Swap: 2097148 65064 2032084
No OOM actions are recorded.
What specs are your servers ie cpu and memory, is it ecc memory?
These are virtual machines with 4 allocated cores and 2GB of RAM. The
host systems are Intel(R) Xeon(R) CPU E5-2620 v3 with 64 of ECC RAM.
The two VMs running 389-ds are on different physical hosts, but have the
same problems at roughly the same frequency, at roughly the same uptime.
What kind of disk are they on? Are there issues in dmesg?
One physical system has a RAID10 mdraid array of SAS disks. The other
has a RAID1 mdraid array of SAS disks. No errors have been recorded.
The virtual machines are LVM-backed with standard (not sparse) LVs.
Have you configured system activity reporter (sar), and have out
from
the same time of disk io, memory usage, cpu etc?
I believe that's set up by default, yes.
https://paste.fedoraproject.org/483468/93401501/
The DS stopped responding at about 12:30AM in this readout (system time
is in UTC).
What's your sysctl setup like?
Standard for a CentOS 7 system, with these additions:
net.ipv4.ip_local_port_range = 1024 65000
net.ipv4.tcp_keepalive_time = 600
Have you increased file descriptors for Directory Server?
I thought I had, but it looks like I haven't:
# cat /proc/sys/fs/file-max
185059
# grep nofile /etc/security/limits.conf
# - nofile - max number of open file descriptors
# grep ulimit /etc/profile
nsslapd-maxdescriptors: 1024
Have you lowered the TCP close wait timeout?
No.
When I hear of problems like this, I'm always inclined to
investigate
the host first, as there is a surprising amount that can affect DS from
the host.
I suspect so, too, since the problem correlates with the system uptime,
not how long the daemon has been running. But beyond that I'm not sure
how to track this down further.
6:05 p.m.
On Wed, 2016-11-16 at 16:00 -0800, Gordon Messmer wrote:
On 11/16/2016 01:23 PM, William Brown wrote:
> What's your ioblocktimeout set to?
nsslapd-ioblocktimeout: 1800000
Hmm, that's default, but it's quite high, you could lower this if you
wanted. See:
https://access.redhat.com/documentation/en-US/Red_Hat_Directory_Server/10...
> How many connections are idle on the server?
How would I check?
cn=monitor should show you if you search it.
> Are you seeing OOM behaviour or memory not being released to the OS?
No, the systems use very little memory:
# free
total used free shared buff/cache
available
Mem: 1883872 148932 72752 97156 1662188 1429468
Swap: 2097148 65064 2032084
No OOM actions are recorded.
> What specs are your servers ie cpu and memory, is it ecc memory?
These are virtual machines with 4 allocated cores and 2GB of RAM. The
host systems are Intel(R) Xeon(R) CPU E5-2620 v3 with 64 of ECC RAM.
The two VMs running 389-ds are on different physical hosts, but have the
same problems at roughly the same frequency, at roughly the same uptime.
> What kind of disk are they on? Are there issues in dmesg?
One physical system has a RAID10 mdraid array of SAS disks. The other
has a RAID1 mdraid array of SAS disks. No errors have been recorded.
The virtual machines are LVM-backed with standard (not sparse) LVs.
That all sounds great, no issues there.
> Have you configured system activity reporter (sar), and have out from
> the same time of disk io, memory usage, cpu etc?
I believe that's set up by default, yes.
https://paste.fedoraproject.org/483468/93401501/
It looks like there is some activity just as it stops.
12:00:01 AM proc/s cswch/s
12:10:01 AM 4.91 393.92
12:20:01 AM 4.93 385.64
12:30:01 AM 2.79 312.10
12:40:01 AM 1.57 320.06
12:50:01 AM 0.84 282.43
01:00:01 AM 0.23 217.87
01:10:01 AM 0.38 276.50
12:00:01 AM pgpgin/s pgpgout/s fault/s majflt/s pgfree/s pgscank/s
pgscand/s pgsteal/s %vmeff
12:10:01 AM 0.27 51.65 2192.75 0.00 1020.59 0.00
0.00 0.00 0.00
12:20:01 AM 0.32 59.12 2193.29 0.00 1018.92 0.00
0.00 0.00 0.00
12:30:01 AM 0.04 124.12 1242.81 0.04 559.39 0.00
0.00 0.00 0.00
12:40:01 AM 1.77 23.27 685.10 0.00 324.02 0.00
0.00 0.00 0.00
12:50:01 AM 1.05 89.72 866.32 0.01 490.28 0.00
0.00 0.00 0.00
Then at 3:30 there is some more paging:
03:30:01 AM 29.34 171.17 472.71 0.11 289.21 0.00
0.00 0.00 0.00
There appears to be an increase in disk activity here too:
12:00:01 AM DEV tps rd_sec/s wr_sec/s avgrq-sz avgqu-sz
await svctm %util
12:10:01 AM dev252-0 7.86 0.55 103.30 13.21 8.90
1132.98 15.29 12.02
12:10:01 AM dev253-0 0.05 0.52 0.00 9.75 0.01
238.28 20.59 0.11
12:10:01 AM dev253-1 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00
12:10:01 AM dev253-2 8.82 0.03 103.30 11.72 9.06
1027.71 13.63 12.01
12:20:01 AM dev252-0 9.48 0.64 118.24 12.55 12.15
1281.81 15.56 14.75
12:20:01 AM dev253-0 0.10 0.64 0.16 8.00 0.03
251.33 25.82 0.26
12:20:01 AM dev253-1 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00
12:20:01 AM dev253-2 10.50 0.00 118.08 11.25 12.30
1171.42 13.96 14.65
12:30:01 AM dev252-0 4.39 0.08 248.25 56.57 5.20
1183.77 27.41 12.03
12:30:01 AM dev253-0 0.20 0.08 3.30 16.87 0.04
199.68 31.60 0.63
12:30:01 AM dev253-1 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00
12:30:01 AM dev253-2 5.27 0.00 244.94 46.48 5.37
1019.43 22.10 11.65
But the amount of activity is mirrored at 8:40pm, so it's probably okay.
In generally, it doesn't look too busy, and the memory usage seems okay.
No other process runs at 12:30, IE backups?
The DS stopped responding at about 12:30AM in this readout (system time
is in UTC).
> What's your sysctl setup like?
Standard for a CentOS 7 system, with these additions:
net.ipv4.ip_local_port_range = 1024 65000
net.ipv4.tcp_keepalive_time = 600
> Have you increased file descriptors for Directory Server?
I thought I had, but it looks like I haven't:
# cat /proc/sys/fs/file-max
185059
# grep nofile /etc/security/limits.conf
# - nofile - max number of open file descriptors
# grep ulimit /etc/profile
nsslapd-maxdescriptors: 1024
> Have you lowered the TCP close wait timeout?
No.
> When I hear of problems like this, I'm always inclined to investigate
> the host first, as there is a surprising amount that can affect DS from
> the host.
I suspect so, too, since the problem correlates with the system uptime,
not how long the daemon has been running. But beyond that I'm not sure
how to track this down further.
It may appear to be uptime, but may not. It would be worth checking
ss/netstat when the issue occurs next, see how many sockets are blocked
on CLOSE_WAIT, because it could be a resource exhaustion there which
makes it appear as though it's slowing, but really, the threads are
starved of work. I'd need to study your pstack outputs to be sure.
Have you done any other Directory Server tuning (threads, memory
cache?). I think the out of box defaults are conservative, but in this
case probably aren't too bad for you.
Might also be worth checking your VM hosts at the time the issues occur,
see if you see a spike on other systems or storage.
--
Sincerely,
William Brown
Software Engineer
Red Hat, Brisbane
1:14 a.m.
On 11/15/2016 12:08 PM, Rich Megginson wrote:
It is also useful to get a few stacktraces which will give us
detailed
information about what the server is doing. For example, if you can
"catch" the server while it is misbehaving, and get stacktraces every
second for 10 seconds.
http://www.port389.org/docs/389ds/FAQ/faq.html#debugging-hangs
One other note: I did get ten traces, at one second intervals, but they
were all mostly the same. I've attached the diff between two
haphazardly chosen traces. Any two traces differ in the same spots, as
far as I can tell.
3:23 p.m.
On 11/15/2016 11:58 AM, Marc Sauton wrote:
What is the test filter like?
my $LDAP_BASE = 'dc=dept,dc=uni,dc=edu';
my $LDAP_ATTRS = [qw/cn/];
my $LDAP_FILTER = '(cn=sysadm)';
...
my $ldap =
Net::LDAP->new( $LDAP_SERVER, timeout => $TIMEOUT, onerror =>
'die' )
or die "error: connect failed: $LDAP_SERVER: $@";
# anon binds must be permitted by server
my $mesg = $ldap->bind();
$mesg = $ldap->search(
base => $LDAP_BASE,
filter => $LDAP_FILTER,
attrs => $LDAP_ATTRS
);
Can we see a sanitized sample of the access log with the SRCH and
RESULT?
I'm working on getting that during a CPU spike, as well as the gdb
stacktraces that Rich requested.
If using SSL, review the output of
cat /proc/sys/kernel/random/entropy_avail
SSL is available, but we don't operate all of the clients, so I'm not
sure how many use it. At the moment, that file's content is a number
around 150 on each server.
Do we have replication? (and large attribute values?)
Yes on replication. Unsure about large attribute values.
You may want to run the "dbmon.sh" script to monitor cache
usage for
db cache and entry cache, try to capture a few samples of line about
dbcachefree and userroot:ent (if the db with the problems is
userroot), when the searches are becoming too long, like this example:
INCR=1 HOST=m2.example.com <http://m2.example.com>
BINDDN="cn=directory manager" BINDPW="password" VERBOSE=2
/usr/sbin/dbmon.sh
and review the ns-slapd errors and system messages log files for any
unusual activity.
I'm watching that now. At the moment, output looks like:
dbname count free free% size
userroot:ent 3606 78696358 75.1 7254.9
userroot:dn 3606 10162904 96.9 89.5
what is the ns-slapd memory foot print from restart to slow
responses?
A couple of seconds after startup:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+
COMMAND
32654 ldap 20 0 2740472 84884 37396 S 1.7 4.5 0:00.99
ns-slapd
And then a minute later:
32654 ldap 20 0 2742196 88060 37504 S 32.9 4.7 0:05.65
ns-slapd
any "too high" disk i/o? (or "bad" ssd?)
There's more write activity than I'd expect (reported by iostat), and
the slapd db files show mtime updates regularly, but I've enabled the
audit log and see no updates logged. That's what I'd expect; we don't
anticipate many writes to these DBs.
# find /var/lib/dirsrv/slapd-master1/ -type f -mmin -5 | xargs ls -l
-rw-------. 1 ldap ldap 2408448 Nov 15 21:01
/var/lib/dirsrv/slapd-master1/db/__db.001
-rw-------. 1 ldap ldap 7380992 Nov 15 21:01
/var/lib/dirsrv/slapd-master1/db/__db.002
-rw-------. 1 ldap ldap 22897880 Nov 15 21:01
/var/lib/dirsrv/slapd-master1/db/__db.003
# date
Tue Nov 15 21:01:09 UTC 2016
2709
days inactive
2712
days old
389-users@lists.fedoraproject.org
13 comments
6 participants
participants (6)
-
Gordon Messmer -
Marc Sauton -
Michael Lang -
Noriko Hosoi -
Rich Megginson -
William Brown