Ideen und Konzepte für dynamisches Logging

[Karol B. (johnpatcher)]

Hi,

ich überdenke zur Zeit das Logging Konzept eines meiner Mikrocontroller 
Projekte [1]. Derzeit wird das so gehandhabt, dass es in einer 
Konfigurationsdatei (config.h) diverse defines gibt, die darüber 
entscheiden, ob die Logging Funktionalitäten für ein bestimmtes 
Software-Modul mit einkompiliert werden sollen, oder nicht.

Konkret sieht dies z.B. so aus:

#define LOG_BRIGHTNESS 1

#if (LOG_BRIGHTNESS == 1)
    uart_puts_P("Log");
#endif

Ich denke mit diesem Ansatz dürften die meisten vertraut sein. Das 
Logging aktiviert man i.d.R. nur zu Entwicklungszwecken und dabei muss 
man die Software sowieso neu kompilieren.

Im Zuge einer Erweiterung würde ich das Ganze nun aber gerne flexibler 
bzw. dynamischer gestalten wollen, sodass das Logging zur Laufzeit 
aktiviert bzw. deaktiviert werden kann. Mir ist klar, dass ich dabei 
nicht drum herum komme die entsprechende Funktionalität dauerhaft in die 
Software einzukompilieren und es dadurch notwendigerweise in seiner 
Größe wächst.

Mein erster Ansatz war nun ein dediziertes Logging-Modul mit (in etwa) 
folgendem Interface:

void log_output(uint8_t id, char* message);

void log_register(uint8_t id, char* name);
void log_unregister(uint8_t id);

void log_enable(uint8_t id);
void log_disable(uint8_t id);

Jedes Modul das Ausgaben loggen möchte, würde sich also über 
"log_register()", einem Namen und einer eindeutigen ID anmelden. Der 
Name wird bei der Ausgabe als Präfix voran gestellt, sodass man zuordnen 
kann von wem die Nachricht denn eigentlich stammt.

Über "log_enable()" kann man dann zur Laufzeit die Ausgaben für ein 
bestimmtes Modul aktivieren.

"log_output()" wird zum Ausgeben von Nachrichten verwendet. Beim Aufruf 
der Funktion wird zunächst geprüft, ob die Ausgabe für das gegebene 
Modul überhaupt aktiviert ist, ansonsten erfolgt keine Ausgabe.

Im Prinzip funktioniert das alles auch wie geplant. Allerdings bin ich 
in Sachen Flexibilität und Komplexität noch nicht ganz zufrieden. In der 
obigen Form lassen sich nur Strings ausgeben. Wenn ich also irgendwelche 
Variableninhalte oder ähnliches ausgeben möchte, dann muss ich mir 
zunächst händisch (mittels strcpy & Konsorten) einen String zusammen 
bauen, welchen ich an "log_output()" übergeben kann. Das kostet aber 
wiederum Rechenzeit und ist im Worst Case vergeudet, weil "log_output()" 
es einfach verwirft und nichts ausgibt (je nachdem ob Logging für 
entsprechendes Modul aktiviert).

Daraufhin habe ich eine Funktion "log_is_enabled()" gebastelt, die mir 
den aktuellen Status für ein gegebenes Modul zurückliefert. Einen String 
baue ich nur noch zusammen, wenn das Logging für das Modul wirklich 
aktiviert ist. Das wiederum gefällt mir aber nicht, weil ich dadurch an 
jeder Stelle an der ich loggen möchte zusätzliche Logik einbauen muss. 
Ein Ziel des Moduls war es aber, genau dies zu verhindern.

Zusätzlich würde ich gerne soviel konstante Strings wie möglich im 
Programmspeicher ablegen und nicht noch unnötig RAM belegen. Dies würde 
aber für jede Funktion eine zusätzliche "_P()" Variante notwendig machen 
und lässt sich nur "umständlich" mit dynamischen Inhalten (z.B. 
Variablen) verknüpfen.

Zugegeben: Ich neige wohl etwas zum Perfektionismus und bin wohl durch 
die Programmierung von "großen" Machinen verwöhnt. Hier kann man solche 
Probleme i.d.R. elegant lösen und den dabei entstehenden Overhead 
vernachlässigen. In der Welt der Mikrocontroller hingegen muss man wohl 
oder übel Trade-Offs in Kauf nehmen, um nicht die gesamten Ressourcen 
mit einem möglichst allgemein gehaltenem Logging-Modul zu füllen.

Mir fällt es allerdings schwer hier eine klare Linie anzusetzen. Wie ihr 
das? Gibt es eine elegante Möglichkeit das Ganze allgemein und flexibel 
zu lösen? Wie handhabt ihr so etwas bzw. wie würdet ihr so etwas 
angehen? Mir geht es hier wirklich nicht um fertigen Code, sondern ganz 
grundsätzlich um Konzepte und Ideen bzw. Meinungen von erfahrenen Leuten 
in diesem Gebiet.

Mit freundlichen Grüßen,
Karol Babioch

[1]: https://github.com/Wordclock/firmware

[Amateur (Gast)]

Wie wäre es mit einer formatierten Ausgabe z. B.:
Schlüssel (Zahl oder Zeichen für Datentyp)
Länge (Zahl oder im Datentyp implementiert)
Daten (s.o.)
Ev. CRC
Dann braucht Deine Empfangsroutine "nur" alles was kommt verarbeiten.
Was nicht kommt ist gesperrt oder nicht implementiert.

[Karol B. (johnpatcher)]

Amateur schrieb:
> Dann braucht Deine Empfangsroutine "nur" alles was kommt verarbeiten.
> Was nicht kommt ist gesperrt oder nicht implementiert.

Könntest du deine Idee vielleicht ein bisschen ausführen? Ich kann mir 
gerade nicht so wirklich vorstellen, was du meinst :(.

Mit freundlichen Grüßen,
Karol Babioch

[holger (Gast)]

>Wenn ich also irgendwelche
>Variableninhalte oder ähnliches ausgeben möchte, dann muss ich mir
>zunächst händisch (mittels strcpy & Konsorten) einen String zusammen
>bauen, welchen ich an "log_output()"

Dann bau dir ein log_output() das so arbeitet wie printf()
mit Formatstring und Variabler Parameterliste.
So schwer ist das auch nicht.

[Stephan (Gast)]

Hi,

was hältst du von 'Variable Argument Lists'?
Wenn du deiner Funktion Output noch einen 3. Parameter spendierst 
kannst, kannst du die Sache flexibler aufbauen.

void log_output(uint8_t ModulID, char* LogMessage, ...);

jetzt kannst du deine Funktion den String 'LogMessage' Parsen lassen, 
wie in printf und weißt dann, was für Parameter in der Liste folgen.

Ich habe diese Variante bei meinen Ereigniss-Loggern genutzt, auf dem 
AVR hatte ich meine Strings aber ins Flash gelegt und mir das Parsen mit 
einer MessageID gesparrt.

log_output(RS232Buffer, "Fehler: Buffer OVF %d Zeichen", toManyChars);

nur als Idee :-)

Stephan

[Karol B. (johnpatcher)]

holger schrieb:
> Dann bau dir ein log_output() das so arbeitet wie printf()
> mit Formatstring und Variabler Parameterliste.

Stephan schrieb:
> was hältst du von 'Variable Argument Lists'?
> Wenn du deiner Funktion Output noch einen 3. Parameter spendierst
> kannst, kannst du die Sache flexibler aufbauen.

Ja, die Idee gefällt mir sehr gut. Variable Parameterlisten verwende ich 
an anderer Stelle schon, bin allerdings nicht darauf gekommen printf() 
nachzubauen (Baum und Bäume und so). Die "offizielle" Version jedenfalls 
wollte ich nicht verwenden, weil die doch recht groß ist.

Vielen Dank für euren Input!

Stephan schrieb:
> Ich habe diese Variante bei meinen Ereigniss-Loggern genutzt,

Gibt es das irgendwo zum Ansehen ;)? Rein aus Interesse bzw. zur 
Inspiration ... ;).

> auf dem AVR hatte ich meine Strings aber ins Flash gelegt

Wie machst du das konkret bzw. was ist am Bequemsten? In deinem Beispiel 
ist davon nichts zu sehen und der String würde im RAM landen, oder?

Bisher habe ich hierfür ein eigenes Makro der Form:

#define uart_puts_P(s) uart_puts_p(PSTR(s))

Entsprechend würde sich wahrscheinlich ein log_output_P() Makro 
anbieten, oder? Makros mit flexiblen Parameter kennt GCC ja [1].

Mit freundlichen Grüßen,
Karol Babioch

[1]: https://gcc.gnu.org/onlinedocs/cpp/Variadic-Macros.html

[Amateur (Gast)]

Ein Supersimpelbeispiel
Dein Messsystem sendet z.B.
"P" 1234<CR>
"T" 567<CR>
"S" 12345<CR>
Beim Datenempfang via serielle Schnittstelle kann die Zeilenorientierung 
sehr gut zur Synchronisierung der einzelnen Datenpakete verwendet 
werden.
Ein Empfänger liest immer eine ganze Zeile und "schaut" sich das erste 
Zeichen an.

switch (Puffer [0])

'P': // ... z.B. Druck
'T': // ... z.B. Temperatur
'S': // ... z.B. Geschwindigkeit
default printf ("Moag i ned" );

Die obige Abfrage "merkt" gar nicht, wenn überhaupt kein 'T' kommt.
Natürlich ist das Ganze, je nach Anforderung (Sicherheit, Datenvolumen), 
so nicht brauchbar.

[Amateur (Gast)]

Ich vergaß:
Natürlich ohne ", Leerzeichen und einem "echten" Zeilenumbruch.

Also als C-Konstante (alle Zeilen):
"P1234\nT567\nS12345\n"
[0]    [0]   [0]

[Markus M. (Firma: EleLa - www.elela.de) (mmvisual)]

Karol Babioch schrieb:
> Gibt es eine elegante Möglichkeit das Ganze allgemein und flexibel
> zu lösen? Wie handhabt ihr so etwas bzw. wie würdet ihr so etwas
> angehen?

Die Ausgabe ist nicht wichtig, denn die meiste "Rechenzeit" benötigt das 
Warten bis das Zeichen auf dem UART endlich übertragen ist.
Somit sollte eine Ausgabe vermieden werden.

Danach die String-Verarbeitung im µC. Die ist für so ein kleines Ding 
mit begrenztem Speicher absolutes Gift.

Somit sind schon mal beide Ansätze für einen µC nur begrenzt brauchbar.

Ich habe jedoch genau so etwas schon programmiert, jedoch einen ganz 
anderen Ansatz verwendet:

Ein Array mit z.B. 50 Elementen und uint32_t. Bei jedem Prozeduraufruf 
wird der ProgrammCounter in das nächste Array Element geschrieben, und 
das als Ring-Speicher.
Wenn man sich noch extra Zahlen merken möchte so kann man die auch noch 
mit in das Array legen.

Nun, zum anschauen hält man den Debugger an und schaut in das Array.

Oder beim STM32 gibt es diverse Exceptions, die der µC automatisch ein 
z.B. Speicherzugriffsfehler anspringt (HardFaultException), darin habe 
ich auch schon mal eine UART-Ausgabe geschrieben, die das Array aus 
gibt.
Nun geht man mit der MAP-Datei her und kann die gezeigten Adressen der 
Funktion zuordnen.
Das ganze ist zwar für die Diagnose etwas aufwändiger, dafür belegt es 
kaum Ressourcen und ist schnell in der Bearbeitung.

[Karol B. (johnpatcher)]

Amateur schrieb:
> Ein Supersimpelbeispiel

Ok, danke für den Nachtrag. So ganz überzeugen tut mich das Konzept aber 
nicht, zumindest nicht in meinem Anwendungsfall. Ich will nicht nur 
Messwerte ausgeben können, sondern auch formatierte Nachrichten von 
verschiedenen Module.

Markus Müller schrieb:
> Warten bis das Zeichen auf dem UART endlich übertragen ist.
> Somit sollte eine Ausgabe vermieden werden.

Klar, UART ist langsam. Allerdings wird die Ausgabe bei mir in einem 
FIFO zwischengepuffert und solange dieser nicht voll ist, geht das alles 
ziemlich flink.

Markus Müller schrieb:
> Danach die String-Verarbeitung im µC. Die ist für so ein kleines Ding
> mit begrenztem Speicher absolutes Gift.

Ja.

Markus Müller schrieb:
> Somit sind schon mal beide Ansätze für einen µC nur begrenzt brauchbar.

Klar, das hatte ich im Eingangspost ja auch schon festgestellt.

Markus Müller schrieb:
> Ich habe jedoch genau so etwas schon programmiert, jedoch einen ganz
> anderen Ansatz verwendet:

> [...]

Halte ich für meinen Anwendungsfall auch für wenig sinnvoll. Es geht 
hier nicht unbedingt nur ums Debuggen, sondern auch um informative 
Ausgabe an (interessierte) Benutzer. Und da halte ich den Ansatz mit 
Debugger und Breakpoints für unpraktikabel - zumal es bei den ATmegas 
auch lange nicht so guten Support dafür gibt wie z.B. bei STM32.

Mit freundlichen Grüßen,
Karol Babioch

[Amateur (Gast)]

>Ok, danke für den Nachtrag. So ganz überzeugen tut mich das Konzept aber
>nicht, zumindest nicht in meinem Anwendungsfall. Ich will nicht nur
>Messwerte ausgeben können, sondern auch formatierte Nachrichten von
>verschiedenen Module.

Ich sehe keinen Grund, warum Du nicht z. B. hinter "M" eine Meldung des 
Moduls XY kundtust und "N" einen Meckerer des Thermometers ein 
einleitet.

Das Konzept: "Schlüssel" "Schlüsselstring/Datum" "Zeilenumbruch" sollte 
flexibel genug sein.

Einfach irgendwas mitten im Ausgabestrom ausgeben ist in den meisten 
Fällen nicht möglich, denn dies entspräche einem Brief ohne Adresse.

Der in meinem ersten Beispiel angeführte Fall: "default" entbindet dich 
nicht von der Verarbeitung.

Ein Schlüssel im Bereich von z. B. 20h bis F0h reicht für über 200 
Dingsbümser.

Benutzt Du das im ersten Post angerissene Format mit einem Längenfeld, 
so kannst Du auch völlig formatlose Binärdaten, beliebiger Länge 
(solange der Vorrat an RAM reicht), versenden. Also incl. dem Zeichen 
für einen Zeilenumbruch.

Brauchst  Du mehr als 255 Pakettypen, so ist an anderer Stelle was in 
die Hose gegangen und Du hast Dich mächtig verzettelt. Wobei man auch 2 
Bytes als Schlüssel verwenden kann;-)

[Axel S. (a-za-z0-9)]

Karol Babioch schrieb:
> ich überdenke zur Zeit das Logging Konzept eines meiner Mikrocontroller
> Projekte

Wenn man mal einen Blick über den Tellerrand wirft, dann gibt es in der 
Welt der Programmierung etablierte Konzepte für sowas.

Die Grundidee ist dabei, daß jeder Aufruf der Logging-Funktion eine 
Logmessage entlang zweier Koordinaten beschreibt:

1. Facility. Das könnte man in etwa mit "Software Modul" übersetzen. Das 
ist typischerweise eine Aufzählung. Z.B. {Konfiguration, Sensoren, 
Aktoren, Nutzereingabe, ...}

2. Severity. Das ist der Schweregrad der Meldung. Das ist typisch eine 
geordnete Liste: {Debug, Info, Warnung, Fehler, fataler Fehler}

Parametrisiert wird das log-System, indem man ihm eine Liste der zu 
loggenden Facilities mitgibt und die kleinste zu loggende Severity 
(alles was schwerwiegender ist, wird dann automatisch auch geloggt).

Noch komfortabler wird es, wenn man mehrere Log-Dispatcher hat (z.B. ein 
Display, einen Debug-Port, ein NVRAM) und für jeden eine derartige 
Parametrisierung durchführt.

Der Quellcode wird dabei prinzipiell nie verändert. Er enthält also 
immer alle Aufrufe der Logging-Funktion. Diese ist meist variadisch, 
z.B. mit 3 zwingenden Parametern (Facility, Severity, Format-String) und 
weiteren optionalen in Stil von printf().

Beispiele:

log(FILE_IO, ERROR, "Datei '%s' nicht gefunden", filename);

/* ... */

log(SENSORS, INFO, "Umgebungstemperatur ist %.1f°C", temp);

/* ... */

if (0 == 1)
  log(INTEGRITY, FATAL, "Ein Wunder!");

Das Logsystem kann evtl. weitere Daten hinzufügen. Etwa einen Timestamp 
vor der eigentlichen Meldung.

Ein bekannter Vertreter dieser Familie wäre log4j: 
https://en.wikipedia.org/wiki/Log4j

Für einen µC würde man die log() Funktion aber wohl eher als C-Makro 
implementieren. Dann kann man die Parametrisierung zwar nur zur 
Compilezeit machen, spart dafür aber jede Menge Code, wenn das Logging 
ausgeschaltet ist.


XL

[Karol B. (johnpatcher)]

Amateur schrieb:
> Ich sehe keinen Grund, warum Du nicht z. B. hinter "M" eine Meldung des
> Moduls XY kundtust und "N" einen Meckerer des Thermometers ein
> einleitet.

Naja, das löst halt das eigentliche Problem nicht wirklich. Ich war auf 
der Suche nach einem dynamischen Ansatz, der sich mit vertretbarem 
Umfang implementieren lässt und das Laufzeitverhalten nicht zu sehr 
beeinflusst. Dein Ansatz löst ja eher das Problem wie ich welche 
Datensätze auf der "Empfangsseite" zuordnen kann. Das Problem stellt 
sich mir aktuell aber gar nicht. Und beliebige Schlüssel für 
irgendwelche Module sind auch nur bedingt zu gebrauchen bzw. erfordern 
dann mehr Logik im Client, um das Ganze brauchbar darzustellen.

Axel Schwenke schrieb:
> Wenn man mal einen Blick über den Tellerrand wirft, dann gibt es in der
> Welt der Programmierung etablierte Konzepte für sowas.

> [...]

Ja, das ist mir durchaus bekannt. Das Problem ist aber, wie oben 
angemerkt, dass ein Mikrocontroller sich halt nur bedingt für ein solch 
"komplexes" System eignet. Mir persönlich reicht derzeit ein einfacher 
Wechsel zwischen an und aus, Loglevel benötige ich nicht, könnte ich 
aber relativ unproblematisch auch noch einbauen.

Axel Schwenke schrieb:
> Noch komfortabler wird es, wenn man mehrere Log-Dispatcher hat (z.B. ein
> Display, einen Debug-Port, ein NVRAM) und für jeden eine derartige
> Parametrisierung durchführt.

Ja, rein konzeptuell natürlich der beste Ansatz. In meinem Fall aber 
wieder Overkill, den man mit einer höheren Laufzeit sowie mehr RAM und 
Flashverbrauch bezahlen müsste.

Axel Schwenke schrieb:
> Das Logsystem kann evtl. weitere Daten hinzufügen. Etwa einen Timestamp
> vor der eigentlichen Meldung.

Ja, das hatte ich vorgesehen ;).

Axel Schwenke schrieb:
> Ein bekannter Vertreter dieser Familie wäre log4j:
> https://en.wikipedia.org/wiki/Log4j

Ist mir bekannt und habe ich auch schon benutzt. Nur kann man im 
Java-Umfeld den Overhead halt gut und gerne in Kauf nehmen, bei 
Mikrocontrollern sieht das etwas anders aus.

Axel Schwenke schrieb:
> Für einen µC würde man die log() Funktion aber wohl eher als C-Makro
> implementieren. Dann kann man die Parametrisierung zwar nur zur
> Compilezeit machen, spart dafür aber jede Menge Code, wenn das Logging
> ausgeschaltet ist.

Das war ja genau eine meiner Anforderungen. Ich möchte das Logging zur 
Laufzeit einschalten können, d.h. um den Code-Verbrauch komme ich nicht 
herum. Diesen wollte ich allerdings so gering wie möglich halten.

Letztendlich habe ich den o.g. Ansatz mit variablen Argumenten 
umgesetzt. Das Ganze lässt sich übrigens auch mit einem entsprechenden 
PSTR() Makro umsetzen, sodass die Strings im Flash landen und keinen 
zusätzlichen Ram in Anspruch nehmen, z.B. so:

#define log_output_P(module, fmt, ...) log_output_p(module, PSTR(fmt), ##__VA_ARGS__)

Dann gibt es zwei Funktionen der Form:

void log_output(log_module_t module, const char* fmt, ...);
void log_output_p(log_module_t module, const char* fmt, ...);

Letztendlich lassen sich beide auf die Funktion log_outputv() 
zurückführen, welche unter anderem eine va_list als Argument erwartet:

static void log_outputv(log_module_t module, const char* fmt, va_list ap);

Mit dem Resultat bin ich soweit in Sachen Codeverbrauch und Flexibilität 
ganz zufrieden. Ich werde darauf verlinken, sobald ich es vollständig 
aufgeräumt und dokumentiert ist.

Vielen Dank für euren Input, das hat mir in jedem Fall weitergeholfen.

Mit freundlichen Grüßen,
Karol Babioch

[Purzel H. (hacky)]

Debugging ist bei mir Teil des Projekts, Teil des Produkts. Dh ich kann 
immer alles was ich moechte abfragen, dh zur Laufzeit, nicht nur zur 
Entwicklungszeit. Die Commands zum Debuggen sind etwas anders 
parametrisiert, aber aehnlich zum normalen Commandset. Gleiches 
Protokoll.

Soviele Resourcen muss man sich einfach goennen.