instrumentedsql icon indicating copy to clipboard operation
instrumentedsql copied to clipboard

Relate spans together

Open nvx opened this issue 5 years ago • 2 comments

Currently if you run a query that returns a lot of rows, a separate span is created for sql-conn-query, and then different unrelated spans for sql-rows-next. If there is only one or two rows this isn't a big deal, but when there's a lot of rows (especially if it takes a considerable amount of time to read them all) it becomes quite difficult to see as the number of spans gets quite large and it's not possible to easily collapse the query down where it can be viewed easily.

This also occurs with transaction start and end with the queries run inside the transaction not being related at all either.

One could manually create a span around each query, but then that increases the boiler plate code required in a project. Ideally the library would have an option that when a query is run a span is created and all the related spans are created under that parent. Likewise when a transaction block is entered the same behaviour occurs.

Another option that the opentracing-contrib/go-stdlib/nethttp library (https://github.com/opentracing-contrib/go-stdlib/tree/master/nethttp) makes use of is creating a single span for the HTTP request, then using logs to signal the different stages. This approach probably wouldn't make much sense for transaction blocks, but could work well for queries and next row calls (1000 spans vs 1 span with 1000 logs for a query that returns 1000 rows)

I'm not sure if there's any technical restrictions around achieving either of these options. At a glance it seems transactions might be harder as you're passing a separate context.Context to each query you run within the transaction and some people might want to leverage spans in between the two. On the other hand though rows.Next() does not take a context so there isn't an opportunity to pass a different span here anyway so it seems like it would make sense to do something automatically in the library for this case.

nvx avatar May 12 '19 14:05 nvx

I've had a bit more of a think about it and have come to the conclusion Transactions aren't really feasible, but rows should work.

I'm thinking for compatibility default behaviour would be unchanged. If an option is provided to enable it though, in any func where driver.Rows object is returned a parent span is created above the normal span (ie OpSQLConnQuery). When the query has finished (ie the OpSQLConnQuery span) a new span would be created for the Rows. Both the parent and "Rows" spans will persist until wrappedRows.Close() is called.

There's a couple of options for what happens with the Rows span:

  1. Whenever wrappedRows.Next() is called a timestamped log is created in the Rows span at the start and end of the call. This mimics the behaviour of the opentracing-contrib/nethttp package. While spans might be logically the better option, using logs for start and done events makes browsing traces a far more usable experience - especially with a lot of rows returned, while not sacrificing on visibility.

  2. Whenever wrappedRows.Next() is called a child span under the Rows span is created. The advantage of this over current behaviour is at least all the rows are grouped together so it's a lot easier to collapse a single query to move onto the next one in a trace.

I like the answer as to which to do is actually both. If you want the grouping provide the option to enable it which would also provide a flag to control if logs should be generated, and if you don't want child spans for each Next() call disable it using the existing op exclude functionality.

The main dependency on this is a timestamped log functionality. OpenTracing supports this in Span.LogFields(). From what I can tell OpenCensus Span.Annotate() is equivalent. Unfortunately I have no experience with xray or Google Cloud tracing but I imagine similar functionality would exist there too.

Thoughts on this proposal? I'm happy to implement the instrumentedsql and opentracing tracer parts of this, and can probably have a crack at the opencensus tracer too, but I would need guidance for the Google Cloud and xray tracers.

nvx avatar May 20 '19 12:05 nvx

I apologize for the incredibly late response, I've had a chaotic few months with a long sick leave and a change of jobs. Am now finally on vacation and catching up with this, I'd be happy to accept such a functionality and assist with the other tracers as needed.

luna-duclos avatar Jul 14 '19 11:07 luna-duclos