pg.ddx.io pgsql-performance@postgresql.org mailing list archive
help / color / mirror / Atom feedPostgreSQL 9.0.4 blocking in lseek?
16+ messages / 6 participants
[nested] [flat]
* PostgreSQL 9.0.4 blocking in lseek?
@ 2011-10-26 15:47 Sören Meyer-Eppler <soerenme@google.com>
0 siblings, 3 replies; 16+ messages in thread
From: Sören Meyer-Eppler @ 2011-10-26 15:47 UTC (permalink / raw)
To: pgsql-performance
We are running into a significant performance issue with
"PostgreSQL 9.0.4 on x86_64-pc-linux-gnu, compiled by GCC gcc-4.4.real
(Debian 4.4.5-8) 4.4.5, 64-bit"
(the version string pqAdmin displays).
A fairly complex insert query on an empty destination table will run for
an indefinite amount of time (we waited literally days for the query to
complete). This does not happen every time we run the query but often.
Now ordinarily I'd assume we did something wrong with our indices or
query, but the execution plan looks sane and, more tellingly, we have:
- no CPU load
- no network traffic
- no disk I/O
- no other load on the server except this single query
and strace displaying a seemingly endless list of lseek calls.
So my assumption is that we are not running into bad Big-O() runtime
behavior but rather into some locking problem.
Any ideas what might cause this? Workarounds we could try?
thank you,
Sören
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: PostgreSQL 9.0.4 blocking in lseek?
@ 2011-10-27 07:42 Gregg Jaskiewicz <gryzman@gmail.com>
parent: Sören Meyer-Eppler <soerenme@google.com>
2 siblings, 2 replies; 16+ messages in thread
From: Gregg Jaskiewicz @ 2011-10-27 07:42 UTC (permalink / raw)
To: Sören Meyer-Eppler <soerenme@google.com>; +Cc: pgsql-performance
What does 'select * from pg_stat_activity' say, more precisely - the
"waiting" column.
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: PostgreSQL 9.0.4 blocking in lseek?
@ 2011-10-27 12:03 Sören Meyer-Eppler <soerenme@google.com>
parent: Gregg Jaskiewicz <gryzman@gmail.com>
1 sibling, 0 replies; 16+ messages in thread
From: Sören Meyer-Eppler @ 2011-10-27 12:03 UTC (permalink / raw)
To: Gregg Jaskiewicz <gryzman@gmail.com>; +Cc: pgsql-performance
On 2011-10-27 09:42, Gregg Jaskiewicz wrote:
> What does 'select * from pg_stat_activity' say, more precisely - the
> "waiting" column.
Waiting is "false" for all rows. If I use pgadmin to lock at the server
status all locks have been granted for hours.
Although the process does in fact use CPU this time, strace still gives
a seemingly endless list of lseek calls.
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: PostgreSQL 9.0.4 blocking in lseek?
@ 2011-10-27 14:54 Claudio Freire <klaussfreire@gmail.com>
parent: Gregg Jaskiewicz <gryzman@gmail.com>
1 sibling, 0 replies; 16+ messages in thread
From: Claudio Freire @ 2011-10-27 14:54 UTC (permalink / raw)
To: Gregg Jaskiewicz <gryzman@gmail.com>; +Cc: Sören Meyer-Eppler <soerenme@google.com>; pgsql-performance
On Thu, Oct 27, 2011 at 4:42 AM, Gregg Jaskiewicz <gryzman@gmail.com> wrote:
> What does 'select * from pg_stat_activity' say, more precisely - the
> "waiting" column.
Whether that particular process is waiting for it to be granted some
kind of database-level lock.
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: PostgreSQL 9.0.4 blocking in lseek?
@ 2011-10-28 00:32 Tom Lane <tgl@sss.pgh.pa.us>
parent: Sören Meyer-Eppler <soerenme@google.com>
2 siblings, 2 replies; 16+ messages in thread
From: Tom Lane @ 2011-10-28 00:32 UTC (permalink / raw)
To: Sören Meyer-Eppler <soerenme@google.com>; +Cc: pgsql-performance
=?ISO-8859-1?Q?S=F6ren_Meyer-Eppler?= <soerenme@google.com> writes:
> A fairly complex insert query on an empty destination table will run for
> an indefinite amount of time (we waited literally days for the query to
> complete). This does not happen every time we run the query but often.
> Now ordinarily I'd assume we did something wrong with our indices or
> query, but the execution plan looks sane and, more tellingly, we have:
> - no CPU load
> - no network traffic
> - no disk I/O
> - no other load on the server except this single query
> and strace displaying a seemingly endless list of lseek calls.
> So my assumption is that we are not running into bad Big-O() runtime
> behavior but rather into some locking problem.
If it were blocked on a lock, it wouldn't be doing lseeks().
The most obvious explanation for a backend that's doing repeated lseeks
and nothing else is that it's repeatedly doing seqscans on a table
that's fully cached in shared buffers. I'd wonder about queries
embedded in often-executed plpgsql functions, for instance. Can you
identify which table the lseeks are issued against?
(Now, having said that, I don't see how that type of theory explains no
CPU load. But you're really going to need to provide more info before
anyone can explain it, and finding out what the lseeks are on would be
one good step.)
regards, tom lane
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: PostgreSQL 9.0.4 blocking in lseek?
@ 2011-10-28 02:42 Josh Berkus <josh@agliodbs.com>
parent: Sören Meyer-Eppler <soerenme@google.com>
2 siblings, 1 reply; 16+ messages in thread
From: Josh Berkus @ 2011-10-28 02:42 UTC (permalink / raw)
To: pgsql-performance
On 10/26/11 8:47 AM, Sören Meyer-Eppler wrote:
> A fairly complex insert query on an empty destination table will run for
> an indefinite amount of time (we waited literally days for the query to
> complete). This does not happen every time we run the query but often.
> Now ordinarily I'd assume we did something wrong with our indices or
> query, but the execution plan looks sane and, more tellingly, we have:
> - no CPU load
> - no network traffic
> - no disk I/O
> - no other load on the server except this single query
> and strace displaying a seemingly endless list of lseek calls.
Hmmmm. If you were on Solaris or OSX, I'd say you'd hit one of their
I/O bugs which can cause endless lseeks for individual disk pages.
However, I've never seen that particular pattern on Linux (other I/O
bugs, but not that one).
Questions:
(1) is it *only* that query?
(2) is there some reason you might have excessive disk fragmentation,
like running on a VM?
--
Josh Berkus
PostgreSQL Experts Inc.
http://pgexperts.com
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: PostgreSQL 9.0.4 blocking in lseek?
@ 2011-10-31 13:56 Sören Meyer-Eppler <soerenme@google.com>
parent: Josh Berkus <josh@agliodbs.com>
0 siblings, 0 replies; 16+ messages in thread
From: Sören Meyer-Eppler @ 2011-10-31 13:56 UTC (permalink / raw)
To: Josh Berkus <josh@agliodbs.com>; +Cc: pgsql-performance
> (1) is it *only* that query?
No. There seem to be one or two others exhibiting similarly bad performance.
> (2) is there some reason you might have excessive disk fragmentation,
> like running on a VM?
No VM. The database is the only thing running on the server. Filesystem
is XFS.
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: PostgreSQL 9.0.4 blocking in lseek?
@ 2011-10-31 14:09 Sören Meyer-Eppler <soerenme@google.com>
parent: Tom Lane <tgl@sss.pgh.pa.us>
1 sibling, 1 reply; 16+ messages in thread
From: Sören Meyer-Eppler @ 2011-10-31 14:09 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: pgsql-performance
> embedded in often-executed plpgsql functions, for instance. Can you
> identify which table the lseeks are issued against?
I wouldn't know how? I'm just using htop and "s" on the postgres process
to find these...
> (Now, having said that, I don't see how that type of theory explains no
> CPU load.
My bad sorry. I was relaying information from the guy administering the
server. It turns out that "no CPU load" really meant: only one of the
cores is being utilized. On a 16 core machine that looks like "no load"
but of course for the individual query still means 100%.
> But you're really going to need to provide more info before
> anyone can explain it, and finding out what the lseeks are on would be
> one good step.)
I have attached two of the offending execution plans. Anything obviously
wrong with them?
thank you for looking into it!
Sören
Attachments:
execution_plans.txt (text/plain, 2.9K) download
"Insert (cost=51.21..51.24 rows=1 width=26) (actual time=0.016..0.016 rows=0 loops=1)"
" -> Subquery Scan on "*SELECT*" (cost=51.21..51.24 rows=1 width=26) (actual time=0.014..0.014 rows=0 loops=1)"
" -> Sort (cost=51.21..51.22 rows=1 width=8) (actual time=0.014..0.014 rows=0 loops=1)"
" Sort Key: basic_blocks.id"
" Sort Method: quicksort Memory: 25kB"
" -> Nested Loop (cost=0.00..51.20 rows=1 width=8) (actual time=0.010..0.010 rows=0 loops=1)"
" -> Nested Loop (cost=0.00..42.33 rows=1 width=20) (actual time=0.010..0.010 rows=0 loops=1)"
" Join Filter: (bn_functions.address = bn_function_views.function)"
" -> Index Scan using bn_functions_pkey on bn_functions (cost=0.00..8.34 rows=1 width=8) (actual time=0.009..0.009 rows=0 loops=1)"
" Index Cond: (module_id = 82)"
" Filter: (type <> 'import'::function_type)"
" -> Index Scan using bn_function_views_module_id_idx on bn_function_views (cost=0.00..33.77 rows=18 width=12) (never executed)"
" Index Cond: (bn_function_views.module_id = 82)"
" -> Index Scan using ex_82_basic_blocks_parent_function_idx on ex_82_basic_blocks basic_blocks (cost=0.00..8.63 rows=19 width=12) (never executed)"
" Index Cond: (basic_blocks.parent_function = bn_functions.address)"
"Total runtime: 0.082 ms"
"Insert (cost=14581.76..19565.92 rows=11146 width=8) (actual time=2426.967..2426.967 rows=0 loops=1)"
" -> Merge Join (cost=14581.76..19565.92 rows=11146 width=8) (actual time=187.650..537.181 rows=166905 loops=1)"
" Merge Cond: (destination_function.function = callgraph.destination)"
" -> Index Scan using bn_function_nodes_module_id_function_idx on bn_function_nodes destination_function (cost=0.00..4667.05 rows=43094 width=12) (actual time=0.068..15.326 rows=43346 loops=1)"
" Index Cond: (module_id = 94)"
" -> Sort (cost=14534.90..14643.30 rows=43360 width=12) (actual time=187.365..225.911 rows=166905 loops=1)"
" Sort Key: callgraph.destination"
" Sort Method: quicksort Memory: 13968kB"
" -> Merge Join (cost=46.54..11195.29 rows=43360 width=12) (actual time=0.016..121.661 rows=166905 loops=1)"
" Merge Cond: (source_function.function = callgraph.source)"
" -> Index Scan using bn_function_nodes_module_id_function_idx on bn_function_nodes source_function (cost=0.00..4667.05 rows=43094 width=12) (actual time=0.007..14.936 rows=41149 loops=1)"
" Index Cond: (module_id = 94)"
" -> Index Scan using ex_94_callgraph_source_idx on ex_94_callgraph callgraph (cost=0.00..5773.07 rows=166905 width=16) (actual time=0.006..60.455 rows=166905 loops=1)"
"Total runtime: 2434.736 ms"
* Re: PostgreSQL 9.0.4 blocking in lseek?
@ 2011-10-31 15:28 Tom Lane <tgl@sss.pgh.pa.us>
parent: Sören Meyer-Eppler <soerenme@google.com>
0 siblings, 1 reply; 16+ messages in thread
From: Tom Lane @ 2011-10-31 15:28 UTC (permalink / raw)
To: Sören Meyer-Eppler <soerenme@google.com>; +Cc: pgsql-performance
=?ISO-8859-1?Q?S=F6ren_Meyer-Eppler?= <soerenme@google.com> writes:
>> embedded in often-executed plpgsql functions, for instance. Can you
>> identify which table the lseeks are issued against?
> I wouldn't know how? I'm just using htop and "s" on the postgres process
> to find these...
Note the file number appearing in the lseeks, run "lsof -p PID" against
the backend process to discover the actual filename of that file, then
look for a match to the filename in pg_class.relfilenode.
> I have attached two of the offending execution plans. Anything obviously
> wrong with them?
What makes you say these are "offending execution plans"? Both of them
seem to be completing just fine.
regards, tom lane
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: PostgreSQL 9.0.4 blocking in lseek?
@ 2011-10-31 16:17 Sören Meyer-Eppler <soerenme@google.com>
parent: Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 0 replies; 16+ messages in thread
From: Sören Meyer-Eppler @ 2011-10-31 16:17 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: pgsql-performance
> Note the file number appearing in the lseeks, run "lsof -p PID" against
> the backend process to discover the actual filename of that file, then
> look for a match to the filename in pg_class.relfilenode.
Will do. I need to reproduce the error first which may take a while.
>> I have attached two of the offending execution plans. Anything obviously
>> wrong with them?
>
> What makes you say these are "offending execution plans"? Both of them
> seem to be completing just fine.
That's exactly the point. The plan looks good, the execution times will
usually be good. But sometimes, for no immediately obvious reasons,
they'll run for hours.
I know these are the offending queries because this is what
"select now() - query_start, current_query from pg_stat_activity"
will tell me.
We execute these queries from a Java program via JDBC
(postgresql-9.1-901.jdbc4.jar). But since little data is being
transferred between the Java client and the database I hope that cannot
be the issue.
Anything else I should look out for/log during the next test run?
Sören
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: PostgreSQL 9.0.4 blocking in lseek?
@ 2011-12-28 09:57 Matteo Beccati <php@beccati.com>
parent: Tom Lane <tgl@sss.pgh.pa.us>
1 sibling, 2 replies; 16+ messages in thread
From: Matteo Beccati @ 2011-12-28 09:57 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: Sören Meyer-Eppler <soerenme@google.com>; pgsql-performance
Hi everyone,
On 28/10/2011 02:32, Tom Lane wrote:
> =?ISO-8859-1?Q?S=F6ren_Meyer-Eppler?= <soerenme@google.com> writes:
>> A fairly complex insert query on an empty destination table will run for
>> an indefinite amount of time (we waited literally days for the query to
>> complete). This does not happen every time we run the query but often.
>> Now ordinarily I'd assume we did something wrong with our indices or
>> query, but the execution plan looks sane and, more tellingly, we have:
>> - no CPU load
>> - no network traffic
>> - no disk I/O
>> - no other load on the server except this single query
>> and strace displaying a seemingly endless list of lseek calls.
>
>> So my assumption is that we are not running into bad Big-O() runtime
>> behavior but rather into some locking problem.
>
> If it were blocked on a lock, it wouldn't be doing lseeks().
>
> The most obvious explanation for a backend that's doing repeated lseeks
> and nothing else is that it's repeatedly doing seqscans on a table
> that's fully cached in shared buffers. I'd wonder about queries
> embedded in often-executed plpgsql functions, for instance. Can you
> identify which table the lseeks are issued against?
I'm resuming the old thread as we've recently been hit twice by a
similar issue, both on 9.1.1 and 9.1.2. Details follow the quoted part.
The first time we've seen such behaviour was a few weeks ago, using
9.1.1. I've decided to avoid posting as I messed up with gdb while
trying to gather more information. This time, I've kept the query
running, just in case I need to provide more information.
So, here they are:
Linux (ubuntu oneiric x64) on and EC2 instance (8 virtual cores, 68GB
RAM). Storage is on EBS using xfs as filesystem. Currently using
PostgreSQL 9.1.2 manually compiled.
A rather long import process is stuck since ~12hrs on a query that
normally returns in a few seconds or minutes. Kust like to OP there's
almost no activity on the box, only a single postgres process at 100% CPU.
Two separate queries, (although similar) have triggered the issue, and
they are run one after another. Also, the import is also not always
failing, I think it happened twice in about 10 runs. We're expected to
go live in about two weeks so these were only test runs.
The explain looks like this:
http://explain.depesz.com/s/TqD
The strace output:
...
2011-12-28 09:33:59.506037500 lseek(64, 0, SEEK_END) = 27623424
2011-12-28 09:33:59.555167500 lseek(64, 0, SEEK_END) = 27623424
2011-12-28 09:33:59.604315500 lseek(64, 0, SEEK_END) = 27623424
2011-12-28 09:33:59.653482500 lseek(64, 0, SEEK_END) = 27623424
2011-12-28 09:33:59.676128500 lseek(67, 0, SEEK_END) = 65511424
2011-12-28 09:33:59.676287500 write(67,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
8192) = 8192
...
2011-12-28 09:34:04.935944500 lseek(64, 0, SEEK_END) = 27623424
2011-12-28 09:34:04.945279500 lseek(67, 0, SEEK_END) = 65519616
2011-12-28 09:34:04.945394500 write(67,
"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
8192) = 8192
...
so an lseek on fd 64 roughly every 50ms and lseek/write to fd 67 every
5s. Lsof shows:
postgres 1991 postgres 64u REG 252,0 27623424
134250744 /data/postgresql/main/base/16387/44859
postgres 1991 postgres 67u REG 252,0 65732608
134250602 /data/postgresql/main/base/16387/44675
with 64 being the carts table and 67 cart_products, according to
pg_class' relfilenode. All the tables involved are regular tables but
log_conversion_item, which is unlogged.
I'm also trying an EXPLAIN ANALYZE for the SELECT part, but it seems to
take a while too and is seemingly calling only gettimeofday.
Here are the custom values in postgresql.conf:
max_connections = 200
maintenance_work_mem = 1GB
checkpoint_completion_target = 0.9
effective_cache_size = 48GB
work_mem = 128MB
wal_buffers = 16MB
checkpoint_segments = 64
shared_buffers = 8GB
synchronous_commit = off
random_page_cost = 2
archive_mode = off
wal_level = hot_standby
max_wal_senders = 2
wal_keep_segments = 256
Streaming replication was accidentally left enabled during the run, but
I'm pretty sure that I didn't set it up yet when we had the previous
failure.
I'll be happy to provide more information. For now we're going to
disconnect the slave and use that for another test import run.
Cheers
--
Matteo Beccati
Development & Consulting - http://www.beccati.com/
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: PostgreSQL 9.0.4 blocking in lseek?
@ 2011-12-28 14:20 Matteo Beccati <php@beccati.com>
parent: Matteo Beccati <php@beccati.com>
1 sibling, 0 replies; 16+ messages in thread
From: Matteo Beccati @ 2011-12-28 14:20 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: pgsql-performance
Hi,
> I'm also trying an EXPLAIN ANALYZE for the SELECT part, but it seems to
> take a while too and is seemingly calling only gettimeofday.
An update on this. Apart from gettimeofday calls, which I filtered out
when logging, I've seen about 80 lseeks recorded every 1h10m (each 1us
apart):
2011-12-28 11:06:25.546661500 lseek(10, 0, SEEK_END) = 27623424
2011-12-28 11:06:25.546662500 lseek(10, 0, SEEK_END) = 27623424
2011-12-28 11:06:25.546663500 lseek(10, 0, SEEK_END) = 27623424
...
2011-12-28 12:16:56.144663500 lseek(10, 0, SEEK_END) = 27623424
...
2011-12-28 13:28:20.436549500 lseek(10, 0, SEEK_END) = 27623424
...
I've then decided to interrupt the EXPLAIN ANALYZE. But I suppose that
the database as it is now will likely allow to further debug what's
happening.
Cheers
--
Matteo Beccati
Development & Consulting - http://www.beccati.com/
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: PostgreSQL 9.0.4 blocking in lseek?
@ 2011-12-28 18:02 Matteo Beccati <php@beccati.com>
parent: Matteo Beccati <php@beccati.com>
1 sibling, 1 reply; 16+ messages in thread
From: Matteo Beccati @ 2011-12-28 18:02 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: Sören Meyer-Eppler <soerenme@google.com>; pgsql-performance
Hi,
> A rather long import process is stuck since ~12hrs on a query that
> normally returns in a few seconds or minutes. Kust like to OP there's
> almost no activity on the box, only a single postgres process at 100% CPU.
>
> Two separate queries, (although similar) have triggered the issue, and
> they are run one after another. Also, the import is also not always
> failing, I think it happened twice in about 10 runs. We're expected to
> go live in about two weeks so these were only test runs.
>
> The explain looks like this:
> http://explain.depesz.com/s/TqD
The query eventually completed in more than 18h. For comparison a normal
run doesn't take more than 1m for that specific step.
Do you think that bad stats and suboptimal plan alone could explain such
a behaviour?
Cheers
--
Matteo Beccati
Development & Consulting - http://www.beccati.com/
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: PostgreSQL 9.0.4 blocking in lseek?
@ 2011-12-28 18:07 Claudio Freire <klaussfreire@gmail.com>
parent: Matteo Beccati <php@beccati.com>
0 siblings, 1 reply; 16+ messages in thread
From: Claudio Freire @ 2011-12-28 18:07 UTC (permalink / raw)
To: Matteo Beccati <php@beccati.com>; +Cc: Tom Lane <tgl@sss.pgh.pa.us>; Sören Meyer-Eppler <soerenme@google.com>; pgsql-performance
On Wed, Dec 28, 2011 at 3:02 PM, Matteo Beccati <php@beccati.com> wrote:
> The query eventually completed in more than 18h. For comparison a normal
> run doesn't take more than 1m for that specific step.
>
> Do you think that bad stats and suboptimal plan alone could explain such
> a behaviour?
Did you get the explain analyze output?
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: PostgreSQL 9.0.4 blocking in lseek?
@ 2011-12-28 18:41 Matteo Beccati <php@beccati.com>
parent: Claudio Freire <klaussfreire@gmail.com>
0 siblings, 1 reply; 16+ messages in thread
From: Matteo Beccati @ 2011-12-28 18:41 UTC (permalink / raw)
To: Claudio Freire <klaussfreire@gmail.com>; +Cc: Tom Lane <tgl@sss.pgh.pa.us>; Sören Meyer-Eppler <soerenme@google.com>; pgsql-performance
On 28/12/2011 19:07, Claudio Freire wrote:
> On Wed, Dec 28, 2011 at 3:02 PM, Matteo Beccati <php@beccati.com> wrote:
>> The query eventually completed in more than 18h. For comparison a normal
>> run doesn't take more than 1m for that specific step.
>>
>> Do you think that bad stats and suboptimal plan alone could explain such
>> a behaviour?
>
> Did you get the explain analyze output?
Unfortunately I stopped it as I thought it wasn't going to return
anything meaningful. I've restarted the import process and it will break
right before the problematic query. Let's see if I can get any more info
tomorrow.
Cheers
--
Matteo Beccati
Development & Consulting - http://www.beccati.com/
^ permalink raw reply [nested|flat] 16+ messages in thread
* Re: PostgreSQL 9.0.4 blocking in lseek?
@ 2011-12-29 09:03 Matteo Beccati <php@beccati.com>
parent: Matteo Beccati <php@beccati.com>
0 siblings, 0 replies; 16+ messages in thread
From: Matteo Beccati @ 2011-12-29 09:03 UTC (permalink / raw)
To: Claudio Freire <klaussfreire@gmail.com>; +Cc: Tom Lane <tgl@sss.pgh.pa.us>; Sören Meyer-Eppler <soerenme@google.com>; pgsql-performance
On 28/12/2011 19:41, Matteo Beccati wrote:
> On 28/12/2011 19:07, Claudio Freire wrote:
>> On Wed, Dec 28, 2011 at 3:02 PM, Matteo Beccati <php@beccati.com> wrote:
>>> The query eventually completed in more than 18h. For comparison a normal
>>> run doesn't take more than 1m for that specific step.
>>>
>>> Do you think that bad stats and suboptimal plan alone could explain such
>>> a behaviour?
>>
>> Did you get the explain analyze output?
>
> Unfortunately I stopped it as I thought it wasn't going to return
> anything meaningful. I've restarted the import process and it will break
> right before the problematic query. Let's see if I can get any more info
> tomorrow.
So, I'm running again the EXPLAIN ANALYZE, although I don't expect it to
return anytime soon.
However I've discovered a few typos in the index creation. If we add it
to the fact that row estimates are off for this specific query, I can
understand that the chosen plan might have been way far from optimal
with some badly picked statistics.
This is the explain analyze of the query with proper indexes in place.
As you can see estimates are still off, even though run time is ~20s:
http://explain.depesz.com/s/1UY
For comparison, here is the old explain output:
http://explain.depesz.com/s/TqD
The case is closed and as Tom pointed out already the lseek-only
activity is due to the fact that the table is fully cached in the shared
buffers and a sequential scan inside a nested loop is consistent with it.
Sorry for the noise.
Cheers
--
Matteo Beccati
Development & Consulting - http://www.beccati.com/
^ permalink raw reply [nested|flat] 16+ messages in thread
end of thread, other threads:[~2011-12-29 09:03 UTC | newest]
Thread overview: 16+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2011-10-26 15:47 PostgreSQL 9.0.4 blocking in lseek? Sören Meyer-Eppler <soerenme@google.com>
2011-10-27 07:42 ` Gregg Jaskiewicz <gryzman@gmail.com>
2011-10-27 12:03 ` Sören Meyer-Eppler <soerenme@google.com>
2011-10-27 14:54 ` Claudio Freire <klaussfreire@gmail.com>
2011-10-28 00:32 ` Tom Lane <tgl@sss.pgh.pa.us>
2011-10-31 14:09 ` Sören Meyer-Eppler <soerenme@google.com>
2011-10-31 15:28 ` Tom Lane <tgl@sss.pgh.pa.us>
2011-10-31 16:17 ` Sören Meyer-Eppler <soerenme@google.com>
2011-12-28 09:57 ` Matteo Beccati <php@beccati.com>
2011-12-28 14:20 ` Matteo Beccati <php@beccati.com>
2011-12-28 18:02 ` Matteo Beccati <php@beccati.com>
2011-12-28 18:07 ` Claudio Freire <klaussfreire@gmail.com>
2011-12-28 18:41 ` Matteo Beccati <php@beccati.com>
2011-12-29 09:03 ` Matteo Beccati <php@beccati.com>
2011-10-28 02:42 ` Josh Berkus <josh@agliodbs.com>
2011-10-31 13:56 ` Sören Meyer-Eppler <soerenme@google.com>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox