Files
HellionChat/HellionChat/MessageManager.cs
T
JonKazama-Hellion 6051e49307 chore(profiling): instrument plugin-load hot paths (v1.4.9 R3)
Bump AutoTranslate-warmup and FilterAllTabs log-level from Debug to
Information so the xllog tail surfaces them without a Debug filter.
Wrap MessageStore.Connect and MessageStore.Migrate in Stopwatches so
the SQLite open and migration-chain costs are visible too.

Sub-Task 3.4 Befund on v1.4.8-baseline (4 reloads, medians):
- MessageStore.Connect: 50.5 ms
- MessageStore.Migrate:    2 ms
- MessageManager.FilterAllTabs: 68.5 ms
- AutoTranslate warmup:  108 ms
- UiBuilder HITCH:       108.9 ms

Outcome D — none of the three dominates the 200 ms threshold. The
ChatTwo "300 ms" comment for AutoTranslate is falsified at ~108 ms;
SQLite is not the bottleneck (52.5 ms total); FilterAllTabs runs on
the worker thread and only competes for CPU slots. The HITCH is left
unexplained by these probes, which keeps Hypothesis c (multi-window
WindowSystem.Draw initial pass) as the main R2 suspect to be
validated by the R1 lazy-window refactor.

Logs stay in as belt-and-suspenders for future plugin-load
regressions.
2026-05-14 23:33:56 +02:00

401 lines
13 KiB
C#

using System.Collections.Concurrent;
using System.Diagnostics;
using System.Text;
using Dalamud.Game.Chat;
using Dalamud.Game.Text;
using Dalamud.Game.Text.SeStringHandling;
using Dalamud.Hooking;
using Dalamud.Interface.ImGuiNotification;
using Dalamud.Plugin.Services;
using FFXIVClientStructs.FFXIV.Client.UI.Misc;
using HellionChat.Code;
using HellionChat.Resources;
using HellionChat.Util;
using Lumina.Text.Expressions;
using Lumina.Text.Payloads;
using Lumina.Text.ReadOnly;
namespace HellionChat;
internal class MessageManager : IAsyncDisposable
{
internal const int MessageDisplayLimit = 10_000;
private Plugin Plugin { get; }
internal MessageStore Store { get; }
private Dictionary<ChatType, NameFormatting> Formats { get; } = [];
private ulong LastContentId { get; set; }
// PendingSync (main thread) → PendingAsync (worker thread); LinkedList for O(1) Last access
private LinkedList<PendingMessage> PendingSync { get; } = [];
private ConcurrentQueue<PendingMessage> PendingAsync { get; } = [];
private readonly Thread PendingMessageThread;
private readonly CancellationTokenSource PendingThreadCancellationToken = new();
private Hook<RaptureLogModule.Delegates.AddMsgSourceEntry>? ContentIdResolverHook { get; init; }
internal ulong CurrentContentId
{
get
{
var contentId = Plugin.PlayerState.ContentId;
return contentId == 0 ? LastContentId : contentId;
}
}
// Auto-Tell-Tabs hook: fires after a message is processed and stored, allowing
// AutoTellTabsService to spawn or refresh temp tabs without coupling.
public event Action<Message>? MessageProcessed;
internal unsafe MessageManager(Plugin plugin)
{
Plugin = plugin;
Store = new MessageStore(DatabasePath(), Plugin.PlatformUtil, Plugin.LogProxy);
PendingMessageThread = new Thread(() =>
ProcessPendingMessages(PendingThreadCancellationToken.Token)
)
{
IsBackground = true,
};
PendingMessageThread.Start();
ContentIdResolverHook =
Plugin.GameInteropProvider.HookFromAddress<RaptureLogModule.Delegates.AddMsgSourceEntry>(
RaptureLogModule.MemberFunctionPointers.AddMsgSourceEntry,
ContentIdResolver
);
ContentIdResolverHook.Enable();
Plugin.ChatGui.ChatMessageUnhandled += ChatMessage;
Plugin.Framework.Update += OnFrameworkUpdate;
Plugin.ClientState.Logout += Logout;
}
public async ValueTask DisposeAsync()
{
ContentIdResolverHook?.Dispose();
Plugin.ClientState.Logout -= Logout;
Plugin.Framework.Update -= OnFrameworkUpdate;
Plugin.ChatGui.ChatMessageUnhandled -= ChatMessage;
await PendingThreadCancellationToken.CancelAsync();
// 10s cooperative window; Thread.Abort is gone since .NET 5, so a
// stuck worker has to ride out the next AppDomain unload.
var deadline = TimeSpan.FromSeconds(10);
var stopwatch = Stopwatch.StartNew();
while (stopwatch.Elapsed < deadline && PendingMessageThread.IsAlive)
await Task.Delay(100);
if (PendingMessageThread.IsAlive)
Plugin.LogProxy.Warning(
"PendingMessageThread did not observe cancellation within 10s. "
+ "Worker remains on background thread; next plugin reload releases it."
);
PendingThreadCancellationToken.Dispose();
Store.Dispose();
}
internal static string DatabasePath()
{
return Path.Join(Plugin.Interface.ConfigDirectory.FullName, "chat-sqlite.db");
}
private void Logout(int _, int __)
{
LastContentId = 0;
}
private void OnFrameworkUpdate(IFramework framework)
{
var contentId = Plugin.PlayerState.ContentId;
if (contentId != 0)
LastContentId = contentId;
// Drain the PendingSync queue into the PendingAsync queue.
while (PendingSync.First is { } first)
{
PendingSync.RemoveFirst();
PendingAsync.Enqueue(first.Value);
}
}
private void ProcessPendingMessages(CancellationToken token)
{
while (!token.IsCancellationRequested)
{
if (PendingAsync.TryDequeue(out var pendingMessage))
{
try
{
ProcessMessage(pendingMessage);
}
catch (Exception ex)
{
Plugin.LogProxy.Error(ex, "Error processing pending message");
}
}
else
{
Thread.Sleep(1);
}
}
}
internal void ClearAllTabs()
{
// TempTabs are session-only (not persisted); exclude them to preserve Tell history
foreach (var tab in Plugin.Config.Tabs.Where(t => !t.IsTempTab))
tab.Clear();
}
internal void FilterAllTabs()
{
DateTimeOffset? since = null;
if (!Plugin.Config.FilterIncludePreviousSessions)
since = Plugin.GameStarted;
using var messages = Store.GetMostRecentMessages(CurrentContentId, since);
// TempTabs are excluded; they maintain live state from AutoTellTabsService
var pendingTabs = Plugin
.Config.Tabs.Where(t => !t.IsTempTab)
.Select(tab => (tab, new List<Message>()))
.ToList();
foreach (var message in messages)
foreach (var (_, pendingMessages) in pendingTabs.Where(ptab => ptab.Item1.Matches(message)))
pendingMessages.Add(message);
// Apply messages to chat log all at once.
foreach (var (tab, pendingMessages) in pendingTabs)
tab.Messages.AddSortPrune(pendingMessages, MessageDisplayLimit);
if (!messages.DidError)
return;
WrapperUtil.AddNotification(Language.LoadMessages_Error, NotificationType.Error);
// Mark failed messages as deleted to prevent retry attempts
var failedIds = messages.FailedMessageIds();
Plugin.LogProxy.Info(
$"Marking {failedIds.Count} messages as deleted due to parse failures"
);
foreach (var msgId in messages.FailedMessageIds())
{
Plugin.LogProxy.Debug($"Marking message '{msgId}' as deleted due to parse failure");
Store.DeleteMessage(msgId);
}
}
internal void FilterAllTabsAsync()
{
Task.Run(() =>
{
var stopwatch = Stopwatch.StartNew();
try
{
FilterAllTabs();
}
catch (Exception ex)
{
Plugin.LogProxy.Error(ex, "Error in FilterAllTabs");
}
// v1.4.9 R3 profiling: Information so the xllog tail surfaces this
// without a Debug filter. Belt-and-suspenders for future plugin-load
// regressions; remains in place after Sub-Task 3.4 Befund.
Plugin.LogProxy.Information($"FilterAllTabs took {stopwatch.ElapsedMilliseconds}ms");
});
}
public (SeString? Sender, SeString? Message) LastMessage = (null, null);
private void ChatMessage(IChatMessage message)
{
LastMessage = (message.Sender, message.Message);
var pendingMessage = new PendingMessage
{
ContentId = 0,
AccountId = 0,
LogKind = message.LogKind,
SourceKind = message.SourceKind,
TargetKind = message.TargetKind,
Sender = message.Sender,
Content = message.Message,
};
// Update colour codes.
GlobalParametersCache.Refresh();
// Delay to next tick to get content ID from ContentIdResolver hook
PendingSync.AddLast(pendingMessage);
}
private unsafe void ContentIdResolver(
RaptureLogModule* agent,
ulong contentId,
ulong accountId,
int messageIndex,
ushort worldId,
ushort chatType
)
{
try
{
ContentIdResolverHook?.Original(
agent,
contentId,
accountId,
messageIndex,
worldId,
chatType
);
if (PendingSync.Last is not { } last)
return;
last.Value.ContentId = contentId;
last.Value.AccountId = accountId;
}
catch (Exception ex)
{
Plugin.LogProxy.Error(ex, "Error in ContentIdResolver");
}
}
private void ProcessMessage(PendingMessage pendingMessage)
{
var chatCode = new ChatCode(
pendingMessage.LogKind,
pendingMessage.SourceKind,
pendingMessage.TargetKind
);
NameFormatting? formatting = null;
if (pendingMessage.Sender.Payloads.Count > 0)
formatting = FormatFor(chatCode.Type);
var senderChunks = new List<Chunk>();
if (formatting is { IsPresent: true })
{
senderChunks.Add(
new TextChunk(ChunkSource.None, null, formatting.Before)
{
FallbackColour = chatCode.Type,
}
);
senderChunks.AddRange(
ChunkUtil.ToChunks(pendingMessage.Sender, ChunkSource.Sender, chatCode.Type)
);
senderChunks.Add(
new TextChunk(ChunkSource.None, null, formatting.After)
{
FallbackColour = chatCode.Type,
}
);
}
var contentChunks = ChunkUtil
.ToChunks(pendingMessage.Content, ChunkSource.Content, chatCode.Type)
.ToList();
var message = new Message(
CurrentContentId,
pendingMessage.ContentId,
pendingMessage.AccountId,
chatCode,
senderChunks,
contentChunks,
pendingMessage.Sender,
pendingMessage.Content
);
if (Plugin.Config.DatabaseBattleMessages || !message.Code.IsBattle())
Store.UpsertMessage(message);
var currentMatches = Plugin.CurrentTab.Matches(message);
foreach (var tab in Plugin.Config.Tabs)
{
var unread = !(
tab.UnreadMode == UnreadMode.Unseen && Plugin.CurrentTab != tab && currentMatches
);
if (tab.Matches(message))
tab.AddMessage(message, unread);
}
MessageProcessed?.Invoke(message);
}
internal class NameFormatting
{
internal string Before { get; private set; } = string.Empty;
internal string After { get; private set; } = string.Empty;
internal bool IsPresent { get; private set; } = true;
internal static NameFormatting Empty()
{
return new NameFormatting { IsPresent = false };
}
internal static NameFormatting Of(string before, string after)
{
return new NameFormatting { Before = before, After = after };
}
}
private NameFormatting FormatFor(ChatType type)
{
if (Formats.TryGetValue(type, out var cached))
return cached;
var formats = Sheets.LogKindSheet.GetRow((uint)type).Format.ToList();
static bool IsStringParam(ReadOnlySePayload payload, byte num)
{
if (payload.MacroCode != MacroCode.String)
return false;
return payload.TryGetExpression(out var expr1)
&& expr1.TryGetParameterExpression(out var expressionType, out var operand)
&& expressionType == (byte)ExpressionType.LocalString
&& operand.TryGetInt(out var lstrIndex)
&& lstrIndex == num;
}
var firstStringParam = formats.FindIndex(payload => IsStringParam(payload, 1));
var secondStringParam = formats.FindIndex(payload => IsStringParam(payload, 2));
if (firstStringParam == -1 || secondStringParam == -1)
return NameFormatting.Empty();
var before = formats
.GetRange(0, firstStringParam)
.Where(payload => payload.Type == ReadOnlySePayloadType.Text)
.Select(text => Encoding.UTF8.GetString(text.Body.Span));
var after = formats
.GetRange(firstStringParam + 1, secondStringParam - firstStringParam)
.Where(payload => payload.Type == ReadOnlySePayloadType.Text)
.Select(text => Encoding.UTF8.GetString(text.Body.Span));
var nameFormatting = NameFormatting.Of(string.Join("", before), string.Join("", after));
Formats[type] = nameFormatting;
return nameFormatting;
}
private class PendingMessage
{
public ulong ContentId; // 0 if unknown
public ulong AccountId; // 0 if unknown
public XivChatType LogKind;
public XivChatRelationKind SourceKind;
public XivChatRelationKind TargetKind;
public required SeString Sender;
public required SeString Content;
}
}