Activity Log Swapping

expecco · exept:workflow · Entwicklerdokumentation

Activity Log Swapping

Fertige Aktivitätsprotokolle wandern in eine Swap-Datei; im Speicher bleibt ein Stellvertreter von 24 Byte und eine Zeile in den Indextabellen. Konzept, Lebenszyklus der Dateien, Einstellungen, umgesetzte Änderungen, die 22 Tests und die gemessene wie geschätzte Speicherwirkung.

Stand 10.09.2026 Packages exept:workflow, exept:expecco

1. Konzept

Ein Testlauf über mehrere Tage erzeugt Millionen von Log-Einträgen, die bisher vollständig im Speicher bleiben. maxNumberOfChildrenInlog ist per Voreinstellung nil, es gibt also keinen Deckel – und wo einer gesetzt ist, werden die ältesten Einträge schlicht verworfen.

Das Feature schreibt abgeschlossene Logs in eine Datei und ersetzt sie im Baum durch eine Referenz. Entscheidend ist dabei nicht das Schreiben an sich, sondern die Aufteilung: Nicht alles am Log wandert in die Datei.

Was im Speicher bleibt und was in die Datei geht

Speicher — Indextabellen

Alles, was der Log-Baum, die Zeitleiste und die Zustandsaggregation zum Zeichnen brauchen.

• filePositions, recordSizes
• states (Verdikt)
• startDeltas, durations
• stepIndices → stepTable
• childIndices (IntegerArray)
• parentIndices
• hasTraces
• typeTable (Datentypen)

Folge: Den ganzen Baum aufklappen, die Zeitleiste zeichnen und das Verdikt aggregieren kostet kein einziges Byte Dateizugriff.

Datei — Record je Log

Nur, was erst beim Öffnen eines einzelnen Knotens gebraucht wird.

• inputPinEnvelopes
• outputPinEnvelopes
• traces

Ein Record ist ein eigener BinaryObjectStorage, gerahmt von Magic ELOG und einer 32-Bit-Länge. Damit ist jeder Record ohne Vorwissen lesbar: ein seek, ein read.

Schreiben und Verdrängen sind getrennt

Ein fertiges Log wird beim Beenden der Aktivität nur in eine SharedQueue eingereiht. Ein Hintergrundprozess auf userBackgroundPriority serialisiert und schreibt in 32-KB-Blöcken. Das Verdrängen dagegen – der Austausch des Logs gegen seine Referenz in subActivityLogs – ist ein reiner Zeigertausch ohne jeden Dateizugriff:

Workflow::StandardActivityLog >> subActivityLogsAdd:maxNumberOfChildrenInTree:

numTooMany > 0 ifTrue:[
    swapper isNil ifTrue:[
        "/ unverändertes Verhalten: ohne Swapper gehen die ältesten Logs verloren
        subActivityLogs dropAllSuchThat:[:log| ... ].
    ] ifFalse:[
        "/ #swapOut: macht KEIN I/O und antwortet nil für ein Log, das noch
        "/ nicht geschrieben ist - das bleibt dann einfach im Speicher
        ref := swapper swapOut:log.
        ref notNil ifTrue:[ subActivityLogs at:i put:ref ].
    ].
].

Weil swapOut: nie wartet, kann die Auslagerung den Testlauf konstruktionsbedingt nicht ausbremsen. Was noch nicht geschrieben ist, wird beim nächsten Kind erneut betrachtet.

Geteilte Objekte gehören nicht in die Datei

Steps und Datentypen sind gemeinsam genutzt und langlebig. Sie liegen in einer Tabelle im Speicher; der Record trägt nur einen Index. Beim Datentyp ist das nicht Feinschliff, sondern tragend: DataEnvelope>>type ist ein ExpeccoDatatypeHolder, und der hält eine Instanzvariable project. BinaryObjectStorage serialisiert Instanzvariablen, keine Getter – die komplette Testsuite landete damit in jedem einzelnen Record.

Gemessen an einem Envelope mit einem einzigen Wert (200ms) data = 62 Byte, type = 4.686.964 Byte, davon project = 4.686.930 Byte. Ein Lauf mit 687 Records ergab eine Datei von 806 MB.

Nach Auslagerung der Datentypen in die Tabelle: derselbe Lauf, größter Record 228 Byte, 22 Records = 4.732 Byte.

Die Referenz

Ein Objekt mit genau einer Instanzvariablen – kein blanker Integer. Der Grund ist Identität: Die Referenz ist der Slot-Inhalt in subActivityLogs, und die Aufrufer arbeiten mit includesIdentical: und identityIndexOf:.

Diese eine Variable trägt zwei Dinge: In den oberen Bits die laufende Nummer des Swappers, in den unteren 24 den Index in dessen Tabellen. Damit findet eine Referenz ihre Daten auch dann noch, wenn längst ein neuer Lauf mit eigenem Swapper läuft.

Workflow::ActivityLogSwapper class >> initialize

"/ 24 bits leave 38 for the number on a 64bit image, 20 leave 10 on a 32bit one
RecordIndexBits := SmallInteger maxVal highBit > 32 ifTrue:[24] ifFalse:[20].
RecordIndexMask := (1 bitShift:RecordIndexBits) - 1.

Die Aufteilung ist so gewählt, dass der Wert ein SmallInteger bleibt: Ein LargeInteger hinge als zweites Heap-Objekt an jeder einzelnen Referenz. Auf einem 64-Bit-Image bleiben 38 Bit für die Laufnummer – rund 275 Milliarden Läufe bei 16 Millionen Records je Lauf.

Kinderlisten stehen explizit im Index

Records werden in Post-Order geschrieben – ein Knoten also nach seinem gesamten Teilbaum. Das macht den Teilbaum zusammenhängend, aber nie die direkten Kinder: Zwei Geschwister sind immer durch die Nachkommen des zweiten getrennt. Ein Intervall lo..hi scheidet damit aus; childIndices hält je Knoten ein IntegerArray mit den tatsächlichen Indizes. Gemessen an einem Lauf mit zwei parallelen Zweigen: die Wurzel hat die Kinder (21 42).

Zwei Kinderzahlen, nicht eine

Die vorhandene Einstellung maxNumberOfChildrenInlog ist eine Verlustgrenze: Ohne Swapper wird alles darüber verworfen, man setzt sie also so hoch, wie der Speicher es zulässt. Mit Swapper ist dieselbe Zahl eine Cache-Größe: Nichts geht verloren, der Rest wandert in die Datei, also setzt man sie so niedrig, wie die Anzeige es erträgt. Die beiden Wünsche laufen gegeneinander – deshalb gibt es ein eigenes Feld maxNumberOfChildrenInMemoryWhenSwapping mit Vorgabewert 100.

2. Lebenszyklus

Der Swapper hängt an vier Ereignissen: zum ersten Mal wird verdrängt, ein Lauf endet, der Letzte hört auf hinzusehen, expecco wird beendet. Alles Weitere – Datei anlegen, Schreibprozess starten und stoppen, Datei löschen – folgt daraus. Es gibt genau einen Swapper je Lauf, gemeinsam für alle beteiligten Logger, damit ein von einem Logger ausgelagertes Log über jeden anderen wieder lesbar ist – und ein Lauf, der nie über die Cache-Größe kommt, bekommt gar keinen.

Der Lauf beginnt – Einstellungen lesen

Workflow::AbstractActivityLogger >> initializeSettingsForProject: → setupForSwappingIfEnabled

Der Einhängepunkt ist bewusst nicht executionStarted – das ist ein wirkungsloser Zweitaufruf. Hier werden die drei Benutzereinstellungen gelesen, an den Schalter und an die Swapper-Klasse weitergereicht, und bei aktivem Swapping wird maxNumberOfChildren auf die Cache-Größe umgestellt.

Workflow::AbstractActivityLogger >> initializeSettingsForProject:

"/ swapping is a user setting only, there is no project counterpart - so it
"/ is read whichever branch was taken above
preferences := Expecco::ExpeccoPreferences current.
self class swappingEnabled:preferences shouldSwapActivityLogToFile.
Workflow::ActivityLogSwapper swapDirectory:preferences activityLogSwapDirectory.

self class swappingEnabled ifTrue:[
    maxNumberOfChildren := preferences maxNumberOfChildrenInMemoryWhenSwapping.
].
self setupForSwappingIfEnabled.

Ein Swapper entsteht hier noch nicht. setupForSwappingIfEnabled setzt nur die Kinderzahl – ohne Grenze würde nie etwas verdrängt –, und falls keine gesetzt ist, den Vorgabewert 100. Die Methode kann während eines Laufs mehrfach aufgerufen werden und ist deshalb idempotent.

Der erste Überlauf – jetzt wird der Swapper geholt

Workflow::StandardActivityLog >> subActivityLogsAdd:maxNumberOfChildrenInTree: → Workflow::AbstractActivityLogger >> swapperForSwapOut → Workflow::ActivityLogSwapper class >> acquireFor:

Der Swapper wird erst angefordert, wenn ein Knoten zum ersten Mal mehr Kinder hat, als die Cache-Größe erlaubt. Das ist wichtig, weil jeder Testfall eines Testplans seinen eigenen Logger bekommt: Ein Testfall, der unter der Grenze bleibt, kostet dadurch gar nichts – keine Datei, keinen Schreibprozess, keine Indextabellen. In einem Schleifenlauf aus vielen kurzen Testfällen ist das der Normalfall.

Workflow::AbstractActivityLogger >> swapperForSwapOut

(swapper notNil and:[swapper isStopped not]) ifTrue:[ ^ swapper ].
self class swappingEnabled ifFalse:[ ^ nil ].

swapper := Workflow::ActivityLogSwapper acquireFor:self.
^ swapper

Ein noch laufender Swapper wird behalten, niemals freigegeben und neu angelegt: Ein Freigeben würde die Datei löschen, während die Referenzen im Baum noch Indizes hineintragen – kein Fehler, nur falsche Daten. Ein gestoppter wird ersetzt, denn ein neuer Lauf muss wieder schreiben.

acquireFor: nutzt diesen Moment zugleich als Aufräumzeitpunkt (Schritt 07) und schließt einen liegengebliebenen Swapper, dessen Logger sich alle nie abgemeldet haben – sonst schriebe jeder folgende Lauf an dieselbe Datei an. addLogger: trägt den Logger schließlich in activeLoggers und schwach in knownLoggers ein.

Alles, was vor diesem Zeitpunkt fertig wurde, ist nie eingereiht worden – es gab ja keinen Swapper. Das wird sofort nachgeholt, in Post-Order:

Workflow::ActivityLogSwapper >> enqueueFinishedLogsIn:

anActivityLogOrNil isActivityLogReference ifTrue:[ ^ self ].

(children := anActivityLogOrNil subActivityLogs) notNil ifTrue:[
    children do:[:each| self enqueueFinishedLogsIn:each ].
].

"/ the path which is still running must NOT be written: it is not stable
"/ yet, and more children are still to come
anActivityLogOrNil isFinished ifTrue:[
    self enqueue:anActivityLogOrNil
].

Ohne das Nachholen bliebe nicht nur Speicher liegen: write: lässt ein Kind, für das es keinen Index findet, aus der Kinderliste des Vaters heraus – der Vater bekäme also einen Record mit still fehlenden Kindern, und das Auslagern dieses Vaters würde sie endgültig verlieren.

Die Datei entsteht (Datei da)

Workflow::ActivityLogSwapper >> start

Jetzt erst wird eine Datei angelegt – atomar über FileStream newTemporaryIn:nameTemplate:, im eingestellten Verzeichnis oder im Temp-Verzeichnis des Images.

Workflow::ActivityLogSwapper >> start

swapStream := FileStream
                newTemporaryIn:self class swapDirectory
                nameTemplate:'expeccoActivityLog%1_%2.swap'.
swapStream binary.

"/ as an AutoDeletedFilename the file goes away when expecco quits, and
"/ also if I am collected without anybody having sent me #discardSwapFile
swapFile := swapStream fileName asAutoDeletedFilename.

"/ they grow as needed - see InitialTableSize in #initialize
filePositions := OrderedCollection new:InitialTableSize.
...
AccessLock critical:[
    Registry add:self.
    swapperNumber := Registry size.
].

Der Name trägt die Prozess-ID des schreibenden Images (%1) – das ist die Grundlage für Schritt 10. Die Registrierung liefert die Swapper-Nummer, die jede Referenz in den oberen Bits ihres Index mitführt; ein einmal vergebener Registry-Platz wird nie wiederverwendet, sonst läse eine Referenz eines freigegebenen Laufs die Records eines fremden. Danach werden die neun Indextabellen angelegt – klein, sie wachsen selbst – und der Schreibprozess auf userBackgroundPriority gestartet.

Während des Laufs

Workflow::StandardActivityLog >> subActivityLogsAdd:maxNumberOfChildrenInTree: · Workflow::ActivityLogSwapper >> enqueue: / swapOut:

Ein fertiges Log wird eingereiht (enqueue:) und vom Hintergrundprozess in 32-KB-Blöcken geschrieben. Sobald ein Knoten mehr Kinder hat, als die Cache-Größe erlaubt, ersetzt swapOut: die ältesten bereits geschriebenen durch Referenzen. Beides ist entkoppelt: Verdrängen macht kein I/O und wartet nie.

Workflow::ActivityLogSwapper >> enqueue:

"/ If the queue is full, this log is simply not written and can therefore
"/ never be swapped out. Best effort by design
stopped ifTrue:[ ^ self ].
anActivityLog isNil ifTrue:[ ^ self ].
writeQueue size >= MaxQueueSize ifTrue:[ ^ self ].
writeQueue nextPut:anActivityLog.

Weil ein Log auf diesem Weg ausbleiben kann – volle Queue, fehlgeschlagene Serialisierung –, prüft write:, ob jedes Kind einen Index hat, bevor es den Vater schreibt:

Workflow::ActivityLogSwapper >> write:

indices := anActivityLog subActivityLogs
                collect:[:each|
                    each isActivityLogReference
                        ifTrue:[ self recordIndexOfReference:each ]
                        ifFalse:[ writtenLogs at:each ifAbsent:nil ]].

(indices includes:nil) ifTrue:[
    "/ writing me anyway would give me a record whose children are
    "/ silently missing, and swapping me out would then lose them.
    "/ Staying in memory is the safe answer
    ^ self
].

Der Lauf endet – die Datei bleibt

Workflow::AbstractActivityLogger >> executionFinished → Workflow::ActivityLogSwapper >> removeLogger:

Der Logger meldet sich ab. Erst wenn der letzte Logger fort ist, wird stop gesendet: Sentinel in die Queue, auf den Schreibprozess warten, Puffer schreiben, Stream schließen. Die Datei bleibt bestehen – Report, Log-Ansicht und Zeitleiste lesen danach weiter aus ihr.

Workflow::ActivityLogSwapper >> removeLogger:

shouldStop := AccessLock critical:[
    aLogger notNil ifTrue:[ activeLoggers remove:aLogger ifAbsent:[] ].
    self dropFinishedLoggers.
    activeLoggers isEmpty
].
shouldStop ifTrue:[
    "/ NOT under AccessLock - #stop waits for the writer process,
    "/ which needs the lock itself in #appendRecord:
    self stop.
].

dropFinishedLoggers wirft dabei Logger heraus, deren Lauf zu Ende ist, die sich aber nie abgemeldet haben (Abbruch, Ausführungspfad ohne executionFinished).

Solange jemand hinsieht

Workflow::ActivityLogSwapper >> isInUse

Eine Swap-Datei darf verschwinden, wenn niemand ihre Records mehr liest. Drei Bedingungen, von denen jede allein genügt:

Workflow::ActivityLogSwapper >> isInUse

activeLoggers notEmptyOrNil ifTrue:[ ^ true ].  "/ ein Lauf schreibt noch
knownLoggers notEmptyOrNil ifTrue:[ ^ true ].   "/ ein Baum ist auf dem Schirm
^ references notEmptyOrNil                      "/ jemand hält Referenzen

activeLoggers hält stark, wer noch schreibt; knownLoggers schwach jeden je bedienten Logger; references ist eine WeakValueDictionary der ausgegebenen Stellvertreter. Die beiden schwachen Sammlungen leeren sich von selbst. Die dritte Bedingung ist unverzichtbar, weil die Zeitleiste in ihren Blöcken nur die einzelnen Logs hält, nicht die Wurzel des Baums – und eine Referenz selbst hält nichts. Eine falsche Antwort hinkt der Wahrheit nach: Unerreichbar ist ein Objekt lange vor dem Einsammeln. Das schadet niemandem – eine Datei ein wenig länger zu behalten kostet nichts.

Aufräumen im Vorbeigehen (Datei weg, wenn ungenutzt)

Workflow::ActivityLogSwapper class >> releaseUnusedSwappers · basicReleaseUnusedSwappers

Ausgelöst an zwei Stellen, die beide ein Loslassen bedeuten: beim Start eines Laufs (aus acquireFor:) und wenn der Testplan-Editor sein zwischengespeichertes Gesamtlog verwirft (TestplanPO >> flushCachedActivityLog).

Freigegeben wird jeder Swapper, der gestoppt ist und entweder nicht mehr in Gebrauch ist oder dessen Datei hinter seinem Rücken verschwunden ist (swapFileIsGone); discardSwapFile stoppt ihn, löscht die Datei und leert seinen Registry-Platz – danach findet eine Referenz dieses Laufs keinen Swapper mehr, statt unter derselben Nummer fremde Records zu lesen. Ein Lauf in Gebrauch wird nie angetastet, die Datei kann also keiner offenen Ansicht unter den Füßen weggezogen werden.

Workflow::ActivityLogSwapper class >> basicReleaseUnusedSwappers

"/ #discardSwapFile sends #stop, which waits for the writer - and that one
"/ needs AccessLock itself. So pick under the lock, release outside it
unused := AccessLock critical:[
    Registry select:[:each|
        each notNil
          and:[each isStopped
          and:[each isInUse not or:[each swapFileIsGone]]]
    ]
].
unused do:[:each| each discardSwapFile ].

Daraus folgt, dass die Gesamtgröße nur eine weiche Grenze sein kann: Wird MaxTotalSwapFileSize (1 GB) überschritten, ist der wahrscheinlichste Grund, dass unerreichbare Logger noch nicht eingesammelt wurden – also einmal garbageCollect und noch einmal hinsehen. Bleibt es dabei, werden die Läufe tatsächlich alle noch betrachtet; dann gibt es eine Warnung ins Log, statt einen davon zu zerstören.

Der Benutzer löscht alle Ergebnisse (Datei weg)

Expecco::Browser >> removeAllTestResults · removeAllTestResultsInSystem · removeAllTestDemoResultsInSystem

Hier gilt etwas anderes als in Schritt 07: Nach Remove all Results sollen die Ergebnisse wirklich weg sein, und eine Datei, die bleibt, weil irgendein Fenster noch eine Referenz hält, wäre genau das, was der Benutzer nicht wollte. releaseAllFinishedSwappers gibt deshalb jeden beendeten Lauf frei, ob betrachtet oder nicht; nur ein noch schreibender bleibt unangetastet. Ansichten, die einen solchen Lauf noch zeigen, bekommen anschließend isBrokenActivityLog = true und überspringen die Einträge, statt in ein nil startTimeAt: zu laufen.

Workflow::ActivityLogSwapper class >> releaseAllFinishedSwappers

finished := AccessLock critical:[
    Registry select:[:each| each notNil and:[each hasActiveLoggers not]]
].
finished do:[:each| each discardSwapFile ].

expecco wird beendet (Datei weg)

Filename >> asAutoDeletedFilename · Workflow::ActivityLogSwapper >> swapFileIsGone

Die Datei ist von Anfang an ein AutoDeletedFilename; deren Lobby wird auf #aboutToQuit geleert. Damit verschwinden die Dateien auch dann, wenn niemand aufgeräumt hat.

Workflow::ActivityLogSwapper >> swapFileIsGone

^ swapFile isNil or:[ swapFile exists not ]

Nebenwirkung, die abgefangen werden muss: Wird nur die Anwendung geschlossen, während das Image weiterläuft, leert die Lobby ebenfalls – die Datei ist fort, der Swapper aber noch da. Records, die nicht mehr gelesen werden können, sind schlimmer als gar keine, deshalb fällt ein solcher Swapper beim nächsten Aufräumen heraus, auch wenn noch jemand Referenzen hält.

Das Image ist abgestürzt (Datei weg)

Workflow::ActivityLogSwapper class >> removeOrphanedSwapFiles

Nach Absturz, kill oder Maschinenneustart bleiben Dateien liegen. Beim nächsten Laufstart werden sie eingesammelt – sicher, weil der Dateiname die Prozess-ID trägt: Die eigenen Dateien nennen immer einen lebenden Prozess, die eines parallel laufenden expecco ebenfalls. Nur eine Datei, deren Prozess fort ist, gehört niemandem mehr. Fehler beim Löschen (fremde Datei, schreibgeschütztes Verzeichnis, abgehängtes Laufwerk) werden protokolliert und ignoriert – Aufräumen darf einen Lauf nie am Starten hindern.

Workflow::ActivityLogSwapper class >> removeOrphanedSwapFiles

(dir filesMatching:prefix , '*.swap') do:[:eachName| |pid|
    pid := Integer readFrom:((eachName copyFrom:prefix size + 1) upTo:$_) onError:nil.
    (pid notNil and:[(OperatingSystem isProcessIdPresent:pid) not]) ifTrue:[
        (dir construct:eachName) remove.
    ].
].

Wer gibt was frei

Auslöser	Methode	Umfang
Lauf startet · Testplan verwirft sein Gesamtlog	releaseUnusedSwappers	gestoppte Läufe, die niemand mehr betrachtet, plus solche ohne Datei; darüber hinaus verwaiste Dateien toter Prozesse
Menü Remove all Results	releaseAllFinishedSwappers	alle beendeten Läufe, unabhängig davon, ob noch jemand hinsieht
expecco beenden · Anwendung schließen	AutoDeletedFilename	alle Dateien des Images
Absturz des vorigen Images	removeOrphanedSwapFiles	Dateien, deren Prozess-ID zu keinem lebenden Prozess gehört

Ein loses Ende

releaseUnusedSwappersCollectingFirst – releaseUnusedSwappers mit vorgezogenem garbageCollect – wurde für den Menüpunkt Remove all Results geschrieben und dort später durch releaseAllFinishedSwappers ersetzt. Die Methode hat derzeit keinen Sender; sie kann vor dem Checkin entfallen oder als Werkzeug stehen bleiben.

3. Einstellungen

Drei Felder auf der Settings-Seite Log, alle drei reine Benutzereinstellungen. Ein Projekt-Gegenstück gibt es bewusst nicht: Ob ausgelagert wird, hängt an der Maschine, auf der gefahren wird, nicht an der Testsuite – deshalb werden sie gelesen, gleich welchen Zweig useUserActivityLogSettings nimmt.

☐ Swap Finished Activity Logs to a File

shouldSwapActivityLogToFile · Vorgabe: aus

Der Hauptschalter. Ausgeschaltet bleibt alles wie bisher, es wird keine Datei angelegt und kein Prozess gestartet – das lohnt sich erst bei langen Läufen. Die beiden folgenden Felder hängen über enableChannel: an ihm, ihre Beschriftungen über enableDisableColorChannel:.

Max. Nr. of Subactivities Kept in Memory: [ 100 ]

maxNumberOfChildrenInMemoryWhenSwapping · Vorgabe: leer → 100

Die Cache-Größe je Knoten, nicht die Verlustgrenze maxNumberOfChildrenInlog (siehe Kapitel 01). 100 lässt eine normale Ansicht vollständig im Speicher und verdrängt trotzdem eine Schleife mit hunderttausend Durchläufen.

Bleibt das Feld leer, zeigt es den Vorgabewert grau und kursiv an – der Wert kommt aus dem Code, nicht aus der Spezifikation, und bleibt damit auch dann richtig, wenn die Vorgabe geändert wird:

Expecco::LogSettingsApp >> postBuildMaxChildrenInMemoryField:

aField emptyFieldReplacementText:
    Workflow::AbstractActivityLogger defaultMaxNumberOfChildrenWhenSwapping printString

Swap File Directory: [ /tmp ] […]

activityLogSwapDirectory · Vorgabe: leer → Filename tempDirectory

Eingabefeld mit Verzeichnisauswahl über den …-Knopf; leer zeigt grau das tatsächlich verwendete Temp-Verzeichnis. Ein eigenes Verzeichnis lohnt sich auf Maschinen, deren Temp-Verzeichnis eine RAM-Disk ist – das Activity-Log auf eine RAM-Disk auszulagern hebt den Zweck der Sache auf –, und für lange Läufe, die dort echten Platz brauchen.

Gespeichert wird ein String, keine Filename: Die Einstellungsdatei enthält literale Arrays, und ein Filename hat keine literale Kodierung. Ein leerer Wert entfernt den Schlüssel wieder.

Geprüft wird beim Speichern, nicht beim nächsten Lauf

Ein Verzeichnis, in das nicht geschrieben werden kann, fiele sonst erst zu Beginn des nächsten Laufs auf – als Warnung im Log, wenn der Benutzer längst woanders ist. saveSettings bricht deshalb vorher ab:

Expecco::LogSettingsApp >> checkSwapDirectory

path isEmpty ifTrue:[ ^ true ].         "/ leer ist in Ordnung: Temp-Verzeichnis

dir := path asFilename.
dir exists ifFalse:[
    (Dialog confirm:'The swap file directory %1 does not exist.\Create it?') ifFalse:[ ^ false ].
    ... dir recursiveMakeDirectory ...
].
dir isDirectory ifFalse:[ Dialog warn:'%1 is not a directory.'. ^ false ].
dir isWritable ifFalse:[ Dialog warn:'%1 is not writable.'. ^ false ].
^ true

Ablage und Übersetzung

Expecco::ExpeccoPreferences >> activityLogSwapDirectory:

"/ a Filename is stored as a String: the settings file holds literal
"/ arrays, and a Filename has no literal encoding
(path isNil or:[path withoutSeparators isEmpty]) ifTrue:[
    identityAspects removeKey:#activityLogSwapDirectory ifAbsent:[].
    ^ self
].
identityAspects at:#activityLogSwapDirectory put:path withoutSeparators

Alle drei Werte liegen in identityAspects von Expecco::ExpeccoPreferences; ein Eingriff in den encodingVector ist damit nicht nötig. Die Beschriftungen und Hilfetexte stehen als sieben Zeilen in resources/de.rs – die übrigen Sprachen fehlen noch, was der Lint für fr.rs auch meldet.

4. Änderungen im Code

Neue Klassen

exept:workflow, Kategorie Workflow-Execution-Log

Klasse	Aufgabe
ActivityLogSwapper	Hält Datei, Schreibprozess und die Indextabellen eines Laufs. Klassenseitig die Registry, über die eine Referenz ihren Swapper anhand der kodierten Nummer findet, sowie das Aufräumen der Dateien.
ActivityLogReference	Stellvertreter im Baum, eine Instanzvariable. Beantwortet Name, Verdikt, Zeiten und Kinder aus den Tabellen; alles Weitere liest den Record oder materialisiert das Log. doesNotUnderstand: materialisiert im Auslieferungsimage und meldet im Entwicklungsimage.

Geänderte Klassen

Klasse	Package	Änderung
AbstractActivityLogger	workflow	Klassenvariablen SwappingEnabled und DefaultMaxNumberOfChildrenWhenSwapping; neu setupForSwappingIfEnabled und swapperForSwapOut. initializeSettingsForProject: liest die drei Einstellungen und setzt die Kinderzahl; der Swapper selbst entsteht erst beim ersten Verdrängen. executionFinished meldet den Logger ab, behält aber die Swapper-Referenz für die Verdikt-Aggregation.
StandardActivityLog	workflow	subActivityLogsAdd:maxNumberOfChildrenInTree: verdrängt statt zu verwerfen, sobald ein Swapper hängt; computeActivityLogState zieht das aggregierte Verdikt der ausgelagerten Kinder heran; neu setupFromSwappedRecord:step:state:startTime:endTime:logger: für das Materialisieren.
Activity	workflow	basicFinishMeWriteValues:writeEno:canCheckForNewActivity: reiht das fertige Log beim Swapper ein.
Object	workflow	Extension isActivityLogReference.
TimelineView	workflow	Verwirft die gemerkte Auswahl beim Neuaufbau der Blöcke und zeichnet keine Blöcke, deren Log nicht mehr lesbar ist.
ExpeccoPreferences	expecco	Drei Einstellungen als identityAspects: shouldSwapActivityLogToFile, maxNumberOfChildrenInMemoryWhenSwapping, activityLogSwapDirectory. Kein Eingriff in den encodingVector nötig.
LogSettingsApp	expecco	Checkbox, Zahlenfeld und Verzeichnisfeld mit Auswahldialog im Dialog Log; Prüfung des Verzeichnisses beim Speichern samt Angebot, es anzulegen; die jeweiligen Vorgabewerte erscheinen grau im leeren Feld.
Browser	expecco	Die drei Wege, die Testergebnisse entfernen, geben anschließend die Swap-Dateien der beendeten Läufe frei.

Ressourcen

Sieben Zeilen in de.rs – zwei Feldbeschriftungen, ein Feldname und vier Dialogmeldungen. en.rs bleibt unberührt, da der Schlüssel selbst der englische Text ist.

Die drei tragenden Methodenpaare

Datentyp aus dem Record heraushalten

Workflow::ActivityLogSwapper >> detachTypesFrom:

detachTypesFrom:envelopesOrNil
    "... An envelope's type is an ExpeccoDatatypeHolder, and that one holds
     the PROJECT: storing it writes the whole test suite into the record"
    ^ envelopesOrNil collect:[:each| |slot holder copy|
        slot := self typeSlotIndexIn:each.
        (slot == 0 or:[(holder := each instVarAt:slot) isNil])
            ifTrue:[ { each. nil } ]
            ifFalse:[
                copy := each shallowCopy.
                copy instVarAt:slot put:nil.
                { copy. self indexOfType:holder } ]]

readRecordAt: hängt die Typen beim Lesen wieder an, bevor irgendein Aufrufer den Payload sieht. Dadurch blieben logAt:, setupFromSwappedRecord: und alle Envelope-Zugriffe unverändert.

Nummer und Index verpacken

Workflow::ActivityLogSwapper >> codedIndexFor:

codedIndexFor:index
    index > RecordIndexMask ifTrue:[
        "/ silently letting it overflow would corrupt the swapper number and
        "/ send every following reference to a different swapper"
        ^ self error:(...)
    ].
    ^ (swapperNumber bitShift:RecordIndexBits) + index

Gebaut wird ein kodierter Index an genau einer Stelle, ausgepackt an genau zweien (swapper, recordIndex der Referenz). Innerhalb des Swappers bleibt jeder Tabellenindex ein reiner Record-Index.

Nutzer je Logger zählen, nicht je Aufruf

Workflow::ActivityLogSwapper >> addLogger:

addLogger:aLogger
    "Counted PER LOGGER, not per call: #initializeSettingsForProject: may
     run more than once for the same run, and a plain counter would then
     never come back to zero"
    AccessLock critical:[
        activeLoggers add:aLogger.
        knownLoggers add:aLogger.
    ].

dropFinishedLoggers entfernt zusätzlich Logger, deren Lauf beendet ist, die sich aber nie abgemeldet haben – sonst hielte ein abgebrochener Lauf seine Datei für immer offen.

5. Tests

Zwei Ebenen, bewusst getrennt: 22 Tests, davon 15 schnelle für die Mechanik des Swappers und 7 langsame über einen echten Testplanlauf. Die schnellen brauchen nichts außer exept:workflow, die langsamen den Testplan-Executor aus exept:expecco – und überspringen sich selbst, wenn er fehlt.

Workflow::ActivityLogSwapperTests — die Mechanik, ohne Executor

Test	Aussage
testCodedIndexEncoding	Nummer und Index kommen aus dem kodierten Wert zurück, der Wert bleibt ein SmallInteger, und ein Record über der Maske wird abgelehnt
testSwapFileLifecycle	Datei entsteht mit start, verschwindet mit discardSwapFile, der Registry-Platz wird geleert
testOrphanedSwapFilesOfDeadProcessesAreRemoved	Datei mit toter Prozess-ID wird geräumt, die eines lebenden Prozesses bleibt
testReferenceIsRebuiltAfterItHasBeenCollected	Regression: nach einem erzwungenen garbageCollect liefert referenceAt: eine neue Referenz statt eines Fehlers
testRoundTripOfPinValuesAndTraces	Pin-Werte und Traces kommen unverändert aus der Datei zurück
testSwapOutOfALogWithoutCreator	Regression: ein Log ohne Creator lässt sich auslagern
testChildIndicesAreCompleteAndInOrder	der Record eines Vaters nennt jedes Kind, in derselben Reihenfolge
testRecordIsSkippedWhenAChildIsMissing	Regression: fehlt einem Kind der Index, wird der Vater gar nicht geschrieben und bleibt im Speicher
testSwapperIsCreatedOnDemandOnly	unter der Grenze entsteht kein Swapper, beim ersten Überlauf schon
testLogsFinishedBeforeTheSwapperAreCaughtUp	enqueueFinishedLogsIn: holt die früher fertigen Kinder nach, der noch laufende Vater wird nicht geschrieben
testTreeIsTheSameWithAndWithoutSwapping	derselbe Baum mit Deckel und ohne: gleiche Knotenzahl, gleiche Pin-Werte
testEnqueuedLogIsWrittenByTheWriterProcess	der echte asynchrone Weg über die Queue
testWriterKeepsTheOrderOfTheQueue	Post-Order bleibt erhalten: Kindindex kleiner als Vaterindex
testNothingIsLostWhenTheQueueIsFull	bei voller Queue wird nicht geschrieben, nicht verdrängt – und nichts geht verloren
testIsInUse	die drei Bedingungen einzeln, inklusive „nur noch eine Referenz lebt"

Workflow::ActivityLogSwappingRunTests — der Gesamtablauf, headless über den Executor

Test	Aussage
testTreeIsTheSameWithAndWithoutSwapping	derselbe Testplan mit Cache 2 und ohne Swapping: gleiche Knotenzahl, gleiche Namen, gleiche Werte und gleiche Datentypen
testEveryNodeKeepsItsOwnValues	jeder Schritt trägt seinen eigenen Wert; alle paarweise verschieden, Zeitstempel im Laufzeitfenster
testSwapFilesAppearAndGoWithTheResults	nach dem Lauf liegen Dateien da, mit dem Verwerfen der Ergebnisse sind sie weg
testReportContainsEveryNode	der Report liest die ausgelagerten Knoten zurück und nennt jeden Schritt
testElfExportIsTheSameSizeAsWithoutSwapping	der elf-Export ebenso; verglichen wird die Archivgröße mit und ohne Auslagerung
testLoopingRunKeepsOneResultPerTestcase	Schleifenlauf über drei Zyklen: je Testfall ein Ergebnis, alles lesbar
testNothingIsSwappedWhenTheSwitchIsOff	Gegenprobe: keine Datei, keine Referenz, Baum vollständig

Was die Tests gefunden haben

Drei Fehler, alle aus derselben Ecke – Zustände, die der lesende Teil des Codes längst kannte, an denen der schreibende aber abbrach:

Stelle	Fehler
referenceAt:	at:ifAbsentPut: auf einer WeakValueDictionary: Ist der Wert eingesammelt, bleibt der Schlüssel stehen, der Block läuft nicht, und die Dictionary wirft einen Fehler statt eine neue Referenz zu liefern
swapOut:	schrieb den Creator ungeprüft in eine WeakValueDictionary – und nil ist dort kein gültiger Wert. Ein Log ohne Creator ist überall sonst ein vorgesehener Zustand; der Absturz wäre mitten im Ausführungspfad passiert
flushWriteBuffer	schrieb in den Stream, den stop längst geschlossen hatte – ein zweites stop oder ein discardSwapFile danach brach ab

Fünf Fallstricke beim Testen dieses Features

Ohne Executor reiht niemand ein Log ein. Im echten Lauf tut das die Aktivität, wenn sie fertig ist. Ein Test, der Verdrängung erwartet, muss selbst einreihen und warten – sonst hängt das Ergebnis daran, ob der Schreibprozess zufällig drankam. Gewartet wird mit Frist, nie mit festem Delay:

Workflow::ActivityLogSwapperTests >> waitFor:

"/ Tolerant on purpose: the writer runs at background priority, so how long
"/ it takes is not predictable. A fixed delay would be either flaky or slow
deadline := Timestamp now addSeconds:10.
[ aBlock value ] whileFalse:[
    Timestamp now > deadline ifTrue:[ ^ false ].
    Delay waitForMilliseconds:20.
].
^ true

Unverbundene Steps laufen gleichzeitig. Dann werden alle Kinder an den Log gehängt, bevor eines fertig und geschrieben ist – und es wird nie etwas verdrängt. Die Steps des Testprojekts sind deshalb über ihre Enable-Pins verkettet:

Workflow::ActivityLogSwappingRunTests >> buildProjectWithCases:stepsEach:

eno := previous hasEnableOutputPin
            ifTrue:[ previous enableOutputPin ]
            ifFalse:[ previous createEnableOutputPin ].
eni := step hasEnableInputPin
            ifTrue:[ step enableInputPin ]
            ifFalse:[ step createEnableInputPin ].
eno connectWithPin:eni.

Konstante Werte machen blind. Jeder Schritt friert einen eigenen Wert ein (Fall·100 + Schritt) und schreibt ihn über drei Ausgänge verschiedenen Datentyps zurück. Erst dadurch fällt auf, wenn eine Referenz den Record eines anderen Knotens liest – und die drei Typen prüfen zugleich detachTypesFrom:/attachTypesTo::

Testaktion leaf

counter value:(n value).
stamp   value:(Timestamp now).
text    value:('run-', n value printString).
"/ give the activityLog writer process a chance
Delay waitForMilliseconds:20.

Die Enable-Pins schreiben einen eigenen *DONE*-Token mit – beim Auswerten über data isENOToken not herausfiltern, das ist Ablaufsteuerung und keine Nutzdaten. Und loopCount: allein schleift nicht: loop:true ist der Schalter.

Prüfen, bevor gelesen wird. Report und elf-Export materialisieren die ausgelagerten Knoten. Wer vorher schon die Werte einsammelt, nimmt ihnen genau das weg, was sie prüfen sollen – die Zählung der Referenzen fragt deshalb nur isActivityLogReference und liest keinen einzigen Record.

Was die Prüfung nicht hergibt: Der Standardreport listet Schritte, nicht deren Pin-Werte – geprüft wird also, dass jeder Schritt vorkommt. Und die .elf-Datei ist ein ZIP, dessen Einträge dieses Image nicht wieder auspacken kann; statt einer Textsuche vergleicht der Test die Archivgrößen mit und ohne Auslagerung.

Aufräumen gehört dazu

Beide Klassen setzen im setUp ein eigenes Swap-Verzeichnis und stellen im tearDown jede angefasste Benutzereinstellung zurück – bei den Laufzeit-Tests sind das vier: Schalter, Cache-Größe, Verzeichnis und die Verlustgrenze maxNumberOfChildrenInlog, die für den Vergleichslauf ohne Swapper leer sein muss, damit er nichts verwirft. Jeder erzeugte Swapper wird verworfen, und gelöscht wird rekursiv: Der Report legt neben seinem HTML ein .files-Verzeichnis an.

Laufzeit: die 15 Mechanik-Tests laufen in Sekundenbruchteilen, die 7 Laufzeit-Tests brauchen zusammen rund fünfeinhalb Sekunden.

6. Speicherabschätzung

Gemessen sind die Dateigrößen; die Zahlen für den Hauptspeicher sind Rechnungen aus den Objektlayouts. Grundlage: 64-Bit-Image, Objektkopf 16 Byte, ein Slot 8 Byte – belegt durch StandardActivityLog mit instSize 16 und daraus 144 Byte.

Ein Log-Eintrag ohne Auslagerung

Blattknoten mit einem Eingangs- und zwei Ausgangswerten

Bestandteil	Byte	Rechnung
StandardActivityLog	144	16 + 16 × 8
3 × DataEnvelope	96	je 16 + 2 × 8
2 Envelope-Sammlungen	80	je Array-Kopf + Slots
Verwaltung, Ausrichtung	~120	Erfahrungswert
Summe	~440

Derselbe Eintrag ausgelagert

Bestandteil	Byte	Rechnung
ActivityLogReference	24	16 + 1 × 8
Eintrag in references	~16	WeakValueDictionary, 2 Slots
9 Tabellenzeilen	72	9 × 8 (OrderedCollection-Slot)
2 Timestamp-Objekte	~48	startDeltas, durations
Summe	~160

• je Eintrag vorher: 440 B
• je Eintrag nachher: 160 B
• Einsparung: 64 %
• Faktor: 2,8 ×

Hochgerechnet auf eine Million Einträge

• ohne Auslagerung: 440 MB
• mit Auslagerung, heutiger Stand: 160 MB
• mit den Maßnahmen aus Kapitel 07: ≈ 38 MB

Dazu kommt die Swap-Datei mit rund 200 MB – auf der Platte, nicht im Adressraum. Ihre Größe hängt fast vollständig von den Pin-Werten ab, denn genau die sind der variable Anteil, der ausgelagert wird.

Gemessen am Testlauf

SwapTest20, 22 Records, Cache-Größe 5

Größe	Wert	Anmerkung
Datei gesamt	4.732 B	22 Records inklusive Rahmen
Record, größter	228 B	Blattknoten mit Pin-Werten
Record, kleinster	15 B	Compound ohne eigene Werte
Rahmen je Record	8 B	4 Magic + 4 Länge
Wurzel-Kinder im Speicher	5 von 20	15 durch Referenzen ersetzt

Wovon die Einsparung wirklich abhängt Der feste Anteil eines Logs – Objektkopf, Zeiten, Verdikt, Verweise – schrumpft von rund 240 auf 160 Byte, also nur um ein Drittel. Der große Hebel ist der variable Anteil: Pin-Werte und Traces verlassen den Speicher vollständig. Ein Lauf mit vielen oder großen Pin-Werten profitiert deutlich stärker als die 2,8 × dieser Rechnung, ein Lauf mit leeren Pins entsprechend weniger.

7. Weitere Einsparung

Die verbleibenden 160 Byte je Eintrag stecken fast vollständig in den Indextabellen und im Stellvertreterobjekt. Fünf Maßnahmen, nach abnehmendem Verhältnis von Gewinn zu Risiko.

Zeitstempel als Integer-Deltas

−40 B je Eintrag

Die Instanzvariablen heißen startDeltas und durations, halten aber vollständige Timestamp-Objekte. Bei einer Million Einträgen sind das zwei Millionen Objekte für eine Information, die als Abstand zum Laufbeginn in ein IntegerArray passt: 2 × 4 Byte statt 2 × (8 + 16).

Dafür

• Größter Einzelposten, und die Namen versprechen es ohnehin schon.
• Rein intern; nach außen liefern startTimeAt: und endTimeAt: weiterhin Timestamps.

Dagegen

• Auflösung und Bereich müssen festgelegt werden. logTimesWithMicrosecondPrecision und ein dreitägiger Lauf ergeben 2,6·10¹¹ µs – das braucht 64 Bit, Millisekunden kämen mit 32 aus.
• Jeder Lesezugriff rechnet um.

Referenzobjekte durch blanke Integer ersetzen

−40 B je Eintrag

Die von Anfang an vorgesehene zweite Stufe: subActivityLogs enthält für ausgelagerte Kinder direkt den kodierten Index statt eines Objekts. Das spart die 24 Byte des Stellvertreters und den Eintrag im references-Verzeichnis.

Dafür

• Der zweitgrößte Posten, und er entfällt vollständig statt zu schrumpfen.
• Der kodierte Index existiert bereits und ist genau dafür gebaut.

Dagegen

• Die Identität bricht: includesIdentical: in ActivityLogItem>>basicUpdateChildren und identityIndexOf: in replaceSublog:by: müssen umgebaut werden – und jede weitere Stelle, die einen Sublog wiedererkennt.
• Alle rund 80 Selektoren der Referenz müssten woanders leben; jeder Aufrufer, der heute ein Log-artiges Objekt bekommt, sähe plötzlich einen Integer.
• Der größte Eingriff von allen. Lohnt erst jenseits von etwa einer Million Einträgen.

Typisierte Arrays statt OrderedCollection

−40 B je Eintrag

Neun OrderedCollection kosten je Eintrag neun Zeiger-Slots à 8 Byte. states passt in ein ByteArray, hasTraces in ein Bit, recordSizes, stepIndices und parentIndices in ein IntegerArray; nur filePositions braucht wirklich 64 Bit.

Dafür

• Rein lokal im Swapper, keine Auswirkung nach außen.
• Nebeneffekt: bessere Lokalität beim Durchlaufen großer Bäume.

Dagegen

• Wachstum kopiert den ganzen Puffer; braucht eine Verdopplungsstrategie.
• childIndices speichert nil für Blätter und bleibt eine Objektsammlung – siehe die nächste Maßnahme.

Kinderlisten in einem gemeinsamen Array

−16 B je Knoten mit Kindern

Statt eines eigenen IntegerArray je Knoten ein einziges großes Array plus eine Offsettabelle, wie bei dünn besetzten Matrizen. Das spart je Knoten mit Kindern einen Objektkopf; bei einer Million Knoten mit durchschnittlich einem Kind sind das 16 MB.

Dafür

• Blätter kosten dann gar nichts mehr statt eines nil-Slots.
• Passt zur vorigen Maßnahme, beide betreffen dieselbe Tabelle.

Dagegen

• Kinderlisten entstehen erst beim Schreiben des Elternknotens, also spät – das Anhängen ist unproblematisch, ein nachträgliches Ändern aber teuer.
• childReferencesAt: und noteParentIndicesBelow: werden weniger offensichtlich.

Kleinere Cache-Größe

wirkt sofort, ohne Codeänderung

Die Vorgabe von 100 Kindern je Knoten ist großzügig. Ein Wert von 20 verdrängt früher und hält entsprechend weniger vollständige Logs im Speicher – bei einem Baum mit vielen Verzweigungen ist das der schnellste Hebel überhaupt, weil er den variablen Anteil trifft.

Dafür

• Eine Einstellung, kein Eingriff. Pro Installation wählbar.
• Wirkt auf den teuersten Anteil, die Pin-Werte.

Dagegen

• Jedes Aufklappen eines älteren Knotens liest die Datei.
• Bei einem laufenden Test kann das Verdrängen den Writer einholen; dann bleiben Logs im Speicher, bis sie geschrieben sind.

Summe

je Log-Eintrag, kumuliert

Stand	Byte	bei 1 Mio	gegenüber heute
ohne Auslagerung	440	440 MB	—
heutiger Stand	160	160 MB	2,8 ×
+ Zeitstempel als Deltas	120	120 MB	3,7 ×
+ typisierte Arrays	80	80 MB	5,5 ×
+ Integer statt Referenzobjekt	40	40 MB	11 ×
+ gemeinsames Kinderarray	~38	~38 MB	11,6 ×

Die ersten drei Maßnahmen sind lokal im Swapper und zusammen an einem Tag zu machen. Die vierte ist der eigentliche Einschnitt und sollte erst angegangen werden, wenn ein realer Lauf zeigt, dass die 160 Byte tatsächlich das Problem sind – bis dahin ist die Cache-Größe der bessere Hebel, weil sie den variablen Anteil trifft und nichts kostet.

expecco · Activity Log Swapping · Stand 10.09.2026

Dateigrößen gemessen, Speichergrößen gerechnet aus Objektlayout und instSize.

---

Copyright © 2014-2024 eXept Software AG