MemoryContextStats doesn't deduct memory gp_freed from currently_allocated

[soumyadeep2007]

Bug Report

Greenplum version or build

OS version and uname -a

autoconf options used ( config.status --config )

Installation information ( pg_config )

Expected behavior

MemoryContextStats should deduct gp_freed memory from the currentlyAllocated output field here:
write_stderr("context: occurrences_count, currently_allocated, currently_available, total_allocated, total_freed, name\n");

Actual behavior

// Even though the memory is freed from the SRF and ExprContext below

2022-11-21 14:33:41.284965 PST,"pivotal","postgres",p4114148,th-136174592,"192.168.0.148","48140",2022-11-21 14:33:25 PST,0,con8,cmd1,seg1,,,,sx1,"LOG","00000","context->name: SRF multi-call context: gp_freed 97054264 bytes",,,,,,"select pg_catalog.gp_acquire_sample_rows(114693, 1000000, 'f');",0,,"aset.c"   ------ 90M
1    0x564d28193398 postgres errstart + 0x473
2    0x564d281d8319 postgres <symbol not found> + 0x281d8319
3    0x564d281dbfa6 postgres MemoryContextDeleteImpl + 0x110
4    0x564d281a525f postgres <symbol not found> + 0x281a525f
5    0x564d281a5209 postgres end_MultiFuncCall + 0x53
6    0x564d27d733ff postgres gp_acquire_sample_rows + 0xafe

2022-11-21 14:33:41.358444 PST,"pivotal","postgres",p4114148,th-136174592,"192.168.0.148","48140",2022-11-21 14:33:25 PST,0,con8,cmd1,seg1,,,,sx1,"LOG","00000","context->name: ExprContext: gp_freed 301981696 bytes",,,,,,"select pg_catalog.gp_acquire_sample_rows(114693, 1000000, 'f');",0,,"aset.c",1121 ---------- 300M
1    0x564d28193398 postgres errstart + 0x473
2    0x564d281d8319 postgres <symbol not found> + 0x281d8319
3    0x564d281dbfa6 postgres MemoryContextDeleteImpl + 0x110
4    0x564d27da3f41 postgres FreeExprContext + 0x4a
5    0x564d27da3c24 postgres FreeExecutorState + 0x35

// We still report the memory as "currently_allocated" in parent contexts `TopMemoryContext` and `TopMemoryContext/PortalMemory`
MemoryContextStats after last call to gp_acquire_sample_rows::
TopMemoryContext.currently_allocated = 1598774744
	PortalMemory.currently_allocated = 1596696800
		PortalMemory/PortalHeapMemory/ExecutorState.currently_allocated = 399069752
			PortalMemory/PortalHeapMemory/ExecutorState/SRF multi-call context.currently_allocated = 97070648
			PortalMemory/PortalHeapMemory/ExecutorState/ExprContext.currently_allocated = 301981696

Step to reproduce the behavior

This is not a minimal repro.

Apply the attached patch, run the following and observe the logs.

diff --cc src/backend/commands/analyzefuncs.c
index 35171364c8c,35171364c8c..d4dc243424b
--- a/src/backend/commands/analyzefuncs.c
+++ b/src/backend/commands/analyzefuncs.c
@@@ -349,6 -349,6 +349,14 @@@ gp_acquire_sample_rows(PG_FUNCTION_ARGS
                SRF_RETURN_NEXT(funcctx, HeapTupleGetDatum(res));
        }
  
++      /*elog(LOG, "CurrentMemoryContext->name = %s, peak usage = %lu",
++               CurrentMemoryContext->name,
++               MemoryContextGetPeakSpace(CurrentMemoryContext));
++      MemoryContextStats(CurrentMemoryContext);*/
++
++      elog(LOG, "MemoryContextStats after last call to gp_acquire_sample_rows: ");
++      MemoryContextStats(TopMemoryContext);
++

diff --cc src/backend/utils/mmgr/aset.c
index 4cde8a874cf,4cde8a874cf..7e3245c92fd
--- a/src/backend/utils/mmgr/aset.c
+++ b/src/backend/utils/mmgr/aset.c
@@@ -1104,10 -1104,10 +1104,12 @@@ AllocSetDelete(MemoryContext context
        set->blocks = NULL;
        set->keeper = NULL;
  
++      Size freed = 0;
        while (block != NULL)
        {
                AllocBlock      next = block->next;
                size_t freesz = UserPtr_GetUserPtrSize(block);
++              freed += freesz;
          MemoryContextNoteFree(&set->header, freesz);
  
  #ifdef CLOBBER_FREED_MEMORY
@@@ -1116,6 -1116,6 +1118,11 @@@
                gp_free(block);
                block = next;
        }
++      ereportif(strcmp(context->name, "SRF multi-call context") == 0 ||
++                        strcmp(context->name, "ExprContext") == 0 ||
++                        strcmp(context->name, "ExecutorState") == 0,
++                        LOG,
++              (errmsg("context->name: %s: gp_freed %lu bytes", context->name, freed), errprintstack(true)));

CREATE TABLE public.foo (
    i integer,
    j integer,
    k integer
)
WITH (appendonly='true')
 DISTRIBUTED BY (i);
ALTER TABLE ONLY public.foo ALTER COLUMN i SET STATISTICS 10000;
ALTER TABLE ONLY public.foo ALTER COLUMN j SET STATISTICS 10000;
ALTER TABLE ONLY public.foo ALTER COLUMN k SET STATISTICS 10000;

-- all data skewed on seg0
insert into foo select 0, j, 1000 from generate_series(1, 100000000) j;

-- Now inspect seg1's pg_log.

Note: This does not exist in 7X due to iteration 9.6 merge commit:

commit 7c7fba2fe15eb195cb82f0aaff347b3b7a299637
Author: Adam Lee <adam8157@gmail.com>
Date:   Fri Sep 6 13:18:36 2019 +0800

    Resolve conflicts in mcxt.c
    
    Follow the stats function of upstream, revisit here to check if
    Greenplum's version is better at some places.

Historical commit that added the deviation from upstream:

Collapsing large number of identically named sibling contexts to redu…
…ce log size during OOM.

[soumyadeep2007]

Differences for 6X_STABLE with 9_4_STABLE/7X:

(1) AllocBlock lacks a endptr in 6X, which makes totalspace calculation in AllocSetStats more complicated.

(2) AllocChunk has a sharedHeader field in 6X, as opposed to an aset field for chunk list traversal.

(3) In 6X, we have cumulative stats collection done in MemoryContextData:

/* CDB: Lifetime cumulative stats for this context and all descendants */
uint64      allBytesAlloc;  /* bytes allocated from lower level mem mgr */
uint64      allBytesFreed;  /* bytes returned to lower level mem mgr */
Size        maxBytesHeld;   /* high-water mark for total bytes held */
Size        localMinHeld;   /* low-water mark since last increase in hwm */

which is then consulted in AllocSetStats().

In 9_4_STABLE/7X, AllocSetStats() gathers all space stats by simply consulting the blocks and chunks in the context with 2 simple loops. It does not need to consult anything else.

(4) The recursion mechanism is also different, due to the concept of "collapsing sibling contexts". 9_4_STABLE does very simple recursion and also doesn't overly complicate the stats() callback interface:

(*context->methods->stats) (context, level);
	for (child = context->firstchild; child != NULL; child = child->nextchild)
		MemoryContextStatsInternal(child, level + 1);

In 6X, we have to do a lot more work because we have to maintain the Lifetime cumulative stats. See MemoryContextStats_recur().

Rationale for differences:

(1) There is no mention of why we have cumulative stats captured like this in MemoryContextData beyond the historical commit message: Memory stats dumped to stderr on an 'out of memory' error have been improved.  Cumulative memory stats, including peak usage, are kept internally for each MemoryContext subtree.

(2) Part of the changes was introduced by historical commit: Collapsing large number of identically named sibling contexts to reduce log size during OOM. This is similar to the problem fixed by Tom Lane in 9.6 (also in 7X): postgres/postgres@7b5ef8f

Possible direction:

The notion of Lifetime cumulative stats doesn't add much value in the context of MemoryContextStats() reporting during an OOM. These fields have other uses (specially for peak reporting etc with EXPLAIN), so let's keep them instead of discarding them entirely.

However, for stats reporting purposes, lets revert to using the upstream implementation. This essentially means:

• MemoryContextStats(), MemoryContextMethods->stats, AllocSet_GetStats can be reverted to using the same interface and implementation as upstream.

  • Note the difference mentioned about endptr above. So we will have to rely on vmem functions such as UserPtr_GetUserPtrSize to actually get at how much space is in a block.
  • Note the difference mentioned about sharedHeader above, we will have to use it for chunk list traversal.

• Lets absorb changes from postgres/postgres@7b5ef8f so we don't face unreasonable log file growth during OOM reporting.

[ashwinstar]

This was fixed closing.