RE: osd suicide timeout

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Greg --

Not sure how to tell whether rebalancing occurred at that time.
I do see in other osd logs complaints that they do not get a reply from
osd.8 starting around 15:52 on that day.

I see the deep-scrub of pool 14 but that was almost 30 minutes earlier.

-- Tom


> -----Original Message-----
> From: Gregory Farnum [mailto:greg@xxxxxxxxxxx]
> Sent: Monday, July 13, 2015 11:45 AM
> To: Deneau, Tom
> Cc: ceph-devel
> Subject: Re: osd suicide timeout
> 
> heartbeat_map reset_timeout 'OSD::osd_op_tp thread 0x3ff6eb0efd0' had suicide
> timed out after 150
> 
> So that's the OSD's "op thread", which is the one that does most of the work.
> You often see the FileStore::op_tp when it's the disk or filesystem breaking,
> but I do see the line
> 
> waiting 51 > 50 ops || 57248008 > 104857600
> 
> which leaves me feeling pretty confident that the disk is just getting more
> work than it can keep up with. It looks like there was some rebalancing
> happening around this time?
> -Greg
> 
> 
> 
> On Mon, Jul 13, 2015 at 5:04 PM, Deneau, Tom <tom.deneau@xxxxxxx> wrote:
> > Greg --
> >
> > Thanks.  I put the osd.log file at
> >
> > https://drive.google.com/file/d/0B_rfwWh40kPwQjZ3OXdjLUZNRVU/view?usp=
> > sharing
> >
> > I noticed the following from journalctl output around that time, so other
> nodes were complaining they could not reach osd.8.
> >
> > Jul 09 15:53:04 seattle-04-ausisv bash[8486]: 2015-07-09
> > 15:53:03.905386 3ffa0d9efd0 -1 osd.9 2487 heartbeat_check: no reply
> > from osd.8 since back 2015-07-09 15:52:43.256581 front 2015-07-09
> > 15:52:43.256581 (cutoff 2015-07-09 15:52:43.905384) Jul 09 15:53:06
> > seattle-04-ausisv bash[1060]: 2015-07-09 15:53:06.784069 3ff916fefd0
> > -1 osd.7 2487 heartbeat_check: no reply from osd.8 since back
> > 2015-07-09 15:52:46.474273 front 2015-07-09 15:52:46.474273 (cutoff
> > 2015-07-09 15:52:46.784066)
> >
> > and here is some sar data for the disk that osd.8 was controlling
> > (sde1=journal partition, sde2=data partition)
> >
> > 03:40:02 PM       DEV       tps  rd_sec/s  wr_sec/s  avgrq-sz  avgqu-sz
> await     svctm     %util
> > 03:50:17 PM      sde1      9.67      0.00  19046.40   1970.32      0.35
> 35.86     30.62     29.60
> > 03:50:17 PM      sde2     60.47   1524.27  14597.67    266.63     24.45
> 404.30      8.54     51.67
> > 03:50:32 PM      sde1     12.13      0.00  18158.93   1496.62      0.25
> 20.66     17.58     21.33
> > 03:50:32 PM      sde2     28.00   1550.93  17958.33    696.76     10.54
> 376.50     13.52     37.87
> > 03:50:47 PM      sde1     12.73      0.00  25446.40   1998.41      0.31
> 24.19     22.30     28.40
> > 03:50:47 PM      sde2     51.60    338.67  18091.73    357.18     13.05
> 252.91      8.02     41.40
> > 03:51:02 PM      sde1     12.27      0.00  18790.40   1531.83      0.31
> 25.33     18.53     22.73
> > 03:51:02 PM      sde2     33.13   2635.20  18026.67    623.60      5.02
> 151.57     10.99     36.40
> > 03:51:17 PM      sde1     10.13      0.00  14557.87   1436.63      0.16
> 16.18     12.76     12.93
> > 03:51:17 PM      sde2     46.73   1107.73  12067.00    281.91      8.55
> 182.88      5.46     25.53
> > 03:51:32 PM      sde1     11.93      0.00  18594.13   1558.17      0.35
> 29.27     16.42     19.60
> > 03:51:32 PM      sde2     22.20    555.20  18834.33    873.40      4.24
> 191.08     13.51     30.00
> > 03:51:47 PM      sde1     18.00      0.00  13926.40    773.69      0.19
> 10.78     10.07     18.13
> > 03:51:47 PM      sde2     47.27   1652.80  10775.53    262.94     12.24
> 259.01      6.66     31.47
> > 03:52:02 PM      sde1     21.60      0.00  10845.87    502.12      0.24
> 11.08      9.75     21.07
> > 03:52:02 PM      sde2     34.33   1652.80   9089.13    312.87      7.43
> 216.41      8.45     29.00
> > 03:52:17 PM      sde1     19.87      0.00  20198.40   1016.70      0.33
> 16.85     13.46     26.73
> > 03:52:17 PM      sde2     35.60   2752.53  16355.53    536.74     11.90
> 333.33     10.90     38.80
> > 03:52:32 PM      sde1     22.54      0.00   8434.04    374.18      0.15
> 6.67      6.17     13.90
> > 03:52:32 PM      sde2     35.84   2738.30   4586.30    204.38      2.01
> 28.11      6.53     23.40
> > 03:52:47 PM      sde1      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00
> > 03:52:47 PM      sde2     13.37     35.83   1101.80     85.09      1.87
> 218.65      5.75      7.69
> > 03:53:02 PM      sde1      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00
> > 03:53:02 PM      sde2      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00
> > 03:53:17 PM      sde1      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00
> > 03:53:17 PM      sde2      0.13      0.00      0.20      1.50      0.00
> 20.00     20.00      0.27
> > 03:53:32 PM      sde1      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00
> > 03:53:32 PM      sde2      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00
> > 03:53:47 PM      sde1      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00
> > 03:53:47 PM      sde2      0.13      0.00      0.20      1.50      0.00
> 5.00      5.00      0.07
> > 03:54:02 PM      sde1      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00
> > 03:54:02 PM      sde2      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00
> > 03:54:17 PM      sde1      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00
> > 03:54:17 PM      sde2      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00
> > 03:54:32 PM      sde1      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00
> > 03:54:32 PM      sde2      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00
> >
> > -- Tom
> >
> >> -----Original Message-----
> >> From: Gregory Farnum [mailto:greg@xxxxxxxxxxx]
> >> Sent: Monday, July 13, 2015 5:07 AM
> >> To: Deneau, Tom
> >> Cc: ceph-devel
> >> Subject: Re: osd suicide timeout
> >>
> >> On Fri, Jul 10, 2015 at 10:45 PM, Deneau, Tom <tom.deneau@xxxxxxx> wrote:
> >> > I have an osd log file from an osd that hit a suicide timeout (with
> >> > the
> >> previous 10000 events logged).
> >> > (On this node I have also seen this suicide timeout happen once
> >> > before and
> >> also a sync_entry timeout.
> >> >
> >> > I can see that 6 minutes or so before that osd died, other osds on
> >> > the same node were logging messages such as
> >> >     heartbeat_check: no reply from osd.8 so it appears that osd8
> >> > stopped responding quite some time before it died.
> >>
> >> It does this deliberately when its disk threads look like they might
> >> be stuck.
> >>
> >> >
> >> > I'm wondering if there is enough information in the osd8 log file
> >> > to deduce
> >> why osd 8 stopped responding?
> >> > I don't know enough to figure it out myself.
> >> >
> >> > Is there any expert who would be willing to take a look at the log file?
> >>
> >> The logs will have a backtrace in them; if you can include that and
> >> the last hundred lines or so prior in a pastebin that you email the
> >> list with several people can give you a pretty good idea of what's going
> on.
> >>
> >> In general though, it's just going to be that the disk can't keep up
> >> with the load being applied to it. That could be because it's
> >> failing, or because you're pushing too much work on to it in some fashion.
> >> -Greg
��.n��������+%������w��{.n����z��u���ܨ}���Ơz�j:+v�����w����ޙ��&�)ߡ�a����z�ޗ���ݢj��w�f




[Index of Archives]     [CEPH Users]     [Ceph Large]     [Information on CEPH]     [Linux BTRFS]     [Linux USB Devel]     [Video for Linux]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]
  Powered by Linux