Category Archives: Programming

Should methods be declared on T or *T

This post is a continuation of a suggestion I made on twitter a few days ago.

In Go, for any type T, there exists a type *T which is the result of an expression that takes the address of a variable of type T1. For example:

type T struct { a int; b bool }
var t T    // t's type is T
var p = &t // p's type is *T

These two types, T and *T are distinct, but *T is not substitutable for T2.

You can declare a method on any type that you own; that is, a type that you declare in your package3. Thus it follows that you can declare methods on both the type you declare, T, and its corresponding derived pointer type, *T. Another way to talk about this is to say methods on a type are declared to take a copy of their receiver’s value, or a pointer to their receiver’s value 4. So the question becomes, which is the most appropriate form to use?

Obviously if your method mutates its receiver, it should be declared on *T. However, if the method does not mutate its receiver, is it safe to declare it on T instead5?

It turns out that the cases where it is safe to do so are very limited. For example, it is well known that you should not copy a sync.Mutex value as that breaks the invariants of the mutex. As mutexes control access to other things, they are frequently wrapped up in a struct with the value they control:

package counter

type Val struct {
        mu  sync.Mutex
        val int
}

func (v *Val) Get() int {
        v.mu.Lock()
        defer v.mu.Unlock()
        return v.val
}

func (v *Val) Add(n int) {
        v.mu.Lock()
        defer v.mu.Unlock()
        v.val += n
}

Most Go programmers know that it is a mistake to forget to declare the Get or Add methods on the pointer receiver *Val. However any type that embeds a Val to utilise its zero value, must also only declare methods on its pointer receiver otherwise it may inadvertently copy the contents of its embedded type’s values.

type Stats struct {
        a, b, c counter.Val
}

func (s Stats) Sum() int {
        return s.a.Get() + s.b.Get() + s.c.Get() // whoops
}

A similar pitfall can occur with types that maintain slices of values, and of course there is the possibility for an unintended data race.

In short, I think that you should prefer declaring methods on *T unless you have a strong reason to do otherwise.

  1. We say T but that is just a place holder for a type that you declare.
  2. This rule is recursive, taking the address of a variable of type *T returns a result of type **T.
  3. This is why nobody can declare methods on primitive types like int.
  4. Methods in Go are just syntactic sugar for a function which passes the receiver as the first formal parameter.
  5. If the method does not mutate its receiver, does it need to be a method?

Suggestions for contributing to an Open Source project

Occasionally I am asked for advice on how to get started contributing to an Open Source project. I thought it may be useful to write down my suggestions.

These points were written in the context of the Go programming language, but I think this advice is applicable to the majority of modern Open Source projects.

  1. Pick an issue you know how to solve. The best way to get started with a project is to fix a bug. You’ll need to be self sufficient, so do some research and investigate the history behind a bug. Don’t pick an issue you have no familiarity with and then ask “Who can tell me how to solve this bug?”
  2. Ask for more detail. Many bugs lack enough detail to be addressed, so promoting the reporter for more information is in itself a useful service. You may discover that the bug is a duplicate of another, in which case it can be closed. If you can distil the bug report into a reproduction or a test case that is a valuable contribution in itself.
  3. Discuss your change first. When you have chosen a bug, discuss your change before starting to code. You can experiment privately, but do not send a change without discussing it first. Your can probably skip this with very trivial changes, like typos or adding a small test case to an existing package, but for anything larger the rule is: discuss, then code.
  4. Always include a test. One of the first things a reviewer will do is patch in your test and verify that it fails before even looking at your fix. You should therefore write the failing test case first, then write the fix. It may be that you need to refactor the code to be able to write a failing test, which is fine, but brings me back to point 3; discuss your change first. If the project does not have a strong testing regime then you should describe how you went about verifying the fix so someone reviewing your change can do the same.
  5. Change as little as possible. All things being equal, smaller changes are easier to review and are merged faster than large ones. You should aim to change as little as possible to keep the size of the change as small as possible. Avoid the temptation to include a bunch of unrelated changes.
  6. Follow the existing style. Even with tools like gofmt, large projects will commonly exhibit minor stylistic differences. My rule of thumb is: always follow the predominant style of the file in question; if they use long identifiers, use long identifiers, if they use short ones, do so too, and so on. Above all, resist the temptation to include a large stylistic change along with your bug fix.
  7. Be polite, but persistent. If you haven’t received feedback on your proposal after a few days, politely ask for a response. It may be that your proposal was overlooked, or that the project is currently in a feature freeze. Assuming you have followed the advice above, you should expect to get actionable advice on how to improve your change so it can be reviewed.

Investigate your package dependencies with prdeps and Unix

At $DAYJOB I work on a very large Go application; hundreds and hundreds of packages. Recently I’ve been trying to untangle some code that has inadvertently grown huge trunks of dependencies. I suspect this is what is causing the time taken to link our tests to become the subject of ridicule.

I’ve tried previously to visualise the dependency graph of a package, and found the results unsatisfying. This time around I decided to write something simpler, and was pleased with the results. I present prdeps.

In traditional unix style, prdeps does very little, and expects to be part of a larger text processing pipeline.

% prdeps github.com/pkg/sftp
github.com/pkg/sftp:
  github.com/kr/fs:
  golang.org/x/crypto/ssh:
    golang.org/x/crypto/curve25519:

Because Go packages are not a DAG, but a graph not a tree, but a directed graph, the output of running prdeps on any non trivial package is going to be verbose–be prepared for this.

prdeps, like go list takes a -f flag to modify its output. In this example we alter the output format from the usual indented version (which is presented to the template as .Indent) and disable suppression of the stdlib with the -s flag.

% prdeps -s -f {{.ImportPath}} github.com/pkg/sftp | head -n5
github.com/pkg/sftp
bytes
errors
io
errors

Note that errors appears twice in the first five lines of output. errors actually appears 763 times in the output because almost every package either imports it directly and imports a package which also imports errors.

% prdeps -s -f {{.ImportPath}} github.com/pkg/sftp | grep -c errors
763

Another prdeps feature is to print the import graph from the perspective of a test (-t is for internal tests, -T is for external):

% prdeps -T github.com/pkg/sftp
github.com/pkg/sftp:
  github.com/pkg/sftp:
    github.com/kr/fs:
    golang.org/x/crypto/ssh:
      golang.org/x/crypto/curve25519:
  golang.org/x/crypto/ssh:
    golang.org/x/crypto/curve25519:

Compare this to the previous non test output above. This feature was why I built prdeps as I wanted to track down reason the linker was taking so long to link the tests for some of our packages.

prdeps took about 30 minutes to write, and another hour to address the performance issues from several million lines of output that are produced by a non trivial invocation. I’m sure the same result could be done with the right amount of go list, but the pleasure of being able to write exactly the tool I wanted for the job at hand was reason enough for me.

Unhelpful abstractions

Sandi Metz’s post on abstraction struck a chord with me recently. I was working with a piece of code which looked like this (in pseudo code):

func Start() {
        const filename = "..."
        createOuputFile(filename)
        go run(filename)
}

It turned out that createOutputFile was written in an obscure way which first caused me to look at it more closely. Why the code expected the file to exist before starting wasn’t immediately clear. It may have been because some other goroutine was expecting the file to exist on disk, even if nothing had been written yet (slight race smell), or more likely the necessary information was not available for the job itself to create the file with the correct permissions. This calls for a refactoring!

There is a well known UNIX utility that provides these semantics, touch(1). So, I reasoned, createOutputFile is really touch plus the ability to set file permissions, which the former was hard coded to do implicitly. This was a job for abstraction!

How would you write the signature for TouchFile? Here is what I came up with:

// TouchFile ensures path exists, or creates it using
// the supplied file mode.
func TouchFile(path string, mode os.FileMode) error

This looked pretty reasonable, and was a nice generalisation over the previous function. TouchFile makes setting the file mode on creation, the primary reason why this code existed in the first place, explicit.

However, this is precisely the train of thought that Metz warned of in her post. By generalising this function I had made its API worse.

Specifically, now every caller to this function has to pass in a mode value, even if the file exists, even if they don’t really care and are happy with a default file mode. Worse still, mode is only applied if the file is not already present. Not only had I made this function harder to use in its default use case, I’d added a footgun to the API that someone might call this function expecting it to update the mode of an existing file.

The second clue that I was heading in the wrong direction was the implementation of TouchFile itself:

func TouchFile(path string, mode os.FileMode) error {
        f, err := os.OpenFile(path, os.O_WRONLY|os.O_CREATE, mode)
        if err != nil {
                return err
        }
        return f.Close()
}

TouchFile just calls os.OpenFile passing in the right flags to get the create-if-missing semantics it wants. You still have to pass in the mode, because os.OpenFile requires a mode, so the utility of TouchFile as a wrapper is undermined by the cognitive overhead of having to remember its quirks.

Coming to my senses, I reverted my change and replaced createOutputFile with a direct call to os.OpenFile.

Whereas someone reading this code and seeing a call to TouchFile may think that the goal is to ensure the file exists, will miss the subtle point that purpose of Start was to ensure that the file exists with the right permission. By making a direct call to the os package in body of the function it becomes explicit to the next reader, who already knows the os package, that the file is being created explicitly is to set the mode.

I realised that I hadn’t made things simpler by adding this abstraction, instead I’d made them more opaque. Sometimes it’s better to be explicit than abstract.

cgo is not Go

To steal a quote from JWZ,

Some people, when confronted with a problem, think “I know, I’ll use cgo.”
Now they have two problems.

Recently the use of cgo came up on the Gophers’ slack channel and I voiced my concerns that using cgo, especially on a project that is intended to showcase Go inside an organisation was a bad idea. I’ve said this a number of times, and people are probably sick of hearing my spiel, so I figured that I’d write it down and be done with it.

cgo is an amazing technology which allows Go programs to interoperate with C libraries. It’s a tremendously useful feature without which Go would not be in the position it is today. cgo is key to ability to run Go programs on Android and iOS.

However, and to be clear these are my opinions, I am not speaking for anyone else, I think cgo is overused in Go projects. I believe that when faced with reimplementing a large piece of C code in Go, programmers choose instead to use cgo to wrap the library, believing that it is a more tractable problem. I believe this is a false economy.

Obviously, there are some cases where cgo is unavoidable, most notably where you have to interoperate with a graphics driver or windowing system that is only available as a binary blob. But those cases where cgo’s use justifies its trade-offs are fewer and further between than many are prepared to admit.

Here is an incomplete list of trade-offs you make, possibly without realising them, when you base your Go project on a cgo library.

Slower build times

When you import "C" in your Go package, go build has to do a lot more work to build your code. Building your package is no longer simply passing a list of all the .go files in scope to a single invocation of go tool compile, instead:

  • The cgo tool needs to be invoked to generate the C to Go and Go to C thunks and stubs.
  • Your system C compiler has to be invoked for every C file in the package.
  • The individual compilation units are combined together into a single .o file.
  • The resulting .o file take a trip through the system linker for fix-ups against shared objects they reference.

All this work happens every time you compile or test your package, which is constantly, if you’re actively working in that package. The Go tool parallelises some of this work where possible, but your packages’ compile time just grew to include a full rebuild of all that C code.

It’s possible to work around this by pushing the cgo shims out into their own package, avoiding the compile time hit, but now you’ve had to restructure your application to work around a problem that you didn’t have before you started to use cgo.

Oh, and you have to debug C compilation failures on the various platforms your package supports.

Complicated builds

One of the goals of Go was to produce a language who’s build process was self describing; the source of your program contains enough information for a tool to build the project. This is not to say that using a Makefile to automate your build workflow is bad, but before cgo was introduced into a project, you may not have needed anything but the go tool to build and test. Afterwards, to set all the environment variables, keep track of shared objects and header files that may be installed in weird places, now you do.

Keep in mind that Go supports platforms that don’t ship with make out of the box, so you’ll have to dedicate some time to coming up with a solution for your Windows users.

Oh, and now your users have to have a C compiler installed, not just a Go compiler. They also have to install the C libraries your project depends on, so you’ll be taking on that support cost as well.

Cross compilation goes out the window

Go’s support for cross compilation is best in class. As of Go 1.5 you can cross compile from any supported platform to any other platform with the official installer available on the Go project website.

By default cgo is disabled when cross compiling. Normally this isn’t a problem if your project is pure Go. When you mix in dependencies on C libraries, you either have to give up the option to cross compile your product, or you have to invest time in finding and maintaining cross compilation C toolchains for all your targets.

Maybe if you work on a product that only communicates with clients over TCP sockets and you intend to run it in a SaaS model it’s reasonable to say that you don’t care about cross compilation. However, if you’re making a product which others will use, possibly integrated into their products, maybe it’s a monitoring solution, maybe it’s a client for your SaaS service, then you’ve locked them out of being able to easily cross compile.

The number of platforms that Go supports continues to grow. Go 1.5 added support for 64 bit ARM and PowerPC. Go 1.6 adds support for 64 bit MIPS, and IBM’s s390 architecture is touted for Go 1.7. RISC-V is in the pipeline. If your product relies on a C library, not only do you have the all problems of cross compilation described above, you also have to make sure the C code you depend on works reliably on the new platforms Go is supporting — and you have to do that with the limited debuggability a C/Go hybrid affords you. Which brings me to my next point.

You lose access to all your tools

Go has great tools; we have the race detector, pprof for profiling code, coverage, fuzz testing, and source code analysis tools. None of those work across the cgo blood/brain barrier.

Conversely excellent tools like valgrind don’t understand Go’s calling conventions or stack layout.  On that point, Ian Lance Taylor’s work to integrate clang’s memory sanitiser to debug dangling pointers on the C side will be of benefit for cgo users in Go 1.6.

Combing Go code and C code results in the intersection of both worlds, not the union; the memory safety of C, and the debuggability of a Go program.

Performance will always be an issue

C code and Go code live in two different universes, cgo traverses the boundary between them. This transition is not free and depending on where it exists in your code, the cost could be inconsequential, or substantial.

C doesn’t know anything about Go’s calling convention or growable stacks, so a call down to C code must record all the details of the goroutine stack, switch to the C stack, and run C code which has no knowledge of how it was invoked, or the larger Go runtime in charge of the program.

To be fair, Go doesn’t know anything about C’s world either. This is why the rules for passing data between the two have become more onerous over time as the compiler becomes better at spotting stack data that is no longer considered live, and the garbage collector becomes better at doing the same for the heap.

If there is a fault while in the C universe, the Go code has to recover enough state to at least print a stack trace and exit the program cleanly, rather than barfing up a core file.

Managing this transition across call stacks, especially where signals, threads and callbacks are involved is non trivial, and again Ian Lance Taylor has done a huge amount of work in Go 1.6 to improve the interoperability of signal handling with C.

The take away is that the transition between the C and Go world is non trivial, and it will never be free from overhead.

C calls the shots, not your code

It doesn’t matter which language you’re writing bindings or wrapping C code with; Python, Java with JNI, some language using libFFI, or Go via cgo; it’s C’s world, you’re just living in it.

Go code and C code have to agree on how resources like address space, signal handlers, and thread TLS slots are to be shared — and when I say agree, I actually mean Go has to work around the C code’s assumption. C code that can assume it always runs on one thread, or blithely be unprepared to work in a multi threaded environment at all.

You’re not writing a Go program that uses some logic from a C library, instead you’re writing a Go program that has to coexist with a belligerent piece of C code that is hard to replace, has the upper hand negotiations, and doesn’t care about your problems.

Deployment gets more complicated

Any presentation on Go to a general audience will contain at least one slide with these words:

Single, static binary

This is Go’s ace in the hole that has lead it to become a poster child of the movement away from virtual machines and managed runtimes. Using cgo, you give that up.

Depending on your environment, it’s probably possible to build your Go project into a deb or rpm, and assuming your other dependencies are also packaged, add them as an install dependency and push the problem off the operating system’s package manager. But that’s several significant changes to a build and deploy process that was previously as straight forward as go build && scp.

It is possible to compile a Go program entirely statically, but it is by no means simple and shows that the ramifications of including cgo in your project will ripple through your entire build and deploy life cycle.

Choose wisely

To be clear, I am not saying that you should not use cgo. But before you make that Faustian bargain, please consider carefully the qualities of Go that you’ll be giving up in return.

Are Go maps sensitive to data races ?

Panic messages from unexpected program crashes are often reported on the Go issue tracker. An overwhelming number of these panics are caused by data races, and an overwhelming number of those reports centre around Go’s built in map type.

unexpected fault address 0x0
fatal error: fault
[signal 0x7 code=0x80 addr=0x0 pc=0x40873b]

goroutine 97699 [running]:
runtime.throw(0x17f5cc0, 0x5)
    /usr/local/go/src/runtime/panic.go:527
runtime.sigpanic()
    /usr/local/go/src/runtime/sigpanic_unix.go:21
runtime.mapassign1(0x12c6fe0, 0xc88283b998, 0xc8c9b63c68, 0xc8c9b63cd8)
    /usr/local/go/src/runtime/hashmap.go:446

Why is this so ? Why is a map commonly involved with a crash ? Is Go’s map implementation inherently fragile ?

To cut to the chase: no, there is nothing wrong with Go’s map implementation. But if there is nothing wrong with the implementation, why do maps and panic reports commonly find themselves in close proximity ?

There are three reasons that I can think of.

Maps are often used for shared state

Maps are fabulously useful data structures and this makes them perfect for tasks such as a shared cache of precomputed data or a lookup table of outstanding requests. The common theme here is the map is being used to store data shared across multiple goroutines.

Maps are more complex structures

Compared to the other built in data types like channels and slices, Go maps are more complex — they aren’t just views onto a backing array of elements. Go maps contain significant internal state, and map iterators (for k, v := range m) contain even more.

Go maps are not goroutine safe, you must use a sync.Mutex, sync.RWMutex or other memory barrier primitive to ensure reads and writes are properly synchronised. Getting your locking wrong will corrupt the internal structure of the map.

Maps move things

Of all of Go’s built in data structures, maps are the only ones that move data internally. When you insert or delete entries, the map may need to rebalance itself to retain its O(1) guarantee. This is why map values are not addressable.

Without proper synchronisation different CPUs will have different representations of the map’s internal structure in their caches. Although the language lawyers will tell you that a program with a data race exhibits undefined behaviour, it’s easy to see how having a stale copy of a map’s internal structure can lead to following a stale pointer to oblivion.

Please use the race detector

Go ships with a data race detector that works on Windows, Linux, FreeBSD and OSX. The race detector will spot this issue, and many more.

Please use it when testing your code.

How will you be programming in a decade ?

What does the computing landscape look like in a decade ?

In a word, bifurcated.

At the individual level there will be range of battery powered devices; watches, mobile phones, tablets with removable keyboards, and those without. They will be numerous, at a wide range of price points, allowing them to be dedicated to the individual. A personal computer if you will.

Of course these devices will have to always be connected to a network and the eponymous cloud, and thus the other half of the puzzle. If you think you’re going to be able to walk downstairs in a decade and touch the hardware your software runs on — you’re in for a rude shock.

What happened to the middle ?

Well, Steve Jobs blew up the desktop market, and with it the outlook for PC shipments.

Desktop PC shipments, 2010-2019

Desktop PC shipments, 2010-2019

But, but, I hear you say. You, the reader, might have a desktop computer for gaming, or enjoy software development on a workstation, rather than a laptop, or your phone.

That’s fine, nobody said you’re wrong, but you are increasingly a minority, and the economics of scale are not working in your favour.

What about us developers ?

Yongsan Electronics Market. Korea’s strategic reserve of whitebox desktop PCs stretches to the horizon.

So we know where the hardware is going, but a16z says software is eating the world. Who’s going to write all this software ? And if there are no desktop computers, how ?

Maybe, companies like Nitrous.io (now defunct) and Koding are right, and we’ll all be using online tools. In which case tablets with all day battery life and WiFi are the ticket — the market is certainly betting on that.

But I think there are serious and persistent problems with the idea of always on that cannot be fixed with money.

Broadband cellular or WiFi data has an upper limit, sure you can stack channels to make a single TCP flow go faster, but when everyone wants fast flows — and good upload bandwidth, will that scale to cities with tens of millions of individual ? Will it scale to people who don’t want to live in said Megalopolis ?

Probably not.

The other outcome is the developer PC continues to exist, in an increasingly rarified (and expensive) form as workstations migrate to the economies of scale that drive server chip sets.

Video editing suite

Video editing suite

This is what video editing looks like today, part PC, mostly custom packaged single use solution. Imagine what it would look like if this was what was required to produce software ?

How will you be programming in a decade ?

LISP Machine

A whirlwind tour of Go’s runtime environment variables

Introduction

The Go runtime, in addition to providing the usual services of garbage collection, goroutine scheduling, timers, network polling and so forth, contains facilities to enable extra debugging output and even alter the behaviour of the runtime itself.

These facilities are controlled by environment variables passed to the Go program. This post describes the function of the major environment variables supported by the runtime.

GOGC

GOGC is one of the oldest environment variable supported by the Go runtime. It’s possibly older than GOROOT, but nowhere near as well known.

GOGC controls the aggressiveness of the garbage collector. By default this value is assumed to be 100, which means garbage collection will not be triggered until the heap has grown by 100% since the previous collection. Effectively GOGC=100 (the default) means the garbage collector will run each time the live heap doubles.

Setting this value higher, say GOGC=200, will delay the start of a garbage collection cycle until the live heap has grown to 200% of the previous size. Setting the value lower, say GOGC=20 will cause the garbage collector to be triggered more often as less new data can be allocated on the heap before triggering a collection.

Setting GOGC=off will disable garbage collection entirely.

With the introduction of the low latency collector in Go 1.5, phrases like “trigger a garbage collection cycle” become more fluid, but the underlying message that values of GOGC greater than 100 mean the garbage collector will run less often, and for values of GOGC less than 100, more often, remains the same.

GOTRACEBACK

GOTRACEBACK controls the level of detail when a panic hits the top of your program. In Go 1.5 GOTRACEBACK has four valid values.

  • GOTRACEBACK=0 will suppress all tracebacks, you only get the panic message.
  • GOTRACEBACK=1 is the default behaviour, stack traces for all goroutines are shown, but stack frames related to the runtime are suppressed.
  • GOTRACEBACK=2 is the same as the previous value, but frames related to the runtime are also shown, this will reveal goroutines started by the runtime itself.
  • GOTRACEBACK=crash is the same as the previous value, but rather than calling os.Exit, the runtime will cause the process to segfault, triggering a core dump if permitted by the operating system.

The effect of GOTRACEBACK can be seen with a simple program.

package main

func main() {
        panic("kerboom")
}

Compiling and running this program with GOTRACEBACK=0 shows the suppression of all goroutine stack traces.

% env GOTRACEBACK=0 ./crash 
panic: kerboom
% echo $?
2

Experimentation with the other possible values of GOTRACEBACK is left as an exercise to the reader.

Changes to GOTRACEBACK coming in Go 1.6

For Go 1.6 the interpretation of GOTRACEBACK is changing. The new values of GOTRACEBACK will be:

  • GOTRACEBACK=none will suppress all tracebacks, you only get the panic message.
  • GOTRACEBACK=single is the new default behaviour that prints only the goroutine believed to have caused the panic.
  • GOTRACEBACK=all causes stack traces for all goroutines to be shown, but stack frames related to the runtime are suppressed.
  • GOTRACEBACK=system is the same as the previous value, but frames related to the runtime are also shown, this will reveal goroutines started by the runtime itself.
  • GOTRACEBACK=crash is unchanged from Go 1.5.

For compatibility with Go 1.5, a value of 0 maps to none, 1 maps to all, and 2 maps to system.

The major take away from this change is, by default in Go 1.6, panic messages will only print the stack trace for the faulting goroutine. This change is detailed in issue 12366 and CL 16512.

GOMAXPROCS

GOMAXPROCS is the well known (and cargo culted via its runtime.GOMAXPROCS counterpart), value that controls the number of operating system threads allocated to goroutines in your program.

As of Go 1.5, the default value of GOMAXPROCS is the number of CPUs (whatever your operating system considers to be a CPU) visible to the program at startup.

note: the number of operating system threads in use by a Go program includes threads servicing cgo calls, thread blocked on operating system calls, and may be larger than the value of GOMAXPROCS.

GODEBUG

Saving the best for last is GODEBUG. The contents of GODEBUG are interpreted as a list of name=value pairs separated by commas, where each name is a runtime debugging facility. Here is an example invoking godoc with garbage collection and schedule tracing enabled:

% env GODEBUG=gctrace=1,schedtrace=1000 godoc -http=:8080

The remainder of this post will discuss the GODEBUG debugging facilities that I find useful to diagnosing Go programs.

gctrace

Of all the GODEBUG facilities, gctrace is the one I find most useful. Here is the output of the first few milliseconds of a godoc -http server with gctrace debugging enabled:

% env GODEBUG=gctrace=1 godoc -http=:8080 -index
gc #1 @0.042s 4%: 0.051+1.1+0.026+16+0.43 ms clock, 0.10+1.1+0+2.0/6.7/0+0.86 ms cpu, 4->32->10 MB, 4 MB goal, 4 P
gc #2 @0.062s 5%: 0.044+1.0+0.017+2.3+0.23 ms clock, 0.044+1.0+0+0.46/2.0/0+0.23 ms cpu, 4->12->3 MB, 8 MB goal, 4 P
gc #3 @0.067s 6%: 0.041+1.1+0.078+4.0+0.31 ms clock, 0.082+1.1+0+0/2.8/0+0.62 ms cpu, 4->6->4 MB, 8 MB goal, 4 P
gc #4 @0.073s 7%: 0.044+1.3+0.018+3.1+0.27 ms clock, 0.089+1.3+0+0/2.9/0+0.54 ms cpu, 4->7->4 MB, 6 MB goal, 4 P

The format of this output changes with every version of Go, but you will always find commonalities like the amount of time of the various gc phases; 0.051+1.1+0.026+16+0.43 ms clock, and the various heap sizes during garbage collection cycle; 4->6->4 MB. This trace also includes the timestamp the gc cycle completed, relative to the start time of the program, however older versions of Go omit this information.

The individual output lines may be useful for analysis, but I find it more useful to view them in aggregate. For example, if you enable gc tracing and the output is continuous, it’s a clear sign that the program is allocation bound. Likewise if the reported size of the heap continues to grow over time, that is a clear sign of a memory leak where references that are expected to be freed are being retained in some global structure.

The overhead of enabling gctrace is effectively zero for production deployments as these statistics are always being collected, but are normally suppressed. I recommend that you enable it at least for some representative sample of your application’s production deployment.

note:setting gctrace to values larger than 1 causes each garbage collection cycle to be run twice. This exercises some aspects of finalisation that require two garbage collection cycles to complete. You should not use this as a mechanism to alter finalisation performance in your programs because you should not write programs whose correctness depends on finalisation.

The heap scavenger

By far the most useful piece of output enabled by gctrace=1 is the output of the heap scavenger.

scvg143: inuse: 8, idle: 104, sys: 113, released: 104, consumed: 8 (MB)

The scavenger’s job is to periodically sweep the heap looking for unused operating system pages. The scavenger then releases them by notifying the operating system that these memory pages from the heap that are not in use. There is no facility to force the operating system to take back the page and many operating systems choose to ignore this advice, or at least defer taking any action until the a time when the machine is starved for free memory.

The output from the scavenger is the best way I know of to tell how much virtual address space is in use by your Go program. It is expected that these values will vary significantly from what tools like free(1) and top(1) report. You should trust the values reported by the scavenger.

schedtrace

Because the Go runtime manages the allocation of a large set of goroutines onto a smaller set of operating system threads, observing your program externally may not give sufficient detail to understand its performance. You may need to investigate the operation of the runtime scheduler directly.  This output is controlled with the schedtrace value:

% env GODEBUG=schedtrace=1000 godoc -http=:8080 -index
SCHED 0ms: gomaxprocs=4 idleprocs=2 threads=4 spinningthreads=1 idlethreads=0 runqueue=0 [0 0 0 0]
SCHED 1001ms: gomaxprocs=4 idleprocs=0 threads=8 spinningthreads=0 idlethreads=2 runqueue=0 [189 197 231 142]
SCHED 2004ms: gomaxprocs=4 idleprocs=0 threads=9 spinningthreads=0 idlethreads=1 runqueue=0 [54 45 38 86]
SCHED 3011ms: gomaxprocs=4 idleprocs=0 threads=9 spinningthreads=0 idlethreads=2 runqueue=2 [85 0 67 111]
SCHED 4018ms: gomaxprocs=4 idleprocs=3 threads=9 spinningthreads=0 idlethreads=4 runqueue=0 [0 0 0 0]

A detailed discussion of the schedtrace output is available in Dmitry Vyukov’s excellent blog post from the Intel DeveloperZone.

Append scheddetail=1 will cause the runtime to output the state of each individual goroutine in addition to the summary, producing very verbose output.

% env GODEBUG=scheddetail=1,schedtrace=1000 godoc -http=:8080 -index
SCHED 0ms: gomaxprocs=4 idleprocs=3 threads=3 spinningthreads=0 idlethreads=0 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=1 schedtick=0 syscalltick=0 m=0 runqsize=0 gfreecnt=0
  P1: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  P2: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  P3: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 helpgc=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 helpgc=0 spinning=false blocked=false lockedg=17
  M0: p=0 curg=1 mallocing=0 throwing=0 preemptoff= locks=2 dying=0 helpgc=0 spinning=false blocked=false lockedg=1
  G1: status=2(stack growth) m=0 lockedm=0
  G17: status=3() m=1 lockedm=1
  G2: status=1() m=-1 lockedm=-1

This output may be useful for debugging leaking goroutines, but other facilities like net/http/pprof are likely to be more useful.

Further reading

All the environment variables available for your version of Go are detailed in the godoc for the runtime package.

Wednesday pop quiz: spot the race

The following program contains a data race

package main

import (
        "fmt"
        "time"
)

type RPC struct {
        result int
        done   chan struct{}
}

func (rpc *RPC) compute() {
        time.Sleep(time.Second) // strenuous computation intensifies
        rpc.result = 42
        close(rpc.done)
}

func (RPC) version() int {
        return 1 // never going to need to change this
}

func main() {
        rpc := &RPC{done: make(chan struct{})}

        go rpc.compute()         // kick off computation in the background
        version := rpc.version() // grab some other information while we're waiting
        <-rpc.done               // wait for computation to finish
        result := rpc.result

        fmt.Printf("RPC computation complete, result: %d, version: %d\n", result, version)
}

Where is the data race, and what is the smallest change that will fix it ?

Answer: the smallest change I know that will solve the race in this program is to change the receiver of the version method from RPC to *RPC.

Postscript

The example above is derived from a larger, and more confusing example. You may be interested in the original race report.

Let’s talk about logging

This is a post inspired by a thread that Nate Finch started on the Go Forum. This post focuses on Go, but if you can see your way past that, I think the ideas presented here are widely applicable.

Why no love ?

Go’s log package doesn’t have leveled logs, you have to manually add prefixes like debug, info, warn, and error, yourself. Also, Go’s logger type doesn’t have a way to turn these various levels on or off on a per package basis. By way of comparison let’s look at a few replacements from third parties.

glog from Google provides the following levels:

  • Info
  • Warning
  • Error
  • Fatal (which terminates the program)

Looking at another library, loggo, which we developed for Juju, provides the following levels:

  • Trace
  • Debug
  • Info
  • Warning
  • Error
  • Critical

Loggo also provides the ability to adjust the verbosity of logging on a per package basis.

So here are two examples, clearly influenced by other logging libraries in other languages. In fact their linage can be traced back to syslog(3), maybe even earlier. And I think they are wrong.

I want to take a contradictory position. I think that all logging libraries are bad because the offer too many features; a bewildering array of choice that dazzles the programmer right at the point they must be thinking clearly about how to communicate with the reader from the future; the one who will be consuming their logs.

I posit that successful logging packages need far less features, and certainly fewer levels.

Let’s talk about warnings

Let’s start with the easiest one. Nobody needs a warning log level.

Nobody reads warnings, because by definition nothing went wrong. Maybe something might go wrong in the future, but that sounds like someone else’s problem.

Furthermore, if you’re using some kind of leveled logging then why would you set the level at warning ? You’d set the level at info, or error. Setting the level to warning is an admission that you’re probably logging errors at warning level.

Eliminate the warning level, it’s either an informational message, or an error condition.

Let’s talk about fatal

Fatal level is effectively logging the message, then calling os.Exit(1). In principal this means:

  • defer statements in other goroutines don’t run.
  • buffers aren’t flushed.
  • temporary files and directories aren’t removed.

In effect, log.Fatal is a less verbose than, but semantically equivalent to, panic.

It is commonly accepted that libraries should not use panic1, but if calling log.Fatal2 has the same effect, surely this should also be outlawed.

Suggestions that this cleanup problem can be solved by registering shutdown handlers with the logging system introduces tight coupling between your logging system and every place where cleanup operations happen; its also violates the separation of concerns.

Don’t log at fatal level, prefer instead to return an error to the caller. If the error bubbles all the way up to main.main then that is the right place to handle any cleanup actions before exiting.

Let’s talk about error

Error handling and logging are closely related, so on the face of it, logging at error level should be easily justifiable. I disagree.

In Go, if a function or method call returns an error value, realistically you have two options:

  • handle the error.
  • return the error to your caller. You may choose to gift wrap the error, but that is not important to this discussion.

If you choose to handle the error by logging it, by definition it’s not an error any more — you handled it. The act of logging an error handles the error, hence it is no longer appropriate to log it as an error.

Let me try to convince you with this code fragment:

err := somethingHard()
if err != nil {
        log.Error("oops, something was too hard", err)
        return err // what is this, Java ?
}

You should never be logging anything at error level because you should either handle the error, or pass it back to the caller.

To be clear, I am not saying you should not log that a condition occurred

if err := planA(); err != nil {
        log.Infof("could't open the foo file, continuing with plan b: %v", err)
        planB()
}

but in effect log.Info and log.Error have the same purpose.

I am not saying DO NOT LOG ERRORS! Instead the question is, what is the smallest possible logging API ? And when it comes to errors, I believe that an overwhelming proportion of items logged at error level are simple done that way because they are related to an error. They are in fact, just informational, hence we can remove logging at error level from our API.

What’s left ?

We’ve ruled out warnings, argued that nothing should be logged at error level, and shown that only the top level of the application should have some kind of log.Fatal behaviour. What’s left ?

I believe that there are only two things you should log:

  1. Things that developers care about when they are developing or debugging software.
  2. Things that users care about when using your software.

Obviously these are debug and info levels, respectively.

log.Info should simply write that line to the log output. There should not be an option to turn it off as the user should only be told things which are useful for them. If an error that cannot be handled occurs, it should bubble up main.main where the program terminates. The minor inconvenience of having to insert the FATAL prefix in front of the final log message, or writing directly to os.Stderr with fmt.Fprintf is not sufficient justification for a logging package growing a log.Fatal method.

log.Debug, is an entirely different matter. It is for the developer or support engineer to control. During development, debugging statements should be plentiful, without resorting to trace or debug2 (you know who you are) level. The log package should support fine grained control to enable or disable debug, and only debug, statements at the package or possibly even finer scope.

Wrapping up

If this were a twitter poll, I’d ask you to choose between

  • logging is important
  • logging is hard

But the fact is, logging is both. The solution to this problem must be to de-construct and ruthlessly pair down unnecessary distraction.

What do you think ? Is this just crazy enough to work, or just plain crazy ?

Notes

  1. Some libraries may use panic/recover as an internal control flow mechanism, but the overriding mantra is they must not let these control flow operations leak outside the package boundary.
  2. Ironically while it lacks a debug level output, the Go standard log package has both Fatal and Panic functions. In this package the number of functions that cause a program to exit abruptly outnumber those that do not.