Robbi
7. Januar 2023 um 21:37
1
Hallo zusammen,
Ich muss zugeben wirklich Plan wie ich mein Problem in den Griff bekommen kann habe ich nicht.Vielleicht ist meine Konfiguration schlicht “totaler Blödsinn” oder die Anwendung die ich nutze macht Mist.
In Kurzfassung - meine Anwendung die ich nutzen will heißt “Photo Supreme”. Es ist eine Bildverwaltung. Wenn die Anwendung viele Dateien aktualisieren will - sagen wir mehr als 20000 ist es sicher, dass der Server es nicht überlebt und irgendwann wegen “out of memory” alles hinschmeißt.
Mein Server hat 48GB RAM, 8 CPU Kerne und läuft virtuell auf einem Linux Debian KVM Server.
Stelle ich in der Konfiguration Anzahl der max Verbindungen auf 50, so macht die Anwenung Ärger und kommt immer wieder mit:
Setze ich die Verbindungen auf 70 kommt irgendwann:
und kurz danach ist Ende.
Momentan sehen die wichtigste Konfigeinträge so aus
max_connections = 100
shared_buffers = 64MB
temp_buffers = 1GB
work_mem = 64MB
maintenance_work_mem = 1GB
max_wal_size = 3GB
effective_cache_size = 24GB
dynamic_shared_memory_type = posix
Mir kommt es so vor, dass aus welchem Grund auch immer der Server mit der Zeit mehr Speicher benutzen will als überhaupt vorhanden und dann kommt es zu dem Crash.
ist das dediziert für PostgreSQL, oder läuft da noch mehr auf der Maschine? Also auch noch die Bildverarbeitung? Ist in der Anwendung einstellbar, wie viele Verbindungen zur DB aufgemacht werden?
Der Wert für shared_buffers ist SEHR, SEHR klein, wenn das dediziert für PG ist sollte das auf ca. 25% RAM sein. work_mem ist dafür vermutlich zu groß. Aber alles in allem: wir wissen zu wenig über das alles… was z.B. heißt ‘kurz danach ist Ende’? Fehlermeldung?
PS.: hab grad Deinen Beitrag in der FB-Gruppe freigegeben (ja, bin da einer der Admins). Da hast Du aber eine andere Konfiguration angegeben…
Robbi
8. Januar 2023 um 12:05
4
Vielen Dank für die Antwoten.
Ja da habe ich andere Konfig angegeben, wollte (mache ich die Änderungen auch gleich hier)
Ich habe etwas probiert. Die aktuelle Konfiguration ist zum großen Teil aus der Dokumentation der Anwendung. Und nein da kann man nichts einstellen bzgl. der Verbindungen.
Die sparsame Dokumentation zu der Anwendung und Postgres ist hier zu finden https://manualsu.idimager.com/version7/QuickInstall-PostgreSQL14-PhotoSupreme.pdf
Die angegebene Parameter zu der VM sind für die Exklusiv. Die Hostmaschine hat 128GB RAM und 24 Kerne. Das wird auf andere VM’s verteilt.
Die aktuelle Parameter sehen also so aus:
max_connections = 300
shared_buffers = 12GB
work_mem = 32MB
maintenance_work_mem = 512MB
dynamic_shared_memory_type = posix
checkpoint_timeout = 30min
max_wal_size = 10GB
min_wal_size = 3GB
cpu_tuple_cost = 0.03
Brachte aber nicht wirklich etwas. Der Server ist nach etwas mehr als 10000 Datensätze abgestürzt.
Mit welcher Fehlermeldung im Log?
Robbi
8. Januar 2023 um 12:13
6
Irgendwann kommt so etwas:
2023-01-08 01:58:02.443 CET [765] LOG: Checkpoints passieren zu oft (alle 28 Sekunden)
2023-01-08 01:58:02.443 CET [765] TIPP: Erhöhen Sie eventuell den Konfigurationsparameter »max_wal_size«.
2023-01-08 01:58:29.354 CET [765] LOG: Checkpoints passieren zu oft (alle 27 Sekunden)
2023-01-08 01:58:29.354 CET [765] TIPP: Erhöhen Sie eventuell den Konfigurationsparameter »max_wal_size«.
2023-01-08 01:58:57.827 CET [765] LOG: Checkpoints passieren zu oft (alle 28 Sekunden)
2023-01-08 01:58:57.827 CET [765] TIPP: Erhöhen Sie eventuell den Konfigurationsparameter »max_wal_size«.
2023-01-08 01:59:19.819 CET [763] LOG: schnelles Herunterfahren verlangt
2023-01-08 01:59:19.845 CET [763] LOG: etwaige aktive Transaktionen werden abgebrochen
2023-01-08 01:59:19.845 CET [2548] idimager_main@moments of time FATAL: Verbindung wird abgebrochen aufgrund von Anweisung des Administrators
2023-01-08 01:59:19.845 CET [2533] idimager_main@moments of time FATAL: Verbindung wird abgebrochen aufgrund von Anweisung des Administrators
2023-01-08 01:59:19.845 CET [2547] idimager_main@moments of time FATAL: Verbindung wird abgebrochen aufgrund von Anweisung des Administrators
2023-01-08 01:59:19.846 CET [763] LOG: Checkpointer-Prozess (PID 765) wurde von Signal 9 beendet: Getötet
2023-01-08 01:59:19.846 CET [763] LOG: aktive Serverprozesse werden abgebrochen
2023-01-08 01:59:19.846 CET [2533] idimager_main@moments of time LOG: SSL error: protocol is shutdown
2023-01-08 01:59:19.846 CET [2548] idimager_main@moments of time LOG: SSL error: protocol is shutdown
2023-01-08 01:59:19.846 CET [2547] idimager_main@moments of time LOG: SSL error: protocol is shutdown
2023-01-08 01:59:19.846 CET [2548] idimager_main@moments of time LOG: could not send data to client: Die Verbindung wurde vom Kommunikationspartner zurückgesetzt
2023-01-08 01:59:19.846 CET [2533] idimager_main@moments of time LOG: could not send data to client: Die Verbindung wurde vom Kommunikationspartner zurückgesetzt
2023-01-08 01:59:19.846 CET [2547] idimager_main@moments of time LOG: could not send data to client: Die Verbindung wurde vom Kommunikationspartner zurückgesetzt
2023-01-08 01:59:20.025 CET [2562] idimager_main@moments of time FATAL: das Datenbanksystem fährt herunter
...
...
2023-01-08 01:59:24.014 CET [763] LOG: SIGKILL wird an ungehorsame Kinder gesendet
Robbi
8. Januar 2023 um 12:17
7
Und nein die Bildverarbeitung selbst läuft auf der Windowsmaschine.
Die Anwendung nutzt 2 Datenbanken. Eine wo so zu sagen alle Daten stehen und eine wo die Vorschaubilder gespeichert werden.
Klingt als ob Du / der Admin den Server beendet. Steht im OS-Log was von out-of-memory (OOM)?
Und du solltest max_wal_size erhöhen, aber das ist nur ein Hint.
Robbi
8. Januar 2023 um 12:22
9
Im Log ist zu OCM nichts zu finden
Ach jetzt bei neusten Versucht mit den o.g Parametern steht da
Grand total: 652718376 bytes in 116271 blocks; 189213416 free (16544 chunks); 463504960 used
2023-01-08 13:21:48.322 CET [5955] idimager_main@moments of time FEHLER: Speicher aufgebraucht
2023-01-08 13:21:48.322 CET [5955] idimager_main@moments of time DETAIL: Fehler bei Anfrage mit Größe 5632 im Speicherkontext »ExecutorState«.
2023-01-08 13:21:48.322 CET [5955] idimager_main@moments of time ANWEISUNG: prepare prepst8301 as select * from v_CatalogItem where GUID = '00BDA053572E4B4691CAFED76A13FBFE'
2023-01-08 13:21:48.329 CET [1461] LOG: konnte neuen Prozess für Verbindung nicht starten (fork-Fehler): Nicht genügend Hauptspeicher verfügbar```
okay, du könntest work_mem reduzieren und/oder shared_buffers reduzieren sowie auch max_connections, um mehr RAM dynamisch zur Verfügung zu haben. Wie viele postgresql-Prozesse laufen denn?
Robbi
8. Januar 2023 um 15:50
11
Ich habe jetzt es noch mal gestartet und sehe 33 Prozesse der Anwendung und 6 so allgemeine
ps aux | grep postgres
root 832 0.0 0.0 5400 472 pts/3 S+ 09:32 0:00 tail -f /var/log/postgresql/postgresql-14-main.log
root 833 0.0 0.0 10112 3912 pts/4 S 09:32 0:00 su - postgres
postgres 834 0.0 0.0 7164 2992 pts/4 S+ 09:32 0:00 -bash
root 837 0.0 0.0 10112 3976 pts/5 S 09:32 0:00 su - postgres
postgres 838 0.0 0.0 7164 2496 pts/5 S 09:32 0:00 -bash
postgres 2806 0.0 0.0 21032 7964 pts/5 S+ 10:59 0:00 /usr/lib/postgresql/14/bin/psql
postgres 6769 0.0 0.5 12955592 283496 ? Ss 13:27 0:00 /usr/lib/postgresql/14/bin/postgres -D /var/lib/postgresql/14/main -c config_file=/etc/postgresql/14/main/postgresql.conf
postgres 6771 0.0 1.1 12955872 564572 ? Ss 13:27 0:01 postgres: 14/main: checkpointer
postgres 6772 0.0 0.2 12955784 108676 ? Ss 13:27 0:00 postgres: 14/main: background writer
postgres 6773 0.0 0.0 12955592 22500 ? Ss 13:27 0:00 postgres: 14/main: walwriter
postgres 6774 0.0 0.0 12956496 8904 ? Ss 13:27 0:00 postgres: 14/main: autovacuum launcher
postgres 6775 0.0 0.0 69448 5792 ? Ss 13:27 0:01 postgres: 14/main: stats collector
postgres 6776 0.0 0.0 12956192 6856 ? Ss 13:27 0:00 postgres: 14/main: logical replication launcher
postgres 7060 0.0 0.2 13053576 140956 ? Ss 13:42 0:00 postgres: 14/main: idimager_main moments of time 192.168.4.15(51556) idle
postgres 7081 0.1 7.3 15459968 3606776 ? Ss 13:43 0:17 postgres: 14/main: idimager_main moments of time 192.168.4.15(51564) idle
postgres 9217 2.6 2.4 13033364 1193744 ? Ss 16:47 0:01 postgres: 14/main: idimager_main moments of time 192.168.4.15(53932) idle
postgres 9219 2.6 2.1 13030216 1080960 ? Ss 16:47 0:01 postgres: 14/main: idimager_main moments of time 192.168.4.15(53934) idle
postgres 9220 1.8 1.8 13015516 900848 ? Ss 16:47 0:01 postgres: 14/main: idimager_main moments of time 192.168.4.15(53935) idle
postgres 9221 2.4 2.0 13029260 1031936 ? Ss 16:47 0:01 postgres: 14/main: idimager_main moments of time 192.168.4.15(53936) idle
postgres 9222 2.2 2.1 13024648 1039676 ? Ds 16:47 0:01 postgres: 14/main: idimager_main moments of time 192.168.4.15(53937) COMMIT
postgres 9223 2.0 2.0 13018060 1030792 ? Ss 16:47 0:01 postgres: 14/main: idimager_main moments of time 192.168.4.15(53938) idle
postgres 9224 2.2 2.0 13024376 999632 ? Ss 16:47 0:01 postgres: 14/main: idimager_main moments of time 192.168.4.15(53939) idle
postgres 9225 2.1 1.9 13018204 975968 ? Ds 16:47 0:01 postgres: 14/main: idimager_main moments of time 192.168.4.15(53940) INSERT
postgres 9226 2.2 2.0 13019048 1017508 ? Ss 16:47 0:01 postgres: 14/main: idimager_main moments of time 192.168.4.15(53941) idle
postgres 9228 2.8 2.2 13035848 1120236 ? Ss 16:47 0:01 postgres: 14/main: idimager_main moments of time 192.168.4.15(53943) idle
postgres 9229 1.9 1.7 13019100 857660 ? Ss 16:47 0:01 postgres: 14/main: idimager_main moments of time 192.168.4.15(53944) idle
postgres 9230 2.4 2.1 13029276 1071208 ? Ss 16:47 0:01 postgres: 14/main: idimager_main moments of time 192.168.4.15(53945) idle
postgres 9231 2.1 1.8 13023028 895604 ? Ss 16:47 0:01 postgres: 14/main: idimager_main moments of time 192.168.4.15(53946) idle
postgres 9234 2.0 1.9 13017260 963024 ? Ds 16:47 0:01 postgres: 14/main: idimager_main moments of time 192.168.4.15(53949) INSERT
postgres 9235 0.8 0.5 13046312 269892 ? Ss 16:47 0:00 postgres: 14/main: idimager_main moments of time 192.168.4.15(53950) idle
postgres 9236 2.3 2.1 13029956 1045592 ? Ss 16:47 0:01 postgres: 14/main: idimager_main moments of time 192.168.4.15(53951) idle
postgres 9237 1.9 1.6 13021256 806620 ? Ss 16:47 0:01 postgres: 14/main: idimager_main moments of time 192.168.4.15(53952) idle
postgres 9239 0.9 0.5 13052200 284352 ? Ss 16:47 0:00 postgres: 14/main: idimager_main moments of time 192.168.4.15(53954) idle
postgres 9244 2.3 0.5 13005724 276828 ? Ss 16:47 0:01 postgres: 14/main: idimager_main moments of time 192.168.4.15(53959) COMMIT
postgres 9251 0.9 0.5 13046128 270080 ? Ss 16:47 0:00 postgres: 14/main: idimager_main moments of time 192.168.4.15(53969) idle
postgres 9252 0.8 0.5 13044648 264564 ? Ss 16:47 0:00 postgres: 14/main: idimager_main moments of time 192.168.4.15(53970) idle
postgres 9255 1.0 0.5 13052580 283276 ? Ss 16:47 0:00 postgres: 14/main: idimager_main moments of time 192.168.4.15(53973) idle
postgres 9260 1.2 0.4 12962400 219688 ? Ss 16:47 0:00 postgres: 14/main: idimager_main moments of time_thumbs 192.168.4.15(53978) idle
postgres 9261 1.2 0.4 12962436 217680 ? Ss 16:47 0:00 postgres: 14/main: idimager_main moments of time_thumbs 192.168.4.15(53979) idle
postgres 9262 1.2 0.4 12961672 212492 ? Ss 16:47 0:00 postgres: 14/main: idimager_main moments of time_thumbs 192.168.4.15(53980) idle
postgres 9270 1.2 0.4 12962268 211716 ? Ss 16:47 0:00 postgres: 14/main: idimager_main moments of time_thumbs 192.168.4.15(53988) idle
postgres 9271 1.3 0.4 12962428 217368 ? Ss 16:47 0:00 postgres: 14/main: idimager_main moments of time_thumbs 192.168.4.15(53989) idle
postgres 9291 1.1 0.2 12958600 132240 ? Ss 16:48 0:00 postgres: 14/main: idimager_main moments of time 192.168.4.15(54025) idle
postgres 9292 0.3 0.3 12958420 171840 ? Ss 16:48 0:00 postgres: 14/main: idimager_main moments of time 192.168.4.15(54026) idle
postgres 9294 1.5 0.1 12958124 89196 ? Ss 16:48 0:00 postgres: 14/main: idimager_main moments of time 192.168.4.15(54028) COMMIT
postgres 9295 0.5 0.3 12958040 151492 ? Ss 16:48 0:00 postgres: 14/main: idimager_main moments of time 192.168.4.15(54029) idle
Robbi
8. Januar 2023 um 15:52
12
last pid: 9416; load avg: 3.03, 1.75, 0.73; up 0+07:41:06 16:51 39 processes: 5 other background task(s), 28 idle, 6 active
CPU states: 4.3% user, 0.0% nice, 0.9% system, 76.6% idle, 18.3% iowait
Memory: 42G used, 5033M free, 0K shared, 93M buffers, 33G cached
Swap: 376K used, 4619M free, 28K cached, 0K in, 0K out
PID USERNAME SIZE RES STATE XTIME QTIME %CPU LOCKS COMMAND
9417 postgres 12G 30M active 0:00 0:00 0.0 8 postgres: 14/main: postgres postgres [local] idle
9260 idimager 12G 538M active 0:00 0:00 1.2 7 postgres: 14/main: idimager_main moments of time_thumbs 192.168.4.15(53978) COMMIT
9382 idimager 12G 204M active 0:00 0:00 2.0 6 postgres: 14/main: idimager_main moments of time 192.168.4.15(54113) COMMIT
9415 idimager 12G 103M active 0:00 0:00 0.6 1 postgres: 14/main: idimager_main moments of time 192.168.4.15(54135) COMMIT
9270 idimager 12G 538M active 0:00 0:00 1.2 7 postgres: 14/main: idimager_main moments of time_thumbs 192.168.4.15(53988) COMMIT
9219 idimager 13G 2408M idle 0:00 0:00 1.4 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53934) idle
9230 idimager 13G 2398M idle 0:00 0:00 0.2 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53945) idle
9226 idimager 13G 2349M idle 0:00 0:00 1.2 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53941) idle
9261 idimager 12G 539M idle 0:00 0:00 1.2 0 postgres: 14/main: idimager_main moments of time_thumbs 192.168.4.15(53979) idle
9416 idimager 12G 206M idle 0:00 0:00 0.2 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(54136) idle
9223 idimager 13G 2503M idle 0:00 0:00 2.0 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53938) idle
9221 idimager 13G 2370M idle 0:00 0:00 2.0 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53936) idle
6772 12G 106M 0:00 0:00 0.0 0 postgres: 14/main: background writer
9224 idimager 13G 2454M idle 0:00 0:00 1.4 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53939) idle
9271 idimager 12G 547M idle 0:00 0:00 1.2 0 postgres: 14/main: idimager_main moments of time_thumbs 192.168.4.15(53989) idle
9237 idimager 13G 2319M idle 0:00 0:00 4.2 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53952) idle
9229 idimager 13G 2466M idle 0:00 0:00 2.2 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53944) idle
9217 idimager 13G 2496M idle 0:00 0:00 0.8 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53932) idle
9262 idimager 12G 541M idle 0:00 0:00 1.4 0 postgres: 14/main: idimager_main moments of time_thumbs 192.168.4.15(53980) idle
6771 12G 551M 0:00 0:00 0.0 0 postgres: 14/main: checkpointer
9231 idimager 13G 2609M idle 0:00 0:00 0.8 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53946) idle
6774 12G 8904K 0:00 0:00 0.0 0 postgres: 14/main: autovacuum launcher
9404 idimager 12G 262M idle 0:00 0:00 0.8 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(54130) idle
9225 idimager 13G 2407M idle 0:00 0:00 1.4 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53940) idle
9252 idimager 13G 524M idle 0:00 0:00 0.6 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53970) idle
9228 idimager 13G 2444M idle 0:00 0:00 1.2 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53943) idle
9235 idimager 13G 536M idle 0:00 0:00 0.6 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53950) idle
9255 idimager 13G 554M idle 0:00 0:00 0.6 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53973) idle
9397 idimager 12G 592M idle 0:00 0:00 0.0 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(54127) idle
6773 12G 22M 0:00 0:00 0.2 0 postgres: 14/main: walwriter
7081 idimager 15G 4894M idle 0:00 0:00 0.0 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(51564) idle
9222 idimager 13G 2555M idle 0:00 0:00 2.0 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53937) idle
9220 idimager 13G 2460M idle 0:00 0:00 1.4 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53935) idle
9251 idimager 13G 536M idle 0:00 0:00 0.4 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53969) idle
9236 idimager 13G 2358M idle 0:00 0:00 1.8 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53951) idle
7060 idimager 13G 336M idle 0:00 0:00 0.4 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(51556) idle
9234 idimager 13G 2381M active 0:00 0:00 2.4 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53949) BIND
6776 postgres 12G 6856K 0:00 0:00 0.0 0 postgres: 14/main: logical replication launcher
9239 idimager 13G 557M idle 0:00 0:00 0.8 0 postgres: 14/main: idimager_main moments of time 192.168.4.15(53954) idle
Robbi
8. Januar 2023 um 18:45
13
OK, mit weiterer Suche auf dem System ist mir aufgefallen, dass ich wohl vor Jahren als das System aufgebaut war und deutlich weniger RAM/ CPU Power hatte Parameter an den Linux Kernel übergeben hatte, die die Ressourcen an anderer Stelle beschnitten hatten.
echo 10737418240 > /proc/sys/kernel/shmmax
echo 2097152 > /proc/sys/kernel/shmall
echo 2 > /proc/sys/vm/overcommit_memory
Bei dem System selbst ohne diese Parameter liefert mir der Kernel:
cat /proc/sys/kernel/shmmax
18446744073692774399
cat /proc/sys/kernel/shmmall
18446744073692774399
cat /proc/sys/vm/overcommit_memory
0
Mit etwa kritischer Datenmenge ist ein Testlauf durchgelaufen. Ob das jetzt so bleiben wird, muss ich weiter testen.
Auf jedem Fall verringern der Werte für work_mem und shared_buffers haben zu Absturz der Datenbank geführt nach etwa 10000 datensätze.
Was mich aber jetzt wundert - die Applikation ist so weit “fertig”. Also die macht nichts mehr.
Musste in so einem Fall nicht der belegte Speicher wieder frei werden?
Es bleiben diese 10 Applikationsprozesse und Speicher wird nicht frei.
Gibt es dafür irgendeinen Parameter? Womöglich ist meine Annahme falsch, aber ich denke, wenn ich jetzt verarbeiten weiterer Datensätze anstoße ohne vorher die Applikation auf der Windows Maschine zu beenden, wird es nicht sehr lange dauern und der Datenbankserver wird wieder Probleme machen.
die Prozesse bleiben solange die Applikation, die diese gestartet hat, nicht beendet. shared_buffers werden bei Start der DB allokiert und bleiben dies auch, bis zum Ende. work_mem ist Speicher, der dynamisch allokiert wird - und freigegeben, wenn nicht mehr benötigt. Dies passiert je Client-Prozess. Jede neue Verbindung zur DB startet einen Client-Prozess, diese kann bis zu work_mem je Abfragenode allokieren, dynamisch.
Robbi
9. Januar 2023 um 08:07
15
Ich glaube ich gebe auf. Ich habe bei dem System SWAP Partition auf 25 GB erweitert. Dachte - oj super, jetzt läuft das ganze. Ja 16.000 Datensätze konnten verarbeitet werden und dann war Schluss
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411335] postgres invoked oom-killer: gfp_mask=0x100cca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=0
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411337] CPU: 3 PID: 920 Comm: postgres Not tainted 5.10.0-19-amd64 #1 Debian 5.10.149-2
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411337] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.14.0-2 04/01/2014
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411338] Call Trace:
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411348] dump_stack+0x6b/0x83
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411350] dump_header+0x4a/0x1f4
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411351] oom_kill_process.cold+0xb/0x10
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411353] out_of_memory+0x1bd/0x4e0
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411355] __alloc_pages_slowpath.constprop.0+0xbcc/0xc90
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411356] __alloc_pages_nodemask+0x2de/0x310
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411357] pagecache_get_page+0x175/0x390
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411358] filemap_fault+0x6a2/0x900
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411360] ? xas_load+0x5/0x80
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411370] ext4_filemap_fault+0x2d/0x50 [ext4]
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411372] __do_fault+0x37/0x170
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411374] handle_mm_fault+0x1208/0x1c10
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411376] do_user_addr_fault+0x1b8/0x400
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411378] exc_page_fault+0x78/0x160
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411379] ? asm_exc_page_fault+0x8/0x30
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411380] asm_exc_page_fault+0x1e/0x30
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411381] RIP: 0033:0x55a6a44de420
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411384] Code: Unable to access opcode bytes at RIP 0x55a6a44de3f6.
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411385] RSP: 002b:00007ffcbd643ef8 EFLAGS: 00010246
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411386] RAX: 000055a6a5ee4980 RBX: 000055a6a5ee51a8 RCX: 0000000000000006
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411386] RDX: 000055a6a5ee4980 RSI: 000055a6a5ee51a8 RDI: 000055a6a5ee4948
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411386] RBP: 00007ffcbd643fb0 R08: 000055a6a4685727 R09: 000055a6a5ee49f0
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411387] R10: 000055a759822d18 R11: 00007f261408bc80 R12: 000055a6a5ee4998
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411387] R13: 000055a6a5ee4868 R14: 0000000000000000 R15: 000055a6a5ee4948
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411388] Mem-Info:
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411390] active_anon:3252410 inactive_anon:8714454 isolated_anon:0
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411390] active_file:172 inactive_file:28 isolated_file:0
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411390] unevictable:0 dirty:2 writeback:0
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411390] slab_reclaimable:50439 slab_unreclaimable:10546
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411390] mapped:3204479 shmem:3204570 pagetables:226265 bounce:0
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411390] free:67530 free_pcp:907 free_cma:0
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411391] Node 0 active_anon:13009640kB inactive_anon:34857816kB active_file:688kB inactive_file:112kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:12817916kB dirty:8kB writeback:0kB shmem:12818280kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 585728kB writeback_tmp:0kB kernel_stack:3568kB all_unreclaimable? no
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411392] Node 0 DMA free:15908kB min:20kB low:32kB high:44kB reserved_highatomic:0KB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15908kB mlocked:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411393] lowmem_reserve[]: 0 1940 48143 48143 48143
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411395] Node 0 DMA32 free:187496kB min:2720kB low:4704kB high:6688kB reserved_highatomic:0KB active_anon:447520kB inactive_anon:1347524kB active_file:8kB inactive_file:28kB unevictable:0kB writepending:0kB present:2080624kB managed:2015088kB mlocked:0kB pagetables:29652kB bounce:0kB free_pcp:260kB local_pcp:248kB free_cma:0kB
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411396] lowmem_reserve[]: 0 0 46203 46203 46203
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411398] Node 0 Normal free:66716kB min:64836kB low:112148kB high:159460kB reserved_highatomic:2048KB active_anon:12562120kB inactive_anon:33510292kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:8kB present:48234496kB managed:47317716kB mlocked:0kB pagetables:875408kB bounce:0kB free_pcp:3368kB local_pcp:408kB free_cma:0kB
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411399] lowmem_reserve[]: 0 0 0 0 0
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411400] Node 0 DMA: 1*4kB (U) 0*8kB 0*16kB 1*32kB (U) 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15908kB
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411405] Node 0 DMA32: 347*4kB (UE) 217*8kB (UME) 467*16kB (UME) 849*32kB (UME) 476*64kB (UME) 168*128kB (UME) 160*256kB (UME) 77*512kB (UME) 17*1024kB (UME) 0*2048kB 0*4096kB = 187524kB
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411409] Node 0 Normal: 770*4kB (UME) 599*8kB (UME) 2073*16kB (UME) 608*32kB (UME) 107*64kB (UME) 1*128kB (M) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 67472kB
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411414] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411414] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411415] 3225456 total pagecache pages
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411416] 20473 pages in swap cache
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411417] Swap cache stats: add 7670676, delete 7650202, find 146536/150576
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411417] Free swap = 0kB
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411418] Total swap = 25701372kB
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411418] 12582778 pages RAM
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411418] 0 pages HighMem/MovableOnly
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411418] 245600 pages reserved
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411419] 0 pages hwpoisoned
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411419] Tasks state (memory values in pages):
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411420] [ pid ] uid tgid total_vm rss pgtables_bytes swapents oom_score_adj name
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411423] [ 293] 0 293 13583 222 135168 0 -250 systemd-journal
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411424] [ 312] 0 312 5398 278 65536 0 -1000 systemd-udevd
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411425] [ 411] 0 411 24972 332 73728 1 0 dhclient
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411425] [ 427] 109 427 1976 113 53248 0 0 rpcbind
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411426] [ 429] 0 429 1687 68 53248 0 0 cron
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411427] [ 430] 105 430 2065 114 53248 0 -900 dbus-daemon
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411428] [ 436] 0 436 55234 638 69632 57 0 rsyslogd
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411429] [ 438] 0 438 3430 197 65536 0 0 systemd-logind
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411429] [ 573] 103 573 4652 255 81920 0 0 exim4
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411430] [ 694] 0 694 958 52 49152 0 0 ntpd
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411431] [ 696] 110 696 994 35 49152 0 0 ntpd
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411432] [ 698] 110 698 1011 56 49152 0 0 ntpd
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411432] [ 740] 0 740 2412 92 57344 1 0 xinetd
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411433] [ 741] 0 741 3737 307 61440 7 0 sshd
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411434] [ 744] 0 744 3800 293 73728 0 0 systemd
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411434] [ 745] 0 745 41754 650 94208 11 0 (sd-pam)
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411435] [ 762] 0 762 1791 2 57344 139 0 bash
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411436] [ 765] 0 765 1715 16 53248 45 0 screen
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411436] [ 766] 0 766 2475 596 57344 244 0 screen
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411437] [ 767] 0 767 1791 1 61440 124 0 bash
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411438] [ 768] 0 768 1791 1 53248 124 0 bash
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411438] [ 769] 0 769 1791 27 49152 83 0 bash
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411439] [ 770] 0 770 1791 1 53248 133 0 bash
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411440] [ 771] 0 771 1791 1 53248 142 0 bash
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411440] [ 772] 0 772 1791 1 61440 141 0 bash
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411441] [ 773] 0 773 1791 1 57344 141 0 bash
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411441] [ 774] 0 774 1791 1 57344 141 0 bash
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411442] [ 781] 107 781 3237047 55414 675840 310 -900 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411443] [ 783] 107 783 3237297 3183505 25681920 329 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411444] [ 784] 107 784 3237086 3075367 25624576 323 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411444] [ 785] 107 785 3237047 4367 176128 331 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411445] [ 786] 107 786 17358 206 131072 359 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411446] [ 787] 107 787 3237187 253 155648 377 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411446] [ 795] 0 795 2591 189 61440 19 0 top
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411447] [ 800] 0 800 1462 28 45056 0 0 agetty
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411448] [ 802] 0 802 2528 33 57344 113 0 su
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411449] [ 803] 107 803 1791 5 53248 121 0 bash
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411449] [ 805] 107 805 4457 742 73728 109 0 pg_top
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411450] [ 809] 0 809 1350 13 45056 2 0 tail
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411450] [ 814] 0 814 1350 0 49152 19 0 tail
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411451] [ 816] 0 816 2528 76 57344 70 0 su
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411452] [ 817] 107 817 1791 77 53248 48 0 bash
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411452] [ 820] 107 820 5258 164 77824 186 0 psql
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411453] [ 821] 107 821 3237318 1507 266240 528 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411454] [ 895] 107 895 4176597 470580 8835072 440570 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411454] [ 916] 107 916 3998518 3307919 31916032 363732 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411455] [ 920] 107 920 3974889 3427544 31723520 213220 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411456] [ 1440] 107 1440 3991991 3315035 31862784 352355 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411456] [ 1441] 107 1441 3980138 3288174 31772672 355637 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411457] [ 1442] 107 1442 3949216 3256933 31522816 337108 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411458] [ 1443] 107 1443 3985666 3293792 31809536 356836 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411458] [ 1444] 107 1444 3968051 3292503 31674368 340971 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411459] [ 1445] 107 1445 3964887 3302708 31649792 330042 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411460] [ 1446] 107 1446 3956283 3283604 31580160 331813 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411460] [ 1447] 107 1447 3977547 3288972 31752192 354726 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411461] [ 1448] 107 1448 3992117 3304474 31862784 361598 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411462] [ 1449] 107 1449 3970448 3300835 31694848 336678 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411462] [ 1450] 107 1450 3978281 3292648 31756288 351614 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411463] [ 1452] 107 1452 3948804 3272602 31518720 332384 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411464] [ 1453] 107 1453 3952763 3277925 31551488 332973 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411464] [ 1454] 107 1454 3970674 3292624 31694848 343132 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411465] [ 1456] 107 1456 3986605 3292711 31817728 359756 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411466] [ 1496] 107 1496 3267949 910914 25538560 18162 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411466] [ 1498] 107 1498 3268046 909466 25456640 18233 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411467] [ 1499] 107 1499 3267457 901230 25513984 18050 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411468] [ 1500] 107 1500 3266930 899750 25526272 17580 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411468] [ 1501] 107 1501 3267822 898528 25505792 18096 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411469] [ 1962] 107 1962 3548712 388651 27648000 132307 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411470] [ 2132] 107 2132 3237928 458277 25616384 896 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411471] [ 3115] 107 3115 3539254 445361 13619200 261 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411471] [ 3118] 107 3118 3536983 448909 13660160 262 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411472] [ 3119] 107 3119 3542391 451070 13713408 262 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411473] [ 3121] 107 3121 3542814 446970 13594624 262 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411473] [ 3122] 107 3122 3541475 443816 13451264 262 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411474] [ 3297] 107 3297 3237732 418883 24821760 262 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411475] [ 3307] 107 3307 3237704 415495 24813568 262 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411475] [ 3311] 107 3311 3237654 15367 1142784 262 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411476] [ 3312] 107 3312 3237688 413668 24805376 262 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411477] [ 3314] 107 3314 3237226 680 184320 284 0 postgres
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411477] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/system.slice/system-postgresql.slice/postgresql@14-main.service,task=postgres,pid=916,uid=107
Jan 9 08:30:36 xenpsql001 kernel: [ 7328.411490] Out of memory: Killed process 916 (postgres) total-vm:15994072kB, anon-rss:1548688kB, file-rss:4kB, shmem-rss:11682984kB, UID:107 pgtables:31168kB oom_score_adj:0
Jan 9 08:30:37 xenpsql001 systemd[1]: postgresql@14-main.service: A process of this unit has been killed by the OOM killer.
Jan 9 08:30:43 xenpsql001 systemd[1]: postgresql@14-main.service: Failed with result 'oom-kill'.
Jan 9 08:30:43 xenpsql001 systemd[1]: postgresql@14-main.service: Consumed 25min 49.114s CPU time.
Jan 9 08:35:01 xenpsql001 CRON[3702]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Jan 9 08:45:01 xenpsql001 CRON[3707]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Jan 9 08:46:32 xenpsql001 systemd[1]: postgresql.service: Succeeded.
Jan 9 08:46:32 xenpsql001 systemd[1]: Stopped PostgreSQL RDBMS.
strange. Welche PG-Versio ist im Einsatz?
Hmm, irgendwo wird immer noch zu viel Speicher verbraucht (zumindest aus Sicht des Betriebssystems).
Kannst Du den OOM Killer nicht komplett abschalten?
Robbi
9. Januar 2023 um 10:36
18
PostgreSQL 14.6 (Debian 14.6-1.pgdg110+1)
Hmm, wie kann man es machen?
Robbi
9. Januar 2023 um 11:25
20
Hmm, OK mal schauen was es bringt. Ein “cat” bringt mir Standardmäßig 666 als Ergebnis. Ich habe jetzt ein -1000 in das _adj gesetzt.
cat /proc/1004/oom_score
666
Ob damit gleich die ganze VM um die Ohren fliegt…