aboutsummaryrefslogtreecommitdiffstatshomepage
path: root/OpenSim/Framework
diff options
context:
space:
mode:
authorJustin Clark-Casey (justincc)2012-05-04 01:12:56 +0100
committerJustin Clark-Casey (justincc)2012-05-04 01:12:56 +0100
commitc9faf0df741c89ec92b09d54ab471b070e5a1dff (patch)
treeb9804b6b5b652e5fb863661ebb1a0737c142720e /OpenSim/Framework
parentMerge branch 'master' of ssh://opensimulator.org/var/git/opensim (diff)
downloadopensim-SC_OLD-c9faf0df741c89ec92b09d54ab471b070e5a1dff.zip
opensim-SC_OLD-c9faf0df741c89ec92b09d54ab471b070e5a1dff.tar.gz
opensim-SC_OLD-c9faf0df741c89ec92b09d54ab471b070e5a1dff.tar.bz2
opensim-SC_OLD-c9faf0df741c89ec92b09d54ab471b070e5a1dff.tar.xz
Extend 'slow' request logging to other server outbound requests (forms, rest, async rest) as well as the existing logging on outbound OSD requests.
Also prints out the first 100 chars of any slow request data since this can contain useful info (such as agent ID).
Diffstat (limited to 'OpenSim/Framework')
-rw-r--r--OpenSim/Framework/WebUtil.cs273
1 files changed, 194 insertions, 79 deletions
diff --git a/OpenSim/Framework/WebUtil.cs b/OpenSim/Framework/WebUtil.cs
index d2aa538..478d2a7 100644
--- a/OpenSim/Framework/WebUtil.cs
+++ b/OpenSim/Framework/WebUtil.cs
@@ -53,19 +53,36 @@ namespace OpenSim.Framework
53 LogManager.GetLogger( 53 LogManager.GetLogger(
54 MethodBase.GetCurrentMethod().DeclaringType); 54 MethodBase.GetCurrentMethod().DeclaringType);
55 55
56 private static int m_requestNumber = 0; 56 /// <summary>
57 /// Request number for diagnostic purposes.
58 /// </summary>
59 public static int RequestNumber = 0;
57 60
58 // this is the header field used to communicate the local request id 61 /// <summary>
59 // used for performance and debugging 62 /// this is the header field used to communicate the local request id
63 /// used for performance and debugging
64 /// </summary>
60 public const string OSHeaderRequestID = "opensim-request-id"; 65 public const string OSHeaderRequestID = "opensim-request-id";
61 66
62 // number of milliseconds a call can take before it is considered 67 /// <summary>
63 // a "long" call for warning & debugging purposes 68 /// Number of milliseconds a call can take before it is considered
69 /// a "long" call for warning & debugging purposes
70 /// </summary>
64 public const int LongCallTime = 500; 71 public const int LongCallTime = 500;
65 72
66 // dictionary of end points 73 /// <summary>
74 /// The maximum length of any data logged because of a long request time.
75 /// </summary>
76 /// <remarks>
77 /// This is to truncate any really large post data, such as an asset. In theory, the first section should
78 /// give us useful information about the call (which agent it relates to if applicable, etc.).
79 /// </remarks>
80 public const int MaxRequestDiagLength = 100;
81
82 /// <summary>
83 /// Dictionary of end points
84 /// </summary>
67 private static Dictionary<string,object> m_endpointSerializer = new Dictionary<string,object>(); 85 private static Dictionary<string,object> m_endpointSerializer = new Dictionary<string,object>();
68
69 86
70 private static object EndPointLock(string url) 87 private static object EndPointLock(string url)
71 { 88 {
@@ -128,12 +145,13 @@ namespace OpenSim.Framework
128 145
129 private static OSDMap ServiceOSDRequestWorker(string url, OSDMap data, string method, int timeout, bool compressed) 146 private static OSDMap ServiceOSDRequestWorker(string url, OSDMap data, string method, int timeout, bool compressed)
130 { 147 {
131 int reqnum = m_requestNumber++; 148 int reqnum = RequestNumber++;
132 // m_log.DebugFormat("[WEB UTIL]: <{0}> start osd request for {1}, method {2}",reqnum,url,method); 149 // m_log.DebugFormat("[WEB UTIL]: <{0}> start osd request for {1}, method {2}",reqnum,url,method);
133 150
134 string errorMessage = "unknown error"; 151 string errorMessage = "unknown error";
135 int tickstart = Util.EnvironmentTickCount(); 152 int tickstart = Util.EnvironmentTickCount();
136 int tickdata = 0; 153 int tickdata = 0;
154 string strBuffer = null;
137 155
138 try 156 try
139 { 157 {
@@ -148,7 +166,7 @@ namespace OpenSim.Framework
148 // If there is some input, write it into the request 166 // If there is some input, write it into the request
149 if (data != null) 167 if (data != null)
150 { 168 {
151 string strBuffer = OSDParser.SerializeJsonString(data); 169 strBuffer = OSDParser.SerializeJsonString(data);
152 byte[] buffer = System.Text.Encoding.UTF8.GetBytes(strBuffer); 170 byte[] buffer = System.Text.Encoding.UTF8.GetBytes(strBuffer);
153 171
154 if (compressed) 172 if (compressed)
@@ -208,11 +226,18 @@ namespace OpenSim.Framework
208 } 226 }
209 finally 227 finally
210 { 228 {
211 // This just dumps a warning for any operation that takes more than 100 ms
212 int tickdiff = Util.EnvironmentTickCountSubtract(tickstart); 229 int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
213 if (tickdiff > LongCallTime) 230 if (tickdiff > LongCallTime)
214 m_log.DebugFormat("[WEB UTIL]: osd request <{0}> (URI:{1}, METHOD:{2}) took {3}ms overall, {4}ms writing", 231 m_log.InfoFormat(
215 reqnum,url,method,tickdiff,tickdata); 232 "[OSD REQUEST]: Slow request to <{0}> {1} {2} took {3}ms, {4}ms writing, {5}",
233 reqnum,
234 method,
235 url,
236 tickdiff,
237 tickdata,
238 strBuffer != null
239 ? (strBuffer.Length > MaxRequestDiagLength ? strBuffer.Remove(MaxRequestDiagLength) : strBuffer)
240 : "");
216 } 241 }
217 242
218 m_log.DebugFormat( 243 m_log.DebugFormat(
@@ -290,17 +315,17 @@ namespace OpenSim.Framework
290 315
291 private static OSDMap ServiceFormRequestWorker(string url, NameValueCollection data, int timeout) 316 private static OSDMap ServiceFormRequestWorker(string url, NameValueCollection data, int timeout)
292 { 317 {
293 int reqnum = m_requestNumber++; 318 int reqnum = RequestNumber++;
294 string method = (data != null && data["RequestMethod"] != null) ? data["RequestMethod"] : "unknown"; 319 string method = (data != null && data["RequestMethod"] != null) ? data["RequestMethod"] : "unknown";
295 // m_log.DebugFormat("[WEB UTIL]: <{0}> start form request for {1}, method {2}",reqnum,url,method); 320 // m_log.DebugFormat("[WEB UTIL]: <{0}> start form request for {1}, method {2}",reqnum,url,method);
296 321
297 string errorMessage = "unknown error"; 322 string errorMessage = "unknown error";
298 int tickstart = Util.EnvironmentTickCount(); 323 int tickstart = Util.EnvironmentTickCount();
299 int tickdata = 0; 324 int tickdata = 0;
325 string queryString = null;
300 326
301 try 327 try
302 { 328 {
303
304 HttpWebRequest request = (HttpWebRequest)HttpWebRequest.Create(url); 329 HttpWebRequest request = (HttpWebRequest)HttpWebRequest.Create(url);
305 request.Method = "POST"; 330 request.Method = "POST";
306 request.Timeout = timeout; 331 request.Timeout = timeout;
@@ -311,7 +336,7 @@ namespace OpenSim.Framework
311 336
312 if (data != null) 337 if (data != null)
313 { 338 {
314 string queryString = BuildQueryString(data); 339 queryString = BuildQueryString(data);
315 byte[] buffer = System.Text.Encoding.UTF8.GetBytes(queryString); 340 byte[] buffer = System.Text.Encoding.UTF8.GetBytes(queryString);
316 341
317 request.ContentLength = buffer.Length; 342 request.ContentLength = buffer.Length;
@@ -354,11 +379,19 @@ namespace OpenSim.Framework
354 { 379 {
355 int tickdiff = Util.EnvironmentTickCountSubtract(tickstart); 380 int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
356 if (tickdiff > LongCallTime) 381 if (tickdiff > LongCallTime)
357 m_log.InfoFormat("[WEB UTIL]: form request <{0}> (URI:{1}, METHOD:{2}) took {3}ms overall, {4}ms writing", 382 m_log.InfoFormat(
358 reqnum,url,method,tickdiff,tickdata); 383 "[SERVICE FORM]: Slow request to <{0}> {1} {2} took {3}ms, {4}ms writing, {5}",
384 reqnum,
385 method,
386 url,
387 tickdiff,
388 tickdata,
389 queryString != null
390 ? (queryString.Length > MaxRequestDiagLength) ? queryString.Remove(MaxRequestDiagLength) : queryString
391 : "");
359 } 392 }
360 393
361 m_log.WarnFormat("[WEB UTIL]: <{0}> form request to {1} failed: {2}", reqnum, url, errorMessage); 394 m_log.WarnFormat("[SERVICE FORM]: <{0}> form request to {1} failed: {2}", reqnum, url, errorMessage);
362 395
363 return ErrorResponseMap(errorMessage); 396 return ErrorResponseMap(errorMessage);
364 } 397 }
@@ -639,8 +672,6 @@ namespace OpenSim.Framework
639 672
640 return new string[0]; 673 return new string[0];
641 } 674 }
642
643
644 } 675 }
645 676
646 public static class AsynchronousRestObjectRequester 677 public static class AsynchronousRestObjectRequester
@@ -663,6 +694,12 @@ namespace OpenSim.Framework
663 public static void MakeRequest<TRequest, TResponse>(string verb, 694 public static void MakeRequest<TRequest, TResponse>(string verb,
664 string requestUrl, TRequest obj, Action<TResponse> action) 695 string requestUrl, TRequest obj, Action<TResponse> action)
665 { 696 {
697 int reqnum = WebUtil.RequestNumber++;
698 // m_log.DebugFormat("[WEB UTIL]: <{0}> start osd request for {1}, method {2}",reqnum,url,method);
699
700 int tickstart = Util.EnvironmentTickCount();
701 int tickdata = 0;
702
666 // m_log.DebugFormat("[ASYNC REQUEST]: Starting {0} {1}", verb, requestUrl); 703 // m_log.DebugFormat("[ASYNC REQUEST]: Starting {0} {1}", verb, requestUrl);
667 704
668 Type type = typeof(TRequest); 705 Type type = typeof(TRequest);
@@ -673,12 +710,13 @@ namespace OpenSim.Framework
673 XmlSerializer deserializer = new XmlSerializer(typeof(TResponse)); 710 XmlSerializer deserializer = new XmlSerializer(typeof(TResponse));
674 711
675 request.Method = verb; 712 request.Method = verb;
713 MemoryStream buffer = null;
676 714
677 if (verb == "POST") 715 if (verb == "POST")
678 { 716 {
679 request.ContentType = "text/xml"; 717 request.ContentType = "text/xml";
680 718
681 MemoryStream buffer = new MemoryStream(); 719 buffer = new MemoryStream();
682 720
683 XmlWriterSettings settings = new XmlWriterSettings(); 721 XmlWriterSettings settings = new XmlWriterSettings();
684 settings.Encoding = Encoding.UTF8; 722 settings.Encoding = Encoding.UTF8;
@@ -700,6 +738,9 @@ namespace OpenSim.Framework
700 requestStream.Write(buffer.ToArray(), 0, length); 738 requestStream.Write(buffer.ToArray(), 0, length);
701 requestStream.Close(); 739 requestStream.Close();
702 740
741 // capture how much time was spent writing
742 tickdata = Util.EnvironmentTickCountSubtract(tickstart);
743
703 request.BeginGetResponse(delegate(IAsyncResult ar) 744 request.BeginGetResponse(delegate(IAsyncResult ar)
704 { 745 {
705 response = request.EndGetResponse(ar); 746 response = request.EndGetResponse(ar);
@@ -725,88 +766,108 @@ namespace OpenSim.Framework
725 766
726 }, null); 767 }, null);
727 }, null); 768 }, null);
728
729
730 return;
731 } 769 }
732 770 else
733 request.BeginGetResponse(delegate(IAsyncResult res2)
734 { 771 {
735 try 772 request.BeginGetResponse(delegate(IAsyncResult res2)
736 { 773 {
737 // If the server returns a 404, this appears to trigger a System.Net.WebException even though that isn't
738 // documented in MSDN
739 response = request.EndGetResponse(res2);
740
741 Stream respStream = null;
742 try 774 try
743 { 775 {
744 respStream = response.GetResponseStream(); 776 // If the server returns a 404, this appears to trigger a System.Net.WebException even though that isn't
745 deserial = (TResponse)deserializer.Deserialize(respStream); 777 // documented in MSDN
746 } 778 response = request.EndGetResponse(res2);
747 catch (System.InvalidOperationException) 779
748 { 780 Stream respStream = null;
749 } 781 try
750 finally 782 {
751 { 783 respStream = response.GetResponseStream();
752 respStream.Close(); 784 deserial = (TResponse)deserializer.Deserialize(respStream);
753 response.Close(); 785 }
786 catch (System.InvalidOperationException)
787 {
788 }
789 finally
790 {
791 respStream.Close();
792 response.Close();
793 }
754 } 794 }
755 } 795 catch (WebException e)
756 catch (WebException e)
757 {
758 if (e.Status == WebExceptionStatus.ProtocolError)
759 { 796 {
760 if (e.Response is HttpWebResponse) 797 if (e.Status == WebExceptionStatus.ProtocolError)
761 { 798 {
762 HttpWebResponse httpResponse = (HttpWebResponse)e.Response; 799 if (e.Response is HttpWebResponse)
763
764 if (httpResponse.StatusCode != HttpStatusCode.NotFound)
765 { 800 {
766 // We don't appear to be handling any other status codes, so log these feailures to that 801 HttpWebResponse httpResponse = (HttpWebResponse)e.Response;
767 // people don't spend unnecessary hours hunting phantom bugs. 802
768 m_log.DebugFormat( 803 if (httpResponse.StatusCode != HttpStatusCode.NotFound)
769 "[ASYNC REQUEST]: Request {0} {1} failed with unexpected status code {2}", 804 {
770 verb, requestUrl, httpResponse.StatusCode); 805 // We don't appear to be handling any other status codes, so log these feailures to that
806 // people don't spend unnecessary hours hunting phantom bugs.
807 m_log.DebugFormat(
808 "[ASYNC REQUEST]: Request {0} {1} failed with unexpected status code {2}",
809 verb, requestUrl, httpResponse.StatusCode);
810 }
771 } 811 }
772 } 812 }
813 else
814 {
815 m_log.ErrorFormat(
816 "[ASYNC REQUEST]: Request {0} {1} failed with status {2} and message {3}",
817 verb, requestUrl, e.Status, e.Message);
818 }
773 } 819 }
774 else 820 catch (Exception e)
775 { 821 {
776 m_log.ErrorFormat( 822 m_log.ErrorFormat(
777 "[ASYNC REQUEST]: Request {0} {1} failed with status {2} and message {3}", 823 "[ASYNC REQUEST]: Request {0} {1} failed with exception {2}{3}",
778 verb, requestUrl, e.Status, e.Message); 824 verb, requestUrl, e.Message, e.StackTrace);
779 } 825 }
780 } 826
781 catch (Exception e) 827 // m_log.DebugFormat("[ASYNC REQUEST]: Received {0}", deserial.ToString());
782 { 828
783 m_log.ErrorFormat( 829 try
784 "[ASYNC REQUEST]: Request {0} {1} failed with exception {2}{3}", 830 {
785 verb, requestUrl, e.Message, e.StackTrace); 831 action(deserial);
786 } 832 }
833 catch (Exception e)
834 {
835 m_log.ErrorFormat(
836 "[ASYNC REQUEST]: Request {0} {1} callback failed with exception {2}{3}",
837 verb, requestUrl, e.Message, e.StackTrace);
838 }
839
840 }, null);
841 }
787 842
788 // m_log.DebugFormat("[ASYNC REQUEST]: Received {0}", deserial.ToString()); 843 int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
844 if (tickdiff > WebUtil.LongCallTime)
845 {
846 string originalRequest = null;
789 847
790 try 848 if (buffer != null)
791 {
792 action(deserial);
793 }
794 catch (Exception e)
795 { 849 {
796 m_log.ErrorFormat( 850 originalRequest = Encoding.UTF8.GetString(buffer.ToArray());
797 "[ASYNC REQUEST]: Request {0} {1} callback failed with exception {2}{3}", 851
798 verb, requestUrl, e.Message, e.StackTrace); 852 if (originalRequest.Length > WebUtil.MaxRequestDiagLength)
853 originalRequest = originalRequest.Remove(WebUtil.MaxRequestDiagLength);
799 } 854 }
800 855
801 }, null); 856 m_log.InfoFormat(
857 "[ASYNC REQUEST]: Slow request to <{0}> {1} {2} took {3}ms, {4}ms writing, {5}",
858 reqnum,
859 verb,
860 requestUrl,
861 tickdiff,
862 tickdata,
863 originalRequest);
864 }
802 } 865 }
803 } 866 }
804 867
805 public static class SynchronousRestFormsRequester 868 public static class SynchronousRestFormsRequester
806 { 869 {
807 private static readonly ILog m_log = 870 private static readonly ILog m_log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);
808 LogManager.GetLogger(
809 MethodBase.GetCurrentMethod().DeclaringType);
810 871
811 /// <summary> 872 /// <summary>
812 /// Perform a synchronous REST request. 873 /// Perform a synchronous REST request.
@@ -820,6 +881,12 @@ namespace OpenSim.Framework
820 /// the request. You'll want to make sure you deal with this as they're not uncommon</exception> 881 /// the request. You'll want to make sure you deal with this as they're not uncommon</exception>
821 public static string MakeRequest(string verb, string requestUrl, string obj) 882 public static string MakeRequest(string verb, string requestUrl, string obj)
822 { 883 {
884 int reqnum = WebUtil.RequestNumber++;
885 // m_log.DebugFormat("[WEB UTIL]: <{0}> start osd request for {1}, method {2}",reqnum,url,method);
886
887 int tickstart = Util.EnvironmentTickCount();
888 int tickdata = 0;
889
823 WebRequest request = WebRequest.Create(requestUrl); 890 WebRequest request = WebRequest.Create(requestUrl);
824 request.Method = verb; 891 request.Method = verb;
825 string respstring = String.Empty; 892 string respstring = String.Empty;
@@ -855,6 +922,9 @@ namespace OpenSim.Framework
855 { 922 {
856 if (requestStream != null) 923 if (requestStream != null)
857 requestStream.Close(); 924 requestStream.Close();
925
926 // capture how much time was spent writing
927 tickdata = Util.EnvironmentTickCountSubtract(tickstart);
858 } 928 }
859 } 929 }
860 930
@@ -893,6 +963,18 @@ namespace OpenSim.Framework
893 m_log.DebugFormat("[FORMS]: InvalidOperationException on receiving {0} {1}", verb, requestUrl); 963 m_log.DebugFormat("[FORMS]: InvalidOperationException on receiving {0} {1}", verb, requestUrl);
894 } 964 }
895 } 965 }
966
967 int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
968 if (tickdiff > WebUtil.LongCallTime)
969 m_log.InfoFormat(
970 "[FORMS]: Slow request to <{0}> {1} {2} took {3}ms, {4}ms writing, {5}",
971 reqnum,
972 verb,
973 requestUrl,
974 tickdiff,
975 tickdata,
976 obj.Length > WebUtil.MaxRequestDiagLength ? obj.Remove(WebUtil.MaxRequestDiagLength) : obj);
977
896 return respstring; 978 return respstring;
897 } 979 }
898 } 980 }
@@ -915,17 +997,24 @@ namespace OpenSim.Framework
915 /// the request. You'll want to make sure you deal with this as they're not uncommon</exception> 997 /// the request. You'll want to make sure you deal with this as they're not uncommon</exception>
916 public static TResponse MakeRequest<TRequest, TResponse>(string verb, string requestUrl, TRequest obj) 998 public static TResponse MakeRequest<TRequest, TResponse>(string verb, string requestUrl, TRequest obj)
917 { 999 {
1000 int reqnum = WebUtil.RequestNumber++;
1001 // m_log.DebugFormat("[WEB UTIL]: <{0}> start osd request for {1}, method {2}",reqnum,url,method);
1002
1003 int tickstart = Util.EnvironmentTickCount();
1004 int tickdata = 0;
1005
918 Type type = typeof(TRequest); 1006 Type type = typeof(TRequest);
919 TResponse deserial = default(TResponse); 1007 TResponse deserial = default(TResponse);
920 1008
921 WebRequest request = WebRequest.Create(requestUrl); 1009 WebRequest request = WebRequest.Create(requestUrl);
922 request.Method = verb; 1010 request.Method = verb;
1011 MemoryStream buffer = null;
923 1012
924 if ((verb == "POST") || (verb == "PUT")) 1013 if ((verb == "POST") || (verb == "PUT"))
925 { 1014 {
926 request.ContentType = "text/xml"; 1015 request.ContentType = "text/xml";
927 1016
928 MemoryStream buffer = new MemoryStream(); 1017 buffer = new MemoryStream();
929 1018
930 XmlWriterSettings settings = new XmlWriterSettings(); 1019 XmlWriterSettings settings = new XmlWriterSettings();
931 settings.Encoding = Encoding.UTF8; 1020 settings.Encoding = Encoding.UTF8;
@@ -958,6 +1047,9 @@ namespace OpenSim.Framework
958 { 1047 {
959 if (requestStream != null) 1048 if (requestStream != null)
960 requestStream.Close(); 1049 requestStream.Close();
1050
1051 // capture how much time was spent writing
1052 tickdata = Util.EnvironmentTickCountSubtract(tickstart);
961 } 1053 }
962 } 1054 }
963 1055
@@ -1005,6 +1097,29 @@ namespace OpenSim.Framework
1005 verb, requestUrl, e.Message, e.StackTrace); 1097 verb, requestUrl, e.Message, e.StackTrace);
1006 } 1098 }
1007 1099
1100 int tickdiff = Util.EnvironmentTickCountSubtract(tickstart);
1101 if (tickdiff > WebUtil.LongCallTime)
1102 {
1103 string originalRequest = null;
1104
1105 if (buffer != null)
1106 {
1107 originalRequest = Encoding.UTF8.GetString(buffer.ToArray());
1108
1109 if (originalRequest.Length > WebUtil.MaxRequestDiagLength)
1110 originalRequest = originalRequest.Remove(WebUtil.MaxRequestDiagLength);
1111 }
1112
1113 m_log.InfoFormat(
1114 "[SynchronousRestObjectRequester]: Slow request to <{0}> {1} {2} took {3}ms, {4}ms writing, {5}",
1115 reqnum,
1116 verb,
1117 requestUrl,
1118 tickdiff,
1119 tickdata,
1120 originalRequest);
1121 }
1122
1008 return deserial; 1123 return deserial;
1009 } 1124 }
1010 } 1125 }