Start sending spare frame time MS viewer stat. Make frame time correctly display total frame time, not just non-spare time.

This makes it easier to see when components of frame time exceed normal permitted frame time.
Currently reflect scene frame times.
0.7.3-extended
Justin Clark-Casey (justincc) 2012-06-05 00:17:55 +01:00
parent 61e7d4a0e2
commit 280d005d55
2 changed files with 125 additions and 78 deletions

View File

@ -218,6 +218,7 @@ namespace OpenSim.Region.Framework.Scenes
private int backupMS; private int backupMS;
private int terrainMS; private int terrainMS;
private int landMS; private int landMS;
private int spareMS;
/// <summary> /// <summary>
/// Tick at which the last frame was processed. /// Tick at which the last frame was processed.
@ -1341,35 +1342,34 @@ namespace OpenSim.Region.Framework.Scenes
endFrame = Frame + frames; endFrame = Frame + frames;
float physicsFPS = 0f; float physicsFPS = 0f;
int tmpPhysicsMS, tmpPhysicsMS2, tmpAgentMS, tmpTempOnRezMS, evMS, backMS, terMS; int previousFrameTick, tmpMS;
int previousFrameTick; int maintc = Util.EnvironmentTickCount();
int maintc;
while (!m_shuttingDown && (endFrame == null || Frame < endFrame)) while (!m_shuttingDown && (endFrame == null || Frame < endFrame))
{ {
maintc = Util.EnvironmentTickCount();
++Frame; ++Frame;
// m_log.DebugFormat("[SCENE]: Processing frame {0} in {1}", Frame, RegionInfo.RegionName); // m_log.DebugFormat("[SCENE]: Processing frame {0} in {1}", Frame, RegionInfo.RegionName);
agentMS = tempOnRezMS = eventMS = backupMS = terrainMS = landMS = 0; agentMS = tempOnRezMS = eventMS = backupMS = terrainMS = landMS = spareMS = 0;
try try
{ {
tmpPhysicsMS2 = Util.EnvironmentTickCount(); tmpMS = Util.EnvironmentTickCount();
if ((Frame % m_update_physics == 0) && m_physics_enabled) if ((Frame % m_update_physics == 0) && m_physics_enabled)
m_sceneGraph.UpdatePreparePhysics(); m_sceneGraph.UpdatePreparePhysics();
physicsMS2 = Util.EnvironmentTickCountSubtract(tmpPhysicsMS2); physicsMS2 = Util.EnvironmentTickCountSubtract(tmpMS);
// Apply any pending avatar force input to the avatar's velocity // Apply any pending avatar force input to the avatar's velocity
tmpAgentMS = Util.EnvironmentTickCount(); tmpMS = Util.EnvironmentTickCount();
if (Frame % m_update_entitymovement == 0) if (Frame % m_update_entitymovement == 0)
m_sceneGraph.UpdateScenePresenceMovement(); m_sceneGraph.UpdateScenePresenceMovement();
agentMS = Util.EnvironmentTickCountSubtract(tmpAgentMS); agentMS = Util.EnvironmentTickCountSubtract(tmpMS);
// Perform the main physics update. This will do the actual work of moving objects and avatars according to their // Perform the main physics update. This will do the actual work of moving objects and avatars according to their
// velocity // velocity
tmpPhysicsMS = Util.EnvironmentTickCount(); tmpMS = Util.EnvironmentTickCount();
if (Frame % m_update_physics == 0) if (Frame % m_update_physics == 0)
{ {
if (m_physics_enabled) if (m_physics_enabled)
@ -1378,9 +1378,9 @@ namespace OpenSim.Region.Framework.Scenes
if (SynchronizeScene != null) if (SynchronizeScene != null)
SynchronizeScene(this); SynchronizeScene(this);
} }
physicsMS = Util.EnvironmentTickCountSubtract(tmpPhysicsMS); physicsMS = Util.EnvironmentTickCountSubtract(tmpMS);
tmpAgentMS = Util.EnvironmentTickCount(); tmpMS = Util.EnvironmentTickCount();
// Check if any objects have reached their targets // Check if any objects have reached their targets
CheckAtTargets(); CheckAtTargets();
@ -1395,36 +1395,36 @@ namespace OpenSim.Region.Framework.Scenes
if (Frame % m_update_presences == 0) if (Frame % m_update_presences == 0)
m_sceneGraph.UpdatePresences(); m_sceneGraph.UpdatePresences();
agentMS += Util.EnvironmentTickCountSubtract(tmpAgentMS); agentMS += Util.EnvironmentTickCountSubtract(tmpMS);
// Delete temp-on-rez stuff // Delete temp-on-rez stuff
if (Frame % m_update_temp_cleaning == 0 && !m_cleaningTemps) if (Frame % m_update_temp_cleaning == 0 && !m_cleaningTemps)
{ {
tmpTempOnRezMS = Util.EnvironmentTickCount(); tmpMS = Util.EnvironmentTickCount();
m_cleaningTemps = true; m_cleaningTemps = true;
Util.FireAndForget(delegate { CleanTempObjects(); m_cleaningTemps = false; }); Util.FireAndForget(delegate { CleanTempObjects(); m_cleaningTemps = false; });
tempOnRezMS = Util.EnvironmentTickCountSubtract(tmpTempOnRezMS); tempOnRezMS = Util.EnvironmentTickCountSubtract(tmpMS);
} }
if (Frame % m_update_events == 0) if (Frame % m_update_events == 0)
{ {
evMS = Util.EnvironmentTickCount(); tmpMS = Util.EnvironmentTickCount();
UpdateEvents(); UpdateEvents();
eventMS = Util.EnvironmentTickCountSubtract(evMS); eventMS = Util.EnvironmentTickCountSubtract(tmpMS);
} }
if (Frame % m_update_backup == 0) if (Frame % m_update_backup == 0)
{ {
backMS = Util.EnvironmentTickCount(); tmpMS = Util.EnvironmentTickCount();
UpdateStorageBackup(); UpdateStorageBackup();
backupMS = Util.EnvironmentTickCountSubtract(backMS); backupMS = Util.EnvironmentTickCountSubtract(tmpMS);
} }
if (Frame % m_update_terrain == 0) if (Frame % m_update_terrain == 0)
{ {
terMS = Util.EnvironmentTickCount(); tmpMS = Util.EnvironmentTickCount();
UpdateTerrain(); UpdateTerrain();
terrainMS = Util.EnvironmentTickCountSubtract(terMS); terrainMS = Util.EnvironmentTickCountSubtract(tmpMS);
} }
//if (Frame % m_update_land == 0) //if (Frame % m_update_land == 0)
@ -1434,24 +1434,6 @@ namespace OpenSim.Region.Framework.Scenes
// landMS = Util.EnvironmentTickCountSubtract(ldMS); // landMS = Util.EnvironmentTickCountSubtract(ldMS);
//} //}
frameMS = Util.EnvironmentTickCountSubtract(maintc);
otherMS = tempOnRezMS + eventMS + backupMS + terrainMS + landMS;
// if (Frame%m_update_avatars == 0)
// UpdateInWorldTime();
StatsReporter.AddPhysicsFPS(physicsFPS);
StatsReporter.AddTimeDilation(TimeDilation);
StatsReporter.AddFPS(1);
// frameMS currently records work frame times, not total frame times (work + any required sleep to
// reach min frame time.
StatsReporter.addFrameMS(frameMS);
StatsReporter.addAgentMS(agentMS);
StatsReporter.addPhysicsMS(physicsMS + physicsMS2);
StatsReporter.addOtherMS(otherMS);
StatsReporter.addScriptLines(m_sceneGraph.GetScriptLPS());
if (LoginsDisabled && Frame == 20) if (LoginsDisabled && Frame == 20)
{ {
// m_log.DebugFormat("{0} {1} {2}", LoginsDisabled, m_sceneGraph.GetActiveScriptsCount(), LoginLock); // m_log.DebugFormat("{0} {1} {2}", LoginsDisabled, m_sceneGraph.GetActiveScriptsCount(), LoginLock);
@ -1501,11 +1483,32 @@ namespace OpenSim.Region.Framework.Scenes
previousFrameTick = m_lastFrameTick; previousFrameTick = m_lastFrameTick;
m_lastFrameTick = Util.EnvironmentTickCount(); m_lastFrameTick = Util.EnvironmentTickCount();
maintc = Util.EnvironmentTickCountSubtract(m_lastFrameTick, maintc); tmpMS = Util.EnvironmentTickCountSubtract(m_lastFrameTick, maintc);
maintc = (int)(MinFrameTime * 1000) - maintc; tmpMS = (int)(MinFrameTime * 1000) - tmpMS;
if (maintc > 0) if (tmpMS > 0)
Thread.Sleep(maintc); {
Thread.Sleep(tmpMS);
spareMS += tmpMS;
}
frameMS = Util.EnvironmentTickCountSubtract(maintc);
maintc = Util.EnvironmentTickCount();
otherMS = tempOnRezMS + eventMS + backupMS + terrainMS + landMS;
// if (Frame%m_update_avatars == 0)
// UpdateInWorldTime();
StatsReporter.AddPhysicsFPS(physicsFPS);
StatsReporter.AddTimeDilation(TimeDilation);
StatsReporter.AddFPS(1);
StatsReporter.addFrameMS(frameMS);
StatsReporter.addAgentMS(agentMS);
StatsReporter.addPhysicsMS(physicsMS + physicsMS2);
StatsReporter.addOtherMS(otherMS);
StatsReporter.AddSpareMS(spareMS);
StatsReporter.addScriptLines(m_sceneGraph.GetScriptLPS());
// Optionally warn if a frame takes double the amount of time that it should. // Optionally warn if a frame takes double the amount of time that it should.
if (DebugUpdates if (DebugUpdates

View File

@ -56,10 +56,17 @@ namespace OpenSim.Region.Framework.Scenes
public event YourStatsAreWrong OnStatsIncorrect; public event YourStatsAreWrong OnStatsIncorrect;
private SendStatResult handlerSendStatResult = null; private SendStatResult handlerSendStatResult;
private YourStatsAreWrong handlerStatsIncorrect = null; private YourStatsAreWrong handlerStatsIncorrect;
/// <summary>
/// These are the IDs of stats sent in the StatsPacket to the viewer.
/// </summary>
/// <remarks>
/// Some of these are not relevant to OpenSimulator since it is architected differently to other simulators
/// (e.g. script instructions aren't executed as part of the frame loop so 'script time' is tricky).
/// </remarks>
public enum Stats : uint public enum Stats : uint
{ {
TimeDilation = 0, TimeDilation = 0,
@ -83,7 +90,20 @@ namespace OpenSim.Region.Framework.Scenes
OutPacketsPerSecond = 18, OutPacketsPerSecond = 18,
PendingDownloads = 19, PendingDownloads = 19,
PendingUploads = 20, PendingUploads = 20,
VirtualSizeKb = 21,
ResidentSizeKb = 22,
PendingLocalUploads = 23,
UnAckedBytes = 24, UnAckedBytes = 24,
PhysicsPinnedTasks = 25,
PhysicsLodTasks = 26,
SimPhysicsStepMs = 27,
SimPhysicsShapeMs = 28,
SimPhysicsOtherMs = 29,
SimPhysicsMemory = 30,
ScriptEps = 31,
SimSpareMs = 32,
SimSleepMs = 33,
SimIoPumpTime = 34
} }
/// <summary> /// <summary>
@ -118,9 +138,9 @@ namespace OpenSim.Region.Framework.Scenes
// Sending a stats update every 3 seconds- // Sending a stats update every 3 seconds-
private int m_statsUpdatesEveryMS = 3000; private int m_statsUpdatesEveryMS = 3000;
private float m_statsUpdateFactor = 0; private float m_statsUpdateFactor;
private float m_timeDilation = 0; private float m_timeDilation;
private int m_fps = 0; private int m_fps;
/// <summary> /// <summary>
/// Number of the last frame on which we processed a stats udpate. /// Number of the last frame on which we processed a stats udpate.
@ -143,41 +163,42 @@ namespace OpenSim.Region.Framework.Scenes
private float m_reportedFpsCorrectionFactor = 5; private float m_reportedFpsCorrectionFactor = 5;
// saved last reported value so there is something available for llGetRegionFPS // saved last reported value so there is something available for llGetRegionFPS
private float lastReportedSimFPS = 0; private float lastReportedSimFPS;
private float[] lastReportedSimStats = new float[21]; private float[] lastReportedSimStats = new float[22];
private float m_pfps = 0; private float m_pfps;
/// <summary> /// <summary>
/// Number of agent updates requested in this stats cycle /// Number of agent updates requested in this stats cycle
/// </summary> /// </summary>
private int m_agentUpdates = 0; private int m_agentUpdates;
/// <summary> /// <summary>
/// Number of object updates requested in this stats cycle /// Number of object updates requested in this stats cycle
/// </summary> /// </summary>
private int m_objectUpdates; private int m_objectUpdates;
private int m_frameMS = 0; private int m_frameMS;
private int m_netMS = 0; private int m_spareMS;
private int m_agentMS = 0; private int m_netMS;
private int m_physicsMS = 0; private int m_agentMS;
private int m_imageMS = 0; private int m_physicsMS;
private int m_otherMS = 0; private int m_imageMS;
private int m_otherMS;
//Ckrinke: (3-21-08) Comment out to remove a compiler warning. Bring back into play when needed. //Ckrinke: (3-21-08) Comment out to remove a compiler warning. Bring back into play when needed.
//Ckrinke private int m_scriptMS = 0; //Ckrinke private int m_scriptMS = 0;
private int m_rootAgents = 0; private int m_rootAgents;
private int m_childAgents = 0; private int m_childAgents;
private int m_numPrim = 0; private int m_numPrim;
private int m_inPacketsPerSecond = 0; private int m_inPacketsPerSecond;
private int m_outPacketsPerSecond = 0; private int m_outPacketsPerSecond;
private int m_activePrim = 0; private int m_activePrim;
private int m_unAckedBytes = 0; private int m_unAckedBytes;
private int m_pendingDownloads = 0; private int m_pendingDownloads;
private int m_pendingUploads = 0; private int m_pendingUploads = 0; // FIXME: Not currently filled in
private int m_activeScripts = 0; private int m_activeScripts;
private int m_scriptLinesPerSecond = 0; private int m_scriptLinesPerSecond;
private int m_objectCapacity = 45000; private int m_objectCapacity = 45000;
@ -199,7 +220,7 @@ namespace OpenSim.Region.Framework.Scenes
m_objectCapacity = scene.RegionInfo.ObjectCapacity; m_objectCapacity = scene.RegionInfo.ObjectCapacity;
m_report.AutoReset = true; m_report.AutoReset = true;
m_report.Interval = m_statsUpdatesEveryMS; m_report.Interval = m_statsUpdatesEveryMS;
m_report.Elapsed += statsHeartBeat; m_report.Elapsed += TriggerStatsHeartbeat;
m_report.Enabled = true; m_report.Enabled = true;
if (StatsManager.SimExtraStats != null) if (StatsManager.SimExtraStats != null)
@ -208,7 +229,7 @@ namespace OpenSim.Region.Framework.Scenes
public void Close() public void Close()
{ {
m_report.Elapsed -= statsHeartBeat; m_report.Elapsed -= TriggerStatsHeartbeat;
m_report.Close(); m_report.Close();
} }
@ -223,9 +244,23 @@ namespace OpenSim.Region.Framework.Scenes
m_report.Interval = m_statsUpdatesEveryMS; m_report.Interval = m_statsUpdatesEveryMS;
} }
private void TriggerStatsHeartbeat(object sender, EventArgs args)
{
try
{
statsHeartBeat(sender, args);
}
catch (Exception e)
{
m_log.Warn(string.Format(
"[SIM STATS REPORTER] Update for {0} failed with exception ",
m_scene.RegionInfo.RegionName), e);
}
}
private void statsHeartBeat(object sender, EventArgs e) private void statsHeartBeat(object sender, EventArgs e)
{ {
SimStatsPacket.StatBlock[] sb = new SimStatsPacket.StatBlock[21]; SimStatsPacket.StatBlock[] sb = new SimStatsPacket.StatBlock[22];
SimStatsPacket.RegionBlock rb = new SimStatsPacket.RegionBlock(); SimStatsPacket.RegionBlock rb = new SimStatsPacket.RegionBlock();
// Know what's not thread safe in Mono... modifying timers. // Know what's not thread safe in Mono... modifying timers.
@ -292,7 +327,7 @@ namespace OpenSim.Region.Framework.Scenes
if (framesUpdated == 0) if (framesUpdated == 0)
framesUpdated = 1; framesUpdated = 1;
for (int i = 0; i < 21; i++) for (int i = 0; i < 22; i++)
{ {
sb[i] = new SimStatsPacket.StatBlock(); sb[i] = new SimStatsPacket.StatBlock();
} }
@ -360,7 +395,10 @@ namespace OpenSim.Region.Framework.Scenes
sb[20].StatID = (uint)Stats.ScriptLinesPerSecond; sb[20].StatID = (uint)Stats.ScriptLinesPerSecond;
sb[20].StatValue = m_scriptLinesPerSecond / m_statsUpdateFactor; sb[20].StatValue = m_scriptLinesPerSecond / m_statsUpdateFactor;
for (int i = 0; i < 21; i++) sb[21].StatID = (uint)Stats.SimSpareMs;
sb[21].StatValue = m_spareMS / framesUpdated;
for (int i = 0; i < 22; i++)
{ {
lastReportedSimStats[i] = sb[i].StatValue; lastReportedSimStats[i] = sb[i].StatValue;
} }
@ -398,11 +436,11 @@ namespace OpenSim.Region.Framework.Scenes
} }
} }
resetvalues(); ResetValues();
} }
} }
private void resetvalues() private void ResetValues()
{ {
m_timeDilation = 0; m_timeDilation = 0;
m_fps = 0; m_fps = 0;
@ -420,6 +458,7 @@ namespace OpenSim.Region.Framework.Scenes
m_physicsMS = 0; m_physicsMS = 0;
m_imageMS = 0; m_imageMS = 0;
m_otherMS = 0; m_otherMS = 0;
m_spareMS = 0;
//Ckrinke This variable is not used, so comment to remove compiler warning until it is used. //Ckrinke This variable is not used, so comment to remove compiler warning until it is used.
//Ckrinke m_scriptMS = 0; //Ckrinke m_scriptMS = 0;
@ -498,6 +537,11 @@ namespace OpenSim.Region.Framework.Scenes
m_frameMS += ms; m_frameMS += ms;
} }
public void AddSpareMS(int ms)
{
m_spareMS += ms;
}
public void addNetMS(int ms) public void addNetMS(int ms)
{ {
m_netMS += ms; m_netMS += ms;