Eliminate a few unnecessary calculations in the maintenance loop.

Also uses wait event instead of sleep for periodicity control.

CONTRIBUTORS.txt

@@ -72,10 +72,12 @@ what it is today.
 * Allen Kerensky
 * BigFootAg
 * BlueWall Slade
+* bobshaffer2
 * brianw/Sir_Ahzz
 * CharlieO
 * ChrisDown
 * Chris Yeoh (IBM)
+* cinderblocks
 * controlbreak
 * coyled
 * ctrlaltdavid (David Rowe)

OpenSim/Framework/Monitoring/JobEngine.cs

@@ -0,0 +1,312 @@
+/*
+ * Copyright (c) Contributors, http://opensimulator.org/
+ * See CONTRIBUTORS.TXT for a full list of copyright holders.
+ *
+ * Redistribution and use in source and binary forms, with or without
+ * modification, are permitted provided that the following conditions are met:
+ *     * Redistributions of source code must retain the above copyright
+ *       notice, this list of conditions and the following disclaimer.
+ *     * Redistributions in binary form must reproduce the above copyright
+ *       notice, this list of conditions and the following disclaimer in the
+ *       documentation and/or other materials provided with the distribution.
+ *     * Neither the name of the OpenSimulator Project nor the
+ *       names of its contributors may be used to endorse or promote products
+ *       derived from this software without specific prior written permission.
+ *
+ * THIS SOFTWARE IS PROVIDED BY THE DEVELOPERS ``AS IS'' AND ANY
+ * EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED
+ * WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE
+ * DISCLAIMED. IN NO EVENT SHALL THE CONTRIBUTORS BE LIABLE FOR ANY
+ * DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES
+ * (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES;
+ * LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND
+ * ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
+ * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS
+ * SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
+ */
+
+using System;
+using System.Collections.Concurrent;
+using System.Reflection;
+using System.Threading;
+using log4net;
+using OpenSim.Framework;
+
+namespace OpenSim.Framework.Monitoring
+{
+    public class Job
+    {
+        public string Name;
+        public WaitCallback Callback;
+        public object O;
+
+        public Job(string name, WaitCallback callback, object o)
+        {
+            Name = name;
+            Callback = callback;
+            O = o;
+        }
+    }
+
+    public class JobEngine
+    {
+        private static readonly ILog m_log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);
+
+        public int LogLevel { get; set; }
+
+        public bool IsRunning { get; private set; } 
+
+        /// <summary>
+        /// The timeout in milliseconds to wait for at least one event to be written when the recorder is stopping.
+        /// </summary>
+        public int RequestProcessTimeoutOnStop { get; set; }
+
+        /// <summary>
+        /// Controls whether we need to warn in the log about exceeding the max queue size.
+        /// </summary>
+        /// <remarks>
+        /// This is flipped to false once queue max has been exceeded and back to true when it falls below max, in 
+        /// order to avoid spamming the log with lots of warnings.
+        /// </remarks>
+        private bool m_warnOverMaxQueue = true;
+
+        private BlockingCollection<Job> m_requestQueue;
+
+        private CancellationTokenSource m_cancelSource = new CancellationTokenSource();
+
+        private Stat m_requestsWaitingStat;
+
+        private Job m_currentJob;
+
+        /// <summary>
+        /// Used to signal that we are ready to complete stop.
+        /// </summary>
+        private ManualResetEvent m_finishedProcessingAfterStop = new ManualResetEvent(false);
+
+        public JobEngine()
+        {
+            RequestProcessTimeoutOnStop = 5000;
+
+            MainConsole.Instance.Commands.AddCommand(
+                "Debug",
+                false,
+                "debug jobengine",
+                "debug jobengine <start|stop|status>",
+                "Start, stop or get status of the job engine.",
+                "If stopped then all jobs are processed immediately.",
+                HandleControlCommand);
+        }
+
+        public void Start()
+        {
+            lock (this)
+            {
+                if (IsRunning)
+                    return;
+
+                IsRunning = true;
+
+                m_finishedProcessingAfterStop.Reset();
+
+                m_requestQueue = new BlockingCollection<Job>(new ConcurrentQueue<Job>(), 5000);
+
+                m_requestsWaitingStat = 
+                    new Stat(
+                        "JobsWaiting",
+                        "Number of jobs waiting for processing.",
+                        "",
+                        "",
+                        "server",
+                        "jobengine",
+                        StatType.Pull,
+                        MeasuresOfInterest.None,
+                        stat => stat.Value = m_requestQueue.Count,
+                        StatVerbosity.Debug);
+
+                StatsManager.RegisterStat(m_requestsWaitingStat);
+
+                Watchdog.StartThread(
+                    ProcessRequests,
+                    "JobEngineThread",
+                    ThreadPriority.Normal,
+                    false,
+                    true,
+                    null,
+                    int.MaxValue);
+            }
+        }
+
+        public void Stop()
+        {   
+            lock (this)
+            {
+                try
+                {
+                    if (!IsRunning)
+                        return;
+
+                    IsRunning = false;
+
+                    int requestsLeft = m_requestQueue.Count;
+
+                    if (requestsLeft <= 0)
+                    {
+                        m_cancelSource.Cancel();
+                    }
+                    else 
+                    {
+                        m_log.InfoFormat("[JOB ENGINE]: Waiting to write {0} events after stop.", requestsLeft);
+
+                        while (requestsLeft > 0)
+                        {
+                            if (!m_finishedProcessingAfterStop.WaitOne(RequestProcessTimeoutOnStop))
+                            {
+                                // After timeout no events have been written
+                                if (requestsLeft == m_requestQueue.Count)
+                                {
+                                    m_log.WarnFormat(
+                                        "[JOB ENGINE]: No requests processed after {0} ms wait.  Discarding remaining {1} requests", 
+                                        RequestProcessTimeoutOnStop, requestsLeft);
+
+                                    break;
+                                }
+                            }
+
+                            requestsLeft = m_requestQueue.Count;
+                        }
+                    }
+                }
+                finally
+                {
+                    m_cancelSource.Dispose();
+                    StatsManager.DeregisterStat(m_requestsWaitingStat);
+                    m_requestsWaitingStat = null;
+                    m_requestQueue = null;
+                }
+            }
+        }
+
+        public bool QueueRequest(string name, WaitCallback req, object o)
+        {
+            if (LogLevel >= 1)
+                m_log.DebugFormat("[JOB ENGINE]: Queued job {0}", name);
+
+            if (m_requestQueue.Count < m_requestQueue.BoundedCapacity)
+            {
+                //                m_log.DebugFormat(
+                //                    "[OUTGOING QUEUE REFILL ENGINE]: Adding request for categories {0} for {1} in {2}", 
+                //                    categories, client.AgentID, m_udpServer.Scene.Name);
+
+                m_requestQueue.Add(new Job(name, req, o));
+
+                if (!m_warnOverMaxQueue)
+                    m_warnOverMaxQueue = true;
+
+                return true;
+            }
+            else
+            {
+                if (m_warnOverMaxQueue)
+                {
+//                    m_log.WarnFormat(
+//                        "[JOB ENGINE]: Request queue at maximum capacity, not recording request from {0} in {1}", 
+//                        client.AgentID, m_udpServer.Scene.Name);
+
+                    m_log.WarnFormat("[JOB ENGINE]: Request queue at maximum capacity, not recording job");
+
+                    m_warnOverMaxQueue = false;
+                }
+
+                return false;
+            }
+        }
+
+        private void ProcessRequests()
+        {
+            try
+            {
+                while (IsRunning || m_requestQueue.Count > 0)
+                {
+                    m_currentJob = m_requestQueue.Take(m_cancelSource.Token);
+
+                    //                QueueEmpty callback = req.Client.OnQueueEmpty;                      
+                    //
+                    //                if (callback != null)
+                    //                {               
+                    //                    try 
+                    //                    { 
+                    //                        callback(req.Categories); 
+                    //                    }
+                    //                    catch (Exception e) 
+                    //                    { 
+                    //                        m_log.Error("[OUTGOING QUEUE REFILL ENGINE]: ProcessRequests(" + req.Categories + ") threw an exception: " + e.Message, e); 
+                    //                    }
+                    //                }
+
+                    if (LogLevel >= 1)
+                        m_log.DebugFormat("[JOB ENGINE]: Processing job {0}", m_currentJob.Name);
+
+                    m_currentJob.Callback.Invoke(m_currentJob.O);
+
+                    if (LogLevel >= 1)
+                        m_log.DebugFormat("[JOB ENGINE]: Processed job {0}", m_currentJob.Name);
+
+                    m_currentJob = null;
+                }
+            }
+            catch (OperationCanceledException)
+            {
+            }
+
+            m_finishedProcessingAfterStop.Set();
+        }
+
+        private void HandleControlCommand(string module, string[] args)
+        {
+//            if (SceneManager.Instance.CurrentScene != null && SceneManager.Instance.CurrentScene != m_udpServer.Scene)
+//                return;
+
+            if (args.Length < 3)
+            {
+                MainConsole.Instance.Output("Usage: debug jobengine <stop|start|status|loglevel>");
+                return;
+            }
+
+            string subCommand = args[2];
+
+            if (subCommand == "stop")
+            {
+                Stop();
+                MainConsole.Instance.OutputFormat("Stopped job engine.");
+            }
+            else if (subCommand == "start")
+            {
+                Start();
+                MainConsole.Instance.OutputFormat("Started job engine.");
+            }
+            else if (subCommand == "status")
+            {
+                MainConsole.Instance.OutputFormat("Job engine running: {0}", IsRunning);
+                MainConsole.Instance.OutputFormat("Current job {0}", m_currentJob != null ? m_currentJob.Name : "none");
+                MainConsole.Instance.OutputFormat(
+                    "Jobs waiting: {0}", IsRunning ? m_requestQueue.Count.ToString() : "n/a");
+                MainConsole.Instance.OutputFormat("Log Level: {0}", LogLevel);
+            }
+
+            else if (subCommand == "loglevel")
+            {
+//                int logLevel;
+                int logLevel = int.Parse(args[3]);
+//                if (ConsoleUtil.TryParseConsoleInt(MainConsole.Instance, args[4], out logLevel))
+//                {                 
+                    LogLevel = logLevel;
+                    MainConsole.Instance.OutputFormat("Set log level to {0}", LogLevel);
+//                }
+            }
+            else 
+            {
+                MainConsole.Instance.OutputFormat("Unrecognized job engine subcommand {0}", subCommand);
+            }
+        }
+    }
+}

OpenSim/Framework/Monitoring/Stats/Stat.cs

@@ -171,7 +171,8 @@ namespace OpenSim.Framework.Monitoring
             foreach (char c in DisallowedShortNameCharacters)
             {
                 if (shortName.IndexOf(c) != -1)
-                    throw new Exception(string.Format("Stat name {0} cannot contain character {1}", shortName, c));
+                    shortName = shortName.Replace(c, '#');
+//                    throw new Exception(string.Format("Stat name {0} cannot contain character {1}", shortName, c));
             }
 
             ShortName = shortName;

OpenSim/Framework/Monitoring/Watchdog.cs

@@ -133,6 +133,8 @@ namespace OpenSim.Framework.Monitoring
         /// /summary>
         public static event Action<ThreadWatchdogInfo> OnWatchdogTimeout;
 
+        public static JobEngine JobEngine { get; private set; }
+
         /// <summary>
         /// Is this watchdog active?
         /// </summary>
@@ -173,6 +175,7 @@ namespace OpenSim.Framework.Monitoring
 
         static Watchdog()
         {
+            JobEngine = new JobEngine();
             m_threads = new Dictionary<int, ThreadWatchdogInfo>();
             m_watchdogTimer = new System.Timers.Timer(WATCHDOG_INTERVAL_MS);
             m_watchdogTimer.AutoReset = false;
@@ -449,5 +452,20 @@ namespace OpenSim.Framework.Monitoring
 
             m_watchdogTimer.Start();
         }
+
+        public static void RunWhenPossible(string jobType, WaitCallback callback, string name, object obj, bool log = false)
+        {
+            if (Util.FireAndForgetMethod == FireAndForgetMethod.RegressionTest)           
+            {
+                Culture.SetCurrentCulture();
+                callback(obj);
+                return;
+            }
+
+            if (JobEngine.IsRunning)
+                JobEngine.QueueRequest(name, callback, obj);
+            else
+                RunInThread(callback, name, obj, log);
+        }
     }
 }

OpenSim/Region/ClientStack/Linden/UDP/LLUDPClient.cs

@@ -76,6 +76,12 @@ namespace OpenSim.Region.ClientStack.LindenUDP
         /// or removed, this number must also change</summary>
         const int THROTTLE_CATEGORY_COUNT = 8;
 
+        /// <summary>
+        /// Controls whether information is logged about each outbound packet immediately before it is sent.  For debug purposes.
+        /// </summary>
+        /// <remarks>Any level above 0 will turn on logging.</remarks>
+        public int DebugDataOutLevel { get; set; }
+
         /// <summary>Fired when updated networking stats are produced for this client</summary>
         public event PacketStats OnPacketStats;
         /// <summary>Fired when the queue for a packet category is empty. This event can be

OpenSim/Region/ClientStack/Linden/UDP/LLUDPServer.cs

@@ -686,7 +686,7 @@ namespace OpenSim.Region.ClientStack.LindenUDP
             MainConsole.Instance.Commands.AddCommand(
                 "Debug", false, "debug lludp packet",
                  "debug lludp packet [--default | --all] <level> [<avatar-first-name> <avatar-last-name>]",
-                 "Turn on packet debugging",
+                 "Turn on packet debugging.  This logs information when the client stack hands a processed packet off to downstream code or when upstream code first requests that a certain packet be sent.",
                    "If level >  255 then all incoming and outgoing packets are logged.\n"
                  + "If level <= 255 then incoming AgentUpdate and outgoing SimStats and SimulatorViewerTimeMessage packets are not logged.\n"
                  + "If level <= 200 then incoming RequestImage and outgoing ImagePacket, ImageData, LayerData and CoarseLocationUpdate packets are not logged.\n"
@@ -699,6 +699,15 @@ namespace OpenSim.Region.ClientStack.LindenUDP
                  + "If an avatar name is given then only packets from that avatar are logged.",
                  HandlePacketCommand);
 
+            MainConsole.Instance.Commands.AddCommand(
+                "Debug", false, "debug lludp data out",
+                "debug lludp data out <level> <avatar-first-name> <avatar-last-name>\"",
+                "Turn on debugging for final outgoing data to the given user's client.",
+                "This operates at a much lower level than the packet command and prints out available details when the data is actually sent.\n"
+                + "If level >  0 then information about all outgoing UDP data for this avatar is logged.\n"
+                + "If level <= 0 then no information about outgoing UDP data for this avatar is logged.",
+                HandleDataCommand);
+
             MainConsole.Instance.Commands.AddCommand(
                 "Debug", false, "debug lludp drop",
                 "debug lludp drop <in|out> <add|remove> <packet-name>",
@@ -755,6 +764,37 @@ namespace OpenSim.Region.ClientStack.LindenUDP
                 HandleAgentUpdateCommand);
         }
 
+        private void HandleDataCommand(string module, string[] args)
+        {
+            if (SceneManager.Instance.CurrentScene != null && SceneManager.Instance.CurrentScene != Scene)
+                return;
+
+            if (args.Length != 7)
+            {
+                MainConsole.Instance.OutputFormat("Usage: debug lludp data out <true|false> <avatar-first-name> <avatar-last-name>");
+                return;
+            }
+
+            int level;
+            if (!ConsoleUtil.TryParseConsoleInt(MainConsole.Instance, args[4], out level))
+                return;
+
+            string firstName = args[5];
+            string lastName = args[6];
+
+            Scene.ForEachScenePresence(sp =>
+            {
+                if (sp.Firstname == firstName && sp.Lastname == lastName)
+                {
+                    MainConsole.Instance.OutputFormat(
+                        "Data debug for {0} ({1}) set to {2} in {3}",
+                        sp.Name, sp.IsChildAgent ? "child" : "root", level, Scene.Name);
+
+                    ((LLClientView)sp.ControllingClient).UDPClient.DebugDataOutLevel = level;
+                }
+            });
+        }
+
         private void HandlePacketCommand(string module, string[] args)
         {
             if (SceneManager.Instance.CurrentScene != null && SceneManager.Instance.CurrentScene != Scene)
@@ -1360,6 +1400,11 @@ namespace OpenSim.Region.ClientStack.LindenUDP
             // is 100% correct
             PacketsSentCount++;
 
+            if (udpClient.DebugDataOutLevel > 0)
+                m_log.DebugFormat(
+                    "[LLUDPSERVER]: Sending packet #{0} (rel: {1}, res: {2}) to {3} from {4}",
+                    outgoingPacket.SequenceNumber, isReliable, isResend, udpClient.AgentID, Scene.Name);
+
             // Put the UDP payload on the wire
             AsyncBeginSend(buffer);
 
@@ -2055,6 +2100,8 @@ namespace OpenSim.Region.ClientStack.LindenUDP
 
         private void IncomingPacketHandler()
         {
+            Thread.CurrentThread.Priority = ThreadPriority.Highest;
+
             // Set this culture for the thread that incoming packets are received
             // on to en-US to avoid number parsing issues
             Culture.SetCurrentCulture();
@@ -2100,6 +2147,8 @@ namespace OpenSim.Region.ClientStack.LindenUDP
 
         private void OutgoingPacketHandler()
         {
+            Thread.CurrentThread.Priority = ThreadPriority.Highest;
+
             // Set this culture for the thread that outgoing packets are sent
             // on to en-US to avoid number parsing issues
             Culture.SetCurrentCulture();

OpenSim/Region/ClientStack/Linden/UDP/OutgoingQueueRefillEngine.cs

@@ -217,6 +217,8 @@ namespace OpenSim.Region.ClientStack.LindenUDP
 
         private void ProcessRequests()
         {
+            Thread.CurrentThread.Priority = ThreadPriority.Highest;
+
             try
             {
                 while (IsRunning || m_requestQueue.Count > 0)

OpenSim/Region/Framework/Scenes/Scene.cs

@@ -360,19 +360,41 @@ namespace OpenSim.Region.Framework.Scenes
         public uint MaintenanceRun { get; private set; }
 
         /// <summary>
-        /// The minimum length of time in seconds that will be taken for a scene frame.  If the frame takes less time then we
+        /// The minimum length of time in milliseconds that will be taken for a scene frame.  If the frame takes less time then we
         /// will sleep for the remaining period.
         /// </summary>
         /// <remarks>
         /// One can tweak this number to experiment.  One current effect of reducing it is to make avatar animations
         /// occur too quickly (viewer 1) or with even more slide (viewer 2).
         /// </remarks>
-        public float MinFrameTime { get; private set; }
+        public int MinFrameTicks 
+        { 
+            get { return m_minFrameTicks; } 
+            private set 
+            { 
+                m_minFrameTicks = value;
+                MinFrameSeconds = (float)m_minFrameTicks / 1000;
+            }
+        } 
+        private int m_minFrameTicks;
 
         /// <summary>
-        /// The minimum length of time in seconds that will be taken for a maintenance run.
+        /// The minimum length of time in seconds that will be taken for a scene frame.
         /// </summary>
-        public float MinMaintenanceTime { get; private set; }
+        /// <remarks>
+        /// Always derived from MinFrameTicks.
+        /// </remarks>
+        public float MinFrameSeconds { get; private set; }
+
+        /// <summary>
+        /// The minimum length of time in milliseconds that will be taken for a scene frame.  If the frame takes less time then we
+        /// will sleep for the remaining period.
+        /// </summary>
+        /// <remarks>
+        /// One can tweak this number to experiment.  One current effect of reducing it is to make avatar animations
+        /// occur too quickly (viewer 1) or with even more slide (viewer 2).
+        /// </remarks>
+        public int MinMaintenanceTicks { get; set; }
 
         private int m_update_physics = 1;
         private int m_update_entitymovement = 1;
@@ -412,8 +434,16 @@ namespace OpenSim.Region.Framework.Scenes
         /// asynchronously from the update loop.
         /// </summary>
         private bool m_cleaningTemps = false;
+                
+        /// <summary>
+        /// Used to control main scene thread looping time when not updating via timer.
+        /// </summary>
+        private ManualResetEvent m_updateWaitEvent = new ManualResetEvent(false);
 
-//        private Object m_heartbeatLock = new Object();
+        /// <summary>
+        /// Used to control maintenance thread runs.
+        /// </summary>
+        private ManualResetEvent m_maintenanceWaitEvent = new ManualResetEvent(false);
 
         // TODO: Possibly stop other classes being able to manipulate this directly.
         private SceneGraph m_sceneGraph;
@@ -782,8 +812,8 @@ namespace OpenSim.Region.Framework.Scenes
             : this(regInfo, physicsScene)
         {
             m_config = config;
-            MinFrameTime = 0.089f;
-            MinMaintenanceTime = 1;
+            MinFrameTicks = 89;
+            MinMaintenanceTicks = 1000;
             SeeIntoRegion = true;
 
             Random random = new Random();
@@ -1005,7 +1035,9 @@ namespace OpenSim.Region.Framework.Scenes
                     }
                 }
 
-                MinFrameTime              = startupConfig.GetFloat( "MinFrameTime",                      MinFrameTime);
+                if (startupConfig.Contains("MinFrameTime"))
+                    MinFrameTicks = (int)(startupConfig.GetFloat("MinFrameTime") * 1000);
+
                 m_update_backup           = startupConfig.GetInt(   "UpdateStorageEveryNFrames",         m_update_backup);
                 m_update_coarse_locations = startupConfig.GetInt(   "UpdateCoarseLocationsEveryNFrames", m_update_coarse_locations);
                 m_update_entitymovement   = startupConfig.GetInt(   "UpdateEntityMovementEveryNFrames",  m_update_entitymovement);
@@ -1018,7 +1050,7 @@ namespace OpenSim.Region.Framework.Scenes
             }
 
             // FIXME: Ultimately this should be in a module.
-            SendPeriodicAppearanceUpdates = true;
+            SendPeriodicAppearanceUpdates = false;
             
             IConfig appearanceConfig = m_config.Configs["Appearance"];
             if (appearanceConfig != null)
@@ -1444,13 +1476,14 @@ namespace OpenSim.Region.Framework.Scenes
 
             if (UpdateOnTimer)
             {
-                m_sceneUpdateTimer = new Timer(MinFrameTime * 1000);
+                m_sceneUpdateTimer = new Timer(MinFrameTicks);
                 m_sceneUpdateTimer.AutoReset = true;
                 m_sceneUpdateTimer.Elapsed += Update;
                 m_sceneUpdateTimer.Start();
             }
             else
             {
+                Thread.CurrentThread.Priority = ThreadPriority.Highest;
                 Update(-1);
                 Watchdog.RemoveThread();
                 m_isRunning = false;
@@ -1530,19 +1563,19 @@ namespace OpenSim.Region.Framework.Scenes
                 previousMaintenanceTick = m_lastMaintenanceTick;
                 m_lastMaintenanceTick = Util.EnvironmentTickCount();
                 runtc = Util.EnvironmentTickCountSubtract(m_lastMaintenanceTick, runtc);
-                runtc = (int)(MinMaintenanceTime * 1000) - runtc;
+                runtc = MinMaintenanceTicks - runtc;
     
                 if (runtc > 0)
-                    Thread.Sleep(runtc);
+                    m_maintenanceWaitEvent.WaitOne(runtc);
     
                 // Optionally warn if a frame takes double the amount of time that it should.
                 if (DebugUpdates
                     && Util.EnvironmentTickCountSubtract(
-                        m_lastMaintenanceTick, previousMaintenanceTick) > (int)(MinMaintenanceTime * 1000 * 2))
+                        m_lastMaintenanceTick, previousMaintenanceTick) > MinMaintenanceTicks * 2)
                     m_log.WarnFormat(
                         "[SCENE]: Maintenance took {0} ms (desired max {1} ms) in {2}",
                         Util.EnvironmentTickCountSubtract(m_lastMaintenanceTick, previousMaintenanceTick),
-                        MinMaintenanceTime * 1000,
+                        MinMaintenanceTicks,
                         RegionInfo.RegionName);
             }
         }
@@ -1594,7 +1627,7 @@ namespace OpenSim.Region.Framework.Scenes
                     if (Frame % m_update_physics == 0)
                     {
                         if (PhysicsEnabled)
-                            physicsFPS = m_sceneGraph.UpdatePhysics(MinFrameTime);
+                            physicsFPS = m_sceneGraph.UpdatePhysics(MinFrameSeconds);
     
                         if (SynchronizeScene != null)
                             SynchronizeScene(this);
@@ -1706,18 +1739,16 @@ namespace OpenSim.Region.Framework.Scenes
                 {
                     Watchdog.UpdateThread();
 
-                    tmpMS = Util.EnvironmentTickCountSubtract(Util.EnvironmentTickCount(), m_lastFrameTick);
-                    tmpMS = (int)(MinFrameTime * 1000) - tmpMS;
+                    spareMS = MinFrameTicks - Util.EnvironmentTickCountSubtract(m_lastFrameTick);
 
-                    if (tmpMS > 0)
-                    {
-                        spareMS = tmpMS;
-                        Thread.Sleep(tmpMS);
-                    }           
+                    if (spareMS > 0)
+                        m_updateWaitEvent.WaitOne(spareMS);
+                    else
+                        spareMS = 0;
                 }
                 else
                 {
-                    spareMS = Math.Max(0, (int)(MinFrameTime * 1000) - physicsMS2 - agentMS - physicsMS -otherMS);
+                    spareMS = Math.Max(0, MinFrameTicks - physicsMS2 - agentMS - physicsMS - otherMS);
                 }
 
                 previousFrameTick = m_lastFrameTick;
@@ -1740,11 +1771,11 @@ namespace OpenSim.Region.Framework.Scenes
                 // Optionally warn if a frame takes double the amount of time that it should.
                 if (DebugUpdates
                     && Util.EnvironmentTickCountSubtract(
-                        m_lastFrameTick, previousFrameTick) > (int)(MinFrameTime * 1000 * 2))
+                        m_lastFrameTick, previousFrameTick) > MinFrameTicks * 2)
                     m_log.WarnFormat(
                         "[SCENE]: Frame took {0} ms (desired max {1} ms) in {2}",
                         Util.EnvironmentTickCountSubtract(m_lastFrameTick, previousFrameTick),
-                        MinFrameTime * 1000,
+                        MinFrameTicks,
                         RegionInfo.RegionName);
             }
 
@@ -4466,14 +4497,9 @@ namespace OpenSim.Region.Framework.Scenes
                 sp.LifecycleState = ScenePresenceState.Removing;
             }
 
-            if (sp != null)
-            {
-                sp.ControllingClient.Close(force);
-                return true;
-            }
+            sp.ControllingClient.Close(force);
 
-            // Agent not here 
-            return false;
+            return true;
         }
 
         /// <summary>

OpenSim/Region/Framework/Scenes/SceneObjectPart.cs

@@ -1589,20 +1589,29 @@ namespace OpenSim.Region.Framework.Scenes
 
         public void AddTextureAnimation(Primitive.TextureAnimation pTexAnim)
         {
-            byte[] data = new byte[16];
-            int pos = 0;
+            byte[] data;
 
-            // The flags don't like conversion from uint to byte, so we have to do
-            // it the crappy way.  See the above function :(
+            if (pTexAnim.Flags == Primitive.TextureAnimMode.ANIM_OFF)
+            {
+                data = Utils.EmptyBytes;
+            }
+            else
+            {
+                data = new byte[16];
+                int pos = 0;
 
-            data[pos] = ConvertScriptUintToByte((uint)pTexAnim.Flags); pos++;
-            data[pos] = (byte)pTexAnim.Face; pos++;
-            data[pos] = (byte)pTexAnim.SizeX; pos++;
-            data[pos] = (byte)pTexAnim.SizeY; pos++;
+                // The flags don't like conversion from uint to byte, so we have to do
+                // it the crappy way.  See the above function :(
 
-            Utils.FloatToBytes(pTexAnim.Start).CopyTo(data, pos);
-            Utils.FloatToBytes(pTexAnim.Length).CopyTo(data, pos + 4);
-            Utils.FloatToBytes(pTexAnim.Rate).CopyTo(data, pos + 8);
+                data[pos] = ConvertScriptUintToByte((uint)pTexAnim.Flags); pos++;
+                data[pos] = (byte)pTexAnim.Face; pos++;
+                data[pos] = (byte)pTexAnim.SizeX; pos++;
+                data[pos] = (byte)pTexAnim.SizeY; pos++;
+
+                Utils.FloatToBytes(pTexAnim.Start).CopyTo(data, pos);
+                Utils.FloatToBytes(pTexAnim.Length).CopyTo(data, pos + 4);
+                Utils.FloatToBytes(pTexAnim.Rate).CopyTo(data, pos + 8);
+            }
 
             m_TextureAnimation = data;
         }

OpenSim/Region/Framework/Scenes/ScenePresence.cs

@@ -1228,10 +1228,14 @@ namespace OpenSim.Region.Framework.Scenes
                 // viewers without (e.g. v1 viewers) will not, so we still need to make this call.
                 if (Scene.AttachmentsModule != null)
                 {
-                    Util.FireAndForget(o =>
-                    {
-                        Scene.AttachmentsModule.RezAttachments(this);
-                    });
+                    if (Watchdog.JobEngine.IsRunning)
+                        Watchdog.RunWhenPossible(
+                            "RezAttachments", 
+                            o => Scene.AttachmentsModule.RezAttachments(this), 
+                            string.Format("Rez attachments for {0} in {1}", Name, Scene.Name), 
+                            null);
+                    else
+                        Util.FireAndForget(o => Scene.AttachmentsModule.RezAttachments(this));
                 }
             }
             else
@@ -2618,7 +2622,6 @@ namespace OpenSim.Region.Framework.Scenes
                     }
                 }
 
-                Vector3 sitPartWorldPosition = part.GetWorldPosition();
                 ControllingClient.SendClearFollowCamProperties(part.ParentUUID);
 
                 ParentID = 0;
@@ -2647,13 +2650,13 @@ namespace OpenSim.Region.Framework.Scenes
 
 //                Vector3 standPositionAdjustment 
 //                    = part.SitTargetPosition + new Vector3(0.5f, 0f, m_sitAvatarHeight / 2f);
-                Vector3 adjustmentForSitPosition = (part.SitTargetPosition + OffsetPosition) * part.GetWorldRotation();
+                Vector3 adjustmentForSitPosition = (OffsetPosition - SIT_TARGET_ADJUSTMENT) * part.GetWorldRotation();
 
                 // XXX: This is based on the physics capsule sizes.  Need to find a better way to read this rather than
                 // hardcoding here.
                 Vector3 adjustmentForSitPose = new Vector3(0.74f, 0f, 0f) * standRotation;
 
-                Vector3 standPos = sitPartWorldPosition + adjustmentForSitPosition + adjustmentForSitPose;
+                Vector3 standPos = part.ParentGroup.AbsolutePosition + adjustmentForSitPosition + adjustmentForSitPose;
 
 //                m_log.DebugFormat(
 //                    "[SCENE PRESENCE]: Setting stand to pos {0}, (adjustmentForSitPosition {1}, adjustmentForSitPose {2}) rotation {3} for {4} in {5}", 
@@ -3363,7 +3366,7 @@ namespace OpenSim.Region.Framework.Scenes
             SentInitialDataToClient = true;
 
             // Send all scene object to the new client
-            Watchdog.RunInThread(delegate
+            Watchdog.RunWhenPossible("SendInitialDataToClient", delegate
             {
 //                m_log.DebugFormat(
 //                    "[SCENE PRESENCE]: Sending initial data to {0} agent {1} in {2}, tp flags {3}", 

OpenSim/Region/Framework/Scenes/SimStatsReporter.cs

@@ -224,7 +224,7 @@ namespace OpenSim.Region.Framework.Scenes
         public SimStatsReporter(Scene scene)
         {
             m_scene = scene;
-            m_reportedFpsCorrectionFactor = scene.MinFrameTime * m_nominalReportedFps;
+            m_reportedFpsCorrectionFactor = scene.MinFrameSeconds * m_nominalReportedFps;
             m_statsUpdateFactor = (float)(m_statsUpdatesEveryMS / 1000);
             ReportingRegion = scene.RegionInfo;
 
@@ -239,7 +239,7 @@ namespace OpenSim.Region.Framework.Scenes
 
             /// At the moment, we'll only report if a frame is over 120% of target, since commonly frames are a bit
             /// longer than ideal (which in itself is a concern).
-            SlowFramesStatReportThreshold = (int)Math.Ceiling(m_scene.MinFrameTime * 1000 * 1.2);
+            SlowFramesStatReportThreshold = (int)Math.Ceiling(scene.MinFrameTicks * 1.2);
 
             SlowFramesStat
                 = new Stat(

OpenSim/Region/OptionalModules/World/NPC/NPCModule.cs

@@ -234,6 +234,9 @@ namespace OpenSim.Region.OptionalModules.World.NPC
                     ScenePresence sp;
                     if (scene.TryGetScenePresence(agentID, out sp))
                     {
+                        if (sp.IsSatOnObject || sp.SitGround)
+                            return false;
+
 //                        m_log.DebugFormat(
 //                                "[NPC MODULE]: Moving {0} to {1} in {2}, noFly {3}, landAtTarget {4}",
 //                                sp.Name, pos, scene.RegionInfo.RegionName,

OpenSim/Region/OptionalModules/World/NPC/Tests/NPCModuleTests.cs

@@ -300,7 +300,7 @@ namespace OpenSim.Region.OptionalModules.World.NPC.Tests
         public void TestMove()
         {
             TestHelpers.InMethod();
-//            log4net.Config.XmlConfigurator.Configure();
+//            TestHelpers.EnableLogging();
 
             SetUpScene();
 

OpenSim/Region/Physics/BulletSPlugin/BSScene.cs

@@ -130,6 +130,11 @@ public sealed class BSScene : PhysicsScene, IPhysicsParameters
     internal int m_maxUpdatesPerFrame;
     internal EntityProperties[] m_updateArray;
 
+    /// <summary>
+    /// Used to control physics simulation timing if Bullet is running on its own thread.
+    /// </summary>
+    private ManualResetEvent m_updateWaitEvent;
+
     public const uint TERRAIN_ID = 0;       // OpenSim senses terrain with a localID of zero
     public const uint GROUNDPLANE_ID = 1;
     public const uint CHILDTERRAIN_ID = 2;  // Terrain allocated based on our mega-prim childre start here
@@ -838,6 +843,9 @@ public sealed class BSScene : PhysicsScene, IPhysicsParameters
 
     public void BulletSPluginPhysicsThread()
     {
+        Thread.CurrentThread.Priority = ThreadPriority.Highest;
+        m_updateWaitEvent = new ManualResetEvent(false);
+
         while (m_initialized)
         {
             int beginSimulationRealtimeMS = Util.EnvironmentTickCount();
@@ -851,8 +859,9 @@ public sealed class BSScene : PhysicsScene, IPhysicsParameters
             if (simulationTimeVsRealtimeDifferenceMS > 0)
             {
                 // The simulation of the time interval took less than realtime.
-                // Do a sleep for the rest of realtime.
-                Thread.Sleep(simulationTimeVsRealtimeDifferenceMS);
+                // Do a wait for the rest of realtime.
+                 m_updateWaitEvent.WaitOne(simulationTimeVsRealtimeDifferenceMS);
+                //Thread.Sleep(simulationTimeVsRealtimeDifferenceMS);
             }
             else
             {

OpenSim/Region/Physics/BulletSPlugin/BulletSimData.cs

@@ -231,7 +231,7 @@ public static Dictionary<CollisionType, CollisionTypeFilterGroup> CollisionTypeM
     { CollisionType.Avatar,
                 new CollisionTypeFilterGroup(CollisionType.Avatar,
                                 (uint)CollisionFilterGroups.BCharacterGroup,
-                                (uint)CollisionFilterGroups.BAllGroup)
+                                (uint)(CollisionFilterGroups.BAllGroup & ~CollisionFilterGroups.BCharacterGroup))
     },
     { CollisionType.Groundplane,
                 new CollisionTypeFilterGroup(CollisionType.Groundplane,

OpenSim/Tools/pCampBot/Bot.cs

@@ -35,6 +35,7 @@ using System.Timers;
 using log4net;
 using OpenMetaverse;
 using OpenMetaverse.Assets;
+using OpenMetaverse.Packets;
 using Nini.Config;
 using OpenSim.Framework;
 using OpenSim.Framework.Console;
@@ -56,6 +57,27 @@ namespace pCampBot
     {
         private static readonly ILog m_log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);
 
+        public int PacketDebugLevel 
+        { 
+            get { return m_packetDebugLevel; }
+            set 
+            {
+                if (value == m_packetDebugLevel)
+                    return;
+
+                m_packetDebugLevel = value;
+
+                if (Client != null)
+                {
+                    if (m_packetDebugLevel <= 0)
+                        Client.Network.UnregisterCallback(PacketType.Default, PacketReceivedDebugHandler);
+                    else
+                        Client.Network.RegisterCallback(PacketType.Default, PacketReceivedDebugHandler, false);
+                }
+            }
+        }
+        private int m_packetDebugLevel;
+
         public delegate void AnEvent(Bot callbot, EventType someevent); // event delegate for bot events
 
         /// <summary>
@@ -231,6 +253,9 @@ namespace pCampBot
 
             if (Client != null)
             {
+                // Remove any registered debug handlers
+                Client.Network.UnregisterCallback(PacketType.Default, PacketReceivedDebugHandler);
+
                 newClient.Settings.LOGIN_SERVER = Client.Settings.LOGIN_SERVER;
                 newClient.Settings.ALWAYS_DECODE_OBJECTS = Client.Settings.ALWAYS_DECODE_OBJECTS;
                 newClient.Settings.AVATAR_TRACKING = Client.Settings.AVATAR_TRACKING;
@@ -273,6 +298,9 @@ namespace pCampBot
             newClient.Network.Disconnected += Network_OnDisconnected;
             newClient.Objects.ObjectUpdate += Objects_NewPrim;
 
+            if (m_packetDebugLevel > 0)
+                newClient.Network.RegisterCallback(PacketType.Default, PacketReceivedDebugHandler);
+
             Client = newClient;
         }
 
@@ -705,5 +733,16 @@ namespace pCampBot
 //                SaveAsset((AssetWearable) asset);
 //            }
         }
+         
+        private void PacketReceivedDebugHandler(object o, PacketReceivedEventArgs args)
+        {
+            Packet p = args.Packet;
+            Header h = p.Header;
+            Simulator s = args.Simulator;
+
+            m_log.DebugFormat(
+                "[BOT]: Bot {0} received from {1} packet {2} #{3}, rel {4}, res {5}", 
+                Name, s.Name, p.Type, h.Sequence, h.Reliable, h.Resent);
+        }
     }
 }

OpenSim/Tools/pCampBot/BotManager.cs

@@ -43,6 +43,14 @@ using pCampBot.Interfaces;
 
 namespace pCampBot
 {
+    public enum BotManagerBotConnectingState
+    {
+        Initializing,
+        Ready,
+        Connecting,
+        Disconnecting
+    }
+
     /// <summary>
     /// Thread/Bot manager for the application
     /// </summary>
@@ -53,14 +61,14 @@ namespace pCampBot
         public const int DefaultLoginDelay = 5000;
 
         /// <summary>
-        /// Is pCampbot in the process of connecting bots?
+        /// Is pCampbot ready to connect or currently in the process of connecting or disconnecting bots?
         /// </summary>
-        public bool ConnectingBots { get; private set; }
+        public BotManagerBotConnectingState BotConnectingState { get; private set; }
 
         /// <summary>
-        /// Is pCampbot in the process of disconnecting bots?
+        /// Used to control locking as we can't lock an enum.
         /// </summary>
-        public bool DisconnectingBots { get; private set; }
+        private object BotConnectingStateChangeObject = new object();
 
         /// <summary>
         /// Delay between logins of multiple bots.
@@ -239,12 +247,25 @@ namespace pCampBot
                 "Bots", false, "show regions", "show regions", "Show regions known to bots", HandleShowRegions);
 
             m_console.Commands.AddCommand(
-                "Bots", false, "show bots", "show bots", "Shows the status of all bots", HandleShowBotsStatus);
+                "Bots", false, "show bots", "show bots", "Shows the status of all bots.", HandleShowBotsStatus);
 
             m_console.Commands.AddCommand(
                 "Bots", false, "show bot", "show bot <bot-number>", 
                 "Shows the detailed status and settings of a particular bot.", HandleShowBotStatus);
 
+            m_console.Commands.AddCommand(
+                "Debug", 
+                false, 
+                "debug lludp packet", 
+                "debug lludp packet <level> <avatar-first-name> <avatar-last-name>", 
+                "Turn on received packet logging.",
+                "If level >  0 then all received packets that are not duplicates are logged.\n"
+                + "If level <= 0 then no received packets are logged.",
+                HandleDebugLludpPacketCommand);
+
+            m_console.Commands.AddCommand(
+                "Bots", false, "show status", "show status", "Shows pCampbot status.", HandleShowStatus);
+
             m_bots = new List<Bot>();
 
             Watchdog.Enabled = true;
@@ -254,6 +275,8 @@ namespace pCampBot
             m_serverStatsCollector.Initialise(null);
             m_serverStatsCollector.Enabled = true;
             m_serverStatsCollector.Start();
+
+            BotConnectingState = BotManagerBotConnectingState.Ready;
         }
 
         /// <summary>
@@ -335,7 +358,17 @@ namespace pCampBot
 
         public void ConnectBots(int botcount)
         {
-            ConnectingBots = true;
+            lock (BotConnectingStateChangeObject)
+            {
+                if (BotConnectingState != BotManagerBotConnectingState.Ready)
+                {
+                    MainConsole.Instance.OutputFormat(
+                        "Bot connecting status is {0}.  Please wait for previous process to complete.", BotConnectingState);
+                    return;
+                }
+
+                BotConnectingState = BotManagerBotConnectingState.Connecting;
+            }
 
             Thread connectBotThread = new Thread(o => ConnectBotsInternal(botcount));
 
@@ -373,11 +406,14 @@ namespace pCampBot
 
             foreach (Bot bot in botsToConnect)
             {
-                if (!ConnectingBots)
+                lock (BotConnectingStateChangeObject)
                 {
-                    MainConsole.Instance.Output(
-                        "[BOT MANAGER]: Aborting bot connection due to user-initiated disconnection");
-                    break;
+                    if (BotConnectingState != BotManagerBotConnectingState.Connecting)
+                    {
+                        MainConsole.Instance.Output(
+                            "[BOT MANAGER]: Aborting bot connection due to user-initiated disconnection");
+                        return;
+                    }
                 }
 
                 bot.Connect();
@@ -386,7 +422,11 @@ namespace pCampBot
                 Thread.Sleep(LoginDelay);
             }
 
-            ConnectingBots = false;
+            lock (BotConnectingStateChangeObject)
+            {
+                if (BotConnectingState == BotManagerBotConnectingState.Connecting)
+                    BotConnectingState = BotManagerBotConnectingState.Ready;
+            }
         }
 
         /// <summary>
@@ -491,13 +531,7 @@ namespace pCampBot
         }
 
         private void HandleConnect(string module, string[] cmd)
-        {
-            if (ConnectingBots)
-            {
-                MainConsole.Instance.Output("Still connecting bots.  Please wait for previous process to complete.");
-                return;
-            }
-
+        {           
             lock (m_bots)
             {
                 int botsToConnect;
@@ -653,7 +687,8 @@ namespace pCampBot
                 botsToDisconnectCount = Math.Min(botsToDisconnectCount, connectedBots.Count);
             }
 
-            DisconnectingBots = true;
+            lock (BotConnectingStateChangeObject)
+                BotConnectingState = BotManagerBotConnectingState.Disconnecting;
 
             Thread disconnectBotThread = new Thread(o => DisconnectBotsInternal(connectedBots, botsToDisconnectCount));
 
@@ -662,9 +697,7 @@ namespace pCampBot
         }
 
         private void DisconnectBotsInternal(List<Bot> connectedBots, int disconnectCount)
-        {             
-            ConnectingBots = false;
-
+        {
             MainConsole.Instance.OutputFormat("Disconnecting {0} bots", disconnectCount);
 
             int disconnectedBots = 0;
@@ -683,7 +716,8 @@ namespace pCampBot
                 }
             }
 
-            DisconnectingBots = false;
+            lock (BotConnectingStateChangeObject)
+                BotConnectingState = BotManagerBotConnectingState.Ready;
         }
 
         private void HandleSit(string module, string[] cmd)
@@ -760,6 +794,38 @@ namespace pCampBot
             }
         }
 
+        private void HandleDebugLludpPacketCommand(string module, string[] args)
+        {
+            if (args.Length != 6)
+            {
+                MainConsole.Instance.OutputFormat("Usage: debug lludp packet <level> <bot-first-name> <bot-last-name>");
+                return;
+            }
+
+            int level;
+
+            if (!ConsoleUtil.TryParseConsoleInt(MainConsole.Instance, args[3], out level))
+                return;
+
+            string botFirstName = args[4];
+            string botLastName = args[5];
+
+            Bot bot;
+
+            lock (m_bots)
+                bot = m_bots.FirstOrDefault(b => b.FirstName == botFirstName && b.LastName == botLastName);
+
+            if (bot == null)
+            {
+                MainConsole.Instance.OutputFormat("No bot named {0} {1}", botFirstName, botLastName);
+                return;
+            }
+
+            bot.PacketDebugLevel = level;
+
+            MainConsole.Instance.OutputFormat("Set debug level of {0} to {1}", bot.Name, bot.PacketDebugLevel);
+        }
+
         private void HandleShowRegions(string module, string[] cmd)
         {
             string outputFormat = "{0,-30}  {1, -20}  {2, -5}  {3, -5}";
@@ -775,6 +841,14 @@ namespace pCampBot
             }
         }
 
+        private void HandleShowStatus(string module, string[] cmd)
+        {
+            ConsoleDisplayList cdl = new ConsoleDisplayList();
+            cdl.AddRow("Bot connecting state", BotConnectingState);
+
+            MainConsole.Instance.Output(cdl.ToString());
+        }
+
         private void HandleShowBotsStatus(string module, string[] cmd)
         {
             ConsoleDisplayTable cdt = new ConsoleDisplayTable();

bin/OpenSimDefaults.ini

@@ -762,7 +762,7 @@
     ; If true, avatar appearance information is resent to other avatars in the simulator every 60 seconds.
     ; This may help with some situations where avatars are persistently grey, though it will not help 
     ; in other situations (e.g. appearance baking failures where the avatar only appears as a cloud to others).
-    ResendAppearanceUpdates = true
+    ResendAppearanceUpdates = false
 
     ; Turning this on responds to CachedTexture packets to possibly avoid rebaking the avatar 
     ; on every login