perf(runtime): apply-path cache write off-mailbox; stash deferred dispatches
This commit is contained in:
Joseph Doherty
+130
@@ -0,0 +1,130 @@
|
||||
using System.Text.Json;
|
||||
using Akka.Actor;
|
||||
using Akka.Event;
|
||||
using Shouldly;
|
||||
using Xunit;
|
||||
using ZB.MOM.WW.OtOpcUa.Commons.Messages.Deploy;
|
||||
using ZB.MOM.WW.OtOpcUa.Commons.Types;
|
||||
using ZB.MOM.WW.OtOpcUa.Runtime.DeploymentCache;
|
||||
using ZB.MOM.WW.OtOpcUa.Runtime.Drivers;
|
||||
using ZB.MOM.WW.OtOpcUa.Runtime.Tests.Harness;
|
||||
|
||||
namespace ZB.MOM.WW.OtOpcUa.Runtime.Tests.Drivers;
|
||||
|
||||
/// <summary>
|
||||
/// Surgical-deploys Task 7 Part B — a dispatch that arrives while an apply is in flight is
|
||||
/// STASHED, not re-forwarded to <c>Self</c>.
|
||||
/// </summary>
|
||||
/// <remarks>
|
||||
/// <para>
|
||||
/// <c>Self.Forward</c> put the message back at the tail of the actor's OWN mailbox, so with
|
||||
/// nothing else to do the host spun dequeue → log → enqueue for the entire fetch window —
|
||||
/// thousands of iterations and thousands of log lines for one deferred deployment, burning a
|
||||
/// core and starving nothing but itself of useful work. The stash holds it outside the mailbox
|
||||
/// until the apply finishes.
|
||||
/// </para>
|
||||
/// <para>
|
||||
/// Runs at <c>DEBUG</c> because the assertion IS a log line: a spin is only distinguishable
|
||||
/// from a single deferral by how many times it is announced. A log event below
|
||||
/// <c>akka.loglevel</c> never reaches the EventStream at all, so at the default WARNING this
|
||||
/// test would count zero either way and pass vacuously.
|
||||
/// </para>
|
||||
/// </remarks>
|
||||
public sealed class DriverHostActorApplyingStashTests()
|
||||
: RuntimeActorTestBase(AkkaTestHoconAtLevel("DEBUG"))
|
||||
{
|
||||
private static readonly NodeId TestNode = NodeId.Parse("driver-test");
|
||||
private static readonly RevisionHash RevA = RevisionHash.Parse(new string('a', 64));
|
||||
private static readonly RevisionHash RevB = RevisionHash.Parse(new string('b', 64));
|
||||
|
||||
/// <summary>Minimal parseable artifact — no drivers.</summary>
|
||||
private static byte[] ArtifactBytes() =>
|
||||
JsonSerializer.SerializeToUtf8Bytes(new { DriverInstances = Array.Empty<object>() });
|
||||
|
||||
[Fact]
|
||||
public void ADispatchArrivingMidApply_IsDeferredOnce_AndAppliedAfterTheApplyCompletes()
|
||||
{
|
||||
var db = NewInMemoryDbFactory();
|
||||
var fetcher = new GatedFetcher(ArtifactBytes());
|
||||
var deploymentA = DeploymentId.NewId();
|
||||
var deploymentB = DeploymentId.NewId();
|
||||
|
||||
var coordinator = CreateTestProbe();
|
||||
var actor = Sys.ActorOf(DriverHostActor.Props(
|
||||
db, TestNode, coordinator.Ref,
|
||||
localRoles: new HashSet<string> { "driver" },
|
||||
deploymentArtifactCache: new NullArtifactCache(),
|
||||
fetchAndCacheMode: true,
|
||||
artifactFetcher: fetcher));
|
||||
|
||||
try
|
||||
{
|
||||
// A is in flight: the fetch has started and its task will not complete until released.
|
||||
actor.Tell(new DispatchDeployment(deploymentA, RevA, CorrelationId.NewId()));
|
||||
AwaitAssert(() => fetcher.Calls.ShouldBe(1), duration: PresenceBudget);
|
||||
|
||||
var logs = CreateTestProbe();
|
||||
Sys.EventStream.Subscribe(logs.Ref, typeof(LogEvent));
|
||||
|
||||
actor.Tell(new DispatchDeployment(deploymentB, RevB, CorrelationId.NewId()));
|
||||
|
||||
// Collect for long enough that a forward-spin would announce itself thousands of times.
|
||||
var deferrals = 0;
|
||||
var deadline = DateTime.UtcNow + TimeSpan.FromSeconds(1.5);
|
||||
while (DateTime.UtcNow < deadline)
|
||||
{
|
||||
if (logs.ReceiveOne(TimeSpan.FromMilliseconds(150)) is LogEvent e &&
|
||||
e.Message?.ToString()?.Contains("deferring", StringComparison.Ordinal) == true)
|
||||
{
|
||||
deferrals++;
|
||||
}
|
||||
}
|
||||
|
||||
deferrals.ShouldBe(1);
|
||||
|
||||
// Nothing was lost: B re-enters exactly once, after A's apply transitions back to Steady.
|
||||
fetcher.Release();
|
||||
coordinator.ExpectMsg<ApplyAck>(TimeSpan.FromSeconds(10)).Outcome.ShouldBe(ApplyAckOutcome.Applied);
|
||||
coordinator.ExpectMsg<ApplyAck>(TimeSpan.FromSeconds(10)).Outcome.ShouldBe(ApplyAckOutcome.Applied);
|
||||
fetcher.Calls.ShouldBe(2);
|
||||
}
|
||||
finally
|
||||
{
|
||||
// Never leave the fetch parked: a blocked apply would hang ActorSystem shutdown.
|
||||
fetcher.Release();
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>Gates the FIRST fetch on the test; later fetches complete immediately.</summary>
|
||||
private sealed class GatedFetcher(byte[] bytes) : IDeploymentArtifactFetcher
|
||||
{
|
||||
private readonly TaskCompletionSource _gate =
|
||||
new(TaskCreationOptions.RunContinuationsAsynchronously);
|
||||
private int _calls;
|
||||
|
||||
public int Calls => Volatile.Read(ref _calls);
|
||||
|
||||
public void Release() => _gate.TrySetResult();
|
||||
|
||||
public async Task<byte[]?> FetchAsync(string deploymentId, string expectedRevisionHash, CancellationToken ct)
|
||||
{
|
||||
if (Interlocked.Increment(ref _calls) == 1)
|
||||
await _gate.Task.ConfigureAwait(false);
|
||||
return bytes;
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>Accepts every store; this class asserts on dispatch handling, not on caching.</summary>
|
||||
private sealed class NullArtifactCache : IDeploymentArtifactCache
|
||||
{
|
||||
public Task StoreAsync(string clusterId, string deploymentId, string revisionHash,
|
||||
byte[] artifact, CancellationToken ct = default)
|
||||
=> Task.CompletedTask;
|
||||
|
||||
public Task<CachedDeploymentArtifact?> GetCurrentAsync(string clusterId, CancellationToken ct = default)
|
||||
=> Task.FromResult<CachedDeploymentArtifact?>(null);
|
||||
|
||||
public Task<CachedDeploymentArtifact?> GetCurrentUnkeyedAsync(CancellationToken ct = default)
|
||||
=> Task.FromResult<CachedDeploymentArtifact?>(null);
|
||||
}
|
||||
}
|
||||
+175
@@ -0,0 +1,175 @@
|
||||
using System.Text.Json;
|
||||
using Akka.Actor;
|
||||
using Microsoft.EntityFrameworkCore;
|
||||
using Shouldly;
|
||||
using Xunit;
|
||||
using ZB.MOM.WW.OtOpcUa.Commons.Interfaces;
|
||||
using ZB.MOM.WW.OtOpcUa.Commons.Messages.Deploy;
|
||||
using ZB.MOM.WW.OtOpcUa.Commons.Messages.Fleet;
|
||||
using ZB.MOM.WW.OtOpcUa.Commons.Types;
|
||||
using ZB.MOM.WW.OtOpcUa.Configuration;
|
||||
using ZB.MOM.WW.OtOpcUa.Configuration.Entities;
|
||||
using ZB.MOM.WW.OtOpcUa.Configuration.Enums;
|
||||
using ZB.MOM.WW.OtOpcUa.Runtime.DeploymentCache;
|
||||
using ZB.MOM.WW.OtOpcUa.Runtime.Drivers;
|
||||
using ZB.MOM.WW.OtOpcUa.Runtime.Tests.Harness;
|
||||
|
||||
namespace ZB.MOM.WW.OtOpcUa.Runtime.Tests.Drivers;
|
||||
|
||||
/// <summary>
|
||||
/// Surgical-deploys Task 7 Part A — the artifact-cache write is I/O (hundreds of chunk inserts
|
||||
/// into LocalDb) and must not run on the actor thread.
|
||||
/// </summary>
|
||||
/// <remarks>
|
||||
/// <para>
|
||||
/// The ACK was never the thing at risk: <c>ApplyAndAck</c> sends it BEFORE it caches, so a
|
||||
/// blocking store still acked promptly. What it blocked was <b>everything after</b> — the host
|
||||
/// could not dequeue a driver value burst, a diagnostics request or the next dispatch until
|
||||
/// SQLite was done. So the load-bearing assertion here is that the actor answers an unrelated
|
||||
/// message while the store is still in flight, not that the ACK arrived.
|
||||
/// </para>
|
||||
/// <para>
|
||||
/// Runs at <c>INFO</c> so the completion self-message's log line is observable — the pipe-back
|
||||
/// is private, and its visible effect is that line.
|
||||
/// </para>
|
||||
/// </remarks>
|
||||
public sealed class DriverHostActorAsyncCacheWriteTests()
|
||||
: RuntimeActorTestBase(AkkaTestHoconAtLevel("INFO"))
|
||||
{
|
||||
private static readonly NodeId TestNode = NodeId.Parse("driver-test");
|
||||
private static readonly RevisionHash RevA = RevisionHash.Parse(new string('a', 64));
|
||||
|
||||
[Fact]
|
||||
public void AStillRunningCacheStore_DoesNotBlockTheHostMailbox()
|
||||
{
|
||||
var db = NewInMemoryDbFactory();
|
||||
var cache = new GatedArtifactCache();
|
||||
var deploymentId = SeedDeployment(db, RevA);
|
||||
|
||||
var coordinator = CreateTestProbe();
|
||||
var actor = Sys.ActorOf(DriverHostActor.Props(
|
||||
db, TestNode, coordinator.Ref,
|
||||
localRoles: new HashSet<string> { "driver" },
|
||||
deploymentArtifactCache: cache));
|
||||
|
||||
try
|
||||
{
|
||||
actor.Tell(new DispatchDeployment(deploymentId, RevA, CorrelationId.NewId()));
|
||||
coordinator.ExpectMsg<ApplyAck>(TimeSpan.FromSeconds(5)).Outcome.ShouldBe(ApplyAckOutcome.Applied);
|
||||
|
||||
// The store was entered and has NOT completed — the gate is still closed.
|
||||
AwaitAssert(() => cache.StoresEntered.ShouldBe(1), duration: PresenceBudget);
|
||||
cache.StoresCompleted.ShouldBe(0);
|
||||
|
||||
// THE assertion: with the store still in flight the host is still processing its mailbox.
|
||||
// A blocking `.GetAwaiter().GetResult()` parks the actor thread here and this times out.
|
||||
actor.Tell(new GetDiagnostics(CorrelationId.NewId()), coordinator.Ref);
|
||||
coordinator.ExpectMsg<NodeDiagnosticsSnapshot>(TimeSpan.FromSeconds(3));
|
||||
|
||||
// Completion is observed rather than fire-and-forgotten: the store pipes back to Self and
|
||||
// the handler logs it, so an operator can tell a cached apply from an uncached one.
|
||||
EventFilter.Info(contains: "cached applied deployment")
|
||||
.ExpectOne(TimeSpan.FromSeconds(5), () => cache.Release());
|
||||
}
|
||||
finally
|
||||
{
|
||||
// Never leave the fake gated: a parked store would hang ActorSystem shutdown.
|
||||
cache.Release();
|
||||
}
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void AFailingCacheStore_WarnsAndLeavesTheApplyApplied()
|
||||
{
|
||||
// The cache is a boot fallback, not part of the deployment protocol. A failed store must
|
||||
// surface as a Warning and nothing else — emphatically NOT as a second, contradictory Failed
|
||||
// ACK for a deployment the fleet already believes is live.
|
||||
var db = NewInMemoryDbFactory();
|
||||
var deploymentId = SeedDeployment(db, RevA);
|
||||
|
||||
var coordinator = CreateTestProbe();
|
||||
var actor = Sys.ActorOf(DriverHostActor.Props(
|
||||
db, TestNode, coordinator.Ref,
|
||||
localRoles: new HashSet<string> { "driver" },
|
||||
deploymentArtifactCache: new AsyncFailingArtifactCache()));
|
||||
|
||||
EventFilter.Warning(contains: "could not be cached").ExpectOne(TimeSpan.FromSeconds(5), () =>
|
||||
{
|
||||
actor.Tell(new DispatchDeployment(deploymentId, RevA, CorrelationId.NewId()));
|
||||
coordinator.ExpectMsg<ApplyAck>(TimeSpan.FromSeconds(5)).Outcome.ShouldBe(ApplyAckOutcome.Applied);
|
||||
});
|
||||
|
||||
coordinator.ExpectNoMsg(TimeSpan.FromMilliseconds(300));
|
||||
}
|
||||
|
||||
/// <summary>Seeds a sealed, parseable deployment and returns its id.</summary>
|
||||
private static DeploymentId SeedDeployment(IDbContextFactory<OtOpcUaConfigDbContext> db, RevisionHash rev)
|
||||
{
|
||||
var artifact = JsonSerializer.SerializeToUtf8Bytes(new { DriverInstances = Array.Empty<object>() });
|
||||
var id = DeploymentId.NewId();
|
||||
using var ctx = db.CreateDbContext();
|
||||
ctx.Deployments.Add(new Deployment
|
||||
{
|
||||
DeploymentId = id.Value,
|
||||
RevisionHash = rev.Value,
|
||||
Status = DeploymentStatus.Sealed,
|
||||
CreatedBy = "test",
|
||||
SealedAtUtc = DateTime.UtcNow,
|
||||
ArtifactBlob = artifact,
|
||||
});
|
||||
ctx.SaveChanges();
|
||||
return id;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// A store that never completes until the test releases it — the fake shape of a slow LocalDb
|
||||
/// write. It must not complete synchronously, or it would prove nothing about the mailbox.
|
||||
/// </summary>
|
||||
private sealed class GatedArtifactCache : IDeploymentArtifactCache
|
||||
{
|
||||
private readonly TaskCompletionSource _gate =
|
||||
new(TaskCreationOptions.RunContinuationsAsynchronously);
|
||||
private int _entered;
|
||||
private int _completed;
|
||||
|
||||
public int StoresEntered => Volatile.Read(ref _entered);
|
||||
public int StoresCompleted => Volatile.Read(ref _completed);
|
||||
|
||||
public void Release() => _gate.TrySetResult();
|
||||
|
||||
public async Task StoreAsync(string clusterId, string deploymentId, string revisionHash,
|
||||
byte[] artifact, CancellationToken ct = default)
|
||||
{
|
||||
Interlocked.Increment(ref _entered);
|
||||
await _gate.Task.ConfigureAwait(false);
|
||||
Interlocked.Increment(ref _completed);
|
||||
}
|
||||
|
||||
public Task<CachedDeploymentArtifact?> GetCurrentAsync(string clusterId, CancellationToken ct = default)
|
||||
=> Task.FromResult<CachedDeploymentArtifact?>(null);
|
||||
|
||||
public Task<CachedDeploymentArtifact?> GetCurrentUnkeyedAsync(CancellationToken ct = default)
|
||||
=> Task.FromResult<CachedDeploymentArtifact?>(null);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Fails the store ASYNCHRONOUSLY (a faulted task), which is how a real LocalDb write fails —
|
||||
/// as distinct from <c>DriverHostActorArtifactCacheTests</c>'s synchronously-throwing fake,
|
||||
/// which exercises the other half of the guard.
|
||||
/// </summary>
|
||||
private sealed class AsyncFailingArtifactCache : IDeploymentArtifactCache
|
||||
{
|
||||
public async Task StoreAsync(string clusterId, string deploymentId, string revisionHash,
|
||||
byte[] artifact, CancellationToken ct = default)
|
||||
{
|
||||
await Task.Yield();
|
||||
throw new InvalidOperationException("disk full");
|
||||
}
|
||||
|
||||
public Task<CachedDeploymentArtifact?> GetCurrentAsync(string clusterId, CancellationToken ct = default)
|
||||
=> Task.FromResult<CachedDeploymentArtifact?>(null);
|
||||
|
||||
public Task<CachedDeploymentArtifact?> GetCurrentUnkeyedAsync(CancellationToken ct = default)
|
||||
=> Task.FromResult<CachedDeploymentArtifact?>(null);
|
||||
}
|
||||
}
|
||||
@@ -55,8 +55,30 @@ akka {
|
||||
}
|
||||
}";
|
||||
|
||||
/// <summary>
|
||||
/// The same single-node HOCON at a caller-chosen <c>loglevel</c>.
|
||||
/// </summary>
|
||||
/// <remarks>
|
||||
/// A log event below <c>akka.loglevel</c> is never published to the EventStream at all, so
|
||||
/// neither <c>EventFilter</c> nor an EventStream-subscribed probe can see it. A test whose
|
||||
/// subject IS a log line (e.g. "this Debug line must be emitted exactly once, not in a spin")
|
||||
/// therefore has to raise the level for its own ActorSystem; the default stays
|
||||
/// <c>WARNING</c> so the other 40-odd classes keep their quiet output.
|
||||
/// </remarks>
|
||||
/// <param name="level">An Akka log level — <c>DEBUG</c>, <c>INFO</c>, <c>WARNING</c>, <c>ERROR</c>.</param>
|
||||
/// <returns>The base test HOCON with its <c>loglevel</c> replaced.</returns>
|
||||
protected static string AkkaTestHoconAtLevel(string level) =>
|
||||
AkkaTestHocon.Replace(@"loglevel = ""WARNING""", $@"loglevel = ""{level}""", StringComparison.Ordinal);
|
||||
|
||||
/// <summary>Initializes a new instance of the RuntimeActorTestBase class with Akka test setup.</summary>
|
||||
protected RuntimeActorTestBase() : base(AkkaTestHocon)
|
||||
protected RuntimeActorTestBase() : this(AkkaTestHocon)
|
||||
{
|
||||
}
|
||||
|
||||
/// <summary>Initializes a new instance of the RuntimeActorTestBase class with caller-supplied HOCON.</summary>
|
||||
/// <param name="hocon">The Akka configuration for this class's ActorSystem — usually
|
||||
/// <see cref="AkkaTestHoconAtLevel"/>.</param>
|
||||
protected RuntimeActorTestBase(string hocon) : base(hocon)
|
||||
{
|
||||
var cluster = Akka.Cluster.Cluster.Get(Sys);
|
||||
cluster.Join(cluster.SelfAddress);
|
||||
|
||||
Reference in New Issue
Block a user