Too high memory usage #137

notsure2 · 2020-12-05T01:33:04Z

Stress testing ck-server with NumConn=0 and making only around 70 Cloak sessions, it's already consuming 180 MB of RAM and it continues to climb. It doesn't seem to be releasing memory properly even after the connections are stopped. There seems to be a memory leak.

notsure2 · 2020-12-05T01:54:56Z

Info from pprof:

File: ck-server
Type: inuse_space
Time: Dec 5, 2020 at 3:53am (EET)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 71.75MB, 100% of 71.75MB total
Showing top 10 nodes out of 16
      flat  flat%   sum%        cum   cum%
      49MB 68.30% 68.30%    54.70MB 76.23%  time.AfterFunc
   12.50MB 17.42% 85.72%    67.20MB 93.66%  github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).WriteTo
    5.69MB  7.93% 93.66%     5.69MB  7.93%  time.startTimer
    2.02MB  2.81% 96.46%     2.52MB  3.51%  github.com/cbeuw/Cloak/internal/multiplex.MakeSession
    1.02MB  1.42% 97.89%     1.02MB  1.42%  github.com/cbeuw/Cloak/internal/multiplex.(*switchboard).deplex
    0.51MB  0.71% 98.60%     0.51MB  0.71%  github.com/cbeuw/Cloak/internal/multiplex.(*Stream).ReadFrom
    0.51MB  0.71% 99.30%     0.51MB  0.71%  github.com/cbeuw/Cloak/internal/common.NewTLSConn
    0.50MB   0.7%   100%     0.50MB   0.7%  github.com/cbeuw/Cloak/internal/multiplex.makeSwitchboard
         0     0%   100%    67.71MB 94.37%  github.com/cbeuw/Cloak/internal/common.Copy
         0     0%   100%    67.20MB 93.66%  github.com/cbeuw/Cloak/internal/multiplex.(*Stream).WriteTo

notsure2 · 2020-12-05T02:02:07Z

notsure2 · 2020-12-05T02:09:42Z

Example of triggering event: Use NumConn=0, setup as plugin with shadowsocks, setup with qBittorrent, set large number of simultaneous connections in qBittorrent, download a torrent with lot of sources (eg: Linux Distro).

notsure2 · 2020-12-05T02:19:38Z

(pprof) list multiplex
Total: 161.43MB
ROUTINE ======================== github.com/cbeuw/Cloak/internal/multiplex.(*Stream).ReadFrom in /d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go
    1.02MB     1.02MB (flat, cum)  0.63% of Total
         .          .    172:
         .          .    173:https:// ReadFrom continuously read data from r and send it off, until either r returns error or nothing has been read
         .          .    174:https:// for readFromTimeout amount of time
         .          .    175:func (s *Stream) ReadFrom(r io.Reader) (n int64, err error) {
         .          .    176:   if s.obfsBuf == nil {
    1.02MB     1.02MB    177:           s.obfsBuf = make([]byte, s.session.StreamSendBufferSize)
         .          .    178:   }
         .          .    179:   for {
         .          .    180:           if s.readFromTimeout != 0 {
         .          .    181:                   if rder, ok := r.(net.Conn); !ok {
         .          .    182:                           log.Warn("ReadFrom timeout is set but reader doesn't implement SetReadDeadline")
ROUTINE ======================== github.com/cbeuw/Cloak/internal/multiplex.(*Stream).WriteTo in /d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go
         0   158.38MB (flat, cum) 98.11% of Total
         .          .    100:}
         .          .    101:
         .          .    102:https:// WriteTo continuously write data Stream has received into the writer w.
         .          .    103:func (s *Stream) WriteTo(w io.Writer) (int64, error) {
         .          .    104:   // will keep writing until the underlying buffer is closed
         .   158.38MB    105:   n, err := s.recvBuf.WriteTo(w)
         .          .    106:   log.Tracef("%v read from stream %v with err %v", n, s.id, err)
         .          .    107:   if err == io.EOF {
         .          .    108:           return n, ErrBrokenStream
         .          .    109:   }
         .          .    110:   return n, nil
ROUTINE ======================== github.com/cbeuw/Cloak/internal/multiplex.(*streamBuffer).WriteTo in /d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBuffer.go
         0   158.38MB (flat, cum) 98.11% of Total
         .          .     98:func (sb *streamBuffer) Read(buf []byte) (int, error) {
         .          .     99:   return sb.buf.Read(buf)
         .          .    100:}
         .          .    101:
         .          .    102:func (sb *streamBuffer) WriteTo(w io.Writer) (int64, error) {
         .   158.38MB    103:   return sb.buf.WriteTo(w)
         .          .    104:}
         .          .    105:
         .          .    106:func (sb *streamBuffer) Close() error {
         .          .    107:   sb.recvM.Lock()
         .          .    108:   defer sb.recvM.Unlock()
ROUTINE ======================== github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).WriteTo in /d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go
   31.50MB   158.38MB (flat, cum) 98.11% of Total
         .          .     75:                           time.AfterFunc(d, p.rwCond.Broadcast)
         .          .     76:                   }
         .          .     77:           }
         .          .     78:           if p.wtTimeout != 0 {
         .          .     79:                   p.rDeadline = time.Now().Add(p.wtTimeout)
   31.50MB   158.38MB     80:                   time.AfterFunc(p.wtTimeout, p.rwCond.Broadcast)
         .          .     81:           }
         .          .     82:           if p.buf.Len() > 0 {
         .          .     83:                   written, er := p.buf.WriteTo(w)
         .          .     84:                   n += written
         .          .     85:                   if er != nil {
ROUTINE ======================== github.com/cbeuw/Cloak/internal/multiplex.(*switchboard).deplex in /d/Users/User/Work/GitHub/Cloak/internal/multiplex/switchboard.go
  522.06kB   522.06kB (flat, cum)  0.32% of Total
         .          .    157:}
         .          .    158:
         .          .    159:https:// deplex function costantly reads from a TCP connection
         .          .    160:func (sb *switchboard) deplex(connId uint32, conn net.Conn) {
         .          .    161:   defer conn.Close()
  522.06kB   522.06kB    162:   buf := make([]byte, sb.session.ConnReceiveBufferSize)
         .          .    163:   for {
         .          .    164:           n, err := conn.Read(buf)
         .          .    165:           sb.valve.rxWait(n)
         .          .    166:           sb.valve.AddRx(int64(n))
         .          .    167:           if err != nil {
(pprof)

notsure2 · 2020-12-05T02:41:02Z

I think I have a guess for the issue. I think that in case a connection is closed, Cloak does not clear the callback registered with timer.AfterFunc, so the Timer instances are getting accumulated in memory (memory leak). Eventually they timeout and get cleared but if a program opens and closes many connections in a short time, it will cause infinite memory growth until cloak is killed by the server.

notsure2 · 2020-12-05T03:07:31Z

Possible workaround, reduce StreamTimeout. But the correct solution is track the timers created per connection, don't create more than 1 timeout timer for each connection and when the connection is closed, cancel and destroy the timer.

notsure2 · 2020-12-05T03:30:44Z

Actually, maybe I'm misunderstanding the code, I'm not completely familiar with golang rwCond, the problem maybe simply only that the timeout was too long.

cbeuw · 2020-12-05T12:08:13Z

So apparently timer.AfterFunc() creates a timer that does not get garbage collected until the timer fires: https://medium.com/@oboturov/golang-time-after-is-not-garbage-collected-4cbc94740082

Since it is in a hot loop, a lot of timers were created. They would get garbage collected eventually but this is still a memory leak. The new commit should fix it by only having one timer per connection

cbeuw · 2020-12-05T12:23:15Z

Hmmm this might have broken things. Will fix

cbeuw · 2020-12-05T13:10:15Z

nvm it's my setup. Should actually be fine

notsure2 · 2020-12-05T15:20:42Z

@cbeuw this issue is still not fixed although it is reduced in severity. You still need to clean up the timer when the connection is prematurely closed from the sender side before the timeout elapsed, otherwise the timer will wait until the timeout elapsed in order to get garbage collected, even after the connection is closed by a long time.

notsure2 · 2020-12-05T20:55:53Z

Memory usage is still climbing. Now the pprof is showing different results:

File: ck-server
Type: inuse_space
Time: Dec 5, 2020 at 10:53pm (EET)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 33722.22kB, 95.64% of 35258.32kB total
Showing top 10 nodes out of 37
      flat  flat%   sum%        cum   cum%
12292.50kB 34.86% 34.86% 12292.50kB 34.86%  runtime.malg
 6144.56kB 17.43% 52.29%  6144.56kB 17.43%  github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).broadcastAfter.func1
 5657.96kB 16.05% 68.34%  5657.96kB 16.05%  bytes.makeSlice
 2610.33kB  7.40% 75.74%  9804.39kB 27.81%  github.com/cbeuw/Cloak/internal/multiplex.(*switchboard).deplex
 2088.26kB  5.92% 81.66%  2600.27kB  7.37%  github.com/cbeuw/Cloak/internal/multiplex.(*Stream).ReadFrom
 1322.42kB  3.75% 85.42%  1322.42kB  3.75%  github.com/cbeuw/Cloak/internal/server.(*State).registerRandom
 1038.06kB  2.94% 88.36%  1038.06kB  2.94%  github.com/cbeuw/Cloak/internal/common.NewTLSConn
 1032.02kB  2.93% 91.29%  1032.02kB  2.93%  github.com/cbeuw/Cloak/internal/multiplex.MakeSession
 1024.06kB  2.90% 94.19%  1024.06kB  2.90%  time.NewTimer
  512.05kB  1.45% 95.64%   512.05kB  1.45%  github.com/cbeuw/Cloak/internal/multiplex.(*Session).Accept

alloc_space mode:

Showing nodes accounting for 264.58MB, 81.01% of 326.60MB total
Dropped 48 nodes (cum <= 1.63MB)
Showing top 10 nodes out of 79
      flat  flat%   sum%        cum   cum%
   67.74MB 20.74% 20.74%    72.29MB 22.14%  github.com/cbeuw/Cloak/internal/multiplex.(*Stream).ReadFrom
   66.79MB 20.45% 41.19%    97.82MB 29.95%  github.com/cbeuw/Cloak/internal/multiplex.(*switchboard).deplex
   58.29MB 17.85% 59.04%    58.29MB 17.85%  github.com/cbeuw/Cloak/internal/common.NewTLSConn (inline)
   29.22MB  8.95% 67.98%    29.72MB  9.10%  github.com/cbeuw/Cloak/internal/multiplex.MakeSession
      12MB  3.68% 71.66%       12MB  3.68%  runtime.malg
    6.53MB  2.00% 73.66%     6.53MB  2.00%  bytes.makeSlice
    6.50MB  1.99% 75.65%     6.50MB  1.99%  github.com/cbeuw/Cloak/internal/server.parseExtensions
    6.01MB  1.84% 77.49%   125.82MB 38.52%  github.com/cbeuw/Cloak/internal/server.dispatchConnection
       6MB  1.84% 79.33%        6MB  1.84%  github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).broadcastAfter.func1
    5.50MB  1.68% 81.01%    13.50MB  4.13%  github.com/cbeuw/Cloak/internal/multiplex.NewStreamBufferedPipe

cbeuw · 2020-12-05T21:09:53Z

Thanks for your effort! Could you please check how many goroutines are running and if that figure ever goes down when things become quiet? I tried the two channel approach earlier and the main issue was that there are hundreds of goroutines stuck alive, somehow never selected the closing channel.

Prior to 4baca25, there wasn't any goroutine issues raising from the use of AfterFunc().

notsure2 · 2020-12-05T21:13:18Z

goroutine profile: total 60913
60333 @ 0x437050 0x446eb3 0x789873 0x466241
#	0x789872	github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).broadcastAfter.func1+0xa2	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:159

100 @ 0x437050 0x40528d 0x405055 0x787bbd 0x786f50 0x783d3c 0x785267 0x785248 0x78435c 0x788900 0x466241
#	0x787bbc	github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).Close+0xac	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:130
#	0x786f4f	github.com/cbeuw/Cloak/internal/multiplex.(*streamBuffer).Close+0x6f		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBuffer.go:110
#	0x783d3b	github.com/cbeuw/Cloak/internal/multiplex.(*Session).closeStream+0x11b		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/session.go:171
#	0x785266	github.com/cbeuw/Cloak/internal/multiplex.(*Stream).passiveClose+0x96		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:214
#	0x785247	github.com/cbeuw/Cloak/internal/multiplex.(*Stream).recvFrame+0x77		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:77
#	0x78435b	github.com/cbeuw/Cloak/internal/multiplex.(*Session).recvDataFromRemote+0x18b	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/session.go:234
#	0x7888ff	github.com/cbeuw/Cloak/internal/multiplex.(*switchboard).deplex+0x18f		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/switchboard.go:175

99 @ 0x437050 0x4479f0 0x4479db 0x447757 0x47ee0c 0x47ecf7 0x787d68 0x787049 0x791084 0x791045 0x790523 0x466241
#	0x447756	sync.runtime_SemacquireMutex+0x46							/usr/lib/go-1.14/src/runtime/sema.go:71
#	0x47ee0b	sync.(*Mutex).lockSlow+0xfb								/usr/lib/go-1.14/src/sync/mutex.go:138
#	0x47ecf6	sync.(*Mutex).Lock+0x46									/usr/lib/go-1.14/src/sync/mutex.go:81
#	0x787d67	github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).SetWriteToTimeout+0x47	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:145
#	0x787048	github.com/cbeuw/Cloak/internal/multiplex.(*streamBuffer).SetWriteToTimeout+0x38	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBuffer.go:114
#	0x791083	github.com/cbeuw/Cloak/internal/multiplex.(*Stream).SetWriteToTimeout+0x673		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:228
#	0x791044	github.com/cbeuw/Cloak/internal/server.serveSession+0x634				/d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:279
#	0x790522	github.com/cbeuw/Cloak/internal/server.dispatchConnection+0x1282			/d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:248

75 @ 0x437050 0x45389a 0x784f3f 0x466241
#	0x453899	time.Sleep+0xb9								/usr/lib/go-1.14/src/runtime/time.go:188
#	0x784f3e	github.com/cbeuw/Cloak/internal/multiplex.(*Session).timeoutAfter+0x2e	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/session.go:338

62 @ 0x437050 0x405ea7 0x405b6b 0x787e8b 0x787776 0x786ea3 0x785613 0x7241d0 0x795d6d 0x466241
#	0x787e8a	github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).broadcastAfter+0xaa	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:155
#	0x787775	github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).WriteTo+0x225		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:85
#	0x786ea2	github.com/cbeuw/Cloak/internal/multiplex.(*streamBuffer).WriteTo+0x42			/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBuffer.go:103
#	0x785612	github.com/cbeuw/Cloak/internal/multiplex.(*Stream).WriteTo+0x62			/d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:105
#	0x7241cf	github.com/cbeuw/Cloak/internal/common.Copy+0x42f					/d/Users/User/Work/GitHub/Cloak/internal/common/copy.go:46
#	0x795d6c	github.com/cbeuw/Cloak/internal/server.serveSession.func1+0x4c				/d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:281

62 @ 0x437050 0x42ffda 0x42f545 0x4c4595 0x4c542b 0x4c540d 0x515d6f 0x52876e 0x785f82 0x724100 0x795e4d 0x466241
#	0x42f544	internal/poll.runtime_pollWait+0x54					/usr/lib/go-1.14/src/runtime/netpoll.go:203
#	0x4c4594	internal/poll.(*pollDesc).wait+0x44					/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:87
#	0x4c542a	internal/poll.(*pollDesc).waitRead+0x19a				/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:92
#	0x4c540c	internal/poll.(*FD).Read+0x17c						/usr/lib/go-1.14/src/internal/poll/fd_unix.go:169
#	0x515d6e	net.(*netFD).Read+0x4e							/usr/lib/go-1.14/src/net/fd_unix.go:202
#	0x52876d	net.(*conn).Read+0x8d							/usr/lib/go-1.14/src/net/net.go:184
#	0x785f81	github.com/cbeuw/Cloak/internal/multiplex.(*Stream).ReadFrom+0xe1	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:187
#	0x7240ff	github.com/cbeuw/Cloak/internal/common.Copy+0x35f			/d/Users/User/Work/GitHub/Cloak/internal/common/copy.go:50
#	0x795e4c	github.com/cbeuw/Cloak/internal/server.serveSession.func2+0x4c		/d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:287

59 @ 0x437050 0x405ea7 0x405b6b 0x783abb 0x790a53 0x790523 0x466241
#	0x783aba	github.com/cbeuw/Cloak/internal/multiplex.(*Session).Accept+0x5a	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/session.go:159
#	0x790a52	github.com/cbeuw/Cloak/internal/server.serveSession+0x42		/d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:254
#	0x790522	github.com/cbeuw/Cloak/internal/server.dispatchConnection+0x1282	/d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:248

58 @ 0x437050 0x42ffda 0x42f545 0x4c4595 0x4c542b 0x4c540d 0x515d6f 0x52876e 0x4a68a7 0x724cf4 0x724c91 0x788856 0x466241
#	0x42f544	internal/poll.runtime_pollWait+0x54					/usr/lib/go-1.14/src/runtime/netpoll.go:203
#	0x4c4594	internal/poll.(*pollDesc).wait+0x44					/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:87
#	0x4c542a	internal/poll.(*pollDesc).waitRead+0x19a				/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:92
#	0x4c540c	internal/poll.(*FD).Read+0x17c						/usr/lib/go-1.14/src/internal/poll/fd_unix.go:169
#	0x515d6e	net.(*netFD).Read+0x4e							/usr/lib/go-1.14/src/net/fd_unix.go:202
#	0x52876d	net.(*conn).Read+0x8d							/usr/lib/go-1.14/src/net/net.go:184
#	0x4a68a6	io.ReadAtLeast+0x86							/usr/lib/go-1.14/src/io/io.go:310
#	0x724cf3	io.ReadFull+0x93							/usr/lib/go-1.14/src/io/io.go:329
#	0x724c90	github.com/cbeuw/Cloak/internal/common.(*TLSConn).Read+0x30		/d/Users/User/Work/GitHub/Cloak/internal/common/tls.go:82
#	0x788855	github.com/cbeuw/Cloak/internal/multiplex.(*switchboard).deplex+0xe5	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/switchboard.go:164

58 @ 0x437050 0x4488e8 0x4488be 0x47cfcd 0x78766b 0x786ea3 0x785613 0x7241d0 0x795d6d 0x466241
#	0x4488bd	sync.runtime_notifyListWait+0xcd						/usr/lib/go-1.14/src/runtime/sema.go:513
#	0x47cfcc	sync.(*Cond).Wait+0x9c								/usr/lib/go-1.14/src/sync/cond.go:56
#	0x78766a	github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).WriteTo+0x11a	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:96
#	0x786ea2	github.com/cbeuw/Cloak/internal/multiplex.(*streamBuffer).WriteTo+0x42		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBuffer.go:103
#	0x785612	github.com/cbeuw/Cloak/internal/multiplex.(*Stream).WriteTo+0x62		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:105
#	0x7241cf	github.com/cbeuw/Cloak/internal/common.Copy+0x42f				/d/Users/User/Work/GitHub/Cloak/internal/common/copy.go:46
#	0x795d6c	github.com/cbeuw/Cloak/internal/server.serveSession.func1+0x4c			/d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:281

1 @ 0x437050 0x42ffda 0x42f545 0x4c4595 0x4c542b 0x4c540d 0x515d6f 0x52876e 0x6dc338 0x466241
#	0x42f544	internal/poll.runtime_pollWait+0x54		/usr/lib/go-1.14/src/runtime/netpoll.go:203
#	0x4c4594	internal/poll.(*pollDesc).wait+0x44		/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:87
#	0x4c542a	internal/poll.(*pollDesc).waitRead+0x19a	/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:92
#	0x4c540c	internal/poll.(*FD).Read+0x17c			/usr/lib/go-1.14/src/internal/poll/fd_unix.go:169
#	0x515d6e	net.(*netFD).Read+0x4e				/usr/lib/go-1.14/src/net/fd_unix.go:202
#	0x52876d	net.(*conn).Read+0x8d				/usr/lib/go-1.14/src/net/net.go:184
#	0x6dc337	net/http.(*connReader).backgroundRead+0x57	/usr/lib/go-1.14/src/net/http/server.go:678

1 @ 0x437050 0x42ffda 0x42f545 0x4c4595 0x4c6dd4 0x4c6db6 0x516622 0x5327b2 0x531544 0x6e6a8d 0x6e67d7 0x7ea486 0x7ea432 0x466241
#	0x42f544	internal/poll.runtime_pollWait+0x54		/usr/lib/go-1.14/src/runtime/netpoll.go:203
#	0x4c4594	internal/poll.(*pollDesc).wait+0x44		/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:87
#	0x4c6dd3	internal/poll.(*pollDesc).waitRead+0x1d3	/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:92
#	0x4c6db5	internal/poll.(*FD).Accept+0x1b5		/usr/lib/go-1.14/src/internal/poll/fd_unix.go:384
#	0x516621	net.(*netFD).accept+0x41			/usr/lib/go-1.14/src/net/fd_unix.go:238
#	0x5327b1	net.(*TCPListener).accept+0x31			/usr/lib/go-1.14/src/net/tcpsock_posix.go:139
#	0x531543	net.(*TCPListener).Accept+0x63			/usr/lib/go-1.14/src/net/tcpsock.go:261
#	0x6e6a8c	net/http.(*Server).Serve+0x25c			/usr/lib/go-1.14/src/net/http/server.go:2901
#	0x6e67d6	net/http.(*Server).ListenAndServe+0xb6		/usr/lib/go-1.14/src/net/http/server.go:2830
#	0x7ea485	net/http.ListenAndServe+0x75			/usr/lib/go-1.14/src/net/http/server.go:3086
#	0x7ea431	main.main.func1+0x21				/d/Users/User/Work/GitHub/Cloak/cmd/ck-server/ck-server.go:112

1 @ 0x437050 0x42ffda 0x42f545 0x4c4595 0x4c6dd4 0x4c6db6 0x516622 0x5327b2 0x531544 0x78e37f 0x7ea693 0x7e95e9 0x436c72 0x466241
#	0x42f544	internal/poll.runtime_pollWait+0x54			/usr/lib/go-1.14/src/runtime/netpoll.go:203
#	0x4c4594	internal/poll.(*pollDesc).wait+0x44			/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:87
#	0x4c6dd3	internal/poll.(*pollDesc).waitRead+0x1d3		/usr/lib/go-1.14/src/internal/poll/fd_poll_runtime.go:92
#	0x4c6db5	internal/poll.(*FD).Accept+0x1b5			/usr/lib/go-1.14/src/internal/poll/fd_unix.go:384
#	0x516621	net.(*netFD).accept+0x41				/usr/lib/go-1.14/src/net/fd_unix.go:238
#	0x5327b1	net.(*TCPListener).accept+0x31				/usr/lib/go-1.14/src/net/tcpsock_posix.go:139
#	0x531543	net.(*TCPListener).Accept+0x63				/usr/lib/go-1.14/src/net/tcpsock.go:261
#	0x78e37e	github.com/cbeuw/Cloak/internal/server.Serve+0x6e	/d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:29
#	0x7ea692	main.main.func2+0x192					/d/Users/User/Work/GitHub/Cloak/cmd/ck-server/ck-server.go:170
#	0x7e95e8	main.main+0x428						/d/Users/User/Work/GitHub/Cloak/cmd/ck-server/ck-server.go:178
#	0x436c71	runtime.main+0x211					/usr/lib/go-1.14/src/runtime/proc.go:203

1 @ 0x437050 0x4479f0 0x4479db 0x447757 0x47ee0c 0x47ecf7 0x7875af 0x786ea3 0x785613 0x7241d0 0x795d6d 0x466241
#	0x447756	sync.runtime_SemacquireMutex+0x46						/usr/lib/go-1.14/src/runtime/sema.go:71
#	0x47ee0b	sync.(*Mutex).lockSlow+0xfb							/usr/lib/go-1.14/src/sync/mutex.go:138
#	0x47ecf6	sync.(*Mutex).Lock+0x46								/usr/lib/go-1.14/src/sync/mutex.go:81
#	0x7875ae	github.com/cbeuw/Cloak/internal/multiplex.(*streamBufferedPipe).WriteTo+0x5e	/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBufferedPipe.go:64
#	0x786ea2	github.com/cbeuw/Cloak/internal/multiplex.(*streamBuffer).WriteTo+0x42		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/streamBuffer.go:103
#	0x785612	github.com/cbeuw/Cloak/internal/multiplex.(*Stream).WriteTo+0x62		/d/Users/User/Work/GitHub/Cloak/internal/multiplex/stream.go:105
#	0x7241cf	github.com/cbeuw/Cloak/internal/common.Copy+0x42f				/d/Users/User/Work/GitHub/Cloak/internal/common/copy.go:46
#	0x795d6c	github.com/cbeuw/Cloak/internal/server.serveSession.func1+0x4c			/d/Users/User/Work/GitHub/Cloak/internal/server/dispatcher.go:281

1 @ 0x437050 0x45389a 0x7927d1 0x466241
#	0x453899	time.Sleep+0xb9								/usr/lib/go-1.14/src/runtime/time.go:188
#	0x7927d0	github.com/cbeuw/Cloak/internal/server.(*State).UsedRandomCleaner+0x170	/d/Users/User/Work/GitHub/Cloak/internal/server/state.go:213

1 @ 0x437050 0x45389a 0x79449f 0x466241
#	0x453899	time.Sleep+0xb9									/usr/lib/go-1.14/src/runtime/time.go:188
#	0x79449e	github.com/cbeuw/Cloak/internal/server.(*userPanel).regularQueueUpload+0x2e	/d/Users/User/Work/GitHub/Cloak/internal/server/userpanel.go:210

1 @ 0x7dd625 0x7dd440 0x7da1da 0x7e764a 0x7e80a5 0x6e3354 0x6e5195 0x6e66e3 0x6e215c 0x466241
#	0x7dd624	runtime/pprof.writeRuntimeProfile+0x94	/usr/lib/go-1.14/src/runtime/pprof/pprof.go:694
#	0x7dd43f	runtime/pprof.writeGoroutine+0x9f	/usr/lib/go-1.14/src/runtime/pprof/pprof.go:656
#	0x7da1d9	runtime/pprof.(*Profile).WriteTo+0x3d9	/usr/lib/go-1.14/src/runtime/pprof/pprof.go:329
#	0x7e7649	net/http/pprof.handler.ServeHTTP+0x339	/usr/lib/go-1.14/src/net/http/pprof/pprof.go:248
#	0x7e80a4	net/http/pprof.Index+0x734		/usr/lib/go-1.14/src/net/http/pprof/pprof.go:271
#	0x6e3353	net/http.HandlerFunc.ServeHTTP+0x43	/usr/lib/go-1.14/src/net/http/server.go:2012
#	0x6e5194	net/http.(*ServeMux).ServeHTTP+0x1a4	/usr/lib/go-1.14/src/net/http/server.go:2387
#	0x6e66e2	net/http.serverHandler.ServeHTTP+0xa2	/usr/lib/go-1.14/src/net/http/server.go:2807
#	0x6e215b	net/http.(*conn).serve+0x86b		/usr/lib/go-1.14/src/net/http/server.go:1895

You're right I'm getting the same issue.

notsure2 · 2020-12-05T21:29:39Z

maybe there's a case where close is not getting called, or broadcastAfter is getting called after close is called....

cbeuw · 2020-12-05T21:40:55Z

Because a memory leak is better than an excessive goroutine leak under normal load, I've reverted 4baca25.

Additionally I couldn't reproduce the memory leak without a stress test. I'll experiment with a stress test and see how serious it is and try to find a better solution

notsure2 · 2020-12-05T21:56:33Z

The thing is, it shouldn't have leaked unless broadcastAfter is being called after Close (or both are called together). I'll add some logging messages to investigate this. I think it's possible to solve without reverting.

notsure2 · 2020-12-05T22:12:03Z

@cbeuw to reproduce this, just setup shadowsocks + cloak. then setup torrent client to use shadowsocks, then download a torrent with lot of seeds with torrent client set to use ~100 connections per torrent. Set Cloak NumConn=0

notsure2 · 2020-12-05T23:19:09Z

@cbeuw I think there's something weird with this part:

Cloak/internal/multiplex/streamBufferedPipe.go

Lines 78 to 93 in c0040f2

 if p.wtTimeout != 0 { 

 p.rDeadline = time.Now().Add(p.wtTimeout) 

 time.AfterFunc(p.wtTimeout, p.rwCond.Broadcast) 

 } 

 if p.buf.Len() > 0 { 

 written, er := p.buf.WriteTo(w) 

 n += written 

 if er != nil { 

 p.rwCond.Broadcast() 

 return n, er 

 } 

 p.rwCond.Broadcast() 

 } else { 

 p.rwCond.Wait() 

 } 

 }

In case wTimeout is not 0 (ie: StreamTimeout is set in the config), it schedules a next broadcast (here's an allocated timer).

However, in the very next line, if the buffer is NOT empty, it writes its contents and sends a broadcast by itself without waiting, making the previously scheduled timer callback redundant.

Shouldn't this if block be moved inside the next else block ? You only need to schedule a broadcast if you are then going to wait. In fact, this is going to create a new timer every loop whether there is data in the buffer or not.

cbeuw · 2020-12-06T00:15:51Z

I think you are right. We should only schedule a broadcast via AfterFunc only if we know we will wait for an indeterminate amount of time. In fact, this should apply to the bit above checking if rDeadline is set as well

cbeuw closed this as completed in 4baca25 Dec 5, 2020

notsure2 mentioned this issue Dec 5, 2020

Explicitly stop the timer when the connection is closed. #138

Merged

cbeuw reopened this Dec 5, 2020

cbeuw closed this as completed in a3520c1 Dec 5, 2020

cbeuw reopened this Dec 5, 2020

cbeuw closed this as completed in #138 Dec 6, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Too high memory usage #137

Too high memory usage #137

notsure2 commented Dec 5, 2020

notsure2 commented Dec 5, 2020

notsure2 commented Dec 5, 2020

notsure2 commented Dec 5, 2020

notsure2 commented Dec 5, 2020

notsure2 commented Dec 5, 2020 •

edited

Loading

notsure2 commented Dec 5, 2020

notsure2 commented Dec 5, 2020

cbeuw commented Dec 5, 2020

cbeuw commented Dec 5, 2020

cbeuw commented Dec 5, 2020

notsure2 commented Dec 5, 2020 •

edited

Loading

notsure2 commented Dec 5, 2020

cbeuw commented Dec 5, 2020

notsure2 commented Dec 5, 2020

notsure2 commented Dec 5, 2020

cbeuw commented Dec 5, 2020

notsure2 commented Dec 5, 2020

notsure2 commented Dec 5, 2020 •

edited

Loading

notsure2 commented Dec 5, 2020 •

edited

Loading

cbeuw commented Dec 6, 2020

Too high memory usage #137

Too high memory usage #137

Comments

notsure2 commented Dec 5, 2020

notsure2 commented Dec 5, 2020

notsure2 commented Dec 5, 2020

notsure2 commented Dec 5, 2020

notsure2 commented Dec 5, 2020

notsure2 commented Dec 5, 2020 • edited Loading

notsure2 commented Dec 5, 2020

notsure2 commented Dec 5, 2020

cbeuw commented Dec 5, 2020

cbeuw commented Dec 5, 2020

cbeuw commented Dec 5, 2020

notsure2 commented Dec 5, 2020 • edited Loading

notsure2 commented Dec 5, 2020

cbeuw commented Dec 5, 2020

notsure2 commented Dec 5, 2020

notsure2 commented Dec 5, 2020

cbeuw commented Dec 5, 2020

notsure2 commented Dec 5, 2020

notsure2 commented Dec 5, 2020 • edited Loading

notsure2 commented Dec 5, 2020 • edited Loading

cbeuw commented Dec 6, 2020

notsure2 commented Dec 5, 2020 •

edited

Loading

notsure2 commented Dec 5, 2020 •

edited

Loading

notsure2 commented Dec 5, 2020 •

edited

Loading

notsure2 commented Dec 5, 2020 •

edited

Loading