SoFunction
Updated on 2025-03-05

Golang log4go log output optimization detailed explanation

Preface

In the go language, it has integrated certain log modules, and developers can use the go language's own log package(import “log”) . There are also many open source packaging for their own logs. For some simple development, its own log module is enough to deal with. However, for some large and complex developments, logs need to be output in categories or output through the network, and their own log module will be difficult to deal with.

Currently, there are some more heavyweight log modules, such as logrus, that can implement more complex functions. Here is a lightweight log module - log4go

Recently, I have read some golang log packages and related articles, and carefully read the logs and logs provided by go 1.9.2 system andgo-log, resulting in the idea of ​​optimizing log output of log4go.

Structured and multiwriter

Log uses multiwriter to support multiple log outputs, and uses Mutex to lock to resolve conflicts in multithreaded log outputs. log4go uses structured programming to pass LogRecord logging using channel.

I originally thought that channel is more efficient... In fact, this is a false proposition. channel is a global lock queue that can be used to lock, but is relatively inefficient. Because it has more functions such as passing data, coordinating sequence processing, and timout, it is not just locking. It's not the same as Mutex.

log4go puts the screen log output termlog in the structure, which brings a small problem. When we use log4go to debug the applet, it runs too fast and the goroutine of termlog has not yet been run, the program exits. The result is that no logs are displayed on the screen. This problem can only be done inClose() time delay, wait for goroutine to start to resolve. Then check the channel...

func (f *Filter) Close() {
 if  {
  return
 }
 // sleep at most one second and let go routine running
 // drain the log channel before closing
 for i := 10; i > 0; i-- {
  // Must call Sleep here, otherwise, may panic send on closed channel
  (100 * )
  if len() <= 0 {
   break
  }
 }
 // block write channel
  = true
 defer ()
 close()
 if len() <= 0 {
  return
 }
 // drain the log channel and write driect
 for rec := range  {
  (rec)
 }
}

Log directly outputs formatted log information to the screen, which is much simpler.

Try to take into account both, add a writer to log4go and output it directly to the screen. It is planned to use FileLog and SocketLog as backends and still place them in the structure. In this way, debugging applets and production programs can use the same log library. The actual measurement efficiency has been slightly reduced. I don’t know how ColorLog is under Windows, so I will talk about it later.

You can call it in log4goSetOutput(nil) ,makeout = nil to turn off screen output.

Determine caller func - it's expensive

This sentence is commented in the log source file, and log4go must also be called(skip int)Function to get the source file name and line number. It is expensive - consumes CPU. It is recommended to shut down in production environment.(-1). If you want to encapsulate log4go, set (()+1)

format optimization

In fact, this is the subject of the article.

Log output cannot avoid printing dates and times. In the Linux environment, it also needs to print microseconds, and maybe the time zone needs to be printed. log4go does this job.

  • There is a cache mechanism that is updated once every 1 second. very beautiful.
  • Use string formatting functions extensively -.
  • Returns the string. The writer generally supports []byte. Make an extra conversion.
  • Every time, the format string is decomposed into [][] byte in % characters.

I have a cheap itoa function in the log.

// Cheap integer to fixed-width decimal ASCII. Give a negative width to avoid zero-padding.
func itoa(buf *[]byte, i int, wid int) {
 // Assemble decimal in reverse order.
 var b [20]byte
 bp := len(b) - 1
 for i >= 10 || wid > 1 {
  wid--
  q := i / 10
  b[bp] = byte('0' + i - q*10)
  bp--
  i = q
 }
 // i < 10
 b[bp] = byte('0' + i)
 *buf = append(*buf, b[bp:]...)
}

Replace the string formatting function of date and time with this function. Use []byte instead of string.

Before optimization, log4go benchmark.

BenchmarkFormatLogRecord-4    300000    4480 ns/op
BenchmarkConsoleLog-4     1000000    1748 ns/op
BenchmarkConsoleNotLogged-4    20000000    97.5 ns/op
BenchmarkConsoleUtilLog-4     300000    3496 ns/op
BenchmarkConsoleUtilNotLog-4   20000000    104 ns/op

After optimization:

BenchmarkFormatLogRecord-4  1000000    1443 ns/op
BenchmarkConsoleLog-4   2000000    982 ns/op
BenchmarkConsoleUtilLog-4   500000    3242 ns/op
BenchmarkConsoleUtilNotLog-4 30000000    48.4 ns/op

The time it takes to format the date and time is 1/3 of the original time.

The time it takes to print unformatted information is 1/2 of the original time.

BenchmarkConsoleUtilLog is called, format the information and add the time to output information to the screen.

String formatting – more expensive.

Summarize

The above is the entire content of this article. I hope that the content of this article has certain reference value for everyone's study or work. If you have any questions, you can leave a message to communicate. Thank you for your support.