You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@cassandra.apache.org by Gabriel Tataranu <ga...@wajam.com> on 2011/05/11 20:55:20 UTC
Excessive allocation during hinted handoff
Greetings,
I'm experiencing some issues with 2 nodes (out of more than 10). Right
after startup (Listening for thrift clients...) the nodes will create
objects at high rate using all available CPU cores:
INFO 18:13:15,350 GC for PS Scavenge: 292 ms, 494902976 reclaimed
leaving 2024909864 used; max is 6658457600
INFO 18:13:20,393 GC for PS Scavenge: 252 ms, 478691280 reclaimed
leaving 2184252600 used; max is 6658457600
....
INFO 18:15:23,909 GC for PS Scavenge: 283 ms, 452943472 reclaimed
leaving 5523891120 used; max is 6658457600
INFO 18:15:24,912 GC for PS Scavenge: 273 ms, 466157568 reclaimed
leaving 5594606128 used; max is 6658457600
This will eventually trigger old-gen GC and then the process repeats
until hinted handoff finishes.
The build version was updated from 0.7.2 to 0.7.5 but the behavior was
exactly the same.
Thank you.
Re: Excessive allocation during hinted handoff
Posted by Gabriel Tataranu <ga...@wajam.com>.
> An if you have 10 nodes, do all of them happen to send hints to the two
> with GC?
The 2 nodes are adjacent in token range. They are replicating to each other.
Other nodes have no data to replicate so there's no proof one way or
another.
Best,
Gabriel
Re: Excessive allocation during hinted handoff
Posted by Terje Marthinussen <tm...@gmail.com>.
An if you have 10 nodes, do all of them happen to send hints to the two with
GC?
Terje
On Thu, May 12, 2011 at 6:10 PM, Terje Marthinussen <tmarthinussen@gmail.com
> wrote:
> Just out of curiosity is this on the receiver or sender side?
>
> I have been wondering a bit if the hint playback could need some
> adjustment.
> There is potentially quite big differences on how much is sent per throttle
> delay time depending on what your data looks like.
>
> Early 0.7 releases also built up hints very easily under load due to nodes
> quickly getting marked as down due to gossip sharing the same thread as many
> other operations.
>
> Terje
>
> On Thu, May 12, 2011 at 1:28 PM, Jonathan Ellis <jb...@gmail.com> wrote:
>
>> Doesn't really look abnormal to me for a heavy write load situation
>> which is what "receiving hints" is.
>>
>> On Wed, May 11, 2011 at 1:55 PM, Gabriel Tataranu <ga...@wajam.com>
>> wrote:
>> > Greetings,
>> >
>> > I'm experiencing some issues with 2 nodes (out of more than 10). Right
>> > after startup (Listening for thrift clients...) the nodes will create
>> > objects at high rate using all available CPU cores:
>> >
>> > INFO 18:13:15,350 GC for PS Scavenge: 292 ms, 494902976 reclaimed
>> > leaving 2024909864 used; max is 6658457600
>> > INFO 18:13:20,393 GC for PS Scavenge: 252 ms, 478691280 reclaimed
>> > leaving 2184252600 used; max is 6658457600
>> > ....
>> > INFO 18:15:23,909 GC for PS Scavenge: 283 ms, 452943472 reclaimed
>> > leaving 5523891120 used; max is 6658457600
>> > INFO 18:15:24,912 GC for PS Scavenge: 273 ms, 466157568 reclaimed
>> > leaving 5594606128 used; max is 6658457600
>> >
>> > This will eventually trigger old-gen GC and then the process repeats
>> > until hinted handoff finishes.
>> >
>> > The build version was updated from 0.7.2 to 0.7.5 but the behavior was
>> > exactly the same.
>> >
>> > Thank you.
>> >
>> >
>>
>>
>>
>> --
>> Jonathan Ellis
>> Project Chair, Apache Cassandra
>> co-founder of DataStax, the source for professional Cassandra support
>> http://www.datastax.com
>>
>
>
Re: Excessive allocation during hinted handoff
Posted by Gabriel Tataranu <ga...@wajam.com>.
Greetings,
> Just out of curiosity is this on the receiver or sender side?
Looks like sender side, although the 2 nodes were replicating to each
other so it's hard to tell.
>
> I have been wondering a bit if the hint playback could need some
> adjustment.
> There is potentially quite big differences on how much is sent per
> throttle delay time depending on what your data looks like.
>
> Early 0.7 releases also built up hints very easily under load due to
> nodes quickly getting marked as down due to gossip sharing the same
> thread as many other operations.
Like I said, cassandra was updated to 0.7.5 (latest build as of today)
following the advice on IRC. There was no change in behavior.
Best,
Gabriel
Re: Excessive allocation during hinted handoff
Posted by Terje Marthinussen <tm...@gmail.com>.
Just out of curiosity is this on the receiver or sender side?
I have been wondering a bit if the hint playback could need some
adjustment.
There is potentially quite big differences on how much is sent per throttle
delay time depending on what your data looks like.
Early 0.7 releases also built up hints very easily under load due to nodes
quickly getting marked as down due to gossip sharing the same thread as many
other operations.
Terje
On Thu, May 12, 2011 at 1:28 PM, Jonathan Ellis <jb...@gmail.com> wrote:
> Doesn't really look abnormal to me for a heavy write load situation
> which is what "receiving hints" is.
>
> On Wed, May 11, 2011 at 1:55 PM, Gabriel Tataranu <ga...@wajam.com>
> wrote:
> > Greetings,
> >
> > I'm experiencing some issues with 2 nodes (out of more than 10). Right
> > after startup (Listening for thrift clients...) the nodes will create
> > objects at high rate using all available CPU cores:
> >
> > INFO 18:13:15,350 GC for PS Scavenge: 292 ms, 494902976 reclaimed
> > leaving 2024909864 used; max is 6658457600
> > INFO 18:13:20,393 GC for PS Scavenge: 252 ms, 478691280 reclaimed
> > leaving 2184252600 used; max is 6658457600
> > ....
> > INFO 18:15:23,909 GC for PS Scavenge: 283 ms, 452943472 reclaimed
> > leaving 5523891120 used; max is 6658457600
> > INFO 18:15:24,912 GC for PS Scavenge: 273 ms, 466157568 reclaimed
> > leaving 5594606128 used; max is 6658457600
> >
> > This will eventually trigger old-gen GC and then the process repeats
> > until hinted handoff finishes.
> >
> > The build version was updated from 0.7.2 to 0.7.5 but the behavior was
> > exactly the same.
> >
> > Thank you.
> >
> >
>
>
>
> --
> Jonathan Ellis
> Project Chair, Apache Cassandra
> co-founder of DataStax, the source for professional Cassandra support
> http://www.datastax.com
>
Re: Excessive allocation during hinted handoff
Posted by Gabriel Tataranu <ga...@wajam.com>.
Greetings,
> Doesn't really look abnormal to me for a heavy write load situation
> which is what "receiving hints" is.
I would agree with you but this raises some questions about write
performance. Plus I've only seen this kind of behavior recently and only
on 2 adjacent nodes. So I have good reason to believe this is the
exception and not the rule.
Best,
Gabriel
Re: Excessive allocation during hinted handoff
Posted by Jonathan Ellis <jb...@gmail.com>.
Doesn't really look abnormal to me for a heavy write load situation
which is what "receiving hints" is.
On Wed, May 11, 2011 at 1:55 PM, Gabriel Tataranu <ga...@wajam.com> wrote:
> Greetings,
>
> I'm experiencing some issues with 2 nodes (out of more than 10). Right
> after startup (Listening for thrift clients...) the nodes will create
> objects at high rate using all available CPU cores:
>
> INFO 18:13:15,350 GC for PS Scavenge: 292 ms, 494902976 reclaimed
> leaving 2024909864 used; max is 6658457600
> INFO 18:13:20,393 GC for PS Scavenge: 252 ms, 478691280 reclaimed
> leaving 2184252600 used; max is 6658457600
> ....
> INFO 18:15:23,909 GC for PS Scavenge: 283 ms, 452943472 reclaimed
> leaving 5523891120 used; max is 6658457600
> INFO 18:15:24,912 GC for PS Scavenge: 273 ms, 466157568 reclaimed
> leaving 5594606128 used; max is 6658457600
>
> This will eventually trigger old-gen GC and then the process repeats
> until hinted handoff finishes.
>
> The build version was updated from 0.7.2 to 0.7.5 but the behavior was
> exactly the same.
>
> Thank you.
>
>
--
Jonathan Ellis
Project Chair, Apache Cassandra
co-founder of DataStax, the source for professional Cassandra support
http://www.datastax.com
Re: Excessive allocation during hinted handoff
Posted by Gabriel Tataranu <ga...@wajam.com>.
> The number of Completed HH tasks is interesting. AFAIK a task is started when the node detects another in the cluster has returned. Were you doing some other restarts around the cluster ?
Not at all. The restarts seem to happen as normal operation.
>
> I don't want to divert from the GC issue, just wondering if something else is going on as well. Like the node is been asked to record a lot of hints.
NP, this is another issue that a bit weird. Nodes goes MIA and then
return few seconds latter. Not sure why.
In other news, I've discovered than one of the nodes had some
corruption in one of the SSTables - some 1TB record. I'm looking into
cleaning up the data and monitoring the nodes.
Gabriel
Re: Excessive allocation during hinted handoff
Posted by aaron morton <aa...@thelastpickle.com>.
The number of Completed HH tasks is interesting. AFAIK a task is started when the node detects another in the cluster has returned. Were you doing some other restarts around the cluster ?
I don't want to divert from the GC issue, just wondering if something else is going on as well. Like the node is been asked to record a lot of hints.
Cheers
-----------------
Aaron Morton
Freelance Cassandra Developer
@aaronmorton
http://www.thelastpickle.com
On 13 May 2011, at 03:51, Gabriel Tataranu wrote:
>>> What does the TPStats look like on the nodes under pressure ? And how many nodes are delivering hints to the nodes when they restart?
>
> $nodetool -h 127.0.0.1 tpstats
> Pool Name Active Pending Completed
> ReadStage 1 1 1992475
> RequestResponseStage 0 0 2247486
> MutationStage 0 0 1631349
> ReadRepairStage 0 0 583432
> GossipStage 0 0 241324
> AntiEntropyStage 0 0 0
> MigrationStage 0 0 0
> MemtablePostFlusher 0 0 46
> StreamStage 0 0 0
> FlushWriter 0 0 46
> MiscStage 0 0 0
> FlushSorter 0 0 0
> InternalResponseStage 0 0 0
> HintedHandoff 1 5 152
>
>
> dstat -cmdln during the event:
>
> ----total-cpu-usage---- ------memory-usage----- ---load-avg---
> -dsk/total- -net/total-
> usr sys idl wai hiq siq| used buff cach free| 1m 5m 15m | read
> writ| recv send
> 87 6 6 0 0 1|6890M 32.1M 1001M 42.8M|2.36 2.87 1.73| 0
> 0 | 75k 144k
> 88 10 2 0 0 0|6889M 32.2M 1002M 41.6M|3.05 3.00 1.78| 0
> 0 | 60k 102k
> 89 9 2 0 0 0|6890M 32.2M 1003M 41.0M|3.05 3.00 1.78| 0
> 0 | 38k 70k
> 89 10 1 0 0 0|6890M 32.2M 1003M 40.7M|3.05 3.00 1.78| 0
> 0 | 26k 24k
> 93 6 2 0 0 0|6890M 32.2M 1003M 40.9M|3.05 3.00 1.78| 0
> 0 | 37k 31k
> 90 8 2 0 0 0|6890M 32.2M 1003M 39.9M|3.05 3.00 1.78| 0
> 0 | 67k 69k
> 87 8 4 0 0 1|6890M 32.2M 1004M 38.7M|4.09 3.22 1.85| 0
> 0 | 123k 262k
> 83 13 2 0 0 2|6890M 32.2M 1004M 38.3M|4.09 3.22 1.85| 0
> 0 | 445k 18M
> 90 6 3 0 0 0|6890M 32.2M 1005M 38.2M|4.09 3.22 1.85| 0
> 0 | 72k 91k
> 40 7 25 27 0 0|6890M 32.2M 1005M 37.8M|4.09 3.22 1.85| 0
> 0 | 246k 8034k
> 0 0 59 41 0 0|6890M 32.2M 1005M 37.7M|4.09 3.22 1.85| 0
> 0 | 19k 6490B
> 1 2 45 52 0 0|6891M 32.2M 999M 43.1M|4.00 3.21 1.86| 0
> 0 | 29k 18k
> 72 8 15 3 0 1|6892M 32.2M 999M 41.6M|4.00 3.21 1.86| 0
> 0 | 431k 11M
> 88 9 2 0 0 1|6907M 32.0M 985M 41.1M|4.00 3.21 1.86| 0
> 0 | 99k 77k
> 88 10 1 0 0 1|6913M 31.9M 977M 44.1M|4.00 3.21 1.86| 0
> 0 | 112k 619k
> 89 9 1 0 0 1|6892M 31.9M 977M 64.4M|4.00 3.21 1.86| 0
> 0 | 109k 369k
> 90 8 1 0 0 0|6892M 31.9M 979M 62.5M|4.80 3.39 1.92| 0
> 0 | 130k 97k
> 83 13 1 0 0 3|6893M 32.0M 981M 59.8M|4.80 3.39 1.92| 0
> 0 | 503k 18M
> 78 11 10 0 0 0|6893M 32.0M 981M 59.5M|4.80 3.39 1.92| 0
> 0 | 102k 110k
>
>
> The low cpu periods are due to major GC (JVM frozen).
>
>>
>> TPStats do show activity on the HH. I'll have some examples latter if
>> the nodes decide to do this again.
>>
>>>
>>> Finally hinted_handoff_throttle_delay_in_ms in conf/cassandra.yaml will let you slow down the delivery rate if HH is indeed the problem.
>>
>
>
> Best,
>
> Gabriel
>
Re: Excessive allocation during hinted handoff
Posted by Gabriel Tataranu <ga...@wajam.com>.
>> What does the TPStats look like on the nodes under pressure ? And how many nodes are delivering hints to the nodes when they restart?
$nodetool -h 127.0.0.1 tpstats
Pool Name Active Pending Completed
ReadStage 1 1 1992475
RequestResponseStage 0 0 2247486
MutationStage 0 0 1631349
ReadRepairStage 0 0 583432
GossipStage 0 0 241324
AntiEntropyStage 0 0 0
MigrationStage 0 0 0
MemtablePostFlusher 0 0 46
StreamStage 0 0 0
FlushWriter 0 0 46
MiscStage 0 0 0
FlushSorter 0 0 0
InternalResponseStage 0 0 0
HintedHandoff 1 5 152
dstat -cmdln during the event:
----total-cpu-usage---- ------memory-usage----- ---load-avg---
-dsk/total- -net/total-
usr sys idl wai hiq siq| used buff cach free| 1m 5m 15m | read
writ| recv send
87 6 6 0 0 1|6890M 32.1M 1001M 42.8M|2.36 2.87 1.73| 0
0 | 75k 144k
88 10 2 0 0 0|6889M 32.2M 1002M 41.6M|3.05 3.00 1.78| 0
0 | 60k 102k
89 9 2 0 0 0|6890M 32.2M 1003M 41.0M|3.05 3.00 1.78| 0
0 | 38k 70k
89 10 1 0 0 0|6890M 32.2M 1003M 40.7M|3.05 3.00 1.78| 0
0 | 26k 24k
93 6 2 0 0 0|6890M 32.2M 1003M 40.9M|3.05 3.00 1.78| 0
0 | 37k 31k
90 8 2 0 0 0|6890M 32.2M 1003M 39.9M|3.05 3.00 1.78| 0
0 | 67k 69k
87 8 4 0 0 1|6890M 32.2M 1004M 38.7M|4.09 3.22 1.85| 0
0 | 123k 262k
83 13 2 0 0 2|6890M 32.2M 1004M 38.3M|4.09 3.22 1.85| 0
0 | 445k 18M
90 6 3 0 0 0|6890M 32.2M 1005M 38.2M|4.09 3.22 1.85| 0
0 | 72k 91k
40 7 25 27 0 0|6890M 32.2M 1005M 37.8M|4.09 3.22 1.85| 0
0 | 246k 8034k
0 0 59 41 0 0|6890M 32.2M 1005M 37.7M|4.09 3.22 1.85| 0
0 | 19k 6490B
1 2 45 52 0 0|6891M 32.2M 999M 43.1M|4.00 3.21 1.86| 0
0 | 29k 18k
72 8 15 3 0 1|6892M 32.2M 999M 41.6M|4.00 3.21 1.86| 0
0 | 431k 11M
88 9 2 0 0 1|6907M 32.0M 985M 41.1M|4.00 3.21 1.86| 0
0 | 99k 77k
88 10 1 0 0 1|6913M 31.9M 977M 44.1M|4.00 3.21 1.86| 0
0 | 112k 619k
89 9 1 0 0 1|6892M 31.9M 977M 64.4M|4.00 3.21 1.86| 0
0 | 109k 369k
90 8 1 0 0 0|6892M 31.9M 979M 62.5M|4.80 3.39 1.92| 0
0 | 130k 97k
83 13 1 0 0 3|6893M 32.0M 981M 59.8M|4.80 3.39 1.92| 0
0 | 503k 18M
78 11 10 0 0 0|6893M 32.0M 981M 59.5M|4.80 3.39 1.92| 0
0 | 102k 110k
The low cpu periods are due to major GC (JVM frozen).
>
> TPStats do show activity on the HH. I'll have some examples latter if
> the nodes decide to do this again.
>
>>
>> Finally hinted_handoff_throttle_delay_in_ms in conf/cassandra.yaml will let you slow down the delivery rate if HH is indeed the problem.
>
Best,
Gabriel
Re: Excessive allocation during hinted handoff
Posted by Gabriel Tataranu <ga...@wajam.com>.
> I'm assuming the two nodes are the ones receiving the HH after they were down.
Adjacent, so yes.
>
> Are there a lot of hints collected while they are down ? you can check the HintedHandOffManager MBean in JConsole
There wasn't any downtime - that's something else that's weird.
>
> What does the TPStats look like on the nodes under pressure ? And how many nodes are delivering hints to the nodes when they restart?
TPStats do show activity on the HH. I'll have some examples latter if
the nodes decide to do this again.
>
> Finally hinted_handoff_throttle_delay_in_ms in conf/cassandra.yaml will let you slow down the delivery rate if HH is indeed the problem.
That's useful info. Thanks.
Best,
Gabriel
Re: Excessive allocation during hinted handoff
Posted by aaron morton <aa...@thelastpickle.com>.
I'm assuming the two nodes are the ones receiving the HH after they were down.
Are there a lot of hints collected while they are down ? you can check the HintedHandOffManager MBean in JConsole
What does the TPStats look like on the nodes under pressure ? And how many nodes are delivering hints to the nodes when they restart?
Finally hinted_handoff_throttle_delay_in_ms in conf/cassandra.yaml will let you slow down the delivery rate if HH is indeed the problem.
Hope that helps.
-----------------
Aaron Morton
Freelance Cassandra Developer
@aaronmorton
http://www.thelastpickle.com
On 12 May 2011, at 06:55, Gabriel Tataranu wrote:
> Greetings,
>
> I'm experiencing some issues with 2 nodes (out of more than 10). Right
> after startup (Listening for thrift clients...) the nodes will create
> objects at high rate using all available CPU cores:
>
> INFO 18:13:15,350 GC for PS Scavenge: 292 ms, 494902976 reclaimed
> leaving 2024909864 used; max is 6658457600
> INFO 18:13:20,393 GC for PS Scavenge: 252 ms, 478691280 reclaimed
> leaving 2184252600 used; max is 6658457600
> ....
> INFO 18:15:23,909 GC for PS Scavenge: 283 ms, 452943472 reclaimed
> leaving 5523891120 used; max is 6658457600
> INFO 18:15:24,912 GC for PS Scavenge: 273 ms, 466157568 reclaimed
> leaving 5594606128 used; max is 6658457600
>
> This will eventually trigger old-gen GC and then the process repeats
> until hinted handoff finishes.
>
> The build version was updated from 0.7.2 to 0.7.5 but the behavior was
> exactly the same.
>
> Thank you.
>