مشاركة عبر

استكشاف أخطاء الاستعلامات بطيئة التشغيل وتحديدها في قاعدة بيانات Azure ل PostgreSQL وإصلاحها

توضح هذه المقالة كيفية تحديد وتشخيص السبب الجذري للاستعلامات بطيئة التشغيل.

في هذه المقالة، يمكنك أن تتعلم:

  • كيفية تحديد الاستعلامات بطيئة التشغيل.
  • كيفية تحديد إجراء يعمل ببطء جنبا إلى جنب معه. تحديد استعلام بطيء بين قائمة الاستعلامات التي تنتمي إلى نفس الإجراء المخزن الذي يعمل ببطء.

المتطلبات الأساسية

  1. قم بتمكين أدلة استكشاف الأخطاء وإصلاحها باتباع الخطوات الموضحة في استخدام أدلة استكشاف الأخطاء وإصلاحها.

  2. قم بتكوين الملحق auto_explain عن طريق السماح بقائمة الامتداد وتحميله.

  3. بعد تكوين الملحقauto_explain، قم بتغيير معلمات الخادم التالية، والتي تتحكم في سلوك الملحق:

    • auto_explain.log_analyze إلى ON.
    • auto_explain.log_buffers إلى ON.
    • auto_explain.log_min_duration وفقا لما هو معقول في السيناريو الخاص بك.
    • auto_explain.log_timing إلى ON.
    • auto_explain.log_verbose إلى ON.

    لقطة شاشة تعرض معلمات خادم auto_explain التي تحتاج إلى تكوين.

إشعار

إذا قمت بتعيين auto_explain.log_min_duration إلى 0، يبدأ الملحق في تسجيل جميع الاستعلامات التي يتم تنفيذها على الخادم. قد يؤثر هذا على أداء قاعدة البيانات. يجب بذل العناية الواجبة المناسبة للوصول إلى قيمة تعتبر بطيئة على الخادم. على سبيل المثال، إذا اكتملت جميع الاستعلامات في أقل من 30 ثانية، وكان ذلك مقبولا لتطبيقك، فمن المستحسن تحديث المعلمة إلى 30,000 مللي ثانية. سيؤدي هذا بعد ذلك إلى تسجيل أي استعلام ، والذي يستغرق أكثر من 30 ثانية لإكماله.

تحديد الاستعلام البطيء

مع إرشادات استكشاف الأخطاء وإصلاحها والملحق auto_explain في مكانها، نصف السيناريو بمساعدة مثال.

لدينا سيناريو حيث ترتفع نسبة استخدام وحدة المعالجة المركزية إلى 90٪ ونريد تحديد سبب الارتفاع. لتصحيح أخطاء السيناريو، اتبع الخطوات التالية:

  1. بمجرد تنبيهك من سيناريو وحدة المعالجة المركزية، في قائمة الموارد للمثيل المتأثر لقاعدة بيانات Azure للخادم المرن PostgreSQL، ضمن قسم المراقبة ، حدد أدلة استكشاف الأخطاء وإصلاحها.

    لقطة شاشة لخيار قائمة إرشادات استكشاف الأخطاء وإصلاحها.

  2. حدد علامة التبويب CPU. يفتح دليل تحسين استكشاف أخطاء استخدام وحدة المعالجة المركزية العالية وإصلاحها.

    لقطة شاشة لقائمة أدلة استكشاف الأخطاء وإصلاحها - علامات التبويب.

  3. من القائمة المنسدلة فترة التحليل (بالتوقيت المحلي)، حدد النطاق الزمني الذي تريد تركيز التحليل عليه.

    لقطة شاشة لقائمة أدلة استكشاف الأخطاء وإصلاحها - علامة التبويب CPU.

  4. حدد علامة التبويب Queries . يعرض تفاصيل جميع الاستعلامات التي تم تشغيلها في الفاصل الزمني حيث تم رؤية استخدام وحدة المعالجة المركزية بنسبة 90٪. من اللقطة، يبدو أن الاستعلام الذي كان متوسط وقت التنفيذ الأبطأ خلال الفاصل الزمني حوالي 2.6 دقيقة، وتم تشغيل الاستعلام 22 مرة أثناء الفاصل الزمني. هذا الاستعلام هو على الأرجح سبب ارتفاع وحدة المعالجة المركزية.

    لقطة شاشة لقائمة أدلة استكشاف الأخطاء وإصلاحها - علامة تبويب الاستعلامات الأكثر استهلاكا لوحدة المعالجة المركزية.

  5. لاسترداد نص الاستعلام الفعلي، اتصل بقاعدة azure_sys البيانات وقم بتنفيذ الاستعلام التالي.

    psql -h <server>.postgres.database.azure.com -U <user> -d azure_sys

     SELECT query_sql_text
     FROM query_store.query_texts_view
     WHERE query_text_id = <query_id>;
  1. في المثال المدروس، كان الاستعلام الذي تم العثور عليه بطيئا:
SELECT  c_id, SUM(c_balance) AS total_balance
FROM customer
GROUP BY c_w_id, c_id
ORDER BY c_w_id;

  1. لفهم خطة الشرح الدقيقة التي تم إنشاؤها، استخدم قاعدة بيانات Azure لسجلات PostgreSQL. في كل مرة يكمل فيها الاستعلام التنفيذ خلال تلك النافذة الزمنية auto_explain ، يجب أن يكتب الملحق إدخالا في السجلات. في قائمة الموارد، ضمن قسم Monitoring ، حدد Logs.

    لقطة شاشة لقائمة أدلة استكشاف الأخطاء وإصلاحها - السجلات.

  2. حدد النطاق الزمني حيث تم العثور على استخدام وحدة المعالجة المركزية بنسبة 90٪.

    لقطة شاشة توضح كيفية اختيار نافذة زمنية في أدلة استكشاف الأخطاء وإصلاحها.

  3. نفذ الاستعلام التالي لاسترداد إخراج EXPLAIN ANALYZE للاستعلام المحدد.

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

يخزن عمود الرسالة خطة التنفيذ كما هو موضح في هذا الإخراج:

2024-11-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 مللي ثانية من إخراج خطة التنفيذ التي تم جلبها ذلك. استخدم إخراج EXPLAIN ANALYZE لاستكشاف المزيد من الأخطاء وإصلاحها وضبط الاستعلام.

إشعار

لاحظ أن الاستعلام تم تشغيله 22 مرة أثناء الفاصل الزمني، وأن السجلات المعروضة تحتوي على مثل هذه الإدخالات التي تم التقاطها أثناء الفاصل الزمني.

تحديد استعلام التشغيل البطيء في إجراء مخزن

مع إرشادات استكشاف الأخطاء وإصلاحها وملحق auto_explain في مكانها، نشرح السيناريو بمساعدة مثال.

لدينا سيناريو حيث ترتفع نسبة استخدام وحدة المعالجة المركزية إلى 90٪ ونريد تحديد سبب الارتفاع. لتصحيح أخطاء السيناريو، اتبع الخطوات التالية:

  1. بمجرد تنبيهك من سيناريو وحدة المعالجة المركزية، في قائمة الموارد للمثيل المتأثر لقاعدة بيانات Azure للخادم المرن PostgreSQL، ضمن قسم المراقبة ، حدد أدلة استكشاف الأخطاء وإصلاحها.

    لقطة شاشة لقائمة أدلة استكشاف الأخطاء وإصلاحها.

  2. حدد علامة التبويب CPU. يفتح دليل تحسين استكشاف أخطاء استخدام وحدة المعالجة المركزية العالية وإصلاحها.

    لقطة شاشة لعلامات تبويب إرشادات استكشاف الأخطاء وإصلاحها.

  3. من القائمة المنسدلة فترة التحليل (بالتوقيت المحلي)، حدد النطاق الزمني الذي تريد تركيز التحليل عليه.

    لقطة شاشة لأدلة استكشاف الأخطاء وإصلاحها - علامة التبويب CPU.

  4. حدد علامة التبويب Queries . يعرض تفاصيل جميع الاستعلامات التي تم تشغيلها في الفاصل الزمني حيث تم رؤية استخدام وحدة المعالجة المركزية بنسبة 90٪. من اللقطة، يبدو أن الاستعلام الذي كان متوسط وقت التنفيذ الأبطأ خلال الفاصل الزمني حوالي 2.6 دقيقة، وتم تشغيل الاستعلام 22 مرة أثناء الفاصل الزمني. هذا الاستعلام هو على الأرجح سبب ارتفاع وحدة المعالجة المركزية.

    لقطة شاشة لأدلة استكشاف الأخطاء وإصلاحها - علامة تبويب وحدة المعالجة المركزية - الاستعلامات.

  5. الاتصال بقاعدة بيانات azure_sys وتنفيذ الاستعلام لاسترداد نص الاستعلام الفعلي باستخدام البرنامج النصي أدناه.

    psql -h <server>.postgres.database.azure.com -U <user> -d azure_sys

     SELECT query_sql_text
     FROM query_store.query_texts_view
     WHERE query_text_id = <query_id>;
  1. في المثال المدروس، كان الاستعلام الذي تم العثور عليه بطيئا إجراء مخزنا:
    call autoexplain_test ();
  1. لفهم خطة الشرح الدقيقة التي تم إنشاؤها، استخدم قاعدة بيانات Azure لسجلات PostgreSQL. في كل مرة يكمل فيها الاستعلام التنفيذ خلال تلك النافذة الزمنية auto_explain ، يجب أن يكتب الملحق إدخالا في السجلات. في قائمة الموارد، ضمن قسم Monitoring ، حدد Logs. بعد ذلك، في النطاق الزمني:، حدد النافذة الزمنية حيث تريد تركيز التحليل.

لقطة شاشة لقائمة أدلة استكشاف الأخطاء وإصلاحها - النطاق الزمني للسجلات.

  1. قم بتنفيذ الاستعلام التالي لاسترداد إخراج تحليل الشرح للاستعلام المحدد.
AzureDiagnostics
| where Category contains  'PostgreSQLLogs'
| where Message contains "<snippet of SQL text identified or name of any of the tables referenced in the query>"
| project TimeGenerated, Message

يحتوي الإجراء على استعلامات متعددة، والتي يتم تمييزها أدناه. يتم تسجيل إخراج تحليل الشرح لكل استعلام مستخدم في الإجراء المخزن لتحليل المزيد واستكشاف الأخطاء وإصلاحها. يمكن استخدام وقت تنفيذ الاستعلامات المسجلة لتحديد أبطأ الاستعلامات التي تعد جزءا من الإجراء المخزن.

2024-11-10 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

2024-11-10 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

2024-11-10 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

إشعار

لأغراض العرض التوضيحي، يتم عرض إخراج EXPLAIN ANALYZE لعدد قليل من الاستعلامات المستخدمة في الإجراء. الفكرة هي أنه يمكن جمع مخرجات EXPLAIN ANALYZE لجميع الاستعلامات من السجلات، وتحديد أبطأها ومحاولة ضبطها.

المحتوى ذو الصلة

  • Last updated on