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 D78A110BF6 for ; Tue, 16 Dec 2014 21:13:07 +0000 (UTC) Received: (qmail 29770 invoked by uid 500); 16 Dec 2014 21:13:05 -0000 Delivered-To: apmail-cassandra-user-archive@cassandra.apache.org Received: (qmail 29730 invoked by uid 500); 16 Dec 2014 21:13:05 -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 29720 invoked by uid 99); 16 Dec 2014 21:13:05 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 16 Dec 2014 21:13:05 +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 (athena.apache.org: domain of rsvihla@datastax.com designates 209.85.213.47 as permitted sender) Received: from [209.85.213.47] (HELO mail-yh0-f47.google.com) (209.85.213.47) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 16 Dec 2014 21:13:01 +0000 Received: by mail-yh0-f47.google.com with SMTP id f73so6519596yha.6 for ; Tue, 16 Dec 2014 13:12:40 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=datastax.com; s=google; h=mime-version:in-reply-to:references:date:message-id:subject:from:to :content-type; bh=3u69fyib2tKcASJTJvReSZBhMlm+4sImO5uopeXkl7c=; b=YfDn2o8/Yp0SdL/0ralarLDD9m6O1UhChggmN21d22GK2NJl2RFGKVSjJ3m4INqe7/ zrZLb2n+k6qdnOJoQtgGp9HLxyeb5e2Fn04v4++E4DmBpxt66Ha5Baj5NAM3XphA0GQT sHwg72vpAQvC+oVd2sMk2484DgML0lKyF6yro= 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=3u69fyib2tKcASJTJvReSZBhMlm+4sImO5uopeXkl7c=; b=VcRMs39h7qS5PRT424ruLrU30bmKSg1stlrdVPTRE3tOfYsKQ4FGPNzCitw8OE3Y1c oQukkokP5pD8dgoW932xtpODIXbgXrBUg5vLhOF9RZSrsjJ39XojDa9HBR4SGV/iF1Q+ AAqWvTBXo8z6YGRYd4i2+T3nAmoP8vv5xi0ZjgKQFELqL6MGP8ypoq0EdDMPEouJFh+j AaVeA/hXldob1TsXZocheRXGAjrVmQN2MEE39preGvIM6lEW1hl37GeaeJEGmFf00gSJ aSvyFRqSTVI0skmWpXqBtJ6o5yI2V6v7iY4PQ2fCi8diOYJa+PtOXirUiN62d3uH8hys QbJA== X-Gm-Message-State: ALoCoQl9DVpybFxsrp8zkcSXSuwhbh16pqMtVapMe51JfsS3NMcdTXrW8oS/JRFt1yFEWYHkwLLJ MIME-Version: 1.0 X-Received: by 10.170.42.151 with SMTP id 145mr31893028ykk.74.1418764360416; Tue, 16 Dec 2014 13:12:40 -0800 (PST) Received: by 10.170.216.2 with HTTP; Tue, 16 Dec 2014 13:12:40 -0800 (PST) In-Reply-To: References: Date: Tue, 16 Dec 2014 15:12:40 -0600 Message-ID: Subject: Re: 100% CPU utilization, ParNew and never completing compactions From: Ryan Svihla To: user@cassandra.apache.org Content-Type: multipart/alternative; boundary=001a1138e9deb91879050a5bd144 X-Virus-Checked: Checked by ClamAV on apache.org --001a1138e9deb91879050a5bd144 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable So heap of that size without some tuning will create a number of problems (high cpu usage one of them), I suggest either 8GB heap and 400mb parnew (which I'd only set that low for that low cpu count) , or attempt the tunings as indicated in https://issues.apache.org/jira/browse/CASSANDRA-815= 0 On Tue, Dec 16, 2014 at 3:06 PM, Arne Claassen wrote: > > Changed the 15GB node to 25GB heap and the nice CPU is down to ~20% now. > Checked my dev cluster to see if the ParNew log entries are just par for > the course, but not seeing them there. However, both have the following > every 30 seconds: > > DEBUG [BatchlogTasks:1] 2014-12-16 21:00:44,898 BatchlogManager.java (lin= e > 165) Started replayAllFailedBatches > DEBUG [MemtablePostFlusher:1] 2014-12-16 21:00:44,899 > ColumnFamilyStore.java (line 866) forceFlush requested but everything is > clean in batchlog > DEBUG [BatchlogTasks:1] 2014-12-16 21:00:44,899 BatchlogManager.java (lin= e > 200) Finished replayAllFailedBatches > > Is that just routine scheduled house-keeping or a sign of something else? > > On Tue, Dec 16, 2014 at 12:52 PM, Arne Claassen wrote= : >> >> Sorry, I meant 15GB heap on the one machine that has less nice CPU% now. >> The others are 6GB >> >> On Tue, Dec 16, 2014 at 12:50 PM, Arne Claassen >> wrote: >>> >>> AWS r3.xlarge, 30GB, but only using a Heap of 10GB, new 2GB because we >>> might go c3.2xlarge instead if CPU is more important than RAM >>> Storage is optimized EBS SSD (but iostat shows no real IO going on) >>> Each node only has about 10GB with ownership of 67%, 64.7% & 68.3%. >>> >>> The node on which I set the Heap to 10GB from 6GB the utlilization has >>> dropped to 46%nice now, but the ParNew log messages still continue at t= he >>> same pace. I'm gonna up the HEAP to 20GB for a bit, see if that brings = that >>> nice CPU further down. >>> >>> No TombstoneOverflowingExceptions. >>> >>> On Tue, Dec 16, 2014 at 11:50 AM, Ryan Svihla >>> wrote: >>>> >>>> What's CPU, RAM, Storage layer, and data density per node? Exact heap >>>> settings would be nice. In the logs look for TombstoneOverflowingExcep= tion >>>> >>>> >>>> On Tue, Dec 16, 2014 at 1:36 PM, Arne Claassen >>>> wrote: >>>>> >>>>> I'm running 2.0.10. >>>>> >>>>> The data is all time series data and as we change our pipeline, we've >>>>> been periodically been reprocessing the data sources, which causes ea= ch >>>>> time series to be overwritten, i.e. every row per partition key is de= leted >>>>> and re-written, so I assume i've been collecting a bunch of tombstone= s. >>>>> >>>>> Also, the presence of the ever present and never completing compactio= n >>>>> types, i assumed were an artifact of tombstoning, but i fully admit t= o >>>>> conjecture based on about ~20 blog posts and stackoverflow questions = i've >>>>> surveyed. >>>>> >>>>> I doubled the Heap on one node and it changed nothing regarding the >>>>> load or the ParNew log statements. New Generation Usage is 50%, Eden = itself >>>>> is 56%. >>>>> >>>>> Anything else i should look at and report, let me know. >>>>> >>>>> On Tue, Dec 16, 2014 at 11:14 AM, Jonathan Lacefield < >>>>> jlacefield@datastax.com> wrote: >>>>>> >>>>>> Hello, >>>>>> >>>>>> What version of Cassandra are you running? >>>>>> >>>>>> If it's 2.0, we recently experienced something similar with 8447 >>>>>> [1], which 8485 [2] should hopefully resolve. >>>>>> >>>>>> Please note that 8447 is not related to tombstones. Tombstone >>>>>> processing can put a lot of pressure on the heap as well. Why do you= think >>>>>> you have a lot of tombstones in that one particular table? >>>>>> >>>>>> [1] https://issues.apache.org/jira/browse/CASSANDRA-8447 >>>>>> [2] https://issues.apache.org/jira/browse/CASSANDRA-8485 >>>>>> >>>>>> Jonathan >>>>>> >>>>>> [image: datastax_logo.png] >>>>>> >>>>>> Jonathan Lacefield >>>>>> >>>>>> Solution Architect | (404) 822 3487 | jlacefield@datastax.com >>>>>> >>>>>> [image: linkedin.png] [imag= e: >>>>>> facebook.png] [image: >>>>>> twitter.png] [image: g+.png] >>>>>> >>>>>> >>>>>> >>>>>> On Tue, Dec 16, 2014 at 2:04 PM, Arne Claassen >>>>>> wrote: >>>>>>> >>>>>>> I have a three node cluster that has been sitting at a load of 4 >>>>>>> (for each node), 100% CPI utilization (although 92% nice) for that = last 12 >>>>>>> hours, ever since some significant writes finished. I'm trying to d= etermine >>>>>>> what tuning I should be doing to get it out of this state. The debu= g log is >>>>>>> just an endless series of: >>>>>>> >>>>>>> DEBUG [ScheduledTasks:1] 2014-12-16 19:03:35,042 GCInspector.java >>>>>>> (line 118) GC for ParNew: 166 ms for 10 collections, 4400928736 use= d; max >>>>>>> is 8000634880 >>>>>>> DEBUG [ScheduledTasks:1] 2014-12-16 19:03:36,043 GCInspector.java >>>>>>> (line 118) GC for ParNew: 165 ms for 10 collections, 4440011176 use= d; max >>>>>>> is 8000634880 >>>>>>> DEBUG [ScheduledTasks:1] 2014-12-16 19:03:37,043 GCInspector.java >>>>>>> (line 118) GC for ParNew: 135 ms for 8 collections, 4402220568 >>>>>>> used; max is 8000634880 >>>>>>> >>>>>>> iostat shows virtually no I/O. >>>>>>> >>>>>>> Compaction may enter into this, but i don't really know what to mak= e >>>>>>> of compaction stats since they never change: >>>>>>> >>>>>>> [root@cassandra-37919c3a ~]# nodetool compactionstats >>>>>>> pending tasks: 10 >>>>>>> compaction type keyspace table >>>>>>> completed total unit progress >>>>>>> Compaction mediamedia_tracks_raw >>>>>>> 271651482 563615497 bytes 48.20% >>>>>>> Compaction mediamedia_tracks_raw >>>>>>> 30308910 21676695677 bytes 0.14% >>>>>>> Compaction mediamedia_tracks_raw >>>>>>> 1198384080 1815603161 bytes 66.00% >>>>>>> Active compaction remaining time : 0h22m24s >>>>>>> >>>>>>> 5 minutes later: >>>>>>> >>>>>>> [root@cassandra-37919c3a ~]# nodetool compactionstats >>>>>>> pending tasks: 9 >>>>>>> compaction type keyspace table >>>>>>> completed total unit progress >>>>>>> Compaction mediamedia_tracks_raw >>>>>>> 271651482 563615497 bytes 48.20% >>>>>>> Compaction mediamedia_tracks_raw >>>>>>> 30308910 21676695677 bytes 0.14% >>>>>>> Compaction mediamedia_tracks_raw >>>>>>> 1198384080 1815603161 bytes 66.00% >>>>>>> Active compaction remaining time : 0h22m24s >>>>>>> >>>>>>> Sure the pending tasks went down by one, but the rest is identical. >>>>>>> media_tracks_raw likely has a bunch of tombstones (can't figure out= how to >>>>>>> get stats on that). >>>>>>> >>>>>>> Is this behavior something that indicates that i need more Heap, >>>>>>> larger new generation? Should I be manually running compaction on t= ables >>>>>>> with lots of tombstones? >>>>>>> >>>>>>> Any suggestions or places to educate myself better on performance >>>>>>> tuning would be appreciated. >>>>>>> >>>>>>> arne >>>>>>> >>>>>> >>>> >>>> -- >>>> >>>> [image: datastax_logo.png] >>>> >>>> Ryan Svihla >>>> >>>> Solution Architect >>>> >>>> [image: twitter.png] [image: >>>> linkedin.png] >>>> >>>> DataStax is the fastest, most scalable distributed database technology= , >>>> delivering Apache Cassandra to the world=E2=80=99s most innovative ent= erprises. >>>> Datastax is built to be agile, always-on, and predictably scalable to = any >>>> size. With more than 500 customers in 45 countries, DataStax is the >>>> database technology and transactional backbone of choice for the world= s >>>> most innovative companies such as Netflix, Adobe, Intuit, and eBay. >>>> >>>> --=20 [image: datastax_logo.png] Ryan Svihla Solution Architect [image: twitter.png] [image: linkedin.png] DataStax is the fastest, most scalable distributed database technology, delivering Apache Cassandra to the world=E2=80=99s most innovative enterpri= ses. Datastax is built to be agile, always-on, and predictably scalable to any size. With more than 500 customers in 45 countries, DataStax is the database technology and transactional backbone of choice for the worlds most innovative companies such as Netflix, Adobe, Intuit, and eBay. --001a1138e9deb91879050a5bd144 Content-Type: text/html; charset=UTF-8 Content-Transfer-Encoding: quoted-printable
So heap of that size without some tuning will create = a number of problems (high cpu usage one of them), I suggest either 8GB hea= p and 400mb parnew (which I'd only set that low for that low cpu count)= , or attempt the tunings as indicated in https://issues.apache.org/jira/browse/CASSA= NDRA-8150

On Tue, Dec 16, 2014 at 3:06 PM, Arne Claassen <arne@emotient.= com> wrote:
Ch= anged the 15GB node to 25GB heap and the nice CPU is down to ~20% now. Chec= ked my dev cluster to see if the ParNew log entries are just par for the co= urse, but not seeing them there. However, both have the following every 30 = seconds:

DEBUG [BatchlogTasks:1] 2014-12-16 21:00:4= 4,898 BatchlogManager.java (line 165) Started replayAllFailedBatches
<= div>DEBUG [MemtablePostFlusher:1] 2014-12-16 21:00:44,899 ColumnFamilyStore= .java (line 866) forceFlush requested but everything is clean in batchlog
DEBUG [BatchlogTasks:1] 2014-12-16 21:00:44,899 BatchlogManager.ja= va (line 200) Finished replayAllFailedBatches

Is that just routine scheduled house-keeping or a sign of something else?=

On Tue, Dec 16, 2014 at 12:52 PM, Arne C= laassen <arne@emotient.com> wrote:
Sorry, I meant 15GB heap on the one machine that ha= s less nice CPU% now. The others are 6GB

On Tue, Dec 16, 2014 at 12:50 PM, Ar= ne Claassen <arne@emotient.com> wrote:
AWS r3.xlarge, 30GB, but only using a Heap of 10G= B, new 2GB because we might go c3.2xlarge instead if CPU is more important = than RAM
Storage is optimized EBS SSD (but iostat shows no real IO goin= g on)
Each node only has about 10GB with ownership of 67%, 64.7% = & 68.3%.

The node on which I set the Heap to 1= 0GB from 6GB the utlilization has dropped to 46%nice now, but the ParNew lo= g messages still continue at the same pace. I'm gonna up the HEAP to 20= GB for a bit, see if that brings that nice CPU further down.

=
No TombstoneOverflowingExceptions.

On Tue, Dec 16, 2014 at 1= 1:50 AM, Ryan Svihla <rsvihla@datastax.com> wrote:
What's CPU, RAM, Storage layer= , and data density per node? Exact heap settings would be nice. In the logs= look for TombstoneOverflowingException


On Tue, Dec 16, 2014 at 1:36 = PM, Arne Claassen <arne@emotient.com> wrote:
I'm running 2.0.10.

= The data is all time series data and as we change our pipeline, we've b= een periodically been reprocessing the data sources, which causes each time= series to be overwritten, i.e. every row per partition key is deleted and = re-written, so I assume i've been collecting a bunch of tombstones.

Also, the presence of the ever present and never comp= leting compaction types, i assumed were an artifact of tombstoning, but i f= ully admit to conjecture based on about ~20 blog posts and stackoverflow qu= estions i've surveyed.

I doubled the Heap on o= ne node and it changed nothing regarding the load or the ParNew log stateme= nts. New Generation Usage is 50%, Eden itself is 56%.

<= div>Anything else i should look at and report, let me know.

On Tue, Dec= 16, 2014 at 11:14 AM, Jonathan Lacefield <jlacefield@datastax.com> wrote:
Hello,<= div>
=C2=A0 What version of Cassandra are you running? =C2=A0=

=C2=A0 If it's 2.0, we recently experienced s= omething similar with 8447 [1], which=C2=A08485=C2=A0[2] should hopefully r= esolve. =C2=A0

=C2=A0 Please note that 8447 is not= related to tombstones.=C2=A0 Tombstone processing can put a lot of pressur= e on the heap as well. Why do you think you have a lot of tombstones in tha= t one particular table?


3D"datastax_lo=

Jonathan Lacefield

Solution Architect | (404) 822 3487 | = jlacefield@dat= astax.com


3D"linkedin.png" 3D"facebook.png" 3D"twitter.png"= 3D"g+.png"

On Tue, Dec 16, 2014 at 2:04 PM, Arne Claass= en <arne@emotient.com> wrote:
=
I have a three node cluster that has been sitting at a loa= d of 4 (for each node), 100% CPI utilization (although 92% nice) for that l= ast 12 hours, ever since some significant writes finished. I'm trying t= o determine what tuning I should be doing to get it out of this state. The = debug log is just an endless series of:

DEBUG [Sche= duledTasks:1] 2014-12-16 19:03:35,042 GCInspector.java (line 118) GC for Pa= rNew: 166 ms for 10 collections, 4400928736 used; max is 8000634880
DEBUG [ScheduledTasks:1] 2014-12-16 19:03:36,043 GCInspector.java (line = 118) GC for ParNew: 165 ms for 10 collections, 4440011176 used; max is 8000= 634880
DEBUG [ScheduledTasks:1] 2014-12-16 19:03:37,043 GCInspect= or.java (line 118) GC for ParNew: 135 ms for 8 collections, 4402220568 used; m= ax is 8000634880

iostat shows virtually no I/O.

Compaction may enter into this, but i don't real= ly know what to make of compaction stats since they never change:

[root@cassandra-37919c3a ~]# nodetool compactionstats<= /div>
pending tasks: 10
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 co= mpaction type =C2=A0 =C2=A0 =C2=A0 =C2=A0keyspace =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 table =C2=A0 =C2=A0 =C2=A0 completed =C2=A0 =C2=A0 =C2=A0 =C2=A0= =C2=A0 total =C2=A0 =C2=A0 =C2=A0unit =C2=A0progress
=C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Compaction =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 mediamedia_tracks_raw =C2=A0 =C2=A0 =C2=A0 271651482 =C2= =A0 =C2=A0 =C2=A0 563615497 =C2=A0 =C2=A0 bytes =C2=A0 =C2=A048.20%
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Compaction =C2=A0= =C2=A0 =C2=A0 =C2=A0 =C2=A0 mediamedia_tracks_raw =C2=A0 =C2=A0 =C2=A0 =C2= =A030308910 =C2=A0 =C2=A0 21676695677 =C2=A0 =C2=A0 bytes =C2=A0 =C2=A0 0.1= 4%
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Compact= ion =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 mediamedia_tracks_raw =C2=A0 =C2=A0 = =C2=A01198384080 =C2=A0 =C2=A0 =C2=A01815603161 =C2=A0 =C2=A0 bytes =C2=A0 = =C2=A066.00%
Active compaction remaining time : =C2=A0 0h22m24s

5 minutes later:

[root@cas= sandra-37919c3a ~]# nodetool compactionstats
pending tasks: 9
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 compaction type =C2=A0 =C2=A0 =C2= =A0 =C2=A0keyspace =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 table =C2=A0 =C2=A0 = =C2=A0 completed =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 total =C2=A0 =C2=A0 =C2= =A0unit =C2=A0progress
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0Compaction =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 mediamedia_track= s_raw =C2=A0 =C2=A0 =C2=A0 271651482 =C2=A0 =C2=A0 =C2=A0 563615497 =C2=A0 = =C2=A0 bytes =C2=A0 =C2=A048.20%
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0Compaction =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 media= media_tracks_raw =C2=A0 =C2=A0 =C2=A0 =C2=A030308910 =C2=A0 =C2=A0 21676695= 677 =C2=A0 =C2=A0 bytes =C2=A0 =C2=A0 0.14%
=C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Compaction =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 mediamedia_tracks_raw =C2=A0 =C2=A0 =C2=A01198384080 =C2=A0 =C2=A0 = =C2=A01815603161 =C2=A0 =C2=A0 bytes =C2=A0 =C2=A066.00%
Active c= ompaction remaining time : =C2=A0 0h22m24s

S= ure the pending tasks went down by one, but the rest is identical. media_tr= acks_raw likely has a bunch of tombstones (can't figure out how to get = stats on that).

Is this behavior something that in= dicates that i need more Heap, larger new generation? Should I be manually = running compaction on tables with lots of tombstones?

<= /div>
Any suggestions or places to educate myself better on performance= tuning would be appreciated.

<= /div>
arne


-- <= br>

3D"datastax_logo.png"

Ryan S= vihla

Solution Architect


3D"twitter.png" 3D"linkedin.=

DataStax is the fastest, most scalable distributed database te= chnology, delivering Apache Cassandra to the world=E2=80=99s most innovativ= e enterprises. Datastax is built to be agile, always-on, and predictably sc= alable to any size. With more than 500 customers in 45 countries, DataStax is the database technology an= d transactional backbone of choice for the worlds most innovative companies= such as Netflix, Adobe, Intuit, and eBay.


<= /div>


--

3D"datastax_logo.png"

Solution Architect


3D"twitter.png"<= /span> 3D"l=
<= div dir=3D"ltr">

DataStax is the fastest, most scalable distributed data= base technology, delivering Apache Cassandra to the world=E2=80=99s most in= novative enterprises. Datastax is built to be agile, always-on, and predict= ably scalable to any size. With more than 500 customers in 45 countries, DataStax is the database techno= logy and transactional backbone of choice for the worlds most innovative co= mpanies such as Netflix, Adobe, Intuit, and eBay.


<= /span>
--001a1138e9deb91879050a5bd144--