Re: UPDATEDs slowing SELECTs in a fully cached database - Mailing list pgsql-performance
From | lars |
---|---|
Subject | Re: UPDATEDs slowing SELECTs in a fully cached database |
Date | |
Msg-id | 4E1DDFA7.9070007@yahoo.com Whole thread Raw |
In response to | Re: UPDATEDs slowing SELECTs in a fully cached database (Tom Lane <tgl@sss.pgh.pa.us>) |
Responses |
Re: UPDATEDs slowing SELECTs in a fully cached database
(Merlin Moncure <mmoncure@gmail.com>)
Re: UPDATEDs slowing SELECTs in a fully cached database (Jeff Janes <jeff.janes@gmail.com>) |
List | pgsql-performance |
On 07/13/2011 08:17 AM, Tom Lane wrote: > "Kevin Grittner"<Kevin.Grittner@wicourts.gov> writes: >> ... Jeff does raise a good point, though -- it seems odd >> that WAL-logging of this pruning would need to be synchronous. > Yeah, we need to get to the bottom of that. If there's enough > shared_buffer space then it shouldn't be. This thread has gotten long, let me try to compile all the relevant information in one email. \d test Table "lars.test" Column | Type | Modifiers --------------+---------------+----------- tenant | character(15) | created_by | character(15) | created_date | date | Indexes: "i1" btree (tenant) "i11" btree (created_by) -- Table is populated like this: ------------------------------------ create table test(tenant char(15), created_by char(15), created_date date); insert into test values('x', 'y','2011-6-30'); insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; -- 256k rows update test set tenant = lpad((random()*10000)::int::text,15,'0'), created_by = lpad((random()*10000)::int::text,15,'0'); insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; insert into test select * from test; -- 32m rows create index i1 on test(tenant); create index i11 on test(created_by); vacuum analyze; -- I doubt it needs that many rows. => SELECT 'version'::text AS "name", version() AS "current_setting" UNION ALL SELECT name,current_setting(name) FROM pg_settings WHERE NOT source='default' AND NOT name IN ('config_file','data_directory','hba_file','ident_file', 'log_timezone','DateStyle','lc_messages','lc_monetary', 'lc_numeric','lc_time','timezone_abbreviations', 'default_text_search_config','application_name', 'transaction_deferrable','transaction_isolation', 'transaction_read_only'); name | current_setting ------------------------------+------------------------------------------------------------------------------------------------------------------ version | PostgreSQL 9.1beta2 on x86_64-unknown-linux-gnu, compiled by gcc (GCC) 4.4.4 20100726 (Red Hat 4.4.4-13), 64-bit bgwriter_delay | 10ms bgwriter_lru_maxpages | 1000 checkpoint_completion_target | 0.9 checkpoint_segments | 128 client_encoding | UTF8 effective_cache_size | 64GB lc_collate | en_US.UTF-8 lc_ctype | en_US.UTF-8 log_checkpoints | on log_line_prefix | %m maintenance_work_mem | 2GB max_connections | 100 max_stack_depth | 2MB server_encoding | UTF8 shared_buffers | 20GB TimeZone | UTC wal_buffers | 16MB work_mem | 1GB (19 rows) -- Now: ---------- => select count(*) from test where tenant = '000000000000001' and created_date = '2011-6-30'; count ------- 3712 (1 row) => SELECT c.relname, isdirty, count(*) * 8192 / 1024/1024 AS buffers FROM pg_buffercache b, pg_class c WHERE b.relfilenode = pg_relation_filenode(c.oid) AND b.reldatabase IN (0, (SELECT oid FROM pg_database WHERE datname = current_database())) GROUP BY c.relname,isdirty ORDER BY 3 DESC LIMIT 6; relname | isdirty | buffers -------------------------------+---------+--------- test | t | 14 pg_opclass_oid_index | f | 0 pg_rewrite | f | 0 i11 | t | 0 pg_rewrite_rel_rulename_index | f | 0 pg_constraint | f | 0 -- Just started the server, no nothing else is cached, yet -- it doesn't matter if that update is executed by the same or another backend. => update test set created_by = '000000000000001' where tenant = '000000000000001'; UPDATE 3712 => select count(*) from test where tenant = '000000000000001' and created_date = '2011-6-30'; count ------- 3712 (1 row) strace now shows: ------------------------- Q\0\0\0_select count(*) from test w"..., 8192, 0, NULL, NULL) = 96 gettimeofday({1310579341, 854669}, NULL) = 0 lseek(38, 0, SEEK_END) = 187465728 lseek(41, 0, SEEK_END) = 115564544 lseek(43, 0, SEEK_END) = 101040128 lseek(38, 0, SEEK_END) = 187465728 brk(0x1a85000) = 0x1a85000 brk(0x1a5d000) = 0x1a5d000 lseek(52, 12443648, SEEK_SET) = 12443648 write(52, "f\320\1\0\1\0\0\0\276\0\0\0\0\340\275\0016\0\0\0S\0\0\0\4\0cY\3\0\0\0"..., 122880) = 122880 fdatasync(52) = 0 semop(688135, {{9, 1, 0}}, 1) = 0 gettimeofday({1310579341, 889163}, NULL) = 0 sendto(5, "\2\0\0\0\350\0\0\0\1@\0\0\2\0\0\0\1\0\0\0\0\0\0\0\376\200\0\0<\0\2\0"..., 232, 0, NULL, 0) = 232 sendto(6, "T\0\0\0\36\0\1count\0\0\0\0\0\0\0\0\0\0\24\0\10\377\377\377\377\0\0D"..., 66, 0, NULL, 0) = 66 -- fd 52 was opened earlier to the WAL file in pg_xlog. => select count(*) from test where tenant = '000000000000001' and created_date = '2011-6-30'; count ------- 3712 (1 row) now strace shows: ------------------------- Q\0\0\0_select count(*) from test w"..., 8192, 0, NULL, NULL) = 96 gettimeofday({1310579380, 862637}, NULL) = 0 lseek(38, 0, SEEK_END) = 187465728 lseek(41, 0, SEEK_END) = 115564544 lseek(43, 0, SEEK_END) = 101040128 lseek(38, 0, SEEK_END) = 187465728 gettimeofday({1310579380, 868149}, NULL) = 0 sendto(5, "\2\0\0\0\350\0\0\0\1@\0\0\2\0\0\0\1\0\0\0\0\0\0\0\376\200\0\0@\0\2\0"..., 232, 0, NULL, 0) = 232 sendto(6, "T\0\0\0\36\0\1count\0\0\0\0\0\0\0\0\0\0\24\0\10\377\377\377\377\0\0D"..., 66, 0, NULL, 0) = 66 => update test set created_by = '000000000000001' where tenant = '000000000000001'; UPDATE 3712 => select count(*) from test where tenant = '000000000000001' and created_date = '2011-6-30'; count ------- 3712 (1 row) strace again indicates that a WAL log is written by the backend by the select: --------------------------------------------------------------------------------------- Q\0\0\0_select count(*) from test w"..., 8192, 0, NULL, NULL) = 96 gettimeofday({1310579663, 890641}, NULL) = 0 lseek(38, 0, SEEK_END) = 187596800 lseek(41, 0, SEEK_END) = 115638272 lseek(43, 0, SEEK_END) = 101122048 lseek(38, 0, SEEK_END) = 187596800 brk(0x1a85000) = 0x1a85000 brk(0x1a5d000) = 0x1a5d000 semop(688135, {{3, -1, 0}}, 1) = 0 lseek(52, 10223616, SEEK_SET) = 10223616 write(52, "f\320\1\0\1\0\0\0\276\0\0\0\0\0\234\2\16\0\0\0C(\0\0\1\0\0\0~\0\177\0"..., 16384) = 16384 fdatasync(52) = 0 gettimeofday({1310579663, 921932}, NULL) = 0 sendto(5, "\2\0\0\0\350\0\0\0\1@\0\0\2\0\0\0\1\0\0\0\0\0\0\0\376\200\0\0?\0\2\0"..., 232, 0, NULL, 0) = 232 sendto(6, "T\0\0\0\36\0\1count\0\0\0\0\0\0\0\0\0\0\24\0\10\377\377\377\377\0\0D"..., 66, 0, NULL, 0) = 66 => explain (analyze on, buffers on) select count(*) from test where tenant = '000000000000001' and created_date = '2011-6-30'; QUERY PLAN -------------------------------------------------------------------------------- ----------------------------------------- Aggregate (cost=12284.65..12284.66 rows=1 width=0) (actual time=9.150..9.150 r ows=1 loops=1) Buffers: shared hit=1976 -> Bitmap Heap Scan on test (cost=91.78..12276.35 rows=3319 width=0) (actua l time=2.338..6.866 rows=3712 loops=1) Recheck Cond: (tenant = '000000000000001'::bpchar) Filter: (created_date = '2011-06-30'::date) Buffers: shared hit=1976 -> Bitmap Index Scan on i1 (cost=0.00..90.95 rows=3319 width=0) (actu al time=2.063..2.063 rows=15179 loops=1) Index Cond: (tenant = '000000000000001'::bpchar) Buffers: shared hit=98 Total runtime: 9.206 ms (10 rows) => update test set created_by = '000000000000001' where tenant = '000000000000001'; UPDATE 3712 => explain (analyze on, buffers on) select count(*) from test where tenant = '000000000000001' and created_date = '2011-6-30'; QUERY PLAN -------------------------------------------------------------------------------- ----------------------------------------- Aggregate (cost=12284.68..12284.69 rows=1 width=0) (actual time=30.738..30.739 rows=1 loops=1) Buffers: shared hit=2001 -> Bitmap Heap Scan on test (cost=91.78..12276.38 rows=3319 width=0) (actua l time=2.589..28.361 rows=3712 loops=1) Recheck Cond: (tenant = '000000000000001'::bpchar) Filter: (created_date = '2011-06-30'::date) Buffers: shared hit=2001 -> Bitmap Index Scan on i1 (cost=0.00..90.95 rows=3319 width=0) (actu al time=2.301..2.301 rows=17123 loops=1) Index Cond: (tenant = '000000000000001'::bpchar) Buffers: shared hit=107 Total runtime: 30.785 ms (10 rows) ---- There seems to be definitely something funky going on. Since created_by is indexed it shouldn't do any HOT logic. Is there any other information that I can provide? I'm happy to recompile with a patch applied, etc. Thanks. -- Lars
pgsql-performance by date: