بازگشت به بلاگ
۹ شهریور ۱۴۰۵Sergei Solod10 دقیقه مطالعه

VPS من آنلاین بود؛ بعد Linux برای خواندن دیسک ۱۸ ثانیه منتظر ماند

روایت یک عیب‌یابی واقعی در محیط production روی Linux: VPS آنلاین بود، اما کار مفید تقریباً متوقف شده بود. فشار I/O به نزدیکی ۱۰۰٪ رسید، خواندن‌ها تا ۱۸٫۷ ثانیه طول کشیدند و Nginx در EXT4 گیر کرد، در حالی که backend هنوز در حدود ۳ میلی‌ثانیه پاسخ می‌داد.

لینوکسDevOpsVPSکاراییعیب‌یابی

قبل از ورود به جزئیات عیب‌یابی، یک نکته را روشن کنم: برداشت کلی من از FDCServers منفی نیست. این نوشته قرار نیست به کسی بگوید از این ارائه‌دهنده دوری کند و قضاوتی درباره کل زیرساخت آن هم نیست. من فقط یک VPS داشتم که در یک بازه مشخص با یک مشکل غیرعادی و دشوار روبه‌رو شد.

مدت زیادی VPS طبیعی کار می‌کرد و ترافیک واقعی production را بدون مشکل سرو می‌کرد. بعد چیزی تغییر کرد. درخواست‌های عادی ناگهان بسیار کند شدند. صفحه‌ها ابتدا دیر باز می‌شدند و گاهی اصلاً باز نمی‌شدند. در بعضی زمان‌ها نیز قبل از اینکه بتوانم خطا را درست بررسی کنم، ماشین دوباره کاملاً طبیعی به نظر می‌رسید.

در بدترین حالت این مقادیر را ثبت کردم:

CPU iowait:       97–100%
I/O PSI full:     ~95–98%
read latency:     up to 18.7 seconds
flush latency:    up to 53.6 seconds
I/O queue depth:  128+

Nginx در حال اجرا بود. backend در حال اجرا بود. VM آنلاین بود. اما تقریباً هیچ کار مفیدی جلو نمی‌رفت.

اختلال production آزاردهنده بود، ولی خود فرایند عیب‌یابی برایم واقعاً لذت‌بخش بود. یکی از دلایلی که Linux را دوست دارم همین است: سیستم از بیرون زنده به نظر می‌رسد، اما چند interface مستقل kernel نشان می‌دهند پیشرفت مفید دقیقاً کجا متوقف شده است. این مقاله درباره دنبال‌کردن همین نشانه‌هاست، نه اینکه FDCServers را provider خوب یا بدی اعلام کند.

active (running) تقریباً بی‌معنی شد

از بررسی‌های معمول شروع کردم:

top
free -h
df -h
systemctl status nginx

در دوره‌های سالم تقریباً این مقادیر را می‌دیدم:

D-state processes: 0
CPU iowait:        ~0%
disk latency:      ~2–4 ms
I/O PSI some:      0.04
I/O PSI full:      0.04

اگر فقط در همان لحظه وصل می‌شدم، احتمالاً نتیجه می‌گرفتم همه چیز سالم است. بعد ترافیک عادی برمی‌گشت و وضعیت ماشین کاملاً تغییر می‌کرد. یک snapshot سالم از خطای intermittent چیز زیادی درباره حالت خراب سیستم نمی‌گوید. باید هنگام وقوع خطا evidence جمع می‌کردم.

نمونه iostat که مسیر بررسی را عوض کرد

r_await = 18744 ms
f_await = 53561 ms
aqu-sz  = 128.54
util    ≈ 100%
read    = 88 KB/s

خواندن‌های تکمیل‌شده حدود ۱۸٫۷ ثانیه طول می‌کشیدند. flush حدود ۵۳٫۶ ثانیه بود. میانگین صف از ۱۲۸ بیشتر شده بود، در حالی که throughput مفید خواندن فقط 88 KB/s بود.

این شبیه storageای نبود که فقط به دلیل workload سنگین، اما مفید، مشغول باشد. مسیر block مجازی عملاً اشباع بود، ولی کار بسیار کمی انجام می‌داد. utilization بالا به‌تنهایی خطا نیست؛ اما ترکیب آن با latency عظیم، queue بزرگ، taskهای متوقف، throughput بسیار کم و requestهای ناموفق تصویر دیگری می‌سازد.

دیگر iowait را به‌تنهایی تشخیص در نظر نگرفتم

blocked processes: 4–9
CPU iowait:        97–100%
CPU idle:          0%

وسوسه‌انگیز است بگوییم CPU صد درصد زمانش را منتظر دیسک بوده، اما accounting در Linux پیچیده‌تر است. iowait اندازه‌گیری مستقیم خود دیسک نیست، بنابراین آن را فقط یک نشانه در نظر گرفتم و دنبال evidence مستقل رفتم.

PSI نشان داد I/O عملاً جلوی کار مفید را می‌گیرد

cat /proc/pressure/io

در یک دوره شدید:

some avg10=99.14
full avg10=95.55

در تکرارهای بعدی full به حدود ۹۸٪ رسید. در I/O PSI، مقدار some زمانی را نشان می‌دهد که حداقل بخشی از کار non-idle روی I/O متوقف است؛ full زمانی را نشان می‌دهد که همه taskهای non-idle هم‌زمان روی I/O متوقف‌اند. عدد نزدیک ۱۰۰٪ فقط به معنای busy بودن دیسک نیست؛ workload تقریباً فرصتی برای پیشرفت ندارد.

D-state باعث شد یک process خاص را مقصر ندانم

ps -eo state,pid,ppid,etime,wchan:50,comm,args | awk 'NR==1 || $1 ~ /^D/'

یک process که کوتاه‌مدت وارد D-state می‌شود، storage problem را ثابت نمی‌کند. مهم این بود که چه processهایی هم‌زمان گیر کرده بودند. من jbd2، systemd-journald، workerهای Nginx، processهای cache و فعالیت‌های دیگر filesystem را هم‌زمان متوقف دیدم.

اگر فقط backend گیر کند، backend را بررسی می‌کنم. اگر فقط Nginx گیر کند، Nginx را بررسی می‌کنم. وقتی Nginx، system journal و journal thread مربوط به EXT4 هم‌زمان پیشرفت نمی‌کنند، dependency مشترک مهم‌تر می‌شود. در این مورد filesystem و storage path زیر آن نقطه مشترک بودند.

Kernel stackها لایه بعدی را نشان دادند

EXT4 journal thread در مسیرهایی مثل این بود:

wait_on_buffer
jbd2_log_wait_commit
jbd2_journal_commit_transaction

workerهای Nginx در مسیرهای عادی خواندن فایل دیده می‌شدند:

folio_wait_bit_common
filemap_read
generic_file_read_iter
ext4_file_read_iter
vfs_read
pread64

در یک لحظه kernel گزارش داد:

INFO: task nginx blocked for more than 122 seconds.

systemctl status nginx هنوز active (running) نشان می‌داد. هر دو درست بودند: process وجود داشت، اما یکی از taskهای Nginx بیش از دو دقیقه قادر به تمام کردن کار مفید نبود. running بودن process مساوی healthy بودن service نیست.

شفاف‌ترین آزمایش من حدود سه میلی‌ثانیه طول کشید

در مسیر Nginx request شکست خورد:

HTTP=000
SSL connection timeout

بعد Nginx را دور زدم و مستقیم به backend محلی وصل شدم:

connect = 0.000423 s
TTFB    = 0.003063 s
total   = 0.003139 s

حدود ۳ میلی‌ثانیه. status دقیق HTTP برای این تست مهم نبود. backend connection را پذیرفت، request را اجرا کرد و تقریباً فوراً پاسخ داد. تقریباً در همان زمان workerهای Nginx داخل مسیرهای خواندن EXT4 بودند.

application execution       → progressing normally
filesystem-backed web path  → not progressing normally

هرچه جلوتر رفتم، توضیح application-level کمتر قابل دفاع شد.

همان VPS می‌توانست در حدود ۳۰ ثانیه از حالت سالم به خراب برود

قبل از یک reproduction:

HTTP:          200
D-state:       0
CPU iowait:    3%
r_await:       ~1.18 ms
I/O PSI full:  ~2.95%

حدود نیم دقیقه بعد:

D-state:       4
CPU iowait:    91%
CPU idle:      0%
I/O PSI some:  86.11%
I/O PSI full:  78.02%
r_await:       236.50 ms
HTTP:          000

و بعد بدتر:

CPU iowait:    96–100%
I/O PSI full:  ~98%
HTTPS queue:   512
HTTP:          000

با حذف workload ممکن بود خیلی سریع به حالت سالم برگردد:

D-state:      0
CPU iowait:   6%
r_await:      ~0.98 ms
queue depth:  ~0.07
HTTP:         200

به همین دلیل خطاهای intermittent زیرساختی این‌قدر دشوارند. ممکن است کسی ده دقیقه بعد همان VM را بررسی کند و latency کمتر از یک میلی‌ثانیه ببیند و کاملاً هم درست بگوید؛ فقط وضعیت دیگری را دیده است.

Latency صفر همیشه خبر خوبی نیست

در یک interval مقدار r_await = 0 دیدم، در حالی که سیستم واضحاً خراب بود: iowait بالا، processهای D-state، I/O در انتظار، تقریباً بدون read تکمیل‌شده و throughput نزدیک صفر.

میانگین‌هایی که بر اساس operationهای تکمیل‌شده‌اند وقتی تقریباً هیچ چیزی تمام نمی‌شود اطلاعات کمی می‌دهند. صفر الزاماً به این معنا نیست که read فوراً تمام شده؛ ممکن است completion کافی برای توصیف operationهای گیرکرده وجود نداشته باشد.

از آن زمان latency، IOPS، throughput، queue depth، in-flight I/O، D-state، PSI و completion واقعی request را کنار هم می‌بینم.

یک incident به یک بررسی طولانی‌تر با پشتیبانی تبدیل شد

اولین رخداد شدید با یک backup زمان‌بندی‌شده روی زیرساخت اولیه هم‌زمان بود و FDCServers تأیید کرد backup در حال اجرا بوده است. برای شروع توضیح معقولی بود. اما بعد همان نوع storage stall را پس از پایان backup و خارج از window اصلی آن دوباره ایجاد کردم.

مشکل در چند روز تکرار شد. در یکی از رخدادها VPS طبق logهای من بعداً به مدت ۴ ساعت و ۴۱ دقیقه و ۱۵ ثانیه در دسترس نبود. نمی‌توانم ثابت کنم storage stall باعث آن وضعیت VM شده بود؛ برای این نتیجه host-side data لازم بود.

application
    ↓
Linux VFS
    ↓
EXT4
    ↓
virtual block device
    ↓
?

پشت علامت سؤال ممکن است virtualization، host queue، storage network، distributed storage، media فیزیکی، schedulerها و لایه‌های دیگری باشند که guest نمی‌بیند. محل بروز failure را می‌دیدم، ولی physical root cause را نه.

FDCServers موضوع را escalate کرد و VPS را به node دیگری منتقل کرد. بعد از migration باز هم یک storage stall شدید را از داخل guest ثبت کردم. این ثابت نمی‌کند همه nodeهای FDCServers مشکل storage داشتند؛ فقط می‌گوید مشکل VPS من از دید من هنوز برطرف نشده بود.

چرا هنوز این را داستانی منفی درباره FDCServers نمی‌دانم

تبدیل یک incident زیرساختی به حکم کلی درباره provider آسان است. من نمی‌خواهم این کار را انجام دهم.

برای من فرق دارد که service ذاتاً و در حالت عادی برای workload من مناسب نباشد یا با یک مشکل intermittent روبه‌رو شویم که بازتولید و isolate کردنش سخت است. تجربه من با FDCServers بیشتر شبیه حالت دوم بود.

VPS قبل از incident طبیعی کار کرده و ترافیک واقعی production را حمل کرده بود. پشتیبانی بررسی کرد و برای رفع مشکل تلاش کرد. در نهایت evidence کافی داشتم تا تصمیم بگیرم دیگر production را به همان VPS وابسته نکنم.

درخواست cancel و refund دادم و FDCServers پول را برگرداند. این موضوع روی برداشت کلی من تأثیر دارد.

زیرساخت فعلی آنها را دوباره تست نکرده‌ام، بنابراین نمی‌توانم بگویم امروز VPS آنها چگونه کار می‌کند. همچنین مدرکی ندارم که مشکل instance من نماینده کل fleet بوده باشد. Infrastructure دائماً تغییر می‌کند. نمی‌خواهم یک incident سخت در یک VPS را به حکم دائمی درباره provider تبدیل کنم. اینجا FDCServers را recommend هم نمی‌کنم؛ فقط تجربه خودم را ثبت می‌کنم.

بخش مورد علاقه‌ام خود Linux بود

Downtime آزاردهنده بود، ولی investigation واقعاً لذت‌بخش بود. پیدا کردن boundary مشکل برایم جالب بود.

برای تشخیص physical root cause visibility کافی نداشتم. سؤال مورد نظرم ساده‌تر بود: کار مفید در کدام لایه متوقف می‌شود؟

backend در حدود سه ms پاسخ می‌داد. Nginx active بود، اما kernel stackها نشان می‌دادند داخل EXT4 read منتظر است. vmstat processهای blocked و I/O wait شدید را نشان می‌داد. PSI تقریباً stall کامل I/O را نشان می‌داد. iostat latency و queueing عظیم داشت. D-state processهای نامرتبط را هم‌زمان در انتظار نشان می‌داد. Kernel حتی گزارش کرد یک task مربوط به Nginx بیش از 122 ثانیه blocked بوده است.

هیچ metricای به‌تنهایی مسئله را حل نکرد. توافق بین آنها این کار را کرد. یکی از دلایل علاقه من به Linux همین است: از جمله‌ای مبهم مثل «سایت گاهی باز نمی‌شود» می‌توانید قدم‌به‌قدم به یک توصیف دقیق از لایه‌ای برسید که useful work در آن متوقف شده است.

Workflow عیب‌یابی‌ای که حالا استفاده می‌کنم

top
free -h
df -h

date -u
uptime
cat /proc/pressure/io
cat /proc/pressure/memory
cat /proc/pressure/cpu
vmstat 1 10
iostat -x 1 10
ps -eo state,pid,ppid,etime,wchan:50,comm,args | awk 'NR==1 || $1 ~ /^D/'
ss -lntp
journalctl -k --since "30 min ago" --no-pager

هر وقت ممکن باشد، بخش‌های مختلف request path را جداگانه تست می‌کنم:

public request
      ↓
reverse proxy
      ↓
direct backend
      ↓
filesystem
      ↓
block device

دیگر فقط نمی‌پرسم چرا server کند است. می‌پرسم: در کدام لایه completion کار مفید متوقف می‌شود؟ این سؤال experimentهای بسیار بهتری می‌سازد.

یک قانون آخر: قبل از reboot مدرک جمع کنید

reboot ممکن است دقیقاً چیزی باشد که production نیاز دارد، اما می‌تواند باارزش‌ترین state تشخیصی را پاک کند.

Before reboot:
D-state:     high
I/O PSI:     ~97%
iowait:      ~100%
queues:      large
requests:    failing

After reboot:
D-state:     0
latency:     milliseconds
requests:    healthy

هر وقت availability و اثر تجاری اجازه دهد، اول UTC timestamp، PSI، vmstat، iostat، D-state، wchan، پیام‌های kernel، socket queue و request timing را ثبت می‌کنم و بعد recovery را انجام می‌دهم.

Server در حال اجرا بود؛ workload نه

هیچ‌وقت نفهمیدم کدام component در host علت نهایی incident بود. نمی‌توانم بگویم یک SSD خاص خراب بوده، یک storage node مشخص را نام ببرم یا ثابت کنم پشت virtual block device چه اتفاقی افتاده است.

اما آنچه از داخل Linux می‌توانستم ثابت کنم کافی بود:

read latency:       up to 18.7 s
flush latency:      up to 53.6 s
I/O PSI full:       almost 100%
iowait:             almost 100%
I/O queue:          128+
Nginx:              blocked in filesystem reads
EXT4/jbd2:          blocked waiting for I/O
direct backend:     ~3 ms
HTTP through Nginx: timing out

همین برای جداکردن application از لایه مشکل‌دار و گرفتن یک تصمیم عملیاتی کافی بود. FDCServers مبلغ VPS را برگرداند، من ادامه دادم و این incident سخت را حکم دائمی درباره provider نمی‌دانم.

آنچه برایم ماند مهم‌تر بود: process می‌تواند running باشد، service می‌تواند active باشد، VM می‌تواند online باشد و ping هم کار کند، در حالی که machine تقریباً هیچ کار مفیدی تکمیل نمی‌کند.

Linux برای دیدن این تفاوت evidence کافی می‌دهد؛ فقط باید وقتی failure هنوز وجود دارد سؤال‌های درست را بپرسید.