Разное время одного и того же запроса включая explain analyze / PostgreSQL

Мобильная версия Контакт Правила FAQ Помощь

Гость

Войти | Регистрация | Профиль | Очистить

Форумы | Пользователи | Статистика | Мод. лог | Поиск

Доб. в избранное | Игнор. тему | Прикреп. тему | Пометить прочит. / непрочит. | Фильтр

Форумы / PostgreSQL [игнор отключен] [закрыт для гостей] / Разное время одного и того же запроса включая explain analyze

10 сообщений из 10, страница 1 из 1

Разное время одного и того же запроса включая explain analyze

#39717182

BigBudda

Гость

На сервере СУБД Postgresql 9.6.1 запускаю psql и выполняю один и тот же запрос, который то отрабатывает за 5-7 секунд, то висит по нескольку часов. Блокировок нет, по крайней мере я их не наблюдаю.
Не понятна картина происходящего.

Код: plsql

1.
2.
3.
4.

db1=# explain analyze select *,  shirota as latitude, dolgota as longitude
from some.journal(null,null,null,to_timestamp('09.10.2018 00:00:00','DD.MM.YYYY HH24:MI:SS')::timestamp,
to_timestamp('12.10.2018 20:59:59','DD.MM.YYYY HH24:MI:SS')::timestamp,null,null::varchar,null)
order by some_date desc limit 10;

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.

                                                               QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=31.87..31.89 rows=10 width=696) (actual time=6992.614..6992.618 rows=10 loops=1)
   ->  Sort  (cost=31.87..34.37 rows=1000 width=696) (actual time=6992.612..6992.613 rows=10 loops=1)
         Sort Key: some_date DESC
         Sort Method: top-N heapsort  Memory: 29kB
         ->  Function Scan on journal  (cost=0.26..10.26 rows=1000 width=696) (actual time=6609.147..6819.728 rows=268444 loops=1)
 Planning time: 0.168 ms

Execution time: 7019.588 ms
(7 rows)

Тот же запрос, но время выполнения больше часа. Количество обрабатываемых строк одно и тоже.

Код: plsql

1.
2.
3.
4.

db1=# explain analyze select *,  shirota as latitude, dolgota as longitude
from some.journal(null,null,null,to_timestamp('09.10.2018 00:00:00','DD.MM.YYYY HH24:MI:SS')::timestamp,
to_timestamp('12.10.2018 20:59:59','DD.MM.YYYY HH24:MI:SS')::timestamp,null,null::varchar,null)
order by some_date desc limit 10;

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.

                                                                  QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=31.87..31.89 rows=10 width=696) (actual time=4122829.020..4122829.024 rows=10 loops=1)
   ->  Sort  (cost=31.87..34.37 rows=1000 width=696) (actual time=4122829.019..4122829.019 rows=10 loops=1)
         Sort Key: some_date DESC
         Sort Method: top-N heapsort  Memory: 29kB
         ->  Function Scan on journal  (cost=0.26..10.26 rows=1000 width=696) (actual time=4122477.150..4122666.161 rows=268444 loops=1)
 Planning time: 0.189 ms

Execution time: 4122855.497 ms
(7 rows)

В чём может быть причина?
По БД собирал статистику ( analyze ), делал vacuum full . По CPU виртуальная машина загружена на 45-50%.
Явного свопа не наблюдаю. По дискам тоже не сказать, что есть проблема.

Запрос рандомно, то отрабатывает, то напрочь зависает.

...

Рейтинг:

0 / 0

14.10.2018, 02:58

| Ответить | Цитировать | Написать

Разное время одного и того же запроса включая explain analyze

#39717184

BigBudda

Гость

Функция some.journal из запроса вызывается со следующими характеристиками

Код: plsql

1.
2.
3.

COST 100
VOLATILE 
ROWS 1000

Может быть всё дело в cost и volatile?
Я не очень хорошо знаком с функциями в postgresql. Насколько корректным тут будет использовать вариант с STABLE или IMMUTABLE?

...

Рейтинг:

0 / 0

14.10.2018, 03:34

| Ответить | Цитировать | Написать

Разное время одного и того же запроса включая explain analyze

#39717202

qwwq

Участник

Сообщения: 2 880

Рейтинг: 0 / 0

BigBudda...

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.

                                                               QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=31.87..31.89 rows=10 width=696) (actual time=6992.614..6992.618 rows=10 loops=1)
   ->  Sort  (cost=31.87..34.37 rows=1000 width=696) (actual time=6992.612..6992.613 rows=10 loops=1)
         Sort Key: some_date DESC
         Sort Method: top-N heapsort  Memory: 29kB
         ->  Function Scan on journal  (cost=0.26..10.26 rows=1000 width=696) (actual time=6609.147..6819.728 rows=268444 loops=1)
 Planning time: 0.168 ms

Execution time: 7019.588 ms
(7 rows)

...

Код: plaintext

1.
2.
3.
4.
5.
6.
7.
8.

                                                                  QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=31.87..31.89 rows=10 width=696) (actual time=4122829.020..4122829.024 rows=10 loops=1)
   ->  Sort  (cost=31.87..34.37 rows=1000 width=696) (actual time=4122829.019..4122829.019 rows=10 loops=1)
         Sort Key: some_date DESC
         Sort Method: top-N heapsort  Memory: 29kB
         ->  Function Scan on journal  (cost=0.26..10.26 rows=1000 width=696) (actual time=4122477.150..4122666.161 rows=268444 loops=1)
 Planning time: 0.189 ms

Execution time: 4122855.497 ms
(7 rows)
.
трабла с функцией

у вас во втором случае функция начинает выводить данные через 4122477.150

причина может быть в блокировке. (как и где вы ее не наблюдаете не ясно)

может быть в холодных данных/индексах (что там у вас в хфункции деется отсюда не видно. хотя бы буфера вывели бы, что ли, в експлейне)

и вообще влезьте в свою функцию превратите ее в препаред по возможности и тюньте
если большая -- погоняйте куски запросами. чел, пишущий хфункции, должен представлять, какая у них там унутре неонка . и что и скока стоит в планах.

ну и про виртуалку ничо не ясно. могабыть и своп.

...

Рейтинг:

0 / 0

14.10.2018, 09:23

| Ответить | Цитировать | Написать

Разное время одного и того же запроса включая explain analyze

#39717259

BigBudda

Гость

авторпричина может быть в блокировке. (как и где вы ее не наблюдаете не ясно)

блокировки смотрю в pgcenter по полям wait_etype, wait_event - они пустые.

Код: plsql

1.
2.

pid   cl_addr  cl_port  datname      usename   state   wait_etype  wait_event  xact_age  query_age  change_age    query
4476           -1         db1        postgres  active                          00:03:54  00:03:54    00:03:54    explain (analyze,buffers) select *, shirota as latitude, dolgota as longitude from some.journal(null,null,

...

Рейтинг:

0 / 0

14.10.2018, 14:59

| Ответить | Цитировать | Написать

Разное время одного и того же запроса включая explain analyze

#39717261

BigBudda

Гость

нагрузку также наблюдаю через pgcenter, видно что своп всего 46 Мб.

Код: plsql

1.
2.
3.
4.

pgcenter: 2018-10-14 15:05:24, load average: 1.45, 1.43, 1.13                                                         conn1 [ok]: /tmp:5432 postgres@postgres (ver: 9.6.1, up 1 day 17:26:33)
    %cpu: 22.2 us,  3.8 sy,  0.0 ni, 73.8 id,  0.1 wa,  0.0 hi,  0.4 si,  0.0 st                                        activity: 13 total, 10 idle,  0 idle_in_xact,  3 active,  0 waiting,  0 others
 MiB mem:  32013 total,   1800 free,    702 used,    29511 buff/cached                                                autovacuum:  0/3 workers/max,  0 manual,  0 wraparound, 00:00:00 vac_maxtime
MiB swap:  16127 total,  16081 free,     46 used,    895/55 dirty/writeback                                           statements:  15 stmt/s,  18.798 stmt_avgtime, 00:13:39 xact_maxtime

...

Рейтинг:

0 / 0

14.10.2018, 15:07

| Ответить | Цитировать | Написать

Разное время одного и того же запроса включая explain analyze

#39717269

qwwq

Участник

Сообщения: 2 880

Рейтинг: 0 / 0

BigBuddaнагрузку также наблюдаю через pgcenter, видно что своп всего 46 Мб.

своп (при работе с субд) бывает "всего" 0
и "приплыли" -- если >0
имхо

...

Рейтинг:

0 / 0

14.10.2018, 16:25

| Ответить | Цитировать | Написать

Разное время одного и того же запроса включая explain analyze

#39717288

Maxim Boguk

Участник

Откуда: Melbourne, Австралия

Сообщения: 5 148

Рейтинг: 0 / 0

BigBudda,

Вы вообще ничего не показали своими данными.
Вам надо лезть внутрь кода функции и смотреть что там происходит и почему оно тормозит.
Проще всего туда десяток RAISE WARNING/NOTICE вставить с clock_timestamp и посмотреть какая часть тормозит
а потом уже предметно ее смотреть что там не так.

--
Maxim Boguk
лучшая поддержка PostgreSQL: dataegret.ru [/quot]

...

Рейтинг:

0 / 0

14.10.2018, 18:19

| Ответить | Цитировать | Написать

Разное время одного и того же запроса включая explain analyze

#39717297

BigBudda

Гость

авторхотя бы буфера вывели бы, что ли, в експлейне

Отработал explain с buffers. Размер одного буфера по умолчанию 8 Кб?
Тогда запрос запихивает в кэш 180841652 * 8 Кб = 1379 Гб?! Что просто дохрена.
А с учётом того, что запрос выполняется постоянно, кэша в 8 ГБ (shared_buffers=8096MB) не хватает и отсюда видимо и проблема. Я так предполагаю.

Код: plsql

1.
2.
3.
4.

db1=# explain (analyze,buffers) select *,  shirota as latitude, dolgota as longitude
from some.journal(null,null,null,to_timestamp('09.10.2018 00:00:00','DD.MM.YYYY HH24:MI:SS')::timestamp,
to_timestamp('12.10.2018 20:59:59','DD.MM.YYYY HH24:MI:SS')::timestamp,null,null::varchar,null)
order by position_date desc limit 10;

Код: plsql

1.
2.
3.
4.
5.
6.
7.

                                                                 QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=31.87..31.89 rows=10 width=696) (actual time=4418047.874..4418047.882 rows=10 loops=1)
   Buffers: shared hit=180841652, temp read=58312 written=45096
   ->  Sort  (cost=31.87..34.37 rows=1000 width=696) (actual time=4418047.873..4418047.878 rows=10 loops=1)
         Sort Key: position_date DESC
         Sort Method: top-N heapsort  Memory: 29kB

Buffers: shared hit=180841652, temp read=58312 written=45096
-> Function Scan on journal (cost=0.26..10.26 rows=1000 width=696) (actual time=4417637.535..4417852.014 rows=268468 loops=1)
Buffers: shared hit=180841652, temp read=58312 written=45096
Planning time: 0.190 ms
Execution time: 4418092.168 ms
(10 rows)

Основную идею сказанного я понял. Буду общаться с разработчиками.
Вопрос только в том, почему запрос иногда отрабатывает быстро (3-5 секунд)? Как это объяснить?
Из-за того, что ничего не нужно вытеснять из кэша и нужные буфферы там уже есть?

...

Рейтинг:

0 / 0

14.10.2018, 19:25

| Ответить | Цитировать | Написать

Разное время одного и того же запроса включая explain analyze

#39717346

Maxim Boguk

Участник

Откуда: Melbourne, Австралия

Сообщения: 5 148

Рейтинг: 0 / 0

BigBudda,

Скорее всего там запрос который в зависимости от данных в базе может или очень быстро или очень медленно работать где то.
Но где именно не видя исходников - не сказать.

--
Maxim Boguk
лучшая поддержка PostgreSQL: dataegret.ru [/quot]

...

Рейтинг:

0 / 0

14.10.2018, 23:07

| Ответить | Цитировать | Написать

Разное время одного и того же запроса включая explain analyze

#39717381

qwwq

Участник

Сообщения: 2 880

Рейтинг: 0 / 0

BigBudda
Тогда запрос запихивает в кэш 180841652 * 8 Кб = 1379 Гб?!

Buffers: shared hit=180841652, temp read=58312 written=45096

нет. он берет из кеша в сумме стока сколько хит. вероятно многократно повторно одно и то же.
то что он читает с диска -- это рид. пишет -- вриттен.

т.к. в буферсах явной работы с диском нет, то он либо рабртает с ним неявно (своп) либо планы внутре скачут.

теперь представьте, что он произвольным доступом кладет и берет это вот все мимо тазика -- т.е. из ваших 64МБ свопа. и так 100500 раз. т.е. по полоборота на каждый доступ. вот оно то и набежит за 180лямов доступов.

хотя это вольный домыысел. и при таких объёмах вычислений без ридов все мможет зависеть от плана счета. как говорит максим.

...

Рейтинг:

0 / 0

15.10.2018, 08:10

| Ответить | Цитировать | Написать

10 сообщений из 10, страница 1 из 1

Форумы / PostgreSQL [игнор отключен] [закрыт для гостей] / Разное время одного и того же запроса включая explain analyze

Цитировать

Написать

Автор*:

Ввести пароль для входа

Тема*:

Сообщение

Данное сообщение тематическое

Сообщение содержит картинки или видео 18+

Автор:

ВНИМАНИЕ! На данном подфоруме действуют строгие правила. Удостоверьтесь, что ваше сообщение соответствует им!

Форум или тема закрыты для гостей. Необходима авторизация!

Загрузить последнюю сохраненную версию

Вложение:

Вставить как галерею

Максимальный размер вложений: 4,0 МБ, аудио/видео: 8,0 МБ. Картинки большего размера ужимаются, если возможно.

Введите код, изображенный на картинке. Если код нечитаемый, кликните картинку, чтобы загрузить другой вариант.

Отправляя сообщение, я выражаю свое согласие с правилами форума и принимаю пользовательское соглашение.

Читали тему (0):

Читали форум (0):

Пользователи онлайн (0):

start [/forum/topic.php?fid=53&msg=39717381&tid=1995549]:	0ms
get settings:	10ms
get forum list:	12ms
check forum access:	4ms
check topic access:	4ms
track hit:	48ms
get topic data:	9ms
get forum data:	2ms
get page messages:	52ms
get tp. blocked users:	1ms
others:	259ms

total:	401ms