Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Memory usage not going down on macOS #24892

Closed
tshuval opened this issue Apr 17, 2018 · 8 comments
Closed

Memory usage not going down on macOS #24892

tshuval opened this issue Apr 17, 2018 · 8 comments
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.

Comments

@tshuval
Copy link

tshuval commented Apr 17, 2018

What version of Go are you using (go version)?

1.9.4 and 1.10.1

Does this issue reproduce with the latest release?

yes

What operating system and processor architecture are you using (go env)?

macOS 10.13.1 darwin amd64
(edit: also macOS 10.13.4)

What did you do?

I created a super simple tcp server. Source: https://play.golang.org/p/wGAwdtU1nGY
I stress-tested it using tcpkali like so:
tcpkali -em "testing\r\n" -c 100 -r 1000 -T 60 127.0.0.1:8888
and then I waited for a few minutes, while the server is idle.
I could see that the RSS usage is going up during the test (using ps I can see RSS at 12384).
BUT this number is not going down even after 10 minutes of idle.

I ran the same test on ubuntu 14.04, and memory starts to go down as expected after around 5 minutes.

What did you expect to see?

used memory going down after a few minutes of idle

What did you see instead?

used memory not going down even after 20 minutes.
to make it worse, another stress-test makes the RSS usage increase to 12532. This number is also not going down when the server is back in idle mode.

@davecheney
Copy link
Contributor

Please repeat your test with GODEBUG=gctrace=1 and look for lines that state with scvg.

If the runtime reports that it has released memory to the operating system then that is all we can do (there is no POSIX mechanism to force the operating system to reclaim memory, we can only advise it).

@davecheney davecheney added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Apr 17, 2018
@tshuval
Copy link
Author

tshuval commented Apr 17, 2018

I did as you suggested. I only see gc rows, no scvg at all.
The server has been idle for 20 minutes already.

@davecheney
Copy link
Contributor

davecheney commented Apr 17, 2018 via email

@tshuval
Copy link
Author

tshuval commented Apr 17, 2018

gc 1 @4.044s 0%: 0.029+0.51+0.056 ms clock, 0.23+0.91/0.58/0.008+0.45 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 2 @4.918s 0%: 0.032+0.43+0.052 ms clock, 0.25+0.81/0.49/0+0.41 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 3 @5.789s 0%: 0.006+0.33+0.051 ms clock, 0.050+0.71/0.34/0.15+0.41 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 4 @6.664s 0%: 0.014+0.31+0.066 ms clock, 0.11+0.77/0.43/0.001+0.53 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 5 @7.540s 0%: 0.040+0.41+0.078 ms clock, 0.32+0.50/0.55/0+0.62 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 6 @8.414s 0%: 0.037+0.46+0.083 ms clock, 0.30+0.79/0.47/0.003+0.66 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 7 @9.288s 0%: 0.021+0.55+0.048 ms clock, 0.17+0.79/0.78/0.036+0.39 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 8 @10.165s 0%: 0.038+0.41+0.043 ms clock, 0.30+0.60/0.52/0+0.35 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 9 @11.039s 0%: 0.026+0.34+0.049 ms clock, 0.21+0.58/0.48/0.001+0.39 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 10 @11.911s 0%: 0.014+0.22+0.060 ms clock, 0.11+0.51/0.34/0.14+0.48 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 11 @12.789s 0%: 0.027+0.25+0.036 ms clock, 0.22+0.65/0.32/0+0.29 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 12 @13.663s 0%: 0.033+0.36+0.049 ms clock, 0.26+0.85/0.37/0+0.39 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 13 @14.534s 0%: 0.026+0.29+0.033 ms clock, 0.21+0.73/0.38/0+0.26 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 14 @15.407s 0%: 0.055+0.36+0.10 ms clock, 0.44+0.46/0.61/0+0.86 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 15 @16.285s 0%: 0.056+0.25+0.050 ms clock, 0.45+0.62/0.36/0.002+0.40 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 16 @17.165s 0%: 0.030+0.32+0.065 ms clock, 0.24+0.62/0.38/0.001+0.52 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 17 @18.039s 0%: 0.026+0.26+0.041 ms clock, 0.21+0.58/0.37/0.010+0.32 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 18 @18.914s 0%: 0.041+0.33+0.057 ms clock, 0.32+0.73/0.44/0+0.46 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 19 @19.779s 0%: 0.008+0.35+0.049 ms clock, 0.067+0.85/0.40/0+0.39 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 20 @20.655s 0%: 0.036+0.34+0.058 ms clock, 0.29+0.67/0.44/0+0.46 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 21 @21.530s 0%: 0.020+0.31+0.051 ms clock, 0.16+0.89/0.43/0.001+0.41 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 22 @22.401s 0%: 0.027+0.23+0.084 ms clock, 0.22+0.61/0.36/0+0.67 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 23 @23.278s 0%: 0.038+0.38+0.11 ms clock, 0.30+0.55/0.61/0+0.91 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 24 @24.155s 0%: 0.021+0.27+0.031 ms clock, 0.17+0.45/0.40/0.39+0.25 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 25 @25.029s 0%: 0.024+0.35+0.047 ms clock, 0.19+0.52/0.47/0.003+0.37 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 26 @25.904s 0%: 0.015+0.30+0.035 ms clock, 0.12+0.66/0.38/0.001+0.28 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 27 @26.780s 0%: 0.027+0.35+0.070 ms clock, 0.21+0.79/0.46/0+0.56 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 28 @27.654s 0%: 0.007+0.25+0.052 ms clock, 0.062+0.62/0.32/0.036+0.42 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 29 @28.528s 0%: 0.009+0.29+0.054 ms clock, 0.076+0.68/0.34/0.011+0.43 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 30 @29.403s 0%: 0.028+0.43+0.061 ms clock, 0.22+0.65/0.46/0.004+0.48 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 31 @30.277s 0%: 0.045+0.42+0.057 ms clock, 0.36+0.90/0.50/0+0.46 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 32 @31.154s 0%: 0.010+0.28+0.049 ms clock, 0.081+0.58/0.40/0+0.39 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 33 @32.027s 0%: 0.030+0.27+0.037 ms clock, 0.24+0.64/0.37/0+0.29 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 34 @32.903s 0%: 0.062+0.62+0.038 ms clock, 0.50+0.69/0.81/0+0.30 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 35 @33.774s 0%: 0.038+0.56+0.047 ms clock, 0.30+0.66/0.35/0+0.37 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
GC forced
gc 36 @153.886s 0%: 0.015+0.12+0.061 ms clock, 0.12+0/0.12/0.28+0.48 ms cpu, 1->1->0 MB, 4 MB goal, 8 P
GC forced
gc 37 @273.892s 0%: 0.010+0.15+0.062 ms clock, 0.087+0/0.17/0.27+0.50 ms cpu, 0->0->0 MB, 4 MB goal, 8 P
GC forced
gc 38 @393.894s 0%: 0.008+0.16+0.064 ms clock, 0.068+0/0.13/0.31+0.51 ms cpu, 0->0->0 MB, 4 MB goal, 8 P
GC forced
gc 39 @513.897s 0%: 0.010+0.11+0.078 ms clock, 0.082+0/0.13/0.23+0.62 ms cpu, 0->0->0 MB, 4 MB goal, 8 P
GC forced
gc 40 @633.908s 0%: 0.009+0.15+0.045 ms clock, 0.076+0/0.16/0.28+0.36 ms cpu, 0->0->0 MB, 4 MB goal, 8 P
GC forced
gc 41 @753.920s 0%: 0.008+0.10+0.042 ms clock, 0.067+0/0.12/0.20+0.34 ms cpu, 0->0->0 MB, 4 MB goal, 8 P
GC forced
gc 42 @873.931s 0%: 0.009+0.11+0.031 ms clock, 0.072+0/0.11/0.25+0.25 ms cpu, 0->0->0 MB, 4 MB goal, 8 P
GC forced
gc 43 @993.940s 0%: 0.024+0.15+0.043 ms clock, 0.19+0/0.12/0.22+0.34 ms cpu, 0->0->0 MB, 4 MB goal, 8 P
GC forced
gc 44 @1113.950s 0%: 0.022+0.13+0.048 ms clock, 0.18+0/0.14/0.25+0.38 ms cpu, 0->0->0 MB, 4 MB goal, 8 P
GC forced
gc 45 @1233.954s 0%: 0.009+0.14+0.051 ms clock, 0.076+0/0.16/0.13+0.41 ms cpu, 0->0->0 MB, 4 MB goal, 8 P
GC forced
gc 46 @1353.965s 0%: 0.010+0.10+0.035 ms clock, 0.087+0/0.12/0.19+0.28 ms cpu, 0->0->0 MB, 4 MB goal, 8 P
GC forced
gc 47 @1473.975s 0%: 0.014+0.26+0.051 ms clock, 0.11+0/0.29/0.16+0.41 ms cpu, 0->0->0 MB, 4 MB goal, 8 P
GC forced
gc 48 @1593.982s 0%: 0.015+0.36+0.071 ms clock, 0.12+0/0.40/0.56+0.57 ms cpu, 0->0->0 MB, 4 MB goal, 8 P
GC forced
gc 49 @1713.985s 0%: 0.007+0.12+0.065 ms clock, 0.060+0/0.13/0.18+0.52 ms cpu, 0->0->0 MB, 4 MB goal, 8 P
GC forced
gc 50 @1833.997s 0%: 0.007+0.12+0.030 ms clock, 0.059+0/0.13/0.16+0.24 ms cpu, 0->0->0 MB, 4 MB goal, 8 P
GC forced
gc 51 @1954.002s 0%: 0.012+0.13+0.031 ms clock, 0.096+0/0.17/0.27+0.25 ms cpu, 0->0->0 MB, 4 MB goal, 8 P
GC forced
gc 52 @2074.015s 0%: 0.009+0.17+0.052 ms clock, 0.076+0/0.19/0.36+0.41 ms cpu, 0->0->0 MB, 4 MB goal, 8 P
GC forced
gc 53 @2194.021s 0%: 0.009+0.11+0.033 ms clock, 0.073+0/0.12/0.21+0.26 ms cpu, 0->0->0 MB, 4 MB goal, 8 P

@davecheney
Copy link
Contributor

davecheney commented Apr 17, 2018 via email

@tshuval
Copy link
Author

tshuval commented Apr 17, 2018

So how come the RSS stays high on the mac?
This doesn't happen in ubuntu...

@davecheney
Copy link
Contributor

davecheney commented Apr 17, 2018 via email

@tshuval
Copy link
Author

tshuval commented Apr 17, 2018

ok sir, thanks!

@tshuval tshuval closed this as completed Apr 17, 2018
@golang golang locked and limited conversation to collaborators Apr 17, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Development

No branches or pull requests

3 participants