DMVs לבדיקת הפעילות בשרת: sys.dm_exec_query_stats, sys.dm_exec_procedure_stats, sys.dm_exec_cached_plans

24/09/2015

ניתן למצוא כאן רשימה של ה-DMVs השונים העוסקים בפעילות על השרת (מי עושה מה וכו’),
ואני אתמקד בשלושת אלו שבכותרת שעוסקים במה שמתבצע/התבצע, עם הדגש על “מה” ולא על “מי”.

דרך הקישור למעלה ניתן להגיע לתיעוד הרישמי של כל אחת משלוש הפונקציות הנ”ל, ובניסוח חופשי שלי ניתן לתאר את תפקידן כך:

  • sys.dm_exec_query_stats – הפקודות השונות שהתבצעו בשרת (פקודות כגון הרצת Select, ביצוע Update וכו’). הנתונים הם ברמת הפקודה, ומתייחסים לפקודות שנמצאות ב-Cache ושיש להן Plan.
  • sys.dm_exec_procedure_stats – הפרוצדורות השונות שב-Cache. כל פרוצדורה – שורה.
  • sys.dm_exec_cached_plans – התוכניות (Plans) השונות ב-Cache. משלימה את המידע שב-sys.dm_exec_query_stats במידע שמתייחס ל-Cache ולא לביצועי השרת.

השליפות השונות שניעזר בהן (זו “הצעת הגשה” וניתן על פי הצורך להוסיף או לגרוע עמודות ולשנות מיונים):

Select  Concat(DB_Name(IsNull(PSh.dbid,PSph.dbid)),'.'+Object_Schema_Name(PSh.ObjectId,IsNull(PSh.dbid,PSph.dbid)),'.'+Object_Name(PSh.ObjectId,IsNull(PSh.dbid,PSph.dbid))) ObjectName,

        SubString(text,statement_start_offset/2+Iif(statement_end_offset=-1,1,0),(Iif(statement_end_offset=-1,DataLength(text),statement_end_offset)-statement_start_offset)/2) SubText,

        ES.creation_time,

        ES.last_execution_time,

        ES.total_worker_time,

        ES.total_logical_writes,

        ES.total_logical_reads,

        ES.total_elapsed_time,

        ES.execution_count,

        PSh.text,

        PSph.query_plan

From    sys.dm_exec_query_stats ES

Outer Apply sys.dm_exec_sql_text(ES.sql_handle) PSh

Outer Apply sys.dm_exec_query_plan(ES.plan_handle) PSph

Where    DB_Name(IsNull(PSh.dbid,PSph.dbid))='tempdb'

        And PSh.text Not Like '%sys.dm_exec_sql_text%'

Order By ES.creation_time;

Go

 

Select  Concat(DB_Name(PSh.dbid),'.'+Object_Schema_Name(PSh.ObjectId,PSh.dbid),'.'+Object_Name(PSh.ObjectId,PSh.dbid)) ObjectName,

        PS.cached_time,

        PS.last_execution_time,

        PS.total_worker_time,

        PS.total_logical_writes,

        PS.total_logical_reads,

        PS.total_elapsed_time,

        PS.execution_count,

        PSh.text,

        PSph.query_plan

From    sys.dm_exec_procedure_stats PS

Outer Apply sys.dm_exec_sql_text(PS.sql_handle) PSh

Outer Apply sys.dm_exec_query_plan(PS.plan_handle) PSph

Where    DB_Name(PS.database_id)='tempdb'

        And PSh.text Not Like '%sys.dm_exec_sql_text%'

Order By PS.cached_time;

 

Select  Concat(DB_Name(IsNull(PSh.dbid,PSph.dbid)),'.'+Object_Schema_Name(PSh.objectid,IsNull(PSh.dbid,PSph.dbid)),'.'+Object_Name(PSh.objectid,IsNull(PSh.dbid,PSph.dbid))) ObjectName,

        CP.usecounts,

        CP.cacheobjtype,

        CP.objtype,

        PSh.text,

        PSph.query_plan

From    sys.dm_exec_cached_plans CP

Outer Apply sys.dm_exec_sql_text(CP.plan_handle) PSh

Outer Apply sys.dm_exec_query_plan(CP.plan_handle) PSph

Where    DB_Name(IsNull(PSh.dbid,PSph.dbid))='tempdb'

        And PSh.text Not Like '%sys.dm_exec_sql_text%'

Order By ObjectName;

בכולן הוספתי פילטר על דטבייס tempdb כי בו אבצע את כל הנסיונות להלן (בשימוש “אמיתי” יש להסירו),
ופילטר נוסף כדי לסנן את הרצות ה-DMVs עצמם (אפשר להשאיר)..
המיון הוא על פי מועד יצירת ה-Plan, אך אם רוצים לשפר ביצועים, אני מציע למיין מיון יורד לפי היחס שבין PS.total_logical_reads לזמן שעבר בדקות מאז שהאובייקט נוצר או קומפל ועלה ל-cache וכו’, וכך נוכל לראות מה המחיר לדקה (יש כאלו שקיימים כבר כמה חודשים ואחרים כמה דקות ולכן צריך לתקנן את זה ליחידת זמן), ולהתמקד ביקרים יותר. בהרבה דוגמאות ברשת הנטייה היא לחלק את הסה”כ במספר הריצות ולקבל מחיר לריצה (logical reads לריצה או worker time = CPU לריצה וכו’), אלא שיש פקודות שמופעלות לעיתים קרובות ואחרות שלא, ולדעתי עדיף על בסיס יחידת זמן.

מה נריץ? ניצור פרוצדורה אחת שתטחן קצת את המערכת (P1), שנייה שתפעיל מספר פעמים את הראשונה (P2) וגם תריץ כמה פקודות, ושלישית (P3) שתפעיל את השנייה ותריץ בנוסף כמה פקודות:

If Object_ID('P1','P') Is Not Null Drop Proc P1;

Go

Create Proc P1 As

Insert Into T Select * From sys.messages;

Insert Into S Select * From sys.all_columns;

Go

 

If Object_ID('P2','P') Is Not Null Drop Proc P2;

Go

Create Proc P2 @N Int=1 As

While    @N>0

        Begin

        Exec P1;

        Set    @N-=1;

        End

Insert Into T Select * From sys.messages;

Insert Into S Select * From sys.all_columns;

Go

 

If Object_ID('P3','P') Is Not Null Drop Proc P3;

Go

Create Proc P3 @N Int=1 As

Exec P2 @N;

Insert Into T Select * From sys.messages;

Insert Into S Select * From sys.all_columns;

Go

לפני כל הרצה ננקה את ה-Cache בעזרת DBCC FreeProcCache ו-DBCC DropCleanBuffers.

נסיון 1 – נריץ מספר פקודות כמו אלו שבפרוצדורה P1, אך לא במסגרת פרוצדורות, חלקן בתוך פקודת Exec וחלקן לא:

If Object_ID('tempdb..T','U') Is Not Null Drop Table T;

Select * Into T From sys.messages Where 1=0;

If Object_ID('tempdb..S','U') Is Not Null Drop Table S;

Select * Into S From sys.all_columns Where 1=0;

 

Set NoCount On;

 

DBCC FreeProcCache;

DBCC DropCleanBuffers;

Go

 

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff---------------------------------------------------------------------------------------------------------------');

Go

Insert Into T Select * From sys.messages;

Insert Into S Select * From sys.all_columns;

Go

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff---------------------------------------------------------------------------------------------------------------');

Go

Exec('Insert Into T Select * From sys.messages;

Insert Into S Select * From sys.all_columns;');

Go

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff---------------------------------------------------------------------------------------------------------------');

Go

Exec('Insert Into T Select * From sys.messages;

Insert Into S Select * From sys.all_columns;');

Go

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff---------------------------------------------------------------------------------------------------------------');

Go

Insert Into S Select * From sys.all_columns;

Go

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff---------------------------------------------------------------------------------------------------------------');

Go

בנוסף ליצירת טבלאות היעד ופקודות ה-DBCC לאתחול המערכת, אפשר לראות כאן 5 Batches המופרדים ב-Go וב-Print של הזמן:

  • שתי פקודות Insert
  • אותן שתי פקודות אך בתוך Exec (כלומר- SQL דינאמי)
  • כנ”ל (ה-SQL הדינאמי)
  • אחת משתי פקודות ה-Insert

image

קודם כל – sys.dm_exec_procedure_stats לא החזירה דבר, כי אף פרוצדורה אינה מעורבת בריצה.
ה-sys.dm_exec_query_stats החזיר 5 שורות (לעומת 3 שורות מה-sys.dm_exec_cached_plans):

  • שתי שורות עבור שתי הפקודות הראשונות
  • שתי שורות כנגד הפקודות שהורצו פעמיים כקוד דינאמי, ולכן ה-execution_count הוא 2 (זה שבעיגול גם היה אמור להיות 2, וכנראה נוצר plan חדש בפעם השניה מסיבה לא ברורה והמונה התאפס)
  • שורה אחת כנגד הפקודה האחרונה.

ניתן לראות מתי נוצרה כל תוכנית ב-Cache הודות לפקודות ה-Print בין ה-batches.
ב-sys.dm_exec_cached_plans ניתן לראות את 3 התוכניות שב-Cache והתאמתן ל-sys.dm_exec_query_stats.

נסיון 2- נריץ את P1 פעם אחת, את P2 עם פרמטר 2 (=פעמיים את P1), ואת P3 עם פרמטר 3 (=פעם אחת את P2 עם פרמטר 3, ו-3 פעמים את P1):

Set NoCount On;

 

DBCC FreeProcCache;

DBCC DropCleanBuffers;

Go

 

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff---------------------------------------------------------------------------------------------------------------');

Go

Exec P1;

Go

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff---------------------------------------------------------------------------------------------------------------');

Go

Exec P2 2;

Go

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff---------------------------------------------------------------------------------------------------------------');

Go

Exec P3 3;

Go

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff---------------------------------------------------------------------------------------------------------------');

Go

image

הפעם הפעלנו פרוצדורות, ולכן ניתן לראות את הסיכומים ברמת הפרוצדורה בחלק האמצעי של ה-sys.dm_exec_procedure_stats.
ברמת הפקודה, ניתן לראות בחלק העליון, שמ-sys.messages בוצעו 9 שליפות: 6 דרך P1, 2 דרך P2 ו-1 דרך P3, ושלושת ה-plans בוצעו בהרצה הראשונה של כל שליפה מכל פרוצדורה. מה שלא כל כך מסתדר הוא השליפות מ-sys.all_columns, וכנראה שבכל שליפה נוצר plan חדש, וכך בהפעלה של P3 הוא רץ פעם אחת, P2 רץ פעמיים, ו-P1 שלוש פעמים.

נסיון 3- ניצור ונריץ את רצף הפרוצדורות הבאות, וההסברים בהמשך לפלט:

Use tempdb;

 

If Object_ID('T_Messages','U') Is Not Null Drop Table T_Messages;

Select * Into T_Messages From sys.messages;

Go

 

If Object_ID('tempdb..T','U') Is Not Null Drop Table T;

Select * Into T From sys.messages Where 1=0;

Go

 

If Object_ID('P4','P') Is Not Null Drop Proc P4;

Go

Create Proc P4 With Recompile As

Insert Into T Select Top 1004 * From T_Messages;

Insert Into T Select Top 1004 * From T_Messages;

Go

 

If Object_ID('P5','P') Is Not Null Drop Proc P5;

Go

Create Proc P5 As

Insert Into T Select Top 1005 * From T_Messages Option (Recompile);

Insert Into T Select Top 1005 * From T_Messages Option (Recompile);

Go

 

If Object_ID('P6','P') Is Not Null Drop Proc P6;

Go

Create Proc P6 As

Insert Into T Select Top 1006 * From T_Messages;

Insert Into T Select Top 1006 * From T_Messages;

Go

 

If Object_ID('P7','P') Is Not Null Drop Proc P7;

Go

Create Proc P7 As

Exec('Insert Into T Select Top 1007 * From T_Messages;');

Exec('Insert Into T Select Top 1007 * From T_Messages;');

Go

 

If Object_ID('P8','P') Is Not Null Drop Proc P8;

Go

Create Proc P8 As

Insert Into T Exec('Select Top 1008 * From T_Messages;');

Insert Into T Exec('Select Top 1008 * From T_Messages;');

Go

 

DBCC FreeProcCache;

DBCC DropCleanBuffers;

 

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff-- -4----------------------------------------------------------------------------------------------------------');

Exec P4;

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff--4-5----------------------------------------------------------------------------------------------------------');

Exec P5;

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff--5-6----------------------------------------------------------------------------------------------------------');

Exec P6;

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff--6-7----------------------------------------------------------------------------------------------------------');

Exec P7;

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff--7-8----------------------------------------------------------------------------------------------------------');

Exec P8;

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff--8-4----------------------------------------------------------------------------------------------------------');

Exec P4;

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff--4-5----------------------------------------------------------------------------------------------------------');

Exec P5;

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff--5-6----------------------------------------------------------------------------------------------------------');

Exec P6;

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff--6-7----------------------------------------------------------------------------------------------------------');

Exec P7;

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff--7-8----------------------------------------------------------------------------------------------------------');

Exec P8;

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff--8- ----------------------------------------------------------------------------------------------------------');

image

  • P4 – הפרוצדורה מוגדרת עם Recompile (כלומר – ברמת הפרוצדורה ולא הפקודה), ולכן אינה מופיעה בטבלאות המערכת ואינה נשמרת ב-Cache. בכל הרצה נוצר Plan חד פעמי, והוא אינו נשמר.
  • P5 – בפרצדורה יש 2 פקודות זהות עם Recompile (ברמת הפקודה), ולכן הפרוצדורה מופיעה פעמיים, אך הפקודות מופיעות פעם אחת (כל אחת לחוד) כי רק הריצה האחרונה שלהן נשמרת.
  • P6 – בפרצדורה יש 2 פקודות זהות כנ”ל, אך ללא Recompile; ולכן הפרוצדורה מופיעה פעמיים וכל אחת משתי הפקודות פעמיים.
  • P7 – בפרוצדורה 2 פקודות זהות כנ”ל, אך הן מבוצעות כ-SQL דינאמי. הפרוצדורה עצמה מופיעה פעמיים, אך הפקודות שבוצעו בקונטקסט של ה-Exec ולא של הפרוצדורה – מופיעות בשל כך כ-4 ריצות של אותה פקודה (ה-Exec בוצע 4 פעמים).
  • P8 – בפרוצדורה 2 פקודות זהות המבוצעות כ-SQL דינאמי, אך ה-Insert מחוץ ל-Exec ולכן הוא מתבצע בקונטקסט של הפרוצדורה ולא של ה-Exec. הפרוצדורה בוצעה איפוא פעמיים, ה-Select שבתוך ה-Exec – בוצע 4 פעמים, וה-Insert מופיע בשתי שורות נפרדות (כי בוצע פעמיים בתוך הפרוצדורה) ובכל שורה פעמיים (כי הפרוצדורה בוצעה פעמיים).

ונסיים בסדרת פרוצדורות שאמורות להיות תמימות למראה – מכניסות שורה אחת לטבלה, אבל מאחורי הקלעים עובדות לעיתים קשה מאוד וזוללות משאבים בתיאבון.
השיטה: לכל פרוצדורה גלויה (P11 ,P21 ,P31) תהיה פרוצדורת עזר (P10 ,P20 ,P30 בהתאמה) שתחזיר שורה אחת בלבד, אלא שבחלק מהמקרים פרוצדורת העזר תעבוד קשה מאוד בטרם תחזיר אותה שורה תמימה.

If Object_ID('P10','P') Is Not Null Drop Proc P10;

Go

Create Proc P10 As

Select Top 1 * From T_Messages;

Go

 

If Object_ID('P11','P') Is Not Null Drop Proc P11;

Go

Create Proc P11 As

Insert Into T Exec P10;

Go

 

If Object_ID('P20','P') Is Not Null Drop Proc P20;

Go

Create Proc P20 As

Select Top 1 * From T_Messages Order By Len(text);

Go

 

If Object_ID('P21','P') Is Not Null Drop Proc P21;

Go

Create Proc P21 As

Insert Into T Exec P20;

Go

 

If Object_ID('P30','P') Is Not Null Drop Proc P30;

Go

Create Proc P30 As

Insert Into T Select * From T_Messages;

Select Top 1 * From T_Messages Order By Len(text);

Go

 

If Object_ID('P31','P') Is Not Null Drop Proc P31;

Go

Create Proc P31 As

Insert Into T Exec P30;

Go

 

Truncate Table T;

 

DBCC FreeProcCache;

DBCC DropCleanBuffers;

 

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff--7-8----------------------------------------------------------------------------------------------------------');

Exec P11;

Exec P21;

Exec P31;

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff--8-9----------------------------------------------------------------------------------------------------------');

Exec P11;

Exec P21;

Exec P31;

Print Format(GetDate(),'yyyyMMdd HH:mm:ss.fff--8-9----------------------------------------------------------------------------------------------------------');

  • P11 – פרוצדורת העזר שולפת שורה אחת בלבד מטבלת המקור, ללא מיון (כלומר- פעולה די פשוטה ללא תוספות נסתרות).
  • P21- פרוצדורה העזר ממיינת לפי אורך הטקסט בעמודת הטקסט, לזה אין אינדקס ויש למיין את הטבלה, ולפחות לבצע Scan מלא.
  • P31 – פרוצדורת העזר גם ממיינת כמו הקודמת, וגם מבצעת Insert גדול לתוך טבלה אחרת.

מה שמעניין אותי הוא מתי ואיך נראה את פעולת ה-Insert הפשוטה והגלויה, ומתי ואיך את טחינת המשאבים מאחורי הקלעים.

image

נתחיל מה-Grid האמצעי של sys.dm_exec_procedure_stats: יש התאמה בין P10 ל-P11, בין P20 ל-P21, ובין P30ל-P31; והמחירים הם ברוטו – כולל מה שמאחורי הקלעים. בקיצור- רואים במה באמת הפרוצדורה מעורבת, ולא רק את ה-Insert של השורה הבודדת.
נעבור ל-Grid העליון המורכב והמפורט יותר. נעיין ב-3 השורות של ה-Insert Into T Exec: נראה שהן מציגות נתוני ברוטו, כלומר – לא רק את ה-Insert של השורה הבודדת, אלא את כל מה שכרוך בכך, אם כי ה-total_worker_time אינו מסתדר במקרה של P20.
אפשר לשים לב ששתי השורות עם ה-(Select Top 1 .. Order By Len(text מציגות ערכי CPU שונים (total_worker_time), כנראה כתוצאה מכך שבריצה הראשונה התבצעה קומפילציה.

סיכום- קצת קשה לסכם כי אין כאן מסקנות חותכות או תגליות מרעישות, אך הייתי אומר כך:

  • ב-sys.dm_exec_procedure_stats נמצא סיכומים לגבי פרוצדורות. נכון שבפרוצדורה יכולות להיות הרבה פעילויות, ויש רבות שאינן במסגרת פרוצדורות; אבל בדרך כלל הן הלב של הקוד במערכת, והסקריפטים הכבדים יותר רצים לרוב בתור פרוצדורות.
  • ב-sys.dm_exec_query_stats נמצא סיכומים לגבי פקודות בודדות, במסגרת פרוצדורות ושלא במסגרתן.
  • כשיש Recompile ברמת הפרוצדורה לא נמצא פרטים עליה ועל הפקודות שבה בשני הנ”ל, אך כשהוא ברמת הפקודה אזי כן (אם כי הפקודות עם ה-Recompile יתבצעו תמיד רק פעם אחת).
  • בדרך כלל סיכומי הפקודות יהיו “ברוטו”, ויכללו את כל מה שמתבצע מאחורי הקלעים.
  • פקודות זהות באותה פרוצדורה (ולא כל שכן בפרוצדורות שונות) יופיעו בשורות נפרדות ב-sys.dm_exec_query_stats.
  • פקודות זהות בפרוצדורות שונות (ולא כל שכן בפרוצדורות זהות) יופיעו באותה שואה כשהן מתבצעות כ-Ad Hoc Queries, למשל בתוך Exec כקוד דינאמי.
  • כדי לתקנן את הנתוני למכנה משותף, כדאי לחלק את המדדים המצטברים (.._total) בזמן שחלף מאז שה-Plan נוצר. כך מקבלים מחירים ליחידת זמן.
הוסף תגובה
facebook linkedin twitter email

כתיבת תגובה

האימייל לא יוצג באתר. שדות החובה מסומנים *