Tigraine

Daniel Hoelbling-Inzko talks about programming

Debugging Go IOWait Hang: Sometimes it's really not your code

If something looks like a bug in the Language Runtime, Standard Library or the Operating System I tend to always approach it with caution: It's usually a bug in my code and I'm just not seeing it.

But sometimes it's not me - it's really the compiler and you spend a solid week debugging a Go program until you find out that cross-compiling from OSX to Linux leads to a stdlib Bug that manifests itself with the whole application just hanging in IOWait loops given enough concurrency.

Obviously the whole thing was really frustrating because:

  • The bug only happened on production servers (obviously - anything else would not be fun).
  • Could only be reproduced on a large dataset of 300 million items (so every test also takes quite a while)
  • I had to test if it works without concurrency (which took 2 days and yes it did)

But the important finding from this exercise was that you can print the full stacktrace of all running Goroutines as well as their status for a running/hanging program! You just have to send the kill -ABRT signal to a process! This is similar to what you see when a panic occurs and was massively helpful in hunting down this bug. Kudos to the Go team for that.

An example for this:

package main

func main() {
  for {}
}

The program will obviously hang and do a busy loop, but if you send the kill -ABRT signal you'll get something similar to this printed to stderr:

SIGABRT: abort
PC=0x1056d70 m=0 sigcode=0

goroutine 1 [running]:
main.main()
        /Users/tigraine/projects/test/main.go:4 fp=0xc00003c788 sp=0xc00003c780 pc=0x1056d70
runtime.main()
        /usr/local/Cellar/go/1.14.1/libexec/src/runtime/proc.go:203 +0x212 fp=0xc00003c7e0 sp=0xc00003c788 pc=0x102b3f2
runtime.goexit()
        /usr/local/Cellar/go/1.14.1/libexec/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc00003c7e8 sp=0xc00003c7e0 pc=0x10528f1
...
Filed under golang, go, debugging

Convert a millisecond precision unix timestamp to Time in go

It's no real secret that I do love the programming language Go. So I was really delighted to see that Go apparently does all the right things when it comes to their time package that handles time zones etc correctly by default as opposed to be something bolted on after the fact like most other languages.

But for some unknown reason it's just way too complex to convert a millisecond resolution Unix timestamp to time.Time. The built-in time.Unix() function only supports second and nanosecond precision.

This means that you either have to multiply the millis to nanoseconds or split them into seconds and nanoseconds. So obviously my naive implementation was:

time.Unix(0, timestamp * int64(1000000))

But that code looked ugly to me - especially if you have to do this a few times around the codebase - so I wrote a function.

But for some reason I also decided to benchmark my function as I am working on a performance critical piece of code right now. And it turns out that the simple multiplication to turn millis into nanos is 2x slower than dividing the millis into seconds and then turning the remainder into nanos.

time.Unix(ms/int64(millisInSecond), (ms%int64(millisInSecond))*int64(nsInSecond))

Benchmark:

goos: darwin
goarch: amd64
pkg: github.com/tigraine/go-timemillis
BenchmarkMult-8         2000000000               0.50 ns/op
BenchmarkDiv-8          2000000000               0.25 ns/op

So I packaged my findings into a library which is now available on GitHub: go-timemilli

Filed under golang, time

Golang hidden gems: testing.T.Log

One thing I love about Go is it's build chain and overall ease of use. Some things take time to get used to, but the lightning fast builds and the convention-based testing Go offers are addicting right from the start.

Today I found another hidden Gem I think is just genius: testing.T.Log(). Ok I admit, not the most sexy method to get excited about - but bear with me for a moment. Imagine the following code.

func TestSomething(t *testing.T) {
  t.Log("Hello World")
}

What's the output? If you'd expect Hello World you are mistaken. The output is exactly nothing :)

testing.T.Log() only prints something if a testing.T.Error or testing.T.Fatal occurred. Brilliant! Nothing is more annoying than chatty test suites where your actual problem is buried in 2-3 megabytes of meaningless debug statements! And this solves the problem really elegantly. You can log as much debug info as you want and it will only surface if the test actually failed.

Filed under golang, go, testing

Golang: int is not a type

Today I ran into a very interesting compiler error in my go program: int is not a type. Although the same lines of code that didn't compile worked a few minutes earlier.

It took me 20 minutes to figure it out. I was already halfway through a forum post on the golangbridge forums and trying to put together a minimal example when I noticed the problem. Apparently I had a typo in mit func init() and had inadvertently called it func int()!

The go compiler didn't even complain with me overriding one of it's core types.

Filed under golang

My Photography business

Projects

dynamic css for .NET

Archives

more