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 93925E521 for ; Tue, 4 Dec 2012 18:04:50 +0000 (UTC) Received: (qmail 96056 invoked by uid 500); 4 Dec 2012 18:04:48 -0000 Delivered-To: apmail-cassandra-user-archive@cassandra.apache.org Received: (qmail 96011 invoked by uid 500); 4 Dec 2012 18:04:48 -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 96003 invoked by uid 99); 4 Dec 2012 18:04:48 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 04 Dec 2012 18:04:48 +0000 X-ASF-Spam-Status: No, hits=0.2 required=5.0 tests=FREEMAIL_ENVFROM_END_DIGIT,RCVD_IN_DNSWL_NONE,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: local policy) Received: from [98.139.212.185] (HELO nm26.bullet.mail.bf1.yahoo.com) (98.139.212.185) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 04 Dec 2012 18:04:38 +0000 Received: from [98.139.212.148] by nm26.bullet.mail.bf1.yahoo.com with NNFMP; 04 Dec 2012 18:04:17 -0000 Received: from [98.139.211.192] by tm5.bullet.mail.bf1.yahoo.com with NNFMP; 04 Dec 2012 18:04:17 -0000 Received: from [127.0.0.1] by smtp201.mail.bf1.yahoo.com with NNFMP; 04 Dec 2012 18:04:17 -0000 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=yahoo.com; s=s1024; t=1354644257; bh=0DrBnS6Gv9g6VnkYlEL8xfEw+dtpXYYf48sD2AxUxfs=; h=X-Yahoo-Newman-Id:X-Yahoo-Newman-Property:X-YMail-OSG:X-Yahoo-SMTP:Received:Message-ID:Date:From:User-Agent:MIME-Version:To:Subject:Content-Type:Content-Transfer-Encoding; b=dWdbwPjlf4zLDKf6qjLPuNBYWeiZrzx/suNyu3bMDDF46akN1K411/gosU/+5yrAP/rP+8f9HrfG16JBjzBwklEWToyTUF6MH9peNRR2OCh4L63oTZUf7eJqniq8GbrrBkCc5DUUHwrl5i3inzNyAujpZnY0CJTxqIvObjdTuDc= X-Yahoo-Newman-Id: 594703.65636.bm@smtp201.mail.bf1.yahoo.com X-Yahoo-Newman-Property: ymail-3 X-YMail-OSG: wjz_gegVM1l2mFJ147vyGWON9J.xICIxRExmi0Pu13cBUcn JYUdzd4_g9OdF90HyWcA9C3VzUBrAK2gFrSGaZ7zPV6w.2rC_xGYkJ0rMJe. e4XB52ydQTXgYyEnk0orc8Z7dDWv6GBxW9rXyEOT48kJVNwLIELWyBA4a4uu 1RvCRnZ4l00jXjln4m6Z9xIwmlrqSPIvVHEm64P3RFKzrRWx13CyxCms0hhV LV_bpeOa8ON3icOZrO6txniN8tfdYdlrJ2mgsRAkdRnWRnhZOq8SQfdRy_MG jeY9YOqlch1OHlHDgI2cTPez_ZflqFewh4yQYilJjVQtMaWtXYYyeXH47.Yc jzAfH0XR8fXhVRG.3wvOQACOZ.yG4FZYQ8wWk_Hua6lRjqrQB8D_OTg7wmOQ mmMeZSNaRFPcVALq__06dt3udZYLakWAdoCEzi7gIBRhLRh4TVJqjrGb8x3K j4S3FbyqqGEGVSiCSWec12JvzfhlknJ9z0T5mtZzi_wp9aZ9U1xMgrPwr1Cg hD77abMrRKEw047xJ54BWsMZDcA-- X-Yahoo-SMTP: t0UN_U2swBCFgwLIRu70LU92TrvpdQ-- Received: from [192.168.1.5] (mtheroux2@76.118.248.45 with plain) by smtp201.mail.bf1.yahoo.com with SMTP; 04 Dec 2012 10:04:17 -0800 PST Message-ID: <50BE3B22.1000103@yahoo.com> Date: Tue, 04 Dec 2012 13:04:18 -0500 From: Mike User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:16.0) Gecko/20121026 Thunderbird/16.0.2 MIME-Version: 1.0 To: user@cassandra.apache.org Subject: Diagnosing memory issues Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit X-Virus-Checked: Checked by ClamAV on apache.org Hello, Our Cassandra cluster has, relatively recently, started experiencing memory pressure that I am in the midsts of diagnosing. Our system has uneven levels of traffic, relatively light during the day, but extremely heavy during some overnight processing. We have started getting a message: WARN [ScheduledTasks:1] 2012-12-04 09:08:58,579 GCInspector.java (line 145) Heap is 0.7520105072262254 full. You may need to reduce memtable and/or cache sizes. Cassandra will now flush up to the two largest memtables to free up memory. Adjust flush_largest_memtables_at threshold in cassandra.yaml if you don't want Cassandra to do this automatically I've started implementing some instrumentation to gather stats from JMX to determine what is happening. However, last night, the GCInspector was kind enough to log the information below. Couple of things jumped out at me. The maximum heap for the Cassandra is 4GB. We are running Cassandra 1.1.2, on a 6 node cluster, with a replication factor of 3. All our queries use LOCAL_QUORUM consistency. Adding up the caches + the memtable "data" in the trace below, comes to under 600MB The number that really jumps out at me below is the number of Pending requests for the Message Service. 24,000+ pending requests. Does this number represent the number of outstanding client requests that this node is processing? If so, does this mean we potentially have 24,000 responses being pulled into memory, thereby causing this memory issue? What else should I look at? INFO [ScheduledTasks:1] 2012-12-04 09:00:37,585 StatusLogger.java (line 57) Pool Name Active Pending Blocked INFO [ScheduledTasks:1] 2012-12-04 09:00:37,695 StatusLogger.java (line 72) ReadStage 32 66 0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,696 StatusLogger.java (line 72) RequestResponseStage 0 193 0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,696 StatusLogger.java (line 72) ReadRepairStage 0 0 0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,696 StatusLogger.java (line 72) MutationStage 2 2 0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,697 StatusLogger.java (line 72) ReplicateOnWriteStage 5 5 0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,698 StatusLogger.java (line 72) GossipStage 0 13 0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,698 StatusLogger.java (line 72) AntiEntropyStage 0 0 0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,698 StatusLogger.java (line 72) MigrationStage 0 0 0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,699 StatusLogger.java (line 72) StreamStage 0 0 0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,699 StatusLogger.java (line 72) MemtablePostFlusher 0 0 0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,699 StatusLogger.java (line 72) FlushWriter 0 0 0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,700 StatusLogger.java (line 72) MiscStage 0 0 0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,700 StatusLogger.java (line 72) commitlog_archiver 0 0 0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,700 StatusLogger.java (line 72) InternalResponseStage 0 0 0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,701 StatusLogger.java (line 72) AntiEntropySessions 0 0 0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,701 StatusLogger.java (line 72) HintedHandoff 0 0 0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,702 StatusLogger.java (line 77) CompactionManager 2 4 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,702 StatusLogger.java (line 89) MessagingService n/a 24,229 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,702 StatusLogger.java (line 99) Cache Type Size Capacity KeysToSave Provider INFO [ScheduledTasks:1] 2012-12-04 09:00:37,702 StatusLogger.java (line 100) KeyCache 2184533 2184533 all INFO [ScheduledTasks:1] 2012-12-04 09:00:37,703 StatusLogger.java (line 106) RowCache 52385581 52428800 all org.apache.cassandra.cache.SerializingCacheProvider INFO [ScheduledTasks:1] 2012-12-04 09:00:37,703 StatusLogger.java (line 113) ColumnFamily Memtable ops,data INFO [ScheduledTasks:1] 2012-12-04 09:00:37,703 StatusLogger.java (line 116) system.NodeIdInfo 0,0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,704 StatusLogger.java (line 116) system.IndexInfo 0,0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,705 StatusLogger.java (line 116) system.LocationInfo 0,0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,705 StatusLogger.java (line 116) system.Versions 0,0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,705 StatusLogger.java (line 116) system.schema_keyspaces 0,0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,705 StatusLogger.java (line 116) system.Migrations 0,0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,706 StatusLogger.java (line 116) system.schema_columnfamilies 0,0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,706 StatusLogger.java (line 116) system.schema_columns 0,0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,706 StatusLogger.java (line 116) system.HintsColumnFamily 0,0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,706 StatusLogger.java (line 116) system.Schema 0,0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,707 StatusLogger.java (line 116) open.comp 0,0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,707 StatusLogger.java (line 116) open.bp 0,0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,707 StatusLogger.java (line 116) open.bn 312832,47184787 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,707 StatusLogger.java (line 116) open.p 711,193201 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,707 StatusLogger.java (line 116) open.bid 273064,46316018 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,708 StatusLogger.java (line 116) open.rel 0,0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,708 StatusLogger.java (line 116) open.images 0,0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,708 StatusLogger.java (line 116) open.users 62287,86665510 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,708 StatusLogger.java (line 116) open.sessions 4710,13153051 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,709 StatusLogger.java (line 116) open.userIndices 4,1960 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,709 StatusLogger.java (line 116) open.caches 50,4813457 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,709 StatusLogger.java (line 116) open.content 0,0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,710 StatusLogger.java (line 116) open.enrich 30,20793 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,744 StatusLogger.java (line 116) open.bt 1133,776831 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,863 StatusLogger.java (line 116) open.alias 253,163933 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,864 StatusLogger.java (line 116) open.bymsgid 249610,73075517 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,864 StatusLogger.java (line 116) open.rank 319956,70898417 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,865 StatusLogger.java (line 116) open.cmap 448,406193 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,865 StatusLogger.java (line 116) open.pmap 659,566220 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,865 StatusLogger.java (line 116) open.pict 50944,58659596 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,878 StatusLogger.java (line 116) open.w 0,0 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,879 StatusLogger.java (line 116) open.s 92395,46160381 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,879 StatusLogger.java (line 116) open.bymrel 136607,57780555 INFO [ScheduledTasks:1] 2012-12-04 09:00:37,879 StatusLogger.java (line 116) open.m 26720,51150067 It's appreciated, Thanks, -Mike