Hilfestellung Fehlersuche PG_9.3 und Windows Server 2012 R2

Hallo @all,

nach einer Softwareumstellung läuft ein kommerzielles Programm nun mit einer Postgresql Datenbank auf einem Windows Server (Vorgabe des Herstellers). In dem Zuge wurde die komplette EDV erneuert. Der Dell Server mit Xeon CPU, 12 GB RAM und WIndows 2012 R2 Essentials und Intel Pro1000 NIC sollte ausreichend stark sein, da seitens des Softwareherstellers ein “alter Windowsrechner ausreicht”. Die 5 Clients sind Windows 7 mit Intel CPU. Switch Netgear GS716T. (Alles aktuelle Geräte). Die Software läuft auf allen 5 Clients und greift auf die Datenbank des Servers mit Standardport 5432 zu. Leider rückt der Hersteller der Software nicht mit den Passwörtern (user postgres) heraus, weshalb ein Zugriff auf die Datenbank z.B. per PGAdmin per editierter pg_hba.conf erfolgen kann. EDIT: Die komplette Datenbank hat ca. 220 MB laut PgAdmin. Ein Backup ca. 15MB.

Nun der Fehler:
Wenn alle Clients das Programm geöffnet haben, und einer nun eine Kundenakte öffnen will, so kann es vorkommen, dass sich das Programm etliche Gedenksekunden Zeit nimmt, bis die Akte angezeigt wird. Anders kann ich es auch nicht beschreiben, aber es fühlt sich so an, als ob sich das Programm aufhängt, da es die Daten nicht geliefert bekommt.

Was schon getan:
Die komplette Netzwerkstruktur wurde schon auf Fehler untersucht, inkl. Überprüfung der Datenpakete. Keine Auffälligkeiten, keine Drops, Rejects usw… Die Netzwerkkarten wurden auch schon austauscht, sowie auch der Switch. Da die zu übertragenden Daten nur minimal sind, ist der Fehler nicht wirklich eingrenzbar.
Die CPU-Auslastung des Servers pendelt zwischen 1-5%, die Festplattenauslastung ist vergleichbar. Alle Virenscanner deinstalliert.

Log-Dateien:
auffällig ist, dass bei einer Abfrage viele Einzelsitzungen erstellt werden mit einer Sitzungszeit von wenigen Millisekunden.

Verbindung authorisiert: Benutzer=dlus Datenbank=5000_1
Verbindung empfangen: Host=192.168.1.110 Port=57212
Verbindung authorisiert: Benutzer=dlus Datenbank=5000_1
Verbindungsende: Sitzungszeit: 0:00:01.857 Benutzer=dlus Datenbank=5000_1 Host=192.168.1.110 port=57212
Verbindung empfangen: Host=192.168.1.110 Port=57213
Verbindung authorisiert: Benutzer=dlus Datenbank=5000_1
Verbindungsende: Sitzungszeit: 0:00:00.015 Benutzer=dlus Datenbank=5000_1 Host=192.168.1.110 port=57213
Verbindung empfangen: Host=192.168.1.110 Port=57214
Verbindung authorisiert: Benutzer=dlus Datenbank=5000_1
Verbindungsende: Sitzungszeit: 0:00:00.000 Benutzer=dlus Datenbank=5000_1 Host=192.168.1.110 port=57214
Verbindung empfangen: Host=192.168.1.110 Port=57215
Verbindung authorisiert: Benutzer=dlus Datenbank=5000_1
Verbindungsende: Sitzungszeit: 0:00:00.063 Benutzer=dlus Datenbank=5000_1 Host=192.168.1.110 port=57215

Verbindung empfangen: Host=192.168.1.111 Port=56862
Verbindung authorisiert: Benutzer=dlus Datenbank=5000_1
Verbindungsende: Sitzungszeit: 0:00:00.125 Benutzer=dlus Datenbank=5000_1 Host=192.168.1.111 port=56862

Wenn ich mit dem PgAdmin-Tool auf die DB zugreife, und eine große Tabelle mit knapp 380.000 Zeilen öffne, dann dauert das ca. 34 Sekunden, bis es im PgAdmin-Tool angezeigt wird. Dabei geht die Netzwerkauslastung auf ca. 34MBit (1-2MB/s). Leider kann man bei Datenträgerauslastung wie auch CPU-Auslastung keinen Prozess erkennen, der für die Datenlieferung verantwortlich ist. Eine Auslastung ist also nicht erkennbar. Freier RAM über ein paar Gigabyte ist auch noch vorhanden.

Tabellengröße	48 MB	
Indexgröße	36 MB

In den Log-Dateien findet sich dann folgendes:

Verbindung empfangen: Host=::1 Port=52918
Verbindung authorisiert: Benutzer=postgres Datenbank=5000_1
 Dauer: 34840.000 ms  Anweisung: SELECT * FROM public.kunde
	 ORDER BY be_kun_nr ASC, be_datum ASC, be_uhrzeit ASC
Verbindungsende: Sitzungszeit: 0:05:36.778 Benutzer=postgres Datenbank=postgres Host=::1
Verbindungsende: Sitzungszeit: 0:02:11.602 Benutzer=postgres Datenbank=5000_1 Host=::1

Vielleicht hat ja jemand von euch eine Idee, was ich noch anstellen könnte, um den Fehler zu finden. Der Hersteller gibt nur für die Software Support, weshalb ich selbst auf der Suche nach einem Defekt bin. Hinweise seitens des Softwareherstellers: “Bildschirmschoner könnte der Grund sein”… (naja, auf dem Server (auch wenn es nun Windows ist) läuft kein Bildschirmschoner, und die Festplatten werden nicht in standby geschickt)…

Besten Grüße
Maximilian

Du hast 2 Probleme:

Log-Dateien:
auffällig ist, dass bei einer Abfrage viele Einzelsitzungen erstellt werden mit einer Sitzungszeit von wenigen Millisekunden.

Problem 1: viele kurze Verbindungen. Möglicherweise ein Problem des Treibers, vielleicht kannst Du da persistente Verbindungen konfigurieren. Falls nicht könnte ein ConnectionPooler helfen.

Wenn ich mit dem PgAdmin-Tool auf die DB zugreife, und eine große Tabelle mit knapp 380.000 Zeilen öffne, dann dauert das ca. 34 Sekunden,

Das 2. Problem ist ein komplett anderes. Die 380.000 Zeilen müssen von der Platte geschrubbt werden, durch den Netzwerkstack an PGAdmin geschoben und dort bunt dargestellt werden.

Eine ernsthafte Anwendung macht selten ein “SELECT * FROM public.kunde ORDER BY be_kun_nr ASC, be_datum ASC, be_uhrzeit ASC” auf 380.000 Datensätzen. Hier sitzt das Problem eher vor dem Monitor.

Hi akretschmer,

Problem 1: viele kurze Verbindungen. Möglicherweise ein Problem des Treibers, vielleicht kannst Du da persistente Verbindungen konfigurieren. Falls nicht könnte ein ConnectionPooler helfen.

die vielen kurzen Verbindungen kann ich mir auch nicht erklären. Die Treiber der Netzwerkkarten sind alle signiert und aktuell. Hatte auch verschiedene Karten ausprobiert. Oder welche Treiber meinst du? Mangels postgres Passwort kann ich auch kein Update (auf 9.4) durchführen. Lese noch über den Connection Pooler. Ist das deiner Einschätzung ein Hardwareproblem, oder kann das Programm falsch programmiert worden sein?

Hier ein aktueller Auszug der Log-Datei. Programm wurde geöffnet, ein Patient geladen, ein Eintrag verändert und die Anzeigemaske wieder geschlossen. Werden denn die ganzen Verbindungen vom Programm aus initiiert, oder liegt es an einer defekten Hardware? (hier kam es zu keinem “Hänger” beim Aufruf der Kundenmaske)

2015-01-27 20:44:50 CET LOG:  Verbindung empfangen: Host=192.168.1.115 Port=54426
2015-01-27 20:44:50 CET LOG:  Verbindung empfangen: Host=192.168.1.115 Port=54427
2015-01-27 20:44:50 CET LOG:  Verbindung authorisiert: Benutzer=dlus Datenbank=5000_1
2015-01-27 20:45:03 CET LOG:  Verbindung empfangen: Host=192.168.1.115 Port=54428
2015-01-27 20:45:03 CET LOG:  Verbindung authorisiert: Benutzer=dlus Datenbank=5000_1
2015-01-27 20:45:04 CET LOG:  Verbindungsende: Sitzungszeit: 0:00:00.141 Benutzer=dlus Datenbank=5000_1 Host=192.168.1.115 port=54428
2015-01-27 20:45:07 CET LOG:  Verbindung empfangen: Host=192.168.1.115 Port=54429
2015-01-27 20:45:07 CET LOG:  Verbindung authorisiert: Benutzer=dlus Datenbank=5000_1
2015-01-27 20:45:09 CET LOG:  Verbindungsende: Sitzungszeit: 0:00:02.437 Benutzer=dlus Datenbank=5000_1 Host=192.168.1.115 port=54429
2015-01-27 20:45:09 CET LOG:  Verbindung empfangen: Host=192.168.1.115 Port=54430
2015-01-27 20:45:09 CET LOG:  Verbindung authorisiert: Benutzer=dlus Datenbank=5000_1
2015-01-27 20:45:10 CET LOG:  Verbindungsende: Sitzungszeit: 0:00:00.032 Benutzer=dlus Datenbank=5000_1 Host=192.168.1.115 port=54430
2015-01-27 20:45:10 CET LOG:  Verbindung empfangen: Host=192.168.1.115 Port=54431
2015-01-27 20:45:10 CET LOG:  Verbindung authorisiert: Benutzer=dlus Datenbank=5000_1
2015-01-27 20:45:12 CET LOG:  Verbindung empfangen: Host=192.168.1.115 Port=54432
2015-01-27 20:45:12 CET LOG:  Verbindung authorisiert: Benutzer=dlus Datenbank=5000_1
2015-01-27 20:45:12 CET LOG:  Verbindungsende: Sitzungszeit: 0:00:00.094 Benutzer=dlus Datenbank=5000_1 Host=192.168.1.115 port=54432
2015-01-27 20:45:17 CET LOG:  Verbindung empfangen: Host=192.168.1.115 Port=54433
2015-01-27 20:45:17 CET LOG:  Verbindung authorisiert: Benutzer=dlus Datenbank=5000_1
2015-01-27 20:45:21 CET LOG:  Verbindungsende: Sitzungszeit: 0:00:03.517 Benutzer=dlus Datenbank=5000_1 Host=192.168.1.115 port=54433
2015-01-27 20:45:34 CET LOG:  Verbindung empfangen: Host=192.168.1.115 Port=54434
2015-01-27 20:45:34 CET LOG:  Verbindung authorisiert: Benutzer=dlus Datenbank=5000_1
2015-01-27 20:45:34 CET LOG:  Verbindungsende: Sitzungszeit: 0:00:00.031 Benutzer=dlus Datenbank=5000_1 Host=192.168.1.115 port=54434
2015-01-27 20:45:34 CET LOG:  Verbindungsende: Sitzungszeit: 0:00:24.703 Benutzer=dlus Datenbank=5000_1 Host=192.168.1.115 port=54431
2015-01-27 20:45:42 CET LOG:  Verbindungsende: Sitzungszeit: 0:00:51.180 Benutzer=dlus Datenbank=5000_1 Host=192.168.1.115 port=54427



Das 2. Problem ist ein komplett anderes. Die 380.000 Zeilen müssen von der Platte geschrubbt werden, durch den Netzwerkstack an PGAdmin geschoben und dort bunt dargestellt werden.

Naja, ich habe halt mal den größten Eintrag rausgesucht, um auf Fehlersuche gehen zu können. Komischerweise wird in der Festplattenauslastungsanzeige per Ressourcenmonitor kein Lesevorgang angezeigt. Wird denn nicht der komplette Datensatz in den RAM geladen, wenn genügend RAM vorhanden ist? Auch ein mehrmaliges Anzeigen dieser langen Tabelle beschleunigt den Vorgang nicht…

Wie kann ich denn den Fehler genauer eingrenzen. Gibt es ein Benchmark-Tool, welches vom Server aus läuft? Tipps, Links oder weitere Hinweise jeglicher Art sind hilfreich :slight_smile:

Beste Grüße
Max

Nein nein, die Applikation macht die Verbindungen, kein Problem der Hardware oder Netzwerktreibers. Du arbeitets ja vermutlich via ODBC oder JDBC oder sowas, dort ist das Problem, vermute ich.




Das 2. Problem ist ein komplett anderes. Die 380.000 Zeilen müssen von der Platte geschrubbt werden, durch den Netzwerkstack an PGAdmin geschoben und dort bunt dargestellt werden.

Naja, ich habe halt mal den größten Eintrag rausgesucht, um auf Fehlersuche gehen zu können. Komischerweise wird in der Festplattenauslastungsanzeige per Ressourcenmonitor kein Lesevorgang angezeigt. Wird denn nicht der komplette Datensatz in den RAM geladen, wenn genügend RAM vorhanden ist? Auch ein mehrmaliges Anzeigen dieser langen Tabelle beschleunigt den Vorgang nicht…

Wie kann ich denn den Fehler genauer eingrenzen. Gibt es ein Benchmark-Tool, welches vom Server aus läuft? Tipps, Links oder weitere Hinweise jeglicher Art sind hilfreich :slight_smile:

Beste Grüße
Max[/quote]

Wenn die Tabelle im Shared_memory liegt, liegt sie dort. Oder im RAM, der als Cache fungiert. Das läßt sich so genau remote nicht sagen, ein EXPLAIN (analyse, buffers) könnte da Licht ins Dunkel bringen.

Ansonsten: erst mal NICHT mit bunten GUI’s arbeiten, sondern mit psql, dem CMD-Tool zu PostgreSQL. Ich arbeite nur damit.

Hi akretschmer,

sondern mit psql, dem CMD-Tool zu PostgreSQL. Ich arbeite nur damit.

Wäre mir auch sehr lieb, da ich aus der Linux Ecke komme. Allerdings musste ich mir erst einmal einen Überblick über die Datenbank verschaffen (habe mit PG bisher noch nicht gearbeitet, und bin nur für die Hardware zuständig), und deshalb PgAdmin.
Das mit “EXPLAIN (analyse, buffers) ” ist für mich auch Neuland und muss mich da erst einmal einlesen.

In der Zwischenzeit habe ich noch einmal mit dem Prozess Explorer die Aktivitäten auf dem Server mitgeschnitten und mir noch einmal die große Tabelle mit dem PgAdmin anzeigen lassen.
Auffällig: keine HDD-Aktivität, keine I/Os, Netzwerkauslastung ca. 1-2 MB/s.
Frage: Falls die Tabelle komplett im RAM liegt (da keine HDD-Aktivität), weshalb nur die geringe Netzwerkauslastung? Müsste die Übertragungsrate nicht maximal sein?
hier der pg_log Eintrag:

Dauer: 34213.000 ms  Anweisung: SELECT * FROM public.kunde ORDER BY be_kun_nr ASC, be_datum ASC, be_uhrzeit ASC
2015-01-29 15:24:24 CET LOG:  Verbindungsende: Sitzungszeit: 0:01:08.783 Benutzer=postgres Datenbank=5000_1 Host=::1 port=49953

Grüße, Max

Hallo!
Habe nun mit Explain experimentiert:

EXPLAIN (ANALYZE on, VERBOSE off, COSTS on, BUFFERS off, TIMING on )SELECT * FROM public.kunde ORDER BY be_kun_nr ASC, be_datum ASC, be_uhrzeit ASC



"Index Scan using kunde_pk on kunde (cost=0.42..27384.55 rows=382279 width=79) (actual time=0.030..164.888 rows=376411 loops=1)"
"Total runtime: 186.247 ms"

Und ein pgbench durchgeführt.
Frage: Ist der Server prinzipiell schnell genug für die Datenbank? Woher kommen dann die sporadisch auftretenden Hänger? WAS kann ich denn noch testen?
Viele Grüße
Maximilian

c:\Postgres\bin>pgbench -h 192.168.1.10 -r -c 4 -t 1000 -U dlus postgres
starting vacuum...end.
transaction type: TPC-B (sort of)
scaling factor: 1
query mode: simple
number of clients: 4
number of threads: 1
number of transactions per client: 1000
number of transactions actually processed: 4000/4000
tps = 514.916357 (including connections establishing)
tps = 524.243170 (excluding connections establishing)
statement latencies in milliseconds:
        0.006310        \set nbranches 1 * :scale
        0.002207        \set ntellers 10 * :scale
        0.002154        \set naccounts 100000 * :scale
        0.002638        \setrandom aid 1 :naccounts
        0.001842        \setrandom bid 1 :nbranches
        0.001671        \setrandom tid 1 :ntellers
        0.002331        \setrandom delta -5000 5000
        0.252861        BEGIN;
        0.652058        UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
        0.538063        SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
        1.169655        UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
        3.244758        UPDATE pgbench_branches SET bbalance = bbalance + :delta  WHERE bid = :bid;
        0.445336        INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
        1.274279        END;

Das sind 186 Millisekunden, also 0.18 Sekunden. Der Rest zu den genannten 34 Sekunden ist die Strafe Gottes für die Benutzung von Windows als Server.

Zum Vergleich, das sind die Werte von meinem Desktop Rechner. Quad Core i7, 16GB RAM, Normale HDD, Windows 7.
Allerdings lokal, ohne Netzwerkverkehr.

C:\Program Files\PostgreSQL\9.4\bin>pgbench -r -c 4 -t 1000 -U pgbench pgbench
starting vacuum...end.
transaction type: TPC-B (sort of)
scaling factor: 1
query mode: simple
number of clients: 4
number of threads: 1
number of transactions per client: 1000
number of transactions actually processed: 4000/4000
latency average: 0.000 ms
tps = 1946.265381 (including connections establishing)
tps = 2033.908868 (excluding connections establishing)
statement latencies in milliseconds:
        0.001342        \set nbranches 1 * :scale
        0.000519        \set ntellers 10 * :scale
        0.000502        \set naccounts 100000 * :scale
        0.000681        \setrandom aid 1 :naccounts
        0.000498        \setrandom bid 1 :nbranches
        0.000546        \setrandom tid 1 :ntellers
        0.000721        \setrandom delta -5000 5000
        0.068284        BEGIN;
        0.181517        UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
        0.125528        SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
        0.304488        UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
        0.827499        UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
        0.123744        INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
        0.312692        END;

Und das sind die Werte von meinem Laptop: Dual Core i5, 8GB, SSD Platte, Windows 7

d:\PostgreSQL\9.4\bin>pgbench -r -c 4 -t 1000 -U pgbench pgbench
starting vacuum...end.
transaction type: TPC-B (sort of)
scaling factor: 1
query mode: simple
number of clients: 4
number of threads: 1
number of transactions per client: 1000
number of transactions actually processed: 4000/4000
latency average: 0.000 ms
tps = 1602.948795 (including connections establishing)
tps = 1653.293413 (excluding connections establishing)
statement latencies in milliseconds:
        0.002418        \set nbranches 1 * :scale
        0.000847        \set ntellers 10 * :scale
        0.000899        \set naccounts 100000 * :scale
        0.001212        \setrandom aid 1 :naccounts
        0.000864        \setrandom bid 1 :nbranches
        0.000820        \setrandom tid 1 :ntellers
        0.001082        \setrandom delta -5000 5000
        0.101540        BEGIN;
        0.254747        UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
        0.195518        SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
        0.561290        UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
        0.733940        UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
        0.167427        INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
        0.366291        END;

Hallo Leute,

habe nun auch um die 1000tps. Leider drehen die WD-Red (raid-Platten) nur mit 5400, weshalb darin wohl die Begrenzung liegt.
Ich habe mich mal mit “Connection Pooling” durchgelesen. Allerdings scheint es für Windows keine Möglichkeit dafür zu geben. Eine nicht ausgereifte Lösung von pg_bouncer gibt es für 64bit, aber die will ich auf dem Produktivsystem nicht einsetzen.
Ich gehe ja davon aus, dass die vielen kleinen Verbindungsanfragen für das sporadische Hängenbleiben des Client-Programms der Grund ist.

Wie kann ich denn herausfinden, ob die 250MB (keine GB) kleine Datenbank vollkommen im ECC-Ram liegt, oder inwiefern auf die Festplatte zugegriffen wird? Unter Windows ist es ja leider so, dass der postgresql-Task nicht für den Festplattenzugriff verantwortlich ist, sondern ein System-Task.
Was kann ich machen, um einen Fortschritt zu erzielen? Ist die Hardware (Platten) zu langsam?

Danke + Grüße
Max

wenn die DB mit allem ‘nur’ 250M groß ist solltest Du mit shared_buffers von vielleicht 512M oder 1GB mit der Zeit die komplett im RAM haben.
Du kannst den Abfragen ein explain (analyse, buffers) vorstellen, dann siehst Du die Cache Hit/Miss - Werte.

Ähm, Windows und Produktivsystem schließt sich übrigens eher aus. Aber das sagte ich schon früher mal.