Skip to content

Commit 1ef9cd3

Browse files
ekampfekampf
committed
Tracing Middleware
1 parent 385f803 commit 1ef9cd3

File tree

4 files changed

+188
-32
lines changed

4 files changed

+188
-32
lines changed

‎graphql/execution/base.py

Lines changed: 0 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,5 @@
11
# -*- coding: utf-8 -*-
22
import sys
3-
import copy
43

54
from ..error import GraphQLError
65
from ..language import ast
@@ -312,22 +311,6 @@ def __init__(self, field_name, field_asts, return_type, parent_type,
312311
self.context = context
313312
self.path = path
314313

315-
def clone(self):
316-
return ResolveInfo(
317-
field_name=self.field_name,
318-
field_asts=self.field_asts,
319-
return_type=self.return_type,
320-
parent_type=self.parent_type,
321-
schema=self.schema,
322-
fragments=self.fragments,
323-
root_value=self.root_value,
324-
operation=self.operation,
325-
variable_values=self.variable_values,
326-
context=self.context,
327-
path=copy.copy(self.path)
328-
)
329-
330-
331314

332315
def default_resolve_fn(source, info, **args):
333316
"""If a resolve function is not given, then a default resolve behavior is used which takes the property of the source object

‎graphql/execution/executor.py

Lines changed: 9 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -39,6 +39,7 @@ def execute(schema, document_ast, root_value=None, context_value=None,
3939
'not multiple versions of GraphQL installed in your node_modules directory.'
4040
)
4141

42+
tracing_middleware = None
4243
if tracing:
4344
tracing_middleware = TracingMiddleware()
4445
tracing_middleware.start()
@@ -83,8 +84,10 @@ def on_resolve(data):
8384
if isinstance(data, Observable):
8485
return data
8586

86-
tracing_middleware.end()
87-
extensions = dict(tracing=tracing_middleware.tracing_dict)
87+
extensions = dict()
88+
if tracing_middleware:
89+
tracing_middleware.end()
90+
extensions['tracing'] = tracing_middleware.tracing_dict
8891

8992
if not context.errors:
9093
return ExecutionResult(data=data, extensions=extensions)
@@ -432,11 +435,12 @@ def complete_list_value(exe_context, return_type, field_asts, info, result):
432435
item_type = return_type.of_type
433436
completed_results = []
434437
contains_promise = False
438+
435439
index = 0
440+
path = info.path[:]
436441
for item in result:
437-
new_info = info.clone()
438-
new_info.path += [index]
439-
completed_item = complete_value_catching_error(exe_context, item_type, field_asts, new_info, item)
442+
info.path = path + [index]
443+
completed_item = complete_value_catching_error(exe_context, item_type, field_asts, info, item)
440444
if not contains_promise and is_thenable(completed_item):
441445
contains_promise = True
442446

‎graphql/execution/tests/test_tracing.py

Lines changed: 169 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,169 @@
1+
import time
2+
3+
from graphql.execution import execute
4+
from graphql.execution.tracing import TracingMiddleware
5+
from graphql.language.parser import parse
6+
from graphql.type import (GraphQLArgument, GraphQLBoolean, GraphQLField,
7+
GraphQLID, GraphQLInt, GraphQLList, GraphQLNonNull,
8+
GraphQLObjectType, GraphQLSchema, GraphQLString)
9+
10+
current_time = -1
11+
12+
13+
def test_tracing_result(mocker):
14+
15+
def get_time():
16+
global current_time
17+
current_time += 1
18+
return current_time
19+
20+
time_mock = mocker.patch('time.time')
21+
time_mock.side_effect = get_time
22+
23+
BlogImage = GraphQLObjectType('BlogImage', {
24+
'url': GraphQLField(GraphQLString),
25+
'width': GraphQLField(GraphQLInt),
26+
'height': GraphQLField(GraphQLInt),
27+
})
28+
29+
BlogAuthor = GraphQLObjectType('Author', lambda: {
30+
'id': GraphQLField(GraphQLString),
31+
'name': GraphQLField(GraphQLString),
32+
'pic': GraphQLField(BlogImage,
33+
args={
34+
'width': GraphQLArgument(GraphQLInt),
35+
'height': GraphQLArgument(GraphQLInt),
36+
},
37+
resolver=lambda obj, info, **args:
38+
obj.pic(args['width'], args['height'])
39+
),
40+
'recentArticle': GraphQLField(BlogArticle),
41+
})
42+
43+
BlogArticle = GraphQLObjectType('Article', {
44+
'id': GraphQLField(GraphQLNonNull(GraphQLString)),
45+
'isPublished': GraphQLField(GraphQLBoolean),
46+
'author': GraphQLField(BlogAuthor),
47+
'title': GraphQLField(GraphQLString),
48+
'body': GraphQLField(GraphQLString),
49+
'keywords': GraphQLField(GraphQLList(GraphQLString)),
50+
})
51+
52+
BlogQuery = GraphQLObjectType('Query', {
53+
'article': GraphQLField(
54+
BlogArticle,
55+
args={'id': GraphQLArgument(GraphQLID)},
56+
resolver=lambda obj, info, **args: Article(args['id'])),
57+
'feed': GraphQLField(
58+
GraphQLList(BlogArticle),
59+
resolver=lambda *_: map(Article, range(1, 2 + 1))),
60+
})
61+
62+
BlogSchema = GraphQLSchema(BlogQuery)
63+
64+
class Article(object):
65+
66+
def __init__(self, id):
67+
self.id = id
68+
self.isPublished = True
69+
self.author = Author()
70+
self.title = 'My Article {}'.format(id)
71+
self.body = 'This is a post'
72+
self.hidden = 'This data is not exposed in the schema'
73+
self.keywords = ['foo', 'bar', 1, True, None]
74+
75+
class Author(object):
76+
id = 123
77+
name = 'John Smith'
78+
79+
def pic(self, width, height):
80+
return Pic(123, width, height)
81+
82+
@property
83+
def recentArticle(self): return Article(1)
84+
85+
class Pic(object):
86+
87+
def __init__(self, uid, width, height):
88+
self.url = 'cdn://{}'.format(uid)
89+
self.width = str(width)
90+
self.height = str(height)
91+
92+
request = '''
93+
{
94+
feed {
95+
id
96+
title
97+
}
98+
}
99+
'''
100+
101+
# Note: this is intentionally not validating to ensure appropriate
102+
# behavior occurs when executing an invalid query.
103+
result = execute(BlogSchema, parse(request), tracing=True)
104+
assert not result.errors
105+
assert result.data == \
106+
{
107+
"feed": [
108+
{
109+
"id": "1",
110+
"title": "My Article 1"
111+
},
112+
{
113+
"id": "2",
114+
"title": "My Article 2"
115+
},
116+
],
117+
}
118+
119+
assert result.extensions['tracing'] == {
120+
'version': 1,
121+
'startTime': time.strftime(TracingMiddleware.DATETIME_FORMAT, time.gmtime(0)),
122+
'endTime': time.strftime(TracingMiddleware.DATETIME_FORMAT, time.gmtime(16)),
123+
'duration': 16000,
124+
'execution': {
125+
'resolvers': [
126+
{
127+
'path': ['feed'],
128+
'parentType': 'Query',
129+
'fieldName': 'feed',
130+
'returnType': '[Article]',
131+
'startOffset': 3000,
132+
'duration': 1000
133+
},
134+
{
135+
'path': ['feed', 0, 'id'],
136+
'parentType': 'Article',
137+
'fieldName': 'id',
138+
'returnType': 'String!',
139+
'startOffset': 6000,
140+
'duration': 1000
141+
},
142+
{
143+
'path': ['feed', 0, 'title'],
144+
'parentType': 'Article',
145+
'fieldName': 'title',
146+
'returnType': 'String',
147+
'startOffset': 9000,
148+
'duration': 1000
149+
},
150+
{
151+
'path': ['feed', 1, 'id'],
152+
'parentType': 'Article',
153+
'fieldName': 'id',
154+
'returnType': 'String!',
155+
'startOffset': 12000,
156+
'duration': 1000
157+
},
158+
{
159+
'path': ['feed', 1, 'title'],
160+
'parentType': 'Article',
161+
'fieldName': 'title',
162+
'returnType': 'String',
163+
'startOffset': 15000,
164+
'duration': 1000
165+
}
166+
]
167+
}
168+
}
169+

‎graphql/execution/tracing.py

Lines changed: 10 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
import time
2-
import datetime
2+
33

44
class TracingMiddleware(object):
55
DATETIME_FORMAT = '%Y-%m-%dT%H:%M:%S.%fZ'
@@ -10,32 +10,32 @@ def __init__(self):
1010
self.end_time = None
1111

1212
def start(self):
13-
self.start_time = time.time()
13+
self.start_time = time.time() * 1000
1414

1515
def end(self):
16-
self.end_time = time.time()
16+
self.end_time = time.time() * 1000
1717

1818
@property
1919
def start_time_str(self):
20-
return time.strftime(self.DATETIME_FORMAT, time.gmtime(self.start_time))
20+
return time.strftime(self.DATETIME_FORMAT, time.gmtime(self.start_time/1000))
2121

2222
@property
2323
def end_time_str(self):
24-
return time.strftime(self.DATETIME_FORMAT, time.gmtime(self.end_time))
24+
return time.strftime(self.DATETIME_FORMAT, time.gmtime(self.end_time/1000))
2525

2626
@property
2727
def duration(self):
2828
if not self.end_time:
2929
raise ValueError("Tracing has not ended yet!")
3030

31-
return (self.end_time - self.start_time) * 1000
31+
return (self.end_time - self.start_time)
3232

3333
@property
3434
def tracing_dict(self):
3535
return dict(
3636
version=1,
37-
startTime=self.start_time,
38-
endTime=self.end_time,
37+
startTime=self.start_time_str,
38+
endTime=self.end_time_str,
3939
duration=self.duration,
4040
execution=dict(
4141
resolvers=self.resolver_stats
@@ -55,7 +55,7 @@ def resolve(self, _next, root, info, *args, **kwargs):
5555
"parentType": str(info.parent_type),
5656
"fieldName": info.field_name,
5757
"returnType": str(info.return_type),
58-
"startOffset": (time.time() - self.start_time) * 1000,
58+
"startOffset": (time.time() * 1000) - self.start_time,
5959
"duration": elapsed_ms,
6060
}
61-
self.resolver_stats.append(stat)
61+
self.resolver_stats.append(stat)

0 commit comments

Comments
 (0)