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
- Using the New MySQL Query Profiler – apraksts par MySQL profiler ar piemēriem, kā to izmantot.
- SHOW PROFILES sintakse MySQL 5.0 dokumentācijā.
Datubāzes 
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?
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ā…
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.