autovacuum just stop vacuuming specific table for 7 hours
Hi, I have the next relation in my db : A(id int, info bytea,date timestamp). Every cell in the info column is very big and because of that there is a toasted table with the data of the info column (pg_toast.pg_toast_123456). The relation contains the login info for every user that logs into the session and cleaned whenever the user disconnected. In case the use doesnt logoff, during the night we clean login info that is older then 3 days. The toasted table grew very fast (more then 50M+ rows per week) and thats why I set the next autovacuum settings for the table : Options: toast.autovacuum_vacuum_scale_factor=0 toast.autovacuum_vacuum_threshold=1 toast.autovacuum_vacuum_cost_limit=1 toast.autovacuum_vacuum_cost_delay=5 Those settings helped but the table still grey very much. I wrote a script that monitored some metadata about the table (pg_stat_all_tables,count(*) from orig and toasted table). I let the system monitor the table for a week and I found out the next info : Autovacuum was running great during the whole week and whenever it reached 10k records in the toasted table it started vacuuming the table. *However, The db grew dramatically during a period of 7 hours in a specific day. In those 7 hours the table contained more then 10k (and kept increasing) but the autovacuum didnt vacuum the table*. I saw that during those 7 hours autovacuum didnt run and as a result of that the table grew to its max size(the current size). an example of an autovacuum run on the toasted table : automatic vacuum of table "db.pg_toast.pg_toast_123456": index scans: 1 pages: 0 removed, 1607656 remain tuples: 6396770 removed, 33778 remain buffer usage: 1743021 hits, 3281298 misses, 3217528 dirtied avg read rate: 2.555 MiB/s, avg write rate: 2.505 MiB/s system usage: CPU 98.44s/54.02u sec elapsed 10034.34 sec the vacuum hits/misses/dirtied are set to default (1,10,20) autovacuum workers - 16 maintenance_work_mem - 200MB 130GB RAM , 23 CPU Can anyone explain why suddenly the autovacuum should stop working for that long period ?
Re: autovacuum just stop vacuuming specific table for 7 hours
On Wed, Mar 06, 2019 at 06:47:21PM +0200, Mariel Cherkassky wrote: > Those settings helped but the table still grey very much. I wrote a script > that monitored some metadata about the table (pg_stat_all_tables,count(*) > from orig and toasted table). I let the system monitor the table for a week > and I found out the next info : > Autovacuum was running great during the whole week and whenever it reached > 10k records in the toasted table it started vacuuming the table. *However, > The db grew dramatically during a period of 7 hours in a specific day. In > those 7 hours the table contained more then 10k (and kept increasing) but > the autovacuum didnt vacuum the table*. I saw that during those 7 hours > autovacuum didnt run and as a result of that the table grew to its max > size(the current size). Does pg_stat_all_tables show that the table ought to have been vacuumed ? SELECT * FROM pg_stat_sys_tables WHERE relid='pg_toast.pg_toast_123456'::regclass; Compare with relpages, reltuple FROM pg_class What postgres version ? Justin
Re: autovacuum just stop vacuuming specific table for 7 hours
The PostgreSQL version is 9.6. I dont have access to the machine right now so I will check tomorrow. Basically those values should be the same because they are updated by the autovacuum process right ? Any idea what else to check ? During the week last_autovacuum (in pg_stat_all_tables) were updated every hour. Only during those problematic 7 hours it wasnt updated. בתאריך יום ד׳, 6 במרץ 2019 ב-19:05 מאת Justin Pryzby < [email protected]>: > On Wed, Mar 06, 2019 at 06:47:21PM +0200, Mariel Cherkassky wrote: > > Those settings helped but the table still grey very much. I wrote a > script > > that monitored some metadata about the table (pg_stat_all_tables,count(*) > > from orig and toasted table). I let the system monitor the table for a > week > > and I found out the next info : > > > Autovacuum was running great during the whole week and whenever it > reached > > 10k records in the toasted table it started vacuuming the table. > *However, > > The db grew dramatically during a period of 7 hours in a specific day. In > > those 7 hours the table contained more then 10k (and kept increasing) but > > the autovacuum didnt vacuum the table*. I saw that during those 7 hours > > autovacuum didnt run and as a result of that the table grew to its max > > size(the current size). > > Does pg_stat_all_tables show that the table ought to have been vacuumed ? > > SELECT * FROM pg_stat_sys_tables WHERE > relid='pg_toast.pg_toast_123456'::regclass; > > Compare with relpages, reltuple FROM pg_class > > What postgres version ? > > Justin >
JIT performance question
Hi, I was playing around with PG11.2 (i6700k with 16GB RAM, on Ubuntu 18.04, compiled from sources) and LLVM, trying a CPU-bound query that in my simple mind should benefit from JIT'ting but (almost) doesn't. 1.) Test table with 195 columns of type 'numeric': CREATE TABLE test (data0 numeric,data1 numeric,data2 numeric,data3 numeric,...,data192 numeric,data193 numeric,data194 numeric); 2.) bulk-loaded (via COPY) 2 mio. rows of randomly generated data into this table (and ran vacuum & analyze afterwards) 3.) Disable parallel workers to just measure JIT performance via 'set max_parallel_workers = 0' 4.) Execute query without JIT a couple of times to make sure table is in memory (I had iostat running in the background to verify that actually no disk access was taking place): test=# explain (analyze,buffers) SELECT SUM(data0) AS data0,SUM(data1) AS data1,SUM(data2) AS data2,...,SUM(data193) AS data193,SUM(data194) AS data194 FROM test; QUERY PLAN -- Finalize Aggregate (cost=815586.31..815586.32 rows=1 width=6240) (actual time=14304.058..14304.058 rows=1 loops=1) Buffers: shared hit=64 read=399936 -> Gather (cost=815583.66..815583.87 rows=2 width=6240) (actual time=14303.925..14303.975 rows=1 loops=1) Workers Planned: 2 Workers Launched: 0 Buffers: shared hit=64 read=399936 -> Partial Aggregate (cost=814583.66..814583.67 rows=1 width=6240) (actual time=14302.966..14302.966 rows=1 loops=1) Buffers: shared hit=64 read=399936 -> Parallel Seq Scan on test (cost=0.00..408333.33 rows=83 width=1170) (actual time=0.017..810.513 rows=200 loops=1) Buffers: shared hit=64 read=399936 Planning Time: 4.707 ms Execution Time: 14305.380 ms 5.) Now I turned on the JIT and repeated the same query a couple of times. This is what I got QUERY PLAN -- Finalize Aggregate (cost=815586.31..815586.32 rows=1 width=6240) (actual time=15558.558..15558.558 rows=1 loops=1) Buffers: shared hit=128 read=399872 -> Gather (cost=815583.66..815583.87 rows=2 width=6240) (actual time=15558.450..15558.499 rows=1 loops=1) Workers Planned: 2 Workers Launched: 0 Buffers: shared hit=128 read=399872 -> Partial Aggregate (cost=814583.66..814583.67 rows=1 width=6240) (actual time=15557.541..15557.541 rows=1 loops=1) Buffers: shared hit=128 read=399872 -> Parallel Seq Scan on test (cost=0.00..408333.33 rows=83 width=1170) (actual time=0.020..941.925 rows=200 loops=1) Buffers: shared hit=128 read=399872 Planning Time: 11.230 ms JIT: Functions: 6 Options: Inlining true, Optimization true, Expressions true, Deforming true Timing: Generation 15.707 ms, Inlining 4.688 ms, Optimization 652.021 ms, Emission 939.556 ms, Total 1611.973 ms Execution Time: 15576.516 ms (16 rows) So (ignoring the time for JIT'ting itself) this yields only ~2-3% performance increase... is this because my query is just too simple to actually benefit a lot, meaning the code path for the 'un-JIT' case is already fairly optimal ? Or does JIT'ting actually only have a large impact on the filter/WHERE part of the query but not so much on aggregation / tuple deforming ? Thanks, Tobias
Re: JIT performance question
Hi, On 2019-03-06 18:16:08 +0100, Tobias Gierke wrote: > I was playing around with PG11.2 (i6700k with 16GB RAM, on Ubuntu 18.04, > compiled from sources) and LLVM, trying a CPU-bound query that in my simple > mind should benefit from JIT'ting but (almost) doesn't. > > 1.) Test table with 195 columns of type 'numeric': > > CREATE TABLE test (data0 numeric,data1 numeric,data2 numeric,data3 > numeric,...,data192 numeric,data193 numeric,data194 numeric); > > 2.) bulk-loaded (via COPY) 2 mio. rows of randomly generated data into this > table (and ran vacuum & analyze afterwards) > > 3.) Disable parallel workers to just measure JIT performance via 'set > max_parallel_workers = 0' FWIW, it's better to do that via max_parallel_workers_per_gather in most cases, because creating a parallel plan and then not using that will have its own consequences. > 4.) Execute query without JIT a couple of times to make sure table is in > memory (I had iostat running in the background to verify that actually no > disk access was taking place): There's definitely accesses outside of PG happening here :(. Probably cached at the IO level, but without track_io_timings that's hard to confirm. Presumably that's caused by the sequential scan ringbuffers. I found that forcing the pages to be read in using pg_prewarm gives more measurable results. > So (ignoring the time for JIT'ting itself) this yields only ~2-3% > performance increase... is this because my query is just too simple to > actually benefit a lot, meaning the code path for the 'un-JIT' case is > already fairly optimal ? Or does JIT'ting actually only have a large impact > on the filter/WHERE part of the query but not so much on aggregation / tuple > deforming ? It's hard to know precisely without running a profile of the workload. My suspicion is that the bottleneck in this query is the use of numeric, which has fairly slow operations, including aggregation. And they're too complicated to be inlined. Generally there's definitely advantage in JITing aggregation. There's a lot of further improvements on the table with better JIT code generation, I just haven't gotten around implementing those :( Greetings, Andres Freund
Re: JIT performance question
On 06.03.19 18:42, Andres Freund wrote: It's hard to know precisely without running a profile of the workload. My suspicion is that the bottleneck in this query is the use of numeric, which has fairly slow operations, including aggregation. And they're too complicated to be inlined. Generally there's definitely advantage in JITing aggregation. There's a lot of further improvements on the table with better JIT code generation, I just haven't gotten around implementing those :( Thanks for the quick response ! I think you're onto something with the numeric type. I replaced it with bigint and repeated my test and now I get a nice 40% speedup (I'm again intentionally ignoring the costs for JIT'ting here as I assume a future PostgreSQL version will have some kind of caching for the generated code): Without JIT: QUERY PLAN -- Aggregate (cost=1395000.49..1395000.50 rows=1 width=6240) (actual time=6023.436..6023.436 rows=1 loops=1) Buffers: shared hit=256 read=399744 I/O Timings: read=475.135 -> Seq Scan on test (cost=0.00..42.00 rows=200 width=1560) (actual time=0.035..862.424 rows=200 loops=1) Buffers: shared hit=256 read=399744 I/O Timings: read=475.135 Planning Time: 0.574 ms Execution Time: 6024.298 ms (8 rows) With JIT: QUERY PLAN -- Aggregate (cost=1395000.49..1395000.50 rows=1 width=6240) (actual time=4840.064..4840.064 rows=1 loops=1) Buffers: shared hit=320 read=399680 I/O Timings: read=493.679 -> Seq Scan on test (cost=0.00..42.00 rows=200 width=1560) (actual time=0.090..847.458 rows=200 loops=1) Buffers: shared hit=320 read=399680 I/O Timings: read=493.679 Planning Time: 1.414 ms JIT: Functions: 3 Options: Inlining true, Optimization true, Expressions true, Deforming true Timing: Generation 19.747 ms, Inlining 10.281 ms, Optimization 222.619 ms, Emission 362.862 ms, Total 615.509 ms Execution Time: 4862.113 ms (12 rows) Cheers, Tobias
Re: JIT performance question
Hi, On 2019-03-06 19:21:33 +0100, Tobias Gierke wrote: > On 06.03.19 18:42, Andres Freund wrote: > > > > It's hard to know precisely without running a profile of the > > workload. My suspicion is that the bottleneck in this query is the use > > of numeric, which has fairly slow operations, including aggregation. And > > they're too complicated to be inlined. > > > > Generally there's definitely advantage in JITing aggregation. > > > > There's a lot of further improvements on the table with better JIT code > > generation, I just haven't gotten around implementing those :( > > Thanks for the quick response ! I think you're onto something with the > numeric type. I replaced it with bigint and repeated my test and now I get a > nice 40% speedup Cool. It'd really be worthwhile for somebody to work on adding fastpaths to the numeric code... Greetings, Andres Freund
Performance regressions found using sqlfuzz
Hello, Thanks for the feedback so far! Continue with the previous report, we sharing another four interesting cases that SQLFuzz discovered. (previous discussion: https://www.postgresql.org/message-id/flat/BN6PR07MB3409EE6CAAF8CCF43820AFB9EE670%40BN6PR07MB3409.namprd07.prod.outlook.com#acc68f0fbd8f0b207e162d2dd401d3e8 ) Here’s the time taken to execute four SQL queries on old (v9.5.16) and newer version (v11.2) of PostgreSQL (in milliseconds): +--++-+-+-+ | | scale1 | scale10 | scale50 | scale300| +--++-+-+-+ | Case-5 (v9.5.16) | 39 | 183 |1459 | 11125 | | Case-5 (v11.2) | 73 | 620 |4818 | 16956 | +--++-+-+-+ | Case-6 (v9.5.16) | 46 | 329 | 15096 | 10721 | | Case-6 (v11.2) | 81 | 671 | 64808 | 26919 | +--++-+-+-+ | Case-7 (v9.5.16) | 19 | X | X | X | | Case-7 (v11.2) | 46 | X | X | X | +--++-+-+-+ | Case-8 (v9.5.16) |215 |2108 | 10460 | 64959 | | Case-8 (v11.2) |449 |3997 | 20246 | 130595 | +--++-+-+-+ For each regression, we share: 1) the associated query, 2) the commit that activated it, 3) our high-level analysis, and 4) query execution plans in old and new versions of PostgreSQL. All these regressions are observed on the latest version. (v11.2 and v9.5.16) * You can download the queries at: https://gts3.org/~/jjung/tpcc/case2.tar.gz * You can reproduce the result by using the same setup that we described before: https://www.postgresql.org/message-id/BN6PR07MB3409922471073F2B619A8CA4EE640%40BN6PR07MB3409.namprd07.prod.outlook.com - As Andrew mentioned before, we increased default work_mem to 128MB Best regards, Jinho Jung QUERY 5 EXPLAIN ANALYZE select ref_0.c_zip as c0 from public.customer as ref_0 where EXISTS ( select ref_1.ol_d_id as c10 from public.order_line as ref_1 where (ref_1.ol_o_id <> ref_0.c_d_id) ) - Commit : 7ca25b7 - Our analysis: We believe newer version is slow when the number of rows in the filter is small. - Query execution plans: [Old version] Nested Loop Semi Join (cost=0.00..15317063263550.52 rows=1 width=10) (actual time=0.019..10888.266 rows=900 loops=1) Join Filter: (ref_1.ol_o_id <> ref_0.c_d_id) Rows Removed by Join Filter: 1170 -> Seq Scan on customer ref_0 (cost=0.00..770327.00 rows=900 width=14) (actual time=0.008..7541.944 rows=900 loops=1) -> Materialize (cost=0.00..2813223.52 rows=90017568 width=4) (actual time=0.000..0.000 rows=2 loops=900) -> Seq Scan on order_line ref_1 (cost=0.00..2011503.68 rows=90017568 width=4) (actual time=0.005..0.007 rows=14 loops=1) Planning time: 0.401 ms Execution time: 11125.538 ms [New version] Nested Loop Semi Join (cost=0.00..3409260.89 rows=900 width=10) (actual time=0.033..16732.988 rows=900 loops=1) Join Filter: (ref_1.ol_o_id <> ref_0.c_d_id) Rows Removed by Join Filter: 1170 -> Seq Scan on customer ref_0 (cost=0.00..770327.00 rows=900 width=14) (actual time=0.017..2113.336 rows=900 loops=1) -> Seq Scan on order_line ref_1 (cost=0.00..2011503.68 rows=90017568 width=4) (actual time=0.001..0.001 rows=2 loops=900) Planning Time: 0.615 ms Execution Time: 16956.115 ms # QUERY 6 select distinct ref_0.h_data as c0, ref_0.h_c_id as c1 from public.history as ref_0 left join public.item as ref_1 on (ref_1.i_im_id < -1) where ref_1.i_price is NULL - Our analysis: We think that the 'merge sort' makes slow execution. We are wondering why newer version applies external merge sort in this case. - Commit: 3fc6e2d (big patch) - Query execution plans: [Old version] HashAggregate (cost=1312274.26..1312274.27 rows=1 width=21) (actual time=7288.727..10443.586 rows=900 loops=1) Group Key: ref_0.h_data, ref_0.h_c_id -> Nested Loop Left Join (cost=0.00..1312274.26 rows=1 width=21) (actual time=26.965..2463.231 rows=900 loops=1) Filter: (ref_1.i_price IS NULL) -> Seq Scan on history ref_0 (cost=0.00..184795.61 rows=8999661 width=21) (actual time=0.347..795.936 rows=900 loops=1) -> Materialize (cost=0.00..2521.05 rows=10 width=6) (actual time=0.000..0.000 rows=0 loops=900) -> Seq Scan on item ref_1 (cost=0.00..2521.00 rows=10 width=6) (actual time=26.610..26.610 rows=0 loops=1) Filter: (i_im_id < '-1'::integer) Rows Removed by Filter: 10 Planning time: 1.538 ms Execution time: 10721.259 ms [New version] Unique (cost=1312334.34..1312334.35 rows=1 width=21) (actual time=21444.459..26651.868 rows=900 loops=1) -> Sort
Good afternoon.
Good afternoon. I need to know the commands to display the execution time, CPU usage and memory usage, but through the Postgres console.Thank you.
rusage (Re: Good afternoon.)
Hi, On Wed, Mar 06, 2019 at 04:09:46PM -0400, Kenia Vergara wrote: > Good afternoon. > I need to know the commands to display the execution time, CPU usage and > memory usage, but through the Postgres console.Thank you. Does this do what you want ? Note that the "QUERY STATISTICS" are log output, and not a part of the sql result. $ psql postgres -Atc "SET client_min_messages=log; SET log_statement_stats=on" -c 'explain analyze SELECT max(i) FROM generate_series(1,99)i' SET LOG: QUERY STATISTICS DETAIL: ! system usage stats: ! 0.625402 s user, 0.059799 s system, 0.687496 s elapsed ! [0.629882 s user, 0.059799 s system total] ! 10672 kB max resident size ! 0/27344 [0/27344] filesystem blocks in/out ! 0/1378 [0/2365] page faults/reclaims, 0 [0] swaps ! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent ! 0/167 [2/167] voluntary/involuntary context switches Aggregate (cost=12.50..12.51 rows=1 width=4) (actual time=680.155..680.161 rows=1 loops=1) -> Function Scan on generate_series i (cost=0.00..10.00 rows=1000 width=4) (actual time=253.512..497.462 rows=99 loops=1) Planning Time: 0.227 ms Execution Time: 686.200 ms Justin
Re: rusage (Re: Good afternoon.)
On Wed, Mar 6, 2019 at 11:49 PM Justin Pryzby wrote: > > Hi, > > On Wed, Mar 06, 2019 at 04:09:46PM -0400, Kenia Vergara wrote: > > Good afternoon. > > I need to know the commands to display the execution time, CPU usage and > > memory usage, but through the Postgres console.Thank you. > > Does this do what you want ? Note that the "QUERY STATISTICS" are log output, > and not a part of the sql result. > > $ psql postgres -Atc "SET client_min_messages=log; SET > log_statement_stats=on" -c 'explain analyze SELECT max(i) FROM > generate_series(1,99)i' > SET > LOG: QUERY STATISTICS > DETAIL: ! system usage stats: > ! 0.625402 s user, 0.059799 s system, 0.687496 s elapsed > ! [0.629882 s user, 0.059799 s system total] > ! 10672 kB max resident size > ! 0/27344 [0/27344] filesystem blocks in/out > ! 0/1378 [0/2365] page faults/reclaims, 0 [0] swaps > ! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent > ! 0/167 [2/167] voluntary/involuntary context switches > Aggregate (cost=12.50..12.51 rows=1 width=4) (actual time=680.155..680.161 > rows=1 loops=1) > -> Function Scan on generate_series i (cost=0.00..10.00 rows=1000 > width=4) (actual time=253.512..497.462 rows=99 loops=1) > Planning Time: 0.227 ms > Execution Time: 686.200 ms You could also consider using pg_stat_kcache (https://github.com/powa-team/pg_stat_kcache/) extension, which gather most of those metrics and accumulate them per (queryid, dbid, userid). It requires more configuration, depends on pg_stat_statements extension, and need a postgres restart to activate it though.
