Обсуждение: BUG #18177: certain queries under certain contexts take multiple orders of magnitude longer compared to v10
BUG #18177: certain queries under certain contexts take multiple orders of magnitude longer compared to v10
От
PG Bug reporting form
Дата:
The following bug has been logged on the website: Bug reference: 18177 Logged by: Robert Leach Email address: rleach@princeton.edu PostgreSQL version: 13.12 Operating system: macOS and linux Description: We upgraded our Django on a large project from 3.2 to 4.2 (and postgres from 10 to 13) and found that our test suite which typically took about 25-30 minutes roughly doubled in running time (50 to 75 minutes). Switching back to Django 3.2 but keeping postgres 13 also experiences the same slow-down. I isolated one test that normally took 90s that now takes consistently 400s and further narrowed it down to a single (simple) query. That test would run fast if run by itself, but it run after a series of other tests, would take 400s. I extracted the SQL generated for the query and performed an `explain` on it, and it showed that the actual time took way longer than the estimated cost. Doing a vacuum full analyze was able to restore the speed, but the only place where I was able to use it to get the speed back, relatively caused weird errors in other tests. I cannot claim to understand the bug that is causing this issue, so the best I can do is simply provide the explain output and try to keep from providing confusing details, because this is outside the realm of my expertise: ``` ('Aggregate (cost=45.77..45.78 rows=1 width=8) (actual time=202326.210..202326.214 rows=1 loops=1)',) (' -> Unique (cost=0.88..45.76 rows=1 width=1052) (actual time=10492.963..202326.205 rows=1 loops=1)',) (' -> Nested Loop (cost=0.88..45.75 rows=1 width=1052) (actual time=10492.959..202326.188 rows=8 loops=1)',) (' Join Filter: ("DataRepo_peakdata".id = "DataRepo_peakdatalabel".peak_data_id)',) (' Rows Removed by Join Filter: 3076',) (' -> Nested Loop (cost=0.62..37.47 rows=1 width=8) (actual time=10492.455..202323.935 rows=8 loops=1)',) (' Join Filter: ("DataRepo_peakgroup".id = "DataRepo_peakdata".peak_group_id)',) (' Rows Removed by Join Filter: 7888',) (' -> Index Scan using "DataRepo_peakdata_peak_group_id_4dd87f4a" on "DataRepo_peakdata" (cost=0.25..8.26 rows=1 width=8) (actual time=0.017..7.149 rows=7896 loops=1)',) (' -> Nested Loop (cost=0.38..29.20 rows=1 width=4) (actual time=2.942..25.621 rows=1 loops=7896)',) (' Join Filter: ("DataRepo_peakgroup".peak_annotation_file_id = "DataRepo_archivefile".id)',) (' -> Nested Loop (cost=0.38..18.43 rows=1 width=8) (actual time=2.935..25.614 rows=1 loops=7896)',) (' Join Filter: ("DataRepo_msrun".sample_id = "DataRepo_sample".id)',) (' Rows Removed by Join Filter: 83',) (' -> Nested Loop (cost=0.12..10.15 rows=1 width=12) (actual time=0.028..2.513 rows=84 loops=7896)',) (' Join Filter: ("DataRepo_peakgroup".msrun_id = "DataRepo_msrun".id)',) (' Rows Removed by Join Filter: 3486',) (' -> Index Scan using "DataRepo_peakgroup_peak_annotation_file_id_6dc2fc25" on "DataRepo_peakgroup" (cost=0.12..8.14 rows=1 width=12) (actual time=0.006..0.464 rows=84 loops=7896)',) (" Filter: ((name)::text = 'serine'::text)",) (' Rows Removed by Filter: 1008',) (' -> Seq Scan on "DataRepo_msrun" (cost=0.00..2.00 rows=1 width=8) (actual time=0.013..0.017 rows=42 loops=663264)',) (' -> Index Scan using "DataRepo_sample_pkey" on "DataRepo_sample" (cost=0.25..8.27 rows=1 width=4) (actual time=0.194..0.275 rows=1 loops=663264)',) (" Filter: ((name)::text = 'xzl5_panc'::text)",) (' Rows Removed by Filter: 281',) (' -> Seq Scan on "DataRepo_archivefile" (cost=0.00..10.75 rows=1 width=4) (actual time=0.002..0.002 rows=1 loops=7896)',) (" Filter: ((filename)::text = 'alafasted_cor.xlsx'::text)",) (' -> Index Scan using "DataRepo_peakdatalabel_peak_data_id_f6151d4a" on "DataRepo_peakdatalabel" (cost=0.25..8.27 rows=1 width=12) (actual time=0.007..0.217 rows=386 loops=8)',) (" Filter: ((element)::text = 'C'::text)",) (' Rows Removed by Filter: 180',) ('Planning Time: 0.963 ms',) ('Execution Time: 202327.334 ms',) ``` There is a thread on the Django forum with lots of other details, but at the outset of that discussion, I didn't even know what was causing the speed issue. For all I knew, it was some other change to our code, but with the help of the folks in the Django forum, I think that this is conclusively due to postgres 13. https://forum.djangoproject.com/t/test-time-doubled-after-django-3-2-4-2-and-postgres-10-13-update/24843/16 If this is a known issue, is there a version of postgres (after v13) that resolves it?
On Thu, 2 Nov 2023 at 21:56, PG Bug reporting form <noreply@postgresql.org> wrote: > I cannot claim to understand the bug that is causing this issue, so the best > I can do is simply provide the explain output and try to keep from providing > confusing details, because this is outside the realm of my expertise: > (' -> Index Scan using > "DataRepo_peakdata_peak_group_id_4dd87f4a" on "DataRepo_peakdata" > (cost=0.25..8.26 rows=1 width=8) (actual time=0.017..7.149 rows=7896 > loops=1)',) Nothing looks particularly bug like so far. It seems the pg_class.reltuples estimate for this relation is way out. Has autovacuum gotten to this table recently? select * from pg_stat_user_tables where relid = '"DataRepo_peakdata"'::regclass; The plan would likely come good if you analyzed that table. You should see if you can figure out why autovacuum hasn't analyzed it. For the future, it might be best to post EXPLAIN output as an attachment. The extra formatting makes it difficult to read. David
Thanks David, I very much appreciate your time and assessment. I feel like I'm stuck, so all suggestions are very much welcome. >> I cannot claim to understand the bug that is causing this issue, so the best >> I can do is simply provide the explain output and try to keep from providing >> confusing details, because this is outside the realm of my expertise: >> >> >> (' -> Index Scan using >> "DataRepo_peakdata_peak_group_id_4dd87f4a" on "DataRepo_peakdata" >> (cost=0.25..8.26 rows=1 width=8) (actual time=0.017..7.149 rows=7896 >> loops=1)',) > > Nothing looks particularly bug like so far. It seems the > pg_class.reltuples estimate for this relation is way out. If this is operating as intended, there are a couple questions I have: 1. In postgres 10, the query always runs in under 1 second, regardless of the context. In postgres 13, depending on thecontext, why does it almost always takes over 200 seconds? 2. In postgres 13, the query runs in under 1 second if I run just the one test that (starting from an empty database) loadsdata and runs the query. BUT, if I run that one test after having run tests in another python/django test class (whichloads data, runs various tests, then destroys all the data that that test class loaded), that query takes over 200seconds to run. Why would that be? I understand that the above involves variables unrelated to postgres (i.e. Django test classes), but if the only thing Ichange is postgres (v10 versus v13), v10 is always fast and v13 has this context-dependent slowness and I have not beenable to find a problem in the python code after having investigated this now for a week and a half. We have been endeavoring to keep our code database-architecture-independent, and as far as I understand the suggestions madeby the Django folks, it seems like running the vacuum command in key places is potentially a strategy to deal with thisissue (even though I haven't been able to get it to consistently work yet), but doing that would tie the codebase toa particular database architecture. Are there alternate solutions that do not involve altering our Django codebase? > Has autovacuum gotten to this table recently? I only just learned the other day about the "VACUUM FULL ANALYZE" command and have been trying to manually run it at differentpoints with mixed outcomes WRT speed. I don't know what the difference between that and "autovacuum" is. > select * from pg_stat_user_tables where relid = '"DataRepo_peakdata"'::regclass; When I try to execute this command, I get: psycopg2.errors.UndefinedTable: relation "DataRepo_peakdata" does not exist Maybe I'm not running it in the correct location? Or I'm running it too many times? > The plan would likely come good if you analyzed that table. You > should see if you can figure out why autovacuum hasn't analyzed it. How do I determine that? Also, I have tried inserting `vacuum full analyze` commands at different points in the code, andit doesn't appear to consistently speed things up. In fact, before I started attempting vacuuming, there are occasionalinstances where it randomly ran fast without me changing anything, i.e. the problem intermittently goes away. Though like I said, I've been working on solving this for a week and a half, so I could be mistaken. I've tried so manythings and I have been switching back to v10 occasionally, so it could be that I was on v10, thinking I was on v13 whenI saw it run fast. > For the future, it might be best to post EXPLAIN output as an > attachment. The extra formatting makes it difficult to read. Sorry about that. I used the web form and there wasn't at attachment field. Rob
On 11/2/23 11:45, David Rowley wrote: > On Thu, 2 Nov 2023 at 21:56, PG Bug reporting form > <noreply@postgresql.org> wrote: >> I cannot claim to understand the bug that is causing this issue, so the best >> I can do is simply provide the explain output and try to keep from providing >> confusing details, because this is outside the realm of my expertise: > > >> (' -> Index Scan using >> "DataRepo_peakdata_peak_group_id_4dd87f4a" on "DataRepo_peakdata" >> (cost=0.25..8.26 rows=1 width=8) (actual time=0.017..7.149 rows=7896 >> loops=1)',) > > Nothing looks particularly bug like so far. It seems the > pg_class.reltuples estimate for this relation is way out. > > Has autovacuum gotten to this table recently? > > select * from pg_stat_user_tables where relid = '"DataRepo_peakdata"'::regclass; > > The plan would likely come good if you analyzed that table. You > should see if you can figure out why autovacuum hasn't analyzed it. > > For the future, it might be best to post EXPLAIN output as an > attachment. The extra formatting makes it difficult to read. > I did look at the django forum, and the plans are there. For convenience I'm attaching them here too. But there's nothing particularly revealing, except that it indeed seems to be related to the index scan. One thing that puzzles me is why it'd behave differently between PG10 and PG13. I'd have expected both releases to do the same thing if there are no stats, but maybe PG10 does analyze it time for some reason? Would be interesting to see the pg_class data (reltuples, relpages and timestamp of last analyze/autoanalyze) for the slow/fast cases. However, the forum thread also claims this: And here is the Django 4.2 and postgres 13 output when running just the one test (which is always fast): Which seems weird. But maybe the table is modified/updated by the tests, so a single test might seem much less data, or something? Not sure. However, there's one more interesting bit - the 'weird errors' after placing VACUUM FULL ANALYZE into test setup/teardown are this: psycopg2.errors.DataCorrupted: missing chunk number 0 for toast value 2884552 in pg_toast_2619 That seems unrelated to the planning issue, but it definitely seems like a bug. Interestingly enough we got a report [1] about the same error on pgsql-hackers a couple days ago. That error affected PG11-16, which seems to be consistent with this (PG13). [1] https://www.postgresql.org/message-id/CALdSSPhmqoN02ciT4UxS6ax0N84NpRwPWm87nKJ_%2B0G-Na8qOQ%40mail.gmail.com regards -- Tomas Vondra EnterpriseDB: http://www.enterprisedb.com The Enterprise PostgreSQL Company
Вложения
On Fri, 3 Nov 2023 at 09:04, Robert Leach <rleach@princeton.edu> wrote: > > Nothing looks particularly bug like so far. It seems the > > pg_class.reltuples estimate for this relation is way out. > > If this is operating as intended, there are a couple questions I have: > > 1. In postgres 10, the query always runs in under 1 second, regardless of the context. In postgres 13, depending on thecontext, why does it almost always takes over 200 seconds? The reason the query is slow is that the planner thinks that there's only 1 row in the DataRepo_peakdata table. In reality, when you executed that query there were 7896 rows. Because the planner thinks there's 1 row. It opts to use the fastest method available to join two relations where one side has just 1 row, i.e. Nested Loop. Unfortunately, it's a risky plan as underestimations have quadratic repercussions. In the v13 query, this comes out at this point in the plan: -> Nested Loop (cost=0.62..37.47 rows=1 width=8) (actual time=10492.455..202323.935 rows=8 loops=1) Join Filter: ("DataRepo_peakgroup".id = "DataRepo_peakdata".peak_group_id) Rows Removed by Join Filter: 7888 -> Index Scan using "DataRepo_peakdata_peak_group_id_4dd87f4a" on "DataRepo_peakdata" (cost=0.25..8.26 rows=1 width=8) (actual time=0.017..7.149 rows=7896 loops=1) -> Nested Loop (cost=0.38..29.20 rows=1 width=4) (actual time=2.942..25.621 rows=1 loops=7896) You can see the planner thought the index scan would produce 1 row. 7896 were found during execution. Most of the time of the entire query can be accounted for by this plan fragment. The average execution time for 1 loop of that 2nd Nested Loop quoted above is 25.621 milliseconds. If you multiply that number by the number of loops (7896), you get 202303.416 milliseconds. Because the scan on DataRepo_peakdata contains no clauses, the row estimate here is derived from pg_class.reltuples for that index. VACUUM and ANALYZE adjust this pg_class column after they run so that the planner has a recent estimate on the number of records in the table. The estimated tuples for a clause-less scan of an index don't come directly from pg_class.reltuples. What happens is it looks at relpages and reltuples to calculate the average tuples per page then we apply that average over the *current* number of pages in the index. It would be interesting to see what pg_class reltuples and relpages is set to for this index. > 2. In postgres 13, the query runs in under 1 second if I run just the one test that (starting from an empty database) loadsdata and runs the query. BUT, if I run that one test after having run tests in another python/django test class (whichloads data, runs various tests, then destroys all the data that that test class loaded), that query takes over 200seconds to run. Why would that be? I don't know what these tests do. If they update some data in the tables then perhaps the index becomes bloated and that results in the number of pages in the index changing which affects the estimate of the number of tuples in the index. It would be good to get the output of pg_relation_size('DataRepo_peakdata_peak_group_id_4dd87f4a') before and after the tests run. > I understand that the above involves variables unrelated to postgres (i.e. Django test classes), but if the only thingI change is postgres (v10 versus v13), v10 is always fast and v13 has this context-dependent slowness and I have notbeen able to find a problem in the python code after having investigated this now for a week and a half. Going by your EXPLAIN output, I think we can confirm the problem is the reltuples value that's calculated in PostgreSQL's estimate_rel_size() function. It's just a question of finding out *why* the reltuples value is not close to reality. An incorrect value does not mean PostgreSQL bugs. Stale stats could be an explanation. Let's dig further to find out. > We have been endeavoring to keep our code database-architecture-independent, and as far as I understand the suggestionsmade by the Django folks, it seems like running the vacuum command in key places is potentially a strategy todeal with this issue (even though I haven't been able to get it to consistently work yet), but doing that would tie thecodebase to a particular database architecture. Are there alternate solutions that do not involve altering our Djangocodebase? We need to find out the problem first. Perhaps more aggressive autovacuum settings could help, but we've not gotten far enough to tell yet. I suspect it's a case of the fact that running tests do a whole load of database changes in a short space of time. In this case, perhaps that's just faster than autovacuum can react to those changes. > > Has autovacuum gotten to this table recently? > > > I only just learned the other day about the "VACUUM FULL ANALYZE" command and have been trying to manually run it at differentpoints with mixed outcomes WRT speed. I don't know what the difference between that and "autovacuum" is. Autovacuum will never do VACUUM FULL. It'll do various forms of VACUUM and also ANALYZE. > > select * from pg_stat_user_tables where relid = '"DataRepo_peakdata"'::regclass; > > When I try to execute this command, I get: > > psycopg2.errors.UndefinedTable: relation "DataRepo_peakdata" does not exist You'd need to be connected to the same database as that table exists in. Your EXPLAIN output had extra formatting in it. I had assumed the quotes were there because the table was created with some upper-case characters. PostgreSQL folds unquoted identifiers to lower-case. Perhaps you can try without the quotes if you still get that when connected to the correct database. > > The plan would likely come good if you analyzed that table. You > > should see if you can figure out why autovacuum hasn't analyzed it. > > How do I determine that? Also, I have tried inserting `vacuum full analyze` commands at different points in the code,and it doesn't appear to consistently speed things up. In fact, before I started attempting vacuuming, there are occasionalinstances where it randomly ran fast without me changing anything, i.e. the problem intermittently goes away. Though like I said, I've been working on solving this for a week and a half, so I could be mistaken. I've tried so manythings and I have been switching back to v10 occasionally, so it could be that I was on v10, thinking I was on v13 whenI saw it run fast. Perhaps it goes away after autovacuum runs ANALYZE on the table again. I suspect this problem depends on the timing of autovacuum and suspect you might see the tests running faster more often if you changed autovacuum_naptime to 1 second. You'd probably see them more consistently running slower if you set autovacuum_naptime to some value higher than it's set to right now. David
Would be interesting to see the pg_class data (reltuples, relpages and
timestamp of last analyze/autoanalyze) for the slow/fast cases.
If you give me the necessary query, I can execute it an give you the output.
However, the forum thread also claims this:
And here is the Django 4.2 and postgres 13 output when running just
the one test (which is always fast):
Which seems weird. But maybe the table is modified/updated by the tests,
so a single test might seem much less data, or something? Not sure.
The tables are not modified by the tests. All that the tests do is load data and make a query. If you run just the 1 test, it loads 1 samples and animals (and other underlying data) in the class setup (to make data available to every test in the class) and the test loads peak data and makes a query. That's the fast case.
In the slow case, before doing all that, the other test class does roughly the same thing, but once that class's tests are done, the data is destroyed and the tests move on to the next class.
However, there's one more interesting bit - the 'weird errors' after
placing VACUUM FULL ANALYZE into test setup/teardown are this:
psycopg2.errors.DataCorrupted: missing chunk number 0 for toast
value 2884552 in pg_toast_2619
That seems unrelated to the planning issue, but it definitely seems like
a bug. Interestingly enough we got a report [1] about the same error on
pgsql-hackers a couple days ago. That error affected PG11-16, which
seems to be consistent with this (PG13).
IMO, you should take that error with a grain of salt. Maybe it means something or maybe it's the result of me not knowing what I'm doing when I started inserting debug code and SQL commands that I'm unfamiliar with and could be using incorrectly. We never got that error until I started messing around to debug this issue.
By the way, the codebase is a public repo. Here are some links, if you would find it useful to peruse the code:
REPO:
The models:
https://github.com/Princeton-LSI-ResearchComputing/tracebase/tree/main/DataRepo/models
My debug branch for this issue (which is actively being worked on and occasionally updated):
https://github.com/Princeton-LSI-ResearchComputing/tracebase/tree/speed_debugging
The test I've been using to debug this issue:
https://github.com/Princeton-LSI-ResearchComputing/tracebase/blob/7c7fa13eec1233a12bd114ec90270bb94fe959ae/DataRepo/tests/loading/test_load_accucor_msruns.py#L929
Rob
I rearranged the order of the responses in this email based on the precedence of the things I've learned...
select * from pg_stat_user_tables where relid = '"DataRepo_peakdata"'::regclass;When I try to execute this command, I get:psycopg2.errors.UndefinedTable: relation "DataRepo_peakdata" does not exist
You'd need to be connected to the same database as that table exists
in. Your EXPLAIN output had extra formatting in it. I had assumed the
quotes were there because the table was created with some upper-case
characters. PostgreSQL folds unquoted identifiers to lower-case.
Perhaps you can try without the quotes if you still get that when
connected to the correct database.
So I finally worked out that only this seems to do the right thing:
cursor.execute("select * from pg_stat_user_tables where relid = '\"DataRepo_peakdata\"'::regclass;")
Before, I was trying:
cursor.execute("""select * from pg_stat_user_tables where relid = '"DataRepo_peakdata"'::regclass;""")
and that apparently didn't work.
Anyway, here's what I see:
Slow case (when having run tests from a separate class first):
After the animal/sample load and before the peak data load:
(2911633, 'public', 'DataRepo_peakdata', 9, 201, 882, 882, 595, 0, 0, 0, 0, 595, 0, 595, None, None, None, None, 0, 0, 0, 0)
After the peak data load and before the *slow* query:
(2914197, 'public', 'DataRepo_peakdata', 9, 201, 882, 882, 595, 0, 0, 0, 0, 595, 0, 595, None, None, None, None, 0, 0, 0, 0)
These are the speeds of the 4 queries in the test:
pg query time: 0.001s
pg count time: 0.141s
carbon count time: 303.786 nitrogen count time: 300.561 (everything runs slower on my laptop at home, so it's over 200s)
Usually slow case (same as above, but the first time I tried it, it went randomly fast):
After the animal/sample load and before the peak data load:
(2911633, 'public', 'DataRepo_peakdata', 9, 201, 882, 882, 595, 0, 0, 0, 0, 595, 0, 595, None, None, None, None, 0, 0, 0, 0)
After the peak data load and before the *slow* query:
(2913556, 'public', 'DataRepo_peakdata', 9, 201, 882, 882, 595, 0, 0, 0, 0, 595, 0, 595, None, None, None, None, 0, 0, 0, 0)
Note, in this particular instance, the queries went FAST:
pg query time: 0.002s
pg count time: 0.066s
carbon count time: 0.036s
nitrogen count time: 0.031s
Always Fast case (when only running that one test):
After the animal/sample load and before the peak data load:
(2912274, 'public', 'DataRepo_peakdata', 3, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, None, None, None, None, 0, 0, 0, 0)
After the peak data load and before the query:
(2912915, 'public', 'DataRepo_peakdata', 3, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, None, None, None, None, 0, 0, 0, 0)
Nothing looks particularly bug like so far. It seems the
pg_class.reltuples estimate for this relation is way out.
If this is operating as intended, there are a couple questions I have:
1. In postgres 10, the query always runs in under 1 second, regardless of the context. In postgres 13, depending on the context, why does it almost always takes over 200 seconds?
The reason the query is slow is that the planner thinks that there's
only 1 row in the DataRepo_peakdata table. In reality, when you
executed that query there were 7896 rows.
Because the planner thinks there's 1 row. It opts to use the fastest
method available to join two relations where one side has just 1 row,
i.e. Nested Loop. Unfortunately, it's a risky plan as
underestimations have quadratic repercussions. In the v13 query, this
comes out at this point in the plan:
-> Nested Loop (cost=0.62..37.47 rows=1 width=8)
(actual time=10492.455..202323.935 rows=8 loops=1)
Join Filter: ("DataRepo_peakgroup".id =
"DataRepo_peakdata".peak_group_id)
Rows Removed by Join Filter: 7888
-> Index Scan using
"DataRepo_peakdata_peak_group_id_4dd87f4a" on "DataRepo_peakdata"
(cost=0.25..8.26 rows=1 width=8) (actual time=0.017..7.149 rows=7896
loops=1)
-> Nested Loop (cost=0.38..29.20 rows=1 width=4)
(actual time=2.942..25.621 rows=1 loops=7896)
You can see the planner thought the index scan would produce 1 row.
7896 were found during execution.
Most of the time of the entire query can be accounted for by this plan
fragment. The average execution time for 1 loop of that 2nd Nested
Loop quoted above is 25.621 milliseconds. If you multiply that number
by the number of loops (7896), you get 202303.416 milliseconds.
Because the scan on DataRepo_peakdata contains no clauses, the row
estimate here is derived from pg_class.reltuples for that index.
VACUUM and ANALYZE adjust this pg_class column after they run so that
the planner has a recent estimate on the number of records in the
table. The estimated tuples for a clause-less scan of an index don't
come directly from pg_class.reltuples. What happens is it looks at
relpages and reltuples to calculate the average tuples per page then
we apply that average over the *current* number of pages in the index.
7896 is the exact number of records that are loaded right before the query. The load is of an excel sheet that has 94 rows and 84 columns:
84 * 94 = 7896
I will point out that the loading is not very fast at all. Those 7896 records (along with other records) have always taken at least 80 seconds to load and the animal sample loading before that always takes at least 10 seconds. It's only the subsequent queries after those loads complete that run unexpectedly slow.
It would be interesting to see what pg_class reltuples and relpages isset to for this index.
If you have a query for me, I can send you the output.
2. In postgres 13, the query runs in under 1 second if I run just the one test that (starting from an empty database) loads data and runs the query. BUT, if I run that one test after having run tests in another python/django test class (which loads data, runs various tests, then destroys all the data that that test class loaded), that query takes over 200 seconds to run. Why would that be?
I don't know what these tests do. If they update some data in the
tables then perhaps the index becomes bloated and that results in the
number of pages in the index changing which affects the estimate of
the number of tuples in the index.
It would be good to get the output of
pg_relation_size('DataRepo_peakdata_peak_group_id_4dd87f4a') before
and after the tests run.
All the tests I've been looking at just insert data.
I tried executing "pg_relation_size('DataRepo_peakdata_peak_group_id_4dd87f4a')" as a command, but I get a syntax error.
Perhaps it goes away after autovacuum runs ANALYZE on the table again.
I suspect this problem depends on the timing of autovacuum and suspect
you might see the tests running faster more often if you changed
autovacuum_naptime to 1 second. You'd probably see them more
consistently running slower if you set autovacuum_naptime to some
value higher than it's set to right now.
Based on a hunch from your comment about connecting to the database, I tried connecting specifically to out database when trying to do the vacuum, because I thought maybe that's why doing the vacuum didn't seem to speed things up (and that the early instances I did see a speed improvement was due to the random speedy queries I sometimes see without doing anything different), but I'm guessing that connecting to our database to do the vacuum doesn't work, because whenever I attempt it, the vacuum command just seems to hang forever.
Rob
> Perhaps more aggressive autovacuum settings could help, but we've not gotten far enough to tell yet. Well, I can report that changing the autovacuum settings does indeed help. I added this to all of the `setUpClass` methodsof our test code: ALTER TABLE "DataRepo_peakdata" SET (autovacuum_vacuum_scale_factor = 0.0); ALTER TABLE "DataRepo_peakdata" SET (autovacuum_vacuum_threshold = 5000); ALTER TABLE "DataRepo_peakdata" SET (autovacuum_analyze_scale_factor = 0.0); ALTER TABLE "DataRepo_peakdata" SET (autovacuum_analyze_threshold = 5000); The one query I've been testing with reproducibly runs in a fraction of a second and when I run the entire test suite ongithub, it runs in 33 minutes as opposed to an hour, which is close to on par with how it was running in postgres 10. It's also notable that I have not been able to get this speed improvement using a `VACUUM FULL ANALYZE`, though I can't besure I ever did it correctly in the first place. The above was based on the feedback you guys provided and the following blog post: https://www.lob.com/blog/supercharge-your-postgresql-performance I still don't like the fact that we have this database-architecture-specific code in our code-base that ties it to a specificdatabase. I'm not sure if where I put it is the best place for it either. Is there a config file I can put thesesettings in? And I'm still curious why this wasn't necessary in postgres 10? Rob
On Tue, 7 Nov 2023 at 11:17, Robert Leach <rleach@princeton.edu> wrote: > ALTER TABLE "DataRepo_peakdata" SET (autovacuum_vacuum_scale_factor = 0.0); > ALTER TABLE "DataRepo_peakdata" SET (autovacuum_vacuum_threshold = 5000); > ALTER TABLE "DataRepo_peakdata" SET (autovacuum_analyze_scale_factor = 0.0); > ALTER TABLE "DataRepo_peakdata" SET (autovacuum_analyze_threshold = 5000); > > I still don't like the fact that we have this database-architecture-specific code in our code-base that ties it to a specificdatabase. I'm not sure if where I put it is the best place for it either. Is there a config file I can put thesesettings in? You can apply those changes globally in postgresql.conf, but having the autovacuum_vacuum_threshold / autovacuum_analyze_threshold set to that constant is unlikely to be very good for all tables. Perhaps there some scale_factor above 0.0 and below 0.2 that you can find that makes it run fast. > And I'm still curious why this wasn't necessary in postgres 10? If you show us the output of the following two queries: SELECT relname, reltuples,relpages,pg_relation_size(oid) from pg_class where oid = '"DataRepo_peakdata"'::regclass; select c.relname, c.reltuples, c.relpages, pg_relation_size(c.oid) from pg_class c inner join pg_index i on c.oid=i.indexrelid where i.indrelid = '"DataRepo_peakdata"'::regclass; run directly before the query in question both on PG10 and on PG13 both when the query runs quickly and when it runs slowly. We might see something there that helps indicate what's going on. David
I haven't tried tweaking the `scale_factor` settings yet, but I did run the queries you requested. Attached are the results.
Rob
Robert William Leach
Robert William Leach
Scientific Programmer
133 Carl C. Icahn Lab
Lewis-Sigler Institute for Integrative Genomics
Princeton University
Princeton, NJ 08544
133 Carl C. Icahn Lab
Lewis-Sigler Institute for Integrative Genomics
Princeton University
Princeton, NJ 08544
On Nov 6, 2023, at 5:38 PM, David Rowley <dgrowleyml@gmail.com> wrote:On Tue, 7 Nov 2023 at 11:17, Robert Leach <rleach@princeton.edu> wrote:ALTER TABLE "DataRepo_peakdata" SET (autovacuum_vacuum_scale_factor = 0.0);
ALTER TABLE "DataRepo_peakdata" SET (autovacuum_vacuum_threshold = 5000);
ALTER TABLE "DataRepo_peakdata" SET (autovacuum_analyze_scale_factor = 0.0);
ALTER TABLE "DataRepo_peakdata" SET (autovacuum_analyze_threshold = 5000);
I still don't like the fact that we have this database-architecture-specific code in our code-base that ties it to a specific database. I'm not sure if where I put it is the best place for it either. Is there a config file I can put these settings in?
You can apply those changes globally in postgresql.conf, but having
the autovacuum_vacuum_threshold / autovacuum_analyze_threshold set to
that constant is unlikely to be very good for all tables. Perhaps
there some scale_factor above 0.0 and below 0.2 that you can find that
makes it run fast.And I'm still curious why this wasn't necessary in postgres 10?
If you show us the output of the following two queries:
SELECT relname, reltuples,relpages,pg_relation_size(oid) from pg_class
where oid = '"DataRepo_peakdata"'::regclass;
select c.relname, c.reltuples, c.relpages, pg_relation_size(c.oid)
from pg_class c inner join pg_index i on c.oid=i.indexrelid where
i.indrelid = '"DataRepo_peakdata"'::regclass;
run directly before the query in question both on PG10 and on PG13
both when the query runs quickly and when it runs slowly. We might
see something there that helps indicate what's going on.
David
Вложения
So unfortunately, even though these custom autovacuum settings in my pull request were only applied to the test database (because that's the only use case we have where large boluses of data are loaded right before a query), and they roughly halve the time of our test suite to run (from ~1h to ~30m), my PR was essentially rejected. Instead, they want the entire test suite to be refactored to deal with the speed issue we had before the upgrade to postgres 13 (so that the tests run in 5m instead of originally 30m), which we've had as an issue since July '22, and I agree it should be done, and would likely also solve the problem, but it's always been lower priority than everything else, and it will take a lot of work.
Did you guys see anything in the query output that could suggest an alternate solution?
Thanks,
Rob
Robert William Leach
Research Software Engineer
133 Carl C. Icahn Lab
Lewis-Sigler Institute for Integrative Genomics
Princeton University
Princeton, NJ 08544
Robert William Leach
Research Software Engineer
133 Carl C. Icahn Lab
Lewis-Sigler Institute for Integrative Genomics
Princeton University
Princeton, NJ 08544
On Nov 7, 2023, at 11:43 AM, Robert Leach <rleach@princeton.edu> wrote:I haven't tried tweaking the `scale_factor` settings yet, but I did run the queries you requested. Attached are the results.<postgres_10v13_stats_queries.txt>Rob
Robert William LeachResearch Software Engineer
133 Carl C. Icahn Lab
Lewis-Sigler Institute for Integrative Genomics
Princeton University
Princeton, NJ 08544On Nov 6, 2023, at 5:38 PM, David Rowley <dgrowleyml@gmail.com> wrote:On Tue, 7 Nov 2023 at 11:17, Robert Leach <rleach@princeton.edu> wrote:ALTER TABLE "DataRepo_peakdata" SET (autovacuum_vacuum_scale_factor = 0.0);
ALTER TABLE "DataRepo_peakdata" SET (autovacuum_vacuum_threshold = 5000);
ALTER TABLE "DataRepo_peakdata" SET (autovacuum_analyze_scale_factor = 0.0);
ALTER TABLE "DataRepo_peakdata" SET (autovacuum_analyze_threshold = 5000);
I still don't like the fact that we have this database-architecture-specific code in our code-base that ties it to a specific database. I'm not sure if where I put it is the best place for it either. Is there a config file I can put these settings in?
You can apply those changes globally in postgresql.conf, but having
the autovacuum_vacuum_threshold / autovacuum_analyze_threshold set to
that constant is unlikely to be very good for all tables. Perhaps
there some scale_factor above 0.0 and below 0.2 that you can find that
makes it run fast.And I'm still curious why this wasn't necessary in postgres 10?
If you show us the output of the following two queries:
SELECT relname, reltuples,relpages,pg_relation_size(oid) from pg_class
where oid = '"DataRepo_peakdata"'::regclass;
select c.relname, c.reltuples, c.relpages, pg_relation_size(c.oid)
from pg_class c inner join pg_index i on c.oid=i.indexrelid where
i.indrelid = '"DataRepo_peakdata"'::regclass;
run directly before the query in question both on PG10 and on PG13
both when the query runs quickly and when it runs slowly. We might
see something there that helps indicate what's going on.
David