From 33d4f83d601f402234fa39f76ddd15e4b8256d6a Mon Sep 17 00:00:00 2001 From: Eran Kampf Date: Tue, 31 Oct 2017 11:39:09 -0700 Subject: [PATCH 01/12] Initial work on tracing middleware --- graphql/execution/base.py | 3 +- graphql/execution/executor.py | 27 ++++++++++++---- graphql/execution/tracing.py | 61 +++++++++++++++++++++++++++++++++++ 3 files changed, 83 insertions(+), 8 deletions(-) create mode 100644 graphql/execution/tracing.py diff --git a/graphql/execution/base.py b/graphql/execution/base.py index f088a16b..4c4287f8 100644 --- a/graphql/execution/base.py +++ b/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 diff --git a/graphql/execution/executor.py b/graphql/execution/executor.py index 7ae0577a..3395fe81 100644 --- a/graphql/execution/executor.py +++ b/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 diff --git a/graphql/execution/tracing.py b/graphql/execution/tracing.py new file mode 100644 index 00000000..bdca56d5 --- /dev/null +++ b/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) \ No newline at end of file From 12dde37c964f23b427b9fc926ebff24649ef4545 Mon Sep 17 00:00:00 2001 From: Eran Kampf Date: Tue, 31 Oct 2017 13:23:14 -0700 Subject: [PATCH 02/12] Added info.path --- graphql/execution/base.py | 24 +++++++++++++++++++++--- graphql/execution/executor.py | 26 ++++++++++++++------------ graphql/execution/tracing.py | 2 +- 3 files changed, 36 insertions(+), 16 deletions(-) diff --git a/graphql/execution/base.py b/graphql/execution/base.py index 4c4287f8..9737d41e 100644 --- a/graphql/execution/base.py +++ b/graphql/execution/base.py @@ -1,5 +1,6 @@ # -*- coding: utf-8 -*- import sys +import copy from ..error import GraphQLError from ..language import ast @@ -126,7 +127,7 @@ class ExecutionResult(object): query, `errors` is null if no errors occurred, and is a non-empty array if an error occurred.""" - __slots__ = 'data', 'errors', 'invalid' + __slots__ = 'data', 'errors', 'invalid', 'extensions' def __init__(self, data=None, errors=None, extensions=None, invalid=False): self.data = data @@ -295,10 +296,10 @@ def get_field_entry_key(node): class ResolveInfo(object): __slots__ = ('field_name', 'field_asts', 'return_type', 'parent_type', - 'schema', 'fragments', 'root_value', 'operation', 'variable_values', 'context') + 'schema', 'fragments', 'root_value', 'operation', 'variable_values', 'context', 'path') def __init__(self, field_name, field_asts, return_type, parent_type, - schema, fragments, root_value, operation, variable_values, context): + schema, fragments, root_value, operation, variable_values, context, path): self.field_name = field_name self.field_asts = field_asts self.return_type = return_type @@ -309,6 +310,23 @@ def __init__(self, field_name, field_asts, return_type, parent_type, self.operation = operation self.variable_values = variable_values self.context = context + self.path = path + + def clone(self): + return ResolveInfo( + field_name=self.field_name, + field_asts=self.field_asts, + return_type=self.return_type, + parent_type=self.parent_type, + schema=self.schema, + fragments=self.fragments, + root_value=self.root_value, + operation=self.operation, + variable_values=self.variable_values, + context=self.context, + path=copy.copy(self.path) + ) + def default_resolve_fn(source, info, **args): diff --git a/graphql/execution/executor.py b/graphql/execution/executor.py index 3395fe81..f366cb48 100644 --- a/graphql/execution/executor.py +++ b/graphql/execution/executor.py @@ -83,6 +83,7 @@ def on_resolve(data): if isinstance(data, Observable): return data + tracing_middleware.end() extensions = dict(tracing=tracing_middleware.tracing_dict) if not context.errors: @@ -121,7 +122,7 @@ def execute_operation(exe_context, operation, root_value): ) return subscribe_fields(exe_context, type, root_value, fields) - return execute_fields(exe_context, type, root_value, fields) + return execute_fields(exe_context, type, root_value, fields, None) def execute_fields_serially(exe_context, parent_type, source_value, fields): @@ -152,14 +153,13 @@ def execute_field(prev_promise, response_name): return functools.reduce(execute_field, fields.keys(), Promise.resolve(collections.OrderedDict())) -def execute_fields(exe_context, parent_type, source_value, fields): +def execute_fields(exe_context, parent_type, source_value, fields, info): contains_promise = False final_results = OrderedDict() for response_name, field_asts in fields.items(): - result = resolve_field(exe_context, parent_type, - source_value, field_asts) + result = resolve_field(exe_context, parent_type, source_value, field_asts, info) if result is Undefined: continue @@ -211,7 +211,7 @@ def catch_error(error): return Observable.merge(observables) -def resolve_field(exe_context, parent_type, source, field_asts): +def resolve_field(exe_context, parent_type, source, field_asts, parent_info): field_ast = field_asts[0] field_name = field_ast.name.value @@ -246,12 +246,12 @@ def resolve_field(exe_context, parent_type, source, field_asts): root_value=exe_context.root_value, operation=exe_context.operation, variable_values=exe_context.variable_values, - context=context + context=context, + path=parent_info.path+[field_name] if parent_info else [field_name] ) executor = exe_context.executor - result = resolve_or_error(resolve_fn_middleware, - source, info, args, executor) + result = resolve_or_error(resolve_fn_middleware, source, info, args, executor) return complete_value_catching_error( exe_context, @@ -377,7 +377,6 @@ def complete_value(exe_context, return_type, field_asts, info, result): """ # If field type is NonNull, complete for inner type, and throw field error # if result is null. - if is_thenable(result): return Promise.resolve(result).then( lambda resolved: complete_value( @@ -432,13 +431,16 @@ def complete_list_value(exe_context, return_type, field_asts, info, result): item_type = return_type.of_type completed_results = [] contains_promise = False + index = 0 for item in result: - completed_item = complete_value_catching_error( - exe_context, item_type, field_asts, info, item) + new_info = info.clone() + new_info.path += [index] + completed_item = complete_value_catching_error(exe_context, item_type, field_asts, new_info, item) if not contains_promise and is_thenable(completed_item): contains_promise = True completed_results.append(completed_item) + index += 1 return Promise.all(completed_results) if contains_promise else completed_results @@ -514,7 +516,7 @@ def complete_object_value(exe_context, return_type, field_asts, info, result): # Collect sub-fields to execute to complete this value. subfield_asts = exe_context.get_sub_fields(return_type, field_asts) - return execute_fields(exe_context, return_type, result, subfield_asts) + return execute_fields(exe_context, return_type, result, subfield_asts, info) def complete_nonnull_value(exe_context, return_type, field_asts, info, result): diff --git a/graphql/execution/tracing.py b/graphql/execution/tracing.py index bdca56d5..6e7d8c15 100644 --- a/graphql/execution/tracing.py +++ b/graphql/execution/tracing.py @@ -51,7 +51,7 @@ def resolve(self, _next, root, info, *args, **kwargs): elapsed_ms = (end - start) * 1000 stat = { - # "path": [ <>, ...], + "path": info.path, "parentType": str(info.parent_type), "fieldName": info.field_name, "returnType": str(info.return_type), From 633a8a2bd1400e01653b6af12d4d29a322ba0a28 Mon Sep 17 00:00:00 2001 From: Eran Kampf Date: Tue, 31 Oct 2017 13:56:20 -0700 Subject: [PATCH 03/12] Tracing should be off by default --- graphql/execution/executor.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/graphql/execution/executor.py b/graphql/execution/executor.py index f366cb48..aec1de8b 100644 --- a/graphql/execution/executor.py +++ b/graphql/execution/executor.py @@ -32,7 +32,7 @@ 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, - tracing=True): + tracing=False): assert schema, 'Must provide schema' assert isinstance(schema, GraphQLSchema), ( 'Schema must be an instance of GraphQLSchema. Also ensure that there are ' + From 385f80353fb564f2f43d08c5a3f4bb8712b2d08d Mon Sep 17 00:00:00 2001 From: Eran Kampf Date: Tue, 31 Oct 2017 13:56:32 -0700 Subject: [PATCH 04/12] path fixes --- graphql/execution/executor.py | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/graphql/execution/executor.py b/graphql/execution/executor.py index aec1de8b..1cf47f56 100644 --- a/graphql/execution/executor.py +++ b/graphql/execution/executor.py @@ -132,7 +132,8 @@ def execute_field_callback(results, response_name): exe_context, parent_type, source_value, - field_asts + field_asts, + None ) if result is Undefined: return results @@ -193,8 +194,7 @@ def map_result(data): for response_name, field_asts in fields.items(): - result = subscribe_field(exe_context, parent_type, - source_value, field_asts) + result = subscribe_field(exe_context, parent_type, source_value, field_asts) if result is Undefined: continue @@ -297,7 +297,8 @@ def subscribe_field(exe_context, parent_type, source, field_asts): root_value=exe_context.root_value, operation=exe_context.operation, variable_values=exe_context.variable_values, - context=context + context=context, + path=[field_name] ) executor = exe_context.executor From 1ef9cd34cdec9657c4a489ed8212781e7a550758 Mon Sep 17 00:00:00 2001 From: Eran Kampf Date: Tue, 31 Oct 2017 15:34:02 -0700 Subject: [PATCH 05/12] Tracing Middleware --- graphql/execution/base.py | 17 --- graphql/execution/executor.py | 14 +- graphql/execution/tests/test_tracing.py | 169 ++++++++++++++++++++++++ graphql/execution/tracing.py | 20 +-- 4 files changed, 188 insertions(+), 32 deletions(-) create mode 100644 graphql/execution/tests/test_tracing.py diff --git a/graphql/execution/base.py b/graphql/execution/base.py index 9737d41e..47fe9810 100644 --- a/graphql/execution/base.py +++ b/graphql/execution/base.py @@ -1,6 +1,5 @@ # -*- coding: utf-8 -*- import sys -import copy from ..error import GraphQLError from ..language import ast @@ -312,22 +311,6 @@ def __init__(self, field_name, field_asts, return_type, parent_type, self.context = context self.path = path - def clone(self): - return ResolveInfo( - field_name=self.field_name, - field_asts=self.field_asts, - return_type=self.return_type, - parent_type=self.parent_type, - schema=self.schema, - fragments=self.fragments, - root_value=self.root_value, - operation=self.operation, - variable_values=self.variable_values, - context=self.context, - path=copy.copy(self.path) - ) - - def default_resolve_fn(source, info, **args): """If a resolve function is not given, then a default resolve behavior is used which takes the property of the source object diff --git a/graphql/execution/executor.py b/graphql/execution/executor.py index 1cf47f56..222688a4 100644 --- a/graphql/execution/executor.py +++ b/graphql/execution/executor.py @@ -39,6 +39,7 @@ def execute(schema, document_ast, root_value=None, context_value=None, 'not multiple versions of GraphQL installed in your node_modules directory.' ) + tracing_middleware = None if tracing: tracing_middleware = TracingMiddleware() tracing_middleware.start() @@ -83,8 +84,10 @@ def on_resolve(data): if isinstance(data, Observable): return data - tracing_middleware.end() - extensions = dict(tracing=tracing_middleware.tracing_dict) + extensions = dict() + if tracing_middleware: + tracing_middleware.end() + extensions['tracing'] = tracing_middleware.tracing_dict if not context.errors: return ExecutionResult(data=data, extensions=extensions) @@ -432,11 +435,12 @@ def complete_list_value(exe_context, return_type, field_asts, info, result): item_type = return_type.of_type completed_results = [] contains_promise = False + index = 0 + path = info.path[:] for item in result: - new_info = info.clone() - new_info.path += [index] - completed_item = complete_value_catching_error(exe_context, item_type, field_asts, new_info, item) + info.path = path + [index] + completed_item = complete_value_catching_error(exe_context, item_type, field_asts, info, item) if not contains_promise and is_thenable(completed_item): contains_promise = True diff --git a/graphql/execution/tests/test_tracing.py b/graphql/execution/tests/test_tracing.py new file mode 100644 index 00000000..8b5086d6 --- /dev/null +++ b/graphql/execution/tests/test_tracing.py @@ -0,0 +1,169 @@ +import time + +from graphql.execution import execute +from graphql.execution.tracing import TracingMiddleware +from graphql.language.parser import parse +from graphql.type import (GraphQLArgument, GraphQLBoolean, GraphQLField, + GraphQLID, GraphQLInt, GraphQLList, GraphQLNonNull, + GraphQLObjectType, GraphQLSchema, GraphQLString) + +current_time = -1 + + +def test_tracing_result(mocker): + + def get_time(): + global current_time + current_time += 1 + return current_time + + time_mock = mocker.patch('time.time') + time_mock.side_effect = get_time + + BlogImage = GraphQLObjectType('BlogImage', { + 'url': GraphQLField(GraphQLString), + 'width': GraphQLField(GraphQLInt), + 'height': GraphQLField(GraphQLInt), + }) + + BlogAuthor = GraphQLObjectType('Author', lambda: { + 'id': GraphQLField(GraphQLString), + 'name': GraphQLField(GraphQLString), + 'pic': GraphQLField(BlogImage, + args={ + 'width': GraphQLArgument(GraphQLInt), + 'height': GraphQLArgument(GraphQLInt), + }, + resolver=lambda obj, info, **args: + obj.pic(args['width'], args['height']) + ), + 'recentArticle': GraphQLField(BlogArticle), + }) + + BlogArticle = GraphQLObjectType('Article', { + 'id': GraphQLField(GraphQLNonNull(GraphQLString)), + 'isPublished': GraphQLField(GraphQLBoolean), + 'author': GraphQLField(BlogAuthor), + 'title': GraphQLField(GraphQLString), + 'body': GraphQLField(GraphQLString), + 'keywords': GraphQLField(GraphQLList(GraphQLString)), + }) + + BlogQuery = GraphQLObjectType('Query', { + 'article': GraphQLField( + BlogArticle, + args={'id': GraphQLArgument(GraphQLID)}, + resolver=lambda obj, info, **args: Article(args['id'])), + 'feed': GraphQLField( + GraphQLList(BlogArticle), + resolver=lambda *_: map(Article, range(1, 2 + 1))), + }) + + BlogSchema = GraphQLSchema(BlogQuery) + + class Article(object): + + def __init__(self, id): + self.id = id + self.isPublished = True + self.author = Author() + self.title = 'My Article {}'.format(id) + self.body = 'This is a post' + self.hidden = 'This data is not exposed in the schema' + self.keywords = ['foo', 'bar', 1, True, None] + + class Author(object): + id = 123 + name = 'John Smith' + + def pic(self, width, height): + return Pic(123, width, height) + + @property + def recentArticle(self): return Article(1) + + class Pic(object): + + def __init__(self, uid, width, height): + self.url = 'cdn://{}'.format(uid) + self.width = str(width) + self.height = str(height) + + request = ''' + { + feed { + id + title + } + } + ''' + + # Note: this is intentionally not validating to ensure appropriate + # behavior occurs when executing an invalid query. + result = execute(BlogSchema, parse(request), tracing=True) + assert not result.errors + assert result.data == \ + { + "feed": [ + { + "id": "1", + "title": "My Article 1" + }, + { + "id": "2", + "title": "My Article 2" + }, + ], + } + + assert result.extensions['tracing'] == { + 'version': 1, + 'startTime': time.strftime(TracingMiddleware.DATETIME_FORMAT, time.gmtime(0)), + 'endTime': time.strftime(TracingMiddleware.DATETIME_FORMAT, time.gmtime(16)), + 'duration': 16000, + 'execution': { + 'resolvers': [ + { + 'path': ['feed'], + 'parentType': 'Query', + 'fieldName': 'feed', + 'returnType': '[Article]', + 'startOffset': 3000, + 'duration': 1000 + }, + { + 'path': ['feed', 0, 'id'], + 'parentType': 'Article', + 'fieldName': 'id', + 'returnType': 'String!', + 'startOffset': 6000, + 'duration': 1000 + }, + { + 'path': ['feed', 0, 'title'], + 'parentType': 'Article', + 'fieldName': 'title', + 'returnType': 'String', + 'startOffset': 9000, + 'duration': 1000 + }, + { + 'path': ['feed', 1, 'id'], + 'parentType': 'Article', + 'fieldName': 'id', + 'returnType': 'String!', + 'startOffset': 12000, + 'duration': 1000 + }, + { + 'path': ['feed', 1, 'title'], + 'parentType': 'Article', + 'fieldName': 'title', + 'returnType': 'String', + 'startOffset': 15000, + 'duration': 1000 + } + ] + } + } + diff --git a/graphql/execution/tracing.py b/graphql/execution/tracing.py index 6e7d8c15..c2bda4b0 100644 --- a/graphql/execution/tracing.py +++ b/graphql/execution/tracing.py @@ -1,5 +1,5 @@ import time -import datetime + class TracingMiddleware(object): DATETIME_FORMAT = '%Y-%m-%dT%H:%M:%S.%fZ' @@ -10,32 +10,32 @@ def __init__(self): self.end_time = None def start(self): - self.start_time = time.time() + self.start_time = time.time() * 1000 def end(self): - self.end_time = time.time() + self.end_time = time.time() * 1000 @property def start_time_str(self): - return time.strftime(self.DATETIME_FORMAT, time.gmtime(self.start_time)) + return time.strftime(self.DATETIME_FORMAT, time.gmtime(self.start_time/1000)) @property def end_time_str(self): - return time.strftime(self.DATETIME_FORMAT, time.gmtime(self.end_time)) + return time.strftime(self.DATETIME_FORMAT, time.gmtime(self.end_time/1000)) @property def duration(self): if not self.end_time: raise ValueError("Tracing has not ended yet!") - return (self.end_time - self.start_time) * 1000 + return (self.end_time - self.start_time) @property def tracing_dict(self): return dict( version=1, - startTime=self.start_time, - endTime=self.end_time, + startTime=self.start_time_str, + endTime=self.end_time_str, duration=self.duration, execution=dict( resolvers=self.resolver_stats @@ -55,7 +55,7 @@ def resolve(self, _next, root, info, *args, **kwargs): "parentType": str(info.parent_type), "fieldName": info.field_name, "returnType": str(info.return_type), - "startOffset": (time.time() - self.start_time) * 1000, + "startOffset": (time.time() * 1000) - self.start_time, "duration": elapsed_ms, } - self.resolver_stats.append(stat) \ No newline at end of file + self.resolver_stats.append(stat) From 8f823b6fa76b2d252d2896c42d873b8b0c94cab6 Mon Sep 17 00:00:00 2001 From: Eran Kampf Date: Tue, 31 Oct 2017 15:37:03 -0700 Subject: [PATCH 06/12] Fixed missing dependency in tox file --- tox.ini | 1 + 1 file changed, 1 insertion(+) diff --git a/tox.ini b/tox.ini index 929bb4e3..215e2656 100644 --- a/tox.ini +++ b/tox.ini @@ -8,6 +8,7 @@ deps = promise>=2.0 six>=1.10.0 pytest-mock + pytest-benchmark commands = py{27,33,34,py}: py.test graphql tests {posargs} py35: py.test graphql tests tests_py35 {posargs} From 27faf0f76cdaa698c8735e36a1bc2f2a8c36c580 Mon Sep 17 00:00:00 2001 From: Eran Kampf Date: Tue, 31 Oct 2017 15:57:16 -0700 Subject: [PATCH 07/12] correct order for ExecutionResult kwargs --- graphql/execution/base.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/graphql/execution/base.py b/graphql/execution/base.py index 47fe9810..86b3d977 100644 --- a/graphql/execution/base.py +++ b/graphql/execution/base.py @@ -128,7 +128,7 @@ class ExecutionResult(object): __slots__ = 'data', 'errors', 'invalid', 'extensions' - def __init__(self, data=None, errors=None, extensions=None, invalid=False): + def __init__(self, data=None, errors=None, invalid=False, extensions=None): self.data = data self.errors = errors self.extensions = extensions or dict() From b0a02afdf33fa7f1869bbd8409cdf565fd9e3907 Mon Sep 17 00:00:00 2001 From: Eran Kampf Date: Tue, 31 Oct 2017 16:02:57 -0700 Subject: [PATCH 08/12] Better tracing middleware initialization --- graphql/execution/executor.py | 21 +++++++++++---------- 1 file changed, 11 insertions(+), 10 deletions(-) diff --git a/graphql/execution/executor.py b/graphql/execution/executor.py index 222688a4..7b790739 100644 --- a/graphql/execution/executor.py +++ b/graphql/execution/executor.py @@ -39,16 +39,6 @@ def execute(schema, document_ast, root_value=None, context_value=None, 'not multiple versions of GraphQL installed in your node_modules directory.' ) - tracing_middleware = None - 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) @@ -58,6 +48,17 @@ def execute(schema, document_ast, root_value=None, context_value=None, ' of MiddlewareManager. Received "{}".'.format(middleware) ) + tracing_middleware = None + if tracing: + tracing_middleware = TracingMiddleware() + tracing_middleware.start() + + if middleware: + middleware.middlewares.insert(0, tracing_middleware) + else: + middleware = MiddlewareManager(tracing_middleware) + + if executor is None: executor = SyncExecutor() From f4bc6a339bea7d8b9851972eabdb879099ee422f Mon Sep 17 00:00:00 2001 From: Eran Kampf Date: Tue, 31 Oct 2017 16:09:17 -0700 Subject: [PATCH 09/12] nicer test code --- graphql/execution/tests/test_tracing.py | 10 +--------- 1 file changed, 1 insertion(+), 9 deletions(-) diff --git a/graphql/execution/tests/test_tracing.py b/graphql/execution/tests/test_tracing.py index 8b5086d6..0895004b 100644 --- a/graphql/execution/tests/test_tracing.py +++ b/graphql/execution/tests/test_tracing.py @@ -7,18 +7,10 @@ GraphQLID, GraphQLInt, GraphQLList, GraphQLNonNull, GraphQLObjectType, GraphQLSchema, GraphQLString) -current_time = -1 - def test_tracing_result(mocker): - - def get_time(): - global current_time - current_time += 1 - return current_time - time_mock = mocker.patch('time.time') - time_mock.side_effect = get_time + time_mock.side_effect = range(0, 10000) BlogImage = GraphQLObjectType('BlogImage', { 'url': GraphQLField(GraphQLString), From 9ac6beef3def89ead842f38904410f74297d9db8 Mon Sep 17 00:00:00 2001 From: Eran Kampf Date: Tue, 31 Oct 2017 16:20:01 -0700 Subject: [PATCH 10/12] More tests --- graphql/execution/tests/test_tracing.py | 86 +++++++++++-------------- 1 file changed, 39 insertions(+), 47 deletions(-) diff --git a/graphql/execution/tests/test_tracing.py b/graphql/execution/tests/test_tracing.py index 0895004b..95640949 100644 --- a/graphql/execution/tests/test_tracing.py +++ b/graphql/execution/tests/test_tracing.py @@ -8,7 +8,7 @@ GraphQLObjectType, GraphQLSchema, GraphQLString) -def test_tracing_result(mocker): +def test_tracing(mocker): time_mock = mocker.patch('time.time') time_mock.side_effect = range(0, 10000) @@ -85,8 +85,17 @@ def __init__(self, uid, width, height): { feed { id - title - } + ...articleFields + author { + id + name + } + }, + } + fragment articleFields on Article { + title, + body, + hidden, } ''' @@ -99,11 +108,21 @@ def __init__(self, uid, width, height): "feed": [ { "id": "1", - "title": "My Article 1" + "title": "My Article 1", + "body": "This is a post", + "author": { + "id": "123", + "name": "John Smith" + } }, { "id": "2", - "title": "My Article 2" + "title": "My Article 2", + "body": "This is a post", + "author": { + "id": "123", + "name": "John Smith" + } }, ], } @@ -111,50 +130,23 @@ def __init__(self, uid, width, height): assert result.extensions['tracing'] == { 'version': 1, 'startTime': time.strftime(TracingMiddleware.DATETIME_FORMAT, time.gmtime(0)), - 'endTime': time.strftime(TracingMiddleware.DATETIME_FORMAT, time.gmtime(16)), - 'duration': 16000, + 'endTime': time.strftime(TracingMiddleware.DATETIME_FORMAT, time.gmtime(40)), + 'duration': 40000, 'execution': { 'resolvers': [ - { - 'path': ['feed'], - 'parentType': 'Query', - 'fieldName': 'feed', - 'returnType': '[Article]', - 'startOffset': 3000, - 'duration': 1000 - }, - { - 'path': ['feed', 0, 'id'], - 'parentType': 'Article', - 'fieldName': 'id', - 'returnType': 'String!', - 'startOffset': 6000, - 'duration': 1000 - }, - { - 'path': ['feed', 0, 'title'], - 'parentType': 'Article', - 'fieldName': 'title', - 'returnType': 'String', - 'startOffset': 9000, - 'duration': 1000 - }, - { - 'path': ['feed', 1, 'id'], - 'parentType': 'Article', - 'fieldName': 'id', - 'returnType': 'String!', - 'startOffset': 12000, - 'duration': 1000 - }, - { - 'path': ['feed', 1, 'title'], - 'parentType': 'Article', - 'fieldName': 'title', - 'returnType': 'String', - 'startOffset': 15000, - 'duration': 1000 - } + {'path': ['feed'], 'parentType': 'Query', 'fieldName': 'feed', 'returnType': '[Article]', 'startOffset': 3000, 'duration': 1000}, + {'path': ['feed', 0, 'id'], 'parentType': 'Article', 'fieldName': 'id', 'returnType': 'String!', 'startOffset': 6000, 'duration': 1000}, + {'path': ['feed', 0, 'title'], 'parentType': 'Article', 'fieldName': 'title', 'returnType': 'String', 'startOffset': 9000, 'duration': 1000}, + {'path': ['feed', 0, 'body'], 'parentType': 'Article', 'fieldName': 'body', 'returnType': 'String', 'startOffset': 12000, 'duration': 1000}, + {'path': ['feed', 0, 'author'], 'parentType': 'Article', 'fieldName': 'author', 'returnType': 'Author', 'startOffset': 15000, 'duration': 1000}, + {'path': ['feed', 1, 'id'], 'parentType': 'Article', 'fieldName': 'id', 'returnType': 'String!', 'startOffset': 18000, 'duration': 1000}, + {'path': ['feed', 1, 'title'], 'parentType': 'Article', 'fieldName': 'title', 'returnType': 'String', 'startOffset': 21000, 'duration': 1000}, + {'path': ['feed', 1, 'body'], 'parentType': 'Article', 'fieldName': 'body', 'returnType': 'String', 'startOffset': 24000, 'duration': 1000}, + {'path': ['feed', 1, 'author'], 'parentType': 'Article', 'fieldName': 'author', 'returnType': 'Author', 'startOffset': 27000, 'duration': 1000}, + {'path': ['feed', 0, 'author', 'id'], 'parentType': 'Author', 'fieldName': 'id', 'returnType': 'String', 'startOffset': 30000, 'duration': 1000}, + {'path': ['feed', 0, 'author', 'name'], 'parentType': 'Author', 'fieldName': 'name', 'returnType': 'String', 'startOffset': 33000, 'duration': 1000}, + {'path': ['feed', 1, 'author', 'id'], 'parentType': 'Author', 'fieldName': 'id', 'returnType': 'String', 'startOffset': 36000, 'duration': 1000}, + {'path': ['feed', 1, 'author', 'name'], 'parentType': 'Author', 'fieldName': 'name', 'returnType': 'String', 'startOffset': 39000, 'duration': 1000} ] } } From c67320ca09850a305dd4f5c0303c0774d070b690 Mon Sep 17 00:00:00 2001 From: Eran Kampf Date: Wed, 1 Nov 2017 10:33:33 -0700 Subject: [PATCH 11/12] Removed tracing middleware which should be in graphql-server-core --- graphql/execution/executor.py | 24 +--- graphql/execution/tests/test_executor.py | 147 +++++++++++++++++++++- graphql/execution/tests/test_tracing.py | 153 ----------------------- graphql/execution/tracing.py | 61 --------- 4 files changed, 149 insertions(+), 236 deletions(-) delete mode 100644 graphql/execution/tests/test_tracing.py delete mode 100644 graphql/execution/tracing.py diff --git a/graphql/execution/executor.py b/graphql/execution/executor.py index 7b790739..31428ee6 100644 --- a/graphql/execution/executor.py +++ b/graphql/execution/executor.py @@ -19,7 +19,6 @@ get_operation_root_type, SubscriberExecutionContext) from .executors.sync import SyncExecutor from .middleware import MiddlewareManager -from .tracing import TracingMiddleware logger = logging.getLogger(__name__) @@ -31,8 +30,7 @@ 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, - tracing=False): + return_promise=False, middleware=None, allow_subscriptions=False): assert schema, 'Must provide schema' assert isinstance(schema, GraphQLSchema), ( 'Schema must be an instance of GraphQLSchema. Also ensure that there are ' + @@ -48,17 +46,6 @@ def execute(schema, document_ast, root_value=None, context_value=None, ' of MiddlewareManager. Received "{}".'.format(middleware) ) - tracing_middleware = None - if tracing: - tracing_middleware = TracingMiddleware() - tracing_middleware.start() - - if middleware: - middleware.middlewares.insert(0, tracing_middleware) - else: - middleware = MiddlewareManager(tracing_middleware) - - if executor is None: executor = SyncExecutor() @@ -85,15 +72,10 @@ def on_resolve(data): if isinstance(data, Observable): return data - extensions = dict() - if tracing_middleware: - tracing_middleware.end() - extensions['tracing'] = tracing_middleware.tracing_dict - if not context.errors: - return ExecutionResult(data=data, extensions=extensions) + return ExecutionResult(data=data) - return ExecutionResult(data=data, extensions=extensions, errors=context.errors) + return ExecutionResult(data=data, errors=context.errors) promise = Promise.resolve(None).then(executor).catch(on_rejected).then(on_resolve) diff --git a/graphql/execution/tests/test_executor.py b/graphql/execution/tests/test_executor.py index e36c596f..cc107362 100644 --- a/graphql/execution/tests/test_executor.py +++ b/graphql/execution/tests/test_executor.py @@ -7,7 +7,7 @@ from graphql.language.parser import parse from graphql.type import (GraphQLArgument, GraphQLBoolean, GraphQLField, GraphQLInt, GraphQLList, GraphQLObjectType, - GraphQLSchema, GraphQLString) + GraphQLSchema, GraphQLString, GraphQLNonNull, GraphQLID) from promise import Promise @@ -668,3 +668,148 @@ def resolve(self, next, *args, **kwargs): middleware=middlewares_without_promise) assert result1.data == result2.data and result1.data == { 'ok': 'ok', 'not_ok': 'not_ok'} + + +def test_executor_properly_propogates_path_data(mocker): + time_mock = mocker.patch('time.time') + time_mock.side_effect = range(0, 10000) + + BlogImage = GraphQLObjectType('BlogImage', { + 'url': GraphQLField(GraphQLString), + 'width': GraphQLField(GraphQLInt), + 'height': GraphQLField(GraphQLInt), + }) + + BlogAuthor = GraphQLObjectType('Author', lambda: { + 'id': GraphQLField(GraphQLString), + 'name': GraphQLField(GraphQLString), + 'pic': GraphQLField(BlogImage, + args={ + 'width': GraphQLArgument(GraphQLInt), + 'height': GraphQLArgument(GraphQLInt), + }, + resolver=lambda obj, info, **args: + obj.pic(args['width'], args['height']) + ), + 'recentArticle': GraphQLField(BlogArticle), + }) + + BlogArticle = GraphQLObjectType('Article', { + 'id': GraphQLField(GraphQLNonNull(GraphQLString)), + 'isPublished': GraphQLField(GraphQLBoolean), + 'author': GraphQLField(BlogAuthor), + 'title': GraphQLField(GraphQLString), + 'body': GraphQLField(GraphQLString), + 'keywords': GraphQLField(GraphQLList(GraphQLString)), + }) + + BlogQuery = GraphQLObjectType('Query', { + 'article': GraphQLField( + BlogArticle, + args={'id': GraphQLArgument(GraphQLID)}, + resolver=lambda obj, info, **args: Article(args['id'])), + 'feed': GraphQLField( + GraphQLList(BlogArticle), + resolver=lambda *_: map(Article, range(1, 2 + 1))), + }) + + BlogSchema = GraphQLSchema(BlogQuery) + + class Article(object): + + def __init__(self, id): + self.id = id + self.isPublished = True + self.author = Author() + self.title = 'My Article {}'.format(id) + self.body = 'This is a post' + self.hidden = 'This data is not exposed in the schema' + self.keywords = ['foo', 'bar', 1, True, None] + + class Author(object): + id = 123 + name = 'John Smith' + + def pic(self, width, height): + return Pic(123, width, height) + + @property + def recentArticle(self): return Article(1) + + class Pic(object): + def __init__(self, uid, width, height): + self.url = 'cdn://{}'.format(uid) + self.width = str(width) + self.height = str(height) + + class PathCollectorMiddleware(object): + def __init__(self): + self.paths = [] + + def resolve(self, _next, root, info, *args, **kwargs): + self.paths.append(info.path) + return _next(root, info, *args, **kwargs) + + request = ''' + { + feed { + id + ...articleFields + author { + id + name + } + }, + } + fragment articleFields on Article { + title, + body, + hidden, + } + ''' + + paths_middleware = PathCollectorMiddleware() + + result = execute(BlogSchema, parse(request), middleware=(paths_middleware, )) + assert not result.errors + assert result.data == \ + { + "feed": [ + { + "id": "1", + "title": "My Article 1", + "body": "This is a post", + "author": { + "id": "123", + "name": "John Smith" + } + }, + { + "id": "2", + "title": "My Article 2", + "body": "This is a post", + "author": { + "id": "123", + "name": "John Smith" + } + }, + ], + } + + traversed_paths = paths_middleware.paths + assert traversed_paths == [ + ['feed'], + ['feed', 0, 'id'], + ['feed', 0, 'title'], + ['feed', 0, 'body'], + ['feed', 0, 'author'], + ['feed', 1, 'id'], + ['feed', 1, 'title'], + ['feed', 1, 'body'], + ['feed', 1, 'author'], + ['feed', 0, 'author', 'id'], + ['feed', 0, 'author', 'name'], + ['feed', 1, 'author', 'id'], + ['feed', 1, 'author', 'name'] + ] + diff --git a/graphql/execution/tests/test_tracing.py b/graphql/execution/tests/test_tracing.py deleted file mode 100644 index 95640949..00000000 --- a/graphql/execution/tests/test_tracing.py +++ /dev/null @@ -1,153 +0,0 @@ -import time - -from graphql.execution import execute -from graphql.execution.tracing import TracingMiddleware -from graphql.language.parser import parse -from graphql.type import (GraphQLArgument, GraphQLBoolean, GraphQLField, - GraphQLID, GraphQLInt, GraphQLList, GraphQLNonNull, - GraphQLObjectType, GraphQLSchema, GraphQLString) - - -def test_tracing(mocker): - time_mock = mocker.patch('time.time') - time_mock.side_effect = range(0, 10000) - - BlogImage = GraphQLObjectType('BlogImage', { - 'url': GraphQLField(GraphQLString), - 'width': GraphQLField(GraphQLInt), - 'height': GraphQLField(GraphQLInt), - }) - - BlogAuthor = GraphQLObjectType('Author', lambda: { - 'id': GraphQLField(GraphQLString), - 'name': GraphQLField(GraphQLString), - 'pic': GraphQLField(BlogImage, - args={ - 'width': GraphQLArgument(GraphQLInt), - 'height': GraphQLArgument(GraphQLInt), - }, - resolver=lambda obj, info, **args: - obj.pic(args['width'], args['height']) - ), - 'recentArticle': GraphQLField(BlogArticle), - }) - - BlogArticle = GraphQLObjectType('Article', { - 'id': GraphQLField(GraphQLNonNull(GraphQLString)), - 'isPublished': GraphQLField(GraphQLBoolean), - 'author': GraphQLField(BlogAuthor), - 'title': GraphQLField(GraphQLString), - 'body': GraphQLField(GraphQLString), - 'keywords': GraphQLField(GraphQLList(GraphQLString)), - }) - - BlogQuery = GraphQLObjectType('Query', { - 'article': GraphQLField( - BlogArticle, - args={'id': GraphQLArgument(GraphQLID)}, - resolver=lambda obj, info, **args: Article(args['id'])), - 'feed': GraphQLField( - GraphQLList(BlogArticle), - resolver=lambda *_: map(Article, range(1, 2 + 1))), - }) - - BlogSchema = GraphQLSchema(BlogQuery) - - class Article(object): - - def __init__(self, id): - self.id = id - self.isPublished = True - self.author = Author() - self.title = 'My Article {}'.format(id) - self.body = 'This is a post' - self.hidden = 'This data is not exposed in the schema' - self.keywords = ['foo', 'bar', 1, True, None] - - class Author(object): - id = 123 - name = 'John Smith' - - def pic(self, width, height): - return Pic(123, width, height) - - @property - def recentArticle(self): return Article(1) - - class Pic(object): - - def __init__(self, uid, width, height): - self.url = 'cdn://{}'.format(uid) - self.width = str(width) - self.height = str(height) - - request = ''' - { - feed { - id - ...articleFields - author { - id - name - } - }, - } - fragment articleFields on Article { - title, - body, - hidden, - } - ''' - - # Note: this is intentionally not validating to ensure appropriate - # behavior occurs when executing an invalid query. - result = execute(BlogSchema, parse(request), tracing=True) - assert not result.errors - assert result.data == \ - { - "feed": [ - { - "id": "1", - "title": "My Article 1", - "body": "This is a post", - "author": { - "id": "123", - "name": "John Smith" - } - }, - { - "id": "2", - "title": "My Article 2", - "body": "This is a post", - "author": { - "id": "123", - "name": "John Smith" - } - }, - ], - } - - assert result.extensions['tracing'] == { - 'version': 1, - 'startTime': time.strftime(TracingMiddleware.DATETIME_FORMAT, time.gmtime(0)), - 'endTime': time.strftime(TracingMiddleware.DATETIME_FORMAT, time.gmtime(40)), - 'duration': 40000, - 'execution': { - 'resolvers': [ - {'path': ['feed'], 'parentType': 'Query', 'fieldName': 'feed', 'returnType': '[Article]', 'startOffset': 3000, 'duration': 1000}, - {'path': ['feed', 0, 'id'], 'parentType': 'Article', 'fieldName': 'id', 'returnType': 'String!', 'startOffset': 6000, 'duration': 1000}, - {'path': ['feed', 0, 'title'], 'parentType': 'Article', 'fieldName': 'title', 'returnType': 'String', 'startOffset': 9000, 'duration': 1000}, - {'path': ['feed', 0, 'body'], 'parentType': 'Article', 'fieldName': 'body', 'returnType': 'String', 'startOffset': 12000, 'duration': 1000}, - {'path': ['feed', 0, 'author'], 'parentType': 'Article', 'fieldName': 'author', 'returnType': 'Author', 'startOffset': 15000, 'duration': 1000}, - {'path': ['feed', 1, 'id'], 'parentType': 'Article', 'fieldName': 'id', 'returnType': 'String!', 'startOffset': 18000, 'duration': 1000}, - {'path': ['feed', 1, 'title'], 'parentType': 'Article', 'fieldName': 'title', 'returnType': 'String', 'startOffset': 21000, 'duration': 1000}, - {'path': ['feed', 1, 'body'], 'parentType': 'Article', 'fieldName': 'body', 'returnType': 'String', 'startOffset': 24000, 'duration': 1000}, - {'path': ['feed', 1, 'author'], 'parentType': 'Article', 'fieldName': 'author', 'returnType': 'Author', 'startOffset': 27000, 'duration': 1000}, - {'path': ['feed', 0, 'author', 'id'], 'parentType': 'Author', 'fieldName': 'id', 'returnType': 'String', 'startOffset': 30000, 'duration': 1000}, - {'path': ['feed', 0, 'author', 'name'], 'parentType': 'Author', 'fieldName': 'name', 'returnType': 'String', 'startOffset': 33000, 'duration': 1000}, - {'path': ['feed', 1, 'author', 'id'], 'parentType': 'Author', 'fieldName': 'id', 'returnType': 'String', 'startOffset': 36000, 'duration': 1000}, - {'path': ['feed', 1, 'author', 'name'], 'parentType': 'Author', 'fieldName': 'name', 'returnType': 'String', 'startOffset': 39000, 'duration': 1000} - ] - } - } - diff --git a/graphql/execution/tracing.py b/graphql/execution/tracing.py deleted file mode 100644 index c2bda4b0..00000000 --- a/graphql/execution/tracing.py +++ /dev/null @@ -1,61 +0,0 @@ -import time - - -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() * 1000 - - def end(self): - self.end_time = time.time() * 1000 - - @property - def start_time_str(self): - return time.strftime(self.DATETIME_FORMAT, time.gmtime(self.start_time/1000)) - - @property - def end_time_str(self): - return time.strftime(self.DATETIME_FORMAT, time.gmtime(self.end_time/1000)) - - @property - def duration(self): - if not self.end_time: - raise ValueError("Tracing has not ended yet!") - - return (self.end_time - self.start_time) - - @property - def tracing_dict(self): - return dict( - version=1, - startTime=self.start_time_str, - endTime=self.end_time_str, - 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": info.path, - "parentType": str(info.parent_type), - "fieldName": info.field_name, - "returnType": str(info.return_type), - "startOffset": (time.time() * 1000) - self.start_time, - "duration": elapsed_ms, - } - self.resolver_stats.append(stat) From b791ac3adf77762ac88bec51dc171a12e54fad1d Mon Sep 17 00:00:00 2001 From: Eran Kampf Date: Mon, 13 Nov 2017 15:35:34 -0800 Subject: [PATCH 12/12] inc version --- graphql/__init__.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/graphql/__init__.py b/graphql/__init__.py index cc73931e..08f25683 100644 --- a/graphql/__init__.py +++ b/graphql/__init__.py @@ -194,7 +194,7 @@ ) -VERSION = (2, 0, 0, 'final', 0) +VERSION = (2, 0, 1, 'final', 0) __version__ = get_version(VERSION)