go1.6文件方法WriteStringfrequent调用导致大的系统缓存

Question

go1.6 File method WriteStringfrequent calls led to a large system cache.

How to solve this problem.

go env: linux amd64.

Is this a problem of Linux system?

code:

package main

import (
    "fmt"
    "net/http"
    "os"
    "time"
)

var logCtxCh chan *http.Request
var accessLogFile *os.File

type HandlerHttp struct{}

func (this *HandlerHttp) ServeHTTP(w http.ResponseWriter, req *http.Request) {
    sendAccessLog(req) 
    w.Write([]byte("Hello Word"))
}

func main() {
    s := &http.Server{
        Addr:    ":8012",
        Handler: &HandlerHttp{},
    }
    logCtxCh = make(chan *http.Request, 500)
    go startAcessLog()

   err:= s.ListenAndServe()
   fmt.Println(err.Error())
}

func startAcessLog() {
    for {
        select {
        case ctx := <-logCtxCh:
            handleAccessLog(ctx)
        }
    }
}

func sendAccessLog(req *http.Request) {
    logCtxCh <- req
}

func handleAccessLog(req *http.Request) {
    uri := req.RequestURI
    ip := req.RemoteAddr
    agent := req.UserAgent()
    refer := req.Referer()
    method := req.Method
    now := time.Now().Format("2006-01-02 15:04:05")

    logText := fmt.Sprintf("%s %s %s %s %s %s
",
        now,
        ip,
        method,
        uri,
        agent,
        refer,
    )

    fileName := fmt.Sprintf("/data/logs/zyapi/access_zyapi%s.log",
        time.Now().Format("2006010215"),
    )
    writeLog(fileName, logText)
}

func writeLog(fileName, logText string) {
    var err error
    var exist = true

    if _, err = os.Stat(fileName); os.IsNotExist(err) {
        exist = false
    }

    if exist == false {
        if accessLogFile != nil {
            accessLogFile.Sync()
            accessLogFile.Close()
        }

        accessLogFile, err = os.OpenFile(fileName, os.O_WRONLY|os.O_CREATE|os.O_TRUNC, 0644)
        if err == nil {
            _, err = accessLogFile.WriteString(logText)
        }
        if err != nil {
            fmt.Errorf(err.Error())
        }
    } else {
        if accessLogFile == nil {
            accessLogFile, err = os.OpenFile(fileName, os.O_WRONLY|os.O_APPEND, 0666)
            if err != nil {
                fmt.Errorf(err.Error())
                return
            }
        }
        _, err = accessLogFile.WriteString(logText)
        if err != nil {
            fmt.Errorf(err.Error())
        }
    }
}

test:

ab -n100000 -c10 -k "http://127.0.0.1:8012/"
ab -n100000 -c10 -k "http://127.0.0.1:8012/"
ab -n100000 -c10 -k "http://127.0.0.1:8012/"
ab -n100000 -c10 -k "http://127.0.0.1:8012/"
ab -n100000 -c10 -k "http://127.0.0.1:8012/"

After running several times the system file cache becomes very large

CONTAINER    CPU %   MEM USAGE/LIMIT   MEM %     NET I/O   BLOCK I/O

api_8011  38.47%    6.442GB/6.442GB   100.00%    0B/0B     0B/115.4MB 

api_8012  36.90%    6.442GB/6.442GB   99.99%     0B/0B     0B/115.6 MB

Answer 1

There's a bunch of things going on, I can't spot the bug right away but these things will help:

1. Try to use bufio.Writer as much as possible if you are calling file.WriteString, otherwise every single write will be a syscall, hurting performance.

2. You don't need to use select in you startAccessLog function:

   func startAcessLog() { for ctx := <-logCtxCh { handleAccessLog(ctx) } }

3. Change your error checks from:

   if err != nil { fmt.Errorf(err.Error()) }

   to:

   if err != nil { fmt.Println(err) }

   otherwise you are not printing errors. fmt.Errorf formats a string, like fmt.Sprintf does and returns it as an error. It doesn't print anything at all.

4. You should guard accessLog with a sync.Mutex or write to it via a channel. Why? Because there's more than one goroutine trying to work with accessLog and you don't want data races to happen.
   Doing it via a channel would simplify your writeLog function a log. Currently it's hard to follow the logic. I initially thought you weren't properly closing the file.