I have made a modification to the JVM row of the Cassandra dashboard in Grafana, which I feel adds some clarity around the garbage collection values.

As per the guidelines here: https://www.robustperception.io/measuring-java-garbage-collection-with-prometheus

I have created separate graphs for:

• Frequency of garbage collections
• Average duration of garbage collections
• Percentage of total time spent collecting garbage

As per the original graphs, these show both old and new generations, but I have also included a combined total percentage of time spent colelcting graph.

I think that these will be useful in tracking down further GC related issues.

For instance:

After the loading jobs that ended shortly after midnight UTC, the behaviour seems much improved compared to yesterday, but there are still some interesting observations and possibly some room for improvement.

We can see a number of effects by delving into the graphs:

• All Cassandra 3 servers spent more time doing GC than Cassandra 2 servers.
• The Cassandra 2 loading finished more quickly than the Cassandra 3 loading.
• Neither cluster spent any appreciable time doing old generation GC. It was all in young generation.
• Cassandra 2 had more pending compactions after the loading than Cassandra 3.

@JAllemandou mentioned the differences in the loading mechanism yesterday, specifically that:

• Cassandra 2 is loaded via a MapReduce job
• Cassandra 3 is loaded via a Spark job
• The batch size is configurable on the MapReduce job, whereas the Spark job is limited instead by a submission size in bytes and this tends to be much smaller than the Cassandra 2 batches. (Is this recollection correct @JAllemandou?)

Should we modify the way that the Cassandra 3 loading works, or do we think that no changes are required at the moment?

Looking at the last 30days of heap usage for 1010-a...

You can see that after the node was restarted (between Dec 14 & 15), usage returned to something more normal looking; GC kicks in at around 13G, and drops to ~6GB after collection. Over time, less and less is collected (the graph flattens).

The other nodes of the new cluster look similar; For comparison, here is 1004-a (from the legacy cluster):

We seem to be accumulating references over time, eventually we run short on room for new allocations, and the JVM thrashes.

A heap dump is likely to be the best means of identifying what is holding up all of this memory. For this to be most effective, we'll want the heap from a JVM that is prominently exhibiting the problem, which means letting at least one node go for a minimum of one week, preferably two.

Capturing the heap dump is straightforward (i.e. jmap -dump:[live],format=b,file=<file-path> <pid>), but analyzing one that is 16G is anything but. In the past, it has taken a host with about as much (free) system memory as the dump is large. Additionally, the (best) tools for this all have a graphical component, so it also needs to have a windowing system (which complicates grabbing a VM somewhere). Hopefully the tooling has gotten better since I last did this...

Thinking ahead somewhat: Assuming we have identified the root cause, our next step would be to establish whether this is reproducible with the most recent Cassandra release. If it's a resource leak of some sort that has since been rectified, then upgrading would be the solution. If not, then we'd need to work on a patch, which should be against the latest release version so that we can commit it upstream. Frankly, we're also well past due for an upgrade.

Just skimming changelog entries between 3.11.4 (what we're running in production) and 3.11.11 (most current release), the following catch my eye:

• Fix memory leak in CompressedChunkReader (CASSANDRA-15880) (3.11.9)
• Fix resource leak in CompressedSequentialWriter (CASSANDRA-15340) (3.11.5)

However, there are over 200 changes between 3.11.4 and 3.11.11, so it's likely there are other candidates as well.

I propose the following (can be worked on concurrently):

• Designate a node(s) to capture a heap dump (basically: avoid restarting until heap utilization portends a death spiral)
• Designate a node to canary an upgrade to 3.11.11

The latter has proven difficult to accomplish cleanly in the past. Ideally, we'd be able to support an arbitrary number of Cassandra versions, and configure the version on a node-by-node basis. I'd very much like to get there one day, but inserting that as a dependency for this probably isn't pragmatic. What I have done previously is to disable Puppet for the duration of the test (to prevent it from attempting to downgrade), and then manually upgrade the node. I think we'd need to plan on having the node in this state for at least a couple of days (preferably a week).

Thoughts?

Could we give the upgrade a try to see if it resolves the memory leak, and if not only then proceed with the profiling?

In T298516#7600211, @odimitrijevic wrote:

Could we give the upgrade a try to see if it resolves the memory leak, and if not only then proceed with the profiling?

We need to wait a few days after upgrading to see whether or not that fixes it. While that's happening (starting now, actually) we can bring another node closer to that inflection point, and capture a dump.

Basically it costs us nothing to do both.

+1 to try both!

I propose to take aheap dump from aqs1014-b which has been running for 3 weeks and 2 days.
Its heap usage graph currently looks like this:

Looking at the GC graphs, it is currently spending more time doing GC than any other instance, but I would not say that it yet portends a death spiral so I plan to leave it over the weekend and try to take a heap dump when it is at its worst.

I'll try to analyse it on my workstation, which has 32 GB of RAM and X11.

I will take a heap dump now anyway, in case I can't catch it at a later state. It might be useful to diff the two (somehow) as well.

I have created the heap dump file. I had to chown to the cassandra user, as even root couldn't connect to the running JVM.

root@aqs1014:~# sudo su - cassandra -s /bin/bash
cassandra@aqs1014:~$ jmap -dump:live,format=b,file=/srv/cassandra-b/tmp/aqs1014-b-dump202201071450.hprof 4468
Dumping heap to /srv/cassandra-b/tmp/aqs1014-b-dump202201071450.hprof ...
Heap dump file created

The file is 13 GB in size.

Compressing the dump file:

root@aqs1014:/srv/cassandra-b/tmp# tar cjvf aqs1014-b-dump202201071450.hprof.bz2 aqs1014-b-dump202201071450.hprof
aqs1014-b-dump202201071450.hprof

I have placed the resulting 2.6 GB bzip2 file at aqs1014.eqiad.wmnet:/home/btullis/aqs1014-b-dump202201071450.hprof.bz2 in case you'd like to take a copy off-host for analysis @Eevans.
I'm currently transferring it to my workstation for analysis. The original, uncompressed 13 GB file is also still in /srv/cassandra-b/tmp.

If this host goes into a period of sustained GC I will take another heap dump using a similar method.

In T298516#7605339, @BTullis wrote:

I have placed the resulting 2.6 GB bzip2 file at aqs1014.eqiad.wmnet:/home/btullis/aqs1014-b-dump202201071450.hprof.bz2 in case you'd like to take a copy off-host for analysis @Eevans.
I'm currently transferring it to my workstation for analysis. The original, uncompressed 13 GB file is also still in /srv/cassandra-b/tmp.

If this host goes into a period of sustained GC I will take another heap dump using a similar method.

Perfect; Thanks @BTullis !

I've been looking at the dump captured on Friday, but I confess that I'm not really certain how to get much information from it.

One thing that is immediately apparent upon loading it into VisualVM is that bytes as opposed to other native java or cassandra objects, take up the vast majority of the size of the dump 79.1%.

This would perhaps fit the hypothesis of a slow memory leak caused by either of the two candidates above, but whilst delving into a few of these memory structures structures at random I couldn't find any specific references to either CompressedChunkReader or CompressedSequentialWriter.

The situation hasn't got noticeably worse since Friday, so I haven't captured another dump yet.

If anyone else has any ideas on how to get more useful information out of the dump file, that would be great.

In T298516#7608491, @BTullis wrote:

[ ... ]
If anyone else has any ideas on how to get more useful information out of the dump file, that would be great.

Regrettably, I don't think VisualVM is up to this task. :(

I've requested an open source YourKit profiler license (yjp). Failing that, my best hope would be that MAT has made some strides since I last looked it. Updates to come...

In T298516#7604802, @BTullis wrote:

I have created the heap dump file. I had to chown to the cassandra user, as even root couldn't connect to the running JVM.

root@aqs1014:~# sudo su - cassandra -s /bin/bash
cassandra@aqs1014:~$ jmap -dump:live,format=b,file=/srv/cassandra-b/tmp/aqs1014-b-dump202201071450.hprof 4468
Dumping heap to /srv/cassandra-b/tmp/aqs1014-b-dump202201071450.hprof ...
Heap dump file created

The file is 13 GB in size.

If you capture another, could you do so without the live option above (just in case)? I.e....

jmap -dump:format=b,file=/srv/cassandra-b/tmp/aqs1014-b-dump202201071450.hprof `cat /var/run/cassandra/cassandra-b.pid`

The trouble is that this pattern has bene stable for 7 days now. aqs1014-b is still fairly busy, with more GC than the other hosts, but it hasn't shown any old generation GCs for a week.

I'm not sure at what point we should just restart it and continue with the migration.

I'm starting to work with mat and its ParseHeapDump.sh script on the existing dump file.

btullis@marlin:~/Downloads/MemoryAnalyzer-1.12.0.20210602-linux.gtk.x86_64/mat$ ./ParseHeapDump.sh ~/tmp/aqs1014-b-dump202201071450.hprof
Task: Parsing aqs1014-b-dump202201071450.hprof
[Task: Parsing /home/btullis/tmp/aqs1014-b-dump202201071450.hprof
[
Subtask: Scanning /home/btullis/tmp/aqs1014-b-dump202201071450.hprof
[
[INFO] Detected compressed references, because with uncompressed 64-bit references the array at 0x3c001bb80 would overlap the array at 0x3c001bb60
[....................
[INFO] Wrote threads call stacks to /home/btullis/tmp/aqs1014-b-dump202201071450.threads
[....................
[INFO] Heap /home/btullis/tmp/aqs1014-b-dump202201071450.hprof contains 69,267,488 objects
[....................
Subtask: Extracting objects from /home/btullis/tmp/aqs1014-b-dump202201071450.hprof
`

Will report back if there is anything interesting.

Change 754988 had a related patch set uploaded (by Btullis; author: Btullis):

[operations/puppet@production] Deploy the dev version of cassandra to aqs1010.eqiad.wmnet

https://gerrit.wikimedia.org/r/754988

By way of an update:

Heap utilization since the 4th has remained stable. Our canary (1014-b) continues to be tight -but hasn't worsened- and none of the other nodes have regressed (1010-a shown in the graph below, for comparison).

I suggest we proceed with the upgrade of 1010 as planned, perform a rolling restart of all nodes, and consider adding some production back while we monitor.

I'm happy to tackle the 1010 update tomorrow (and barring that, Monday?), if that is OK with everyone.

That's great. Thanks for the updated patch Eric. I'm happy for you to go ahead and upgrade aqs1010 whenever you like.

Change 754988 merged by Btullis:

[operations/puppet@production] Deploy the dev version of cassandra to aqs1010.eqiad.wmnet

https://gerrit.wikimedia.org/r/754988

I've merged and deployed the patch, then checked with a puppet run on aqs1010.
The new version of cassandra is ready to be installed whenever you're ready @Eevans.

btullis@aqs1010:~$ apt-cache policy cassandra
cassandra:
  Installed: 3.11.4
  Candidate: 3.11.11
  Version table:
     3.11.11 1001
       1001 http://apt.wikimedia.org/wikimedia buster-wikimedia/component/cassandradev amd64 Packages
 *** 3.11.4 100
        100 /var/lib/dpkg/status
     2.2.6-wmf5 1001
       1001 http://apt.wikimedia.org/wikimedia buster-wikimedia/main amd64 Packages

Mentioned in SAL (#wikimedia-operations) [2022-01-20T20:37:45Z] <urandom> upgrading Cassandra to 3.11.11, aqs1010 -- T298516

Change 755800 had a related patch set uploaded (by Eevans; author: Eevans):

[operations/puppet@production] Pin Cassandra 3.11.11 as 'dev'

https://gerrit.wikimedia.org/r/755800

Change 755800 merged by Cwhite:

[operations/puppet@production] Pin Cassandra 3.11.11 as 'dev'

https://gerrit.wikimedia.org/r/755800

Mentioned in SAL (#wikimedia-operations) [2022-01-20T22:27:08Z] <urandom> rolling restart of Cassandra, aqs-next -- T298516

@JAllemandou noticed several really interesting thing about the Java heap graphs, which might affect how we proceed with this migration.
Firstly, it looks like there is some correllation between the loading of the mediarequest_per_file table (otherwise known as the big table) and the subsequent memory exhaustion.
The loading of the the pageviews_per_article table (otherwise known as the huge table), was completed well before the big table was started and didn't cause this behaviour.

Scratch that previous theory...

Now I look at it more closely, the heap exhaustion seems to correlate much more closely with when aqs1010 was pooled and receiving queries.
The strange thing is that only one host was pooled, but all hosts exhibited the behaviour.

My theory is that it is this bug which is affecting us: Memory leak in CompressedChunkReader

i.e. all the time we are adding data to the cluster, everything is fine. No memory leak.
Whenever we start receiving read requests from the AQS app, the CompresssedChunkReader function comes into play and starts leaking memory.
If the reads are distributed between cluster members then every instance would be leaking memory, irrespective of which node received the client request.

In order to test this theory, I believe that we should:

1. Pool one node - but not aqs1010
2. Watch the graphs of the heap over a few days.

If the theory is correct, then we would expect to see all nodes except aqs1010 exhibit heap exhaustion.
If this happens, that at this point we could say that the upgrade to 3.11.11 fixes the issue and that it should be deployed to the remainder of aqs_next.

If we do not see heap exhaustion even under read load, then we could choose to roll back aqs1010 and complete the migration using 3.11.4 if we wish, or proceed with a plan to roll out 3.11.11 to the rest of the cluster and then complete the migration.

@JAllemandou - @Eevans - What do you think?

If you agree, then I'm ready at any time to do this:

btullis@puppetmaster1001:~$ sudo -i confctl select name=aqs1011.eqiad.wmnet set/pooled=yes

That would send traffic to the two instances on aqs1011 and we could start looking for the heap exhaustion from that point.

Suggestion from @JAllemandou is to wait until mid-week (maybe Tuesday morning 2022-01-25) before pooling it.
Then we've had a few days to monitor aqs1010 with 3.11.11 under normal loading conditions. We will have a few work days in a row to monitor the cluster's behaviour under a little read load.

In T298516#7640651, @BTullis wrote:

Scratch that previous theory...

Now I look at it more closely, the heap exhaustion seems to correlate much more closely with when aqs1010 was pooled and receiving queries.
The strange thing is that only one host was pooled, but all hosts exhibited the behaviour.

My theory is that it is this bug which is affecting us: Memory leak in CompressedChunkReader

Possibly, but the trend seems to start prior to when it was pooled (it seems to begin right after the restart). It also doesn't explain the period preceding that, from ~6th to ~11th.

i.e. all the time we are adding data to the cluster, everything is fine. No memory leak.
Whenever we start receiving read requests from the AQS app, the CompresssedChunkReader function comes into play and starts leaking memory.
If the reads are distributed between cluster members then every instance would be leaking memory, irrespective of which node received the client request.

Strictly speaking, I think CompressedChunkReader is used elsewhere as well (compaction, for example).

In order to test this theory, I believe that we should:

1. Pool one node - but not aqs1010
2. Watch the graphs of the heap over a few days.

If the theory is correct, then we would expect to see all nodes except aqs1010 exhibit heap exhaustion.
If this happens, that at this point we could say that the upgrade to 3.11.11 fixes the issue and that it should be deployed to the remainder of aqs_next.

If we do not see heap exhaustion even under read load, then we could choose to roll back aqs1010 and complete the migration using 3.11.4 if we wish, or proceed with a plan to roll out 3.11.11 to the rest of the cluster and then complete the migration.

@JAllemandou - @Eevans - What do you think?

I think this is consistent with the current/last plan, so SGTM.

In T298516#7640760, @BTullis wrote:

Suggestion from @JAllemandou is to wait until mid-week (maybe Tuesday morning 2022-01-25) before pooling it.
Then we've had a few days to monitor aqs1010 with 3.11.11 under normal loading conditions. We will have a few work days in a row to monitor the cluster's behaviour under a little read load.

Yes, +1 (no sooner than Monday, anyway)

@BTullis: Regarding which node(s) to (re)pool (presumably tomorrow, Jan 25?)...

It shouldn't matter (much) which are/are not pooled. The requests are fielded by RESTBase, each instance of which will distribute requests across all the nodes of the cluster (each of which can in turn serve as coordinator, if needed). Other than perhaps contention for resources under very heavy load (Cassandra v RESTBase), I can't see any reason for a meaningful correlation.

Put another way: I assume that if the first node to fall over last time was also the one pooled, that this was a red herring. So if we see that again, I'd be very interested see what happens if we move the pooled node (it would make for a noteworthy data point).

Mentioned in SAL (#wikimedia-analytics) [2022-01-25T11:30:06Z] <btullis> pooled aqs1011 T298516

After 2 days I think we can begin to see the pattern that we were expecting. Namely that aqs1010 has lower average heap memory use than the other members of the aqs_next cluster.
In order to smooth out the regular GCs I applied an avg_over_time[1h] function to the graph, but we can now see that aqs1010-[ab] have significanlty less heap usage than the other servers.

I'd say that the pattern is clearer again this morning, with both aqs1010 instances exhibiting less average heap usage, and the other instances clearly becoming constrained under pressure from read activity.

• Should we leave aqs1011 pooled over the weekend?
• Should we aim to take heap dumps of a 3.11.4 and a 3.11.11 node at a time of extreme memory pressure?
• Should we start planning to roll out 3.11.11 to other canaries in other Cassandra clusters?

I think that the DE team is keen to leave it running over the weekend to gether more data, but if you have any other suggestions or recommendations please feel free to advise.

In T298516#7659099, @BTullis wrote:

[ ... ]

@Eevans - what course of action do you think we should take next?

• Should we leave aqs1011 pooled over the weekend?
• Should we aim to take heap dumps of a 3.11.4 and a 3.11.11 node at a time of extreme memory pressure?
• Should we start planning to roll out 3.11.11 to other canaries in other Cassandra clusters?

I think that the DE team is keen to leave it running over the weekend to gether more data, but if you have any other suggestions or recommendations please feel free to advise.

Sorry, I meant to reply yesterday, and lost track of it...

I concur with the pattern that seems to be developing, and I too would be interested to see things play out for a more days; I think we can make it through the weekend.

As a next-step, I propose to complete the upgrade to 3.11.11, and repeat the test for a comparable duration.

I'm happy to pick that up first thing Monday, if everyone agrees.

As a next-step, I propose to complete the upgrade to 3.11.11, and repeat the test for a comparable duration.
I'm happy to pick that up first thing Monday, if everyone agrees.

Sounds good to me.

Good for me too! Thanks @BTullis and @Eevans :)

Change 757998 had a related patch set uploaded (by Eevans; author: Eevans):

[operations/puppet@production] Fold-in (minor) upstream configuration changes

https://gerrit.wikimedia.org/r/757998

Change 757999 had a related patch set uploaded (by Eevans; author: Eevans):

[operations/puppet@production] Upgrade remaining aqs_next nodes to 'dev' (Cassandra 3.11.11)

https://gerrit.wikimedia.org/r/757999

For posterity sake:

1010-b / 3.11.11

1014-a / 3.11.4

@JAllemandou @BTullis What do yo think? Shall we proceed?

Yes ! The pattern difference is even more visible here.

Change 757999 merged by Btullis:

[operations/puppet@production] Upgrade remaining aqs_next nodes to 'dev' (Cassandra 3.11.11)

https://gerrit.wikimedia.org/r/757999

@Eevans is going to go ahead with the upgrade of the remaining nodes.

Mentioned in SAL (#wikimedia-operations) [2022-01-31T16:53:18Z] <urandom> restarting Cassandra, aqs1011-{a,b}, to apply upgrade to 3.11.11 -- T298516

Mentioned in SAL (#wikimedia-operations) [2022-01-31T17:03:57Z] <urandom> restarting Cassandra, aqs1012-{a,b}, to apply upgrade to 3.11.11 -- T298516

Mentioned in SAL (#wikimedia-operations) [2022-01-31T17:11:06Z] <urandom> restarting Cassandra, aqs1012-{a,b}, to apply upgrade to 3.11.11 -- T298516

Mentioned in SAL (#wikimedia-operations) [2022-01-31T17:11:19Z] <urandom> restarting Cassandra, aqs1013-{a,b}, to apply upgrade to 3.11.11 -- T298516

Mentioned in SAL (#wikimedia-operations) [2022-01-31T17:15:45Z] <urandom> restarting Cassandra, aqs1014-{a,b}, to apply upgrade to 3.11.11 -- T298516

Mentioned in SAL (#wikimedia-operations) [2022-01-31T17:23:50Z] <urandom> restarting Cassandra, aqs1015-{a,b}, to apply upgrade to 3.11.11 -- T298516

The upgrade to 3.11.11 is complete.

Thanks a lot @Eevans for the upgrade!
I assume we'll leave it bake for a few days before pooling more nodes - right?

In T298516#7665016, @JAllemandou wrote:

Thanks a lot @Eevans for the upgrade!
I assume we'll leave it bake for a few days before pooling more nodes - right?

If we want an apples/apples comparison to the last week, we can let it simmer like this for the next. The alternative would be to take it on good faith that it's Problem Solved™, and move ahead. I don't feel passionately about this one way or the other (and am in no particular hurry), so I'll leave that to you all.

Looks good to me too.

Change 757998 merged by Btullis:

[operations/puppet@production] Fold-in (minor) upstream configuration changes

https://gerrit.wikimedia.org/r/757998