From 7f0f3cc01125522c409263c69c2ea16ea40301e7 Mon Sep 17 00:00:00 2001
From: "Justin Clark-Casey (justincc)" <jjustincc@googlemail.com>
Date: Mon, 22 Jul 2013 23:30:09 +0100
Subject: [PATCH] Add AverageUDPProcessTime stat to try and get a handle on how
 long we're taking on the initial processing of a UDP packet.

If we're not receiving packets with multiple threads (m_asyncPacketHandling) then this is critical since it will limit the number of incoming UDP requests that the region can handle and affects packet loss.
If m_asyncPacketHandling then this is less critical though a long process will increase the scope for threads to race.
This is an experimental stat which may be changed.
---
 .../ClientStack/Linden/UDP/LLUDPServer.cs     | 19 ++++++++-
 .../ClientStack/Linden/UDP/OpenSimUDPBase.cs  | 39 +++++++++++++++++++
 2 files changed, 56 insertions(+), 2 deletions(-)

diff --git a/OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs b/OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs
index 32282af19a..32c541501c 100644
--- a/OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs
+++ b/OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs
@@ -70,8 +70,8 @@ namespace OpenSim.Region.ClientStack.LindenUDP
             StatsManager.RegisterStat(
                 new Stat(
                     "IncomingPacketsProcessedCount",
-                    "Number of inbound UDP packets processed",
-                    "Number of inbound UDP packets processed",
+                    "Number of inbound LL protocol packets processed",
+                    "Number of inbound LL protocol packets processed",
                     "",
                     "clientstack",
                     scene.Name,
@@ -79,6 +79,21 @@ namespace OpenSim.Region.ClientStack.LindenUDP
                     MeasuresOfInterest.AverageChangeOverTime,
                     stat => stat.Value = m_udpServer.IncomingPacketsProcessed,
                     StatVerbosity.Debug));
+
+            StatsManager.RegisterStat(
+                new Stat(
+                    "AverageUDPProcessTime",
+                    "Average number of milliseconds taken to process each incoming UDP packet in a sample.",
+                    "This is for initial receive processing which is separate from the later client LL packet processing stage.",
+                    "ms",
+                    "clientstack",
+                    scene.Name,
+                    StatType.Pull,
+                    MeasuresOfInterest.None,
+                    stat => stat.Value = m_udpServer.AverageReceiveTicksForLastSamplePeriod / TimeSpan.TicksPerMillisecond,
+//                    stat => 
+//                        stat.Value = Math.Round(m_udpServer.AverageReceiveTicksForLastSamplePeriod / TimeSpan.TicksPerMillisecond, 7),
+                    StatVerbosity.Debug));
         }
 
         public bool HandlesRegion(Location x)
diff --git a/OpenSim/Region/ClientStack/Linden/UDP/OpenSimUDPBase.cs b/OpenSim/Region/ClientStack/Linden/UDP/OpenSimUDPBase.cs
index a91914140a..46a32615c5 100644
--- a/OpenSim/Region/ClientStack/Linden/UDP/OpenSimUDPBase.cs
+++ b/OpenSim/Region/ClientStack/Linden/UDP/OpenSimUDPBase.cs
@@ -77,6 +77,26 @@ namespace OpenMetaverse
         /// <remarks>If IsRunningOut = false, then any request to send a packet is simply dropped.</remarks>
         public bool IsRunningOutbound { get; private set; }
 
+        /// <summary>
+        /// Number of receives over which to establish a receive time average.
+        /// </summary>
+        private readonly static int s_receiveTimeSamples = 500;
+
+        /// <summary>
+        /// Current number of samples taken to establish a receive time average.
+        /// </summary>
+        private int m_currentReceiveTimeSamples;
+
+        /// <summary>
+        /// Cumulative receive time for the sample so far.
+        /// </summary>
+        private int m_receiveTicksInCurrentSamplePeriod;
+
+        /// <summary>
+        /// The average time taken for each require receive in the last sample.
+        /// </summary>
+        public float AverageReceiveTicksForLastSamplePeriod { get; private set; }
+
         /// <summary>
         /// Default constructor
         /// </summary>
@@ -286,6 +306,8 @@ namespace OpenMetaverse
 
                 try
                 {
+                    int startTick = Util.EnvironmentTickCount();
+
                     // get the length of data actually read from the socket, store it with the
                     // buffer
                     buffer.DataLength = m_udpSocket.EndReceiveFrom(iar, ref buffer.RemoteEndPoint);
@@ -293,6 +315,23 @@ namespace OpenMetaverse
                     // call the abstract method PacketReceived(), passing the buffer that
                     // has just been filled from the socket read.
                     PacketReceived(buffer);
+
+                    // If more than one thread can be calling AsyncEndReceive() at once (e.g. if m_asyncPacketHandler)
+                    // then a particular stat may be inaccurate due to a race condition.  We won't worry about this
+                    // since this should be rare and  won't cause a runtime problem.
+                    if (m_currentReceiveTimeSamples >= s_receiveTimeSamples)
+                    {
+                        AverageReceiveTicksForLastSamplePeriod 
+                            = (float)m_receiveTicksInCurrentSamplePeriod / s_receiveTimeSamples;
+
+                        m_receiveTicksInCurrentSamplePeriod = 0;
+                        m_currentReceiveTimeSamples = 0;
+                    }
+                    else
+                    {
+                        m_receiveTicksInCurrentSamplePeriod += Util.EnvironmentTickCountSubtract(startTick);
+                        m_currentReceiveTimeSamples++;
+                    }
                 }
                 catch (SocketException) { }
                 catch (ObjectDisposedException) { }