Extended Event on Azure
לפני זמן מה, אחד המפתחים אצלנו התלונן על איטיות בהפעלת פקודת bulk insert בבסיס נתונים שנמצא על Azure (תצורת PaaS).
כדי לבדוק את האטיות החלטתי להפעיל extended event session, שיראה את הwait statistics של כל תהליך שמריץ את הפקודה BULK INSERT. לרוב, אני מפעיל את הextended events ונותן לו לכתוב לקובץ ולא לזיכרון (בכתיבה לזיכרון יש באג, שגורם לכך שחלק מהנתונים "מועלמים" ע"י השרת ללא מתן הודעת שגיאה או אזהרה. ניתן לקרוא על הבאג הזה בעברית כאן, ובאנגלית כאן). הפעם בגלל שמדובר על שרת Azure, שכתיבה לדיסק לא אפשרית, וכתיבה לblob storage קצת יותר מסובכת, התעצלתי וכתבתי לring buffer. הגדרת הsession נראתה כך:
CREATE EVENT SESSION [WaitStats] ON DATABASE
ADD EVENT sqlos.wait_info(
ACTION(sqlserver.sql_text)
WHERE ([sqlserver].[like_i_sql_unicode_string]([sqlserver].[sql_text],N'%BULK%') AND Duration > 0))
ADD TARGET package0.ring_buffer
GO
בערך 20 דקות אחרי הפעלת הextended event session, השרת התרסק. לא ניתן היה להתחבר אליו. ופתחנו קריאה במייקרוסופט. לאחר יום, הופתענו לשמוע מהם שכניראה השרת התרסק בגלל הפעלת extended event. הם שאלו אם אפשר לשלוח להם את ההגדרה של הextended event session. שלחתי להם את ההגדרה. לאחר יום נוסף, הם הודיעו לנו שבוודאות הextended event session שלנו הפיל את השרת.
שלחו לי הגדרה אחרת וביקשו שבפעם הבאה נשתמש בה. ההגדרה שהם שלחו נראית כך:
CREATE EVENT SESSION [WaitStats] ON DATABASE
ADD EVENT sqlos.wait_info(
ACTION(sqlserver.sql_text)
WHERE (Duration > 0))
ADD TARGET package0.ring_buffer
GO
ניתן להבחין, שהם פשוט הורידו את התנאי שבודק שהפרוסס מריץ את הפקודה BULK INSERT (או יותר נכון שבתוך הפקודה מופיע צירוף האותיות BULK). לטענתם צריך להריץ את הבדיקה של הפקודה במשפט select שעובר על הXML, שהextended event יוצר, ושם לסנן את הנתונים שמעניינים אותנו. זה נשמע לא הגיוני. בדרך שלהם אני אוסף הרבה יותר נתונים. בדרך שלי לעומת זאת אני אוסף רק את הנתונים שמעניינים אותי. ביקשנו מהם הסבר למה הדרך שאמורה לקחת פחות משאבים מהשרת מפילה אותו לעומת הדרך שלוקחת הרבה יותר משאבים מהשרת ולא מפילה אותו. לצערי לא קיבלנו תשובה מפורטת. הדבר היחיד שהם אמרו לנו זה שהevent הספציפי wait_info, הוא יוצא דופן, והדרך שלי גורמת לו לרקורסיות אינסופיות, שבסופו של דבר מפילות את השרת. למטה אני מצרף ציטוט מהמייל שבו הם נתנו לנו תשובות (מאד חלקיות לצערי):
Please find the clarifications you are looking for… let me know if you need any other details on this.
1. Why the predicate should be moved out?
Short answer is we cannot use blocking predicate (like predicate in this case) with wait_info xevent. This is not allowed. This will lead to infinite recursion in publishing wait_info xevent and will cause this issue. We moved the predicate out from event session so that we don’t do like predicate evaluation while xevent is being published.
2. Does this apply to all events?
It does not apply to all events. Not that we are aware of. This wait_info event is special as we are publishing while we are going into wait.
3. Any specific conditions/criteria, customer would need to ensure that these (applies to all events) don’t recur again?
The safest would be to not use predicate in xevent session because it might be blocking operation – especially string predicate. In this case, since “like” predicate is the problem, we only moved that predicate out from xevent session.
ששאלנו אותם מה זה blocking predicate, אבל לא הצלחנו לקבל תשובה. שורה תחתונה – נאלצתי לשנות את הדרך שאני עובד עם extended events ובמידה שאני עובד עם wait_info event, לא לסנן לפי פקודה.
מקווה שזה ימנע מכם להפיל שרת...
