为什么这个快速的 postgres 查询会出现在慢查询日志中？

Question

在调查 Postgres 日志中的一个条目时，我注意到报告的持续时间和查询速度之间存在很大差异。

2015-07-28 17:27:26 UTC [dms_segment_3] LOG:  duration: 2924.763 ms  bind <unnamed>: SELECT  prospect.id AS prospect_id,  0,  am.id, am.customer_id, 0 FROM xxxxx.audience_member am LEFT OUTER JOIN xxxxx.campaign campaign     ON campaign.id = $1 LEFT OUTER JOIN xxxxx.end_user prospect     ON campaign.id=prospect.campaign_id        AND prospect.email_id=am.customer_id        AND prospect.end_user_type != 1 WHERE am.audience_id = $2  ORDER BY am.id limit $3
2015-07-28 17:27:26 UTC [dms_segment_3] DETAIL:  parameters: $1 = '4000013578869', $2 = '4000013744916', $3 = '500'

在该查询上运行解释会产生更快的速度：

explain analyze
SELECT  prospect.id AS prospect_id
,  0,  am.id, am.customer_id, 0
FROM xxxxx.audience_member am
LEFT OUTER JOIN xxxxx.campaign campaign
     ON campaign.id = 4000013578869 
LEFT OUTER JOIN xxxxx.end_user prospect
     ON campaign.id = prospect.campaign_id
    AND prospect.email_id = am.customer_id
    AND prospect.end_user_type != 1
WHERE am.audience_id = 4000013744916
ORDER BY am.id
limit 500;
                                                                                     QUERY PLAN

-------------------------------------------------------------------------------------------------------------------------------------------------------------
-----------------------
 Limit  (cost=326.61..326.67 rows=26 width=24) (actual time=0.500..0.517 rows=4 loops=1)
   ->  Sort  (cost=326.61..326.67 rows=26 width=24) (actual time=0.491..0.498 rows=4 loops=1)
         Sort Key: am.id
         Sort Method: quicksort  Memory: 25kB
         ->  Nested Loop Left Join  (cost=0.00..326.00 rows=26 width=24) (actual time=0.260..0.402 rows=4 loops=1)
               Join Filter: (campaign.id = prospect.campaign_id)
               ->  Nested Loop Left Join  (cost=0.00..107.25 rows=26 width=24) (actual time=0.237..0.346 rows=4 loops=1)
                     ->  Index Scan using idx_audience_member_audience_id on audience_member am  (cost=0.00..99.62 rows=26 width=16) (actual time=0.062.
.0.071 rows=4 loops=1)
                           Index Cond: (audience_id = 4000013744916::bigint)
                     ->  Materialize  (cost=0.00..7.30 rows=1 width=8) (actual time=0.042..0.060 rows=1 loops=4)
                           ->  Seq Scan on campaign  (cost=0.00..7.30 rows=1 width=8) (actual time=0.154..0.219 rows=1 loops=1)
                                 Filter: (id = 4000013578869::bigint)
                                 Rows Removed by Filter: 23
               ->  Index Scan using idx_enduser_emailaddress on end_user prospect  (cost=0.00..8.40 rows=1 width=24) (actual time=0.006..0.006 rows=0 loops=4
)
                     Index Cond: (email_id = am.customer_id)
                     Filter: ((end_user_type <> 1) AND (campaign_id = 4000013578869::bigint))
 Total runtime: 0.701 ms
(17 rows)

有什么我想念的吗？什么可以解释日志与“真实”查询持续时间之间 2 秒以上的差距？

我们使用的是 Postgres 9.2。在生产中，我们在 Tomcat 6 应用程序中混合使用 Hibernate 查询和本机 SQL。

更新：

jpmc26 的鹰眼发现参数在日志中作为字符串传递，但在解释中没有，所以我再次运行它：

explain analyze SELECT  prospect.id AS prospect_id,  0,  am.id, am.customer_id, 0 FROM xxxxx.audience_member am LEFT OUTER JOIN xxxxx.campaign campaign     ON campaign.id = '4000013578869' LEFT OUTER JOIN xxxxx.end_user prospect     ON campaign.id=prospect.campaign_id        AND prospect.email_id=am.customer_id        AND prospect.end_user_type != 1 WHERE am.audience_id = '4000013744916'  ORDER BY am.id limit '500';
                                                                                     QUERY PLAN

-------------------------------------------------------------------------------------------------------------------------------------------------------------
-----------------------
 Limit  (cost=326.62..326.68 rows=26 width=24) (actual time=0.168..0.186 rows=4 loops=1)
   ->  Sort  (cost=326.62..326.68 rows=26 width=24) (actual time=0.164..0.171 rows=4 loops=1)
         Sort Key: am.id
         Sort Method: quicksort  Memory: 25kB
         ->  Nested Loop Left Join  (cost=0.00..326.01 rows=26 width=24) (actual time=0.065..0.145 rows=4 loops=1)
               Join Filter: (campaign.id = prospect.campaign_id)
               ->  Nested Loop Left Join  (cost=0.00..107.25 rows=26 width=24) (actual time=0.051..0.102 rows=4 loops=1)
                     ->  Index Scan using idx_audience_member_audience_id on audience_member am  (cost=0.00..99.62 rows=26 width=16) (actual time=0.017.
.0.025 rows=4 loops=1)
                           Index Cond: (audience_id = 4000013744916::bigint)
                     ->  Materialize  (cost=0.00..7.30 rows=1 width=8) (actual time=0.009..0.013 rows=1 loops=4)
                           ->  Seq Scan on campaign  (cost=0.00..7.30 rows=1 width=8) (actual time=0.023..0.031 rows=1 loops=1)
                                 Filter: (id = 4000013578869::bigint)
                                 Rows Removed by Filter: 23
               ->  Index Scan using idx_enduser_emailaddress on end_user prospect  (cost=0.00..8.40 rows=1 width=24) (actual time=0.005..0.005 rows=0 loops=4
)
                     Index Cond: (email_id = am.customer_id)
                     Filter: ((end_user_type <> 1) AND (campaign_id = 4000013578869::bigint))
 Total runtime: 0.259 ms
(17 rows)

这一次在内存中查询的好处是显而易见的，但其他方面没有任何改变。

Answer 1

您在日志中看到的是准备好的语句执行。使用准备好的语句是从应用程序层与数据库交互的常用方法。

例如，使用 Hibernate，可以编写如下内容（希望下面的代码片段是有效的，没有测试它）：

String sql = "SELECT first_name, last_name FROM customer WHERE email = :customer_email";
...
query.setParameter("customer_email", Customer.email);

除此之外，这是避免SQL 注入的好方法- 与使用连接构建完整的查询文本（包括参数）不同。

人们也可以从 PostgreSQL 客户端执行此操作：

PREPARE fetch_customer (text) AS
    SELECT first_name, last_name FROM customer WHERE email = $1;

[EXPLAIN ANALYZE] EXECUTE fetch_customer ('john@gmail.com');

另一方面，这就是您所经历的，准备好的查询可能会导致性能较差。准备好的语句不能从知道传递给它的值是什么中获得优势 - 只是因为它们在准备时是未知的。因此，它必须选择一个足够通用的查询计划，以便在可接受的时间内获得任何可能的结果。

例如，假设您有一个像这样的部分索引

CREATE INDEX ON xxxx.campaign (campaign_id) WHERE campaign.id > 4000000000000;

（这在现实生活中没有多大意义，但没关系）。

当规划器知道它有 4000013578869 as 时campaign_id，它可以选择使用此索引，这可能会显着减少要获取的数据页的数量。然而，准备好的声明无法做到这一点，因为一些（大多数？）可能的活动将被排除在外。