[Debian Jessie/Beaglebone] Pico CMS laadt traag, CPU spikes

[Borromini]

Ik heb m'n webserver thuis gemigreerd van mijn x86_64 system naar de Beaglebone Black (eerste staat niet constant aan, tweede wel, da's handiger).

De configuratie is eenvoudig - Lighttpd met PHP, en daar bovenop Pico CMS. Licht, snel, geen database nodig - perfect voor mij. Dat draaide goed op mijn x86 server (ook Debian Jessie). Nu ik het geheel naar de Beaglebone Black verhuisd heb, duurt het 2-3s eer een pagina op de blog laadt, en dat belast de processor ook even voor 100%.

Ik heb het volgende al kunnen vaststellen/uitsluiten:

• De blog (PHP) heeft 2-3s nodig om eender welke pagina te laden, dat belast de CPU even voor 100%.
• De downloadpagina - gewoon een dir listing - laadt normaal, dus het lijkt erop dat het probleem niet bij Lighttpd ligt.
• Als ik php-cgi aanroep via SSH, dan zie ik dat hij ook een paar seconden hangt voor hij HTML genereert.
• Ik heb in Lighttpd FastCGI debugging aangezet maar daar lijkt niks mis te lopen, de PHP interpreter doet er echt 2-3s over.
• CPU governor van 'ondemand' naar 'performance' gewijzigd. Laadtijd blijft 2-3s.

Site: http://www.volatilesystems.org, de downloadpagina (die dus normaal laadt) is http://www.volatilesystems.org/dl/.

Wat kan ik doen om het probleem verder te onderzoeken? Ik heb de configuraties zo goed als één op één overgezet (van Lighttpd en Pico), de PHP-configuratie heb ik niet aangeraakt op de Beaglebone, die is stock.

Ik weet niet of dit in NOS hoort of in netwerken btw. Maar aangezien het op Linux draait...

[MacGrumpy]

Volgens mij geef je zelf al duidelijk aan dat de Beagle Bone Black niet snel genoeg is voor de php blog.

pico cms lijkt markdown gebaseerd? is het mogelijk om de 'gerenderde' paginas te cachen? in de plaats ze elke keer op nieuw te genereren?

[johnkeates]

Kan je met XDebug niet een profile draaien en die door CallGrind of Valgrind ofzo halen?

[Borromini]

MacGrumpy schreef op donderdag 10 juli 2014 @ 22:05:
Volgens mij geef je zelf al duidelijk aan dat de Beagle Bone Black niet snel genoeg is voor de php blog.

Hoe dan? Een ARM v7 1 GHz CPU lijkt me toch snel zat voor wat PHP... Zo intensief is PHP nu ook weer niet, of vergis ik me daar in? Anders zijn commerciële ARM-servers een slechte gok van AMD .

pico cms lijkt markdown gebaseerd? is het mogelijk om de 'gerenderde' paginas te cachen? in de plaats ze elke keer op nieuw te genereren?

Ik heb PHP caching (APC) geprobeerd maar dat maakt niks uit. Ik kan de uiteindelijke HTML wel in een statische map dumpen maar dat is geen definitieve oplossing.

johnkeates schreef op donderdag 10 juli 2014 @ 22:08:
Kan je met XDebug niet een profile draaien en die door CallGrind of Valgrind ofzo halen?

Daar ga ik naar kijken, bedankt.

[ Voor 14% gewijzigd door Borromini op 11-07-2014 15:06 ]

[MacGrumpy]

Borromini schreef op vrijdag 11 juli 2014 @ 15:06:
[...]

Hoe dan? Een ARM v7 1 GHz CPU lijkt me toch snel zat voor wat PHP... Zo intensief is PHP nu ook weer niet, of vergis ik me daar in? Anders zijn commerciële ARM-servers een slechte gok van AMD .

Mee eens (ik doelde ook meer op pico cms blog te traag dan de BBB), het klinkt voornamelijk alsof pico-cms niet zo efficient is als ze beweren. Ik draai zelf een tt-rss instance op een 800 mhz v5 arm en die is een veel sneller (terwijl hardware veel trager). Heb je in pico-cms de twig cache aanstaan?

[ Voor 4% gewijzigd door MacGrumpy op 11-07-2014 15:27 ]

[Borromini]

Nee. Er zijn nog mensen die gesuggereerd hebben dat Pico misschien nogal inefficiënt is.

Ik ga dat aanpassen als ik thuis ben en es testen. Bedankt voor de tip.

[ Voor 36% gewijzigd door Borromini op 11-07-2014 15:32 ]

[Kees]

Inderdaad trace met XDebug, of met strace kijken waar de php mee bezig is. Of een 'pro-trial' nemen bij newrelic.

[ Voor 20% gewijzigd door Kees op 11-07-2014 16:01 ]

[Borromini]

Ok.

Ik heb Twigs cache-functionaliteit ingeschakeld. In de cachedir zie ik nu één PHP-bestand opduiken (functionaliteit gisteren ingeschakeld, timestamp op bestand van zelfde tijdstip). Dat blijft beperkt tot dat ene bestand. Ik neem aan dat niks abnormaals is (aangezien ik maar één layout gebruik?). De laadtijd met of zonder Twig cache is identiek.

Ik heb strace gedraaid, als er iemand even zou willen meekijken? Ik heb er geen ervaring mee. Het lijkt me wel dat er nogal veel tijdsinfo wordt opgevraagd, weet niet of dit abnormaal is.

Zonder argumenten produceert het zo'n 1000 regels aan output, ik weet niet of dat de juiste manier is om het te checken?

Hieronder wat strace -s geeft. Waar elke pagina 2-3s nodig heeft om te laden lijkt strace te vertellen dat php het op een paar honderdste seconden afgehandeld heeft... Lijkt me erg bizar (of het probleem moet weer ergens anders zitten).

code:

root@enceladus:/var/www/pico# strace -c >/dev/null php-cgi index.php
PHP Notice:  Undefined index: HTTP_HOST in /var/www/pico/lib/pico.php on line 301
PHP Notice:  Undefined index: REQUEST_URI in /var/www/pico/lib/pico.php on line 301
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 51.48    0.000157           0       671         1 stat64
 48.52    0.000148           3        54           mprotect
  0.00    0.000000           0       140           read
  0.00    0.000000           0         2           write
  0.00    0.000000           0        75         5 open
  0.00    0.000000           0        97           close
  0.00    0.000000           0         1           unlink
  0.00    0.000000           0         1           execve
  0.00    0.000000           0        56           lseek
  0.00    0.000000           0        32        28 access
  0.00    0.000000           0        15           brk
  0.00    0.000000           0         3         3 ioctl
  0.00    0.000000           0       134           gettimeofday
  0.00    0.000000           0         2           readlink
  0.00    0.000000           0        26           munmap
  0.00    0.000000           0         1           fchmod
  0.00    0.000000           0         2           setitimer
  0.00    0.000000           0         1           uname
  0.00    0.000000           0        20           _llseek
  0.00    0.000000           0         6           rt_sigaction
  0.00    0.000000           0         7           rt_sigprocmask
  0.00    0.000000           0         5           getcwd
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0       108           mmap2
  0.00    0.000000           0        51         3 lstat64
  0.00    0.000000           0       131           fstat64
  0.00    0.000000           0        56           getdents64
  0.00    0.000000           0        38           fcntl64
  0.00    0.000000           0         3           futex
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1         1 getpeername
  0.00    0.000000           0        28           openat
  0.00    0.000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    0.000305                  1770        41 total
System call usage summary for 32 bit mode:
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
   nan    0.000000           0         1           set_tls
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                     1           total

Ter vergelijking, time geeft dit als resultaat:

code:

# time (php-cgi index.php)
real    0m1.829s
user    0m1.670s
sys     0m0.110s

Ik heb ook xdebug geïnstalleerd, maar het logbestand is te groot voor pastebin en andere paste-sites (en voor GoT. Ik heb het hier geüpload:

http://www.volatilesystems.org/dl/trace.1488429128.xt

[ Voor 98% gewijzigd door Borromini op 12-07-2014 23:08 ]

[Borromini]

.

[ Voor 99% gewijzigd door Borromini op 12-07-2014 21:30 . Reden: Was strace output zonder argumenten. ]

[CH4OS]

Borromini schreef op vrijdag 11 juli 2014 @ 15:06:
Ik heb PHP caching (APC) geprobeerd maar dat maakt niks uit. Ik kan de uiteindelijke HTML wel in een statische map dumpen maar dat is geen definitieve oplossing.

APC is een PHP OpCode cache. Dat is een andere cache dan de cache van de totale output, die je al hebt draaien. Voordat het PHP-script gecached is gaat wel even overheen. Hoe het precies werkt weet ik niet precies.

[FireDrunk]

Heb je al eens gekeken naar de hoeveelheid geheugen die in de php.ini aangegeven staat? is dat default niet te weinig ofzo? Op Debian staat dat default misschien wel anders dan op je BeagleBone.

Just a thought.

[Kees]

Wat ik zie in die trace is een bizar grote hoeveelheid functioncalls, er is blijkbaar geen enkele moeite genomen om het een beetje soepel te houden.

That said, even een kleine drilldown later:
0.3196 222712 -> Pico->get_pages() /var/www/pico/lib/pico.php:68
Deze functie doet er ruim 4,1 seconden over in de trace. Verder zie je in je strace heel veel stat calls waar hij verreweg het langste mee bezig is.

Die kun je goed cachen met APC of de default php 5.5 opcode cacher:

opcache.revalidate_freq = 10 << hoe lang de stat calls te cachen, in jouw geval langer dan dit)
opcache.enable_file_override = 1

of

apc.ttl				= 0
apc.stat			= 10

Verder kan ik het hele pico niet, maar mischien is de output van Michelf\Markdown te cachen (doet er ook bijna een seconde of 4 over in de trace). Het zal wel iets van Markup toevoegen zijn, en dat is iets wat je uitstekend kan cachen.

FireDrunk schreef op dinsdag 15 juli 2014 @ 12:00:
Heb je al eens gekeken naar de hoeveelheid geheugen die in de php.ini aangegeven staat? is dat default niet te weinig ofzo? Op Debian staat dat default misschien wel anders dan op je BeagleBone.

Just a thought.

Te weinig geheugen merk je wel. Dan krijg je een fatal error en niet een langzame pagina.

[ Voor 18% gewijzigd door Kees op 15-07-2014 12:53 ]

[deadinspace]

Borromini schreef op zaterdag 12 juli 2014 @ 21:03:
Ter vergelijking, time geeft dit als resultaat:

code:

# time (php-cgi index.php)
real    0m1.829s
user    0m1.670s
sys     0m0.110s

En wat voor resultaat krijg je als je dat doet op het vorige systeem (het x86-64 systeem)? En wat voor een CPU zit daar precies in?

[Borromini]

Kees schreef op dinsdag 15 juli 2014 @ 12:52:
Wat ik zie in die trace is een bizar grote hoeveelheid functioncalls, er is blijkbaar geen enkele moeite genomen om het een beetje soepel te houden.

Die stat calls wijzen voor het overgrote deel naar timezone-bestanden, niet naar de timezone die ik zelf gebruik, maar naar zowat alle die er beschikbaar zijn. Geen idee waarvoor dat nuttig is.

That said, even een kleine drilldown later:
0.3196 222712 -> Pico->get_pages() /var/www/pico/lib/pico.php:68
Deze functie doet er ruim 4,1 seconden over in de trace. Verder zie je in je strace heel veel stat calls waar hij verreweg het langste mee bezig is.

Die kun je goed cachen met APC of de default php 5.5 opcode cacher:

opcache.revalidate_freq = 10 << hoe lang de stat calls te cachen, in jouw geval langer dan dit)
opcache.enable_file_override = 1

of

apc.ttl				= 0
apc.stat			= 10

Bedankt, dat ga ik testen. Ik had eerder uapc (da's wat er in Debian Testing beschikbaar is) geïnstalleerd maar dat leek niet veel zoden aan de dijk te zetten, misschien dat de configuratie niet volledig was.

Verder kan ik het hele pico niet, maar mischien is de output van Michelf\Markdown te cachen (doet er ook bijna een seconde of 4 over in de trace). Het zal wel iets van Markup toevoegen zijn, en dat is iets wat je uitstekend kan cachen.

Ik heb even gecheckt maar kan niet direct een kant en klare oplossing vinden in die richting. Op Stack Overflow wordt wel vermeld dat Markdown CPU-intensief is.

Ik heb momenteel de cache-plugin ingeschakeld in Pico, dat werkt netjes eenmaal de pagina's gerenderd zijn. Als APC geen verschil maakt dan houd ik het bij Pico's caching, ik ga niet in de code gaan wroeten (mijn PHP-kennis is erg oppervlakkig).

Bedankt in ieder geval voor jullie tijd .

deadinspace schreef op dinsdag 15 juli 2014 @ 12:56:
[...]

En wat voor resultaat krijg je als je dat doet op het vorige systeem (het x86-64 systeem)? En wat voor een CPU zit daar precies in?

Een Celeron G1610.

time(php5-cgi /var/chroot/var/www/pico/index.php)
real    0m1.037s
user    0m0.268s
sys     0m0.016s

[ Voor 8% gewijzigd door Borromini op 15-07-2014 22:49 ]

[deadinspace]

Borromini schreef op dinsdag 15 juli 2014 @ 16:46:
Een Celeron G1610.

time(php5-cgi /var/chroot/var/www/pico/index.php)
real    0m1.037s
user    0m0.268s
sys     0m0.016s

Da's een best hoge real time gezien de user en sys?

Maargoed, afgaande op user+sys is het op je Celeron dus ongeveer 6 keer zo snel als op je Beaglebone. Hij is ook 2.6 keer zo hoog geklokt, dus genormaliseerd naar kloksnelheid is het op je Celeron 2.4 keer zo snel als op je ARM cpu. Dat vind ik niet geheel ongeloofwaardig eigenlijk.

Het zou dus kunnen dat het snelheidsverschil tussen die twee systemen vrij normaal is. In dat geval zou ik zeggen dat picocms iets minder pico is dan de naam doet vermoeden

Kun je vanuit picocms geen statische HTML genereren ofzo? Dat is altijd snel

[Borromini]

Ja, via de cache-plugin. En inderdaad, zo lightweight is het niet heb ik de indruk

[Rainmaker]

Allereerst; de pagina laadt bij mij in 1.27 seconden (0.02 seconden voor rendering):


De /dl laadt in 300 ms, dus de PHP is inderdaad langzamer, wat natuurlijk nogal logisch is.

Als ik even door de strace output kijk (geweldige tool btw), denk ik dat deze niet echt representatief is. Je strace retourneert namelijk in 0.000305 seconden.
Dus, waarschijnlijk is het alleen merkbaar als je ook daadwerkelijk parameters meegeeft.

Desalniettemin lijkt er een behoorlijk aantal stat() calls gedaan te worden. Waarschijnlijk wordt er een directory o.i.d. gescand. Ik zou dus eerder denken aan I/O, in plaats van CPU als bottleneck.

Probeer eens

code:

strace -Te stat php-cgi...

?

[Borromini]

De stat() calls wijzen vooral naar /usr/share/timezone. Welke output verwacht je van de -Te stat optie? 't Is maar dat, als ik dat draai, er geen cijfers tevoorschijn komen...

root@enceladus:/var/www/phile# strace -Te stat php-cgi index.php
--- SIGILL {si_signo=SIGILL, si_code=ILL_ILLOPC, si_addr=0xb6e26ce8} ---
PHP Notice:  Undefined index: HTTP_HOST in /var/www/phile/lib/Phile/Utility.php on line 53
PHP Notice:  Undefined index: REQUEST_URI in /var/www/phile/lib/Phile/Utility.php on line 53
PHP Notice:  Use of undefined constant on - assumed 'on' in /var/www/phile/config.php on line 22
PHP Notice:  Use of undefined constant on - assumed 'on' in /var/www/phile/config.php on line 24
PHP Notice:  Undefined offset: 1 in /var/www/phile/lib/Phile/Core.php on line 111
PHP Notice:  Undefined offset: 1 in /var/www/phile/lib/Phile/Core.php on line 111
PHP Notice:  Undefined offset: 1 in /var/www/phile/lib/Phile/Core.php on line 111
the key date for sorting is deprecated use meta:date or any other meta tag
Status: 500 Internal Server Error
Content-type: text/html; charset=UTF-8

<html>
[snip]
+++ exited with 0 +++