Golang the road to optimization-build a log wheel on your own

This is a creation in Article, where the information may have evolved or changed.

Write in front

Golang Log package content is not much, to tell the truth, directly used to do the journal development is simple. The main feature is missing some features:

1. Print and control logs at the log level;
2. Automatic segmentation of log files;
3. Asynchronously prints the log.

Print and control logs at the log level

The log modules we implement will support 4 levels:

const (    LevelError = iota    LevelWarning    LevelInformational    LevelDebug)

Define a log structure body:

type Logger struct {    level int    l     *log.Logger}func (ll *Logger) Error(format string, v ...interface{}) {    if LevelError > ll.level {        return    }    msg := fmt.Sprintf("[E] "+format, v...)    ll.l.Printf(msg)}

This enables the log level control output and, when printed, appends a tag, such as the example above, and theError level is appended with [E].

This implementation is already available, but there is still room for optimization. For example, when you print the append tag [E] , the string addition is used. The string addition will request new memory and is not optimized for performance. We need to optimize by character array.

But I'm not going to optimize it that way. This time look at the log packet API, you can find that the native package is supported by the setting prefix:

func (l *Logger) SetPrefix(prefix string)

Take a look at the specific implementation:

func (l *Logger) formatHeader(buf *[]byte, t time.Time, file string, line int) {    *buf = append(*buf, l.prefix...)

Native packages are used to improve performance when writing log prefixes []byte . Since we have already provided it, we should not build it ourselves. Then the problem comes, the setting prefix is initialized when the setting is set, printing automatically output. An log.Logger object can have only one prefix, and we need 4 levels of prefix, how does this print?

type Logger struct {    level int    err   *log.Logger    warn  *log.Logger    info  *log.Logger    debug *log.Logger}

We apply directly to 4 log objects to resolve. To ensure that all levels are printed in the same file, the initialization time is set to the same one io.Writer .

logger := new(LcLogger)logger.err = log.New(w, "[E] ", flag)logger.warn = log.New(w, "[W] ", flag)logger.info = log.New(w, "[I] ", flag)logger.debug = log.New(w, "[D] ", flag)

To set the logging level:

func (ll *Logger) SetLevel(l int) {    ll.level = l}

The output is controlled according to the log level when printing. (Tell me about a hole I met.) Once there was too much print log and the disk was full, I was thinking of turning the log level up to reduce the print content. The level of error after the discovery or no effect, and finally looked at the code to find the problem of the log print Error level ... The error level log should be played as little as possible. ）

func (ll *Logger) Error(format string, v ...interface{}) {    if LevelError > ll.level {        return    }    ll.err.Printf(format, v...)}

Automatic log file segmentation

Log files need to be split automatically. Otherwise, a file is too large to clean up the disk when the file is still printed on the log is not able to clean up.

Log splitting I think it's better to simply split the size.

So how does the log splitting function access the log module we implemented above? The key is io.Writer .

type Writer interface {    Write(p []byte) (n int, err error)}

WriterThis interface has only one method, so simple. The default print log for the native package is output to the os.Stderr inside, which is a os.File type of variable that implements Writer this interface.

func (f *File) Write(b []byte) (n int, err error)

The log packet automatically calls the method when it is written Write . We can implement one ourselves Writer , at Write the time to calculate the current log file size after writing this line log, if it exceeds the set value, perform a split. Splitting logs by day is also the time to operate.

It is recommended to use GOPKG.IN/NATEFINCH/LUMBERJACK.V2 this package to do the log segmentation, the function is very powerful.

jack := &lumberjack.Logger{    Filename: lfn,    MaxSize:  maxsize, // megabytes}

The use is also very simple, the jack object is one Writer , can be copied directly to Logger use.

Asynchronous output of the log

The Federation pool is also the entire package: Github.com/ivpusic/grpool. The pool does not unfold, and it is interesting to see the implementation of this package.

The structure of the log is once again upgraded:

type Logger struct {    level int    err   *log.Logger    warn  *log.Logger    info  *log.Logger    debug *log.Logger    p     *grpool.Pool}

Initialization

logger.p = grpool.NewPool(numWorkers, jobQueueLen)

Log output:

func (ll *Logger) Error(format string, v ...interface{}) {    if LevelError > ll.level {        return    }    ll.p.JobQueue <- func() {        ll.err.Printf(format, v...)    }}

Journal line number

If you do it one step at a time, the print log is set Lshortfile and the line number is displayed, you may find that there is a problem with the line number printed. The stack information is used when the log is printed runtime , because we encapsulate a layer, so the stack depth of the print changes. Simply put is a deep layer.

The native log package provided func (l *Logger) Output(calldepth int, s string) error to control the log stack depth output, and we adjusted the code again.

type Logger struct {    level int    err   *log.Logger    warn  *log.Logger    info  *log.Logger    debug *log.Logger    p     *grpool.Pool    depth int}func (ll *Logger) Error(format string, v ...interface{}) {    if LevelError > ll.level {        return    }    ll.p.JobQueue <- func() {        ll.err.Output(ll.depth, fmt.Sprintf(format, v...))    }}

We only encapsulate one layer, so the depth is set to 3.

Thread Safety

Native package print logs are thread-safe:

func (l *Logger) Output(calldepth int, s string) error {    now := time.Now() // get this early.    var file string    var line int    l.mu.Lock() // 看到这里了么？    defer l.mu.Unlock()    if l.flag&(Lshortfile|Llongfile) != 0 {        // release lock while getting caller info - it's expensive.        l.mu.Unlock()        var ok bool        _, file, line, ok = runtime.Caller(calldepth)        if !ok {            file = "???"            line = 0        }        l.mu.Lock()    }    l.buf = l.buf[:0]    l.formatHeader(&l.buf, now, file, line)    l.buf = append(l.buf, s...)    if len(s) == 0 || s[len(s)-1] != '\n' {        l.buf = append(l.buf, '\n')    }    _, err := l.out.Write(l.buf)    return err}

With its assurance, we do not need to consider thread safety issues anymore.

So the question is, fmt is the package print log thread-safe? are println you safe? fmtand println where are the print logs printed? Interested can leave a message to discuss together.

At last

The print of the log will use fmt.Sprintf something like this, which will be used to reflect when it is implemented. Reflection can have an effect on performance, but the code is too disgusting without reflection.

The full code is put on GitHub, the address.

The logs described above are only for output to a file. If you want to output mail, Elasticsearch and other places, do not be initialized with a variety of complex configuration parameters to achieve.

That's what I'm talking about:

NewLogger("es", ...)NewLogger("smtp", ...)

The problem with this is that I can only use you to provide good things, if you want to expand can only modify the log package. If this package is a third-party package, how can it be extended to others? And this implementation is not the Golang style of implementation.

In fact, we look at the original of these packages, many are connected through the interface together. Native log packet, you can think of his service is mainly the process of services , splicing good to print the content, including line number, time and so on, to ensure that thread security, and then call Writer to print. If we're going to print the logs into ES, we'll implement one ESWriter . This is the Golang style code.

Reference documents

• "1" "Go language Combat"