Investigate goroutine leakage issue in Kubelet #15805

dchen1107 · 2015-10-16T23:48:21Z

I profile kubelet without much workload (one or two pods), and found both goroutine and heap increased crazily. For example, on node:

/debug/pprof/

profiles:
0 block
1010 goroutine
1658 heap
12 threadcreate

And still keeping going.

Among 1010 goroutines: there are >450 with same stack trace:

goroutine 100 [IO wait]:
net.(*pollDesc).Wait(0xc2081e6a00, 0x72, 0x0, 0x0)
    /usr/src/go/src/net/fd_poll_runtime.go:84 +0x47
net.(*pollDesc).WaitRead(0xc2081e6a00, 0x0, 0x0)
    /usr/src/go/src/net/fd_poll_runtime.go:89 +0x43
net.(*netFD).Read(0xc2081e69a0, 0xc20887e000, 0x1000, 0x1000, 0x0, 0x7f78d4509048, 0xc2096c7ea8)
    /usr/src/go/src/net/fd_unix.go:242 +0x40f
net.(*conn).Read(0xc20803a788, 0xc20887e000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/src/go/src/net/net.go:121 +0xdc
crypto/tls.(*block).readFromUntil(0xc20829c1b0, 0x7f78d4516f50, 0xc20803a788, 0x5, 0x0, 0x0)
    /usr/src/go/src/crypto/tls/conn.go:454 +0xe6
crypto/tls.(*Conn).readRecord(0xc2080a5b80, 0x17, 0x0, 0x0)
    /usr/src/go/src/crypto/tls/conn.go:539 +0x2da
crypto/tls.(*Conn).Read(0xc2080a5b80, 0xc208260000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/src/go/src/crypto/tls/conn.go:904 +0x166
net/http.noteEOFReader.Read(0x7f78d451dcc8, 0xc2080a5b80, 0xc20839e5d8, 0xc208260000, 0x1000, 0x1000, 0x1540420, 0x0, 0x0)
    /usr/src/go/src/net/http/transport.go:1270 +0x6e
net/http.(*noteEOFReader).Read(0xc20836fa80, 0xc208260000, 0x1000, 0x1000, 0xc20813a900, 0x0, 0x0)
    <autogenerated>:125 +0xd4
bufio.(*Reader).fill(0xc20824be00)
    /usr/src/go/src/bufio/bufio.go:97 +0x1ce
bufio.(*Reader).Peek(0xc20824be00, 0x1, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/src/go/src/bufio/bufio.go:132 +0xf0
net/http.(*persistConn).readLoop(0xc20839e580)
    /usr/src/go/src/net/http/transport.go:842 +0xa4
created by net/http.(*Transport).dialConn
    /usr/src/go/src/net/http/transport.go:660 +0xc9f

or

goroutine 36 [select, 76 minutes]:
net/http.(*persistConn).readLoop(0xc20839e000)
    /usr/src/go/src/net/http/transport.go:928 +0x9ce
created by net/http.(*Transport).dialConn
    /usr/src/go/src/net/http/transport.go:660 +0xc9f

Then another 477 with net/http.(*persistConn).writeLoop

The text was updated successfully, but these errors were encountered:

yujuhong · 2015-10-16T23:56:10Z

Similar goroutine leakage from my cluster that had been running for 5 hours. My kubelet happily accumulate over 18000 goroutines.

8930 @ 0x417025 0x4138e0 0x412d78 0x56a587 0x56a5f3 0x56c2af 0x57f75c 0x5c6b0e 0x5d0a14 0x7a59fe 0x7a5c40 0x5c4304 0x440751
#   0x56a587    net.(*pollDesc).Wait+0x47       /usr/src/go/src/net/fd_poll_runtime.go:84
#   0x56a5f3    net.(*pollDesc).WaitRead+0x43       /usr/src/go/src/net/fd_poll_runtime.go:89
#   0x56c2af    net.(*netFD).Read+0x40f         /usr/src/go/src/net/fd_unix.go:242
#   0x57f75c    net.(*conn).Read+0xdc           /usr/src/go/src/net/net.go:121
#   0x5c6b0e    net/http.noteEOFReader.Read+0x6e    /usr/src/go/src/net/http/transport.go:1270
#   0x5d0a14    net/http.(*noteEOFReader).Read+0xd4 <autogenerated>:125
#   0x7a59fe    bufio.(*Reader).fill+0x1ce      /usr/src/go/src/bufio/bufio.go:97
#   0x7a5c40    bufio.(*Reader).Peek+0xf0       /usr/src/go/src/bufio/bufio.go:132
#   0x5c4304    net/http.(*persistConn).readLoop+0xa4   /usr/src/go/src/net/http/transport.go:842

8935 @ 0x417025 0x4192cc 0x418762 0x5c540d 0x440751
#   0x5c540d    net/http.(*persistConn).writeLoop+0x41d /usr/src/go/src/net/http/transport.go:945

dchen1107 · 2015-10-16T23:56:58Z

As an record: I measured this before 1.0 release, and found some leakages from cAdvsor. After that fix, we reasonably keep the goroutine down to some number (i.e. 100)

This should be a regression. This explains Kubelet CPU, memory usage increasing.

yujuhong · 2015-10-18T00:27:27Z

I found the culprit.

TL;DR: go-dockerclient now saves and reuses the connection. cadvisor.GetVersionInfo creates a new docker client each time, causing the connection leakage. This does not affect v1.1 because go-dockerclient was only updated recently (#15127).

Kubelet calls cadvisor to get version info whenever updating the node status. In every cadvisor.GetVersionInfo function call, cadvisor creates and using a new docker client each time to get the Docker version.

A recent go-dockerclient commit fsouza/go-dockerclient@1632686 changes to use http.Client for HTTP requests over UNIX domain socket. This changes the behavior of the client - it no longer closes the connection immediately after the request, instead, it saves it for future use.

Note that the cadvisor repository still uses the older go-dockerclient, hence could not have caught the leakage.

Removing this issue from v1.1milestone since it only affects HEAD (verified).

Simple code to reproduce this issue:
Using cadvisor (through k8s): https://gist.github.com/yujuhong/bed3f6757da772bef50b
Using go-dockerclient directly: https://gist.github.com/yujuhong/6068441fb45746dfcc77

pmorie · 2015-10-18T19:22:38Z

Classy digging 🏆

vishh · 2015-10-19T17:17:46Z

Some PRs from cadvisor (#909, @jimmidyson's prometheus PRs) and a pending PR for issue #920, might have to be cherry-picked into v1.1. I think resolving this issue right away in cadvisor is necessary.

yujuhong · 2015-10-19T17:23:10Z

Some PRs from cadvisor (#909, @jimmidyson's prometheus PRs) and a pending PR for issue #920, might have to be cherry-picked into v1.1. I think resolving this issue right away in cadvisor is necessary.

We should resolve this issue in cadvisor, but as long as we don't bump the go-dockerclient version in v1.1, v1.1 wouldn't be affected.

yujuhong · 2015-10-19T22:07:29Z

Update: cadvisor also creates a new docker client for each container. With the new go-dockerclient, it would use one connection per container, and never reclaims those connections after the containers die.

dchen1107 · 2015-10-19T22:58:38Z

Here are the reason I moved this back to v1.1 milestone:

#15612 (comment)

cc/ @pmorie Do we really need AdditionalGroups feature for 1.1 release? Otherwise, we don't need to bump go-dockerclient library to include commit fsouza/go-dockerclient@1632686

dchen1107 · 2015-10-21T17:10:38Z

All pr required from cAdvisor were merged, we just need to cut a new release: google/cadvisor#935, and update our GoDep here.

Fixes kubernetes#15805

pmorie · 2015-10-23T19:15:53Z

@dchen1107 I would like to have SupplementalGroups for use in 1.1, yeah.

paralin · 2015-10-26T22:08:33Z

Is this what causes my Kubelets to use a massive amount of memory?

dchen1107 · 2015-10-26T22:27:58Z

@paralin If you are running kubelet from HEAD, you might hit by this issue caused by misuse of new go-dockerclient library by cAdvisor. But if you are running 1.0 release, that should be a different issue.

paralin · 2015-10-26T22:30:59Z

@dchen1107 It's on HEAD. Is there a fix PR yet?

yujuhong · 2015-10-26T22:48:54Z

@paralin: The fix #16127 (cadvisor version bump) should be merged soon.

Fixes kubernetes#15805

bgrant0607 · 2015-10-30T02:54:45Z

Needs cherrypick, also

Fixes kubernetes#15805

dchen1107 added priority/critical-urgent Highest priority. Must be actively worked on as someone's top priority right now. kind/bug Categorizes issue or PR as related to a bug. sig/node Categorizes an issue or PR as relevant to SIG Node. labels Oct 16, 2015

dchen1107 added this to the v1.1 milestone Oct 16, 2015

dchen1107 mentioned this issue Oct 16, 2015

kubelet cpu usage increases over time #15661

Closed

yujuhong removed this from the v1.1 milestone Oct 18, 2015

yujuhong added priority/important-soon Must be staffed and worked on either currently, or very soon, ideally in time for the next release. and removed priority/critical-urgent Highest priority. Must be actively worked on as someone's top priority right now. labels Oct 18, 2015

This was referenced Oct 19, 2015

cadvisor leaks goroutines when running with latest go-dockerclient google/cadvisor#925

Closed

kubelet cpu high #15528

Closed

dchen1107 added this to the v1.1 milestone Oct 19, 2015

dchen1107 added priority/critical-urgent Highest priority. Must be actively worked on as someone's top priority right now. and removed priority/important-soon Must be staffed and worked on either currently, or very soon, ideally in time for the next release. labels Oct 19, 2015

dchen1107 added the area/cadvisor label Oct 21, 2015

dchen1107 mentioned this issue Oct 21, 2015

Cut 0.19 release for Kubernetes 1.1 release google/cadvisor#935

Closed

jimmidyson mentioned this issue Oct 22, 2015

Bump cadvisor & libcontainer #16127

Merged

jimmidyson added a commit to jimmidyson/kubernetes that referenced this issue Oct 23, 2015

Bump cadvisor & libcontainer

1edcc07

Fixes kubernetes#15805

yujuhong mentioned this issue Oct 27, 2015

Provide an option to disable/mock cadvisor in kubelet #16296

Closed

jimmidyson added a commit to jimmidyson/kubernetes that referenced this issue Oct 28, 2015

Bump cadvisor & libcontainer

762f1a8

Fixes kubernetes#15805

jimmidyson added a commit to jimmidyson/kubernetes that referenced this issue Oct 29, 2015

Bump cadvisor & libcontainer

38ad073

Fixes kubernetes#15805

dchen1107 closed this as completed in #16127 Oct 30, 2015

ncdc mentioned this issue Nov 4, 2015

docker socket file descriptor leak openshift/origin#5631

Closed

RichieEscarez pushed a commit to RichieEscarez/kubernetes that referenced this issue Dec 4, 2015

Bump cadvisor & libcontainer

c446a25

Fixes kubernetes#15805

dchen1107 mentioned this issue Dec 4, 2015

Failed to collect filesystem stats, no such file or directory #16651

Closed

This was referenced Jan 14, 2016

High CPU consumption of Kubelet 1.1 #19658

Closed

Kubelet consumes 50% of CPU weaveworks/service#289

Closed

shyamjvs pushed a commit to shyamjvs/kubernetes that referenced this issue Dec 1, 2016

Bump cadvisor & libcontainer

520396c

Fixes kubernetes#15805

shouhong pushed a commit to shouhong/kubernetes that referenced this issue Feb 14, 2017

Bump cadvisor & libcontainer

51ef8c3

Fixes kubernetes#15805

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Investigate goroutine leakage issue in Kubelet #15805

Investigate goroutine leakage issue in Kubelet #15805

dchen1107 commented Oct 16, 2015

yujuhong commented Oct 16, 2015

dchen1107 commented Oct 16, 2015

yujuhong commented Oct 18, 2015

pmorie commented Oct 18, 2015

vishh commented Oct 19, 2015

yujuhong commented Oct 19, 2015

yujuhong commented Oct 19, 2015

dchen1107 commented Oct 19, 2015

dchen1107 commented Oct 21, 2015

pmorie commented Oct 23, 2015

paralin commented Oct 26, 2015

dchen1107 commented Oct 26, 2015

paralin commented Oct 26, 2015

yujuhong commented Oct 26, 2015

bgrant0607 commented Oct 30, 2015

Investigate goroutine leakage issue in Kubelet #15805

Investigate goroutine leakage issue in Kubelet #15805

Comments

dchen1107 commented Oct 16, 2015

yujuhong commented Oct 16, 2015

dchen1107 commented Oct 16, 2015

yujuhong commented Oct 18, 2015

pmorie commented Oct 18, 2015

vishh commented Oct 19, 2015

yujuhong commented Oct 19, 2015

yujuhong commented Oct 19, 2015

dchen1107 commented Oct 19, 2015

dchen1107 commented Oct 21, 2015

pmorie commented Oct 23, 2015

paralin commented Oct 26, 2015

dchen1107 commented Oct 26, 2015

paralin commented Oct 26, 2015

yujuhong commented Oct 26, 2015

bgrant0607 commented Oct 30, 2015