Locking en Multi-Threading bij File IO

In de vorige post hebben we gekeken hoe we een eigen web server kunnen neerzetten, nu is de tijd aangebroken om er ook wat nuttigs mee te doen. Een mooie functionaliteit om eens in te bouwen is Request-Logging, redelijk simpel maar ook hier zitten er ook weer een paar zaken die net iets vaak over het hoofd worden gezien. Zeker omdat onze server netjes multi-threaded is, en dat bij het loggen naar een bestand niet helemaal optimaal is, daarnaast doen we 12k Requests per second dus het zijn er ook wat veel.

Wishful Thinking

Loggen met Create en AppendText()

'Wishful thinking', zei mijn wiskunde leraar altijd, als we weer eens creatief rekenwerk deden en de makkelijkste manier kozen om iets op te lossen. Natuurlijk was dit ook altijd een foute oplossing. Poging 1, gewoon omdat het ook eens leuk is om te zien wat het effect dan is van foute code.

Gelukkig is de CPU en Performance meter het met mij eens, dit werkt niet. CPU naar 100% en 12 Request per Second welke gelogged worden. De Applicatie crashed ook wanneer er 2 threads overlappen, en er tegelijkertijd naar dezelfde file wordt geschreven,.

Uitkomst

• Req per Sec: 12
• CPU Load: 100%
• Errors: App. Crash

Global/Static/Singelton Concept

Één Instantie altijd open

Laten we bij een simpele verbetering beginnen, de CPU load. Windows is geen fan van het continue openen en sluiten van bestanden. Wat prima werk voor uitgebreidere acties gaat nu mis op de kwantiteit van de requests. Aangezien we toch altijd naar 1 bestand willen schrijven en dat non stop doen, kunnen we daarvoor net zo goed een gesharede StreamWriter voor gebruiken.

Kijk dit gaat al een stuk beter, misschien zelfs iets te goed. Laat hem maar even lopen, en je bestand vlieg de pan uit, en na een tijdje bij genoeg belasting raakt hij toch met zichzelf in de knoop. De Flush is verplicht, anders krijg je bijna direct een foutmelding. (uiteindelijk wil je niet bij elke WriteLine Flushen, dus ook deze is voor verbetering vatbaar) En dan moeten we ook nog iets verzinnen om van bestand te wisselen, want zoals te zien is wordt die wel erg groot. Zeker met 12k Regels per seconde.

Uitkomst

• Req per Sec: 9500
• CPU Load: 15%
• Errors: Na verloop van tijd, en Filesize

Lock

Dan Locken we de boel toch, en wisselen we het bestand

Poging 3, netjes een lock gebruiken en een check of het bestand te groot wordt. Daarna Flushen, Closen, en een nieuwe aanmaken, zou goed moeten gaan.

En ook hier gaat het in het begin helemaal goed, lekker snel, iets meer processor belasting. Maar bij het wisselen van bestanden laat de server een paar steken vallen, en heeft de CPU het moeilijk. Als we nog eens goed naar de code kijken is dat ook niet zo heel raar, we locken tenslotte alles voor de hele actie.Op het moment dat we een bestand Closen en een nieuwe aanmaken, moeten alle threads op alles wachten. Misschien wel selectiever locken, en kijken of we de rest kunnen laten doorlopen.

Uitkomst

• Req per Sec: 9500
• CPU Load: 25% - 75% wisselen
• Errors: Bij bestand wisselen, dropt performance.

Locks

Creatief met locks en statussen.

Nu kunnen we eens goed gaan kijken hoe we de locks kunnen optimaliseren. Er komen wel direct een aantal complicerende factoren bij kijken, maar het eind resultaat mag er zijn... Zoals we zagen houd een lock de overige threads tegen, en dus willen we zo min mogelijk code binnen een lock moeten uitvoeren. Neem bijvoorbeeld het maken/openen van een nieuwe LogFile, daar zouden de andere threads niet op hoeven wachten. Pas wanneer we de wissel maken van de oude stream naar de nieuwe zouden de andere threads even niet mogen wegschrijven.

Wat hebben we precies gedaan, we hebben 2 aparte locks aangebracht, nl de lock om weg te schrijven naar een stream, zodat tijdens het omschakelen naar een nieuwe stream dit voor geen problemen zorgt. De tweede lock zorgt ervoor dat we geen meerdere nieuwe bestanden krijgen bij 1 wisseling. Want als we alleen op fileSize zouden checken, zou er in de periode van fileSize > maxFileLength en de daarwerkelijke log = newLog, meerdere keren een nieuw bestand gemaakt kunnen worden. Door van 2 verschillende locks gebruik te maken zorgen we er ook voor dat het schrijven naar het log niet hoeft te wachten of de check of er een nieuw log moet komen. De uiteindelijke code welke nu in een lock statement staat is minimaal,

• Lock(log): Het wisselen van Log Streams
• Lock(log): Het wegschrijven naar de Stream en het lezen van de Filesize
• Lock(isBeingCreatedLock): Het controleren of er een nieuw bestand moet komen
• Lock(isBeingCreatedLock): Het aangeven dat er een nieuw bestand gemaakt is

Logisch gezien zou je de laatste lock kunnen plaatsen in de lock(log), maar dan zou je iets proberen te voorkomen wat in de praktijk nooit kan gebeuren. Let verder even op het gebruik van de shouldCreate variabele, en waarom we die gebruiken. Als laatste zouden we nog de actie welke in de if(shouldCreate) valt, kunnen verplaatsen naar een eigen thread, zeker als we verwachten dat dit heel lang duurt zou dat handig zijn. (nu is er één request welke wat langzamer is tijdens het openen en sluiten van de log bestanden)

Uitkomst

• Req per Sec: 9500
• CPU Load: 15% - 75% wisselen
• Errors: Geen, blijft stabiel

Zoals je ziet is ook dit net even anders als de rechtdoorzee code welke veel geschreven wordt, vaak worden hier ook o.o.t.b. componenten voor gebruikt zodat je hier eigenlijk helemaal niet mee te maken heb. Toch is het goed om soms eens wat verder te kijken, en zeker als je zelf creatief bezig bent, of echte maatwerk integratie/oplossingen bouwt is het belangrijk dat je goed weet wat er precies allemaal onder de motorkap gebeurd. In dat geval heb je ook volledige controle en kennis indien er performance problemen ontstaan.

BB, Marinus