From mboxrd@z Thu Jan 1 00:00:00 1970 From: "Jim Schutt" Subject: Re: cosd multi-second stalls cause "wrongly marked me down" Date: Fri, 8 Apr 2011 10:23:23 -0600 Message-ID: <4D9F367B.1070904@sandia.gov> References: <1297891508.25491.120.camel@sale659.sandia.gov> <75157CFDA63D45458FC47FB7BA6CB974@gmail.com> <1297893011.25491.124.camel@sale659.sandia.gov> Mime-Version: 1.0 Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 7bit Return-path: Received: from sentry-three.sandia.gov ([132.175.109.17]:41135 "EHLO sentry-three.sandia.gov" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752739Ab1DHQXr (ORCPT ); Fri, 8 Apr 2011 12:23:47 -0400 In-Reply-To: Sender: ceph-devel-owner@vger.kernel.org List-ID: To: Sage Weil Cc: Gregory Farnum , "ceph-devel@vger.kernel.org" Hi Sage, Sage Weil wrote: > On Wed, 16 Feb 2011, Jim Schutt wrote: >> On Wed, 2011-02-16 at 14:40 -0700, Gregory Farnum wrote: >>> On Wednesday, February 16, 2011 at 1:25 PM, Jim Schutt wrote: >>>> Hi, >>>> >>>> I've been testing v0.24.3 w/ 64 clients against >>>> 1 mon, 1 mds, 96 osds. Under heavy write load I >>>> see: >>>> [WRN] map e7 wrongly marked me down or wrong addr >>>> >>>> I was able to sort through the logs and discover that when >>>> this happens I have large gaps (10 seconds or more) in osd >>>> heatbeat processing. In those heartbeat gaps I've discovered >>>> long periods (5-15 seconds) where an osd logs nothing, even >>>> though I am running with debug osd/filestore/journal = 20. >>>> >>>> Is this a known issue? >>> You're running on btrfs? >> Yep. > > Are the cosd log files on the same btrfs volume as the btrfs data, or > elsewhere? The heartbeat thread takes some pains to avoid any locks that > may be contented and do avoid any disk io, so in theory a btrfs stall > shouldn't affect anything. We may have missed something.. do you have a > log showing this in action? In the end, after all the various things I've tried, I think that the root cause of this is relatively simple: I don't have enough CPU cycles available on my servers to do the amount of OSD processing required to service my client load, given the number of OSDs per server I'm running. With too much work and not enough cycles to do it, the one real-time component of Ceph, heartbeat processing, eventually must miss its deadline (no heartbeat "observed" in osd_heartbeat_grace seconds), since it requires work done by components (messengers, memory allocation system) that don't provide real-time guarantees. All of my experiences on this make perfect sense when viewed from this perspective. For example, when working with tcmalloc, I learned I could compile it with CXXFLAGS=-DTCMALLOC_LARGE_PAGES, which causes tcmalloc to allow objects up to 256k in its thread caches, rather than the default 32k. So I used that in combination with a 256k stripe width, on the theory that deallocating messages would mostly only interact with the thread cache, but it didn't help. When looking at thread stacks generated by my Mutex::LockOrAbort trick with a 5 sec wait to acquire the pipe_lock, I often saw threads waiting on the DoutLocker mutex. Since lots of Ceph debugging output happens with other locks being held, debugging might thus slow things down out of proportion to the processing required to generate the log messages. Yet, when I configured no debugging, I saw no improvement; it might be that things got a little worse. This now makes sense to me in light of my above hypothesis about not enough available CPU cycles - there's still too much work to do, even with no cycles spent on debugging output. What I didn't see very often in my thread stacks were stack frames from tcmalloc. This doesn't make sense to me if the memory allocation subsystem is the root cause of my problem, but makes perfect sense if there's not enough CPU cycles: not so much time is spent deallocating memory, so it is caught in the act less often by LockOrAbort. What finally seemed to help at avoiding missed heartbeats in my configuration was the following combination: turning off debugging, running with these throttling paramters: osd client message size cap = 14000000 client oc size = 14000000 client oc max dirty = 35000000 filestore queue max bytes = 35000000 journal queue max bytes = 35000000 ms dispatch throttle bytes = 14000000 objector inflight op bytes = 35000000 and using a 512k stripe width. Evidently keeping a relatively small amount of data in flight, in smaller chunks, allowed heartbeat processing to hit its mark more often. But, it only delayed things, it didn't solve the problem. This makes sense to me if the root cause is that I don't have enough CPU cycles available per OSD, because I didn't change the offered load. So, in the short term I guess I need to run fewer cosd instances per server. If my analysis above is correct, do you think anything can be gained by running the heartbeat and heartbeat dispatcher threads as SCHED_RR threads? Since tick() runs heartbeat_check(), that would also need to be SCHED_RR, or the heartbeats could arrive on time, but not checked until it was too late. Anyway, please let me know what you think of the above. Thanks -- Jim > > sage > >