Just about any server application with users is an application with impatient users. You need to keep on top of performance of your application. If you have an HTTP handler, you can just go and do some simple timing of start and end of the request and log it. Then you can analyze the logs, and look for slow endpoints.
But to dig deeper, inevitably you need to collect information which lets you triage the performance issue. Is it time spent waiting for a service? Is it time spend doing real work? Is it the database? Is it lupus?
One such library that solves these problems nicely is newrelic’s go agent library. It’s not the only approach in the go community, but it is a gold standard in terms of feature set and efficiency of data collection. A surprising amount of information is tallied, aggregated in your program and lazily sent to newrelic for later useful insights.
Whatever profiling library you use, hopefully you’ll find the use of this library as an illustration helpful in solving this concern for yourself.
Passing profiling objects via context, or: the missing guide to using newrelic’s go-agent in practice
The examples and guide tell you to set up an application, and then wrap your main handler function with it. Already, this has achieved the simple timing of the request’s start and stop, and gives you a fancy dashboard to boot. But it scratches the surface of the library’s ability to help answer that question: why is my endpoint slow?
This library has the same fundamental problem as logging does when it
comes to its use. There’s an object it wants to pass down to users,
but there is no clear way to do it and you can’t use globals. The
agent sneaks its way in by wrapping the http.ResponseWriter in its
own interface type. To get it out, you use:
func myHandler(w http.ResponseWriter, r *http.Request) {
if txn, ok := w.(newrelic.Transaction); ok {
txn.NoticeError(errors.New("my error message"))
}
}
Very clever, newrelic. This certainly gets around the fact that the
standard net/http handler function API does not allow any extra
auxilliary stack arguments.
But what about if you have several layers of abstraction between the
handler, and the service call (eg, database call) you want to time?
Pass that http.ResponseWriter around? The newrelic.Transaction
object?
The answer is, naturally, context.
Saving and Retrieving profiling objects
Again, let’s make a couple of functions to get newrelic things in and out of the context:
package profiling
import (
"context"
newrelic "github.com/newrelic/go-agent"
)
type profilingKeyType int
const (
appKey profilingKeyType = iota
txKey
)
// NewContext adds a newrelic thingy to the context
func NewContext(
ctx context.Context, thing interface{},
) context.Context {
var key profilingKeyType
switch thing := thing.(type) {
case newrelic.Application:
key = appKey
case newrelic.Transaction:
key = txKey
default:
return ctx
}
return context.WithValue(ctx, key, thing)
}
// GetApp returns a stashed newrelic.Application from the context
func GetApp(ctx context.Context) newrelic.Application {
if nrApp, ok := ctx.Value(appKey).(newrelic.Application); ok {
return nrApp
} else {
return nil
}
}
// GetTx returns a stashed newrelic.Transaction from the context
func GetTx(ctx context.Context) newrelic.Transaction {
if nrTx, ok := ctx.Value(appKey).(newrelic.Transaction); ok {
return nrTx
} else {
return nil
}
}
Timing your database queries
In your model code, you can now access the newrelic objects and time your database calls appropriately. First we’ll need a common function and some types in your model class.
package mymodels
type Ender interface {
End()
}
type NoopEnder struct {}
func (*NoopEnder) End() {}
var noopEnder = NoopEnder{}
// TraceOp allows the definition of a datastore segment to be
// referenced with a single data structure
type TraceOp struct {
Collection string
Operation string
}
// StartTrace takes a context, and if newrelic is detected, will
// return a started newrelic.DatastoreSegment representing the
// specified TraceOp. Otherwise, returns a no-op Ender
func StartTrace(ctx context.Context, traceOp TraceOp) Ender {
if txn := profiling.GetTx(ctx); txn != nil {
ds := &newrelic.DatastoreSegment{
Product: newrelic.DatastorePostgres,
Collection: traceOp.Collection,
Operation: traceOp.Operation,
}
ds.StartTime = newrelic.StartSegmentNow(txn)
return ds
} else {
return &noopEnder
}
}
With that established, in the model code, you can augment your model
functions with a single line call to this StartTrace function:
var MyModelFuncTrace = TraceOp{
Collection: "Model",
Operation: "Func",
}
func MyModelFunc(ctx context.Context, arg int) {
defer StartTrace(ctx, &MyModelFuncTrace).End()
modelFuncStmt.Exec(arg)
}
One important characteristic is that regardless of whether the passed-in function had a newrelic transaction in it or not, the method can succeed. But if it does, you’ll get a nice attribution of some time to the “Func on Model” postgres database operation.
So, if you can connect all the call stacks to the model function with
ctx calls, then you can get tracing. If you don’t, then you don’t
get tracing. This gives a nice, gradual path for enhancing your code
base to pass context around.
Unless of course, you were already passing it all around for the logging based on part 1 of this blog series!
Slave goroutines and passing a root context into the application
For various reasons (my guess is performance and model simplicity),
newrelic’s transaction are not to be shared between goroutines. This
means that if your program starts a new goroutine, it needs to create
a new newrelic.Transaction for that goroutine. To do that, it needs
the newrelic.Application instance. But if you followed the
examples, that was in your main package, and go’s strict limitation
of dependencies means you can’t access it as a global variable.
Now, you could of course just create it as a common dependency and use
a global, but why not use context?
A little trick with a closure can feed this context with a populated
newrelic.Application (apologies for the strange line wrap, but I’m
working with narrow margins here):
package main
import (
"fmt"
"io"
"net/http"
"os"
"github.com/newrelic/go-agent"
"github.com/FooStartup/profiling"
)
func helloHandler(
ctx context.Context, w http.ResponseWriter, r *http.Request,
) {
// to be meaningful, this handler would do something with
// ctx :)
io.WriteString(w, "hello, world")
}
// wrapWithProfilingContext curries the passed-in three argument
// handler function to a standard 2-argument function, and makes
// a new context with the newrelic transaction.
func wrapWithProfilingContext(
httpCtx context.Context,
ctxHanlerFunc func(context.Context, http.ResponseWriter,
*http.Request),
) (
rf func(w http.ResponseWriter, r *http.Request),
) {
ctx := httpCtx
if tx, ok := w.(newrelic.Transaction); ok {
ctx = profiling.NewContext(ctx, tx)
}
return func(w http.ResponseWriter, r *http.Request) {
ctxHandlerFunc(ctx, w, r)
}
}
func main() {
// Create a config. You need to provide the desired
// application name and your New Relic license key.
cfg := newrelic.NewConfig(
"My Go Application", "__YOUR_NEW_RELIC_LICENSE_KEY__",
)
// Create an application. This represents an application in
// the New Relic UI.
app, err := newrelic.NewApplication(cfg)
if err != nil {
fmt.Println(err)
os.Exit(1)
}
httpContext := profiling.NewContext(context.Background(), app)
// Wrap helloHandler. The performance of this handler will
// be recorded.
http.HandleFunc(
newrelic.WrapHandleFunc(
app, "/", wrapWithProfilingContext(
httpContext, helloHandler,
),
),
)
http.ListenAndServe(":8000", nil)
}
Now, any caller can create a new newrelic.Transaction by retrieving
the newrelic.Application object during the goroutine setup:
go func() {
goroCtx := ctx
var txn newrelic.Transaction
if app := profiling.GetApp(ctx); app != nil {
txn = app.StartTransaction("MyBackgroundFunc", nil, nil)
defer txn.End()
}
goroCtx = profiling.NewContext(ctx, txn)
MyBackgroundFunc(goroCtx, foo, bar)
}()
i.e., if the application was stored in the context, then create a new transaction and “overwrite” the one that was already there by creating a new context with the key replaced.
There’s a subtlety here: if the application wasn’t in the context, I
explicitly want the stored transaction to be “removed”. So I store a
nil. This is equivalent to there never having been any item there.
It’s probably possible to turn that into a convenient one-liner as the
StartTrace example did, but hopefully this can illustrate how you
can use context to pass objects for cross-cutting concerns like
profiling.