In the end this came down to one slow OSD. There were no hardware
issues so have to just assume something gummed up during rebalancing
and peering.
I restarted the osd process after setting the cluster to noout.
After the osd was restarted the rebalance completed and the cluster
returned to health ok.
As soon as the osd restarted all previously hanging operations
returned to normal.
I'm surprised by a single slow OSD impacting access to the entire
cluster. I understand now that only the primary osd is used for
reads and writes must go to the primary then secondary, but I would
have expected the impact to be more contained.
We currently build XFS file systems directly on RBD images. I'm
wondering if there would be any value in using an LVM abstraction on
top to spread access to other osds for read and failure scenarios.
Any thoughts on the above appreciated.
~jpr
On 05/28/2015 03:18 PM, John-Paul
Robinson wrote:
To follow up on the original post,
Further digging indicates this is a problem with RBD image access
and is not related to NFS-RBD interaction as initially suspected.
The nfsd is simply hanging as a result of a hung request to the
XFS file system mounted on our RBD-NFS gateway. This hung XFS
call is caused by a problem with the RBD module interacting with
our Ceph pool.
I've found a reliable way to trigger a hang directly on an rbd
image mapped into our RBD-NFS gateway box. The image contains an
XFS file system. When I try to list the contents of a particular
directory, the request hangs indefinitely.
Two weeks ago our ceph status was:
jpr@rcs-02:~/projects/rstore-utils$ sudo ceph --id
nova status
health HEALTH_WARN 1 near full osd(s)
monmap e1: 3 mons at
{da0-36-9f-0e-28-2c=172.16.171.6:6789/0,da0-36-9f-0e-2b-88=172.16.171.5:6789/0,da0-36-9f-0e-2b-a0=172.16.171.4:6789/0},
election epoch 350, quorum 0,1,2
da0-36-9f-0e-28-2c,da0-36-9f-0e-2b-88,da0-36-9f-0e-2b-a0
osdmap e5978: 66 osds: 66 up, 66 in
pgmap v26434260: 3072 pgs: 3062 active+clean, 6
active+clean+scrubbing, 4 active+clean+scrubbing+deep; 45712
GB data, 91590 GB used, 51713 GB / 139 TB avail; 12234B/s wr,
1op/s
mdsmap e1: 0/0/1 up
The near full osd was number 53 and we updated our crush map to
rewieght the osd. All of the OSDs had a weight of 1 based on the
assumption that all osds were 2.0TB. Apparently one of our severs
had the OSDs Sized to 2.8TB and this caused the OSD imbalance
eventhough we are only at 50% utilization. We reweighted the near
full osd to .8 and that initiated a rebalance that has since
relieved the 95% full condition on that OSD.
However, since that time the repeering has not completed and we
suspect this is causing problems with our access of RBD images.
Our current ceph status is:
jpr@rcs-02:~/projects/rstore-utils$ sudo ceph --id
nova status
health HEALTH_WARN 1 pgs peering; 1 pgs stuck inactive; 4
pgs stuck unclean; recovery 9/23842120 degraded (0.000%)
monmap e1: 3 mons at
{da0-36-9f-0e-28-2c=172.16.171.6:6789/0,da0-36-9f-0e-2b-88=172.16.171.5:6789/0,da0-36-9f-0e-2b-a0=172.16.171.4:6789/0},
election epoch 350, quorum 0,1,2
da0-36-9f-0e-28-2c,da0-36-9f-0e-2b-88,da0-36-9f-0e-2b-a0
osdmap e6036: 66 osds: 66 up, 66 in
pgmap v27104371: 3072 pgs: 3 active, 3056 active+clean,
9 active+clean+scrubbing, 1 remapped+peering, 3
active+clean+scrubbing+deep; 45868 GB data, 92006 GB used,
51297 GB / 139 TB avail; 3125B/s wr, 0op/s; 9/23842120
degraded (0.000%)
mdsmap e1: 0/0/1 up
Here are further details on our stuck pgs:
jpr@rcs-02:~/projects/rstore-utils$ sudo ceph --id
nova pg dump_stuck inactive
ok
pg_stat objects mip degr unf bytes log
disklog state state_stamp v reported
up acting last_scrub scrub_stamp last_deep_scrub
deep_scrub_stamp
3.3af 11600 0 0 0 47941791744
153812 153812 remapped+peering 2015-05-15
12:47:17.223786 5979'293066 6000'1248735 [48,62]
[53,48,62] 5979'293056 2015-05-15
07:40:36.275563 5979'293056 2015-05-15
07:40:36.275563
jpr@rcs-02:~/projects/rstore-utils$ sudo ceph --id nova pg
dump_stuck unclean
ok
pg_stat objects mip degr unf bytes log
disklog state state_stamp v reported
up acting last_scrub scrub_stamp last_deep_scrub
deep_scrub_stamp
3.106 11870 0 9 0 49010106368
163991 163991 active 2015-05-15 12:47:19.761469
6035'356332 5968'1358516 [62,53] [62,53] 5979'356242
2015-05-14 22:22:12.966150 5979'351351 2015-05-12
18:04:41.838686
5.104 0 0 0 0 0 0
0 active 2015-05-15 12:47:19.800676 0'0
5968'1615 [62,53] [62,53] 0'0 2015-05-14
18:43:22.425105 0'0 2015-05-08 10:19:54.938934
4.105 0 0 0 0 0 0
0 active 2015-05-15 12:47:19.801028 0'0
5968'1615 [62,53] [62,53] 0'0 2015-05-14
18:43:04.434826 0'0 2015-05-14 18:43:04.434826
3.3af 11600 0 0 0 47941791744
153812 153812 remapped+peering 2015-05-15
12:47:17.223786 5979'293066 6000'1248735 [48,62]
[53,48,62] 5979'293056 2015-05-15
07:40:36.275563 5979'293056 2015-05-15
07:40:36.275563
The servers in the pool are not overloaded. On the ceph server
that originally had the nearly full osd, (osd 53), I'm seeing
entries like this in the osd log:
2015-05-28 06:25:02.900129 7f2ea8a4f700 0 log
[WRN] : 6 slow requests, 6 included below; oldest blocked for
> 1096430.805069 secs
2015-05-28 06:25:02.900145 7f2ea8a4f700 0 log [WRN] : slow
request 1096430.805069 seconds old, received at 2015-05-15
13:51:12.094956: osd_op
(client.153458.0:274955541 rb.0.d204.238e1f29.0000000844d2
[sparse-read 3706880~4096] 3.773a03af) v4 currently reached pg
2015-05-28 06:25:02.900156 7f2ea8a4f700 0 log [WRN] : slow
request 1095097.235862 seconds old, received at 2015-05-15
14:13:25.664163: osd_op(client.154124.1:68230513
rb.0.176f3.238e1f29.000000002cd8 [write 0~524288] 3.4329faf)
v4 currently reached pg
2015-05-28 06:25:02.900162 7f2ea8a4f700 0 log [WRN] : slow
request 1095097.214366 seconds old, received at 2015-05-15
14:13:25.685659: osd_op(client.154124.1:68230514
rb.0.176f3.238e1f29.000000002cd8 [write 524288~524288]
3.4329faf) v4 currently reached pg
2015-05-28 06:25:02.900169 7f2ea8a4f700 0 log [WRN] : slow
request 1095097.191725 seconds old, received at 2015-05-15
14:13:25.708300: osd_op(client.154124.1:68230515
rb.0.176f3.238e1f29.000000002cd8 [write 1048576~524288]
3.4329faf) v4 currently reached pg
2015-05-28 06:25:02.900175 7f2ea8a4f700 0 log [WRN] : slow
request 1095097.169399 seconds old, received at 2015-05-15
14:13:25.730626: osd_op(client.154124.1:68230516
...
These happen once per second and the only thing that changes in
the whole batch of messages is that the seconds old increases.
According to dmesg, syslog, and bmc there are no current hw
malfunctions on this machine.
I'm assuming that whatever is causing the slow request in the osd
logs might be gumming up the works.
What I don't get is how to get my pg out of the stuck inactive
state. The doc solution hints don't seem to apply in this case.
Finally here is the health detail, it sorta repeats the above:
jpr@rcs-02:~/projects/rstore-utils$ sudo ceph --id
nova osd lspools
3 rbd,4 data,5 metadata,
jpr@rcs-02:~/projects/rstore-utils$ sudo ceph --id nova health
detail
HEALTH_WARN 1 pgs peering; 1 pgs stuck inactive; 4 pgs stuck
unclean; recovery 9/23842120 degraded (0.000%)
pg 3.3af is stuck inactive for 1132739.583540, current state
remapped+peering, last acting [53,48,62]
pg 3.106 is stuck unclean for 1131876.351202, current state
active, last acting [62,53]
pg 5.104 is stuck unclean for 1131876.350931, current state
active, last acting [62,53]
pg 4.105 is stuck unclean for 1131876.351729, current state
active, last acting [62,53]
pg 3.3af is stuck unclean for 1132739.583697, current state
remapped+peering, last acting [53,48,62]
pg 3.3af is remapped+peering, acting [53,48,62]
recovery 9/23842120 degraded (0.000%)
I'd like to get to ceph health OK to see if that's contributing to
the problem.
Thanks for any pointers.
~jpr
On 05/24/2015 11:02 PM, Christian
Balzer wrote:
Hello,
lets compare your case with John-Paul's.
Different OS and Ceph versions (thus we can assume different NFS versions
as well).
The only common thing is that both of you added OSDs and are likely
suffering from delays stemming from Ceph re-balancing or deep-scrubbing.
Ceph logs will only pipe up when things have been blocked for more than 30
seconds, NFS might take offense to lower values (or the accumulation of
several distributed delays).
You added 23 OSDs, tell us more about your cluster, HW, network.
Were these added to the existing 16 nodes, are these on new storage nodes
(so could there be something different with those nodes?), how busy is your
network, CPU.
Running something like collectd to gather all ceph perf data and other
data from the storage nodes and then feeding it to graphite (or similar)
can be VERY helpful to identify if something is going wrong and what it is
in particular.
Otherwise run atop on your storage nodes to identify if CPU, network,
specific HDDs/OSDs are bottlenecks.
Deep scrubbing can be _very_ taxing, do your problems persist if inject
into your running cluster an "osd_scrub_sleep" value of "0.5" (lower that
until it hurts again) or if you turn of deep scrubs altogether for the
moment?
Christian
On Sat, 23 May 2015 23:28:32 +0200 Jens-Christian Fischer wrote:
We see something very similar on our Ceph cluster, starting as of today.
We use a 16 node, 102 OSD Ceph installation as the basis for an Icehouse
OpenStack cluster (we applied the RBD patches for live migration etc)
On this cluster we have a big ownCloud installation (Sync & Share) that
stores its files on three NFS servers, each mounting 6 2TB RBD volumes
and exposing them to around 10 web server VMs (we originally started
with one NFS server with a 100TB volume, but that has become unwieldy).
All of the servers (hypervisors, ceph storage nodes and VMs) are using
Ubuntu 14.04
Yesterday evening we added 23 ODSs to the cluster bringing it up to 125
OSDs (because we had 4 OSDs that were nearing the 90% full mark). The
rebalancing process ended this morning (after around 12 hours) The
cluster has been clean since then:
cluster b1f3f4c8-xxxxx
health HEALTH_OK
monmap e2: 3 mons at
{zhdk0009=[yyyy:xxxx::1009]:6789/0,zhdk0013=[yyyy:xxxx::1013]:6789/0,zhdk0025=[yyyy:xxxx::1025]:6789/0},
election epoch 612, quorum 0,1,2 zhdk0009,zhdk0013,zhdk0025 osdmap
e43476: 125 osds: 125 up, 125 in pgmap v18928606: 3336 pgs, 17 pools,
82447 GB data, 22585 kobjects 266 TB used, 187 TB / 454 TB avail 3319
active+clean 17 active+clean+scrubbing+deep
client io 8186 kB/s rd, 7747 kB/s wr, 2288 op/s
At midnight, we run a script that creates an RBD snapshot of all RBD
volumes that are attached to the NFS servers (for backup purposes).
Looking at our monitoring, around that time, one of the NFS servers
became unresponsive and took down the complete ownCloud installation
(load on the web server was > 200 and they had lost some of the NFS
mounts)
Rebooting the NFS server solved that problem, but the NFS kernel server
kept crashing all day long after having run between 10 to 90 minutes.
We initially suspected a corrupt rbd volume (as it seemed that we could
trigger the kernel crash by just “ls -l” one of the volumes, but
subsequent “xfs_repair -n” checks on those RBD volumes showed no
problems.
We migrated the NFS server off of its hypervisor, suspecting a problem
with RBD kernel modules, rebooted the hypervisor but the problem
persisted (both on the new hypervisor, and on the old one when we
migrated it back)
We changed the /etc/default/nfs-kernel-server to start up 256 servers
(even though the defaults had been working fine for over a year)
Only one of our 3 NFS servers crashes (see below for syslog information)
- the other 2 have been fine
May 23 21:44:10 drive-nfs1 kernel: [ 165.264648] NFSD:
Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory May
23 21:44:19 drive-nfs1 kernel: [ 173.880092] NFSD: starting 90-second
grace period (net ffffffff81cdab00) May 23 21:44:23 drive-nfs1
rpc.mountd[1724]: Version 1.2.8 starting May 23 21:44:28 drive-nfs1
kernel: [ 182.917775] ip_tables: (C) 2000-2006 Netfilter Core Team May
23 21:44:28 drive-nfs1 kernel: [ 182.958465] nf_conntrack version 0.5.0
(16384 buckets, 65536 max) May 23 21:44:28 drive-nfs1 kernel:
[ 183.044091] ip6_tables: (C) 2000-2006 Netfilter Core Team May 23
21:45:10 drive-nfs1 CRON[1867]: (root) CMD (command -v debian-sa1
/dev/null && debian-sa1 1 1) May 23 21:45:17 drive-nfs1
collectd[1872]: python: Plugin loaded but not configured. May 23
21:45:17 drive-nfs1 collectd[1872]: Initialization complete, entering
read-loop. May 23 21:47:11 drive-nfs1 kernel: [ 346.392283] init:
plymouth-upstart-bridge main process ended, respawning May 23 21:51:26
drive-nfs1 kernel: [ 600.776177] INFO: task nfsd:1696 blocked for
more than 120 seconds.
May 23 21:51:26 drive-nfs1 kernel: [ 600.778090] Not tainted
3.13.0-53-generic #89-Ubuntu May 23 21:51:26 drive-nfs1 kernel:
[ 600.779507] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message. May 23 21:51:26 drive-nfs1 kernel: [ 600.781504]
nfsd D ffff88013fd93180 0 1696 2 0x00000000 May 23
21:51:26 drive-nfs1 kernel: [ 600.781508] ffff8800b2391c50
0000000000000046 ffff8800b22f9800 ffff8800b2391fd8 May 23 21:51:26
drive-nfs1 kernel: [ 600.781511] 0000000000013180 0000000000013180
ffff8800b22f9800 ffff880035f48240 May 23 21:51:26 drive-nfs1 kernel:
[ 600.781513] ffff880035f48244 ffff8800b22f9800 00000000ffffffff
ffff880035f48248 May 23 21:51:26 drive-nfs1 kernel: [ 600.781515] Call
Trace: May 23 21:51:26 drive-nfs1 kernel: [ 600.781523]
[<ffffffff81727749>] schedule_preempt_disabled+0x29/0x70 May 23 21:51:26
drive-nfs1 kernel: [ 600.781526] [<ffffffff817295b5>]
__mutex_lock_slowpath+0x135/0x1b0 May 23 21:51:26 drive-nfs1 kernel:
[ 600.781528] [<ffffffff8172964f>] mutex_lock+0x1f/0x2f May 23
21:51:26 drive-nfs1 kernel: [ 600.781557] [<ffffffffa03b1761>]
nfsd_lookup_dentry+0xa1/0x490 [nfsd] May 23 21:51:26 drive-nfs1 kernel:
[ 600.781568] [<ffffffffa03b044b>] ? fh_verify+0x14b/0x5e0 [nfsd] May
23 21:51:26 drive-nfs1 kernel: [ 600.781591] [<ffffffffa03b1bb9>]
nfsd_lookup+0x69/0x130 [nfsd] May 23 21:51:26 drive-nfs1 kernel:
[ 600.781613] [<ffffffffa03be90a>] nfsd4_lookup+0x1a/0x20 [nfsd] May
23 21:51:26 drive-nfs1 kernel: [ 600.781628] [<ffffffffa03c055a>]
nfsd4_proc_compound+0x56a/0x7d0 [nfsd] May 23 21:51:26 drive-nfs1
kernel: [ 600.781638] [<ffffffffa03acd3b>] nfsd_dispatch+0xbb/0x200
[nfsd] May 23 21:51:26 drive-nfs1 kernel: [ 600.781662]
[<ffffffffa028762d>] svc_process_common+0x46d/0x6d0 [sunrpc] May 23
21:51:26 drive-nfs1 kernel: [ 600.781678] [<ffffffffa0287997>]
svc_process+0x107/0x170 [sunrpc] May 23 21:51:26 drive-nfs1 kernel:
[ 600.781687] [<ffffffffa03ac71f>] nfsd+0xbf/0x130 [nfsd] May 23
21:51:26 drive-nfs1 kernel: [ 600.781696] [<ffffffffa03ac660>] ?
nfsd_destroy+0x80/0x80 [nfsd] May 23 21:51:26 drive-nfs1 kernel:
[ 600.781702] [<ffffffff8108b6b2>] kthread+0xd2/0xf0 May 23 21:51:26
drive-nfs1 kernel: [ 600.781707] [<ffffffff8108b5e0>] ?
kthread_create_on_node+0x1c0/0x1c0 May 23 21:51:26 drive-nfs1 kernel:
[ 600.781712] [<ffffffff81733868>] ret_from_fork+0x58/0x90 May 23
21:51:26 drive-nfs1 kernel: [ 600.781717] [<ffffffff8108b5e0>] ?
kthread_create_on_node+0x1c0/0x1c0
Before each crash, we see the disk utilization of one or two random
mounted RBD volumes to go to 100% - there is no pattern on which of the
RBD disks start to act up.
We have scoured the log files of the Ceph cluster for any signs of
problems but came up empty.
The NFS server has almost no load (compared to regular usage) as most
sync clients are either turned off (weekend) or have given up connecting
to the server.
There haven't been any configuration change on the NFS servers prior to
the problems. The only change was the adding of 23 OSDs.
We use ceph version 0.80.7 (6c0127fcb58008793d3c8b62d925bc91963672a3)
Our team is completely out of ideas. We have removed the 100TB volume
from the nfs server (we used the downtime to migrate the last data off
of it to one of the smaller volumes). The NFS server has been running
for 30 minutes now (with close to no load) but we don’t really expect it
to make it until tomorrow.
send help
Jens-Christian
|
