go backsqlschool blogs list

Identify slow running queries with SQL Profiler trace data

by Antonios Chatzipavlis

Με αφορμή το τελευταίο μου SQL Server Saturday Night που σαν θέμα είχε τον SQL Server Profiler και μπορείτε να το δείτε εδώ και στο οποίο αναφέρθηκα στο συγκεκριμένο θέμα αποφάσισα να γράψω το συγκεκριμένο ώστε να δώσω περισσότερες λεπτομέρειες.

Όπως ανέφερα και στη παρουσίαση μου το ποια events θα διαλέξει κάνεις έχει περισσότερο να κάνει με την εμπειρία που έχει αλλά και την ικανότητα με αυτά να εντοπίσει το εν λόγω πρόβλημα.

Προσωπικά επιλέγω αυτά που θα σας παραθέσω παρακάτω αλλά αυτό φυσικά δεν είναι το απόλυτο. Ο καθένας από εσάς μπορεί να προσθέσει ή να αφαιρέσει events με τα οποία πιστεύει ότι θα κάνει καλύτερα την αναζήτηση του στο θέμα μας.

Events

RPC:Completed

Το event αυτό πυροδοτείτε όταν αφού μια stored procedure έχει εκτελεστεί σαν remote procedure call. Θα το βρείτε κάτω από την κατηγορία Stored Procedures και περιέχει χρήσιμες πληροφορίες για την εκτέλεση μιας stored procedure όπως, Duration, CPU, Read, Writes αλλά και το όνομα της stored procedure. Όμως το συγκεκριμένο event δεν πυροδοτείτε όταν κάνουμε εκτέλεση της stored procedure με την EXECUTE T-SQL εντολή. Επίσης το ίδιο ισχύει και για το T-SQL statements τα οποία είναι εκτός μίας stored procedure.

SP:StmtCompleted

Το event αυτό πυροδοτείτε όταν ένα statement σε μια stored procedure έχει ολοκληρωθεί. Θα το βρείτε κάτω από την κατηγορία Stored Procedures και περιέχει πληροφορίες όπως Duration, CPU, Reads, Writes. Βέβαια θα πρέπει να λάβουμε υπόψη ότι μια stored procedure μπορεί να έχει πολλά statements άρα θα έχουμε τόσα events όσα αυτά είναι, και φυσικά δεν πυροδοτείτε για τα εκτός stored procedure statements.

SQL:BatchStarting

Το event αυτό πυροδοτείτε οποτεδήποτε ένα νέο T-SQL batch ξεκινάει είτε είναι μέσα είτε όχι σε stored procedure. Θα το βρείτε κάτω από την κατηγορία SQL. Η επιλογή μου για αυτό είναι γιατί προσωπικά με βοηθάει να δω την συνέχεια στην αλυσίδα των queries.

SQL:BatchCompleted

Το event αυτό συμβαίνει κάθε φορά που ένα οποιοδήποτε T-SQL statement ολοκληρώνετε, είτε είναι είτε όχι μέσα σε stored procedure.Αν είναι βέβαια μέσα σε stored procedure τότε δεν έχω το πραγματικό T-SQL statement αλλά το όνομα της stored procedure. Περιέχει πληροφορίες όπως Duration, CPU, Reads, Writes για το statement. Ουσιαστικά αυτό το χρειάζομαι για να πιάσω τα events που γίνονται από T-SQL statements τα οποία είναι εκτός stored procedure. Θα το βρείτε κάτω από την κατηγορία SQL.

ShowPlanXML

Το event αυτό κάνει display το γραφικό execution plan ενός query. Θα το βρείτε στην κατηγορία Performance, και οι λόγοι για την επιλογή μου αυτή είναι προφανείς καθώς θέλω αν ξέρω για το κάθε ένα το execution plan του.

Columns

Από τα παραπάνω events επιλέγω τα εξής columns από αυτά.

Duration

Παρέχει την πληροφορία της διάρκειας εκτέλεσης τους event. Όπως τόνισα και στην παρουσίαση μου by default o SQL Server Profiler μετράει το χρόνο σε microseconds αλλά τα δείχνει σε milliseconds. Στην παρουσίαση μου έδειξα πως αυτό μπορεί να αλλάξει να τα δείχνει σε microseconds. Δεν νομίζω ότι χρειάζεται να εξηγήσω γιατί χρειάζομαι την πληροφορία που μου δίνει το column αυτό. Μια ακόμα παρατήρηση για αυτούς που ίσως δεν έχουν την εμπειρία με τον SQL Profiler και δεν έχουν δει ακόμα την παρουσίαση μου για αυτό είναι ότι η συγκεκριμένη κολώνα υπάρχει μόνο στα events RPC:Competed, SP:Competed και SQL:BatchCompleted.

ObjectName

Είναι το λογικό όνομα του object το οποίο πυροδότησε το event. Εάν είναι stored procedure τότε σε αυτή την κολώνα αναγράφεται το όνομα της stored procedure ενώ αν είναι ένα μεμονωμένο query η κολώνα λέει “Dynamic SQL”. Υπάρχει μόνο στα SQL:BatchStarting και SQL:BatchCompleted events.

TextData

Περιέχει είτε το όνομα της stored procedure είτε το T-SQL query που έχει εκτελεστεί εφόσον αυτό είναι εκτός stored procedure. Μια παρατήρηση σημαντική στο SP:StmtCompleted event η κολώνα αυτή περιέχει τον T-SQL κώδικα που έχει εκτελεστεί μέσα στην stored procedure, και για το Showplan XML περιέχει τον XML κώδικα που χρησιμοποιήθηκε για την δημιουργία του execution plan.

CPU

Η κολώνα αυτή δείχνει το ποσό του χρόνου σε milliseconds που η CPU χρησιμοποιήθηκε για το συγκεκριμένο event. Τιμές για την συγκεκριμένη κολώνα θα βρούμε μόνο στα RPC:Completed, SP:StmtCompleted και SQL:BatchCompleted events.

Reads

Η κολώνα αυτή δείχνει τον αριθμό των logical reads που έγιναν κατά τη διάρκεια του event. Φυσικά όσο μικρότερος είναι ο αριθμός αυτός τόσο λιγότερα disk I/O resources χρησιμοποιήθηκαν για το event αυτό. Τιμές σε αυτή θα έχουμε μόνο στα RPC:Completed, SP:StmtCompleted και SQL:BatchCompleted events.

Writes

Η κολώνα αυτή δείχνει τον αριθμό των physical writes που έγιναν κατά τη διάρκεια του event. Φυσικά όσο μικρότερος είναι ο αριθμός αυτός τόσο λιγότερα disk I/O resources χρησιμοποιήθηκαν για το event αυτό. Τιμές σε αυτή θα έχουμε μόνο στα RPC:Completed, SP:StmtCompleted και SQL:BatchCompleted events.

IntegerData

Η τιμή που δείχνει η συγκεκριμένη κολώνα είναι διαφορετική ανά event. Αν το event είναι το SP:StmtCompleted τότε δείχνει την πραγματικό αριθμό των εγγραφών που επεστράφησαν. Εάν το event είναι το ShowPlan XML δείχνει το εκτιμώμενο αριθμό των εγγραφών που θα επιστραφούν βασιζόμενο στο execution plan. Έτσι γνωρίζοντας τον αριθμό εγγραφών που περιμένουμε να επιστραφούν και τον εκτιμώμενο αριθμό και παρατηρήσουμε σημαντική διαφορά αυτό σημαίνει ότι έχουν ουτ of date στατιστικά με τα οποία ο query optimizer έβγαλε το execution plan και ίσως είναι και ο λόγος της κακής απόδοσης στο query. Άρα καλό θα είναι να κάνουμε update statistics.

DatabaseName

Το όνομα της. Το θέλω κυρίως για να μπορώ να κάνω filtering.

ApplicationName

Το όνομα της εφαρμογής ένα φυσικά αυτή το παρέχει. Στην περίπτωση που το παρέχει το θέλω για να κάνω filtering.

StartTime

H ώρα έναρξης του event. Χρήσιμη γιατί μπορώ να συγκρίνω και να δω τι άλλο έχει ξεκινήσει παράλληλα με αυτό.

EndTime

Η ώρα λήξης του event. Χρήσιμη για να μπορώ να δω αν ένα query /transaction τρέχει σε συγκεκριμένη στιγμή πάντα.

SPID

Όπως έχω ήδη πει και στην παρουσίαση μου αυτή είναι υποχρεωτική κολώνα και περιέχει το Server Process ID του client που έκανε το event. Μπορώ να έχω filtering σε αυτή που θα με βοηθήσει να δω αν το query/transaction γίνεται από ένα συγκεκριμένο client.

LoginName

Περιέχει είτε το Windows Login Name είτε το SQL Server Login Name. Αρκετά χρήσιμη πληροφορία τόσο για να δω ποιος δημιουργεί το πρόβλημα όσο και για να κάνω filtering.

EventSequence

Σε κάθε event που δημιουργείται ο SQL Profiler δίνει ένα σειριακό αριθμό ο οποίος δείχνει την σειρά που δημιουργήθηκε αυτό. Αρκετές φορές εκτός από τα StartTime & EndTime για λόγους ταξινόμησης και αναζήτησης είναι χρήσιμο να υπάρχει και αυτό.

BinaryData

Η κολώνα αυτή είναι σημαντική και γεμίζει μόνο στο Showplan XML event και περιέχει το εκτιμώμενο κόστος για το query το οποίο χρησιμοποιείται στο γραφικό execution plan. Τα δεδομένα δεν είναι αναγνώσιμα αλλά χρησιμοποιούνται εσωτερικά από τον SQL Profiler για αν δείξει το execution plan.

Columns Grouping & Ordering

Ένα από τα πράγματα τα οποία θεωρώ ότι είναι σημαντικά είναι το να φέρεις όλες τις παραπάνω κολώνες σε μια τέτοια σειρά ώστε να μπορείς γρήγορα να βρίσκεις αυτό που ψάχνεις. Η σειρά η οποία εμένα με εξυπηρετεί αλλά το grouping το οποίο κάνω είναι η παρακάτω και την οποία μπορείτε σχετικά εύκολα να υλοποιήσετε αφού πατήσετε το Organize Columns button.

  • Groups
    • Duration
  • · Columns
    • SPID
    • EventSequence
    • EventClass
    • ObjectName
    • TextData
    • CPU
    • Reads
    • Writes
    • IntergerData
    • DatabaseName
    • ApplicationName
    • StartTime
    • EndTime
    • LoginName
    • BinaryData

Φυσικά δεν χρειάζεται να τονίσω ότι όλα αυτά δεν χρειάζεται να τα φτιάχνετε κάθε φορά καθώς μπορούμε να δημιουργήσουμε δικά μας templates.

Ανάλυση Αποτελεσμάτων

Αφού έχουμε μαζέψει τα δεδομένα μας μπορούμε είτε να τα δούμε με τις μεθόδους aggregation έχουμε μέσα από τον SQL Profiler είτε να αποθηκεύσουμε τα δεδομένα αυτά σε XML μορφή και να τα βάλουμε σε κάποιο Excel ή ακόμα να τα βάλουμε σε κάποιον πίνακα όπου μπορούμε να κάνουμε queries πάνω σε αυτό. Ανάλογα με τα ευρήματα μας δρούμε ώστε να λύσουμε τα προβλήματα μας. Αυτό όμως είναι κάτι το οποίο δεν μπορώ να σας το περιγράψω καθώς είναι κάτι το οποίο έρχεται σε άμεση συνάρτηση με τα ευρήματα που έχουμε και δεν είναι ο σκοπός μου αυτός. Ο σκοπός μου είναι να σας δώσω κάτι το οποίο άμεσα μπορείτε να το χρησιμοποιήσετε για να μαζέψετε τα απαραίτητα κατ’ εμένα δεδομένα.

Enjoy it!

antonch

Ημερομηνία: 20 March 2011 13:11
Αξιολόγηση:
Κατηγορίες:
Tags:
Share it:

Σχετικά Blog Post

Αφήστε το σχόλιο σας - Leave your comment

Τα σχόλια έχουν κλείσει.
Επιτρέπονται μόνο τα σχόλια από τα μέλη του SqlSchool.gr.


newsletter subscription

Εάν επιθυμείτε να λαμβάνετε ενημέρωση από εμάς, δώστε μας το e-mail σας.
PASS chapter logo
Official Professional Association for SQL Server (PASS) chapter for Greece
Join to PASS