Skip to content

Commit

Permalink
remove inspect.stack() from @rule parsing to fix import time regressi…
Browse files Browse the repository at this point in the history
…on in py3 (#7447)

### Problem

Fixes #7373, fixes #7442. `inspect.stack()` in the `@rule` decorator was responsible for the majority of time taken during import when running pants in python 3, in particular, this line: https://github.com/pantsbuild/pants/blob/6739a81b6008274bfb4abd3436d9adb543a19e5a/src/python/pants/engine/rules.py#L245

In the below image a snakeviz profile was created of the import statement which brings in all our v2 rules, showing that an `inspect.stack()` in the `@rule` decorator was taking up 66% of the import time:

<img width="1744" alt="Screen Shot 2019-03-27 at 14 38 53 (2)" src="https://user-images.githubusercontent.com/1305167/55118058-3a0b6b00-50aa-11e9-9343-bcc2ca0e53d2.png">

This profile was generated via applying the following diff:
```diff
diff --git a/src/python/pants/bin/pants_loader.py b/src/python/pants/bin/pants_loader.py
index 91a4ca1..7510e6e 100644
--- a/src/python/pants/bin/pants_loader.py
+++ b/src/python/pants/bin/pants_loader.py
@@ -101,7 +101,9 @@ class PantsLoader(object):
   def load_and_execute(entrypoint):
     assert ':' in entrypoint, 'ERROR: entrypoint must be of the form `module.path:callable`'
     module_path, func_name = entrypoint.split(':', 1)
-    module = importlib.import_module(module_path)
+    from pants.util.contextutil import maybe_profiled
+    with maybe_profiled('import_module_profile.prof'):
+      module = importlib.import_module(module_path)
     entrypoint_main = getattr(module, func_name)
     assert callable(entrypoint_main), 'ERROR: entrypoint `{}` is not callable'.format(entrypoint)
     entrypoint_main()
```
then running `./pants goals` to produce `import_module_profile.prof`, then running `snakeviz import_module_profile.prof`. `snakeviz` must be installed with `pip3` for some reason.

### Solution

- Instead of getting the current interpreter frame with `inspect.stack()`, get the decorated function's module from `sys.modules`, and use that to obtain the type-valued arguments of a `Get` call during `@rule` parsing.

### Result

`./pants goals` went from ~4.8 seconds to ~2.3 seconds, while `./pants2 goals` went from ~2.3 seconds to ~2.2 seconds. The semantics of how types for `Get()` arguments are resolved from the `@rule` function's module *should* be unchanged.

### Explanation
@Eric-Arellano noted that the return type of `inspect.stack()` changed in python 3.5: https://docs.python.org/3/library/inspect.html#inspect.stack, which may have contributed to it.

@jsirois ran a quick experiment:
```
$ for py in python{2.7,3.{4,5,6,7}}; do echo -n "$py: " && $py -c "import timeit; print(timeit.timeit('import inspect; inspect.stack()', number=10000))"; done
python2.7: 2.63740515709
python3.4: 3.8067204039980425
python3.5: 4.471806422996451
python3.6: 4.527370049007004
python3.7: 3.3335486440046225
```

Note that the original line of code was getting the whole stack just to get the one containing the decorated method, so it's likely that this slowdown is proportional to depth (or worse). See the section "Foil in this hypothesis" in #7442 for some behavior which may bear out the hypothesis that slowdown is proportional to stack depth, e.g. directly importing `native_toolchain.py` is significantly faster than when it is imported indirectly.

A StackOverflow answer describes that filesystem access in generating each stack frame may be the culprit (https://stackoverflow.com/a/17407257/2518889):
> per frame, collect the filename, linenumber, and source file context (the source file line plus some extra lines around it if requested). The latter requires reading the source file for each stack frame. *This is the expensive step.*

Apparently, `inspect.stack(0)` might be usable to avoid this file access, but since the resulting code is able to avoid deep introspection anyway, it seems reasonable to keep this change.

### TODO

Make a python bug about this regression if it isn't already known.
  • Loading branch information
cosmicexplorer authored and stuhood committed Mar 29, 2019
1 parent c9d0b06 commit 2213f71
Show file tree
Hide file tree
Showing 2 changed files with 41 additions and 15 deletions.
24 changes: 14 additions & 10 deletions src/python/pants/engine/rules.py
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@
import inspect
import itertools
import logging
import sys
from abc import abstractproperty
from builtins import bytes, str
from types import GeneratorType
Expand All @@ -34,14 +35,13 @@
class _RuleVisitor(ast.NodeVisitor):
"""Pull `Get` calls out of an @rule body and validate `yield` statements."""

def __init__(self, func, func_node, func_source, orig_indent, frame, parents_table):
def __init__(self, func, func_node, func_source, orig_indent, parents_table):
super(_RuleVisitor, self).__init__()
self._gets = []
self._func = func
self._func_node = func_node
self._func_source = func_source
self._orig_indent = orig_indent
self._frame = frame
self._parents_table = parents_table
self._yields_in_assignments = set()

Expand All @@ -51,7 +51,8 @@ def gets(self):

def _generate_ast_error_message(self, node, msg):
# This is the location info of the start of the decorated @rule.
filename, line_number, _, context_lines, _ = inspect.getframeinfo(self._frame, context=4)
filename = inspect.getsourcefile(self._func)
source_lines, line_number = inspect.getsourcelines(self._func)

# The asttokens library is able to keep track of line numbers and column offsets for us -- the
# stdlib ast library only provides these relative to each parent node.
Expand Down Expand Up @@ -82,14 +83,14 @@ def _generate_ast_error_message(self, node, msg):
The rule defined by function `{func_name}` begins at:
{filename}:{line_number}:{orig_indent}
{context_lines}
{source_lines}
""".format(func_name=self._func.__name__, msg=msg,
filename=filename, line_number=line_number, orig_indent=self._orig_indent,
node_line_number=node_file_line,
node_col=fully_indented_node_col,
node_text=indented_node_text,
# Strip any leading or trailing newlines from the start of the rule body.
context_lines=''.join(context_lines).strip('\n')))
source_lines=''.join(source_lines).strip('\n')))

class YieldVisitError(Exception): pass

Expand Down Expand Up @@ -242,17 +243,21 @@ def wrapper(func):
if not inspect.isfunction(func):
raise ValueError('The @rule decorator must be applied innermost of all decorators.')

caller_frame = inspect.stack()[1][0]
owning_module = sys.modules[func.__module__]
source = inspect.getsource(func)
beginning_indent = _get_starting_indent(source)
if beginning_indent:
source = "\n".join(line[beginning_indent:] for line in source.split("\n"))
module_ast = ast.parse(source)

def resolve_type(name):
resolved = caller_frame.f_globals.get(name) or caller_frame.f_builtins.get(name)
if not isinstance(resolved, type):
raise ValueError('Expected a `type` constructor, but got: {}'.format(name))
resolved = getattr(owning_module, name, None) or owning_module.__builtins__.get(name, None)
if resolved is None:
raise ValueError('Could not resolve type `{}` in top level of module {}'
.format(name, owning_module.__name__))
elif not isinstance(resolved, type):
raise ValueError('Expected a `type` constructor for `{}`, but got: {} (type `{}`)'
.format(name, resolved, type(resolved).__name__))
return resolved

gets = OrderedSet()
Expand All @@ -270,7 +275,6 @@ def resolve_type(name):
func_node=rule_func_node,
func_source=source,
orig_indent=beginning_indent,
frame=caller_frame,
parents_table=parents_table,
)
rule_visitor.visit(rule_func_node)
Expand Down
32 changes: 27 additions & 5 deletions tests/python/pants_test/engine/test_rules.py
Original file line number Diff line number Diff line change
Expand Up @@ -60,6 +60,9 @@ def __repr__(self):
_suba_root_rules = [RootRule(SubA)]


_this_is_not_a_type = 3


@console_rule('example', [Select(Console)])
def a_console_rule_generator(console):
a = yield Get(A, str('a str!'))
Expand All @@ -81,7 +84,7 @@ def test_creation_fails_with_bad_declaration_type(self):
RuleIndex.create([A()])


class RuleGraphTest(unittest.TestCase):
class RuleGraphTest(TestBase):
def test_ruleset_with_missing_product_type(self):
@rule(A, [Select(B)])
def a_from_b_noop(b):
Expand Down Expand Up @@ -694,7 +697,24 @@ def b_from_d(d):
}""").strip(),
subgraph)

def test_validate_yield_statements(self):
def test_invalid_get_arguments(self):
with self.assertRaisesWithMessage(ValueError, """\
Could not resolve type `XXX` in top level of module pants_test.engine.test_rules"""):
class XXX(object): pass
@rule(A, [])
def f():
a = yield Get(A, XXX, 3)
yield a

# This fails because the argument is defined in this file's module, but it is not a type.
with self.assertRaisesWithMessage(ValueError, """\
Expected a `type` constructor for `_this_is_not_a_type`, but got: 3 (type `int`)"""):
@rule(A, [])
def g():
a = yield Get(A, _this_is_not_a_type, 3)
yield a

def test_validate_yield_statements_in_rule_body(self):
with self.assertRaisesRegexp(_RuleVisitor.YieldVisitError, re.escape('yield A()')):
@rule(A, [])
def f():
Expand Down Expand Up @@ -737,12 +757,14 @@ def g():
The rule defined by function `g` begins at:
test_rules.py:{rule_lineno}:{rule_col}
with self.assertRaises(_RuleVisitor.YieldVisitError) as cm:
@rule(A, [])
def g():
""".format(lineno=(sys._getframe().f_lineno - 20),
# This is a yield statement without an assignment, and not at the end.
yield Get(B, D, D())
yield A()
""".format(lineno=(sys._getframe().f_lineno - 22),
col=8,
rule_lineno=(sys._getframe().f_lineno - 25),
rule_lineno=(sys._getframe().f_lineno - 27),
rule_col=6))

def create_full_graph(self, rules, validate=True):
Expand Down

0 comments on commit 2213f71

Please sign in to comment.