vtexplain: Suppress duplicate vtexplain error messages

[tycol7]

Description

vtexplain can generate many duplicate error messages, which can also slow execution (especially for batch jobs). This PR aims to suppress duplicate messages by outputting unique error messages once and only once.

The two error messages that tend to repeat are:

1. vtexplain_vttablet.go:842] vtexplain: invalid column .column_name, tableColumnMap +map[:map[]], and
2. throttler.go:510] Throttler.retryReadAndApplyThrottlerConfig(): error reading throttler config. Will retry in 10s. Err=node doesn't exist: cells/explainCell/CellInfo.

This is a bug fix, and I think the fix should be backported.

Before

W0129 12:42:18.665555   27941 http.go:57] Beginning in v20, pprof-http will default to `false`; to continue enabling pprof endpoints, please manually set this flag before upgrading.
E0129 12:42:18.717969   27941 vtexplain_vttablet.go:838] vtexplain: invalid column .column_name, tableColumnMap +map[:map[]]
E0129 12:42:18.722407   27941 throttler.go:505] Throttler.retryReadAndApplyThrottlerConfig(): error reading throttler config. Will retry in 10s. Err=node doesn't exist: cells/explainCell/CellInfo
E0129 12:42:18.731644   27941 vtexplain_vttablet.go:838] vtexplain: invalid column .column_name, tableColumnMap +map[:map[]]
E0129 12:42:18.732837   27941 throttler.go:505] Throttler.retryReadAndApplyThrottlerConfig(): error reading throttler config. Will retry in 10s. Err=node doesn't exist: cells/explainCell/CellInfo
E0129 12:42:18.738915   27941 vtexplain_vttablet.go:838] vtexplain: invalid column .column_name, tableColumnMap +map[:map[]]
E0129 12:42:18.739785   27941 throttler.go:505] Throttler.retryReadAndApplyThrottlerConfig(): error reading throttler config. Will retry in 10s. Err=node doesn't exist: cells/explainCell/CellInfo
E0129 12:42:18.746963   27941 vtexplain_vttablet.go:838] vtexplain: invalid column .column_name, tableColumnMap +map[:map[]]
E0129 12:42:18.747931   27941 throttler.go:505] Throttler.retryReadAndApplyThrottlerConfig(): error reading throttler config. Will retry in 10s. Err=node doesn't exist: cells/explainCell/CellInfo
E0129 12:42:18.754793   27941 vtexplain_vttablet.go:838] vtexplain: invalid column .column_name, tableColumnMap +map[:map[]]
E0129 12:42:18.755805   27941 throttler.go:505] Throttler.retryReadAndApplyThrottlerConfig(): error reading throttler config. Will retry in 10s. Err=node doesn't exist: cells/explainCell/CellInfo
E0129 12:42:18.761785   27941 vtexplain_vttablet.go:838] vtexplain: invalid column .column_name, tableColumnMap +map[:map[]]
E0129 12:42:18.762973   27941 throttler.go:505] Throttler.retryReadAndApplyThrottlerConfig(): error reading throttler config. Will retry in 10s. Err=node doesn't exist: cells/explainCell/CellInfo
E0129 12:42:18.772016   27941 vtexplain_vttablet.go:838] vtexplain: invalid column .column_name, tableColumnMap +map[:map[]]
E0129 12:42:18.773177   27941 throttler.go:505] Throttler.retryReadAndApplyThrottlerConfig(): error reading throttler config. Will retry in 10s. Err=node doesn't exist: cells/explainCell/CellInfo
E0129 12:42:18.780159   27941 vtexplain_vttablet.go:838] vtexplain: invalid column .column_name, tableColumnMap +map[:map[]]
E0129 12:42:18.781245   27941 throttler.go:505] Throttler.retryReadAndApplyThrottlerConfig(): error reading throttler config. Will retry in 10s. Err=node doesn't exist: cells/explainCell/CellInfo

After

W0214 17:16:18.066363   32650 http.go:57] Beginning in v20, pprof-http will default to `false`; to continue enabling pprof endpoints, please manually set this flag before upgrading.
E0214 17:16:18.083682   32650 vtexplain_vttablet.go:842] vtexplain: invalid column .column_name, tableColumnMap +map[:map[]]
E0214 17:16:18.090247   32650 throttler.go:510] Throttler.retryReadAndApplyThrottlerConfig(): error reading throttler config. Will retry in 10s. Err=node doesn't exist: cells/explainCell/CellInfo

Related Issue(s)

#15242

Checklist

• "Backport to:" labels have been added if this change should be back-ported to release branches
• If this change is to be back-ported to previous releases, a justification is included in the PR description
• Tests were added or are not required
• Did the new or modified tests pass consistently locally and on CI?
• Documentation was added or is not required

Deployment Notes

N/A

[vitess-bot]

Review Checklist

Hello reviewers! 👋 Please follow this checklist when reviewing this Pull Request.

General

• Ensure that the Pull Request has a descriptive title.
• Ensure there is a link to an issue (except for internal cleanup and flaky test fixes), new features should have an RFC that documents use cases and test cases.

Tests

• Bug fixes should have at least one unit or end-to-end test, enhancement and new features should have a sufficient number of tests.

Documentation

• Apply the release notes (needs details) label if users need to know about this change.
• New features should be documented.
• There should be some code comments as to why things are implemented the way they are.
• There should be a comment at the top of each new or modified test to explain what the test does.

New flags

• Is this flag really necessary?
• Flag names must be clear and intuitive, use dashes (-), and have a clear help text.

If a workflow is added or modified:

• Each item in Jobs should be named in order to mark it as required.
• If the workflow needs to be marked as required, the maintainer team must be notified.

Backward compatibility

• Protobuf changes should be wire-compatible.
• Changes to _vt tables and RPCs need to be backward compatible.
• RPC changes should be compatible with vitess-operator
• If a flag is removed, then it should also be removed from vitess-operator and arewefastyet, if used there.
• vtctl command output order should be stable and awk-able.

[codecov]

Codecov Report

Attention: 114 lines in your changes are missing coverage. Please review.

Comparison is base (696fe0e) 67.41% compared to head (de5cecf) 67.44%.
Report is 10 commits behind head on main.

Files	Patch %	Lines
go/vt/vttablet/tabletmanager/vdiff/stats.go	45.31%	35 Missing ⚠️
go/vt/vttablet/tabletmanager/vdiff/controller.go	0.00%	13 Missing ⚠️
go/vt/vttablet/tabletmanager/vdiff/engine.go	0.00%	11 Missing ⚠️
go/vt/sqlparser/ast_funcs.go	77.27%	10 Missing ⚠️
go/vt/vttablet/tabletmanager/vdiff/table_differ.go	0.00%	10 Missing ⚠️
go/mysql/query.go	43.75%	9 Missing ⚠️
go/vt/vttablet/tabletmanager/vdiff/action.go	50.00%	5 Missing ⚠️
...vt/vttablet/tabletmanager/vdiff/workflow_differ.go	0.00%	5 Missing ⚠️
go/vt/vtexplain/vtexplain_vttablet.go	50.00%	4 Missing ⚠️
go/vt/vtgate/semantics/analyzer.go	96.10%	3 Missing ⚠️
... and 6 more

Additional details and impacted files

@@            Coverage Diff             @@
##             main   #15243      +/-   ##
==========================================
+ Coverage   67.41%   67.44%   +0.02%     
==========================================
  Files        1560     1560              
  Lines      192752   193005     +253     
==========================================
+ Hits       129952   130163     +211     
- Misses      62800    62842      +42     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[dbussink]

Isn't the bigger question here, why do we log this over and over? As in, the logging itself is only a symptom of an underlying problem that we keep doing the same work over and over and that's causing the real slowdown?

Regardless, we should not use global maps to reduce logging here and see if we can remove a lot of the duplicate work we're doing here.

[dbussink]

We should definitely not use a global for this in this way.

[dbussink]

unit_race / Unit Test (Race) (pull_request)

The failure here also shows why it's broken to use a shared global map for this.

[tycol7]

Isn't the bigger question here, why do we log this over and over? As in, the logging itself is only a symptom of an underlying problem that we keep doing the same work over and over and that's causing the real slowdown?

Yes, I'm looking into why we're doing the same work repeatedly in a separate issue. But removing the log lines alone reduces the run time of vtexplain by over 80% in trials, so applying a patch in the meantime while we investigate the root cause.

Regardless, we should not use global maps to reduce logging here and see if we can remove a lot of the duplicate work we're doing here.

I can look into another way to reduce logging - thanks for the tip!

[tycol7]

Going after the root cause instead.

[tycol7]

FWIW, it appears the gRPC version bump from 1.55.0 → 1.59.0 causes a vtexplain slowdown across Vitess versions.

This change introduces the repeated vtexplain_vttablet.go:778] vtexplain: invalid column .column_name, tableColumnMap +map[:map[]] log lines: #13312