contrib/database/sql: properly annotate DB operations with execution trace tasks by nsrip-dd · Pull Request #2060 · DataDog/dd-trace-go

nsrip-dd · 2023-06-21T17:42:16Z

What does this PR do?

This PR creates execution trace tasks (if the execution tracer is enabled)
before the operations, and provides a way of communicating to the APM tracer
that it doesn't need to create a task for the span. The APM tracer will still
annotate the task with the span ID even if a task was already created.

Motivation

After #336, spans for database operations are created after the operation.
This is necessary because some operations may return ErrSkip if they aren't
supported, and creating spans with those errors is very noisy. But because of
this, execution trace tasks associated with those spans would appear to be only
a few microseconds long since they are created alongside the span and thus only
cover the very end of the operation.

Describe how to test/QA your changes

This PR adds a unit test which checks that spans get associated tasks with
a realistic duration.

I've tested this locally using a simple program which connects to Postgres and
pg_sleeps:

package main

import (
	"context"
	"net/http"
	"os"
	"runtime/trace"

	"github.com/lib/pq"
	sqltrace "gopkg.in/DataDog/dd-trace-go.v1/contrib/database/sql"
	"gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer"
)

func main() {
	tracer.Start()
	defer tracer.Stop()

	f, err := os.Create("go.trace")
	if err != nil {
		panic(err)
	}
	defer f.Close()
	if err := trace.Start(f); err != nil {
		panic(err)
	}
	defer trace.Stop()

	sqltrace.Register("pq", &pq.Driver{})
	uri := "host=localhost port=5432 user=postgres password=postgres dbname=postgres sslmode=disable"
	db, err := sqltrace.Open("pq", uri)
	defer db.Close()

	span, ctx := tracer.StartSpanFromContext(context.Background(), "parent")
	_, err = db.ExecContext(ctx, "select pg_sleep(0.5);")
	if err != nil {
		panic(err)
	}
	span.Finish()
}

Before:

After:

Reviewer's Checklist

Changed code has unit tests for its functionality.
If this interacts with the agent in a new way, a system test has been added.

pr-commenter · 2023-06-21T17:51:42Z

Benchmarks

Benchmark execution time: 2023-06-26 12:38:46

Comparing candidate commit 57fe40d in PR branch nick.ripley/fix-sql-span-trace-coverage with baseline commit 1330a36 in branch main.

Found 0 performance improvements and 0 performance regressions! Performance is the same for 24 metrics, 0 unstable metrics.

…tion trace tasks After #336, spans for database operations are created *after* the operation. This is necessary because some operations may return ErrSkip if they aren't supported, and creating spans with those errors is very noisy. But because of this, execution trace tasks associated with those spans would appear to be only a few microseconds long since they are created alongside the span and thus only cover the very end of the operation. This commit creates execution trace tasks (if the execution tracer is enabled) before the operations, and provides a way of communicating to the APM tracer that it doesn't need to create a task for the span. The APM tracer will still annotate the task with the span ID even if a task was already created. Still TODO: add tests

We test that a few spans show up as execution trace tasks, and have the correct annotations.

This doesn't cover absolutely everything, but it is better.

ajgajg1134

Overall looks good to me, it definitely adds a bit of complication to the database/sql contrib code, but unfortunately I can't see a better way to deal with the driver.ErrSkip business that causes this contrib to be so complicated.

nsrip-dd

Thanks for the review Andrew!

ajgajg1134

Looks good to me!

Missed in #2060 after adding a new dependency.

Missed in #2060 after adding a new dependency

The context used to prepare a statement and the context used to execute a statement need not be the same (see https://pkg.go.dev/database/sql#DB.PrepareContext) The execution trace task changes added in #2060 incorrectly used the statement's context from preparation to derive the execution trace task. We should be using the context provided for executing the statement instead. Fixes #2172

…ts (#2173) The context used to prepare a statement and the context used to execute a statement need not be the same (see https://pkg.go.dev/database/sql#DB.PrepareContext) The execution trace task changes added in #2060 incorrectly used the statement's context from preparation to derive the execution trace task. We should be using the context provided for executing the statement instead. Fixes #2172

Port the contrib/database/sql execution tracer test to use the new golang.org/x/exp/trace parser. The test is slightly cleaned up, but for the most part covers the same logic as its predecessor (see #2060). The primary difference is that, rather than hooking into a mock database/sql driver, we use a real one (sqlite3). To simulate a slow operation, the test registers a sleep function and also sleeps on connection. The purpose of this is to ensure, where we can, the tracer tasks cover the whole operation and not just the end of it. We no longer hook into _every_ operation, though, so we drop some time assertions.

nsrip-dd force-pushed the nick.ripley/fix-sql-span-trace-coverage branch from ee66e21 to 8f30854 Compare June 21, 2023 17:52

nsrip-dd force-pushed the nick.ripley/fix-sql-span-trace-coverage branch from 8f30854 to 509dc34 Compare June 21, 2023 18:31

nsrip-dd added 3 commits June 23, 2023 10:25

contrib/database/sql: add test for execution trace annotations

a95fe4c

We test that a few spans show up as execution trace tasks, and have the correct annotations.

contrib/database/sql: don't mutate stmt/tx contexts

7a997fe

contrib/database/sql: add more execution trace test coverage

7426c82

This doesn't cover absolutely everything, but it is better.

nsrip-dd changed the title ~~WIP: contrib/database/sql: properly annotate DB operations with execution trace tasks~~ contrib/database/sql: properly annotate DB operations with execution trace tasks Jun 23, 2023

Merge branch 'main' into nick.ripley/fix-sql-span-trace-coverage

675b8d1

nsrip-dd marked this pull request as ready for review June 23, 2023 16:44

nsrip-dd requested a review from a team June 23, 2023 16:44

nsrip-dd requested a review from a team as a code owner June 23, 2023 16:44

ajgajg1134 requested changes Jun 23, 2023

View reviewed changes

Comment thread internal/trace_context.go Outdated

Comment thread contrib/database/sql/tx.go Outdated

Comment thread contrib/database/sql/exec_trace_test.go Outdated

Comment thread contrib/database/sql/exec_trace_test.go

Comment thread contrib/database/sql/exec_trace_test.go

contrib/database/sql: respond to review comments

890b155

nsrip-dd commented Jun 23, 2023

View reviewed changes

Comment thread contrib/database/sql/exec_trace_test.go

Comment thread contrib/database/sql/exec_trace_test.go

Comment thread contrib/database/sql/tx.go Outdated

Comment thread internal/trace_context.go Outdated

Comment thread contrib/database/sql/exec_trace_test.go Outdated

ajgajg1134 approved these changes Jun 23, 2023

View reviewed changes

Merge branch 'main' into nick.ripley/fix-sql-span-trace-coverage

57fe40d

nsrip-dd merged commit ea87357 into main Jun 26, 2023

nsrip-dd deleted the nick.ripley/fix-sql-span-trace-coverage branch June 26, 2023 12:50

nsrip-dd mentioned this pull request Jun 26, 2023

ddtrace/tracer: changed default tracecontext propagation order #2072

Merged

2 tasks

nsrip-dd added a commit that referenced this pull request Jun 26, 2023

all: run go mod tidy

6472e5e

Missed in #2060 after adding a new dependency.

nsrip-dd mentioned this pull request Jun 26, 2023

all: run go mod tidy #2073

Merged

nsrip-dd added a commit that referenced this pull request Jun 26, 2023

all: run go mod tidy (#2073)

ed9cc9c

Missed in #2060 after adding a new dependency

nsrip-dd mentioned this pull request Aug 14, 2023

contrib/database/sql: use correct context for trace tasks in statements #2173

Merged

3 tasks

ajgajg1134 mentioned this pull request Sep 5, 2023

contrib/database/sql: use correct context for trace tasks in statemen… #2202

Merged

5 tasks

nsrip-dd mentioned this pull request Jul 16, 2024

internal/exectracetest: port database/sql test to the new parser #2790

Merged

6 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

contrib/database/sql: properly annotate DB operations with execution trace tasks#2060

contrib/database/sql: properly annotate DB operations with execution trace tasks#2060
nsrip-dd merged 7 commits into
mainfrom
nick.ripley/fix-sql-span-trace-coverage

nsrip-dd commented Jun 21, 2023 •

edited

Loading

Uh oh!

pr-commenter Bot commented Jun 21, 2023 •

edited

Loading

Uh oh!

ajgajg1134 left a comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

nsrip-dd left a comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

ajgajg1134 left a comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Uh oh!

Conversation

nsrip-dd commented Jun 21, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

What does this PR do?

Motivation

Describe how to test/QA your changes

Reviewer's Checklist

Uh oh!

pr-commenter Bot commented Jun 21, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Benchmarks

Uh oh!

ajgajg1134 left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

nsrip-dd left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

ajgajg1134 left a comment

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

nsrip-dd commented Jun 21, 2023 •

edited

Loading

pr-commenter Bot commented Jun 21, 2023 •

edited

Loading