Glad to help!
On Tue, Feb 12, 2019 at 4:55 PM Massimo Sgaravatto
<massimo.sgaravatto@xxxxxxxxx> wrote:
>
> Thanks a lot Brad !
>
> The problem is indeed in the network: we moved the OSD nodes back to the "old" switches and the problem disappeared.
>
> Now we have to figure out what is wrong/misconfigured with the new switch: we would try to replicate the problem, possibly without a ceph deployment ...
>
> Thanks again for your help !
>
> Cheers, Massimo
>
> On Sun, Feb 10, 2019 at 12:07 AM Brad Hubbard <bhubbard@xxxxxxxxxx> wrote:
>>
>> The log ends at
>>
>> $ zcat ceph-osd.5.log.gz |tail -2
>> 2019-02-09 07:37:00.022534 7f5fce60d700 1 --
>> 192.168.61.202:6816/157436 >> - conn(0x56308edcf000 :6816
>> s=STATE_ACCEPTING pgs=0 cs=0 l=0)._process_connection sd=296 -
>>
>> The last two messages are outbound to 192.168.222.204 and there are no
>> further messages between these two hosts (other than osd_pings) in the
>> log.
>>
>> $ zcat ceph-osd.5.log.gz |gawk
>> '!/osd_ping/&&/192.168.222.202/&&/192.168.222.204/&&/07:29:3/'|tail -5
>> 2019-02-09 07:29:34.267744 7f5fcee0e700 1 --
>> 192.168.222.202:6816/157436 <== osd.29 192.168.222.204:6804/4159520
>> 1946 ==== rep_scrubmap(8.2bc e1205735 from shard 29) v2 ==== 40+0+1492
>> (3695125937 0 2050362985) 0x563090674d80 con 0x56308bf61000
>> 2019-02-09 07:29:34.375223 7f5faf4b4700 1 --
>> 192.168.222.202:6816/157436 --> 192.168.222.204:6804/4159520 --
>> replica_scrub(pg:
>> 8.2bc,from:0'0,to:0'0,epoch:1205833/1205735,start:8:3d4e6145:::rbd_data.35f46d19abe4ed.00000000000077a4:0,end:8:3d4e6916:::rbd_data.a6dc2425de9600.000000000006249c:0,chunky:1,deep:0,version:9,allow_preemption:1,priority=5)
>> v9 -- 0x56308bdf2000 con 0
>> 2019-02-09 07:29:34.378535 7f5fcee0e700 1 --
>> 192.168.222.202:6816/157436 <== osd.29 192.168.222.204:6804/4159520
>> 1947 ==== rep_scrubmap(8.2bc e1205735 from shard 29) v2 ==== 40+0+1494
>> (3695125937 0 865217733) 0x563092d90900 con 0x56308bf61000
>> 2019-02-09 07:29:34.415868 7f5faf4b4700 1 --
>> 192.168.222.202:6816/157436 --> 192.168.222.204:6804/4159520 --
>> osd_repop(client.171725953.0:404377591 8.9b e1205833/1205735
>> 8:d90adab6:::rbd_data.c47f3c390c8495.000000000001934a:head v
>> 1205833'4767322) v2 -- 0x56308ca42400 con 0
>> 2019-02-09 07:29:34.486296 7f5faf4b4700 1 --
>> 192.168.222.202:6816/157436 --> 192.168.222.204:6804/4159520 --
>> replica_scrub(pg:
>> 8.2bc,from:0'0,to:0'0,epoch:1205833/1205735,start:8:3d4e6916:::rbd_data.a6dc2425de9600.000000000006249c:0,end:8:3d4e7434:::rbd_data.47c1b437840214.000000000003c594:0,chunky:1,deep:0,version:9,allow_preemption:1,priority=5)
>> v9 -- 0x56308e565340 con 0
>>
>> I'd be taking a good, hard look at the network, yes.
>>
>> On Sat, Feb 9, 2019 at 6:33 PM Massimo Sgaravatto
>> <massimo.sgaravatto@xxxxxxxxx> wrote:
>> >
>> > Thanks for your feedback !
>> >
>> > I increased debug_ms to 1/5.
>> >
>> > This is another slow request (full output from 'ceph daemon osd.5 dump_historic_ops' for this event is attached):
>> >
>> >
>> > {
>> > "description": "osd_op(client.171725953.0:404377591 8.9b 8:d90adab6:
>> > ::rbd_data.c47f3c390c8495.000000000001934a:head [set-alloc-hint object_size 4194
>> > 304 write_size 4194304,write 1413120~122880] snapc 0=[] ondisk+write+known_if_re
>> > directed e1205833)",
>> > "initiated_at": "2019-02-09 07:29:34.404655",
>> > "age": 387.914193,
>> > "duration": 340.224154,
>> > "type_data": {
>> > "flag_point": "commit sent; apply or cleanup",
>> > "client_info": {
>> > "client": "client.171725953",
>> > "client_addr": "192.168.61.66:0/4056439540",
>> > "tid": 404377591
>> > },
>> > "events": [
>> > {
>> > "time": "2019-02-09 07:29:34.404655",
>> > "event": "initiated"
>> > },
>> > ....
>> > ....
>> > {
>> > "time": "2019-02-09 07:29:34.416752",
>> > "event": "op_applied"
>> > },
>> > {
>> > "time": "2019-02-09 07:29:34.417200",
>> > "event": "sub_op_commit_rec from 14"
>> > },
>> > {
>> > "time": "2019-02-09 07:35:14.628724",
>> > "event": "sub_op_commit_rec from 29"
>> > },
>> >
>> > osd.5 has IP 192.168.222.202
>> > osd.14 has IP 192.168.222.203
>> > osd.29 has IP 192.168.222.204
>> >
>> >
>> > Grepping using that client id from osd.5 log as far as I can understand (please correct me if my debugging is completely wrong) the request to 5 and 14 is sent at 07:29:34:
>> >
>> > 2019-02-09 07:29:34.415808 7f5faf4b4700 1 -- 192.168.222.202:6816/157436 --> 192.168.222.203:6811/158495 -- osd_repop(client.171725953.0:404377591 8.9b e1205833/1205735 8:d90ada\
>> > b6:::rbd_data.c47f3c390c8495.000000000001934a:head v 1205833'4767322) v2 -- 0x56307bb61e00 con 0
>> > 2019-02-09 07:29:34.415868 7f5faf4b4700 1 -- 192.168.222.202:6816/157436 --> 192.168.222.204:6804/4159520 -- osd_repop(client.171725953.0:404377591 8.9b e1205833/1205735 8:d90ad\
>> > ab6:::rbd_data.c47f3c390c8495.000000000001934a:head v 1205833'4767322) v2 -- 0x56308ca42400 con 0
>> > 2019-02-09 07:29:34.417132 7f5fcf60f700 1 -- 192.168.222.202:6816/157436 <== osd.14 192.168.222.203:6811/158495 11242 ==== osd_repop_reply(client.171725953.0:404377591 8.9b e120\
>> > 5833/1205735) v2 ==== 111+0+0 (634943494 0 0) 0x563090642780 con 0x56308bbd0000
>> >
>> > The answer from 14 arrives immediately:
>> >
>> > 2019-02-09 07:29:34.417132 7f5fcf60f700 1 -- 192.168.222.202:6816/157436 <== osd.14 192.168.222.203:6811/158495 11242 ==== osd_repop_reply(client.171725953.0:404377591 8.9b e120\
>> > 5833/1205735) v2 ==== 111+0+0 (634943494 0 0) 0x563090642780 con 0x56308bbd0000
>> >
>> > while the one from 29 arrives only at 7.35:
>> >
>> > 2019-02-09 07:35:14.628614 7f5fcee0e700 1 -- 192.168.222.202:6816/157436 <== osd.29 192.168.222.204:6804/4159520 1952 ==== osd_repop_reply(client.171725953.0:404377591 8.9b e120\
>> > 5833/1205735) v2 ==== 111+0+0 (3804866849 0 0) 0x56308f3f2a00 con 0x56308bf61000
>> >
>> >
>> > In osd.29 log it looks like the request only arrives at 07.35 (and it promptly replies):
>> >
>> > 2019-02-09 07:35:14.627462 7f99972cc700 1 -- 192.168.222.204:6804/4159520 <== osd.5 192.168.222.202:6816/157436 2527 ==== osd_repop(client.171725953.0:404377591 8.9b e1205833/1205735) v2 ==== 1050+0+123635 (1225076790 0 171428115) 0x5610f5128a00 con 0x5610fc5bf000
>> > 2019-02-09 07:35:14.628343 7f998d6d4700 1 -- 192.168.222.204:6804/4159520 --> 192.168.222.202:6816/157436 -- osd_repop_reply(client.171725953.0:404377591 8.9b e1205833/1205735 ondisk, result = 0) v2 -- 0x5610f4a51180 con 0
>> >
>> >
>> > Network problems ?
>> >
>> >
>> > Full logs for the 3 relevant OSDs (just for that time period) is at: https://drive.google.com/drive/folders/1TG5MomMJsqVbsuFosvYokNptLufxOnPY?usp=sharing
>> >
>> >
>> >
>> > Thanks again !
>> > Cheers, Massimo
>> >
>> >
>> >
>> > On Fri, Feb 8, 2019 at 11:50 PM Brad Hubbard <bhubbard@xxxxxxxxxx> wrote:
>> >>
>> >> Try capturing another log with debug_ms turned up. 1 or 5 should be Ok
>> >> to start with.
>> >>
>> >> On Fri, Feb 8, 2019 at 8:37 PM Massimo Sgaravatto
>> >> <massimo.sgaravatto@xxxxxxxxx> wrote:
>> >> >
>> >> > Our Luminous ceph cluster have been worked without problems for a while, but in the last days we have been suffering from continuous slow requests.
>> >> >
>> >> > We have indeed done some changes in the infrastructure recently:
>> >> >
>> >> > - Moved OSD nodes to a new switch
>> >> > - Increased pg nums for a pool, to have about ~ 100 PGs/OSD (also because we have to install new OSDs in the cluster). The output of 'ceph osd df' is attached.
>> >> >
>> >> > The problem could also be due to some ''bad' client, but in the log I don't see a clear "correlation" with specific clients or images for such blocked requests.
>> >> >
>> >> > I also tried to update to latest luminous release and latest CentOS7, but this didn't help.
>> >> >
>> >> >
>> >> >
>> >> > Attached you can find the detail of one of such slow operations which took about 266 secs (output from 'ceph daemon osd.11 dump_historic_ops').
>> >> > So as far as I can understand from these events:
>> >> > {
>> >> > "time": "2019-02-08 10:26:25.651728",
>> >> > "event": "op_commit"
>> >> > },
>> >> > {
>> >> > "time": "2019-02-08 10:26:25.651965",
>> >> > "event": "op_applied"
>> >> > },
>> >> >
>> >> > {
>> >> > "time": "2019-02-08 10:26:25.653236",
>> >> > "event": "sub_op_commit_rec from 33"
>> >> > },
>> >> > {
>> >> > "time": "2019-02-08 10:30:51.890404",
>> >> > "event": "sub_op_commit_rec from 23"
>> >> > },
>> >> >
>> >> > the problem seems with the "sub_op_commit_rec from 23" event which took too much.
>> >> > So the problem is that the answer from OSD 23 took to much ?
>> >> >
>> >> >
>> >> > In the logs of the 2 OSD (11 and 23)in that time frame (attached) I can't find anything useful.
>> >> > When the problem happened the load and the usage of memory was not high in the relevant nodes.
>> >> >
>> >> >
>> >> > Any help to debug the issue is really appreciated ! :-)
>> >> >
>> >> > Thanks, Massimo
>> >> >
>> >> > _______________________________________________
>> >> > ceph-users mailing list
>> >> > ceph-users@xxxxxxxxxxxxxx
>> >> > http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
>> >>
>> >>
>> >>
>> >> --
>> >> Cheers,
>> >> Brad
>>
>>
>>
>> --
>> Cheers,
>> Brad
--
Cheers,
Brad
_______________________________________________
ceph-users mailing list
ceph-users@xxxxxxxxxxxxxx
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
