Simples Logfile erstellen, aber als Thread loggen

Wenn du dir nicht sicher bist, in welchem der anderen Foren du die Frage stellen sollst, dann bist du hier im Forum für allgemeine Fragen sicher richtig.
Antworten
harryberlin
User
Beiträge: 227
Registriert: Donnerstag 17. Dezember 2015, 12:17

Und wieder mal was von mir zum verbessern.
In der Docu zu Logging hab ich zwar was mit Thread gelesen, aber bei dem englishen tu ich mir schwer und ich brauch was zum anfassen, sprich ein Beispiel.

Hab jetzt einfach mal selbst ne Classe erstellt und das event mit nen thread verknüpft.
Hintergrund ist, ich möchte so wenig wie möglich zeit fürs loggen verschwenden.
Gibts auch irgendwie ne Möglichkeit, das Komma vor den tausendstel Sekunden zu nen Punkt zu bekommen? So wie ich das gelesen hab, geht das nicht einfach mit dem zeitformat argument des loggers.

Code: Alles auswählen

#!/usr/bin/env python
# -*- coding: utf-8 -*-

import os
import time
import logging
from threading import Thread

class LoggerClass:
    def __init__(self, logheader, filepath):
        directory = os.path.dirname(filepath)
        if not os.path.exists(directory):
            os.makedirs(directory)
        self.logger = logging
        self.logger.basicConfig(format='%(asctime)s: ' + logheader + ': %(message)s' , filename=file, level=logging.DEBUG)

    def log(self, logmsg):
        thread = Thread(target=self.log_thread,args=[logmsg])
        thread.setDaemon(True)
        thread.start()

    def log_thread(self, logmsg):
        self.logger.debug('%s' % logmsg)

    def note(self):
        # for kodi notification
        pass


def main():
    Logger = LoggerClass('MyHead','./test/logfile.log')
    Logger.log('test')
    time.sleep(0.020)
    Logger.log('test2')
    del Logger


if __name__ == '__main__':
    main()

empty Sig
BlackJack

@harryberlin: Für jede Lognachricht einen eigenen Thread zu starten ist ziemlich sicher langsamer als einfach ganz normal zu loggen. Wieviel Anteil an der Laufzeit nimmt denn Logging bei Dir in Anspruch? Bis Du das nicht tatsächlich *gemessen* hast, solltest Du nicht versuchen etwas zu verbessern oder zu fixen von dem Du gar nicht weisst ob/wie schlecht es ist. Zudem wird Dir Multithreading zumindest bei CPython kaum etwas nützen, denn es kann auch bei mehreren Threads immer nur *einer* zur gleichen Zeit Python-Bytecode ausführen.
harryberlin
User
Beiträge: 227
Registriert: Donnerstag 17. Dezember 2015, 12:17

ok, im kodi log war es schon leicht verzögert, deswegen dachte ich mir, bau ichs hier auch gleich mit ein.
denn loggen über kodi v16 ist jetzt umständlich geworden, das logfile zu lesen.
also eigener logger.

aber was meinst du mit cpython? ist das python 2.7 was in kodi läuft cpython?

im code oben ist noch ein fehler:
self.logger.basicConfig(format='%(asctime)s: ' + logheader + ': %(message)s' , filename=filepath, level=logging.DEBUG)
empty Sig
BlackJack

@harryberlin: CPython ist die in C geschriebene Python-Implementierung von python.org. Andere Implementierungen müssen kein „global interpreter lock“ (GIL) haben. Jython (JVM) und IronPython (.NET) haben das beispielsweise nicht. Und es gibt eine experimentelle PyPy-Version ohne GIL.
__deets__
User
Beiträge: 14494
Registriert: Mittwoch 14. Oktober 2015, 14:29

@BlackJack ich denke schon, dass threading hier hilft - weil es ja IO-bound ist.

Folgendes Testprogramm liefert fuer mich ~60K im threaded und ~10K "normal" auf meinem Mac Book Air.

Code: Alles auswählen

import logging
import Queue
import threading
from functools import partial
import time
from itertools import count
import sys

logger = logging.getLogger()


def background_logger(q):
    while True:
        logger.error(q.get())


def threaded():
    queue = Queue.Queue()
    t = threading.Thread(target=partial(background_logger, queue))
    t.setDaemon(True)
    t.start()

    then = time.time()
    for n in count():
        queue.put("throughput: %f" % (float(n) / (time.time() - then)))


def normal():
    then = time.time()
    for n in count():
        logger.error("throughput: %f" % (float(n) / (time.time() - then)))


def main():
    logging.basicConfig(level=logging.DEBUG, stream=sys.stdout)
    if sys.argv[1] == "threaded":
        threaded()
    else:
        normal()

if __name__ == "__main__":
    main()
Natuerlich darf man nur einen Thread starten.
Sirius3
User
Beiträge: 17712
Registriert: Sonntag 21. Oktober 2012, 17:20

@__deets__: das liegt daran, dass Du im threaded-Fall gar nichts ausgibst, sondern nur Deine Queue füllst. Begrenzt Du die Länge Deiner Queue kommst Du nur auf den halben Throughput wegen dem Overhead der Queue. Ein einigermaßen intelligentes Betriebssystem sollte auch bei einem normalen Log relativ schnell weitermachen, weil es die Schreiboperation zwischenspeichert. Somit kann man bei Schreiboperationen relativ wenig gewinnen, weil so gut wie kein IO-Wait vorkommt.
BlackJack

Ein Problem sehe ich auch beim Zeitstempel. Ich würde ja erwarten, dass der Zeitstempel die Zeit des protokollierten Ereignisses angibt und nicht nicht die Zeit wann der Logging-Thread dazu gekommen ist das zu schreiben. Durch das GIL und dadurch das im Grunde keine Garantien gegeben werden in welcher Reihenfolge mehrere Threads dran kommen, kann man eventuell ”interessante” Effekte beobachten. Beispielsweise Protokolleinträge die laut Zeitstempel in ”batches” auftreten. Ausserdem kann es auf Systemen wie einem Raspberry Pi auch problematisch werden wenn wirklich viel protokolliert wird und das Protokoll auf die SD-Karte geschrieben wird. Ich könnte mir vorstellen das der Thread dann nicht hinterher kommt, und sich die Queue ordentlich füllt und die Zeitstempel dann wirklich gar nichts mehr mit dem Zeitpunkt des Ereignisses zu tun haben.
DasIch
User
Beiträge: 2718
Registriert: Montag 19. Mai 2008, 04:21
Wohnort: Berlin

Man sollte auch Bedenken dass man an Informationen die an den aktuellen Thread gebunden sind im anderen Thread nicht kommt. Das könnte z.B. bei Ausnahmen ein Problem sein.
harryberlin
User
Beiträge: 227
Registriert: Donnerstag 17. Dezember 2015, 12:17

Welche Informationen sollte ich beim schreiben von Infos in eine Datei aus dem Thread brauchen?

Hintergrund war ein einfaches Informationen ablegen, ohne dabei aufgehalten zu werden.
Da es das Modul gibt, dacht ich mir "das bietet sich doch an".
Dass beim nutzen von Thread ggf. ein schreib Prozess vor dem anderen kommt, kann natürlich vorkommen.
Doch dem sollte sich der Programmierer bewusst sein. Abhängig von den Daten, die geloggt werden sollen.
z.B. 1.banale Infos zu 2.Messwerten von Sensoren.
2. ganz klar ohne Thread.

Meine Ausführungen des Codes scheinen ja soweit zu passen.
Ne andere Idee, als Thread wegzulassen(weil es evtl. den Gegeneffekt erzielt), konnte ich jetzt nicht rauslesen.
empty Sig
__deets__
User
Beiträge: 14494
Registriert: Mittwoch 14. Oktober 2015, 14:29

@Sirius3

Ja und nein. Klar, mein Beispiel ist so nicht reell, weil ich immer mehr Speicher verbrauche. Aber mir ging es ja darum zu zeigen, dass auch Python's Multithreading Sinn hat - und zwar genau fuer einen Fall wie hier, wo man die IO-Last im Hintergrund abhandeln lassen kann.

Und in einem echten System sollte logging ja auch eher sporadisch sein - ich muss die Queue also so einstellen, dass die zu erwartende Spitzenlast abgefedert wird.

Die Ueberlegungen zur abgeschlossenheit eines Logeintrages sind davon in meinen Augen unabhaengig - und natuerlich bedeutet das Threading auch zwangsweise eine Entkopplung von Entstehungszeit und Logzeit. So kann man kein Journaled Filesystem machen, aber ein Bottleneck in einer Anfrageverarbeitung in einem Service halt schon.
BlackJack

@harryberlin: Wie DasIch schon geschrieben hat: Alle Informationen die an den Thread gebunden sind und nur lokal dort zur Verfügung stehen. Das sind auf jeden Fall Ausnahmen, also kann man die `exception()`-Methode vom Logger nicht verwenden, aber auch Bibliotheken können von `threading.local` gebrauch machen.

Noch mal: Das erstellen von Threads ist nicht kostenlos zu haben! Du solltest den Mehraufwand einen Thread pro Nachricht zu erstellen wirklich mal messen, ob das Programm dadurch wirklich schneller wird. Ausserdem kann man nicht unendlich viele Threads erstellen, die sind in der Regel vom Betriebssystem begrenzt, also solltest Du auch testen ob das mit vielen, schnell aufeinanderfolgenden Nachrichten überhaupt funktioniert, oder ob Du diese Grenze nicht schnell erreichst.

Threads wegzulassen ist in der Tat *die* Idee. Logging sollte nicht lange dauern. Tut es das doch, dann gibt es mit Threads die ganzen Probleme mit falschen Zeitstempeln und sich aufstauenden Nachrichten, entweder in einer Queue, oder noch schlimmer, in Form von immer mehr werdenden Threads, bis das Betriebssystem die einfach hart verweigert wenn die Grenze erreicht ist.

Wenn das Loggen zu langsam ist, weil zum Beispiel das Ziel eine Datei auf einer SD-Karte ist, dann sollte man *dort* ansetzen und nicht in eine langsame Datei loggen. Zum Beispiel in dem man eine RAM-Disk anlegt (sehr wahrscheinlich gibt es die bereits auf solchen Systemen), oder in dem man sich das asynchrone Loggen nicht selber bastelt, sondern einen dafür vorgesehenen Daemon verwendet. Auch so etwas sollte es bereits geben.
Antworten