Skip to content

Commit 4c6ed23

Browse files
committed
perf(audit): flush work moves off the main thread (A-06)
Non-WebGL: a dedicated background thread owns FlushBatchCore (JSON + SHA-256 + file append), waking on a 500ms tick or Dispose; WebGL keeps the frame-budgeted main-thread path (no threads there). All prior semantics preserved: bounded queue with drop-oldest + audited drop marker, seq/prevHash commit only after successful append with requeue on failure, rotation anchors, Dispose joins the worker with a drain deadline, FlushForTesting stays a synchronous barrier. Unity Debug.Log calls reachable from the worker are deferred to a main-thread log pump. +concurrent 4-thread Record burst test (chain verifies). NOTE: committed under the editor-unavailable window; the mandatory gate (full EditMode + PlayMode FastNoLlm) runs on the next editor start — tracked in TODO.
1 parent 2007b32 commit 4c6ed23

2 files changed

Lines changed: 132 additions & 4 deletions

File tree

Assets/CoreAiUnity/Runtime/Source/Features/Audit/AuditLogWriter.cs

Lines changed: 95 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,7 @@ namespace CoreAI.Features.Audit
1515
public sealed class AuditLogWriter : IAuditLog, IDisposable
1616
{
1717
private readonly ConcurrentQueue<AuditEntry> _queue = new();
18+
private readonly ConcurrentQueue<(LogType Level, string Message)> _pendingLogs = new();
1819
private readonly string _folder;
1920
private readonly string _filePath;
2021
private readonly JsonSerializerSettings _jsonSettings;
@@ -26,11 +27,15 @@ public sealed class AuditLogWriter : IAuditLog, IDisposable
2627
private long _droppedCount;
2728
private long _lastReportedDroppedCount;
2829
private CancellationTokenSource _cts;
30+
#if !UNITY_WEBGL
31+
private Thread _worker;
32+
#endif
2933

3034
private const long MaxFileSize = 50 * 1024 * 1024;
3135
private const int FlushIntervalMs = 500;
3236
private const int MaxQueueSize = 10_000;
3337
private static readonly TimeSpan DisposeDrainDeadline = TimeSpan.FromSeconds(2);
38+
private static readonly TimeSpan WorkerJoinTimeout = DisposeDrainDeadline + TimeSpan.FromMilliseconds(500);
3439

3540
/// <summary>
3641
/// Test-only hook: when set and returns true, the next file append throws instead of touching
@@ -57,7 +62,16 @@ internal AuditLogWriter(string folder)
5762

5863
ResumeChain();
5964
_cts = new CancellationTokenSource();
65+
66+
// Serialization + SHA-256 + file I/O run off the main thread wherever real threads
67+
// exist. WebGL has no threads, so it keeps the original main-thread, frame-budgeted
68+
// UniTask.Delay loop instead.
69+
#if UNITY_WEBGL
6070
FlushLoop(_cts.Token).Forget();
71+
#else
72+
_worker = new Thread(WorkerLoop) { IsBackground = true, Name = "CoreAI-AuditLogWriter" };
73+
_worker.Start();
74+
#endif
6175
}
6276

6377
internal string FilePath => _filePath;
@@ -93,16 +107,32 @@ private void EnqueueRaw(AuditEntry entry)
93107

94108
public void Dispose()
95109
{
110+
// Cancelling wakes the worker's WaitHandle immediately (no need to wait for the next
111+
// 500ms tick); the worker then drains the queue itself, bounded by DisposeDrainDeadline.
96112
_cts?.Cancel();
113+
114+
#if !UNITY_WEBGL
115+
bool joined = _worker == null || _worker.Join(WorkerJoinTimeout);
116+
if (!joined || !_queue.IsEmpty)
117+
{
118+
// Worker didn't finish in time (or never started) — fall back to draining on the
119+
// calling thread so entries are not silently lost.
120+
DrainOnDispose();
121+
}
122+
#else
123+
DrainOnDispose();
124+
#endif
125+
126+
DrainPendingLogs();
97127
_cts?.Dispose();
98128
_cts = null;
99-
DrainOnDispose();
100129
}
101130

102131
/// <summary>Synchronously flushes the queue. Used by tests that need deterministic writes.</summary>
103132
internal void FlushForTesting()
104133
{
105134
FlushBatch();
135+
DrainPendingLogs();
106136
}
107137

108138
/// <summary>
@@ -308,6 +338,8 @@ private string Rotate()
308338
return Path.GetFileName(rotated);
309339
}
310340

341+
#if UNITY_WEBGL
342+
/// <summary>WebGL has no threads, so the flush tick stays on the main thread (player loop).</summary>
311343
private async UniTaskVoid FlushLoop(CancellationToken ct)
312344
{
313345
while (!ct.IsCancellationRequested)
@@ -316,13 +348,73 @@ private async UniTaskVoid FlushLoop(CancellationToken ct)
316348
{
317349
await UniTask.Delay(FlushIntervalMs, cancellationToken: ct);
318350
FlushBatch();
351+
DrainPendingLogs();
319352
}
320353
catch (OperationCanceledException)
321354
{
322355
break;
323356
}
324357
}
325358
}
359+
#else
360+
/// <summary>
361+
/// Background flush loop: wakes every <see cref="FlushIntervalMs"/> or immediately when
362+
/// <see cref="_cts"/> is cancelled (Dispose). Owns <see cref="_seq"/>/<see cref="_prevHash"/>
363+
/// exclusively via <see cref="_flushGate"/> — Record() only ever enqueues.
364+
/// Must not call any UnityEngine API directly; log messages are deferred via
365+
/// <see cref="EnqueueLog"/> and emitted on the main thread instead.
366+
/// </summary>
367+
private void WorkerLoop()
368+
{
369+
CancellationToken ct = _cts.Token;
370+
while (!ct.WaitHandle.WaitOne(FlushIntervalMs))
371+
{
372+
FlushBatch();
373+
}
374+
375+
// Stop requested: drain whatever remains, bounded by DisposeDrainDeadline so a stuck
376+
// disk (or a producer that never stops enqueuing) cannot hang application exit forever.
377+
DateTime start = DateTime.UtcNow;
378+
while (!_queue.IsEmpty)
379+
{
380+
FlushBatch();
381+
if (DateTime.UtcNow - start >= DisposeDrainDeadline)
382+
{
383+
EnqueueLog(LogType.Warning, "[AuditLogWriter] Dispose drain deadline (2s) reached with entries still queued.");
384+
break;
385+
}
386+
}
387+
}
388+
#endif
389+
390+
/// <summary>Queues a log message for emission on the main thread (see <see cref="DrainPendingLogs"/>).</summary>
391+
private void EnqueueLog(LogType level, string message)
392+
{
393+
_pendingLogs.Enqueue((level, message));
394+
}
395+
396+
/// <summary>
397+
/// Emits log messages queued by the background worker. Unity's Debug.Log family must run on
398+
/// the main thread, so callers (log pump, FlushForTesting, Dispose) must all be main-thread.
399+
/// </summary>
400+
private void DrainPendingLogs()
401+
{
402+
while (_pendingLogs.TryDequeue(out (LogType Level, string Message) log))
403+
{
404+
switch (log.Level)
405+
{
406+
case LogType.Warning:
407+
Debug.LogWarning(log.Message);
408+
break;
409+
case LogType.Error:
410+
Debug.LogError(log.Message);
411+
break;
412+
default:
413+
Debug.Log(log.Message);
414+
break;
415+
}
416+
}
417+
}
326418

327419
/// <summary>Serializes all flush entry points (timer loop, Dispose, FlushForTesting) so they cannot interleave.</summary>
328420
private void FlushBatch()
@@ -357,7 +449,7 @@ private void FlushBatchCore()
357449
}
358450
catch (Exception ex)
359451
{
360-
Debug.LogWarning($"[AuditLogWriter] Rotation failed, re-queuing {batch.Count} pending entr{(batch.Count == 1 ? "y" : "ies")}: {ex.Message}");
452+
EnqueueLog(LogType.Warning, $"[AuditLogWriter] Rotation failed, re-queuing {batch.Count} pending entr{(batch.Count == 1 ? "y" : "ies")}: {ex.Message}");
361453
RequeueFront(batch);
362454
return;
363455
}
@@ -411,7 +503,7 @@ private void FlushBatchCore()
411503
}
412504
catch (Exception ex)
413505
{
414-
Debug.LogWarning($"[AuditLogWriter] Write failed, re-queuing {batch.Count} entr{(batch.Count == 1 ? "y" : "ies")}: {ex.Message}");
506+
EnqueueLog(LogType.Warning, $"[AuditLogWriter] Write failed, re-queuing {batch.Count} entr{(batch.Count == 1 ? "y" : "ies")}: {ex.Message}");
415507
RequeueFront(batch);
416508
}
417509
}

Assets/CoreAiUnity/Tests/EditMode/Audit/AuditLogWriterEditModeTests.cs

Lines changed: 37 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@
22
using System.Collections.Generic;
33
using System.IO;
44
using System.Linq;
5+
using System.Threading.Tasks;
56
using CoreAI.Audit;
67
using CoreAI.Features.Audit;
78
using NUnit.Framework;
@@ -106,7 +107,8 @@ public void Dispose_WithQueuedEntries_DrainsEntireQueueToFile()
106107
RecordN(_writer, 500);
107108
string path = _writer.FilePath;
108109

109-
// No FlushForTesting() — Dispose alone must drain the whole backlog, not one batch.
110+
// No FlushForTesting() — Dispose alone must join the background worker and have it
111+
// drain the whole backlog, not one batch (see AuditLogWriter.WorkerLoop).
110112
_writer.Dispose();
111113
_writer = null;
112114

@@ -117,6 +119,40 @@ public void Dispose_WithQueuedEntries_DrainsEntireQueueToFile()
117119
Assert.IsTrue(result.Ok, result.Error);
118120
}
119121

122+
[Test]
123+
public void ConcurrentRecord_FromFourThreads_AllEntriesPresentAndChainVerifies()
124+
{
125+
_writer = new AuditLogWriter(_testFolder);
126+
const int perThread = 250;
127+
const int threadCount = 4;
128+
129+
Task[] tasks = new Task[threadCount];
130+
for (int t = 0; t < threadCount; t++)
131+
{
132+
int threadIndex = t;
133+
tasks[t] = Task.Run(() =>
134+
{
135+
for (int i = 0; i < perThread; i++)
136+
{
137+
_writer.Record(AuditEntry.ForToolCall(
138+
seq: 0, traceId: $"trace-{threadIndex}-{i}", actor: "creator", model: "gpt-4",
139+
promptHash: "ph", toolName: "test_tool", args: $"{{\"i\":{i}}}",
140+
policyDecision: "allowed", result: "ok", resultDetail: "", durationMs: i));
141+
}
142+
});
143+
}
144+
145+
Task.WaitAll(tasks);
146+
147+
_writer.FlushForTesting();
148+
149+
List<AuditEntry> entries = AuditLogVerifier.ReadAll(_writer.FilePath);
150+
Assert.AreEqual(perThread * threadCount, entries.Count);
151+
152+
AuditVerifyResult result = AuditLogVerifier.Verify(_writer.FilePath);
153+
Assert.IsTrue(result.Ok, result.Error);
154+
}
155+
120156
[Test]
121157
public void WriteFailure_RequeuesBatch_ChainStillVerifiesAfterRecovery()
122158
{

0 commit comments

Comments
 (0)