Showing posts with label logging. Show all posts
Showing posts with label logging. Show all posts

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.