التتبع الموزع وOpenTelemetry

التتبع في التطبيق العملي: تصحيح الأخطاء باستخدام التتبع

18 دقيقة الدرس 8 من 28

التتبع في التطبيق العملي: تصحيح الأخطاء باستخدام التتبع

أن تعرف بوجود التتبع شيء، وأن تتقن قراءة مخططات الشلال تحت الضغط — في الساعة الثانية صباحًا وقد قفزت زمن الاستجابة p99 إلى ثماني ثوانٍ — شيء آخر تمامًا. هذا الدرس يُعنى بالحرفة العملية: كيف تفتح مخطط شلال التتبع، وتحدد الامتداد البطيء في ثوانٍ، وتنسب الخطأ إلى مصدره الحقيقي لا إلى أول خدمة تكشف عنه.

تشريح مخطط شلال التتبع

تعرض كل واجهة تتبع موزع مخطط شلال — رسم بياني على طريقة Gantt، محور السينات يمثل وقت الساعة الحقيقي، وكل صف يمثل امتدادًا واحدًا. الامتداد الجذري يقع في الأعلى، وأبناؤه مُتَدرِّجون تحته، كل منهم يبدأ لحظة إطلاق الطلب وينتهي لحظة وصول الاستجابة. قد تتداخل الامتدادات حين تتواصل خدمة ما مع عدة خدمات صعودية في آنٍ واحد.

مخطط شلال لطلب إنشاء طلب استغرق 595 مللي ثانية. امتداد Postgres الأحمر (440 مللي ثانية) يظهر فورًا بوصفه الاختناق الرئيسي.

ثلاثة أشياء تقرأها بنظرة واحدة:

عرض شريط الامتداد — يتناسب مع الزمن المُستهلك. الشريط الممتد على طول الامتداد الجذري تقريبًا هو المشتبه به الأول.
الفجوات بين الأب وأول ابن — الوقت الذي يقضيه الأب في منطق عمله الخاص (التسلسل، المعالجة، انتظار الأقفال).
التوزيع المتوازي مقابل السلاسل التسلسلية — الأبناء المتوازيون (أشرطة متداخلة في نفس المستوى) يدلون على تزامن مقصود. السلاسل التسلسلية (كل ابن يبدأ بعد انتهاء السابق) تُضاعف الزمن الكلي؛ حذف حلقة واحدة قد يقلّصه إلى النصف.

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

تتيح معظم الواجهات (Jaeger وGrafana Tempo وHoneycomb) فرز الامتدادات تنازليًا حسب المدة. لكنك في بيئات الإنتاج تصل إلى التتبع قادمًا من تنبيه زمن استجابة، لا من تصفح عشوائي. سير العمل كالتالي:

ربط التنبيه بمعرّف التتبع. تنبيهك يُطلق على p99. الطلبات البطيئة تحمل trace_id في سجلاتها (تسجيل منظم + ربط سجلات OTel). اسحب المعرّف من سطر سجل بطيء.
افتح التتبع في الواجهة. رتّب جدول الامتدادات تنازليًا حسب المدة — يصعد الامتداد الأبطأ إلى القمة. يُظهره المخطط بأعرض شريط.
افحص سمات الامتداد. انقر الامتداد البطيء. ابحث عن: db.statement (الاستعلام الدقيق)، http.url، rpc.method، db.row_count. اتفاقيات OTel الدلالية تضمن أن هذه السمات موحدة عبر اللغات.
انظر إلى الامتداد الأب. يخبرك بما أطلق هذا الامتداد. إن كان معالج HTTP واحد يستدعي امتداد قاعدة البيانات البطيء 47 مرة، فأنت أمام مشكلة N+1.

استخدم Exemplars للقفز من المقاييس إلى التتبع. تربط Prometheus exemplars وسم trace_id بعينات المدرّج التكراري. حين يُظهر Grafana ارتفاعًا في زمن الاستجابة على خريطة الحرارة، انقر نقطة الارتفاع — إن كانت exemplars مفعّلة، يعرض Grafana رابطًا مباشرًا للتتبع المسبّب. هذا يقلّص وقت التشخيص من دقائق إلى ثوانٍ.

استخراج التتبع من السجلات

في حوادث الإنتاج تبدأ عادةً من Grafana (Loki أو CloudWatch) بتنبيه مبني على السجلات. مع تفعيل ربط سجلات OTel، يحمل كل سطر trace_id وspan_id. استخدمهما للانتقال إلى Tempo:

# 1. ابحث عن الطلبات البطيئة في Loki (LogQL)
{app="order-service"} | json | duration > 500ms

# مثال على سطر سجل مطابق (JSON منظّم):
# {"level":"error","message":"request failed","trace_id":"4bf92f3577b34da6a3ce929d0e0e4736",
#   "span_id":"00f067aa0ba902b7","duration_ms":601,"http.status_code":500}

# 2. انسخ trace_id، افتح Tempo في Grafana:
#    Explore → Data source: Tempo → TraceID → الصق 4bf92f3577b34da6a3ce929d0e0e4736

# 3. أو استعلم Tempo HTTP API مباشرةً:
curl -s "http://tempo:3200/api/traces/4bf92f3577b34da6a3ce929d0e0e4736" \
  | jq '.batches[].scopeSpans[].spans[] | {name, durationNanos, status}'

نسب الأخطاء إلى مصادرها الحقيقية

أصعب مهارة في تصحيح التتبع هي التمييز بين مكان نشوء الخطأ ومكان ظهوره. في سلسلة خدمات مصغرة، يتسبب تعطّل قاعدة البيانات في خطأ 500 من خدمة الطلبات، التي تُعيده 502 من بوابة API، وهو ما يراه المستخدم. ثلاث خدمات تبدو معطوبة، لكن واحدة فقط هي السبب.

تُرمِّز OTel هذا في حالة الامتداد. تقول مواصفات OTel: ضع حالة ERROR على الامتداد فقط إن كان هو نفسه تسبب في الخطأ — لا إن مرّر فشلًا من خدمة تالية. الخدمة المُجهَّزة جيدًا التي تلتقط خطأ 500 من تحتها وتعيد رمي الاستثناء يجب أن تُسجّل امتداد الاستدعاء البعيد بحالة ERROR (لأن الاستدعاء نفسه فشل)، لكن الامتداد الأب يُعلَّم ERROR أيضًا فقط إن فشلت العملية التجارية برمّتها.

قاعدة نسب الأخطاء: ابحث عن أعمق امتداد مُعلَّم بـERROR لا يملك أبناءً بحالة ERROR. هذا هو المصدر الأصلي. كل امتداد ERROR فوقه هو فشل منقول — حقيقي لأغراض التنبيه، لكنه ليس السبب الجذري. إصلاح المصدر يُسكت جميع الأخطاء المتتالية تلقائيًا.

في Jaeger تظهر الأخطاء بامتدادات حمراء. في Grafana Tempo يحمل جدول الامتدادات عمود الحالة. في كلا الواجهتين، اطوِ جميع الامتدادات وابحث عن أعمق عقدة حمراء. سمات الامتداد exception.message وexception.stacktrace تحمل الاستثناء الأصلي.

# نمط نسب الأخطاء الصحيح — OTel Python SDK
from opentelemetry import trace
from opentelemetry.trace import StatusCode

tracer = trace.get_tracer(__name__)

def create_order(order_data):
    with tracer.start_as_current_span("createOrder") as order_span:
        try:
            # هذا الامتداد الداخلي سيُعلَّم ERROR إن فشل استدعاء DB
            with tracer.start_as_current_span("db.insert_order") as db_span:
                db.execute("INSERT INTO orders ...", order_data)
        except Exception as exc:
            # علّم هذا الامتداد (db.insert_order) بوصفه مصدر الخطأ
            db_span.set_status(StatusCode.ERROR, str(exc))
            db_span.record_exception(exc)
            # أعِد الرمي — الامتداد الأب (createOrder) سيُعلَّم ERROR أيضًا
            # لأن العملية التجارية فشلت، لكن التتبع يُظهر المصدر بوضوح
            raise

التعرف على نمطَي N+1 والتوزيع المتوازي

نمطان هيكليان يستحق كل منهما التعرف بمجرد النظر:

استعلام N+1: في المخطط ترى عشرات الامتدادات القصيرة المتطابقة تقريبًا من عميل قاعدة البيانات، كل منها يبدأ بعد انتهاء السابق مباشرةً، وجميعها أبناء للامتداد الأب نفسه. الزمن الكلي هو مجموع N استعلام صغير. الحل: تجميع الاستعلامات أو استخدام JOIN. التتبع يُثبت المشكلة بلا جدال — يمكنك عدّ الامتدادات.
السلسلة التسلسلية غير الضرورية: الخدمة A تستدعي B، تنتظر الاستجابة كاملةً، ثم تستدعي C. إن كانت B وC مستقلتين، فهذا يُضاعف الزمن دون مبرر. يُظهر المخطط B وC بأشرطة تسلسلية في نفس مستوى التدرج. الحل: إطلاق كلا الاستدعاءين معًا (Promise.all، asyncio.gather، goroutines). بعد الإصلاح يُظهر المخطط B وC متداخلتين — ويصبح الزمن الكلي max(B, C) بدلًا من B + C.

لا تثق بمدة الامتداد الجذري وحده. امتداد جذري مدته 600 مللي ثانية مع ابن DB بـ440 مللي وابن auth بـ55 مللي يترك ~105 مللي غير محسوبة. هذه الفجوة يقضيها الامتداد في نفسه — تسلسل، منطق تجاري، أو I/O محجوب. إن نمت هذه الفجوة مع مرور الوقت دون نموّ أي ابن، فلديك مشكلة CPU أو تنافس على الأقفال داخل الخدمة لا يمكن لأي امتداد تالٍ الكشف عنها. أضف امتدادًا داخليًا حول مسار الكود المشتبه به.

سير عمل التشخيص الحقيقي

هذا هو التسلسل الذي يتبعه مهندس SRE في شركة كبرى حين يُطلق التنبيه:

إطلاق التنبيه: تجاوز p99 لـPOST /order حد 500 مللي ثانية لخمس دقائق.
فتح لوحة Grafana. تأكيد ارتفاع المقياس. فحص رابط exemplar على نقطة الارتفاع.
يفتح exemplar أبطأ تتبع. ترتيب الامتدادات حسب المدة. أعلاها: db.insert_order، 440 مللي.
النقر على الامتداد. سمة db.statement تُظهر SELECT * FROM products WHERE id = ? — مُنفَّذة 47 مرة. N+1 كلاسيكي.
فحص الامتداد الأب: createOrder → مسار الكود order_service/handlers/create.py:83. التنقل مباشرةً إلى هناك.
إصلاح، نشر، مراقبة هبوط p99. إغلاق الحادثة.

الوقت الكلي من التنبيه إلى السبب الجذري: أقل من أربع دقائق. بدون التتبع، يستلزم التشخيص نفسه البحث في السجلات، وإضافة قياسات، وإعادة النشر، والأمل في تكرار المشكلة — ما يستغرق بسهولة 30 إلى 60 دقيقة.