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 CF59456C0 for ; Thu, 12 May 2011 23:27:29 +0000 (UTC) Received: (qmail 68007 invoked by uid 500); 12 May 2011 23:27:27 -0000 Delivered-To: apmail-cassandra-user-archive@cassandra.apache.org Received: (qmail 67980 invoked by uid 500); 12 May 2011 23:27:27 -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 67968 invoked by uid 99); 12 May 2011 23:27:27 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 12 May 2011 23:27:27 +0000 X-ASF-Spam-Status: No, hits=1.5 required=5.0 tests=FREEMAIL_FROM,HTML_MESSAGE,RCVD_IN_DNSWL_LOW,RFC_ABUSE_POST,SPF_PASS,T_TO_NO_BRKTS_FREEMAIL X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of cassandralabs@gmail.com designates 209.85.210.172 as permitted sender) Received: from [209.85.210.172] (HELO mail-iy0-f172.google.com) (209.85.210.172) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 12 May 2011 23:27:23 +0000 Received: by iyn15 with SMTP id 15so2123066iyn.31 for ; Thu, 12 May 2011 16:27:03 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=domainkey-signature:mime-version:in-reply-to:references:date :message-id:subject:from:to:content-type; bh=xWjHsn4usUjuy5xmFn0a528DErZ7lXa4WyFjmBUHwJw=; b=S5/2KapGpm8lrftExs+N3id6M7Vct1wq+1Ug0lxptryMclsQmlitEKhEAtq1tkkGAY j/j+B/T+8MZOxmzsFcZoMwCpHniOf0oLtJa5mIQEAXRyFRJnihM89PNo3Gq3dcom1ZdT V62fX+65WjyLEQ0GOTFlOs1F6nZGOqCD28160= DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=mime-version:in-reply-to:references:date:message-id:subject:from:to :content-type; b=cZrMTrqlNpy4TPzqZfoP6xY6LShEuEQv//1GG4o7YC0qxFEJyj5gZeeoEwxbeNnxsa Tmm1DM3r1vd3gSdZp5/uYg54/o9kBoSSmbnqdvbgfKRIm9uANB0VLDEJqQyf3FaNSoTL 8q7YMgLuysiAn6zy4T2gNbluohmdDNr0+mW1k= MIME-Version: 1.0 Received: by 10.231.116.132 with SMTP id m4mr625590ibq.86.1305242822931; Thu, 12 May 2011 16:27:02 -0700 (PDT) Received: by 10.231.211.142 with HTTP; Thu, 12 May 2011 16:27:02 -0700 (PDT) In-Reply-To: References: Date: Thu, 12 May 2011 16:27:02 -0700 Message-ID: Subject: Re: Crash when uploading large data sets From: Sameer Farooqui To: user@cassandra.apache.org Content-Type: multipart/alternative; boundary=005045015ed1ce741404a31c86df --005045015ed1ce741404a31c86df Content-Type: text/plain; charset=ISO-8859-1 The key JVM options for Cassandra are in cassandra.in.sh. What is your min and max heap size? The default setting of max heap size is 1GB. How much RAM do your nodes have? You may want to increase this setting. You can also set the -Xmx and -Xms options to the same value to keep Java from having to manage heap growth. On a 32-bit machine, you can get a max of about 1.6 GB of heap; you can get a lot more on 64-bit. Try messing with some of the other settings in the cassandra.in.sh file. You may not have DEBUG mode turned on for Cassandra and therefore may not be getting the full details of what's going on when the server crashes. In the /conf/log4j-server.properties file, set this line from the default of INFO to DEBUG: log4j.rootLogger=INFO,stdout,R Also, you haven't configured JNA on this server. Here's some info about it and how to configure it: JNA provides Java programs easy access to native shared libraries without writing anything but Java code. Note from Cassandra developers for why JNA is needed: "*Linux aggressively swaps out infrequently used memory to make more room for its file system buffer cache. Unfortunately, modern generational garbage collectors like the JVM's leave parts of its heap un-touched for relatively large amounts of time, leading Linux to swap it out. When the JVM finally goes to use or GC that memory, swap hell ensues. Setting swappiness to zero can mitigate this behavior but does not eliminate it entirely. Turning off swap entirely is effective. But to avoid surprising people who don't know about this behavior, the best solution is to tell Linux not to swap out the JVM, and that is what we do now with mlockall via JNA. Because of licensing issues, we can't distribute JNA with Cassandra, so you must manually add it to the Cassandra lib/ directory or otherwise place it on the classpath. If the JNA jar is not present, Cassandra will continue as before.*" Get JNA with: *cd ~ wget http://debian.riptano.com/debian/pool/libjna-java_3.2.7-0~nmu.2_amd64.deb* To install: *techlabs@cassandraN1:~$ sudo dpkg -i libjna-java_3.2.7-0~nmu.2_amd64.deb (Reading database ... 44334 files and directories currently installed.) Preparing to replace libjna-java 3.2.4-2 (using libjna-java_3.2.7-0~nmu.2_amd64.deb) ... Unpacking replacement libjna-java ... Setting up libjna-java (3.2.7-0~nmu.2) ...* The deb package will install the JNA jar file to /usr/share/java/jna.jar, but Cassandra only loads it if its in the class path. The easy way to do this is just create a symlink into your Cassandra lib directory (note: replace /home/techlabs with your home dir location): *ln -s /usr/share/java/jna.jar /home/techlabs/apache-cassandra-0.7.0/lib* Research: http://journal.paul.querna.org/articles/2010/11/11/enabling-jna-in-cassandra/ - Sameer On Thu, May 12, 2011 at 4:15 PM, James Cipar wrote: > I'm using Cassandra 0.7.5, and uploading about 200 GB of data total (20 GB > unique data), to a cluster of 10 servers. I'm using batch_mutate, and > breaking the data up into chunks of about 10k records. Each record is about > 5KB, so a total of about 50MB per batch. When I upload a smaller 2 GB data > set, everything works fine. When I upload the 20 GB data set, servers will > occasionally crash. Currently I have my client code automatically detect > this and restart the server, but that is less than ideal. > > I'm not sure what information to gather to determine what's going on here. > Here is a sample of a log file from when a crash occurred. The crash was > immediately after the log entry tagged "2011-05-12 19:02:19,377". Any idea > what's going on here? Any other info I can gather to try to debug this? > > > > > > > > INFO [ScheduledTasks:1] 2011-05-12 19:02:07,855 GCInspector.java (line > 128) GC for ParNew: 375 ms, 576641232 reclaimed leaving 5471432144 used; max > is 7774142464 > INFO [ScheduledTasks:1] 2011-05-12 19:02:08,857 GCInspector.java (line > 128) GC for ParNew: 450 ms, -63738232 reclaimed leaving 5546942544 used; max > is 7774142464 > INFO [COMMIT-LOG-WRITER] 2011-05-12 19:02:10,652 CommitLogSegment.java > (line 50) Creating new commitlog segment > /mnt/scratch/jcipar/cassandra/commitlog/CommitLog-1305241330652.log > INFO [MutationStage:24] 2011-05-12 19:02:10,680 ColumnFamilyStore.java > (line 1070) Enqueuing flush of Memtable-Standard1@1256245282(51921529 > bytes, 1115783 operations) > INFO [FlushWriter:1] 2011-05-12 19:02:10,680 Memtable.java (line 158) > Writing Memtable-Standard1@1256245282(51921529 bytes, 1115783 operations) > INFO [ScheduledTasks:1] 2011-05-12 19:02:12,932 GCInspector.java (line > 128) GC for ParNew: 249 ms, 571827736 reclaimed leaving 3165899760 used; max > is 7774142464 > INFO [ScheduledTasks:1] 2011-05-12 19:02:15,253 GCInspector.java (line > 128) GC for ParNew: 341 ms, 561823592 reclaimed leaving 1764208800 used; max > is 7774142464 > INFO [FlushWriter:1] 2011-05-12 19:02:16,743 Memtable.java (line 165) > Completed flushing > /mnt/scratch/jcipar/cassandra/data/Keyspace1/Standard1-f-74-Data.db > (53646223 bytes) > INFO [COMMIT-LOG-WRITER] 2011-05-12 19:02:16,745 CommitLog.java (line 440) > Discarding obsolete commit > log:CommitLogSegment(/mnt/scratch/jcipar/cassandra/commitlog/CommitLog-1305241306438.log) > INFO [ScheduledTasks:1] 2011-05-12 19:02:18,256 GCInspector.java (line > 128) GC for ParNew: 305 ms, 544491840 reclaimed leaving 865198712 used; max > is 7774142464 > INFO [MutationStage:19] 2011-05-12 19:02:19,000 ColumnFamilyStore.java > (line 1070) Enqueuing flush of Memtable-Standard1@479849353(51941121 > bytes, 1115783 operations) > INFO [FlushWriter:1] 2011-05-12 19:02:19,000 Memtable.java (line 158) > Writing Memtable-Standard1@479849353(51941121 bytes, 1115783 operations) > INFO [NonPeriodicTasks:1] 2011-05-12 19:02:19,310 SSTable.java (line 147) > Deleted /mnt/scratch/jcipar/cassandra/data/Keyspace1/Standard1-f-51 > INFO [NonPeriodicTasks:1] 2011-05-12 19:02:19,324 SSTable.java (line 147) > Deleted /mnt/scratch/jcipar/cassandra/data/Keyspace1/Standard1-f-55 > INFO [NonPeriodicTasks:1] 2011-05-12 19:02:19,339 SSTable.java (line 147) > Deleted /mnt/scratch/jcipar/cassandra/data/Keyspace1/Standard1-f-58 > INFO [NonPeriodicTasks:1] 2011-05-12 19:02:19,357 SSTable.java (line 147) > Deleted /mnt/scratch/jcipar/cassandra/data/Keyspace1/Standard1-f-67 > INFO [NonPeriodicTasks:1] 2011-05-12 19:02:19,377 SSTable.java (line 147) > Deleted /mnt/scratch/jcipar/cassandra/data/Keyspace1/Standard1-f-61 > INFO [main] 2011-05-12 19:02:21,026 AbstractCassandraDaemon.java (line 78) > Logging initialized > INFO [main] 2011-05-12 19:02:21,040 AbstractCassandraDaemon.java (line 96) > Heap size: 7634681856/7635730432 > INFO [main] 2011-05-12 19:02:21,042 CLibrary.java (line 61) JNA not found. > Native methods will be disabled. > INFO [main] 2011-05-12 19:02:21,052 DatabaseDescriptor.java (line 121) > Loading settings from > file:/h/jcipar/Projects/HP/OtherDBs/Cassandra/apache-cassandra-0.7.5/conf/cassandra.yaml > INFO [main] 2011-05-12 19:02:21,178 DatabaseDescriptor.java (line 181) > DiskAccessMode 'auto' determined to be mmap, indexAccessMode is mmap > INFO [main] 2011-05-12 19:02:21,310 SSTableReader.java (line 154) Opening > /mnt/scratch/jcipar/cassandra/data/system/Schema-f-1 > INFO [main] 2011-05-12 19:02:21,327 SSTableReader.java (line 154) Opening > /mnt/scratch/jcipar/cassandra/data/system/Schema-f-2 > INFO [main] 2011-05-12 19:02:21,336 SSTableReader.java (line 154) Opening > /mnt/scratch/jcipar/cassandra/data/system/Migrations-f-1 > INFO [main] 2011-05-12 19:02:21,337 SSTableReader.java (line 154) Opening > /mnt/scratch/jcipar/cassandra/data/system/Migrations-f-2 > INFO [main] 2011-05-12 19:02:21,342 SSTableReader.java (line 154) Opening > /mnt/scratch/jcipar/cassandra/data/system/LocationInfo-f-2 > INFO [main] 2011-05-12 19:02:21,344 SSTableReader.java (line 154) Opening > /mnt/scratch/jcipar/cassandra/data/system/LocationInfo-f-1 > INFO [main] 2011-05-12 19:02:21,379 DatabaseDescriptor.java (line 461) > Loading schema version 9467ffe0-7cea-11e0-8ddc-f74ef74e382f --005045015ed1ce741404a31c86df Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable The key JVM options for Cassandra are in cassandra.in.sh.

What is your min and max heap size= ?

The default setting of max heap size is 1GB. How= much RAM do your nodes have? You may want to increase this setting. You ca= n also set the -Xmx and -Xms options to the same value to keep Java from ha= ving to manage heap growth. On a 32-bit machine, you can get a max of about= 1.6 GB of heap; you can get a lot more on 64-bit.

Try messing with some of the other settings in the cassandra.in.sh file.

You may not have DEBUG mode turned on for Cassandra and therefore ma= y not be getting the full details of what's going on when the server cr= ashes. In the <cassandra-home>/conf/log4j-server.properties file, set= this line from the default of INFO to DEBUG:

log4j.rootLogger=3DINFO,stdout,R


Also, you haven't configured JNA on this server. Here= 's some info about it and how to configure it:

JNA provides Java programs easy access to native= shared libraries without writing anything but Java code.

Note from = Cassandra developers for why JNA is needed:
"Linux aggressively swaps out infrequently used memory to make more= room for its file system buffer cache. Unfortunately, modern generational = garbage collectors like the JVM's leave parts of its heap un-touched fo= r relatively large amounts of time, leading Linux to swap it out. When the = JVM finally goes to use or GC that memory, swap hell ensues.

Setting swappiness to zero can mitigate this behavior but does not elim= inate it entirely. Turning off swap entirely is effective. But to avoid sur= prising people who don't know about this behavior, the best solution is= to tell Linux not to swap out the JVM, and that is what we do now with mlo= ckall via JNA.

Because of licensing issues, we can't distribute JNA with Cassandra= , so you must manually add it to the Cassandra lib/ directory or otherwise = place it on the classpath. If the JNA jar is not present, Cassandra will co= ntinue as before."

Get JNA with:=A0
cd ~
http://debian.riptano.com/debian/pool/libjna-java_3.2.7-= 0~nmu.2_amd64.deb

To install:=A0
techlabs@cassandraN1:~$=A0sudo dpkg -i l= ibjna-java_3.2.7-0~nmu.2_amd64.deb
(Reading da= tabase ... 44334 files and directories currently installed.)
Preparing to replace libjna-java= 3.2.4-2 (using libjna-java_3.2.7-0~nmu.2_amd64.deb) ...
Unpacking r= eplacement libjna-java ...
Setting up libjna-java (3.2.7-0~nmu.2) ...


The deb package will install the JNA jar file to /usr/share/java/jn= a.jar, but Cassandra only loads it if its in the class path. The easy way t= o do this is just create a symlink into your Cassandra lib directory (note:= replace /home/techlabs with your home dir location):
ln -s /u= sr/share/java/jna.jar /home/techlabs/apache-cassandra-0.7.0/lib<= br>
Research:
http://journal.paul.querna.org/articles/2010/11/11/enabling-jna-in-= cassandra/


- Sameer


=
On Thu, May 12, 2011 at 4:15 PM, James Cipar <jcipar@cmu.edu>= wrote:
I'm using Cassandra 0.7.5, and uploadin= g about 200 GB of data total (20 GB unique data), to a cluster of 10 server= s. =A0I'm using batch_mutate, and breaking the data up into chunks of a= bout 10k records. =A0Each record is about 5KB, so a total of about 50MB per= batch. =A0When I upload a smaller 2 GB data set, everything works fine. = =A0When I upload the 20 GB data set, servers will occasionally crash. =A0Cu= rrently I have my client code automatically detect this and restart the ser= ver, but that is less than ideal.

I'm not sure what information to gather to determine what's going o= n here. =A0Here is a sample of a log file from when a crash occurred. =A0Th= e crash was immediately after the log entry tagged "2011-05-12 19:02:1= 9,377". =A0Any idea what's going on here? =A0Any other info I can = gather to try to debug this?







=A0INFO [ScheduledTasks:1] 2011-05-12 19:02:07,855 GCInspector.java (line 1= 28) GC for ParNew: 375 ms, 576641232 reclaimed leaving 5471432144 used; max= is 7774142464
=A0INFO [ScheduledTasks:1] 2011-05-12 19:02:08,857 GCInspector.java (line 1= 28) GC for ParNew: 450 ms, -63738232 reclaimed leaving 5546942544 used; max= is 7774142464
=A0INFO [COMMIT-LOG-WRITER] 2011-05-12 19:02:10,652 CommitLogSegment.java (= line 50) Creating new commitlog segment /mnt/scratch/jcipar/cassandra/commi= tlog/CommitLog-1305241330652.log
=A0INFO [MutationStage:24] 2011-05-12 19:02:10,680 ColumnFamilyStore.java (= line 1070) Enqueuing flush of Memtable-Standard1@1256245282(51921529 bytes,= 1115783 operations)
=A0INFO [FlushWriter:1] 2011-05-12 19:02:10,680 Memtable.java (line 158) Wr= iting Memtable-Standard1@1256245282(51921529 bytes, 1115783 operations)
=A0INFO [ScheduledTasks:1] 2011-05-12 19:02:12,932 GCInspector.java (line 1= 28) GC for ParNew: 249 ms, 571827736 reclaimed leaving 3165899760 used; max= is 7774142464
=A0INFO [ScheduledTasks:1] 2011-05-12 19:02:15,253 GCInspector.java (line 1= 28) GC for ParNew: 341 ms, 561823592 reclaimed leaving 1764208800 used; max= is 7774142464
=A0INFO [FlushWriter:1] 2011-05-12 19:02:16,743 Memtable.java (line 165) Co= mpleted flushing /mnt/scratch/jcipar/cassandra/data/Keyspace1/Standard1-f-7= 4-Data.db (53646223 bytes)
=A0INFO [COMMIT-LOG-WRITER] 2011-05-12 19:02:16,745 CommitLog.java (line 44= 0) Discarding obsolete commit log:CommitLogSegment(/mnt/scratch/jcipar/cass= andra/commitlog/CommitLog-1305241306438.log)
=A0INFO [ScheduledTasks:1] 2011-05-12 19:02:18,256 GCInspector.java (line 1= 28) GC for ParNew: 305 ms, 544491840 reclaimed leaving 865198712 used; max = is 7774142464
=A0INFO [MutationStage:19] 2011-05-12 19:02:19,000 ColumnFamilyStore.java (= line 1070) Enqueuing flush of Memtable-Standard1@479849353(51941121 bytes, = 1115783 operations)
=A0INFO [FlushWriter:1] 2011-05-12 19:02:19,000 Memtable.java (line 158) Wr= iting Memtable-Standard1@479849353(51941121 bytes, 1115783 operations)
=A0INFO [NonPeriodicTasks:1] 2011-05-12 19:02:19,310 SSTable.java (line 147= ) Deleted /mnt/scratch/jcipar/cassandra/data/Keyspace1/Standard1-f-51
=A0INFO [NonPeriodicTasks:1] 2011-05-12 19:02:19,324 SSTable.java (line 147= ) Deleted /mnt/scratch/jcipar/cassandra/data/Keyspace1/Standard1-f-55
=A0INFO [NonPeriodicTasks:1] 2011-05-12 19:02:19,339 SSTable.java (line 147= ) Deleted /mnt/scratch/jcipar/cassandra/data/Keyspace1/Standard1-f-58
=A0INFO [NonPeriodicTasks:1] 2011-05-12 19:02:19,357 SSTable.java (line 147= ) Deleted /mnt/scratch/jcipar/cassandra/data/Keyspace1/Standard1-f-67
=A0INFO [NonPeriodicTasks:1] 2011-05-12 19:02:19,377 SSTable.java (line 147= ) Deleted /mnt/scratch/jcipar/cassandra/data/Keyspace1/Standard1-f-61
=A0INFO [main] 2011-05-12 19:02:21,026 AbstractCassandraDaemon.java (line 7= 8) Logging initialized
=A0INFO [main] 2011-05-12 19:02:21,040 AbstractCassandraDaemon.java (line 9= 6) Heap size: 7634681856/7635730432
=A0INFO [main] 2011-05-12 19:02:21,042 CLibrary.java (line 61) JNA not foun= d. Native methods will be disabled.
=A0INFO [main] 2011-05-12 19:02:21,052 DatabaseDescriptor.java (line 121) L= oading settings from file:/h/jcipar/Projects/HP/OtherDBs/Cassandra/apache-c= assandra-0.7.5/conf/cassandra.yaml
=A0INFO [main] 2011-05-12 19:02:21,178 DatabaseDescriptor.java (line 181) D= iskAccessMode 'auto' determined to be mmap, indexAccessMode is mmap=
=A0INFO [main] 2011-05-12 19:02:21,310 SSTableReader.java (line 154) Openin= g /mnt/scratch/jcipar/cassandra/data/system/Schema-f-1
=A0INFO [main] 2011-05-12 19:02:21,327 SSTableReader.java (line 154) Openin= g /mnt/scratch/jcipar/cassandra/data/system/Schema-f-2
=A0INFO [main] 2011-05-12 19:02:21,336 SSTableReader.java (line 154) Openin= g /mnt/scratch/jcipar/cassandra/data/system/Migrations-f-1
=A0INFO [main] 2011-05-12 19:02:21,337 SSTableReader.java (line 154) Openin= g /mnt/scratch/jcipar/cassandra/data/system/Migrations-f-2
=A0INFO [main] 2011-05-12 19:02:21,342 SSTableReader.java (line 154) Openin= g /mnt/scratch/jcipar/cassandra/data/system/LocationInfo-f-2
=A0INFO [main] 2011-05-12 19:02:21,344 SSTableReader.java (line 154) Openin= g /mnt/scratch/jcipar/cassandra/data/system/LocationInfo-f-1
=A0INFO [main] 2011-05-12 19:02:21,379 DatabaseDescriptor.java (line 461) L= oading schema version 9467ffe0-7cea-11e0-8ddc-f74ef74e382f

--005045015ed1ce741404a31c86df--