using PostgreSQL 9.1.2
I'm seeing excessive CPU usage and large amounts of writes to disk from postmaster tasks. This happens even while my application is doing almost nothing (10s of inserts per MINUTE). There are a reasonable number of connections open however.
I've been trying to determine what in my application is causing this. I'm pretty newb with postgresql, and haven't gotten anywhere so far. I've turned on some logging options in my config file, and looked at connections in the pg_stat_activity table, but they are all idle. Yet each connection consumes ~ 50% CPU, and is writing ~15M/s to disk (reading nothing).
I'm basically using the stock postgresql.conf with very little tweaks. I'd appreciate any advice or pointers on what I can do to track this down.
Here is a sample of what top/iotop is showing me:
Cpu(s): 18.9%us, 14.4%sy, 0.0%ni, 53.4%id, 11.8%wa, 0.0%hi, 1.5%si, 0.0%st
Mem: 32865916k total, 7263720k used, 25602196k free, 575608k buffers
Swap: 16777208k total, 0k used, 16777208k free, 4464212k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
17057 postgres 20 0 236m 33m 13m R 45.0 0.1 73:48.78 postmaster
17188 postgres 20 0 219m 15m 11m R 42.3 0.0 61:45.57 postmaster
17963 postgres 20 0 219m 16m 11m R 42.3 0.1 27:15.01 postmaster
17084 postgres 20 0 219m 15m 11m S 41.7 0.0 63:13.64 postmaster
17964 postgres 20 0 219m 17m 12m R 41.7 0.1 27:23.28 postmaster
18688 postgres 20 0 219m 15m 11m R 41.3 0.0 63:46.81 postmaster
17088 postgres 20 0 226m 24m 12m R 41.0 0.1 64:39.63 postmaster
24767 postgres 20 0 219m 17m 12m R 41.0 0.1 24:39.24 postmaster
18660 postgres 20 0 219m 14m 9.9m S 40.7 0.0 60:51.52 postmaster
18664 postgres 20 0 218m 15m 11m S 40.7 0.0 61:39.61 postmaster
17962 postgres 20 0 222m 19m 11m S 40.3 0.1 11:48.79 postmaster
18671 postgres 20 0 219m 14m 9m S 39.4 0.0 60:53.21 postmaster
26168 postgres 20 0 219m 15m 10m S 38.4 0.0 59:04.55 postmaster
Total DISK READ: 0.00 B/s | Total DISK WRITE: 195.97 M/s
TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
17962 be/4 postgres 0.00 B/s 14.83 M/s 0.00 % 0.25 % postgres: aggw aggw [local] idle
17084 be/4 postgres 0.00 B/s 15.53 M/s 0.00 % 0.24 % postgres: aggw aggw [local] idle
17963 be/4 postgres 0.00 B/s 15.00 M/s 0.00 % 0.24 % postgres: aggw aggw [local] idle
17188 be/4 postgres 0.00 B/s 14.80 M/s 0.00 % 0.24 % postgres: aggw aggw [local] idle
17964 be/4 postgres 0.00 B/s 15.50 M/s 0.00 % 0.24 % postgres: aggw aggw [local] idle
18664 be/4 postgres 0.00 B/s 15.13 M/s 0.00 % 0.23 % postgres: aggw aggw [local] idle
17088 be/4 postgres 0.00 B/s 14.71 M/s 0.00 % 0.13 % postgres: aggw aggw [local] idle
18688 be/4 postgres 0.00 B/s 14.72 M/s 0.00 % 0.00 % postgres: aggw aggw [local] idle
24767 be/4 postgres 0.00 B/s 14.93 M/s 0.00 % 0.00 % postgres: aggw aggw [local] idle
18671 be/4 postgres 0.00 B/s 16.14 M/s 0.00 % 0.00 % postgres: aggw aggw [local] idle
17057 be/4 postgres 0.00 B/s 13.58 M/s 0.00 % 0.00 % postgres: aggw aggw [local] idle
26168 be/4 postgres 0.00 B/s 15.50 M/s 0.00 % 0.00 % postgres: aggw aggw [local] idle
18660 be/4 postgres 0.00 B/s 15.85 M/s 0.00 % 0.00 % postgres: aggw aggw [local] idle
Update: A lot of the file writing seems to be to some temporary (?) files in the $PG_DATA/base/ directory. My understanding of the file structure here is that each table is basically stored as a file whose name is the OID of the table. However, there are tons of files named tnn_nnnnnnn
, and it is these files that appear to be written to (perhaps written over) constantly. What are these files for? There is ~4700 of the files, and all are 8K in size:
-rw-------. 1 postgres postgres 8192 Jul 3 23:08 t12_1430975
-rw-------. 1 postgres postgres 8192 Jul 3 23:08 t16_1432736
-rw-------. 1 postgres postgres 8192 Jul 3 23:08 t28_1439066
-rw-------. 1 postgres postgres 8192 Jul 3 23:08 t24_1436243
-rw-------. 1 postgres postgres 8192 Jul 3 23:08 t24_1436210
-rw-------. 1 postgres postgres 8192 Jul 3 23:08 t19_1393372
-rw-------. 1 postgres postgres 8192 Jul 3 23:08 t28_1439051
-rw-------. 1 postgres postgres 8192 Jul 3 23:08 t8_1430334
Update: Running strace on the postmaster processes basically shows a lot of file I/O stuff:
open("base/16388/t24_1435947_fsm", O_RDWR) = -1 ENOENT (No such file or directory)
open("base/16388/t24_1435947_vm", O_RDWR) = -1 ENOENT (No such file or directory)
open("base/16388/t24_1435947", O_RDWR) = 9
lseek(9, 0, SEEK_END) = 8192
ftruncate(9, 0) = 0
lseek(9, 0, SEEK_END) = 0
open("base/16388/t24_1435941", O_RDWR) = 18
lseek(18, 0, SEEK_END) = 0
write(9, "\0\0\0\0\0\0\0\0\1\0\0\0000\0\360\37\360\37\4 \0\0\0\0b1\5\0\2\0\0\0"..., 8192) = 8192
lseek(18, 0, SEEK_END) = 0
close(9) = 0
open("base/16388/t24_1435947", O_RDWR) = 9
lseek(9, 0, SEEK_END) = 8192
close(18) = 0
close(9) = 0
open("base/16388/t24_1435944_fsm", O_RDWR) = -1 ENOENT (No such file or directory)
open("base/16388/t24_1435944_vm", O_RDWR) = -1 ENOENT (No such file or directory)
open("base/16388/t24_1435944", O_RDWR) = 9
lseek(9, 0, SEEK_END) = 0
close(9) = 0
Update: So this problem does appear to be everything to do with temporary tables. We changed our setup so the temporary tables are 'regular' tables, and all the disk activity went away, and performance is back to where I expected it to be. Now, this change was just a quick and dirty test: if we are really going to change to use regular tables, we have issues with concurrency, and cleanup. Are temporary tables really that evil, or are we abusing them?
Update: Some more background. I'm making use of a in-house developed statement based replication middleware. It's quite mature and has been in use on a number of projects over a number of years, but using MySQL. We've only been working with PostgreSQL for the last year or two. We were essentially using the temporary tables as part of the replication mechanism. Whenever a new connection is established, we create a temporary table for each table in the database. With 10-20 (long-lived) connections and ~50 tables, this can amount to a lot of temporary tables. All temporary tables were created with:
CREATE TEMPORARY TABLE... ON COMMIT DELETE ROWS;
The semantics of temporary tables fit very well with our replication scheme, and simplified a lot of the code we had to use for MySQL, but it looks like the implementation didn't fair as well. From the bit of research I've done, I don't think temporary tables were really meant for the function we were using them for.
I'm not the in-house expert (not even close) on this subject, just a user of it, so my explanation might not be 100% accurate, but I think it's pretty close.