Re: Momjian "Support Functions" section: possible typo and question

Hi everybody,
I just vacuumed and vacuumed analyzed my database. Now, I am trying to
execute a view, which was perfectly working before, but it seems to be
very slow. It was sitting there for 10 mins before I cancelled it.
Usually it was taking on the order of 5 secs to execute the view.
I just recreated the view, but the problem still persists.
Here is what EXPLAIN tells me:
EXPLAIN select * from progress_report;
Subquery Scan progress_report (cost=16386.56..16386.56 rows=2
width=128)
-> Sort (cost=16386.56..16386.56 rows=2 width=128)
-> Nested Loop (cost=16299.45..16386.55 rows=2 width=128)

How can I "restore" the "before-the-vacuum" performance?
thanks,

Oleg

Oleg,

> I just vacuumed and vacuumed analyzed my database. Now, I am trying
> to
> execute a view, which was perfectly working before, but it seems to
> be
> very slow. It was sitting there for 10 mins before I cancelled it.
> Usually it was taking on the order of 5 secs to execute the view.
> I just recreated the view, but the problem still persists.
> Here is what EXPLAIN tells me:
> EXPLAIN select * from progress_report;
> Subquery Scan progress_report (cost=16386.56..16386.56 rows=2
> width=128)
> -> Sort (cost=16386.56..16386.56 rows=2 width=128)
> -> Nested Loop (cost=16299.45..16386.55 rows=2 width=128)
>
> How can I "restore" the "before-the-vacuum" performance?
> thanks,

This is not normal. I suspect that you have something wrong with your
Postgres system configuration or your system in general.

Please post:
1. Your postgres version
2. Your platform (OS and version)
3. Your hardware statistics, including:
Processor & RAM
Disk space free on your root drive and postgres drive
4. The view definition
5. Row counts on all tables involved in the view, as well as whether
those tables have very large text fields or BLOBs.
6. Finally, check your Postgres log to see if VACUUM raised any errors,
and to see if selecting the view causes any errors.

-Josh Berkus

______AGLIO DATABASE SOLUTIONS___________________________
Josh Berkus
Complete information technology josh(at)agliodbs(dot)com
and data management solutions (415) 565-7293
for law firms, small businesses fax 621-2533
and non-profit organizations. San Francisco

Hi Oleg,
At 19:28 -0700 12/14/2001, Oleg Lebedev wrote:
>Hi everybody,
>I just vacuumed and vacuumed analyzed my database. Now, I am trying to
>execute a view, which was perfectly working before, but it seems to be
>very slow. It was sitting there for 10 mins before I cancelled it.
>Usually it was taking on the order of 5 secs to execute the view.
>I just recreated the view, but the problem still persists.
>Here is what EXPLAIN tells me:
>EXPLAIN select * from progress_report;
>Subquery Scan progress_report (cost=16386.56..16386.56 rows=2
>width=128)
> -> Sort (cost=16386.56..16386.56 rows=2 width=128)
> -> Nested Loop (cost=16299.45..16386.55 rows=2 width=128)
>
>How can I "restore" the "before-the-vacuum" performance?
>thanks,

I don't know much about the internal workings about 'vacuum'. My
guess is that there is something wrong with one of the indexes in
your db somewhere. I would try and rebuild them - starting with the
ones involved in the view. You might have to drop and re-create them
- as well as the view.

Good luck,
Chris
--
Chris Ruprecht
Network grunt and bit pusher extraordinaíre

_________________________________________________________
Do You Yahoo!?
Get your free @yahoo.com address at http://mail.yahoo.com

Josh,
I just recreated all the indexes on the tables, but it didn't help.
Please let me know if there is any other information you need to help me
resolve performance issue.
Here are answers to your questions:

1. I am using PostgreSQL 7.1.2
2. Linux RedHat 7.1
3. Pentium II 400 with 256 Megs of RAM
14 out of 17 Gigs are free (there is only one disk on this system)
4. Here is the view definition:
CREATE VIEW progress_report AS
SELECT acts.product_code AS product_code,
acts.component AS component,
acts.priority AS priority,
acts.status AS status,
COALESCE(media_acts.art_checked_in, 0) AS art_in,
COALESCE(media_acts.art_waiting, 0) AS art_wait,
COALESCE(media_acts.audio_checked_in, 0) AS audio_in,
COALESCE(media_acts.audio_waiting, 0) AS audio_wait,
COALESCE(media_acts.video_checked_in, 0) AS video_in,
COALESCE(media_acts.video_waiting, 0) AS video_wait
FROM
(SELECT objectid AS actid,
productcode AS product_code,
actname AS component,
status AS status,
priority AS priority
FROM activity
WHERE activity.productcode ~ '^m3') acts

LEFT OUTER JOIN
(
SELECT actid,
SUM (CASE WHEN
lower(stats.media_status)~'^checked'
AND lower(stats.type)='art'
THEN 1 ELSE 0 END)
AS art_checked_in,
SUM (CASE WHEN
lower(stats.media_status)~'^waiting'
AND lower(stats.type)='art'
THEN 1 ELSE 0 END)
AS art_waiting,
SUM (CASE WHEN
lower(stats.media_status)~'^checked'
AND lower(stats.type)='audio'
THEN 1 ELSE 0 END)
AS audio_checked_in,
SUM (CASE WHEN
lower(stats.media_status)~'^waiting'
AND lower(stats.type)='audio'
THEN 1 ELSE 0 END)
AS audio_waiting,
SUM (CASE WHEN
lower(stats.media_status)~'^checked'
AND lower(stats.type)='video'
THEN 1 ELSE 0 END)
AS video_checked_in,
SUM (CASE WHEN
lower(stats.media_status)~'^waiting'
AND lower(stats.type)='video'
THEN 1 ELSE 0 END)
AS video_waiting
FROM
(
(SELECT media.objectid AS mediaid,
media.status AS media_status,
mediatypemap.typecategory AS type,
media.activity AS actid
FROM media, mediatypemap
WHERE media.mediatype = mediatypemap.mediatype)
UNION
(SELECT intsetmedia.media AS mediaid,
media.status AS media_status,
mediatypemap.typecategory AS type,
set.activity AS actid
FROM intsetmedia, set, media, mediatypemap
WHERE media.mediatype = mediatypemap.mediatype
AND intsetmedia.set = set.objectid
AND intsetmedia.media = media.objectid
)
UNION
(SELECT dtrowmedia.media AS mediaid,
media.status AS media_status,
mediatypemap.typecategory AS type,
datatable.activity AS actid
FROM media, mediatypemap, dtrowmedia, dtrow, dtcol, datatable
WHERE media.mediatype = mediatypemap.mediatype
AND dtrowmedia.media = media.objectid
AND dtrowmedia.dtrow = dtrow.objectid
AND dtrow.dtcol = dtcol.objectid
AND dtcol.datatable = datatable.objectid

)
) stats
GROUP BY actid ) media_acts

ON
acts.actid = media_acts.actid
ORDER BY product_code;

5. None of the tables involved in the view has BLOBs in it.
Row count for the tables are as follows:
activity: 253
media: 12406
set: 826
intsetmedia: 22916
mediatypemap: 25
datatable: 318
dtcol: 1698
dtrow: 18406
dtrowmedia: 10238

6. I didn't have debug on when running vacuum, so I can't tell you if it
raised any errors.

thanks,

Josh Berkus wrote:

> Oleg,
>
> > I just vacuumed and vacuumed analyzed my database. Now, I am trying
> > to
> > execute a view, which was perfectly working before, but it seems to
> > be
> > very slow. It was sitting there for 10 mins before I cancelled it.
> > Usually it was taking on the order of 5 secs to execute the view.
> > I just recreated the view, but the problem still persists.
> > Here is what EXPLAIN tells me:
> > EXPLAIN select * from progress_report;
> > Subquery Scan progress_report (cost=16386.56..16386.56 rows=2
> > width=128)
> > -> Sort (cost=16386.56..16386.56 rows=2 width=128)
> > -> Nested Loop (cost=16299.45..16386.55 rows=2 width=128)
> >
> > How can I "restore" the "before-the-vacuum" performance?
> > thanks,
>
> This is not normal. I suspect that you have something wrong with your
> Postgres system configuration or your system in general.
>
> Please post:
> 1. Your postgres version
> 2. Your platform (OS and version)
> 3. Your hardware statistics, including:
> Processor & RAM
> Disk space free on your root drive and postgres drive
> 4. The view definition
> 5. Row counts on all tables involved in the view, as well as whether
> those tables have very large text fields or BLOBs.
> 6. Finally, check your Postgres log to see if VACUUM raised any errors,
> and to see if selecting the view causes any errors.
>
> -Josh Berkus
>
> ______AGLIO DATABASE SOLUTIONS___________________________
> Josh Berkus
> Complete information technology josh(at)agliodbs(dot)com
> and data management solutions (415) 565-7293
> for law firms, small businesses fax 621-2533
> and non-profit organizations. San Francisco

Oleg,

> 1. I am using PostgreSQL 7.1.2
> 2. Linux RedHat 7.1
> 3. Pentium II 400 with 256 Megs of RAM
> 14 out of 17 Gigs are free (there is only one disk on this
> system)
> 4. Here is the view definition:
<snip>
> 5. None of the tables involved in the view has BLOBs in it.
> Row count for the tables are as follows:
> activity: 253
> media: 12406
> set: 826
> intsetmedia: 22916
> mediatypemap: 25
> datatable: 318
> dtcol: 1698
> dtrow: 18406
> dtrowmedia: 10238
>
> 6. I didn't have debug on when running vacuum, so I can't tell you if
> it
> raised any errors.

Damn. I can only really help with the obvious things, and you've
covered most of those. That view should take a long time, given the
complexity ... but a long time is 30-60 seconds, not 10 minutes.

Therefore:

1. Turn up the debug level in postgres.conf
2. Re-start postgresql, and open a console to tail the log.
3. Watch the log as you:
a) Vacuum Analyze
b) SELECT from the view again
4. Hope that one of the core team looks into your question.

Beyond that, we're down to monkeying with Postgres' memory settings;
it's possible (but not likely) that you've exhausted the available sort
memory and Postgres is getting stuck in swap-access. However, that's
just a stab in the dark.

-Josh

______AGLIO DATABASE SOLUTIONS___________________________
Josh Berkus
Complete information technology josh(at)agliodbs(dot)com
and data management solutions (415) 565-7293
for law firms, small businesses fax 621-2533
and non-profit organizations. San Francisco

"Josh Berkus" <josh(at)agliodbs(dot)com> writes:
> Damn. I can only really help with the obvious things, and you've
> covered most of those. That view should take a long time, given the
> complexity ... but a long time is 30-60 seconds, not 10 minutes.

I'm guessing it's ye olde stupid-choice-of-plan kind of problem.
Unless I missed it, we have not been shown the plan currently being
used (no, the first four lines don't do it for me...)

You could probably get back to the previous, not-so-slow plan choice
by doing "DELETE FROM pg_statistic" to remove the data collected by
VACUUM ANALYZE. A comparison of the EXPLAIN output in that state
vs. the EXPLAIN output in the analyzed state might be enlightening.

regards, tom lane

Thanks everybody for your help.
Deleting from pg_statistic restored view performance to the way it was
before I ran vacuum analyze.
Below I attach two files that contain explain statistics for the view before
(progress_report.txt) and after (progress_report_analyzed.txt) I ran vacuum
analyze. The first one takes about 15 secs. to complete, the second one
takes 12-13 minutes to complete.
I hope this will help you improve your query optimizer.
thanks,

Oleg

Tom Lane wrote:

> "Josh Berkus" <josh(at)agliodbs(dot)com> writes:
> > Damn. I can only really help with the obvious things, and you've
> > covered most of those. That view should take a long time, given the
> > complexity ... but a long time is 30-60 seconds, not 10 minutes.
>
> I'm guessing it's ye olde stupid-choice-of-plan kind of problem.
> Unless I missed it, we have not been shown the plan currently being
> used (no, the first four lines don't do it for me...)
>
> You could probably get back to the previous, not-so-slow plan choice
> by doing "DELETE FROM pg_statistic" to remove the data collected by
> VACUUM ANALYZE. A comparison of the EXPLAIN output in that state
> vs. the EXPLAIN output in the analyzed state might be enlightening.
>
> regards, tom lane
>
> ---------------------------(end of broadcast)---------------------------
> TIP 5: Have you checked our extensive FAQ?
>
> http://www.postgresql.org/users-lounge/docs/faq.html

Oleg Lebedev <olebedev(at)waterford(dot)org> writes:
> Deleting from pg_statistic restored view performance to the way it was
> before I ran vacuum analyze.
> Below I attach two files that contain explain statistics for the view before
> (progress_report.txt) and after (progress_report_analyzed.txt) I ran vacuum
> analyze. The first one takes about 15 secs. to complete, the second one
> takes 12-13 minutes to complete.

Looks like the issue is the number of rows estimated to be obtained from
the "activity" table:

good plan:

> -> Merge Join (cost=14644.00..14648.62 rows=4 width=128)
> -> Sort (cost=11.02..11.02 rows=2 width=48)
> -> Seq Scan on activity (cost=0.00..11.00 rows=2 width=48)
> -> Sort (cost=14632.99..14632.99 rows=367 width=112)
> -> Subquery Scan media_acts (cost=14553.17..14617.36 rows=367 width=112)

bad plan:

> -> Nested Loop (cost=14605.17..14686.99 rows=2 width=128)
> -> Seq Scan on activity (cost=0.00..11.00 rows=1 width=48)
> -> Subquery Scan media_acts (cost=14605.17..14671.27 rows=378 width=112)

The plans for media_acts look about the same, so I have to guess that
activity actually yields 50 or so rows, not just one. That doesn't
hurt the mergejoin too much, but it is a killer for the nestloop.

You showed the query as
(SELECT ...
FROM activity
WHERE activity.productcode ~ '^m3') acts
How many rows actually match activity.productcode ~ '^m3' ? How many
rows altogether in activity?

regards, tom lane

You are right Tom,
(SELECT ...
FROM activity
WHERE activity.productcode ~ '^m3') acts
yeilds 235 rows, with a total of 240 rows in activity table. I wonder why EXPLAIN estimates only 1
row? Are there any online docs on how the planner works?
BTW, I would like to buy a book that would help me tune up postgres performance. Which book would
you suggest?
Thanks,

Oleg

Tom Lane wrote:

> Oleg Lebedev <olebedev(at)waterford(dot)org> writes:
> > Deleting from pg_statistic restored view performance to the way it was
> > before I ran vacuum analyze.
> > Below I attach two files that contain explain statistics for the view before
> > (progress_report.txt) and after (progress_report_analyzed.txt) I ran vacuum
> > analyze. The first one takes about 15 secs. to complete, the second one
> > takes 12-13 minutes to complete.
>
> Looks like the issue is the number of rows estimated to be obtained from
> the "activity" table:
>
> good plan:
>
> > -> Merge Join (cost=14644.00..14648.62 rows=4 width=128)
> > -> Sort (cost=11.02..11.02 rows=2 width=48)
> > -> Seq Scan on activity (cost=0.00..11.00 rows=2 width=48)
> > -> Sort (cost=14632.99..14632.99 rows=367 width=112)
> > -> Subquery Scan media_acts (cost=14553.17..14617.36 rows=367 width=112)
>
> bad plan:
>
> > -> Nested Loop (cost=14605.17..14686.99 rows=2 width=128)
> > -> Seq Scan on activity (cost=0.00..11.00 rows=1 width=48)
> > -> Subquery Scan media_acts (cost=14605.17..14671.27 rows=378 width=112)
>
> The plans for media_acts look about the same, so I have to guess that
> activity actually yields 50 or so rows, not just one. That doesn't
> hurt the mergejoin too much, but it is a killer for the nestloop.
>
> You showed the query as
> (SELECT ...
> FROM activity
> WHERE activity.productcode ~ '^m3') acts
> How many rows actually match activity.productcode ~ '^m3' ? How many
> rows altogether in activity?
>
> regards, tom lane

Oleg Lebedev <olebedev(at)waterford(dot)org> writes:
> yeilds 235 rows, with a total of 240 rows in activity table. I wonder
> why EXPLAIN estimates only 1 row?

Ugh, that's a pretty horrible misestimation. What do you get from

select attname,attdispersion,s.*
from pg_statistic s, pg_attribute a, pg_class c
where starelid = c.oid and attrelid = c.oid and staattnum = attnum
and relname = 'activity';

(you'll need to do "VACUUM ANALYZE activity" first).

> Are there any online docs on how the planner works?

The first two sections of
http://developer.postgresql.org/docs/postgres/performance-tips.html
are a starting point --- but keep in mind that section 11.2 describes
PG 7.2's stats. The pg_statistic scheme in 7.1 is much simpler.

I am hoping that 7.2 will get a better result for this query, but can't
tell without more info.

regards, tom lane

Thanks for your comments Tom.
I attached a file with the query you mentioned in your posting and it's output. Those numbers don't
really tell me anything, but let me know if you find anything interesting there.
thanks,

Oleg

Tom Lane wrote:

> Oleg Lebedev <olebedev(at)waterford(dot)org> writes:
> > Deleting from pg_statistic restored view performance to the way it was
> > before I ran vacuum analyze.
> > Below I attach two files that contain explain statistics for the view before
> > (progress_report.txt) and after (progress_report_analyzed.txt) I ran vacuum
> > analyze. The first one takes about 15 secs. to complete, the second one
> > takes 12-13 minutes to complete.
>
> Looks like the issue is the number of rows estimated to be obtained from
> the "activity" table:
>
> good plan:
>
> > -> Merge Join (cost=14644.00..14648.62 rows=4 width=128)
> > -> Sort (cost=11.02..11.02 rows=2 width=48)
> > -> Seq Scan on activity (cost=0.00..11.00 rows=2 width=48)
> > -> Sort (cost=14632.99..14632.99 rows=367 width=112)
> > -> Subquery Scan media_acts (cost=14553.17..14617.36 rows=367 width=112)
>
> bad plan:
>
> > -> Nested Loop (cost=14605.17..14686.99 rows=2 width=128)
> > -> Seq Scan on activity (cost=0.00..11.00 rows=1 width=48)
> > -> Subquery Scan media_acts (cost=14605.17..14671.27 rows=378 width=112)
>
> The plans for media_acts look about the same, so I have to guess that
> activity actually yields 50 or so rows, not just one. That doesn't
> hurt the mergejoin too much, but it is a killer for the nestloop.
>
> You showed the query as
> (SELECT ...
> FROM activity
> WHERE activity.productcode ~ '^m3') acts
> How many rows actually match activity.productcode ~ '^m3' ? How many
> rows altogether in activity?
>
> regards, tom lane

Oleg Lebedev <olebedev(at)waterford(dot)org> writes:
> select attname, attdispersion, s.*
> from pg_statistic s, pg_attribute a, pg_class c
> where starelid = c.oid and attrelid=c.oid and staattnum=attnum and relname='activity';

> attname | attdispersion | starelid | staattnum | staop | stanullfrac | stacommonfrac | stacommonval | staloval | stahival
> -------------------------+---------------+----------+-----------+-------+-------------+---------------+--------------------------------------+-------------+------------------------------
> productcode | 0.002625 | 14559105 | 17 | 1066 | 0 | 0.0125 | m3nt22 | 0000 | t3nt15

Well, I can see that 7.1 wouldn't be likely to make a good estimate
about the selectivity of productcode ~ '^m3' on this table; it doesn't
take stacommonval into account (and that's only 1% of the table anyway),
and the range '0000' .. 't3nt15' is too wide to make it plausible that
m3's take up 98% of the table. I believe 7.2 will do better though.
Care to try out your database with a beta version?

regards, tom lane

I am reading the Momjian "Support Functions" section and have the
following comments:

1 - there is a comma after "BOTH" that is not before "LEADING" or
"TRAILING", so I believe it is an error.

  trim(BOTH...) trim(BOTH, col) same as trim()
  trim(LEADING...) trim(LEADING col) col with leading spaces
removed
  trim(TRAILING...) trim(TRAILING col) col with trailing
spaces removed

2 - I typed \h trim and no help came up. Is it required to resort
to HTML documentation for docs on this function

Terrence Brannon wrote:
> I am reading the Momjian "Support Functions" section and have the
> following comments:
>
> 1 - there is a comma after "BOTH" that is not before "LEADING" or
> "TRAILING", so I believe it is an error.
>
> ? trim(BOTH...) trim(BOTH, col) same as trim()
> ? trim(LEADING...) trim(LEADING col) col with leading spaces
> removed
> ? trim(TRAILING...) trim(TRAILING col) col with trailing
> spaces removed

Thanks. The BOTH, is wrong, it should be just BOTH. I have updated the
book web site with this error.

> 2 - I typed \h trim and no help came up. Is it required to resort
> to HTML documentation for docs on this function

TRIM is an ANSI word that masks several functions like rtrim, ltrim, and
btrim. \df rtrim shows these.

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 853-3000
+ If your life is a hard drive, | 830 Blythe Avenue
+ Christ can be your backup. | Drexel Hill, Pennsylvania 19026