[client/idd] input: add transport diagnostics

client/transports/LGMP/input.c

@@ -30,6 +30,7 @@
 #include "common/thread.h"
 #include "common/time.h"
 
+#include <inttypes.h>
 #include <limits.h>
 #include <stdatomic.h>
 #include <stdint.h>
@@ -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,7 +219,10 @@ 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;
@@ -190,10 +239,56 @@ static void connectionFailed(LGMPInput * input, LGMP_STATUS status)
   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,
+    const bool probeOutstanding = input->stats.probeOutstanding;
-      &message, sizeof(message), NULL);
+    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,
+    const LGMP_STATUS status = trySend(input, &item->message, true);
-      &item->message, sizeof(item->message), NULL);
     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;
   }

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<int32_t>(x);
           tail.payload.mouseRelative.deltaY = static_cast<int32_t>(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<double>(writeTicks) * 1000.0 /
+      m_performanceFrequency.QuadPart : 0.0;
+  const double maxWriteMs = m_performanceFrequency.QuadPart ?
+    static_cast<double>(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<unsigned long long>(enqueued),
+    static_cast<unsigned long long>(sent),
+    static_cast<unsigned long long>(stale),
+    static_cast<unsigned long long>(writeFailed),
+    static_cast<unsigned long long>(relativeCoalesced),
+    static_cast<unsigned long long>(absoluteCoalesced),
+    static_cast<unsigned long long>(resyncs),
+    static_cast<unsigned long long>(resyncDiscarded),
+    queueHighWater,
+    writeMs,
+    maxWriteMs,
+    static_cast<unsigned long long>(slowWrites));
+}
+
 void CInputPipeServer::Invalidate(uint64_t state, bool requireMatch)
 {
   CSRWExclusiveLock connectionLock(&m_connectionLock);
@@ -435,9 +557,13 @@ void CInputPipeServer::Thread()
 
     QueueItem item = {};
     while (Pop(item))
-      if (!Send(item))
+    {
+      const bool sent = Send(item);
+      if (!sent)
         break;
     }
+    LogStatistics();
+  }
 
   Invalidate(0, false);
 }

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);

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 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<double>(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<unsigned long long>(statistics.reports),
+    statistics.maxDrain,
+    static_cast<unsigned long long>(statistics.drainLimit),
+    static_cast<unsigned long long>(statistics.malformedSize),
+    static_cast<unsigned long long>(statistics.malformedMessage),
+    static_cast<unsigned long long>(statistics.sequenceErrors),
+    static_cast<unsigned long long>(statistics.nonOwner),
+    static_cast<unsigned long long>(statistics.deliveryFailures),
+    static_cast<unsigned long long>(statistics.claims),
+    static_cast<unsigned long long>(statistics.releases));
+}
+
 DWORD CALLBACK CLGMPInputTransport::ThreadProc(void * context)
 {
   static_cast<CLGMPInputTransport *>(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())
+    const bool received = DrainMessages();
-      activeUntil = GetTickCount64() + ACTIVE_POLL_MS;
     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");

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;
 
@@ -60,11 +77,13 @@ private:
   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);

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<int16_t>(x);
           previous->y = static_cast<int16_t>(y);
+          ++context->statistics.relativeCoalesced;
           return STATUS_SUCCESS;
         }
       }
@@ -250,20 +267,27 @@ 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 =
     (context->reportHead + context->reportCount) % REPORT_QUEUE_LENGTH;
@@ -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<const HIDConsumerReport *>(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<unsigned long long>(statistics.direct),
+    static_cast<unsigned long long>(statistics.queued),
+    statistics.queueHighWater,
+    static_cast<unsigned long long>(statistics.relativeCoalesced),
+    static_cast<unsigned long long>(statistics.absoluteCoalesced),
+    static_cast<unsigned long long>(statistics.staleAbsoluteCompacted),
+    static_cast<unsigned long long>(statistics.keyboardDuplicates),
+    static_cast<unsigned long long>(statistics.consumerDuplicates),
+    static_cast<unsigned long long>(statistics.overflows),
+    static_cast<unsigned long long>(statistics.resetDiscarded));
+}
+
 VOID HIDEvtIoDeviceControl(
   _In_ WDFQUEUE queue,
   _In_ WDFREQUEST request,

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();
 };

idd/LGInput/ipc/CInputPipeClient.cpp

@@ -37,7 +37,13 @@ static constexpr uint16_t HID_CONSUMER_USAGE_VOLUME_DOWN = 0xea;
 
 bool CInputPipeClient::Start()
 {
+  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<const LGInputPipeMessage *>(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<unsigned long long>(received),
+      static_cast<unsigned long long>(malformed),
+      static_cast<unsigned long long>(sequenceResets),
+      static_cast<unsigned long long>(submitFailed));
+  }
+  CHIDDevice::LogStatistics();
+}

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_statReceived       = 0;
+  uint64_t      m_statMalformed      = 0;
+  uint64_t      m_statSequenceResets = 0;
+  uint64_t      m_statSubmitFailed   = 0;
+  ULONGLONG     m_lastStatistics     = 0;
 };