Magento, vertraging door de cache?

Sinds korte tijd hebben wij een nieuwe grote webshop erbij. Geen probleem, daar is netjes een apart cluster voor aangemaakt, en een prive applicatie server, en de website is sneller dan ooit. Klinkt fantastisch, maar toch zijn er een paar kleine probleempjes met deze site.

Zo kregen wij van de klant door dat de site af en toe heel even extreem langzaam was, en bijna niet meer te bereiken. Een vergelijking van de tijdstippen van deze meldingen met de grafieken en logs die wij bijhouden bevestigde deze meldingen. Hoge load, veel I/O, veel interrupts.

Vanmiddag was het weer zo ver, zoals te zien, maar waren we net ingelogd op de server waar het gebeurde, waardoor we nu ook veel gegevens konden verzamelen. Wat bleek? Veel php5 processen die erg druk met de schijf bezig waren. Even snel gestrace‘d, en daar kwamen tientallen pagina’s zoals onderstaand uit, elk met een andere locale setting.

open("/home/users/domeinftp/domein.nl/var/cache/mage--a/mage---internal-metadatas ---Zend_LocaleC_zh_TW_country_TW", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFIL flock(5, LOCK_EX)                       = 0 write(5, "a:4:{s:4:\"hash\";i:1092545841;s:5:"..., 98) = 98 flock(5, LOCK_UN)                       = 0 close(5)                                = 0 chmod("/home/users/domeinftp/domein.nl/var/cache/mage--a/mage---internal-metadatas ---Zend_LocaleC_zh_TW_country_TW", 0600) = 0 stat64("/home/users/domeinftp/domein.nl/var/cache/mage--a/mage---Zend_LocaleC_zh_TW _country_TW", {st_mode=S_IFREG|0600, st_size=13, ...}) = 0 open("/home/users/domeinftp/domein.nl/var/cache/mage--a/mage---Zend_LocaleC_zh_TW _country_TW", O_RDONLY|O_LARGEFILE) = 5 fstat64(5, {st_mode=S_IFREG|0600, st_size=13, ...}) = 0 flock(5, LOCK_SH)                       = 0 read(5, "s:6:\"\350\207\272\347\201\243\";"..., 8192) = 13 flock(5, LOCK_UN)                       = 0 close(5)                                = 0

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17

open("/home/users/domeinftp/domein.nl/var/cache/mage--a/mage---internal-metadatas   ---Zend_LocaleC_zh_TW_country_TW", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFIL flock(5, LOCK_EX)                       = 0 write(5, "a:4:{s:4:\"hash\";i:1092545841;s:5:"..., 98) = 98 flock(5, LOCK_UN)                       = 0 close(5)                                = 0 chmod("/home/users/domeinftp/domein.nl/var/cache/mage--a/mage---internal-metadatas   ---Zend_LocaleC_zh_TW_country_TW", 0600) = 0 stat64("/home/users/domeinftp/domein.nl/var/cache/mage--a/mage---Zend_LocaleC_zh_TW   _country_TW", {st_mode=S_IFREG|0600, st_size=13, ...}) = 0 open("/home/users/domeinftp/domein.nl/var/cache/mage--a/mage---Zend_LocaleC_zh_TW   _country_TW", O_RDONLY|O_LARGEFILE) = 5 fstat64(5, {st_mode=S_IFREG|0600, st_size=13, ...}) = 0 flock(5, LOCK_SH)                       = 0 read(5, "s:6:\"\350\207\272\347\201\243\";"..., 8192) = 13 flock(5, LOCK_UN)                       = 0 close(5)                                = 0

Korte samenvatting? Magento maakt een grote cache aan met daarin honderden kleine files. Deze worden geopened, iets in weggeschreven, en daarna op read-only gezet. Nog wat dieper gezocht, en het bleek de default caching van Zend::Cache::File te zijn. Deze slaat alle gegevens die Magento aangeeft op in een File cache, welke daarna weer door Magento ingelezen kon worden. Een goed idee, maar niet zo super uitgevoerd. Dit werkt inderdaad prima voor langzame servers, of servers met een snelle cache. Maar File caching is niet zo snel, het wegschrijven op de schijf en het weer inlezen zijn redelijk zware acties voor een server.

private function _filePutContents($file, $string) { $result = false; $f = @fopen($file, 'wb'); if ($f) { if ($this->_options['file_locking']) @flock($f, LOCK_EX); $tmp = @fwrite($f, $string); if (!($tmp === FALSE)) { $result = true; } if ($this->_options['file_locking']) @flock($f, LOCK_UN); @fclose($f); } //Uitgecomment door byte - mogelijke oorzaak vertragings pieken. //@chmod($file, $this->_options['cache_file_umask']); return $result; }

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17

private function _filePutContents($file, $string) {   $result = false;   $f = @fopen($file, 'wb');   if ($f) {     if ($this->_options['file_locking']) @flock($f, LOCK_EX);     $tmp = @fwrite($f, $string);     if (!($tmp === FALSE)) {       $result = true;     }     if ($this->_options['file_locking']) @flock($f, LOCK_UN);     @fclose($f);   }   //Uitgecomment door byte - mogelijke oorzaak vertragings pieken.   //@chmod($file, $this->_options['cache_file_umask']);   return $result; }

Omdat het toch een prive server betreft, hebben we hier een paar kleine veranderingen aan gemaakt. Geen idee nog of dit het gewenste effect gaat hebben, maar het kan zeker geen kwaad om op elke cache opsla actie wat system calls te besparen. Want, zoals boven te zien in de grafiek, het zijn de extra system calls die ineens vertraging veroorzaken.

Waarom dit ineens spontaan gebeurt op willekeurige tijden, helaas nog geen idee, maar we gaan het zo eens proberen. Mocht dit nou geen effect hebben op de snelheid van Magento, dan gaan we maar eens kijken of de klant op een andere Backend kan overstappen. Zend ondersteunt namelijk native APC, EAccelerator, of Memcached. Een daarvan moet toch goed moeten werken, zou je denken.