Performanceproblem

Hallo,

habe in einer Transaktion mehrere Statements abzuarbeiten, wobei diese Transaktion unter PostgreSQL ca. 2 Minuten benötigt und als Vergleich mit der SQLBase von der wir Richtung PostgreSQL wechseln, die selbe Transaktion nur ca. 3 Sekunden benötigt.

Folgendes Statement wurde als der Flaschenhals identifiziert (habe mit der Entwicklungsumgebung im Debug/Animationsmodus jene Statements rausgepickt, bei denen die App auf das Ergebnis lange gewartet hat:

explain analyse select sum (coalesce(nettobetrag,0)-coalesce(rabattbetrag,0)), sum (coalesce(ustbetrag,0)),
sum (coalesce(bruttobetrag,0)), sum (1), sum(coalesce(is_ausgelifert,0)), sum(coalesce(is_fakturiert,0)),
sum (coalesce(ekwert,0)), sum (coalesce(anzeigenabgabe,0))

from sysadm.aufpos where auftraginr = 615404 and ebene = 0;


Wenn ich das Statement Analysiere komme ich auf Superkurze Antwortzeiten:

“Aggregate (cost=622.23…622.25 rows=1 width=75) (actual time=0.282…0.282 rows=1 loops=1)”
" -> Index Scan using xif23aufpos on aufpos (cost=0.00…619.01 rows=160 width=75) (actual time=0.026…0.033 rows=2 loops=1)"
" Index Cond: (auftraginr = 615404)"
" Filter: (ebene = 0)"
“Total runtime: 0.421 ms”

Die Anzahl der Datensätze die summiert werden sollen schwankt zwischen 1 - bis ca. 100, wobei der vorhandene Index benutzt wird.

Wie ist das möglich? Die PG läuft einem HP Dual Xenon 2,4GHz, 2GB Speicher auf einem Raid-1 System.

Das postgresql.conf File hat folgende Einstellungen:

port = 5432
max_connections = 100
shared_buffers = 256MB
maintenance_work_mem = 16MB
max_fsm_pages = 204800
fsync = on
effective_cache_size = 512MB
stats_start_collector = on
stats_row_level = on
autovacuum = on

Die restlichen Parameter sind auskommentiert.

Jeder Hinweis zur Beschleunigung der Kiste ist herzlich willkommen.

Hans

Dein Select hat an der Laufzeit von ca. 2 Minuten lediglich einen Anteil von 0.4ms. Da sehe ich keinen Spielraum für Optimierungen.

Andreas

Da hat akretschmer Recht, das kann nicht die problematische Stelle sein:

(cost=622.23..622.25 rows=1 width=75) (actual time=0.282..0.282 rows=1 loops=1)

PostgreSQL denkt vorher, es braucht ungefähr 620 Plattenzugriffe, um das auszuführen (ANALYZE mal laufen lassen), effektiv ausgeführt werden kann das aber in einem Plattenzugriff. Alles in allem sind selbst die geschätzten 600 Zugriffe in ein paar Millisekunden erledigt, dass das ganze noch schneller ist, siehst du ja an der Ausführungszeit.

habe ANALYZE auf die betreffende Datenbank ausgeführt. Beim erstenmal dauert obige Transaktion ca. 1 min, beim 2-ten…n-ten mal ausführen can 15 sec.

Da muß es doch noch einige Schrauben geben, an denen man drehen kann.

Ich kann nicht glauben, dass die PG (lt. Performance Test vom Juli/2007 12% langsamer als Oracle und 10% schneller als MySql) von einer Pimperldatenbank wie der SQLBase überholt wird (Datenbankgröße 5GB, in 3 Tabellen die in die Transaktion involviert sind, existieren jeweils ca. 1,2 - 1,4 Mio Datensätze).

Was sagt Ihr dazu?

Gruß
Hans

Wir sagen dazu: wir haben keine Ahnung, wie deine Datenbank aufgebaut ist.

Ausserdem haben wir aufgezeigt, das die Stelle von der du dachtest das sie ein Problem ist, das nun genau nicht ist.
Also muss dein Problem woanders liegen :wink:

Zu was?

PG braucht etwas Pflege in Form von VACUUM und ANALYSE, aber das sollte kein Problem darstellen. Ansonsten muß man halt das Select und die Meinung von EXPLAIN ANALYSE dazu betrachten. Es gibt Anwender, die haben etliche Zehnerpotenzen mehr Daten in ihrem System und keine Probleme.

Andreas

Ich glaubs auch nicht :slight_smile:

Ähm wie?
Ich dachte obiger Request dauert 0.4 ms?

Bist Du dir sicher, dass du nicht den falschen (oder zu wenig) explain analyse gepastet hast?

Grüße

Jochen

Und stell mal deine log-settings um:
log_statement_stats = on

Ich hab jetzt mal die Statements beisammen mit der Analyse. Beim Update habe ich nur zwei statt den zwanzig Spalten genommen (war etwas mühselig die einzelnen Werte aus de Bindvariablen zu holen), es geht aber über den PK wobei ein Rowlvel Trigger gefeuert wird um die roversion zu prüfen ob sie noch gleich ist wie vor dem Update (wenn ja, wir um eins weitergezählt, wenn nein: bekommt der User eine Meldung (raise exception) daß jemand anderer die gleiche row bereits geändert hat.


Die Werte:
select distinct lsinr from sysadm.lieferschein where auftraginr = 615344;

“Unique (cost=8.74…8.77 rows=6 width=8)”
" -> Sort (cost=8.74…8.75 rows=6 width=8)"
" Sort Key: lsinr"
" -> Index Scan using lief_auftraginr on lieferschein (cost=0.00…8.66 rows=6 width=8)"
" Index Cond: (auftraginr = 615344)"



select max (a.ebene) from sysadm.aufpos a, sysadm.rechpos r
where a.auftraginr = 615344 and r.reinr =3243143 and a.auftraginr = r.auftraginr and a.aufposinr = r.aufposinr;

“Aggregate (cost=592.54…592.55 rows=1 width=8)”
" -> Nested Loop (cost=0.00…592.53 rows=1 width=8)"
" -> Index Scan using xif51rechpos on rechpos r (cost=0.00…584.13 rows=1 width=16)"
" Index Cond: (reinr = 3243143)"
" Filter: (auftraginr = 615344)"
" -> Index Scan using xpkaufpos on aufpos a (cost=0.00…8.39 rows=1 width=24)"
" Index Cond: (a.aufposinr = r.aufposinr)"
" Filter: (auftraginr = 615344)"


select kurs_1, kurs_2, eingabewaehrung, p_sonder_rabatt, rowversion
from sysadm.auftrag where auftraginr =615344;

“Index Scan using xpkauftrag on auftrag (cost=0.00…8.29 rows=1 width=45)”
" Index Cond: (auftraginr = 615344)"


select sum (coalesce(nettobetrag,0) - coalesce(rabattbetrag,0)), sum (coalesce(ustbetrag,0)),
sum (coalesce(bruttobetrag,0)), sum (1), sum(coalesce(is_ausgelifert,0)), sum(coalesce(is_fakturiert,0)),
sum (coalesce(ekwert,0)), sum (coalesce(anzeigenabgabe,0))
from sysadm.aufpos where auftraginr = 615344 and ebene = 0;

“Aggregate (cost=594.98…594.99 rows=1 width=75)”
" -> Index Scan using xif23aufpos on aufpos (cost=0.00…591.78 rows=159 width=75)"
" Index Cond: (auftraginr = 615344)"
" Filter: (ebene = 0)"


select sum (coalesce(netto_abzgl_rab,0)), sum (coalesce(netto_abzgl_rab_1,0)), sum (coalesce(netto_abzgl_rab_2,0))
from sysadm.lieferschein where auftraginr = 615344;

“Aggregate (cost=8.71…8.72 rows=1 width=34)”
" -> Index Scan using lief_auftraginr on lieferschein (cost=0.00…8.66 rows=6 width=34)"
" Index Cond: (auftraginr = 615344)"


UPDATE sysadm.auftrag SET wert_auftrag = 89,03, rowversion = 4 WHERE auftraginr = 615344;
“Index Scan using xpkauftrag on auftrag (cost=0.00…8.29 rows=1 width=1083)”
" Index Cond: (auftraginr = 615344)"


So wie es aussieht muß es wohl am ODBC Treiber liegen. Meiner hat die Version 8.2.4 vom 27.04.2007

Liege ich mit meiner Vermutung richtig?

Gruß
Hans

Das waren nur EXPLAIN, nicht EXPLAIN ANALYSE. Davon abgesehen sah es aber ned schlecht aus, keine Seq-Scans.

So wie es aussieht muß es wohl am ODBC Treiber liegen. Meiner hat die Version 8.2.4 vom 27.04.2007

Liege ich mit meiner Vermutung richtig?

Gruß
Hans

Kann ich nicht sagen, weil ich noch immer nicht sehe, wo die Zeit sein soll. Das erste EXPLAIN ANALYSE im ursprünglichen Beitrag lief ja nur 0,4ms. Bis zu der vor Dir dort genannten Zeit von 2 Minuten fehlen noch 119.9996 Sekunden.


Andreas

Hielte ich für nen recht voreiligen Schluss. Deine version ist zwar nicht die aktuellste, ist aber ja auch nicht sooo weit aus der Welt …


Ehrlich gesagt … nicht böse sein … ich tippe a bisserl auf die Applikation … fühlt sich wie irgend ein timout an, wenns immer 120 sekunden sein sollten

Aber vorgehen wiefolgt:
1.) Datenbankproblem ausschließen -> explain analyses pasten
2.) ODBC-Settings checken
3.) App durchleuchten
4.) Erst dann Schuld auf ODBC-Treiber schieben :wink:



Grüße

jochen

Hallo Hans,

ändere mal in der postgresql.conf folgende Einstellungen

client_min_messages = debug5
log_min_messages = debug5
log_error_verbosity = verbose
log_min_error_statement = debug5

Nach den Senden des SELECT-Befehl vom Client kannst Du in der LOG-Datei analysieren, wie der SELECT-Befehl vom Server ausgeführt wurde. Ein Beispiel hierzu findest Du unter diesem Link: PG-Forum.de - Einzelnen Beitrag anzeigen - Wunderliche Queries aus psql-odbc treiber & M$Access. Jochen “dasblauehandtuch” musste mit ODBC auch so einige Erfahrungen machen.

Um eine Referenzzeit zu erhalten, solltest Du auf dem Datenbank-Server pgAdmin installieren und den SELECT-Befehl im Query-Dialog ausführen. In der Statuszeile, unten rechts, wird auch eine Zeit für die Ausführung des Befehls angegeben. Diese ist bei der ersten Ausführung des Befehls in der Regel länger. Also den Befehl mehrmals ausführen und den Mittelwert bilden. Da pgAdmin über den LOCALHOST zugreift sind Zeiten, die durch die Applikation und das Netz entstehen, weitgehendst eleminiert.




mfg

fristo

a) es gibt über dem Eingabefeld einen Knopf für CODE, wenn man den benutzt und die Ausgaben dort hineinpackt, werden die auch schön formatiert dargestellt

b) wenn du eine andere Anfrage an die Datenbank stellst als die, welche das eigentliche Problem ist, wirst du nicht weiterkommen. Wenn deine Ausgabe nur auf 2 statt 20 IDs eingeschränkt ist, erstellt PostgreSQL einen anderen Anfrageplan, der gut auf deine neue, kleine Anfrage passt. Du wirst also die eigentliche, problematische Anfrage stellen müssen und dir dafür den Queryplan zeigen lassen müssen. Alles andere hat keinen Sinn.

Danke für die Hilfe,

habe mittlerweile folgendes rausgefunden: Die Datenbank ist sehr schnell, der Transport des Resultsets dauert sehr lange. Das liegt aber nicht an einem überlasteten Netzwerk, sondern an der Größe des Empfanspuffers der Applikation. Gottseidank kann ich diesen verändern und habe jetzt eine Einstellung die mir Clientseitig einen Puffer von 32KB bereitstellt. Damit haben sich die zwei Minuten auf 5 sec. reduziert.

Womit ich noch nicht klarkomme sind die vielen Parameter im ODBC-Treiber. Gibt es dazu eine Beschreibung? Ich habe diesbezüglich nix gefunden außer Mutmaßungen anderer User.

Ein Frage noch zum Autovacuum:
In den Logfiles wurde auch immer der Start von Autovacuum protokolliert. Der kommt ziemlich häufig, kann man den reduzieren? Oder stört er die Datenbank nicht?

Habe folgende Einstellungen:
autovacuum = on # enable autovacuum subprocess?

‘on’ requires stats_start_collector

and stats_row_level to also be on

#autovacuum_naptime = 1min # time between autovacuum runs
#autovacuum_vacuum_threshold = 500 # min # of tuple updates before

vacuum

#autovacuum_analyze_threshold = 250 # min # of tuple updates before

analyze

#autovacuum_vacuum_scale_factor = 0.2 # fraction of rel size before

vacuum

#autovacuum_analyze_scale_factor = 0.1 # fraction of rel size before

analyze

#autovacuum_freeze_max_age = 200000000 # maximum XID age before forced vacuum

(change requires restart)

#autovacuum_vacuum_cost_delay = 200 # default vacuum cost delay for

autovacuum, -1 means use

vacuum_cost_delay

#autovacuum_vacuum_cost_limit = 100 # default vacuum cost limit for

autovacuum, -1 means use

vacuum_cost_limit



Herzliche Grüße
Hans

Vielleicht auf der Homepage zum ODBC-Treiber.

Ein Frage noch zum Autovacuum:
In den Logfiles wurde auch immer der Start von Autovacuum protokolliert. Der kommt ziemlich häufig, kann man den reduzieren? Oder stört er die Datenbank nicht?

Ich würde es lassen, der Daemon stört nicht. Ansonsten schau mal hier rein:
PostgreSQL: Documentation: Manuals: PostgreSQL 8.2: Routine Vacuuming

Andreas

Hier sind die Dokus zur aktuellen Version
http://cvs.pgfoundry.org/cgi-bin/cvsweb.cgi/psqlodbc/psqlodbc/docs/config-opt.htmlhttp://cvs.pgfoundry.org/cgi-bin/cvsweb.cgi/psqlodbc/psqlodbc/docs/http://cvs.pgfoundry.org/cgi-bin/cvsweb.cgi/~checkout~/psqlodbc/psqlodbc/docs/config.html?rev=1.8&content-type=text/html

Grüße

Jochen