Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

sql: improve stack trace for get-user-timeout timeouts #95794

Closed
ecwall opened this issue Jan 24, 2023 · 0 comments · Fixed by #95797 or #96659
Closed

sql: improve stack trace for get-user-timeout timeouts #95794

ecwall opened this issue Jan 24, 2023 · 0 comments · Fixed by #95797 or #96659
Assignees
@ecwall
Labels
C-enhancement Solution expected to add code/behavior + preserve backward-compat (pg compat issues are exception) T-sql-foundations SQL Foundations Team (formerly SQL Schema + SQL Sessions)

Comments

@ecwall
Copy link
Contributor

ecwall commented Jan 24, 2023 •
edited
Loading

The cause of the get-user-timeout errors is unknown. Part of the problem is that the stack trace gets cut off at

  |   | github.com/cockroachdb/cockroach/pkg/sql.retrieveSessionInitInfoWithCache
  |   | 	github.com/cockroachdb/cockroach/pkg/sql/user.go:238

which does not explain what is actually being blocked.

The reason that the stack trace is cut off is that the timeout is initiated by contextutil.RunWithTimeout which results in a "simple" (no stack trace) context.DeadlineExceeded error.

retrieveSessionInitInfoWithCache is the first line in the stack trace because it calls errors.Wrap on the error from context.DeadlineExceeded.

To get fuller stack trace, context.DeadlineExceeded must be wrapped immediately (errors.Wrap or errors.WithStack) before it bubbles up.

This is to diagnose the get-user-timeout errors here where the stack trace is cut off before the place we call errors.Wrap(...): https://github.com/cockroachlabs/support/issues/2017#issuecomment-1402418577

Jira issue: CRDB-23745
@ecwall ecwall added C-enhancement Solution expected to add code/behavior + preserve backward-compat (pg compat issues are exception) T-sql-foundations SQL Foundations Team (formerly SQL Schema + SQL Sessions) labels Jan 24, 2023
@ecwall ecwall self-assigned this Jan 24, 2023
@ecwall ecwall mentioned this issue Jan 24, 2023
Merged
craig bot pushed a commit that referenced this issue Jan 25, 2023
@ecwall @maryliag @jbowens
Merge #95013 #95797 #95830 #95852 #95863
4858095 
95013: sql: add ability set, edit, read tenant capabilities r=knz a=ecwall

Fixes #87851

Add new SQL syntax for
1) Setting tenant capabilities:
`ALTER TENANT t GRANT CAPABILITY capabilitiy_name=capability_value;`
2) Resetting tenant capabilities:
`ALTER TENANT t REVOKE CAPABILITIY capability_name;`
3) Reading tenant capabilities:
`SHOW TENANT t WITH CAPABILITIES;`

Release note: None

95797: sql: improve stack trace for get-user-timeout timeouts r=knz a=ecwall

Fixes #95794

The cause of the `get-user-timeout` errors is unknown. Part of the problem is that the stack trace gets cut off at
```
  |   | github.com/cockroachdb/cockroach/pkg/sql.retrieveSessionInitInfoWithCache
  |   | 	github.com/cockroachdb/cockroach/pkg/sql/user.go:238
```
which does not explain what is actually being blocked.

The reason that the stack trace is cut off is that the timeout is initiated by `contextutil.RunWithTimeout` which results in a "simple" (no stack trace) `context.DeadlineExceeded` error.

`retrieveSessionInitInfoWithCache` is the first line in the stack trace because it calls `errors.Wrap` on `context.DeadlineExceeded`.

To get a fuller stack trace, `context.DeadlineExceeded` must be wrapped immediately (`errors.Wrap` or `errors.WithStack`) before it bubbles up.

Release note: None

95830: validate: use immutable descriptors only r=postamar a=postamar

The descriptor validation logic will accept any implementation of catalog.Descriptor be it mutable or immutable, it doesn't care. However, using mutable implementations can have a significant performance impact especially in the case of tables, where every column or index or constraint lookup will lead to the cache being regenerated for the whole descriptor.

This commit fixes this by having validate.Validate replace any mutable descriptor instances it encounters with immutable copies. This doesn't change anything except performance.

Fixes #95827.

Release note: None

95852: ui: cache sqlroles results r=maryliag a=maryliag

Previously, the call to get sql roles was constantly being requested. This commits adds a cache limit, so it will only get request after the expiration time.

https://www.loom.com/share/6814309f91234fa2b17490df8160bde6

Epic: None
Release note: None

95863: storage: reorder EventListeners r=jbowens a=jbowens

To be defensive, sequence the EventListener responsible for crashing the process during a disk stall first, before the Pebble logging event listener.

Informs #94373.
Epic: None
Release note: None

Co-authored-by: Evan Wall <[email protected]>
Co-authored-by: Marius Posta <[email protected]>
Co-authored-by: maryliag <[email protected]>
Co-authored-by: Jackson Owens <[email protected]>
@craig craig bot closed this as completed in 662e19c Jan 26, 2023
blathers-crl bot pushed a commit that referenced this issue Jan 26, 2023
@ecwall
sql: improve stack trace for get-user-timeout timeouts
60e3926 
Fixes #95794

The cause of the `get-user-timeout errors` is unknown.
Part of the problem is that the stack trace gets cut off at
```
  |   | github.com/cockroachdb/cockroach/pkg/sql.retrieveSessionInitInfoWithCache
  |   | 	github.com/cockroachdb/cockroach/pkg/sql/user.go:238
```
which does not explain what is actually being blocked.

The reason that the stack trace is cut off is that the timeout is initiated by
`contextutil.RunWithTimeout` which results in a "simple" (no stack trace)
`context.DeadlineExceeded` error.

`retrieveSessionInitInfoWithCache` is the first line in the stack trace because
it calls `errors.Wrap` on `context.DeadlineExceeded`.

To get a fuller stack trace, `context.DeadlineExceeded` must be wrapped
immediately (`errors.Wrap` or `errors.WithStack`) before it bubbles up.

Release note: None
This was referenced Jan 26, 2023
Merged
Merged
blathers-crl bot pushed a commit that referenced this issue Jan 26, 2023
@ecwall
sql: improve stack trace for get-user-timeout timeouts
f366520 
Fixes #95794

The cause of the `get-user-timeout errors` is unknown.
Part of the problem is that the stack trace gets cut off at
```
  |   | github.com/cockroachdb/cockroach/pkg/sql.retrieveSessionInitInfoWithCache
  |   | 	github.com/cockroachdb/cockroach/pkg/sql/user.go:238
```
which does not explain what is actually being blocked.

The reason that the stack trace is cut off is that the timeout is initiated by
`contextutil.RunWithTimeout` which results in a "simple" (no stack trace)
`context.DeadlineExceeded` error.

`retrieveSessionInitInfoWithCache` is the first line in the stack trace because
it calls `errors.Wrap` on `context.DeadlineExceeded`.

To get a fuller stack trace, `context.DeadlineExceeded` must be wrapped
immediately (`errors.Wrap` or `errors.WithStack`) before it bubbles up.

Release note: None
nathanstilwell pushed a commit that referenced this issue Feb 2, 2023
@ecwall
sql: improve stack trace for get-user-timeout timeouts
06ba962 
Fixes #95794

The cause of the `get-user-timeout errors` is unknown.
Part of the problem is that the stack trace gets cut off at
```
  |   | github.com/cockroachdb/cockroach/pkg/sql.retrieveSessionInitInfoWithCache
  |   | 	github.com/cockroachdb/cockroach/pkg/sql/user.go:238
```
which does not explain what is actually being blocked.

The reason that the stack trace is cut off is that the timeout is initiated by
`contextutil.RunWithTimeout` which results in a "simple" (no stack trace)
`context.DeadlineExceeded` error.

`retrieveSessionInitInfoWithCache` is the first line in the stack trace because
it calls `errors.Wrap` on `context.DeadlineExceeded`.

To get a fuller stack trace, `context.DeadlineExceeded` must be wrapped
immediately (`errors.Wrap` or `errors.WithStack`) before it bubbles up.

Release note: None
@ecwall ecwall mentioned this issue Feb 6, 2023
Closed
@rafiss rafiss mentioned this issue Feb 6, 2023
Merged
@ecwall ecwall mentioned this issue Feb 6, 2023
Merged
craig bot pushed a commit that referenced this issue Feb 6, 2023
@rafiss @abarganier
Merge #96504 #96516
0723521 
96504: Revert "sql: improve stack trace for get-user-timeout timeouts" r=ecwall a=rafiss

This reverts commit 662e19c.

gRPC does not expect the context to be wrapped, so it can get confused.

informs #95794
Release note: None

96516: pkg/util/metric: fix HistogramMode for streamingingest histograms r=dhartunian a=abarganier

Ref: #96514

The above patch migrated all histogram constructors over to
use a generic constructor, which has the ability to specify
a HistogramMode. While preparing a backport of this patch,
I noticed that the following streamingest histograms were
incorrectly tagged with a HistogramMode of
HistogramModePreferHdrLatency:

1. FlushHistNanos
2. CommitLatency
3. AdmitLatency

If you look at the original migration, when HDR was still being
used, these histograms were *not* using the HDR latency defaults:

a82aa82#diff-1bc5bdba63149e8efeadce17e7eb62bb5cd1dcee22974b37881a627e13c0501dL137-L143

This patch fixes these histograms to no longer incorrectly specify
the HistogramModePreferHdrLatency mode in the histogram options.

This was also fixed in the backport PR #96514.

Release note: none

Part of #95833

Co-authored-by: Rafi Shamim <[email protected]>
Co-authored-by: Alex Barganier <[email protected]>
@blathers-crl blathers-crl bot mentioned this issue Feb 6, 2023
Closed
craig bot pushed a commit that referenced this issue Feb 8, 2023
@jayshrivastava @tbg
@ecwall @RaduBerinde
Merge #89752 #94633 #96650 #96659 #96770 #96793
844a370 
89752: jobs/cdc: add metrics for paused jobs  r=miretskiy a=jayshrivastava

 This change adds new metrics to count paused jobs for every job type. For
  example, the metric for paused changefeed jobs is
  `jobs.changefeed.currently_paused`. These metrics are counted at an
  interval defined by the cluster setting `jobs.metrics.interval.poll`.
  
  This is implemented by a job which periodically queries `system.jobs`
  to count the number of paused jobs. This job is of the newly added type
  `jobspb.TypePollJobsStats`. When a node starts it's job registry, it will
  create an adoptable stats polling job if it does not exist already using a
  transaction.
  
  This change adds a test which pauses and resumes changefeeds while asserting
  the value of the `jobs.changefeed.currently_paused` metric. It also adds a
  logictest to ensure one instance of the stats polling job is created in a
  cluster.
  
  Resolves: #85467
  
  Release note (general change): This change adds new metrics to count
  paused jobs for every job type. For example, the metric for paused
  changefeed jobs is `jobs.changefeed.currently_paused`. These metrics
  are updated at an interval defined by the cluster setting
  `jobs.metrics.interval.poll`, which is defauled to 10 seconds.
  
  Epic: None


94633: kvserver: document reproposals r=nvanbenschoten a=tbg

Reproposals are a deep rabbit hole and an area in which past changes
were all related to subtle bugs. Write it all up and in particular make
some simplifications that ought to be possible if my understanding is
correct:

- have proposals always enter `(*Replica).propose` without a
  MaxLeaseIndex or prior encoded command set, i.e. `propose`
  behaves the same for reproposals as for first proposals.
- assert that after a failed call to tryReproposeWithNewLeaseIndex,
  the command is not in the proposals map, i.e. check absence of
  a leak.
- replace code that should be impossible to reach (and had me confused
  for a good amount of time) with an assertion.
- add long comment on `r.mu.proposals`.

This commit also moves `tryReproposeWithNewLeaseIndex` off `(*Replica)`,
which is possible due to recent changes[^1]. In doing so, I realized
there was a (small) data race (now fixed): when returning a
`NotLeaseholderError` from that method, we weren't acquiring `r.mu`. It
may have looked as though we were holding it already since we're
accessing `r.mu.propBuf`, however that field has special semantics - it
wraps `r.mu` and acquires it when needed.

[^1]: The "below raft" test mentioned in the previous comment was
changed in #93785 and
no longer causes a false positive.

Epic: CRDB-220
Release note: None


96650: kvserver: extract kvstorage.DestroyReplica r=pavelkalinnikov a=tbg

This series of commits extracts `(*Replica).preDestroyRaftMuLocked` into a
free-standing method `kvstorage.DestroyReplica`.

In doing so, it separates the in-memory and on-disk steps that are a part
of replica removal, and makes the on-disk steps unit testable.

Touches #93241.

Epic: CRDB-220
Release note: None


96659: sql: wrap stacktraceless errors with errors.Wrap r=andreimatei a=ecwall

Fixes #95794

This replaces the previous attempt to add logging here #95797.

The context itself cannot be augmented to add a stack trace to errors because
it interferes with grpc timeout logic - gRPC compares errors directly without
checking causes https://github.com/grpc/grpc-go/blob/v1.46.0/rpc_util.go#L833.
Although the method signature allows it, `Context.Err()` should not be
overriden to customize the error:
```
// If Done is not yet closed, Err returns nil.
// If Done is closed, Err returns a non-nil error explaining why:
// Canceled if the context was canceled
// or DeadlineExceeded if the context's deadline passed.
// After Err returns a non-nil error, successive calls to Err return the same error.
Err() error
```
Additionally, a child context of the augmented context may end up being used
which will circumvent the stack trace capture.

This change instead wraps `errors.Wrap` in a few places that might end up
helping debug the original problem:
1) Where we call `Context.Err()` directly.
2) Where gRPC returns an error after possibly calling `Context.Err()`
   internally or returns an error that does not have a stack trace.

Release note: None

96770: storage: don't modify the given cfg.Opts r=RaduBerinde a=RaduBerinde

This change improves the `NewPebble` code to not modify the given `cfg.Opts`. Such behavior is surprising and can trip up tests that reuse the same config.

Also, `ResolveEncryptedEnvOptions` and `wrapFilesystemMiddleware` no longer modify the `Options` directly; and `CheckNoRegistryFile` is now a standalone function.

Release note: None
Epic: none

96793: kvserver: de-flake TestReplicaProbeRequest r=pavelkalinnikov a=tbg

Chanced upon this failure mode in unrelated PR #96781.

Epic: none
Release note: None


Co-authored-by: Jayant Shrivastava <[email protected]>
Co-authored-by: Tobias Grieger <[email protected]>
Co-authored-by: Evan Wall <[email protected]>
Co-authored-by: Radu Berinde <[email protected]>
This was referenced Feb 8, 2023
Merged
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@ecwall ecwall

Labels
C-enhancement Solution expected to add code/behavior + preserve backward-compat (pg compat issues are exception) T-sql-foundations SQL Foundations Team (formerly SQL Schema + SQL Sessions)
Projects
None yet
Milestone
No milestone
1 participant
@ecwall