On Mon, Apr 13, 2020 at 4:14 PM Gregory Farnum <gfarnum(a)redhat.com> wrote:
On Mon, Apr 13, 2020 at 1:33 PM Josh Haft <paccrap(a)gmail.com> wrote:
Hi,
I upgraded from 13.2.5 to 14.2.6 last week and am now seeing
significantly higher latency on various MDS operations. For example,
the 2min rate of ceph_mds_server_req_create_latency_sum /
ceph_mds_server_req_create_latency_count for an 8hr window last Monday
prior to the upgrade was an average of 2ms. Today, however the same
stat shows 869ms. Other operations including open, readdir, rmdir,
etc. are also taking significantly longer.
Here's a partial example of an op from dump_ops_in_flight:
{
"description": "client_request(client.342513090:334359409
create #...)",
"initiated_at": "2020-04-13 15:30:15.707637",
"age": 0.19583208099999999,
"duration": 0.19767626299999999,
"type_data": {
"flag_point": "submit entry: journal_and_reply",
"reqid": "client.342513090:334359409",
"op_type": "client_request",
"client_info": {
"client": "client.342513090",
"tid": 334359409
},
"events": [
{
"time": "2020-04-13 15:30:15.707637",
"event": "initiated"
},
{
"time": "2020-04-13 15:30:15.707637",
"event": "header_read"
},
{
"time": "2020-04-13 15:30:15.707638",
"event": "throttled"
},
{
"time": "2020-04-13 15:30:15.707640",
"event": "all_read"
},
{
"time": "2020-04-13 15:30:15.781935",
"event": "dispatched"
},
{
"time": "2020-04-13 15:30:15.785086",
"event": "acquired locks"
},
{
"time": "2020-04-13 15:30:15.785507",
"event": "early_replied"
},
{
"time": "2020-04-13 15:30:15.785508",
"event": "submit entry: journal_and_reply"
}
]
}
}
This along with every other 'create' op I've seen has a 50ms+ delay
between all_read and dispatched events - what is happening during this
time?
The incoming client request messages are read on a messenger thread,
and then they get transferred into a queue for the main server event
loop. "all_read" means the message has been read off the wire (in the
messenger reader thread), and then "dispatched' means it the main
server loop thread has started work.
So a long wait in that period has nothing to do with the particular
message which is waiting, it just indicates that the server is
somewhat backed up.
Thanks for the clarification - the total op time does include the wait
between those two events, though - correct?
In this case, once processing started it took about 3
ms to get locks
(which IIRC probably means it had to queue and wait for something else
to happen) and then sent back a reply and queued up the journal event
(ie, sent off the write to disk) in another half a millisecond.
Anyway, I don't off-hand know of any reason things should have slowed
down (really, I'd expect them to be a little faster as a bit more
stuff got parallelized). Have the number of requests being processed
by the MDS changed? Are your clients noticing the apparent new
slowness?
The client workload should be roughly the same, though the number
being processed has dropped from over 6000/s to under 500/s,
presumably because of the increase in time to process each. Clients
are definitely noticing this increased latency.
Thanks,
Josh
> > I'm not sure what I'm looking for the in the MDS debug logs.
> >
> > We have a mix of clients from 12.2.x through 14.2.8; my plan was to
> > upgrade those pre-Nautilus clients this week. There is only a single
> > MDS rank with 1 backup. Other functions of this cluster - RBDs and RGW
> > - do not appear impacted so this looks limited to the MDS. I did not
> > observe this behavior after upgrading a dev cluster last month.
> >
> > Has anyone seen anything similar? Thanks for any assistance!
> > Josh
> > _______________________________________________
> > ceph-users mailing list -- ceph-users(a)ceph.io
> > To unsubscribe send an email to ceph-users-leave(a)ceph.io
> >
>