Обсуждение: Подвисший запрос

Добрый день
Есть такая проблема: иногда возникает "подвисший запрос". Запрос,
который обычно выполняется порядка 100мс, может выполняться часами.
Что приводит к заметному снижению производительности. Процесс
приходится убивать. За месяц столкнулись 6 раз.
Вопрос: с чем это может быть связано, какие параметры нужно замерить в
след раз, чтобы локализовать проблему.

Сам запрос:
SELECT "v3_vacancy"."id" FROM "v3_vacancy" WHERE (("v3_vacancy"."fti_title" @@ to_tsquery('default_russian',
'официант'))AND ("v3_vacancy"."is_spam" IS FALSE ) AND ("v3_vacancy"."published_date" >= '2007-02-23 00:00:00') AND
("v3_vacancy"."is_searchable"IS TRUE ) ) AND (("v3_vacancy"."city_id" = '1') )  ORDER BY
"v3_vacancy"."is_paid_top_search"DESC, "v3_vacancy"."modified_date" DESC LIMIT 30 OFFSET 120 
(строка поиска каждый раз разная)
Характерно использование TSearch для данной таблицы



CREATE TABLE v3_vacancy
(
  id serial NOT NULL,
  ...
  fti_all tsvector, -- TSearch2 index для всей вакансии.
  fti_title tsvector, -- TSearch2 index для названия вакансии.
)
WITH OIDS;

CREATE INDEX v3_vacancy_fti_all_idx
  ON v3_vacancy
  USING gist
  (fti_all);

CREATE INDEX v3_vacancy_fti_title_idx
  ON v3_vacancy
  USING gist
  (fti_title);


 SELECT * from pg_ts_cfg;
     ts_name     | prs_name |    locale
-----------------+----------+--------------
 default         | default  | C
 default_russian | default  | ru_RU.KOI8-R
 simple          | default  |



SELECT * from pg_ts_cfgmap ;
     ts_name     |  tok_alias   | dict_name
-----------------+--------------+-----------
 default         | lword        | {en_stem}
 default         | nlword       | {simple}
 default         | word         | {simple}
 default         | email        | {simple}
 default         | url          | {simple}
 default         | host         | {simple}
 default         | sfloat       | {simple}
 default         | version      | {simple}
 default         | part_hword   | {simple}
 default         | nlpart_hword | {simple}
 default         | lpart_hword  | {en_stem}
 default         | hword        | {simple}
 default         | lhword       | {en_stem}
 default         | nlhword      | {simple}
 default         | uri          | {simple}
 default         | file         | {simple}
 default         | float        | {simple}
 default         | int          | {simple}
 default         | uint         | {simple}
 default_russian | lword        | {en_stem}
 default_russian | nlword       | {ru_stem}
 default_russian | word         | {ru_stem}
 default_russian | email        | {simple}
 default_russian | url          | {simple}
 default_russian | host         | {simple}
 default_russian | sfloat       | {simple}
 default_russian | version      | {simple}
 default_russian | part_hword   | {simple}
 default_russian | nlpart_hword | {ru_stem}
 default_russian | lpart_hword  | {en_stem}
 default_russian | hword        | {ru_stem}
 default_russian | lhword       | {en_stem}
 default_russian | nlhword      | {ru_stem}
 default_russian | uri          | {simple}
 default_russian | file         | {simple}
 default_russian | float        | {simple}
 default_russian | int          | {simple}
 default_russian | uint         | {simple}
 simple          | lword        | {simple}
 simple          | nlword       | {simple}
 simple          | word         | {simple}
 simple          | email        | {simple}
 simple          | url          | {simple}
 simple          | host         | {simple}
 simple          | sfloat       | {simple}
 simple          | version      | {simple}
 simple          | part_hword   | {simple}
 simple          | nlpart_hword | {simple}
 simple          | lpart_hword  | {simple}
 simple          | hword        | {simple}
 simple          | lhword       | {simple}
 simple          | nlhword      | {simple}
 simple          | uri          | {simple}
 simple          | file         | {simple}
 simple          | float        | {simple}
 simple          | int          | {simple}
 simple          | uint         | {simple}

 SELECT dict_name, dict_init, dict_lexize, dict_comment from pg_ts_dict ;
    dict_name    |       dict_init       |               dict_lexize               |                   dict_comment
      

-----------------+-----------------------+-----------------------------------------+--------------------------------------------------
 simple          | dex_init(internal)    | dex_lexize(internal,internal,integer)   | Simple example of dictionary.
 en_stem         | snb_en_init(internal) | snb_lexize(internal,internal,integer)   | English Stemmer. Snowball.
 ru_stem         | snb_ru_init(internal) | snb_lexize(internal,internal,integer)   | Russian Stemmer. Snowball.
 ispell_template | spell_init(internal)  | spell_lexize(internal,internal,integer) | ISpell interface. Must have .dict
and.aff files 
 synonym         | syn_init(internal)    | syn_lexize(internal,internal,integer)   | Example of synonym dictionary



SELECT * from pg_ts_parser;
 prs_name |          prs_start           |               prs_nexttoken                |      prs_end       |
  prs_headline                |      prs_lextype       |        prs_comment 

----------+------------------------------+--------------------------------------------+--------------------+-------------------------------------------+------------------------+---------------------------
 default  | prsd_start(internal,integer) | prsd_getlexeme(internal,internal,internal) | prsd_end(internal) |
prsd_headline(internal,internal,internal)| prsd_lextype(internal) | Parser from OpenFTS v0.34 



PostgreSQL 8.1.8
OS Linux version 2.6.16-gentoo-r9 (gcc version 3.4.4 (Gentoo 3.4.4-r1, ssp-3.4.4-1.0, pie-8.7.8))


--
С уважением,
 isk                          mailto:isk@rdw.ru

hi all

Вот два эксплэйна, не спешите копаться в их WHERE хотя это и любопытно,
но не так сильно...
обратите внимание что запросы отличаются ТОЛЬКО СЕЛЕКТ-ЛИСТОМ
в первом запросе, который выполняется в 30 раз быстрее, выбираются все
поля, а во втором, выбирается только одно поле (которое входит также и в
первый запрос)
и откуда же происходит такая радикальная разница в планах ????



cms1=> EXPLAIN ANALYZE SELECT * from article as a,  (select st.id as
stid, t1.id, t1.title FROM topic as t1, topic as st WHERE t1.up=304532
and st.trail <@ t1.trail) as t where a.topic=t.stid;

                               QUERY PLAN


 Hash Join  (cost=30877.69..31472.42 rows=432 width=844) (actual
time=1.113..11.370 rows=745 loops=1)
   Hash Cond: ("outer".topic = "inner".id)
   ->  Seq Scan on article a  (cost=0.00..566.94 rows=4694 width=824)
(actual time=0.006..4.328 rows=4692 loops=1)
   ->  Hash  (cost=30856.18..30856.18 rows=8604 width=20) (actual
time=1.089..1.089 rows=30 loops=1)
         ->  Nested Loop  (cost=4.33..30856.18 rows=8604 width=20)
(actual time=0.106..1.046 rows=30 loops=1)
               ->  Index Scan using topic_up_idx on topic t1
(cost=0.00..346.48 rows=92 width=59) (actual time=0.017..0.041 rows=16
loops=1)
                     Index Cond: (up = 304532)
               ->  Bitmap Heap Scan on topic st  (cost=4.33..330.45
rows=94 width=47) (actual time=0.055..0.057 rows=2 loops=16)
                     Recheck Cond: (st.trail <@ "outer".trail)
                     ->  Bitmap Index Scan on topic_trail_idx
(cost=0.00..4.33 rows=94 width=0) (actual time=0.053..0.053 rows=2 loops=16)
                           Index Cond: (st.trail <@ "outer".trail)
 Total runtime: 11.886 ms
(12 rows)


cms1=> EXPLAIN ANALYZE SELECT t.id from article as a,  (select st.id as
stid, t1.id, t1.title FROM topic as t1, topic as st WHERE t1.up=304532
and st.trail <@ t1.trail) as t where a.topic=t.stid;

                    QUERY PLAN


 Nested Loop  (cost=6294.70..16331.26 rows=432 width=4) (actual
time=227.417..314.261 rows=745 loops=1)
   Join Filter: ("inner".trail <@ "outer".trail)
   ->  Bitmap Heap Scan on topic t1  (cost=2.32..322.30 rows=92
width=47) (actual time=0.036..0.076 rows=16 loops=1)
         Recheck Cond: (up = 304532)
         ->  Bitmap Index Scan on topic_up_idx  (cost=0.00..2.32 rows=92
width=0) (actual time=0.029..0.029 rows=16 loops=1)
               Index Cond: (up = 304532)
   ->  Materialize  (cost=6292.38..6339.32 rows=4694 width=43) (actual
time=0.853..16.298 rows=4692 loops=16)
         ->  Merge Join  (cost=853.19..6287.69 rows=4694 width=43)
(actual time=13.633..218.724 rows=4692 loops=1)
               Merge Cond: ("outer".id = "inner".topic)
               ->  Index Scan using topic_pkey on topic st
(cost=0.00..5130.78 rows=93527 width=47) (actual time=0.075..141.011
rows=93526 loops=1)
               ->  Sort  (cost=853.19..864.93 rows=4694 width=4) (actual
time=13.536..15.858 rows=4692 loops=1)
                     Sort Key: a.topic
                     ->  Seq Scan on article a  (cost=0.00..566.94
rows=4694 width=4) (actual time=0.005..7.273 rows=4692 loops=1)
 Total runtime: 315.343 ms
(14 rows)

Какие колонки в article?
Наверняка там varlena-типы есть (varchar, text, bytea и тд). В таких случаях работает TOAST-инг. Когда выбираем все колонки -- Постгресу приходится залезать в toast-таблицу. Если всё так, то ничего удивительного не случилось.
Про TOAST тут: http://www.postgresql.org/docs/8.2/interactive/storage-toast.html




--
Best regards,
Nikolay

Nikolay Samokhvalov wrote:
> Какие колонки в article?
> Наверняка там varlena-типы есть (varchar, text, bytea и тд). В таких

Есть. и много.

> случаях работает TOAST-инг. Когда выбираем все колонки -- Постгресу
> приходится залезать в toast-таблицу. Если всё так, то ничего
> удивительного не случилось.

Если это неудивительно и вы ожидали такой эффект, то скажите:
какой запрос по-вашему должен быть тормознутее ?

> Про TOAST тут:
> http://www.postgresql.org/docs/8.2/interactive/storage-toast.html
>
> On 3/28/07, * silly_sad* <sad@bankir.ru <mailto:sad@bankir.ru>> wrote:
>
>     hi all
>
>     Вот два эксплэйна, не спешите копаться в их WHERE хотя это и любопытно,
>     но не так сильно...
>     обратите внимание что запросы отличаются ТОЛЬКО СЕЛЕКТ-ЛИСТОМ
>     в первом запросе, который выполняется в 30 раз быстрее, выбираются все
>     поля, а во втором, выбирается только одно поле (которое входит также и в
>     первый запрос)
>     и откуда же происходит такая радикальная разница в планах ????
>
>
>
>     cms1=> EXPLAIN ANALYZE SELECT * from article as a,  (select st.id
>     <http://st.id> as
>     stid, t1.id <http://t1.id>, t1.title FROM topic as t1, topic as st
>     WHERE t1.up=304532
>     and st.trail <@ t1.trail) as t where a.topic=t.stid;
>
>                                    QUERY PLAN
>
>
>     Hash Join  (cost=30877.69..31472.42 rows=432 width=844) (actual
>     time=1.113..11.370 rows=745 loops=1)
>        Hash Cond: ("outer".topic = "inner".id)
>        ->  Seq Scan on article a  (cost= 0.00..566.94 rows=4694 width=824)
>     (actual time=0.006..4.328 rows=4692 loops=1)
>        ->  Hash  (cost=30856.18..30856.18 rows=8604 width=20) (actual
>     time=1.089..1.089 rows=30 loops=1)
>              ->  Nested Loop  (cost= 4.33..30856.18 rows=8604 width=20)
>     (actual time=0.106..1.046 rows=30 loops=1)
>                    ->  Index Scan using topic_up_idx on topic t1
>     (cost=0.00..346.48 rows=92 width=59) (actual time=0.017..0.041 rows=16
>     loops=1)
>                          Index Cond: (up = 304532)
>                    ->  Bitmap Heap Scan on topic st  (cost=4.33..330.45
>     rows=94 width=47) (actual time=0.055..0.057 rows=2 loops=16)
>                          Recheck Cond: ( st.trail <@ "outer".trail)
>                          ->  Bitmap Index Scan on topic_trail_idx
>     (cost=0.00..4.33 rows=94 width=0) (actual time=0.053..0.053 rows=2
>     loops=16)
>                                Index Cond: ( st.trail <@ "outer".trail)
>     Total runtime: 11.886 ms
>     (12 rows)
>
>
>     cms1=> EXPLAIN ANALYZE SELECT t.id <http://t.id> from article as
>     a,  (select st.id <http://st.id> as
>     stid, t1.id <http://t1.id>, t1.title FROM topic as t1, topic as st
>     WHERE t1.up=304532
>     and st.trail <@ t1.trail) as t where a.topic=t.stid;
>
>                         QUERY PLAN
>
>
>     Nested Loop  (cost= 6294.70..16331.26 rows=432 width=4) (actual
>     time=227.417..314.261 rows=745 loops=1)
>        Join Filter: ("inner".trail <@ "outer".trail)
>        ->  Bitmap Heap Scan on topic t1  (cost=2.32..322.30 rows=92
>     width=47) (actual time=0.036..0.076 rows=16 loops=1)
>              Recheck Cond: (up = 304532)
>              ->  Bitmap Index Scan on topic_up_idx  (cost=0.00..2.32 rows=92
>     width=0) (actual time=0.029..0.029 rows=16 loops=1)
>                    Index Cond: (up = 304532)
>        ->  Materialize  (cost=6292.38..6339.32 rows=4694 width=43) (actual
>     time=0.853..16.298 rows=4692 loops=16)
>              ->  Merge Join  (cost=853.19..6287.69 rows=4694 width=43)
>     (actual time=13.633..218.724 rows=4692 loops=1)
>                    Merge Cond: ("outer".id = "inner".topic)
>                    ->  Index Scan using topic_pkey on topic st
>     (cost= 0.00..5130.78 rows=93527 width=47) (actual time=0.075..141.011
>     rows=93526 loops=1)
>                    ->  Sort  (cost=853.19..864.93 rows=4694 width=4) (actual
>     time=13.536..15.858 rows=4692 loops=1)
>                          Sort Key: a.topic
>                          ->  Seq Scan on article a  (cost=0.00..566.94
>     rows=4694 width=4) (actual time=0.005..7.273 rows=4692 loops=1)
>     Total runtime: 315.343 ms
>     (14 rows)
>
>     ---------------------------(end of
>     broadcast)---------------------------
>     TIP 4: Have you searched our list archives?
>
>                    http://archives.postgresql.org
>
>
>
>
> --
> Best regards,
> Nikolay

Nikolay Samokhvalov wrote:
> А можно схему таблиц посмотреть?

Можно, но она большая.
Поэтому если чо, я могу рассказать.

article.up references article.id
article.topic references topic.id
topic.up references topic.id

Схема ниже, кому не интересно может не читать.

\d topic

   Column    |            Type             |
  Modifiers
-------------+-----------------------------+---------------------------------------------------------------------
 id          | integer                     | not null
 name        | text                        | not null
 realm       | text                        | not null
 guid        | text                        |
 usr         | text                        | not null
 grp         | text                        | not null
 acl         | row_acl                     | not null
 created     | timestamp without time zone | not null default now()
 creator     | text                        | not null
 updated     | timestamp without time zone | not null default now()
 updater     | text                        | not null
 exported    | timestamp without time zone | not null default
'1970-01-01 00:00:00'::timestamp without time zone
 vector      | tsvector                    |
 up          | integer                     |
 trail       | ltree                       | not null
 layer       | integer                     | not null
 pid         | integer                     | not null default 0
 score       | integer                     | not null default 0
 title       | text                        | not null default ''::text
 description | text                        | not null default ''::text
 extra       | text                        | not null default ''::text
 revision    | integer                     | not null default 0
Indexes:
    "topic_pkey" PRIMARY KEY, btree (id)
    "topic_guid_idx" UNIQUE, btree (guid)
    "topic_name_key" UNIQUE, btree (name, pid)
    "topic_acl_idx" gist (acl)
    "topic_grp_idx" btree (grp)
    "topic_layer_idx" btree (layer)
    "topic_realm_idx" btree (realm)
    "topic_trail_idx" gist (trail)
    "topic_up_idx" btree (up)
    "topic_usr_idx" btree (usr)
    "topic_vector_key" gist (vector)



\d article

  Column  |            Type             |
Modifiers
----------+-----------------------------+-----------------------------------------------------------------------
 id       | integer                     | not null
 name     | text                        | not null
 realm    | text                        | not null
 guid     | text                        |
 usr      | text                        | not null
 grp      | text                        | not null
 acl      | row_acl                     | not null
 created  | timestamp without time zone | not null default now()
 creator  | text                        | not null
 updated  | timestamp without time zone | not null default now()
 updater  | text                        | not null
 exported | timestamp without time zone | not null default '1970-01-01
00:00:00'::timestamp without time zone
 vector   | tsvector                    |
 up       | integer                     |
 trail    | ltree                       | not null
 layer    | integer                     | not null
 pid      | integer                     | not null default 0
 topic    | integer                     | not null
 title    | text                        | not null default ''::text
 abstract | text                        | not null default ''::text
 content  | text                        | not null default ''::text
 author   | text                        | not null default ''::text
 start    | timestamp without time zone | not null default now()
 stop     | timestamp without time zone | not null default
(date_trunc('day'::text, now()) + '1 day'::interval)
 extra    | text                        | not null default ''::text
 revision | integer                     | not null default 0
 locked   | timestamp without time zone | not null default
'infinity'::timestamp without time zone
 locker   | text                        | not null default 'anonymous'::text
 score    | integer                     | not null default 0
 type     | integer                     | not null default 0
 section  | integer[]                   | not null default '{}'::integer[]
Indexes:
    "article_pkey" PRIMARY KEY, btree (id)
    "article_guid_idx" UNIQUE, btree (guid)
    "article_name_key" UNIQUE, btree (name, topic)
    "article_acl_idx" gist (acl)
    "article_grp_idx" btree (grp)
    "article_layer_idx" btree (layer)
    "article_realm_idx" btree (realm)
    "article_section_idx" gist (section)
    "article_topic_idx" btree (topic)
    "article_trail_idx" gist (trail)
    "article_up_idx" btree (up)
    "article_usr_idx" btree (usr)
    "article_vector_key" gist (vector)

Nikolay Samokhvalov wrote:
>>     обратите внимание что запросы отличаются ТОЛЬКО СЕЛЕКТ-ЛИСТОМ
> Какие колонки в article?

я вдогонку хочу ещё разх обратить ваше внимание на то как изменился план
(второй по сравнению с первым) article ушёл в глубину зачем-то
и если верить эксплэйну был полностью выбран без условия:

>                    ->  Sort  (cost=853.19..864.93 rows=4694 width=4) (actual
>     time=13.536..15.858 rows=4692 loops=1)
>                          Sort Key: a.topic
>                          ->  Seq Scan on article a  (cost=0.00..566.94
>     rows=4694 width=4) (actual time=0.005..7.273 rows=4692 loops=1)