وقایع نگاری یک دیباگ: وضعیت عجیب MongoDB

استفاده از Mongo و Python برای ایجاد یک RESTFUL API دیگر آن‌چنان هم سناریوی دور از انتظاری نیست، خصوصا این که اگر کمی جستجو کنید می‌بینید که افراد زیادی اشاره به پایداری و Performance همچین استکی می‌کنند و راه‌کار‌های بسیار زیادی نیز برای بهتر کردن آن ارائه کرده‌اند. در یکی از پروژه‌های تیم فاندرز ما هم با استکی به شرح زیر، RESTFUL API مربوط به اپلیکیشمان را طراحی‌کرده‌ایم:

• Mongo
• Python 3
• PyMongo
• Django
• Memcached
• uWsgi
• Nginx

در چهار ماه اول لانچ API، هیچ مشکلی در داده‌های دریافتی و پردازش‌های مورد نیاز مشاهده نمی‌شد. Performance کلی استک هم در حد قابل قبولی جواب‌گوی نیاز‌ها بود. تا این که با تغییری در نحوهٔ ارائهٔ خدمات پروژهٔ اصلی‌، حجم کاربران سرویس به نحو چشم‌گیری بالا رفت و ماجرا آغاز شد!

مشکل ایجاد شده‌، نه در Performance سیستم بود و نه حتی می‌توان گفت که پایداری API زیر سوال رفته بود. قضیه از این قرار بود که درخواست‌هایی که منجر به خواندن داده از پایگاه دادهٔ سرویس بود‌ (Mongo) در زمان‌های خاصی از روز‌ (که عمدتا تایم شلوغی برای پروژه بود) تنها تکه‌ای از داده‌های مورد انتظار را بر می‌گرداندند. برای مثال اگر ما انتظار داشتیم که کوئری X روی دیتابیس‌، شامل ۲۰ سند (Document منظور آبجکت‌های دیتابیس Mongo است) باشد‌، بعضی از درخواست‌ها نتیجه‌ای در بازه‌ای کوچکتر از ۲۰ را بر می‌گرداند.

قضیه جایی بحرانی می‌شد که این نتیجه را برای یک بازهٔ زمانی مشخص Cache می‌کردیم، و خوب در صورت خراب شدن یکی از این کوئری‌ها‌، کاربران در آن مدت‌، نتیجهٔ ناقص را مشاهده می‌کردند. جدای از این، هیچ ضعف مشخصی از سیستم برای تراکنش‌ها مشاهده نمی‌شد.

حدس اولیه می‌توانست خود سیستم کش (Memcached) باشد. ولی همانطور که اگر با Mongo کار کرده باشید می‌دانید‌، داده‌ها در این دیتابیس به صورت JSON ذخیره می‌شوند‌، و ما حتی در نتایج ناقص دریافتی‌، هیچ سند ناقصی نمی‌دیدیم. نتایجی که نهایتا توسط Django به صورت JSON سرو می‌شدند هم کاملا ولید بودند. از طرف دیگر‌، وقتی سعی می‌کردیم با اجرای متد ‎.count()‎‍ روی Cursor دریافتی از Mongo نتایج دریافت شده را بسنجیم‌، نتایع دقیقا همان مشکلی را داشتند که ما در خروجی JSON جانگو می‌دیدیم.

پس از مدتی جستجو و نیافتن نتیجهٔ خاصی‌، سعی کردیم بتوانیم مشکل را باز تولید کنیم تا شاید با بررسی لاگ‌ها بتوانیم‌، علت آن را پیدا کنیم. امیر یکی از اعضای پروژه‌، با پایتون اسکریپتی نوشت که به صورت Multithread ریکوئست‌هایی را به سمت Endpoint‌هایی که این مشکل را در آن‌ها مشاهده کرده بودیم ارسال کند تا شاید مشکل سریع‌تر بروز کند. ساختار کلی این اسکریپت بسیار ساده بود‌، و درست یا اشتباه بودن نتایج را با استفاده از Parse کردن نتیجهٔ JSON دریافتی‌، شمارش تعداد آبجکت‌ها و مقایسه با نتیجهٔ مورد نظر انجام می‌داد.(بدیهی است که در زمان بررسی دیگر از Cache استفاده نمی‌کردیم :))

هر بار که اسکریپت را اجرا می‌کردیم، چیزی حدود ۳-۴ ساعت زمان لازم بود تا اولین نتایج اشتباه را دریافت کنیم. و بعد از اولین مشاهدهٔ نتایج اشتباه‌، به سرعت تعداد این نتایج زیاد می‌شد تا این که ۸۰٪ نتایج دریافتی را شامل می‌شد. یعنی ۳ ساعت هیچ مشکلی نداشتیم‌، بعد در عرض ۱۰ دقیقه‌، ۸۰٪ نتایج ناقص می‌شدند. حالا این وضعیت را چطور رفع کنیم؟‌ کافی بود uWSGI را ری استارت کنیم‌، تا برای یک مدت طولانی دیگر، نتایج کاملا درست بگیریم.

این قضیه ری‌استارت کردن uWSGI باعث شد‌، به پروسه‌های اجرا شده توسط آن مشکوک شویم. پس سعی کردیم مشکل را در تنظیمات uWSGI پیدا کنیم. یکسری تغییرات مثل کم کردن تعداد پروسه‌های در حال اجرا‌ و یا respawn کردن پروسه‌ها بعد از ۵۰۰۰ درخواست‌، نتایج را کمی بهتر کرد. ولی باز هم بعد از گذشت چیزی در حدود ۸ ساعت‌، مشکل را مشاهده می‌کردیم.

حتی در اقدامی‌، که بعد از بررسی دقیق کد‌های PyMongo توسط امیر رخ داد‌، سعی کردیم به طور مستقیم Cursorهای دریافتی PyMongo را هر کجای کد که دیگر نیازی بهشان نداریم close()‎ کنیم. یا همانطور که در مستندات PyMongo اشاره شده‌، تنها از یک MongoClient در سراسر کد استفاده کنیم تا خود درایور بتواند به درستی Thread safety کوئری‌های را فراهم کند. نتیجه این شد که یک بار در یک بازهٔ طولانی ۴۸ ساعته‌، هیچ مشکلی در سیستم ندیدیم و بعد‌، دوباره، روز از نو…

در این مرحله سعی کردیم مساله را جمع‌بندی کنیم و از دیگران راهنمایی بگیریم. طرح مساله در Stackoverflow ، چند گروه ایمیلی‌، تماس مستقیم با اشخاص مطلع در این خصوص و حتی مشاوره اسکایپی با یک نفر که از Hackhands پیدا کرده بودیم، از جملهٔ این درخواست راهنمایی‌ها بود. نتیجه؟ خوب نتایج در نوع خودشان عالی بودند:

1. بعضی‌ها مشکل را درست درک نمی‌کردند و خوب طبیعی بود‌، چون اگر این مشکل آن‌چنان فراگیر بود‌، مطمئنا منابع زیادی می‌شد در خصوصش روی اینترنت پیدا کرد.
2. بعضی‌ها که در واقع جزء با مرام‌های دستهٔ اول بودند‌، سعی می‌کردند بهمان نشان بدهند که اگر خودشان در این موقعیت گیر می‌کردند‌، از چه روش‌هایی برای دیباگ کردن قضیه استفاده می‌کردند.
3. بعضی‌ها می‌گفتند‌، کلا استفاده از Mongo اشتباه است و کاش MySQL بود (نه باور کنید دقیقا همین جایگزین). یا چه می‌دانم‌، پایتون؟ نه آقا شوخی نکنید‌، فقط Nodejs جواب مساله است.

کمک‌های دستهٔ دوم‌، بسیار ارزشمند بود‌، خصوصا این که برای جاهای مختلف استک‌، با یک دوجین ابزار دیباگ مختلف آشنایمان کرد که حداقل نه برای پیدا کردن جواب مساله‌، ولی برای تست تئوری‌های‌مان بسیار کمک کننده بود.

ولی راهنمایی‌های دستهٔ سوم که شامل تغییر یکی از اعضای استک‌، بدون دانستن این که مشکل به وجود آمده در کجای استک رخ داده‌، جدای از این که تایم زیادی می‌خواست و معلوم نبود بتواند مشکل را به صورت ۱۰۰٪ حل کند‌، نمی‌توانست حس کنجکاوی دولوپر‌های تیم را ارضا کند. بماند که به قولی تغییر صورت مساله بود و رسما در فرهنگ لغت اشکان (لیدر تیم) جایی ندارد :)

نا امید از این که نتوانسته بودیم حتی یک اشارهٔ کوچک در رابطه با این که مشکل اصلی کجای استک دارد رخ می‌دهد پیدا کنیم‌، سعی کردیم‌، سرویس را روی سرور ضعیف‌تری که داشتیم اجرا کنیم و وضعیت را روی آن بررسی کنیم. با این تفاوت که کلیه کانفیگ‌ها را خودمان انجام داده‌ایم و از ریز به ریز جزئیات تراکنش‌ها می‌توانیم در یک محیط ایزوله‌تر لاگ بگیریم. نتیجه؟ در بیشترین فشار ممکن‌، حتی یک نتیجهٔ ناقص هم دریافت نکردیم! CPU این سرور فوق‌العاده ضعیف‌تر بود و تعداد پروسه‌ها برابر با سرور اصلی. اما هیچ نتیجهٔ ناقصی نمی‌دیدیم!

این در حالی بود که حتی با خارج کرد uWSGI از استک و اجرای سرویس با سرور توسعهٔ Django، بعد از ۱۰-۱۲ ساعت‌، مشکل را مشاهده می‌کردیم. پس از جستجوی بیشتر حقیقتش دیگر داشتیم کم کم راضی می‌شدیم که به نصایح دسته سومی‌ها عمل کنیم! چرا که سرویس دیگری برای همین پروژه‌، روی همان سرور که دقیقا از همین Mongo دیتا را می‌خواند‌، ولی با یک کش بسیار بلند‌تر ارائه می‌کرد‌، در این مدت داشت مثل ساعت کار می‌کرد.

به عنوان آخرین امید‌، سعی کردیم تیکتی در باب مطرح کردن مشکل روی Issue tracker پروژهٔ‌درایور پایتون Mongo، باز کنیم تا شاید نتیجه‌ای بگیریم. Bernie Hackett توسعه دهندهٔ اصلی درایور به کارت اساین شد و انصافا‌، خیلی خوب و با صبر‌، پیگیری مساله را انجام می‌داد.

حالا دیگر تایم زیادی از مواجهه به مشکل گذشته بود‌ و کاربران پروژه‌، چندین برابر قبل بود. دیگر به جایی رسیده بودیم که حتی بدون کش هم بسیاری از ریکوئست‌ها خراب بود. در بین بحث‌ها Hackett به نکته‌ای اشاره کرد که می‌توانست جواب مساله باشد… البته با چیز‌هایی که از مستندات دیده بودیم و قولی که برای Thread safe بودن مونگو می‌داد‌، بیشتر تیری در تاریکی بود.

قضیه از این قرار است که PyMongo، خصوصا در نسخهٔ ۳ به بعد‌، دیگر آبجکت Cursor را به جای یک آبجکت پایتونی استاندارد‌، برای نتایج کوئری بر می‌گرداند. طوری که Hackett در تیکت اشاره کرده‌، هر باری که به قولی کلیهٔ عناصر این Cursor، پیمایش (Iterate) شوند‌، آبجکت Cursor بسته می‌شود. ما هم تا به الان قضیه دیده‌ایم که نتایج Cursorها کمتر از میزان مورد انتظار ما هستند، ولی نمی‌دانیم دقیقا این نتایج از کجا می‌آیند. اول لیست؟ آخرش؟ آن وسط مسط‌ها؟

این بود که سعی کردیم بی‌خیال کل استک شویم و جور دیگری قضیه را تست کنیم.

res = collection.find({'key': 'STH'})
a_test = [x for x in res]
len(a_test)
>> 25

b_test = [x for x in res]
len(b_test)
>> 0

همانطور که انتظار داشتیم‌، بعد از بار اول، دیگر Cursor خالی شده و نتیجه‌ای را در بر نمی‌گیرد. حالا یک کمی قضیه را عوض می‌کنیم:

res = collection.find({'key': 'STH'})
first_elem = res.next()

all_elems = [x for x in res]
len(all_elems)
>> 24

حالا می‌دانیم اگر قبل از شروع پیمایش‌، یک بار متد next()‎ را صدا کنیم‌، زمان فراخوانی پیمایش‌، آیتم اول دیگر در نتیجه وجود نخواهد داشت! چه می‌شود اگر همین Cursor را تحویل چند Thread مختلف بدهیم؟

<pymongo.cursor.Cursor object at 0x7f6aac5ad8d0> 0 15
<pymongo.cursor.Cursor object at 0x7f6aac5ad8d0> 1 15
<pymongo.cursor.Cursor object at 0x7f6aac5ad8d0> 2 0
<pymongo.cursor.Cursor object at 0x7f6aac5ad8d0> 3 0
<pymongo.cursor.Cursor object at 0x7f6aac5ad8d0> 4 0
<pymongo.cursor.Cursor object at 0x7f6aac5ad8d0> 5 0
<pymongo.cursor.Cursor object at 0x7f6aac5ad8d0> 6 0
<pymongo.cursor.Cursor object at 0x7f6aac5ad8d0> 7 0
<pymongo.cursor.Cursor object at 0x7f6aac5ad8d0> 8 0
<pymongo.cursor.Cursor object at 0x7f6aac5ad8d0> 9 0
[31/Oct/2015 19:30:43]"GET /v1/apps/featured/ HTTP/1.1" 200 34652
<pymongo.cursor.Cursor object at 0x7f6aac5ad668> 0 15
<pymongo.cursor.Cursor object at 0x7f6aac5ad668> 1 0
<pymongo.cursor.Cursor object at 0x7f6aac5ad668> 2 0
<pymongo.cursor.Cursor object at 0x7f6aac5ad668> 3 0
<pymongo.cursor.Cursor object at 0x7f6aac5ad668> 4 0
<pymongo.cursor.Cursor object at 0x7f6aac5ad668> 5 0
<pymongo.cursor.Cursor object at 0x7f6aac5ad668> 6 0
<pymongo.cursor.Cursor object at 0x7f6aac5ad668> 7 0
<pymongo.cursor.Cursor object at 0x7f6aac5ad668> 8 0
<pymongo.cursor.Cursor object at 0x7f6aac5ad668> 9 0
[31/Oct/2015 19:30:44]"GET /v1/apps/featured/ HTTP/1.1" 200 34652
<pymongo.cursor.Cursor object at 0x7f6aac5a5320> 0 15
<pymongo.cursor.Cursor object at 0x7f6aac5a5320> 1 15
<pymongo.cursor.Cursor object at 0x7f6aac5a5320> 3 0
<pymongo.cursor.Cursor object at 0x7f6aac5a5320> 4 0
<pymongo.cursor.Cursor object at 0x7f6aac5a5320> 2 15
<pymongo.cursor.Cursor object at 0x7f6aac5a5320> 5 0
<pymongo.cursor.Cursor object at 0x7f6aac5a5320> 7 0
<pymongo.cursor.Cursor object at 0x7f6aac5a5320> 8 0
<pymongo.cursor.Cursor object at 0x7f6aac5a5320> 9 0
<pymongo.cursor.Cursor object at 0x7f6aac5a5320> 6 0
[31/Oct/2015 19:30:44]"GET /v1/apps/featured/ HTTP/1.1" 200 34652
<pymongo.cursor.Cursor object at 0x7f4153a28208> 0 15
<pymongo.cursor.Cursor object at 0x7f4153a28208> 4 0
<pymongo.cursor.Cursor object at 0x7f4153a28208> 1 15
<pymongo.cursor.Cursor object at 0x7f4153a28208> 5 0
<pymongo.cursor.Cursor object at 0x7f4153a28208> 6 0
<pymongo.cursor.Cursor object at 0x7f4153a28208> 3 15
<pymongo.cursor.Cursor object at 0x7f4153a28208> 8 0
<pymongo.cursor.Cursor object at 0x7f4153a28208> 9 0
<pymongo.cursor.Cursor object at 0x7f4153a28208> 7 0
[31/Oct/2015 19:20:44]"GET /v1/apps/featured/ HTTP/1.1" 200 34652

این نتیجهٔ اجرای ایده روی سیستم ضعیف من است. نتیجهٔ ناقص نمی‌بینیم‌، ولی در سه بار از فراخوانی‌ها‌، بیش از یک Thread به یک Cursor دسترسی پیدا کرده است! این مساله را می‌توان در یک مقیاس خیلی بزرگتر مثل سرور Production این پروژه و آن همه Thread، به نتایج ناقص هم ربط داد… این‌طور نیست؟ جواب A. Jesse Jiryu Davis توسعه دهندهٔ Motor (درایور پایتونی و async -بله پایتون هم از این کارها بلد است- :)) تایید همین مطلب است.

خوب چه کار کنیم؟‌ بیاییم، Cursorهایی که کلا Thread safe نیستند‌ را به یک آبجکت پایتونی Thread safe تبدیل کنیم. یک همچین پترنی شاید:

res = list(collection.find({'key': 'STH'}))

و انگار جواب مساله را پیدا کرده‌ایم. بماند که بعد از این که بار‌ها به در بسته خوردن سر این مساله، اعضای تیم را کمی بد‌بین کرده بود و تا دلشان خواست انتقامشان ر موقع تست تئوری جدید گرفتند (امیر حتی به Multithread پایتون هم رضایت نداد و یک نمونهٔ C++‎ هم از اسکریپت تستش نوشت)‌، API با یک Performance عالی‌، بدون هیچ مشکلی همهٔ تست‌ها را درست رد کرد.

نتیجه؟ یکی از طولانی‌ترین دیباگ‌هایی که تا به الان انجام داده‌ایم‌، به سادگی یک list()‎ قابل حل بود، ولی در این مسیر‌، طی تبادل نظرات‌، تست تئوری‌ها‌، بررسی‌های کلی استک‌، تجربه‌های زیادی کسب کردیم که نهایتا به بسیار بهتر شدن API نسبت به وضعیت قبل و نه تنها در رابطه با همین مساله منجر شد.