Profiling vs autovacuum (was Re: building 8.3beta2 w/ 'make check' consumes A LOT of disk space)

J=?ISO-8859-1?B?9g==?=rg Beyer <Beyerj(at)students(dot)uni-marburg(dot)de> writes:
> Attached is the log with the "du" output, one block for the build directory,
> one for the installation directory, and one for the 8.3-cluster. Some
> comments are added.

> I suspect gprof to be the culprit, everything gprof related is incredibly
> huge.

Oh, you didn't mention you were using gprof. Yeah, that's definitely
where the problem is:

...
364 ./src/test/regress/tmp_check/data/global
8040 ./src/test/regress/tmp_check/data/gprof/17805
8036 ./src/test/regress/tmp_check/data/gprof/17807
... 150 lines snipped ...
8120 ./src/test/regress/tmp_check/data/gprof/18286
8120 ./src/test/regress/tmp_check/data/gprof/18287
8056 ./src/test/regress/tmp_check/data/gprof/18288
8124 ./src/test/regress/tmp_check/data/gprof/18289
8080 ./src/test/regress/tmp_check/data/gprof/18290
8140 ./src/test/regress/tmp_check/data/gprof/18328
8056 ./src/test/regress/tmp_check/data/gprof/18332
8124 ./src/test/regress/tmp_check/data/gprof/18333
1296368 ./src/test/regress/tmp_check/data/gprof
8 ./src/test/regress/tmp_check/data/pg_clog
...

That is, each one of the 150+ backend processes launched during the
regression test run dropped a separate 8MB gprof file. Presto, 1.2GB
eaten up.

The reason you didn't see this before is that we used to drop gmon.out
files directly in $PGDATA, so there was only one, with different backends
overwriting it as they exited. A patch got put into 8.3 to drop
gmon.out in subdirectories (as you see above) so that the files wouldn't
get overwritten right away. When autovacuum is enabled this is just
about essential if you want to learn anything useful from profiling.

However, accumulation of zillions of gmon.out files is definitely a
downside of the approach; one that I've noticed myself. I've also
noticed that it takes a heck of a long time to rm -rf $PGDATA once
you've built up a few tens of thousands of gprof subdirectories. What's
worse, this accumulation will occur pretty quick even if you're not
doing anything with the DB, because of autovacuum process launches.

I wonder if we need to rein in gmon.out accumulation somehow, and if
so how? This isn't an issue for ordinary users but I can see it
becoming a PITA for developers.

> And I suspect that some kind of permission problem could play a role, too.

The gprof subdirectories are mode 0700 IIRC ... maybe that's causing you
a problem?

regards, tom lane

You see, I'm not a trained developer, I'm just a dumb psychologist,
sometimes poking around w/ things I don't fully understand -- learning by
doing, or die trying ;-) Give me at least three years...

Seriously now, I didn't even think about possible downsides of
--enable-profiling, I just thought profiling could be a good thing to have,
and switched it on. Now I know better and will stay away from it. I used
the last hour to build and install a clean beta2, initialized a fresh
cluster, and everything is O.K. now (at least so far).

My apologies for the noise, and for wasting your time -- you have definitely
more urgent items on your list.

Regards

Joerg Beyer

Am 03.11.2007 23:39 Uhr schrieb Tom Lane (<tgl(at)sss(dot)pgh(dot)pa(dot)us>):

> J=?ISO-8859-1?B?9g==?=rg Beyer <Beyerj(at)students(dot)uni-marburg(dot)de> writes:
>> Attached is the log with the "du" output, one block for the build directory,
>> one for the installation directory, and one for the 8.3-cluster. Some
>> comments are added.
>
>> I suspect gprof to be the culprit, everything gprof related is incredibly
>> huge.
>
> Oh, you didn't mention you were using gprof. Yeah, that's definitely
> where the problem is:
>
> ...
> 364 ./src/test/regress/tmp_check/data/global
> 8040 ./src/test/regress/tmp_check/data/gprof/17805
> 8036 ./src/test/regress/tmp_check/data/gprof/17807
> ... 150 lines snipped ...
> 8120 ./src/test/regress/tmp_check/data/gprof/18286
> 8120 ./src/test/regress/tmp_check/data/gprof/18287
> 8056 ./src/test/regress/tmp_check/data/gprof/18288
> 8124 ./src/test/regress/tmp_check/data/gprof/18289
> 8080 ./src/test/regress/tmp_check/data/gprof/18290
> 8140 ./src/test/regress/tmp_check/data/gprof/18328
> 8056 ./src/test/regress/tmp_check/data/gprof/18332
> 8124 ./src/test/regress/tmp_check/data/gprof/18333
> 1296368 ./src/test/regress/tmp_check/data/gprof
> 8 ./src/test/regress/tmp_check/data/pg_clog
> ...
>
> That is, each one of the 150+ backend processes launched during the
> regression test run dropped a separate 8MB gprof file. Presto, 1.2GB
> eaten up.
>
> The reason you didn't see this before is that we used to drop gmon.out
> files directly in $PGDATA, so there was only one, with different backends
> overwriting it as they exited. A patch got put into 8.3 to drop
> gmon.out in subdirectories (as you see above) so that the files wouldn't
> get overwritten right away. When autovacuum is enabled this is just
> about essential if you want to learn anything useful from profiling.
>
> However, accumulation of zillions of gmon.out files is definitely a
> downside of the approach; one that I've noticed myself. I've also
> noticed that it takes a heck of a long time to rm -rf $PGDATA once
> you've built up a few tens of thousands of gprof subdirectories. What's
> worse, this accumulation will occur pretty quick even if you're not
> doing anything with the DB, because of autovacuum process launches.
>
> I wonder if we need to rein in gmon.out accumulation somehow, and if
> so how? This isn't an issue for ordinary users but I can see it
> becoming a PITA for developers.
>
>> And I suspect that some kind of permission problem could play a role, too.
>
> The gprof subdirectories are mode 0700 IIRC ... maybe that's causing you
> a problem?
>
> regards, tom lane

I wrote:
> However, accumulation of zillions of gmon.out files is definitely a
> downside of the approach; one that I've noticed myself. I've also
> noticed that it takes a heck of a long time to rm -rf $PGDATA once
> you've built up a few tens of thousands of gprof subdirectories. What's
> worse, this accumulation will occur pretty quick even if you're not
> doing anything with the DB, because of autovacuum process launches.

> I wonder if we need to rein in gmon.out accumulation somehow, and if
> so how? This isn't an issue for ordinary users but I can see it
> becoming a PITA for developers.

On reflection, it seems like the worst part of this is the steady
accumulation of gprof files from autovacuum workers, which are unlikely
to be of interest at all (if you want to profile vacuuming, you'd
probably issue manual vacuum commands anyway). So I propose something
like the attached, untested patch to force all AV workers to dump to the
same gmon.out file. Comments?

regards, tom lane

"Tom Lane" <tgl(at)sss(dot)pgh(dot)pa(dot)us> writes:

>> However, accumulation of zillions of gmon.out files is definitely a
>> downside of the approach; one that I've noticed myself.

> Comments?

All I can add is that I've run into this problem myself too.

--
Gregory Stark
EnterpriseDB http://www.enterprisedb.com
Ask me about EnterpriseDB's 24x7 Postgres support!