Huge number of disk writes after migration to 8.1

"Marcin" <migor@op.pl> wrote

I suffer from huge increase in number of disk writes after migration
from 8.0.3 to 8.1.2. The average number of sectors written increased 10
times and transfer stays at 20MB of writes per second during work hours
(with 20% cpu time wasted in iowait). The number of queries lasting more
than 300ms increased thrice.

AFAICS the difference maybe related to this between 8.0 and 8.1 is the
introduction of autovacuum. But seems you didn't turn it on. Do you observed
only writes increased or both read/write? If the latter, that might be an
unoptimized query plan invloves seqscan ... Can you find out what's the
writes on?

Regards,
Qingqing

On Mon, Jan 16, 2006 at 05:09:18PM -0500, Qingqing Zhou wrote:

AFAICS the difference maybe related to this between 8.0 and 8.1 is the
introduction of autovacuum. But seems you didn't turn it on. Do you observed
only writes increased or both read/write? If the latter, that might be an
unoptimized query plan invloves seqscan ... Can you find out what's the
writes on?

Autovacuum is turned off.
The reads remains on very, very low level. According to monitored values
from /sys/block/md?/stat (confirmed by iostat output) the reads rate
stays at 70-80 blocks per second, while the writes rate keeps at 20000 blocks.

However, I found something interesting.

Playing with postgresql.conf I changed "stats_command_string" to off,
reloaded config, and restarted connection from applications (the postgresql
wasn't restarted). The write rate immediately drops down, and is now
at 8000-9000 blocks per second (which is still 4-5 times more than in
8.0.3).

Looking at the CPU usage in top, I found strange stats for postgres processes
(ps aux dump):
11:25 /usr/lib/postgresql/bin/postmaster
0:25 postgres: writer process
4:21 postgres: stats buffer process
201:46 postgres: stats collector process
(PostgreSQL is running for two and a half day now).

I found some ps -aux dumps from last week, (with 8.0.3 and
stats_command_string enabled) and CPU usage was completely different:
31:07 /usr/lib/postgresql/bin/postmaster
175:10 postgres: writer process
30:55 postgres: stats buffer process
58:43 postgres: stats collector process
(PostgreSQL was running for 12 days).

It seems that some changes to stats collector introduced in 8.1 are now eating
my CPU power, and probably also the (I)/O bandwidth. :(

Thanks for help,
--
Marcin

Marcin <migor@op.pl> writes:

It seems that some changes to stats collector introduced in 8.1 are
now eating my CPU power, and probably also the (I)/O bandwidth. :(

Yeah, something wrong there :-(. What did you say your platform was
exactly? Would you strace the collector process, and send maybe ten K
or so of trace output to pgsql-bugs? It's probably not appropriate for
pgsql-general.

regards, tom lane

On Tue, 17 Jan 2006, Marcin wrote:

Playing with postgresql.conf I changed "stats_command_string" to off,
reloaded config, and restarted connection from applications (the
postgresql
wasn't restarted). The write rate immediately drops down, and is now
at 8000-9000 blocks per second (which is still 4-5 times more than in
8.0.3).

A similar problem was reported before:

http://archives.postgresql.org/pgsql-admin/2005-12/msg00266.php

But we conclude that's not related to pgstats. See if that's related to
your situation.

Regards,
Qingqing

Short introduction:
After migration from 8.0.3 to 8.1.2 I noticed huge increase in number of
bytes written to disk. I think it's caused by stats collector process,
but I may be wrong.

Some details:

1. Hardware: 2*Opteron 275, Tyan motherboard, 8GBs DDR ECC RAM, 2*SCSI
73GB 15k RPM drives.

2. Software: Debian Sarge amd64, kernel 2.6.12.5, PostgreSQL 8.1.2 built
from sources with:
./configure --host=x86_64-linux --build=x86_64-linux --enable-recode
--enable-nls --enable-integer-datetimes --disable-debug --disable-rpath
--without-tcl --without-perl --without-python --without-pam
--with-openssl --with-gnu-ld --without-krb5 --without-tk --without-java
--with-maxbackends=1024 --with-pgport=5432 --enable-thread-safety
gcc (GCC) 3.4.4 20050314 (prerelease) (Debian 3.4.3-13)
Note: Exactly the same environment were used to build previous 8.0.3
version.

3. 14-20GBs of data, ~120 DBs, ~60 used simultaneously, 1000-2000 tables
in each DB, 200-250 connections. Queries: 120-160 selects, 18-25
INSERT/UPDATE/DELETE per seconds during work hours.

4. postgresql.conf:
shared_buffers=30000
max_prepared_transactions=0 #(line added after migration 8.1)
work_mem=256000
maintenance_work_mem=512000
max_fsm_pages=1800000
max_fsm_relations=80000

fsync_on

checkpoints_segments=12
effective_cache_size=800000

log_destination='syslog'
client_min_messages=warning
log_min_messages=notice
log_min_duration_statement=200

stats_start_collector = on
stats_command_string = on

5. The writes rate stays at 20MB/s during work hours, the reads rate is
unnoticeable (60KB-100KB/s). With 8.0.3 the writes rate stayed at 1-1,5MB/s.
6. After disabling stats_command_string, the writes rate stepped down to
~10MB/s
7. No autovacuum, VACUUM FULL is performed every night, and VACUUM
ANALYZE is performed every 30 minutes on few critical tables.
8. About 2000 (with stats_command_string enabled) queries lasts longer
than 300ms, after disabling the stats_command_string it dropped to 900
(it used to be ~500-600 with 8.0.3). The duration of the longest query
in last two day was 18s.
9. ps aux shows:
208:39 postgres: stats collector process
12:33 /usr/lib/postgresql/bin/postmaster
0:28 postgres: writer process
4:23 postgres: stats buffer process
after three days run. Two days with stats_command_string enabled
resulted in ~180 minutes of CPU time utilized by stats collector,
while during near one day with disabled command_string stats collector
utilized only 58 minutes.

With 8.0.3 it used to be like that:
31:07 /usr/lib/postgresql/bin/postmaster
175:10 postgres: writer process
30:55 postgres: stats buffer process
58:43 postgres: stats collector process
(PostgreSQL was running for almost 12 days).

Tom Lane wrote:

Yeah, something wrong there :-(. What did you say your platform was
exactly? Would you strace the collector process, and send maybe ten K
or so of trace output to pgsql-bugs? It's probably not appropriate for
pgsql-general.

The gzipped strace output of collector is attached. Unfortunately, the
server wasn't very busy (just 10-20% utilization).
The stats_command_string was disabled during stracing.

Thanks in advance
--
Marcin

Qingqing Zhou wrote:

A similar problem was reported before:

http://archives.postgresql.org/pgsql-admin/2005-12/msg00266.php

But we conclude that's not related to pgstats. See if that's related to
your situation.

Unfortunately, I don't think so. The 8.0.3 run just fine. And I don't
see any pgsql_tmp files. The problems started after migration to 8.1.2.
I posted to pgsql-bugs, following Tom suggestion.
BTW, I made some benchmarks on test machine (which is 32bit 2xPIII
1.4GHz) with pgbench and I was quite amazed:
pgbench -S -c 50 -t 10000 -v pgbench
with stats collector disabled resulted in:
tps = 3178.346439 (including connections establishing)
tps = 3183.360731 (excluding connections establishing)

with stats collector enabled, but stats_command_prompt disabled:
tps = 3143.376908 (including connections establishing)
tps = 3147.564695 (excluding connections establishing)

and with stats_command_prompt enabled:
tps = 2446.136610 (including connections establishing)
tps = 2448.785260 (excluding connections establishing)

However, I didn't notice any suspicious write activity.

Thanks for suggestion,
--
Marcin

Marcin <migor@op.pl> writes:

After migration from 8.0.3 to 8.1.2 I noticed huge increase in number of
bytes written to disk. I think it's caused by stats collector process,
but I may be wrong.

The strace output shows that the collector is writing about 8.5MB to the
stats display file on each cycle. That seems like rather a lot :-(.
A quick comparison of the 8.0 and HEAD versions of pgstats says that the
8.1 file format should be slightly bulkier than 8.0, but not a lot so.

The first theory that comes to mind is that 8.1 is somehow failing to
discard dead table entries and continues to write them when no longer
needed.

Could you send me the following data (off-list since we know it will be
several meg):

* A copy of $PGDATA/global/pgstat.stat (note this file is rewritten
every half second, so copy it before you start packing it into a
message)

* The output of "ps auxww | grep postgres", taken at the same time you
copy pgstat.stat (or as close as you can easily get, anyway).

This does not need to be done under particularly heavy load, in fact
light load would be better since it'd be more obvious if there are
too many backend entries.

Thanks!

regards, tom lane

Marcin <migor@op.pl> writes:

Attached you'll find the archive with data you've asked.

Well, breaking down the contents of the stats file I find:
190 backends (218880 bytes)
118 databases (8496 bytes)
81952 tables (8523008 bytes)
And the ps listing shows there actually are about 190 live backends,
so the idea about leaked backend stats entries is clearly wrong.

The per-table data is 104 bytes/table, up from 80 in 8.0, so that's
a noticeable increase but hardly a killer. What I have to conclude
is that 8.1 is tracking stats for a lot more tables than 8.0 was.
(Do you happen to have a number for the size of the stats file in
the 8.0 installation? I don't need to see its contents, I just want
to know how big it is.)

Do you actually have 81952 tables in the installation? Maybe we are
looking at a table-level leak. Do you have autovacuum on where it was
not in 8.0? Maybe that's causing it.

regards, tom lane

Marcin <migor@op.pl> writes:

Autovacuum is off.
The VACUUM FULL bottom line is:
INFO: free space map contains 59842 pages in 25371 relations
DETAIL: A total of 426720 page slots are in use (including overhead).
426720 page slots are required to track all free space.

And the quick iterations for all the DBs with psql -t -c "\dt" shows
67654 rows.

So there's not 81952, BUT, the tables are created (and dropped) quite
often during the work hours (and they're regular, not TEMPORARY tables).
I also find out, that there were 11170 tables created (and most of them
dropped) today.

Looking at the code, stats entries for dropped tables are cleaned out
only when a VACUUM command is done; which is something we probably ought
to change. However, that's always been the case, so I don't understand
why your stats file is so much bigger in 8.1. Have you changed your
vacuuming strategy at all since the 8.0 installation? Perhaps row or
block statistics weren't enabled in the 8.0 installation and are now?

regards, tom lane

Tom Lane wrote:

Marcin <migor@op.pl> writes:

So there's not 81952, BUT, the tables are created (and dropped) quite
often during the work hours (and they're regular, not TEMPORARY tables).
I also find out, that there were 11170 tables created (and most of them
dropped) today.

Looking at the code, stats entries for dropped tables are cleaned out
only when a VACUUM command is done; which is something we probably ought
to change.

I was going to ask if you were confusing pgstat_vacuum_tabstat with a
VACUUM command, when I noticed that only in vacuum() is that function
called! This surprised me and I agree that it should be changed. I'm
not sure what would be a more appropiate place to call it, however.

Maybe in heap_drop_with_catalog() we could place a call, or a limited
version that'd only "vacuum" the table being dropped.

--
Alvaro Herrera http://www.amazon.com/gp/registry/DXLWNGRJD34J
"Having your biases confirmed independently is how scientific progress is
made, and hence made our great society what it is today" (Mary Gardiner)

Alvaro Herrera <alvherre@commandprompt.com> writes:

Tom Lane wrote:

Looking at the code, stats entries for dropped tables are cleaned out
only when a VACUUM command is done; which is something we probably ought
to change.

I was going to ask if you were confusing pgstat_vacuum_tabstat with a
VACUUM command, when I noticed that only in vacuum() is that function
called! This surprised me and I agree that it should be changed. I'm
not sure what would be a more appropiate place to call it, however.

I don't have a problem with that. What I'm thinking is that a DROP
TABLE command should issue a tabpurge message for the specific table
(or index) being zapped. We still need vacuum_tabstat as a backstop
in case the tabpurge message gets lost, though.

Another thought is that in autovacuum, pgstat_vacuum_tabstat is really
called too often: once per autovac cycle would be sufficient, but
instead it's repeated for each table we vacuum.

regards, tom lane

On Tue, Jan 17, 2006 at 05:12:09PM -0500, Tom Lane wrote:

However, that's always been the case, so I don't understand
why your stats file is so much bigger in 8.1. Have you changed your
vacuuming strategy at all since the 8.0 installation? Perhaps row or
block statistics weren't enabled in the 8.0 installation and are now?

The only change was the upgrade to 8.1. I run VACUUM FULL everyday, and
double checked that it finished succesfully in last two days.
The block and row statistics are disabled:
stats_start_collector = on
stats_command_string = off
stats_block_level = off
stats_row_level = off
stats_reset_on_server_start = off

I have no idea, why the pgstat.stat is so large. I just shutdown the
idle backend connection, so there're only 30 left (instead of 200),
and the pgstat size decreases by 200KB from 8.8 to 8.6 MB. The lowest size
of pgstat in last six hours was 8.5 MB.

--
Marcin

Marcin <migor@op.pl> writes:

On Tue, Jan 17, 2006 at 05:12:09PM -0500, Tom Lane wrote:

However, that's always been the case, so I don't understand
why your stats file is so much bigger in 8.1. Have you changed your
vacuuming strategy at all since the 8.0 installation? Perhaps row or
block statistics weren't enabled in the 8.0 installation and are now?

The only change was the upgrade to 8.1. I run VACUUM FULL everyday, and
double checked that it finished succesfully in last two days.
The block and row statistics are disabled:
stats_start_collector = on
stats_command_string = off
stats_block_level = off
stats_row_level = off
stats_reset_on_server_start = off

Stats off and it's still bloating the file??

[ studies code... ] I see the culprit: it's the pgstat_report_vacuum
and pgstat_report_analyze routines that were added in 8.1. Those send
messages unconditionally, meaning that the collector will create table
entries for every table during a database-wide vacuum, even with stats
turned off.

This seems like a bad idea. Given the nature of what's counted, I think
that treating these messages as "row level" stats would be appropriate.
Alvaro, what do you think?

regards, tom lane

Tom Lane wrote:

Stats off and it's still bloating the file??

[ studies code... ] I see the culprit: it's the pgstat_report_vacuum
and pgstat_report_analyze routines that were added in 8.1. Those send
messages unconditionally, meaning that the collector will create table
entries for every table during a database-wide vacuum, even with stats
turned off.

This seems like a bad idea.

Sorry, clearly my bug :-(

Given the nature of what's counted, I think that treating these
messages as "row level" stats would be appropriate. Alvaro, what do
you think?

Yeah, row level seems appropiate for what we use it. I'll take care of
it, unless you want to do it.

--
Alvaro Herrera http://www.PlanetPostgreSQL.org
<inflex> really, I see PHP as like a strange amalgamation of C, Perl, Shell
<crab> inflex: you know that "amalgam" means "mixture with mercury",
more or less, right?
<crab> i.e., "deadly poison"

Do you mean stats_command_string? I have seen degradation in using that
and am working on a patch for 8.2 to fix it.

---------------------------------------------------------------------------

Marcin wrote:

Qingqing Zhou wrote:

A similar problem was reported before:

http://archives.postgresql.org/pgsql-admin/2005-12/msg00266.php

But we conclude that's not related to pgstats. See if that's related to
your situation.

Unfortunately, I don't think so. The 8.0.3 run just fine. And I don't
see any pgsql_tmp files. The problems started after migration to 8.1.2.
I posted to pgsql-bugs, following Tom suggestion.
BTW, I made some benchmarks on test machine (which is 32bit 2xPIII
1.4GHz) with pgbench and I was quite amazed:
pgbench -S -c 50 -t 10000 -v pgbench
with stats collector disabled resulted in:
tps = 3178.346439 (including connections establishing)
tps = 3183.360731 (excluding connections establishing)

with stats collector enabled, but stats_command_prompt disabled:
tps = 3143.376908 (including connections establishing)
tps = 3147.564695 (excluding connections establishing)

and with stats_command_prompt enabled:
tps = 2446.136610 (including connections establishing)
tps = 2448.785260 (excluding connections establishing)

However, I didn't notice any suspicious write activity.

Thanks for suggestion,
--
Marcin

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073

Alvaro Herrera <alvherre@alvh.no-ip.org> writes:

Yeah, row level seems appropiate for what we use it. I'll take care of
it, unless you want to do it.

I'll fix it --- I want to put in an immediate tabpurge on drop, too.

regards, tom lane

Alvaro Herrera <alvherre@alvh.no-ip.org> writes:

Tom Lane wrote:

Given the nature of what's counted, I think that treating these
messages as "row level" stats would be appropriate. Alvaro, what do
you think?

Yeah, row level seems appropiate for what we use it. I'll take care of
it, unless you want to do it.

Actually, there's another problem here: if we do have row-level stats
turned on, a manual "VACUUM" command will still cause the set of tables
listed in the stats file to grow to include every table in the DB,
whether or not anything interesting is happening to that table. I think
this is probably undesirable. I'm tempted to change pgstat_recv_vacuum
and pgstat_recv_analyze so that they will not create new hash entries,
but only insert the row count if the hash entry already exists. I am a
bit worried that I might be missing something about possible
interactions with autovacuum though. I see that autovac skips vacuuming
tables that have no hash entry ... is there some circular reasoning
going on there?

regards, tom lane

Bruce Momjian wrote:

Do you mean stats_command_string? I have seen degradation in using that

Yes, I meant stats_command_string, sorry for my stupid mistake.

and am working on a patch for 8.2 to fix it.

That's nice, because it's very helpful.

Thanks for response,
--
Marcin

Tom Lane wrote:

Actually, there's another problem here: if we do have row-level stats
turned on, a manual "VACUUM" command will still cause the set of tables
listed in the stats file to grow to include every table in the DB,
whether or not anything interesting is happening to that table. I think
this is probably undesirable. I'm tempted to change pgstat_recv_vacuum
and pgstat_recv_analyze so that they will not create new hash entries,
but only insert the row count if the hash entry already exists. I am a
bit worried that I might be missing something about possible
interactions with autovacuum though. I see that autovac skips vacuuming
tables that have no hash entry ... is there some circular reasoning
going on there?

The idea was that autovac should skip tables for which it doesn't have
info, because it can't decide and we chose to err on the side of
caution. However, after a vacuum or analyze we do have info about the
table, which is what we store in the pgstat_recv functions
inconditionally. Thus the next autovacuum is able to make an informed
decision about this table.

The principles are: 1) store as much information as possible,
2) autovacuum should act iff it has information.

I don't think this is a bug, but I'm not dead set on it if you want to
change this behavior.

--
Alvaro Herrera http://www.amazon.com/gp/registry/DXLWNGRJD34J
"The first of April is the day we remember what we are
the other 364 days of the year" (Mark Twain)