Surprise at CPU Hogging in Golang

In one of my applications, for various reasons, we now have a batch like process and a HTTP based REST application running inside the same binary. Today I came up against an issue where HTTP latencies were around 10 seconds when the batch process was running.

After some debugging, the reason for this is that although the two are running in separate Go routines, the batch process is not allowing the scheduler to schedule the HTTP request until the batch process has finished.

This is a noddy example. It runs two goroutines and forcibly sets the number of threads to 1. The first goroutine is a “cpu intensive” routine. The second is a print line. Run this, and note how it waits until the cpu intensive routine has finished before scheduling anything else.

Intuitively, from our experience with OS threads in other languages, we would have expected that it should have spawned a thread, and instantly moved on to the next line. But it doesn’t. https://play.golang.org/p/PDsbUphk5Q

package main

import "fmt"
import "runtime"
import "time"

func cpuIntensive(p *int64) {
  for i := int64(1); i <= 10000000; i++ {
    *p = i
  }
  fmt.Println("Done intensive thing")
}

func printVar(p *int64) {
  fmt.Printf("print x = %d.\n", *p)
}

func main() {
  runtime.GOMAXPROCS(1)

  x := int64(0)
  go cpuIntensive(&x) // This should go into background
  go printVar(&x)

  // This won't get scheduled until everything has finished.
  time.Sleep(1 * time.Nanosecond) // Wait for goroutines to finish
}

Done intensive thing
print x = 10000000.

This is because that the golang scheduler needs to be called manually to perform a scheduling event. Now add the code: runtime.Gosched() At line 10. In the for loop. This manually calls the scheduler. Now print the variable first, with a low number, because we have manually called a schedule event.

print x = 1.
Done intensive thing

Now, apparently, the go base code is littered with Gosched calls so that whenever you call time.Sleep or printf or whatever, it will schedule for you.

So, if we try something more realistic, like decoding JSON: https://play.golang.org/p/qyN2iFrJED

package main

import "fmt"
import "runtime"
import "time"
import "encoding/json"
import "strings"

const testBytes = `{ "Test": "value" }`

type Message struct {
  Test string
}

func cpuIntensive(p *Message) {
  for i := int64(1); i <= 1000; i++ {
	json.NewDecoder(strings.NewReader(testBytes)).Decode(p)
  }
  fmt.Println("Done intensive thing")
}

func printVar(p *Message) {
  fmt.Printf("print x = %v.\n", *p)
}

func main() {
  runtime.GOMAXPROCS(1)

  x := Message{}
  go cpuIntensive(&x) // This should go into background
  go printVar(&x)

  // This won't get scheduled until everything has finished.
  time.Sleep(1 * time.Nanosecond) // Wait for goroutines to finish
}

Low an behold, same issues. Add a Gosched and it’s fixed.

The interesting thing is that even if you force the GOMAXPROCS to something more than 1, it still occurs. I think this is because the playground is only allowing one equivalent CPU. And the scheduling is happening on a cpu basis.

So, the short story is for each CPU Golang is always going to act like it’s running on a single thread. That is unless you call Gosched yourself, or call something that does or the Go routine ends. It doesn’t matter how many threads you specify or Goroutines you start, it will still do one CPU intensive thing at a time.

Surprising!