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?