Speicherverbrauch bei aktiviertem Debug

[demel42]

Eine Beobachtung: ich hatte letzte Tage ein IPS, das out of memory lief; nach 24h war der symcon-Prozess 5.2 GB groß, Tendenz weiter steigend.

Normalerweise liegt die Größe beim Start bei 2 GB und erhöht sich dann im Laufe einiger Stunden und liegt dann relativ stabil bei etwa 2.5-2.7 GB.
Das ist zwar auch nicht ohne, liegt aber auch daran, das ich ThreadCount = 100 gestellt und in der php.ini memory_limit=128M konfiguriert habe.

Der Hintergrund: ich hatte in einer Instanz den Debug in die Datei gelenkt und dieser Prozess war sehr geschwätzig (27 GB in 24h).

Nach IPS-Reboot war alles wieder tako.

Meine Version: IP-Symcon 6.4, Ubuntu (amd64), 23.05.2023, 6dccc096176c

Das recht hohe memory_limit habe ich übrigens, weil bestimmte Module sonst nicht durch laufen, zum einen meldet das Backup-Modul

Fatal error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 20480 bytes) in /var/lib/symcon/modules/.store/de.symcon.backup/libs/vendor/phpseclib/phpseclib/phpseclib/Net/SFTP.php on line 3083

Die größte Datei ist die settings.json mit 13m.

Zum andern habe ich drei Module, die IPS_GetSnapshot() bzw IPS_GetSnapshotChanges() nutzen und häufiger mal an Memorygrenzen stossen (brauchen aber eigentlich nur ein Bruchteil des Snapshot).

Nachtrag (26.9.2023)
leider hat sich die Hoffnung zerschlagen, das ohne Logging in die Datei das System stabil bleibt. Ich musste gestern das IPS neu starten, weil das Memory komplett verbraucht war (5,6 GB für IPS), d.h. das IPS hat in einem knappen Monat zusätzlich 3 GB RAM belegt. Auch wenn es schnell geht - senden Monat das IPS zu geboten ist ja nicht erstrebenswert.

Die IPS-Verson ist unverändert (IP-Symcon 6.4, Ubuntu (amd64), 23.05.2023, 6dccc096176c).

Dieser Memoryverbrauch ist meiner Erinnerung nicht schon immer so gewesen.
Ich kennen die Einbindung von PHP nicht, aber bin bisher davon ausgegangen, das der Speicher, den ein PHP-Thread benötigt, wieder freigegeben wird, wenn der Thread nicht mehr aktiv ist?
ThreadMemoryCleanup steht auf 10.

@paresy : gibt es irgend eine Möglichkeit, zu sehen, wo der Speicher verloren geht?

[demel42]

@paresy: das Speicherproblem ist leider noch weiterhin da

nach einer Woche war mein Symcon wieder zu groß - 17 GB

Ich hatte in der Linux-ServerInfo eingebaut, das er regelmäßig auch die Größe des Symcon-Dämons protokolliert

Nach dem fälligen Reboot ging es wieder von vorne los, der Prozess ist inzwischen wieder auf 6 GB.

Ich hatte dann in meinen Modulen eingebaut, was die Threads so an Speicher verbrauchen (mittels memory_get_peak_usage()).
Die meisten meiner Module sind zwischen 1-2 MB, nur das Syslog- und das ICinga-Modul sind deutlich größer

Das liegt daran, das ich dort IPS_GetSnapshotChanges() benutze, das offensichtlich echt viel Speicher braucht - so viel, das manchmal sogar ein Limit von 100 MB nicht reicht.

Trotzdem - auch dieser Speicherverbrauch dürfte ja nicht dazu führen, das immer mehr Speicher gebraucht wird, jeder Thread gibt doch sicherlich den gebrauchten Speicher wieder frei.

Ich bin ziemlich ratlos, was ich noch machen kann, wo ich suchen sollte. Eine Dauer zwischen zwei Reboot von 1-2 Wochen ist ja nun wirklich nicht so dolle. Ein solches Problem ist mir von früher nicht erinnerlich.

IPS ist immer noch: IP-Symcon 6.4, Ubuntu (amd64), 23.05.2023, 6dccc096176c

[paresy]

Hast du irgendeine Chance das Problem (auch wenn geringer) auf deinem Debug System nachzustellen?

Für die GetSnapshotChanges Funktion haben wir intern ja einen Puffer von 8196 Einträgen. Aber bei deinem Verbrauch müssten ja konstant alle Slots mit Debug-Meldungen von > 2 MB belegt sein.

Könntest du mal schauen, was passiert, wenn du IPS_TrimKernel(); alle 60 Sekunden aufrufst? (Seit der 7.0 ist dies Standardmäßig aktiv; aber in der 6.4 nur zum Testen drin).

paresy

[demel42]

@paresy

Hast du irgendeine Chance das Problem (auch wenn geringer) auf deinem Debug System nachzustellen?

Eher schwierig, vermutlich ist da zuwenig los. Ich probiere aber nich ein bisschen rum.
Wäre natürlich am besten

@paresy

Für die GetSnapshotChanges Funktion haben wir intern ja einen Puffer von 8196 Einträgen. Aber bei deinem Verbrauch müssten ja konstant alle Slots mit Debug-Meldungen von > 2 MB belegt sein

wenn mit Debug-Meldung > 2 MB gemeint ist, wie lang die Meldung ist, dann ist das nicht der Fall.

Ich mache das:

        $memory_limit = ini_get('memory_limit');
        if (preg_match('/^(\d+)(.)$/', $memory_limit, $matches)) {
            if ($matches[2] == 'M') {
                $memory_limit = $matches[1] * 1024 * 1024; // nnnM -> nnn MB
            } elseif ($matches[2] == 'K') {
                $memory_limit = $matches[1] * 1024; // nnnK -> nnn KB
            }
        }

        $sdata = @IPS_GetSnapshotChanges($TimeStamp);
        if ($sdata != '') {
            $slen = strlen($sdata);
            if ($slen > ($memory_limit / 2)) {
                $this->SendDebug(__FUNCTION__, 'snapshot (#' . $TimeStamp . ') is too large (len=' . $slen . ') - reset', 0);
                $this->LogMessage('snapshot (#' . $TimeStamp . ') is too large (len=' . $slen . ') - reset', KL_NOTIFY);
                $sdata = '';
            }
        }
        if ($sdata == '') {
            $this->MaintainStatus(self::$IS_NOSNAPSHOT);
            $old_ts = $TimeStamp;
            $this->InitialSnapshot();
            $TimeStamp = $this->GetBuffer('TimeStamp');
            $this->SendDebug(__FUNCTION__, 'unable to get snapshot (old=' . $old_ts . ', new=' . $TimeStamp . ') , resetting', 0);
            $this->LogMessage('unable to get snapshot (old=' . $old_ts . ', new=' . $TimeStamp . '), resetting', KL_NOTIFY);
            $sdata = @IPS_GetSnapshotChanges($TimeStamp);
            if ($sdata == '') {
                $this->SendDebug(__FUNCTION__, 'unable to get snapshot (#' . $TimeStamp . '), reset failed', 0);
                $this->LogMessage('unable to get snapshot (#' . $TimeStamp . '), reset failed', KL_NOTIFY);
                return;
            }
        }
        $snapshot = json_decode($sdata, true);
        if ($snapshot == '') {
            $txt = strlen($sdata) > 7000 ? substr($sdata, 0, 7000) . '...' : $r;
            $this->SendDebug(__FUNCTION__, 'unable to decode json-data, error=' . json_last_error() . ', len=' . strlen($sdata) . ', data=' . $txt . '...', 0);
            $this->LogMessage('unable to decode json-data, error=' . json_last_error() . ', length of data=' . strlen($sdata), KL_NOTIFY);
            $this->MaintainStatus(self::$IS_BADDATA);
            return;
        }

d.h ich hole SnapshotChanges, prüfe, ob es größer ist als die max. memory-size, wenn ja, wird ein IPS_GetSnapshotChanges(0); ausgelöst.
Das Ergebnis wird dann per json_decode() umgewandelt.
Dh die Größe ist des Snapshot-Delta ist dann pi*Daumen die Hälfte, also 50 MB. 50 MB durch 8192 sind dann, wenn ich richtig rechne, 6,25 KB … oder?

@paresy

Könntest du mal schauen, was passiert, wenn du IPS_TrimKernel(); alle 60 Sekunden aufrufst?

manuell schon mal aufgerufen, resident set size geht ordentlich zurück, Prozessgröße bleibt, aktuell so:

root@ips-prod:/var/lib/symcon/modules# ps -o size,rss,vsize,pmem,etimes,cputimes,pcpu -h -p 1859392
6817432 3171268 7215828 38.9 198909 9980  5.0

was / welcher syscall wird durch diese Funktion intern ausgelöst?

p1=Array
(
    [IPS_HANDLECOUNT] => 111
    [IPS_NUMTHREADS] => 179
    [IPS_VIRTUALSIZE] => 7429787648
    [IPS_WORKINGSETSIZE] => 5018058752
    [IPS_PAGEFILE] => 0
    [PROCESSCOUNT] => 138
)

p2=Array
(
    [IPS_HANDLECOUNT] => 111
    [IPS_NUMTHREADS] => 179
    [IPS_VIRTUALSIZE] => 7397400576
    [IPS_WORKINGSETSIZE] => 3002703872
    [IPS_PAGEFILE] => 0
    [PROCESSCOUNT] => 138
)

1921,9921875 MB

ich lasse es jetzt minütlich laufen und gebe morgen mal Bescheid

[paresy]

malloc_trim(0);

Technische Details zum Memory Hoarding von glibc findest du hier: When allocators are hoarding your precious memory | Algolia

Es kann dein Problem verbessern - aber evtl. ist es auch was anderes, da bbernhard ein ähnliches Problem (aber unter Windows) hier beschreibt: https://community.symcon.de/t/ursache-fuer-steigenden-speicherbedarf-gefunden/134344/4

Wie viele PHP-Threads hast du denn eigentlich aktiv? Denn bei z.B. 100 Stück á 100 MB wäre die obere Grenze ca. 10 GB für PHP anzusehen.

Wobei es gut wäre, wenn du nicht die Virtual Memory trackst, sondern eher RSS. Das ist die relevante Größe. Und 7 GB bzw. 5 GB ist da auch schon massiv zu viel.

paresy

[demel42]

@paresy

malloc_trim

ok, das passt dazu, das der RSS absinkt

@paresy

Wie viele PHP-Threads hast du denn eigentlich aktiv?

ja, 100 sind eingetragen

aber 10 GB wäre ja nur erreicht, wenn alle Threads so große Prozesse haben, die Threads geben genutzten Speicher doch wieder frei, oder?

Das mit dem Syslog/ICinga mache ich so aber auch schon Seitz „immer“ und aufgefallen ist mir das in der Deutlichkeit ja erst „neulich“. Ansonsten läuft IPS ja stur durch …

[paresy]

@demel42

aber 10 GB wäre ja nur erreicht, wenn alle Threads so große Prozesse haben, die Threads geben genutzten Speicher doch wieder frei, oder?

Genau. Das ist aber die Vermutung, die bberndard geäußert hatte. Dass eben dies nicht korrekt freigegeben wird.

@demel42

Das mit dem Syslog/ICinga mache ich so aber auch schon Seitz „immer“ und aufgefallen ist mir das in der Deutlichkeit ja erst „neulich“. Ansonsten läuft IPS ja stur durch …

Das ist das Problem mit dem glibc Problem. Das kam halt irgendwann mit einem OS Update und vollkommen unabhänging von Symcon.

paresy

[demel42]

das OS ist ein 20.04.6 LTS (GNU/Linux 5.4.0-163-generic x86_64). immer mit akt. Patches, ansonstenen bin ich auf der OS-version schon lange.

ich kann natürlich das mal auf 22.04 LTS aktualisieren. Ist eine VM unter Proxmox, sollte also nicht ganz so kompliziert sein.

Was die Freigabe angeht, hätte ich nur eine Erinnerung an (ur)alte Zeiten mit insuffizienter Memory-verwaltung: bei der Freigabe entstehen immer wieder Chunks, die zu klein sind um größere Blöcken bedienen zu können. d.h. der Speicher wird immer weiter fragmentiert und neue große Speicher-Blöcke wurden hinten angehängt. Die Head-Verwaltung was seinerzeit (war irgendein GCC-Problem) so doof, das die das nicht gehandelt bekommen hat. Dagegen könnte aber das trim helfen.

Das ist aber so lange her - quasi letztes Jahrtausend.

[paresy]

Schau dir mal den Artikel an, den ich oben verlinkt habe. Das Problem von glibc ist quasi sehr neu. Die haben das quasi kaputt optimiert

paresy

[demel42]

@paresy

Schau dir mal den Artikel an, den ich oben verlinkt habe. Das Problem von glibc ist quasi sehr neu. Die haben das quasi kaputt optimiert

ja, das sieht interessant aus. gute dinge kommen eben immer wieder
dann bin ich mal gespannt, was morgen / übermorgen die kurve so sagt

[demel42]

@paresy

Leider hat dr minütliche Aufruf von IPS_TrimKernel() nicht soviel gebracht.

Mittwoch nachmittag letzter Woche war der letzte Reboot vom IPS und man sieht, das es in Stufen hoch geht. Der Sprung in dieser Woche sieht natürlich nur wegen der dynamische Skalierung so heftig aus, waren aber trotzdem fast 500 MB in recht kurzer Zeit.
Z.Zt ist der Prozess 12,5 GB groß (nach einer Woche); vermutlich werden ich das IPS dann nachher neu starten müssen.
Cih werde die beiden Module, bei denen ich IPS_GetSnapshotChanges() benutze mal totlegen; ist zwar keine Dauerlösung, weil ich dann keine Weiterleitung an den Syslog mehr habe, lässt sich aber übergangsweise verschmerzen.
Und ich deaktiviere Kern->Backup, weil der auch ab und an mit memory-Fehlern kommt

Fatal error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 327680 bytes) in /var/lib/symcon/modules/.store/de.symcon.backup/libs/vendor/phpseclib/phpseclib/phpseclib/Net/SFTP.php on line 1314

[ubittner]

Ich hänge mich mal hier dran.

Ich habe eine Syncon Installation 6.4 auf einem RPi mit Docker, dies sieht für mich auch nach einem hohen Verbrauch aus:

Wie kann das gelöst werden?

Uli

[paresy]

@ubittner

Wie kann das gelöst werden?

Ich finde 230 MB nicht wirklich hoch. Nur die RES Spalte ist relevant.

@demel42: Wenn dein System mal einen Tag „langsamer“ laufen kann, könnten wir auf dem Ubuntu Heaptrack anwerfen und dort mal genauer tracken, was uns den Speicher klaut.

paresy

[demel42]

@paresy
klar, können wir gerne machen.

ich könnte die eine tailscale-adresse geben, dann kannst du auf dem server, so wie es bei dir passt, unabhängig von teamviewer-session o.ä.
oder wie wolltest du das am liebsten machen?

falls die vm (auf proxmox) zu langsam wäre, könnte ich da auch mehr cpu zuteilen

[demel42]

@paresy
ich habe eine neue Information.
Und zwar verwende ich ein AttributeString bei bestimmten Modulen um Informationen zu speichern über API-Aufrufe zu speichern (json-kodierte Daten). Aufgrund eines Designfehlers (bzw. ungenügender Kontrolle der Daten) wurde diese in einem Modul 5.6 MB groß, daher war settings.json 15 MB groß. Durch eine geschicktere Datenauswahl ist das Attribute jetzt nur noch wenige KB groß; settings,json hat nun eine Größe von 8.4 MB.

Diese Daten werden vielfach täglich (alle paar Minuten) aktualisiert.

Und das führt, so wie es jetzt aussieht, zu einem erheblichen Speicherverbrauch des Symcon-Prozesses.

Die aktuelle Kurve sieht dann jetzt auch so aus (ab Donnerstag nachmittag)

Das Level ist deutlich niedriger als vorher und es steigt nur moderat an; muss ich natürlich noch weiter beobachten.

Eventuell ist hier die Lücke zu finden - natürlich ist die Nutzung des Attributes hierfür nicht i.O., andererseits deutet der erhebliche Speicherverbrauch darauf hin, das hier Speicher nicht freigegeben wird.

Wenn es aus deiner Sicht sinn mach kann ich auch gerne versuchen ein solches Verhakten in einem Modul zu provozieren, dann könnt ihr sicherlich einfacher Debugger.

[paresy]

Wie oft hast du das Attribut denn aktualisiert?

paresy

[demel42]

hmm, so 1500-2000/Tag bestimmt

[demel42]

@paresy
ich habe mal ein Modul gebaut, mit dem man den Speicherverbrauch provozieren kann: GitHub - demel42/TestModule, Branch: memory_usage.

Das Modul hat 3 Properties

• initial_size: die initiale Größe des Attributes in MB
• increment_interval: die Angabe, bei jedem wievielten Aufruf das Attribute erweitert wird (0=nie, 1=jedesmal …), jeweils um 100 Bytes.
• step_interval: Sekunden zwischen den Aufrufen.

Es wird ein AttributeString mit eine simplen json-Struktur gefüllt

Es dauert ein bisschen, bis was passiert, aber es passiert

Mit dem Modul ServerInfo kannst du auch einfach die Prozessgröße im Auge behalten.

Vielleicht hilft das ja etwas. Wenn ich sonst noch unterstützen kann, gerne …

Nachtrag: das Problem tritt auch auf, wenn das Attribute nur verändert wird (also increment_interval = 0 ist)