Disable most tracing in the prelude. (#2616)

This is intended to address currently flaky timeouts that are likely caused by the size of the prelude. I'm addressing a performance bottleneck in AnalyzeProgram with trace output. Trying to omit prelude traces reduces most trace output significantly,  and I think it'll scale better as the prelude size increases.

The basic mechanics here are:

- In order to consistently track whether tracing is on, I've added a TraceStream class, explorer/interpreter/trace_stream.h.
- The AST now has a num_prelude_declarations field, so that it's provided where the boundary is.
- In order to mark where we try to skip prelude output, I've added calls to set_in_prelude in type_checker.
- In exec_program, I just use num_prelude_declarations directly to skip over.
- Everywhere checks TraceStream::is_enabled before printing, similar to the std::optional check that was previously used.

This does add some timing output in order to better diagnose where slowness is coming from, when tracing. It also adds "verbose" targets to make it easier to get the trace output.

So for example, here's a timing for zero.carbon:

```
Timings:
- Parse: 13ms
- AddPrelude: 25ms
- AnalyzeProgram: 116ms
- ExecProgram: 12ms
```

If I make a small change to just not set skipping_prelude (essentially getting back to current output):

```
- Parse: 13ms
- AddPrelude: 25ms
- AnalyzeProgram: 2359ms
- ExecProgram: 57ms
```

Thus in this trivial example, I'm eliminating about 95% of the execution time.

Note this approach could still be refined in a few ways:

- We could add a flag to allow overriding in_prelude. It should be a small amount of work after this change. But it's a little consistent with how parser_debug works, that it won't print prelude output by default (unless there's an error).
- Execution could skip messages involving initialization of globals declared in the prelude. This is a little noisy right now, but I don't think it's significant for performance because ExecProgram is tiny.
- Once files are more separated, we should be able to change the num_prelude_declarations/set_in_prelude approach.

Co-authored-by: Richard Smith <richard@metafoo.co.uk>
This commit is contained in:
Jon Ross-Perkins
2023-02-22 13:41:12 -08:00
committed by GitHub
co-authored by Richard Smith
parent 86aecb532f
commit 9df70fb115
17 changed files with 442 additions and 287 deletions
+26 -22
View File
@@ -19,12 +19,12 @@
namespace Carbon {
auto AnalyzeProgram(Nonnull<Arena*> arena, AST ast,
std::optional<Nonnull<llvm::raw_ostream*>> trace_stream)
-> ErrorOr<AST> {
if (trace_stream) {
**trace_stream << "********** source program **********\n";
for (auto* const decl : ast.declarations) {
**trace_stream << *decl;
Nonnull<TraceStream*> trace_stream) -> ErrorOr<AST> {
if (trace_stream->is_enabled()) {
*trace_stream << "********** source program **********\n";
for (int i = ast.num_prelude_declarations;
i < static_cast<int>(ast.declarations.size()); ++i) {
*trace_stream << *ast.declarations[i];
}
}
SourceLocation source_loc("<Main()>", 0);
@@ -33,36 +33,40 @@ auto AnalyzeProgram(Nonnull<Arena*> arena, AST ast,
arena->New<TupleLiteral>(source_loc));
// Although name resolution is currently done once, generic programming
// (particularly templates) may require more passes.
if (trace_stream) {
**trace_stream << "********** resolving names **********\n";
if (trace_stream->is_enabled()) {
*trace_stream << "********** resolving names **********\n";
}
CARBON_RETURN_IF_ERROR(ResolveNames(ast));
if (trace_stream) {
**trace_stream << "********** resolving control flow **********\n";
if (trace_stream->is_enabled()) {
*trace_stream << "********** resolving control flow **********\n";
}
CARBON_RETURN_IF_ERROR(ResolveControlFlow(ast));
if (trace_stream) {
**trace_stream << "********** type checking **********\n";
if (trace_stream->is_enabled()) {
*trace_stream << "********** type checking **********\n";
}
CARBON_RETURN_IF_ERROR(TypeChecker(arena, trace_stream).TypeCheck(ast));
if (trace_stream) {
**trace_stream << "********** resolving unformed variables **********\n";
if (trace_stream->is_enabled()) {
*trace_stream << "********** resolving unformed variables **********\n";
}
CARBON_RETURN_IF_ERROR(ResolveUnformed(ast));
if (trace_stream) {
**trace_stream << "********** printing declarations **********\n";
for (auto* const decl : ast.declarations) {
**trace_stream << *decl;
if (trace_stream->is_enabled()) {
*trace_stream << "********** printing declarations **********\n";
for (int i = ast.num_prelude_declarations;
i < static_cast<int>(ast.declarations.size()); ++i) {
*trace_stream << *ast.declarations[i];
}
}
return ast;
}
auto ExecProgram(Nonnull<Arena*> arena, AST ast,
std::optional<Nonnull<llvm::raw_ostream*>> trace_stream)
-> ErrorOr<int> {
if (trace_stream) {
**trace_stream << "********** starting execution **********\n";
Nonnull<TraceStream*> trace_stream) -> ErrorOr<int> {
if (trace_stream->is_enabled()) {
*trace_stream << "********** starting execution **********\n";
}
return InterpProgram(ast, arena, trace_stream);
}