In my last post, I showed a program that had a strange behavior that caught my eye. I was trying to look at how Go handles shared access to globals, but the program also had the unintended effect of measuring the “fairness” of the Go scheduler. Here’s the program again, for context:
package main
import "runtime"
var x int
var ch = make(chan bool)
func f(inc int) {
for {
println("f: ", inc)
x += inc
ch <- true
}
}
func main() {
go f(1)
go f(-1)
runtime.Gosched()
for {
_ = <- ch
_ = <- ch
println("main sees x = ", x)
}
}When you run this with GOMAXPROCS=3, and you are on a machine with at least three cores, you get precisely what you’d expect: three system threads, each one running one goroutine, and total fairness: f(1) happens once for every f(-1), and the long-run value of x is around 0, but sometimes higher or lower.
When you run this with GOMAXPROCS=1, you see something else. x goes to infinity because the goroutines are called in a unchanging cycle like this:
* f(1)
* f(1)
* f(-1)
* main
Talk about two steps forward, one step back!
Now, no one ever said life was fair, nor that the Go scheduler is fair. But in the spirit of digging down into Go more, let’s go find out why not.
Taking a look at the assembly for main, we can see that each read on the channel results in a call into runtime.readchan1. It is this call into the runtime that causes main() to yield control to the scheduler and let the f(1), f(1), f(-1) cycle begin again, so it should be interesting. If we go take a look at that function (see $GOROOT/src/pkg/runtime/chan.c) it’s not easy to understand right away how marking the sending goroutine as unblocked and ready results in the behavior we see. But this does give us a chance to talk about the Go runtime’s debugging feature, which is useful.
This snippet from chan.c shows how the Go runtime does debugging:
static int32 debug = 0;
...
void
chanrecv(Hchan* c, byte *ep, bool* pres)
{
...
f(debug)
printf("chanrecv: chan=%p\n", c);
Not exactly earth-shattering, I know, but this is what’s nice about Go’s code: it is the simplest possible thing that work.
If you change debug = 0 to debug = 1, then recompile (gomake -C $GOMAKE/src/pkg/runtime clean install) your runtime will now spam out messages about channels. This pattern works for other modules, like slices and the scheduler (found in proc.c). Once we have debugging turned on in our runtime, we recompile and relink the test program, and now we have this output:
1: makechan: chan=0xb7f1d000; elemsize=1; elemalg=0; elemalign=1; dataqsiz=0
2: f: 1
3: chansend: chan=0xb7f1d000; elem=1
4: f: -1
5: chansend: chan=0xb7f1d000; elem=1
6: chanrecv: chan=0xb7f1d000
7: chanrecv: chan=0xb7f1d000
8: main sees x = 0
9: chanrecv: chan=0xb7f1d000
10: f: 1
11: chansend: chan=0xb7f1d000; elem=1
12: f: 1
13: chansend: chan=0xb7f1d000; elem=1
14: f: -1
15: chansend: chan=0xb7f1d000; elem=1
16: chanrecv: chan=0xb7f1d000
17: main sees x = 1
18: chanrecv: chan=0xb7f1d000
19: chanrecv: chan=0xb7f1d000
Hidden in there is the answer to our question, but we’ll have to take it line by line to find it. I have added line numbers to help talk about the output.
In lines 2-5, f(1) and f(-1) do their thing and then block themselves by writing to the channel. Once they are both blocked, and now that the channel has got two values waiting on it, main wakes up and receives them both (lines 6-8). In line 9, main’s just gone to sleep waiting on the channel at the top of its loop, on the second time through the loop.
Now that main is asleep, the scheduler looks around for something to do. f(1) and f(-1) are runnable because they are no longer blocked on their channel writes. In lines 10 and 11, f(1) gets a chance to increment x, and then sends on the channel. What we expect to happen now (on average, anyway) is that f(-1) will get a chance to run. Instead f(1) gets to run again (lines 12-13). Why? Because main was already sleeping on the channel when f(1) wrote to it. Instead of being put to sleep, f(1) completes it’s write and keeps running. On the second write to the channel, it ends up asleep.
This points out the key lesson about unbuffered channels from this post: if the receiver is blocked on a read, and the sender does a send, he zips right through the send without yielding control to the Go scheduler.
After f(1) takes the second trip through the loop and finds that the reader is now waiting to wake up on the value he wrote last time through, now he finally goes to sleep. In $GOROOT/src/pkg/runtime/chan.c, in function chansend, the difference between the first time through f(1) and the second time through f(1) is the difference between the dequeue returns non-nil case and the code that follows, where a new pseudo-g is allocated and filled in, then gosched() is called, resulting in the f(1) goroutine yielding.
The Go runtime needs to choose the next goroutine to run. It has now got two choices, main and f(-1). It takes the routine that was marked runnable longest ago and runs it; in this case f(-1). Why? Probably to ensure that goroutines cannot be starved for time to run. f(-1) decrements and then tries to send on the channel, but is discovers that there’s no waiting channel reader (remember, f(1) filled up main’s outstanding read request before) and goes to sleep. main gets to run and reads f(1)’s first value (line 9, which happens after line 15), then it’s second (line 16). It prints, loops, finds the message from f(-1) and then goes to sleep again.
So it’s clear that due to the behavior of writes onto channels with pending readers, this program is not doing what we wanted at all. A solution is to use two channels instead of one shared channel:
package main
import "runtime"
var x int
func f(inc int, ch chan bool) {
for {
println("f: ", inc)
x += inc
ch <- true
}
}
func main() {
ch1 := make(chan bool)
ch2 := make(chan bool)
go f(1, ch1)
go f(-1, ch2)
runtime.Gosched()
for {
_ = <- ch1
_ = <- ch2
println("main sees x = ", x)
}
}
The results are satisfying:
makechan: chan=0xb7e47000; elemsize=1; elemalg=0; elemalign=1; dataqsiz=0
makechan: chan=0xb7e477c0; elemsize=1; elemalg=0; elemalign=1; dataqsiz=0
f: 1
chansend: chan=0xb7e47000; elem=1
f: -1
chansend: chan=0xb7e477c0; elem=1
chanrecv: chan=0xb7e47000
chanrecv: chan=0xb7e477c0
main sees x = 0
chanrecv: chan=0xb7e47000
f: 1
chansend: chan=0xb7e47000; elem=1
f: 1
chansend: chan=0xb7e47000; elem=1
f: -1
chansend: chan=0xb7e477c0; elem=1
chanrecv: chan=0xb7e477c0
main sees x = 1
chanrecv: chan=0xb7e47000
chanrecv: chan=0xb7e477c0
f: -1
chansend: chan=0xb7e477c0; elem=1
f: -1
chansend: chan=0xb7e477c0; elem=1
f: 1
chansend: chan=0xb7e47000; elem=1
main sees x = 0
Note that there’s a new interesting pattern, f(1), f(1), f(-1), main, f(-1), f(-1), f(1), main. But that one will have to wait for another post, the baby wants to play… 🙂
Leave a Reply