* Start recording asset request times after a cache miss. This is very primtive at the moment - only the last time is kept for some classes of request

* This can be seen as "Latest asset request time after cache miss" in show stats on the region console

2 files changed, 33 insertions, 6 deletions

diff --git a/OpenSim/Framework/Communications/Cache/AssetCache.cs b/OpenSim/Framework/Communications/Cache/AssetCache.cs
index 0112198..9c73587 100644
--- a/OpenSim/Framework/Communications/Cache/AssetCache.cs
+++ b/OpenSim/Framework/Communications/Cache/AssetCache.cs
@@ -252,7 +252,7 @@ namespace OpenSim.Framework.Communications.Cache
             else
             {
                 // m_log.DebugFormat("[ASSET CACHE]: Adding request for {0} {1}", isTexture ? "texture" : "asset", assetId);
-
+                
                 NewAssetRequest req = new NewAssetRequest(assetId, callback);
                 AssetRequestsList requestList;
 
@@ -268,8 +268,11 @@ namespace OpenSim.Framework.Communications.Cache
                     {
                         // m_log.DebugFormat("[ASSET CACHE]: Adding request for {0} {1}", isTexture ? "texture" : "asset", assetId);
                         requestList = new AssetRequestsList(assetId);
-                        RequestLists.Add(assetId, requestList);
-                        requestList.Requests.Add(req);
+                        requestList.TimeRequested = DateTime.Now;
+                        requestList.Requests.Add(req);           
+                        
+                        RequestLists.Add(assetId, requestList);                        
+                        
                         m_assetServer.RequestAsset(assetId, isTexture);
                     }
                 }
@@ -446,6 +449,9 @@ namespace OpenSim.Framework.Communications.Cache
 
             if (reqList != null)
             {
+                if (StatsManager.SimExtraStats != null)
+                    StatsManager.SimExtraStats.AddAssetRequestTimeAfterCacheMiss(DateTime.Now - reqList.TimeRequested);
+                
                 foreach (NewAssetRequest req in reqList.Requests)
                 {
                     // Xantor 20080526 are we really calling all the callbacks if multiple queued for 1 request? -- Yes, checked
@@ -479,6 +485,9 @@ namespace OpenSim.Framework.Communications.Cache
 
             if (reqList != null)
             {
+                if (StatsManager.SimExtraStats != null)
+                    StatsManager.SimExtraStats.AddAssetRequestTimeAfterCacheMiss(DateTime.Now - reqList.TimeRequested);
+                
                 foreach (NewAssetRequest req in reqList.Requests)
                 {
                     req.Callback(assetID, null);
@@ -670,6 +679,11 @@ namespace OpenSim.Framework.Communications.Cache
         {
             public UUID AssetID;
             public List<NewAssetRequest> Requests = new List<NewAssetRequest>();
+            
+            /// <summary>
+            /// Record the time that this request was first made.
+            /// </summary>
+            public DateTime TimeRequested;
 
             public AssetRequestsList(UUID assetID)
             {
diff --git a/OpenSim/Framework/Statistics/SimExtraStatsCollector.cs b/OpenSim/Framework/Statistics/SimExtraStatsCollector.cs
index cc64ed6..2f6bb7e 100644
--- a/OpenSim/Framework/Statistics/SimExtraStatsCollector.cs
+++ b/OpenSim/Framework/Statistics/SimExtraStatsCollector.cs
@@ -45,6 +45,7 @@ namespace OpenSim.Framework.Statistics
         private long texturesInCache;
         private long assetCacheMemoryUsage;
         private long textureCacheMemoryUsage;
+        private TimeSpan assetRequestTimeAfterCacheMiss;
         private long blockedMissingTextureRequests;
 
         private long assetServiceRequestFailures;
@@ -86,6 +87,11 @@ namespace OpenSim.Framework.Statistics
         public long TexturesInCache { get { return texturesInCache; } }
         public long AssetCacheMemoryUsage { get { return assetCacheMemoryUsage; } }
         public long TextureCacheMemoryUsage { get { return textureCacheMemoryUsage; } }
+        
+        /// <summary>
+        /// This is the time it took for the last asset request made in response to a cache miss.
+        /// </summary>
+        public TimeSpan AssetRequestTimeAfterCacheMiss { get { return assetRequestTimeAfterCacheMiss; } }
 
         /// <summary>
         /// Number of persistent requests for missing textures we have started blocking from clients.  To some extent
@@ -148,7 +154,7 @@ namespace OpenSim.Framework.Statistics
         }
 
         /// <summary>
-        /// Signal that the asset cache can be cleared.
+        /// Signal that the asset cache has been cleared.
         /// </summary>
         public void ClearAssetCacheStatistics()
         {
@@ -157,6 +163,11 @@ namespace OpenSim.Framework.Statistics
             texturesInCache = 0;
             textureCacheMemoryUsage = 0;
         }
+        
+        public void AddAssetRequestTimeAfterCacheMiss(TimeSpan ts)
+        {
+            assetRequestTimeAfterCacheMiss = ts;
+        }
 
         public void AddBlockedMissingTextureRequest()
         {
@@ -245,10 +256,12 @@ namespace OpenSim.Framework.Statistics
                 string.Format(
 @"Asset cache contains   {0,6} non-texture assets using {1,10} K
 Texture cache contains {2,6} texture     assets using {3,10} K
-Blocked client requests for missing textures: {4}
-Asset service request failures: {5}"+ Environment.NewLine,
+Latest asset request time after cache miss: {4}s
+Blocked client requests for missing textures: {5}
+Asset service request failures: {6}"+ Environment.NewLine,
                     AssetsInCache, Math.Round(AssetCacheMemoryUsage / 1024.0),
                     TexturesInCache, Math.Round(TextureCacheMemoryUsage / 1024.0),
+                    assetRequestTimeAfterCacheMiss.Milliseconds / 1000.0,
                     BlockedMissingTextureRequests,
                     AssetServiceRequestFailures));