I ran into this oddity lately that goes against everything I thought I
understood and was wondering if anyone had any insight. Version/env
details at the end.
The root of it is these query times:
marcs=# select * from ccrimes offset 5140000 limit 1;
[...data omitted...]
(1 row)
Time: 650.280 ms
marcs=# select description from ccrimes offset 5140000 limit 1;
description
-------------------------------------
FINANCIAL IDENTITY THEFT OVER $ 300
(1 row)
Time: 1298.672 ms
These times are all from data that is cached and are very repeatable.
Yes, I know that offset and limit without an order by isn't useful for
paging through data.
And an explain on them both... everything looks the same other than
the width and actual times:
marcs=# explain (analyze,buffers) select * from ccrimes offset 5140000 limit 1;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------
Limit (cost=204146.73..204146.73 rows=1 width=202) (actual
time=1067.901..1067.901 rows=1 loops=1)
Buffers: shared hit=152743
-> Seq Scan on ccrimes (cost=0.00..204146.73 rows=5139873
width=202) (actual time=0.014..810.672 rows=5140001 loops=1)
Buffers: shared hit=152743
Total runtime: 1067.951 ms
(5 rows)
Time: 1068.612 ms
marcs=# explain (analyze,buffers) select description from ccrimes
offset 5140000 limit 1;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------
Limit (cost=204146.73..204146.73 rows=1 width=17) (actual
time=1713.027..1713.027 rows=1 loops=1)
Buffers: shared hit=152743
-> Seq Scan on ccrimes (cost=0.00..204146.73 rows=5139873
width=17) (actual time=0.013..1457.521 rows=5140001 loops=1)
Buffers: shared hit=152743
Total runtime: 1713.053 ms
(5 rows)
Time: 1713.612 ms
When I run the query and capture a profile using "perf" and compare
the two, the thing that stands out is the slot_getsomeattrs call that
dominates the trace in the slow query but not in the faster "SELECT *"
version:
- 39.25% postgres postgres [.] _start
- _start
- 99.47% slot_getsomeattrs
ExecProject
ExecScan
ExecProcNode
ExecLimit
ExecProcNode
standard_ExecutorRun
0x7f4315f7c427
PortalRun
PostgresMain
PostmasterMain
main
__libc_start_main
+ 0.53% ExecProject
+ 18.82% postgres postgres [.] HeapTupleSatisfiesMVCC
+ 12.01% postgres postgres [.] 0xb6353
+ 9.47% postgres postgres [.] ExecProject
The table is defined as:
Column | Type | Modifiers
----------------------+--------------------------------+-----------
s_updated_at_0 | timestamp(3) with time zone |
s_version_1 | bigint |
s_id_2 | bigint |
s_created_at_3 | timestamp(3) with time zone |
id | numeric |
case_number | text |
date | timestamp(3) without time zone |
block | text |
iucr | text |
primary_type | text |
description | text |
location_description | text |
arrest | boolean |
domestic | boolean |
beat | text |
district | text |
ward | numeric |
community_area | text |
fbi_code | text |
x_coordinate | numeric |
y_coordinate | numeric |
year | numeric |
updated_on | timestamp(3) without time zone |
latitude | numeric |
longitude | numeric |
location_lat | double precision |
location_long | double precision |
I've been testing this against Postgres 9.3.5 on Ubuntu 12.04 LTS
running with a 3.2.0 kernel, and get similar results on both raw
hardware and in Azure VMs. This repros on boxes with no other load.
Any suggestions about what is going on or where to dig further would
be appreciated. I can make a pgdump of the data I'm using if anyone
is interested.
Thanks.
--
Sent via pgsql-performance mailing list (pgsql-performance@xxxxxxxxxxxxxx)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
