Tuesday 22 May 2012

Simple Synchronous and Asynchronous Logging

Almost all services need to write to a log for auditing purposes. When these services require high throughput this write to disk can be a real bottleneck.

So, I wrote a simple log package that implements asynchronous logging to standard output. I only ever write to standard out for service logs. For me redirecting to a file from the command line has proven too flexible over the years to even consider named logs.

Here is the ad/log package:

/*
Package log implements standard logging functions for logging to standard out
*/
package log

import (
    "log"
    "os"
    "fmt"
    "strings"
    "time"
)

var myLog *log.Logger = log.New(os.Stdout, "", log.Ldate+log.Lmicroseconds)

var (
    AsyncBuffer = 1000
    asyncLogging = false
    asyncChannel chan string 
)

//Print message to standard out prefixed with date and time
func Print(s string) {
    if asyncLogging {
        s = "(" + strings.Fields(time.Now().Format(time.StampMicro))[2] + ") " + s
        asyncChannel <- s
    } else {
        myLog.Print(s)
    }
}

//Enable / disable asynchronous logging
func EnableAsync(enable bool) {

    if enable == asyncLogging {
        return
    }

    if enable {
        asyncChannel = make(chan string,AsyncBuffer)
        go func() {
            for {
                message, ok := <-asyncChannel
                if ok {
                    myLog.Print(message)
                } else {
                    asyncLogging = false
                    return
                }
            }
        }()
    } else {
        close(asyncChannel)
    }

    asyncLogging = enable

}

//Returns current asynchronous logging value
func Async() (bool) {
    return asyncLogging
}

Here is a simple example:

package main

import (
    "fmt"
    "time"
    "ad/log"
    "ad/utl"
)

var i = 0;

func main() {

    utl.UseAllCPU()

    incAndPrint()
    log.EnableAsync(true)

    for {
        incAndPrint()
        incAndPrint()
        fmt.Printf("Doing my own thing\n")
        incAndPrint()
        time.Sleep(1e9)
    }

}

func incAndPrint() {
    i += 1
    log.Print(fmt.Sprintf("%v",i))
}

Output looks like this:

~/go/src/ad/misc$ go run logT.go 
2012/05/22 15:39:26.229273 Running log 1.2.1
2012/05/22 15:39:26.229771 Running utl 1.0.0
2012/05/22 15:39:26.229812 Setting UseCPU from 1 to 4
2012/05/22 15:39:26.229874 1
Doing my own thing
2012/05/22 15:39:26.230098 (15:39:26.229989) 2
2012/05/22 15:39:26.230151 (15:39:26.230035) 3
2012/05/22 15:39:26.230163 (15:39:26.230092) 4
Doing my own thing
2012/05/22 15:39:27.230701 (15:39:27.230555) 5
2012/05/22 15:39:27.230761 (15:39:27.230612) 6
2012/05/22 15:39:27.230775 (15:39:27.230696) 7
Doing my own thing
2012/05/22 15:39:28.231295 (15:39:28.231143) 8
2012/05/22 15:39:28.231356 (15:39:28.231203) 9
2012/05/22 15:39:28.231369 (15:39:28.231262) 10

For me the power of this painfully simple package comes when we code log.Print and take the value of the log.asyncLogging flag from a command line switch. This allows you to code in a standard fashion but run individual service instances up with a dedicated logging goroutine if entering a busy period. Alternatively, the log.asyncLogging flag could be set on the fly when the service decided; say when demand is high.