timers

README

zafnz/go-timers

go-timers is a library to assist with timing various code blocks in go in such a way that the values can be inspected later, in runtime, without invoking a debugger.

It's original purpose was to track downstream API calls, to measure what downstream callers were impacting the handlers the most.

Usage

See examples/main.go for a full overview, however here are the highlights.

Timers are created and stored in a context.Context, this is because the typical and expect use it they are associated with http transactions. Technically you can get the TimerSet and handle it yourself, but that's not the idea.

Chaining and defer

Timers can be chained, which provides a very nice interaction.

t := timers.From(ctx).New("My New Timer").Tag("mine").Start()

Due to the chaining they can be used to measure an entire function with just one line:

func MyFunction(ctx context.Context, args...) {
    defer timers.From(ctx).New("MyFunction").Start().Stop()
    ...
}

This timer will terminate when the function returns. How neat!

You can measure a code segment (such as an API call, etc) with a simple wrapper function that handles the timer.

ctx := timers.NewContext(context.Background())
timers.From(ctx).New("some function").Measure(func() {
    someFunctionThatTakesTime()
})

Output and waterfalls

You can retrieve all timers that have been created using timers.From(ctx).All() and .AllDeep() to get all the context timers or all the context timers and their children respectively. This can be outputted as a tree using timers.From(ctx).Tree(callback), or -- if you are writting a web server -- you can use the Server-Timings header and waterfall display.

http headers

The Middleware function registers a http handler that adds a TimerSet to the request context, and writes the Server-Timing header.

Once a Server-Timing header is set, you can view the timings either using the in browser inspector, or you can use the go-timers built-in waterfall display.

mux := http.NewServeMux()
mux.HandleFunc("/api", func(w http.ResponseWriter, r *http.Request) {
    defer timers.From(r.Context()).New("Api Function").Start().Stop()
    // Do stuff.
    fmt.Fprintf(w, "Results of stuff")
})
// Add the waterfall handler too.
// Note the trailing slashes are important!
mux.Handle("/waterfall/", http.StripPrefix("/waterfall/", timers.WaterfallHandler()))
handler := timers.Middleware(mux, timers.MiddlewareOptions{})
http.ListenAndServe("127.0.0.1:3000", handler)

Waterfall

By calling timers.WaterfallHandler() you get a http Handler that will render a waterfall of calls to your web process. See the examples/waterfall directory for a very simple example.

Grouping/children

Timers can be grouped by deriving a new context.

func MyFunc(ctx context.Context) {
    newCtx, _ := timers.NewContextWithTimer(ctx, "A new group of timers that are under the previous ctx")  
    timers.From(newCtx).New("Timer1")
    timers.From(newCtx).New("Timer2")
}

A wrap function provides a clean way to do this.

func MyFunc(ctx context.Context) {
    ...
    // You have to provide the ctx to the Wrap function as the TimerSet itself
    // does not hold the context to avoid leaking it. 
    timers.From(ctx).Wrap(ctx, "A library call", func(ctx context.Context) {
        MakeSomeCall(ctx, ...)
    })
    // All timers that MakeSomeCall() created are under "A library call" timer. 
    for _, t := range timers.From(ctx).Find("A library call").Children {
      fmt.Println(t) // Prints all the timers that were created.
    }
}

Thread safety

TimerSets are thread (go routine) safe, but Timers are not. Do not pass a Timer to another go routine, instead pass the ctx and let it create it's own.

Global timers and CLI

If you have a desire to have global timers, perhaps you are writing a CLI application or something that isn't request driven, then the timers package exposes timers.GlobalTimers and a convienance function timers.New. The timers.New(...) is a wrapper for timers.GlobalTimers.New(...). As is the case with other TimerSets, GlobalTimers is threadsafe, but the individual timers are not.

The author cannot fathom what particular use there may be for using timers like this without using a context, but if you have one, please let me know.

As for making use of these GlobalTimers, since they are simply a global TimerSet, any of the functions such as All() and Tree() will work. Perhaps at the end of main() you'd print all the timers for debugging purposes. In which case calling timers.GlobalTimers.String() would probably be useful.

Documentation

Overview

This package timers provides useful timers for measuring code paths in a production type environment. While pprof may be considered an overkill or disadventagous for use in production systems, this code is designed to be lightweight and produce useful output.

It's original purpose was to aid in providing latency timings for downstream API calls for an API service. With strategic timers placed around and use of middleware performance timers for services can be provided.

Example

package main

import (
	"context"
	"fmt"
	"math/rand"
	"strings"
	"sync"
	"time"

	"github.com/zafnz/go-timers"
)

func majorWork(ctx context.Context, wg *sync.WaitGroup) {
	fmt.Println("Some other major work starting")
	time.Sleep(time.Duration(rand.Intn(1000) * int(time.Millisecond)))
	fmt.Println("Some other major work finished")
	wg.Done()

}
func moreMajorWork(ctx context.Context) {
	fmt.Println("more major work starting")
	time.Sleep(time.Duration(rand.Intn(1000) * int(time.Millisecond)))
	timers.From(ctx).Wrap(ctx, "subwork", func(ctx context.Context) {
		fmt.Println("Subwork going on")
		time.Sleep(time.Duration(rand.Intn(500)) * time.Millisecond)
		fmt.Println("subwork finished")
	})
	fmt.Println("more major work finished")
}

func main() {
	// Create a new TimerSet in a new context.
	ctx := timers.NewContext(context.Background())

	// do things
	func() {
		defer timers.From(ctx).New("Measure Sleep").Start().Stop()
		time.Sleep(100 * time.Millisecond)
	}()
	t := timers.From(ctx).New("Count to a hundred million")
	t.Start()
	for i := 0; i < 100000000; i++ {
	}
	t.Stop()

	// Create a new context and do a bunch of major work under
	// that context, bundling all those timers in their own collection.
	// All the timers are retrievable from the parent context.
	func() {
		ctx, t := timers.NewContextWithTimer(ctx, "All major work")
		t.Start()
		defer t.Stop()

		wg := sync.WaitGroup{}
		for i := 0; i < 2; i++ {
			wg.Add(1)
			go timers.From(ctx).Wrap(ctx, "majorWork", func(ctx context.Context) {
				majorWork(ctx, &wg)
			})
		}
		wg.Wait()
		fmt.Println("All major work complete")
	}()

	workCtx, t := timers.NewContextWithTimer(ctx, "More work")
	t.Start()
	moreMajorWork(workCtx)
	t.Stop()

	fmt.Println("\nLets see how we did:")
	for _, t := range timers.From(ctx).AllDeep() {
		fmt.Println(t)
	}
	fmt.Println("\n\nAs a tree")
	timers.From(ctx).Tree(func(timer timers.Timer, depth int, _ *timers.TimerSet) {
		fmt.Printf("%s %s\n", strings.Repeat(" ", depth), timer.String())
	})

}

Index

• func Middleware(next http.Handler, opts MiddlewareOptions) http.Handler
• func NewContext(ctx context.Context) context.Context
• func WaterfallHandler() http.Handler
• type MiddlewareOptions
• type Timer
  • func New(name string, a ...interface{}) *Timer
  • func NewContextWithTimer(ctx context.Context, name string, a ...interface{}) (context.Context, *Timer)
  • func (t *Timer) Children() []Timer
  • func (t *Timer) Compare(t2 *Timer) bool
  • func (t *Timer) Duration() time.Duration
  • func (t *Timer) IsRunning() bool
  • func (t Timer) MarshalJSON() ([]byte, error)
  • func (t *Timer) Measure(fn func())
  • func (t *Timer) Milliseconds() float64
  • func (t *Timer) Start() *Timer
  • func (t *Timer) Stop() *Timer
  • func (t Timer) String() string
  • func (t *Timer) Tag(tag string) *Timer
  • func (t *Timer) Tags() []string
  • func (t *Timer) UnmarshalJSON(bytes []byte) error
• type TimerSet
  • func From(ctx context.Context) *TimerSet
  • func Get(ctx context.Context) *TimerSet
  • func SetFromContext(ctx context.Context) *TimerSet
  • func (s *TimerSet) AddHeader(w http.ResponseWriter)
  • func (s *TimerSet) All() []Timer
  • func (s *TimerSet) AllDeep() []*Timer
  • func (s *TimerSet) Find(name string) *Timer
  • func (s *TimerSet) MarshalJSON() ([]byte, error)
  • func (s *TimerSet) New(name string, a ...interface{}) *Timer
  • func (s *TimerSet) String() string
  • func (s *TimerSet) Tree(fn func(Timer, int, *TimerSet))
  • func (s *TimerSet) UnmarshalJSON(bytes []byte) error
  • func (s *TimerSet) Wrap(ctx context.Context, name string, fn func(context.Context))

Examples

• Package
• Middleware
• New
• NewContextWithTimer
• Timer.Measure
• Timer.Tags
• TimerSet.MarshalJSON
• TimerSet.New
• TimerSet.Wrap

Functions

func Middleware

func Middleware(next http.Handler, opts MiddlewareOptions) http.Handler

The middleware function sets up timers for each request, and for each request emits a Server-Timing header. A default "Request" timer is created, unless the option NoDefaultTimer is true. Use this function as you would any other middleware function

handler = timers.Middleware(handler, MiddlewareOptions{})

Example

package main

import (
	"net/http"

	"github.com/zafnz/go-timers"
)

func main() {
	mux := http.NewServeMux()
	mux.HandleFunc("/api", func(w http.ResponseWriter, r *http.Request) {
		defer timers.From(r.Context()).New("Api Function").Start().Stop()
	})
	// Add the waterfall handler too.
	// Note the trailing slashes are important!
	mux.Handle("/waterfall/", http.StripPrefix("/waterfall/", timers.WaterfallHandler()))
	handler := timers.Middleware(mux, timers.MiddlewareOptions{})
	http.ListenAndServe("127.0.0.1:3000", handler)
}

func NewContext

func NewContext(ctx context.Context) context.Context

Returns a context containing a new TimerSet. If the existing supplied context includes a TimerSet, then a timer is added to that with the name "Subtimer" to keep the timer tree. If you want to control the name of the parent timer, use NewContextWithTimer, if you do not want a timer at all, use context.Background(), or simply create a TimerSet empty struct that will not be attached to the current context.

func WaterfallHandler

func WaterfallHandler() http.Handler

Returns a http.Handler that will serve the waterfall inspector suitable for rendering a waterfall of the Server-Timing header. When registering the handler, ensure you strip prefix. Eg:

http.Handle("/waterfall/", http.StripPrefix("/waterfall/", timers.WaterfallHandler()))

Types

type MiddlewareOptions

type MiddlewareOptions struct {
	Callback       func(*TimerSet) // This function will be called at the end of the request
	NoDefaultTimer bool            // If true, then no default timer will be set.
}

type Timer

type Timer struct {
	// contains filtered or unexported fields
}

An individual timer is used to measure, well, time elapsed, and is stored in a timerset. This type provides different functionality from a traditional time.Timer, as it has an interface designed to be quick and easy to instrument functions and code blocks.

To get a Timer, you call New from a TimerSet, retrieved from the context:

timers.From(ctx).New("Blah")

func New

func New(name string, a ...interface{}) *Timer

Create a new global timer with the provided name. Name is a format string (like Printf) This is a convienance function for timers.GlobalTimers.New(...)

Example

package main

import (
	"fmt"

	"github.com/zafnz/go-timers"
)

func main() {
	defer timers.New("Example").Start().Stop()
	// ... Do some work...
	timer := timers.GlobalTimers.Find("Example")
	fmt.Println(timer)
}

Output:
Example: Running

func NewContextWithTimer

func NewContextWithTimer(ctx context.Context, name string, a ...interface{}) (context.Context, *Timer)

Returns a new context with a new TimerSet attached to it, and a timer attached to the previous context (if any). If the previous context did not have a TimerSet, then the timer is a floating timer (but safe to use). The timer name string can be a formatted string (just like fmt.Printf)

TimerSets are threadsafe, you can create new timers across threads using the same TimerSet, however the Timers themselves are not. Don't manipulate the same Timer in different go routines at the same time. You're probably doing it wrong if you find yourself wanting to.

Example

package main

import (
	"context"
	"fmt"

	"github.com/zafnz/go-timers"
)

func goDoSomeWork(_ context.Context) {

}

func main() {
	// Create a context to use for timings.
	ctx := context.Background()
	// Create a new TimerSet for grouping timers.
	newCtx, t := timers.NewContextWithTimer(ctx, "group")
	t.Start()
	goDoSomeWork(newCtx)
	t.Stop()
	workTimerSet := timers.From(newCtx)
	fmt.Printf("Work took %d ms and produced %d timers", t.Duration(), len(workTimerSet.All()))
}

func (*Timer) Children

func (t *Timer) Children() []Timer

Returns a _copy_ of the timers under this timer, if any. Returns empty list otherwise.

func (*Timer) Compare

func (t *Timer) Compare(t2 *Timer) bool

Compares the provided timer with this timer and returns true or false on whether they are equivilent. (Note: The timers have nanosecond resolution, so this function really is "is this the exact same timer?")

func (*Timer) Duration

func (t *Timer) Duration() time.Duration

Returns how long the timer ran for. If the timer hasn't started, returns 0. If the timer is still running, it returns it's current runtime If the timer has been stopped it returns it's duration.

func (*Timer) IsRunning

func (t *Timer) IsRunning() bool

Returns true if the timer is running

func (Timer) MarshalJSON

func (t Timer) MarshalJSON() ([]byte, error)

func (*Timer) Measure

func (t *Timer) Measure(fn func())

Very trivial wrapper function. Simply wraps the provided function with the timer, allowing simple duration measurement. Use with closure style. Differs from timers.From(ctx).Wrap() because this method does not create a new context and TimerSet. See `TimerSet.Wrap()“

From(ctx).New("Timer").Wrap(func() {
    SomeFunction(things, stuff)
})

Example

package main

import (
	"context"
	"fmt"
	"math"
	"time"

	"github.com/zafnz/go-timers"
)

func someApiCall(_ int) {
	time.Sleep(10 * time.Millisecond)
}

func main() {
	ctx := timers.NewContext(context.Background())
	// Want to measure how long this API call will take.
	someData := 42
	timers.From(ctx).New("apiCall").Measure(func() {
		// This function will take just over 10ms
		someApiCall(someData)
	})
	ms := timers.From(ctx).Find("apiCall").Milliseconds()
	fmt.Println(math.Floor(ms))
	// Would print "10", except if time.Sleep() takes longer
}

func (*Timer) Milliseconds

func (t *Timer) Milliseconds() float64

Returns the duration the timer ran for or has been running in milliseconds, as a float rounded to 3 decimal places.

func (*Timer) Start

func (t *Timer) Start() *Timer

Starts the timer.

func (*Timer) Stop

func (t *Timer) Stop() *Timer

Stops the timer

func (Timer) String

func (t Timer) String() string

Returns a string representing the timer's current state

func (*Timer) Tag

func (t *Timer) Tag(tag string) *Timer

Tags the timer with a string. Multiple tags are supported. You can do timer.Timers(ctx).New("Test").Tag("tagA").Tag("tagB").Start()

func (*Timer) Tags

func (t *Timer) Tags() []string

Returns a list of all tags the timer has

Example

package main

import (
	"context"
	"fmt"

	"github.com/zafnz/go-timers"
)

func main() {
	// Grab a floating timer from the background context, which has no timerset
	timer := timers.From(context.Background()).New("MyFunc")
	// Assign it a tag and start
	timer.Tag("Test").Start()
	fmt.Printf("%s", timer.Tags())
}

Output:
[Test]

func (*Timer) UnmarshalJSON

func (t *Timer) UnmarshalJSON(bytes []byte) error

type TimerSet

type TimerSet struct {
	// contains filtered or unexported fields
}

A TimerSet is the list of timers inside a Context. The TimerSet provides a collection of functions to create, retrieve, and export timers. Creation of a TimerSet is done with the NewContext function.

var GlobalTimers *TimerSet = &TimerSet{}

func From

func From(ctx context.Context) *TimerSet

Returns the TimerSet in the supplied context. If one doesn't exist, it returns a floating TimerSet that will be garbage collected. This ensures that chaining is always possible.

Example:

t := timers.From(ctx).New("blah")

Regardless of whether there is a TimerSet in the current context, you will get back a working timer you can use.

func Get

func Get(ctx context.Context) *TimerSet

Deprecated: Use `From` instead, this function will disappear next major version.

func SetFromContext

func SetFromContext(ctx context.Context) *TimerSet

Get TimerSet from provided context (if any), otherwise return nil.

You probably don't want this function. You want to always create a context with a new TimerSet (timers.NewContext()) and just use timers.From(ctx) to retrieve it -- knowing it's safe because if you end up in a context that has no timers it will still give you a working TimerSet. Otherwise what are you going to do if this function returns nil? Create a new context with NewContext()? Then just use NewContext in the first place.

func (*TimerSet) AddHeader

func (s *TimerSet) AddHeader(w http.ResponseWriter)

Adds a Server-Timing header to the provided ResponseWriter, which contains all of the timers in the timerset, including all child timers.

This function is useful primarily if you don't want to use the entire timers middleware suit

Ex:

func ApiCall(w http.ResponseWriter, r *http.Request) {
    ctx := timers.NewContext(r.Context())
    result := DoAllTheApiWork(ctx) // Bunch of timers and subtimers created doing the work
    timers.Get(ctx).AddHeader(w) // Add the response header
    fmt.Fprintf(w, result)
}

func (*TimerSet) All

func (s *TimerSet) All() []Timer

Returns a copy of all timers in this context. Note: These are a copy of the timers, not the original. TimerSets are threadsafe, Timers aren't.

func (*TimerSet) AllDeep

func (s *TimerSet) AllDeep() []*Timer

Returns a copy of all timers in this context and timers created in child contexts (regardless of whether the underlying context) has been canceled.

func (*TimerSet) Find

func (s *TimerSet) Find(name string) *Timer

Retrives the first timer with the provided name (Names do not have to be unique)

func (*TimerSet) MarshalJSON

func (s *TimerSet) MarshalJSON() ([]byte, error)

Exports a TimerSet as a list of timers, each timer may have a "children" field, which contains a list of it's children in a tree like structure.

To create an output suitable for a waterfall, use json.Marshal(set.GetAll())

Example

package main

import (
	"context"
	"encoding/json"
	"fmt"

	"github.com/zafnz/go-timers"
)

func main() {
	ctx := timers.NewContext(context.Background())
	timers.From(ctx).New("Timer 1")
	timers.From(ctx).New("Timer 1")
	timers.From(ctx).New("Timer 1")
	bytes, _ := json.MarshalIndent(timers.From(ctx), "", " ")
	fmt.Print(string(bytes))
}

Output:
[
 {
  "name": "Timer 1",
  "start": 0,
  "duration": 0
 },
 {
  "name": "Timer 1",
  "start": 0,
  "duration": 0
 },
 {
  "name": "Timer 1",
  "start": 0,
  "duration": 0
 }
]

func (*TimerSet) New

func (s *TimerSet) New(name string, a ...interface{}) *Timer

Create a new timer with the provided name. Name is a format string (like Printf)

Example

package main

import (
	"context"

	"github.com/zafnz/go-timers"
)

func main() {
	// The method chaining provides for a very useful way of performing timing on a
	// whole function. Assume your function is provided a context that has been generated
	// like so:
	ctx := context.Background()
	// At the top of the function we put this one line, and the "My Function" timer in
	// the current ctx now has the duration of this function.
	defer timers.From(ctx).New("My function").Start().Stop()

	// The New function supports string formatting directives using fmt.Sprintf
	defer timers.From(ctx).New("My function(%s, %d)", "Calling Parameter", 5)
}

func (*TimerSet) String

func (s *TimerSet) String() string

func (*TimerSet) Tree

func (s *TimerSet) Tree(fn func(Timer, int, *TimerSet))

Walk the timer tree. Since you can create new TimerSets in new contexts, the timers are effectively a tree. You can retrieve all the timers from the tree using GetAll() or you can walk the tree using Tree(). This function takes a callback function that will be called with a COPY of each timer, and supplied with the current tree depth, and the parent TimerSet (that is the parent of the current TimerSet this Timer belongs to). If the timer is part of this TimerSet, then the parent will be nil.

func (*TimerSet) UnmarshalJSON

func (s *TimerSet) UnmarshalJSON(bytes []byte) error

Given a list of timers, turns it back into a TimerSet Be aware that the TimerSet will be lacking any context and will not be able to be associated to a context. You have essentially just imported a block of floating timers

func (*TimerSet) Wrap

func (s *TimerSet) Wrap(ctx context.Context, name string, fn func(context.Context))

Wrap a block of work with a timer set in a new context. All timers that occur in the provided context will be children of the current context. The current context will have a timer measuring the duration.

NOTE: You may find TImer.Wrap() to be better suited, it is simplier and doesn't require context passing.

e.g. In the example below, a new Main context is created, and it will have 2 timers, Stuff and Some Work. The "Some Work" timer will have 3 sub timers under it.

Example

package main

import (
	"context"

	"github.com/zafnz/go-timers"
)

func main() {
	ctx := timers.NewContext(context.Background())
	timers.From(ctx).New("Stuff").Start().Stop()
	timers.From(ctx).Wrap(ctx, "Some Work", func(ctx context.Context) {
		timers.From(ctx).New("work step 1").Start().Stop()
		timers.From(ctx).New("work step 2").Start().Stop()
		timers.From(ctx).New("work step 3").Start().Stop()
	})

}