Strange memory usage pattern after v3.1.3 -> v3.2.6 upgrade #8472
Comments
|
Possibly from GC. Did anything change around 15:00? @gyuho does this happen with kubemark? |
|
Never seen it in our kubemark tests http://dash.etcd.io/dashboard/db/test-etcd-kubernetes?orgId=1. |
No, the drop happened without any kind of intervention or change on my part. |
|
Just so you know, I'm running Kubernetes v1.7.4. Do you folks have some tips on how can I proceed to find out what's happening, and if it's indeed a problem? Right now I'm trying to take a heap dump from etcd, but I'm having trouble doing so due to the fact I'm running etcd from inside rkt. |
|
@danielfm Probably you can run etcd with go GC trace enable. I would suspect it is due to less aggressive GC. |
|
@xiang90 @heyitsanthony I spent some time looking at our Prometheus to find out other metrics that could help explain that memory usage, and here goes some of them:
What do you think after looking at these graphs? Is the GC responsible for this behavior? If you need other metrics in order to answer this, please let me know and I'll get them for you. |
|
@danielfm Do you have any CPU usage and QPS data? |
|
Not sure what you mean by QPS data, but I'm sending the number of RPC calls per second.
Edit:
|
|
I managed to take a heap dumps from a running instance, and this is what happened when taking successive heap dumps: In summary, what I observed was that the heap usage went consistently up (with just one entry being responsible for >80% of the used heap space, if I interpreted the outputs correctly), but when those objects got reclaimed, the resident memory usage took 5-10 minutes to drop, so those events look related although I expected the resident memory usage to drop at the same time. (This delay might have something to do with how/when Go releases memory back to the operating system, I'm not a Go expert). Is this information useful at all? |
|
I also enabled the GC tracing, this is the log from the last 2h (later I'll try to capture logs around the moment the RSS drops again): |
|
@danielfm what does |
|
@heyitsanthony here is the PDF. I don't think this cluster has any v2 data, but is there a way I can check? Some command perhaps? Edit: As far as I could check, this cluster was first created with etcd 3.1.3, with |
|
More information: I have a systemd unit that regularly takes a snapshot of the etcd data and uploads it to S3 every 60s or so. I tried disabling it for a moment, and the GC finally were able to reclaim some memory back to the OS, although not too much (~60MB): One thing I noticed is that I started to see Then, after trying to re-enabling the systemd unit again, I noticed the RSS spiked again (around 19:50):
So, I disabled it again and I'll let it run for a few hours to see how the memory usage progresses without the snapshot. |
|
You may want to try GOGC=50; the GC goal is 2x the size of the in-use heap. The snapshot operation seems to be generating a lot of garbage while encoding messages. |
|
@heyitsanthony I'll try that next week But the ultimate question is: should I worry about this, or is this expected? |
it seems to me that it is GC related, and you do not really have to worry about it. But, at the mean time, we probably should start to understand this behavior better. |
|
As requested, I let etcd run with
The variable was set around Sep 1st 8:34PM, after which the RSS peaks went down a little, but the "shape" did not change. Also, the snapshot systemd unit I mentioned earlier was not running during this test, so apparently this behavior does not seem to be caused by it. I've just re-enabled the snapshot systemd unit; let's see if I notice anything now that I have set |
@xiang90 , real memory usage increased 2x, it is hardly "nothing to worry about" |
|
I do not think you read my full sentence or probably you misunderstood what I was saying. To be clear, what I said is that an operator, do not worry about this issue that much since he/she cannot take any immediate action to solve it. And it is not critical enough to kill the cluster. This issue seems more like a GC problem/patter change. We need to understand the problem first before we can give any suggestions or fixes. |
|
@danielfm would you be able to gradually switch versions from 3.2.1 to 3.2.6 without touching anything else? given that all 3 nodes show this behaviour, it probably would be enough to do it on one node by editing 40-version.conf, then |
|
Oops, it is 3.1.3 where you are coming from :( furthest you can go is 3.2.0, if you are lucky, there we'll see previous memory usage pattern,then we can narrow it to exact version, if not, then at least we know it happened between 3.1.3 and 3.2.0 |
|
Can I downgrade a patch version just by changing the etcd version like that? If so, I'm willing to test it, although I'm not sure we'll see any difference. (On the other hand, if I could get a Golang v1.7-linked etcd 3.2.6 instead of the Golang v1.8-linked etcd 3.2.6 I'm currently using, I think we could at least rule out changes in the GC itself as being the culprit in this case.) |
|
@danielfm , seems that you can clone etcd repo, checkout tag, change Dockerfile to and then |
|
Don't rkt make some sort of verification on the image, meaning that this image would need to be signed by some sort of key? |
|
adding |
|
@redbaron tried doing that, but etcd 3.2.6 does not compile with Go 1.7. I want to avoid changing the code just to make it compile. 😅 |
|
Well, at least try it with 1.9, maybe there'll be a visible change |
|
@redbaron Did what you suggested: The Golang 1.9-based image is available here. I kept the So far, I didn't notice any changes in the memory usage pattern. I'll let it run for a while more just to be certain. Edit: Nothing changed. At this time, I even tried running the |
|
Well, I spent more time on this than I should have. If anyone has any other suggestions, please let me know and I'll try to provide the requested information as soon as I can. |
|
any news on that? we also had this issue in our pre prod environment. 3.1.5 hadn‘t had this issue. 3.2.6 went up to more than 1gbyte memory consumption. |
|
@danielfm any updates on this? are you still seeing the same issue? |
|
@fanminshi I'm now running etcd v3.2.9, but the behavior remains the same. |
|
@danielfm could you show me how to reproduce this issue ? it will be nice if i can reproduce this myself so that I can help you on to debug this. |
|
@fanminshi Sure. As described previously, my etcd cluster was created by kube-aws, a tool originally authored by CoreOS. This is the https://gist.github.com/danielfm/c04e808616a55de74aec2f007dc21ef4 |
|
@danielfm from previous provided |
|
At the time, the number was between 10-20 worker nodes (m4.large), for 2 controllers (m3.large) and 3 etcd instances (m3.large). Currently, I'm running 58 nodes (m4.xlarge), for 4 controllers (m4.xlarge), and 3 etcd instances (m4.large), but the memory usage pattern is the same. Edit: I can send updated graphs if that helps. |
|
@danielfm yea, if you can you send the updated graphs. it will be great. specifically, i want to see memory usage pattern and gc rate. |
|
Edit: Data from the last 12h from all three instances.
|
|
@danielfm thanks for the data. could you elaborate |
|
@fanminshi I updated the graphs, the first one is now the GC rate per second. |
|
AFAIK Go GC triggers at 2x heap size, which pretty much matches what we see on graphs. Question is why it wasn't like that before |
|
The memory usage is the total use of the machine (RSS), not just etcd. There is the baseline usage of the system itself. Thus, I suspect etcd memory usage grows from 3.1.x to 3.2.x, so that its spike is more visible. But I am not exactly sure. @fanminshi is looking into this. |
|
@danielfm could you explain the y-axis of the graph |
|
just to be clear, I am talking about the 1st graph in the thread. some other graphs have the etcd tag on it. |
|
Yes, I believe the graph plots the RSS of the entire system. Querying only Golang metrics (roughly the same period as previous graphs):
|
|
@danielfm thanks for the clarification. @xiang90 you assumption is correct. let's focus on etcd consumption only. |
|
I'm not sure if I got the right data, let me know if you need anything else. |
ProblemThere is a spiky memory RSS pattern when upgrading from etcd 3.1.x to 3.2.x.
The first third shows RSS pattern for etcd Version: 3.1.10 compiled with Go Version: go1.8.5. The middle section shows RSS pattern for etcd etcd Version: 3.2.9 compiled with Go Version: go1.8.4. As seen from above, etcd 3.1.10 shows a flatter RSS Pattern than that 3.2.9 and also consumes less memory. Backgroundetcd stores all key changes to an in-memory log, and this log is periodically truncated when it reaches to a certain size so that log doesn't increase forever. Analysisetcd 3.1.x Memory PatternBy default, 3.1.x truncates the log when 10k new entries are added starting at log idx 0. Therefore, etcd periodically discards 5k or 10k oldest entries when the new 10k are added. We can see the same behavior from the etcd log gathered from kubemark: etcd increases its live heap usage from Because the etcd keeps its log small and discards entries often, the memory size never grows too much nor decreases too much; this reflects the RSS usage pattern of 3.1.0 from above. etcd 3.2.x Memory PatternIn 3.2.x, etcd truncates the log when to 100k new entries are added; pr #7160. We can see the behavior from the etcd log gathered from kubemark: etcd increases its live heap usage from Since etcd 3.2 keeps its log large and discard entries less frequently, the memory size grows to a large size and drop heavily when large chunk of entries are being discarded; etcd 3.2.x with 10k snapshot countWe did another experiment which changes the the etcd log gathered from kubemark: from above, the live heap keeps around range of The third section of ConclusionThe default snapshot count is change from etcd 3.1.x to etcd 3.2.x which introduces the difference in memory usage pattern. |
|
Closing this since the behavior is expected. Please reopen if you have any questions! |
|
@fanminshi Thank you for the detailed analysis. |
First reported this issue in kubernetes-retired/kube-aws#795.
I'm experiencing a strange memory usage pattern after upgrading etcd from v3.1.3 to v3.2.6:
We can see very clearly the memory consumption used to stay stable until the update, after which the memory consumption went through the roof. Despite the high memory usage, so far it seems the load is under control, and found no errors in the logs:
My environment:
Is this behavior expected?
The text was updated successfully, but these errors were encountered: