database/sql: support tracing queries

[kardianos]

The database now supports passing context to query methods and to the drivers.

Look into supporting some sort of trace functionality for the sql package.

[kevpie]

I would be happy to help with this.

[kardianos]

I don't know if this is the best way to go, but here is the direction I've been thinking:

• Clients of database/sql would pass in a context with some type of sqltrace value stored in it.
• Drivers and the sql pool could check for this value and if present write to it.
• The sqltrace value when created would be set with some OR'ed bits of message types it accepts like:
  • timing
  • query text
  • argument values
  • driver messages
  • driver protocol
• Time would always be recorded.
• There would also be a sub-type of message like "timing: [query start, query return, rows close]".

I would think that this sqltrace type would be an interface, allowing various backing methods to be used: memory, db, disk, stderr.

From a driver maintainer's perspective, I think it would be sweet to have a context value I could ask a user encountering a bug to instrument their query with, then on error, grab the trace and return it with the error. Then when I get the error report I can see all the way through to the driver protocol and messages.

From a line of business application maintainer's perspective I'd like a comprehensive way to instrument my queries to get timing information out of them, bubbling up any queries that take a long time exposing the query text and parameters used for it.

@kevpie What do you think of this? Do you think you could propose something concrete based on this or an alternate design?

[kardianos]

@rsc Before I go down this road too far, one thing on your recent blog post is you'd like to clarify what does and doesn't go into context values.

I think something like this makes sense. I know others would push back on having something like a logger in a context.

Any guidance on what would be acceptable would be great.

[kevpie]

@kardianos I was thinking it could follow in the spirit of https://golang.org/pkg/net/http/httptrace/

I am using the httptrace.ClientTrace with timing logic similar to the implementation found in https://github.com/davecheney/httpstat. Being able to see dns, connect, tls handshake, upload time, processing time, download time among others could be useful.

[rsc]

@kardianos Try it and see. I don't know for sure but it's something that seems reasonable. It doesn't have the problems that transaction isolation mode did.

[kardianos]

@luna-duclos do you have any opinion on this topic? https://github.com/ExpansiveWorlds/instrumentedsql is an interesting take on this.

[luna-duclos]

Unlike HTTP, I see very few things that an sql driver doesn't already have access to to trace, so I think a wrapping driver is mostly the correct approach.

There are a few mechanisms however that are managed by the database/sql package and are completely invisible to the drivers, connection pooling being the primary one of those.
If the database/sql package could somehow provide visibility into the connection pool, perhaps in the form of a new interface with hooks that can be called when connections are created/closed, then that would be enough for everyone's needs I think.

[kardianos]

@luna-duclos I generally like this approach. It nicely removes the tracing logic away from the rest of the SQL logic.

Instrumenting the connection pool is also a good idea. Right now the connection pool is too opaque. If it isn't too invasive, I'll see what I can work up. I think it will be alright, the calls to get/put new conns are fairly centralized. However, this information would need to be attached at the driver level and not the request level I think. Could you propose an interface on your existing instrumentedsql package report conn pool stats?

Off the top of my head, it seems we could define:

type interface DriverPoolStats {
    driver.Driver

    OpenedConn(total int)
    ClosedConn(total int)
}

But I'm fairly sure that isn't right.

[gm42]

Some time ago I proposed a (MySQL) driver-level implementation: go-sql-driver/mysql#445

[kardianos]

I'm removing this milestone for now until more people have experience with @luna-duclos method and interface.

[shogo82148]

FYI: I'm developing https://github.com/shogo82148/go-sql-proxy.
It is the same approach as @luna-duclos method.

[pavelnikolov]

I started playing with github.com/opentracing/opentracing-go and wrapping the database/sql. Most things are easy to be wrapped except for transactions. Ideally I'd like to create a drop-in replacement so that my new db objects satisfy the existing interfaces. The problem is that the transactions are structs and can't really be wrapped without using a custom type.

[luna-duclos]

Have a look at https://github.com/ExpansiveWorlds/instrumentedsql, it provides exactly what you're looking for and can wrap any arbitrary SQL driver to provide tracing.

…

On Mon, Dec 4, 2017 at 1:25 PM, Pavel Nikolov ***@***.***> wrote: I started playing with github.com/opentracing/opentracing-go and wrapping the database/sql. Most things are easy to be wrapped except for transactions. Ideally I'd like to create a drop-in replacement so that my new db objects satisfy the existing interfaces. The problem is that the transactions are structs and can't really be wrapped without using a custom type. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#18080 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AFUXAMHkeaFtI0SWolr_FoNF9m8AYuhDks5s8-SzgaJpZM4K-KLA> .

[bboreham]

Anecdote: I spent some time this week trying to figure out what was slowing down my (Postgres) SQL queries, and it turned out that connection pooling was disabled. The tracing solutions mentioned here do not show this.

(I would question the statement that it is opaque to drivers: I was able to show connections being created by inserting Printf statements into instrumentedsql. But the Open() call does not receive a Context so it cannot be attached to a tracing span.)

[saward]

@luna-duclos would you recommend using your fork at https://github.com/luna-duclos/instrumentedsql now?

[ConradWoodGuru]

I started a thread[1] on the golang nuts mailing list about something similar.

tldr; wrapping a driver is clearly a viable approach, however I think there are some benefits to including this in the core sql package, for convenience I include my reasoning from the mailing list here:

In my view, there are two benefits to adding it to the main sql package
compared to wrapping a driver:

1. It makes it very simple, and thus encourages, the monitoring of sql
   queries, which I think is a good addition to the core golang libraries.

2. The interceptor can be added/removed at runtime. Of course, this
   could also be done with a driver-wrapper, but not quite as elegantly
   and IMHO with more potential to subtle race-conditions.

3. gRPC already has such mechanism (which is very useful) and being in-
   line and consistent with another package, namely gRPC, makes life
   easier for golang developers.(SQL Queries to a database are in my view
   similar to RPC calls, since both call external systems),

4. we can encourage 3rd parties to add interceptors to their products.
   For example: I like to see a hook to expose metrics to prometheus.
   currently the default client exposes useful golang core metrics (e.g.
   "go_gc_duration_seconds"). Adding it to core language (and applying the
   compatibility guarantees) is likely to increase uptake and we all
   benefit. Thus I could submit a patch to prometheus and say "look, this
   exposes more core metrics" ;)

[1] https://groups.google.com/forum/#!topic/golang-nuts/g8rBUu9MMmw

[kardianos]

@ConradWoodGuru I am interested in the interceptor concept. What would the interceptor interface look like? Would it look something like this:

package sql

// Queryer satisfies the interface for *DB, *Conn, and *Tx
// (assuming Tx grows a BeginTx and PingContext methods).
type Queryer interface {
    BeginTx(ctx context.Context, opts *TxOptions) (*Tx, error)
    PingContext(ctx context.Context) error
    ExecContext(ctx context.Context, query string, args ...interface{}) (Result, error)
    PrepareContext(ctx context.Context, query string) (*Stmt, error)
    QueryContext(ctx context.Context, query string, args ...interface{}) (*Rows, error)
    QueryRowContext(ctx context.Context, query string, args ...interface{}) *Row
}

// Interceptor is run instead of the given queries.
type Interceptor interface {
    InterceptPing(ctx context.Context, Queryer) (error)
    InterceptQuery(ctx context.Context, c Queryer, q string, params []interface{}) (*Rows, error)
    InterceptExec(ctx context.Context, c Queryer, q string, params []interface{}) (Result, error)

    InterceptPrepare(ctx context.Context, c Queryer, q string, params []interface{}) (*Stmt, error)
    InterceptStmeQuery(ctx context.Context, stmt *Stmt, q string, params []interface{}) (*Rows, error)
    InterceptStmtExec(ctx context.Context, stmt *Stmt, q string, params []interface{}) (Result, error)

    InterceptBeginTx(ctx context.Context, c Queryer, opts *TxOptions) (*Tx, error)
    InterceptCommit(ctx context.Context, tx *Tx) (error)
    InterceptRollback(ctx context.Context, tx *Tx) (error)
}

func (db *DB) SetInterceptor(Interceptor) { ... }

[ConradWoodGuru]

sorry for the late answer - github is not on my "closely being monitored list" of apps. I'll try to check this "issue" regularly from now on.

as per the answer:.
tldr; "something" like this yes :) - would be happy with the interfaces you described.

I would try to simplify the interceptor (so that it is easy to implement only the parts necessary).

type Interceptor interface {
beginDatabaseRequest(ctx context.Context, type DB_TYPE_ENUM, query string) error
completeDatabaseRequest(ctx context.Context, type DB_TYPE_ENUM, query string, error)
}
(DB_TYPE_ENUM is one of Ping/Query/Exec/Prepare...)

the functions are probably something like:

func (m *myInterceptor) beginDatabaseRequest(...) error {
if (type != DB_TYPE_Query) { // in this example: only interested in queries
return nil
}
// do stuff
if ( "stuff" failed ) {
return err // propgate, do not execute sql statement
}
// add current time to context.. and perhaps some 'id' to match in "completeDatabaseRequest"...
return nil // go ahead as normal
}

func (m *myInterceptor) completeDatabaseRequest(...) error {
if (type != DB_TYPE_Query) { // in this example: only interested in queries
return nil
}
// match request via context
// publish timing & error information to your favourite monitoring system
}

I realise this is somewhat unusual but it has a couple of benefits:

1. the execution code path of the query fully remains the responsibility of the SQL package
2. one can implement an interceptor with less code :)
3. results from the database may not be modified (which I think is feature not a bug )
4. the loose coupling between interceptor interface and sql package leaves more flexibility in (re)designing the sql package in the future, e.g. we can add an enum which is simply ignored by current interceptors. Given the interface with calls seperated out, we have to change the interface to add functionality, means the clients will have to follow immediately

Saying that - the interfaces you posted will solve my usecase too and are a great improvement, so if that's the way you want to go - I am happy to go with that!

wdyt?

[luna-duclos]

@luna-duclos would you recommend using your fork at https://github.com/luna-duclos/instrumentedsql now?

Yes

[inconshreveable]

Hiya all. We needed something like this at ngrok with a bit more flexibility so I put this together: https://github.com/ngrok/sqlmw

I think this is a pretty general purpose abstraction that allows for easy implementations of instrumentation like tracing in addition to support more powerful behaviors like caching, query rewriting, etc that require intermediating the calls.

The API is more or less what @kardianos proposed and I ended up forking @luna-duclos's branch of instrumentedsql to create the code. I took to heart @ConradWoodGuru's suggestion that you should only need to override the parts of the intercepting interface that you want to use by creating the NullInterceptor concept that you embed into your own.

Would appreciate feedback from everyone here who's had this problem.

Lastly, a quick example of what it looks like to use the API:

func run(dsn string) {
        // install the wrapped driver
        sql.Register("postgres-mw", sqlmw.Driver(pq.Dirver{}, new(sqlInterceptor)))
        db, err := sql.Open("postgres-mw", dsn)
        ...
}

type sqlInterceptor struct {
        sqlmw.NullInterceptor
}

func (in *sqlInterceptor) StmtQueryContext(ctx context.Context, conn driver.StmtQueryContext, query string, args []driver.NamedValue) (driver.Rows, error) {
        startedAt := time.Now()
        rows, err := conn.QueryContext(ctx, args)
        log.Debug("executed sql query", "duration", time.Since(startedAt), "query", query, "args", args, "err", err)
        return rows, err
}

[tcolgate]

The current setup for wrapping drivers is fairly painful to work with if you want minimal impact on the original code. You can't just wrap a *sql.DB the user has passed to you. You either have to open it for them (doing wierd round trips to get the driver.Driver, and name, and register a new name, and re-open with the wrapped driver), or wrap the driver in advance, and have them open their DB using the wrapped driver name (which isn't too bad), but doing it that way means we don't have access to DBStats, which would be a nice easy way to get some simple metrics.

[kardianos]

@tcolgate
I'm not a fan of wrapping drivers either. Can someone provide a summery of behavior different wrappers provide? It is obvious there is a need; it isn't obvious the exact outcomes integrated hooks would need to deliver. I can guess as I have above, but I'd prefer to see real code with real examples we can point to.

[tcolgate]

Sqlhooks provides the most simple option, a query start , finish and onerror approach. It's too simple for rich tracing, but ...
https://github.com/gchaincl/sqlhooks/blob/master/hooks/othooks/othooks.go

[tcolgate]

DBStats is good for connection pool metrics, but it would be nice to be able to trace through that process. Ideally you'd be able to see query submission to the API, through connection allocation, and the actual server hand off, with stuff around tx commit and rollback too.

[stevenh]

It's not sure what you're trying to achieve from the original description but if you're looking for full observability then I would suggest https://www.solarwinds.com/database-performance-monitor previously named vividcortex.

[jeffreydpayne]

We looked into creating a wrapping driver just to detect connection leaks and it didn't seem workable for many of the reasons mentioned above. We ended up forking and modifying the mysql driver instead.

[dolmen]

@jeffreydpayne What was missing with the Interceptor driver by @inconshreveable?

Edit: I found some missing interception callbacks and I opened an issue.

[prashanthpai]

@inconshreveable Thank you for sqlmw! I found it to be incredibly useful. Here's a sample caching middleware that uses sqlmw - https://github.com/prashanthpai/sqlcache