לקחת את הביצועים ברצינות, בעזרת MySQL Performance Schema

פוסטים בסדרה:
"תסביר לי" - גרסת ה SQL
לקחת את הביצועים ברצינות, בעזרת MySQL Performance Schema
נושאים מתקדמים ב MySQL: חלק א' - עבודה עם JSON
נושאים מתקדמים ב MySQL: חלק ב' - json_each  ו Generated Columns

נושאים מתקדמים ב MySQL: חלק ג׳ - מנועי אחסון, ומבנה האינדקסים
----

טוב. בפוסט הקודם דיברנו על Explain, הפקודה שמציגה לנו את תוכנית ההרצה של שאילתה נבחרת.

איך יודעים אלו שאילתות רצות לאט?

הדרך הנפוצה ביותר היא בעזרת ה slow-log.

MySQL slow Query Log

• בכדי להפעיל אותו יש לקבוע 1 בפרמטר slow_query_log. הוא ירשום כל שאילתה שארכה יותר מ 10 שניות.
  
• ניתן לקבוע סף אחר בעזרת הפרמטר long_query_time, בו ניתן לקבוע גם ערכים שאינם מספרים שלמים, למשל "0.6".
• אם תקבעו בפרמטר ערך של 0 - סביר להניח שכתיבה ללוג תהיה החלק האטי במערכת שלכם 😀.
• שינוי הפרמטר ישפיע רק על connections חדשים ל DB, כך שאם שיניתם את הערך ושרת סורר מחזיק חיבורים פתוחים בעזרת ה connection pool שלו, שאילתות שעמודות בסף החדש שנקבע - לא ירשמו ללוג.
• בכדי לשלוף ערכים מה slow log פשוט בצעו שאילתה על הטבלה mysql.slow_log.
• למשל: SELECT * FROM mysql.slow_log ORDER BY start_time DESC limit 50;
• אני לא זוכר מה הם ערכי ברירת המחדל, ייתכן וצריך לשנות עוד קונפיגורציה בכדי שהלוג ייכתב לטבלה.

התוצאה נראית כך:

• user_host (הסתרתי את כתובות ה IP) - עוזר להבין איזה צרכן יצר את השאילתה. זה חשוב ב DB מונולטיים - המשרתים צרכנים רבים ומגוונים.
• lock_time (בשניות) - הזמן בו ממתינים ל"תפיסת מנעול" על מנת להתחיל ולהריץ את השאילתה. למשל: הטבלה נעולה ע"י פעולה אחרת.
• query_time (בשניות) - זמן הריצה הכולל. 
• הרצה עוקבת של אותה שאילתה אמורה להיות מהירה יותר - כאשר הנתונים טעונים כבר ל buffer pool.
• כמובן שגם השפעות חיצוניות שונות (שאילתות אחרות שרצות ברקע ומתחרות על משאבי ה DB Server) - ישפיעו על זמני הריצה. אני לא מכיר דרך פשוטה להוסיף מדדים כמו cpu ו/או disk_queue_depth לשאילתה, בכדי לקשר את זמני הביצוע שלה למה שהתרחש ב DB Server באותו הרגע.
• מספר שורות שנשלח / נסרק - בשונה מפקודת ה Explain, זהו המספר בפועל ולא הערכה. 
• ייתכנו מקרים בהם Explain יעריך תוכנית אחת - אך ה slow log יראה שבוצע משהו אחר (יקר יותר) בפועל. זה עלול לקרות.

• db - שם בסיס הנתונים (= סכמה) שבה בוצעה השאילתה. 
• למשל, אני יכול לבחור לפלטר את הסכמה של redash - כי רצות שהם הרבה שאילתות אטיות, וזה בסדר מבחינתי.

שווה עוד לציין ששאילתות שלא משתמשות באינדקסים - אינן נרשמות ל slow_log כהתנהגות ברירת-מחדל. אפשר לשנות זאת בעזרת הפרמטר log_queries_not_using_indexes. ייתכן ויהיה שווה גם לקבוע ערך בפרמטר log_throttle_queries_not_using_indexes - כדי שלא תוצפו.

ה Performance Schema

אפשרות מודרנית יותר לאתר שאילתות אטיות היא על בסיס ה Performance Schema (בקיצור: ps)

מאז MySQL 5.6 ה ps מופעלת כברירת מחדל, אבל אם אתם רצים על AWS RDS - יהיה עליכם להדליק אותה ולבצע restart לשרת, לפני שתוכלו להשתמש בה.

השאילתה ה"קצרה" לשלוף נתונים של שאילתות אטיות מה ps היא:

SELECT * FROM sys.statements_with_runtimes_in_95th_percentile; 

שאילתה זו מציגה את 5% השאילתות האטיות ביותר, ללא קשר כמה זמן אבסולוטית הן ארכו (סף שניות כזה או אחר).

אתם שמים לב, בוודאי, שאנו קוראים ל system_schema  (השימוש ב FROM sys) ולא ל ps (השימוש ב FROM performance_schema).
ה ps חושפת כמות אדירה של נתונים (+ כמות גדולה של קונפיגורציה מה לאסוף ובאיזו רזולוציה) - מה שמקשה על השימוש בה עבור רוב המשתמשים.
ה system schema משמשת כשכבת הפשטה המציגה רשימה של views המרכזים מידע מתוך ה ps (וכמה מקומות אחרים) - ומנגישים את המידע המורכב למשתמש הפשוט.

נ.ב. -  על גרסה שהותקנה כ 5.7 ה system schema מגיעה כברירת-מחדל. על גרסאות ישנות יותר - ייתכן ותצטרכו להתקין אותה.

הנה תוצאה לדוגמה:

ספציפית, עניין שמציק לי הוא שבראש הטבלה נמצאת שאילתה, שאמנם לקחה כ 4 דקות לרוץ - אך התרחשה רק פעם אחת. בכלל: בראש הטבלה מככבות הרבה שאילתות שאינן מעניינות כי הן רצו פעמים בודדות בלבד. שירוצו.

יותר מעניין אותי למצוא שאילתה שגרמה להכנסה של כמיליון רשומות לאחת הטבלאות, לאורך 5 שעות שרת, גם אם כל מופע של השאילתה אורך 15 מילישניות בלבד. שאילתה כזו - לעולם לא תכנס ל slow log.

נ.ב: לא לדאוג לגבי "5 שעות שרת", גם בהינתן שזה מידע של כשבוע: השרת מריץ הרבה שאילתות במקביל. הנתונים הנ״ל נלקחו משרת שפועל בעצימות נמוכה יחסית.


את המידע הזה אני שולף בעזרת השאילתה הבאה:

SELECT `schema_name` AS db, 
       digest_text AS query, 
       IF (( ( `stmts`.`sum_no_good_index_used` > 0 ) 
         OR ( `stmts`.`sum_no_index_used` > 0 ) ), '*', '') AS `full_scan`, 
       Format(count_star, 0) AS events_count, 
       sys.Format_time(sum_timer_wait) AS total_latency, 
       sys.Format_time(avg_timer_wait) AS avg_latency, 
       sys.Format_time(max_timer_wait) AS max_latency, 
       Format(sum_rows_examined, 0) AS rows_scanned_sum, 
       Format(Round(Ifnull(( `stmts`.`sum_rows_examined` / 
         Nullif(`stmts`.`count_star`, 0) ), 0), 0), 0) AS `rows_scanned_avg`, 
       Format(Round(Ifnull(( `stmts`.`sum_rows_sent` / 
         Nullif(`stmts`.`count_star`, 0) ), 0), 0), 0) AS `rows_sent_avg`, 
       Format(sum_no_index_used, 0) AS rows_no_index_sum, 
       last_seen, 
       digest 
FROM   performance_schema.events_statements_summary_by_digest AS `stmts` 
WHERE  last_seen > ( Curdate() - INTERVAL 15 day ) 
ORDER  BY sum_timer_wait DESC; 

השאילתה הזו ממיינת את התוצאה ע"פ sum_timer_wait, כלומר - זמן ההמתנה הכולל לכל המופעים של אותה השאילתה.

השאילתה הנ״ל תשמיט מהתוצאה שאילתות שלא נראו מופעים שלהן ב 15 הימים האחרונים. מה שנפתר / השתנה - כבר לא מעניין.

ניתוח ריצה של שאילתות

שלב הבא אחרי איתור שאילתה בעייתית הוא הרצה שלה, עם Explain וכלים נוספים.

כלי שימושי במיוחד של ה ps הוא הפרוצדורה trace_statement_digest. אנו מעתיקים את תוצאת ה digest (זיהוי ייחודי לדפוס של query) מתוך העמודה האחרונה של השאילתה הנ״ל, ומעתיקים אותה לתוך הביטוי הבא:

CALL sys.ps_trace_statement_digest('1149...405b', 60, 0.1, TRUE, TRUE); 

הפרוצדורה הזו תדגום עכשיו את בסיס הנתונים לאורך 60 שניות, כל עשירית שניה, ותאסוף נתוני-ריצה על השאילתה המדוברת. זהו כנראה הכלי הפשוט והמקיף ביותר לאסוף מידע על הרצה בפועל של שאילתה.

שימו לב שאתם זקוקים להרשאות אדמין בכדי להריץ את הפונקציה.


אם אין לכם הרשאות אדמין, הנה כלים נוספים שניתן להפעיל:

ראשית יש את ה optimizer trace שניתן להפעיל על שאילתה בודדת.

-- Turn tracing on (it's off by default):
SET optimizer_trace="enabled=on";

SELECT ...; -- your query here

SELECT * FROM information_schema.optimizer_trace;

ה Optimizer trace מספק לנו פירוט דיי מדוקדק של אלו החלטות לקח ה optimizer בעת הרצת השאילתה. התיאור הוא של מה שקרה בפועל (ולא הערכה) אם כי גם ביצוע בפועל מבוסס על הערכות (למשל: סטטיסטיקות של טבלאות) שעשויות להיות מוטעות.

ה trace ממש מציג את שלבי ההחלטה השונים של ה optimizer, איזה מידע ואלו אופציות עמדו לפניו, במה הוא בחר - ולמה. הנה דוגמה לחתיכה מתוך ה trace:

אם זו איננה מכונת פיתוח, חשוב לזכור ולסגור את ה optimizer_trace, שיש לו תקורה לא מבוטלת:

SET optimizer_trace="enabled=off";

ה trace מספק את תהליך ההחלטות של הרצת השאילתה, אך לא זמנים בפועל. בכדי לקבל זמנים אנו משתמשים ב profile:

SET profiling = 1;             -- turn on profiling

SELECT ...;                    -- your query here

SHOW profiles;                 -- list profiled queries

SHOW profile cpu FOR query 12; -- place the proper query_id

בדרך ל profile הנכסף עליכם להפעיל את איסוף ה profiling, לבצע את השאילתה, לראות את השאילתות שנאספו - ולבחור את המספר השאילתה שלכם. התוצאה נראית כך:

"מה?? כמעט 5 שניות על שליחת נתונים בחזרה ללקוח? - אני מתקשר להוט!"

כמובן שכדאי גם לבדוק מה המשמעות של כל שורה. sending data כולל את קריאת הנתונים מהדיסק, העיבוד שלהם, והשליחה חזרה ל client.

בד"כ ה Sending Data יהיה החלק הארי, ודווקא כאשר סעיף אחר תופס נפח משמעותי - יש משהו חדש ללמוד מזה.

נ.ב - ניתן לבצע profiling גם על בסיס ה ps - מה שאמור להיות מדויק יותר, ו customizable - אבל מעולם לא השתמשתי ביכול הזו.

לבסוף, אל תשכחו לסגור את איסוף ה profiling:

SET profiling = 0;  

עוד שאילתות שימושיות מתוך ה System Schema

הזכרנו את ה system schema, העוטפת את ה performance schema (ועוד קצת) בצורה נוחה יותר.

שווה להזכיר כמה שאילתות שימושיות:

SELECT * FROM sys.version; 

הצגת גרסה מדויקת של שרת בסיס הנתונים, מתוך ממשק ה SQL.

SELECT * FROM sys.schema_tables_with_full_table_scans;

הצגה של רשימת הטבלאות שסרקו בהן את כל הרשמות כחלק משאילתה.

SELECT * FROM sys.schema_table_statistics;

SELECT * FROM sys.schema_index_statistics;

פרטים על הטבלאות והאינדקסים השונים - כמה ״עובד״ כל אחד.

SELECT * FROM sys.schema_unused_indexes;

SELECT * FROM sys.schema_redundant_indexes;

דרך טובה למצוא אינדקסים לא נחוצים.
אינדקסים מיותרים גורמים להכנסות (insert/update) להיות אטיות יותר - כי צריך לעדכן גם את האינדקס.

SELECT * FROM sys.statements_with_errors_or_warnings;

SELECT * FROM sys.statements_with_temp_tables;

עוד נתונים שכדאי להסתכל עליהם מדי-פעם.

SELECT * FROM sys.io_global_by_wait_by_latency;

SELECT * FROM sys.io_global_by_file_by_latency;

אחרון חביב, שאילתות אלו יעזרו לכם לאתר עבודה בלתי צפויה שבסיס הנתונים עושה.
מישהו פתח איזה לוג כבד, ושכח לסגור אותו?

בסיס נתונים מונוליטי

אתם בוודאי מכירים את המצב בו שרת בסיס נתונים אחד מריץ loads שונים ושונים של עבודה.
בד"כ זה יהיה בסיס נתונים של מערכת מונוליטית, שמשמש גם לעבודות BI כאלו או אחרות (הוא מונוליטי, וכל הנתונים נמצאים בו - למה להשתמש במערכת אחרת?)

בבסיס נתונים מונוליטי יש מגוון רחב של workloads שרצים במקביל. כאשר בסיס הנתונים מתחיל להתנהג בצורה לא יפה (הרבה CPU, וגמגומים) - אנחנו מנסים לאתר מי מכל המשתמשים הרבים והמגוונים של בסיס הנתונים יוצר את העומס החריג. הרבה פעמים נוכל להרוג תהליך אחד (בשאיפה: לא mission critical) - ולייצב את שרת בסיס הנתונים.

כלי העבודה הבסיסי הוא השאילתה הזו:

SELECT * FROM sys.session ORDER BY command;

היא דרך טובה לדעת מי עושה מה. זוהי "גרסה משופרת" של השאילתה SHOW PROCESSLIST.
כעת נוכל לראות אלו משתמשים גורמים לעומס הרב ביותר / עומס חריג - ונתחיל לנטר אותם:

SELECT * FROM sys.user_summary;

היא שאילתה שתספק בזריזות כמה ואיזה סוג יוצר כל משתמש לבסיס הנתונים (שורה לכל משתמש). אפשר להשוות את הנתון הזה ל session data בכדי לזהות מי מתנהג בצורה חריגה כרגע.
באופן דומה, השאילתות הבאות יספקו לנו קצת יותר drill down:

SELECT * FROM sys.user_summary_by_statement_type;

SELECT * FROM sys.user_summary_by_statement_latency;

SELECT * FROM performance_schema.user_variables_by_thread;

מכאן ייתכן ונרצה לפרק את העבודה לרמת ה thread של בסיס הנתונים. אולי שרת ספציפי של האפליקציה גורם לעומס החריג?

SELECT * FROM sys.io_by_thread_by_latency;

לא מוצאים את השאילתה?

מדי פעם קורא שאני מוצא שאילתות בעייתיות בעזרת ה ps, אבל מכיוון שיש ? במקום פרמטרים - קשה לי להשלים את הערכים כך שהשאילתה תחזיק תוצאות.
וריאציה אחרת: הקוד שלי שולח שאילתות ואני רוצה לראות מה בדיוק הוא שולח.

יש כנראה דרכים מתוחכמות יותר לעשות זאת, אך אני פשוט משתמש ב  general log:

SET global general_log = 'ON';

SELECT ...; -- your query here

SELECT *
FROM mysql.general_log
WHERE argument LIKE '/*%'
AND event_time >= ( Curdate() - INTERVAL 5 minute )
ORDER BY event_time DESC 

LIMIT 50;

SET global general_log = 'OFF';

ה General Log יותר overhead כבד למדי על בסיס הנתונים, ולכן אם מדובר בסביבת production - אני מפעיל אותו לזמן קצר בלבד (בעזרת 'general_log = 'ON/OFF). על סביבת הפיתוח אני יכול לעבוד כשהוא דלוק כל הזמן.

נ.ב. גם כאן, ייתכן ותצטרכו לכוון את כתיבת הנתונים לטבלה בעזרת:

SET global log_output = 'FILE,TABLE'; 

מכיוון שה framework שאני עובד איתו, JDBI, מוסיף לשאילות מזהה המופיע כהערה בתחילת השאילתה "/* comment */" - הוספתי תנאי המסנן את הלוג לשאילות בהם מופיעה הערה (להלן ...argument LIKE).


שיהיה בהצלחה!