[Performance]: retire Span recording to eliminate IsMOCtledSpan contention

[LeftHandCold]

Summary

MO no longer consumes internal Span records, but the old request path still entered the Span implementation and queried a global controlled-span map protected by a mutex. This issue tracks retiring that unused recording path while preserving the observability data that MO still depends on.

Correction to the original profile conclusion

The flame graphs and the summary image do not prove that "trace consumes 60% CPU" or that trace is the main performance bottleneck.

The reported sync.Mutex.Unlock / IsMOCtledSpan percentages are attribution within a mutex blocking-delay profile. They mean that this lock accounted for a large share of sampled waiting time in those captures; they are not CPU percentages and cannot be added to frontend percentages as total CPU usage.

The supported conclusion is narrower: IsMOCtledSpan was a real, avoidable concurrency hotspot in the tested high-concurrency point-select/read-only/insert workloads. Removing it should reduce contention, but SQL execution, storage reads, compilation/planning, transaction work, syscalls, and GC remain the main workload-dependent costs.

Final decision

Retire the Span recording implementation, not the whole trace/observability subsystem.

Removed by PR #25841:

• MOTracer, MOSpan, MOHungSpan
• Span batch processor/exporter and Span-only buffering
• controlled-span global maps/mutex
• Span-triggered timers and profile capture
• Span-specific tests
• runtime ability to re-enable Span through configuration

Preserved:

• StatementInfo, statement status/error information, and CU accounting
• structured/raw log export
• error export
• SpanContext, context helpers, and RPC wire layout
• trace/span ID fields in retained log/error records
• existing span_info schema/view for upgrade compatibility
• shared collector lifecycle and graceful flush

StatementInfo does not depend on a recorded MOSpan; it has its own statement, transaction, session, status, error, and CU fields. Therefore it is preserved directly rather than filled with artificial Span values.

Compatibility

• Code default remains disable-span=true.
• Explicit disable-span=false is still accepted but cannot re-enable the retired implementation.
• enable-span-profile, long-span-time, and enable-trace-debug remain accepted compatibility no-ops.
• CN/TN TraceSpan control calls return span tracing is no longer supported.
• No new span_info rows are created.
• No schema migration is required; rollback is a binary rollback.

Evidence

Controlled ABBA test on the same machine/configuration/data/workload:

• 128 concurrent clients, 10 measured iterations per side
• baseline: 79,393 QPS
• Span-disabled candidate: 81,463 QPS
• delta: +2.61%
• baseline IsMOCtledSpan mutex-delay attribution: 43.77% / 40.58%
• candidate exact focus: no samples

This verifies a positive effect for the tested workload, but does not claim a universal 2.61% improvement or identify Span as the main CPU bottleneck.

Final implementation validation on machine 10.222.1.50, commit 62c1c608ba, using an explicit disable-span=false configuration:

• Statement, raw-log, and error records continued to increase.
• Successful and failed marker statements retained status, error code, and CU.
• The injected SQL error appeared in system.error_info.
• span_info stayed unchanged at 3 -> 3.
• TraceSpan control calls returned the retired-feature response.
• A 1,000,000-query, concurrency-128 run completed successfully.
• Mutex profile exact focus found no IsMOCtledSpan, MOTracer, MOSpan, or MOHungSpan samples.
• Graceful shutdown flushed retained telemetry successfully.

Full implementation and three validation rounds: #25839 (comment)

[LeftHandCold]

Implementation PR: #25841

Before/after mutex-profile evidence

The following comparison corresponds to the same before/after profile screenshots used during validation.

Before: baseline code, Span enabled by default

The baseline screenshot has 133.35s (100%) total sampled mutex delay and visibly contains the full hot stack:

frontend.(*Routine).handleRequest
  -> trace.Start
    -> motrace.(*MOTracer).Start
      -> trace.IsMOCtledSpan
        -> sync.(*Mutex).Unlock

The same screenshot also contains the Span-end side of the lock through End -> NeedRecord -> IsMOCtledSpan -> Unlock, plus repeated callers from compile, transaction creation, execution, and commit paths.

Exact focus results from two independent baseline runs:

Baseline run	IsMOCtledSpan mutex delay	Share of total mutex delay
1	61.412s	43.77%
2	54.117s	40.58%

After: PR code, no disable-span setting

The candidate screenshot has 88.15s (100%) total sampled mutex delay. It still contains valid non-trace mutex samples such as transaction open/commit/close and connection/authentication locks, proving that mutex profiling was active.

However, all of the following are absent from the sampled hot path:

trace.Start
motrace.(*MOTracer).Start
trace.IsMOCtledSpan
MOSpan.End -> NeedRecord -> IsMOCtledSpan

Most importantly, an exact pprof focus on IsMOCtledSpan returned no samples in both independent candidate runs:

Candidate run	Profile total	Exact IsMOCtledSpan focus
1	88.12s	no samples
2	88.15s	no samples

This is the central acceptance result: the IsMOCtledSpan mutex-delay stack present before the change is gone after the change, while the profiler still records other locks.

The profile total is cumulative mutex delay, not CPU time or wall time. The decrease from the baseline profile must therefore not be described as a matching CPU or throughput percentage.

Raw profiles retained on the validation host:

• /tmp/mo-ab-old-6b1ad0c32b-mutex.pb.gz
• /tmp/mo-ab-old-6b1ad0c32b-pass2-mutex.pb.gz
• /tmp/mo-ab-new-966cba0de4-mutex.pb.gz
• /tmp/mo-ab-new-966cba0de4-pass2-mutex.pb.gz

Repeated throughput result with profiling disabled

Both binaries used the same host, same toolchain, byte-identical configuration, same source-data clone, the same primary-key point select, concurrency 128, and 200,000 warmup queries after each restart. The run order was old -> new -> new -> old, with five 1,000,000-query measurements in every block.

Order block	Baseline mean	PR mean	Time reduction
old -> new	12.515s	12.275s	1.92%
new -> old	12.676s	12.276s	3.16%
combined	12.5955s	12.2755s	2.54%

Derived mean throughput: approximately 79,393 -> 81,463 QPS, or +2.61%. Both order blocks were positive, but individual ranges overlap, so this is a controlled point-select result rather than a universal performance claim.

Required observability remains enabled

After successful and expected-failure marker SQL plus exporter flush on the candidate binary:

• system.statement_info: 10619 -> 10922; both successful and failed marker SQL were present;
• system.rawlog: 18643 -> 18709;
• system.error_info: 17 -> 18; expected error 20303 was present;
• system.span_info: 3 -> 3; no new Span was written (the existing rows came from a separate explicit opt-in run).

Therefore the PR removes the default Span hot path without disabling StatementInfo, logs, or errors. It does not delete the trace/motrace module and does not change schema, wire format, or the Span implementation.

[LeftHandCold]

[LeftHandCold]

Final Span retirement implementation and validation

This comment supersedes the earlier implementation note that described the intermediate "disabled by default but still opt-in" version. The final PR #25841 physically retires the Span recording runtime while retaining StatementInfo, logs, errors, CU, compatibility types, RPC layout, and schema.

What changed

• Deleted MOTracer, MOSpan, MOHungSpan, Span batch processing/export, Span timers/profile hooks, and the controlled-span maps/mutex.
• The tracer provider now always returns a no-op tracer. An explicit disable-span=false cannot reactivate Span.
• TraceSpan control calls return span tracing is no longer supported.
• Kept legacy configuration fields as compatibility no-ops.
• Kept the public trace API, SpanContext, context propagation, RPC encoding, and span_info schema/view.
• Kept exactly the retained telemetry exporters: MOZapLog, StatementInfo, and MOErrorHolder.
• Moved shared collector stop/flush ownership from the deleted Span processor into provider shutdown.

Validation round 1: local

Rebased final commit 62c1c608ba on current main 441697fc2a.

Passed:

• trace package race tests
• affected/dependent focused tests
• CGo-aware vet
• full make build
• diff check
• lifecycle, ownership, shutdown, cancellation, and compatibility self-review

The built binary contains no executable symbols for MOTracer, MOSpan, or MOHungSpan.

Validation round 2: machine 50 functional retention

Built and ran the final commit on 10.222.1.50 with configuration explicitly setting disable-span=false (the strongest check that the retired path cannot be re-enabled).

Observed before/after counters:

• statement_info: 11750 -> 12127
• rawlog: 21278 -> 21384
• error_info: 19 -> 20
• span_info: 3 -> 3

Verified records:

• a successful marker statement retained success status and CU
• a deliberately failed statement retained error code 20303 and CU
• the corresponding missing-table error appeared in system.error_info
• CN and TN TraceSpan commands returned span tracing is no longer supported
• graceful shutdown handled the final statement buffer and logged trace.shutdown.complete

Validation round 3: workload and mutex profile

A second clean run on machine 50 executed 1,000,000 point selects with concurrency 128 in 10.565 seconds.

After the run:

• statement/log/error collection remained active
• span_info was still 3 -> 3
• the mutex profile contained other normal mutex samples
• exact focus on IsMOCtledSpan: no samples / 0%
• exact focus on MOTracer|MOSpan|MOHungSpan: no samples / 0%
• graceful shutdown again flushed retained telemetry

This directly confirms what the before/after screenshots show: the old trace.Start -> MOTracer.Start -> IsMOCtledSpan -> sync.Mutex branch is absent after the change. Screenshot comparison: #25839 (comment)

Performance interpretation

The earlier controlled ABBA result remains the performance evidence for removing the active path: 79,393 -> 81,463 QPS (+2.61%) under that test. The profile percentages are mutex waiting-delay attribution, not CPU percentages. Physical deletion is primarily code/risk cleanup after making Span permanently inactive; no extra performance improvement beyond the disabled behavior is claimed.

[LeftHandCold]

Follow-up review closure: preserve non-recording correlation

The second full PR review found one valid P1 compatibility gap after Span recording was removed: trace.Generate had become a pure no-op, so frontend connection contexts no longer received per-request TraceID/SpanID values. That would preserve log/error rows but lose their request correlation and MORPC propagation identity.

Fixed in PR head 7748b5706e without restoring Span recording:

• fully disabled tracing still uses the zero-allocation NoopTracer;
• enabled observability uses a lightweight NonRecordingTracer that only generates and propagates root/child IDs;
• no Span records, profiles, queues, exporters, controlled-span maps, or trace locks were restored;
• frontend routine, log row, error row, and MORPC propagation tests now cover the retained correlation contract;
• independent roots, disabled behavior, and ordinary no-op behavior are covered explicitly.

This follows the earlier review fix that extracted the former 1-minute metric-query and 30-minute frontend-cleanup deadlines from WithHungThreshold into explicit business contexts.

Fresh validation on main@2d01285f8b: affected normal tests, trace/metric/frontend/MORPC race tests, CGo-aware vet, full build, diff check, binary-symbol audit, and lifecycle/unhappy-path review all passed. The latest GitHub CI has no failures at the time of this update; long-running UT/Coverage/BVT jobs and renewed reviewer approval are pending.

Detailed reviewer response: #25841 (comment)

[LeftHandCold]

Follow-up: PR BVT regression diagnosed and fixed

The zz_statement_query_type/query_stmt.sql failure on PR #25841 was caused by the PR's first non-recording implementation, not by an unrelated main change.

The removed controlled-span check had also encoded default-off behavior for four diagnostic kinds. Without that check, a LocalFS/RemoteFS/TN-RPC start could overwrite the parent span_kind, and raw-log export persisted the diagnostic kind verbatim. The BVT then returned 0 because those values are outside its compatibility allowlist.

Commit 6dc3383ce0 keeps exactly the four retired controlled kinds default-off using a static filter, without restoring the old mutex/map/exporter path or broadening the BVT expectation. A regression test covers the full LocalFS start -> log report -> raw-log row path and verifies that the parent internal kind is retained.

Local focused, normal, race, vet, build, diff, and lifecycle checks passed. Fresh CI, including the same Coverage BVT, is running: https://github.com/matrixorigin/matrixone/actions/runs/29671757688