ضبط‌کننده پرواز: یک ردیاب اجرای جدید Go

در سال ۲۰۲۴، ما جهان را با ردیابی‌های اجرایی قدرتمندتر Go آشنا کردیم. در آن پست وبلاگ، نگاهی اجمالی به برخی از قابلیت‌های جدیدی که می‌توانستیم با ردیاب اجرایی جدید خود باز کنیم، از جمله ردیابی در زمان واقعی (بلادرنگ) ارائه دادیم. خوشحالیم که اعلام کنیم ردیابی در زمان واقعی (بلادرنگ) اکنون در Go 1.25 در دسترس است و ابزاری قدرتمند و جدید در جعبه ابزار تشخیصی Go است.

ردیابی‌های اجرایی

ابتدا، مروری سریع بر ردیابی‌های اجرایی Go.

\ زمان اجرای Go را می‌توان طوری تنظیم کرد که گزارشی از بسیاری از رویدادهایی که در طول اجرای یک برنامه Go رخ می‌دهد، ثبت کند. این گزارش، ردیابی اجرایی زمان اجرا نامیده می‌شود. ردیابی‌های اجرایی Go حاوی اطلاعات فراوانی در مورد نحوه تعامل گوروتین‌ها با یکدیگر و سیستم زیربنایی است. این امر آنها را برای اشکال‌زدایی مسائل تأخیر بسیار مفید می‌کند، زیرا به شما می‌گویند که گوروتین‌های شما چه زمانی در حال اجرا هستند و مهم‌تر از آن، چه زمانی در حال اجرا نیستند.

\ بسته runtime/trace یک API برای جمع‌آوری ردیابی اجرایی در یک پنجره زمانی مشخص با فراخوانی runtime/trace.Start و runtime/trace.Stop ارائه می‌دهد. این روش اگر کدی که ردیابی می‌کنید فقط یک آزمون، میکروبنچمارک یا ابزار خط فرمان باشد، به خوبی کار می‌کند. می‌توانید ردیابی کاملی از اجرای سرتاسری یا فقط بخش‌هایی که برایتان مهم است، جمع‌آوری کنید.

\ با این حال، در سرویس‌های وب با اجرای طولانی، که نوع برنامه‌هایی هستند که Go برای آنها شناخته شده است، این کافی نیست. سرورهای وب ممکن است روزها یا حتی هفته‌ها فعال باشند و جمع‌آوری ردیابی از کل اجرا، داده‌های بسیار زیادی تولید می‌کند که باید در آنها جستجو کرد. اغلب فقط یک بخش از اجرای برنامه اشتباه می‌شود، مانند زمان‌بندی یک درخواست یا بررسی سلامت ناموفق. تا زمانی که این اتفاق می‌افتد، دیگر برای فراخوانی Start خیلی دیر شده است!

\ یک راه برای رویکرد به این مشکل، نمونه‌برداری تصادفی از ردیابی‌های اجرایی در سراسر ناوگان است. در حالی که این رویکرد قدرتمند است و می‌تواند به یافتن مشکلات قبل از تبدیل شدن به قطعی کمک کند، به زیرساخت زیادی برای شروع نیاز دارد. مقادیر زیادی از داده‌های ردیابی اجرایی باید ذخیره، دسته‌بندی و پردازش شوند که بسیاری از آنها اصلاً حاوی چیز جالبی نیستند. و وقتی سعی می‌کنید به ریشه یک مشکل خاص برسید، این روش اصلاً مناسب نیست.

ردیابی در زمان واقعی (بلادرنگ)

این ما را به ردیاب در زمان واقعی (بلادرنگ) می‌رساند.

\ یک برنامه اغلب می‌داند که چه زمانی مشکلی پیش آمده است، اما علت اصلی ممکن است مدت‌ها قبل رخ داده باشد. ردیاب در زمان واقعی (بلادرنگ) به شما امکان می‌دهد ردیابی چند ثانیه آخر اجرا را که منجر به لحظه‌ای می‌شود که برنامه تشخیص می‌دهد مشکلی وجود داشته است، جمع‌آوری کنید.

\ ردیاب در زمان واقعی (بلادرنگ) ردیابی اجرایی را به طور معمول جمع‌آوری می‌کند، اما به جای نوشتن آن در یک سوکت یا فایل، چند ثانیه آخر ردیابی را در حافظه بافر می‌کند. در هر نقطه، برنامه می‌تواند محتویات بافر را درخواست کند و دقیقاً پنجره زمانی مشکل‌دار را عکس‌برداری کند. ردیاب در زمان واقعی (بلادرنگ) مانند یک چاقوی جراحی است که مستقیماً به ناحیه مشکل برش می‌دهد.

مثال

بیایید با یک مثال یاد بگیریم که چگونه از ردیاب در زمان واقعی (بلادرنگ) استفاده کنیم. به طور خاص، بیایید از آن برای تشخیص مشکل عملکرد با یک سرور HTTP که بازی "حدس عدد" را پیاده‌سازی می‌کند، استفاده کنیم. این سرور یک نقطه پایانی /guess-number را در معرض دید قرار می‌دهد که یک عدد صحیح را می‌پذیرد و به تماس‌گیرنده پاسخ می‌دهد و به آنها اطلاع می‌دهد که آیا عدد درستی را حدس زده‌اند یا خیر.

\ همچنین یک گوروتین وجود دارد که هر دقیقه یک بار، گزارشی از تمام اعداد حدس زده شده را از طریق یک درخواست HTTP به سرویس دیگری ارسال می‌کند.

// bucket is a simple mutex-protected counter. type bucket struct { mu sync.Mutex guesses int } func main() { // Make one bucket for each valid number a client could guess. // The HTTP handler will look up the guessed number in buckets by // using the number as an index into the slice. buckets := make([]bucket, 100) // Every minute, we send a report of how many times each number was guessed. go func() { for range time.Tick(1 * time.Minute) { sendReport(buckets) } }() // Choose the number to be guessed. answer := rand.Intn(len(buckets)) http.HandleFunc("/guess-number", func(w http.ResponseWriter, r *http.Request) { start := time.Now() // Fetch the number from the URL query variable "guess" and convert it // to an integer. Then, validate it. guess, err := strconv.Atoi(r.URL.Query().Get("guess")) if err != nil || !(0 <= guess && guess < len(buckets)) { http.Error(w, "invalid 'guess' value", http.StatusBadRequest) return } // Select the appropriate bucket and safely increment its value. b := &buckets[guess] b.mu.Lock() b.guesses++ b.mu.Unlock() // Respond to the client with the guess and whether it was correct. fmt.Fprintf(w, "guess: %d, correct: %t", guess, guess == answer) log.Printf("HTTP request: endpoint=/guess-number guess=%d duration=%s", guess, time.Since(start)) }) log.Fatal(http.ListenAndServe(":8090", nil)) } // sendReport posts the current state of buckets to a remote service. func sendReport(buckets []bucket) { counts := make([]int, len(buckets)) for index := range buckets { b := &buckets[index] b.mu.Lock() defer b.mu.Unlock() counts[index] = b.guesses } // Marshal the report data into a JSON payload. b, err := json.Marshal(counts) if err != nil { log.Printf("failed to marshal report error=%s", err) return } url := "http://localhost:8091/guess-number-report" if _, err := http.Post(url, "application/json", bytes.NewReader(b)); err != nil { log.Printf("failed to send report: %s", err) } }

اینجا کد کامل برای سرور است: https://go.dev/play/p/rX1eyKtVglF، و برای یک کلاینت ساده: https://go.dev/play/p/2PjQ-1ORPiw. برای جلوگیری از یک فرآیند سوم، "کلاینت" همچنین سرور گزارش را پیاده‌سازی می‌کند، اگرچه در یک سیستم واقعی این جداگانه خواهد بود.

\ فرض کنیم که پس از استقرار برنامه در محیط تولید، شکایاتی از کاربران دریافت کردیم مبنی بر اینکه برخی از تماس‌های /guess-number بیش از حد انتظار طول می‌کشند. وقتی به لاگ‌های خود نگاه می‌کنیم، می‌بینیم که گاهی اوقات زمان پاسخ از 100 میلی‌ثانیه فراتر می‌رود، در حالی که اکثر تماس‌ها در حد میکروثانیه هستند.

2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=69 duration=625ns 2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=62 duration=458ns 2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=42 duration=1.417µs 2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=86 duration=115.186167ms 2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=0 duration=127.993375ms

قبل از ادامه، یک دقیقه وقت بگذارید و ببینید آیا می‌توانید مشکل را پیدا کنید!

\ صرف نظر از اینکه مشکل را پیدا کرده‌اید یا نه، بیایید عمیق‌تر شویم و ببینیم چگونه می‌توانیم مشکل را از اصول اولیه پیدا کنیم. به ویژه، عالی می‌شد اگر می‌توانستیم ببینیم که برنامه در زمان منتهی به پاسخ کند چه کاری انجام می‌داده است. این دقیقاً همان چیزی است که ردیاب در زمان واقعی (بلادرنگ) برای آن ساخته شده است! ما از آن برای ثبت یک ردیابی اجرایی پس از مشاهده اولین پاسخی که از 100 میلی‌ثانیه فراتر می‌رود، استفاده خواهیم کرد.

\ ابتدا، در main، ردیاب در زمان واقعی (بلادرنگ) را پیکربندی و راه‌اندازی می‌کنیم:

// Set up the flight recorder fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{ MinAge: 200 * time.Millisecond, MaxBytes: 1 << 20, // 1 MiB }) fr.Start()

MinAge مدت زمانی را که داده‌های ردیابی به طور قابل اعتماد حفظ می‌شوند، پیکربندی می‌کند، و ما پیشنهاد می‌کنیم آن را حدود 2 برابر پنجره زمانی رویداد تنظیم کنید. به عنوان مثال، اگر در حال اشکال‌زدایی یک زمان انتظار 5 ثانیه‌ای هستید، آن را روی 10 ثانیه تنظیم کنید. MaxBytes اندازه ردیابی بافر شده را پیکربندی می‌کند تا استفاده از حافظه شما را افزایش ندهد. به طور متوسط، می‌توانید انتظار داشته باشید که چند مگابایت داده ردیابی در هر ثانیه از اجرا تولید شود، یا 10 مگابایت در ثانیه برای یک سرویس پرمشغله.

\ سپس، یک تابع کمکی برای ثبت عکس فوری یا اسنپ شات و نوشتن آن در یک فایل اضافه می‌کنیم:

var once sync.Once // captureSnapshot captures a flight recorder snapshot. func captureSnapshot(fr *trace.FlightRecorder) { // once.Do ensures that the provided function is executed only once. once.Do(func() { f, err := os.Create("snapshot.trace") if err != nil { log.Printf("opening snapshot file %s failed: %s", f.Name(), err) return } defer f.Close() // ignore error // WriteTo writes the flight recorder data to the provided io.Writer. _, err = fr.WriteTo(f) if err != nil { log.Printf("writing snapshot to file %s failed: %s", f.Name(), err) return } // Stop the flight recorder after the snapshot has been taken. fr.Stop() log.Printf("captured a flight recorder snapshot to %s", f.Name()) }) }

\ و در نهایت، درست قبل از ثبت یک درخواست تکمیل شده، اگر درخواست بیش از 100 میلی‌ثانیه طول کشیده باشد، عکس فوری یا اسنپ شات را فعال می‌کنیم:

// Capture a snapshot if the response takes more than 100ms. // Only the first call has any effect. if fr.Enabled() && time.Since(start) > 100*time.Millisecond { go captureSnapshot(fr) }

\ اینجا کد کامل برای سرور است، اکنون با ردیاب در زمان واقعی (بلادرنگ) ابزارگذاری شده است: https://go.dev/play/p/3V33gfIpmjG

\ اکنون، سرور را دوباره اجرا می‌کنیم و درخواست‌ها را ارسال می‌کنیم تا یک درخواست کند دریافت کنیم که یک عکس فوری یا اسنپ شات را فعال می‌کند.

\ پس از دریافت یک ردیابی، به ابزاری نیاز خواهیم داشت که به ما در بررسی آن کمک کند. زنجیره ابزار Go یک ابزار تحلیل ردیابی اجرایی داخلی از طریق دستور go tool trace ارائه می‌دهد. go tool trace snapshot.trace را اجرا کنید تا ابزار را راه‌اندازی کنید، که یک سرور وب محلی را شروع می‌کند، سپس URL نمایش داده شده را در مرورگر خود باز کنید (اگر ابزار به طور خودکار مرورگر شما را باز نکند).

\ این ابزار چند روش برای نگاه کردن به ردیابی به ما می‌دهد، اما بیایید بر تجسم ردیابی تمرکز کنیم تا درکی از آنچه در حال رخ دادن است، به دست آوریم. برای این کار روی "View trace by proc" کلیک کنید.

\ در این نما، ردیابی به صورت یک خط زمانی از رویدادها ارائه می‌شود. در بالای صفحه، در بخش "STATS"، می‌توانیم خلاصه‌ای از وضعیت برنامه را ببینیم، از جمله تعداد رشته‌ها، اندازه هیپ و تعداد گوروتین.

\ زیر آن، در بخش "PROCS"، می‌توانیم ببینیم که چگونه اجرای گوروتین‌ها روی GOMAXPROCS (تعداد رشته‌های سیستم عامل ایجاد شده توسط برنامه Go) نگاشت می‌شود. می‌توانیم ببینیم که هر گوروتین چه زمانی و چگونه شروع می‌شود، اجرا می‌شود و در نهایت اجرا را متوقف می‌کند.

\ فعلاً، بیایید توجه خود را به این شکاف عظیم در اجرا در سمت راست نمایشگر معطوف کنیم. برای مدتی، حدود 100 میلی‌ثانیه، هیچ اتفاقی نمی‌افتد!

با انتخاب ابزار zoom (یا فشار دادن 3)، می‌توانیم بخشی از ردیابی را درست بعد از شکاف با جزئیات بیشتری بررسی کنیم.

\ علاوه بر فعالیت هر گوروتین به صورت جداگانه، می‌توانیم ببینیم که گوروتین‌ها از طریق "رویدادهای جریان" چگونه با یکدیگر تعامل می‌کنند. یک رویداد جریان ورودی نشان می‌دهد که چه اتفاقی افتاده است تا یک گوروتین شروع به اجرا کند. یک لبه جریان خروجی نشان می‌دهد که یک گوروتین چه تأثیری بر گوروتین دیگر داشته است. فعال کردن تجسم همه رویدادهای جریان اغلب سرنخ‌هایی را ارائه می‌دهد که به منبع مشکل اشاره می‌کنند.

در این مورد، می‌توانیم ببینیم که بسیاری از گوروتین‌ها درست بعد از وقفه در فعالیت، ارتباط مستقیمی با یک گوروتین واحد دارند.

\ کلیک کردن روی گوروتین واحد، جدول رویدادی را نشان می‌دهد که پر از رویدادهای جریان خروجی است، که با آنچه هنگام فعال بودن نمای جریان دیدیم، مطابقت دارد.

\ وقتی این گوروتین اجرا شد، چه اتفاقی افتاد؟ بخشی از اطلاعات ذخیره شده در ردیابی، نمایی از ردیابی پشته در نقاط زمانی مختلف است. وقتی به گوروتین نگاه می‌کنیم، می‌توانیم ببینیم که ردیابی پشته شروع نشان می‌دهد که هنگامی که گوروتین برای اجرا زمان‌بندی شده بود، منتظر تکمیل درخواست HTTP بود. و ردیابی پشته پایان نشان می‌دهد که تابع sendReport قبلاً برگشته بود و منتظر تیکر برای زمان بعدی برنامه‌ریزی شده برای ارسال گزارش بود.

\ بین شروع و پایان اجرای این گوروتین، تعداد زیادی "جریان‌های خروجی" می‌بینیم، جایی که با گوروتین‌های دیگر تعامل می‌کند. کلیک کردن روی یکی از ورودی‌های Outgoing flow ما را به نمایی از تعامل می‌برد.

\ این جریان Unlock در sendReport را متهم می‌کند:

for index := range buckets { b := &buckets[index] b.mu.Lock() defer b.mu.Unlock() counts[index] = b.guesses }

\ در sendReport، قصد داشتیم قفلی روی هر سطل بگیریم و قفل را پس از کپی کردن مقدار آزاد کنیم.

\ اما اینجا مشکل است: ما در واقع قفل را بلافاصله پس از کپی کردن مقدار موجود در bucket.guesses آزاد نمی‌کنیم. از آنجا که از یک عبارت defer برای آزاد کردن قفل استفاده کردیم، این آزادسازی تا زمانی که تابع برگردد، اتفاق نمی‌افتد. ما قفل را نه تنها تا پایان حلقه، بلکه تا پس از تکمیل درخواست HTTP نگه می‌داریم. این یک خطای ظریف است که ممکن است ردیابی آن در یک سیستم تولیدی بزرگ دشوار باشد.

\ خوشبختانه، ردیابی اجرایی به ما کمک کرد تا مشکل را دقیقاً مشخص کنیم. با این حال، اگر سعی می‌کردیم از ردیاب اجرایی در یک سرور با اجرای طولانی بدون حالت جدید ردیابی در زمان واقعی (بلادرنگ) استفاده کنیم، احتمالاً مقدار زیادی داده ردیابی اجرایی جمع می‌شد که یک اپراتور باید آن را ذخیره، منتقل و در آن جستجو کند. ردیاب در زمان واقعی (بلادرنگ) قدرت پس‌نگری را به ما می‌دهد. به ما امکان می‌دهد دقیقاً آنچه را که اشتباه پیش رفته است، پس از وقوع آن ثبت کنیم و سریعاً به علت آن پی ببریم.

\ ردیاب در زمان واقعی (بلادرنگ) فقط آخرین افزودنی به جعبه ابزار توسعه‌دهنده Go برای تشخیص کارکرد داخلی برنامه‌های در حال اجرا است. ما به طور پیوسته در حال بهبود ردیابی در چند نسخه گذشته بوده‌ایم. Go 1.21 سربار زمان اجرای ردیابی را به میزان قابل توجهی کاهش داد. فرمت ردیابی در نسخه Go 1.22 قوی‌تر و همچنین قابل تقسیم شد، که منجر به ویژگی‌هایی مانند ردیاب در زمان واقعی (بلادرنگ) شد. ابزارهای متن‌باز مانند gotraceui و توانایی آینده برای تجزیه برنامه‌ای ردیابی‌های اجرایی، راه‌های بیشتری برای بهره‌برداری از قدرت ردیابی‌های اجرایی هستند. صفحه تشخیص، ابزارهای اضافی زیادی را در اختیار شما قرار می‌دهد. امیدواریم هنگام نوشتن و پالایش برنامه‌های Go خود از آنها استفاده کنید.

تشکر

می‌خواهیم لحظه‌ای وقت بگذاریم و از اعضای جامعه که در جلسات تشخیصی فعال بوده‌اند، در طراحی‌ها مشارکت داشته‌اند و در طول سال‌ها بازخورد ارائه داده‌اند، تشکر کنیم: Felix Geisendörfer (@felixge.de)، Nick Ripley (@nsrip-dd)، Rhys Hiltner (@rhysh)، Dominik Honnef (@dominikh)، Bryan Boreham (@bboreham) و PJ Malloy (@thepudds).

\ بحث‌ها، بازخوردها و کاری که همه شما انجام داده‌اید، در پیشبرد ما به سمت آینده تشخیصی بهتر نقش اساسی داشته است. از شما متشکریم!

---

Carlos Amedee و Michael Knyszek

\ این مقاله در وبلاگ Go تحت مجوز CC BY 4.0 DEED در دسترس است.

\ عکس توسط Lukas Souza در Unsplash

\