:: Не фоксом единым
• Войти
Страницы:  1 2
PostgreSQL - время запроса
S-type
Автор

Сообщений: 2969
Дата регистрации: 24.04.2004
S-type
19.09.19 12:04:08
Из программы на C# с помощью Entity выполняется запрос к базе. В логе PostgreSql-я вижу

Цитата:
2019-09-19 10:49:14.917 MSK [5128] СООБЩЕНИЕ: продолжительность: 3505.839 мс, оператор: SELECT ...

Запрос выполняется 3 с половиной секунды. А если этот же запрос запустить в DBeaver-е, он показывает:

Цитата:
24508 строк получено - 350ms (+248ms)

Т.е. запрос выполняется на порядок быстрее. Вопрос - почему? Какая разница PostgreSQL-ю, откуда прилетел запрос (из бобра или из c#-ной программы)?

Может проблема в кэше? Перезапускаю службу Postgres-а (postgresql-10), выполняю запрос из DBeaver - быстро, запускаю программу - несколько секунд.

Господа, что посоветуете? В какую сторону копать? Может, надо в c#-пе какие то параметры подкрутить, или свойства драйвера настроить?

P.S. А что означает (+248ms)?



Исправлено 4 раз(а). Последнее : S-type, 19.09.19 12:19
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
PaulWist

Сообщений: 14625
Дата регистрации: 01.04.2004
PaulWist
19.09.19 12:12:11
Пример запросов в студию, плюс планы выполнения, но похоже на параметр сниффинг.


------------------
Есть многое на свете, друг Горацио...
Что и не снилось нашим мудрецам.
(В.Шекспир Гамлет)
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
S-type
Автор

Сообщений: 2969
Дата регистрации: 24.04.2004
S-type
19.09.19 12:17:57
Это запрос:

Часть текста скрыта

Вот план:

[attachment 31942 s1.png]
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
S-type
Автор

Сообщений: 2969
Дата регистрации: 24.04.2004
S-type
19.09.19 12:18:50
PaulWist
похоже на параметр сниффинг.

Что за параметр? Где и как он устанавливает? Можно ссылку на почитать?
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
ssa

Сообщений: 13008
Откуда: Москва
Дата регистрации: 23.03.2005
ssa
19.09.19 12:40:27
S-type
PaulWist
похоже на параметр сниффинг.

Что за параметр? Где и как он устанавливает? Можно ссылку на почитать?
Это не параметр, это "прослушивание параметров". Гугли по "parameter sniffing".

------------------
Лень - это неосознанная мудрость.
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
S-type
Автор

Сообщений: 2969
Дата регистрации: 24.04.2004
S-type
19.09.19 12:46:02
Погуглил. Что то все ссылки ведут к Ms Sql-ю.
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
PaulWist

Сообщений: 14625
Дата регистрации: 01.04.2004
PaulWist
19.09.19 14:23:57
1. Теперь давай select и план из твоей проги.

2. У тебя половина времени от ВСЕГО запроса тратится на сортировку, скорее всего для UserGroups.ID индекс есть, а для 
case  

              when ("Extent2"."UserGroup" is null) then (cast (null as int4))  

              else (1)  

          end as "C1"
можно создать вычисляемое поле, что бы его включить в индекс (ID, C1)

3. Индексы на таблицы приведи.


------------------
Есть многое на свете, друг Горацио...
Что и не снилось нашим мудрецам.
(В.Шекспир Гамлет)




Исправлено 1 раз(а). Последнее : PaulWist, 19.09.19 14:26
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
S-type
Автор

Сообщений: 2969
Дата регистрации: 24.04.2004
S-type
19.09.19 15:14:12
PaulWist
1. Теперь давай select и план из твоей проги.

В программе Entity код, который генерит селект. Посмотрел select - он один в один, как в логе.
Из LINQ to Entities можно получить план выполнения запроса? Как его получить?
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
PaulWist

Сообщений: 14625
Дата регистрации: 01.04.2004
PaulWist
19.09.19 15:24:07
Нет, соединение из проги и соединение из бобра имеют разные настройки SET, вот их для начала сравни.

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


------------------
Есть многое на свете, друг Горацио...
Что и не снилось нашим мудрецам.
(В.Шекспир Гамлет)
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
S-type
Автор

Сообщений: 2969
Дата регистрации: 24.04.2004
S-type
19.09.19 15:24:16
PaulWist
2. У тебя половина времени от ВСЕГО запроса тратится на сортировку, скорее всего для UserGroups.ID индекс есть,...
И, пусть тратит. В DBeaver даже с таким планом выполняется за 350 мс - нет смысла оптимизировать запрос с такой скоростью выполнения.

Вопрос в другом - почему этот запрос, вызванный из под C# выполняется на порядок дольше.
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
S-type
Автор

Сообщений: 2969
Дата регистрации: 24.04.2004
S-type
19.09.19 15:29:57
PaulWist
Нет, соединение из проги и соединение из бобра имеют разные настройки SET, вот их для начала сравни.

Посмотреть настройки в бобре можно открыв бобёр и указав:

Цитата:
show all;

А посмотреть из программы - это в программе выполнить этот код и посмотреть - что выведет?
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
S-type
Автор

Сообщений: 2969
Дата регистрации: 24.04.2004
S-type
19.09.19 15:33:20
PaulWist
Ммм, планы создаются и сохраняются на сервере, надо очистить кеш планов на сервере, выполнить запрос из проги, а затем посмотреть (вытащить) план на сервере, он там должен быть один.

Спасибо, гляну!
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
PaulWist

Сообщений: 14625
Дата регистрации: 01.04.2004
PaulWist
19.09.19 16:02:57
Ну да, это же настройки конкретного соединения.


------------------
Есть многое на свете, друг Горацио...
Что и не снилось нашим мудрецам.
(В.Шекспир Гамлет)
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
S-type
Автор

Сообщений: 2969
Дата регистрации: 24.04.2004
S-type
20.09.19 02:38:11
Нарыл habr.com там ссылка на postgrespro.ru - планы можно выводить прямо в лог, попробую.
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
S-type
Автор

Сообщений: 2969
Дата регистрации: 24.04.2004
S-type
20.09.19 11:25:24
В postgresql.conf установил: 




log_min_duration_statement = 1000

shared_preload_libraries = 'auto_explain'

debug_print_plan = on

Т.е. отслеживать запросы, выполняющиеся более секунды, подключить вывод плана. Получилось вот так - что то взрывающее мозг Попробую получить что то более приемлемое.
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
S-type
Автор

Сообщений: 2969
Дата регистрации: 24.04.2004
S-type
20.09.19 11:45:23
Установил в конфиге, как в статье 



shared_preload_libraries = 'auto_explain' 



auto_explain.log_min_duration = '1000ms'

auto_explain.log_analyze = true

auto_explain.log_buffers = true

получил план: 



2019-09-20 11:43:12.948 MSK [8032] СООБЩЕНИЕ:  duration: 3177.924 ms  plan:

    Query Text: SELECT "Project1"."Id", "Project1"."SystemCode", "Project1"."IsActual", "Project1"."Name", "Project1"."DepartmentId", "Project1"."DispatcherId", 

"Project1"."RegionalGroup", "Project1"."TreePath", "Project1"."Parent", "Project1"."C1", "Project1"."Id1", "Project1"."Login", "Project1"."Password", "Project1"."Name1", 

"Project1"."MiddleName", "Project1"."Surname", "Project1"."Position", "Project1"."SecurityToken", "Project1"."Address", "Project1"."Room", "Project1"."InternalPhone", 

"Project1"."CityPhone", "Project1"."MobilePhone", "Project1"."Email", "Project1"."Department", "Project1"."Organisation", "Project1"."PostalCode", "Project1"."IsAD", 

"Project1"."IsActual1", "Project1"."IsExternalEmail", "Project1"."PhotoURI", "Project1"."PhotoSize", "Project1"."FiredDate", "Project1"."FunctioningCapacitySettings", 

"Project1"."Region", "Project1"."Chief", "Project1"."PreviousChief", "Project1"."Settings", "Project1"."Alternate", "Project1"."OrganisationId", "Project1"."DepartmentId1", 

"Project1"."PositionId", "Project1"."TreePath1", "Project1"."Id2", "Project1"."Code", "Project1"."Name2", "Project1"."IsActual2", "Project1"."ParentId", "Project1"."TreePath2", 

"Project1"."OrderNum" FROM (SELECT "Extent1"."Id", "Extent1"."SystemCode", "Extent1"."IsActual", "Extent1"."Name", "Extent1"."DepartmentId", "Extent1"."DispatcherId", 

"Extent1"."RegionalGroup", "Extent1"."TreePath", "Extent1"."Parent", "Extent3"."Id" AS "Id1", "Extent3"."Login", "Extent3"."Password", "Extent3"."Name" AS "Name1", 

"Extent3"."MiddleName", "Extent3"."Surname", "Extent3"."Position", "Extent3"."SecurityToken", "Extent3"."Address", "Extent3"."Room", "Extent3"."InternalPhone", 

"Extent3"."CityPhone", "Extent3"."MobilePhone", "Extent3"."Email", "Extent3"."Department", "Extent3"."Organisation", "Extent3"."PostalCode", "Extent3"."IsAD", "Extent3"."IsActual" 

AS "IsActual1", "Extent3"."IsExternalEmail", "Extent3"."PhotoURI", "Extent3"."PhotoSize", "Extent3"."FiredDate", "Extent3"."FunctioningCapacitySettings", "Extent3"."Region", 

"Extent3"."Chief", "Extent3"."PreviousChief", "Extent3"."Settings", "Extent3"."Alternate", "Extent3"."OrganisationId", "Extent3"."DepartmentId" AS "DepartmentId1", 

"Extent3"."PositionId", "Extent3"."TreePath" AS "TreePath1", "Extent4"."Id" AS "Id2", "Extent4"."Code", "Extent4"."Name" AS "Name2", "Extent4"."IsActual" AS "IsActual2", 

"Extent4"."ParentId", "Extent4"."TreePath" AS "TreePath2", "Extent4"."OrderNum",  CASE  WHEN ("Extent2"."UserGroup" IS NULL) THEN (CAST (NULL AS int4)) ELSE (1) END  AS "C1" FROM 

"public"."UserGroups" AS "Extent1" LEFT OUTER JOIN "public"."UsersUserGroups" AS "Extent2" INNER JOIN "public"."Users" AS "Extent3" ON "Extent2"."User" = "Extent3"."Id" INNER JOIN 

"public"."Regions" AS "Extent4" ON "Extent3"."Region" = "Extent4"."Id" ON "Extent1"."Id" = "Extent2"."UserGroup" WHERE "Extent1"."IsActual" = TRUE) AS "Project1" ORDER BY 

"Project1"."Id" ASC ,"Project1"."C1" ASC 

    Sort  (cost=2926.20..2984.14 rows=23174 width=826) (actual time=102.996..105.507 rows=24506 loops=1)

      Sort Key: "Extent1"."Id", (CASE WHEN ("Extent2"."UserGroup" IS NULL) THEN NULL::integer ELSE 1 END)

      Sort Method: quicksort  Memory: 23462kB

      Buffers: shared hit=21 read=592

      ->  Hash Right Join  (cost=672.88..1246.06 rows=23174 width=826) (actual time=20.739..62.917 rows=24506 loops=1)

            Hash Cond: ("Extent2"."UserGroup" = "Extent1"."Id")

            Buffers: shared hit=21 read=592

            ->  Hash Join  (cost=640.53..1149.46 rows=24359 width=748) (actual time=20.121..51.082 rows=24357 loops=1)

                  Hash Cond: ("Extent3"."Region" = "Extent4"."Id")

                  Buffers: shared hit=15 read=585

                  ->  Hash Join  (cost=638.41..1077.97 rows=24359 width=553) (actual time=20.066..41.540 rows=24357 loops=1)

                        Hash Cond: ("Extent2"."User" = "Extent3"."Id")

                        Buffers: shared hit=14 read=585

                        ->  Seq Scan on "UsersUserGroups" "Extent2"  (cost=0.00..375.59 rows=24359 width=8) (actual time=0.028..4.387 rows=24357 loops=1)

                              Buffers: shared hit=8 read=124

                        ->  Hash  (cost=543.18..543.18 rows=7618 width=549) (actual time=20.002..20.002 rows=7618 loops=1)

                              Buckets: 8192  Batches: 1  Memory Usage: 3654kB

                              Buffers: shared hit=6 read=461

                              ->  Seq Scan on "Users" "Extent3"  (cost=0.00..543.18 rows=7618 width=549) (actual time=0.012..10.967 rows=7618 loops=1)

                                    Buffers: shared hit=6 read=461

                  ->  Hash  (cost=1.50..1.50 rows=50 width=195) (actual time=0.042..0.042 rows=50 loops=1)

                        Buckets: 1024  Batches: 1  Memory Usage: 12kB

                        Buffers: shared hit=1

                        ->  Seq Scan on "Regions" "Extent4"  (cost=0.00..1.50 rows=50 width=195) (actual time=0.013..0.017 rows=50 loops=1)

                              Buffers: shared hit=1

            ->  Hash  (cost=21.84..21.84 rows=841 width=78) (actual time=0.606..0.606 rows=841 loops=1)

                  Buckets: 1024  Batches: 1  Memory Usage: 102kB

                  Buffers: shared hit=6 read=7

                  ->  Seq Scan on "UserGroups" "Extent1"  (cost=0.00..21.84 rows=841 width=78) (actual time=0.023..0.363 rows=841 loops=1)

                        Filter: "IsActual"

                        Rows Removed by Filter: 43

                        Buffers: shared hit=6 read=7



Исправлено 2 раз(а). Последнее : S-type, 20.09.19 11:48
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
S-type
Автор

Сообщений: 2969
Дата регистрации: 24.04.2004
S-type
20.09.19 12:02:18
Глядя на всё это не могу понять, из каких цифр складывается 3177.924 ms.



Исправлено 1 раз(а). Последнее : S-type, 20.09.19 12:02
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
pasha_usue

Сообщений: 3650
Откуда: Е-бург
Дата регистрации: 06.10.2006
pasha_usue
20.09.19 12:20:02
S-type
Глядя на всё это не могу понять, из каких цифр складывается 3177.924 ms.
Всё остальное время потрачено на конвертацию ответа перед отправкой клиенту. Очень широкая таблица, высотой 24506 строк - не мудрено.

Возможно стоит попробовать другой драйвер. Возможно, стоит установить в драйвере кодовую страницу, соответствующую кодовой странице БД.
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
PaulWist

Сообщений: 14625
Дата регистрации: 01.04.2004
PaulWist
20.09.19 12:36:28
1. Планы совпадают, как по стоимости, так и по времени.

2. Настораживает duration: 3177.924, смотри открытые транзакции, блокировки в своей проге.


------------------
Есть многое на свете, друг Горацио...
Что и не снилось нашим мудрецам.
(В.Шекспир Гамлет)
Ratings: 0 negative/0 positive
Re: PostgreSQL - время запроса
pasha_usue

Сообщений: 3650
Откуда: Е-бург
Дата регистрации: 06.10.2006
pasha_usue
20.09.19 12:46:15
PaulWist
2. Настораживает duration: 3177.924, смотри открытые транзакции, блокировки в своей проге.
Он 20 мегабайт на клиента тащит. Даже простая перекодировка UTF8->ANSI может отожрать 2 секунды спокойно. А если там ещё что-то сериализуется под драйвер, то и того больше.
Ratings: 0 negative/0 positive
Страницы:  1 2


:: Список Форумов•Список тем•Поиск•Войти
Извините, только зарегистрированные пользователи могут оставлять сообщения в этом форуме.

On-line: 7 (Гостей: 7)
© 2000-2024 Fox Club 
Яндекс.Метрика