Contents

A Go API usually responds in a few milliseconds, but some requests take 40 milliseconds. Logs reveal the delay, but they do not show whether that time was spent on database queries, rendering, or external calls.

You could introduce tracing infrastructure. But if the problem is confined to a single process, a SQLite file might be enough.

akmadian/gospan records nested spans and writes them to SQLite or log/slog. By instrumenting net/http handlers, running a workload, and querying the resulting file, you can find slow operations and the inputs associated with them.

What makes this useful is that parent-child relationships, durations, and attributes are stored together in tables you can query with ordinary SQL. Recording is asynchronous, however, so events can be dropped.

This article is based on supplied research materials for gospan v0.1.0, verified on October 7, 2026. The measurements below come from that research; they were not obtained from separate runs conducted for this article. The README defines the file format as a stable contract, but the Go API may change before version 1.0.

Use It When the Investigation Fits Within a Single Process#

gospan is well suited to a focused investigation: “Which operations within this program are slowing down requests?”

The core uses Go’s standard library. The SQLite sink uses the pure Go driver modernc.org/sqlite. In the supplied verification, the sample was built with CGO_ENABLED=0. No collector or agent is required.

There is no support for propagating context across processes. An HTTP call to another service therefore does not automatically carry the same trace forward. This boundary matters if you want to follow requests across multiple services.

The comparison with OpenTelemetry also needs to be precise. OpenTelemetry SDKs can run without a collector, and the infrastructure required depends on the exporter and deployment configuration. The appeal of gospan here is the direct path from local instrumentation to a queryable SQLite file.

Create the File and Instrument the Request Entry Point#

The following modules were used for verification:

snippet.txt
github.com/akmadian/gospan v0.1.0
github.com/akmadian/gospan/sqlite v0.1.0

The gospan modules tested require Go 1.25.0. Pin the versions when reproducing this example.

Initialize the sink once when the application starts:

snippet.txt
sink, err := sqlite.New("traces")
if err != nil {
    log.Fatal(err)
}

tracer, err := gospan.New(sink)
if err != nil {
    log.Fatal(err)
}

gospan.SetDefault(tracer)

By default, the sink creates a separate file for each run. You can get its location with sink.Path().

Create a root span at the request entry point and pass the returned context to the handler:

snippet.txt
func traced(route string, next http.HandlerFunc) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        ctx, span := gospan.Start(
            r.Context(),
            "http.request",
            slog.String("http.method", r.Method),
            slog.String("http.route", route),
        )
        defer span.End()

        next(w, r.WithContext(ctx))
    })
}

The r.WithContext(ctx) call establishes the parent span for operations inside the handler. If you start child spans with the original request context, that parent-child relationship is lost.

Keep span names fixed. Use a name such as db.query, and store the table, identifier, and query category in attributes. Including individual user IDs in names needlessly increases the number of distinct entries in in-memory aggregation.

Add Spans Around Operations You Can Improve#

A database helper can record inputs and errors:

snippet.txt
func loadUser(ctx context.Context, id int) error {
    ctx, span := gospan.Start(
        ctx,
        "db.query",
        slog.String("db.table", "users"),
        slog.Int("db.id", id),
    )
    defer span.End()

    err := queryUser(ctx, id)
    if err != nil {
        span.Fail(err)
    }
    return err
}

Fail only records the outcome; it does not end the span. Keep the deferred End call.

Errors that match context.Canceled or context.DeadlineExceeded through errors.Is receive the status canceled. Other errors receive error. This allows a timed-out dependency call and its enclosing HTTP request to record different outcomes. For example, the child span might be marked canceled, while the request is recorded as an error because it returned a 502.

Use SetAttrs for information that becomes available later, such as row counts. Changes made after End have no effect.

For small operations with no children, Track provides a shorter form:

snippet.txt
func checkCache(ctx context.Context) {
    defer gospan.Track(ctx, "cache.lookup")()
    // キャッシュを検索する。
}

Track does not return a context containing its span. Use Start if subsequent operations need to become child spans.

During shutdown, stop accepting requests, wait for running handlers to finish, and then call tracer.Close with an appropriate context. Closing processes the queued events and performs a final flush.

Prepare a Workload with Known Causes#

The supplied experiment sent a total of 300 requests to the following endpoints using eight concurrent workers:

| Endpoint | Deliberately configured behavior | |---|---| | GET /users/{id} | Simulated database work takes 40 ms when id % 10 == 7, and 2 ms otherwise | | GET /report | Three sequential database calls are followed by 15 ms of rendering | | POST /checkout | The payment call has a 30 ms timeout; one in eight inputs attempts 50 ms of work |

These delays were introduced deliberately. They demonstrate whether known causes can be identified from traces; they do not indicate a performance problem in a real database.

In the recorded run, 287 requests succeeded and 13 returned status 502. The tracer statistics were:

snippet.txt
started=1100 completed=1100 written=2500
dropped=0 write_errors=0

The 1,100 spans include request root spans and child operations. Written counts events, not completed spans. There were 1,100 start events, 1,100 end events, and 300 attribute updates, for a total of 2,500 events.

Check both dropped events and write errors before interpreting the file. The recording may be incomplete even if the query results look fine.

Find the Slowest Completed Operations#

The SQLite sink provides a spans_named view with readable names and a calculated duration_ns column. Attributes are stored in a separate attrs table.

Open the completed recording in read-only mode:

snippet.txt
sqlite3 -readonly traces/your-run.sqlite

First, inspect completed spans in descending order of duration:

snippet.txt
SELECT
    trace_id,
    id,
    parent_id,
    name,
    ROUND(duration_ns / 1e6, 2) AS duration_ms
FROM spans_named
WHERE end_ns IS NOT NULL
ORDER BY duration_ns DESC
LIMIT 20;

The root span of a slow request identifies what to investigate. Its child spans show which recorded operations contributed to the delay.

Inspect a single trace by replacing 123 with the trace ID you found:

snippet.txt
SELECT
    id,
    parent_id,
    name,
    ROUND(duration_ns / 1e6, 2) AS duration_ms,
    status,
    error
FROM spans_named
WHERE trace_id = 123
ORDER BY start_ns;

Do not add up the durations of every row and treat the total as the request duration. A parent’s duration includes its children’s execution time. Concurrent children may also overlap. Use the hierarchy and timestamps to interpret each time interval.

For the report endpoint, the sequential database calls and rendering appear as separate operations. This leads to concrete follow-up questions: “Can the database operations be batched?” and “Does rendering account for most of the delay?”

Connect Slow Spans to Their Inputs#

Durations identify which operations are slow. Attributes help you investigate the conditions under which they become slow.

The following query finds database spans longer than 20 milliseconds and lists their recorded IDs:

snippet.txt
SELECT
    t.value AS db_table,
    COUNT(*) AS slow_calls,
    group_concat(i.value, ',') AS ids
FROM spans_named AS s
JOIN attrs AS t
    ON t.span_id = s.id AND t.key = 'db.table'
JOIN attrs AS i
    ON i.span_id = s.id AND i.key = 'db.id'
WHERE s.name = 'db.query'
  AND s.end_ns IS NOT NULL
  AND s.duration_ns > 20e6
GROUP BY t.value;

In this controlled workload, the user IDs expected to be slow satisfy id % 10 == 7. In a real service, the same kind of query might reveal that delays cluster around a particular query category or input size.

That correlation alone does not explain the cause. If you suspect the database, confirm it with query plans and database-side measurements.

Use the following query for failed or incomplete operations:

snippet.txt
SELECT
    CASE
        WHEN end_ns IS NULL THEN 'incomplete'
        WHEN status = 1 THEN 'error'
        ELSE 'canceled'
    END AS outcome,
    name,
    COUNT(*) AS spans,
    MIN(error) AS sample_error
FROM spans_named
WHERE end_ns IS NULL OR status <> 0
GROUP BY outcome, name
ORDER BY spans DESC;

A null end timestamp means that the end was not persisted. Possible causes include an operation that has not finished, a dropped event, or a process that exited before flushing.

Treat Recording Reliability as Part of the Results#

gospan sends events through a bounded channel to a single writer goroutine. The default capacity is 8,192 events. When the channel fills, the default policy drops incoming events and increments Stats().Dropped.

Using WithBlockingPolicy() instead makes the sender wait until space is available. This allows events to enter the queue, but adds waiting time to the operation being measured.

In the supplied tight-loop benchmark, the slog sink dropped roughly 80% of events under the tested configuration. This demonstrates why overhead must not be evaluated without checking for missing events.

SQLite introduces another boundary. Written means the sink accepted an event; it does not guarantee that the event reached persistent storage. The sink buffers events and commits them during Flush. If a flush fails, pending data is discarded without a retry, and the failure is counted in WriteErrors.

Graceful shutdown matters. Forcibly terminating the process can lose queued or uncommitted events.

For a local investigation, these limitations may be acceptable if you check them explicitly. Start with one slow endpoint, add a request span and spans around expensive operations, and run a representative workload. Verify Dropped=0 and WriteErrors=0, inspect the slowest trace, and use its attributes to choose what to measure next.

Source: https://zenn.dev/nonejp/articles/c7dd2859872f9d

Contents