- √ - Ladezeit Cometvisu - rsslog.php

[Chris M.]

Habe nun auf svn rev. 1972 geupdated. Allerdings hat sich am Ladeverhalten nichts geändert. Zuerst wird das rsslog geladen, dann erst die sonstigen Werte. Den Browser Cache habe ich geleert!

Auch ein forceReload=true an die URL angehängt?
Das ist bei Tests eigentlich zwingend notwendig. Zumindest wenn man eine Aussage und nicht hoffen möchte..

OT: Ist es eigentlich normal, dass die Seite nach dem Leeren des Browser Cache zwei Mal läd (Seite baut sich auf, bis alle Elemente geladen sind und dann erfolgt nochmals ein Refresh und die Seite läd ein zweites Mal)?

Wenn der Appcache geändert wurde: ja - ist extra als Feature eingebaut, sonst müsste man das per Hand machen.

[XueSheng]

Kannst du vielleicht deine Config und deine RSS-Datei zur Verfügung stellen, gerne auch per PN?

Werde ich tun.

Kannst Du mal das Ladeverhalten außerhalb der CV testen? Also mit sqlite auf der shell?

# sqlite /etc/wiregate/rss/rsslog.db "SELECT id, title, content, tags, state, strftime('%s', t) AS t FROM Logs ORDER by t DESC LIMIT 20;"

Mit dieser Abfrage erfolgt keine Filterung. Ausführdauer rund 12 Sekunden (entspricht auch der Abfragedauer über das rsslog.php).
Wesentlicher Aspekt ist hierbei das "ORDER by t DESC". Ohne Sortierung und "LIMIT 20" dauert die Abfrage noch keine Sekunde!

Auch ein forceReload=true an die URL angehängt?

Ja, habe ich angefügt. Ändert aber nichts.

[XueSheng]

Noch ein kurzer Nachtrag zum aktuellen Stand.
Ich habe testweise meine config auf wenige Gruppenadressen (auf einer page) und das rsslog reduziert. Bei dieser Konstellation werden die Werte bereits geladen bevor das rsslog zu sehen ist (so wie es auch sein sollte). Hierbei ist das Verhalten bei svn rev. 1971 und 1972 (subjektiv) identisch.

Nehme ich allerdings meine gesamte config (mit mehreren pages), werden die Werte erst nach dem Laden des rsslog angezeigt (hierbei vergehen von sichtbarwerden der config mit Platzhaltern "-" bzw. "NaN" rund 6-7 Sekunden).

Wenn ich rsslog allerdings aus meta/pulgins entferne, dauert das Laden der Werte nur 1-2 Sekunden.

Die Aussagen scheinen etwas widersprüchlich zu sein... aber für mich hat es den Anschein, dass beim Laden vieler Werte und gleichzeitigem Laden des rsslog noch etwas schief läuft.

Meine Vermutung ist folgende (kann totaler blödsinn sein):
Werte werden auf der ersten (sichtbaren) page abgefragt (jedoch noch nicht angezeigt).
Dann wird rsslog geladen.
Dann werden die Werte auf den übrigen pages geladen.
Dann erfolgt erst die Freigabe zur Anzeige aller Werte.


Config und rsslog.db habe ich an MicHau geschickt.

[netzkind]

Der Zugriff auf die sqlite Datenbank sortiert nach t, dem timestamp. Es ist aber kein Index auf t. Da aber beim INSERT t sowieso auf NOW gesetzt wird, kann man stattdessen beim Auslesen nach id sortieren, da dies die identische Reihenfolge wie t bedeutet, aber den PRIMARY KEY nutzt.

So wie der query im Moment geschrieben ist, nutzt er keinen Index. Das zu beheben sollte das erste Ziel sein - da sollte vorgenannte Optimierung schon wesentlich helfen.

Grüße,
Julian

[XueSheng]

Das Thema "index" ist hier auf jeden Fall von großer Relevanz. Wobei das offensichtlich auch nicht immer einfach zu handhaben ist.
Zunächst habe ich einen index mit Bezug auf "id" erstellt. Hierbei musste ich feststellen, dass die SQL Abfrage noch langsamer wurde! 14-16 Sekunden anstatt 12 Sekunden Abfragedauer.
Ähnliche Probleme konnte ich auch über eine Google-Suche finden.

Letztendlich habe ich nun den Index der "id" wieder gelöscht und einen Descending Index auf "t" erstellt... und siehe da, die Abfrage dauert nun nur noch wenige Millisekunden. Das nenn ich mal einen Unterschied.

Zur Vollständigkeit der Befehl zum Erstellen des Index:

# sqlite /etc/wiregate/rss/rsslog.db
sqlite> CREATE INDEX t_index ON logs (t desc);

[netzkind]

Das Thema "index" ist hier auf jeden Fall von großer Relevanz. Wobei das offensichtlich auch nicht immer einfach zu handhaben ist.
Zunächst habe ich einen index mit Bezug auf "id" erstellt. Hierbei musste ich feststellen, dass die SQL Abfrage noch langsamer wurde! 14-16 Sekunden anstatt 12 Sekunden Abfragedauer.
Ähnliche Probleme konnte ich auch über eine Google-Suche finden.

Letztendlich habe ich nun den Index der "id" wieder gelöscht und einen Descending Index auf "t" erstellt... und siehe da, die Abfrage dauert nun nur noch wenige Millisekunden. Das nenn ich mal einen Unterschied.

Zur Vollständigkeit der Befehl zum Erstellen des Index:

# sqlite /etc/wiregate/rss/rsslog.db
sqlite> CREATE INDEX t_index ON logs (t desc);

Per Doku von sqlite ist das Feld id ein Alias auf ROWID, und außerdem bereits ein Primary Key. Da einen zweiten Index drauf zu machen ist Unsinn.
Siehe auch sqlite-Doku zum Thema INTEGER PRIMARY KEY/rowid:
"The data for each table in SQLite is stored as a B-Tree structure containing an entry for each table row, using the rowid value as the key. This means that retrieving or sorting records by rowid is fast. Searching for a record with a specific rowid, or for all records with rowids within a specified range is around twice as fast as a similar search made by specifying any other PRIMARY KEY or indexed value" (Quelle: http://www.sqlite.org/lang_createtable.html)

Damit man den Index auch nutzt, muss natürlich der Quellcode des SQL-Query angepasst werden, so dass es ein ORDER BY id verwendet - sonst hilft der Index nicht.

Einen zusätzlichen Index auf den timestamp zu machen... Naja.
Gleichzeitig verlangsamt man mit jedem zusätzlichen Index alle Inserts, da nicht mehr ein, sondern mehrere Indizes gepflegt werden müssen.

Grüße,
Julian

[XueSheng]

Damit man den Index auch nutzt, muss natürlich der Quellcode des SQL-Query angepasst werden, so dass es ein ORDER BY id verwendet - sonst hilft der Index nicht.

Einen zusätzlichen Index auf den timestamp zu machen... Naja.

Getestet habe ich nicht mit dem rsslog.php, sondern direkt in der Konsole. Den SQL-Query habe ich natürlich auf "ORDER BY id" angepasst. Allerdings wurde das Ganze dadurch nur langsamer. Warum? Keine Ahnung.

Ob es nun unschön ist den timestamp zu indizieren kann ich nicht sagen, aber bei meinen Tests war das mit Abstand die schnellste Variante.

Offensichtlich hast Du viel Ahnung von dem Thema. Welche konkreten Anpassungen müssten denn Deiner Meinung nach erfolgen? Deine Umschreibungen sind für mich (unwissenden) nicht eindeutig genug!

[netzkind]

Getestet habe ich nicht mit dem rsslog.php, sondern direkt in der Konsole. Den SQL-Query habe ich natürlich auf "ORDER BY id" angepasst. Allerdings wurde das Ganze dadurch nur langsamer. Warum? Keine Ahnung.

Das kann ich aus der Ferne schwer diagnostizieren.
Du kannst aber mal das Szenario wieder herstellen, und dann den SELECT noch mal abfeuern, aber mit einem EXPLAIN davor (EXPLAIN SELECT...). Dadurch kommt man zur Erläuterung, wie sqlite den Query abarbeiten will, und ob/welche Indizes es verwenden will. Das kann wesentlich weiterhelfen.

Welche konkreten Anpassungen müssten denn Deiner Meinung nach erfolgen? Deine Umschreibungen sind für mich (unwissenden) nicht eindeutig genug!

Ich würde annehmen dass ein guter Index und dessen Nutzung reicht, um das Problem zu lösen. Mit den Ausgaben vom EXPLAIN kann man schauen, wie man da am besten vorgeht.

Grüße,
Julian

[XueSheng]

Dann wollen wir mal mit den Details beginnen. Das Ganze läuft übrigens auf dem Wiregate.

# sqlite version
SQLite version 2.8.17

Ich habe die ursprüngliche Datenbank wiederhergestellt.

# sqlite /etc/wiregate/rss/rsslog.db "select * from sqlite_master;"                                                        table|Logs|Logs|3|CREATE TABLE Logs(  id INTEGER PRIMARY KEY,  title TEXT,  content TEXT NOT NULL,  tags TEXT,  t TIMESTAMP,  state INT)

Hier die Abfrage mit "ORDER BY t" mit Zeitmessung (bei mir i.d.R. 2 Sekunden schneller als "ORDER BY id").

# START=$(date +%s); sqlite /etc/wiregate/rss/rsslog.db "SELECT id FROM Logs ORDER BY t DESC LIMIT 20;" >/dev/null; END=$(date +%s); echo "RUNTIME: $(($END-$START))";
RUNTIME: 6

Hier die Abfrage mit "ORDER BY id" mit Zeitmessung.

# START=$(date +%s); sqlite /etc/wiregate/rss/rsslog.db "SELECT id FROM Logs ORDER BY id DESC LIMIT 20;" >/dev/null; END=$(date +%s); echo "RUNTIME: $(($END-$START))";
RUNTIME: 8

Hier das "EXPLAIN SELECT" der Abfrage:

# sqlite /etc/wiregate/rss/rsslog.db "EXPLAIN SELECT id FROM Logs ORDER BY id DESC LIMIT 20;"
0|ColumnName|0|1|id
1|Integer|-20|0|
2|MemStore|0|1|
3|ColumnName|1|0|INTEGER
4|Integer|0|0|
5|OpenRead|0|3|Logs
6|VerifyCookie|0|235|
7|Rewind|0|14|
8|Recno|0|0|
9|SortMakeRec|1|0|
10|Recno|0|0|
11|SortMakeKey|1|0|-
12|SortPut|0|0|
13|Next|0|8|
14|Close|0|0|
15|Sort|0|0|
16|SortNext|0|21|
17|MemIncr|0|20|
18|SortCallback|1|0|
19|Goto|0|16|
20|Pop|1|0|
21|SortReset|0|0|
22|Halt|0|0|

[XueSheng]

Hab das Ganze eben mal mit sqlite3 (version 3.5.9) getestet (mit sqlite2 einen dump erstellt und dann mit sqlite3 wieder importiert). Damit geht das "ORDER BY id" auf jeden Fall flott. "ORDER BY t" ist etwas schneller als vorher.

ORDER BY t

# START=$(date +%s); sqlite3 /etc/wiregate/rss/rsslog.sqlite3.db "SELECT id FROM Logs ORDER BY t DESC LIMIT 20;" >/dev/null; END=$(date +%s); echo "RUNTIME: $(($END-$START))";
RUNTIME: 5

ORDER BY id

# START=$(date +%s); sqlite3 /etc/wiregate/rss/rsslog.sqlite3.db "SELECT id FROM Logs ORDER BY id DESC LIMIT 20;" >/dev/null; END=$(date +%s); echo "RUNTIME: $(($END-$START))";
RUNTIME: 0

Hilft mir allerdings nicht, da auf dem wiregate kein sqlite3 für php5 zur Verfügung steht.

Ist das Ganze jetzt ein Problem der alten sqlite Version?

[ctr]

Das kann ich jetzt nicht einschätzen, aber Deine Ergebnisse legen es Nahe (btw, benutze doch einfach ein "time" anstatt dieser date/runtime Konstruktion)

Das wäre dann mal wieder ein Beispiel dafür, dass es echt traurig, dass das WG auf Lenny (inzwischen seit über 1,5 Jahren offiziell unsupported) bleibt, aber der Rant gehört eher ins WG Forum anstatt hierher.

[MicHau]

Nehme ich allerdings meine gesamte config (mit mehreren pages), werden die Werte erst nach dem Laden des rsslog angezeigt (hierbei vergehen von sichtbarwerden der config mit Platzhaltern "-" bzw. "NaN" rund 6-7 Sekunden).

Wenn ich rsslog allerdings aus meta/pulgins entferne, dauert das Laden der Werte nur 1-2 Sekunden.

Die Aussagen scheinen etwas widersprüchlich zu sein... aber für mich hat es den Anschein, dass beim Laden vieler Werte und gleichzeitigem Laden des rsslog noch etwas schief läuft.

Meine Vermutung ist folgende (kann totaler blödsinn sein):
Werte werden auf der ersten (sichtbaren) page abgefragt (jedoch noch nicht angezeigt).
Dann wird rsslog geladen.
Dann werden die Werte auf den übrigen pages geladen.
Dann erfolgt erst die Freigabe zur Anzeige aller Werte.


Config und rsslog.db habe ich an MicHau geschickt.

Erst einmal danke für das Zusenden.

Ich habe soeben versucht, dein Problem nachzustellen, kann aber leider deine Beobachtungen nicht nachvollziehen. Ich bekomme auf der Startseite zuerst die Werte der GAs angezeigt und dann wird mit einiger Verzögerung erst der Inhalt des RSSLog angezeigt.
Das komische ist, dass das auch mit der vorherigen Version so funktioniert, also vor meinen Änderungen.

Ich bin etwas ratlos, weil es eigentlich so läuft, wie es gewünscht ist.

[ctr]

(mit sqlite2 einen dump erstellt und dann mit sqlite3 wieder importiert)

Kannst Du das mal mit sqlite2 machen? Also quasi alte db dumpen und in eine neue sqlite2 einlesen und die dann benutzen anstatt der Alten.
Nach dem was michau gerade geschrieben hat, ist es vielleicht nur ein Problem der Fragmentierung (obwohl dies eigtl *gerade* bei Flash-Speicher so gut wie keine Auswirkung haben sollte)

[XueSheng]

Habe ich schon versucht. Jedoch ohne Erfolg. Wie bereits geschrieben, geht sqlite2 ja auch flott, wenn ich mit dem timestamp einen index erstelle.

[netzkind]

Ich fasse zusammen:
Auf dem wiregate läuft eine sehr alte Sqlite-Version (Dezember 2005), die sich in dem Szenario komplett seltsam verhält.
Das Problem lässt sich umgehen, indem auf t ein Index gemacht wird.

Super, dann machen wir das.
Ich würde vorschlagen, dann auch im rsslog.php das CREATE-Statement anzupassen.

Grüße,
Julian