From b324b45b557c6563cf73df8a0bf3fa17bcb20db8 Mon Sep 17 00:00:00 2001 From: fanlusky <1730976608@qq.com> Date: Tue, 25 Aug 2026 13:54:33 +0800 Subject: [PATCH] Optimize the logging on both the TSF and Server sides to facilitate issue diagnosis. --- src/Edit/TextEditSink.cpp | 112 +++++++++++++++- src/IME/MetasequoiaIME.cpp | 13 +- src/IME/MetasequoiaIME.h | 15 ++- src/IPC/Ipc.cpp | 210 ++++++++++++++++++++++++++++++ src/IPC/Ipc.h | 23 +++- src/Key/KeyEventSink.cpp | 10 ++ src/Key/KeyHandlerEditSession.cpp | 3 + src/Thread/ThreadMgrEventSink.cpp | 17 +++ 8 files changed, 389 insertions(+), 14 deletions(-) diff --git a/src/Edit/TextEditSink.cpp b/src/Edit/TextEditSink.cpp index 3e712f80..52a8c9f0 100644 --- a/src/Edit/TextEditSink.cpp +++ b/src/Edit/TextEditSink.cpp @@ -2,6 +2,94 @@ #include "Globals.h" #include "MetasequoiaIME.h" #include "Ipc.h" + +bool CMetasequoiaIME::_IsSameComObject(_In_opt_ IUnknown *left, _In_opt_ IUnknown *right) +{ + if (left == nullptr || right == nullptr) + { + return left == right; + } + + IUnknown *leftIdentity = nullptr; + IUnknown *rightIdentity = nullptr; + const HRESULT leftHr = left->QueryInterface(IID_IUnknown, reinterpret_cast(&leftIdentity)); + const HRESULT rightHr = right->QueryInterface(IID_IUnknown, reinterpret_cast(&rightIdentity)); + const bool matches = SUCCEEDED(leftHr) && SUCCEEDED(rightHr) && leftIdentity == rightIdentity; + if (leftIdentity) + { + leftIdentity->Release(); + } + if (rightIdentity) + { + rightIdentity->Release(); + } + return matches; +} + +void CMetasequoiaIME::_DebugCompositionRecovery(_In_z_ const WCHAR *reason, HRESULT hr) const +{ + if (!Global::TsfDiagnosticLogEnabled.load(std::memory_order_relaxed)) + { + return; + } + + WCHAR message[512] = {}; + const WCHAR *processName = + Global::current_process_name.empty() ? L"unknown" : Global::current_process_name.c_str(); + StringCchPrintfW(message, ARRAYSIZE(message), + L"[msime][composition-recovery] reason=%s hr=0x%08lX epoch=%llu focus_token=%llu process=%s\n", + reason, static_cast(hr), + static_cast(_CaptureCompositionEpoch()), + static_cast(_CaptureFocusSessionToken()), processName); + QueueTsfDiagnosticLog(message); +} + +namespace +{ +bool HasActiveComposingProperty(_In_ ITfContext *context, TfEditCookie ecReadOnly, + _In_ ITfComposition *composition, _Out_ HRESULT *result) +{ + *result = E_FAIL; + ITfRange *compositionRange = nullptr; + HRESULT hr = composition->GetRange(&compositionRange); + if (FAILED(hr) || compositionRange == nullptr) + { + *result = FAILED(hr) ? hr : E_FAIL; + return false; + } + + BOOL isEmpty = FALSE; + hr = compositionRange->IsEmpty(ecReadOnly, &isEmpty); + if (SUCCEEDED(hr) && isEmpty) + { + // StartComposition legitimately creates an empty range before the + // first preedit update. There is no covered text on which GetValue + // could return GUID_PROP_COMPOSING yet. + compositionRange->Release(); + *result = S_OK; + return true; + } + + ITfProperty *composingProperty = nullptr; + hr = context->GetProperty(GUID_PROP_COMPOSING, &composingProperty); + if (FAILED(hr) || composingProperty == nullptr) + { + compositionRange->Release(); + *result = FAILED(hr) ? hr : E_FAIL; + return false; + } + + VARIANT value; + VariantInit(&value); + hr = composingProperty->GetValue(ecReadOnly, compositionRange, &value); + const bool active = SUCCEEDED(hr) && value.vt == VT_I4 && value.lVal != 0; + VariantClear(&value); + composingProperty->Release(); + compositionRange->Release(); + *result = hr; + return active; +} +} // namespace //+--------------------------------------------------------------------------- // @@ -25,11 +113,25 @@ STDAPI CMetasequoiaIME::OnEndEdit(__RPC__in_opt ITfContext *pContext, TfEditCook // The caret position is represent as the empty selection range when // there is no selection. // - if (pEditRecord == nullptr) - { - return E_INVALIDARG; - } - if (SUCCEEDED(pEditRecord->GetSelectionStatus(&isSelectionChanged)) && isSelectionChanged) + if (pEditRecord == nullptr) + { + return E_INVALIDARG; + } + if (_IsComposing() && !_localSessionResetPending.load(std::memory_order_acquire)) + { + HRESULT compositionStateHr = S_OK; + const bool ownerMatches = pContext && _pContext && _IsSameComObject(pContext, _pContext); + const bool propertyActive = + ownerMatches && HasActiveComposingProperty(pContext, ecReadOnly, _pComposition, &compositionStateHr); + if (!ownerMatches || !propertyActive) + { + _DebugCompositionRecovery(ownerMatches ? L"composing-property-missing" : L"edit-context-mismatch", + compositionStateHr); + MarkNamedpipeSessionDirtyForOwner(this); + return S_OK; + } + } + if (SUCCEEDED(pEditRecord->GetSelectionStatus(&isSelectionChanged)) && isSelectionChanged) { // If the selection is moved to out side of the current composition, // we terminate the composition. This TextService supports only one diff --git a/src/IME/MetasequoiaIME.cpp b/src/IME/MetasequoiaIME.cpp index f442d36d..9e965078 100644 --- a/src/IME/MetasequoiaIME.cpp +++ b/src/IME/MetasequoiaIME.cpp @@ -90,7 +90,10 @@ bool LaunchServerIfNeeded() const std::wstring serverPath = ReadServerPath(); if (serverPath.empty() || GetFileAttributesW(serverPath.c_str()) == INVALID_FILE_ATTRIBUTES) { - OutputDebugStringW(L"[msime]: Server path is unavailable; cannot revive Server.\n"); + if (Global::TsfDiagnosticLogEnabled.load(std::memory_order_relaxed)) + { + QueueTsfDiagnosticLog(L"[msime]: Server path is unavailable; cannot revive Server."); + } ReleaseMutex(launchMutex); CloseHandle(launchMutex); return false; @@ -1781,7 +1784,8 @@ void CMetasequoiaIME::IpcWorkerThread(CMetasequoiaIME *pIME) buf.msg_type == Global::DataToTsfWorkerThreadMsgType::PairedPunctuationChanged || buf.msg_type == Global::DataToTsfWorkerThreadMsgType::MicrosoftShuangpinChanged || buf.msg_type == Global::DataToTsfWorkerThreadMsgType::InputModeChanged || - buf.msg_type == Global::DataToTsfWorkerThreadMsgType::CapsLockChanged)) + buf.msg_type == Global::DataToTsfWorkerThreadMsgType::CapsLockChanged || + buf.msg_type == Global::DataToTsfWorkerThreadMsgType::TsfDiagnosticLogChanged)) { bool hasTerminator = false; for (const wchar_t ch : buf.data) @@ -1845,6 +1849,7 @@ void CMetasequoiaIME::IpcWorkerThread(CMetasequoiaIME *pIME) buf.msg_type == Global::DataToTsfWorkerThreadMsgType::MicrosoftShuangpinChanged || buf.msg_type == Global::DataToTsfWorkerThreadMsgType::InputModeChanged || buf.msg_type == Global::DataToTsfWorkerThreadMsgType::CapsLockChanged || + buf.msg_type == Global::DataToTsfWorkerThreadMsgType::TsfDiagnosticLogChanged || buf.msg_type == Global::DataToTsfWorkerThreadMsgType::PipeReady || buf.msg_type == Global::DataToTsfWorkerThreadMsgType::FocusSessionReady || buf.msg_type == Global::DataToTsfWorkerThreadMsgType::UpdateVoiceComposition || @@ -1944,6 +1949,10 @@ void CMetasequoiaIME::IpcWorkerThread(CMetasequoiaIME *pIME) PostMessage(ownerWindow, WM_RefreshLanguageBarTheme, 0, 0); } } + else if (buf.msg_type == Global::DataToTsfWorkerThreadMsgType::TsfDiagnosticLogChanged) + { + Global::TsfDiagnosticLogEnabled.store(buf.data[0] == L'1', std::memory_order_relaxed); + } else if (buf.msg_type == Global::DataToTsfWorkerThreadMsgType::CapsLockChanged) { Global::CapsLockEnabled.store(buf.data[0] == L'1', std::memory_order_relaxed); diff --git a/src/IME/MetasequoiaIME.h b/src/IME/MetasequoiaIME.h index 63554551..2c0725f3 100644 --- a/src/IME/MetasequoiaIME.h +++ b/src/IME/MetasequoiaIME.h @@ -226,10 +226,12 @@ class CMetasequoiaIME : public ITfTextInputProcessorEx, // so an old worker/key message cannot commit into the next document. uint64_t _CaptureFocusSessionToken() const; bool _IsFocusSessionCurrent(uint64_t focusToken, _In_opt_ ITfContext *expectedContext = nullptr) const; - uint64_t _CaptureCompositionEpoch() const; - bool _IsCompositionEpochCurrent(uint64_t compositionEpoch) const; - bool _IsCompositionCurrent(_In_opt_ ITfComposition *expectedComposition) const; - bool _IsLocalSessionResetCurrent(UINT resetToken) const; + uint64_t _CaptureCompositionEpoch() const; + bool _IsCompositionEpochCurrent(uint64_t compositionEpoch) const; + bool _IsCompositionCurrent(_In_opt_ ITfComposition *expectedComposition) const; + static bool _IsSameComObject(_In_opt_ IUnknown *left, _In_opt_ IUnknown *right); + void _DebugCompositionRecovery(_In_z_ const WCHAR *reason, HRESULT hr) const; + bool _IsLocalSessionResetCurrent(UINT resetToken) const; void _CompleteLocalSessionReset(UINT resetToken); bool _IsDeferredKeyReplayCurrent(uint64_t replayToken, uint64_t focusGeneration, @@ -321,8 +323,9 @@ class CMetasequoiaIME : public ITfTextInputProcessorEx, UINT modifiersDown = 0; _KEYSTROKE_STATE keyState = {}; GUID preservedKey = {}; - uint64_t focusGeneration = 0; - UINT replayAttempts = 0; + uint64_t focusGeneration = 0; + ULONGLONG queuedAtMs = 0; + UINT replayAttempts = 0; bool preservedApplied = false; }; enum class KeyDownDispatchResult diff --git a/src/IPC/Ipc.cpp b/src/IPC/Ipc.cpp index 4b1cd111..26f6f106 100644 --- a/src/IPC/Ipc.cpp +++ b/src/IPC/Ipc.cpp @@ -1,8 +1,11 @@ #include "Ipc.h" +#include +#include #include #include #include #include +#include #include #include #include @@ -11,6 +14,7 @@ #include "FanyDefines.h" #include "MetasequoiaIME.h" #include +#include "../Utils/PerfTimer.h" static thread_local HANDLE hMapFile = nullptr; @@ -46,6 +50,140 @@ static const int ServerDtPipeDataSize = 512; namespace { constexpr size_t MaxPendingReplyCount = 64; +constexpr size_t MaxDiagnosticRecordCount = 256; +constexpr size_t MaxDiagnosticQueuedUnits = 32 * 1024; +constexpr DWORD DiagnosticFlushDelayMs = 250; +std::mutex diagnosticLogMutex; +std::deque diagnosticLogRecords; +size_t diagnosticLogQueuedUnits = 0; +uint32_t diagnosticLogDroppedCount = 0; +bool diagnosticFlushScheduled = false; + +void CALLBACK FlushTsfDiagnosticLogs(PTP_CALLBACK_INSTANCE, PVOID); + +void ScheduleDiagnosticFlushLocked() +{ + if (diagnosticFlushScheduled) + { + return; + } + diagnosticFlushScheduled = true; + DllAddRef(); + if (!TrySubmitThreadpoolCallback(FlushTsfDiagnosticLogs, nullptr, nullptr)) + { + diagnosticFlushScheduled = false; + DllRelease(); + } +} + +bool SendDiagnosticBatch(const FanyImeTsfDiagnosticBatchHeader &header, const std::wstring &payload) +{ + HANDLE pipe = INVALID_HANDLE_VALUE; + for (int attempt = 0; attempt < 2; ++attempt) + { + pipe = CreateFileW(FANY_IME_TSF_DIAGNOSTIC_NAMED_PIPE, GENERIC_WRITE, 0, nullptr, OPEN_EXISTING, 0, nullptr); + if (pipe != INVALID_HANDLE_VALUE) + { + break; + } + if (GetLastError() != ERROR_PIPE_BUSY || !WaitNamedPipeW(FANY_IME_TSF_DIAGNOSTIC_NAMED_PIPE, 20)) + { + break; + } + } + if (pipe == INVALID_HANDLE_VALUE) + { + return false; + } + + const size_t payloadBytes = payload.size() * sizeof(wchar_t); + std::vector frame(sizeof(header) + payloadBytes); + memcpy(frame.data(), &header, sizeof(header)); + if (payloadBytes != 0) + { + memcpy(frame.data() + sizeof(header), payload.data(), payloadBytes); + } + DWORD bytesWritten = 0; + const BOOL writeResult = WriteFile(pipe, frame.data(), static_cast(frame.size()), &bytesWritten, nullptr); + CloseHandle(pipe); + return writeResult && bytesWritten == frame.size(); +} + +void CALLBACK FlushTsfDiagnosticLogs(PTP_CALLBACK_INSTANCE, PVOID) +{ + Sleep(DiagnosticFlushDelayMs); + + FanyImeTsfDiagnosticBatchHeader header; + std::vector batchRecords; + batchRecords.reserve(MaxDiagnosticRecordCount); + size_t batchUnits = 0; + std::wstring payload; + bool loggingDisabled = false; + { + std::lock_guard lock(diagnosticLogMutex); + if (!Global::TsfDiagnosticLogEnabled.load(std::memory_order_relaxed)) + { + diagnosticLogRecords.clear(); + diagnosticLogQueuedUnits = 0; + diagnosticLogDroppedCount = 0; + diagnosticFlushScheduled = false; + loggingDisabled = true; + } + else + { + const size_t maxPayloadUnits = + (FANY_IME_TSF_DIAGNOSTIC_MAX_FRAME_BYTES - sizeof(FanyImeTsfDiagnosticBatchHeader)) / + sizeof(wchar_t); + while (!diagnosticLogRecords.empty()) + { + const std::wstring &record = diagnosticLogRecords.front(); + if (!batchRecords.empty() && batchUnits + record.size() > maxPayloadUnits) + { + break; + } + batchUnits += (std::min)(record.size(), maxPayloadUnits - batchUnits); + diagnosticLogQueuedUnits -= record.size(); + batchRecords.push_back(std::move(diagnosticLogRecords.front())); + diagnosticLogRecords.pop_front(); + ++header.record_count; + if (batchUnits == maxPayloadUnits) + { + break; + } + } + header.dropped_count = diagnosticLogDroppedCount; + header.source_process_id = GetCurrentProcessId(); + diagnosticLogDroppedCount = 0; + } + } + if (loggingDisabled) + { + DllRelease(); + return; + } + + payload.reserve(batchUnits); + for (const std::wstring &record : batchRecords) + { + payload.append(record.data(), (std::min)(record.size(), batchUnits - payload.size())); + } + header.payload_bytes = static_cast(payload.size() * sizeof(wchar_t)); + + const bool sent = header.record_count != 0 && SendDiagnosticBatch(header, payload); + { + std::lock_guard lock(diagnosticLogMutex); + if (!sent) + { + diagnosticLogDroppedCount += header.record_count; + } + diagnosticFlushScheduled = false; + if (!diagnosticLogRecords.empty()) + { + ScheduleDiagnosticFlushLocked(); + } + } + DllRelease(); +} // These tokens fence messages that can outlive a CMetasequoiaIME instance. // Per-instance counters can collide after HWND/HANDLE reuse during a rapid // deactivate/reactivate cycle. @@ -846,6 +984,68 @@ KeyEventSendResult SendKeyEventToUIProcess(uint64_t *requestId) return SendKeyEventToUIProcessViaNamedPipe(requestId); } +void DebugTsfKeyLatency(const wchar_t *stage, uint64_t requestId, double elapsedMs, HRESULT result) +{ + constexpr double kSlowStageThresholdMs = 8.0; + if (!Global::TsfDiagnosticLogEnabled.load(std::memory_order_relaxed) || + (elapsedMs < kSlowStageThresholdMs && SUCCEEDED(result))) + { + return; + } + + const std::wstring message = fmt::format( + L"[msime][key-latency] side=tsf stage={} request={} elapsed_ms={:.3f} result=0x{:08X} process={}\n", + stage, requestId, elapsedMs, static_cast(result), + Global::current_process_name.empty() ? L"unknown" : Global::current_process_name); + QueueTsfDiagnosticLog(message); +} + +void QueueTsfDiagnosticLog(const std::wstring &line) +{ + if (!Global::TsfDiagnosticLogEnabled.load(std::memory_order_relaxed)) + { + return; + } + + std::wstring sanitized = line; + for (wchar_t &ch : sanitized) + { + if (ch == L'\r' || ch == L'\n') + { + ch = L' '; + } + } + while (!sanitized.empty() && sanitized.back() == L' ') + { + sanitized.pop_back(); + } + constexpr size_t MaxSingleRecordUnits = 1024; + if (sanitized.size() > MaxSingleRecordUnits) + { + sanitized.resize(MaxSingleRecordUnits); + } + SYSTEMTIME sourceTime{}; + GetLocalTime(&sourceTime); + sanitized = fmt::format( + L"[tsf source={:04}-{:02}-{:02} {:02}:{:02}:{:02}.{:03} p{}:t{} tick={}] {}\n", + sourceTime.wYear, sourceTime.wMonth, sourceTime.wDay, sourceTime.wHour, sourceTime.wMinute, + sourceTime.wSecond, sourceTime.wMilliseconds, GetCurrentProcessId(), GetCurrentThreadId(), GetTickCount64(), + sanitized); + + std::lock_guard lock(diagnosticLogMutex); + while (!diagnosticLogRecords.empty() && + (diagnosticLogRecords.size() >= MaxDiagnosticRecordCount || + diagnosticLogQueuedUnits + sanitized.size() > MaxDiagnosticQueuedUnits)) + { + diagnosticLogQueuedUnits -= diagnosticLogRecords.front().size(); + diagnosticLogRecords.pop_front(); + ++diagnosticLogDroppedCount; + } + diagnosticLogQueuedUnits += sanitized.size(); + diagnosticLogRecords.push_back(std::move(sanitized)); + ScheduleDiagnosticFlushLocked(); +} + int SendHideCandidateWndEventToUIProcess() { return SendHideCandidateWndEventToUIProcessViaNamedPipe(); @@ -997,6 +1197,7 @@ struct FanyImeNamedpipeDataToTsf *TryReadDataFromServerPipeWithTimeout(uint64_t bool abortTransportOnTimeout) { constexpr int timeoutMs = 50; + PerfTimer replyWaitTimer; auto transportUnavailable = []() { transportUnavailableReply = {}; @@ -1052,6 +1253,8 @@ struct FanyImeNamedpipeDataToTsf *TryReadDataFromServerPipeWithTimeout(uint64_t hFromServerPipe, &namedpipeDataFromServer, sizeof(namedpipeDataFromServer), remainingMs, bytesRead); if (readResult == OverlappedReadResult::TimedOut) { + DebugTsfKeyLatency(L"reply-wait-timeout", expectedRequestId, replyWaitTimer.ElapsedMs(), + HRESULT_FROM_WIN32(ERROR_TIMEOUT)); if (!abortTransportOnTimeout) { return softMiss(expectedRequestId); @@ -1062,6 +1265,7 @@ struct FanyImeNamedpipeDataToTsf *TryReadDataFromServerPipeWithTimeout(uint64_t } if (readResult == OverlappedReadResult::Failed) { + DebugTsfKeyLatency(L"reply-read-failed", expectedRequestId, replyWaitTimer.ElapsedMs(), E_FAIL); ClosePipeHandleIfValid(hFromServerPipe); pendingReplies.clear(); unsolicitedReplies.clear(); @@ -1070,6 +1274,7 @@ struct FanyImeNamedpipeDataToTsf *TryReadDataFromServerPipeWithTimeout(uint64_t } if (bytesRead != sizeof(namedpipeDataFromServer)) { + DebugTsfKeyLatency(L"reply-size-invalid", expectedRequestId, replyWaitTimer.ElapsedMs(), E_FAIL); ClosePipeHandleIfValid(hFromServerPipe); pendingReplies.clear(); unsolicitedReplies.clear(); @@ -1078,6 +1283,7 @@ struct FanyImeNamedpipeDataToTsf *TryReadDataFromServerPipeWithTimeout(uint64_t } if (!IsValidServerReply(namedpipeDataFromServer)) { + DebugTsfKeyLatency(L"reply-frame-invalid", expectedRequestId, replyWaitTimer.ElapsedMs(), E_FAIL); ClosePipeHandleIfValid(hFromServerPipe); pendingReplies.clear(); unsolicitedReplies.clear(); @@ -1090,6 +1296,7 @@ struct FanyImeNamedpipeDataToTsf *TryReadDataFromServerPipeWithTimeout(uint64_t if (namedpipeDataFromServer.msg_type != Global::DataFromServerMsgType::PipeReady && namedpipeDataFromServer.request_id == expectedRequestId) { + DebugTsfKeyLatency(L"reply-wait", expectedRequestId, replyWaitTimer.ElapsedMs(), S_OK); return &namedpipeDataFromServer; } @@ -1109,8 +1316,11 @@ struct FanyImeNamedpipeDataToTsf *TryReadDataFromServerPipeWithTimeout(uint64_t // a broken transport and schedule a tokenized reset plus local cancel. if (!abortTransportOnTimeout) { + DebugTsfKeyLatency(L"reply-soft-miss", expectedRequestId, replyWaitTimer.ElapsedMs(), S_FALSE); return softMiss(expectedRequestId); } + DebugTsfKeyLatency(L"reply-id-timeout", expectedRequestId, replyWaitTimer.ElapsedMs(), + HRESULT_FROM_WIN32(ERROR_TIMEOUT)); ClosePipeHandleIfValid(hFromServerPipe); RequestNamedpipeReconnect(); return transportUnavailable(); diff --git a/src/IPC/Ipc.h b/src/IPC/Ipc.h index 6979500f..1c42e4da 100644 --- a/src/IPC/Ipc.h +++ b/src/IPC/Ipc.h @@ -14,6 +14,10 @@ inline const wchar_t *FANY_IME_NAMED_PIPE = L"\\\\.\\pipe\\FanyImeNamedPipe"; inline const wchar_t *FANY_IME_TO_TSF_NAMED_PIPE = L"\\\\.\\pipe\\FanyImeToTsfNamedPipe"; inline const wchar_t *FANY_IME_TO_TSF_WORKER_THREAD_NAMED_PIPE = L"\\\\.\\pipe\\FanyImeToTsfWorkerThreadNamedPipe"; inline const wchar_t *FANY_IME_AUX_NAMED_PIPE = L"\\\\.\\pipe\\FanyImeAuxNamedPipe"; +inline const wchar_t *FANY_IME_TSF_DIAGNOSTIC_NAMED_PIPE = L"\\\\.\\pipe\\FanyImeTsfDiagnosticNamedPipe"; +inline constexpr uint32_t FANY_IME_TSF_DIAGNOSTIC_MAGIC = 0x474F4C54; // "TLOG" +inline constexpr uint32_t FANY_IME_TSF_DIAGNOSTIC_VERSION = 1; +inline constexpr size_t FANY_IME_TSF_DIAGNOSTIC_MAX_FRAME_BYTES = 16 * 1024; inline constexpr uint64_t FANY_IME_UNSOLICITED_REQUEST_ID = 0; inline constexpr uint64_t FANY_IME_NO_REQUEST_ID = UINT64_MAX; @@ -142,6 +146,17 @@ struct FanyImeNamedpipeDataToTsfWorkerThread wchar_t data[200]; }; +struct FanyImeTsfDiagnosticBatchHeader +{ + uint32_t magic = FANY_IME_TSF_DIAGNOSTIC_MAGIC; + uint32_t version = FANY_IME_TSF_DIAGNOSTIC_VERSION; + uint32_t header_size = 28; + uint32_t payload_bytes = 0; + uint32_t record_count = 0; + uint32_t dropped_count = 0; + uint32_t source_process_id = 0; +}; + static_assert(sizeof(WCHAR) == 2, "The IPC ABI requires 16-bit WCHAR."); static_assert(offsetof(FanyImeNamedpipeData, client_id) == 8); static_assert(offsetof(FanyImeNamedpipeData, request_id) == 16); @@ -153,6 +168,7 @@ static_assert(offsetof(FanyImeNamedpipeDataToTsf, candidate_string) == 16); static_assert(sizeof(FanyImeNamedpipeDataToTsf) == 416); static_assert(sizeof(FanyImePipeHello) == 16); static_assert(sizeof(FanyImeNamedpipeDataToTsfWorkerThread) == 404); +static_assert(sizeof(FanyImeTsfDiagnosticBatchHeader) == 28); enum class KeyEventSendResult { @@ -200,6 +216,8 @@ int WriteDataToSharedMemory( // UINT write_flag // ); KeyEventSendResult SendKeyEventToUIProcess(_Out_opt_ uint64_t *requestId = nullptr); +void DebugTsfKeyLatency(_In_z_ const wchar_t *stage, uint64_t requestId, double elapsedMs, HRESULT result); +void QueueTsfDiagnosticLog(const std::wstring &line); int SendHideCandidateWndEventToUIProcess(); int SendShowCandidateWndEventToUIProcess(); int SendMoveCandidateWndEventToUIProcess(); @@ -335,7 +353,9 @@ constexpr UINT CommitVoiceComposition = 17; constexpr UINT InputModeChanged = 18; // Payload "1" when Caps Lock is on. Server is the source of truth. constexpr UINT CapsLockChanged = 19; -constexpr UINT MaxKnown = CapsLockChanged; +// Enables buffered TSF diagnostics sent to Server. Payload "0"/"1". +constexpr UINT TsfDiagnosticLogChanged = 20; +constexpr UINT MaxKnown = TsfDiagnosticLogChanged; } // namespace DataToTsfWorkerThreadMsgType inline std::atomic_bool PagingCommaPeriodEnabled{false}; @@ -348,6 +368,7 @@ inline std::atomic_bool PairedPunctuationEnabled{true}; inline std::atomic_bool MicrosoftShuangpinEnabled{false}; inline std::atomic_bool JapaneseInputModeEnabled{false}; inline std::atomic_bool CapsLockEnabled{false}; +inline std::atomic_bool TsfDiagnosticLogEnabled{false}; inline thread_local bool g_connected = false; } // namespace Global diff --git a/src/Key/KeyEventSink.cpp b/src/Key/KeyEventSink.cpp index 993988b4..d7e4ba9d 100644 --- a/src/Key/KeyEventSink.cpp +++ b/src/Key/KeyEventSink.cpp @@ -1485,6 +1485,7 @@ bool CMetasequoiaIME::_QueueDeferredKeyDown(_In_ ITfContext *pContext, WPARAM wP key.modifiersDown = modifiersDown; key.keyState = keyState; key.focusGeneration = _deferredKeyFocusGeneration; + key.queuedAtMs = GetTickCount64(); _deferredKeyDowns.push_back(key); if (key.kind == DeferredKeyDown::Kind::KeyDown) { @@ -1512,6 +1513,7 @@ bool CMetasequoiaIME::_QueueDeferredPreservedKey(_In_ ITfContext *pContext, key.context = pContext; key.preservedKey = preservedKey; key.focusGeneration = _deferredKeyFocusGeneration; + key.queuedAtMs = GetTickCount64(); _deferredKeyDowns.push_back(key); _ApplyDeferredPreservedKeyProjection(preservedKey); _ScheduleDeferredKeyDownDrain(); @@ -1797,6 +1799,11 @@ void CMetasequoiaIME::_DrainOneDeferredKeyDown() } while (_deferredKeyReplayToken == 0); DeferredKeyDown &key = _deferredKeyInFlight; + if (key.queuedAtMs != 0) + { + DebugTsfKeyLatency(L"deferred-key-queue", 0, + static_cast(GetTickCount64() - key.queuedAtMs), S_OK); + } ++key.replayAttempts; const uint64_t replayToken = _deferredKeyReplayToken; const uint64_t focusToken = _CaptureFocusSessionToken(); @@ -1931,6 +1938,7 @@ STDAPI CMetasequoiaIME::OnKeyDown(ITfContext *pContext, WPARAM wParam, LPARAM lP const uint64_t focusGeneration = _deferredKeyFocusGeneration; (void)_DispatchKeyDown(pContext, wParam, lParam, pIsEaten, nullptr, nullptr, nullptr, true, focusGeneration); + DebugTsfKeyLatency(L"on-key-down", 0, onKeyDownTimer.ElapsedMs(), S_OK); return S_OK; } @@ -2146,6 +2154,8 @@ CMetasequoiaIME::KeyDownDispatchResult CMetasequoiaIME::_DispatchKeyDown( PerfTimer sendKeyEventTimer; const KeyEventSendResult sendResult = SendKeyEventToUIProcess(&requestId); + DebugTsfKeyLatency(L"main-pipe-send", requestId, sendKeyEventTimer.ElapsedMs(), + sendResult == KeyEventSendResult::Sent ? S_OK : E_FAIL); if (sendResult != KeyEventSendResult::Sent) { if (!canDefer) diff --git a/src/Key/KeyHandlerEditSession.cpp b/src/Key/KeyHandlerEditSession.cpp index 7ee7207d..410f3476 100644 --- a/src/Key/KeyHandlerEditSession.cpp +++ b/src/Key/KeyHandlerEditSession.cpp @@ -4,6 +4,7 @@ #include "MetasequoiaIME.h" #include "CompositionProcessorEngine.h" #include "KeyStateCategory.h" +#include "Ipc.h" #include "fmt/xchar.h" #include "../Utils/PerfTimer.h" @@ -75,6 +76,7 @@ STDAPI CKeyHandlerEditSession::DoEditSession(TfEditCookie ec) QueryPerformanceCounter(&nowQpc); double queueElapsedMs = static_cast(nowQpc.QuadPart - _requestStartQpc.QuadPart) * 1000.0 / static_cast(freq.QuadPart); + DebugTsfKeyLatency(L"edit-session-queue", _requestId, queueElapsedMs, S_OK); CKeyStateCategoryFactory *pKeyStateCategoryFactory = CKeyStateCategoryFactory::Instance(); CKeyStateCategory *pKeyStateCategory = pKeyStateCategoryFactory @@ -100,5 +102,6 @@ STDAPI CKeyHandlerEditSession::DoEditSession(TfEditCookie ec) { _pTextService->_CompleteLocalSessionReset(_localResetToken); } + DebugTsfKeyLatency(L"edit-session-body", _requestId, doEditSessionTimer.ElapsedMs(), hResult); return hResult; } diff --git a/src/Thread/ThreadMgrEventSink.cpp b/src/Thread/ThreadMgrEventSink.cpp index 95435c6a..90994b6b 100644 --- a/src/Thread/ThreadMgrEventSink.cpp +++ b/src/Thread/ThreadMgrEventSink.cpp @@ -49,6 +49,23 @@ STDAPI CMetasequoiaIME::OnSetFocus(_In_ ITfDocumentMgr *pDocMgrFocus, _In_ ITfDo return S_OK; } + if (pDocMgrFocus && _pContext && _IsComposing() && + !_localSessionResetPending.load(std::memory_order_acquire)) + { + ITfDocumentMgr *compositionDocumentMgr = nullptr; + const HRESULT ownerHr = _pContext->GetDocumentMgr(&compositionDocumentMgr); + if (FAILED(ownerHr) || compositionDocumentMgr == nullptr || + !_IsSameComObject(compositionDocumentMgr, pDocMgrFocus)) + { + _DebugCompositionRecovery(L"focus-document-mismatch", ownerHr); + MarkNamedpipeSessionDirtyForOwner(this); + } + if (compositionDocumentMgr) + { + compositionDocumentMgr->Release(); + } + } + // Chrome / Twitter contenteditable swaps ITfDocumentMgr on almost every // edit (digit passthrough, Backspace, etc.): both pointers are non-null and // unequal. Resetting smart-punctuation there drops a just-armed ASCII