The tpstats shows there was no read request pending on this node. Maybe you should have a look at the other nodes first.
But my suggestion is to upgrade hector to 1.0.x if possible. Hector 0.7 is for cassandra 0.7. Just FYI, we had some issues when upgrading cassandra from 0.8 to 1.0. And the problem went away when we upgraded hector as well. Best, Cheng 2012/4/24 马超 <hossc...@gmail.com> > 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.m...@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 马超 <hossc...@gmail.com>: >> > Does any one have idea for this? Thanks~ >> > >> > >> > 2012/4/24 马超 <hossc...@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. >> > >> > >> > >
