gologgingoverhead

Overhead for Golang's logger if set to discard


I have a HTTP handler that has 40 loggers that is set to os.Stdout.

It works just fine for me as I am the only one testing at the moment. But, when it goes to the production, I'm afraid it will have too much overhead.

Currently loggers are set to os.Stdout and os.Stderr. But once it gets to the production, os.Stdout will be set to ioutil.discard.

Q1. Will it impact the performance if I still have the logger in set to discard?

Q2. For the best practice, is it better to remove loggers completely from the HTTP handler?

---- UPDATE ----

package main

import (
    "time"
    "fmt"
    "log"
    "io/ioutil"
    "io"
)

func testPrintf(w io.Writer, note string, cnt int) {
    l := log.New(w, "", 0)
    t1 := time.Now()
    for i:=0; i<cnt; i++ {
        l.Printf("%s - %d", "test", i)
    }
    t2 := time.Now()
    fmt.Printf("%-15s  %-15s, %v\n","Printf ", note, t2.Sub(t1))
}

func testPrintln(w io.Writer, note string, cnt int) {
    l := log.New(w, "", 0)
    t1 := time.Now()
    for i:=0; i<cnt; i++ {
        l.Println("test" + string(i))
    }
    t2 := time.Now()
    fmt.Printf("%-15s  %-15s, %v\n","Println", note, t2.Sub(t1))
}

func testDoNothing(w io.Writer, note string, cnt int) {
    //l := log.New(w, "", 0)
    t1 := time.Now()
    for i:=0; i<cnt; i++ {
        _ = "test" + string(i) // evaluated but didn't do any.
    }
    t2 := time.Now()
    fmt.Printf("%-15s  %-15s, %v\n", "DoNothing", note, t2.Sub(t1))
}

func main() {
    cnt := 10000000 // ten million
    testPrintf(ioutil.Discard, "discard.Attempt.1", cnt)
    testPrintln(ioutil.Discard, "discard.Attempt.1", cnt)
    testDoNothing(ioutil.Discard, "discard.Attempt.1", cnt)
    fmt.Println("\n")
    testPrintf(ioutil.Discard, "discard.Attempt.2", cnt)
    testPrintln(ioutil.Discard, "discard.Attempt.2", cnt)
    testDoNothing(ioutil.Discard, "discard.Attempt.2", cnt)
    fmt.Println("\n")
    testPrintf(ioutil.Discard, "discard.Attempt.3", cnt)
    testPrintln(ioutil.Discard, "discard.Attempt.3", cnt)
    testDoNothing(ioutil.Discard, "discard.Attempt.3", cnt)
}

--- RESULT ---

Printf           discard.Attempt.1, 2.663697209s
Println          discard.Attempt.1, 2.4289759s
DoNothing        discard.Attempt.1, 190.480694ms

Printf           discard.Attempt.2, 2.493506245s
Println          discard.Attempt.2, 2.426081786s
DoNothing        discard.Attempt.2, 182.899574ms

Printf           discard.Attempt.3, 2.480853275s
Println          discard.Attempt.3, 2.481552836s
DoNothing        discard.Attempt.3, 180.916608ms
  1. I ran for 10M times for each.
  2. 2~3 sec for 10M log to io.Discard is faster than I thought.. I guess I don't have to worry about the speed.
  3. os.Stdout which I didn't mean to use; (my original concern was keeping code with ioutil.Discard vs remove the code), but since os.Stdout was not buffered, it was slow.
  4. By the way, printf() was a lot faster than I thought. Almost same as println()

I don't write Go code daily basis, so this test may be inaccurate. If you see misleading info from the test, please leave a comment here for others to aware. Thank you.


Solution

  • Benchmarks

    While my gut says that dropping the logs to Discard will have minimal impact to your code I would recommend setting up a benchmark to test the performance impact of your loggers.

    Fortunately Go makes this very easy by writing a func BenchmarkXxxxx(*testing.B) function in your unit tests and running go test -bench. More information can be found in the documentation. For your benchmark I recommend writing two tests, one with the os.Stdout and the other with ioutil.Discard - make sure the inputs to both tests are the same.

    Relevant code from ioutil to show just what will happen "under the hood":

    // ioutil.go
    type devNull int
    
    func (devNull) Write(p []byte) (int, error) {
        return len(p), nil
    }
    
    func (devNull) WriteString(s string) (int, error) {
        return len(s), nil
    }
    

    Logging Best Practices

    One approach to logging is the common "Level Based Logging" where you pick the severity of the message wishing to be logged (DEBUG/INFO/WARN/ERROR etc.) then choose which levels to display when deploying your application (e.g. DEBUG and above in development but WARN and above in production).

    As you will have noticed Go only provides Print and Error level statements in the standard library so you will need an external package to benefit from something like this (these can also help structuring your logs in a more machine readable/search friendly JSON format too). Dave Cheney has justified the reasoning behind this decision in a blog post.

    In your case 40 log statements sounds like a lot but this may depend on how many are simple Print logs; size and complexity of the handler etc. Print logging can be exceptionally helpful as a temporary measure in development and Error to help diagnose during failures if you are not surfacing the error to the client.