Résoudre les problèmes et identifier les requêtes s’exécutant lentement dans Azure Database pour PostgreSQL - Serveur flexible

S’APPLIQUE À : Azure Database pour PostgreSQL : serveur flexible

Cet article explique comment résoudre les problèmes et identifier les requêtes s’exécutant lentement avec leserveur flexible Azure Database pour PostgreSQL.

Dans un scénario d’utilisation élevée du processeur, dans cet article, vous allez apprendre à :

• Identifier les requêtes s’exécutant lentement.

• Identifier une procédure d’exécution lente en parallèle. Identifier une requête s’exécutant lentement parmi une liste de requêtes qui appartiennent à la même procédure stockée d’exécution lente.

Scénario d’utilisation du processeur élevée - Identifier les requêtes s’exécutant lentement

Prérequis

Vous devez activer les guides de résolution des problèmes et l’extension auto_explain sur l’instance du serveur flexible Azure Database pour PostgreSQL. Pour activer les guides de résolution des problèmes, suivez les étapes indiquées ici.

Pour activer l’extension auto_explain, procédez comme suit :

1. Ajoutez l’extension auto_explain aux bibliothèques de préchargement partagées, comme indiqué ci-dessous depuis la page des paramètres de serveur sur le portail du serveur flexible Azure Database pour PostgreSQL.

   

Remarque

Cette modification nécessitera un redémarrage du serveur.

2. Une fois que l’extension auto_explain est ajoutée aux bibliothèques de préchargement partagées et que le serveur a redémarré, modifiez les paramètres de serveur en surbrillance auto_explain ci-dessous vers ON depuis la page des paramètres de serveur du portail du serveur flexible Azure Database pour PostgreSQL et laissez les autres avec les valeurs par défaut, comme indiqué ci-dessous.

   

Remarque

La mise à jour du paramètre auto_explain.log_min_duration sur 0 démarre la journalisation de toutes les requêtes exécutées sur le serveur. Cela peut avoir un impact sur le niveau de performance de la base de données. Une diligence raisonnable appropriée doit être exercée pour arriver à une valeur considérée comme lente sur le serveur. Par exemple, si 30 secondes est considéré comme un seuil et que toutes les requêtes exécutées en dessous de 30 secondes sont acceptables pour l’application, il est recommandé de mettre à jour le paramètre sur 30 000 millisecondes. Cela journaliserait ensuite toute requête exécutée plus de 30 secondes sur le serveur.

Scénario : identifier la requête s’exécutant lentement

À l’aide des guides de résolution des problèmes et de l’extension auto_explain existante, nous expliquons le scénario avec l’aide d’un exemple.

Nous avons un scénario où l’utilisation du processeur a atteint un pic de 90 % et souhaitons connaître la cause racine du pic. Pour déboguer le scénario, suivez les étapes indiquées ci-dessous.

1. Dès qu’un scénario d’utilisation du processeur génère une alerte, accédez aux guides de résolution des problèmes disponibles sous l’onglet Aide de la page Vue d’ensemble du portail du serveur flexible Azure Database pour PostgreSQL.

   

2. Sélectionnez l’onglet Utilisation élevée du processeur dans la page ouverte. Le guide de résolution des problèmes liés à une utilisation élevée du processeur s’ouvre.

   

3. Sélectionnez l’intervalle de temps du pic d’utilisation du processeur signalé à l’aide de la liste déroulante d’intervalle de temps.

   

4. Sélectionnez l’onglet Requêtes les plus consommatrices de processeur.

   L’onglet partage les détails de toutes les requêtes exécutées dans l’intervalle où une utilisation du processeur de 90 % a été observée. À partir de l’instantané, il semble que la requête avec le temps d’exécution moyen le plus long au cours de l’intervalle de temps était d’environ 2,6 minutes, et que la requête a exécutée 22 fois pendant l’intervalle. Il s’agit probablement de la cause des pics d’utilisation du processeur.

   

5. Connectez-vous à la base de données azure_sys et exécutez la requête pour récupérer le texte de requête réel à l’aide du script suivant.

    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. Dans l’exemple considéré, la requête trouvée lente était la suivante :

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

7. Pour comprendre quel plan d’explication exact a été généré, utilisez les journaux du serveur flexible Azure Database pour PostgreSQL. L’extension d’explication automatique aurait enregistré une entrée dans les journaux à chaque fois que l’exécution de la requête était terminée pendant l’intervalle. Sélectionnez la section Journaux dans l’onglet Monitoring depuis la page de présentation du portail du serveur flexible Azure Database pour PostgreSQL.

   

8. Sélectionnez l’intervalle de temps où une utilisation du processeur de 90 % a été constatée.

   

9. Exécutez la requête suivante pour récupérer l’explication de la sortie d’analyse de la requête identifiée.

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

La colonne des messages stockera le plan d’exécution, comme indiqué ci-dessous :

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

La requête s’est exécutée pendant environ 2,5 minutes, comme indiqué dans les guides de résolution des problèmes, et est confirmée par la valeur duration de 150 692,864 ms depuis la sortie du plan d’exécution extraite. Utilisez l’explication de la sortie d’analyse pour résoudre les problèmes et régler la requête.

Remarque

Notez que la requête s’est exécutée 22 fois pendant l’intervalle et que les journaux montrés ci-dessus sont une entrée de ce type capturée pendant l’intervalle.

Scénario d’utilisation du processeur élevée - Identifier la procédure s’exécutant lentement et les requêtes lentes associées à la procédure

Dans le deuxième scénario, la durée d’exécution d’une procédure stockée est considérée comme lente et l’objectif est d’identifier et de régler la requête s’exécutant lentement qui fait partie de la procédure stockée.

Prérequis

Vous devez activer les guides de résolution des problèmes et l’extension auto_explain sur l’instance du serveur flexible Azure Database pour PostgreSQL en tant que prérequis. Pour activer les guides de résolution des problèmes, suivez les étapes indiquées ici.

Pour activer l’extension auto_explain, procédez comme suit :

1. Ajoutez l’extension auto_explain aux bibliothèques de préchargement partagées, comme indiqué ci-dessous depuis la page des paramètres de serveur sur le portail du serveur flexible Azure Database pour PostgreSQL.

   

Remarque

Cette modification nécessitera un redémarrage du serveur.

2. Une fois que l’extension auto_explain est ajoutée aux bibliothèques de préchargement partagées et que le serveur a redémarré, modifiez les paramètres de serveur en surbrillance auto_explain ci-dessous vers ON depuis la page des paramètres de serveur du portail du serveur flexible Azure Database pour PostgreSQL et laissez les autres avec les valeurs par défaut, comme indiqué ci-dessous.

   

Remarque

• La mise à jour du paramètre auto_explain.log_min_duration sur 0 démarre la journalisation de toutes les requêtes exécutées sur le serveur. Cela peut avoir un impact sur le niveau de performance de la base de données. Une diligence raisonnable appropriée doit être exercée pour arriver à une valeur considérée comme lente sur le serveur. Par exemple, si 30 secondes est considéré comme un seuil et que toutes les requêtes exécutées en dessous de 30 secondes sont acceptables pour l’application, il est recommandé de mettre à jour le paramètre sur 30 000 millisecondes. Cela journaliserait ensuite toute requête exécutée plus de 30 secondes sur le serveur.
• Le paramètre auto_explain.log_nested_statements entraîne la prise en compte des instructions imbriquées (instructions exécutées à l’intérieur d’une fonction ou d’une procédure) pour la journalisation. Lorsqu’il est désactivé, seuls les plans de requête de niveau supérieur sont enregistrés. 

Scénario - Identifier les requêtes s’exécutant lentement dans une procédure stockée

À l’aide des guides de résolution des problèmes et de l’extension auto_explain existante, nous expliquons le scénario avec l’aide d’un exemple.

Nous avons un scénario où l’utilisation du processeur a atteint un pic de 90 % et souhaitons connaître la cause racine du pic. Pour déboguer le scénario, suivez les étapes indiquées ci-dessous.

1. Dès qu’un scénario d’utilisation du processeur génère une alerte, accédez aux guides de résolution des problèmes disponibles sous l’onglet Aide de la page Vue d’ensemble du portail du serveur flexible Azure Database pour PostgreSQL.

   

2. Sélectionnez l’onglet Utilisation élevée du processeur dans la page ouverte. Le guide de résolution des problèmes liés à une utilisation élevée du processeur s’ouvre.

   

3. Sélectionnez l’intervalle de temps du pic d’utilisation du processeur signalé à l’aide de la liste déroulante d’intervalle de temps.

   

4. Sélectionnez l’onglet Requêtes les plus consommatrices de processeur.

   L’onglet partage les détails de toutes les requêtes exécutées dans l’intervalle où une utilisation du processeur de 90 % a été observée. À partir de l’instantané, il semble que la requête avec le temps d’exécution moyen le plus long au cours de l’intervalle de temps était d’environ 6,3 minutes, et que la requête a exécutée 35 fois pendant l’intervalle. Il s’agit probablement de la cause des pics d’utilisation du processeur.

   

   Il est important de noter d’après l’instantané ci-dessous que le type de requête, comme indiqué ci-dessous, est « Utilitaire ». En règle générale, un utilitaire peut être une procédure stockée ou une fonction s’exécutant pendant l’intervalle.

5. Connectez-vous à la base de données azure_sys et exécutez la requête pour récupérer le texte de requête réel à l’aide du script suivant.

    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. Dans l’exemple considéré, la requête trouvée lente était une procédure stockée, comme indiqué ci-dessous :

    call autoexplain_test ();

7. Pour comprendre quelles explications exactes sont générées pour les requêtes qui font partie de la procédure stockée, utilisez les journaux du serveur flexible Azure Database pour PostgreSQL. L’extension d’explication automatique aurait enregistré une entrée dans les journaux à chaque fois que l’exécution de la requête était terminée pendant l’intervalle. Sélectionnez la section Journaux dans l’onglet Monitoring depuis la page de présentation du portail du serveur flexible Azure Database pour PostgreSQL.

   

8. Sélectionnez l’intervalle de temps où une utilisation du processeur de 90 % a été constatée.

   

9. Exécutez la requête ci-dessous pour récupérer la sortie d’analyse expliquée de la requête identifiée.

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

La procédure comporte plusieurs requêtes, qui sont mises en évidence ci-dessous. L’explication de la sortie d’analyse de chaque requête utilisée dans la procédure stockée est consignée pour analyser plus loin et résoudre les problèmes. Le temps d’exécution des requêtes journalisées peut être utilisé pour identifier les requêtes les plus lentes qui font partie de la procédure stockée.

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

Remarque

Veuillez noter qu’à des fins de démonstration, l’explication de la sortie d’analyse de seulement quelques requêtes utilisées dans la procédure est partagée. L’idée est qu’il est possible de rassembler les explications de sortie d’analyse de toutes les requêtes des journaux, puis d’identifier la plus lente de celles-ci et d’essayer de les régler.

Contenu connexe

• Utilisation élevée du processeur
• Réglage du nettoyage automatique