[MySQL] hele trage insert

[rogierslag]

Voor een intern ledensysteem wordt alles wat een gebruiker doet in die applicatie opgeslagen in een logboektabel in MySQL

Deze tabel heeft de volgende vorm

code:

CREATE TABLE `tbl_log` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `gebruiker` int(11) NOT NULL,
  `ip` varchar(15) NOT NULL,
  `tijd` datetime NOT NULL,
  `wat` text NOT NULL,
  PRIMARY KEY (`id`),
  KEY `gebruiker` (`gebruiker`)
) ENGINE=InnoDB  DEFAULT CHARSET=utf8;

Deze tabel staat min of meer vast en bevat momenteel een kleine 5000 records. Niks spectaculairs dus. De indexen staat zodanig gezien er enkel op gebruiker/id wordt gesorteerd of gefilterd (één of ander).

De betreffende database draait slechts één applicatie (PHP-based), de server wordt dus nauwelijks belast (testomgeving, één gebruiker). Het herstarten van het MySQL proces verbetert niets.

Nu duurt het invoegen van een nieuwe rij in deze database met enige regelmaat ontzettend lang, denk aan 1,5 tot 6 seconden. Volgens de profiler van PHP (xDebug) komt dit volledig door één functie: doLog welke een rij invoegt in de databse (niet meer, niet minder). Op dezelfde pagina worden er een kleine 500 selects gedaan met data die vrijwel niet gewijzigd wordt. De gebruikte functie aanroep voor de SQL opdracht is $mysqli->query(query). De query ziet er bijvoorbeeld zo uit

code:

$strInsertLog = "INSERT INTO tbl_log (gebruiker,ip,tijd,wat) VALUES (" . intval(USER_ID) . ",'" . GetClientIP() . "',NOW(),'" . $strMelding . "')";

Hierin is $strMelding een melding vanuit het systeem (string, geen userinput). USER_ID is bekend, getClientIp() geeft het IP adres terug.

Hoe kan het dat zo'n simpele insert zo lang duurt, terwijl de queries naar de db voor de selects wel razendsnel zijn?

P.S. Met enige regelmaat is een van de 500 selects ook wat traag (terwijl uit dezelfde tabel data ophalen), maar dat is max tot 0.08 seconden

[Reinier]

Wat doet getClientIp() exact? Misschien e.e.a. aan DNS-lookups? Heb je het probleem ook als je een statisch IP (hehe ) als test gebruikt? Of een wilekeurige string dus

[rogierslag]

GetClientIp() is meer een abstractie naar de rest toe hoe de boel wordt opgehaald. Volgens de profiler neemt de functie zelfs zo weinig tijd in beslag dat het niet gemeten wordt.

Code van de functie is iig

PHP:

<?php
function GetClientIP()
{
    return $_SERVER['REMOTE_ADDR'];
}
?>

[NMe]

Weet je zeker dat het de query zelf is die vertraagt en niet je PHP-code? Wat gebeurt er als je de letterlijke query in phpMyAdmin gooit? En als je er EXPLAIN voor zet?

[ Voor 10% gewijzigd door NMe op 25-10-2011 16:08 ]

[rogierslag]

code:

INSERT INTO tbl_log (gebruiker,ip,tijd,wat) VALUES (1,'192.168.1.1',NOW(),'Dit is een test')

Geeft soms ook traagheid tot 2 seconden, maar net als in de applicatie niet altijd.

Explain ervoor geeft een verwachte error

[TheNephilim]

Volgens mij kun je INSERT's niet explainen in MySQL. Wat voor database engine gebruik je? MyISAM of InnoDB?

Misschien doe je iets waardoor je locks hebt op de tabel. Dan moet hij wachten voor elke insert/select.

[rogierslag]

innoDB, verder gebruik ik enkel de mysqli libs van PHP en zet nergens expliciete locks. Het herstarten van het databaseproces zorgt voor de komende honderd inserts (ongeveer) dat alles weer soepel loopt, maar daarna begint het probleem weer.

[TheNephilim]

rogierslag schreef op dinsdag 25 oktober 2011 @ 16:31:
innoDB, verder gebruik ik enkel de mysqli libs van PHP en zet nergens expliciete locks. Het herstarten van het databaseproces zorgt voor de komende honderd inserts (ongeveer) dat alles weer soepel loopt, maar daarna begint het probleem weer.

Als het na verloop van tijd/inserts komt, dan gok ik dat het iets te maken heeft met je InnoDB logs. Die zullen vast vollopen en daardoor gaat het na verloop van tijd traag. Transaction logs misschien...

[justmental]

Zo'n text kolom is in mysql toch een niet inline opgeslagen kolom?
Kun je niet beter een varchar gebruiken voor deze toepassing?

[TheNephilim]

TEXT moet geen probleem zijn. We hebben hier ook een forum met miljoenen topics/posts en dat zijn ook gewoon TEXT velden en geen varchars.

[Beatboxx]

Ligt het niet aan je code? Je kan eens meten wat er precies zo lang duurt door voor de regels code dit te zetten:

PHP:

<?php
$time = microtime();
$time = explode(' ', $time);
$time = $time[1] + $time[0];
$start = $time;
?>

en op het einde dit:

PHP:

<?php
$time = microtime();
$time = explode(' ', $time);
$time = $time[1] + $time[0];
$finish = $time;
$total_time = round(($finish - $start), 6);
echo '</br>';
echo 'Page generated in '.$total_time.' seconds.'."\n";
?>

[RobIII]

Beatboxx schreef op dinsdag 25 oktober 2011 @ 17:47:
Ligt het niet aan je code? Je kan eens meten wat er precies zo lang duurt door voor de regels code dit te zetten:

*snip*

Ah, heerlijke copy/paste (gare, als in: overcomplicated en onnodige, PHP4(?)) code

quote: http://php.net/manual/en/function.microtime.php

get_as_float
If used and set to TRUE, microtime() will return a float instead of a string, as described in the return values section below.

Ofwel:

PHP:

<?php
$start = microtime(true);
//Do Stuff here
echo number_format(microtime(true)-$start,6);
?>

All you need, 2 LOC
Of je moet nog in PHP4 werken en dan heb je wel andere problemen dan trage inserts

Alternatief: apd_set_pprof_trace, xdebug, phpDebug etc.

[ Voor 29% gewijzigd door RobIII op 25-10-2011 19:06 ]

[ReenL]

Hoort gebruiker geen foreign key te zijn? (Verwacht echter niet dat de fout hier zit)

- Staat mysql op een VPS?
- Voert de server andere taken uit?
- Hoe ziet je mysql config eruit?

[GlowMouse]

rogierslag schreef op dinsdag 25 oktober 2011 @ 15:37:
Deze tabel staat min of meer vast en bevat momenteel een kleine 5000 records. Niks spectaculairs dus. De indexen staat zodanig gezien er enkel op gebruiker/id wordt gesorteerd of gefilterd (één of ander).

En je sorteert nooit op tijd?

Ik zou het probleem zoeken in je harddisks. Kun je die eens benchmarken (iops graag). Of anders de output van 'iostat -dx 1' terwijl je zo'n insert doet.

[rogierslag]

De server draait op een VPS van Tilaa.nl, daar heb ik meerdere VPS'en draaien en geen daarvan heeft problemen met het wegschrijven van queries. Het OS is Fedora 15, met alle updates, geen grafische schil.

Verder gebruik ik xDebug voor het verzamelen van profilerdata, dus ik ga niet mijn hele code volzetten met zinloze echo's. Vervolgens lees ik de statistieken uit via WinCacheGrind, daarin zie je duidelijk dat er bijvoorbeeld 1739 ms besteed worden aan mysqli::query, dat lijkt me vrij duidelijk dus.

Een test met hdparm -Tt /dev/vda1 (mijn schijf) geeft

code:

[rogier@rogier dev]$ sudo hdparm -tT /dev/vda1
[sudo] password for rogier:

/dev/vda1:
 Timing cached reads:   8658 MB in  2.00 seconds = 4333.89 MB/sec
 Timing buffered disk reads: 208 MB in  3.01 seconds =  69.08 MB/sec

Dei snelheden zouden genoeg moeten zijn om wat kb aan data weg te schrijven.

De MySQL config is eigenlijk de standaard config die meekomt met een 'yum install mysql-server', De content van /etc/my.cnf is dan

code:

[mysqld]
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
user=mysql
# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

Via phpMyAdmin kan ik nog meer info geven, maar om dat allemaal hier rücksichtslos te posten gaat wat ver. Er moet eigenlijk nog een index op tijd, dat klopt wel.

[ReenL]

Is er tijdens het berekenen van die statistieken een langzame insert geweest?

Mijn gevoel zegt dat het de disk is. Als iemand in jouw VPS pool het leuk vind om de hele tijd te swappen, dan kan het zomaar zijn dat jouw mysql ervan over zijn nek gaat.

Je kunt langzame queries loggen:
http://dev.mysql.com/doc/refman/5.0/en/slow-query-log.html

Misschien kun je aan de hand van de timestamps regelmaat vinden in wanneer de query langzaam is, want het lijkt nu redelijk willekeurig te komen.

Als je ongeveer kunt voorspellen wanneer dan kun je nog een keer je disk checken en dan kun je dit pas echt uit sluiten in mijn ogen.

[GlowMouse]

Dat je snel kunt lezen, zegt helemaal niks. Die leesacties zeggen niks, zeker op een vps heb je geen idee wat er met de onderliggende hardware gebeurt.

Aangezien je roottoegang hebt, kun je nog preciezer kijken met strace of oprofile wat MySQL precies doet. Het zou mij niet verbazen als een fsync van de transactielog voor problemen zorgt. Je kunt hier omheen werken met innodb_flush_log_at_trx_commit, maar integriteit van je data is dan niet langer gegarandeerd.

Een standaardconfig is erg slecht voor InnoDB, daar valt zeker nog heel veel winst te halen. Maar insert queries van 2 seconden komen niet door een slechte config, er is wat anders aan de hand.

rogierslag schreef op dinsdag 25 oktober 2011 @ 20:21:
Er moet eigenlijk nog een index op tijd, dat klopt wel.

Nee, je moet naar multi-column indices kijken.

[ Voor 13% gewijzigd door GlowMouse op 25-10-2011 20:54 ]

[_js_]

Je hebt ook nog de SHOW INNODB STATUS opdracht die onder andere van de lopende queries laat zien waar ze op wachten.

[kwaakvaak_v2]

En niemand die op het idee komt om te vragen naar de my.conf om te kijken of er wel voldoende buffers in ram geheugen zijn etc?

[ReenL]

kwaakvaak_v2 schreef op woensdag 26 oktober 2011 @ 08:29:
En niemand die op het idee komt om te vragen naar de my.conf om te kijken of er wel voldoende buffers in ram geheugen zijn etc?

ReenL in "[MySQL] hele trage insert"
rogierslag in "[MySQL] hele trage insert"

Hij staat er, dus trek je conclusie.

[rogierslag]

Dit zijn de relevante innoDB statistieken uit phpMyAdmin

code:

Innodb_buffer_pool_pages_data   1,1 k
Innodb_buffer_pool_pages_dirty  0
Innodb_buffer_pool_pages_flushed    413,0 k
Innodb_buffer_pool_pages_free   7,1 k
Innodb_buffer_pool_pages_misc   4
IInnodb_buffer_pool_pages_total     8,2 k
Innodb_buffer_pool_read_ahead   251
Innodb_buffer_pool_read_ahead_evicted   0   
Innodb_buffer_pool_read_requests    89,0 M
Innodb_buffer_pool_reads    739
Innodb_buffer_pool_wait_free    0 
Innodb_buffer_pool_write_requests   558,7 k
...
Buffer pool grootte 131 k KB

Verder zijn de indexen op een aantal tabellen zeker suboptimaal. Deze moeten namelijk nog worden aangemaakt, er staan nu wat tijdelijke indexen her en der. Ik neem aan dat deze indexen verder geen invloed zouden moeten hebben op zo'n simpele insert..?

/edit:
Schrijftest

code:

 dd if=/dev/zero of=/tmp/random schrijfcrap.img bs=8k count=256k
262144+0 records in
262144+0 records out
2147483648 bytes (2.1 GB) copied, 11.3718 s, 189 MB/s

Zou ook voldoende moeten zijn toch?

[ Voor 12% gewijzigd door rogierslag op 26-10-2011 14:19 ]

[rogierslag]

Ik heb wat met de code zitten spelen. Zo moest deze al langere tijd naar PDO worden omgezet ipv de directe concate queries en dergelijke. Het lijkt erop dat mede door middel van de prepare statements de problemen al wat zijn voorkomen.

Ik heb de server zwaar lopen belasten, qua iops. De inserttijd kan dan nog oplopen tot ongeveer 1 seconde. Het gekke is dat die 100'en objecten wel razendsnel worden opgehaald (1 ms per record).

[GlowMouse]

rogierslag schreef op woensdag 26 oktober 2011 @ 10:41:
/edit:
Schrijftest

code:

 dd if=/dev/zero of=/tmp/random schrijfcrap.img bs=8k count=256k
262144+0 records in
262144+0 records out
2147483648 bytes (2.1 GB) copied, 11.3718 s, 189 MB/s

Zou ook voldoende moeten zijn toch?

Dit zegt nog niets over random writes. Nu doet InnoDB ook geen random writes op het moment dat je een INSERT-query uitvoert, maar er wordt wel een schrijfactie uitgevoerd en je weet niet hoelang die duurt.

Een seconde is echt lang voor een insert, je hoort er duizenden per seconde te kunnen doen. Vandaar:

Aangezien je roottoegang hebt, kun je nog preciezer kijken met strace of oprofile wat MySQL precies doet. Het zou mij niet verbazen als een fsync van de transactielog voor problemen zorgt. Je kunt hier omheen werken met innodb_flush_log_at_trx_commit, maar integriteit van je data is dan niet langer gegarandeerd.

[ Voor 9% gewijzigd door GlowMouse op 26-10-2011 16:37 ]

[kwaakvaak_v2]

ReenL schreef op woensdag 26 oktober 2011 @ 10:21:
[...]

ReenL in "[MySQL] hele trage insert"
rogierslag in "[MySQL] hele trage insert"

Hij staat er, dus trek je conclusie.

zie jij er iets in staan wat op geheugen slaat, ik niet namelijk. Zie alleen settings voor pid files etc..

[ReenL]

kwaakvaak_v2 schreef op woensdag 26 oktober 2011 @ 16:57:
[...]
zie jij er iets in staan wat op geheugen slaat, ik niet namelijk. Zie alleen settings voor pid files etc..

Ik ook niet.

Mijn idee was dat er teveel gelogd werd ofzo, maar als my.ini standaard is, dan verwacht ik niet dat daardoor een insert een seconde gaat duren. Dus nogmaals als jij een setting(reeks) weet waar de TS zijn insert query's met 0,9 seconden kan versnellen be my guest.

Punt is dat my.ini er staat en dat je er commentaar op kan geven, inplaats van onterecht zeuren dat niemand om my.ini vraagt.

[GlowMouse]

ReenL schreef op woensdag 26 oktober 2011 @ 17:04:
[...]

Punt is dat my.ini er staat en dat je er commentaar op kan geven, inplaats van onterecht zeuren dat niemand om my.ini vraagt.

Probleem is dat het niet de my.ini is die MySQL inleest. Dat kun je direct zien aan de grootte van de InnoDB buffer pool, die standaard 8 MB is.
Er kan enorm veel aan de hand zijn, van een grote query cache tot trage flushes. Strace of oprofile geeft direct duidelijkheid. Met blijven gissen schiet je niks op.

[kwaakvaak_v2]

Ik vroeg ook om de my.cnf, niet om de my.ini en ik dacht dat het hier op tweakers de gewoonte was om mensen vooral aan te sporen zelf te zoeken.

Maar goed, zo heel af en toe wil ik dan ook best wel eens een keertje aardig zijn, en 'innodb insert performance' in google in typen, en niet geheel onverwacht kom ik dan op een artikel terecht bij mysql zelf.

Feit is, als de query traag is in alle gevallen. Dus ook als je de insert doet direct op de mysql console, je eerst mag, nee moet gaan kijken wat de oorzaak kan zijn van een trage mysql server.

En wat glowmouse terecht opmerkt, innodb luistert een stuk nauwkeuriger met afstellen dan myisam. Zeker dingen als flushes, transacties etc spelen bij innodb een veel grotere rol.

[jip_86]

rogierslag schreef op woensdag 26 oktober 2011 @ 10:41:
Verder zijn de indexen op een aantal tabellen zeker suboptimaal. Deze moeten namelijk nog worden aangemaakt, er staan nu wat tijdelijke indexen her en der. Ik neem aan dat deze indexen verder geen invloed zouden moeten hebben op zo'n simpele insert..?

Ga dat eerst eens doen dan. Doe het desnoods eens helemaal zonder indexen. Gooi ze anders eens hier neer. Je hebt allemaal vage verhalen over die indexen, maar welke je nu allemaal precies hebt word me niet heel duidelijk. Heb sterk het idee dat ze verre van optimaal zijn en voor elke insert de sortering van de index opnieuw bepaald moet worden.

[rogierslag]

code:

[rogier@rogier ~]$ sudo find / | grep my.cnf
[sudo] password for rogier:
/etc/my.cnf
[rogier@rogier ~]$ cat /etc/my.cnf
[mysqld]
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
user=mysql
# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid
[rogier@rogier ~]$

Het is toch echt mijn my.cnf, de enige op de server. my.ini kan die uberhaupt nergens vinden

Verder staan de indexen in de eerste post, deze staan enkel op id en gebruiker. id heeft momenteel een kardinaliteit van 5120, gebruiker 2.

Heb nu ook nog slow query log aangezet, maar mysql meot eerst nog wat langer draaien voordat het probleem optreedt. Zodra ik weer wat meer resultaten heb zal ik die wel ff posten.

Verder kijk ik ngo wel ff naar strace en dergelijke

/edit:
De resultaten van 25000 inserts op de tabel

code:

/usr/libexec/mysqld, Version: 5.5.14-log (MySQL Community Server (GPL)). started with:
Tcp port: 0  Unix socket: /var/lib/mysql/mysql.sock
Time                 Id Command    Argument
# Time: 111027 13:01:58
# User@Host: ######[######] @ localhost []
# Query_time: 1.091540  Lock_time: 0.000034 Rows_sent: 0  Rows_examined: 0
use ledendb;
SET timestamp=1319713318;
INSERT INTO tbl_log (gebruiker,ip,tijd,wat) VALUES ('1','145.94.187.58',NOW(),'test test 60195959');
# Time: 111027 13:04:07
# User@Host: ######[######] @ localhost []
# Query_time: 1.695167  Lock_time: 0.000063 Rows_sent: 0  Rows_examined: 0
use ledendb;
SET timestamp=1319713447;
INSERT INTO tbl_log (gebruiker,ip,tijd,wat) VALUES ('1','145.94.187.58',NOW(),'test test 32674941');
# Time: 111027 13:04:24
# User@Host: ######[######] @ localhost []
# Query_time: 1.601925  Lock_time: 0.000044 Rows_sent: 0  Rows_examined: 0
SET timestamp=1319713464;
INSERT INTO tbl_log (gebruiker,ip,tijd,wat) VALUES ('1','145.94.187.58',NOW(),'test test 35793219');
# User@Host: ######[######] @ localhost []
# Query_time: 1.832111  Lock_time: 0.000069 Rows_sent: 0  Rows_examined: 0
SET timestamp=1319713464;
INSERT INTO tbl_log (gebruiker,ip,tijd,wat) VALUES ('1','145.94.187.58',NOW(),'test test 60305166');
# Time: 111027 13:04:33
# User@Host: ######[######] @ localhost []
# Query_time: 2.018694  Lock_time: 0.000058 Rows_sent: 0  Rows_examined: 0
SET timestamp=1319713473;
INSERT INTO tbl_log (gebruiker,ip,tijd,wat) VALUES ('1','145.94.187.58',NOW(),'test test 28873368');
# User@Host: ######[######] @ localhost []
# Query_time: 2.022885  Lock_time: 0.000118 Rows_sent: 0  Rows_examined: 0
SET timestamp=1319713473;
INSERT INTO tbl_log (gebruiker,ip,tijd,wat) VALUES ('1','145.94.187.58',NOW(),'test test 50920472');
# Time: 111027 13:04:43
# User@Host: ######[######] @ localhost []
# Query_time: 1.936710  Lock_time: 0.000111 Rows_sent: 0  Rows_examined: 0
SET timestamp=1319713483;
INSERT INTO tbl_log (gebruiker,ip,tijd,wat) VALUES ('1','145.94.187.58',NOW(),'test test 40544543');
# User@Host: ######[######] @ localhost []
# Query_time: 1.938267  Lock_time: 0.000090 Rows_sent: 0  Rows_examined: 0
SET timestamp=1319713483;
INSERT INTO tbl_log (gebruiker,ip,tijd,wat) VALUES ('1','145.94.187.58',NOW(),'test test 36157937');
# Time: 111027 13:05:17
# User@Host: ######[######] @ localhost []
# Query_time: 1.567666  Lock_time: 0.000036 Rows_sent: 0  Rows_examined: 0
SET timestamp=1319713517;
INSERT INTO tbl_log (gebruiker,ip,tijd,wat) VALUES ('1','145.94.187.58',NOW(),'test test 93572692');
# User@Host: ######[######] @ localhost []
# Query_time: 1.566235  Lock_time: 0.000044 Rows_sent: 0  Rows_examined: 0
SET timestamp=1319713517;
INSERT INTO tbl_log (gebruiker,ip,tijd,wat) VALUES ('1','145.94.187.58',NOW(),'test test 72680363');
# Time: 111027 13:05:27
# User@Host: ######[######] @ localhost []
# Query_time: 1.776654  Lock_time: 0.000048 Rows_sent: 0  Rows_examined: 0
SET timestamp=1319713527;
INSERT INTO tbl_log (gebruiker,ip,tijd,wat) VALUES ('1','145.94.187.58',NOW(),'test test 55148486');
# User@Host: ######[######] @ localhost []
# Query_time: 1.780004  Lock_time: 0.000043 Rows_sent: 0  Rows_examined: 0
SET timestamp=1319713527;
INSERT INTO tbl_log (gebruiker,ip,tijd,wat) VALUES ('1','145.94.187.58',NOW(),'test test 40696849');

Bovenstaande testcase werd uitgevoerd door het framework van de webapplicatie, door een aanroep naar doLog in een forloopje te zetten. doLog zelf ziet er zo uit

PHP:

function doLog ( $strMelding )
{
    global $db;
    
    $query = $db->prepare("INSERT INTO tbl_log (gebruiker,ip,tijd,wat) VALUES (?,?,NOW(),?)");
    return $query->execute( array (USER_ID,GetClientIp(),$strMelding) );
}

Tenslotte (sorry voor de giga edit) lijkt het erop dat het probleem pas na verloop van tijd begint te ontstaan. Mysqld is gerestart en eigenlijk treden de problemen nu nauwelijks op, terwijl het aantal inserts in één uur meer is dan de afgelopen weken bij elkaar. Misschien zit er ergens een probleem met betrekking tot een buffer of iets dergelijks die volloopt.

/edit2:
Het toevoegen van wat extra configuratie aan /etc/my.cnf lost al redelijk wat op, de excessen komen in ieder geval niet meer voor (als in ik kan het niet meer reproduceren)

code:

innodb_buffer_pool_size=64MB
query_cache_type = 1
query_cache_size = 16M

[ Voor 72% gewijzigd door rogierslag op 27-10-2011 14:19 ]