diff --git a/client/transports/LGMP/input.c b/client/transports/LGMP/input.c index 2384555d..d2b8cfe7 100644 --- a/client/transports/LGMP/input.c +++ b/client/transports/LGMP/input.c @@ -30,6 +30,7 @@ #include "common/thread.h" #include "common/time.h" +#include #include #include #include @@ -44,6 +45,7 @@ #define INPUT_RELEASE_TIMEOUT_US 50000 #define INPUT_WORKER_IDLE_MS 10 #define INPUT_WORKER_RETRY_MS 1 +#define INPUT_STATS_INTERVAL_US 5000000 #define INPUT_MAX_SPLIT_REPORTS 4 #define INPUT_MOUSE_DELTA_MIN (INT16_MIN * INPUT_MAX_SPLIT_REPORTS) #define INPUT_MOUSE_DELTA_MAX (INT16_MAX * INPUT_MAX_SPLIT_REPORTS) @@ -61,6 +63,42 @@ struct LGMPInputPending bool pureMotion; }; +struct LGMPInputCounters +{ + uint64_t immediateSends; + uint64_t deferredSends; + uint64_t localEnqueues; + uint64_t initialBusy; + uint64_t initialFull; + uint64_t retryBusy; + uint64_t retryFull; + uint64_t relativeCoalesces; + uint64_t absoluteCoalesces; + uint64_t reservedRejects; + uint64_t motionEvictions; + uint64_t discreteOverflowFailures; + uint64_t discreteOverflowResets; + uint64_t claims; + uint64_t releases; + uint64_t keepalives; + uint64_t terminalFailures; + uint64_t ackTotal; + uint64_t ackMax; + uint64_t ackSamples; + unsigned pendingHighWater; +}; + +struct LGMPInputStats +{ + struct LGMPInputCounters counters; + uint64_t lastReport; + uint64_t nextProbe; + uint64_t probeStart; + uint32_t probeSerial; + bool probeOutstanding; + bool probeDue; +}; + struct LGMPInput { PLGMPClient client; @@ -104,6 +142,8 @@ struct LGMPInput LG_InputStatusFn statusCallback; void * statusOpaque; + + struct LGMPInputStats stats; }; static void buildKeyboardPayload(const LGMPInput * input, @@ -162,10 +202,16 @@ static void published(LGMPInput * input, { case KVMFR_INPUT_MESSAGE_CLAIM: input->publishedClaimed = true; + ++input->stats.counters.claims; break; case KVMFR_INPUT_MESSAGE_RELEASE: input->publishedClaimed = false; + ++input->stats.counters.releases; + break; + + case KVMFR_INPUT_MESSAGE_KEEPALIVE: + ++input->stats.counters.keepalives; break; } } @@ -173,27 +219,76 @@ static void published(LGMPInput * input, static void connectionFailed(LGMPInput * input, LGMP_STATUS status) { if (input->connected) + { DEBUG_WARN("LGMP input transport failed: %s", lgmpStatusString(status)); + ++input->stats.counters.terminalFailures; + } if (input->available || input->endpointGeneration) input->notifyStatus = true; - input->connected = false; - input->claimed = false; - input->available = false; - input->ownerBlocked = false; - input->pendingHead = 0; - input->pendingCount = 0; - input->mouseMode = LGMP_INPUT_MOUSE_NONE; - input->mouseButtons = 0; - input->publishedClaimed = false; - input->lastInput = 0; - input->capabilities = 0; - input->statusValid = false; - input->ownerConfirmed = false; + input->connected = false; + input->claimed = false; + input->available = false; + input->ownerBlocked = false; + input->pendingHead = 0; + input->pendingCount = 0; + input->mouseMode = LGMP_INPUT_MOUSE_NONE; + input->mouseButtons = 0; + input->publishedClaimed = false; + input->lastInput = 0; + input->capabilities = 0; + input->statusValid = false; + input->ownerConfirmed = false; + input->stats.probeOutstanding = false; memset(input->keyState, 0, sizeof(input->keyState)); atomic_store_explicit(&input->stop, true, memory_order_release); } +static LGMP_STATUS trySend(LGMPInput * input, + const KVMFRInputMessage * message, bool deferred) +{ + const bool probe = input->stats.probeDue && + !input->stats.probeOutstanding; + uint32_t serial; + const LGMP_STATUS status = lgmpClientTrySendData(input->queue, + message, sizeof(*message), probe ? &serial : NULL); + + if (status == LGMP_OK) + { + if (deferred) + ++input->stats.counters.deferredSends; + else + ++input->stats.counters.immediateSends; + + if (probe) + { + const uint64_t now = microtime(); + input->stats.probeOutstanding = true; + input->stats.probeDue = false; + input->stats.probeSerial = serial; + input->stats.probeStart = now; + input->stats.nextProbe = now + INPUT_STATS_INTERVAL_US; + } + return status; + } + + if (status == LGMP_ERR_QUEUE_BUSY) + { + if (deferred) + ++input->stats.counters.retryBusy; + else + ++input->stats.counters.initialBusy; + } + else if (status == LGMP_ERR_QUEUE_FULL) + { + if (deferred) + ++input->stats.counters.retryFull; + else + ++input->stats.counters.initialFull; + } + return status; +} + static bool coalesceMotion(LGMPInput * input, KVMFRInputMessageType type, const KVMFRInputPayload * payload) { @@ -209,6 +304,7 @@ static bool coalesceMotion(LGMPInput * input, if (type == KVMFR_INPUT_MESSAGE_MOUSE_ABSOLUTE) { tail->message.payload = *payload; + ++input->stats.counters.absoluteCoalesces; return true; } @@ -229,6 +325,7 @@ static bool coalesceMotion(LGMPInput * input, tail->message.payload.mouseRelative.deltaX = (int32_t)x; tail->message.payload.mouseRelative.deltaY = (int32_t)y; + ++input->stats.counters.relativeCoalesces; return true; } @@ -257,6 +354,7 @@ static bool discardPendingMotion(LGMPInput * input) if (generation == input->generation) input->sequence = input->sequence == 1 ? UINT32_MAX : input->sequence - 1; + ++input->stats.counters.motionEvictions; return true; } return false; @@ -280,10 +378,16 @@ static bool queuePayload(LGMPInput * input, KVMFRInputMessageType type, } if (pureMotion && input->pendingCount >= INPUT_PENDING_LENGTH - INPUT_PENDING_RESERVED) + { + ++input->stats.counters.reservedRejects; return false; + } if (!pureMotion && input->pendingCount == INPUT_PENDING_LENGTH && !discardPendingMotion(input)) + { + ++input->stats.counters.discreteOverflowFailures; return false; + } const uint32_t previousSequence = input->sequence; if (++input->sequence == 0) @@ -299,13 +403,15 @@ static bool queuePayload(LGMPInput * input, KVMFRInputMessageType type, if (!input->pendingCount) { - const LGMP_STATUS status = lgmpClientTrySendData(input->queue, - &message, sizeof(message), NULL); + const bool probeOutstanding = input->stats.probeOutstanding; + const LGMP_STATUS status = trySend(input, &message, false); if (status == LGMP_OK) { published(input, &message); if (inputMessage) input->lastInput = microtime(); + if (!probeOutstanding && input->stats.probeOutstanding) + *wake = true; return true; } @@ -326,6 +432,9 @@ static bool queuePayload(LGMPInput * input, KVMFRInputMessageType type, struct LGMPInputPending * item = pendingAt(input, input->pendingCount++); item->message = message; item->pureMotion = pureMotion; + ++input->stats.counters.localEnqueues; + if (input->pendingCount > input->stats.counters.pendingHighWater) + input->stats.counters.pendingHighWater = input->pendingCount; if (inputMessage) input->lastInput = microtime(); *wake = true; @@ -578,8 +687,7 @@ static void flushPending(LGMPInput * input) while (input->connected && input->pendingCount) { struct LGMPInputPending * item = pendingAt(input, 0); - const LGMP_STATUS status = lgmpClientTrySendData(input->queue, - &item->message, sizeof(item->message), NULL); + const LGMP_STATUS status = trySend(input, &item->message, true); if (status == LGMP_ERR_QUEUE_BUSY || status == LGMP_ERR_QUEUE_FULL) return; if (status != LGMP_OK) @@ -595,6 +703,78 @@ static void flushPending(LGMPInput * input) } } +static void pollAckProbe(LGMPInput * input) +{ + if (!input->stats.probeOutstanding) + return; + + uint32_t processed; + const LGMP_STATUS status = + lgmpClientGetSerial(input->queue, &processed); + if (status != LGMP_OK) + { + input->stats.probeOutstanding = false; + connectionFailed(input, status); + return; + } + if ((int32_t)(processed - input->stats.probeSerial) < 0) + return; + + const uint64_t elapsed = microtime() - input->stats.probeStart; + input->stats.probeOutstanding = false; + input->stats.counters.ackTotal += elapsed; + ++input->stats.counters.ackSamples; + if (elapsed > input->stats.counters.ackMax) + input->stats.counters.ackMax = elapsed; +} + +static bool collectStats(LGMPInput * input, uint64_t now, bool force, + struct LGMPInputCounters * result) +{ + if (!force && now - input->stats.lastReport < INPUT_STATS_INTERVAL_US) + return false; + + input->stats.lastReport = now; + *result = input->stats.counters; + memset(&input->stats.counters, 0, sizeof(input->stats.counters)); + input->stats.counters.pendingHighWater = input->pendingCount; + + return result->immediateSends || result->deferredSends || + result->localEnqueues || result->initialBusy || + result->initialFull || result->retryBusy || result->retryFull || + result->relativeCoalesces || result->absoluteCoalesces || + result->reservedRejects || result->motionEvictions || + result->discreteOverflowFailures || + result->discreteOverflowResets || result->claims || + result->releases || result->keepalives || + result->terminalFailures || result->ackSamples; +} + +static void logStats(const struct LGMPInputCounters * stats) +{ + const uint64_t ackAverage = stats->ackSamples ? + stats->ackTotal / stats->ackSamples : 0; + + DEBUG_TRACE("LGMP input: sent immediate/deferred %" PRIu64 "/%" PRIu64 + ", queued %" PRIu64 " (high %u), initial busy/full %" PRIu64 + "/%" PRIu64 ", retry busy/full %" PRIu64 "/%" PRIu64 + ", coalesced relative/absolute %" PRIu64 "/%" PRIu64 + ", motion rejected/evicted %" PRIu64 "/%" PRIu64 + ", overflow failures/resets %" PRIu64 "/%" PRIu64 + ", published claim/release/keepalive %" PRIu64 "/%" PRIu64 + "/%" PRIu64 ", terminal failures %" PRIu64 + ", LGMP ACK average/max %" PRIu64 "/%" PRIu64 " us (%" PRIu64 + " samples)", stats->immediateSends, stats->deferredSends, + stats->localEnqueues, stats->pendingHighWater, + stats->initialBusy, stats->initialFull, stats->retryBusy, + stats->retryFull, stats->relativeCoalesces, + stats->absoluteCoalesces, stats->reservedRejects, + stats->motionEvictions, stats->discreteOverflowFailures, + stats->discreteOverflowResets, stats->claims, stats->releases, + stats->keepalives, stats->terminalFailures, ackAverage, + stats->ackMax, stats->ackSamples); +} + static void releaseOnDisconnect(LGMPInput * input) { if (!input->queue || !input->publishedGeneration) @@ -652,13 +832,18 @@ static int inputThread(void * opaque) LGMPInput * input = opaque; while (!atomic_load_explicit(&input->stop, memory_order_acquire)) { + struct LGMPInputCounters stats = { 0 }; unsigned timeout = INPUT_WORKER_IDLE_MS; bool wake = false; LG_LOCK(input->lock); processInputStatus(input, &wake); flushPending(input); + pollAckProbe(input); const uint64_t now = microtime(); + if (!input->stats.probeOutstanding && + now >= input->stats.nextProbe) + input->stats.probeDue = true; if (input->connected && input->claimed && !inputStateHeld(input) && !input->pendingCount && input->publishedGeneration == input->generation && @@ -678,8 +863,13 @@ static int inputThread(void * opaque) if (input->pendingCount) timeout = INPUT_WORKER_RETRY_MS; + if (input->stats.probeOutstanding) + timeout = INPUT_WORKER_RETRY_MS; + const bool report = collectStats(input, now, false, &stats); LG_UNLOCK(input->lock); + if (report) + logStats(&stats); notifyInputStatus(input); if (wake) lgSignalEvent(input->event); @@ -688,6 +878,13 @@ static int inputThread(void * opaque) break; lgWaitEvent(input->event, timeout); } + + struct LGMPInputCounters stats = { 0 }; + LG_LOCK(input->lock); + const bool report = collectStats(input, microtime(), true, &stats); + LG_UNLOCK(input->lock); + if (report) + logStats(&stats); notifyInputStatus(input); return 0; } @@ -772,6 +969,9 @@ bool lgmpInput_connect(LGMPInput * input, uint32_t clientID) input->lastSend = 0; input->lastInput = 0; input->generation = 0; + memset(&input->stats, 0, sizeof(input->stats)); + input->stats.lastReport = microtime(); + input->stats.probeDue = true; clearInputState(input); atomic_store_explicit(&input->stop, false, memory_order_release); LGThread * thread; @@ -953,10 +1153,17 @@ static bool updateKey(void * opaque, int key, bool pressed) KVMFRInputPayload payload = { 0 }; buildKeyboardPayload(input, &payload); + const uint64_t overflowFailures = + input->stats.counters.discreteOverflowFailures; bool result = queuePayload(input, KVMFR_INPUT_MESSAGE_KEYBOARD, &payload, false, &wake); if (!result && !pressed && input->connected) + { + if (input->stats.counters.discreteOverflowFailures != + overflowFailures) + ++input->stats.counters.discreteOverflowResets; result = release(input, &wake); + } else if (!result && input->connected) *state = previous; LG_UNLOCK(input->lock); @@ -1152,12 +1359,17 @@ static bool updateMouseButton(void * opaque, unsigned int button, return true; } + const uint64_t overflowFailures = + input->stats.counters.discreteOverflowFailures; bool result = input->connected && input->available && claim(input, &wake) && queueMouse(input, mode, 0, 0, 0, buttons, false, &wake); bool reset = false; if (!result && !pressed && input->connected) { + if (input->stats.counters.discreteOverflowFailures != + overflowFailures) + ++input->stats.counters.discreteOverflowResets; reset = release(input, &wake); result = reset; } diff --git a/idd/LGIdd/ipc/CInputPipeServer.cpp b/idd/LGIdd/ipc/CInputPipeServer.cpp index 11a9d584..f6a44488 100644 --- a/idd/LGIdd/ipc/CInputPipeServer.cpp +++ b/idd/LGIdd/ipc/CInputPipeServer.cpp @@ -35,6 +35,10 @@ bool CInputPipeServer::Init() DeInit(); m_state.store(0, std::memory_order_release); + m_performanceFrequency.QuadPart = 0; + if (!QueryPerformanceFrequency(&m_performanceFrequency)) + m_performanceFrequency.QuadPart = 0; + m_lastStatistics = GetTickCount64(); m_stopEvent = CreateEventW(nullptr, TRUE, FALSE, nullptr); m_queueEvent = CreateEventW(nullptr, FALSE, FALSE, nullptr); if (!m_stopEvent || !m_queueEvent) @@ -98,6 +102,19 @@ void CInputPipeServer::DeInit() m_absoluteValid = false; m_relativeButtons = 0; m_absoluteButtons = 0; + + m_statEnqueued = 0; + m_statRelativeCoalesced = 0; + m_statAbsoluteCoalesced = 0; + m_statResyncs = 0; + m_statResyncDiscarded = 0; + m_statQueueHighWater = 0; + m_statSent = 0; + m_statStale = 0; + m_statWriteFailed = 0; + m_statSlowWrites = 0; + m_statWriteTicks = 0; + m_statMaxWriteTicks = 0; } bool CInputPipeServer::QueueLocked( @@ -133,6 +150,7 @@ bool CInputPipeServer::QueueLocked( { tail.payload.mouseRelative.deltaX = static_cast(x); tail.payload.mouseRelative.deltaY = static_cast(y); + ++m_statRelativeCoalesced; return true; } } @@ -145,6 +163,7 @@ bool CInputPipeServer::QueueLocked( { tail.payload.mouseAbsolute.x = payload.mouseAbsolute.x; tail.payload.mouseAbsolute.y = payload.mouseAbsolute.y; + ++m_statAbsoluteCoalesced; return true; } } @@ -169,6 +188,9 @@ bool CInputPipeServer::QueueRawLocked( m_queue[index].payload = payload; m_queue[index].pureMotion = pureMotion; ++m_queueCount; + ++m_statEnqueued; + if (m_queueCount > m_statQueueHighWater) + m_statQueueHighWater = m_queueCount; SetEvent(m_queueEvent); return true; } @@ -201,6 +223,8 @@ bool CInputPipeServer::QueueResetLocked() void CInputPipeServer::ResyncLocked() { + ++m_statResyncs; + m_statResyncDiscarded += m_queueCount; m_queueHead = 0; m_queueCount = 0; uint64_t state = m_state.load(std::memory_order_relaxed); @@ -375,6 +399,9 @@ bool CInputPipeServer::Send(const QueueItem& item) bool current; bool sent = true; + bool timed = false; + LARGE_INTEGER start = {}; + LARGE_INTEGER end = {}; { CSRWSharedLock lock(&m_connectionLock); const uint64_t state = m_state.load(std::memory_order_acquire); @@ -382,10 +409,33 @@ bool CInputPipeServer::Send(const QueueItem& item) if (current) { message.sequence = ++m_sequence; + timed = QueryPerformanceCounter(&start) != FALSE; sent = m_endpoint.Send(&message, sizeof(message)); + timed = timed && QueryPerformanceCounter(&end) != FALSE; } } + if (!current) + ++m_statStale; + else + { + if (timed) + { + const int64_t ticks = end.QuadPart - start.QuadPart; + m_statWriteTicks += ticks; + if (ticks > m_statMaxWriteTicks) + m_statMaxWriteTicks = ticks; + if (m_performanceFrequency.QuadPart && + ticks * 1000 >= m_performanceFrequency.QuadPart) + ++m_statSlowWrites; + } + + if (sent) + ++m_statSent; + else + ++m_statWriteFailed; + } + if (!sent) { Invalidate(item.state, true); @@ -394,6 +444,78 @@ bool CInputPipeServer::Send(const QueueItem& item) return current; } +void CInputPipeServer::LogStatistics() +{ + const ULONGLONG now = GetTickCount64(); + if (now - m_lastStatistics < STATISTICS_INTERVAL_MS) + return; + + uint64_t enqueued; + uint64_t relativeCoalesced; + uint64_t absoluteCoalesced; + uint64_t resyncs; + uint64_t resyncDiscarded; + size_t queueHighWater; + { + CSRWExclusiveLock lock(&m_queueLock); + enqueued = m_statEnqueued; + relativeCoalesced = m_statRelativeCoalesced; + absoluteCoalesced = m_statAbsoluteCoalesced; + resyncs = m_statResyncs; + resyncDiscarded = m_statResyncDiscarded; + queueHighWater = m_statQueueHighWater; + + m_statEnqueued = 0; + m_statRelativeCoalesced = 0; + m_statAbsoluteCoalesced = 0; + m_statResyncs = 0; + m_statResyncDiscarded = 0; + m_statQueueHighWater = m_queueCount; + } + + const uint64_t sent = m_statSent; + const uint64_t stale = m_statStale; + const uint64_t writeFailed = m_statWriteFailed; + const uint64_t slowWrites = m_statSlowWrites; + const int64_t writeTicks = m_statWriteTicks; + const int64_t maxWriteTicks = m_statMaxWriteTicks; + + m_statSent = 0; + m_statStale = 0; + m_statWriteFailed = 0; + m_statSlowWrites = 0; + m_statWriteTicks = 0; + m_statMaxWriteTicks = 0; + m_lastStatistics = now; + + if (!(enqueued || relativeCoalesced || absoluteCoalesced || resyncs || + resyncDiscarded || sent || stale || writeFailed || slowWrites)) + return; + + const double writeMs = m_performanceFrequency.QuadPart ? + static_cast(writeTicks) * 1000.0 / + m_performanceFrequency.QuadPart : 0.0; + const double maxWriteMs = m_performanceFrequency.QuadPart ? + static_cast(maxWriteTicks) * 1000.0 / + m_performanceFrequency.QuadPart : 0.0; + DEBUG_TRACE("LGInput pipe: %llu queued, %llu sent, %llu stale, " + "%llu failed; %llu relative and %llu absolute coalesced, " + "%llu resyncs discarded %llu, peak %zu; %.3f ms writes, " + "%.3f ms max, %llu slow", + static_cast(enqueued), + static_cast(sent), + static_cast(stale), + static_cast(writeFailed), + static_cast(relativeCoalesced), + static_cast(absoluteCoalesced), + static_cast(resyncs), + static_cast(resyncDiscarded), + queueHighWater, + writeMs, + maxWriteMs, + static_cast(slowWrites)); +} + void CInputPipeServer::Invalidate(uint64_t state, bool requireMatch) { CSRWExclusiveLock connectionLock(&m_connectionLock); @@ -435,8 +557,12 @@ void CInputPipeServer::Thread() QueueItem item = {}; while (Pop(item)) - if (!Send(item)) + { + const bool sent = Send(item); + if (!sent) break; + } + LogStatistics(); } Invalidate(0, false); diff --git a/idd/LGIdd/ipc/CInputPipeServer.h b/idd/LGIdd/ipc/CInputPipeServer.h index dc357c58..c93c77ac 100644 --- a/idd/LGIdd/ipc/CInputPipeServer.h +++ b/idd/LGIdd/ipc/CInputPipeServer.h @@ -33,6 +33,7 @@ class CInputPipeServer : public IInputSink, private IPipeEndpointHandler private: static constexpr size_t QUEUE_LENGTH = 128; static constexpr size_t MOTION_COALESCE_THRESHOLD = QUEUE_LENGTH / 2; + static constexpr DWORD STATISTICS_INTERVAL_MS = 5000; struct QueueItem { @@ -72,6 +73,22 @@ private: uint32_t m_relativeButtons = 0; uint32_t m_absoluteButtons = 0; + uint64_t m_statEnqueued = 0; + uint64_t m_statRelativeCoalesced = 0; + uint64_t m_statAbsoluteCoalesced = 0; + uint64_t m_statResyncs = 0; + uint64_t m_statResyncDiscarded = 0; + size_t m_statQueueHighWater = 0; + + uint64_t m_statSent = 0; + uint64_t m_statStale = 0; + uint64_t m_statWriteFailed = 0; + uint64_t m_statSlowWrites = 0; + int64_t m_statWriteTicks = 0; + int64_t m_statMaxWriteTicks = 0; + ULONGLONG m_lastStatistics = 0; + LARGE_INTEGER m_performanceFrequency = {}; + bool QueueLocked(LGInputPipeMessageType type, const KVMFRInputPayload& payload, bool pureMotion); bool QueueRawLocked(LGInputPipeMessageType type, @@ -81,6 +98,7 @@ private: bool Pop(QueueItem& item); bool Send(const QueueItem& item); void Invalidate(uint64_t state, bool requireMatch); + void LogStatistics(); void Thread(); static DWORD WINAPI ThreadProc(void * context); diff --git a/idd/LGIdd/transport/lgmp/CLGMPInputTransport.cpp b/idd/LGIdd/transport/lgmp/CLGMPInputTransport.cpp index 8f72d228..25799394 100644 --- a/idd/LGIdd/transport/lgmp/CLGMPInputTransport.cpp +++ b/idd/LGIdd/transport/lgmp/CLGMPInputTransport.cpp @@ -289,19 +289,31 @@ bool CLGMPInputTransport::IsOwner( bool CLGMPInputTransport::Claim( uint32_t sourceClientID, const KVMFRInputMessage& message) { - if (message.sequence != 1 || !m_sink) + if (message.sequence != 1) + { + ++m_statistics.sequenceErrors; return false; + } + if (!m_sink) + { + ++m_statistics.deliveryFailures; + return false; + } const uint64_t sinkState = m_sink->GetState(); if (!(sinkState & 1) || sinkState != m_sinkState || !m_sink->Reset() || m_sink->GetState() != sinkState) + { + ++m_statistics.deliveryFailures; return false; + } m_ownerClientID = sourceClientID; m_ownerGeneration = message.generation; m_ownerSequence = message.sequence; RenewLease(); m_statusDirty = true; + ++m_statistics.claims; DEBUG_INFO("Input owner %u generation %u acquired", m_ownerClientID, m_ownerGeneration); return true; @@ -328,6 +340,7 @@ void CLGMPInputTransport::ReleaseOwner( m_ownerSequence = 0; m_ownerDeadline = 0; m_statusDirty = true; + ++m_statistics.releases; DEBUG_INFO("Input owner %u generation %u released (%s)", clientID, generation, reason); } @@ -420,6 +433,7 @@ bool CLGMPInputTransport::ProcessMessage( if (!message.generation || !message.sequence || message.reserved || !ValidatePayload(message)) { + ++m_statistics.malformedMessage; if (owner) ReleaseOwner(true, "invalid input message"); return false; @@ -430,10 +444,14 @@ bool CLGMPInputTransport::ProcessMessage( if (m_ownerClientID) { if (!owner) + { + ++m_statistics.nonOwner; return true; + } if (message.sequence == 1 && m_ownerSequence == 1) return true; + ++m_statistics.sequenceErrors; ReleaseOwner(true, "sequence discontinuity"); return false; } @@ -441,18 +459,23 @@ bool CLGMPInputTransport::ProcessMessage( } if (!owner) + { + ++m_statistics.nonOwner; return true; + } uint32_t expectedSequence = m_ownerSequence + 1; if (!expectedSequence) expectedSequence = 1; if (message.sequence != expectedSequence) { + ++m_statistics.sequenceErrors; ReleaseOwner(true, "sequence discontinuity"); return false; } - bool accepted = false; + bool accepted = false; + bool inputReport = false; switch (message.type) { case KVMFR_INPUT_MESSAGE_RELEASE: @@ -468,6 +491,7 @@ bool CLGMPInputTransport::ProcessMessage( break; case KVMFR_INPUT_MESSAGE_MOUSE_RELATIVE: + inputReport = true; accepted = m_sink && m_sink->SendMouseRelative( message.payload.mouseRelative.deltaX, message.payload.mouseRelative.deltaY, @@ -476,6 +500,7 @@ bool CLGMPInputTransport::ProcessMessage( break; case KVMFR_INPUT_MESSAGE_MOUSE_ABSOLUTE: + inputReport = true; accepted = m_sink && m_sink->SendMouseAbsolute( message.payload.mouseAbsolute.x, message.payload.mouseAbsolute.y, @@ -484,6 +509,7 @@ bool CLGMPInputTransport::ProcessMessage( break; case KVMFR_INPUT_MESSAGE_KEYBOARD: + inputReport = true; accepted = m_sink && m_sink->SendKeyboard( message.payload.keyboard.modifiers, message.payload.keyboard.keys); @@ -495,6 +521,7 @@ bool CLGMPInputTransport::ProcessMessage( if (!accepted) { + ++m_statistics.deliveryFailures; ReleaseOwner(true, "input delivery failed"); return false; } @@ -509,13 +536,16 @@ bool CLGMPInputTransport::ProcessMessage( m_ownerSequence = message.sequence; RenewLease(); + if (inputReport) + ++m_statistics.reports; return true; } bool CLGMPInputTransport::DrainMessages() { bool received = false; - for (unsigned count = 0; count < 256; ++count) + unsigned count = 0; + for (; count < 256; ++count) { uint8_t data[LGMP_MSGS_SIZE] = {}; size_t size = 0; @@ -532,9 +562,11 @@ bool CLGMPInputTransport::DrainMessages() } received = true; + ++m_statistics.messages; if (size != sizeof(KVMFRInputMessage)) { DEBUG_WARN("Ignoring invalid KVMFR input message size"); + ++m_statistics.malformedSize; if (sourceClientID == m_ownerClientID) ReleaseOwner(true, "invalid input message"); } @@ -547,9 +579,50 @@ bool CLGMPInputTransport::DrainMessages() lgmpHostAckData(m_queue); } + if (count > m_statistics.maxDrain) + m_statistics.maxDrain = count; + if (count == 256) + ++m_statistics.drainLimit; return received; } +void CLGMPInputTransport::LogStatistics(ULONGLONG now) +{ + if (!m_statistics.lastLog) + { + m_statistics.lastLog = now; + return; + } + if (now - m_statistics.lastLog < LOG_INTERVAL_MS) + return; + + const Statistics statistics = m_statistics; + m_statistics = {}; + m_statistics.lastLog = now; + + if (!statistics.messages && !statistics.claims && + !statistics.releases && !statistics.deliveryFailures) + return; + + const double elapsed = + static_cast(now - statistics.lastLog) / 1000.0; + DEBUG_TRACE("LGMP input host: %.1f msg/s, %llu reports, " + "drain max %u, %llu limit; %llu bad size, %llu malformed, " + "%llu sequence, %llu non-owner, %llu delivery failures; " + "%llu claims, %llu releases", + statistics.messages / elapsed, + static_cast(statistics.reports), + statistics.maxDrain, + static_cast(statistics.drainLimit), + static_cast(statistics.malformedSize), + static_cast(statistics.malformedMessage), + static_cast(statistics.sequenceErrors), + static_cast(statistics.nonOwner), + static_cast(statistics.deliveryFailures), + static_cast(statistics.claims), + static_cast(statistics.releases)); +} + DWORD CALLBACK CLGMPInputTransport::ThreadProc(void * context) { static_cast(context)->Thread(); @@ -567,15 +640,20 @@ void CLGMPInputTransport::Thread() GetLastError()); ULONGLONG activeUntil = 0; + m_statistics = {}; + m_statistics.lastLog = GetTickCount64(); const HANDLE waitHandles[] = { m_stopEvent, m_pollTimer }; for (;;) { CheckOwner(); - if (DrainMessages()) - activeUntil = GetTickCount64() + ACTIVE_POLL_MS; + const bool received = DrainMessages(); PublishStatus(); + const ULONGLONG now = GetTickCount64(); + if (received) + activeUntil = now + ACTIVE_POLL_MS; + LogStatistics(now); - const bool active = GetTickCount64() < activeUntil; + const bool active = now < activeUntil; if (!ArmPollTimer(m_pollTimer, active)) { DEBUG_ERROR_HR(GetLastError(), "Failed to arm LGMP input timer"); diff --git a/idd/LGIdd/transport/lgmp/CLGMPInputTransport.h b/idd/LGIdd/transport/lgmp/CLGMPInputTransport.h index aad5b617..44e4c133 100644 --- a/idd/LGIdd/transport/lgmp/CLGMPInputTransport.h +++ b/idd/LGIdd/transport/lgmp/CLGMPInputTransport.h @@ -40,6 +40,23 @@ class CLGMPInputTransport final : public IInputTransport private: static constexpr ULONGLONG OWNER_LEASE_MS = 500; static constexpr ULONGLONG ACTIVE_POLL_MS = 50; + static constexpr ULONGLONG LOG_INTERVAL_MS = 5000; + + struct Statistics + { + ULONGLONG lastLog; + uint64_t messages; + uint64_t reports; + uint64_t drainLimit; + uint64_t malformedSize; + uint64_t malformedMessage; + uint64_t sequenceErrors; + uint64_t nonOwner; + uint64_t deliveryFailures; + uint64_t claims; + uint64_t releases; + unsigned maxDrain; + }; CLGMPHost& m_host; @@ -52,19 +69,21 @@ private: HANDLE m_pollTimer = nullptr; HANDLE m_thread = nullptr; - uint32_t m_ownerClientID = 0; - uint32_t m_ownerGeneration = 0; - uint32_t m_ownerSequence = 0; - ULONGLONG m_ownerDeadline = 0; - uint64_t m_sinkState = 0; - uint32_t m_endpointGeneration = 0; - uint32_t m_statusSerial = 0; - bool m_statusDirty = false; + uint32_t m_ownerClientID = 0; + uint32_t m_ownerGeneration = 0; + uint32_t m_ownerSequence = 0; + ULONGLONG m_ownerDeadline = 0; + uint64_t m_sinkState = 0; + uint32_t m_endpointGeneration = 0; + uint32_t m_statusSerial = 0; + bool m_statusDirty = false; + Statistics m_statistics = {}; bool Initialize(); void DeInit(); void UpdateSinkState(uint64_t state); void PublishStatus(); + void LogStatistics(ULONGLONG now); bool DrainMessages(); bool ProcessMessage(uint32_t sourceClientID, const KVMFRInputMessage& message); diff --git a/idd/LGInput/CHIDDevice.cpp b/idd/LGInput/CHIDDevice.cpp index f98839cd..9a01a1b9 100644 --- a/idd/LGInput/CHIDDevice.cpp +++ b/idd/LGInput/CHIDDevice.cpp @@ -44,6 +44,20 @@ struct HIDQueuedReport size_t size; }; +struct HIDStatistics +{ + uint64_t direct; + uint64_t queued; + uint64_t relativeCoalesced; + uint64_t absoluteCoalesced; + uint64_t staleAbsoluteCompacted; + uint64_t keyboardDuplicates; + uint64_t consumerDuplicates; + uint64_t overflows; + uint64_t resetDiscarded; + size_t queueHighWater; +}; + struct HIDDeviceContext { WDFQUEUE reportQueue; @@ -63,6 +77,7 @@ struct HIDDeviceContext bool absoluteValid; uint16_t absoluteX; uint16_t absoluteY; + HIDStatistics statistics; HIDQueuedReport reports[REPORT_QUEUE_LENGTH]; CInputPipeClient * inputPipe; }; @@ -199,6 +214,7 @@ static bool CompactStaleMotion( if (superseded) { RemoveQueuedReport(context, i); + ++context->statistics.staleAbsoluteCompacted; return true; } } @@ -236,6 +252,7 @@ static NTSTATUS QueueReport( { previous->x = static_cast(x); previous->y = static_cast(y); + ++context->statistics.relativeCoalesced; return STATUS_SUCCESS; } } @@ -250,19 +267,26 @@ static NTSTATUS QueueReport( { CopyMemory(tail.data, data, size); tail.size = size; + ++context->statistics.absoluteCoalesced; return STATUS_SUCCESS; } } else if (reportId == HID_REPORT_ID_KEYBOARD && tail.size == size && memcmp(tail.data, data, size) == 0) + { + ++context->statistics.keyboardDuplicates; return STATUS_SUCCESS; + } } } if (context->reportCount == REPORT_QUEUE_LENGTH) { if (!CompactStaleMotion(context, reportId)) + { + ++context->statistics.overflows; return STATUS_BUFFER_OVERFLOW; + } } const size_t index = @@ -272,6 +296,9 @@ static NTSTATUS QueueReport( report->size = size; report->pureMotion = pureMotion; ++context->reportCount; + ++context->statistics.queued; + if (context->reportCount > context->statistics.queueHighWater) + context->statistics.queueHighWater = context->reportCount; return STATUS_SUCCESS; } @@ -454,7 +481,10 @@ NTSTATUS CHIDDevice::SubmitReport( if (reportId == HID_REPORT_ID_CONSUMER && context->consumerUsage == static_cast(report)->usage) + { + ++context->statistics.consumerDuplicates; return STATUS_SUCCESS; + } bool pureMotion = false; switch (reportId) @@ -493,7 +523,11 @@ NTSTATUS CHIDDevice::SubmitReport( status = QueueReport(context, report, size, pureMotion); } else if (NT_SUCCESS(status)) + { status = CopyToRequest(request, report, size); + if (NT_SUCCESS(status)) + ++context->statistics.direct; + } if (NT_SUCCESS(status)) { @@ -553,6 +587,7 @@ NTSTATUS CHIDDevice::ResetReports() absoluteValid = context->absoluteValid; absoluteX = context->absoluteX; absoluteY = context->absoluteY; + context->statistics.resetDiscarded += context->reportCount; context->reportHead = 0; context->reportCount = 0; context->mouseMode = 0; @@ -601,6 +636,44 @@ NTSTATUS CHIDDevice::ResetReports() return status; } +void CHIDDevice::LogStatistics() +{ + HIDStatistics statistics = {}; + { + CSRWSharedLock deviceLock(&s_deviceLock); + HIDDeviceContext * context = s_device; + if (!context) + return; + + CSRWExclusiveLock reportLock(&context->reportLock); + statistics = context->statistics; + context->statistics = {}; + context->statistics.queueHighWater = context->reportCount; + } + + if (!(statistics.direct || statistics.queued || + statistics.relativeCoalesced || statistics.absoluteCoalesced || + statistics.staleAbsoluteCompacted || + statistics.keyboardDuplicates || statistics.consumerDuplicates || + statistics.overflows || statistics.resetDiscarded)) + return; + + DEBUG_TRACE("HID reports: %llu direct, %llu queued, peak %zu; " + "%llu relative and %llu absolute coalesced, %llu stale absolute " + "compacted, %llu keyboard and %llu consumer duplicates, " + "%llu overflows, %llu discarded on reset", + static_cast(statistics.direct), + static_cast(statistics.queued), + statistics.queueHighWater, + static_cast(statistics.relativeCoalesced), + static_cast(statistics.absoluteCoalesced), + static_cast(statistics.staleAbsoluteCompacted), + static_cast(statistics.keyboardDuplicates), + static_cast(statistics.consumerDuplicates), + static_cast(statistics.overflows), + static_cast(statistics.resetDiscarded)); +} + VOID HIDEvtIoDeviceControl( _In_ WDFQUEUE queue, _In_ WDFREQUEST request, diff --git a/idd/LGInput/CHIDDevice.h b/idd/LGInput/CHIDDevice.h index 068fdbcf..b2d4482c 100644 --- a/idd/LGInput/CHIDDevice.h +++ b/idd/LGInput/CHIDDevice.h @@ -31,4 +31,5 @@ public: _In_reads_bytes_(size) const void * report, _In_ size_t size); static NTSTATUS ResetReports(); + static void LogStatistics(); }; diff --git a/idd/LGInput/ipc/CInputPipeClient.cpp b/idd/LGInput/ipc/CInputPipeClient.cpp index 3f84faed..d7228361 100644 --- a/idd/LGInput/ipc/CInputPipeClient.cpp +++ b/idd/LGInput/ipc/CInputPipeClient.cpp @@ -37,7 +37,13 @@ static constexpr uint16_t HID_CONSUMER_USAGE_VOLUME_DOWN = 0xea; bool CInputPipeClient::Start() { - m_lastSequence = 0; + m_endpoint.Stop(); + m_lastSequence = 0; + m_statReceived = 0; + m_statMalformed = 0; + m_statSequenceResets = 0; + m_statSubmitFailed = 0; + m_lastStatistics = GetTickCount64(); m_endpoint.SetHandler(this); return m_endpoint.Start( LG_INPUT_PIPE_NAME, @@ -51,7 +57,10 @@ void CInputPipeClient::Stop() m_endpoint.Stop(); m_lastSequence = 0; if (wasRunning) + { + LogStatistics(true); CHIDDevice::ResetReports(); + } } void CInputPipeClient::OnPipeConnected() @@ -63,6 +72,7 @@ void CInputPipeClient::OnPipeConnected() void CInputPipeClient::OnPipeDisconnected() { m_lastSequence = 0; + LogStatistics(true); CHIDDevice::ResetReports(); DEBUG_INFO("Disconnected from the LGIdd input transport; reconnecting"); } @@ -72,7 +82,11 @@ bool CInputPipeClient::OnPipeMessage( size_t size) { if (size != sizeof(LGInputPipeMessage)) + { + ++m_statMalformed; + DEBUG_WARN("Received a malformed LGInput pipe message"); return false; + } const LGInputPipeMessage & message = *static_cast(frame); @@ -80,16 +94,22 @@ bool CInputPipeClient::OnPipeMessage( message.version != LG_INPUT_PIPE_VERSION || !message.payloadSize || message.payloadSize > sizeof(message.payload)) + { + ++m_statMalformed; + DEBUG_WARN("Received a malformed LGInput pipe message"); return false; + } if (!message.sequence || (m_lastSequence && message.sequence != m_lastSequence + 1)) { + ++m_statSequenceResets; DEBUG_WARN("LGInput pipe report sequence changed unexpectedly"); CHIDDevice::ResetReports(); return false; } bool handled = false; + const uint64_t submitFailures = m_statSubmitFailed; switch (message.type) { case LG_INPUT_PIPE_MESSAGE_MOUSE_RELATIVE: @@ -107,13 +127,24 @@ bool CInputPipeClient::OnPipeMessage( break; default: + ++m_statMalformed; + DEBUG_WARN("Received an unknown LGInput pipe message"); return false; } if (!handled) + { + if (m_statSubmitFailed == submitFailures) + { + ++m_statMalformed; + DEBUG_WARN("Received a malformed LGInput pipe payload"); + } return false; + } m_lastSequence = message.sequence; + ++m_statReceived; + LogStatistics(false); return true; } @@ -265,19 +296,53 @@ bool CInputPipeClient::SubmitReport( const NTSTATUS status = CHIDDevice::SubmitReport(report, size); if (status == STATUS_INVALID_PARAMETER) + { + ++m_statSubmitFailed; return false; + } if (status == STATUS_BUFFER_OVERFLOW) { + ++m_statSubmitFailed; DEBUG_WARN("LGInput HID report queue overflowed; resetting input state"); CHIDDevice::ResetReports(); return false; } if (!NT_SUCCESS(status)) { + ++m_statSubmitFailed; if (status != STATUS_DEVICE_NOT_READY) DEBUG_WARN_HR(status, "Failed to submit an LGInput HID report"); return false; } return true; } + +void CInputPipeClient::LogStatistics(bool force) +{ + const ULONGLONG now = GetTickCount64(); + if (!force && now - m_lastStatistics < STATISTICS_INTERVAL_MS) + return; + + const uint64_t received = m_statReceived; + const uint64_t malformed = m_statMalformed; + const uint64_t sequenceResets = m_statSequenceResets; + const uint64_t submitFailed = m_statSubmitFailed; + + m_statReceived = 0; + m_statMalformed = 0; + m_statSequenceResets = 0; + m_statSubmitFailed = 0; + m_lastStatistics = now; + + if (received || malformed || sequenceResets || submitFailed) + { + DEBUG_TRACE("LGInput pipe receive: %llu reports, %llu malformed, " + "%llu sequence resets, %llu HID submit failures", + static_cast(received), + static_cast(malformed), + static_cast(sequenceResets), + static_cast(submitFailed)); + } + CHIDDevice::LogStatistics(); +} diff --git a/idd/LGInput/ipc/CInputPipeClient.h b/idd/LGInput/ipc/CInputPipeClient.h index fcc4a6ec..41c0beac 100644 --- a/idd/LGInput/ipc/CInputPipeClient.h +++ b/idd/LGInput/ipc/CInputPipeClient.h @@ -34,6 +34,8 @@ public: void Stop(); private: + static constexpr ULONGLONG STATISTICS_INTERVAL_MS = 5000; + void OnPipeConnected() override; void OnPipeDisconnected() override; bool OnPipeMessage(const void * message, size_t size) override; @@ -41,7 +43,13 @@ private: bool HandleMouseAbsolute(const void * payload, size_t size); bool HandleKeyboard(const void * payload, size_t size); bool SubmitReport(const void * report, size_t size); + void LogStatistics(bool force); CPipeEndpoint m_endpoint; - uint64_t m_lastSequence = 0; + uint64_t m_lastSequence = 0; + uint64_t m_statReceived = 0; + uint64_t m_statMalformed = 0; + uint64_t m_statSequenceResets = 0; + uint64_t m_statSubmitFailed = 0; + ULONGLONG m_lastStatistics = 0; };