Re: Tweaking PG (again)

On Thu, Nov 13, 2008 at 2:04 PM, Phoenix Kiula <phoenix(dot)kiula(at)gmail(dot)com> wrote:
> On Fri, Nov 14, 2008 at 3:10 AM, Scott Marlowe <scott(dot)marlowe(at)gmail(dot)com> wrote:
>> On Thu, Nov 13, 2008 at 11:59 AM, Phoenix Kiula <phoenix(dot)kiula(at)gmail(dot)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.