Introduction
One of the things I love about Go is the profiling and debug information you can generate. There is a special environmental variable named GODEBUG that will emit debugging information about the runtime as your program executes. You can request summary and detailed information for both the garbage collector and the scheduler. What’s great is you don’t need to build your program with any special switches for it to work.

In this post, I will show you how to interpret the scheduler trace information from a sample concurrent Go program. It will help if you have a basic understanding of the scheduler. I recommend reading these two posts before continuing:

Concurrency, Goroutines and GOMAXPROCS
https://www.ardanlabs.com/blog/2014/01/concurrency-goroutines-and-gomaxprocs.html

Go Scheduler
http://morsmachine.dk/go-scheduler

The Code
This is the sample program we will use to inspect and interpret the results from GODEBUG:

  Listing 1  

The code in listing 1 is designed to be predictable against the debug information we expect to see emitted by the runtime. On line 12, a for loop is declared to create ten goroutines. Then the main function waits on line 16 for all the goroutines to finish their work. The work function on line 22 sleeps for one second and then increments a local variable ten billion times. Once the incrementing is done, the function calls Done on the wait group and returns.

It is a good idea to build your program with go build first, before setting the options for GODEBUG. This variable is picked up by the runtime, so running Go commands will produce tracing output as well. If you use GODEBUG in conjunction with go run for example, then you will see trace information for the build prior to your program running.

Now let’s build the program so we can run it with the GODEBUG scheduler option:


Scheduler Summary Trace
The schedtrace option causes the runtime to emit a single summary line about the scheduler’s state to standard error every X milliseconds. Let’s run the program, setting the GODEBUG option at the same time:


Once the program starts running we will see the tracing begin. The program itself does not output anything to standard out or standard error, so we can just focus on the traces. Let’s look at the first two traces that are emitted:


Let’s break down what each field represents and then understand the values based on the sample program:


The runtime is giving us a lot of great information at the summary level. When we look at the information for the trace at the 1 second mark, we can see how one goroutine is running and the other nine goroutines are waiting inside the local run queue.

  Diagram 1  
In diagram 1, the processor is represented by the letter P, threads by the letter M and goroutines by the letter G. We can see how the global run queue is empty based on the runqueue value being 0. The processor is executing a goroutine based on the idleprocs value being 0 and the remaining goroutines we created are in the local run queue based on the value of 9 being inside the brackets.

How does the trace change when we have more than one processor configured? Let’s run the program again adding GOMAXPROCS and look at the output traces that change:


Let’s focus on the trace for the 2 second mark when we run with two processors:


  Diagram 2  
Let’s look at the information in diagram 2 for the trace at the 2 second mark. We can see how a goroutine is running in each processor. We can also see that eight goroutines are waiting inside of the local run queues, four goroutines inside each of the two local run queues.

Things change when we get to the 6 second mark:


  Diagram 3  
When we get to the 6 second mark things change. Now in diagram 3, two of the goroutines we created completed their work and have been moved to the global run queue. We still have two goroutines running, one in each of the existing processors and three are waiting in each of the respective local run queues.

Advanced Note:
In many cases, goroutines are not moved back to the global run queue prior to being terminated. This program has created a special situation because the for loop is performing logic that runs for more than 10ms and is not calling into any functions. 10ms is the scheduling quant in the scheduler. After 10ms of execution, the scheduler tries to preempt goroutines. These goroutines can’t be preempted because they do not call into any functions. In this case, once the goroutines reach the wg.Done call, the goroutines are instantly preempted and moved to the global run queue for termination.

When the 17 second mark hits, we see the last two goroutines are now running:


  Diagram 4  
In diagram 4, we see how eight goroutines are in the global run queue and the remaining last two goroutines are running. This leaves each of the respective local run queues empty.

The final trace is at the 21 second mark:


  Diagram 5  
At this point, all the goroutines have finished their work and have been terminated.

Detailed Scheduler Trace
The scheduler summary information is very helpful, but sometimes you need an even deeper view. In those cases, we can add the scheddetail option which will provide detailed trace information about each processor, thread and goroutine. Let’s run the program again, setting the GODEBUG option to emit detailed trace information:


Here is the output at the 4 second mark:


The summary section is similar but now we have detailed lines for the processors, threads and goroutines. Let’s start with the processors:


P’s represents a processor. Since GOMAXPROCS is set to 2, we see two P’s listed in the trace. Next, let’s look at the threads:


M’s represents a thread. Since the threads value is set to 4 in the summary trace, we see four M’s listed in the detail. The detailed trace information shows which threads belong to which processors:


Here we see how thread M3 is attached to processor P0. This information is in both the P and M trace records.

A G represents a goroutine. At the 4 second mark we see that there are fourteen goroutines that currently exist and seventeen goroutines have been created since the program started. We know the total number of goroutines created because of the number attached to the last G listed in the trace:


If this program continued to create goroutines, we would see this number increase linearly. If this program was handling web requests for example, we could use this number to get a general idea of the number of requests that have been handled. This estimate would only be close if the program didn’t create any other goroutines during the handling of the request.

Next, let’s look at the goroutine the main function is running against:


We can see that the goroutine for the main function is in a status of 4, blocked on a semacquire which represents the wait group Wait call.

To better understand the rest of the goroutines in this trace, it is helpful to know what the status numbers represent. Here is a list of status codes that are declared in the header file for the runtime:


When we look at the ten goroutines we created, we can now look at their state and better understand what each is doing:


With a basic understanding of the scheduler and knowing the behavior of our program, we can get a detailed view of how things are being scheduled and the state of each processor, thread and goroutine in our program.

Conclusion:
The GODEBUG variable is a great way to peek into the mind of the scheduler while your program runs. It can tell you a lot about how your program is behaving. If you want to learn more, start by writing some simple programs that you can use to predict the traces coming from the scheduler. Learn what to expect before trying to look at a trace for more complicated programs.