Initial work on tracing middleware

Author: ekampf

graphql/execution/base.py

@@ -128,9 +128,10 @@ class ExecutionResult(object):
 
     __slots__ = 'data', 'errors', 'invalid'
 
-    def __init__(self, data=None, errors=None, invalid=False):
+    def __init__(self, data=None, errors=None, extensions=None, invalid=False):
         self.data = data
         self.errors = errors
+        self.extensions = extensions or dict()
 
         if invalid:
             assert data is None

graphql/execution/executor.py

@@ -19,6 +19,7 @@
                    get_operation_root_type, SubscriberExecutionContext)
 from .executors.sync import SyncExecutor
 from .middleware import MiddlewareManager
+from .tracing import TracingMiddleware
 
 logger = logging.getLogger(__name__)
 
@@ -30,12 +31,23 @@ def subscribe(*args, **kwargs):
 
 def execute(schema, document_ast, root_value=None, context_value=None,
             variable_values=None, operation_name=None, executor=None,
-            return_promise=False, middleware=None, allow_subscriptions=False):
+            return_promise=False, middleware=None, allow_subscriptions=False,
+            tracing=True):
     assert schema, 'Must provide schema'
     assert isinstance(schema, GraphQLSchema), (
         'Schema must be an instance of GraphQLSchema. Also ensure that there are ' +
         'not multiple versions of GraphQL installed in your node_modules directory.'
     )
+
+    if tracing:
+        tracing_middleware = TracingMiddleware()
+        tracing_middleware.start()
+
+        if not isinstance(middleware, MiddlewareManager):
+            middleware = MiddlewareManager(tracing_middleware)
+        else:
+            middleware.middlewares.insert(0, tracing_middleware)
+
     if middleware:
         if not isinstance(middleware, MiddlewareManager):
             middleware = MiddlewareManager(*middleware)
@@ -71,12 +83,14 @@ def on_resolve(data):
         if isinstance(data, Observable):
             return data
 
+        extensions = dict(tracing=tracing_middleware.tracing_dict)
+
         if not context.errors:
-            return ExecutionResult(data=data)
-        return ExecutionResult(data=data, errors=context.errors)
+            return ExecutionResult(data=data, extensions=extensions)
+
+        return ExecutionResult(data=data, extensions=extensions, errors=context.errors)
 
-    promise = Promise.resolve(None).then(
-        executor).catch(on_rejected).then(on_resolve)
+    promise = Promise.resolve(None).then(executor).catch(on_rejected).then(on_resolve)
 
     if not return_promise:
         context.executor.wait_until_finished()
@@ -326,8 +340,7 @@ def complete_value_catching_error(exe_context, return_type, field_asts, info, re
     # Otherwise, error protection is applied, logging the error and
     # resolving a null value for this field if one is encountered.
     try:
-        completed = complete_value(
-            exe_context, return_type, field_asts, info, result)
+        completed = complete_value(exe_context, return_type, field_asts, info, result)
         if is_thenable(completed):
             def handle_error(error):
                 traceback = completed._traceback

graphql/execution/tracing.py

@@ -0,0 +1,61 @@
+import time
+import datetime
+
+class TracingMiddleware(object):
+    DATETIME_FORMAT = '%Y-%m-%dT%H:%M:%S.%fZ'
+
+    def __init__(self):
+        self.resolver_stats = list()
+        self.start_time = None
+        self.end_time = None
+
+    def start(self):
+        self.start_time = time.time()
+
+    def end(self):
+        self.end_time = time.time()
+
+    @property
+    def start_time_str(self):
+        return time.strftime(self.DATETIME_FORMAT, time.gmtime(self.start_time))
+
+    @property
+    def end_time_str(self):
+        return time.strftime(self.DATETIME_FORMAT, time.gmtime(self.end_time))
+
+    @property
+    def duration(self):
+        if not self.end_time:
+            raise ValueError("Tracing has not ended yet!")
+
+        return (self.end_time - self.start_time) * 1000
+
+    @property
+    def tracing_dict(self):
+        return dict(
+            version=1,
+            startTime=self.start_time,
+            endTime=self.end_time,
+            duration=self.duration,
+            execution=dict(
+                resolvers=self.resolver_stats
+            )
+        )
+
+    def resolve(self, _next, root, info, *args, **kwargs):
+        start = time.time()
+        try:
+            return _next(root, info, *args, **kwargs)
+        finally:
+            end = time.time()
+            elapsed_ms = (end - start) * 1000
+
+            stat = {
+                # "path": [ <>, ...],
+                "parentType": str(info.parent_type),
+                "fieldName": info.field_name,
+                "returnType": str(info.return_type),
+                "startOffset": (time.time() - self.start_time) * 1000,
+                "duration": elapsed_ms,
+            }
+            self.resolver_stats.append(stat)