Goroutine Profiling with Logging

This will be our last series on profiling and logging.

Take for example, a food delivery service which manages numerous orders per minute. Each order proceeds through several stages: order placement, payment processing, kitchen preparation, and delivery dispatch.

These stages execute concurrently utilizing goroutines to ensure scalability. However, users occasionally experience delays or order failures 😩 during periods of high demand, and the underlying cause is presently unknown.

This is one instance system design scenario in which goroutine profiling would be used to monitor for example, if an excessive number of goroutines are spawned and maybe use logging with context IDs (e.g., order IDs in this case) to trace delays in specific stages and correlate this with goroutine spikes.

Hold on to that thought for a moment. Goroutine, according to Go documentation, is a lightweight thread managed by the Go runtime, which to you my dear reader would not mean anything and so allow me to make your day.

In essence, a Goroutine can be thought of as a function or procedure that runs concurrently with other Goroutines within the same address space. The beauty of Goroutines lies in their lightweight nature.

Unlike traditional operating system threads, which are relatively resource-intensive, Goroutines have a much smaller memory footprint. This allows you to create and run tens of thousans of Goroutines simultaneously without worrying about overwhelming your system’s resources.

The Go runtime handles the scheduling and execution of Goroutines, ensuring that they are efficiently distributed across available CPU cores. This means that you, as a developer, don’t have to manually manage thread creation, synchronization, or context switching. The Go runtime takes care of all the heavy lifting behind the scenes, allowing you to focus on writing clean and concise code. Amazing huh?

Check out this

func worker(id int) { 
  log.Printf("Worker %d starting\n", id) 
  time.Sleep(time.Duration(id) * time.Second) 
  log.Printf("Worker %d done\n", id) 
}

What goes on here is:

• This `worker` function emulates a task with a specified ID.
• It begins by logging a message indicating its start time.
• The `time.Sleep()` function introduces a delay that simulates the worker performing its task. The duration of this delay is directly proportional to the worker’s ID; a worker with an ID of 5 will sleep for 5 seconds.
• Finally, the worker logs a message to signal its completion.

Now assume you wanna count the number of goroutines at any time, we would use runtime.NumGoroutine() to provide insight into how many concurrent tasks are running.

func logGoroutineCount() { 
  for { 
       log.Printf("Number of goroutines: %d\n", 
       runtime.NumGoroutine())  
       time.Sleep(2 * time.Second)  
  } 
}

What goes on here is:

• The `logGoroutineCount` function periodically logs the number of active goroutines.
• The `for` loop ensures continuous execution.
• Within the loop, `log.Printf` prints the count of goroutines returned by `runtime.NumGoroutine()`.
• A 2-second sleep (`time.Sleep(2 * time.Second)`) is introduced to control the logging frequency.

To demo how these functions work, our main() function would look something like;

func main() { 
  log.Println("Application starting...")

  go logGoroutineCount()
 
  for i := 1; i <= 5; i++ {  
    go worker(i) 
  } 
  time.Sleep(10 * time.Second) 
  log.Println("Application exiting...") 
}

Simply:

• Logs the application start and exit messages.
• Spawns the logGoroutineCount goroutine to continuously log the number of goroutines every 2 seconds.
• Spawns multiple worker goroutines to simulate concurrent tasks.
• The time.Sleep(10 * time.Second) ensures the program doesn’t exit before all tasks complete.

We would say this is the end and go home but we have to see where this takes us. An enhanced version of our code involves adding debugging and profiling to detect issues such as goroutine leaks.

Let’s add net/http/pprof. Refer to our last articles to learn more about this Go package.

import _ “net/http/pprof”

import “net/http”

We then add below line to our main() function to start a debug HTTP server

go func() {
    log.Println(http.ListenAndServe("localhost:6060", nil))
}()

You can now start and run your program to access the profiler

http://localhost:6060/debug/pprof/goroutine

Open your browser and navigate to http://localhost:6060/debug/pprof/

Key endpoints:

• /debug/pprof/goroutine: Lists all active goroutines.
• /debug/pprof/heap: Displays heap memory allocation details.
• /debug/pprof/profile: Captures a 30-second CPU profile.

Refer to previous tutorials on how this output would look like.

Remember our food delivery service example, For brevity, we are going to provide skeleton of the code and you can refer back to our previous articles for guidance.

// ProcessOrder simulates processing an order we had mentioned above
func processOrder(order Order) {
  
  // Payment processing
  log.Printf("[ORDER %d] Starting processing", order.ID)
  log.Printf("[ORDER %d] Payment processing", order.ID)  
  time.Sleep(time.Duration(rand.Intn(100)) * time.Millisecond)
  
  // Kitchen preparation
  log.Printf("[ORDER %d] Payment completed", order.ID)
  log.Printf("[ORDER %d] Kitchen preparation", order.ID)
  time.Sleep(time.Duration(rand.Intn(200)) * time.Millisecond)

  // Packaging
  log.Printf("[ORDER %d] Kitchen preparation completed", order.ID)  
  log.Printf("[ORDER %d] Packaging order", order.ID) 
  time.Sleep(time.Duration(rand.Intn(50)) * time.Millisecond)
 
  // Dispatch
  log.Printf("[ORDER %d] Packaging completed", order.ID)
  log.Printf("[ORDER %d] Dispatching order", order.ID) 
  time.Sleep(time.Duration(rand.Intn(100)) * time.Millisecond)

  log.Printf("[ORDER %d] Order dispatched", order.ID) 
  log.Printf("[ORDER %d] Processing complete", order.ID)
}

  // Worker function to process orders from a channel 
  func worker(id int, jobs <-chan Order, wg *sync.WaitGroup) { 
    defer wg.Done() 
    for order := range jobs { 
    log.Printf("[WORKER %d] Processing order %d", id, order.ID)   processOrder(order) 
  } 
}

Whats going on here:

In the `processOrder` Function:

• simulates the entire lifecycle of an order.
• which includes stages like payment processing, kitchen preparation, packaging, and dispatch.
• The `time.Sleep` calls with random durations introduce variability, mimicking real-world processing times.
• Log statements at each stage provide visibility into the order’s progress.

In the `worker` Function:

• represents a single worker in the order processing system.
• receives orders from a channel (`jobs`).
• The `defer wg.Done()` ensures that the worker signals its completion to the `sync.WaitGroup` when it’s done.
• The `for order := range jobs` loop continuously receives and processes orders from the channel until it’s closed.

The above example program simulates a high-throughput system where multiple orders are processed concurrently using a worker pool. In a setup like this, performance bottlenecks, resource exhaustion, or inefficient concurrency handling can lead to degraded user experience or system failure.

To debug and profile this program, we would create a goroutine monitor that logs the number of active goroutines

func monitorGoroutines() {
 for {
  log.Printf("[MONITOR] Active goroutines: %d", runtime.NumGoroutine())
  time.Sleep(2 * time.Second)
 }
}

We would then, from the main() function for demo purposes, launch a goroutine to start the net/http/pprof server for runtime profiling.

go func() {
  log.Println("[DEBUG] Starting pprof server on :6060")

  if err := http.ListenAndServe(":6060", nil); err != nil {
   log.Fatalf("Failed to start pprof server: %v", err)
  }
}()

We would then monitor goroutines on separate goroutines. The monitorGoroutines function logs the count of active goroutines every two seconds using runtime.NumGoroutine()

go monitorGoroutines()

A buffered channel (we will talk about this in the future 😀) jobs with a capacity of 100 is created to queue orders.

jobs := make(chan Order, 100)

The buffered channel prevents immediate blocking when sending orders, allowing producers to enqueue orders efficiently.

A worker pool of workerPoolSize (set to 10) is created to process orders concurrently. sync.WaitGroup is used to track when all worker goroutines finish processing.

var wg sync.WaitGroup
for i := 1; i <= workerPoolSize; i++ {
  wg.Add(1)
  go worker(i, jobs, &wg)
}

For each worker:

• A goroutine is launched to process orders.
• Each worker waits for jobs on the jobs channel and processes them using the processOrder function.
• Once the channel is closed and all jobs are processed, the worker marks itself as done using the WaitGroup.

// Send orders to the jobs channel
 for i := 1; i <= 100; i++ {
  jobs <- Order{ID: i}
 }

What simply happen here is:

• 100 orders are generated and sent to the jobs channel.
• Each order is represented as an Order struct containing a unique ID.
• Orders are enqueued in the channel one by one in a loop.

Close the jobs channel to signal workers to exit

close(jobs)

Wait for all workers to complete

wg.Wait()

That is it. Thats all I had for you today 😎.

As a closing remark, remember managing lots of concurrent operations can be tricky, which is why keeping an eye on goroutines and digging into how they’re running is so important. When you have tons of goroutines running in parallel, things like leaks, uneven workloads, and using channels the wrong way can pop up.

By constantly watching active goroutines and analyzing what’s happening at runtime using profiling tools, engineers can grasp how healthy the system is. This helps keep things running smoothly even when the load changes and makes sure the system can handle more and more demand.

Thank you and see you soon 👋!