- √ - [Alpha] sh.py/python3 frisst Speicher

[henfri]

Hallo,

mein Server reagiert gerade sehr träge:

top - 11:08:13 up 6 days, 23:48,  2 users,  load average: [B]4.50, 4.51, 4.10[/B]
Tasks: 169 total,   1 running, 168 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.7%us,  2.5%sy,  0.0%ni, 43.9%id, [B]52.8%wa[/B],  0.2%hi,  0.0%si,  0.0%st

--> Hohe Last
--> Prozessor ist aber Idle
--> wa ist hoch --> Wartet auf I/O

Sortiert nach Ram:

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
20245 smarthom  20   0 7058m 3.2g   [B]84[/B] D    1 87.9  12:12.93 python3

Anbei ein Log.
Was daran schon auffällt:
Es endet bei 10:45, es ist aber 11:14.

Ich kille sh.py erstmal nicht. Vielleicht habt ihr ja noch Ideen zum Debuggen während das Problem besteht.

Gruß,
Hendrik

[callidomus]

Hallo Hendrik,

ist das bei Dir immer noch so?
Meine Instanz hier pendelt sich bei ca. 25 MByte ein.

Bis bald

Marcus

[mode]

Bei mir siehts so aus:

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
31560 root      20   0  706m  16m 3208 S    1  0.9   4:13.89 python3

[henfri]

Hallo,

ich glaube, bei mir ist es jetzt besser:

top - 16:34:19 up 2 days, 21:41,  1 user,  load average: 1.76, 1.60, 1.59
Tasks: 160 total,   1 running, 159 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.2%us,  1.5%sy,  0.0%ni, 97.7%id,  0.7%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   3795752k total,  3601724k used,   194028k free,   898656k buffers
Swap:  8293372k total,   134880k used,  8158492k free,  1793488k cached

Wobei ich die Load von 1.76 nicht verstehe?! er ist zu 98% idle und seitens IO ist auch nix los. Woher kommt die hohe Load?

Gruß,
Hendrik

[JuMi2006]

Sieh Dir mal den owserver an.

[henfri]

Fehlanzeige!

[dirk2013]

Hallo,

hast Du schon mal mit iostat 1 näher in das System geschaut? Vielleicht ist er am swappen?

[henfri]

Danke für den Tipp.

Ich hatte mit iotop geguckt.
Hier aber mal iostat:

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0,00    0,00    2,01    0,00    0,00   97,99

Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
sda               0,00         0,00         0,00          0          0
sdb               0,00         0,00         0,00          0          0
sdd               0,00         0,00         0,00          0          0
sdc               0,00         0,00         0,00          0          0

^C
root@homeserver:/mnt/Datenplatte/Musik# top
top - 17:46:06 up 2 days, 22:52,  2 users,  load average: 1.85, 2.47, 2.27
Tasks: 167 total,   1 running, 166 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.2%us,  1.7%sy,  0.0%ni, 94.9%id,  3.0%wa,  0.1%hi,  0.0%si,  0.0%st
Mem:   3795752k total,  3413792k used,   381960k free,   930432k buffers

Auf der Platte ist wenig los..

Gruß,
Hendrik

[callidomus]

Hi,

stop doch mal SH.py und schau ob es besser wird.

Bis bald

Marcus

[henfri]

Hallo,

na, sh.py hatte ich schon ausgeschlossen (eben so) sorry, hätte ich besser kommunizieren sollen.

Ich habe jetzt auch den Übeltäter gefunden:
In einem solchen Fall sollte man in top nach Prozessen mit dem Status D suchen:

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
23476 root      20   0     0    0    0 D    2  0.0   4:55.46 kdvb-ad-0-fe-0

Den konnte ich nicht mal killen. Auch nicht so:
Kill -9 does not work - Noah.org

Aber dvb klang nach "benutzt vom vdr".
Seit einem stop vdr ist die Load normal (0.08).

Vermutlich liegt es an nicht angeschlossenen Sat-Kabeln :-(

Aber: Ich hatte Läuse UND Flöhe.
Das Problem mit sh.py war ja in meinem ersten Post augenscheinlich.
Marcus hat es aber zwischendurch gefixt.

Gruß,
Hendrik

[henfri]

Hallo,

jetzt habe ich hier wieder so einen Fall:

top - 21:04:13 up  7:07,  2 users,  load average: 2.61, 1.65, 1.25
Tasks: 179 total,   3 running, 176 sleeping,   0 stopped,   0 zombie
Cpu(s): 49.3%us,  1.3%sy,  0.2%ni, 45.2%id,  3.8%wa,  0.2%hi,  0.0%si,  0.0%st
Mem:   3795752k total,  3611292k used,   184460k free,     1584k buffers
Swap:  8293372k total,   375604k used,  7917768k free,   101248k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 2533 smarthom  20   0 3860m 3.0g 1828 R  100 83.3   3:47.44 python3

beende ich smarthome.py, so ist die Load wieder normal.

Anbei ein Log. Komisch dabei: das Log endet um 19:44. gekillt hab ich sh.py aber erst kurz nach 9. Und die Visu hat auch noch funktioniert.

Gruß,
Hendrik

[henfri]

Hallo,

ich sehe gerade eine Sache:

2013-10-13 21:20:27 ERROR    System       Logic: System, File: system.py, Line: 31, Method: <module>, Exception: unorderable types: type() < type()
Traceback (most recent call last):
  File "/usr/local/smarthome/lib/scheduler.py", line 327, in _task
    exec(obj.bytecode)
  File "system.py", line 31, in <module>
TypeError: unorderable types: type() < type()

Die system.py ist deine:

cat logics/system.py
def td2str(td):
    hours, seconds = divmod(td.seconds, 3600)
    minutes, seconds = divmod(seconds, 60)
    if td.days:
        return "{0}d {1}h {2}m".format(td.days, hours, minutes)
    else:
        return "{0}h {1}m".format(hours, minutes)

# Runtime
runtime = sh.tools.runtime()
sh.smarthome.runtime(td2str(runtime))

# Threads
tn = {}
tc = threading.activeCount()
for t in threading.enumerate():
    tn[t.name] = tn.get(t.name, 0) + 1
logger.info('Threads ({0}): '.format(tc) + ', '.join("{0}: {1}".format(k, v) for (k, v) in list(tn.items())))
sh.smarthome.threads(tc)

# Object Counter
d = {}
sys.modules
# collect all classes
for m in list(sys.modules.values()):
    for sym in dir(m):
        o = getattr (m, sym)
        if isinstance(o, type):
            d[o] = sys.getrefcount (o)
# sort by refcount
pairs = sorted([(x[1],x[0]) for x in list(d.items())])
pairs.reverse()
obj = ''
for n, c in pairs[:10]:
    obj += "{0}: {1}, ".format(c.__name__, n)
obj = obj.strip(', ')
logger.info("Objects (Top 10): {0}".format(obj))

# Garbage
import gc
gc.set_debug(gc.DEBUG_LEAK)
gc.collect()
if gc.garbage != []:
    logger.warning("Garbage: {0}".format(gc.garbage))
    del gc.garbage[:]

# Load
l1, l5, l15 = os.getloadavg()
logger.debug("Load: {0}, {1}, {2}".format(l1, l5, l15))
sh.system.load(round(l5, 2))

# Memory
statusfile = "/proc/{0}/status".format(os.getpid())
units = {'kB': 1024, 'mB': 1048576}
with open(statusfile, 'r') as f:
    data = f.read()
status = {}
for line in data.splitlines():
    key, sep, value = line.partition(':')
    status[key] = value.strip()
size, unit = status['VmRSS'].split(' ')
mem = int(size) * units[unit]
sh.smarthome.memory(mem)

# System Memory
statusfile = "/proc/meminfo"
units = {'kB': 1024, 'mB': 1048576}
with open(statusfile, 'r') as f:
    data = f.read()
for line in data.splitlines():
    key, sep, value = line.partition(':')
    if key.startswith('Mem'):
        size, unit = value.strip().split(' ')
        mem = int(size) * units[unit]
        if key == 'MemTotal':
            total = mem
        elif key == 'MemFree':
            free = mem
sh.system.memory(100-int(free/(total/100)))

# System Uptime
statusfile = "/proc/uptime"
with open(statusfile, 'r') as f:
    data = f.read()
uptime = int(float(data.split()[0]))
uptime = datetime.timedelta(seconds=uptime)
sh.system.uptime(td2str(uptime))

Gruß,
Hendrik

[callidomus]

Hallo Hendrik,

in Deinem Log ist nichts zu finden. Das endet, wie bereits geschrieben um 1944. Da wurde SH.py korrekt herunter gefahren.

Aktualisiere mal SH.py. Dann kannst Du auch die System-Logik löschen.
In der Entwicklerversion gibt es einen env - Baum mit diversen Informationen.

Geh mal per Telnet zum CLI Plugin und gib mal 'ls env' ein.

Bis bald

Marcus

[henfri]

Hi Marcus,

hm, dann hat wohl mal wieder die root-falle zugeschlagen (um 19:44 lief sh.py noch als root, danach wieder als normaler User) (Vermutung).

Zum CLI-Output:
Korellation ist nicht Kausalität, aber in dem Moment als ich das erste mal im CLI etwas eingegeben habe kam im Log zeitgleich:

2013-10-13 22:18:22 ERROR    Main         Connections: 'utf-8' codec can't decode byte 0xff in position 0: invalid start byte
Traceback (most recent call last):
  File "/usr/local/smarthome/lib/connection.py", line 108, in poll
    con._in()
  File "/usr/local/smarthome/lib/connection.py", line 243, in _in
    self.found_terminator(data)
  File "/usr/local/smarthome/plugins/cli/__init__.py", line 45, in found_terminator
    cmd = data.decode().strip()
UnicodeDecodeError: 'utf-8' codec can't decode byte 0xff in position 0: invalid start byte

Es gab KEINEN output am CLI. Beim zweiten Mal kam kein Fehler und dieser Output:

SmartHome.py v0.9-335-gca9a1c7+
                               Enter 'help' for a list of available commands.
                                                                             > ls env

>
> ls env
Items:
======
env
env.core
env.core.version=0.9-335-gca9a1c7+
env.core.uptime=0:00:08.275213
env.core.memory=26701824
env.core.threads=7
env.core.garbage=0
env.location
env.location.sunrise=0
env.location.sunset=0
env.location.moonrise=0
env.location.moonset=0
env.location.moonphase=0
env.system
env.system.uptime=8:21:35
env.system.load=0.35
env.system.name=homeserver

Gruß,
Hendrik

[henfri]

Update:
zu obigem Zeitpunkt bestand das Problem NICHT.
Jetzt besteht es wieder:

top - 22:28:39 up  8:32,  2 users,  load average: 2.41, 2.28, 1.33
Tasks: 174 total,   2 running, 171 sleeping,   1 stopped,   0 zombie
Cpu(s):  9.7%us,  6.7%sy,  0.0%ni, 29.9%id, 53.4%wa,  0.3%hi,  0.0%si,  0.0%st
Mem:   3795752k total,  3711472k used,    84280k free,     1160k buffers
Swap:  8293372k total,   358324k used,  7935048k free,    14840k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
10536 smarthom  20   0 4181m 3.3g 2044 D   25 90.2   1:15.23 python3

und ein ls env gibt keinen Output; sh.py ist wohl zu beschäftigt.

Anbei das aktuelle Log. Es ist -und das wundert mich- 2 min alt.
Nein: gerade noch mal rein geguckt, es ist eine Lücke drin:

2013-10-13 22:28:24 INFO     1w-sen       1-Wire: path not found for Daten.Gaestebad_Wasserleitung
2013-10-13 22:30:35 INFO     Scheduler    Adding worker thread. Total: 6
2013-10-13 22:30:35 INFO     Scheduler    Threads: Allgemein.Stromzaehler.Momentanleistung_1min: 2, Allgemein.Stromzaehler.Leistungsdurchschni24h: 1, idle: 1, Scheduler: 1, Thread-6: 1, Main: 1, wunderground: 1
2013-10-13 22:31:00 ERROR    Main         Connections: 'utf-8' codec can't decode byte 0xff in position 0: invalid start byte
Traceback (most recent call last):
  File "/usr/local/smarthome/lib/connection.py", line 108, in poll
    con._in()
  File "/usr/local/smarthome/lib/connection.py", line 243, in _in
    self.found_terminator(data)
  File "/usr/local/smarthome/plugins/cli/__init__.py", line 45, in found_terminator
    cmd = data.decode().strip()
UnicodeDecodeError: 'utf-8' codec can't decode byte 0xff in position 0: invalid start byte

Es wurde zu dem Zeitpunkt der letzten Zeilen auch eine Aktion, die ich lange vorher per smartvisu ausgelöst habe ausgeführt.

Und jetzt kam auch das ls env durch:

Items:
======
env
env.core
env.core.version=0.9-335-gca9a1c7+
env.core.uptime=0:10:08.711196
env.core.memory=3088281600
env.core.threads=7
env.core.garbage=0
env.location
env.location.sunrise=0
env.location.sunset=0
env.location.moonrise=0
env.location.moonset=0
env.location.moonphase=0
env.system
env.system.uptime=8:31:41
env.system.load=2.37
env.system.name=homeserver

Gruß,
Hendrik