Thank you very much for your replay~

The full message like this:
DEBUG [Thread-6] 2012-04-24 21:04:11,024 IncomingTcpConnection.java (line 116) Version is now 3

During "blocking time" I only saw this message(appendix shown) and seems everything is blocked.

I logged all cassandra calling time in RPC and there is no large delay but RPC itself delay a lot.
I also using JConsole to monitor the GC time (both cassandra and RPC server) and didn't find large GC delay.
Is my OS blocked during that time? 

I also list tpstats as well as compactionstats in the Appendix. Are there something wrong with my cassandra?

Thank you very much for your help again :)

Appendix:

cassandra debug output block:

DEBUG [Thread-6] 2012-04-24 21:04:11,024 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-7] 2012-04-24 21:04:11,430 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-7] 2012-04-24 21:04:11,431 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-4] 2012-04-24 21:04:11,901 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-4] 2012-04-24 21:04:11,902 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-4] 2012-04-24 21:04:12,024 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-7] 2012-04-24 21:04:12,431 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-7] 2012-04-24 21:04:12,431 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-6] 2012-04-24 21:04:13,024 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-6] 2012-04-24 21:04:13,750 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-6] 2012-04-24 21:04:13,751 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-7] 2012-04-24 21:04:14,025 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-4] 2012-04-24 21:04:14,902 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-4] 2012-04-24 21:04:14,902 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-6] 2012-04-24 21:04:15,025 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-6] 2012-04-24 21:04:15,751 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-6] 2012-04-24 21:04:15,751 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-6] 2012-04-24 21:04:16,025 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-7] 2012-04-24 21:04:16,431 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-7] 2012-04-24 21:04:16,432 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-4] 2012-04-24 21:04:16,902 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-4] 2012-04-24 21:04:16,903 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-7] 2012-04-24 21:04:17,025 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-6] 2012-04-24 21:04:18,025 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-4] 2012-04-24 21:04:18,902 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-4] 2012-04-24 21:04:18,903 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-7] 2012-04-24 21:04:19,026 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-6] 2012-04-24 21:04:19,752 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-6] 2012-04-24 21:04:19,752 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-4] 2012-04-24 21:04:19,903 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-4] 2012-04-24 21:04:19,903 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-6] 2012-04-24 21:04:20,026 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-6] 2012-04-24 21:04:20,752 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-6] 2012-04-24 21:04:20,752 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-7] 2012-04-24 21:04:21,026 IncomingTcpConnection.java (line 116) Version is now 3
DEBUG [Thread-4] 2012-04-24 21:04:22,026 IncomingTcpConnection.java (line 116) Version is now 3

tpstats:

Pool Name                    Active   Pending      Completed   Blocked  All time blocked
ReadStage                         0         0         171002         0                 0
RequestResponseStage      0         0        1016620         0                 0
MutationStage                    0         0         278581         0                 0
ReadRepairStage                0         0              0         0                 0
ReplicateOnWriteStage        0         0              0         0                 0
GossipStage                       0         0        1123513         0                 0
AntiEntropyStage                0         0              0         0                 0
MigrationStage                    0         0              0         0                 0
MemtablePostFlusher          0         0             23         0                 0
StreamStage                       0         0              0         0                 0
FlushWriter                         0         0             23         0                 0
MiscStage                           0         0              0         0                 0
InternalResponseStage         0         0              0         0                 0
HintedHandoff                     0         0              0         0                 0

Message type           Dropped
RANGE_SLICE                  0
READ_REPAIR                  0
BINARY                             0
READ                                0
MUTATION                        0
REQUEST_RESPONSE     0


compactionstats:

pending tasks: 0





2012/4/24 Maki Watanabe <watanabe.maki@gmail.com>
If you set trace level for IncomingTCPConnection, the message "Version
is now ..." will be printed for every inter-cassandra message received
by the node, including Gossip.
Enabling this log in high traffic will saturate IO for your log disk by itself.

You should better to inspect nodetool tpstats, compactionstats at first.

maki

2012/4/24 <hosschao@gmail.com>:
> Does any one have idea for this? Thanks~
>
>
> 2012/4/24 <hosschao@gmail.com>
>>
>> Hi all,
>>
>> I have some troubles of cassandra in my production:
>>
>> I build up a RPC server which using hector client to manipulate the
>> cassandra. Wired things happen nowadays: the latency of RPC sometimes
>> becames very high (10seconds~70seconds) in several minutes and reduce
>> to normal level (30ms in average) after that time. I investigate the
>> debug log of cassandra. During high latency time, the cassandra output
>> lots of message like:
>> "IncomingTcpConnection.java(116) Version is now 3. "
>> Seems everything be blocked during that time.
>>
>> Our settings as following:
>> The version of cassandra is 1.0.1 and hector version is 0.7.0 for the
>> compatible of thrift version which we use (0.5.0)
>> The cluster contains 4 nodes and all of them are seeds. The
>> gcgraceseconds is 0 since we needn't delete the data
>>
>> p.s. It works well for a long time (3 months) but becames crazy these
>> days after we push the new RPC server which supports bigger data
>> saving (2mb in average). I'm not sure if these is the reason.
>>
>> Hope getting your replay~~
>>
>> Thanks,
>>
>> Chao.
>
>