浏览代码

HUE-8031 [core] Also log slow REST calls

Romain Rigaux 7 年之前
父节点
当前提交
da7c851e68

+ 7 - 2
desktop/core/src/desktop/lib/apputil.py

@@ -15,12 +15,17 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
+
 import inspect
-import os
-import sys
 from django.conf import settings
 
 
+# When a Thrift or REST call finishes, the level at which we log its duration
+# depends on the number of millis the call took.
+WARN_LEVEL_CALL_DURATION_MS = 5000
+INFO_LEVEL_CALL_DURATION_MS = 1000
+
+
 def get_current_app(frame=None):
   """
   Return the name of the app from INSTALLED_APPS that is most recently

+ 18 - 6
desktop/core/src/desktop/lib/rest/resource.py

@@ -19,6 +19,7 @@ import posixpath
 import time
 
 from desktop.lib.i18n import smart_unicode
+from desktop.lib.apputil import WARN_LEVEL_CALL_DURATION_MS, INFO_LEVEL_CALL_DURATION_MS
 
 
 LOG = logging.getLogger(__name__)
@@ -95,15 +96,16 @@ class Resource(object):
                                 urlencode=self._urlencode,
                                 clear_cookies=clear_cookies)
 
-    if log_response and self._client.logger.isEnabledFor(logging.DEBUG):
-      self._client.logger.debug(
-        "%s %s Got response%s: %s%s" % (
+    if log_response:
+      duration = time.time() - start_time
+      message = "%s %s Got response%s: %s%s" % (
           method,
           smart_unicode(path, errors='ignore'),
-           ' in %dms' % ((time.time() - start_time) * 1000),
-           smart_unicode(resp.content[:1000], errors='replace'),
-           len(resp.content) > 1000 and "..." or "")
+          ' in %dms' % (duration * 1000),
+          smart_unicode(resp.content[:1000], errors='replace'),
+          len(resp.content) > 1000 and "..." or ""
       )
+      log_if_slow_call(duration=duration, message=message, logger=self._client.logger)
 
     return resp
 
@@ -188,3 +190,13 @@ class Resource(object):
                         log_response=log_response)
 
     return resp.url.encode("utf-8")
+
+
+# Same in thrift_util.py for not losing the trace class
+def log_if_slow_call(duration, message, logger):
+  if duration >= WARN_LEVEL_CALL_DURATION_MS / 1000:
+    logger.warn('SLOW: %.2f - %s' % (duration, message))
+  elif duration >= INFO_LEVEL_CALL_DURATION_MS / 1000:
+    logger.info('SLOW: %.2f - %s' % (duration, message))
+  else:
+    logger.debug(message)

+ 21 - 15
desktop/core/src/desktop/lib/thrift_util.py

@@ -37,6 +37,7 @@ from django.conf import settings
 from django.utils.translation import ugettext as _
 from desktop.conf import SASL_MAX_BUFFER, CHERRYPY_SERVER_THREADS
 
+from desktop.lib.apputil import WARN_LEVEL_CALL_DURATION_MS, INFO_LEVEL_CALL_DURATION_MS
 from desktop.lib.python_util import create_synchronous_io_multiplexer
 from desktop.lib.thrift_.http_client import THttpClient
 from desktop.lib.thrift_.TSSLSocketWithWildcardSAN import TSSLSocketWithWildcardSAN
@@ -44,16 +45,14 @@ from desktop.lib.thrift_sasl import TSaslClientTransport
 from desktop.lib.exceptions import StructuredException, StructuredThriftTransportException
 
 
+LOG = logging.getLogger(__name__)
+
+
 # The maximum depth that we will recurse through a "jsonable" structure
 # while converting to thrift. This prevents us from infinite recursion
 # in the case of circular references.
 MAX_RECURSION_DEPTH = 50
 
-# When a thrift call finishes, the level at which we log its duration
-# depends on the number of millis the call took.
-WARN_LEVEL_CALL_DURATION_MS = 5000
-INFO_LEVEL_CALL_DURATION_MS = 1000
-
 
 class LifoQueue(Queue.Queue):
     '''
@@ -220,13 +219,17 @@ class ConnectionPooler(object):
 
       try:
         connection = self.pooldict[_get_pool_key(conf)].get(block=True, timeout=this_round_timeout)
-        logging.debug("Thrift client %s got connection %s after %.2f seconds" % (self, connection, time.time() - start_pool_get_time))
+        duration = time.time() - start_pool_get_time
+        message = "Thrift client %s got connection %s after %.2f seconds" % (self, connection, duration)
+        log_if_slow_call(duration=duration, message=message)
       except Queue.Empty:
         has_waited_for = time.time() - start_pool_get_time
         if get_client_timeout is not None and has_waited_for > get_client_timeout:
           raise socket.timeout(
             ("Timed out after %.2f seconds waiting to retrieve a %s client from the pool.") % (has_waited_for, conf.service_name))
-        logging.warn("Waited %d seconds for a thrift client to %s:%d" % (has_waited_for, conf.host, conf.port))
+        else:
+          message = "Waited %d seconds for a Thrift client to %s:%d" % (has_waited_for, conf.host, conf.port)
+          log_if_slow_call(duration=has_waited_for, message=message)
 
     return connection
 
@@ -372,8 +375,6 @@ class PooledClient(object):
             superclient.transport.open()
 
           superclient.set_timeout(self.conf.timeout_seconds)
-
-          logging.debug("Thrift client %s call" % superclient)
           return attr(*args, **kwargs)
         except TApplicationException, e:
           # Unknown thrift exception... typically IO errors
@@ -447,12 +448,7 @@ class SuperClient(object):
 
           # Log the duration at different levels, depending on how long it took.
           logmsg = "Thrift call: %s.%s(args=%s, kwargs=%s) returned in %dms: %s" % (str(self.wrapped.__class__), attr, str_args, repr(kwargs), duration * 1000, log_msg)
-          if duration >= WARN_LEVEL_CALL_DURATION_MS / 1000:
-            logging.warn(logmsg)
-          elif duration >= INFO_LEVEL_CALL_DURATION_MS / 1000:
-            logging.info(logmsg)
-          else:
-            logging.debug(logmsg)
+          log_if_slow_call(duration=duration, message=logmsg)
 
           return ret
         except socket.error, e:
@@ -750,3 +746,13 @@ def fixup_enums(obj, name_class_map, suffix="AsString"):
 
 def is_thrift_struct(o):
   return hasattr(o.__class__, "thrift_spec")
+
+
+# Same in resource.py for not losing the trace class
+def log_if_slow_call(duration, message):
+  if duration >= WARN_LEVEL_CALL_DURATION_MS / 1000:
+    LOG.warn('SLOW: %.2f - %s' % (duration, message))
+  elif duration >= INFO_LEVEL_CALL_DURATION_MS / 1000:
+    LOG.info('SLOW: %.2f - %s' % (duration, message))
+  else:
+    LOG.debug(message)