MySQL profiler

Es ik pa laikam iedomājos vai MySQLā arī var lietot līdzīgas iespējas, kā piemēram Oracle autotrace, lai varētu mērīt izpildes laiku, paveiktos soļus un kaut kādu statistiku vaicājumiem, un lai salīdzinātu, kas tad izpildījās ātrāk un kāpēc. Tad nu izrādās, ka jau vismaz kopš 2007. gada pavasara eksistē tāda lieta, kā MySQL profiler, kas lielā mērā to nodrošina. Jau pašā sākumā jābrīdina, ka MySQL ir visai dīvaina DBVS un visai dīvainas izstrādes metodes vismaz no mana skatupunkta, jo pirmkārt MySQL Profiler nav pieejams MySQL Enterprise Server un notiek arī tāda mistiska dīvainība, ka vecākās versijās ir, bet jaunākās nē, piemēram, 5.0.37 ir, bet 6.0.4 nav (uz to arī es uzrāvos un brīnījos kā gan tas nākas), savukārt pēdējā novelkamajā 6.0.9. alpha atkal ir. Tā kā iespējams ne visiem lietotājiem būs tā iespēja šo rīku arī izmantot. Vēl tāds interesants fakts, ka šajā brīdī meklējot Googlē MySQL profiler latviskās lapās (tas ir pirms šī raksta, ko pašlaik lasat, publicēšanas) tiek atrasti 17 rezultāti, no kuriem tieši 1 ir kādā sakarā ar meklēto frāzi.

Kā jālieto?

Profiler sākšana un beigšana ir ļoti vienkārša. Lai sāktu, rakstam:

mysql> set profiling=1;
Query OK, 0 rows affected (0.00 sec)

Lai beigtu, rakstam:

mysql> set profiling=0;
Query OK, 0 rows affected (0.00 sec)

Lai noskaidrotu, kādā stāvoklī esam:

mysql> select @@profiling;
+-------------+
| @@profiling |
+-------------+
|           0 |
+-------------+
1 row in set (0.00 sec)

Ko ar to var redzēt?

Apsolījumi ir, ka ar to var redzēt daudz un dažādas lietas ieskaitot kopējo patērēto laiku, procesora laiku, lasītos un rakstītos blokus u.c. lietas. Visuzskatāmāk to var redzēt paskatoties, ko tad glabā information_schema shēmas tabula profiling, kur tiek glabāta profilēšanas informācija.

mysql> desc information_schema.profiling;
+---------------------+--------------+------+
| Field               | Type         | Null |
+---------------------+--------------+------+
| QUERY_ID            | int(20)      | NO   |
| SEQ                 | int(20)      | NO   |
| STATE               | varchar(30)  | NO   |
| DURATION            | decimal(9,6) | NO   |
| CPU_USER            | decimal(9,6) | YES  |
| CPU_SYSTEM          | decimal(9,6) | YES  |
| CONTEXT_VOLUNTARY   | int(20)      | YES  |
| CONTEXT_INVOLUNTARY | int(20)      | YES  |
| BLOCK_OPS_IN        | int(20)      | YES  |
| BLOCK_OPS_OUT       | int(20)      | YES  |
| MESSAGES_SENT       | int(20)      | YES  |
| MESSAGES_RECEIVED   | int(20)      | YES  |
| PAGE_FAULTS_MAJOR   | int(20)      | YES  |
| PAGE_FAULTS_MINOR   | int(20)      | YES  |
| SWAPS               | int(20)      | YES  |
| SOURCE_FUNCTION     | varchar(30)  | YES  |
| SOURCE_FILE         | varchar(20)  | YES  |
| SOURCE_LINE         | int(20)      | YES  |
+---------------------+--------------+------+

Diemžēl arī statistiku ziņā rīks ir nepilnīgs, jo kā rakstīts arī dokumentācijā, ne visur visu var dabūt. Un MySQL uz Windows (ko es arī testēju) noteikti nerāda visu, pareizāk izsakoties rāda statusu (nosacītu vaicājuma izpildes stāvokli), laiku, izejas failu un izejas koda rindiņu. Jāatzīst, ka iesākumam arī tas nav slikti, jo:

  • laiks tiek fiksēts ar precizitāti līdz mikrosekundēm (6 zīmes aiz komata), kas ir krietni labāk nekā noklusētās centisekundes (ko rāda pēc katra izpildītā vaicājuma);
  • skatoties uz stāvokļiem rodas lielāka skaidrība, kādas operācijas vaicājuma izpildes gaitā tiek veiktas, cik tās tiek veiktas un cik laiku katra prasa.

Tātad apskatīsim 2 piemērus, kas balstīti uz tabulām ierakstā par IN un EXISTS apakšvaicājumiem. Pirmais piemērs būs izmantojot IN operatoru, otrais EXISTS, bet to rezultāti ir identiski. Redzēsim, kā apskatīties profilus visus kopā un kā sīkāk katru atsevišķi.

mysql> SELECT * FROM b
    -> WHERE y1 IN (
    ->   SELECT x1
    ->   FROM a);
+------+------+------+
| y1   | y2   | y3   |
+------+------+------+
|    1 |    1 |    1 |
|    1 |    2 |    1 |
|    2 |    2 |    3 |
+------+------+------+
3 rows in set (0.00 sec)
mysql> SELECT * FROM b
    -> WHERE EXISTS (
    ->   SELECT 1
    ->   FROM a
    ->   WHERE a.x1 = b.y1);
+------+------+------+
| y1   | y2   | y3   |
+------+------+------+
|    1 |    1 |    1 |
|    1 |    2 |    1 |
|    2 |    2 |    3 |
+------+------+------+
3 rows in set (0.01 sec)

It kā otrais mums ir izpildījies ilgāk, skatamies kā tad tas ir saskaņā ar profiler datiem. Lai to darītu jāraksta SHOW PROFILES, daudzskaitlī. Man jau ir izpildītii vairāki vaicājumi, tāpēc šie ir ar lielākiem numuriem (46 un 47):

mysql> show profiles;
+----------+------------+-----------------------------------
| Query_ID | Duration   | Query
+----------+------------+-----------------------------------
|       46 | 0.00092950 | SELECT * FROM b
WHERE y1 IN (
  SELECT x1
  FROM a)                     |
|       47 | 0.00084825 | SELECT * FROM b
WHERE EXISTS (
  SELECT 1
  FROM a
  WHERE a.x1 = b.y1) |
+----------+------------+-----------------------------------

Interesanti, ka saskaņā ar profiling info, vaicājums ar EXISTS ir pat izpildījies ātrāk nekā ar IN un kas pats interesantākais neviens no tiem nav tuvu centisekundei. Jādomā, ka tas saistīts ar kaut kādām noapaļošanas kļūdām un pārāk maziem skaitļiem, lai būtu precīzi mērījumi🙂

Tagad nāk interesantākā daļa, skatamies, kāds tad izskatās katrs atsevišķais profails. Tam izmantojam komandu SHOW PROFILE, vienskaitlī. Komandai pieliekot klāt argumentu iegūstam profailu iepriekš izpildītam vaicājumam ar numuru X.

Tātad vaicājuma ar IN operatoru profails izskatās šādi:

mysql> show profile for query 46;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000025 |
| checking query cache for query | 0.000101 |
| Opening tables                 | 0.000033 |
| System lock                    | 0.000007 |
| Table lock                     | 0.000064 |
| init                           | 0.000056 |
| optimizing                     | 0.000021 |
| statistics                     | 0.000028 |
| preparing                      | 0.000162 |
| executing                      | 0.000006 |
| Sending data                   | 0.000209 |
| end                            | 0.000006 |
| removing tmp table             | 0.000023 |
| end                            | 0.000006 |
| query end                      | 0.000005 |
| freeing items                  | 0.000146 |
| storing result in query cache  | 0.000024 |
| logging slow query             | 0.000003 |
| cleaning up                    | 0.000009 |
+--------------------------------+----------+

Tātad skatoties uz šo var izdarīt vairākus secinājumus:

  • kura operācija aizņem visvairāk laiku;
  • rodas priekšstats par to, ko tad serveris vaicājuma izpildes gaitā vispār dara;
  • redzam, ka šis apakšvaicājums ir prasījis pagaidu tabulas izveidi (jo ir solis removing tmp table), tas būs interesanti saistībā ar otru vaicājumu.

Tagad profails ar EXISTS apakšvaicājumu:

mysql> show profile for query 47;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000025 |
| checking query cache for query | 0.000111 |
| Opening tables                 | 0.000034 |
| System lock                    | 0.000006 |
| Table lock                     | 0.000062 |
| init                           | 0.000049 |
| optimizing                     | 0.000009 |
| statistics                     | 0.000022 |
| preparing                      | 0.000016 |
| executing                      | 0.000005 |
| Sending data                   | 0.000054 |
| optimizing                     | 0.000015 |
| statistics                     | 0.000018 |
| preparing                      | 0.000013 |
| executing                      | 0.000004 |
| Sending data                   | 0.000049 |
| executing                      | 0.000004 |
| Sending data                   | 0.000024 |
| executing                      | 0.000003 |
| Sending data                   | 0.000019 |
| executing                      | 0.000004 |
| Sending data                   | 0.000022 |
| executing                      | 0.000003 |
| Sending data                   | 0.000019 |
| executing                      | 0.000003 |
| Sending data                   | 0.000072 |
| end                            | 0.000013 |
| query end                      | 0.000004 |
| freeing items                  | 0.000139 |
| storing result in query cache  | 0.000022 |
| logging slow query             | 0.000003 |
| cleaning up                    | 0.000009 |
+--------------------------------+----------+

Ko redzam šeit:

  • atšķirībā no IN šeit nav pagaidu tabulas dzēšana;
  • ir 2 sekvences optimizing, statistics, preparing, executing, Sending data un pēc tam 5 sekvences executing, Sending data. Tas izskatās pēc 2 vaicājumu optimizēšanas – pirmā virsvaicājumam un otrā apakšvaicājumam un pēc tam vēl 5 reizes ierakstu nolasīšanas. Ja paskatamies izpildes plānā, tad arī tā izskatās, taču, protams, neņemos teoretizēt kādā kārtībā kādi ieraksti tika tur lasīti🙂

Tālāk paskatamies vēl dažas interesantas lietas – palaižam vaicājumu ar EXISTS vēlreiz. Tagad pēc show profiles var redzēt, ka otrajā reizē tieši tas pats vaicājums ir izpildījies ~6 reizes ātrāk nekā pirmajā un ir palikušas tikai dažas operācijas:

mysql> show profiles;
+----------+------------+-----------------------------------
| Query_ID | Duration   | Query
+----------+------------+-----------------------------------
|       49 | 0.00014200 | SELECT * FROM b
WHERE EXISTS (
  SELECT 1
  FROM a
  WHERE a.x1 = b.y1)         |
+----------+------------+--------------------
mysql> show profile for query 49;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000025 |
| checking query cache for query | 0.000009 |
| checking privileges on cached  | 0.000011 |
| sending cached result to clien | 0.000089 |
| logging slow query             | 0.000004 |
| cleaning up                    | 0.000003 |
+--------------------------------+----------+

Pēc visām šīm operācijām ir acīmredzami, ka tiek izmantots iekešotais rezultāts un kā tas iespaido gan operāciju skaitu, gan kopējo vaicājuma izpildes ātrumu.

Dažas papildus lietas, ko atcerēties

  • Profilēšana strādā arī citiem sql teikumiem, ne tikai select vaicājumiem.
  • Ļoti nepatīkami, ka uz Windows nerāda BLOCKS IO, jo tā noteikti varētu būt nākošā interesantākā statistika pēc izpildes laika.
  • Ir tiešām vērts izpētīt izpildāmās operācijas, pie ORDER BY, piemēram, parādās Sorting result un tai atbilstošais laiks, kas ļoti uzskatāmi parāda, ko nozīmē ORDER BY pievienošana. Savukārt GROUP BY parādās gan Sorting result, gan arī pirms tam Creating tmp table, kas parāda kā MySQL veic šīs operācijas.
  • Ilgi izpildošamies vaicājumiem varētu būt ļoti daudzas operācijas un tad vienkārša komanda show profile varētu dot ļoti nepārskatām rezultātu. Tad ir vērts atcerēties par information_schema.profiling tabulu, kuras rezultātus ar tiem pašiem SELECT vaicājumiem un grupēšanu pēc operācijas var padarīt krietni lasāmākus. 

Tālākā lasāmviela

3 Responses to MySQL profiler

  1. Ēriks says:

    1. par tipiem (t.i. show profile ALL for query 5). Iekš 5.051 [block IO] nav redzams nedz windows nedz linux (debian)…
    2. Izpildot kveriju (select * from dict_base where lower like ‘%mest%’ order by lower;) rezultātā saņēmu 36 ierakstus. Pēc statistikas viss notiek daudzmaz ātri izņemot Sending data, kas ir 2s.

    ..
    executing 0.000002
    Sorting result 0.0000037
    Sending data 2.0604395
    end 0.0000127
    ..

    Kautgan, manā skatījumā, vajadzētu būt lielam izpildes laikam pie sorting.
    Idejas?

  2. Gints Plivna says:

    Neņemos spriest kas par vainu, varu tikai izteikt hipotēzes un teoretizēt:
    1) nekorekta uzskaite – šo to uzskaita ne tur
    2) dažas operācijas pazūd – šo te es tā kā pats novēroju, piemēram, augšminētajam vaicājumam ar IN, ir tikai removing tmp table (kur tad izveide?) bet, piemēram, create table as select – bija gan temp tabulas izveide, gan dropošana.

    Tā kā izskatās, ka rīks vēl ir potenciāli zaļš, vai arī izpildes kārtībā ir kaut kas tāds, ko mēs nevaram tik viegli saprast😉 Varbūt arī piemēram darbības kodā nav tik ļoti nodalītas un pārklājas kaut kādā mērā…

  3. Gints Plivna says:

    Jā un kas attiecas uz šo ORDER BY, tad jau var pamēģināt cik aizņem ar to, cik bez un vai sending data kaut kā būtiski atšķiras abos gadījumos. Tiesa gan, lai sakārtotu 36 ierakstus, diez vai ir nepieciešams laiks sekundēs. Otra lieta šādos mēģinājumos – ir vērts, protams, veikt vairākus tādus, lai rezultāts būtu ticams, jo varbūt pirmajā kaut ko lasīja no diska, varbūt kādā kādi citi procesi kaut ko pieprasīja un tas pavisam izbojāja konkrēto testpiemēru.

Komentēt

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Mainīt )

Twitter picture

You are commenting using your Twitter account. Log Out / Mainīt )

Facebook photo

You are commenting using your Facebook account. Log Out / Mainīt )

Google+ photo

You are commenting using your Google+ account. Log Out / Mainīt )

Connecting to %s

%d bloggers like this: