sched_trace

README

Schedule Tracing

We can get specific information about the scheduler using the GODEBUG environmental variable. The variable will cause the schedule to emit information about the health of the logical processors.

GODEBUG

[http://dave.cheney.net/2015/11/29/a-whirlwind-tour-of-gos-runtime-environment-variables](Tour of Go's env variables)

http://golang.org/pkg/runtime/

export GODEBUG=schedtrace=1000,scheddetail=1

*scheddetail*: setting schedtrace=X and scheddetail=1 causes the scheduler to emit
detailed multiline info every X milliseconds, describing state of the scheduler,
processors, threads and goroutines.

*schedtrace*: setting schedtrace=X causes the scheduler to emit a single line to standard
error every X milliseconds, summarizing the scheduler state.

Running Summary Trace

go build
GODEBUG=schedtrace=1000 ./sched_trace

export GOMAXPROCS=1
	SCHED 0ms: gomaxprocs=1 idleprocs=0 threads=2 spinningthreads=0 idlethreads=0 runqueue=0 [1]
	SCHED 1009ms: gomaxprocs=1 idleprocs=0 threads=3 spinningthreads=0 idlethreads=1 runqueue=0 [9]

export GOMAXPROCS=2
	SCHED 1001ms: gomaxprocs=2 idleprocs=2 threads=4 spinningthreads=0 idlethreads=2 runqueue=0 [0 0]
	SCHED 2002ms: gomaxprocs=2 idleprocs=0 threads=4 spinningthreads=0 idlethreads=1 runqueue=0 [4 4]

Scheduler States:
	gomaxprocs=1:  Contexts configured.
	idleprocs=0:   Contexts not in use. Goroutine running.
	threads=3:     Threads in use.
	idlethreads=0: Threads not in use.
	runqueue=0:    Goroutines in the global queue.
	[9]:           Goroutines in a context's run queue.
	[4 4]:         Goroutines in each of the context's run queue.

Running Detailed Trace

go build
GODEBUG=schedtrace=1000,scheddetail=1 ./sched_trace

	SCHED 2016ms: gomaxprocs=1 idleprocs=0 threads=3 spinningthreads=0 idlethreads=1 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
	P0: status=1 schedtick=20 syscalltick=14 m=0 runqsize=9 gfreecnt=0
	M2: p=-1 curg=-1 mallocing=0 throwing=0 gcing=0 locks=0 dying=0 helpgc=0 spinning=0 blocked=0 lockedg=-1
	M1: p=-1 curg=-1 mallocing=0 throwing=0 gcing=0 locks=1 dying=0 helpgc=0 spinning=0 blocked=0 lockedg=-1
	M0: p=0 curg=5 mallocing=0 throwing=0 gcing=0 locks=0 dying=0 helpgc=0 spinning=0 blocked=0 lockedg=-1
	G1: status=4(semacquire) m=-1 lockedm=-1
	G2: status=4(force gc (idle)) m=-1 lockedm=-1
	G3: status=4(GC sweep wait) m=-1 lockedm=-1
	G4: status=4(finalizer wait) m=-1 lockedm=-1
	G5: status=2(sleep) m=0 lockedm=-1
	G6: status=1(sleep) m=-1 lockedm=-1
	G7: status=1(sleep) m=-1 lockedm=-1
	G8: status=1(sleep) m=-1 lockedm=-1
	G9: status=1(sleep) m=-1 lockedm=-1
	G10: status=1(sleep) m=-1 lockedm=-1
	G11: status=1(sleep) m=-1 lockedm=-1
	G12: status=1(sleep) m=-1 lockedm=-1
	G13: status=1(sleep) m=-1 lockedm=-1
	G14: status=1(sleep) m=-1 lockedm=-1
	G15: status=4(timer goroutine (idle)) m=-1 lockedm=-1

Scheduler States:  
	gcwaiting=0: Is the scheduled blocking waiting for GC to finish.

P's represent contexts:  
	P0: status=1 schedtick=20 syscalltick=12 m=3 runqsize=4 gfreecnt=0
	P1: status=1 schedtick=8 syscalltick=2 m=2 runqsize=4 gfreecnt=0
	Context Stats:
		m=3:        The thread being used.
		runqsize=1: Number of goroutines in a context's run queue.

M's represent a thread:
  	M3: p=0 curg=11 mallocing=0 throwing=0 gcing=0 locks=0 dying=0 helpgc=0 spinning=0 blocked=0 lockedg=-1
  	M2: p=1 curg=6 mallocing=0 throwing=0 gcing=0 locks=0 dying=0 helpgc=0 spinning=0 blocked=0 lockedg=-1
  	M1: p=-1 curg=-1 mallocing=0 throwing=0 gcing=0 locks=1 dying=0 helpgc=0 spinning=0 blocked=0 lockedg=-1
  	M0: p=-1 curg=-1 mallocing=0 throwing=0 gcing=0 locks=0 dying=0 helpgc=0 spinning=0 blocked=0 lockedg=-1
	Thread Stats:  
		p=0: The Context this thread is attached to.

G's represent a goroutine:  
	G1: status=4(semacquire) m=-1 lockedm=-1
  	G2: status=4(force gc (idle)) m=-1 lockedm=-1
  	G3: status=4(GC sweep wait) m=-1 lockedm=-1
  	G4: status=4(finalizer wait) m=-1 lockedm=-1
  	G5: status=1(sleep) m=-1 lockedm=-1
  	G6: status=2(sleep) m=2 lockedm=-1
  	G7: status=1(sleep) m=-1 lockedm=-1
  	G8: status=1(sleep) m=-1 lockedm=-1
  	G9: status=1(sleep) m=-1 lockedm=-1
  	G10: status=1(sleep) m=-1 lockedm=-1
  	G11: status=2(sleep) m=3 lockedm=-1
  	G12: status=1(sleep) m=-1 lockedm=-1
  	G13: status=1(sleep) m=-1 lockedm=-1
  	G14: status=1(sleep) m=-1 lockedm=-1
  	G17: status=4(timer goroutine (idle)) m=-1 lockedm=-1
	Goroutine Stats:  
		m=3: The thread being used.
		status: http://golang.org/src/runtime/runtime.h
  			Gidle,                                 // 0 
   			Grunnable,                             // 1 runnable and on a run queue
   			Grunning,                              // 2 running
   			Gsyscall,                              // 3 performing a syscall
   			Gwaiting,                              // 4 waiting for the runtime
   			Gmoribund_unused,                      // 5 currently unused, but hardcoded in gdb scripts
   			Gdead,                                 // 6 goroutine is dead
   			Genqueue,                              // 7 only the Gscanenqueue is used.
   			Gcopystack,                            // 8 in this state when newstack is moving the stack
   			View runtime.h for more

Links

https://software.intel.com/en-us/blogs/2014/05/10/debugging-performance-issues-in-go-programs

http://www.goinggo.net/2015/02/scheduler-tracing-in-go.html

Code Review

Scheduler Stats (Go Playground)

---

All material is licensed under the Apache License Version 2.0, January 2004.

Documentation

Overview

Sample program to review scheduler stats.