Re: Tweaking PG (again)

On Thu, Nov 13, 2008 at 2:04 PM, Phoenix Kiula <phoenix.kiula@gmail.com> wrote:
> On Fri, Nov 14, 2008 at 3:10 AM, Scott Marlowe <scott.marlowe@gmail.com> wrote:
>> On Thu, Nov 13, 2008 at 11:59 AM, Phoenix Kiula <phoenix.kiula@gmail.com> wrote:
>>> Hi.
>>>
>>> I had tweaked my PG 8.2.6 with the very kind help of this list a
>>> couple years ago. It has been working fine, until recently. Not sure
>>> if it is after the update to 8.3 or because my DB has been growing,
>>> but the db is very slow now and the cache doesn't seem enough.
>>
>> Everything you posted looks pretty normal.  I'd find the slowest
>> queries and post explain analyze to see what's happening.
>
> My logs are full of
>
> (1) One SELECT sql
> (2) And INSERT and UPDATE sql to my main table, called "books"
>
> The definition of "books" is as follows --
>
>
>
>                                Table "public.books"
>        Column         |            Type             |
> Modifiers
> -----------------------+-----------------------------+------------------------------
>  id                    | bigint                      | not null
>  book_id               | character varying(10)       | not null
>  alias                 | character varying(20)       | not null
>  url                   | text                        | not null
>  user_known            | smallint                    | not null default 0
>  user_id               | character varying(45)       | not null
>  url_encrypted         | character(40)               | default ''::bpchar
>  title                 | character varying(500)      |
>  status                | character(1)                | default 'Y'::bpchar
>  modify_date           | timestamp without time zone |
> Indexes:
>    "books2_pkey" PRIMARY KEY, btree (id)
>    "books2_alias_key" UNIQUE, btree (alias) WITH (fillfactor=75)
>    "new_idx_books_userid" btree (user_id) WITH (fillfactor=70)
>    "new_idx_modify_date" btree (modify_date) WITH (fillfactor=75)
>    "new_idx_userknown" btree (user_id) WITH (fillfactor=70) WHERE
> user_known = 1
> Check constraints:
>    "books2_id_check" CHECK (id > 0)
>    "books2_url_check" CHECK (url <> ''::text)
>    "books2_user_id_check" CHECK (user_id::text <> ''::text)
>    "books_alias_check" CHECK (alias::text ~ '[-~a-z0-9_]'::text)
>
>
>
>
> (1) The culprit SELECT sql is (note that "MYUSER" in this example can
> be an IP address) --

So, it can be, but might not be?  Darn,  If it was always an ip I'd
suggest changing types.

> explain analyze SELECT alias, id, title, private_key, aliasEntered
>  FROM books
>  WHERE user_id = 'MYUSER'  AND url_encrypted =
> 'bed59c2f2d92e306d4481a276bd8a78c4b0532d4' ;
>
>                                                        QUERY PLAN
> ----------------------------------------------------------------------------------------------------------------
> Index Scan using new_idx_books_userid on books  (cost=0.00..493427.14
> rows=2 width=31) (actual time=0.428..8400.299 rows=1 loops=1)
>   Index Cond: ((user_id)::text = 'MYUSER'::text)
>   Filter: (url_encrypted = 'bed59c2f2d92e306d4481a276bd8a78c4b0532d4'::bpchar)
>  Total runtime: 8400.349 ms
> (4 rows)

8.4 seconds is a very long time to spend looking up a single record.
Is this table bloated?  What does

vacuum verbose books;

say about it?  Look for a line like this:

There were 243 unused item pointers

> (2) The culprit INSERT sql is as follows
>
> explain analyze
> INSERT INTO books (id, book_id, url, user_known, user_id,
> url_encrypted, alias, title, private_key, status, modify_date)
>                values
>                (
>                  9107579
>                 ,'5f7gb'
>                 ,'http://www.google.com'
>                 ,'0'
>                 ,'MYUSER'
>                 ,'73684da5ef05d9589f95d8ba9e4429ea062549c7'
>                 ,'5f7gb'
>                 ,''
>                 ,''
>                 ,'Y'
>                 ,now()
>                )
> ;
>
>                                     QUERY PLAN
> ------------------------------------------------------------------------------------
>  Result  (cost=0.00..0.03 rows=1 width=0) (actual time=0.017..0.022
> rows=1 loops=1)
>  Total runtime: 106.747 ms
> (2 rows)
>
> Time: 3421.424 ms

When the total run time measured by explain analyze is much lower than
the actual run time, this is usually either a trigger firing / fk
issue, or you've got a really expensive (cpu wise) time function on
your OS.  Since there's only one loop here, I'm gonna guess that
you've got some FK stuff going on.  Got a related fk/pk field in
another table that needs an index?  I thought that 8.3 gave some info
on that stuff in explain analyze, but I'm not really sure.