From 7f0f3cc01125522c409263c69c2ea16ea40301e7 Mon Sep 17 00:00:00 2001 From: "Justin Clark-Casey (justincc)" Date: Mon, 22 Jul 2013 23:30:09 +0100 Subject: [PATCH 1/5] 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 /// If IsRunningOut = false, then any request to send a packet is simply dropped. public bool IsRunningOutbound { get; private set; } + /// + /// Number of receives over which to establish a receive time average. + /// + private readonly static int s_receiveTimeSamples = 500; + + /// + /// Current number of samples taken to establish a receive time average. + /// + private int m_currentReceiveTimeSamples; + + /// + /// Cumulative receive time for the sample so far. + /// + private int m_receiveTicksInCurrentSamplePeriod; + + /// + /// The average time taken for each require receive in the last sample. + /// + public float AverageReceiveTicksForLastSamplePeriod { get; private set; } + /// /// Default constructor /// @@ -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) { } From 882efc1a2e0034216751af8f41f73c16e04912b1 Mon Sep 17 00:00:00 2001 From: Robert Adams Date: Mon, 22 Jul 2013 15:41:14 -0700 Subject: [PATCH 2/5] Added check for user movement specification before discarding an incoming AgentUpdate packet. This fixes the problem with vehicles not moving forward after the first up-arrow. Code to fix a potential exception when using different IClientAPIs. Conflicts: OpenSim/Region/ClientStack/Linden/UDP/LLClientView.cs --- .../ClientStack/Linden/UDP/LLClientView.cs | 71 +++++++++---------- .../ClientStack/Linden/UDP/LLUDPServer.cs | 3 +- 2 files changed, 35 insertions(+), 39 deletions(-) diff --git a/OpenSim/Region/ClientStack/Linden/UDP/LLClientView.cs b/OpenSim/Region/ClientStack/Linden/UDP/LLClientView.cs index 021b7c1ea3..32549c8ad2 100644 --- a/OpenSim/Region/ClientStack/Linden/UDP/LLClientView.cs +++ b/OpenSim/Region/ClientStack/Linden/UDP/LLClientView.cs @@ -359,12 +359,6 @@ namespace OpenSim.Region.ClientStack.LindenUDP /// cannot retain a reference to it outside of that method. /// private AgentUpdateArgs m_thisAgentUpdateArgs = new AgentUpdateArgs(); - private float qdelta1; - private float qdelta2; - private float vdelta1; - private float vdelta2; - private float vdelta3; - private float vdelta4; protected Dictionary m_packetHandlers = new Dictionary(); protected Dictionary m_genericPacketHandlers = new Dictionary(); //PauPaw:Local Generic Message handlers @@ -5576,7 +5570,9 @@ namespace OpenSim.Region.ClientStack.LindenUDP #region Scene/Avatar + // Threshold for body rotation to be a significant agent update private const float QDELTA = 0.000001f; + // Threshold for camera rotation to be a significant agent update private const float VDELTA = 0.01f; /// @@ -5587,14 +5583,6 @@ namespace OpenSim.Region.ClientStack.LindenUDP /// public bool CheckAgentUpdateSignificance(AgentUpdatePacket.AgentDataBlock x) { - // Compute these only once, when this function is called from down below - qdelta1 = 1 - (float)Math.Pow(Quaternion.Dot(x.BodyRotation, m_thisAgentUpdateArgs.BodyRotation), 2); - //qdelta2 = 1 - (float)Math.Pow(Quaternion.Dot(x.HeadRotation, m_thisAgentUpdateArgs.HeadRotation), 2); - vdelta1 = Vector3.Distance(x.CameraAtAxis, m_thisAgentUpdateArgs.CameraAtAxis); - vdelta2 = Vector3.Distance(x.CameraCenter, m_thisAgentUpdateArgs.CameraCenter); - vdelta3 = Vector3.Distance(x.CameraLeftAxis, m_thisAgentUpdateArgs.CameraLeftAxis); - vdelta4 = Vector3.Distance(x.CameraUpAxis, m_thisAgentUpdateArgs.CameraUpAxis); - return CheckAgentMovementUpdateSignificance(x) || CheckAgentCameraUpdateSignificance(x); } @@ -5606,24 +5594,27 @@ namespace OpenSim.Region.ClientStack.LindenUDP /// private bool CheckAgentMovementUpdateSignificance(AgentUpdatePacket.AgentDataBlock x) { - if ( - (qdelta1 > QDELTA) || + float qdelta1 = 1 - (float)Math.Pow(Quaternion.Dot(x.BodyRotation, m_thisAgentUpdateArgs.BodyRotation), 2); + //qdelta2 = 1 - (float)Math.Pow(Quaternion.Dot(x.HeadRotation, m_thisAgentUpdateArgs.HeadRotation), 2); + + bool movementSignificant = + (qdelta1 > QDELTA) // significant if body rotation above threshold // Ignoring head rotation altogether, because it's not being used for anything interesting up the stack - //(qdelta2 > QDELTA * 10) || - (x.ControlFlags != m_thisAgentUpdateArgs.ControlFlags) || - (x.Far != m_thisAgentUpdateArgs.Far) || - (x.Flags != m_thisAgentUpdateArgs.Flags) || - (x.State != m_thisAgentUpdateArgs.State) - ) - { + // || (qdelta2 > QDELTA * 10) // significant if head rotation above threshold + || (x.ControlFlags != m_thisAgentUpdateArgs.ControlFlags) // significant if control flags changed + || (x.ControlFlags != (byte)AgentManager.ControlFlags.NONE) // significant if user supplying any movement update commands + || (x.Far != m_thisAgentUpdateArgs.Far) // significant if far distance changed + || (x.Flags != m_thisAgentUpdateArgs.Flags) // significant if Flags changed + || (x.State != m_thisAgentUpdateArgs.State) // significant if Stats changed + ; + //if (movementSignificant) + //{ //m_log.DebugFormat("[LLCLIENTVIEW]: Bod {0} {1}", // qdelta1, qdelta2); - //m_log.DebugFormat("[LLCLIENTVIEW]: St {0} {1} {2} {3} (Thread {4})", - // x.ControlFlags, x.Flags, x.Far, x.State, Thread.CurrentThread.Name); - return true; - } - - return false; + //m_log.DebugFormat("[LLCLIENTVIEW]: St {0} {1} {2} {3}", + // x.ControlFlags, x.Flags, x.Far, x.State); + //} + return movementSignificant; } /// @@ -5634,23 +5625,27 @@ namespace OpenSim.Region.ClientStack.LindenUDP /// private bool CheckAgentCameraUpdateSignificance(AgentUpdatePacket.AgentDataBlock x) { - if ( - /* These 4 are the worst offenders! - * With Singularity, there is a bug where sometimes the spam on these doesn't stop */ + float vdelta1 = Vector3.Distance(x.CameraAtAxis, m_thisAgentUpdateArgs.CameraAtAxis); + float vdelta2 = Vector3.Distance(x.CameraCenter, m_thisAgentUpdateArgs.CameraCenter); + float vdelta3 = Vector3.Distance(x.CameraLeftAxis, m_thisAgentUpdateArgs.CameraLeftAxis); + float vdelta4 = Vector3.Distance(x.CameraUpAxis, m_thisAgentUpdateArgs.CameraUpAxis); + + bool cameraSignificant = (vdelta1 > VDELTA) || (vdelta2 > VDELTA) || (vdelta3 > VDELTA) || - (vdelta4 > VDELTA) - ) - { + (vdelta4 > VDELTA) + ; + + //if (cameraSignificant) + //{ //m_log.DebugFormat("[LLCLIENTVIEW]: Cam1 {0} {1}", // x.CameraAtAxis, x.CameraCenter); //m_log.DebugFormat("[LLCLIENTVIEW]: Cam2 {0} {1}", // x.CameraLeftAxis, x.CameraUpAxis); - return true; - } + //} - return false; + return cameraSignificant; } private bool HandleAgentUpdate(IClientAPI sener, Packet packet) diff --git a/OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs b/OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs index 13cd2675bc..bc4f1c5738 100644 --- a/OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs +++ b/OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs @@ -1346,9 +1346,10 @@ namespace OpenSim.Region.ClientStack.LindenUDP AgentUpdatePacket agentUpdate = (AgentUpdatePacket)packet; + LLClientView llClient = client as LLClientView; if (agentUpdate.AgentData.SessionID != client.SessionId || agentUpdate.AgentData.AgentID != client.AgentId - || !((LLClientView)client).CheckAgentUpdateSignificance(agentUpdate.AgentData)) + || !(llClient == null || llClient.CheckAgentUpdateSignificance(agentUpdate.AgentData)) ) { PacketPool.Instance.ReturnPacket(packet); return; From 94072fb633dca3e44373119a27773a269af07b72 Mon Sep 17 00:00:00 2001 From: "Justin Clark-Casey (justincc)" Date: Mon, 22 Jul 2013 23:58:45 +0100 Subject: [PATCH 3/5] Record raw number of UDP receives as clientstack.IncomingUDPReceivesCount --- .../Region/ClientStack/Linden/UDP/LLUDPServer.cs | 13 +++++++++++++ .../Region/ClientStack/Linden/UDP/OpenSimUDPBase.cs | 8 +++++++- 2 files changed, 20 insertions(+), 1 deletion(-) diff --git a/OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs b/OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs index 13cd2675bc..545e566c20 100644 --- a/OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs +++ b/OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs @@ -67,6 +67,19 @@ namespace OpenSim.Region.ClientStack.LindenUDP { m_udpServer.AddScene(scene); + StatsManager.RegisterStat( + new Stat( + "IncomingUDPReceivesCount", + "Number of inbound LL protocol packets processed", + "Number of inbound LL protocol packets processed", + "", + "clientstack", + scene.Name, + StatType.Pull, + MeasuresOfInterest.AverageChangeOverTime, + stat => stat.Value = m_udpServer.UdpReceives, + StatVerbosity.Debug)); + StatsManager.RegisterStat( new Stat( "IncomingPacketsProcessedCount", diff --git a/OpenSim/Region/ClientStack/Linden/UDP/OpenSimUDPBase.cs b/OpenSim/Region/ClientStack/Linden/UDP/OpenSimUDPBase.cs index 46a32615c5..b4044b510b 100644 --- a/OpenSim/Region/ClientStack/Linden/UDP/OpenSimUDPBase.cs +++ b/OpenSim/Region/ClientStack/Linden/UDP/OpenSimUDPBase.cs @@ -77,6 +77,11 @@ namespace OpenMetaverse /// If IsRunningOut = false, then any request to send a packet is simply dropped. public bool IsRunningOutbound { get; private set; } + /// + /// Number of UDP receives. + /// + public int UdpReceives { get; private set; } + /// /// Number of receives over which to establish a receive time average. /// @@ -295,6 +300,8 @@ namespace OpenMetaverse // to AsyncBeginReceive if (IsRunningInbound) { + UdpReceives++; + // Asynchronous mode will start another receive before the // callback for this packet is even fired. Very parallel :-) if (m_asyncPacketHandling) @@ -345,7 +352,6 @@ namespace OpenMetaverse if (!m_asyncPacketHandling) AsyncBeginReceive(); } - } } From 0d90834f867f6a31cca5ca48e27afcec2cf13dd3 Mon Sep 17 00:00:00 2001 From: "Justin Clark-Casey (justincc)" Date: Tue, 23 Jul 2013 00:15:58 +0100 Subject: [PATCH 4/5] Add clientstack.OutgoingUDPSendsCount stat to show number of outbound UDP packets sent by a region per second --- .../ClientStack/Linden/UDP/LLUDPServer.cs | 18 +++++++++++++++--- .../ClientStack/Linden/UDP/OpenSimUDPBase.cs | 7 +++++++ 2 files changed, 22 insertions(+), 3 deletions(-) diff --git a/OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs b/OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs index 5d21d8ced6..64774291f1 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( "IncomingUDPReceivesCount", - "Number of inbound LL protocol packets processed", - "Number of inbound LL protocol packets processed", + "Number of UDP receives performed", + "Number of UDP receives performed", "", "clientstack", scene.Name, @@ -93,6 +93,19 @@ namespace OpenSim.Region.ClientStack.LindenUDP stat => stat.Value = m_udpServer.IncomingPacketsProcessed, StatVerbosity.Debug)); + StatsManager.RegisterStat( + new Stat( + "OutgoingUDPSendsCount", + "Number of UDP sends performed", + "Number of UDP sends performed", + "", + "clientstack", + scene.Name, + StatType.Pull, + MeasuresOfInterest.AverageChangeOverTime, + stat => stat.Value = m_udpServer.UdpSends, + StatVerbosity.Debug)); + StatsManager.RegisterStat( new Stat( "AverageUDPProcessTime", @@ -856,7 +869,6 @@ namespace OpenSim.Region.ClientStack.LindenUDP PacketPool.Instance.ReturnPacket(packet); m_dataPresentEvent.Set(); - } private AutoResetEvent m_dataPresentEvent = new AutoResetEvent(false); diff --git a/OpenSim/Region/ClientStack/Linden/UDP/OpenSimUDPBase.cs b/OpenSim/Region/ClientStack/Linden/UDP/OpenSimUDPBase.cs index b4044b510b..d0ed7e81e7 100644 --- a/OpenSim/Region/ClientStack/Linden/UDP/OpenSimUDPBase.cs +++ b/OpenSim/Region/ClientStack/Linden/UDP/OpenSimUDPBase.cs @@ -82,6 +82,11 @@ namespace OpenMetaverse /// public int UdpReceives { get; private set; } + /// + /// Number of UDP sends + /// + public int UdpSends { get; private set; } + /// /// Number of receives over which to establish a receive time average. /// @@ -381,6 +386,8 @@ namespace OpenMetaverse { // UDPPacketBuffer buf = (UDPPacketBuffer)result.AsyncState; m_udpSocket.EndSendTo(result); + + UdpSends++; } catch (SocketException) { } catch (ObjectDisposedException) { } From 35e46c2836600abd845a74d8ef070c5b20302b55 Mon Sep 17 00:00:00 2001 From: "Justin Clark-Casey (justincc)" Date: Tue, 23 Jul 2013 00:31:57 +0100 Subject: [PATCH 5/5] Add clientstack.InboxPacketsCount stat. This records the number of packets waiting to be processed at the second stage (after initial UDP processing) If this consistently increases then this is a problem since it means the simulator is receiving more requests than it can distribute to other parts of the code. --- .../Region/ClientStack/Linden/UDP/LLUDPServer.cs | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs b/OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs index 64774291f1..020c9fbeb7 100644 --- a/OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs +++ b/OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs @@ -500,6 +500,19 @@ namespace OpenSim.Region.ClientStack.LindenUDP m_scene = (Scene)scene; m_location = new Location(m_scene.RegionInfo.RegionHandle); + StatsManager.RegisterStat( + new Stat( + "InboxPacketsCount", + "Number of LL protocol packets waiting for the second stage of processing after initial receive.", + "Number of LL protocol packets waiting for the second stage of processing after initial receive.", + "", + "clientstack", + scene.Name, + StatType.Pull, + MeasuresOfInterest.AverageChangeOverTime, + stat => stat.Value = packetInbox.Count, + StatVerbosity.Debug)); + // XXX: These stats are also pool stats but we register them separately since they are currently not // turned on and off by EnablePools()/DisablePools() StatsManager.RegisterStat(