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 2F2C41040C for ; Wed, 21 Aug 2013 06:58:43 +0000 (UTC) Received: (qmail 76105 invoked by uid 500); 21 Aug 2013 06:58:39 -0000 Delivered-To: apmail-cassandra-user-archive@cassandra.apache.org Received: (qmail 76086 invoked by uid 500); 21 Aug 2013 06:58:39 -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 76078 invoked by uid 99); 21 Aug 2013 06:58:38 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 21 Aug 2013 06:58:38 +0000 X-ASF-Spam-Status: No, hits=2.2 required=5.0 tests=HTML_MESSAGE,RCVD_IN_DNSWL_NONE,SPF_PASS,UNPARSEABLE_RELAY X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of kwright@nanigans.com designates 216.82.243.209 as permitted sender) Received: from [216.82.243.209] (HELO mail1.bemta8.messagelabs.com) (216.82.243.209) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 21 Aug 2013 06:58:33 +0000 Received: from [216.82.242.99:21721] by server-17.bemta-8.messagelabs.com id 41/BF-28028-40564125; Wed, 21 Aug 2013 06:58:12 +0000 X-Env-Sender: kwright@nanigans.com X-Msg-Ref: server-9.tower-131.messagelabs.com!1377068290!21769582!2 X-Originating-IP: [216.166.12.98] X-StarScan-Received: X-StarScan-Version: 6.9.11; banners=-,-,- X-VirusChecked: Checked Received: (qmail 5941 invoked from network); 21 Aug 2013 06:58:11 -0000 Received: from out001.collaborationhost.net (HELO out001.collaborationhost.net) (216.166.12.98) by server-9.tower-131.messagelabs.com with RC4-SHA encrypted SMTP; 21 Aug 2013 06:58:11 -0000 Received: from AUSP01VMBX28.collaborationhost.net ([192.168.20.73]) by AUSP01MHUB07.collaborationhost.net ([10.2.8.242]) with mapi; Wed, 21 Aug 2013 01:57:19 -0500 From: Keith Wright To: "user@cassandra.apache.org" Date: Wed, 21 Aug 2013 01:57:18 -0500 Subject: Re: Nodes get stuck Thread-Topic: Nodes get stuck Thread-Index: Ac6eO61VTnEZYIF2RcG8cIzQAhErJg== Message-ID: In-Reply-To: Accept-Language: en-US Content-Language: en-US X-MS-Has-Attach: X-MS-TNEF-Correlator: user-agent: Microsoft-MacOutlook/14.2.3.120616 acceptlanguage: en-US Content-Type: multipart/alternative; boundary="_000_CE39DA85150E7kwrightnaniganscom_" MIME-Version: 1.0 X-Virus-Checked: Checked by ClamAV on apache.org --_000_CE39DA85150E7kwrightnaniganscom_ Content-Type: text/plain; charset="Windows-1252" Content-Transfer-Encoding: quoted-printable Some last minute info on this to hopefully enlighten. We are doing ~200 re= ads and writes across our 7 node SSD cluster right now (usually can do clos= er to 20K reads at least) and seeing CPU load as follows for the nodes (wit= h some par new to give an idea of GC): 001 =96 1200% (Par New at 120 ms / sec) 002 =96 6% (Par New at 0) 003 =96 600% (Par New at 45 ms / sec) 004 =96 900% 005 =96 500% 006 =96 10% 007 =96 130% There are no compactions running on 001 however I did see a broken pipe err= or in the logs there (see below). Netstats for 001 shows nothing pending. = It appears that all of the load/latency is related to one column family. = You can see cfstats & cfhistograms output below and note that we are using = LCS. I have brought the odd cfhistograms behavior to the thread before and= am not sure what's going on there. We are in a production down situation = right now so any help would be much appreciated!!! Column Family: global_user SSTable count: 7546 SSTables in each level: [2, 10, 106/100, 453, 6975, 0, 0] Space used (live): 83848742562 Space used (total): 83848742562 Number of Keys (estimate): 549792896 Memtable Columns Count: 526746 Memtable Data Size: 117408252 Memtable Switch Count: 0 Read Count: 11673 Read Latency: 1950.062 ms. Write Count: 118588 Write Latency: 0.080 ms. Pending Tasks: 0 Bloom Filter False Positives: 4322 Bloom Filter False Ratio: 0.84066 Bloom Filter Space Used: 383507440 Compacted row minimum size: 73 Compacted row maximum size: 2816159 Compacted row mean size: 324 [kwright@lxpcas001 ~]$ nodetool cfhistograms users global_user users/global_user histograms Offset SSTables Write Latency Read Latency Row Size = Column Count 1 8866 0 0 0 = 3420 2 1001 0 0 0 = 99218975 3 1249 0 0 0 = 319713048 4 1074 0 0 0 = 25073893 5 132 0 0 0 = 15359199 6 0 0 0 0 = 27794925 7 0 12 0 0 = 7954974 8 0 23 0 0 = 7733934 10 0 184 0 0 = 13276275 12 0 567 0 0 = 9077508 14 0 1098 0 0 = 5879292 17 0 2722 0 0 = 5693471 20 0 4379 0 0 = 3204131 24 0 8928 0 0 = 2614995 29 0 13525 0 0 = 1824584 35 0 16759 0 0 = 1265911 42 0 17048 0 0 = 868075 50 0 14162 5 0 = 596417 60 0 11806 15 0 = 467747 72 0 8569 108 0 = 354276 86 0 7042 276 227 = 269987 103 0 5936 372 2972 = 218931 124 0 4538 577 157 = 181360 149 0 2981 1076 7388090 = 144298 179 0 1929 1529 90535838 = 116628 215 0 1081 1450 182701876 = 93378 258 0 499 1125 141393480 = 74052 310 0 124 756 18883224 = 58617 372 0 31 460 24599272 = 45453 446 0 25 247 23516772 = 34310 535 0 10 146 13987584 = 26168 642 0 20 194 12091458 = 19965 770 0 8 196 9269197 = 14649 924 0 9 340 8082898 = 11015 1109 0 9 225 4762865 = 8058 1331 0 9 154 3330110 = 5866 1597 0 8 144 2367615 = 4275 1916 0 1 188 1633608 = 3087 2299 0 4 216 1139820 = 2196 2759 0 5 201 819019 = 1456 3311 0 4 194 600522 = 1135 3973 0 6 181 454566 = 786 4768 0 13 136 353886 = 587 5722 0 6 152 280630 = 400 6866 0 5 80 225545 = 254 8239 0 6 112 183285 = 138 9887 0 0 68 149820 = 109 11864 0 5 99 121722 = 66 14237 0 57 86 98352 = 50 17084 0 18 99 79085 = 35 20501 0 1 93 62423 = 11 24601 0 0 61 49471 = 9 29521 0 0 69 37395 = 5 35425 0 4 56 28611 = 6 42510 0 0 57 21876 = 1 51012 0 9 60 16105 = 0 61214 0 0 52 11996 = 0 73457 0 0 50 8791 = 0 88148 0 0 38 6430 = 0 105778 0 0 25 4660 = 0 126934 0 0 15 3308 = 0 152321 0 0 2 2364 = 0 182785 0 0 0 1631 = 0 219342 0 0 0 1156 = 0 263210 0 0 0 887 = 0 315852 0 0 0 618 = 0 379022 0 0 0 427 = 0 454826 0 0 0 272 = 0 545791 0 0 0 168 = 0 654949 0 0 0 115 = 0 785939 0 0 0 61 = 0 943127 0 0 0 58 = 0 1131752 0 0 0 34 = 0 1358102 0 0 0 19 = 0 1629722 0 0 0 9 = 0 1955666 0 0 0 4 = 0 2346799 0 0 0 5 = 0 2816159 0 0 0 2 = 0 3379391 0 0 0 0 = 0 4055269 0 0 0 0 = 0 4866323 0 0 0 0 = 0 5839588 0 0 0 0 = 0 7007506 0 0 0 0 = 0 8409007 0 0 0 0 = 0 10090808 0 0 0 0 = 0 12108970 0 0 0 0 = 0 14530764 0 0 0 0 = 0 17436917 0 0 0 0 = 0 20924300 0 0 0 0 = 0 25109160 0 0 0 0 = 0 ERROR [WRITE-/10.8.44.98] 2013-08-21 06:50:25,450 OutboundTcpConnection.jav= a (line 197) error writing to /10.8.44.98 java.lang.RuntimeException: java.io.IOException: Broken pipe at org.apache.cassandra.db.ColumnSerializer.serialize(ColumnSerializer.java= :59) at org.apache.cassandra.db.ColumnSerializer.serialize(ColumnSerializer.java= :30) at org.apache.cassandra.db.ColumnFamilySerializer.serialize(ColumnFamilySer= ializer.java:73) at org.apache.cassandra.db.Row$RowSerializer.serialize(Row.java:62) at org.apache.cassandra.db.ReadResponseSerializer.serialize(ReadResponse.ja= va:78) at org.apache.cassandra.db.ReadResponseSerializer.serialize(ReadResponse.ja= va:69) at org.apache.cassandra.net.MessageOut.serialize(MessageOut.java:131) at org.apache.cassandra.net.OutboundTcpConnection.write(OutboundTcpConnecti= on.java:221) at org.apache.cassandra.net.OutboundTcpConnection.writeConnected(OutboundTc= pConnection.java:186) at org.apache.cassandra.net.OutboundTcpConnection.run(OutboundTcpConnection= .java:144) Caused by: java.io.IOException: Broken pipe at sun.nio.ch.FileDispatcherImpl.write0(Native Method) at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:94) at sun.nio.ch.IOUtil.write(IOUtil.java:65) at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:450) at java.nio.channels.Channels.writeFullyImpl(Channels.java:78) at java.nio.channels.Channels.writeFully(Channels.java:98) at java.nio.channels.Channels.access$000(Channels.java:61) at java.nio.channels.Channels$1.write(Channels.java:174) at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) at java.io.BufferedOutputStream.write(BufferedOutputStream.java:126) at org.xerial.snappy.SnappyOutputStream.dump(SnappyOutputStream.java:297) at org.xerial.snappy.SnappyOutputStream.rawWrite(SnappyOutputStream.java:24= 4) at org.xerial.snappy.SnappyOutputStream.write(SnappyOutputStream.java:99) at java.io.DataOutputStream.write(DataOutputStream.java:107) at org.apache.cassandra.utils.ByteBufferUtil.write(ByteBufferUtil.java:328) at org.apache.cassandra.utils.ByteBufferUtil.writeWithLength(ByteBufferUtil= .java:315) at org.apache.cassandra.db.ColumnSerializer.serialize(ColumnSerializer.java= :55) ... 9 more From: Keith Wright > Reply-To: "user@cassandra.apache.org" > Date: Wednesday, August 21, 2013 2:35 AM To: "user@cassandra.apache.org" > Subject: Re: Nodes get stuck Still looking for help! We have stopped almost ALL traffic to the cluster = and still some nodes are showing almost 1000% CPU for cassandra with no ios= tat activity. We were running cleanup on one of the nodes that was not sh= owing load spikes however now when I attempt to stop cleanup there via node= tool stop cleanup the java task for stopping cleanup itself is at 1500% and= has not returned after 2 minutes. This is VERY odd behavior. Any ideas? = Hardware failure? Network? We are not seeing anything there but wanted t= o get ideas. Thanks From: Keith Wright > Reply-To: "user@cassandra.apache.org" > Date: Tuesday, August 20, 2013 8:32 PM To: "user@cassandra.apache.org" > Subject: Nodes get stuck Hi all, We are using C* 1.2.4 with Vnodes and SSD. We have seen behavior recen= tly where 3 of our nodes get locked up in high load in what appears to be a= GC spiral while the rest of the cluster (7 total nodes) appears fine. Whe= n I run a tpstats, I see the following (assuming tpstats returns at all) an= d top shows cassandra pegged at 2000%. Obviously we have a large number of= blocked reads. In the past I could explain this due to unexpectedly wide = rows however we have handled that. When the cluster starts to meltdown lik= e this its hard to get visibility into what's going on and what triggered t= he issue as everything starts to pile on. Opscenter becomes unusable and b= ecause the effected nodes are in GC pressure, getting any data via nodetool= or JMX is also difficult. What do people do to handle these situations? = We are going to start graphing reads/writes/sec/CF to Ganglia in the hopes = that it helps. Thanks Pool Name Active Pending Completed Blocked All= time blocked ReadStage 256 381 1245117434 0 = 0 RequestResponseStage 0 0 1161495947 0 = 0 MutationStage 8 8 481721887 0 = 0 ReadRepairStage 0 0 85770600 0 = 0 ReplicateOnWriteStage 0 0 21896804 0 = 0 GossipStage 0 0 1546196 0 = 0 AntiEntropyStage 0 0 5009 0 = 0 MigrationStage 0 0 1082 0 = 0 MemtablePostFlusher 0 0 10178 0 = 0 FlushWriter 0 0 6081 0 = 2075 MiscStage 0 0 57 0 = 0 commitlog_archiver 0 0 0 0 = 0 AntiEntropySessions 0 0 0 0 = 0 InternalResponseStage 0 0 6 0 = 0 HintedHandoff 1 1 246 0 = 0 Message type Dropped RANGE_SLICE 482 READ_REPAIR 0 BINARY 0 READ 515762 MUTATION 39 _TRACE 0 REQUEST_RESPONSE 29 --_000_CE39DA85150E7kwrightnaniganscom_ Content-Type: text/html; charset="Windows-1252" Content-Transfer-Encoding: quoted-printable
Some last minute info on this t= o hopefully enlighten.  We are doing ~200 reads and writes across our = 7 node SSD cluster right now (usually can do closer to 20K reads at least) = and seeing CPU load as follows for the nodes (with some par new to give an = idea of GC):

001 =96 1200%   (Par New at 120 ms / sec)
002 =96 6% (Par New at 0)
003 =96 600% (Par New at 45 ms / sec)
00= 4 =96 900%
005 =96 500%
006 =96 10%
007 =96 130%
=

There are no compactions running on 001 however I did s= ee a broken pipe error in the logs there (see below).  Netstats for 00= 1 shows nothing pending.  It appears that all of the load/latency is r= elated to one column family.  You can see cfstats & cfhistograms o= utput below and note that we are using LCS.  I have brought the odd cf= histograms behavior to the thread before and am not sure what's going on th= ere.  We are in a production down situation right now so any help woul= d be much appreciated!!!

Column Family: global_user
S= STable count: 7546
SSTables in each level: [2, 10, 106/100, 453, 6975, 0, = 0]
Space used (live): 83848742562
Space used (total): 83848742562
Number= of Keys (estimate): 549792896
Memtable Columns Count: 526746
Memtable Da= ta Size: 117408252
Memtable Switch Count: 0
Read Count: 11673
<= span class=3D"Apple-tab-span" style=3D"white-space:pre"> Read Laten= cy: 1950.062 ms.
Write Count: 118588
Write Latency: 0.080 ms.
<= span class=3D"Apple-tab-span" style=3D"white-space:pre"> Pending Ta= sks: 0
= Bloom Filter False Positives: 4322
Bloom Filter False Ratio: 0.840= 66
Bloom Filter Space Used: 383507440
Compacted row minimum size: 73
Com= pacted row maximum size: 2816159
Compacted row mean size: 324
<= div>
[kwright@lxpcas001 ~]$ nodetool cfhistograms users = global_user
users/global_user histograms
Offset   =    SSTables     Write Latency      Read = Latency          Row Size      Colu= mn Count
1               8866 =                 0     &nb= sp;           0          =       0              342= 0
2               1001   =               0       &nb= sp;         0            =     0          99218975
3 &nb= sp;             1249       &nb= sp;         0            =     0                 0 =         319713048
4       &nbs= p;       1074             &nbs= p;   0                 0  = ;               0       &= nbsp;  25073893
5             =    132                 0 =                 0     &nb= sp;           0          = 15359199
6                = ;  0                 0   =               0       &nb= sp;         0          2779492= 5
7                  = ;0                12     =             0         &nb= sp;       0           7954974
=
8                  0 &nbs= p;              23       =           0           &nb= sp;     0           7733934
10=                 0     &n= bsp;         184           &nb= sp;     0                = 0          13276275
12     &n= bsp;           0          = ;     567                = 0                 0     =       9077508
14          = ;       0              10= 98                 0     =             0         &nb= sp; 5879292
17               &= nbsp; 0              2722     =             0         &nb= sp;       0           5693471
=
20                 0   &n= bsp;          4379         &nb= sp;       0              =   0           3204131
24   &n= bsp;             0        = ;      8928              =   0                 0   =         2614995
29        = ;         0             1= 3525                 0    = ;             0         &= nbsp; 1824584
35              =   0             16759     &nb= sp;           0          =       0           1265911
42                 0    = ;         17048           &nbs= p;     0                 = 0            868075
50    = ;             0         &= nbsp;   14162                 = 5                 0     &= nbsp;      596417
60         &= nbsp;       0             1180= 6                15     &= nbsp;           0         &nbs= p;  467747
72             &nbs= p;   0              8569   &nb= sp;           108         &nbs= p;       0            354276
86                 0  = ;            7042        =       276               = 227            269987
103   &n= bsp;            0        =      5936               = 372              2972     &nbs= p;      218931
124         &nb= sp;      0              4= 538               577     &nbs= p;         157            = ;181360
149               &nbs= p;0              2981     &nbs= p;        1076           73880= 90            144298
179   &nb= sp;            0         =      1929              15= 29          90535838         &= nbsp;  116628
215             =    0              1081   =            1450         1= 82701876             93378
258 &nbs= p;              0       &= nbsp;       499             &n= bsp;1125         141393480         =     74052
310            =    0               124  =             756         =  18883224             58617
37= 2                0     &n= bsp;          31          = ;     460          24599272    = ;         45453
446       &nbs= p;        0             &= nbsp;  25               247   =        23516772           &nbs= p; 34310
535               &nb= sp;0                10    = ;           146          = 13987584             26168
642 &nbs= p;              0       &= nbsp;        20           &nbs= p;   194          12091458     &nbs= p;       19965
770         &nb= sp;      0               =   8               196    =       9269197             146= 49
924                0 &= nbsp;               9     &nbs= p;         340           80828= 98             11015
1109   &n= bsp;           0          = ;       9               2= 25           4762865         &= nbsp;    8058
1331           &= nbsp;   0                 9 &n= bsp;             154       &nb= sp;   3330110              5866
1597               0    = ;             8         &= nbsp;     144           2367615   &= nbsp;          4275
1916     &= nbsp;         0           &nbs= p;     1               188 &nb= sp;         1633608           =    3087
2299             =   0                 4   &= nbsp;           216         &n= bsp; 1139820              2196
2759               0     &nbs= p;           5           =     201            819019   &n= bsp;          1456
3311     &n= bsp;         0            = ;     4               194 &nbs= p;          600522         &nb= sp;    1135
3973           &nb= sp;   0                 6 &nbs= p;             181        = ;    454566               786<= /div>
4768               0   &n= bsp;            13        = ;       136            353886 =               587
5722   =             0         &nb= sp;       6              = 152            280630       &= nbsp;       400
6866         &= nbsp;     0               &nbs= p; 5                80    = ;        225545           &nbs= p;   254
8239             &nbs= p; 0                 6    = ;           112          =  183285               138
9887               0     &nb= sp;           0          =      68            149820 &nb= sp;             109
11864   &n= bsp;          0          =       5               &n= bsp;99            121722      =          66
14237       =        0             &nbs= p;  57                86  = ;           98352         &nbs= p;      50
17084          = ;    0                18 =                99     &nb= sp;       79085             &n= bsp;  35
20501             &nb= sp;0                 1    = ;            93         &= nbsp;   62423                1= 1
24601              0   =               0       &nb= sp;        61            = 49471                 9
= 29521              0      = ;           0           &= nbsp;    69             37395  = ;               5
35425  =            0         &nb= sp;       4              =  56             28611     &nb= sp;           6
42510     &nbs= p;        0             &= nbsp;   0                57 &n= bsp;           21876         &= nbsp;       1
51012         &n= bsp;    0                = 9                60     =         16105            =     0
61214             =  0                 0   &n= bsp;            52        = ;     11996               &nbs= p; 0
73457              0 &nbs= p;               0       =          50           &nb= sp;  8791                 0
88148              0   &nbs= p;             0         =        38             &nb= sp;6430                 0
105778             0       &n= bsp;         0            = ;    25              4660 &nbs= p;               0
126934 &nbs= p;           0           =       0               &nb= sp;15              3308     &n= bsp;           0
152321     &n= bsp;       0              = ;   0                 2  =            2364         =         0
182785         =     0                 0 &= nbsp;               0     &nbs= p;        1631            = ;     0
219342            = ; 0                 0    =             0         &n= bsp;    1156               &nb= sp; 0
263210             0   &= nbsp;             0       &nbs= p;         0             =   887                 0
<= div>315852             0      =           0           &n= bsp;     0               618 &= nbsp;               0
379022 &= nbsp;           0         &nbs= p;       0               =   0               427    =             0
454826    =         0             &n= bsp;   0                 0 &nb= sp;             272       &nbs= p;         0
545791       &nbs= p;     0                 = 0                 0     &= nbsp;         168           &n= bsp;     0
654949           &n= bsp; 0                 0   &nb= sp;             0        =       115               =   0
785939             0  = ;               0       &= nbsp;         0           &nbs= p;    61                 = 0
943127             0    = ;             0         &= nbsp;       0             &nbs= p;  58                 0
=
1131752            0      = ;           0           &= nbsp;     0               &nbs= p;34                 0
13= 58102            0        = ;         0             &= nbsp;   0                19 &n= bsp;               0
1629722 &= nbsp;          0          = ;       0               &= nbsp; 0                 9   &n= bsp;             0
1955666   &= nbsp;        0            = ;     0                 0=                 4     &n= bsp;           0
2346799     &= nbsp;      0              = ;   0                 0  =               5       &n= bsp;         0
2816159       &= nbsp;    0                = ; 0                 0    =             2         &n= bsp;       0
3379391         &= nbsp;  0                 0 &nb= sp;               0      =           0           &n= bsp;     0
4055269           &= nbsp;0                 0   &nb= sp;             0        =         0             &n= bsp;   0
4866323            0 =                 0     &nb= sp;           0          =       0               &n= bsp; 0
5839588            0   =               0       &nb= sp;         0            =     0                 0<= /div>
7007506            0     =             0         &nb= sp;       0              =   0                 0
8409007            0       =           0           &nb= sp;     0                = 0                 0
1009= 0808           0          = ;       0               &= nbsp; 0                 0   &n= bsp;             0
12108970   =         0             &nb= sp;   0                 0 &nbs= p;               0       =           0
14530764      = ;     0                 0=                 0     &n= bsp;           0          = ;       0
17436917         &nb= sp; 0                 0   &nbs= p;             0         =         0             &nb= sp;   0
20924300           0  =               0       &n= bsp;         0            = ;     0                 0=
25109160           0     &nbs= p;           0           =       0               &nb= sp; 0                 0
=

ERROR [WRITE-/10.8.44.98] 2013-08-21 06:50:25,450 = OutboundTcpConnection.java (line 197) error writing to /10.8.44.98
java.lang.RuntimeException: java.io.IOException: Broken pipe
at org.apach= e.cassandra.db.ColumnSerializer.serialize(ColumnSerializer.java:59)
at org.= apache.cassandra.db.ColumnSerializer.serialize(ColumnSerializer.java:30)
at= org.apache.cassandra.db.ColumnFamilySerializer.serialize(ColumnFamilySeria= lizer.java:73)
at org.apache.cassandra.db.Row$RowSerializer.serialize(Row.j= ava:62)
= at org.apache.cassandra.db.ReadResponseSerializer.serialize(ReadRes= ponse.java:78)
at org.apache.cassandra.db.ReadResponseSerializer.serialize(= ReadResponse.java:69)
at org.apache.cassandra.net.MessageOut.serialize(Mess= ageOut.java:131)
at org.apache.cassandra.net.OutboundTcpConnection.write(Ou= tboundTcpConnection.java:221)
at org.apache.cassandra.net.OutboundTcpConnec= tion.writeConnected(OutboundTcpConnection.java:186)
at org.apache.cassand= ra.net.OutboundTcpConnection.run(OutboundTcpConnection.java:144)
= Caused by: java.io.IOException: Broken pipe
at sun.nio.ch.FileDispatcherImp= l.write0(Native Method)
at sun.nio.ch.SocketDispatcher.write(SocketDispatch= er.java:47)
at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:94)
at s= un.nio.ch.IOUtil.write(IOUtil.java:65)
at sun.nio.ch.SocketChannelImpl.writ= e(SocketChannelImpl.java:450)
at java.nio.channels.Channels.writeFullyImpl(= Channels.java:78)
at java.nio.channels.Channels.writeFully(Channels.java:98= )
at java.nio.channels.Channels.access$000(Channels.java:61)
at java.nio.ch= annels.Channels$1.write(Channels.java:174)
at java.io.BufferedOutputStream.= flushBuffer(BufferedOutputStream.java:82)
at java.io.BufferedOutputStream.w= rite(BufferedOutputStream.java:126)
at org.xerial.snappy.SnappyOutputStream= .dump(SnappyOutputStream.java:297)
at org.xerial.snappy.SnappyOutputStream.= rawWrite(SnappyOutputStream.java:244)
at org.xerial.snappy.SnappyOutputStre= am.write(SnappyOutputStream.java:99)
at java.io.DataOutputStream.write(Data= OutputStream.java:107)
at org.apache.cassandra.utils.ByteBufferUtil.write(B= yteBufferUtil.java:328)
at org.apache.cassandra.utils.ByteBufferUtil.writeW= ithLength(ByteBufferUtil.java:315)
at org.apache.cassandra.db.ColumnSeriali= zer.serialize(ColumnSerializer.java:55)
... 9 more


From: Keith = Wright <kwright@nanigans.com= >
Reply-To: "user@cassandra.apache.org" <= user@cassandra.apache.org&= gt;
Date: Wednesday, August 21,= 2013 2:35 AM
To: "user@cassandra.apache.org" &= lt;user@cassandra.apache.org>
Subject: Re: Nodes get s= tuck




Hi all,

&n= bsp;   We are using C* 1.2.4 with Vnodes and SSD.  We have seen b= ehavior recently where 3 of our nodes get locked up in high load in what ap= pears to be a GC spiral while the rest of the cluster (7 total nodes) appea= rs fine.  When I run a tpstats, I see the following (assuming tpstats returns at all) and top shows cassandra pegged= at 2000%.  Obviously we have a large number of blocked reads.  I= n the past I could explain this due to unexpectedly wide rows however we ha= ve handled that.  When the cluster starts to meltdown like this its hard to get visibility into what's going on and = what triggered the issue as everything starts to pile on.  Opscenter b= ecomes unusable and because the effected nodes are in GC pressure, getting = any data via nodetool or JMX is also difficult.  What do people do to handle these situations?  We ar= e going to start graphing reads/writes/sec/CF to Ganglia in the hopes that = it helps.

Thanks

Pool Name   &nb= sp;                Active   Pe= nding      Completed   Blocked  All time blocked
ReadStage                 =       256       381     1245117434 =         0             &nb= sp;   0
RequestResponseStage         &nb= sp;    0         0     1161495947 &= nbsp;       0             &nbs= p;   0
MutationStage           &nbs= p;         8         8    = ;  481721887         0        =         0
ReadRepairStage     &nbs= p;             0         = 0       85770600         0    =             0
ReplicateOnWriteStag= e             0         0=       21896804         0     =             0
GossipStage   &n= bsp;                   0  = ;       0        1546196     &= nbsp;   0                 0
AntiEntropyStage               &= nbsp;  0         0         &nb= sp; 5009         0           &= nbsp;     0
MigrationStage         =            0         0 &n= bsp;         1082         0   =               0
MemtablePostFl= usher               0     &nbs= p;   0          10178       &n= bsp; 0                 0
= FlushWriter                   =     0         0         &= nbsp; 6081         0          =    2075
MiscStage           &= nbsp;             0       &nbs= p; 0             57       &nbs= p; 0                 0
co= mmitlog_archiver                0 &= nbsp;       0             &nbs= p;0         0            =     0
AntiEntropySessions         =       0         0       &= nbsp;      0         0     &nb= sp;           0
InternalResponseStage &n= bsp;           0         0 &nb= sp;            6         = 0                 0
Hinte= dHandoff                   &nb= sp; 1         1           &nbs= p;246         0           &nbs= p;     0

Message type     &nbs= p;     Dropped
RANGE_SLICE         =        482
READ_REPAIR       &= nbsp;          0
BINARY     &n= bsp;                 0
RE= AD                    515= 762
MUTATION               &nb= sp;    39
_TRACE           &nb= sp;           0
REQUEST_RESPONSE   =          29

=
--_000_CE39DA85150E7kwrightnaniganscom_--