GitHub

Instrumenting Julia with DTrace, and bpftrace

DTrace و bpftrace هما أداتان تتيحان قياس خفيف للعمليات. يمكنك تشغيل القياس وإيقافه أثناء تشغيل العملية، ومع إيقاف القياس يكون الحمل ضئيلاً.

Julia 1.8

تمت إضافة الدعم للمجسات في جوليا 1.8

Note

تمت كتابة هذه الوثيقة من منظور لينكس، يجب أن يكون معظم هذا صحيحًا على نظام ماك أو إس/داروين وFreeBSD.

Enabling support

على نظام Linux، قم بتثبيت حزمة systemtap التي تحتوي على إصدار من dtrace وأنشئ ملف Make.user يحتوي على

WITH_DTRACE=1

لتمكين مجسات USDT.

Verifying

> readelf -n usr/lib/libjulia-internal.so.1

Displaying notes found in: .note.gnu.build-id
  Owner                Data size  Description
  GNU                  0x00000014 NT_GNU_BUILD_ID (unique build ID bitstring)
    Build ID: 57161002f35548772a87418d2385c284ceb3ead8

Displaying notes found in: .note.stapsdt
  Owner                Data size  Description
  stapsdt              0x00000029 NT_STAPSDT (SystemTap probe descriptors)
    Provider: julia
    Name: gc__begin
    Location: 0x000000000013213e, Base: 0x00000000002bb4da, Semaphore: 0x0000000000346cac
    Arguments:
  stapsdt              0x00000032 NT_STAPSDT (SystemTap probe descriptors)
    Provider: julia
    Name: gc__stop_the_world
    Location: 0x0000000000132144, Base: 0x00000000002bb4da, Semaphore: 0x0000000000346cae
    Arguments:
  stapsdt              0x00000027 NT_STAPSDT (SystemTap probe descriptors)
    Provider: julia
    Name: gc__end
    Location: 0x000000000013214a, Base: 0x00000000002bb4da, Semaphore: 0x0000000000346cb0
    Arguments:
  stapsdt              0x0000002d NT_STAPSDT (SystemTap probe descriptors)
    Provider: julia
    Name: gc__finalizer
    Location: 0x0000000000132150, Base: 0x00000000002bb4da, Semaphore: 0x0000000000346cb2
    Arguments:

Adding probes in libjulia

تُعلن المجسات بتنسيق dtraces في الملف src/uprobes.d. يتم تضمين ملف الرأس المُولد في src/julia_internal.h وإذا قمت بإضافة مجسات، يجب عليك توفير تنفيذ noop هناك.

سيتضمن الرأس إشارة *_ENABLED والاستدعاء الفعلي للمسبار. إذا كانت معلمات المسبار مكلفة في الحساب، يجب عليك أولاً التحقق مما إذا كان المسبار مفعلًا ثم حساب المعلمات واستدعاء المسبار.

  if (JL_PROBE_{PROBE}_ENABLED())
    auto expensive_arg = ...;
    JL_PROBE_{PROBE}(expensive_arg);

إذا لم يكن لدى المجس الخاص بك أي وسائط، يُفضل عدم تضمين فحص السيمفور. مع تمكين مجسات USDT، فإن تكلفة السيمفور هي تحميل في الذاكرة، بغض النظر عن حقيقة أن المجس مفعل أم لا.

#define JL_PROBE_GC_BEGIN_ENABLED() __builtin_expect (julia_gc__begin_semaphore, 0)
__extension__ extern unsigned short julia_gc__begin_semaphore __attribute__ ((unused)) __attribute__ ((section (".probes")));

بينما تكون المجس نفسه زلاجة لا تفعل شيئًا سيتم توصيلها بترامبولين إلى معالج المجس.

Available probes

GC probes

  1. julia:gc__begin: يبدأ جمع القمامة (GC) في العمل على خيط واحد ويؤدي إلى توقف العالم.
  2. julia:gc__stop_the_world: جميع الخيوط قد وصلت إلى نقطة أمان وتعمل جمع القمامة.
  3. julia:gc__mark__begin: بدء مرحلة العلامة
  4. julia:gc__mark_end(scanned_bytes, perm_scanned): انتهت مرحلة العلامة
  5. julia:gc__sweep_begin(full): بدء المسح
  6. julia:gc__sweep_end: انتهت مرحلة المسح
  7. julia:gc__end: انتهت عملية جمع القمامة، وتواصل الخيوط الأخرى العمل
  8. julia:gc__finalizer: انتهى خيط جمع القمامة الأولي من تشغيل المنهيات

Task runtime probes

  1. julia:rt__run__task(task): التبديل إلى المهمة task على الخيط الحالي.
  2. julia:rt__pause__task(task): التبديل من المهمة task على الخيط الحالي.
  3. julia:rt__new__task(parent, child): المهمة parent أنشأت المهمة child على الخيط الحالي.
  4. julia:rt__start__task(task): تم بدء المهمة task للمرة الأولى مع مكدس جديد.
  5. julia:rt__finish__task(task): تم الانتهاء من المهمة task ولن يتم تنفيذها بعد الآن.
  6. julia:rt__start__process__events(task): بدأت المهمة task معالجة أحداث libuv.
  7. julia:rt__finish__process__events(task): المهمة task انتهت من معالجة أحداث libuv.

Task queue probes

  1. julia:rt__taskq__insert(ptls, task): حاول الخيط ptls إدخال task في قائمة متعددة PARTR.
  2. julia:rt__taskq__get(ptls, task): تم سحب task من قائمة متعددة PARTR بواسطة الخيط ptls.

Thread sleep/wake probes

  1. julia:rt__sleep__check__wake(ptls, old_state): الخيط (PTLS ptls) يستيقظ، كان سابقًا في الحالة old_state.
  2. julia:rt__sleep__check__wakeup(ptls): الخيط (PTLS ptls) أيقظ نفسه.
  3. julia:rt__sleep__check__sleep(ptls): الخيط (PTLS ptls) يحاول النوم.
  4. julia:rt__sleep__check__taskq__wake(ptls): الخيط (PTLS ptls) يفشل في النوم بسبب المهام في PARTR multiq.
  5. julia:rt__sleep__check__task__wake(ptls): الخيط (PTLS ptls) يفشل في النوم بسبب المهام في قائمة العمل الأساسية.
  6. julia:rt__sleep__check__uv__wake(ptls): الخيط (PTLS ptls) يفشل في النوم بسبب استيقاظ libuv.

Probe usage examples

GC stop-the-world latency

مثال على سكربت bpftrace موجود في contrib/gc_stop_the_world_latency.bt ويقوم بإنشاء هيستوجرام للزمن المستغرق لجميع الخيوط للوصول إلى نقطة الأمان.

تشغيل هذا الكود بلغة جوليا، مع julia -t 2

using Base.Threads

fib(x) = x <= 1 ? 1 : fib(x-1) + fib(x-2)

beaver = @spawn begin
    while true
        fib(30)
        # A manual safepoint is necessary since otherwise this loop
        # may never yield to GC.
        GC.safepoint()
    end
end

allocator = @spawn begin
    while true
        zeros(1024)
    end
end

wait(allocator)

وفي نافذة طرفية ثانية

> sudo contrib/bpftrace/gc_stop_the_world_latency.bt
Attaching 4 probes...
Tracing Julia GC Stop-The-World Latency... Hit Ctrl-C to end.
^C


@usecs[1743412]:
[4, 8)               971 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[8, 16)              837 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@        |
[16, 32)             129 |@@@@@@                                              |
[32, 64)              10 |                                                    |
[64, 128)              1 |                                                    |

يمكننا رؤية توزيع الكمون لمرحلة التوقف عن العالم في عملية جوليا المنفذة.

Task spawn monitor

من المفيد أحيانًا معرفة متى يقوم مهمة بإنشاء مهام أخرى. من السهل جدًا رؤية ذلك باستخدام rt__new__task. الحجة الأولى للمعاينة، parent، هي المهمة الموجودة التي تقوم بإنشاء مهمة جديدة. هذا يعني أنه إذا كنت تعرف عنوان المهمة التي تريد مراقبتها، يمكنك بسهولة النظر إلى المهام التي أنشأتها تلك المهمة المحددة. دعنا نرى كيف نفعل ذلك؛ أولاً دعنا نبدأ جلسة جوليا ونحصل على PID وعنوان مهمة REPL:

> julia
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.6.2 (2021-07-14)
 _/ |\__'_|_|_|\__'_|  |  Official https://julialang.org/ release
|__/                   |

1> getpid()
997825

2> current_task()
Task (runnable) @0x00007f524d088010

الآن يمكننا بدء bpftrace وجعله يراقب rt__new__task لـ فقط هذا الوالد:

sudo bpftrace -p 997825 -e 'usdt:usr/lib/libjulia-internal.so:julia:rt__new__task /arg0==0x00007f524d088010/{ printf("المهمة: %x\n", arg0); }'

(لاحظ أن arg0 هو الوسيطة الأولى، parent).

وإذا قمنا بإنشاء مهمة واحدة:

@async 1+1

نرى أنه يتم إنشاء هذه المهمة:

Task: 4d088010

ومع ذلك، إذا قمنا بإنشاء مجموعة من المهام من تلك المهمة التي تم إنشاؤها حديثًا:

@async for i in 1:10
   @async 1+1
end

نحن لا نزال نرى مهمة واحدة فقط من bpftrace:

المهمة: 4d088010

وما زال نفس المهمة التي كنا نراقبها! بالطبع، يمكننا إزالة هذا الفلتر لرؤية جميع المهام التي تم إنشاؤها حديثًا بنفس السهولة:

sudo bpftrace -p 997825 -e 'usdt:usr/lib/libjulia-internal.so:julia:rt__new__task { printf("المهمة: %x\n", arg0); }'

Task: 4d088010
Task: 4dc4e290
Task: 4dc4e290
Task: 4dc4e290
Task: 4dc4e290
Task: 4dc4e290
Task: 4dc4e290
Task: 4dc4e290
Task: 4dc4e290
Task: 4dc4e290
Task: 4dc4e290

يمكننا رؤية مهمة الجذر لدينا، والمهمة التي تم إنشاؤها حديثًا كوالد للمهام العشر الأحدث.

Thundering herd detection

يمكن أن تعاني أوقات تنفيذ المهام غالبًا من مشكلة "القطيع الرعدي": عندما يتم إضافة بعض العمل إلى وقت تنفيذ مهمة هادئ، قد يتم إيقاظ جميع الخيوط من سباتها، حتى لو لم يكن هناك ما يكفي من العمل لكل خيط لمعالجته. يمكن أن يتسبب ذلك في تأخير إضافي ودورات CPU بينما تستيقظ جميع الخيوط (وتعود في الوقت نفسه إلى النوم، دون العثور على أي عمل لتنفيذه).

يمكننا رؤية هذه المشكلة موضحة باستخدام bpftrace بسهولة. أولاً، في نافذة طرفية واحدة نبدأ جوليا مع عدة خيوط (6 في هذا المثال)، ونحصل على PID لتلك العملية:

> julia -t 6
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.6.2 (2021-07-14)
 _/ |\__'_|_|_|\__'_|  |  Official https://julialang.org/ release
|__/                   |

1> getpid()
997825

وفي نافذة طرفية أخرى نبدأ bpftrace لمراقبة عمليتنا، مع التركيز على استهداف خطاف rt__sleep__check__wake:

sudo bpftrace -p 997825 -e 'usdt:usr/lib/libjulia-internal.so:julia:rt__sleep__check__wake { printf("استيقاظ الخيط! %x\n", arg0); }'

الآن، نقوم بإنشاء وتنفيذ مهمة واحدة في جوليا:

Threads.@spawn 1+1

وفي bpftrace نرى شيئًا مطبوعًا مثل:

Thread wake up! 3f926100
Thread wake up! 3ebd5140
Thread wake up! 3f876130
Thread wake up! 3e2711a0
Thread wake up! 3e312190

حتى لو قمنا بإنشاء مهمة واحدة فقط (يمكن لمعالج واحد فقط التعامل معها في وقت واحد)، فقد قمنا بإيقاظ جميع خيوطنا الأخرى! في المستقبل، قد يقوم وقت تشغيل المهام الأكثر ذكاءً بإيقاظ خيط واحد فقط (أو لا شيء على الإطلاق؛ يمكن للخيط الذي أنشأ هذه المهمة تنفيذها!)، ويجب أن نرى هذا السلوك يختفي.

Task Monitor with BPFnative.jl

BPFnative.jl قادر على الاتصال بنقاط استكشاف USDT تمامًا مثل bpftrace. هناك عرض توضيحي متاح لمراقبة وقت تشغيل المهام، وجمع القمامة، وانتقالات النوم/الاستيقاظ للخيوط here.

Notes on using bpftrace

مثال على مجس بتنسيق bpftrace يبدو كالتالي:

usdt:usr/lib/libjulia-internal.so:julia:gc__begin
{
  @start[pid] = nsecs;
}

إعلان الاستشعار يأخذ النوع usdt، ثم إما مسار المكتبة أو PID، اسم المزود julia واسم الاستشعار gc__begin. لاحظ أنني أستخدم مسارًا نسبيًا إلى libjulia-internal.so، ولكن قد يحتاج هذا إلى أن يكون مسارًا مطلقًا في نظام الإنتاج.

Useful references: