[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17145048#comment-17145048
]
Sergio Bossa commented on CASSANDRA-15700:
--
[~aleksey] apologies for this late reply. I've pushed the recommended changes,
please have a look when you have a moment.
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Labels: pull-request-available
> Fix For: 4.0-beta
>
> Attachments: Oss40patchedvsOss311.png, Oss40vsOss311.png, oss40.gc,
> oss40_nogc.tar.xz, oss40_system.log
>
> Time Spent: 10m
> Remaining Estimate: 0h
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
> org/apache/cassandra/net/OutboundMessageQueue$1Pruner:onPruned 147
> org/apache/cassandra/net/OutboundConnection$$Lambda$444/740904487:accept 147
> org/apache/cassandra/net/OutboundConnection:onExpired 147
> {noformat}
> And indeed, the {{PrunableArrayQueue:prune()}} self time is dominant:
> {noformat}
> (tprint (top-self-calls oss40nogc "PrunableArrayQueue:prune" 5))
> org/apache/cassandra/net/PrunableArrayQueue:prune 1718
> org/apache/cassandra/net/OutboundConnection:releaseCapacity 27
> java/util/concurrent/ConcurrentHashMap:replaceNode 19
> java/util/concurrent/ConcurrentLinkedQueue:offer 16
> java/util/concurrent/LinkedBlockingQueue:offer 15
> {noformat}
> That said, before proceeding with a PR to fix those issues, I'd like to
> understand: what's the reason to prune so often, rather than just when
> polling the message during delivery? If there's a reason I'm missing, let's
> talk about how to optimize pruning, otherwise let's get rid of that.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail: commits-unsubscr...@cassandra.apache.org
For additional commands, e-mail: commits-h...@cassandra.apache.org
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17126005#comment-17126005
]
Aleksey Yeschenko commented on CASSANDRA-15700:
---
Thanks for your patience overall. Just have a few nits now.
1. Can you change {{maybeUpdateEarliestExpiryTime()}} to have the same
structure as {{maybeUpdateNextExpirationDeadline()}}?
2. In {{add()}}, use the return value of {{maybeUpdateExpiryTime()}} instead of
loading the current value (should be equivalent)?
3. Fix up whitespace in the last commit
4. Check {{Remover}} logic? In particular I don't think {{earliestExpiresAt =
Long.MAX_VALUE;}} belongs there anymore.
And, so long as you don't mind omitting the {{id()}} commit, we can push.
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Labels: pull-request-available
> Fix For: 4.0-beta
>
> Attachments: Oss40patchedvsOss311.png, Oss40vsOss311.png, oss40.gc,
> oss40_nogc.tar.xz, oss40_system.log
>
> Time Spent: 10m
> Remaining Estimate: 0h
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
> org/apache/cassandra/net/OutboundMessageQueue$1Pruner:onPruned 147
> org/apache/cassandra/net/OutboundConnection$$Lambda$444/740904487:accept 147
> org/apache/cassandra/net/OutboundConnection:onExpired 147
> {noformat}
> And indeed, the {{PrunableArrayQueue:prune()}} self time is dominant:
> {noformat}
> (tprint (top-self-calls oss40nogc "PrunableArrayQueue:prune" 5))
> org/apache/cassandra/net/PrunableArrayQueue:prune 1718
> org/apache/cassandra/net/OutboundConnection:releaseCapacity 27
> java/util/concurrent/ConcurrentHashMap:replaceNode 19
> java/util/concurrent/ConcurrentLinkedQueue:offer 16
> java/util/concurrent/LinkedBlockingQueue:offer 15
> {noformat}
> That said, before proceeding with a PR to fix those issues, I'd like to
> understand: what's the reason to prune so often, rather than just when
> polling the message during delivery? If there's a reason I'm missing, let's
> talk about how to optimize pruning, otherwise let's get rid of that.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail:
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17125211#comment-17125211
]
Sergio Bossa commented on CASSANDRA-15700:
--
[~aleksey] thanks for reviewing: getting back to this after two months and
having to rebuild the whole thing in my mind, made me realize how complex this
is, and that I should have put a couple more comments, so apologies and kudos
for getting through it all alone :)
That said, to answer your question straight: the race you point out is
absolutely correct, and was unfortunately overlooked by myself, but there
should be an easy fix. Before going with that, I think I have to clarify first
why I introduced the new {{nextExpirationDeadline}} variable along
{{earliestExpiryTime}}. Simply put, if we only track time via
{{earliestExpiryTime}} during both {{add}} and {{prune}}, we risk getting into
a race where we accumulate an unbounded number of messages until the next
expiration, as shown in the following scenario:
1. {{add}} is called N times with {{earliestExpiryTime}} set as the minimum
time among the added messages; you can't adjust in this case by the current
time otherwise you would never expire (as the time would always shift).
2. {{prune}} is called and {{earliestExpiryTime}} is set as the minimum between
the minimum time among the pruned messages and the current expiry time.
3. This means that any messages arrived between the start and end of the
pruning whose expiry time was not the minimum, but still less than the minimum
expiry time among pruned messages, would be "ignored" and remain in the queue.
At this point you might say it really sounds like the race you discovered and
in a way it is :) Although in the above case the race window would be much
larger (the whole {{prune}}).
Anyway, as I said there should be an easy fix: the deadline should be updated
only if it's actually the minimum value (adjusted by current time), and I've
sent a new commit with such fix. I don't see a way to fix the same kind of
races by just keeping a single variable, but let me know if you find any.
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Labels: pull-request-available
> Fix For: 4.0-beta
>
> Attachments: Oss40patchedvsOss311.png, Oss40vsOss311.png, oss40.gc,
> oss40_nogc.tar.xz, oss40_system.log
>
> Time Spent: 10m
> Remaining Estimate: 0h
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
>
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17124959#comment-17124959
]
Aleksey Yeschenko commented on CASSANDRA-15700:
---
I *think* the way we update times at the end of pruning in this patch is
potentially problematic, but I might be getting this wrong, so pardon me for
any obvious foolishness. Was thinking about this particular scenario:
1. After partial consumption/delivery, thread {{t1}} updates
{{earliestExpiryTime}} with some high value (say, all messages up to now have
been with long timeouts); gets descheduled for a period of time.
2. A different thread, {{t2}}, invokes {{add()}} with an lots of
short-expiration messages, all skipping purging, as the lock is being held by
{{t1}}. Repeatedly updates both {{earliestExpiryTime}} and
{{nextExpirationDeadline}} with a small value
3. Thread {{t1}} is now scheduled again, sets {{nextExpirationDeadline}} to the
high value from step (1)
If there are no {{add()}} incoming and delivery has stalled, we can now hold an
arbitrary # of messages added at step 2, as we use {{nextExpirationDeadline}}
value to determine whether or not pruning is necessary.
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Labels: pull-request-available
> Fix For: 4.0-beta
>
> Attachments: Oss40patchedvsOss311.png, Oss40vsOss311.png, oss40.gc,
> oss40_nogc.tar.xz, oss40_system.log
>
> Time Spent: 10m
> Remaining Estimate: 0h
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
> org/apache/cassandra/net/OutboundMessageQueue$1Pruner:onPruned 147
> org/apache/cassandra/net/OutboundConnection$$Lambda$444/740904487:accept 147
> org/apache/cassandra/net/OutboundConnection:onExpired 147
> {noformat}
> And indeed, the {{PrunableArrayQueue:prune()}} self time is dominant:
> {noformat}
> (tprint (top-self-calls oss40nogc "PrunableArrayQueue:prune" 5))
> org/apache/cassandra/net/PrunableArrayQueue:prune 1718
> org/apache/cassandra/net/OutboundConnection:releaseCapacity 27
> java/util/concurrent/ConcurrentHashMap:replaceNode 19
> java/util/concurrent/ConcurrentLinkedQueue:offer 16
> java/util/concurrent/LinkedBlockingQueue:offer 15
> {noformat}
> That said, before
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17112333#comment-17112333
]
Benedict Elliott Smith commented on CASSANDRA-15700:
That part could also be left to CASSANDRA-15766, which I think is also
addressing this and will do so in a consistent manner across various
NoSpamLogger call sites.
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Labels: pull-request-available
> Fix For: 4.0-beta
>
> Attachments: Oss40patchedvsOss311.png, Oss40vsOss311.png, oss40.gc,
> oss40_nogc.tar.xz, oss40_system.log
>
> Time Spent: 10m
> Remaining Estimate: 0h
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
> org/apache/cassandra/net/OutboundMessageQueue$1Pruner:onPruned 147
> org/apache/cassandra/net/OutboundConnection$$Lambda$444/740904487:accept 147
> org/apache/cassandra/net/OutboundConnection:onExpired 147
> {noformat}
> And indeed, the {{PrunableArrayQueue:prune()}} self time is dominant:
> {noformat}
> (tprint (top-self-calls oss40nogc "PrunableArrayQueue:prune" 5))
> org/apache/cassandra/net/PrunableArrayQueue:prune 1718
> org/apache/cassandra/net/OutboundConnection:releaseCapacity 27
> java/util/concurrent/ConcurrentHashMap:replaceNode 19
> java/util/concurrent/ConcurrentLinkedQueue:offer 16
> java/util/concurrent/LinkedBlockingQueue:offer 15
> {noformat}
> That said, before proceeding with a PR to fix those issues, I'd like to
> understand: what's the reason to prune so often, rather than just when
> polling the message during delivery? If there's a reason I'm missing, let's
> talk about how to optimize pruning, otherwise let's get rid of that.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail: commits-unsubscr...@cassandra.apache.org
For additional commands, e-mail: commits-h...@cassandra.apache.org
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17112255#comment-17112255
]
Aleksey Yeschenko commented on CASSANDRA-15700:
---
On {{id()}} change: the only frequent callers of it are {{onOverloaded()}} and
{{onExpired()}} callbacks, via {{noSpamLogger.warn()}}. To get rid of these we
could pass {{OutboundConnection}} instance as argument itself instead of
explicitly invoking {{id()}}, as {{toString()}} is overloaded to return
{{id()}}, and will only be invoked by formatter if we should log - no more than
once in every 30 seconds. I think the code is a bit cleaner without that
change, though don't mind it too strongly.
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Labels: pull-request-available
> Fix For: 4.0-beta
>
> Attachments: Oss40patchedvsOss311.png, Oss40vsOss311.png, oss40.gc,
> oss40_nogc.tar.xz, oss40_system.log
>
> Time Spent: 10m
> Remaining Estimate: 0h
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
> org/apache/cassandra/net/OutboundMessageQueue$1Pruner:onPruned 147
> org/apache/cassandra/net/OutboundConnection$$Lambda$444/740904487:accept 147
> org/apache/cassandra/net/OutboundConnection:onExpired 147
> {noformat}
> And indeed, the {{PrunableArrayQueue:prune()}} self time is dominant:
> {noformat}
> (tprint (top-self-calls oss40nogc "PrunableArrayQueue:prune" 5))
> org/apache/cassandra/net/PrunableArrayQueue:prune 1718
> org/apache/cassandra/net/OutboundConnection:releaseCapacity 27
> java/util/concurrent/ConcurrentHashMap:replaceNode 19
> java/util/concurrent/ConcurrentLinkedQueue:offer 16
> java/util/concurrent/LinkedBlockingQueue:offer 15
> {noformat}
> That said, before proceeding with a PR to fix those issues, I'd like to
> understand: what's the reason to prune so often, rather than just when
> polling the message during delivery? If there's a reason I'm missing, let's
> talk about how to optimize pruning, otherwise let's get rid of that.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail: commits-unsubscr...@cassandra.apache.org
For additional commands,
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17079208#comment-17079208
]
Sergio Bossa commented on CASSANDRA-15700:
--
Added some more thorough unit tests in the meantime.
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Labels: pull-request-available
> Fix For: 4.0-beta
>
> Attachments: Oss40patchedvsOss311.png, Oss40vsOss311.png, oss40.gc,
> oss40_nogc.tar.xz, oss40_system.log
>
> Time Spent: 10m
> Remaining Estimate: 0h
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
> org/apache/cassandra/net/OutboundMessageQueue$1Pruner:onPruned 147
> org/apache/cassandra/net/OutboundConnection$$Lambda$444/740904487:accept 147
> org/apache/cassandra/net/OutboundConnection:onExpired 147
> {noformat}
> And indeed, the {{PrunableArrayQueue:prune()}} self time is dominant:
> {noformat}
> (tprint (top-self-calls oss40nogc "PrunableArrayQueue:prune" 5))
> org/apache/cassandra/net/PrunableArrayQueue:prune 1718
> org/apache/cassandra/net/OutboundConnection:releaseCapacity 27
> java/util/concurrent/ConcurrentHashMap:replaceNode 19
> java/util/concurrent/ConcurrentLinkedQueue:offer 16
> java/util/concurrent/LinkedBlockingQueue:offer 15
> {noformat}
> That said, before proceeding with a PR to fix those issues, I'd like to
> understand: what's the reason to prune so often, rather than just when
> polling the message during delivery? If there's a reason I'm missing, let's
> talk about how to optimize pruning, otherwise let's get rid of that.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail: commits-unsubscr...@cassandra.apache.org
For additional commands, e-mail: commits-h...@cassandra.apache.org
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17079102#comment-17079102
]
Sergio Bossa commented on CASSANDRA-15700:
--
Thank you both.
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Fix For: 4.0-beta
>
> Attachments: Oss40patchedvsOss311.png, Oss40vsOss311.png, oss40.gc,
> oss40_nogc.tar.xz, oss40_system.log
>
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
> org/apache/cassandra/net/OutboundMessageQueue$1Pruner:onPruned 147
> org/apache/cassandra/net/OutboundConnection$$Lambda$444/740904487:accept 147
> org/apache/cassandra/net/OutboundConnection:onExpired 147
> {noformat}
> And indeed, the {{PrunableArrayQueue:prune()}} self time is dominant:
> {noformat}
> (tprint (top-self-calls oss40nogc "PrunableArrayQueue:prune" 5))
> org/apache/cassandra/net/PrunableArrayQueue:prune 1718
> org/apache/cassandra/net/OutboundConnection:releaseCapacity 27
> java/util/concurrent/ConcurrentHashMap:replaceNode 19
> java/util/concurrent/ConcurrentLinkedQueue:offer 16
> java/util/concurrent/LinkedBlockingQueue:offer 15
> {noformat}
> That said, before proceeding with a PR to fix those issues, I'd like to
> understand: what's the reason to prune so often, rather than just when
> polling the message during delivery? If there's a reason I'm missing, let's
> talk about how to optimize pruning, otherwise let's get rid of that.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail: commits-unsubscr...@cassandra.apache.org
For additional commands, e-mail: commits-h...@cassandra.apache.org
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17078610#comment-17078610
]
Benedict Elliott Smith commented on CASSANDRA-15700:
Your proposed solution sounds great, so there's not much use for me here.
Aleksey is the more natural reviewer anyway.
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Fix For: 4.0-beta
>
> Attachments: Oss40patchedvsOss311.png, Oss40vsOss311.png, oss40.gc,
> oss40_nogc.tar.xz, oss40_system.log
>
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
> org/apache/cassandra/net/OutboundMessageQueue$1Pruner:onPruned 147
> org/apache/cassandra/net/OutboundConnection$$Lambda$444/740904487:accept 147
> org/apache/cassandra/net/OutboundConnection:onExpired 147
> {noformat}
> And indeed, the {{PrunableArrayQueue:prune()}} self time is dominant:
> {noformat}
> (tprint (top-self-calls oss40nogc "PrunableArrayQueue:prune" 5))
> org/apache/cassandra/net/PrunableArrayQueue:prune 1718
> org/apache/cassandra/net/OutboundConnection:releaseCapacity 27
> java/util/concurrent/ConcurrentHashMap:replaceNode 19
> java/util/concurrent/ConcurrentLinkedQueue:offer 16
> java/util/concurrent/LinkedBlockingQueue:offer 15
> {noformat}
> That said, before proceeding with a PR to fix those issues, I'd like to
> understand: what's the reason to prune so often, rather than just when
> polling the message during delivery? If there's a reason I'm missing, let's
> talk about how to optimize pruning, otherwise let's get rid of that.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail: commits-unsubscr...@cassandra.apache.org
For additional commands, e-mail: commits-h...@cassandra.apache.org
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17078557#comment-17078557
]
Aleksey Yeschenko commented on CASSANDRA-15700:
---
I'll take a look soonish.
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Fix For: 4.0-beta
>
> Attachments: Oss40patchedvsOss311.png, Oss40vsOss311.png, oss40.gc,
> oss40_nogc.tar.xz, oss40_system.log
>
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
> org/apache/cassandra/net/OutboundMessageQueue$1Pruner:onPruned 147
> org/apache/cassandra/net/OutboundConnection$$Lambda$444/740904487:accept 147
> org/apache/cassandra/net/OutboundConnection:onExpired 147
> {noformat}
> And indeed, the {{PrunableArrayQueue:prune()}} self time is dominant:
> {noformat}
> (tprint (top-self-calls oss40nogc "PrunableArrayQueue:prune" 5))
> org/apache/cassandra/net/PrunableArrayQueue:prune 1718
> org/apache/cassandra/net/OutboundConnection:releaseCapacity 27
> java/util/concurrent/ConcurrentHashMap:replaceNode 19
> java/util/concurrent/ConcurrentLinkedQueue:offer 16
> java/util/concurrent/LinkedBlockingQueue:offer 15
> {noformat}
> That said, before proceeding with a PR to fix those issues, I'd like to
> understand: what's the reason to prune so often, rather than just when
> polling the message during delivery? If there's a reason I'm missing, let's
> talk about how to optimize pruning, otherwise let's get rid of that.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail: commits-unsubscr...@cassandra.apache.org
For additional commands, e-mail: commits-h...@cassandra.apache.org
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17078510#comment-17078510
]
Sergio Bossa commented on CASSANDRA-15700:
--
{quote}Honestly though it sounds like there is not much between our proposals
now, which is reassuring, so perhaps we should focus on the common ground we
have.
{quote}
Indeed, I think we agree on the necessity to fix this in the least risky way,
which it seems to mean keeping the current pruning implementation and accuracy,
but avoiding it to be run *at every single delivery* (although maybe you
dispute this being the problem, but the collapsed stacks speak soundly about
that).
In the spirit of that, I've fixed the message queue algorithm to compute the
expiration deadline in a way that can be used to actually run the pruning task
_only after such deadline_. I'll give it another review on my own and possibly
add more unit tests (please note the current implementation seems to had none
at all), but performance tests now look much better (orange is patched 4.0):
!Oss40patchedvsOss311.png|width=556,height=299!
Here's the branch:
[https://github.com/sbtourist/cassandra/commits/CASSANDRA-15700]
I understand there's no _panic_ to fix it, and you'll be away the next couple
weeks, but this means realistically postponing this issue for at least 3 weeks,
which will add to the delay we're already accumulating in 4.0 for other
reasons, so maybe you could delegate this to [~aleksey] as you mentioned?
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Fix For: 4.0-beta
>
> Attachments: Oss40patchedvsOss311.png, Oss40vsOss311.png, oss40.gc,
> oss40_nogc.tar.xz, oss40_system.log
>
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
> org/apache/cassandra/net/OutboundMessageQueue$1Pruner:onPruned 147
> org/apache/cassandra/net/OutboundConnection$$Lambda$444/740904487:accept 147
> org/apache/cassandra/net/OutboundConnection:onExpired 147
> {noformat}
> And indeed, the {{PrunableArrayQueue:prune()}} self time is dominant:
> {noformat}
> (tprint (top-self-calls oss40nogc "PrunableArrayQueue:prune" 5))
> org/apache/cassandra/net/PrunableArrayQueue:prune 1718
>
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[ https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17078265#comment-17078265 ] Benedict Elliott Smith commented on CASSANDRA-15700: bq. on what ground you say this is an isolated problem? This appears to be an issue in communication: the word isolated refers to the problem _code_. Please be assured I consider this a _serious_ problem, I am just unconcerned about resolving it. There is no need to panic and rush a fix. bq. I’d still like to understand how the pruning approach we're discussing here is important to the control flow semantics at all In the word of Dirk Gently: everything’s connected :) Your prior alternative proposal to replace the existing semantics involved two distinct changes to control flow, namely introducing a hash timer wheel (something I’m in favour of generally, but demonstrably a control flow change, and preferable to defer until 5.0) and eliminating the expiry on enqueue. I just consider these kinds of change to be riskier at this stage. bq. The collapsed stacks clearly show most time is spent by pruning itself, that is by iterating the queue, rather than by expiring messages I believe it shows as much as 10% of time in real expirations? That is not insignificant, and given how relatively cheap evaluating an expiration is, it _may_ well be the case that the algorithmic inefficiency we are discussing is incidental to the behaviour. bq. to make 4.0 behave as similarly as possible to 3.11 This leaves a significant gap still: 4.0 will use the local node message arrival to determine the timeout for its response, so there is still plenty of scope for messages to expire ahead of 3.x bq. No, I meant to compute the "next expire time" as an approximation of the expire time of the processed messages, rather than relying on exactly computing it via the pruner at every event loop delivery run. bq. We can keep the enqueue() pruning, as that's not the worst offender (see collapsed stacks). The enqueue pruning is cheap because we compute the minimum expiration time, so it is infrequently called; if we only guess this number now, we offer no guarantees the balance of new messages dropped in favour of expired messages. bq. so why adding an additional mechanism and 4th config property (your 20% threshold) Is this an additional mechanism? We already have a mechanism, we just pick our number differently. Guessing at a number is also a mechanism, surely? How would we configure the guess algorithm, and why wouldn’t we expose its parameters? I had assumed we would not make this configurable, in the same way we would not make the assumptions of any guess algorithm configurable, since its purpose is just to guarantee algorithmic complexity and bound how far from our memory limits we permit expired messages to be preferred over unexpired messages. Honestly though it sounds like there is not much between our proposals now, which is reassuring, so perhaps we should focus on the common ground we have. However, I am now on leave so I would appreciate it if you can be patient until I return to continue this discussion. I would also like to look more closely again at the existing behaviour, as the pruning is closely related to the migration of new records from the MPSC queue to the internal queue. I have been trying to respond promptly to your queries, but I feel that in doing so my responses have not been sufficiently well considered, and I would prefer to take time to produce a complete and coherent view and proposal. Is that acceptable to you? > Performance regression on internode messaging > - > > Key: CASSANDRA-15700 > URL: https://issues.apache.org/jira/browse/CASSANDRA-15700 > Project: Cassandra > Issue Type: Bug > Components: Messaging/Internode >Reporter: Sergio Bossa >Assignee: Sergio Bossa >Priority: Normal > Fix For: 4.0 > > Attachments: Oss40vsOss311.png, oss40.gc, oss40_nogc.tar.xz, > oss40_system.log > > > Me and [~jasonstack] have been investigating a performance regression > affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries > like workload, as shown in this plot, where blue is 3.11 and orange is 4.0: > !Oss40vsOss311.png|width=389,height=214! > It's been a bit of a long investigation, but two clues ended up standing out: > 1) An abnormal number of expired messages on 4.0 (as shown in the attached > system log), while 3.11 has almost none. > 2) An abnormal GC activity (as shown in the attached gc log). > Turns out the two are related, as the [on expired > callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462] > creates a huge amount of strings
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17078042#comment-17078042
]
Sergio Bossa commented on CASSANDRA-15700:
--
{quote}This would be a regression from 3.0 unfortunately
{quote}
Oh that's a good point, forgot we do that in 3.0+ too. We can keep the
{{enqueue()}} pruning, as that's not the worst offender (see collapsed stacks).
{quote}I assume you mean to maintain a guess of the number of items we _on
average_ have in the queue?
{quote}
No, I meant to compute the "next expire time" as an approximation of the expire
time of the processed messages, rather than relying on exactly computing it via
the pruner at every event loop delivery run.
{quote}One of the features running through this work is that we make strong
guarantees, and this would weaken that. I would prefer to be able to stipulate
that (e.g.) we never reject an {{enqueue}} if more than 20% of the queue is
already expired.
{quote}
How is that related to what we're discussing? Enqueuing new messages is
regulated by memory limiting, so that's what gives us strong guarantees; also,
we do already prune the backlog if memory limits are met.
{quote}messing with important control flow semantics is something I would
prefer to avoid.
{quote}
I'd still like to understand how the pruning approach we're discussing here is
important to the control flow semantics at all, as I don't think I've got a
clear answer yet, although it might be me missing the point. What I've
heard/understood is:
1) It protects us against saturating memory upon network stalls.
2) It protects us against saturating memory upon too many expired messages.
AFAIU, none of those is accurate, as the current implementation doesn't satisfy
#1, and #2 is covered by the memory limits implementation.
{quote}I think the least risky approach is to change how we compute and select
the expiration time we use for triggering an expiration. This also has the
benefit of maintaining well-define guarantees, is simple, and modifies no
behaviours besides the selection of this value.
{quote}
This is something that can definitely be tried first, to reduce the amount of
pruner runs. I will test this next.
{quote}More specifically (e.g.), you pick a time {{t}}, such that you expect
the set of messages with expiration less than {{t}}, say {{M( Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Fix For: 4.0
>
> Attachments: Oss40vsOss311.png, oss40.gc, oss40_nogc.tar.xz,
> oss40_system.log
>
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17077675#comment-17077675
]
Benedict Elliott Smith commented on CASSANDRA-15700:
I think anyway I've let us get ahead of ourselves, in my race to respond before
disappearing on leave for a period. I hadn't had time to really look at the
code. Aleksey will be better placed to talk about this, as his memory and
understanding of the pruner is likely superior to mine. The semantics of
pruning are actually more intrinsically linked to the queuing than I had
remembered, so all of the above suggestions by both of us probably miss the
mark. Perhaps Aleksey and I can discuss it when I return from leave in a, and
we can make a concrete proposal.
It remains a relatively isolated problem, and nothing that I would be concerned
about causing a delay to GA.
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Fix For: 4.0
>
> Attachments: Oss40vsOss311.png, oss40.gc, oss40_nogc.tar.xz,
> oss40_system.log
>
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
> org/apache/cassandra/net/OutboundMessageQueue$1Pruner:onPruned 147
> org/apache/cassandra/net/OutboundConnection$$Lambda$444/740904487:accept 147
> org/apache/cassandra/net/OutboundConnection:onExpired 147
> {noformat}
> And indeed, the {{PrunableArrayQueue:prune()}} self time is dominant:
> {noformat}
> (tprint (top-self-calls oss40nogc "PrunableArrayQueue:prune" 5))
> org/apache/cassandra/net/PrunableArrayQueue:prune 1718
> org/apache/cassandra/net/OutboundConnection:releaseCapacity 27
> java/util/concurrent/ConcurrentHashMap:replaceNode 19
> java/util/concurrent/ConcurrentLinkedQueue:offer 16
> java/util/concurrent/LinkedBlockingQueue:offer 15
> {noformat}
> That said, before proceeding with a PR to fix those issues, I'd like to
> understand: what's the reason to prune so often, rather than just when
> polling the message during delivery? If there's a reason I'm missing, let's
> talk about how to optimize pruning, otherwise let's get rid of that.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail:
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17077512#comment-17077512
]
Benedict Elliott Smith commented on CASSANDRA-15700:
{quote}Remove pruning and expire time tracking from enqueue.
{quote}
This would be a regression from 3.0 unfortunately, though the semantic for 3.0
was a to use the head of the list, which we could potentially restore (not
necessarily as trivially as might be desired, but it is achievable).
{quote}Compute a weighted average of each message expire time.
{quote}
I assume you mean to maintain a guess of the number of items we _on average_
have in the queue? In which case I am fairly strongly -1 on this category
approach. One of the features running through this work is that we make strong
guarantees, and this would weaken that. I would prefer to be able to stipulate
that (e.g.) we never reject an {{enqueue}} if more than 20% of the queue is
already expired.
{quote}I would personally opt for a fix which doesn't increase overall
complexity
{quote}
Complexity is in the eye of the beholder :) I think the main goal should be
minimising risk to delivery. The stability of this patch has been tested
_fairly_ extensively and so far held up, so messing with important control flow
semantics is something I would prefer to avoid.
I think the least risky approach is to change how we compute and select the
expiration time we use for triggering an expiration. This also has the benefit
of maintaining well-define guarantees, is simple, and modifies no behaviours
besides the selection of this value. For instance, picking an expiration time
that we expect to contain a certain amount of data, then simply tracking
_accurately_ on the delivery thread that it really does so. Once it doesn't, we
prune to pick a better value.
More specifically (e.g.), you pick a time {{t}}, such that you expect the set
of messages with expiration less than {{t}}, say {{M( Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Fix For: 4.0
>
> Attachments: Oss40vsOss311.png, oss40.gc, oss40_nogc.tar.xz,
> oss40_system.log
>
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
>
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17077469#comment-17077469
]
Sergio Bossa commented on CASSANDRA-15700:
--
{quote}So, I'm actually misremembering: though I had thought we scheduled
exactly what you suggest
{quote}
It's ok, I do also forget most stuff past the 24hrs cut-off :)
On a more serious note, I get your point about the need to be precise VS
amortising costs, but wondering what data we have to help with such decision,
if any.
We definitely have evidence that the _current_ implementation massively affects
performance, and given the need to stabilise the codebase upon the 4.0 release,
I would personally opt for a fix which doesn't increase overall complexity, and
rather tries to strike a balance between said complexity and desired accuracy
and performance, along the lines of:
1) Remove pruning and expire time tracking from enqueue.
2) Remove pruning from the event loop delivery run.
3) During event loop delivery:
a) Compute a weighted average of each message expire time.
b) If potentially stalling (flushing over the high water mark), schedule a
background pruning using the computed expire time.
c) If resuming from stalling before the pruning deadline, cancel it (because
we'll keep pruning as we process).
This should be reasonably easy to implement, have decent accuracy, and perform
well, as the expire deadline would be computed on the single threaded event
loop (no contention) and the pruner would only run if actually stalling (which
should *not* be the case most of the time).
How does that sound? Am I missing anything?
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Fix For: 4.0
>
> Attachments: Oss40vsOss311.png, oss40.gc, oss40_nogc.tar.xz,
> oss40_system.log
>
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
> org/apache/cassandra/net/OutboundMessageQueue$1Pruner:onPruned 147
> org/apache/cassandra/net/OutboundConnection$$Lambda$444/740904487:accept 147
> org/apache/cassandra/net/OutboundConnection:onExpired 147
> {noformat}
> And indeed, the {{PrunableArrayQueue:prune()}} self time is dominant:
> {noformat}
> (tprint (top-self-calls oss40nogc "PrunableArrayQueue:prune"
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17077356#comment-17077356
]
Benedict Elliott Smith commented on CASSANDRA-15700:
Sorry, I realise I never made clear in either of my messages a critical fact:
the point of these prunes is not primarily to prune, but to determine when we
must next prune by. It determines this precisely today, and only to the next
precise point, which is of course invalidated whenever we deliver the
soonest-to-expire message. However it should probably be approximate, and
potentially also determine multiple such points at once, so that the linear
cost of deciding this can be amortised effectively.
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Fix For: 4.0
>
> Attachments: Oss40vsOss311.png, oss40.gc, oss40_nogc.tar.xz,
> oss40_system.log
>
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
> org/apache/cassandra/net/OutboundMessageQueue$1Pruner:onPruned 147
> org/apache/cassandra/net/OutboundConnection$$Lambda$444/740904487:accept 147
> org/apache/cassandra/net/OutboundConnection:onExpired 147
> {noformat}
> And indeed, the {{PrunableArrayQueue:prune()}} self time is dominant:
> {noformat}
> (tprint (top-self-calls oss40nogc "PrunableArrayQueue:prune" 5))
> org/apache/cassandra/net/PrunableArrayQueue:prune 1718
> org/apache/cassandra/net/OutboundConnection:releaseCapacity 27
> java/util/concurrent/ConcurrentHashMap:replaceNode 19
> java/util/concurrent/ConcurrentLinkedQueue:offer 16
> java/util/concurrent/LinkedBlockingQueue:offer 15
> {noformat}
> That said, before proceeding with a PR to fix those issues, I'd like to
> understand: what's the reason to prune so often, rather than just when
> polling the message during delivery? If there's a reason I'm missing, let's
> talk about how to optimize pruning, otherwise let's get rid of that.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail: commits-unsubscr...@cassandra.apache.org
For additional commands, e-mail: commits-h...@cassandra.apache.org
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17077336#comment-17077336
]
Benedict Elliott Smith commented on CASSANDRA-15700:
So, I'm actually misremembering: though I had thought we scheduled exactly what
you suggest (for which we must use something like {{earliestExpiresAt}}, and
for which it would need to be maintained) we actually only use it to avoid
wasted work performing a prune on enqueue when it is unnecessary to avoid
head-of-line blocking.
Either way, it's the same basic problem, and the solution is probably to
maintain some kind of minimal histogram of the expiration times that permits us
to prune at worst a little later than we might while bounding the number of
expired messages we leave in place.
It looks like we only schedule regular prunes when disconnected; we should
probably fix that too.
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Fix For: 4.0
>
> Attachments: Oss40vsOss311.png, oss40.gc, oss40_nogc.tar.xz,
> oss40_system.log
>
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
> org/apache/cassandra/net/OutboundMessageQueue$1Pruner:onPruned 147
> org/apache/cassandra/net/OutboundConnection$$Lambda$444/740904487:accept 147
> org/apache/cassandra/net/OutboundConnection:onExpired 147
> {noformat}
> And indeed, the {{PrunableArrayQueue:prune()}} self time is dominant:
> {noformat}
> (tprint (top-self-calls oss40nogc "PrunableArrayQueue:prune" 5))
> org/apache/cassandra/net/PrunableArrayQueue:prune 1718
> org/apache/cassandra/net/OutboundConnection:releaseCapacity 27
> java/util/concurrent/ConcurrentHashMap:replaceNode 19
> java/util/concurrent/ConcurrentLinkedQueue:offer 16
> java/util/concurrent/LinkedBlockingQueue:offer 15
> {noformat}
> That said, before proceeding with a PR to fix those issues, I'd like to
> understand: what's the reason to prune so often, rather than just when
> polling the message during delivery? If there's a reason I'm missing, let's
> talk about how to optimize pruning, otherwise let's get rid of that.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe,
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17077309#comment-17077309
]
Sergio Bossa commented on CASSANDRA-15700:
--
{quote}Delivery will only be scheduled at enqueue if it is not already
processing outstanding work, and though iirc the enqueue operation will itself
forcefully prune in some circumstances, there are anyway no guarantees that new
messages will be arriving to this connection.
{quote}
Correct.
{quote}Delivery will only reschedule itself once the outbound TCP channel has
room, and so in a network outage that does not terminate the connection or
stalled recipient process (for example), where it is making no (or very slow)
progress, it will not be woken up to process further pending messages.
{quote}
Isn't this a problem regardless, given the current implementation? That is, we
currently prune upon:
1) Receiving a new message.
2) Finishing processing messages in an event loop run.
As we said, we have no guarantee we'll keep receiving messages, which rules #1
out, and if the event loop is stalling (i.e. due to network issues or whatever)
we'll not run the message processing loop anyway, which rules #2 out and leaves
us with the same problem of leaving expired messages in the queue.
If this really is the problem we want to solve, which is a bit of an edge case
but fine, something as easy as scheduling a background pruning at the earliest
expiry date before "stalling" (i.e. before setting the connection as
unwritable) would do it (possibly using a Hashed Wheel Timer because the Netty
scheduler sucks a bit at scheduled tasks).
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Fix For: 4.0
>
> Attachments: Oss40vsOss311.png, oss40.gc, oss40_nogc.tar.xz,
> oss40_system.log
>
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
> org/apache/cassandra/net/OutboundMessageQueue$1Pruner:onPruned 147
> org/apache/cassandra/net/OutboundConnection$$Lambda$444/740904487:accept 147
> org/apache/cassandra/net/OutboundConnection:onExpired 147
> {noformat}
> And indeed, the {{PrunableArrayQueue:prune()}} self time is dominant:
> {noformat}
> (tprint (top-self-calls oss40nogc "PrunableArrayQueue:prune" 5))
>
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17077246#comment-17077246
]
Benedict Elliott Smith commented on CASSANDRA-15700:
None of the above factors _guarantee_ that the loop is scheduled promptly. The
loop will only be scheduled at enqueue if it is not already aware of
outstanding work, and if the outbound TCP channel is making no (or very slow)
progress it will not be woken up to process further pending messages.
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Fix For: 4.0
>
> Attachments: Oss40vsOss311.png, oss40.gc, oss40_nogc.tar.xz,
> oss40_system.log
>
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
> org/apache/cassandra/net/OutboundMessageQueue$1Pruner:onPruned 147
> org/apache/cassandra/net/OutboundConnection$$Lambda$444/740904487:accept 147
> org/apache/cassandra/net/OutboundConnection:onExpired 147
> {noformat}
> And indeed, the {{PrunableArrayQueue:prune()}} self time is dominant:
> {noformat}
> (tprint (top-self-calls oss40nogc "PrunableArrayQueue:prune" 5))
> org/apache/cassandra/net/PrunableArrayQueue:prune 1718
> org/apache/cassandra/net/OutboundConnection:releaseCapacity 27
> java/util/concurrent/ConcurrentHashMap:replaceNode 19
> java/util/concurrent/ConcurrentLinkedQueue:offer 16
> java/util/concurrent/LinkedBlockingQueue:offer 15
> {noformat}
> That said, before proceeding with a PR to fix those issues, I'd like to
> understand: what's the reason to prune so often, rather than just when
> polling the message during delivery? If there's a reason I'm missing, let's
> talk about how to optimize pruning, otherwise let's get rid of that.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
-
To unsubscribe, e-mail: commits-unsubscr...@cassandra.apache.org
For additional commands, e-mail: commits-h...@cassandra.apache.org
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17077179#comment-17077179
]
Sergio Bossa commented on CASSANDRA-15700:
--
{quote}This is the only way (presently) to know what deadline the eventLoop
needs to wake up on, to ensure we do not let expiring messages accumulate
indefinitely
{quote}
I'm not sure I follow, it would be great if you could elaborate more, maybe
with some pointers on the code. AFAIU, the "event loop" (assuming you mean the
{{EventLoopDelivery}} class) is potentially scheduled at every new message,
then rescheduling itself based on the number of pending bytes and the writable
state; this means, as long as there are pending bytes, and even if no new
messages arrive, it will keep rescheduling itself and getting rid of expired
messages along the way, so I don't see how they could accumulate indefinitely,
although I might very well missing something. Or you just mean such
"rescheduling to expire" is simply inefficient?
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Fix For: 4.0
>
> Attachments: Oss40vsOss311.png, oss40.gc, oss40_nogc.tar.xz,
> oss40_system.log
>
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
> org/apache/cassandra/net/OutboundMessageQueue$1Pruner:onPruned 147
> org/apache/cassandra/net/OutboundConnection$$Lambda$444/740904487:accept 147
> org/apache/cassandra/net/OutboundConnection:onExpired 147
> {noformat}
> And indeed, the {{PrunableArrayQueue:prune()}} self time is dominant:
> {noformat}
> (tprint (top-self-calls oss40nogc "PrunableArrayQueue:prune" 5))
> org/apache/cassandra/net/PrunableArrayQueue:prune 1718
> org/apache/cassandra/net/OutboundConnection:releaseCapacity 27
> java/util/concurrent/ConcurrentHashMap:replaceNode 19
> java/util/concurrent/ConcurrentLinkedQueue:offer 16
> java/util/concurrent/LinkedBlockingQueue:offer 15
> {noformat}
> That said, before proceeding with a PR to fix those issues, I'd like to
> understand: what's the reason to prune so often, rather than just when
> polling the message during delivery? If there's a reason I'm missing, let's
> talk about how to optimize pruning, otherwise let's get rid of that.
--
This message was sent by
[jira] [Commented] (CASSANDRA-15700) Performance regression on internode messaging
[
https://issues.apache.org/jira/browse/CASSANDRA-15700?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17077168#comment-17077168
]
Benedict Elliott Smith commented on CASSANDRA-15700:
Thanks for the bug report, this is very valuable.
bq. what's the reason to prune so often, rather than just when polling the
message during delivery?
This is the only way (presently) to know what deadline the eventLoop needs to
wake up on, to ensure we do not let expiring messages accumulate indefinitely,
without maintaining an auxiliary structure of expirations or introducing a more
sophisticated queue for maintaining QoS. It is not an astonishing surprise to
see this report, though we had been reassured by this path's absence so far in
other testing, as we consciously implemented a suboptimal approach to keep the
patch tractable. We expected that this work would be self limiting - a cluster
_shouldn't_ have a backlog that dominates unless there are network problems, or
if the receiving node is getting backed up, in which case you would expect
expiry itself to dominate since the cost of performing expiration _should_ be
quite low. Clearly that isn't the case here; fortunately there are numerous
solutions to this problem, none of which are super onerous.
> Performance regression on internode messaging
> -
>
> Key: CASSANDRA-15700
> URL: https://issues.apache.org/jira/browse/CASSANDRA-15700
> Project: Cassandra
> Issue Type: Bug
> Components: Messaging/Internode
>Reporter: Sergio Bossa
>Assignee: Sergio Bossa
>Priority: Normal
> Fix For: 4.0
>
> Attachments: Oss40vsOss311.png, oss40.gc, oss40_nogc.tar.xz,
> oss40_system.log
>
>
> Me and [~jasonstack] have been investigating a performance regression
> affecting 4.0 during a 3 nodes, RF 3 write throughput test with a timeseries
> like workload, as shown in this plot, where blue is 3.11 and orange is 4.0:
> !Oss40vsOss311.png|width=389,height=214!
> It's been a bit of a long investigation, but two clues ended up standing out:
> 1) An abnormal number of expired messages on 4.0 (as shown in the attached
> system log), while 3.11 has almost none.
> 2) An abnormal GC activity (as shown in the attached gc log).
> Turns out the two are related, as the [on expired
> callback|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundConnection.java#L462]
> creates a huge amount of strings in the {{id()}} call. The next question is
> what causes all those message expirations; we thoroughly reviewed the
> internode messaging code and the only issue we could find so far is related
> to the "batch pruning" calls
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L81]
> and
> [here|https://github.com/apache/cassandra/blob/trunk/src/java/org/apache/cassandra/net/OutboundMessageQueue.java#L188]:
> it _seems_ too much time is spent on those, causing the event loop to fall
> behind in processing the rest of the messages, which will end up being
> expired. This is supported by the analysis of the collapsed stacks (after
> fixing the GC issue):
> {noformat}
> (tprint (top-aggregated-calls oss40nogc "EventLoopDelivery:doRun" 5))
> org/apache/cassandra/net/OutboundConnection$EventLoopDelivery:doRun 3456
> org/apache/cassandra/net/OutboundMessageQueue:access$600 1621
> org/apache/cassandra/net/PrunableArrayQueue:prune 1621
> org/apache/cassandra/net/OutboundMessageQueue$WithLock:close 1621
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1620
> {noformat}
> Those are the top 5 sampled calls from {{EventLoopDelivery#doRun()}} which
> spends half of its time pruning. But only a tiny portion of such pruning time
> is spent actually expiring:
> {noformat}
> (tprint (top-aggregated-calls oss40nogc
> "OutboundMessageQueue:pruneInternalQueueWithLock" 5))
> org/apache/cassandra/net/OutboundMessageQueue:pruneInternalQueueWithLock 1900
> org/apache/cassandra/net/PrunableArrayQueue:prune 1894
> org/apache/cassandra/net/OutboundMessageQueue$1Pruner:onPruned 147
> org/apache/cassandra/net/OutboundConnection$$Lambda$444/740904487:accept 147
> org/apache/cassandra/net/OutboundConnection:onExpired 147
> {noformat}
> And indeed, the {{PrunableArrayQueue:prune()}} self time is dominant:
> {noformat}
> (tprint (top-self-calls oss40nogc "PrunableArrayQueue:prune" 5))
> org/apache/cassandra/net/PrunableArrayQueue:prune 1718
> org/apache/cassandra/net/OutboundConnection:releaseCapacity 27
> java/util/concurrent/ConcurrentHashMap:replaceNode 19
> java/util/concurrent/ConcurrentLinkedQueue:offer 16
> java/util/concurrent/LinkedBlockingQueue:offer 15
> {noformat}
> That said, before proceeding with a PR to fix those issues,
