Potential goroutine leak in serverWatchStream #18704

veshij · 2024-10-08T01:03:35Z

Bug report criteria

This bug report is not security related, security issues should be disclosed privately via etcd maintainers.
This is not a support request or question, support requests or questions should be raised in the etcd discussion forums.
You have read the etcd bug reporting guidelines.
Existing open issues along with etcd frequently asked questions have been checked and this is not a duplicate.

What happened?

We run several moderately loaded clusters with the following characteristics:

Tens of thousands of clients (steady count)
Millions of watchers
Hundreds of thousands of keys

We had a few performance issues at this scale, thus client has a logic to:

Spread watchers across multiple http streams.
Periodically move watchers from one stream to another to eventually even watcher load between etcd server nodes.
It's implemented via context metadata:

watchCtx = metadata.AppendToOutgoingContext(watchCtx,
			"watch_group", strconv.Itoa(w.streamId),
			"generation", strconv.FormatInt(w.generation, 10),
		)

We observe a slow what seems to be a slow goroutine leak on our clusters.

root@pdx3a-rp11-24a:~# curl --cert /srv/grpc-certs/etcd/latest/cert.pem --key /srv/grpc-certs/etcd/latest/key.pem --http1.1 -k -s https://localhost:5000/debug/pprof/goroutine?debug=1 | head -n 10
goroutine profile: total 177241
43832 @ 0x43fe6e 0x40a6a5 0x40a2f7 0xd9bb8d 0xd9af66 0x473181
#	0xd9bb8c	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*serverWatchStream).recvLoop+0x70c	external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:348
#	0xd9af65	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*watchServer).Watch.func2+0x45		external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:191

21683 @ 0x43fe6e 0x438617 0x46d665 0x4a77a7 0x4a8a9a 0x4a8a88 0x627365 0x637d45 0xdb842f 0xdb995e 0x68f39b 0x50f178 0x68f57e 0x68cb50 0x692e18 0x692e21 0x4a29f0 0x8b4c85 0x8b4c54 0x8b53c5 0x8c0227 0x473181
#	0x46d664	internal/poll.runtime_pollWait+0x84			GOROOT/src/runtime/netpoll.go:343
#	0x4a77a6	internal/poll.(*pollDesc).wait+0x26			GOROOT/src/internal/poll/fd_poll_runtime.go:84
#	0x4a8a99	internal/poll.(*pollDesc).waitRead+0x279		GOROOT/src/internal/poll/fd_poll_runtime.go:89
#	0x4a8a87	internal/poll.(*FD).Read+0x267				GOROOT/src/internal/poll/fd_unix.go:164

----------------------
# after a few seconds:
----------------------

root@pdx3a-rp11-24a:~# curl --cert /srv/grpc-certs/etcd/latest/cert.pem --key /srv/grpc-certs/etcd/latest/key.pem --http1.1 -k -s https://localhost:5000/debug/pprof/goroutine?debug=1 | head -n 10
goroutine profile: total 177042
43836 @ 0x43fe6e 0x40a6a5 0x40a2f7 0xd9bb8d 0xd9af66 0x473181
#	0xd9bb8c	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*serverWatchStream).recvLoop+0x70c	external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:348
#	0xd9af65	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*watchServer).Watch.func2+0x45		external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:191

21684 @ 0x43fe6e 0x438617 0x46d665 0x4a77a7 0x4a8a9a 0x4a8a88 0x627365 0x637d45 0xdb842f 0xdb995e 0x68f39b 0x50f178 0x68f57e 0x68cb50 0x692e18 0x692e21 0x4a29f0 0x8b4c85 0x8b4c54 0x8b53c5 0x8c0227 0x473181
#	0x46d664	internal/poll.runtime_pollWait+0x84			GOROOT/src/runtime/netpoll.go:343
#	0x4a77a6	internal/poll.(*pollDesc).wait+0x26			GOROOT/src/internal/poll/fd_poll_runtime.go:84
#	0x4a8a99	internal/poll.(*pollDesc).waitRead+0x279		GOROOT/src/internal/poll/fd_poll_runtime.go:89
#	0x4a8a87	internal/poll.(*FD).Read+0x267				GOROOT/src/internal/poll/fd_unix.go:164

so this one in particular seems to be a culprit:

43832 @ 0x43fe6e 0x40a6a5 0x40a2f7 0xd9bb8d 0xd9af66 0x473181
#	0xd9bb8c	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*serverWatchStream).recvLoop+0x70c	external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:348
#	0xd9af65	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*watchServer).Watch.func2+0x45		external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:191

I suspect that it's due to stream not properly closed after all watchers have migrated to a new h/2 stream.

What did you expect to happen?

Steady number of goroutines over time.

How can we reproduce it (as minimally and precisely as possible)?

I'd assume creating and stopping a set of watchers each one with own context metadata would trigger the issue.

Anything else we need to know?

No response

Etcd version (please run commands below)

$ etcd --version
etcd Version: 3.5.14
Git SHA: Not provided (use ./build instead of go build)
Go Version: go1.21.8 X:nocoverageredesign
Go OS/Arch: linux/amd64

$ etcdctl version
etcdctl version: 3.5.14
API version: 3.5

Etcd configuration (command line flags or environment variables)

paste your configuration here

Etcd debug information (please run commands below, feel free to obfuscate the IP address or FQDN in the output)

$ etcdctl member list -w table
+------------------+---------+----------------+----------------------------+----------------------------+------------+
|        ID        | STATUS  |      NAME      |         PEER ADDRS         |        CLIENT ADDRS        | IS LEARNER |
+------------------+---------+----------------+----------------------------+----------------------------+------------+
| 20f075a9d63e8059 | started |  pdx5a-ra32-5b |  https://10.168.15.59:5100 |  https://10.168.15.59:5000 |      false |
| 4ae19b2029c5b406 | started |  pdx5a-ra34-6a |  https://10.168.25.61:5100 |  https://10.168.25.61:5000 |      false |
| 58bc11a0454b8612 | started | pdx3a-rq24-21a |   https://10.90.71.28:5100 |   https://10.90.71.28:5000 |      false |
| 68000ca8f34d6c48 | started |   pdx3a-rw6-9b |  https://10.90.197.51:5100 |  https://10.90.197.51:5000 |      false |
| afd4dcb6f2b8a05f | started |  pdx4a-ri13-9a | https://10.136.212.58:5100 | https://10.136.212.58:5000 |      false |
| d008c4eba2073739 | started | pdx4a-rd10-21a |  https://10.136.25.28:5100 |  https://10.136.25.28:5000 |      false |
| e58692a57c5202f4 | started | pdx3a-rp11-24a |   https://10.90.34.43:5100 |   https://10.90.34.43:5000 |      false |
+------------------+---------+----------------+----------------------------+----------------------------+------------+

$ etcdctl --endpoints=<member list> endpoint status -w table
+--------------------+------------------+---------+---------+-----------+------------+-----------+------------+--------------------+--------+
|      ENDPOINT      |        ID        | VERSION | DB SIZE | IS LEADER | IS LEARNER | RAFT TERM | RAFT INDEX | RAFT APPLIED INDEX | ERRORS |
+--------------------+------------------+---------+---------+-----------+------------+-----------+------------+--------------------+--------+
| 10.136.212.58:5000 | afd4dcb6f2b8a05f |  3.5.14 |  2.6 GB |     false |      false |       369 | 1163505937 |         1163505937 |        |
|  10.136.25.28:5000 | d008c4eba2073739 |  3.5.14 |  2.6 GB |     false |      false |       369 | 1163505938 |         1163505938 |        |
|  10.168.15.59:5000 | 20f075a9d63e8059 |  3.5.14 |  2.6 GB |     false |      false |       369 | 1163505938 |         1163505938 |        |
|  10.168.25.61:5000 | 4ae19b2029c5b406 |  3.5.14 |  2.6 GB |     false |      false |       369 | 1163505939 |         1163505939 |        |
|  10.90.197.51:5000 | 68000ca8f34d6c48 |  3.5.14 |  2.6 GB |     false |      false |       369 | 1163505939 |         1163505937 |        |
|   10.90.34.43:5000 | e58692a57c5202f4 |  3.5.14 |  2.6 GB |      true |      false |       369 | 1163505939 |         1163505939 |        |
|   10.90.71.28:5000 | 58bc11a0454b8612 |  3.5.14 |  2.6 GB |     false |      false |       369 | 1163505939 |         1163505939 |        |
+--------------------+------------------+---------+---------+-----------+------------+-----------+------------+--------------------+--------+

Relevant log output

No response

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

ahrtr · 2024-10-08T16:27:49Z

Based on the diagram you provided, the goroutines were reclaimed periodically. It seems expected behaviour from golang runtime perspectively.

veshij · 2024-10-08T16:32:44Z

Sorry, I needed to state that explicitly, "reclamation" happens on etcd cluster node restart.

ahrtr · 2024-10-08T16:37:38Z

Just to confirm, are you saying the goroutine count for each etcd member doesn't decrease until it's restarted?

etcdserver creates a recvLoop goroutine for each watch stream,

etcd/server/etcdserver/api/v3rpc/watch.go

Line 193 in bc5512a

if rerr := sws.recvLoop(); rerr != nil {

Do the clients keep creating stream and never delete them? What's the client side behaviour?

veshij · 2024-10-08T17:03:55Z

Just to confirm, are you saying the goroutine count for each etcd member doesn't decrease until it's restarted?

that's correct.

etcdserver creates a recvLoop goroutine for each watch stream,

etcd/server/etcdserver/api/v3rpc/watch.go

Line 193 in bc5512a

if rerr := sws.recvLoop(); rerr != nil {

Do the clients keep creating stream and never delete them? What's the client side behaviour?

Stream is created implicitly when new context metadata is passed. I didn't find a way to explicitly close stream on the client side later, but I briefly looked at client code - and it seems like it should close the stream once it has no active watchers (but there is a decent chance I misunderstood the implementation).
To the best of my knowledge there should be no active watchers left in "inactive" streams on the client side.

ahrtr · 2024-10-08T19:06:59Z

I didn't find a way to explicitly close stream on the client side later

You can close the stream by either closing the client or closing the watch stream using wather.Close(), otherwise, there will be more and more streams, according more and more recvLoop goroutines. Please try it out and let me know the results.

etcd/client/v3/watch.go

Line 387 in 68e33d4

func (w *watcher) Close() (err error) {

veshij · 2024-10-08T19:24:34Z

The implementation closes old after new ones are created with new context metadata.
Lets me try to implement a minimal repro for the issue.

veshij · 2024-10-12T00:19:24Z

Started working on implementation and found a metric:

# name: "etcd_debugging_mvcc_watch_stream_total"
# description: "Total number of watch streams."
# type: "gauge"
etcd_debugging_mvcc_watch_stream_total

number of watch streams (reported by server) remains constant, number of goroutines grows over time.

veshij · 2024-10-12T01:28:32Z

So far can't repro with a single client in an isolated environment.
Typical trace looks like (which is expected):

1 @ 0x43fe6e 0x450345 0x90dd6a 0x90dc5b 0x90f22c 0x4a29f0 0x90f196 0x90f16d 0x9722c6 0x972b25 0x97331d 0x98a8ea 0xd8b6ad 0xa5d7a6 0xd9b4c2 0xd9af66 0x473181
#	0x90dd69	google.golang.org/grpc/internal/transport.(*recvBufferReader).read+0x89			external/org_golang_google_grpc/internal/transport/transport.go:181
#	0x90dc5a	google.golang.org/grpc/internal/transport.(*recvBufferReader).Read+0x15a		external/org_golang_google_grpc/internal/transport/transport.go:175
#	0x90f22b	google.golang.org/grpc/internal/transport.(*transportReader).Read+0x2b			external/org_golang_google_grpc/internal/transport/transport.go:525
#	0x4a29ef	io.ReadAtLeast+0x8f									GOROOT/src/io/io.go:335
#	0x90f195	io.ReadFull+0x95									GOROOT/src/io/io.go:354
#	0x90f16c	google.golang.org/grpc/internal/transport.(*Stream).Read+0x6c				external/org_golang_google_grpc/internal/transport/transport.go:509
#	0x9722c5	google.golang.org/grpc.(*parser).recvMsg+0x45						external/org_golang_google_grpc/rpc_util.go:614
#	0x972b24	google.golang.org/grpc.recvAndDecompress+0x84						external/org_golang_google_grpc/rpc_util.go:753
#	0x97331c	google.golang.org/grpc.recv+0x7c							external/org_golang_google_grpc/rpc_util.go:833
#	0x98a8e9	google.golang.org/grpc.(*serverStream).RecvMsg+0x169					external/org_golang_google_grpc/stream.go:1717
#	0xd8b6ac	github.com/grpc-ecosystem/go-grpc-prometheus.(*monitoredServerStream).RecvMsg+0x2c	external/com_github_grpc_ecosystem_go_grpc_prometheus/server_metrics.go:164
#	0xa5d7a5	go.etcd.io/etcd/api/v3/etcdserverpb.(*watchWatchServer).Recv+0x45			external/io_etcd_go_etcd_api_v3/etcdserverpb/rpc.pb.go:6762
#	0xd9b4c1	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*serverWatchStream).recvLoop+0x41	external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:242
#	0xd9af65	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*watchServer).Watch.func2+0x45		external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:191

and no goroutines stuck sending data to ctrlStream in case *pb.WatchRequest_CancelRequest: codepath as described in the issue.

veshij · 2024-10-12T01:47:39Z

Looks like in other places code does not block on sending data to sws.ctrlStream if sws.closec is closed:

etcd/server/etcdserver/api/v3rpc/watch.go

Lines 298 to 303 in 40b4715

    
           select { 
        
           case sws.ctrlStream <- wr: 
        
           	continue 
        
           case <-sws.closec: 
        
           	return nil 
        
           }

etcd/server/etcdserver/api/v3rpc/watch.go

Lines 339 to 343 in 40b4715

    
           select { 
        
           case sws.ctrlStream <- wr: 
        
           case <-sws.closec: 
        
           	return nil 
        
           }

but the codepath I'm seeing in traces does block:

etcd/server/etcdserver/api/v3rpc/watch.go

Lines 349 to 360 in 40b4715

    
           if err == nil { 
        
           	sws.ctrlStream <- &pb.WatchResponse{ 
        
           		Header:   sws.newResponseHeader(sws.watchStream.Rev()), 
        
           		WatchId:  id, 
        
           		Canceled: true, 
        
           	} 
        
           	sws.mu.Lock() 
        
           	delete(sws.progress, mvcc.WatchID(id)) 
        
           	delete(sws.prevKV, mvcc.WatchID(id)) 
        
           	delete(sws.fragment, mvcc.WatchID(id)) 
        
           	sws.mu.Unlock() 
        
           }

Wonder if it could be an issue.

Maybe this codepath should look like:

diff --git a/server/etcdserver/api/v3rpc/watch.go b/server/etcdserver/api/v3rpc/watch.go
index abb465e21..6781c468a 100644
--- a/server/etcdserver/api/v3rpc/watch.go
+++ b/server/etcdserver/api/v3rpc/watch.go
@@ -347,11 +347,17 @@ func (sws *serverWatchStream) recvLoop() error {
                                id := uv.CancelRequest.WatchId
                                err := sws.watchStream.Cancel(mvcc.WatchID(id))
                                if err == nil {
-                                       sws.ctrlStream <- &pb.WatchResponse{
+                                       wr := &pb.WatchResponse{
                                                Header:   sws.newResponseHeader(sws.watchStream.Rev()),
                                                WatchId:  id,
                                                Canceled: true,
                                        }
+                                       select {
+                                       case sws.ctrlStream <- wr:
+                                       case <-sws.closec:
+                                               return nil
+                                       }
+
                                        sws.mu.Lock()
                                        delete(sws.progress, mvcc.WatchID(id))
                                        delete(sws.prevKV, mvcc.WatchID(id))

ahrtr · 2024-10-15T15:50:47Z

Maybe this codepath should look like:

diff --git a/server/etcdserver/api/v3rpc/watch.go b/server/etcdserver/api/v3rpc/watch.go
index abb465e21..6781c468a 100644
--- a/server/etcdserver/api/v3rpc/watch.go
+++ b/server/etcdserver/api/v3rpc/watch.go
@@ -347,11 +347,17 @@ func (sws *serverWatchStream) recvLoop() error {
                                id := uv.CancelRequest.WatchId
                                err := sws.watchStream.Cancel(mvcc.WatchID(id))
                                if err == nil {
-                                       sws.ctrlStream <- &pb.WatchResponse{
+                                       wr := &pb.WatchResponse{
                                                Header:   sws.newResponseHeader(sws.watchStream.Rev()),
                                                WatchId:  id,
                                                Canceled: true,
                                        }
+                                       select {
+                                       case sws.ctrlStream <- wr:
+                                       case <-sws.closec:
+                                               return nil
+                                       }
+
                                        sws.mu.Lock()
                                        delete(sws.progress, mvcc.WatchID(id))
                                        delete(sws.prevKV, mvcc.WatchID(id))

Have you verified it can resolve your performance "issue"? I do not see any real case which may lead to etcdserver being blocked here.

But It won't do any harm to add a protection as you pointed out.

veshij · 2024-10-15T16:28:25Z

I already deployed the change to staging env, today/tmrw I’ll be able to validate in prod. At a first glance it seems to have fixed the issue, there are no goroutines with following traces: ``` # 0xd9bb8c go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*serverWatchStream).recvLoop+0x70c external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:348 # 0xd9af65 go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*watchServer).Watch.func2+0x45 ```

ahrtr · 2024-10-15T18:53:41Z

0xd9bb8c go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*serverWatchStream).recvLoop+0x70c external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:348

Did you see lots of the recvLoop goroutines being blocked exactly on the line sws.ctrlStream <- &pb.WatchResponse?

etcd/server/etcdserver/api/v3rpc/watch.go

Line 350 in 54db7f0

sws.ctrlStream <- &pb.WatchResponse{

Were the count of sendLoop goroutines much much less than the recvLoop when you saw goroutine leak?

etcd/server/etcdserver/api/v3rpc/watch.go

Line 378 in 54db7f0

func (sws *serverWatchStream) sendLoop() {

In theory, it seems that there is a race condition between sendLoop and recvLoop. When the stream is being closed, the recvLoop might receive a WatchRequest_CancelRequest right after sendLoop exits, then it will be blocked on sending message to sws.ctrlStream.

veshij · 2024-10-15T19:25:05Z

In the trace I posted initially there are a 40k+ such goroutines and the number is growing over time:

root@pdx3a-rp11-24a:~# curl --cert /srv/grpc-certs/etcd/latest/cert.pem --key /srv/grpc-certs/etcd/latest/key.pem --http1.1 -k -s https://localhost:5000/debug/pprof/goroutine?debug=1 | head -n 10

goroutine profile: total 177241
43832 @ 0x43fe6e 0x40a6a5 0x40a2f7 0xd9bb8d 0xd9af66 0x473181
#	0xd9bb8c	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*serverWatchStream).recvLoop+0x70c	external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:348
#	0xd9af65	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*watchServer).Watch.func2+0x45		external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:191

----------------------
# after a few seconds:
----------------------

43836 @ 0x43fe6e 0x40a6a5 0x40a2f7 0xd9bb8d 0xd9af66 0x473181
#	0xd9bb8c	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*serverWatchStream).recvLoop+0x70c	external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:348
#	0xd9af65	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*watchServer).Watch.func2+0x45

which points to https://github.com/etcd-io/etcd/blob/v3.5.14/server/etcdserver/api/v3rpc/watch.go#L348

And number of such goroutines does not match number of sendLoops running:

49411 @ 0x43fe6e 0x40a6a5 0x40a2f7 0xd9bb8d 0xd9af66 0x473181
#	0xd9bb8c	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*serverWatchStream).recvLoop+0x70c	external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:348
#	0xd9af65	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*watchServer).Watch.func2+0x45		external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:191

10387 @ 0x43fe6e 0x450345 0x90dd6a 0x90dc5b 0x90f22c 0x4a29f0 0x90f196 0x90f16d 0x9722c6 0x972b25 0x97331d 0x98a8ea 0xd8b6ad 0xa5d7a6 0xd9b4c2 0xd9af66 0x473181
#	0x90dd69	google.golang.org/grpc/internal/transport.(*recvBufferReader).read+0x89			external/org_golang_google_grpc/internal/transport/transport.go:181
#	0x90dc5a	google.golang.org/grpc/internal/transport.(*recvBufferReader).Read+0x15a		external/org_golang_google_grpc/internal/transport/transport.go:175
#	0x90f22b	google.golang.org/grpc/internal/transport.(*transportReader).Read+0x2b			external/org_golang_google_grpc/internal/transport/transport.go:525
#	0x4a29ef	io.ReadAtLeast+0x8f									GOROOT/src/io/io.go:335
#	0x90f195	io.ReadFull+0x95									GOROOT/src/io/io.go:354
#	0x90f16c	google.golang.org/grpc/internal/transport.(*Stream).Read+0x6c				external/org_golang_google_grpc/internal/transport/transport.go:509
#	0x9722c5	google.golang.org/grpc.(*parser).recvMsg+0x45						external/org_golang_google_grpc/rpc_util.go:614
#	0x972b24	google.golang.org/grpc.recvAndDecompress+0x84						external/org_golang_google_grpc/rpc_util.go:753
#	0x97331c	google.golang.org/grpc.recv+0x7c							external/org_golang_google_grpc/rpc_util.go:833
#	0x98a8e9	google.golang.org/grpc.(*serverStream).RecvMsg+0x169					external/org_golang_google_grpc/stream.go:1717
#	0xd8b6ac	github.com/grpc-ecosystem/go-grpc-prometheus.(*monitoredServerStream).RecvMsg+0x2c	external/com_github_grpc_ecosystem_go_grpc_prometheus/server_metrics.go:164
#	0xa5d7a5	go.etcd.io/etcd/api/v3/etcdserverpb.(*watchWatchServer).Recv+0x45			external/io_etcd_go_etcd_api_v3/etcdserverpb/rpc.pb.go:6762
#	0xd9b4c1	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*serverWatchStream).recvLoop+0x41	external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:242
#	0xd9af65	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*watchServer).Watch.func2+0x45		external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:191

10387 @ 0x43fe6e 0x450345 0xd9add1 0xa5d6b1 0xd8c652 0xd909d7 0xd93b82 0xd909d7 0xd90875 0x97cae7 0x97e8e5 0x97772b 0x473181
#	0xd9add0	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*watchServer).Watch+0x390				external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:211
#	0xa5d6b0	go.etcd.io/etcd/api/v3/etcdserverpb._Watch_Watch_Handler+0x90						external/io_etcd_go_etcd_api_v3/etcdserverpb/rpc.pb.go:6743
#	0xd8c651	github.com/grpc-ecosystem/go-grpc-prometheus.init.(*ServerMetrics).StreamServerInterceptor.func4+0xd1	external/com_github_grpc_ecosystem_go_grpc_prometheus/server_metrics.go:121
#	0xd909d6	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.Server.ChainStreamServer.func7.1.1+0x36			external/com_github_grpc_ecosystem_go_grpc_middleware/chain.go:49
#	0xd93b81	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.newStreamInterceptor.func1+0x4a1				external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/interceptor.go:252
#	0xd909d6	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.Server.ChainStreamServer.func7.1.1+0x36			external/com_github_grpc_ecosystem_go_grpc_middleware/chain.go:49
#	0xd90874	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.Server.ChainStreamServer.func7+0xb4			external/com_github_grpc_ecosystem_go_grpc_middleware/chain.go:58
#	0x97cae6	google.golang.org/grpc.(*Server).processStreamingRPC+0x1266						external/org_golang_google_grpc/server.go:1670
#	0x97e8e4	google.golang.org/grpc.(*Server).handleStream+0xfc4							external/org_golang_google_grpc/server.go:1784
#	0x97772a	google.golang.org/grpc.(*Server).serveStreams.func2.1+0x8a						external/org_golang_google_grpc/server.go:1019

10385 @ 0x43fe6e 0x450345 0xd9c3c5 0xd9b33c 0x473181
#	0xd9c3c4	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*serverWatchStream).sendLoop+0x244	external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:398
#	0xd9b33b	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*watchServer).Watch.func1+0x1b		external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:181

ahrtr · 2024-10-15T19:29:48Z

And number of such goroutines does not match number of sendLoops running:

Do you have rough numbers (count of recvLoop: count of sendLoop)?

veshij · 2024-10-15T19:40:15Z

The first column in goroutine profiles depicts the number of goroutines, in this case 49411:

49411 @ 0x43fe6e 0x40a6a5 0x40a2f7 0xd9bb8d 0xd9af66 0x473181
#	0xd9bb8c	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*serverWatchStream).recvLoop+0x70c	external/io_etcd_go_etcd_server_v3/etcdserver/api/v3rpc/watch.go:348
#	0xd9af65	go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.(*watchServer).Watch.func2+0x45

So 10385 sendLoop ones, 10387 healthy recvLoop ones and 49411 recvLoop stuck on sending data to channel.

ahrtr · 2024-10-15T20:07:18Z

The first column in goroutine profiles depicts the number of goroutines, in this case 49411:

I missed it. thx

To double confirm, you do not see this difference (counts of recvLoop and sendLoop) after patching the change in #18704 (comment)?

veshij · 2024-10-16T17:03:50Z

I can confirm no leak after running it for a day:

serathius · 2024-10-16T18:24:03Z

High level the change makes sense, all other usages of ctrlStream select on also on closec. Looks like watch server stream tests seem insufficient. Will look if we can improve that.

ahrtr · 2024-10-17T15:37:37Z

I can confirm no leak after running it for a day:

Thanks for the feedback. The reason should be the race condition pointed out in #18704 (comment).

The problem is that it's a little hard to reproduce and verify in e2e test. One solution that I can think of is to add two metrics (recvLoopCount and sendLoopCount), and

they should be always roughly equal (i.e. diff < 10%)
exactly equal when the watchers & traffic stabilises (i.e. no new watchers being created, and no any watchers being closed)
both should be 0 when all watchers are closed.

The workaround for this performance issue is to restart the etcd instance.

ahrtr · 2024-10-25T12:53:21Z

Reopen to track the backporting effort

ahrtr · 2024-11-01T13:21:34Z

All done.

serathius · 2024-11-01T16:48:41Z

Can we ensure backports are discover-able by linking between to the issue?

veshij added the type/bug label Oct 8, 2024

ahrtr added area/performance and removed type/bug labels Oct 8, 2024

veshij mentioned this issue Oct 14, 2024

etcdserver: terminate recvLoop on serverWatchStream.close() #18739

Merged

ahrtr added type/bug backport/v3.4 backport/v3.5 labels Oct 17, 2024

ahrtr pinned this issue Oct 17, 2024

serathius closed this as completed in #18739 Oct 24, 2024

ahrtr unpinned this issue Oct 25, 2024

ahrtr pinned this issue Oct 25, 2024

ahrtr reopened this Oct 25, 2024

ahrtr closed this as completed Nov 1, 2024

ahrtr unpinned this issue Nov 1, 2024

This was referenced Nov 1, 2024

[3.5] [serverWatchStream] terminate recvLoop on sws.close() #18784

Merged

[3.4] [serverWatchStream] terminate recvLoop on sws.close() #18785

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Potential goroutine leak in serverWatchStream #18704

Potential goroutine leak in serverWatchStream #18704

veshij commented Oct 8, 2024 •

edited

Loading

paste your configuration here

ahrtr commented Oct 8, 2024

veshij commented Oct 8, 2024 •

edited

Loading

ahrtr commented Oct 8, 2024

veshij commented Oct 8, 2024 •

edited

Loading

ahrtr commented Oct 8, 2024

veshij commented Oct 8, 2024

veshij commented Oct 12, 2024 •

edited

Loading

veshij commented Oct 12, 2024 •

edited

Loading

veshij commented Oct 12, 2024 •

edited

Loading

ahrtr commented Oct 15, 2024

veshij commented Oct 15, 2024 via email •

edited

Loading

ahrtr commented Oct 15, 2024

veshij commented Oct 15, 2024

ahrtr commented Oct 15, 2024

veshij commented Oct 15, 2024 •

edited

Loading

ahrtr commented Oct 15, 2024

veshij commented Oct 16, 2024

serathius commented Oct 16, 2024

ahrtr commented Oct 17, 2024 •

edited

Loading

ahrtr commented Oct 25, 2024

ahrtr commented Nov 1, 2024

serathius commented Nov 1, 2024

Potential goroutine leak in serverWatchStream #18704

Potential goroutine leak in serverWatchStream #18704

Comments

veshij commented Oct 8, 2024 • edited Loading

Bug report criteria

What happened?

What did you expect to happen?

How can we reproduce it (as minimally and precisely as possible)?

Anything else we need to know?

Etcd version (please run commands below)

Etcd configuration (command line flags or environment variables)

paste your configuration here

Etcd debug information (please run commands below, feel free to obfuscate the IP address or FQDN in the output)

Relevant log output

ahrtr commented Oct 8, 2024

veshij commented Oct 8, 2024 • edited Loading

ahrtr commented Oct 8, 2024

veshij commented Oct 8, 2024 • edited Loading

ahrtr commented Oct 8, 2024

veshij commented Oct 8, 2024

veshij commented Oct 12, 2024 • edited Loading

veshij commented Oct 12, 2024 • edited Loading

veshij commented Oct 12, 2024 • edited Loading

ahrtr commented Oct 15, 2024

veshij commented Oct 15, 2024 via email • edited Loading

ahrtr commented Oct 15, 2024

veshij commented Oct 15, 2024

ahrtr commented Oct 15, 2024

veshij commented Oct 15, 2024 • edited Loading

ahrtr commented Oct 15, 2024

veshij commented Oct 16, 2024

serathius commented Oct 16, 2024

ahrtr commented Oct 17, 2024 • edited Loading

ahrtr commented Oct 25, 2024

ahrtr commented Nov 1, 2024

serathius commented Nov 1, 2024

veshij commented Oct 8, 2024 •

edited

Loading

veshij commented Oct 8, 2024 •

edited

Loading

veshij commented Oct 8, 2024 •

edited

Loading

veshij commented Oct 12, 2024 •

edited

Loading

veshij commented Oct 12, 2024 •

edited

Loading

veshij commented Oct 12, 2024 •

edited

Loading

veshij commented Oct 15, 2024 via email •

edited

Loading

veshij commented Oct 15, 2024 •

edited

Loading

ahrtr commented Oct 17, 2024 •

edited

Loading