Details of log output optimization for golang log4go

preface

In go, the log module is integrated with go, and developers can use the log package itself (import “log”) . There are also many open source encapsulations of log itself. For some simple development, the log module itself is sufficient. However, for 1 large, complex development, log needs to be categorized or exported over the network, and its own log module will be difficult to cope with.

There are also a number of heavyweight log modules, such as logrus, that can perform more complex functions. Here is a lightweight log module, log4go

Recently, I have read some golang log packages and related articles, and carefully read log and ES24en-ES25en provided by go 1.9.2 system, and came up with the idea of optimizing the log output of log4go.

Structured with multiwriter

log USES multiwriter to support multiple log outputs, and Mutex locks to resolve conflicts of multithreaded log outputs. log4go USES structured programming to pass LogRecord logging with channel.

Originally, channel was thought to be more efficient... This is actually a false statement. channel is a globally locked queue, which can be used for locking, but is less efficient. Because it has more functions such as passing data, coordinating sequential processing, timout, and so on, not just locking. It's not the same thing as Mutex.

log4go puts the screen log output, termlog, in the structure, which presents a minor problem. When we used log4go to debug small program, running too fast, termlog goroutine has not run, the program quit. The resulting log does not appear on the screen. This problem can only be solved through Close() Add delay and wait for goroutine to start. Then check channel...

func (f *Filter) Close() {
 if f.closed {
  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
  time.Sleep(100 * time.Millisecond)
  if len(f.rec) <= 0 {
   break
  }
 }
 // block write channel
 f.closed = true
 defer f.LogWriter.Close()
 close(f.rec)
 if len(f.rec) <= 0 {
  return
 }
 // drain the log channel and write driect
 for rec := range f.rec {
  f.LogWrite(rec)
 }
}

log prints formatted log information directly to the screen, which is much easier.

Try to do both, adding writer to log4go to output directly to the screen. FileLog and SocketLog are still placed in the structure as backend. Thus, debug applets and production programs can use the same log library. The measured efficiency is slightly reduced. I don't know how ColorLog is under windows, I'll talk about it later.

This can be done by calling in log4go SetOutput(nil) To make out = nil To turn off the screen output.

Determine caller func - it's expensive

This comment is in the log source file, which is also called by log4go runtime.Caller(skip int) Function to get the source file name and line number. It's expensive -- CPU. It is recommended to shut down in the production environment, log.SetSkip(-1) . If you want to encapsulate log4go, set log.SetSkip(log.GetSkip()+1) .

format optimization

That, in fact, is the point of the article.

Log output does not avoid printing dates and times, as well as microseconds and perhaps time zones in linux. log4go's ES105en.go does this.

There is an cache mechanism that updates every 1 second. Very beautiful. Heavy use of string formatting functions - ES109en.Sprintf. Returns a string. writer1 generally supports []byte. Do one more conversion. Each time bytes.Splite format string is decomposed as % characters into [][]byte.

There is an cheap itoa function in 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 for date and time with this function. Replace string with []byte.

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 the 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 formatting of the date time takes 1/3 of the original time.

It takes 1/2 as long to print out no formatting information.

BenchmarkConsoleUtilLog calls runtime.Caller , and the time it takes to output the information to the screen.

String formatting - More expensive.

conclusion