[C++] Tracing/logging ostream-style (multithreaded)

[Soultaker]

Voor een hobbyprojectje ben ik een daemon/service aan het schrijven die tenminste onder UNIX en Windows moet gaan draaien. Omdat dit een achtergrondproces is, moet het programma af en toe wat informatie doorgeven over de operatie. Die informatie komt in verschillende categorien, zoals foutmeldingen, informatieve mededelingen en debug informatie. De laatste categorie mag in principe gewoon naar standard output, maar de eerste twee zijn nogal afhankelijk van het platform en de siutatie waarin ze draaien; bijvoorbeeld, foutmeldingen gaan bij het debuggen gewoon naar standard error, maar als Windows service naar de event logger en als UNIX daemon naar syslog.

Op dit moment schrijf ik alle berichten gewoon naar standard output met gebruik van std::cout. Dat werkt erg prettig, omdat ik dan allerlei standaardtypes als integer, doubles, strings, enzovoorts zonder gedoe kan weergeven. Nu wil ik echter een systeem ontwikkelen waarbij ik op deze gemakkelijke manier berichten kan formatteren, maar dat die wel op de juiste plek terecht komen.

Mijn eerste gedachte was om een aantal klassen te schrijven die van std::streambuf erven zodat ik gewoon naar een std::ostream object kan schrijven en dat de inhoud dan ergens anders heengaat (syslog, stdout, event log). Ik maak dan aparte std::ostream objecten voor verschillende doelen (bijvoorbeeld eentje voor foutmeldingen en eentje voor debug messages). Bij het opstarten initialiseer ik de references naar die objecten afhankelijk van de situatie.

Dit werkt best aardig, maar het eerste probleem is al dat het op deze manier nogal lastig is om aparte berichten te onderscheiden; bijvoorbeeld: wanneer zijn drie afzonderlijke regels die afzonderlijke berichten en wanneer is het een enkel bericht dat uit drie regels bestaat?

Om dit probleem te verhelpen dacht ik eraan om een stream modifier te schrijven die het einde van een bericht markeert (een soort std::endl maar dan anders). Maar als ik eenmaal begin met stream modifiers, zijn de mogelijkheden nog veel groter. Ik kan immers ook elk bericht vooraf laten gaan met een modifier die aangeeft wat voor soort melding het is. Dat heeft als voordeel dat ik niet een vast aantal streams hoef aan te maken, wat vooral handig is voor debug traces waarbij het handig kan zijn om een groot aantal debug traces te maken. In het gebruik zou het er dan ongeveer zo uit moeten komen te zien:

C++:

log << log::info()    << "Application started." << log::eot;
log << log::trace(10) << "Incoming request received from " << remote_host << log::eot;
log << log::trace(50) << "Random number generator initialized." << log::eot;

Op zich een mooie oplossing, dacht ik zo, behalve dat dit alleen in een singlethreaded omgeving werkt, en dat is dus het tweede probleem met deze aanpak. Een fix/hack hiervoor zou zijn om een lock te pakken bij het verwerken van zo'n stream modifier die het begin van een bericht aangeeft (zoals log::info in mijn voorbeeld) en die weer vrij te geven bij het verwerken van en log::eot modifier. Echt mooi vind ik dat echter niet.

Als alternatief dacht ik eraan om het threading probleem op te lossen door af te stappen van het idee van een centraal ostream-object waar naar geschreven wordt. Als elk bericht toch vooraf gegaan wordt door een modifier met een constructor, dan kan die modifier zelf ook wel als ostream dienstdoen:

C++:

log::trace(100) << "The aliens have landed at " << time << "!";

Het idee is dat op deze manier lokaal een bericht wordt opgebouwd dat in een keer weggeschreven wordt. Tijdens het opbouwen van het bericht wordt de staat lokaal in de thread bijgehouden en dat is dus thread safe. Maar volgens mij is het allemaal ontzettend ingewikkeld om dat ueberhaupt werkend te krijgen omdat die temporary const moet zijn en 'ie waarschijnlijk al destructed is voor ik er voor de tweede keer naar kan schrijven. Ik heb nog niet in detail uitgezocht hoe dit er dan uit zou moeten komen te zien.

Al met al kom ik dus niet echt tot een bevredigende oplossing, vandaar dat ik hier om suggesties wil vragen. Meer concrete vragen zijn: hoe doen jullie multithread ostream-style logging in C++? Of, indien jullie dat helemaal niet doen omdat het veel handiger anders kan, hoe dan? Slaat mijn idee een beetje ergens op, vergis ik me hier en daar, of klopt het wel maar is het allemaal nodeloos onhandig? Graag jullie reacties.

[.oisyn]

Soultaker schreef op 02 juni 2004 @ 20:59:
Een fix/hack hiervoor zou zijn om een lock te pakken bij het verwerken van zo'n stream modifier die het begin van een bericht aangeeft (zoals log::info in mijn voorbeeld) en die weer vrij te geven bij het verwerken van en log::eot modifier. Echt mooi vind ik dat echter niet.

waarom niet? Het lijkt mij een prima oplossing.

Maar volgens mij is het allemaal ontzettend ingewikkeld om dat ueberhaupt werkend te krijgen omdat die temporary const moet zijn en 'ie waarschijnlijk al destructed is voor ik er voor de tweede keer naar kan schrijven.

Dit snap ik niet helemaal, kun je dat toelichten? Het object zal sowieso niet tijdens het uitvoeren van die statement gedestruct worden, en ook niet zolang er een referentie naar is (waar de compiler vanaf weet iig).

[Soultaker]

.oisyn schreef op 02 juni 2004 @ 21:13:
Dit snap ik niet helemaal, kun je dat toelichten? Het object zal sowieso niet tijdens het uitvoeren van die statement gedestruct worden, en ook niet zolang er een referentie naar is (waar de compiler vanaf weet iig).

Ik ben niet 100% in de C++ standaard thuis (of de mate waarin gangbare compilers aan allerlei details conformeren) dus ik vind het nogal tricky om op allerlei details te vertrouwen. Het idee was om een klasse af te leiden van std::ostringstream en dan upon destruction er iets mee te doen:

C++:

class trace : public std::ostringstream {
public:
    trace(int level = 10) : _level(level) { };
    ~trace() {
        if(level >= min_level)
            cout << str(); // of ipv. cout natuurlijk syslog, of whatever!
    }

protected:
    int _level;
};

Maar dat werkt alleen als de compiler mij garandeert dat bij zulk gebruik:

C++:

trace(50) << "Foo" << 134 << std::endl << "bar";

De temporary (als resultaat van de expressie trace(50)) non-const is (waar het al mis gaat, ben ik bang) en ten tweede dat 'ie aan het einde van de statement gedestruct wordt: niet later, want bij debug tracing is het wel belangrijk dat berichten direct weergegeven worden (voordat, bijvoorbeeld, de volgende instructie de applicatie laat hangen), maar ook niet eerder, omdat al die operator<<'s op hetzelfde object moeten werken (en het object dus niet gedestruct mag zijn waardoor de reference ernaar ongeldig wordt).

Ik twijfel of die methode ueberhaupt haalbaar is, zonder 'm ontzettend ranzig en unportable te maken. Al te 'ingenieuze' constructies zouden wel eens mis kunnen gaan bij het optimizen van een compiler.

[.oisyn]

De garantie dat ie niet in het midden van de statement heb je volgens mij, maar hier zal ik de standaard maar nog eens op naslaan. Dat ie later destruct is op zich niet zo'n probleem als je er accolades omheen zet. Hij zal iig gedestruct worden voor de }

[Olaf van der Spek]

Soultaker schreef op 02 juni 2004 @ 20:59:
Op dit moment schrijf ik alle berichten gewoon naar standard output met gebruik van std::cout. Dat werkt erg prettig, omdat ik dan allerlei standaardtypes als integer, doubles, strings, enzovoorts zonder gedoe kan weergeven. Nu wil ik echter een systeem ontwikkelen waarbij ik op deze gemakkelijke manier berichten kan formatteren, maar dat die wel op de juiste plek terecht komen.

Is dat wel thread-safe dan?
Kan het niet zo zijn dat thread 1 begint met een line naar cout te schrijven en dat dan thread 2 een line schrijft en daarna thread 1 weer verder gaat?

[Soultaker]

OlafvdSpek schreef op 02 juni 2004 @ 21:42:
Is dat wel thread-safe dan? Kan het niet zo zijn dat thread 1 begint met een line naar cout te schrijven en dat dan thread 2 een line schrijft en daarna thread 1 weer verder gaat?

Nu is het inderdaad ook niet threadsafe; ik doe het alleen maar op die manier omdat dat toevallig de makkelijkste manier was om bij het testen wat uitvoer te krijgen. Het doel van het topic is om een structurele, betere oplossing te vinden en dan dus die ad-hoc methode vervangen.

[.oisyn]

Kun je trouwens niet gewoon een stream per thread opzetten? Je trace functie returned dan een reference naar de stream voor de actuele thread. En bij een flush schrijf je het hele bericht weg met behulp van een lock.

[Soultaker]

De threads komen uit een threadpool die door een CORBA ORB (omniORB) beheert wordt. Het is dus vrij lastig om daar mijn eigen thread local storage in te zetten, omdat de ik threads niet zelf aanmaak of opruim. Ik kan misschien wel uitzoeken in welke thread ik momenteel zit, maar dat moet dan ofwel met een omniORB-specifieke techniek of met een platform-specifieke techniek. Het eerste, als het al kan, is erg jammer, omdat het daarmee onmogelijk wordt om de applicatie met een andere ORB te builden, en het tweede is veel werk omdat ik dan allerlei platformafhankelijke code moet schrijven. Op dit moment heb ik eigenlijk nauwelijks platformspecifieke code en denk ik dat ik kan builden voor elk platform dat ofwel Windows ofwel POSIX ondersteund, juist omdat de meeste platformafhankelijke dingen al door de ORB afgehandeld worden.

Vanuit performance oogpunt waren thread local streams wel prettig geweest, omdat er veel minder bij gelockt hoeft te worden, maar de performance is toch al niet zo geweldig omdat de manier die ik voor ogen heb ook in een release build allerlei code zit om debug messages te genereren. Misschien is het handiger om daar eerst wat op te verzinnen (al denk ik dat dat vrij moeilijk op te lossen is).

[Soultaker]

Even een kick, want ik heb nog anderhalve vraag over. Hoe zit het met constness van het temporary object in deze constructie:

C++:

trace(50) << "Foo" << 134 << std::endl << "bar";

Als ik me niet vergis zijn temporaries altijd const. Hoe zorg ik ervoor dat ik er dan toch naar kan schrijven zonder dat ik alle operator<<'s moet overloaden en allerlei mutable members nodig heb? Eventueel kan trace() een functie zijn die een non-const object oplevert, maar heb ik dan nog steeds de garantie dat dat ding het hele statement lang bestaat?

De halve vraag was of er nog principiële haken en ogen zitten aan die constructie. Gevoelsmatig vind ik het niet zo netjes om allerlei relevante code in destructors te hangen. Naar mijn mening moeten constructors en destructors liefst zo transparant mogelijk werken en moet de code niet al te veel vertrouwen op het al dan niet draaien van destructors (al kun je er van uitgaan dat constructors en destructors in balans zijn, natuurlijk).

Tenzij iemand nog interessante dingen toe te voegen heeft, implementeer ik wel het idee met de stream modifiers die zelf locking doen, a la dit voorbeeld:

C++:

log << trace(50) << "Foo" << 134 << std::endl << "bar" << log::eot;

[ Voor 8% gewijzigd door Soultaker op 04-06-2004 12:08 ]

[Verwijderd]

Ik heb iets dergelijks gemaakt onder Visual C++ en daaronder werkt het correct.
De formattering heb ik echter gescheiden van de "sink", dus na het formatteren
wordt de string voor verwerking wordt aangeboden aan een sink-interface
(voor een library waar ik een tijdje aan heb gewerkt wordt deze interface geimplementeerd als een producer/consumer queue met daaraan gekoppeld 1 of meer threads of runnables die het naar een of andere std::ostream sturen.)

O ja, vergeten te zeggen: toevallig destruct Visual C++ alles in de "juiste" volgorde
(dus 2 debug statements achter elkaar worden dan in de goede volgorde afgehandeld, dus bv. "Trying to connect..." wordt dan afgehandeld voor "Connection established"). Bij andere compilers hoeft dat niet zo te zijn, volgens mij zegt de standaard daar niets over.

[ Voor 29% gewijzigd door Verwijderd op 04-06-2004 12:39 ]

[MSalters]

Soultaker schreef op 04 juni 2004 @ 12:08:
Even een kick, want ik heb nog anderhalve vraag over. Hoe zit het met constness van het temporary object in deze constructie:

C++:

trace(50) << "Foo" << 134 << std::endl << "bar";

Als ik me niet vergis zijn temporaries altijd const. Hoe zorg ik ervoor dat ik er dan toch naar kan schrijven zonder dat ik alle operator<<'s moet overloaden en allerlei mutable members nodig heb? Eventueel kan trace() een functie zijn die een non-const object oplevert, maar heb ik dan nog steeds de garantie dat dat ding het hele statement lang bestaat?

Temporaries zijn nooit const. (nou ja, const int (1) dan weer wel ) . Ik denk dat je vergissing komt door reference-binding; alleen const-references kunnen worden gebonden aan temporaries, maar dat slaat op de references niet de temporaries.

Temporaries leven tot het einde van de full-expression (de ; in de praktijk) of tot het uit scope gaan van de eraan gebonden reference, als dat langer is.

De halve vraag was of er nog principiële haken en ogen zitten aan die constructie. Gevoelsmatig vind ik het niet zo netjes om allerlei relevante code in destructors te hangen. Naar mijn mening moeten constructors en destructors liefst zo transparant mogelijk werken en moet de code niet al te veel vertrouwen op het al dan niet draaien van destructors (al kun je er van uitgaan dat constructors en destructors in balans zijn, natuurlijk).

Destructors zijn er juist omdat je die garantie hebt; de hele C++ standaard is erop geschreven dat er geen objectenkwijt raken. Het enige waar je rekening mee moet houden is dat destructors dus ook draaien tijdens een stack-unwind wegens een exception. Je destructors moeten daarom ook vrijwel altijd no-throw zijn.

Tenzij iemand nog interessante dingen toe te voegen heeft, implementeer ik wel het idee met de stream modifiers die zelf locking doen, a la dit voorbeeld:

C++:

log << trace(50) << "Foo" << 134 << std::endl << "bar" << log::eot;

Dit is in praktijk een vrij slecht idee; je lockt de resource veel te lang.

[.oisyn]

Nog een idee: maak een ostream pool, zodat je non-const references terug kan geven. Je trace () functie returned een reference naar een op dat moment ongebruikte stream. Je log::eot modifier zorgt ervoor dat de opgebouwde string wordt weggeschreven en dat die ostream weer als vrij gemarkeerd wordt. De aanroep is dan zoiets:

C++:

trace(50) << "Foo" << 134 << std::endl << "bar" << std::eot;

[Verwijderd]

iostreams biedt de manipulators lock en unlock voor threadsafe programming:

C++:

std::cout << std::lock << "waarde: " << value << std::endl << std::unlock;

je hoeft dus geen eigen manipulators te schrijven. Verder kan ik niet van dienst zijn omdat ik een simpele wrapper rond syslog() gebruik

[.oisyn]

In welke headers staan lock en unlock? Ik zie niets in de MSDN, en ook comeau klaagt als ik gewoon iostream en iomanip include

[Verwijderd]

.oisyn schreef op 04 juni 2004 @ 18:19:
In welke headers staan lock en unlock? Ik zie niets in de MSDN, en ook comeau klaagt als ik gewoon iostream en iomanip include

Erg raar, ze zitten hier gewoon in iostream(.h) en ze worden ook in verschillende manuals vermeld.

[Soultaker]

Lijkt me ook wel vreemd als die manipulators wel bestonden, want verder zit er voor zover ik weet helemaal niets aan threading support (of thread safe classes) in de C++ standard library. Lijkt me dat ze er dan wel gelijk een aantal synchronisatieprimitieven bij hadden kunnen gooien.

[Verwijderd]

Soultaker schreef op 05 juni 2004 @ 03:00:
Lijkt me ook wel vreemd als die manipulators wel bestonden, want verder zit er voor zover ik weet helemaal niets aan threading support (of thread safe classes) in de C++ standard library. Lijkt me dat ze er dan wel gelijk een aantal synchronisatieprimitieven bij hadden kunnen gooien.

Mja, ze bestaan wel, maar het is een extensie op ISO/IEC 14882 (vandaag zitten doornemen). Balen man, ik heb die manipulators jaren lang in mijn code gebruikt

[MSalters]

Verwijderd schreef op 04 juni 2004 @ 22:10:
[...]
Erg raar, ze zitten hier gewoon in iostream(.h) en ze worden ook in verschillende manuals vermeld.

Da's de COMPAQ C++ manual. Er zijn redelijk wat verschillende implementaties van MT-extensies voor C++, en dit is er een.

[Verwijderd]

MSalters schreef op 05 juni 2004 @ 16:07:
Da's de COMPAQ C++ manual. Er zijn redelijk wat verschillende implementaties van MT-extensies voor C++, en dit is er een.

Daar ben ik inmiddels achter, die manual was gewoon de eerste hit in google. Die manipulators zitten dus ook in de GNU-extensies, alleen worden ze niet afgeschermd door #ifdefs zoals de rest van het extensie-spul.

[Soultaker]

In GCC 3.3.3 zitten ze in ieder geval niet gewoon in de iostream-header. Het kan zijn dat dat in GCC 2.x nog anders was; toen zaten dingen als SGI's hashset/hashmap er ook nog gewoon bij alsof ze onderdeel van de standaard waren (al waren die al wel in aparte headers gedeclareerd).

[Soultaker]

.oisyn schreef op 04 juni 2004 @ 15:00:
Nog een idee: maak een ostream pool, zodat je non-const references terug kan geven. Je trace () functie returned een reference naar een op dat moment ongebruikte stream. Je log::eot modifier zorgt ervoor dat de opgebouwde string wordt weggeschreven en dat die ostream weer als vrij gemarkeerd wordt.

Dat is wel een mooie suggestie. Ik denk dat ik die maar eens ga implementeren.

Het enige wat daar jammer aan is, is dat je daar per se zo'n "einde bericht"-markering bij nodig hebt, anders lek je ongemerkt geheugen. (In theorie is daar wel weer omheen te werken, maar dat maakt de zaken helaas weer erg ingewikkeld.)

[Verwijderd]

Soultaker schreef op 05 juni 2004 @ 17:09:
In GCC 3.3.3 zitten ze in ieder geval niet gewoon in de iostream-header. Het kan zijn dat dat in GCC 2.x nog anders was; toen zaten dingen als SGI's hashset/hashmap er ook nog gewoon bij alsof ze onderdeel van de standaard waren (al waren die al wel in aparte headers gedeclareerd).

is dat niet spul wat je in glibc verwachten ipv gcc?

[igmar]

Verwijderd schreef op 06 juni 2004 @ 15:46:
is dat niet spul wat je in glibc verwachten ipv gcc?

Nee, want ze zijn (en ook de implemantatie is) compiler-afhankelijk. Een gedeelte van de C++ standaard zit in libgcc, het andere gedeelte in libstdc++.

[igmar]

.oisyn schreef op 04 juni 2004 @ 15:00:
Nog een idee: maak een ostream pool, zodat je non-const references terug kan geven. Je trace () functie returned een reference naar een op dat moment ongebruikte stream. Je log::eot modifier zorgt ervoor dat de opgebouwde string wordt weggeschreven en dat die ostream weer als vrij gemarkeerd wordt. De aanroep is dan zoiets:

C++:

trace(50) << "Foo" << 134 << std::endl << "bar" << std::eot;

Je moet alleen zorgen dat messages atomic worden weggeschreven : Het is erg vervelend als (gedeelten) van messages door elkaar heen in een logfile staan. Normaliter garandeerd het OS atomic writes als het aantal niet boven een X aantal bytes uitgaat. Dat getal is vaak 512, maar kan varieeren. In dat geval kun je dus een (dure) lock uitsparen.

[.oisyn]

Verwijderd schreef op 05 juni 2004 @ 17:06:
[...]


Daar ben ik inmiddels achter, die manual was gewoon de eerste hit in google. Die manipulators zitten dus ook in de GNU-extensies, alleen worden ze niet afgeschermd door #ifdefs zoals de rest van het extensie-spul.

erg vies dat ze die dan in std stoppen, en niet in stdext

Soultaker schreef op 05 juni 2004 @ 17:12:
[...]

Dat is wel een mooie suggestie. Ik denk dat ik die maar eens ga implementeren.

Het enige wat daar jammer aan is, is dat je daar per se zo'n "einde bericht"-markering bij nodig hebt, anders lek je ongemerkt geheugen. (In theorie is daar wel weer omheen te werken, maar dat maakt de zaken helaas weer erg ingewikkeld.)

Mja, je zou natuurlijk ook een temporary object kunnen returnen wat een wrapper is om zo'n ostream, die te converteren is naar een ostream& door middel van een conversion operator. Bij het destructen van die temporary kun je het bericht wegschrijven en de ostream weer vrijgeven. Je zal dan wel moeten vertrouwen dat een implementatie doet zoals MSalters eerder al uitgelegd had: destruction meteen na het eind van de statement...

Let er wel even op dat je een copy constructor voor die temporary maakt, die het gedrag heeft van een auto_ptr. Een copy geeft de ostream dus over naar het andere object, zodat ie niet al voordat hij nodig is wordt vrijgegeven (omdat je 'm by-value returned is de kans groot dat er onderweg een kopie wordt gemaakt voordat je 'm in de caller kunt gebruiken)

[.edit:
Deze code werkt iig goed onder VC++ 7.1 en gcc 2.95.4

C++:

#include <iostream>
#include <string>

struct S
{
    ~S ()
    {
        std::cout << "S::~S ()" << std::endl;
    }
};

S f ()
{
    return S ();
}

int main ()
{
    std::cout << "checkpoint" << std::endl;
    f ();
    std::cout << "checkpoint" << std::endl;

    return 0;
}

gcc output 1 "S::~S ()" tussen de checkpoints, VC++ geeft er 2 (ook getest met alle optimalisaties aan)]

igmar schreef op 06 juni 2004 @ 19:42:
[...]


Je moet alleen zorgen dat messages atomic worden weggeschreven : Het is erg vervelend als (gedeelten) van messages door elkaar heen in een logfile staan. Normaliter garandeerd het OS atomic writes als het aantal niet boven een X aantal bytes uitgaat. Dat getal is vaak 512, maar kan varieeren. In dat geval kun je dus een (dure) lock uitsparen.

Even goed lezen, ik bedoelde dat zo'n ostream niet direct schrijft naar je buffer, maar juist intern de message aan elkaar koppelt, en als je er dan zo'n eot modifier naartoe stuurt dan wordt die buffer in z'n geheel weggeschreven (vergezeld van een lock op de uiteindelijke stream) en wordt de tijdelijke ostream uit de pool weer vrijgegeven

[ Voor 20% gewijzigd door .oisyn op 07-06-2004 01:04 ]