Return-Path: X-Original-To: apmail-cassandra-user-archive@www.apache.org Delivered-To: apmail-cassandra-user-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 17A9A1106D for ; Wed, 18 Jun 2014 12:24:06 +0000 (UTC) Received: (qmail 22750 invoked by uid 500); 18 Jun 2014 12:23:58 -0000 Delivered-To: apmail-cassandra-user-archive@cassandra.apache.org Received: (qmail 22704 invoked by uid 500); 18 Jun 2014 12:23:58 -0000 Mailing-List: contact user-help@cassandra.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: user@cassandra.apache.org Delivered-To: mailing list user@cassandra.apache.org Received: (qmail 22694 invoked by uid 99); 18 Jun 2014 12:23:58 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 18 Jun 2014 12:23:58 +0000 X-ASF-Spam-Status: No, hits=1.5 required=5.0 tests=HTML_MESSAGE,RCVD_IN_DNSWL_LOW,SPF_PASS,T_REMOTE_IMAGE X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: domain of jlacefield@datastax.com designates 209.85.128.182 as permitted sender) Received: from [209.85.128.182] (HELO mail-ve0-f182.google.com) (209.85.128.182) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 18 Jun 2014 12:23:56 +0000 Received: by mail-ve0-f182.google.com with SMTP id oy12so701516veb.41 for ; Wed, 18 Jun 2014 05:23:32 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:mime-version:in-reply-to:references:date :message-id:subject:from:to:content-type; bh=5B4S//mj3mZrybv+l4uHPlS/6tp6Bj4pbi7bAr6eJdM=; b=fUBFP+RJ01YHVblpt2Dq6iQ9IdGh3joSKpnyOpur1wcSA1dsC0vA8EZV4wrWkfNMVI tfUocTOmVPXbMmnxZUuUU7KPYNpufc7AOYXvui5nr18mu1nHoy3rqVDwp72VLaVytCbc 93JIb+6uOQMWVZfCjJrwhG6sylvU71ROpjRB5u+nJ3JpgkWE+clMBp0PhrLtwb+9k7TX XLsj4UVxVBQbdavUIz7LdVI1sTlFfqfeQvLmo33q9tXr89NvwMIp/YTdxqbUjBW07Fit es84i9f48v4CvOJdog4BzT8/ZvmPSLypQ/0gDhKYFOhyAN5y7lszXh+CAt+zuFyX4Fya bC6A== X-Gm-Message-State: ALoCoQkoXwr18vCOyZn02TFRQq2MuWVIXfCCJa0qzRsrNIvwAmaAMez6osTnQgM66E9QFMi0MOzm MIME-Version: 1.0 X-Received: by 10.52.252.226 with SMTP id zv2mr20997886vdc.19.1403094211871; Wed, 18 Jun 2014 05:23:31 -0700 (PDT) Received: by 10.52.38.234 with HTTP; Wed, 18 Jun 2014 05:23:31 -0700 (PDT) In-Reply-To: References: <5702854404177521145@unknownmsgid> Date: Wed, 18 Jun 2014 08:23:31 -0400 Message-ID: Subject: Re: restarting node makes cpu load of the entire cluster to raise From: Jonathan Lacefield To: "user@cassandra.apache.org" Content-Type: multipart/alternative; boundary=001a1135ed2215f2b304fc1b5412 X-Virus-Checked: Checked by ClamAV on apache.org --001a1135ed2215f2b304fc1b5412 Content-Type: text/plain; charset=UTF-8 There are several long Parnew pauses that were recorded during startup. The young gen size looks large too, if I am reading that line correctly. Did you happen to overwrite the default settings for MAX_HEAP and/or NEW size in the cassandra-env.sh? The large you gen size, set via the env.sh file, could be causing longer than typical pauses, which could make your node appear to be unresponsive and have high CPU (CPU for the ParNew GC event). Check out this one - INFO 11:42:51,939 GC for ParNew: 2148 ms for 2 collections, 1256307568 used; max is 8422162432 That is a 2 second GC pause. That's very high for ParNew. We typically want a lot of tiny ParNew events as opposed to large, and less frequent, ParNew events. One other thing that was noticed, was that the node had a lot of log segment replay's during startup. You could avoid these, or minimize them, by preforming a flush or drain before stopping and starting Cassandra. This will flush memtables and clear your log segments. Jonathan Lacefield Solutions Architect, DataStax (404) 822 3487 On Wed, Jun 18, 2014 at 8:05 AM, Alain RODRIGUEZ wrote: > A simple restart of a node with no changes give this result. > > logs output : https://gist.github.com/arodrime/db9ab152071d1ad39f26 > > Here are some screenshot: > > - htop from a node immediatly after restarting > - opscenter ring view (show load cpu on all nodes) > - opscenter dashboard shows the impact of a restart on latency (can affect > writes or reads, it depends, reaction seems to be quite random) > > > 2014-06-18 13:35 GMT+02:00 Jonathan Lacefield : > > Hello >> >> Have you checked the log file to see what's happening during startup >> ? What caused the rolling restart? Did you preform an upgrade or >> change a config? >> >> > On Jun 18, 2014, at 5:40 AM, Alain RODRIGUEZ >> wrote: >> > >> > Hi guys >> > >> > Using 1.2.11, when I try to rolling restart the cluster, any node I >> restart makes the whole cluster cpu load to increase, reaching a "red" >> state in opscenter (load from 3-4 to 20+). This happens once the node is >> back online. >> > >> > The restarted node uses 100 % cpu for 5 - 10 min and sometimes drop >> mutations. >> > >> > I have tried to throttle handoff to 256 (instead of 1024), yet it >> doesn't seems to help that much. >> > >> > Disks are not the bottleneck. PARNEW GC increase a bit, but nothing >> problematic I think. >> > >> > Basically, what could be happening on node restart ? What is taking >> that much CPU on every machine ? There is no steal or iowait. >> > >> > What can I try to tune ? >> > >> > > --001a1135ed2215f2b304fc1b5412 Content-Type: text/html; charset=UTF-8 Content-Transfer-Encoding: quoted-printable
There are several long Parnew pauses that were recorded du= ring startup. =C2=A0The young gen size looks large too, if I am reading tha= t line correctly. =C2=A0Did you happen to overwrite the default settings fo= r MAX_HEAP and/or NEW size in the cassandra-env.sh? =C2=A0The large you gen= size, set via the env.sh file, could be causing longer than typical pauses= , which could make your node appear to be unresponsive and have high CPU (C= PU for the ParNew GC event). =C2=A0

Check out this one - INFO 11:42:51,939 GC for ParNew: 2148 m= s for 2 collections, 1256307568 used; max is 8422162432
That is a= 2 second GC pause. =C2=A0That's very high for ParNew. =C2=A0We typical= ly want a lot of tiny ParNew events as opposed to large, and less frequent,= ParNew events.

One other thing that was noticed, was that the node had= a lot of log segment replay's during startup. =C2=A0You could avoid th= ese, or minimize them, by preforming a flush or drain before stopping and s= tarting Cassandra. =C2=A0This will flush memtables and clear your log segme= nts. =C2=A0



Jonathan Lacefield
Solutions Architect, Dat= aStax
(404) 822 3487


=



On Wed, Jun 18, 2014 at 8:05 AM, Alain R= ODRIGUEZ <arodrime@gmail.com> wrote:
A simple restart of a node with no changes give this resul= t.


Here are some screenshot:

- ht= op from a node immediatly after restarting
- opscenter ring view = (show load cpu on all nodes)
- opscenter dashboard shows the impa= ct of a restart on latency (can affect writes or reads, it depends, reactio= n seems to be quite random)


2014-06-18 13= :35 GMT+02:00 Jonathan Lacefield <jlacefield@datastax.com>:

Hello

=C2=A0 Have you checked the log file to see what's happening during sta= rtup
? =C2=A0 What caused the rolling restart? =C2=A0Did you preform an upgrade = or
change a config?

> On Jun 18, 2014, at 5:40 AM, Alain RODRIGUEZ <arodrime@gmail.com> wrote:
>
> Hi guys
>
> Using 1.2.11, when I try to rolling restart the cluster, any node I re= start makes the whole cluster cpu load to increase, reaching a "red&qu= ot; state in opscenter (load from 3-4 to 20+). This happens once the node i= s back online.
>
> The restarted node uses 100 % cpu for 5 - 10 min and sometimes drop mu= tations.
>
> I have tried to throttle handoff to 256 (instead of 1024), yet it does= n't seems to help that much.
>
> Disks are not the bottleneck. PARNEW GC increase a bit, but nothing pr= oblematic I think.
>
> Basically, what could be happening on node restart ? What is taking th= at much CPU on every machine ? There is no steal or iowait.
>
> What can I try to tune ?
>


--001a1135ed2215f2b304fc1b5412--