MySQL server probleem

[GuusDeGraeve]

Sinds vandaag zitten we met een eigenaardig probleem op één van onze MySQL servers. Deze draait enkel MySQL op debian lenny.

Deze draait op een VMWare VPS.

Opeens begint de MySQL server vandaag volledig tilt te slaan, we merkten dat er performantie problemen waren met de site die erop draait en we gingen dus op onderzoek.

Nu bleek dat de MySQL server op 400% cpu draaide: zie de output van top:
top - 14:39:43 up 23 min, 1 user, load average: 7.20, 5.07, 3.29
Tasks: 65 total, 1 running, 64 sleeping, 0 stopped, 0 zombie
Cpu(s): 13.3%us, 85.7%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.4%hi, 0.6%si, 0.0%st
Mem: 7942720k total, 1249624k used, 6693096k free, 13796k buffers
Swap: 4305380k total, 0k used, 4305380k free, 704824k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
25275 mysql 20 0 3124m 454m 6004 S 400 5.9 16:45.68 mysqld
25358 root 20 0 18824 1220 940 R 1 0.0 0:00.52 top
1 root 20 0 10312 748 620 S 0 0.0 0:01.38 init
2 root 15 -5 0 0 0 S 0 0.0 0:00.00 kthreadd
3 root RT -5 0 0 0 S 0 0.0 0:00.10 migration/0
4 root 15 -5 0 0 0 S 0 0.0 0:00.24 ksoftirqd/0
5 root RT -5 0 0 0 S 0 0.0 0:00.02 watchdog/0
6 root RT -5 0 0 0 S 0 0.0 0:00.08 migration/1
7 root 15 -5 0 0 0 S 0 0.0 0:00.30 ksoftirqd/1
8 root RT -5 0 0 0 S 0 0.0 0:00.00 watchdog/1
9 root RT -5 0 0 0 S 0 0.0 0:00.12 migration/2
10 root 15 -5 0 0 0 S 0 0.0 0:00.48 ksoftirqd/2
11 root RT -5 0 0 0 S 0 0.0 0:00.00 watchdog/2
12 root RT -5 0 0 0 S 0 0.0 0:00.08 migration/3
13 root 15 -5 0 0 0 S 0 0.0 0:00.64 ksoftirqd/3
14 root RT -5 0 0 0 S 0 0.0 0:00.00 watchdog/3
15 root 15 -5 0 0 0 S 0 0.0 0:00.12 events/0
16 root 15 -5 0 0 0 S 0 0.0 0:00.12 events/1
17 root 15 -5 0 0 0 S 0 0.0 0:00.10 events/2
18 root 15 -5 0 0 0 S 0 0.0 0:00.10 events/3
19 root 15 -5 0 0 0 S 0 0.0 0:00.00 khelper
56 root 15 -5 0 0 0 S 0 0.0 0:00.28 kblockd/0
57 root 15 -5 0 0 0 S 0 0.0 0:00.48 kblockd/1
58 root 15 -5 0 0 0 S 0 0.0 0:00.32 kblockd/2
59 root 15 -5 0 0 0 S 0 0.0 0:00.34 kblockd/3
61 root 15 -5 0 0 0 S 0 0.0 0:00.00 kacpid

Herstarten van de MySQL server hielp niet, meteen zat deze weer aan de 400% cpu. De loads avgs van de server zijn bij gevolg ook niet laag. Deze zweven zo ongeveer rond de 6 a 7.

Als we de processen op de mysql server bekijken zien we een hele hoop queries op tabellen die de status locked hebben. Ook een hoopje die de status "copying to tmp table" hebben.

Het is de eerste keer dat we zoiets hebben. De site krijgt nu ook niet meer bezoekers dan anders en we merken ook nergens iets abnormaals wat zou kunnen wijzen op een aanval of iets dergelijks.

Zijn er mensen die dit ook al gehad hebben en eventueel een oplossing weten?

[maxnet]

Cpu(s): 13.3%us, 85.7%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.4%hi, 0.6%si, 0.0%st

Voornamenlijk in de kernel bezig.

Hoeveel IO doe je volgens "iostat"?

[wonko]

de query die de "copying to tmp" heeft, is een onefficiënte query, die dien je te proberen te optimaliseren door indexen toe te voegen. Als dat niet lukt, zal je moeten kijken naar het verhogen van de parameters die bepalen hoe groot een table mag zijn voor hij naar disk geschreven wordt (max_heap_size en tmp_mem_table_size dacht ik) of het gebruik van een ramdisk voor je tmp-space voor mysql.

Standaard gevalletje voor een dba

[GuusDeGraeve]

Dit is de output van iostat:

Linux 2.6.26-1-amd64 (mysql-master) 24-06-09 _x86_64_

avg-cpu: %user %nice %system %iowait %steal %idle
12,19 0,00 65,67 0,37 0,00 21,77

Device: tps Blk_read/s Blk_wrtn/s Blk_read Blk_wrtn
sda 11,82 239,81 863,30 2526414 9094728
sda1 11,81 239,72 863,30 2525417 9094728
sda2 0,00 0,00 0,00 4 0
sda5 0,01 0,07 0,00 689 0

Dat de mysql queries totaal niet optimaal zijn qua index gebruik wist ik al langer... Jammer genoeg krijgt de serverbeheerder al gouw de vinger gewezen.

Wat wel raar is, deze server heeft dit probleem nu nog maar enkele uren. En er is niks gewijzigd in de code of in het database ontwerp. Ook op de server zelf is niks gewijzigd...

[Randy]

Zet output even tussen [ code] en [ /code] tags, dat leest wat makkelijker voor een volgende keer.

[maxnet]

Dit is de output van iostat

iostat uitvoeren zonder parameters geeft de gemiddelde stats sinds het opstarten van de server (gebruik "iostat 1" om de actuele cijfers te zien).

Een blokje is 512-bytes groot. Dus in totaal heeft ie 4 GB naar schijf weggeschreven, met 400 KB/sec gemiddeld in bijna 3 uur tijd.

Vermoed dat dat ook wel in je geheugen zou hebben gepast,
Dus zou als eerste inderdaad even de max_heap_table_size en tmp_table_size instellingen ophogen, zodat de schijf niet meer gebruikt wordt.

Daarna kan je aan de hand van de slowlog en "explain <query>" de inefficiente queries er uit gaan halen.

[GuusDeGraeve]

Als ik in de server een 8GB aan ram zitten heb.

Tot hoeveel mag ik deze settings dan maximaal ophogen?
Ze staan nu beiden op 386MB.

[systemdeveloper]

Dit is de output van iostat:


Dat de mysql queries totaal niet optimaal zijn qua index gebruik wist ik al langer... Jammer genoeg krijgt de serverbeheerder al gouw de vinger gewezen.

Wat wel raar is, deze server heeft dit probleem nu nog maar enkele uren. En er is niks gewijzigd in de code of in het database ontwerp. Ook op de server zelf is niks gewijzigd...

Een wijziging in de performance van een db server (als NIKS veranderd is kwa config / bezoekers e.d.) kan ook het gevolg zijn van wijziging van de inhoud van de database. Misschien heeft de mysql optimizer voor bepaalde tabellen besloten om geen index meer te gebruiken en dat kan drastisch gevolgen hebben. Indexen op velden zoals 'geslacht' zijn daar goede voorbeelden van. Dit kun je meestal goed oplossen door indexen te maken op meerdere velden.

Maar... laat er gewoon iemand naar kijken. Er zijn namelijk wel 100 redenen waarom een dbserver opeens traag kan worden.

[Tim.Bracquez]

Het mysqltuner script is ook wel handig anders. Let op neem het niet gewoon over!

[maxnet]

Tot hoeveel mag ik deze settings dan maximaal ophogen?
Ze staan nu beiden op 386MB.

Da's al redelijk hoog, geloof dat het standaard 16 MB is.

Stonden ze de hele tijd al op 386 MB, of heb je het nu aangepast naar 386MB en vraag je hoeveel verder dat nog kan?

Er is in bijna 3 uur tijd slechts 4 GB geschreven, en als dat alleen zou gebeuren bij >386MB aan tijdelijke data, dan zou dat betekenen dat de query slechts een keer of 10 is uitgevoerd.

Of er moet een andere reden zijn dat MySQL tmptables aanmaakt.
Doet de query iets met "blob" of "text" velden?

[GuusDeGraeve]

We zijn ondertussen volledig de query aan het herschrijven. We hebben de query gevonden die het probleem gaf en die was alles behalve degelijk geschreven. Hebben die voorlopig uitgeschakeld en alles loopt nu weer vlot.