πŸ•΅οΈβ€β™‚οΈ Exercise 8: Goroutine Sleep Detective - Runtime State Monitoring

In this exercise, you’ll modify the Go runtime scheduler to log goroutine state transitions! πŸ” Every time a goroutine goes to sleep waiting for something, it will announce itself: “Hello, I’m goroutine 42, going to sleep waiting for channel receive”!

🎯 Learning Objectives

By the end of this exercise, you will:

🧠 Background: Goroutine States

Go manages goroutines through different states:

When a goroutine needs to wait (for channels, mutexes, sleep, etc.), it “parks” and transitions to _Gwaiting state.

πŸ” Step 1: Understanding the Park Mechanism

The gopark function is called by ALL synchronization primitives when a goroutine needs to wait.

cd go/src/runtime
grep -n "func gopark" proc.go

Key functions:

Step 2: Find the State Transition Code

# Look at where the state actually changes
grep -n -A 5 "func park_m" proc.go

Around line 4237, you’ll see:

casgstatus(gp, _Grunning, _Gwaiting)

This is the exact line where a goroutine transitions from running to waiting. Perfect for our logging!

Step 3: Add Goroutine Sleep Logging

Edit proc.go:

You’ll need to add logging in three locations where goroutines transition to the waiting state:

Location 1: casGToWaiting function (around line 1366)

Find the casGToWaiting function and add logging after setting the wait reason:

func casGToWaiting(gp *g, old uint32, reason waitReason) {
	// Set the wait reason before calling casgstatus, because casgstatus will use it.
	gp.waitreason = reason
	if gp.goid > 1 { // Skip system goroutines 0 and 1
		print("Hello, I'm goroutine ", gp.goid, ", going to sleep waiting for ", gp.waitreason.String(), "\n")
	}
	casgstatus(gp, old, _Gwaiting)
}

Location 2: casGFromPreempted function (around line 1411)

Find where preempted goroutines transition to waiting:

func casGFromPreempted(gp *g, old, new uint32) bool {
	// ... existing code ...
	if bubble := gp.bubble; bubble != nil {
		if gp.goid > 1 { // Skip system goroutines 0 and 1
			print("Hello, I'm goroutine ", gp.goid, ", going to sleep waiting for ", gp.waitreason.String(), "\n")
		}
		bubble.changegstatus(gp, _Gpreempted, _Gwaiting)
	}
	return true
}

Location 3: park_m function (around line 4240)

Find the park_m function and add logging before the direct casgstatus call:

// Add this before: casgstatus(gp, _Grunning, _Gwaiting)
if gp.goid > 1 { // Skip system goroutines 0 and 1
    print("Hello, I'm goroutine ", gp.goid, ", going to sleep waiting for ", gp.waitreason.String(), "\n")
}
casgstatus(gp, _Grunning, _Gwaiting)

πŸ”§ Understanding the Code

Step 4: Rebuild Go Runtime

cd ../  # back to go/src
./make.bash

Step 5: Test Channel Blocking

Create a channel_test.go file:

package main

import "time"

func main() {
    ch := make(chan string)

    // Start goroutine that will block on receive
    go func() {
        msg := <-ch  // Should trigger our logging!
        println("Received:", msg)
    }()

    // Let the goroutine start and block
    time.Sleep(100 * time.Millisecond)

    // Send something
    ch <- "Hello!"
    time.Sleep(10 * time.Millisecond)
}

Build and run with our modified Go:

../go/bin/go build channel_test.go
./channel_test

Note: We build the binary first and then run it directly. This avoids mixing goroutines from the compiler/build process with goroutines from our program, giving us cleaner output!

Expected output:

Hello, I'm goroutine 4, going to sleep waiting for GC scavenge wait
Hello, I'm goroutine 3, going to sleep waiting for GC sweep wait
Hello, I'm goroutine 2, going to sleep waiting for force gc (idle)
Hello, I'm goroutine 6, going to sleep waiting for chan receive
Hello, I'm goroutine 5, going to sleep waiting for GOMAXPROCS updater (idle)
Received: Hello!

πŸŽ‰ You can now see goroutines blocking!

Understanding What We Did

  1. Found the Park Function: Located where goroutines transition to waiting state
  2. Added Logging: Inserted print statement before state change
  3. Captured Wait Reason: Used gp.waitreason.String() for human-readable output
  4. Tested Scenarios: Verified with channels, mutexes, sleep, and select

Common wait reasons you’ll see:

πŸŽ“ What We Learned

πŸ’‘ Extension Ideas

Try these additional modifications: πŸš€

  1. βž• Add goroutine wakeup logging (when they resume running)
  2. βž• Add emojis for different wait reasons (πŸ“’ channel, πŸ”’ mutex, 😴 sleep)
  3. βž• Include timestamps to measure blocking duration
  4. βž• Filter logging by specific wait reasons only

Cleanup

To remove the logging:

cd go/src/runtime
git checkout proc.go
cd ../
./make.bash

Summary

You’ve gained X-ray vision into Go’s concurrency model! Your modified runtime now announces every goroutine blocking operation:

Hello, I'm goroutine 18, going to sleep waiting for chan receive
Hello, I'm goroutine 19, going to sleep waiting for sync mutex lock
Hello, I'm goroutine 20, going to sleep waiting for sleep

This exercise revealed the internal workings of Go’s scheduler and how synchronization primitives interact with the runtime! πŸ•΅οΈβ€β™‚οΈβœ¨


Continue to Exercise 9 or return to the main workshop