You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cassandra.apache.org by "Tyler Hobbs (JIRA)" <ji...@apache.org> on 2012/08/23 20:44:42 UTC
[jira] [Created] (CASSANDRA-4573) HSHA doesn't handle large
messages gracefully
Tyler Hobbs created CASSANDRA-4573:
--------------------------------------
Summary: HSHA doesn't handle large messages gracefully
Key: CASSANDRA-4573
URL: https://issues.apache.org/jira/browse/CASSANDRA-4573
Project: Cassandra
Issue Type: Bug
Components: Core
Reporter: Tyler Hobbs
Assignee: Vijay
HSHA doesn't seem to enforce any kind of max message length, and when messages are too large, it doesn't fail gracefully.
With debug logs enabled, you'll see this:
{{DEBUG 13:13:31,805 Unexpected state 16}}
Which seems to mean that there's a SelectionKey that's valid, but isn't ready for reading, writing, or accepting.
Client-side, you'll get this thrift error (while trying to read a frame as part of {{recv_batch_mutate}}):
{{TTransportException: TSocket read 0 bytes}}
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (CASSANDRA-4573) HSHA doesn't handle large
messages gracefully
Posted by "Vijay (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/CASSANDRA-4573?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13454602#comment-13454602 ]
Vijay commented on CASSANDRA-4573:
----------------------------------
Hi Tyler, I am not able to re-produce it so far. I am running 2GB/400MB on AWS M4XL....
[ec2-user@ip-10-82-21-221 ~]$ grep -i ThriftServer.java /mnt/log/cassandra/system.log
INFO [main] 2012-09-11 21:52:43,702 ThriftServer.java (line 112) Binding thrift service to localhost/127.0.0.1:9160
INFO [main] 2012-09-11 21:52:43,704 ThriftServer.java (line 121) Using TFastFramedTransport with a max frame size of 15728640 bytes.
INFO [main] 2012-09-11 21:52:43,710 ThriftServer.java (line 191) Using custom half-sync/half-async thrift server on localhost/127.0.0.1 : 9160
INFO [Thread-2] 2012-09-11 21:52:43,720 ThriftServer.java (line 200) Listening for thrift clients...
[ec2-user@ip-10-82-21-221 ~]$
The Timeout happens both in Sync and HSHA servers (randomly and i am not able to reproduce both cases reliably) and the only thing which i can notice is that the client (pycassa) runs 100% CPU most of the time... other than that everything else looks normal.
> HSHA doesn't handle large messages gracefully
> ---------------------------------------------
>
> Key: CASSANDRA-4573
> URL: https://issues.apache.org/jira/browse/CASSANDRA-4573
> Project: Cassandra
> Issue Type: Bug
> Components: Core
> Reporter: Tyler Hobbs
> Assignee: Vijay
> Attachments: repro.py
>
>
> HSHA doesn't seem to enforce any kind of max message length, and when messages are too large, it doesn't fail gracefully.
> With debug logs enabled, you'll see this:
> {{DEBUG 13:13:31,805 Unexpected state 16}}
> Which seems to mean that there's a SelectionKey that's valid, but isn't ready for reading, writing, or accepting.
> Client-side, you'll get this thrift error (while trying to read a frame as part of {{recv_batch_mutate}}):
> {{TTransportException: TSocket read 0 bytes}}
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (CASSANDRA-4573) HSHA doesn't handle large
messages gracefully
Posted by "Tyler Hobbs (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/CASSANDRA-4573?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Tyler Hobbs updated CASSANDRA-4573:
-----------------------------------
Attachment: repro.py
The attached repro.py reproduces the issue using pycassa, but I can also reproduce with phpcassa. I'm testing against 1.1.4, with the only change to cassandra.yaml being a switch to hsha.
> HSHA doesn't handle large messages gracefully
> ---------------------------------------------
>
> Key: CASSANDRA-4573
> URL: https://issues.apache.org/jira/browse/CASSANDRA-4573
> Project: Cassandra
> Issue Type: Bug
> Components: Core
> Reporter: Tyler Hobbs
> Assignee: Vijay
> Attachments: repro.py
>
>
> HSHA doesn't seem to enforce any kind of max message length, and when messages are too large, it doesn't fail gracefully.
> With debug logs enabled, you'll see this:
> {{DEBUG 13:13:31,805 Unexpected state 16}}
> Which seems to mean that there's a SelectionKey that's valid, but isn't ready for reading, writing, or accepting.
> Client-side, you'll get this thrift error (while trying to read a frame as part of {{recv_batch_mutate}}):
> {{TTransportException: TSocket read 0 bytes}}
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Comment Edited] (CASSANDRA-4573) HSHA doesn't handle large
messages gracefully
Posted by "Vijay (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/CASSANDRA-4573?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13442248#comment-13442248 ]
Vijay edited comment on CASSANDRA-4573 at 8/27/12 2:35 PM:
-----------------------------------------------------------
Hi Tyler, I think the issue is related to GC pause can you conform you see the same?
Run: tail -f /var/log/cassandra/system.log |grep GCInspector
Enable GC logging.
Run: python repro.py
You would see timeout when you see "threads were stopped:" to be > 1.5 Seconds or so.
was (Author: vijay2win@yahoo.com):
Hi Tyler, I think the issue is related to GC pause can you conform you see the same?
Run: tail -f /var/log/cassandra/system.log |grep GCInspector
Enable GC logging.
Run: python repro.py
You would see timeout when you see "threads were stopped:" to be > 1.5 Seconds or so.
HSHA copies the data into memory (Frame buffer) that might cause additional GC pressure, if we are used of having a small heap.
We can try reducing the buffer size in the yaml too.
> HSHA doesn't handle large messages gracefully
> ---------------------------------------------
>
> Key: CASSANDRA-4573
> URL: https://issues.apache.org/jira/browse/CASSANDRA-4573
> Project: Cassandra
> Issue Type: Bug
> Components: Core
> Reporter: Tyler Hobbs
> Assignee: Vijay
> Attachments: repro.py
>
>
> HSHA doesn't seem to enforce any kind of max message length, and when messages are too large, it doesn't fail gracefully.
> With debug logs enabled, you'll see this:
> {{DEBUG 13:13:31,805 Unexpected state 16}}
> Which seems to mean that there's a SelectionKey that's valid, but isn't ready for reading, writing, or accepting.
> Client-side, you'll get this thrift error (while trying to read a frame as part of {{recv_batch_mutate}}):
> {{TTransportException: TSocket read 0 bytes}}
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (CASSANDRA-4573) HSHA doesn't handle large
messages gracefully
Posted by "Tyler Hobbs (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/CASSANDRA-4573?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13442538#comment-13442538 ]
Tyler Hobbs commented on CASSANDRA-4573:
----------------------------------------
Vijay, I'm actually not seeing very long garbage collections, if I'm reading the logs correctly. These are the relevant logs, running with a heap of 2GB and young gen size of 400MB:
{noformat}
{Heap before GC invocations=0 (full 0):
par new generation total 368640K, used 327680K [0x2f200000, 0x48200000, 0x48200000)
eden space 327680K, 100% used [0x2f200000, 0x43200000, 0x43200000)
from space 40960K, 0% used [0x43200000, 0x43200000, 0x45a00000)
to space 40960K, 0% used [0x45a00000, 0x45a00000, 0x48200000)
concurrent mark-sweep generation total 1687552K, used 0K [0x48200000, 0xaf200000, 0xaf200000)
concurrent-mark-sweep perm gen total 16384K, used 14333K [0xaf200000, 0xb0200000, 0xb3200000)
2012-08-27T12:03:56.096-0500: [GC Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 432013312
Max Chunk Size: 432013312
Number of Blocks: 1
Av. Block Size: 432013312
Tree Height: 1
Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
Tree Height: 0
[ParNew
Desired survivor size 20971520 bytes, new threshold 1 (max 1)
- age 1: 2692712 bytes, 2692712 total
: 327680K->2642K(368640K), 0.0564410 secs] 327680K->2642K(2056192K)After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 431996928
Max Chunk Size: 431996928
Number of Blocks: 1
Av. Block Size: 431996928
Tree Height: 1
After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
Tree Height: 0
, 0.0567720 secs] [Times: user=0.03 sys=0.00, real=0.06 secs]
Heap after GC invocations=1 (full 0):
par new generation total 368640K, used 2642K [0x2f200000, 0x48200000, 0x48200000)
eden space 327680K, 0% used [0x2f200000, 0x2f200000, 0x43200000)
from space 40960K, 6% used [0x45a00000, 0x45c94998, 0x48200000)
to space 40960K, 0% used [0x43200000, 0x43200000, 0x45a00000)
concurrent mark-sweep generation total 1687552K, used 0K [0x48200000, 0xaf200000, 0xaf200000)
concurrent-mark-sweep perm gen total 16384K, used 14333K [0xaf200000, 0xb0200000, 0xb3200000)
}
Total time for which application threads were stopped: 0.0576140 seconds
Total time for which application threads were stopped: 0.0080490 seconds
Total time for which application threads were stopped: 0.0000810 seconds
Total time for which application threads were stopped: 0.0000410 seconds
Total time for which application threads were stopped: 0.0000360 seconds
Total time for which application threads were stopped: 0.0000340 seconds
Total time for which application threads were stopped: 0.0000360 seconds
Total time for which application threads were stopped: 0.0000340 seconds
Total time for which application threads were stopped: 0.0000340 seconds
Total time for which application threads were stopped: 0.0000320 seconds
Total time for which application threads were stopped: 0.0000350 seconds
Total time for which application threads were stopped: 0.0000350 seconds
Total time for which application threads were stopped: 0.0000350 seconds
Total time for which application threads were stopped: 0.0000370 seconds
Total time for which application threads were stopped: 0.0000360 seconds
Total time for which application threads were stopped: 0.0000350 seconds
Total time for which application threads were stopped: 0.0000350 seconds
Total time for which application threads were stopped: 0.0000340 seconds
Total time for which application threads were stopped: 0.0000340 seconds
Total time for which application threads were stopped: 0.0000340 seconds
Total time for which application threads were stopped: 0.0000330 seconds
Total time for which application threads were stopped: 0.0000360 seconds
Total time for which application threads were stopped: 0.0000320 seconds
Total time for which application threads were stopped: 0.0000340 seconds
Total time for which application threads were stopped: 0.0000330 seconds
Total time for which application threads were stopped: 0.0000330 seconds
Total time for which application threads were stopped: 0.0000330 seconds
Total time for which application threads were stopped: 0.0000350 seconds
Total time for which application threads were stopped: 0.0000330 seconds
Total time for which application threads were stopped: 0.0000330 seconds
Total time for which application threads were stopped: 0.0000320 seconds
Total time for which application threads were stopped: 0.0000330 seconds
Total time for which application threads were stopped: 0.0000760 seconds
Total time for which application threads were stopped: 0.0000490 seconds
Total time for which application threads were stopped: 0.0000330 seconds
Total time for which application threads were stopped: 0.0000370 seconds
Total time for which application threads were stopped: 0.0000460 seconds
Total time for which application threads were stopped: 0.0000350 seconds
Total time for which application threads were stopped: 0.0004150 seconds
Total time for which application threads were stopped: 0.0001230 seconds
Total time for which application threads were stopped: 0.0035150 seconds
{noformat}
The client-side socket timeout is set to 3 seconds, so it's not hitting that timeout due to garbage collections. I should also note that the client-side error is different when there is a client socket timeout (something like {{TTransportException: timed out reading 4 bytes}}).
> HSHA doesn't handle large messages gracefully
> ---------------------------------------------
>
> Key: CASSANDRA-4573
> URL: https://issues.apache.org/jira/browse/CASSANDRA-4573
> Project: Cassandra
> Issue Type: Bug
> Components: Core
> Reporter: Tyler Hobbs
> Assignee: Vijay
> Attachments: repro.py
>
>
> HSHA doesn't seem to enforce any kind of max message length, and when messages are too large, it doesn't fail gracefully.
> With debug logs enabled, you'll see this:
> {{DEBUG 13:13:31,805 Unexpected state 16}}
> Which seems to mean that there's a SelectionKey that's valid, but isn't ready for reading, writing, or accepting.
> Client-side, you'll get this thrift error (while trying to read a frame as part of {{recv_batch_mutate}}):
> {{TTransportException: TSocket read 0 bytes}}
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (CASSANDRA-4573) HSHA doesn't handle large
messages gracefully
Posted by "Vijay (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/CASSANDRA-4573?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13440941#comment-13440941 ]
Vijay commented on CASSANDRA-4573:
----------------------------------
but Frame size is set for both HSHA and Sync
{code}
TNonblockingServer.Args serverArgs = new TNonblockingServer.Args(serverTransport).inputTransportFactory(inTransportFactory)
.outputTransportFactory(outTransportFactory)
{code}
> HSHA doesn't handle large messages gracefully
> ---------------------------------------------
>
> Key: CASSANDRA-4573
> URL: https://issues.apache.org/jira/browse/CASSANDRA-4573
> Project: Cassandra
> Issue Type: Bug
> Components: Core
> Reporter: Tyler Hobbs
> Assignee: Vijay
> Attachments: repro.py
>
>
> HSHA doesn't seem to enforce any kind of max message length, and when messages are too large, it doesn't fail gracefully.
> With debug logs enabled, you'll see this:
> {{DEBUG 13:13:31,805 Unexpected state 16}}
> Which seems to mean that there's a SelectionKey that's valid, but isn't ready for reading, writing, or accepting.
> Client-side, you'll get this thrift error (while trying to read a frame as part of {{recv_batch_mutate}}):
> {{TTransportException: TSocket read 0 bytes}}
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (CASSANDRA-4573) HSHA doesn't handle large
messages gracefully
Posted by "Jonathan Ellis (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/CASSANDRA-4573?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13440908#comment-13440908 ]
Jonathan Ellis commented on CASSANDRA-4573:
-------------------------------------------
bq. neither does sync
sync does enforce frame size
> HSHA doesn't handle large messages gracefully
> ---------------------------------------------
>
> Key: CASSANDRA-4573
> URL: https://issues.apache.org/jira/browse/CASSANDRA-4573
> Project: Cassandra
> Issue Type: Bug
> Components: Core
> Reporter: Tyler Hobbs
> Assignee: Vijay
> Attachments: repro.py
>
>
> HSHA doesn't seem to enforce any kind of max message length, and when messages are too large, it doesn't fail gracefully.
> With debug logs enabled, you'll see this:
> {{DEBUG 13:13:31,805 Unexpected state 16}}
> Which seems to mean that there's a SelectionKey that's valid, but isn't ready for reading, writing, or accepting.
> Client-side, you'll get this thrift error (while trying to read a frame as part of {{recv_batch_mutate}}):
> {{TTransportException: TSocket read 0 bytes}}
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (CASSANDRA-4573) HSHA doesn't handle large
messages gracefully
Posted by "Vijay (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/CASSANDRA-4573?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13442248#comment-13442248 ]
Vijay commented on CASSANDRA-4573:
----------------------------------
Hi Tyler, I think the issue is related to GC pause can you conform you see the same?
Run: tail -f /var/log/cassandra/system.log |grep GCInspector
Enable GC logging.
Run: python repro.py
You would see timeout when you see "threads were stopped:" to be > 1.5 Seconds or so.
HSHA copies the data into memory (Frame buffer) that might cause additional GC pressure, if we are used of having a small heap.
We can try reducing the buffer size in the yaml too.
> HSHA doesn't handle large messages gracefully
> ---------------------------------------------
>
> Key: CASSANDRA-4573
> URL: https://issues.apache.org/jira/browse/CASSANDRA-4573
> Project: Cassandra
> Issue Type: Bug
> Components: Core
> Reporter: Tyler Hobbs
> Assignee: Vijay
> Attachments: repro.py
>
>
> HSHA doesn't seem to enforce any kind of max message length, and when messages are too large, it doesn't fail gracefully.
> With debug logs enabled, you'll see this:
> {{DEBUG 13:13:31,805 Unexpected state 16}}
> Which seems to mean that there's a SelectionKey that's valid, but isn't ready for reading, writing, or accepting.
> Client-side, you'll get this thrift error (while trying to read a frame as part of {{recv_batch_mutate}}):
> {{TTransportException: TSocket read 0 bytes}}
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (CASSANDRA-4573) HSHA doesn't handle large
messages gracefully
Posted by "Vijay (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/CASSANDRA-4573?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13440837#comment-13440837 ]
Vijay commented on CASSANDRA-4573:
----------------------------------
{quote}
With debug logs enabled, you'll see this:
DEBUG 13:13:31,805 Unexpected state 16
{quote}
Unexpected state 16 means the intrest operation is accept.
If you look at the code it is a while loop (the intrestOps can change between the if conditions) and will be handled in the next iteration.
{quote}
HSHA doesn't seem to enforce any kind of max message length
{quote}
neither does sync :) i can reproduce this error both in Sync and hsha, still trying to see where the timeout comes from though.
> HSHA doesn't handle large messages gracefully
> ---------------------------------------------
>
> Key: CASSANDRA-4573
> URL: https://issues.apache.org/jira/browse/CASSANDRA-4573
> Project: Cassandra
> Issue Type: Bug
> Components: Core
> Reporter: Tyler Hobbs
> Assignee: Vijay
> Attachments: repro.py
>
>
> HSHA doesn't seem to enforce any kind of max message length, and when messages are too large, it doesn't fail gracefully.
> With debug logs enabled, you'll see this:
> {{DEBUG 13:13:31,805 Unexpected state 16}}
> Which seems to mean that there's a SelectionKey that's valid, but isn't ready for reading, writing, or accepting.
> Client-side, you'll get this thrift error (while trying to read a frame as part of {{recv_batch_mutate}}):
> {{TTransportException: TSocket read 0 bytes}}
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira