util/tracing: TestSpanPooling failed

[cockroach-teamcity]

util/tracing.TestSpanPooling failed with artifacts on master @ 01e14f68f7c757cab1c878cebfecd73c5119046b:

=== RUN   TestSpanPooling
    test_log_scope.go:161: test logs captured to: /artifacts/tmp/_tmp/569b06419b4849b8fee6fc682962eb0e/logTestSpanPooling3512467931
    test_log_scope.go:79: use -show-logs to present logs inline
    tracer_external_test.go:99: 
        	Error Trace:	/home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/2339/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/util/tracing/tracing_test_/tracing_test.runfiles/com_github_cockroachdb_cockroach/pkg/util/tracing/tracer_external_test.go:99
        	Error:      	Should be zero, but was 1
        	Test:       	TestSpanPooling
        	Messages:   	spans allocated per query: [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 2 2 2 2 2 2 2 2]
    panic.go:522: -- test log scope end --
test logs left over in: /artifacts/tmp/_tmp/569b06419b4849b8fee6fc682962eb0e/logTestSpanPooling3512467931
--- FAIL: TestSpanPooling (0.89s)

Parameters: TAGS=bazel,gss

Help

See also: How To Investigate a Go Test Failure (internal)

/cc @cockroachdb/obs-inf-prs

This test on roachdash | Improve this report!

Jira issue: CRDB-25227

[cockroach-teamcity]

util/tracing.TestSpanPooling failed with artifacts on master @ 5b2a5670cbbe895d76602c230390816e783e0caa:

=== RUN   TestSpanPooling
    test_log_scope.go:161: test logs captured to: /artifacts/tmp/_tmp/569b06419b4849b8fee6fc682962eb0e/logTestSpanPooling938656957
    test_log_scope.go:79: use -show-logs to present logs inline
    tracer_external_test.go:99: 
        	Error Trace:	/home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/1266/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/util/tracing/tracing_test_/tracing_test.runfiles/com_github_cockroachdb_cockroach/pkg/util/tracing/tracer_external_test.go:99
        	Error:      	Should be zero, but was 1
        	Test:       	TestSpanPooling
        	Messages:   	spans allocated per query: [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 2 2 2 2 2 3 3 3 3]
    panic.go:522: -- test log scope end --
test logs left over in: /artifacts/tmp/_tmp/569b06419b4849b8fee6fc682962eb0e/logTestSpanPooling938656957
--- FAIL: TestSpanPooling (0.78s)

Parameters: TAGS=bazel,gss

Help

See also: How To Investigate a Go Test Failure (internal)

This test on roachdash | Improve this report!

[cockroach-teamcity]

util/tracing.TestSpanPooling failed with artifacts on master @ 95684388bfbb372ac8c7e1a8ebd4a0d6f447e147:

=== RUN   TestSpanPooling
    test_log_scope.go:161: test logs captured to: /artifacts/tmp/_tmp/569b06419b4849b8fee6fc682962eb0e/logTestSpanPooling1121965064
    test_log_scope.go:79: use -show-logs to present logs inline
    tracer_external_test.go:99: 
        	Error Trace:	/home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/3076/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/util/tracing/tracing_test_/tracing_test.runfiles/com_github_cockroachdb_cockroach/pkg/util/tracing/tracer_external_test.go:99
        	Error:      	Should be zero, but was 1
        	Test:       	TestSpanPooling
        	Messages:   	spans allocated per query: [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 2 2 2 2 3 3 3 3]
    panic.go:522: -- test log scope end --
test logs left over in: /artifacts/tmp/_tmp/569b06419b4849b8fee6fc682962eb0e/logTestSpanPooling1121965064
--- FAIL: TestSpanPooling (0.77s)

Parameters: TAGS=bazel,gss

Help

See also: How To Investigate a Go Test Failure (internal)

This test on roachdash | Improve this report!

[cockroach-teamcity]

util/tracing.TestSpanPooling failed with artifacts on master @ e4924e2b9be4a36d466beab53a80df9241df4783:

=== RUN   TestSpanPooling
    test_log_scope.go:161: test logs captured to: /artifacts/tmp/_tmp/569b06419b4849b8fee6fc682962eb0e/logTestSpanPooling2842691395
    test_log_scope.go:79: use -show-logs to present logs inline
    tracer_external_test.go:99: 
        	Error Trace:	/home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/2974/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/util/tracing/tracing_test_/tracing_test.runfiles/com_github_cockroachdb_cockroach/pkg/util/tracing/tracer_external_test.go:99
        	Error:      	Should be zero, but was 1
        	Test:       	TestSpanPooling
        	Messages:   	spans allocated per query: [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 2 2 2 2 2 2 2 2 2 2 3 3 3 3]
    panic.go:522: -- test log scope end --
test logs left over in: /artifacts/tmp/_tmp/569b06419b4849b8fee6fc682962eb0e/logTestSpanPooling2842691395
--- FAIL: TestSpanPooling (0.94s)

Parameters: TAGS=bazel,gss

Help

See also: How To Investigate a Go Test Failure (internal)

This test on roachdash | Improve this report!

[andreimatei]

According to my bisecting, this test has been made flaky by #98044, for some reason.
This is the test code.
That patch seems to cause a drop in the reuse rate of spans, as measured by this test. Or, more exactly, the rate of allocating spans (excluding the ones that come from a sync.Pool) while running queries seems to have increased (so it could in theory be some background process that does it).
The test does do a 1PC, fwiw.
@nvanbenschoten , can you think of an explanation, before I dig more?

I can usually repro the failure under stress in 5 min. Before that patch, it doesn't fail in much longer.
I'll slap a GA-Blocker label in case there's something here.

[cockroach-teamcity]

util/tracing.TestSpanPooling failed with artifacts on master @ 0c6ccaf5c6fc8f94bb2a1e6132e44fe9e82bd9ed:

=== RUN   TestSpanPooling
    test_log_scope.go:161: test logs captured to: /artifacts/tmp/_tmp/569b06419b4849b8fee6fc682962eb0e/logTestSpanPooling162499915
    test_log_scope.go:79: use -show-logs to present logs inline
    tracer_external_test.go:99: 
        	Error Trace:	/home/roach/.cache/bazel/_bazel_roach/c5a4e7d36696d9cd970af2045211a7df/sandbox/processwrapper-sandbox/1491/execroot/com_github_cockroachdb_cockroach/bazel-out/k8-fastbuild/bin/pkg/util/tracing/tracing_test_/tracing_test.runfiles/com_github_cockroachdb_cockroach/pkg/util/tracing/tracer_external_test.go:99
        	Error:      	Should be zero, but was 1
        	Test:       	TestSpanPooling
        	Messages:   	spans allocated per query: [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 2 2 2 2 2 2 2 2 3 3 3 3 4]
    panic.go:522: -- test log scope end --
test logs left over in: /artifacts/tmp/_tmp/569b06419b4849b8fee6fc682962eb0e/logTestSpanPooling162499915
--- FAIL: TestSpanPooling (1.01s)

Parameters: TAGS=bazel,gss

Help

See also: How To Investigate a Go Test Failure (internal)

This test on roachdash | Improve this report!

[andreimatei]

Actually removing the GA-Blocker label, since the failure is quite sporadic and, even when the test fails, the average spans per query is still low - so whatever changed is not catastrophic.

[andreimatei]

Seems to have been fixed by #98630