sql: OOM during TPCC with schema changes

[ajwerner]

Describe the problem

This is meta issue to clearly phrase observations from debugging #69100 and #69086. In both of those we see OOMs. We've tracked this down to a change in prepared statement handling due to #68608. We observe that pgx is issuing lots of DEALLOCATE commands, presumably because of something involving its LRU. However, I did try increasing the LRU size to no avail.

https://github.com/jackc/pgconn/blob/53f5fed36c570f0b5c98d6ec2415658c7b9bd11c/stmtcache/lru.go#L118

The issue is not about the DEALLOCATE or cache misses but rather about the OOM that seems to come with it.

To Reproduce

Run schemachange/index/tpcc/w=1000 at 7c36a9d and it seems to happen every time.

Additional data / screenshots

One observation is that we have a lot of allocations in the optimizer and the in numeric constants. These numeric constants hold on to strings which are backed by the pgwire buffer reader. That might be part of the problem and might point to why we don't see the data in the heap profile. However, there's still the question of why we're holding on to all of these. Maybe it's related to the statements metrics.

Another point of confusion is the extent to which the schema changes are actually relevant here. Is it the straw that breaks the camels back?

Jira issue: CRDB-9542

[rafiss]

Note to all working on this: now that #69313 has been merged, the test no longer OOMs, but the underlying issue still exists. We should continue our effort to understand the OOMs better. To reproduce the OOMs, apply this diff:

diff --git a/pkg/workload/pgx_helpers.go b/pkg/workload/pgx_helpers.go
index 356da23a61..5a7a517abf 100644
--- a/pkg/workload/pgx_helpers.go
+++ b/pkg/workload/pgx_helpers.go
@@ -61,9 +61,6 @@ func NewMultiConnPool(
         connsPerPool := distributeMax(connsPerURL[i], maxConnsPerPool)
         for _, numConns := range connsPerPool {
             connCfg, err := pgxpool.ParseConfig(urls[i])
-            // Disable the automatic prepared statement cache. We've seen a lot of
-            // churn in this cache since workloads create many of different queries.
-            connCfg.ConnConfig.BuildStatementCache = nil
             if err != nil {
                 return nil, err
             }

I tried out #69375 to see if storing stats for all the DEALLOCATE statements separately was the problem, but that PR still resulted in an OOM.

Next theory: perhaps the issue is with the prepared statement cache having a memory leak. @ajwerner observes that:

That’d be bad but worth looking into. It would align with the profiles. In fact, it might align better. Notice that a ton of memory is in these numeric constants which are all holding references to strings which are all part of a buffer that’s at least 4k. So, we know that each prepared statement with a numeric constant is holding on to at least 4k.

[rafiss]

I believe there is some sort of issue with dangling references to the prepared statements. I added this diff on top of the one that allows the pgx stmt cache:

diff --git a/pkg/sql/prepared_stmt.go b/pkg/sql/prepared_stmt.go
index 07ac0665f8..9dfef076e4 100644
--- a/pkg/sql/prepared_stmt.go
+++ b/pkg/sql/prepared_stmt.go
@@ -85,6 +85,7 @@ func (p *PreparedStatement) decRef(ctx context.Context) {
                log.Fatal(ctx, "corrupt PreparedStatement refcount")
        }
        p.refCount--
+       log.Warningf(ctx, "decRef: refCount=%d stmt=%s", p.refCount, p.PrepareMetadata.Statement)
        if p.refCount == 0 {
                p.memAcc.Close(ctx)
        }

Then ran schemachange/index/tpcc/w=1000 and noticed this:

ubuntu@rafi-1629927880-01-n5cpu16-0004:~/logs$ grep 'refCount=0' *log | wc
      7     297    3421

ubuntu@rafi-1629927880-01-n5cpu16-0004:~/logs$ grep 'refCount=1' *log | wc
grep: cockroach.rafi-1629927880-01-n5cpu16-0004.ubuntu.2021-08-26T03_21_43Z.011088.log: No such file or directory
 113377 4918900 55051570

[RaduBerinde]

We store portals in a map by value: portals map[string]PreparedPortal and yet we're doing some kind of refcounting on them. Looks like these were pointers and they were changed to values in #48842

[yuzefovich]

I'm currently looking into this.

I tried switching portals map[string]PreparedPortal to portals map[string]*PreparedPortal, and it didn't help, so I would guess that the switch from pointers to values in #48842 isn't to blame.

[RaduBerinde]

Yeah, we looked at it more and that doesn't explain it. I also noticed that we're not clearing prepStmtsNamespaceAtTxnRewindPos when we reset the txn state, which means we may keep around a snapshot of the namespace indefinitely. But that wouldn't explain accumulation of prepared statements either.

[yuzefovich]

I did find something suspicious, here is the comment on preparedStatementsAccessor.Delete:

	// Delete removes the PreparedStatement with the provided name from the
	// collection. If a portal exists for that statement, it is also removed.
	// The method returns true if statement with that name was found and removed,
	// false otherwise.
	Delete(ctx context.Context, name string) bool

Note that we currently don't actually delete any portals created for the prepared statement. The postgres docs aren't clear whether we should be deleting the portals or not, and I haven't looked into the source code yet.

I also think it's possible that the switch to values instead of pointers introduced a bug. In prepStmtNamespace.resetTo we have this code snippet:

	for name, p := range to.portals {
		p.incRef(ctx)
		ns.portals[name] = p
	}

We're taking PreparedPortal, incrementing the reference on it, and then setting it into the space being reset. However, I think the "to" space still contains the original unincremented refcount.

[yuzefovich]

FWIW on the binary with the fixes to both of the problems I mentioned above the schemachange roachtest has successfully gotten past the point of completing all 3 schema changes queries. (I did pollute the binary with logging, but hoping that didn't matter.)

[rafiss]

Note that we currently don't actually delete any portals created for the prepared statement.

Portals that are created outside of a transaction are supposed to automatically be destroyed after they are executed. Portals created in a transaction are supposed to automatically be destroyed at the end of the transaction.

See f612484. one thing I don't see though is that resetExtraTxnState is not called in the txnCommit case -- I only see it happening for txnRestart or txnAborted (despite the comments on resetExtraTxnState saying that it's called when a transaction "commits, rolls back or restarts.")

[RaduBerinde]

I only see it happening for txnRestart or txnAborted

There's a fallthrough above that code.

2624     fallthrough
2625   case txnRestart, txnRollback:
2626     if err := ex.resetExtraTxnState(ex.Ctx(), advInfo.txnEvent); err != nil {
2627       return advanceInfo{}, err
2628     }
2629   default:

[RaduBerinde]

@yuzefovich definitely having the refcounts on values is a problem, but it seems to me like it can only result in "premature" final decRef, and not in the "missing" decRef. In any case, calling or not calling decRef shouldn't affect whether the prepared statement stays alive in memory. I hope your change does fix it, but I'd be curious to find out how exactly.

[yuzefovich]

Tough luck - most runs with the fixes to both possible issues outlines above still failed. I also included the deletion of portals from prepStmtsNamespaceAtTxnRewindPos into resetExtraTxnState, and I still see failures.

[yuzefovich]

Removing the release-blocker label since this is not a regression AFAICT.

[yuzefovich]

I think I was too quick to say that #69479 - I'm now seeing the same failures on schemachange roachtest w/ (with different versions) and w/o that PR, so putting back into the triage box.

[github-actions]

We have marked this issue as stale because it has been inactive for
18 months. If this issue is still relevant, removing the stale label
or adding a comment will keep it active. Otherwise, we'll close it in
10 days to keep the issue queue tidy. Thank you for your contribution
to CockroachDB!