Finding bottleneck

Hello,

we recently upgraded our dual Xeon Dell to a brand new Sun v40z with 4
opterons, 16GB of memory and MegaRAID with enough disks. OS is Debian
Sarge amd64, PostgreSQL is 8.0.3. Size of database is something like 80GB
and our website performs about 600 selects and several updates/inserts a
second.

v40z performs somewhat better than our old Dell but mostly due to
increased amount of memory. The problem is.. there seems to by plenty of
free CPU available and almost no IO-wait but CPU bound queries seem to
linger for some reason. Problem appears very clearly during checkpointing.
Queries accumulate and when checkpointing is over, there can be something
like 400 queries running but over 50% of cpu is just idling.

procs -----------memory------------ ---swap-- -----io---- --system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
3 1 0 494008 159492 14107180 0 0 919 3164 3176 13031 29 12 52 8
5 3 0 477508 159508 14118452 0 0 1071 4479 3474 13298 27 13 47 13
0 0 0 463604 159532 14128832 0 0 922 2903 3352 12627 29 11 52 8
3 1 0 442260 159616 14141668 0 0 1208 3153 3357 13163 28 12 52 9

An example of a lingering query (there's usually several of these or similar):

SELECT u.uid, u.nick, u.name, u.showname, i.status, i.stamp, i.image_id,
i.info, i.t_width, i.t_height FROM users u INNER JOIN image i ON i.uid =
u.uid INNER JOIN user_online uo ON u.uid = uo.uid WHERE u.city_id = 5 AND
i.status = 'd' AND u.status = 'a' ORDER BY city_id, upper(u.nick) LIMIT
(40 + 1) OFFSET 320

Tables involved contain no more than 4 million rows. Those are constantly
accessed and should fit nicely to cache. But database is just slow because
of some unknown reason. Any ideas?

----------------->8 Relevant rows from postgresql.conf 8<-----------------

shared_buffers = 15000 # min 16, at least max_connections*2, 8KB each
work_mem = 1536 # min 64, size in KB
maintenance_work_mem = 32768 # min 1024, size in KB

max_fsm_pages = 1000000 # min max_fsm_relations*16, 6 bytes each
max_fsm_relations = 5000 # min 100, ~50 bytes each

vacuum_cost_delay = 15 # 0-1000 milliseconds
vacuum_cost_limit = 120 # 0-10000 credits

bgwriter_percent = 2 # 0-100% of dirty buffers in each round

fsync = true # turns forced synchronization on or off
# fsync, fdatasync, open_sync, or open_datasync
wal_buffers = 128 # min 4, 8KB each
commit_delay = 80000 # range 0-100000, in microseconds
commit_siblings = 10 # range 1-1000

checkpoint_segments = 200 # in logfile segments, min 1, 16MB each
checkpoint_timeout = 1800 # range 30-3600, in seconds

effective_cache_size = 1000000 # typically 8KB each
random_page_cost = 1.8 # units are one sequential page fetch cost

default_statistics_target = 150 # range 1-1000

stats_start_collector = true
stats_command_string = true

|\__/|
( oo ) Kari Lavikka - tuner(at)bdb(dot)fi - (050) 380 3808
__ooO( )Ooo_______ _____ ___ _ _ _ _ _ _ _
""

Hi,

On Thu, 28 Jul 2005, Kari Lavikka wrote:

> ----------------->8 Relevant rows from postgresql.conf 8<-----------------
>
> shared_buffers = 15000 # min 16, at least max_connections*2, 8KB each
> work_mem = 1536 # min 64, size in KB

As an aside, I'd increase work_mem -- but it doesn't sound like that is
your problem.

> maintenance_work_mem = 32768 # min 1024, size in KB
>
> max_fsm_pages = 1000000 # min max_fsm_relations*16, 6 bytes each
> max_fsm_relations = 5000 # min 100, ~50 bytes each
>
> vacuum_cost_delay = 15 # 0-1000 milliseconds
> vacuum_cost_limit = 120 # 0-10000 credits
>
> bgwriter_percent = 2 # 0-100% of dirty buffers in each round
>
> fsync = true # turns forced synchronization on or off
> # fsync, fdatasync, open_sync, or open_datasync
> wal_buffers = 128 # min 4, 8KB each

Some benchmarking results out today suggest that wal_buffers = 1024 or
even 2048 could greatly assist you.

> commit_delay = 80000 # range 0-100000, in microseconds
> commit_siblings = 10 # range 1-1000

This may explain the fact that you've got backed up queries and idle CPU
-- I'm not certain though. What does disabling commit_delay do to your
situation?

Gavin

> effective_cache_size = 1000000 # typically 8KB each

I have this setting on postgresql 7.4.8 on FreeBSD with 4 GB RAM:

effective_cache_size = 27462

So eventhough your machine runs Debian and you have four times as much
RAM as mine your effective_cache_size is 36 times larger. You could
try lowering this setting.

regards
Claus

On 7/28/05 2:21 AM, "Kari Lavikka" <tuner(at)bdb(dot)fi> wrote:

There's a new profiling tool called oprofile:

http://oprofile.sourceforge.net/download/

that can be run without instrumenting the binaries beforehand. To actually
find out what the code is doing during these stalls, oprofile can show you
in which routines the CPU is spending time when you start/stop the
profiling.

As an alternative to the "guess->change parameters->repeat" approach, this
is the most direct way to find the exact nature of the problem.

- Luke

Hi!

Oprofile looks quite interesting. I'm not very familiar with postgresql
internals, but here's some report output:

CPU: AMD64 processors, speed 2190.23 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit
mask of 0x00 (No unit mask) count 100000
samples % symbol name
13513390 16.0074 AtEOXact_CatCache
4492257 5.3213 StrategyGetBuffer
2279285 2.6999 AllocSetAlloc
2121509 2.5130 LWLockAcquire
2023574 2.3970 hash_seq_search
1971358 2.3352 nocachegetattr
1837168 2.1762 GetSnapshotData
1793693 2.1247 SearchCatCache
1777385 2.1054 hash_search
1460804 1.7304 ExecMakeFunctionResultNoSets
1360930 1.6121 _bt_compare
1344604 1.5928 yyparse
1318407 1.5617 LWLockRelease
1290814 1.5290 FunctionCall2
1137544 1.3475 ExecEvalVar
1102236 1.3057 hash_any
912677 1.0811 OpernameGetCandidates
877993 1.0400 ReadBufferInternal
783908 0.9286 TransactionIdPrecedes
772886 0.9155 MemoryContextAllocZeroAligned
679768 0.8052 StrategyBufferLookup
609339 0.7218 equal
600584 0.7114 PGSemaphoreLock

And btw, I tried to strace lingering queries under different loads. When
number of concurrent queries increases, lseek and read syscalls stay
within quite constant limits but number of semop calls quadruples.

Are there some buffer locking issues?

|\__/|
( oo ) Kari Lavikka - tuner(at)bdb(dot)fi - (050) 380 3808
__ooO( )Ooo_______ _____ ___ _ _ _ _ _ _ _
""

On Thu, 28 Jul 2005, Luke Lonergan wrote:

> On 7/28/05 2:21 AM, "Kari Lavikka" <tuner(at)bdb(dot)fi> wrote:
>
> There's a new profiling tool called oprofile:
>
> http://oprofile.sourceforge.net/download/
>
> that can be run without instrumenting the binaries beforehand. To actually
> find out what the code is doing during these stalls, oprofile can show you
> in which routines the CPU is spending time when you start/stop the
> profiling.
>
> As an alternative to the "guess->change parameters->repeat" approach, this
> is the most direct way to find the exact nature of the problem.
>
> - Luke
>
>
>
> ---------------------------(end of broadcast)---------------------------
> TIP 5: don't forget to increase your free space map settings
>

Kari Lavikka <tuner(at)bdb(dot)fi> writes:
> samples % symbol name
> 13513390 16.0074 AtEOXact_CatCache

That seems quite odd --- I'm not used to seeing that function at the top
of a profile. What is the workload being profiled, exactly?

regards, tom lane