Interpreting query debug output

From: Steve Lane <slane(at)moyergroup(dot)com>
To: <pgsql-admin(at)postgresql(dot)org>
Subject: Interpreting query debug output
Date: 2004-05-18 23:42:10
Message-ID: BCD00982.11773%slane@moyergroup.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-admin

Hello all:

I have a database that is exhibiting sluggishness under load. Suspecting
that some queries may be poorly optimized, I turned on a fair amount of
debugging output in the logs. But I could use some help interpreting it.

For the record, this is Postgres 7.2.1. I've already been rightly chastised
for using such an old version, and the upgrade is scheduled.

Here's some sample output:

2004-05-18 15:46:04 [27129] DEBUG: connection: host=127.0.0.1
user=postgres database=iep_db
2004-05-18 15:46:04 [26914] DEBUG: query: SELECT CAST(name_first || ' '
|| name_last AS TEXT) FROM iep_personnel WHERE id_personnel = $1
2004-05-18 15:46:08 [27015] DEBUG: query: select * from iep_student where
id_student = '1002863';
2004-05-18 15:46:08 [26914] DEBUG: query: SELECT $1
2004-05-18 15:46:08 [26914] DEBUG: query: SELECT CAST(name_county AS
TEXT) FROM iep_county WHERE id_county = $1
2004-05-18 15:46:05 [26892] DEBUG: QUERY STATISTICS
! system usage stats:
! 106.317726 elapsed 21.080000 user 0.240000 system sec
! [21.110000 user 0.250000 sys total]
! 0/0 [0/0] filesystem blocks in/out
! 7959/191 [8515/747] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 0/0 [0/0] voluntary/involuntary context switches
! postgres usage stats:
! Shared blocks: 0 read, 0 written, buffer hit rate
= 100.00%
! Local blocks: 0 read, 0 written, buffer hit rate
= 0.00%
! Direct blocks: 0 read, 0 written

Some questions:

1) The statistics appear to be reporting on a series of queries. These
queries are all from inside a function, hence a single transaction. Are the
query statistics being reported here on a per-transaction basis?

Two numbers leap out: 106 seconds for the query, and a high number on the
page faults line.

2) 106 seconds for the operation is too horrible for words. All of the
operations are where-clauses involving single, index id fields. The server
load is heavy, but I can't account for this slowness due to stupidly-written
queries. Anyone see anything suspect in the queries?

3) I don't know how to read the page faults line. Is this referring to
system virtual memory, or postgres buffer management? What does this line
mean, and what parameter does it imply needs tuning?

I have RAM to spare on this box, as follows:

[root(at)iep log]# cat /proc/meminfo
total: used: free: shared: buffers: cached:
Mem: 6161747968 3970502656 2191245312 0 13320192 3259764736
Swap: 2089209856 47116288 2042093568
MemTotal: 6017332 kB
MemFree: 2139888 kB
MemShared: 0 kB
Buffers: 13008 kB
Cached: 3138220 kB
SwapCached: 45144 kB
Active: 1362996 kB
Inactive: 2210704 kB
HighTotal: 5177216 kB
HighFree: 1643716 kB
LowTotal: 840116 kB
LowFree: 496172 kB
SwapTotal: 2040244 kB
SwapFree: 1994232 kB

Some key postgresql.conf parameters:

max_connections = 150
shared_buffers = 175000 # 2*max_connections, min 16
sort_mem = 32000 # min 32
effective_cache_size = 100000 # default in 8k pages
log_connections = true
log_timestamp = true
log_pid = true
debug_print_query = true
show_query_stats = true

Sorry for the big dump. I'm feeling a bit at sea in this information and I
need to know if I'm swimming in the right direction. Thanks for any help.

-- sgl

In response to

Responses

Browse pgsql-admin by date

  From Date Subject
Next Message Tom Lane 2004-05-19 00:19:03 Re: "IDENT authentication failed" but I'm not using ident
Previous Message brook 2004-05-18 20:26:32 pg_hba.conf and groups