Added more performance checks to the HTTP server. Each request

coming through the WebUtil fns has a request id in the header
that can match the request to the actual work done by the service

2 files changed, 83 insertions, 48 deletions

diff --git a/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs b/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs
index 3343f60..86ad7aa 100644
--- a/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs
+++ b/OpenSim/Framework/Servers/HttpServer/BaseHttpServer.cs
@@ -346,9 +346,15 @@ namespace OpenSim.Framework.Servers.HttpServer
         /// <param name="response"></param>
         public virtual void HandleRequest(OSHttpRequest request, OSHttpResponse response)
         {
+            string reqnum = "unknown";
+            int tickstart = Environment.TickCount;
+
             try
             {
-                //m_log.Debug("[BASE HTTP SERVER]: Handling request to " + request.RawUrl);
+                // OpenSim.Framework.WebUtil.OSHeaderRequestID
+                if (request.Headers["opensim-request-id"] != null)
+                    reqnum = String.Format("{0}:{1}",request.RemoteIPEndPoint,request.Headers["opensim-request-id"]);
+                // m_log.DebugFormat("[BASE HTTP SERVER]: <{0}> handle request for {1}",reqnum,request.RawUrl);
 
                 Thread.CurrentThread.CurrentCulture = new CultureInfo("en-US", true);
 
@@ -576,6 +582,14 @@ namespace OpenSim.Framework.Servers.HttpServer
                 m_log.ErrorFormat("[BASE HTTP SERVER]: HandleRequest() threw {0}", e);
                 SendHTML500(response);
             }
+            finally
+            {
+                // Every month or so this will wrap and give bad numbers, not really a problem
+                // since its just for reporting, 200ms limit can be adjusted
+                int tickdiff = Environment.TickCount - tickstart;
+                if (tickdiff > 200)
+                    m_log.InfoFormat("[BASE HTTP SERVER]: slow request <{0}> for {1} took {2} ms",reqnum,request.RawUrl,tickdiff);
+            }
         }
 
         private bool TryGetStreamHandler(string handlerKey, out IRequestHandler streamHandler)
diff --git a/OpenSim/Framework/WebUtil.cs b/OpenSim/Framework/WebUtil.cs
index a00ea88..d88d095 100644
--- a/OpenSim/Framework/WebUtil.cs
+++ b/OpenSim/Framework/WebUtil.cs
@@ -51,7 +51,15 @@ namespace OpenSim.Framework
                 MethodBase.GetCurrentMethod().DeclaringType);
 
         private static int m_requestNumber = 0;
-        
+
+        // this is the header field used to communicate the local request id
+        // used for performance and debugging
+        public const string OSHeaderRequestID = "opensim-request-id";
+
+        // number of milliseconds a call can take before it is considered
+        // a "long" call for warning & debugging purposes
+        public const int LongCallTime = 200;
+
         /// <summary>
         /// Send LLSD to an HTTP client in application/llsd+json form
         /// </summary>
@@ -146,34 +154,41 @@ namespace OpenSim.Framework
         public static OSDMap ServiceOSDRequest(string url, OSDMap data, string method, int timeout)
         {
             int reqnum = m_requestNumber++;
-            m_log.DebugFormat("[WEB UTIL]: <{0}> start osd request for {1}, method {2}",reqnum,url,method);
+            // m_log.DebugFormat("[WEB UTIL]: <{0}> start osd request for {1}, method {2}",reqnum,url,method);
 
             string errorMessage = "unknown error";
             int tickstart = Util.EnvironmentTickCount();
+            int tickdata = 0;
+
             try
             {
                 HttpWebRequest request = (HttpWebRequest)WebRequest.Create(url);
                 request.Method = method;
                 request.Timeout = timeout;
-                //request.KeepAlive = false;
-
+                request.KeepAlive = false;
+                request.MaximumAutomaticRedirections = 10;
+                request.ReadWriteTimeout = timeout / 4;
+                request.Headers[OSHeaderRequestID] = reqnum.ToString();
+                
                 // If there is some input, write it into the request
                 if (data != null)
                 {
                     string strBuffer = OSDParser.SerializeJsonString(data);
                     byte[] buffer = System.Text.Encoding.UTF8.GetBytes(strBuffer);
-
+                        
                     request.ContentType = "application/json";
                     request.ContentLength = buffer.Length;   //Count bytes to send
                     using (Stream requestStream = request.GetRequestStream())
-                    {
-                        requestStream.Write(buffer, 0, strBuffer.Length);         //Send it
-                    }
+                            requestStream.Write(buffer, 0, buffer.Length);         //Send it
                 }
                 
-                using (WebResponse webResponse = request.GetResponse())
+                // capture how much time was spent writing, this may seem silly
+                // but with the number concurrent requests, this often blocks
+                tickdata = Util.EnvironmentTickCountSubtract(tickstart);
+
+                using (WebResponse response = request.GetResponse())
                 {
-                    using (Stream responseStream = webResponse.GetResponseStream())
+                    using (Stream responseStream = response.GetResponseStream())
                     {
                         string responseStr = null;
                         responseStr = responseStream.GetStreamString();
@@ -199,12 +214,12 @@ namespace OpenSim.Framework
             {
                 // This just dumps a warning for any operation that takes more than 100 ms
                 int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
-                if (tickdiff > 100)
-                    m_log.WarnFormat("[WEB UTIL]: request <{0}> (URI:{1}, METHOD:{2}) took {3} milliseconds",
-                                     reqnum,url,method,tickdiff);
+                if (tickdiff > LongCallTime)
+                    m_log.InfoFormat("[WEB UTIL]: osd request <{0}> (URI:{1}, METHOD:{2}) took {3}ms overall, {4}ms writing",
+                                     reqnum,url,method,tickdiff,tickdata);
             }
             
-            m_log.WarnFormat("[WEB UTIL] <{0}> request failed: {1}",reqnum,errorMessage);
+            m_log.WarnFormat("[WEB UTIL] <{0}> osd request failed: {1}",reqnum,errorMessage);
             return ErrorResponseMap(errorMessage);
         }
 
@@ -248,7 +263,7 @@ namespace OpenSim.Framework
             catch (Exception e)
             {
                 // don't need to treat this as an error... we're just guessing anyway
-                m_log.DebugFormat("[WEB UTIL] couldn't decode result: <{0}>",response);
+                m_log.DebugFormat("[WEB UTIL] couldn't decode <{0}>: {1}",response,e.Message);
             }
             
             return result;
@@ -260,26 +275,44 @@ namespace OpenSim.Framework
         /// </summary>
         public static OSDMap PostToService(string url, NameValueCollection data)
         {
+            return ServiceFormRequest(url,data,10000);
+        }
+        
+        public static OSDMap ServiceFormRequest(string url, NameValueCollection data, int timeout)
+        {
             int reqnum = m_requestNumber++;
-            string method = data["RequestMethod"] != null ? data["RequestMethod"] : "unknown";
-            m_log.DebugFormat("[WEB UTIL]: <{0}> start form request for {1}, method {2}",reqnum,url,method);
-
-            string errorMessage;
+            string method = (data != null && data["RequestMethod"] != null) ? data["RequestMethod"] : "unknown";
+            // m_log.DebugFormat("[WEB UTIL]: <{0}> start form request for {1}, method {2}",reqnum,url,method);
+            
+            string errorMessage = "unknown error";
             int tickstart = Util.EnvironmentTickCount();
+            int tickdata = 0;
 
             try
             {
-                string queryString = BuildQueryString(data);
-                byte[] requestData = System.Text.Encoding.UTF8.GetBytes(queryString);
-
+                
                 HttpWebRequest request = (HttpWebRequest)HttpWebRequest.Create(url);
                 request.Method = "POST";
-                request.ContentLength = requestData.Length;
-                request.ContentType = "application/x-www-form-urlencoded";
+                request.Timeout = timeout;
+                request.KeepAlive = false;
+                request.MaximumAutomaticRedirections = 10;
+                request.ReadWriteTimeout = timeout / 4;
+                request.Headers[OSHeaderRequestID] = reqnum.ToString();
                 
-                Stream requestStream = request.GetRequestStream();
-                requestStream.Write(requestData, 0, requestData.Length);
-                requestStream.Close();
+                if (data != null)
+                {
+                    string queryString = BuildQueryString(data);
+                    byte[] buffer = System.Text.Encoding.UTF8.GetBytes(queryString);
+                    
+                    request.ContentLength = buffer.Length;
+                    request.ContentType = "application/x-www-form-urlencoded";
+                    using (Stream requestStream = request.GetRequestStream())
+                        requestStream.Write(buffer, 0, buffer.Length);
+                }
+
+                // capture how much time was spent writing, this may seem silly
+                // but with the number concurrent requests, this often blocks
+                tickdata = Util.EnvironmentTickCountSubtract(tickstart);
 
                 using (WebResponse response = request.GetResponse())
                 {
@@ -287,22 +320,10 @@ namespace OpenSim.Framework
                     {
                         string responseStr = null;
 
-                        try
-                        {
-                            responseStr = responseStream.GetStreamString();
-                            OSD responseOSD = OSDParser.Deserialize(responseStr);
-                            if (responseOSD.Type == OSDType.Map)
-                                return (OSDMap)responseOSD;
-                            else
-                                errorMessage = "Response format was invalid.";
-                        }
-                        catch (Exception ex)
-                        {
-                            if (!String.IsNullOrEmpty(responseStr))
-                                errorMessage = "Failed to parse the response:\n" + responseStr;
-                            else
-                                errorMessage = "Failed to retrieve the response: " + ex.Message;
-                        }
+                        responseStr = responseStream.GetStreamString();
+                        OSD responseOSD = OSDParser.Deserialize(responseStr);
+                        if (responseOSD.Type == OSDType.Map)
+                            return (OSDMap)responseOSD;
                     }
                 }
             }
@@ -322,12 +343,12 @@ namespace OpenSim.Framework
             finally
             {
                 int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
-                if (tickdiff > 100)
-                    m_log.WarnFormat("[WEB UTIL]: request <{0}> (URI:{1}, METHOD:{2}) took {3} milliseconds",
-                                     reqnum,url,method,tickdiff);
+                if (tickdiff > LongCallTime)
+                    m_log.InfoFormat("[WEB UTIL]: form request <{0}> (URI:{1}, METHOD:{2}) took {3}ms overall, {4}ms writing",
+                                     reqnum,url,method,tickdiff,tickdata);
             }
 
-            m_log.WarnFormat("[WEB UTIL]: <{0}> request failed: {1}",reqnum,errorMessage);
+            m_log.WarnFormat("[WEB UTIL]: <{0}> form request failed: {1}",reqnum,errorMessage);
             return ErrorResponseMap(errorMessage);
         }