From df5e4a1e5b8ef0f02b6b796a1f3fd72671a81a79 Mon Sep 17 00:00:00 2001
From: Mic Bowman
Date: Wed, 29 Dec 2010 20:47:51 -0800
Subject: Standardize the way WebRequests are made in the
SimulationServiceConnector. Added debugging calls for tracking performance of
web requests.
---
OpenSim/Framework/WebUtil.cs | 168 ++++++++++++++++++++++++++++++++++++++++++-
1 file changed, 165 insertions(+), 3 deletions(-)
(limited to 'OpenSim/Framework')
diff --git a/OpenSim/Framework/WebUtil.cs b/OpenSim/Framework/WebUtil.cs
index 1c856af..1cd9054 100644
--- a/OpenSim/Framework/WebUtil.cs
+++ b/OpenSim/Framework/WebUtil.cs
@@ -50,6 +50,8 @@ namespace OpenSim.Framework
LogManager.GetLogger(
MethodBase.GetCurrentMethod().DeclaringType);
+ private static int m_requestNumber = 0;
+
///
/// Send LLSD to an HTTP client in application/llsd+json form
///
@@ -123,12 +125,145 @@ namespace OpenSim.Framework
}
///
+ /// PUT JSON-encoded data to a web service that returns LLSD or
+ /// JSON data
+ ///
+ public static OSDMap PutToService(string url, OSDMap data)
+ {
+ return ServiceOSDRequest(url,data,"PUT",10000);
+ }
+
+ public static OSDMap PostToService(string url, OSDMap data)
+ {
+ return ServiceOSDRequest(url,data,"POST",10000);
+ }
+
+ public static OSDMap GetFromService(string url)
+ {
+ return ServiceOSDRequest(url,null,"GET",10000);
+ }
+
+ public static OSDMap ServiceOSDRequest(string url, OSDMap data, string method, int timeout)
+ {
+ int reqnum = m_requestNumber++;
+ m_log.WarnFormat("[WEB UTIL]: <{0}> start osd request for {1}, method {2}",reqnum,url,method);
+
+ string errorMessage = "unknown error";
+ int tickstart = Util.EnvironmentTickCount();
+ try
+ {
+ HttpWebRequest request = (HttpWebRequest)WebRequest.Create(url);
+ request.Method = method;
+ request.Timeout = timeout;
+ //request.KeepAlive = false;
+
+ // 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
+ }
+ }
+
+ using (WebResponse webResponse = request.GetResponse())
+ {
+ using (Stream responseStream = webResponse.GetResponseStream())
+ {
+ string responseStr = null;
+ responseStr = responseStream.GetStreamString();
+ m_log.WarnFormat("[WEB UTIL]: <{0}> response is <{1}>",reqnum,responseStr);
+ return CanonicalizeResults(responseStr);
+ }
+ }
+ }
+ catch (WebException we)
+ {
+ errorMessage = we.Message;
+ if (we.Status == WebExceptionStatus.ProtocolError)
+ {
+ HttpWebResponse webResponse = (HttpWebResponse)we.Response;
+ errorMessage = String.Format("[{0}] {1}",webResponse.StatusCode,webResponse.StatusDescription);
+ }
+ }
+ catch (Exception ex)
+ {
+ errorMessage = ex.Message;
+ }
+ finally
+ {
+ int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
+ if (tickdiff > 100)
+ m_log.WarnFormat("[WEB UTIL]: request <{0}> took {1} milliseconds",reqnum,tickdiff);
+ }
+
+ m_log.WarnFormat("[WEB UTIL] <{0}> request failed: {1}",reqnum,errorMessage);
+ return ErrorResponseMap(errorMessage);
+ }
+
+ ///
+ /// Since there are no consistencies in the way web requests are
+ /// formed, we need to do a little guessing about the result format.
+ /// Keys:
+ /// Success|success == the success fail of the request
+ /// _RawResult == the raw string that came back
+ /// _Result == the OSD unpacked string
+ ///
+ private static OSDMap CanonicalizeResults(string response)
+ {
+ OSDMap result = new OSDMap();
+
+ // Default values
+ result["Success"] = OSD.FromBoolean(true);
+ result["success"] = OSD.FromBoolean(true);
+ result["_RawResult"] = OSD.FromString(response);
+ result["_Result"] = new OSDMap();
+
+ if (response.Equals("true",System.StringComparison.OrdinalIgnoreCase))
+ return result;
+
+ if (response.Equals("false",System.StringComparison.OrdinalIgnoreCase))
+ {
+ result["Success"] = OSD.FromBoolean(false);
+ result["success"] = OSD.FromBoolean(false);
+ return result;
+ }
+
+ try
+ {
+ OSD responseOSD = OSDParser.Deserialize(response);
+ if (responseOSD.Type == OSDType.Map)
+ {
+ result["_Result"] = (OSDMap)responseOSD;
+ return result;
+ }
+ }
+ 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);
+ }
+
+ return result;
+ }
+
+ ///
/// POST URL-encoded form data to a web service that returns LLSD or
/// JSON data
///
public static OSDMap PostToService(string url, NameValueCollection data)
{
+ int reqnum = m_requestNumber++;
+ string method = data["RequestMethod"] != null ? data["RequestMethod"] : "unknown";
+ m_log.WarnFormat("[WEB UTIL]: <{0}> start form request for {1}, method {2}",reqnum,url,method);
+
string errorMessage;
+ int tickstart = Util.EnvironmentTickCount();
try
{
@@ -139,7 +274,7 @@ namespace OpenSim.Framework
request.Method = "POST";
request.ContentLength = requestData.Length;
request.ContentType = "application/x-www-form-urlencoded";
-
+
Stream requestStream = request.GetRequestStream();
requestStream.Write(requestData, 0, requestData.Length);
requestStream.Close();
@@ -169,15 +304,42 @@ namespace OpenSim.Framework
}
}
}
+ catch (WebException we)
+ {
+ errorMessage = we.Message;
+ if (we.Status == WebExceptionStatus.ProtocolError)
+ {
+ HttpWebResponse webResponse = (HttpWebResponse)we.Response;
+ errorMessage = String.Format("[{0}] {1}",webResponse.StatusCode,webResponse.StatusDescription);
+ }
+ }
catch (Exception ex)
{
- m_log.Warn("POST to URL " + url + " failed: " + ex);
errorMessage = ex.Message;
}
+ finally
+ {
+ int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
+ if (tickdiff > 100)
+ m_log.WarnFormat("[WEB UTIL]: request <{0}> took {1} milliseconds",reqnum,tickdiff);
+ }
- return new OSDMap { { "Message", OSD.FromString("Service request failed. " + errorMessage) } };
+ m_log.WarnFormat("[WEB UTIL]: <{0}> request failed: {1}",reqnum,errorMessage);
+ return ErrorResponseMap(errorMessage);
}
+ ///
+ /// Create a response map for an error, trying to keep
+ /// the result formats consistent
+ ///
+ private static OSDMap ErrorResponseMap(string msg)
+ {
+ OSDMap result = new OSDMap();
+ result["Success"] = "False";
+ result["Message"] = OSD.FromString("Service request failed: " + msg);
+ return result;
+ }
+
#region Uri
///
--
cgit v1.1
From e0da281e3d70fbe1752815f5a7ae4b3ed0cf15ba Mon Sep 17 00:00:00 2001
From: Mic Bowman
Date: Mon, 3 Jan 2011 17:16:22 -0800
Subject: Cleaned up debugging messages in the WebRequest handlers
---
OpenSim/Framework/WebUtil.cs | 13 ++++++++-----
1 file changed, 8 insertions(+), 5 deletions(-)
(limited to 'OpenSim/Framework')
diff --git a/OpenSim/Framework/WebUtil.cs b/OpenSim/Framework/WebUtil.cs
index 1cd9054..a00ea88 100644
--- a/OpenSim/Framework/WebUtil.cs
+++ b/OpenSim/Framework/WebUtil.cs
@@ -146,7 +146,7 @@ namespace OpenSim.Framework
public static OSDMap ServiceOSDRequest(string url, OSDMap data, string method, int timeout)
{
int reqnum = m_requestNumber++;
- m_log.WarnFormat("[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();
@@ -177,7 +177,7 @@ namespace OpenSim.Framework
{
string responseStr = null;
responseStr = responseStream.GetStreamString();
- m_log.WarnFormat("[WEB UTIL]: <{0}> response is <{1}>",reqnum,responseStr);
+ // m_log.DebugFormat("[WEB UTIL]: <{0}> response is <{1}>",reqnum,responseStr);
return CanonicalizeResults(responseStr);
}
}
@@ -197,9 +197,11 @@ namespace OpenSim.Framework
}
finally
{
+ // 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}> took {1} milliseconds",reqnum,tickdiff);
+ m_log.WarnFormat("[WEB UTIL]: request <{0}> (URI:{1}, METHOD:{2}) took {3} milliseconds",
+ reqnum,url,method,tickdiff);
}
m_log.WarnFormat("[WEB UTIL] <{0}> request failed: {1}",reqnum,errorMessage);
@@ -260,7 +262,7 @@ namespace OpenSim.Framework
{
int reqnum = m_requestNumber++;
string method = data["RequestMethod"] != null ? data["RequestMethod"] : "unknown";
- m_log.WarnFormat("[WEB UTIL]: <{0}> start form request for {1}, method {2}",reqnum,url,method);
+ m_log.DebugFormat("[WEB UTIL]: <{0}> start form request for {1}, method {2}",reqnum,url,method);
string errorMessage;
int tickstart = Util.EnvironmentTickCount();
@@ -321,7 +323,8 @@ namespace OpenSim.Framework
{
int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
if (tickdiff > 100)
- m_log.WarnFormat("[WEB UTIL]: request <{0}> took {1} milliseconds",reqnum,tickdiff);
+ m_log.WarnFormat("[WEB UTIL]: request <{0}> (URI:{1}, METHOD:{2}) took {3} milliseconds",
+ reqnum,url,method,tickdiff);
}
m_log.WarnFormat("[WEB UTIL]: <{0}> request failed: {1}",reqnum,errorMessage);
--
cgit v1.1
From 984a9b408534d42f18bd072f70f9e2b31a691f9f Mon Sep 17 00:00:00 2001
From: Mic Bowman
Date: Wed, 5 Jan 2011 14:32:00 -0800
Subject: 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
---
.../Framework/Servers/HttpServer/BaseHttpServer.cs | 16 ++-
OpenSim/Framework/WebUtil.cs | 115 ++++++++++++---------
2 files changed, 83 insertions(+), 48 deletions(-)
(limited to 'OpenSim/Framework')
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
///
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;
+
///
/// Send LLSD to an HTTP client in application/llsd+json form
///
@@ -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
///
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);
}
--
cgit v1.1