0

I've written a simple TCP server.
The problem is that when stress-testing it, it seems that the memory usage is increasing dramatically, and not decreasing when he test is done. When the server is started, it takes ~700KB.
During and after the stress-test, the memory usage jumps to ~7MB.
Here's my code:

package main

import (
    "net"
    "log"
    "fmt"
    "bufio"
)

func main() {
    ln, err := net.Listen("tcp", ":8888")
    if err != nil {
        log.Fatal(err)
    }
    defer ln.Close()
    for {
        conn, err := ln.Accept()
        if err != nil {
            fmt.Println(err)
            continue
        }
        go handle(conn)
    }
}

func handle(conn net.Conn) {
    defer conn.Close()
    fmt.Println("Accepted", conn.LocalAddr())
    for {
        buf, err := bufio.NewReader(conn).ReadString('\n')
        if err != nil {
            break
        }
        msg := string(buf[:len(buf)-2])
        fmt.Println("Received", msg)
        conn.Write([]byte("OK\n"))
    }
}

Any help is much appreciated.

Note: I'm using tcpkali for loading it. This is the command line:

tcpkali -em "testing\r\n" -c 100 -r 1000 -T 60  127.0.0.1:8888

EDIT: Following some comments below, I ran some tests and here are the results:

  1. Started the server and ran tcpkali.
  2. After the first run, RSS was at 8516.
  3. After a second run, RSS climbed to 8572.
  4. Server is now idle. 5 minutes later, RSS climbed to 8588.
  5. 5 more minutes later, RSS climbed to 8608, and seems stable.
  6. After 15 minutes of break, I ran tcpkali again, and RSS climbed to 8684.
  7. A few minutes break, another tcpkali run, RSS climbs to 8696.
  8. A few minutes break, another tcpkali run, RSS climbs to 8704.
  9. A few minutes break, another tcpkali run, RSS climbs to 8712.

Now, I don't know what you call this, but I call this a memory leak. Something is wrong here. No memory is freed, and RSS is keep climbing every time I run a test. Obviously, this thing cannot be deployed to production as it will eventually consume all available memory.
I also tried calling os.FreeOSMemory() but nothing happens.

My system is Go 1.9.4 on macOS 10.13.1. Is this environment related or am I missing something?

LAST UPDATE:
Following @Steffen Ullrich answer and the tests that failed on my environment, I gave it a try on Ubuntu server, and the memory is freed after a few minutes of idle time.
Seems like there's an issue with macOS.

user1102018
  • 4,369
  • 6
  • 26
  • 33
  • 1
    In a comment to a now deleted answer you said you are measuring memory usage with OS tools. Like most runtimes with garbage collection, Go does not return unused memory to the OS immediately to save malloc calls. How long did you wait after the test completed? – Peter Apr 15 '18 at 14:34
  • Well, I've waited around 10 minutes, and the memory is not yet freed – user1102018 Apr 15 '18 at 15:25
  • take a look with expvar and expvarmon. easy to setup, easy to visualize. –  Apr 15 '18 at 15:44
  • I don't understand the downvotes, as there is clearly a problem here. The "duplicate" question is not duplicate. The comments didn't help. I've waited half an hour and the memory is still high. I called `debug.FreeOSMemory()` and nothing happens. There's clearly a problem here and I'm sure that you can create it on your local machine. As I said in the post, I would appreciate any help. Thanks – user1102018 Apr 16 '18 at 07:18
  • Note that “releasing” memory is only advisory, depending on the OS it may not reclaim it until there is memory pressure to do so. – JimB Apr 16 '18 at 16:31

1 Answers1

4

Go does not release memory it allocated from the OS immediately. The reason is probably that allocating memory is costly (needs system calls) and the chance is high that it will be needed in the near future anyway again. But, if memory gets long enough unused it will be released eventually so that the RSS of the process decreases again.

Doing your test again with slight modifications will show this (it did at least for me):

  1. Start you program and look at the RSS.
  2. Run tcpkali, wait for tcpkali to end and look at the RSS again. It is much higher now since lots of memory was needed for the program to do the intended task.
  3. Don't stop the program but run tcpkali again and wait again for it to end. When looking at the RSS you should see that it did not grow (much) further. This means that the program used the already allocated memory again and did not need to allocate new memory from the system.
  4. Now monitor the RSS and wait. After a while (about 10 minutes on my system) you should see the RSS go down again. This is because the program has determined now that the allocated but unused memory will probably not be used any longer and returned the memory back to the OS.

Note that not all memory might be given back. According to Understanding Go Lang Memory Usage it will not return (in go 1.3) the memory used for the stacks of the go routines since it is more likely that this will be needed in the future.

For testing you might also add some debug.FreeOSMemory() (from runtime/debug) at strategic places (like when you break out of the loop in the goroutine) so that the memory gets returned earlier to the OS. But given that the lazy return of memory is for performance such explicit freeing might impact the performance.

Steffen Ullrich
  • 114,247
  • 10
  • 131
  • 172
  • thanks for the suggestion. I monitored the RSS, and after 20 minutes it's still at its peak. I called `FreeOSMemory()` a minute after the load test, and nothing happens. This looks really bad – user1102018 Apr 16 '18 at 07:14
  • @user1102018: I've used your original code and go 1.10.1 on Ubuntu 16.04 and this is the result I've got. Did you really look at the RSS and not the VSZ? And, did you rerun tcpkali with the go program still running to see if the size increases further? – Steffen Ullrich Apr 16 '18 at 08:51
  • I'm running Go 1.9.4 on macOS 10.13.1, and yes, I'm looking at the RSS. After the first run, RSS was at 8516. After the second run, RSS climbed to 8572. Started waiting. 5 minutes into the break, RSS climbed to 8588. 10 minutes into the break, RSS climbed to 8608, and seems stable. After 15 minutes of break, I ran tcpkali again, and RSS climbed to 8684 – user1102018 Apr 16 '18 at 10:14
  • after 20 more minutes of idle time, I ran tcpkali again. Now the RSS is at 8696. For me, this is memory leak. A long running simple server like this will eventually consume all available memory, if such a behavior persists. This is really frustrating. – user1102018 Apr 16 '18 at 10:38
  • @user1102018: given that the RSS does not really climb anymore (this small increase might be due to fragmentation when managing the allocated memory) I don't see it consuming all available memory eventuelly. It is still strange that it does not give the memory back to the OS as it does in my tests. – Steffen Ullrich Apr 16 '18 at 11:04
  • I've just tested the same code on Ubuntu 14.04, and the memory is freed as you said. Seems like a macOS issue. – user1102018 Apr 16 '18 at 11:52