Re: Collecting statistics about contents of JSONB columns

On 1/25/22 17:56, Mahendra Singh Thalor wrote:
>
> ...
>
> For the last few days, I was trying to understand these patches, and
> based on Tomas's suggestion, I was doing some performance tests.
>
> With the attached .SQL file, I can see that analyze is taking more time
> with these patches.
>
> *Setup: *
> autovacuum=off
> rest all are default settings.
>
> Insert attached file with and without the patch to compare the time
> taken by analyze.
>
> *With json patches:*
> postgres=# analyze test ;
> ANALYZE
> Time: *28464.062 ms (00:28.464)*
> postgres=#
> postgres=# SELECT pg_size_pretty(
> pg_total_relation_size('pg_catalog.pg_statistic') );
>  pg_size_pretty
> ----------------
>  328 kB
> (1 row)
> --
>
> *Without json patches:*
> postgres=# analyze test ;
> ANALYZE
> *Time: 120.864* ms
> postgres=# SELECT pg_size_pretty(
> pg_total_relation_size('pg_catalog.pg_statistic') );
>  pg_size_pretty
> ----------------
>  272 kB
>
> I haven't found the root cause of this but I feel that this time is due
> to a loop of all the paths.
> In my test data, there is a total of 951 different-2 paths. While doing
> analysis, first we check all the sample rows(30000) and we collect all
> the different-2 paths (here 951), and after that for every single path,
> we loop over all the sample rows again to collect stats for a particular
> path. I feel that these loops might be taking time.
>
> I will run perf and will try to find out the root cause of this.
>

Thanks, I've been doing some performance tests too, and you're right it
takes quite a bit of time. I wanted to compare how the timing changes
with complexity of the JSON documents (nesting, number of keys, ...) so
I wrote a simple python script to generate random JSON documents with
different parameters - see the attached json-generate.py script.

It's a bit crude, but it generates synthetic documents with a chosen
number of levels, keys per level, distinct key values, etc. The
generated documents are loaded directly into a "json_test" database,
into a table "test_table" with a single jsonb column called "v".
Tweaking this to connect to a different database, or just dump the
generated documents to a file, should be trivial.

The attached bash script runs the data generator for a couple of
combinations, and them measures how long it takes to analyze the table,
how large the statistics are (in a rather crude way), etc.

The results look like this (the last two columns are analyze duration in
milliseconds, for master and with the patch):

levels keys unique keys paths master patched
----------------------------------------------------------
1 1 1 2 153 122
1 1 1000 1001 134 1590
1 8 8 9 157 367
1 8 1000 1001 155 1838
1 64 64 65 189 2298
1 64 1000 1001 46 9322
2 1 1 3 237 197
2 1 1000 30580 152 46468
2 8 8 73 245 1780

So yeah, it's significantly slower - in most cases not as much as you
observed, but an order of magnitude slower than master. For size of the
statistics, it's similar:

levels keys unique keys paths table size master patched
------------------------------------------------------------------
1 1 1 2 1843200 16360 24325
1 1 1000 1001 1843200 16819 1425400
1 8 8 9 4710400 28948 88837
1 8 1000 1001 6504448 42694 3915802
1 64 64 65 30154752 209713 689842
1 64 1000 1001 49086464 1093 7755214
2 1 1 3 2572288 24883 48727
2 1 1000 30580 2572288 11422 26396365
2 8 8 73 23068672 164785 862258

This is measured by by dumping pg_statistic for the column, so in
database it might be compressed etc. It's larger, but that's somewhat
expected because we simply store more detailed stats. The size grows
with the number of paths extracted - which is expected, of course.

If you noticed why this doesn't show data for additional combinations
(e.g. 2 levels 8 keys and 1000 distinct key values), then that's the bad
news - that takes ages (multiple minutes) and then it gets killed by OOM
killer because it eats gigabytes of memory.

I agree the slowness is largely due to extracting all paths and then
processing them one by one - which means we have to loop over the tuples
over and over. In this case there's about 850k distinct paths extracted,
so we do ~850k loops over 30k tuples. That's gotta take time.

I don't know what exactly to do about this, but I already mentioned we
may need to pick a subset of paths to keep, similarly to how we pick
items for MCV. I mean, if we only saw a path once or twice, it's
unlikely to be interesting enough to build stats for it. I haven't
tried, but I'd bet most of the 850k paths might be ignored like this.

The other thing we might do is making it the loops more efficient. For
example, we might track which documents contain each path (by a small
bitmap or something), so that in the loop we can skip rows that don't
contain the path we're currently processing. Or something like that.

Of course, this can't eliminate all the overhead - we've building more
stats and that has a cost. In the "common" case of stable "fixed" schema
with the same paths in all documents we'll still need to do loop for
each of them. So it's bound to be slower than master.

Which probably means it's a bad idea to do this for all JSONB columns,
because in many cases the extra stats are not needed so the extra
analyze time would be a waste. So I guess we'll need some way to enable
this only for selected columns ... I argued against the idea to
implement this as extended statistics in the first message, but it's a
reasonably nice way to do such stuff (expression stats are a precedent).

> Apart from this performance issue, I haven't found any crashes or issues.
>

Well, I haven't seen any crashes either, but as I mentioned for complex
documents (2 levels, many distinct keys) the ANALYZE starts consuming a
lot of memory and may get killed by OOM. For example if you generate
documents like this

./json-generate.py 30000 2 8 1000 6 1000

and then run ANALYZE, that'll take ages and it very quickly gets into a
situation like this (generated from gdb by calling MemoryContextStats on
TopMemoryContext):

-------------------------------------------------------------------------
TopMemoryContext: 80776 total in 6 blocks; 13992 free (18 chunks); 66784
used
...
TopPortalContext: 8192 total in 1 blocks; 7656 free (0 chunks); 536 used
PortalContext: 1024 total in 1 blocks; 488 free (0 chunks); 536
used: <unnamed>
Analyze: 472726496 total in 150 blocks; 3725776 free (4 chunks);
469000720 used
Analyze Column: 921177696 total in 120 blocks; 5123256 free
(238 chunks); 916054440 used
Json Analyze Tmp Context: 8192 total in 1 blocks; 5720 free
(1 chunks); 2472 used
Json Analyze Pass Context: 8192 total in 1 blocks; 7928
free (0 chunks); 264 used
JSON analyze path table: 1639706040 total in 25084 blocks;
1513640 free (33 chunks); 1638192400 used
Vacuum: 8192 total in 1 blocks; 7448 free (0 chunks); 744 used
...
Grand total: 3035316184 bytes in 25542 blocks; 10971120 free (352
chunks); 3024345064 used
-------------------------------------------------------------------------

Yes, that's backend 3GB of memory, out of which 1.6GB is in "analyze
path table" context, 400MB in "analyze" and 900MB in "analyze column"
contexts. I mean, that seems a bit excessive. And it grows over time, so
after a while my laptop gives up and kills the backend.

I'm not sure if it's a memory leak (which would be fixable), or it's due
to keeping stats for all the extracted paths. I mean, in this particular
case we have 850k paths - even if stats are just 1kB per path, that's
850MB. This requires more investigation.

regards

--
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company