Postgres 8.4.13: DEALLOCATE ist langsam

Hallo zusammen,
ich habe auf einem Ubuntu 10.04-Server ein Tool namens Netdisco installiert, mit dem Daten zu Netzwerk-Switch-Ports angezeigt werden. Diese Daten stehen in einer Postgresql-DB. Die über die Paketverwaltung installierte Version 8.4.13 funktioniert grundsätzlich, nur dauert der Seitenaufbau der Weboberfläche dauert viel zu lange (teilweise bis zu 2 Minuten). In der /etc/postgresql/8.4/main/postgresql.conf habe ich log_statement = ‘all’ aktiviert, und im Logfile /var/log/postgresql/postgresql-8.4-main.log sehe ich folgenden Ausschnit:

2012-10-01 13:08:52 CEST LOG:  Anweisung: SELECT 'DBD::Pg ping test'
2012-10-01 13:08:52 CEST LOG:  Ausführen dbdpg_p10032_861: SELECT ip,dns FROM device WHERE (ip = '172.16.1.21')
2012-10-01 13:08:52 CEST LOG:  Anweisung: DEALLOCATE dbdpg_p10032_861
2012-10-01 13:08:52 CEST LOG:  Anweisung: SELECT 'DBD::Pg ping test'
2012-10-01 13:08:52 CEST LOG:  Ausführen dbdpg_p10032_862: SELECT ip,dns FROM device_ip WHERE (alias = '172.16.1.21')
2012-10-01 13:08:52 CEST LOG:  Anweisung: DEALLOCATE dbdpg_p10032_862
2012-10-01 13:08:52 CEST LOG:  Anweisung: SELECT 'DBD::Pg ping test'
2012-10-01 13:08:52 CEST LOG:  Ausführen dbdpg_p10032_863: SELECT ip,dns FROM device WHERE (ip = '172.16.1.9')
2012-10-01 13:08:52 CEST LOG:  Anweisung: DEALLOCATE dbdpg_p10032_863
2012-10-01 13:08:52 CEST LOG:  Anweisung: SELECT 'DBD::Pg ping test'
2012-10-01 13:08:52 CEST LOG:  Ausführen dbdpg_p10032_864: SELECT ip,dns FROM device_ip WHERE (alias = '172.16.1.9')
2012-10-01 13:08:52 CEST LOG:  Anweisung: DEALLOCATE dbdpg_p10032_864
2012-10-01 13:08:52 CEST LOG:  Anweisung: SELECT 'DBD::Pg ping test'
2012-10-01 13:08:52 CEST LOG:  Ausführen dbdpg_p10032_865: SELECT ip,dns FROM device WHERE (ip = '172.16.254.125')
2012-10-01 13:08:52 CEST LOG:  Anweisung: DEALLOCATE dbdpg_p10032_865
2012-10-01 13:08:52 CEST LOG:  Anweisung: SELECT 'DBD::Pg ping test'
2012-10-01 13:08:52 CEST LOG:  Ausführen dbdpg_p10032_866: SELECT ip,dns FROM device_ip WHERE (alias = '172.16.254.125')
2012-10-01 13:08:52 CEST LOG:  Anweisung: DEALLOCATE dbdpg_p10032_866
2012-10-01 13:09:27 CEST LOG:  Anweisung: SELECT 'DBD::Pg ping test'
2012-10-01 13:09:27 CEST LOG:  Ausführen dbdpg_p10032_867: SELECT ip,dns FROM device WHERE (ip = '172.16.1.5')
2012-10-01 13:09:27 CEST LOG:  Anweisung: DEALLOCATE dbdpg_p10032_867
2012-10-01 13:09:27 CEST LOG:  Anweisung: SELECT 'DBD::Pg ping test'
2012-10-01 13:09:27 CEST LOG:  Ausführen dbdpg_p10032_868: SELECT ip,dns FROM device_ip WHERE (alias = '172.16.1.5')
2012-10-01 13:09:27 CEST LOG:  Anweisung: DEALLOCATE dbdpg_p10032_868

Wenn ich es richtig verstehe, dauert die Funktion “DEALLOCATE” bei bestimmten Datensätzen so lange (hier z.B. 35 Sekunden), das summiert sich dann. Wie kann ich hier weiter vorgehen, woran kann das liegen?

Danke und schöne Grüße
Mana

Warum glaubst Du, dass das DEALLOCATE 35 Sekunden dauert? In dem Logfile stehen doch überhaupt keine Laufzeiten drin.

Hallo castorp,
weil zwischen dem Start der “DEALLOCATE” und dem Start des nächsten “SELECTS” 35 Sekunden vergangen sind:

2012-10-01 13:08:52 CEST LOG:  Anweisung: DEALLOCATE dbdpg_p10032_866
2012-10-01 13:09:27 CEST LOG:  Anweisung: SELECT 'DBD::Pg ping test'

So habe ich es zumindest interpretiert, oder stimmt das so nicht?

d.h. nur, dass das Programm nachdem Freigeben des Statements 35 Sekunden lang nichts gemacht hat.

Ausführungszeiten werden getrennt protokolliert (aber dazu musst Du log_min_duration in der Konfiguration einschalten)

Hallo castorp,
danke für den Hinweis, habe jetzt die Ausführungszeiten mitprotokolliert, die sind wirklich alle sehr schnell. Hast du eine Idee, woher diese Gedenkminuten zwischendurch kommen können?

Keine Ahnung was diese Anwendung da macht. Aber solltest Du nicht besser wissen, was das Tool macht, dass ihr da installiert habt?

Aber ich finde es überhaupt nicht ungewöhnlich, dass eine Anwendung 35 Sekunden lang keine Anfrage zur Datenbank schickt.
Im Gegenteil ich fände es alarmierend, wenn die Anwendung ständig, ohne Pause Abfragen abschickt.

Warum erwartest Du, dass die Anwendung die Anfragen ohne Pause abschickt?

Hallo castorp,
weil an dieser Reihe von Abfragen der Seitenaufbau hängt, bevor die Abfragen nicht beendet sind, wird die Webseite nicht angezeigt. Auf einem anderen Testserver funktioniert das tadellos und schnell, aber jetzt wollte ich das Tool auf dem Produktivserver einsetzen, wo jetzt diese Probleme auftreten…

Frag doch mal, was die Anwendung macht. 35 Sekunden, das könnte z.B. ein TIMEOUT einer DNS-Abfrage sein. Vielleicht befragt die Anwendung ja erfolglos einen Nameserver …

Andreas

Hallo Andreas,
vielen Dank für den Tipp mit DNS, daran lag es tatsächlich!! Hab mir auf der Maschine einen nscd aktiviert, jetzt ist der Seitenaufbau schnell. Postgres war also unschuldig :slight_smile:
Schöne Grüße
Mana

Wenn du einen 35 Sekunden Timeout hast, ist irgendetwas aber gewaltig falsch in deinem DNS-Setup. Da ist der nscd nur ein Workaround, keine Lösung für das eigentliche Problem.