Revision as of 23:30, 24 March 2014

Overview

A lot of the work in OpenSim is done in tasks that are run on a general-purpose threadpool. This threadpool is managed in Util.cs.

Tasks are added to the threadpool by calling Util.FireAndForget(function).

Logging Activity

There's a console command that enables logging of the tasks in the threadpool. When this option is enabled, the following events are logged:

• Task queued (added to the threadpool)
• Task started running
• Task finished running
• Task timed-out and was terminated

Each time these events are logged, we also log the number of Queued and Running tasks. This shows how busy OpenSim is.

To enable or disable logging, run from the console:

debug threadpool level <num>

There are 4 logging levels:

0 = no logging (default)
Turns off logging.

1 = only first line of stack trace; don't log common threads
Short logging. Instead of logging the full stack trace where the task was queued, this only logs the first line of the stack trace. This doesn't log common tasks such as BeginFireQueueEmpty, since they tend to fill up the log quickly.

2 = full stack trace; don't log common threads
Logs the full stack trace where the task was queued. Still doesn't log common tasks.

3 = full stack trace, including common threads
Logs everything.

Overload Mode

When the threadpool is close to full, we enter "Overload Mode". In that mode we start logging threadpool activity even if the log level is 0. This is useful when running OpenSim in production, as it means that the log level can be kept at 0, yet we still get useful diagnostic information in case OpenSim becomes overloaded, which can help us find the cause of the overload.

Sample Logging Output

Level 1

2014-03-25 08:50:39,403 DEBUG - OpenSim.Framework.Util Queue threadfunc 32 (Queued 1, Running 0) at OpenSim.Region.ClientStack.LindenUDP.LLClientView.SendWindData(Vector2[] windSpeeds) in c:\opensim\OpenSim\Region\ClientStack\Linden\UDP\LLClientView.cs:line 1292
2014-03-25 08:50:39,406 DEBUG - OpenSim.Framework.Util Run threadfunc 32 (Queued 0, Running 1)
2014-03-25 08:50:39,409 DEBUG - OpenSim.Framework.Util Exit threadfunc 32 (0 ms)

Levels 2-3

2014-03-25 08:50:52,118 DEBUG - OpenSim.Framework.Util Queue threadfunc 33 (Queued 1, Running 0) at OpenSim.Region.Framework.Scenes.ScenePresence.SendScriptEventToAttachments(String eventName, Object[] args) in c:\opensim\OpenSim\Region\Framework\Scenes\ScenePresence.cs:line 4283
   at OpenSim.Region.Framework.Scenes.Animation.ScenePresenceAnimator.TrySetMovementAnimation(String anim) in c:\opensim\OpenSim\Region\Framework\Scenes\Animation\ScenePresenceAnimator.cs:line 190
   at OpenSim.Region.Framework.Scenes.Animation.ScenePresenceAnimator.UpdateMovementAnimations() in c:\opensim\OpenSim\Region\Framework\Scenes\Animation\ScenePresenceAnimator.cs:line 461
   at OpenSim.Region.Framework.Scenes.ScenePresence.AddNewMovement(Vector3 vec, Single thisAddSpeedModifier) in c:\opensim\OpenSim\Region\Framework\Scenes\ScenePresence.cs:line 3060
   at OpenSim.Region.Framework.Scenes.ScenePresence.HandleAgentUpdate(IClientAPI remoteClient, AgentUpdateArgs agentData) in c:\opensim\OpenSim\Region\Framework\Scenes\ScenePresence.cs:line 2154
   at OpenSim.Region.ClientStack.LindenUDP.LLClientView.HandleAgentUpdate(IClientAPI sener, Packet packet) in c:\opensim\OpenSim\Region\ClientStack\Linden\UDP\LLClientView.cs:line 5778
   at OpenSim.Region.ClientStack.LindenUDP.LLClientView.ProcessPacketMethod(Packet packet) in c:\opensim\OpenSim\Region\ClientStack\Linden\UDP\LLClientView.cs:line 707
   at OpenSim.Region.ClientStack.LindenUDP.LLClientView.ProcessInPacket(Packet packet) in c:\opensim\OpenSim\Region\ClientStack\Linden\UDP\LLClientView.cs:line 12372
   at OpenSim.Region.ClientStack.LindenUDP.LLUDPServer.ProcessInPacket(IncomingPacket incomingPacket) in c:\opensim\OpenSim\Region\ClientStack\Linden\UDP\LLUDPServer.cs:line 2265
   at OpenSim.Region.ClientStack.LindenUDP.LLUDPServer.IncomingPacketHandler() in c:\opensim\OpenSim\Region\ClientStack\Linden\UDP\LLUDPServer.cs:line 1990
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.ThreadHelper.ThreadStart()
2014-03-25 08:50:52,126 DEBUG - OpenSim.Framework.Util Run threadfunc 33 (Queued 0, Running 1)
2014-03-25 08:50:52,129 DEBUG - OpenSim.Framework.Util Exit threadfunc 33 (0 ms)

Terminating Hung Threads

This threadpool has a watchdog timer, which terminates threads if they've been running for over a minute. This prevents exhaustion of the threadpool due to threads that are hung.

On Windows (using .NET), OpenSim will even log a stack trace of the point where the thread was hung. Unfortunately this isn't possible when using Mono.

Tasks that might actually run longer than a minute should not be run on the threadpool. There's a different utility method for running such tasks: Util.RunThreadNoTimeout().