Golang Decorators: Logging & Time Profiling

Golang's imperative world

Golang is not, by any means, a functional language; its design remains true to its jingle, which says that it is "C for the 21st Century". One task I tried to do early on in learning the language was search for the map, filter, and reduce functions in the standard library but to no avail. Next, I tried rolling my own versions, but I felt as though I hit a bit of a road block when I discovered that there is no support for generics in the language at the time of writing this. There is, however, support for Higher Order Functions or, more simply put, functions that take other functions as arguments and return functions.

If you have spent some time in Python, you may have come to love a design pattern called "Decorator". In fact, decorators make life in Python so great that support for applying them is built right into the language with a nifty @ operator! Python frameworks such as Flask extensively use decorators. If you have little or no experience in Python, fear not for the concept is a design pattern independent of any language.

Decorators

An alternative name for the decorator pattern is "wrapper", which pretty much sums it all up in one word! A decorator's job is only to wrap a function so that additional code can be executed when the original function is called. This is accomplished by writing a function that takes a function as its argument and returns a function of the same type (Higher Order Functions in action!). While this still calls the original function and passes through its return value, it does something extra along the way.

Decorators for logging

We can easily log which specific method is passed with a little help from our decorator friends. Say, we wanted to log which user liked a blog post and what the ID of the post was all without touching any code in the original likePost function.

Here is our original function:

func likePost(userId int, postId int) bool {
    fmt.Printf("Update Complete!n")
    return true
}

Our decorator might look something similar to this:

type LikeFunc func(int, int) bool

func decoratedLike(f LikeFunc) LikeFunc {
    return func(userId int, postId int) bool {
        fmt.Printf("likePost Log: User %v liked post# %vn", userId, postId)
        return f(userId, postId)
    }
}

Note the use of the type definition here. I encourage you to use it for the sake of readability when defining functions with long signatures, such as those of decorators, as you need to type the function signature twice.

Now, we can apply the decorator and allow the logging to begin:

r := likeStats(likePost)
    r(1414, 324)
    r(5454, 324)
    r(4322, 250)

This produces the following output:

likePost Log: User 1414 liked post# 324
Update Complete!
likePost Log: User 5454 liked post# 324
Update Complete!
likePost Log: User 4322 liked post# 250
Update Complete!

Our original likePost function still gets called and runs as expected, but now we get an additional log detailing the user and post IDs that were passed to the function each time it was called. Hopefully, this will help speed up debugging our likePost function if and when we encounter strange behavior!

Decorators for performance!

Say, we run a "Top 10" site and previously, our main sorting routine to find the top 10 cat photos of this week on the Internet was written with Golang's func Sort(data Interface) function from the sort package of the Golang standard library.

Everything is fine until we are informed that Fluffy the cat is infuriated that she is coming in at number six on the list and not number five. The cats at ranks five and six on the list both had 5000 likes each, but Fluffy reached 5000 likes a day earlier than Bozo the cat, who is currently higher ranked. We like to give credit where it's due, so we apologize to Fluffy and go on to use the stable version of the func Stable(data Interface) sort, which preserves the order of elements equal in value during the sort.

We can improve our code and tests so that this does not happen again (We promised Fluffy!). The tests pass, everything looks great, and we deploy gracefully... or so we think.

Over the course of the day, other developers also deploy their changes, and then, after checking our performance reports, we notice a slowdown somewhere.

Is it from our switch to stable the sorting? Well, let’s use decorators to measure the performance of both sort functions and check whether there is a noticeable dip in performance.

Here’s our testing function:

type SortFunc func(sort.Interface)

func timedSortFunc(f SortFunc) SortFunc {
    return func(data sort.Interface) {

        defer func(t time.Time) {
            fmt.Printf("--- Time Elapsed: %v ---n", time.Since(t))
        }(time.Now())

        f(data)
    }
}

In case you are unfamiliar with defer, all it does is call the function it is passed right after its calling function returns. The arguments passed to defer are evaluated right away, so the value we get from time.Now() is really the start time of the function!

Let’s go ahead and give this test a go:

stable := timedSortFunc(sort.Stable)
    unStable := timedSortFunc(sort.Sort)

    // 10000 Elements with values ranging 
    // between 0 and 5000
    randomCatList1 := randomCatScoreSlice(10000, 5000)
    randomCatList2 := randomCatScoreSlice(10000, 5000)

    fmt.Printf("Unstable Sorting Function:n")
    stable(randomCatList1)
    fmt.Printf("Stable Sorting Function:n")
    unStable(randomCatList2)

The following output is yielded:

Unstable Sorting Function:
--- Time Elapsed: 282.889µs ---
Stable Sorting Function:
--- Time Elapsed: 93.947µs ---

Wow! Fluffy's complaint not only made our top 10 list more accurate but now they sort about three times as fast with the stable version of sort as well! (However, we still need to be careful; sort.Stable most likely uses way more memory than the standard sort.Sort function.)

Final thoughts

Figuring out when and where to apply the decorator pattern is really up to you and your team. There are no hard rules, and you can completely live without it. However, when it comes to things like extra logging or profiling a pesky area of your code, this technique may prove to be a valuable tool.

Where is the rest of the code?

In order get this example up and running, there is some setup code that was not shown here in order to keep the post from becoming too bloated. I encourage you take a look at this code here if you are interested!

About the author

Nick Maccharoli is an iOS/backend developer and open source enthusiast working at a start-up in Tokyo and enjoying the current development scene. You can see what he is up to at @din0sr or github.com/nirma.