Posts Tagged ‘Langsam’

Dienstag, 1. November 2016

upc cablecom Performance an der Melchtalstrasse im Breitenrain

Eine Bekannte von mir hat sich vor einigen Wochen darüber beschwert, dass die Performance ihrer Internetverbindung von upc cablecom (Quadruple Play Kabel-Anbieter hier in der Schweiz) in ihrer Wohnung an der Melchtalstrasse im bernischen Breitenrain gelegentlich zu wünschen übrig lässt.

Sie war sich sicher, dass die in ihrem aktuellen Internet-Abo als Best Effort versprochene 200 MBit/s Downloadgeschwindigkeit und 20 MBit/s Uploadgeschwindigkeit während den angesprochenen Phasen nie und nimmer erreicht werden.

Ich habe ihr deshalb Anfangs Oktober 2016 einen Linux-Laptop (Lenovo X200s mit Gigabit-Ethernet, welcher mit Cat 5e-Kabel direkt am Router TP-LINK WNDR3600 hängt) ins Netzwerk gehängt, welcher jede Stunde einen Ookla Speedtest mit dem Fiber7-Server durchführt und mir die Werte zurückmeldet.

Nach drei Wochen Monitoring verfestigt sich das Bild, dass mit der Internet-Anbindung tatsächlich etwas faul ist. An praktisch jedem Tag zeigt sich im RRDtool-Graph dasselbe Bild: Ab ca. 18 Uhr bricht die Downloadgeschwindigkeit von annähernd 200 MBit/s zunehmend ein, erreicht mit ca. 40 MBit/s den Tiefpunkt und erholt sich ab 22 Uhr langsam wieder:

upc-cablecom-melchtalstrasse-bern-tag
image-7027

upc-cablecom-melchtalstrasse-bern-woche
image-7028

Meine Vermutung: Im Breitenrain könnte die Studentendichte sowie die Dichte der Yuppies sehr hoch sein. Diese schauen nach Feierabend nicht TV, sondern werfen sich Netflix & Konsorten (vielleicht sogar Bittorrent?) an und streamen sich die TV-Sendungen und Filme ihrer Wahl. Was dafür spricht: Am letzten Wochenende war der Einbruch noch dramatischer als unter der Woche. Der Graph zeigt, dass ausserhalb der Stosszeiten die versprochenen Bandbreiten erreicht werden.

Und nein, meine Bekannte sabotiert sich nicht selber: Sie hat unregelmässige Arbeitszeiten (Früh- und Spätschicht, manchmal auch an Wochenenden), weshalb sie in vielen Fällen von den Geschwindigkeitseinbrüchen gar nichts mitbekommt.

Und was tut der ISP, der hoffentlich über ein viel, viel ausgeklügelteres Monitoring verfügt als ich? Nichts. Wie für unsere Halunken-ISPs hier in der Schweiz so üblich versteckt man sich hinter der Vertragsklausel Best Effort, überbucht das Netz gnadenlos und lenkt den Umsatz nicht in den Ausbau des Netzes, sondern lässt diesen in die Taschen der grosskapitalistischen Shareholder in Übersee fliessen. Und natürlich hofft man darauf, dass der dumme Benutzer nicht auf die Idee kommt, regelmässig Geschwindigkeitsmessungen durchzuführen.

upc cablecom, bitte aufwachen! Im Breitsch braucht es eine grössere Leitung, aber bitte zack zack!

Tags: , , , , , , , , , , , , ,
Labels: Schweiz

Keine Kommentare | neuen Kommentar verfassen

Sonntag, 25. Januar 2015

OneNote 2010 extrem langsam

Da ich bei meinem Arbeitgeber faktisch gezwungen bin, in einem Microsoft-Umfeld zu arbeiten, bin ich auch mit Microsofts OneNote in Kontakt gekommen. Und für einmal muss ich festhalten, dass diese Software eigentlich noch ganz OK ist. Ich verwende sie wie ein Wiki, um mit Arbeitskollegen Infos zu laufenden Prüfungen aufzuzeichen, u.a. Interview-Notizen.

Mitte letzter Woche äusserte sich plötzlich das Problem, dass OneNote 2010 bei der Niederschrift von Notizen äussert träge reagierte — teilweise dauerte es eine oder zwei Sekunden, bis ein betätigter Buchstabe auf dem Bildschirm erschien. Im Task Manager, welchen ich zu Analyse-Zwecken parallel geöffnet hatte, konnte ich sehen, dass die CPU-Auslastung des Prozesses auf bis 25 Prozent anstieg.

Ich googlete herum, konnte aber für einmal nicht wirklich hilfreiche Tipps finden. Aus Verzweiflug heraus sprach ich den Bürokollegen an und bat ihn um Hilfe. Sein Vorschlag, doch alle nicht benötigten Notizbücher zu schliessen, erwies sich als goldrichtig. Als ich nämlich halbwegs durch die Liste durch war, entdeckte ich das Übel: Ein Notizbuch enthielt hunderte Kind-Elemente. Dies deshalb, weil offenbar jemand eine ZIP-Datei voller Screenshots in den Notizbuch-Ordner entpackt hatte. Jedes Bild wurde als Notizbuch-Element angezeigt.

Nebenbei: OneNote 2010 scheint offenbar so schitter programmiert zu sein, dass bei jedem Tastendruck alle Notizbücher neu eingelesen respektive auf Veränderungen gescannt werden.

Tags: , , , ,
Labels: IT

Keine Kommentare | neuen Kommentar verfassen

Dienstag, 13. Januar 2015

WordPress vor dem Ausreizen des RAM-Speicher bewahren

Seit einigen Wochen finden sich in meiner php.err täglich Einträge wie den folgenden:

...
[12-Jan-2015 14:19:24 UTC] PHP Fatal error:  Out of memory (allocated 9699328) (tried to allocate 78720 bytes) in /blog/wp-includes/script-loader.php on line 528
[12-Jan-2015 14:19:24 UTC] PHP Fatal error:  Out of memory (allocated 8126464) (tried to allocate 49152 bytes) in /blog/wp-includes/comment-template.php on line 2163
[12-Jan-2015 14:19:24 UTC] PHP Fatal error:  Out of memory (allocated 1572864) (tried to allocate 3072 bytes) in /blog/wp-includes/functions.php on line 3514
[12-Jan-2015 14:19:24 UTC] PHP Fatal error:  Out of memory (allocated 6291456) (tried to allocate 3072 bytes) in /blog/wp-includes/post.php on line 670
[12-Jan-2015 19:59:36 UTC] PHP Fatal error:  Out of memory (allocated 19660800) (tried to allocate 8 bytes) in /blog/wp-includes/pomo/mo.php on line 237
[12-Jan-2015 19:59:36 UTC] PHP Fatal error:  Out of memory (allocated 23592960) (tried to allocate 32 bytes) in /blog/wp-includes/pomo/mo.php on line 243
[12-Jan-2015 19:59:36 UTC] PHP Fatal error:  Out of memory (allocated 16252928) (tried to allocate 49152 bytes) in /blog/wp-content/plugins/stop-spammer-registrations-plugin/stop-spammer-registrations.php on line 163
[12-Jan-2015 19:59:36 UTC] PHP Fatal error:  Out of memory (allocated 22544384) (tried to allocate 32 bytes) in /blog/wp-includes/pomo/mo.php on line 237
[12-Jan-2015 19:59:36 UTC] PHP Fatal error:  Out of memory (allocated 18350080) (tried to allocate 1920 bytes) in /blog/wp-includes/default-widgets.php on line 914
[12-Jan-2015 19:59:36 UTC] PHP Fatal error:  Out of memory (allocated 22806528) (tried to allocate 94 bytes) in /blog/wp-includes/pomo/mo.php on line 250
[12-Jan-2015 19:59:36 UTC] PHP Fatal error:  Out of memory (allocated 22282240) (tried to allocate 32 bytes) in /blog/wp-includes/pomo/mo.php on line 243
[12-Jan-2015 19:59:36 UTC] PHP Fatal error:  Out of memory (allocated 20709376) (tried to allocate 12288 bytes) in /blog/wp-content/plugins/wptouch/themes/foundation/modules/sharing/sharing.php on line 126
[12-Jan-2015 19:59:36 UTC] PHP Fatal error:  Out of memory (allocated 20971520) (tried to allocate 12288 bytes) in /blog/wp-content/plugins/wptouch/themes/foundation/modules/social-links/social-links.php on line 54
[12-Jan-2015 19:59:36 UTC] PHP Fatal error:  Out of memory (allocated 21495808) (tried to allocate 12449 bytes) in /blog/wp-includes/pomo/streams.php on line 113
...

Egal, ob ein WordPress-Update, eine Aktualisierung eines Plugins oder Überbuchungen meines Hosting-Servers durch Cyon der Auslöser war — ich wollte mein Log vor solchen Einträgen bewahren.

Nachfolgend eine Anleitung, wie ich vorgegangen bin:

TPC! Memory Usage

Als erstes installierte ich das Plugin TPC! Memory Usage, welches die Speicherauslastung bei jedem Aufruf eines WordPress-Artikels aufzeichnet und im Administrations-Dashboard anzeigt.

Ca. 120 vom Plugin innerhalb weniger Minuten automatisch generierte und versendete E-Mails später hatte ich dann auch herausgefunden, dass ich in der Administrationsoberfläche im schwarzen, vertikalen Menubalken unter Memory Usage > Einstellungen > Notify if memory usage exceeds: den Schwellenwert von 32MB auf 64MB erhöhen musste, um von der Mailflut verschont zu werden.

Der Schwellenwert ist übrigens auch in der Datei tpcmem-core.php hardkodiert, falls jemand den Wert vor dem Upload der Dateien in die WordPress-Installation anpassen möchte:

...
add_option('tpc_memory_usage_email_high_usage', 32);
...

P3 (Plugin Performance Profiler)

Nachdem ich mit dem Plugin und den automatisch versendeten E-Mails die hohe Speicherauslastung durch meine WordPress-Installation bestätigt hatte, stiess ich mit einer Google-Suche auf folgenden Artikel:

How to monitor and reduce WordPress memory usage by plugins

Ich entschied mich, das in diesem Artikel erwähnte Plugin P3 (Plugin Performance Profiler) zu installieren und auszuführen. Beim ersten Durchlauf wurde ich wieder mit TPC!-Notifikations-E-Mails eingedeckt, die Speicherauslastung lag regelmässig über 80 MB.

Die erste Auswertung sah folgendermassen aus:

WordPress Plugin Profile Report
===========================================
Report date: Dienstag, 13. Januar 2015
Theme name: 
Pages browsed: 31
Avg. load time: 2.1364 sec
Number of plugins: 13
Plugin impact: 79.58% of load time
Avg. plugin time: 1.7001 sec
Avg. core time: 0.5284 sec
Avg. theme time: 0.0218 sec
Avg. mem usage: 86.89 MB
Avg. ticks: 88,114
Avg. db queries : 70.94
Margin of error : -0.1139 sec

Plugin list:
===========================================
P3 (Plugin Performance Profiler) - 0.0073 sec - 0.43%
Akismet - 0.0147 sec - 0.86%
Better WordPress Minify - 0.0540 sec - 3.18%
Google Sitemap Generator - 0.0035 sec - 0.21%
Jetpack von WordPress.com - 0.8103 sec - 47.67%
Limit Login Attempts - 0.0257 sec - 1.51%
Simple Lightbox - 0.4993 sec - 29.37%
Stop Spammer Registrations Plugin - 0.0092 sec - 0.54%
SubToMe - 0.0065 sec - 0.38%
Tpc Memory Usage - 0.0311 sec - 1.83%
WP Permalauts - 0.0327 sec - 1.92%
Wp Super Cache - 0.0138 sec - 0.81%
WPtouch Mobile Plugin - 0.1919 sec - 11.29%

Deaktivierung von Jetpack

Eine Google-Suche zeigte, dass ich offenbar nicht der einzige WordPress-Benutzer bin, dessen Jetpack-Plugin mehr als die Hälfte der Ladezeit eines Blog-Artikels ausmacht.

Deshalb entschied ich mich kurzerhand dazu, Jetpack zu deaktivieren. Der nächste Benchmark mit P3 lieferte folgende Zahlen:

WordPress Plugin Profile Report
===========================================
Report date: Dienstag, 13. Januar 2015
Theme name: 
Pages browsed: 17
Avg. load time: 1.2534 sec
Number of plugins: 12
Plugin impact: 60.86% of load time
Avg. plugin time: 0.7629 sec
Avg. core time: 0.4815 sec
Avg. theme time: 0.0994 sec
Avg. mem usage: 76.41 MB
Avg. ticks: 91,763
Avg. db queries : 56.94
Margin of error : -0.0904 sec

Plugin list:
===========================================
P3 (Plugin Performance Profiler) - 0.0014 sec - 0.19%
Akismet - 0.0098 sec - 1.28%
Better WordPress Minify - 0.0315 sec - 4.13%
Google Sitemap Generator - 0.0071 sec - 0.94%
Limit Login Attempts - 0.0108 sec - 1.42%
Simple Lightbox - 0.5075 sec - 66.53%
Stop Spammer Registrations Plugin - 0.0040 sec - 0.52%
SubToMe - 0.0146 sec - 1.92%
Tpc Memory Usage - 0.0284 sec - 3.72%
WP Permalauts - 0.0231 sec - 3.03%
Wp Super Cache - 0.0087 sec - 1.14%
WPtouch Mobile Plugin - 0.1159 sec - 15.20%

Deaktivierung von Simple Lightbox

Das Plugin Simple Lightbox dient dazu, verlinkte Bilder im Grossformat als Overlay über der aktuellen Seite anzuzeigen. Doch war die Funktionalität es wert, über eine halbe Sekunde auf das Plugin zu warten? Ganz klar: Nein.

Ich deaktivierte auch dieses Plugin und führte die Messungen ein drittes Mal durch:

WordPress Plugin Profile Report
===========================================
Report date: Dienstag, 13. Januar 2015
Theme name: 
Pages browsed: 17
Avg. load time: 0.8826 sec
Number of plugins: 11
Plugin impact: 39.13% of load time
Avg. plugin time: 0.3454 sec
Avg. core time: 0.4266 sec
Avg. theme time: 0.1072 sec
Avg. mem usage: 28.44 MB
Avg. ticks: 5,251
Avg. db queries : 55.35
Margin of error : 0.0034 sec

Plugin list:
===========================================
P3 (Plugin Performance Profiler) - 0.0082 sec - 2.36%
Akismet - 0.0118 sec - 3.42%
Better WordPress Minify - 0.0467 sec - 13.53%
Google Sitemap Generator - 0.0064 sec - 1.87%
Limit Login Attempts - 0.0258 sec - 7.46%
Stop Spammer Registrations Plugin - 0.0064 sec - 1.86%
SubToMe - 0.0215 sec - 6.24%
Tpc Memory Usage - 0.0347 sec - 10.05%
WP Permalauts - 0.0271 sec - 7.84%
Wp Super Cache - 0.0110 sec - 3.19%
WPtouch Mobile Plugin - 0.1457 sec - 42.20%

Bravo! Die Zeiten für das Laden der Plugins lag nun durchgehend im Hundertstel-Sekundenbereich, im Fall von WPTouch Mobile im Zehntelssekundenbereich.

Positiver Nebeneffekt: Auch die RAM-Auslastung brach markant ein:

Ursprungszustand 86.89 MB
Ohne Jetpack 70.94 MB
Ohne Jetpack, ohne Simple Lighbox 28.44 MB

Um die doch wirklich nützliche Lightbox-Funktionalität nicht zu verlieren, installierte ich stattdessen folgendes Plugin:

CSS3 Lightbox

Es handelt sich um eine rein CSS-basierte Lösung; der Einfluss auf die PHP-Renderzeiten von WordPress-Seiten ist vernachlässigbar.

Tags: , , , , , , , , ,
Labels: Web

Keine Kommentare | neuen Kommentar verfassen

Samstag, 10. Januar 2015

Safari benötigt 30 Sekunden zum Starten (ungelöst)

Seit einigen Wochen plagt mein Mac OS X 10.9 Mavericks auf einem Mac mini (Late 2012) ein merkwürdiges Problem: Beim Programmstart von Safari springt das Dock-Icon während genau 30 Sekunden auf und ab, bevor das Browser-Fenster erscheint. Ein Logout und ein Login in mein Benutzerkonto beheben das Problem nicht.

Leider habe ich bis jetzt keine Lösung für das Problem gefunden, weshalb ich hier erst einmal dokumentiere, was ich diesbezüglich herausgefunden habe.

Das Apple-Tool fs_usage ist mein Freund. Hier ein Beispiel-Auszug der Dateizugriffe des Safari-Prozesses:

# fs_usage
...
12:37:38.681696  open              F=13       (RW____)  /dev/dtracehelper                                                                                                                                    0.000026   Safari.6649750
12:37:38.681703  ioctl             F=13                                                                                                                                                      0.000006   Safari.6649750
12:37:38.681708  close             F=13                                                                                                                                                                      0.000005   Safari.6649750
12:37:38.681816  stat64                                 /System/Library/StagedFrameworks/Safari/WebInspectorUI.framework/Versions/A/WebInspectorUI                                                           0.000011   Safari.6649750
12:37:38.681836  open              F=13       (R_____)  /System/Library/StagedFrameworks/Safari/WebInspectorUI.framework/Versions/A/WebInspectorUI                                                           0.000018   Safari.6649750
12:37:38.681840  pread             F=13   B=0x1000     O=0x00000000                                                                                                                                          0.000004   Safari.6649750
12:37:38.681842  pread             F=13   B=0x1000     O=0x00004000                                                                                                                                          0.000002   Safari.6649750
12:37:38.681846  fcntl             F=13                                                                                                                                                              0.000002   Safari.6649750
12:37:38.681887  close             F=13                                                                                                                                                                      0.000003   Safari.6649750
12:37:38.684252  socket            F=13                                                                                                                                           0.000007   Safari.6649750
12:37:38.684284  connect           F=13     private/var/run/usbmuxd                                                                                                                                          0.000020   Safari.6649750
12:37:38.684288  ioctl             F=13                                                                                                                                                      0.000002   Safari.6649750
12:37:38.684365  close             F=14                                                                                                                                                                      0.000004   Safari.6649750
12:37:38.684375  sendto            F=13   B=0x10                                                                                                                                                             0.000008   Safari.6649750
12:37:38.684380  sendto            F=13   B=0x1f2                                                                                                                                                            0.000004   Safari.6649750
12:38:08.684465  close             F=14                                                                                                                                                                      0.000018   Safari.6649750
12:38:08.684588  close             F=13                                                                                                                                                                      0.000107   Safari.6649750
12:38:08.688500  stat64                 [  2]           /Library/Managed Preferences>>>>>>>>>>>>>>>>>>>>>>>>>>>>                                                                                             0.000005   Safari.6649750
12:38:08.688805  open              F=13       (R_____)  /Library/Preferences/com.apple.security.plist                                                                                                        0.000010   Safari.6649750
12:38:08.688811  close             F=13                                                                                                                                                                      0.000002   Safari.6649750
12:38:08.689103  stat64                                 /Users/mario/Library/Preferences/com.apple.security.plist                                                                                            0.000043   Safari.6649750
12:38:08.689108  stat64                 [  2]           /Library/Preferences/com.apple.security-common.plist                                                                                                 0.000003   Safari.6649750
12:38:08.689201  getattrlist                            /Users                                                                                                                                               0.000009   Safari.6649750

Zwischen 12:37:38 und 12:38:08 dreht der Prozess Däumchen. Hinweis gibt die folgende Zeile:

12:37:38.684284  connect           F=13     private/var/run/usbmuxd                                                                                                                                          0.000020   Safari.6649750

Safari scheint 30 Sekunden auf den connect zu private/var/run/usbmuxd zu warten.

In Console.app erscheint zudem genau nach 30 Sekunden folgende Meldung:

...
10.01.15 20:35:58.844 Safari[72526]: _SubscribeForMuxNotifications (thread 0x7fff74373310): USBMuxListenerCreate: Operation timed out
...

usbmuxd ist der Daemon, mit welchem iTunes resp. Mac OS X mit iPhones „spricht“ — wenn ich die Erklärungen verstehe so etwas wie TCP-over-USB: Usbmux — The iPhone Wiki.

Tags: , , , , , ,
Labels: Apple

Keine Kommentare | neuen Kommentar verfassen

Sonntag, 14. Dezember 2014

MySQL-Query auf Dev blitzschnell, in Prod extrem langsam

Am Freitag habe ich mich entschieden, eine bisher nur auf meinem lokalen Mac mini in einem Vagrant-Container laufende Web-Applikation auf meinen „produktiven“ Web-Server bei der Cyon GmbH zu verschieben.

Es handelt sich um eine Applikation, mit welcher Fragen einer Zertifizierungsprüfung mittels Multiple Choice beantwortet werden können. Eine Unterseite der Applikation berechnet aus dem Log der bisher getätigten Antworten Statistiken.

Nach einigen Minuten lief die Web-Applikation und der aktuellste MySQL-Dump war ebenfalls auf dem Server eingespielt. Doch dann kam das böse Erwachen: Beim Aufruf einer neuen Frage wartete ich unzählige Sekunden auf eine Antwort des Servers, bis die Ausführung des PHP-Scripts dann mit einem Timeout abbrach.

Was zum Teufel? Rasch war klar, dass ein SQL-Query zur Berechnung von Statistiken der Übeltäter war.

Auf Dev lief das MySQL-Query folgendermassen rasch durch:

[12-Dec-2014 13:22:18 Europe/Zurich] I - mysql->query() took 0.1694 secs in /var/www/apps/%APP%/inc/%APP%.class.php:343 for URI (Referer: unknown) from IP 192.168.1.1 with User Agent "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/600.1.17 (KHTML, like Gecko) Version/7.1 Safari/537.85.10"

Auf Prod hingegen loggte ich diesen Zeitwert:

[12-Dec-2014 12:40:18 Europe/Zurich] I - mysql->query() took 47.8917 secs in %PATH%%APP%.class.php:343 for URI <%URI%> (Referer: %REFERER%) from IP %IP% with User Agent "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/600.1.17 (KHTML, like Gecko) Version/7.1 Safari/537.85.10"

Eine Verlangsamung von mehr als dem 200-fachen!

Als erstes prüfte ich die Versionen der Datenbank-Software:

Dev

-- Server version	5.6.21-1~dotdeb.1

Prod

-- Server version	5.5.40-cll

Ich verwendete also eine Zehntelsversion bessere Datenbank.

Anschliessend liess ich mir das Query sowohl in Dev als auch in der Produktion „erklären“ (EXPLAIN):

Dev

EXPLAIN-localhost
image-6013

Prod

EXPLAIN-cyon
image-6014

Der Unterschied: Auf Prod führte MySQL ein „Dependent Subquery“ aus, auf Dev „nur“ (?) ein „Subquery“. War das das Problem?

Da mir EXPLAIN hier nun wirklich nicht weiterhalf, wendete ich mich Google zu. Folgende zwei Stackexchange-Artikel erheischten meine Aufmerksamkeit:

Beim Lesen der Antworten kam mir plötzlich die Idee: Vielleicht sind INDEXe deine Freunde? Ich wählte die Spalte Questions-id (`Questions-id` varchar(64) NOT NULL, CLSIDs enthaltend) aus und versah sie mit einem Index.

Und siehe da, beim nächstem Aufruf der Web-Seite wurde folgender Zeitwert registriert:

[12-Dec-2014 23:33:09 Europe/Zurich] I - mysql->query() took 0.0412 secs in %PATH%%APP%.class.php:343 for URI <%URI%> (Referer: %REFERER%) from IP %IP% with User Agent "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/600.1.17 (KHTML, like Gecko) Version/7.1 Safari/537.85.10"

Der zusätzliche Index auf einer Spalte auf hat mein Performance-Problem zu meiner vollsten Zufriedenheit gelöst. Wieso der Index aber in Version 5.6 von MySQL nicht mehr benötigt wird, ist mir derzeit noch ein Rätsel. Wahrscheinlich haben die Entwickler die Subquery-Performance in dieser Version stark verbessert?

Tags: , , , , , , , , , , ,
Labels: Web

Keine Kommentare | neuen Kommentar verfassen