Bug Report: Noisy vtexplain log output

[tycol7]

Overview of the Issue

vtexplain generates many duplicate error messages, which can slow execution.

Reproduction Steps

1. Save an example vschema.json:

{
  "sharded": {
    "sharded": true,
    "vindexes": {
      "hash": {
        "type": "hash"
      }
    },
    "tables": {
      "dap_test2": {
        "column_vindexes": [
          {
            "column": "shard_id",
            "name": "hash"
          }
        ]
      }
    }
  }
}

2. Save an example schema.sql:

CREATE TABLE dap_test2 (
  shard_id bigint not null,
  id bigint,
  id2 bigint,
  primary key(id)
);

3. Execute vtexplain as follows:

vtexplain --planner-version Gen4 --shards 8 --schema-file ./schema.sql --vschema-file ./vschema.json --sql  "SELECT * FROM dap_test2 WHERE (shard_id = 1 and id = 1) OR (shard_id = 2 and id = 2) OR (shard_id = 3 and id = 3)"

4. Observe duplicate error messages in the log output:

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
----------------------------------------------------------------------
SELECT * FROM dap_test2 WHERE (shard_id = 1 and id = 1) OR (shard_id = 2 and id = 2) OR (shard_id = 3 and id = 3)

1 sharded/-20: select * from dap_test2 where shard_id in (1, 2) and (shard_id in (1, 2) or id = 3) and (shard_id = 1 or id = 2 or shard_id = 3) and (shard_id = 1 or id = 2 or id = 3) and (id = 1 or shard_id = 2 or shard_id = 3) and (id = 1 or shard_id = 2 or id = 3) and (id in (1, 2) or shard_id = 3) and id in (1, 2, 3) limit 10001
1 sharded/40-60: select * from dap_test2 where shard_id in (3) and (shard_id in (1, 2) or id = 3) and (shard_id = 1 or id = 2 or shard_id = 3) and (shard_id = 1 or id = 2 or id = 3) and (id = 1 or shard_id = 2 or shard_id = 3) and (id = 1 or shard_id = 2 or id = 3) and (id in (1, 2) or shard_id = 3) and id in (1, 2, 3) limit 10001

----------------------------------------------------------------------

Binary Version

vtgate version Version: 20.0.0-SNAPSHOT (Git revision af1d6d6f47e6aee230d2662dbffcf98c813952af branch 'main') built on Wed Feb 14 17:12:26 PST 2024 by tyler@local using go1.22.0 darwin/amd64

Operating System and Environment details

- macOS 14.3.1 (23D60)
- Darwin 23.3.0
- arm64

Log Fragments

See above.

[tycol7]

This change causes a significant slowdown in vtexplain: #14364

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

[dbussink]

With #15275 & #15279 the tests don't throw a large amount of error logs anymore and they are also 10x faster to run.

This change causes a significant slowdown in vtexplain: #14364

I think this is a red herring or at least some side effect of the bug in #15275 that somehow GRPC connections were made. Since vtexplain is all memory, no network connections are made so I'm not sure how this is related to the problem.

I think we should try again with the above fixes to see if there's still a problem or not.

[tycol7]

Tested on sample data and running fast again. Thank you!