Устранение неполадок и определение медленных запросов в База данных Azure для PostgreSQL — гибкий сервер

ОБЛАСТЬ ПРИМЕНЕНИЯ: База данных Azure для PostgreSQL — гибкий сервер

В этой статье показано, как устранять неполадки и выявлять медленные запросы с помощью База данных Azure для PostgreSQL гибкого сервера.

В сценарии с высоким использованием ЦП в этой статье вы узнаете, как:

• Определите медленные запросы.

• Определите медленно выполняющуюся процедуру вместе с ней. Определите медленный запрос среди списка запросов, относящихся к той же медленно выполняющейся хранимой процедуре.

Сценарий высокой загрузки ЦП. Определение медленного запроса

Необходимые компоненты

Необходимо включить руководства по устранению неполадок и расширение auto_explain на База данных Azure для PostgreSQL гибком экземпляре сервера. Чтобы включить руководства по устранению неполадок, выполните описанные здесь действия.

Чтобы включить расширение auto_explain, выполните следующие действия.

1. Добавьте расширение auto_explain в общие библиотеки предварительной загрузки, как показано ниже на странице параметров сервера на портале гибкого сервера База данных Azure для PostgreSQL.

   

Примечание.

Для внесения этого изменения потребуется перезапуск сервера.

2. После добавления расширения auto_explain в общие библиотеки предварительной загрузки и перезапуск сервера измените указанные ниже параметры сервера auto_explain на страницу параметров ON сервера на портале гибкого сервера База данных Azure для PostgreSQL и оставьте остальные значения по умолчанию, как показано ниже.

   

Примечание.

Обновление auto_explain.log_min_duration параметра до 0 начнет ведение журнала всех запросов, выполняемых на сервере. Это может повлиять на производительность базы данных. Необходимо выполнить надлежащую проверку должного анализа, чтобы прийти к значению, которое считается медленным на сервере. Пример, если пороговое значение считается 30 секунд, и все запросы, выполняемые ниже 30 секунд, допустимы для приложения, рекомендуется обновить параметр до 30000 миллисекунд. Затем он регистрирует любой запрос, который выполняется более 30 секунд на сервере.

Сценарий. Определение медленно выполняющегося запроса

С помощью руководств по устранению неполадок и auto_explain расширения мы объясним сценарий с помощью примера.

У нас есть сценарий, в котором загрузка ЦП возросла до 90 % и хотела бы знать первопричину всплеска. Чтобы выполнить отладку сценария, выполните указанные ниже действия.

1. Как только вы оповещены сценарием ЦП, перейдите к руководствам по устранению неполадок, доступным на вкладке "Справка" на странице обзора портала База данных Azure для PostgreSQL гибкого сервера.

   

2. Перейдите на вкладку "Высокая загрузка ЦП" на открывшейся странице. Откроется руководство по устранению неполадок с высокой загрузкой ЦП.

   

3. Выберите диапазон времени сообщаемого всплеска ЦП с помощью раскрывающегося списка диапазонов времени.

   

4. Перейдите на вкладку "Основные запросы на использование ЦП".

   Вкладка содержит сведения обо всех запросах, запущенных в интервале, в котором было видно 90 % использования ЦП. Из моментального снимка он выглядит как запрос с самым медленным средним временем выполнения в течение интервала времени около 2,6 минут, и запрос выполнялся 22 раза в течение интервала. Это, скорее всего, причина пиков ЦП.

   

5. Подключитесь к базе данных azure_sys и выполните запрос, чтобы получить фактический текст запроса с помощью следующего скрипта.

    psql -h ServerName.postgres.database.azure.com -U AdminUsername -d azure_sys

     SELECT query_sql_text
     FROM query_store.query_texts_view
     WHERE query_text_id = <add query id identified>;

6. В приведенном примере запрос, который был найден медленным, был следующим:

SELECT  c_id, SUM(c_balance) AS total_balance
FROM customer
GROUP BY c_w_id,c_id
order by c_w_id;

7. Чтобы понять, какой план был создан, используйте База данных Azure для PostgreSQL гибкие журналы сервера. Автоматическое объяснение расширения заносило запись в журналы при каждом завершении выполнения запроса во время интервала. Выберите раздел "Журналы" на вкладке Monitoring на странице обзора База данных Azure для PostgreSQL гибкого портала сервера.

   

8. Выберите диапазон времени, в котором обнаружена загрузка ЦП 90 %.

   

9. Выполните следующий запрос, чтобы получить данные анализа определенного запроса.

AzureDiagnostics
| where Category contains  'PostgreSQLLogs'
| where Message contains "<add snippet of SQL text identified or add table name involved in the query>"
| project TimeGenerated, Message

Столбец сообщения будет хранить план выполнения, как показано ниже:

2023-10-10 19:56:46 UTC-6525a8e7.2e3d-LOG: duration: 150692.864 ms plan:

Query Text: SELECT c_id, SUM(c_balance) AS total_balance
FROM customer
GROUP BY c_w_id,c_id
order by c_w_id;
GroupAggregate (cost=1906820.83..2131820.83 rows=10000000 width=40) (actual time=70930.833..129231.950 rows=10000000 loops=1)
Output: c_id, sum(c_balance), c_w_id
Group Key: customer.c_w_id, customer.c_id
Buffers: shared hit=44639 read=355362, temp read=77521 written=77701
-> Sort (cost=1906820.83..1931820.83 rows=10000000 width=13) (actual time=70930.821..81898.430 rows=10000000 loops=1)
Output: c_id, c_w_id, c_balance
Sort Key: customer.c_w_id, customer.c_id
Sort Method: external merge Disk: 225104kB
Buffers: shared hit=44639 read=355362, temp read=77521 written=77701
-> Seq Scan on public.customer (cost=0.00..500001.00 rows=10000000 width=13) (actual time=0.021..22997.697 rows=10000000 loops=1)
Output: c_id, c_w_id, c_balance

Запрос выполнялся около 2,5 минут, как показано в руководствах по устранению неполадок, и подтверждается duration значением 150692,864 мс из выходного результата плана выполнения. Используйте объяснение анализа выходных данных для дальнейшего устранения неполадок и настройки запроса.

Примечание.

Обратите внимание, что запрос выполнялся 22 раза в течение интервала, а журналы, показанные выше, являются одной из таких записей, захваченных в течение интервала.

Сценарий высокой загрузки ЦП. Определение медленно выполняющейся процедуры и медленных запросов, связанных с процедурой

Во втором сценарии время выполнения хранимой процедуры выполняется медленно, и цель — определить и настроить медленный запрос, который является частью хранимой процедуры.

Необходимые компоненты

Необходимо включить руководства по устранению неполадок и расширение auto_explain на База данных Azure для PostgreSQL гибком экземпляре сервера в качестве необходимого условия. Чтобы включить руководства по устранению неполадок, выполните описанные здесь действия.

Чтобы включить расширение auto_explain, выполните следующие действия.

1. Добавьте расширение auto_explain в общие библиотеки предварительной загрузки, как показано ниже на странице параметров сервера на портале гибкого сервера База данных Azure для PostgreSQL.

   

Примечание.

Для внесения этого изменения потребуется перезапуск сервера.

2. После добавления расширения auto_explain в общие библиотеки предварительной загрузки и перезапуск сервера измените указанные ниже параметры сервера auto_explain на страницу параметров ON сервера на портале гибкого сервера База данных Azure для PostgreSQL и оставьте остальные значения по умолчанию, как показано ниже.

   

Примечание.

• Обновление auto_explain.log_min_duration параметра до 0 начнет ведение журнала всех запросов, выполняемых на сервере. Это может повлиять на производительность базы данных. Необходимо выполнить надлежащую проверку должного анализа, чтобы прийти к значению, которое считается медленным на сервере. Пример, если пороговое значение считается 30 секунд, и все запросы, выполняемые ниже 30 секунд, допустимы для приложения, рекомендуется обновить параметр до 30000 миллисекунд. Затем он регистрирует любой запрос, который выполняется более 30 секунд на сервере.
• Параметр auto_explain.log_nested_statements приводит к тому, что вложенные операторы (инструкции, выполняемые внутри функции или процедуры), рассматриваются для ведения журнала. При отключении регистрируются только планы запросов верхнего уровня. 

Сценарий. Определение медленно выполняющегося запроса в хранимой процедуре

С помощью руководств по устранению неполадок и auto_explain расширения мы объясним сценарий с помощью примера.

У нас есть сценарий, в котором загрузка ЦП возросла до 90 % и хотела бы знать первопричину всплеска. Чтобы выполнить отладку сценария, выполните указанные ниже действия.

1. Как только вы оповещены сценарием ЦП, перейдите к руководствам по устранению неполадок, доступным на вкладке "Справка" на странице обзора портала База данных Azure для PostgreSQL гибкого сервера.

   

2. Перейдите на вкладку "Высокая загрузка ЦП" на открывшейся странице. Откроется руководство по устранению неполадок с высокой загрузкой ЦП.

   

3. Выберите диапазон времени сообщаемого всплеска ЦП с помощью раскрывающегося списка диапазонов времени.

   

4. Перейдите на вкладку "Лучшие запросы на использование ЦП".

   Вкладка содержит сведения обо всех запросах, запущенных в интервале, в котором было видно 90 % использования ЦП. Из моментального снимка он выглядит так, как запрос с самым медленным средним временем выполнения в течение интервала времени составил ~6,3 минуты, и запрос выполнялся 35 раз в течение интервала. Это, скорее всего, причина пиков ЦП.

   

   Важно отметить из моментального снимка ниже, что тип запроса, как указано ниже, — "Программа". Как правило, программа может быть хранимой процедурой или функцией, выполняемой в течение интервала.

5. Подключитесь к базе данных azure_sys и выполните запрос, чтобы получить фактический текст запроса с помощью приведенного ниже скрипта.

    psql -h ServerName.postgres.database.azure.com -U AdminUsername -d azure_sys

     SELECT query_sql_text
     FROM query_store.query_texts_view
     WHERE query_text_id = <add query id identified>;

6. В приведенном примере запрос, который был найден медленным, был хранимой процедурой, как упоминалось ниже:

    call autoexplain_test ();

7. Чтобы понять, какие точные объяснения создаются для запросов, входящих в хранимую процедуру, используйте База данных Azure для PostgreSQL гибкие журналы сервера. Автоматическое объяснение расширения заносило запись в журналы при каждом завершении выполнения запроса во время интервала. Выберите раздел "Журналы" на Monitoring вкладке на странице обзора База данных Azure для PostgreSQL гибкого портала сервера.

   

8. Выберите диапазон времени, в котором обнаружена загрузка ЦП 90 %.

   

9. Выполните приведенный ниже запрос, чтобы получить объясняемые выходные данные идентифицированного запроса.

AzureDiagnostics
| where Category contains  'PostgreSQLLogs'
| where Message contains "<add a snippet of SQL text identified or add table name involved in the queries related to stored procedure>"
| project TimeGenerated, Message

Процедура содержит несколько запросов, которые выделены ниже. Объяснение анализа выходных данных каждого запроса, используемого в хранимой процедуре, регистрируется для дальнейшего анализа и устранения неполадок. Время выполнения зарегистрированных запросов можно использовать для определения самых медленных запросов, входящих в хранимую процедуру.

2023-10-11 17:52:45 UTC-6526d7f0.7f67-LOG: duration: 38459.176 ms plan:

Query Text: insert into customer_balance SELECT c_id, SUM(c_balance) AS total_balance FROM customer GROUP BY c_w_id,c_id order by c_w_id
Insert on public.customer_balance (cost=1906820.83..2231820.83 rows=0 width=0) (actual time=38459.173..38459.174 rows=0 loops=1)Buffers: shared hit=10108203 read=454055 dirtied=54058, temp read=77521 written=77701 WAL: records=10000000 fpi=1 bytes=640002197
    -> Subquery Scan on "*SELECT*" (cost=1906820.83..2231820.83 rows=10000000 width=36) (actual time=20415.738..29514.742 rows=10000000 loops=1)
        Output: "*SELECT*".c_id, "*SELECT*".total_balance Buffers: shared hit=1 read=400000, temp read=77521 written=77701
            -> GroupAggregate (cost=1906820.83..2131820.83 rows=10000000 width=40) (actual time=20415.737..28574.266 rows=10000000 loops=1)
                Output: customer.c_id, sum(customer.c_balance), customer.c_w_id Group Key: customer.c_w_id, customer.c_id Buffers: shared hit=1 read=400000, temp read=77521 written=77701
                -> Sort (cost=1906820.83..1931820.83 rows=10000000 width=13) (actual time=20415.723..22023.515 rows=10000000 loops=1)
                    Output: customer.c_id, customer.c_w_id, customer.c_balance Sort Key: customer.c_w_id, customer.c_id Sort Method: external merge Disk: 225104kB Buffers: shared hit=1 read=400000, temp read=77521 written=77701
                     -> Seq Scan on public.customer (cost=0.00..500001.00 rows=10000000 width=13) (actual time=0.310..15061.471 rows=10000000 loops=1) Output: customer.c_id, customer.c_w_id, customer.c_balance Buffers: shared hit=1 read=400000

2023-10-11 17:52:07 UTC-6526d7f0.7f67-LOG: duration: 61939.529 ms plan:
Query Text: delete from customer_balance
Delete on public.customer_balance (cost=0.00..799173.51 rows=0 width=0) (actual time=61939.525..61939.526 rows=0 loops=1) Buffers: shared hit=50027707 read=620942 dirtied=295462 written=71785 WAL: records=50026565 fpi=34 bytes=2711252160
    -> Seq Scan on public.customer_balance (cost=0.00..799173.51 rows=15052451 width=6) (actual time=3185.519..35234.061 rows=50000000 loops=1)
        Output: ctid Buffers: shared hit=27707 read=620942 dirtied=26565 written=71785 WAL: records=26565 fpi=34 bytes=11252160


2023-10-11 17:51:05 UTC-6526d7f0.7f67-LOG: duration: 10387.322 ms plan:
Query Text: select max(c_id) from customer
Finalize Aggregate (cost=180185.84..180185.85 rows=1 width=4) (actual time=10387.220..10387.319 rows=1 loops=1) Output: max(c_id) Buffers: shared hit=37148 read=1204 written=69
    -> Gather (cost=180185.63..180185.84 rows=2 width=4) (actual time=10387.214..10387.314 rows=1 loops=1)
        Output: (PARTIAL max(c_id)) Workers Planned: 2 Workers Launched: 0 Buffers: shared hit=37148 read=1204 written=69
        -> Partial Aggregate (cost=179185.63..179185.64 rows=1 width=4) (actual time=10387.012..10387.013 rows=1 loops=1) Output: PARTIAL max(c_id) Buffers: shared hit=37148 read=1204 written=69
            -> Parallel Index Only Scan using customer_i1 on public.customer (cost=0.43..168768.96 rows=4166667 width=4) (actual time=0.446..7676.356 rows=10000000 loops=1)
               Output: c_w_id, c_d_id, c_id Heap Fetches: 24 Buffers: shared hit=37148 read=1204 written=69

Примечание.

Обратите внимание, что для демонстрации объясняется, что анализ выходных данных только нескольких запросов, используемых в процедуре, общий доступ. Идея заключается в том, что можно собрать анализ выходных данных всех запросов из журналов, а затем определить самые медленные из них и попытаться настроить их.

Связанный контент

• Высокая загрузка ЦП
• Настройка autovacuum