0xMiden / 0xMiden/miden-vm

Operation trace for debugging

Aberta
#1,625 0 comentários 4 reações 0 responsáveis Ver no GitHub
debugging processor
Linguagem predominante
Rust
Estrelas
772
Forks
352
Merge médio
1d 12h
PRs com merge (30d)
93

Descrição

During the account ID refactor I made a small helper for debugging masm, which we could consider adding to miden-base or miden-vm. My preference would be miden-vm, so I'm creating the issue here.

## Motivation

Basically, what I wanted to have was a sort of stacktrace or "operation trace" that would show the last instructions that were executed leading up to a failure. This is useful for failures that don't include any context for where they've failed. For example, `push.2.3 and` would fail with `ExecutionError::NotBinaryValue(3)` but no information about clock cycle and no reference as to where in the code it failed. An `assert.err=123` instruction on the other hand would have the error code which often makes it possible to find the part of code that made the VM abort.

Before having this operation trace shown further below, I used `trace` and `debug` statements to basically binary search to the place where some failure occured. That is, adding `trace.1` and `trace.2` somewhere in the program and if I only saw `trace.1` in the output, I knew the problem was somewhere in between the two. This was cumbersome, slow and honestly a frustrating effort.

So the primary motivation is clearly debugging for MASM developers. Another one is that if we receive reports or requests for help from users in the future about their failing MASM programs, then I think we would rather have at least such an operation trace below instead of just `ExecutionError::NotBinaryValue(3)`.

## Operation Trace

Simply using a `VmStateIterator` and a custom print function, such a trace can be created:

```
...
clk 1026: op `add` in 'kernel::memory::get_account_id'
clk 1027: op `mem_loadw` in 'kernel::memory::get_account_id'
clk 1028: op `drop` in 'kernel::memory::get_account_id'
clk 1029: op `drop` in 'kernel::memory::get_account_id'
clk 1030: op `movup.2` in 'kernel::account::is_id_eq'
clk 1031: op `eq` in 'kernel::account::is_id_eq'
clk 1032: op `movdn.2` in 'kernel::account::is_id_eq'
```

Alternatively I think this would benefit from containing parts of the stack and being aligned. Using the `comfy_table` crate this could also become:

```
+-------+------------+--------------------------------+--------------------------------------------------------------------------------+
| Clock | Operation | Context | Stack (top 4 items) |
+======================================================================================================================================+
| 1026 | add | kernel::memory::get_account_id | [2048, 0, 0, 0] |
|-------+------------+--------------------------------+--------------------------------------------------------------------------------|
| 1027 | mem_loadw | kernel::memory::get_account_id | [1, 0, 12393906174523661584, 261683767475200] |
|-------+------------+--------------------------------+--------------------------------------------------------------------------------|
| 1028 | drop | kernel::memory::get_account_id | [0, 12393906174523661584, 261683767475200, 12393906174523661584] |
|-------+------------+--------------------------------+--------------------------------------------------------------------------------|
| 1029 | drop | kernel::memory::get_account_id | [12393906174523661584, 261683767475200, 12393906174523661584, 261683767475200] |
|-------+------------+--------------------------------+--------------------------------------------------------------------------------|
| 1030 | movup.2 | kernel::account::is_id_eq | [12393906174523661584, 12393906174523661584, 261683767475200, 261683767475200] |
|-------+------------+--------------------------------+--------------------------------------------------------------------------------|
| 1031 | eq | kernel::account::is_id_eq | [1, 261683767475200, 261683767475200, 15753966935105524537] |
|-------+------------+--------------------------------+--------------------------------------------------------------------------------|
| 1032 | movdn.2 | kernel::account::is_id_eq | [261683767475200, 261683767475200, 1, 15753966935105524537] |
+-------+------------+--------------------------------+--------------------------------------------------------------------------------+
```

In our debugging call with the DevRel team, they said such a "stack trace" would be useful to have for users and so I thought about what the best way would be to expose this.
## Current Approach

This section describes how this is currently implemented. The stack trace is produced by a simple function:

```rust
pub fn print_vm_operation_trace(
failed_at_clk: vm_processor::RowIndex,
vm_state_iter: vm_processor::VmStateIterator,
) -> ExecutionError { ... }
```

This simply iterates over the `vm_state_iter` and prints selected parts of `VmState`, nothing more fancy.

One issue with the above is that it doesn't interact as nicely as it should with `trace` or `debug` instructions. The reason is that these are printed directly when the processor executes code while this trace is produced afterwards using the `VmStateIterator`. So the output of these debug instructions appears before the trace. It would be best if these were interleaved. To illustrate, the current output with a `debug.stack.2` instruction after the `movdn.2` instruction @ clock 1031 would be:

```
Stack state before step 1032:
├── 0: 261683767475200
├── 1: 261683767475200
└── (21 more items)
...
clk 1031: op `eq` in 'kernel::account::is_id_eq'
clk 1032: op `movdn.2` in 'kernel::account::is_id_eq'
```

but the desired output is:

```
...
clk 1031: op `eq` in 'kernel::account::is_id_eq'
clk 1032: op `movdn.2` in 'kernel::account::is_id_eq'
Stack state before step 1032:
├── 0: 261683767475200
├── 1: 261683767475200
└── (21 more items)
```

(Aside: This says "Stack state before step 1032" but it's actually the state _after_ the `movdn.2` instruction was executed. Not sure if I'm reading this wrong or if it's a bug.)

This can be addressed by capturing certain events such as `trace` and `debug` instructions using the `Host` interface. E.g. a custom `DebugRecorderHost` which simply wraps and forwards most calls to another host, but adds all `trace`, `debug` and potentially events to a `Vec` works. That list is then later printed as part of `print_vm_operation_trace`.

Just exposing this function is likely not useful enough for users. So what we could also do is expose this as part of [`CodeExecutor`](https://github.com/0xPolygonMiden/miden-base/blob/4b733b276fa767eb2cd335c2c8cb60b55dfa4c53/miden-tx/src/testing/executor.rs#L10-L13) (or create a new test harness to support something similar). Basically, we would recommend users to write their MASM tests with this setup so they have access to the debug capabilities.

By using `CodeExecutor` we have control over the `Process` creation and could wrap a user-provided host with this `DebugRecorderHost`. If some feature flag like `masm-debug` is provided, it prints the operation trace, otherwise nothing.
- One complication I had during proof-of-concepting this was that we would have to unwrap the inner host when returning `Process` from `CodeExecutor::execute_program`. Basically, at this point we have a `Process>` so we'd need to unwrap the inner host. I don't see any methods on `Process` that support this, but since `Process:into_parts` exists, adding a `Process:from_parts` would solve this.

We also have the [`TransactionExecutor`](https://github.com/0xPolygonMiden/miden-base/blob/4b733b276fa767eb2cd335c2c8cb60b55dfa4c53/miden-tx/src/executor/mod.rs#L36-L44) which executes MASM code and will be called by users, so we should also support debugging there. Here we can really only make this available through a feature flag. E.g. if `masm-debug` is set and execution failed, we could re-execute and capture debug info. Not ideal, but it works.
## VM Integration Approach

Instead of building and exposing a custom `Host` from miden-base and adding complexity to `CodeExecutor` and `TransactionExecutor`, maybe this is something that should be directly integrated into the VM, more specifically `Process`. I'm not deeply familiar with it, but it looks like this is something that could be exposed as part of `ExecutionOptions`, where the other debug options `enable_tracing` and `enable_debugging` are already defined, so this would be most consistent for users - all debug options in one place. Basically we could add another option here, say, `ExecutionOptions::enable_operation_trace`. Depending on how easy this is, this could take either a closure with a `ProcessState` and `AsmOpInfo` argument to customize what is being printed. If that is annoying due to generics, maybe explicit options for how many stack items or what part of memory to print might be good enough. Probably sometime during `Process::execute_basic_block_node` this would then print one line of a trace similar to the above.
Mosty likely we would want to limit the number of lines printed, so the `Process` might actually have to buffer all these debug-related things internally and only upon failure print the last, e.g. 100 or configured number of entries.

This would seamlessly integrate into `CodeExecutor`, `TransactionExecutor` or other user-defined executors without having to do anything extra except enable another option on `ExecutionOptions`, and possibly a feature flag on `miden-processor` (if this affects performance even when disabled for some reason). It would also have the desired interleaved output directly, as the operations trace would be printed as part of process execution together with `trace` and `debug` instructions.

Any thoughts on the general idea? And if you think this is useful, where would this best be done, in `miden-base` or `miden-vm`?

cc @Dominik1999, @partylikeits1983

Guia de contribuição

Abrir o guia de contribuição

Avaliação

Esta issue ainda não foi avaliada.

Receba novas issues na sua caixa de entrada

Um resumo curto de issues do GitHub para quem está começando.