pytorch/torch/_dynamo/logging.py
Edward Z. Yang 8b95fb4eb8 Add stack trace to "start tracing" log (#118217)
When debugging problems on unfamiliar model code, I often want to know
"how did I end up in this compiled region."  Printing the stack trace at
tracing start lets me find out this information.

Looks like this:

```
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO] Step 1: torchdynamo start tracing f /data/users/ezyang/c/pytorch/b.py:3
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO] Stack (most recent call last):
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]   File "/data/users/ezyang/c/pytorch/b.py", line 9, in <module>
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]     f(torch.randn(5))
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]   File "/data/users/ezyang/c/pytorch/torch/_dynamo/eval_frame.py", line 437, in _fn
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]     return fn(*args, **kwargs)
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]   File "/data/users/ezyang/c/pytorch/torch/_dynamo/eval_frame.py", line 601, in catch_errors
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]     return callback(frame, cache_entry, hooks, frame_state)
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]   File "/data/users/ezyang/c/pytorch/torch/_dynamo/convert_frame.py", line 743, in _convert_frame
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]     result = inner_convert(frame, cache_entry, hooks, frame_state)
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]   File "/data/users/ezyang/c/pytorch/torch/_dynamo/convert_frame.py", line 386, in _convert_frame_assert
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]     return _compile(
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]   File "/data/users/ezyang/c/pytorch/torch/_dynamo/convert_frame.py", line 645, in _compile
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]     guarded_code = compile_inner(code, one_graph, hooks, transform)
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]   File "/data/users/ezyang/c/pytorch/torch/_dynamo/utils.py", line 248, in time_wrapper
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]     r = func(*args, **kwargs)
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]   File "/data/users/ezyang/c/pytorch/torch/_dynamo/convert_frame.py", line 526, in compile_inner
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]     out_code = transform_code_object(code, transform)
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]   File "/data/users/ezyang/c/pytorch/torch/_dynamo/bytecode_transformation.py", line 1033, in transform_code_object
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]     transformations(instructions, code_options)
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]   File "/data/users/ezyang/c/pytorch/torch/_dynamo/convert_frame.py", line 151, in _fn
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]     return fn(*args, **kwargs)
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]   File "/data/users/ezyang/c/pytorch/torch/_dynamo/convert_frame.py", line 473, in transform
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]     tracer = InstructionTranslator(
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]   File "/data/users/ezyang/c/pytorch/torch/_dynamo/symbolic_convert.py", line 2030, in __init__
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]     _step_logger()(
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]   File "/data/users/ezyang/c/pytorch/torch/_dynamo/logging.py", line 55, in log
[2024-01-24 12:07:11,819] [0/1] torch._dynamo.symbolic_convert: [INFO]     logger.log(level, "Step %s: %s", step, msg, **kwargs)
```

Signed-off-by: Edward Z. Yang <ezyang@meta.com>

Pull Request resolved: https://github.com/pytorch/pytorch/pull/118217
Approved by: https://github.com/albanD
ghstack dependencies: #118215
2024-01-25 06:53:12 +00:00

58 lines
1.5 KiB
Python

import itertools
import logging
from torch.hub import _Faketqdm, tqdm
# Disable progress bar by default, not in dynamo config because otherwise get a circular import
disable_progress = True
# Return all loggers that torchdynamo/torchinductor is responsible for
def get_loggers():
return [
logging.getLogger("torch.fx.experimental.symbolic_shapes"),
logging.getLogger("torch._dynamo"),
logging.getLogger("torch._inductor"),
]
# Creates a logging function that logs a message with a step # prepended.
# get_step_logger should be lazily called (i.e. at runtime, not at module-load time)
# so that step numbers are initialized properly. e.g.:
# @functools.lru_cache(None)
# def _step_logger():
# return get_step_logger(logging.getLogger(...))
# def fn():
# _step_logger()(logging.INFO, "msg")
_step_counter = itertools.count(1)
# Update num_steps if more phases are added: Dynamo, AOT, Backend
# This is very inductor centric
# _inductor.utils.has_triton() gives a circular import error here
if not disable_progress:
try:
import triton # noqa: F401
num_steps = 3
except ImportError:
num_steps = 2
pbar = tqdm(total=num_steps, desc="torch.compile()", delay=0)
def get_step_logger(logger):
if not disable_progress:
pbar.update(1)
if not isinstance(pbar, _Faketqdm):
pbar.set_postfix_str(f"{logger.name}")
step = next(_step_counter)
def log(level, msg, **kwargs):
logger.log(level, "Step %s: %s", step, msg, **kwargs)
return log