Re: 0.7.0beta2 spinning/wedged after aggressive overnight writing

[Jonathan Ellis <jb...@gmail.com>]

(moving to user list.)

This sounds like you are GC storming (gcinspector lines in the log
could confirm/refute this) and if I were to guess it would be that the
memtable thresholds picked by b2 are too high.  We cut them in half
for rc1 in http://issues.apache.org/jira/browse/CASSANDRA-1641, but an
in-place upgrade to rc1 will not reset them, you can do that from the
cli with "update column family" ("help update column family" for full
options) or temporarily via JMX.

"show keyspaces" will show the current thresholds, again in rc1 or nightly.

On Wed, Oct 27, 2010 at 1:06 PM, Chip Salzenberg <ch...@pobox.com> wrote:
> I set 60 clients to aggressively inserting into a 0.7.0beta2 standard
> keyspace overnight.  This morning, its heap usage is maxed, it's using
> 400% CPU (which is a lot less than the box has, so that's OK), and it's
> making progress very... very... slowly.  The timestamps near the end the
> commit logs tell the tale.  Help?
>
> PS: This is not the 128G machine - this is the 72G machine, and it
> seemed to work great until  3:40am.
>
>  INFO [CompactionExecutor:1] 2010-10-27 03:34:31,717
> CompactionManager.java (line 305) Compacted to
> /var/lib/cassandra/data/_chip/Keyspace1/Standard1-tmp-e-155-Data.db.
> 5,582,588,196 to 5,511,562,149 (~98% of original) bytes for 26,781,501
> keys.  Time: 916,298ms.
>  INFO [CompactionExecutor:1] 2010-10-27 03:34:31,717
> CompactionManager.java (line 233) Compacting
> [org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/_chip/Keyspace1/Standard1-e-140-Data.db'),org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/_chip/Keyspace1/Standard1-e-145-Data.db'),org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/_chip/Keyspace1/Standard1-e-150-Data.db'),org.apache.cassandra.io.sstable.SSTableReader(path='/var/lib/cassandra/data/_chip/Keyspace1/Standard1-e-155-Data.db')]
>  INFO [COMMIT-LOG-WRITER] 2010-10-27 03:34:41,359 CommitLogSegment.java
> (line 50) Creating new commitlog segment
> /var/lib/cassandra/commitlog/_chip/CommitLog-1288175681359.log
>  INFO [COMMIT-LOG-WRITER] 2010-10-27 03:35:11,025 CommitLogSegment.java
> (line 50) Creating new commitlog segment
> /var/lib/cassandra/commitlog/_chip/CommitLog-1288175711025.log
>  INFO [COMMIT-LOG-WRITER] 2010-10-27 03:35:39,775 CommitLogSegment.java
> (line 50) Creating new commitlog segment
> /var/lib/cassandra/commitlog/_chip/CommitLog-1288175739775.log
>  INFO [COMMIT-LOG-WRITER] 2010-10-27 03:36:11,619 CommitLogSegment.java
> (line 50) Creating new commitlog segment
> /var/lib/cassandra/commitlog/_chip/CommitLog-1288175771619.log
>  INFO [COMMIT-LOG-WRITER] 2010-10-27 03:36:42,251 CommitLogSegment.java
> (line 50) Creating new commitlog segment
> /var/lib/cassandra/commitlog/_chip/CommitLog-1288175802251.log
>  INFO [COMMIT-LOG-WRITER] 2010-10-27 03:37:14,466 CommitLogSegment.java
> (line 50) Creating new commitlog segment
> /var/lib/cassandra/commitlog/_chip/CommitLog-1288175834466.log
>  INFO [SSTABLE-CLEANUP-TIMER] 2010-10-27 03:37:25,543 SSTable.java (line
> 145) Deleted /var/lib/cassandra/data/_chip/Keyspace1/Standard1-e-153-<>
>  INFO [SSTABLE-CLEANUP-TIMER] 2010-10-27 03:37:26,063 SSTable.java (line
> 145) Deleted /var/lib/cassandra/data/_chip/Keyspace1/Standard1-e-152-<>
>  INFO [SSTABLE-CLEANUP-TIMER] 2010-10-27 03:37:26,679 SSTable.java (line
> 145) Deleted /var/lib/cassandra/data/_chip/Keyspace1/Standard1-e-151-<>
>  INFO [SSTABLE-CLEANUP-TIMER] 2010-10-27 03:37:27,161 SSTable.java (line
> 145) Deleted /var/lib/cassandra/data/_chip/Keyspace1/Standard1-e-154-<>
>  INFO [COMMIT-LOG-WRITER] 2010-10-27 03:37:46,653 CommitLogSegment.java
> (line 50) Creating new commitlog segment
> /var/lib/cassandra/commitlog/_chip/CommitLog-1288175866653.log
>  INFO [COMMIT-LOG-WRITER] 2010-10-27 03:40:34,537 CommitLogSegment.java
> (line 50) Creating new commitlog segment
> /var/lib/cassandra/commitlog/_chip/CommitLog-1288176034537.log
>  INFO [MUTATION_STAGE:30] 2010-10-27 03:40:36,793 ColumnFamilyStore.java
> (line 459) switching in a fresh Memtable for Standard1 at
> CommitLogContext(file='/var/lib/cassandra/commitlog/_chip/CommitLog-1288176034537.log',
> position=9607864)
>  INFO [MUTATION_STAGE:30] 2010-10-27 03:40:36,794 ColumnFamilyStore.java
> (line 771) Enqueuing flush of Memtable-Standard1@222641915(460325998
> bytes, 13109777 operations)
>  INFO [FLUSH-WRITER-POOL:1] 2010-10-27 03:40:36,794 Memtable.java (line
> 150) Writing Memtable-Standard1@222641915(460325998 bytes, 13109777
> operations)
>  INFO [COMMIT-LOG-WRITER] 2010-10-27 03:41:00,029 CommitLogSegment.java
> (line 50) Creating new commitlog segment
> /var/lib/cassandra/commitlog/_chip/CommitLog-1288176060029.log
>  INFO [COMMIT-LOG-WRITER] 2010-10-27 03:43:45,757 CommitLogSegment.java
> (line 50) Creating new commitlog segment
> /var/lib/cassandra/commitlog/_chip/CommitLog-1288176225757.log
>  INFO [COMMIT-LOG-WRITER] 2010-10-27 03:46:48,020 CommitLogSegment.java
> (line 50) Creating new commitlog segment
> /var/lib/cassandra/commitlog/_chip/CommitLog-1288176408020.log
>  INFO [COMMIT-LOG-WRITER] 2010-10-27 05:01:39,861 CommitLogSegment.java
> (line 50) Creating new commitlog segment
> /var/lib/cassandra/commitlog/_chip/CommitLog-1288180899828.log
>  INFO [COMMIT-LOG-WRITER] 2010-10-27 08:01:27,466 CommitLogSegment.java
> (line 50) Creating new commitlog segment
> /var/lib/cassandra/commitlog/_chip/CommitLog-1288191687466.log
>
>
> -rw-r--r-- 1 chip 134217796 2010-10-27 03:36 CommitLog-1288175739775.log
> -rw-r--r-- 1 chip 134217796 2010-10-27 03:36 CommitLog-1288175771619.log
> -rw-r--r-- 1 chip        28 2010-10-27 03:36
> CommitLog-1288175802251.log.header
> -rw-r--r-- 1 chip 134217796 2010-10-27 03:37 CommitLog-1288175802251.log
> -rw-r--r-- 1 chip        28 2010-10-27 03:37
> CommitLog-1288175834466.log.header
> -rw-r--r-- 1 chip        28 2010-10-27 03:37
> CommitLog-1288175866653.log.header
> -rw-r--r-- 1 chip 134217796 2010-10-27 03:37 CommitLog-1288175834466.log
> -rw-r--r-- 1 chip 134217796 2010-10-27 03:40 CommitLog-1288175866653.log
> -rw-r--r-- 1 chip        28 2010-10-27 03:40
> CommitLog-1288176034537.log.header
> -rw-r--r-- 1 chip 134217796 2010-10-27 03:41 CommitLog-1288176034537.log
> -rw-r--r-- 1 chip        28 2010-10-27 03:41
> CommitLog-1288176060029.log.header
> -rw-r--r-- 1 chip 134217796 2010-10-27 03:43 CommitLog-1288176060029.log
> -rw-r--r-- 1 chip        28 2010-10-27 03:43
> CommitLog-1288176225757.log.header
> -rw-r--r-- 1 chip 134217796 2010-10-27 03:46 CommitLog-1288176225757.log
> -rw-r--r-- 1 chip        28 2010-10-27 03:46
> CommitLog-1288176408020.log.header
> -rw-r--r-- 1 chip 134217796 2010-10-27 05:01 CommitLog-1288176408020.log
> -rw-r--r-- 1 chip        28 2010-10-27 05:01
> CommitLog-1288180899828.log.header
> -rw-r--r-- 1 chip 134217796 2010-10-27 08:01 CommitLog-1288180899828.log
> -rw-r--r-- 1 chip        28 2010-10-27 08:01
> CommitLog-1288191687466.log.header
> -rw-r--r-- 1 chip 124846080 2010-10-27 11:00 CommitLog-1288191687466.log
>
> Recent log entries:
>
>
>



-- 
Jonathan Ellis
Project Chair, Apache Cassandra
co-founder of Riptano, the source for professional Cassandra support
http://riptano.com