Add logging to the assembler #1139

Fumuran · 2023-11-06T20:25:25Z

This PR implements Tracing logger for the Miden VM.

TODO:

Update changelog

bobbinth

Looks good! Thank you! I left a few comments inline. Also, I think we should log parsing as well (not just compilation). E.g., "Parsed xyz module in 2.34 ms".

Lastly, could you upload a screenshot of how the output looks like (just one or two examples).

miden/src/cli/prove.rs

assembly/src/ast/mod.rs

miden/src/cli/data.rs

assembly/src/assembler/mod.rs

miden/src/main.rs

Fumuran · 2023-11-10T12:34:58Z

I am not sure that logging of parsing completion will make sense for us, because at the parsing stage we don't have information about name or path of the module, we can obtain this info only at compiling stage. So I can log only something like "Parsed module in 2.34 ms", without specifying the name or the path of the module.

Fumuran · 2023-11-20T15:24:03Z

Executing this program

use.module::path::two
use.bar::baz

begin 
    exec.two::foo
end

we will get this output without logging level specification:

% target/optimized/miden run -a miden/examples/logger/logger.masm -i miden/examples/logger/logger.inputs -l miden/examples/logger/logger.masl
============================================================
Run program
============================================================
Reading library file `miden/examples/logger/logger.masl`
Reading program file `miden/examples/logger/logger.masm`
Parsing program... 
warning: unused imports: "bar::baz"
done (0 ms)
Compiling program... 
done (4 ms)
Reading input file `miden/examples/logger/logger.inputs`
Executing program with hash 8bcf4aab5eaba5f76fed175478a14f84cc61f1c47fcec5fdb138fa38bfff7595... done (0 ms)
Output: [2, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
VM cycles: 39 extended to 64 steps (39% padding).
├── Stack rows: 6
├── Range checker rows: 39
└── Chiplets rows: 9
    ├── Hash chiplet rows: 8
    ├── Bitwise chiplet rows: 0
    ├── Memory chiplet rows: 0
    └── Kernel ROM rows: 0

and this output by specifying level to be trace:

% MIDEN_LOG=trace target/optimized/miden run -a miden/examples/logger/logger.masm -i miden/examples/logger/logger.inputs -l miden/examples/logger/logger.masl
============================================================
Run program
============================================================
Reading library file `miden/examples/logger/logger.masl`
Reading program file `miden/examples/logger/logger.masm`
Parsing program... 
warning: unused imports: "bar::baz"
done (0 ms)
Compiling program... 
- Compiled "module::path::one" module in 0 ms
- Compiled "module::path::two" module in 0 ms
done (2 ms)
Reading input file `miden/examples/logger/logger.inputs`
Executing program with hash 8bcf4aab5eaba5f76fed175478a14f84cc61f1c47fcec5fdb138fa38bfff7595... done (0 ms)
Output: [2, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
VM cycles: 39 extended to 64 steps (39% padding).
├── Stack rows: 6
├── Range checker rows: 39
└── Chiplets rows: 9
    ├── Hash chiplet rows: 8
    ├── Bitwise chiplet rows: 0
    ├── Memory chiplet rows: 0
    └── Kernel ROM rows: 0

Used logger library is just a dummy with two modules, where only module one contains function foo, which I use in the example.

Fumuran · 2023-11-20T16:08:21Z

One thing I don't like in my implementation is that I have to put the done (* ms) string to the new line after parsing and compiling regardless of whether we print warnings or information about compiled modules between them.

bobbinth

Thank you! Looks good! I left some comments inline.

One thing I don't like in my implementation is that I have to put the done (* ms) string to the new line after parsing and compiling regardless of whether we print warnings or information about compiled modules between them.

Yes, agreed. I think we should replace done(* ms) with more meaningful text.

Another option is to use a more sophisticated logging library - but I'm not sure it is worth it.

miden/src/main.rs

miden/src/cli/run.rs

miden/src/cli/data.rs

miden/examples/logger/logger.masm

miden/examples/logger/logger.masl

miden/examples/logger/logger.inputs

assembly/src/ast/program.rs

miden/src/cli/debug/mod.rs

miden/src/cli/prove.rs

Fumuran · 2023-12-14T15:25:47Z

Here is updated output for proving with default logging level:

% target/optimized/miden prove -a miden/examples/logger/logger.masm -i miden/examples/logger/logger.inputs -l miden/examples/logger/lib/logger_lib.masl                
============================================================
Prove program
============================================================
Reading library file `miden/examples/logger/lib/logger_lib.masl`
Reading program file `miden/examples/logger/logger.masm`
Parsing program...
warning: unused imports: "logger_lib::module2"
Parsed the program in 0 ms
Compiling program...
Compiled the program in 3 ms
Reading input file `miden/examples/logger/logger.inputs`
Proving program with hash 74184a73e531e907b5568906c1c2b53732bebcdcd7e197892694aba1d6ce197d...
Program with hash 74184a73e531e907b5568906c1c2b53732bebcdcd7e197892694aba1d6ce197d proved in 15 ms
Creating proof file `miden/examples/logger/logger.proof`
Writing data to proof file - size 31 KB
Creating output file `miden/examples/logger/logger.outputs`
Writing data to output file
Output: [3, 7, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]

Here is the output with trace logging level:

% MIDEN_LOG=trace target/optimized/miden prove -a miden/examples/logger/logger.masm -i miden/examples/logger/logger.inputs -l miden/examples/logger/lib/logger_lib.masl
============================================================
Prove program
============================================================
Reading library file `miden/examples/logger/lib/logger_lib.masl`
Reading program file `miden/examples/logger/logger.masm`
Parsing program...
warning: unused imports: "logger_lib::module2"
Parsed the program in 0 ms
Compiling program...
- Compiled "logger_lib::module1" module in 0 ms
Compiled the program in 2 ms
Reading input file `miden/examples/logger/logger.inputs`
Proving program with hash 74184a73e531e907b5568906c1c2b53732bebcdcd7e197892694aba1d6ce197d...
Generated execution trace of 70 columns and 64 steps (26% padded) in 0 ms
Built domain of 2^9 elements in 0 ms
Extended execution trace of 70 columns from 2^6 to 2^9 steps (8x blowup) in 0 ms
Computed execution trace commitment (Merkle tree of depth 9) in 0 ms
Built auxiliary trace segment of 7 columns and 2^6 steps in 0 ms
Extended execution trace of 7 columns from 2^6 to 2^9 steps (8x blowup) in 0 ms
Computed execution trace commitment (Merkle tree of depth 9) in 0 ms
Evaluated constraints over domain of 2^9 elements in 1 ms
Converted constraint evaluations into 8 composition polynomial columns of degree 63 in 0 ms
Evaluated 8 composition polynomial columns over LDE domain (2^9 elements) in 0 ms
Computed constraint evaluation commitment (Merkle tree of depth 9) in 0 ms
Built DEEP composition polynomial of degree 62 in 6 ms
Evaluated DEEP composition polynomial over LDE domain (2^9 elements) in 0 ms
Computed 0 FRI layers from composition polynomial evaluations in 0 ms
Determined 27 unique query positions in 1 ms
Built proof object in 0 ms
Program with hash 74184a73e531e907b5568906c1c2b53732bebcdcd7e197892694aba1d6ce197d proved in 13 ms
Creating proof file `miden/examples/logger/logger.proof`
Writing data to proof file - size 31 KB
Creating output file `miden/examples/logger/logger.outputs`
Writing data to output file
Output: [3, 7, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]

Here is the output with logger turned off:

% MIDEN_LOG=off target/optimized/miden prove -a miden/examples/logger/logger.masm -i miden/examples/logger/logger.inputs -l miden/examples/logger/lib/logger_lib.masl
============================================================
Prove program
============================================================
Proving program with hash 74184a73e531e907b5568906c1c2b53732bebcdcd7e197892694aba1d6ce197d...
Program with hash 74184a73e531e907b5568906c1c2b53732bebcdcd7e197892694aba1d6ce197d proved in 19 ms
Output: [3, 7, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]

After I added the unused module warning, library parsing and compilation started to look like so:

% target/optimized/miden bundle miden/examples/logger/lib -n logger_lib
============================================================
Build library
============================================================
warning: unused imports: "logger_lib::module1"
Built library logger_lib

For some reason capital letter W is printed with weird space after it. This may be related to the font used in the terminal, but I didn't get the exact reason yet.

Fumuran · 2023-12-26T21:48:18Z

Currently this is how log looks like:

% MIDEN_LOG=trace target/optimized/miden run -a miden/examples/logger/logger.masm -i miden/examples/logger/logger.inputs -l miden/examples/logger/lib/logger_lib.masl
INFO      ===== Run program ===== [ 4.41ms | 3.85% / 100.00% ]
INFO     ┝━ Reading library files [ 102µs | 0.27% / 2.33% ]
INFO     │  ┕━ Reading library file [ 90.4µs | 2.05% ] path: miden/examples/logger/lib/logger_lib.masl
INFO     ┝━ Reading program file [ 81.3µs | 0.88% / 1.85% ] path: miden/examples/logger/logger.masm
INFO     │  ┕━ Parsing program [ 42.7µs | 0.97% ]
WARN     │     ┕━ 🚧 [warn]: warning: unused import: "logger_lib::module2"
INFO     ┝━ Compiling program [ 3.35ms | 74.15% / 76.04% ]
INFO     │  ┕━ Compile AST [ 83.4µs | 1.14% / 1.89% ]
TRACE    │     ┕━ Compiling module [ 33.0µs | 0.75% ] module: "logger_lib::module1"
INFO     ┝━ Reading input file [ 67.0µs | 1.52% ]
INFO     ┝━ Executing program [ 635µs | 14.41% ] hash: 74184a73e531e907b5568906c1c2b53732bebcdcd7e197892694aba1d6ce197d
INFO     ┝━ ｉ [info]: Output: [3, 7, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
INFO     ┕━ ｉ [info]: VM cycles: 47 extended to 64 steps (26% padding).
                       ├── Stack rows: 11
                       ├── Range checker rows: 47
                       └── Chiplets rows: 9
                           ├── Hash chiplet rows: 8
                           ├── Bitwise chiplet rows: 0
                           ├── Memory chiplet rows: 0
                           └── Kernel ROM rows: 0

% target/optimized/miden prove -a miden/examples/logger/logger.masm -i miden/examples/logger/logger.inputs -l miden/examples/logger/lib/logger_lib.masl         
INFO      ===== Prove program ===== [ 19.3ms | 0.79% / 100.00% ]
INFO     ┝━ Reading library files [ 84.5µs | 0.06% / 0.44% ]
INFO     │  ┕━ Reading library file [ 72.7µs | 0.38% ] path: miden/examples/logger/lib/logger_lib.masl
INFO     ┝━ Reading program file [ 69.2µs | 0.14% / 0.36% ] path: miden/examples/logger/logger.masm
INFO     │  ┕━ Parsing program [ 41.5µs | 0.21% ]
WARN     │     ┕━ 🚧 [warn]: warning: unused import: "logger_lib::module2"
INFO     ┝━ Compiling program [ 3.41ms | 17.30% / 17.67% ]
INFO     │  ┕━ Compile AST [ 70.3µs | 0.36% ]
INFO     ┝━ Reading input file [ 66.4µs | 0.34% ]
INFO     ┝━ Proving program [ 14.9ms | 74.43% / 76.93% ]
INFO     │  ┕━ Executing program [ 483µs | 2.50% ] hash: 74184a73e531e907b5568906c1c2b53732bebcdcd7e197892694aba1d6ce197d
INFO     ┝━ Writing data to proof file [ 240µs | 1.24% ] path: miden/examples/logger/logger.proof | size: "31 KB"
INFO     ┝━ Writing data to output file [ 430µs | 2.23% ] path: miden/examples/logger/logger.outputs
INFO     ┕━ ｉ [info]: Output: [3, 7, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]

% MIDEN_LOG=trace target/optimized/miden prove -a miden/examples/logger/logger.masm -i miden/examples/logger/logger.inputs -l miden/examples/logger/lib/logger_lib.masl 
INFO      ===== Prove program ===== [ 20.8ms | 0.73% / 100.00% ]
INFO     ┝━ Reading library files [ 128µs | 0.06% / 0.62% ]
INFO     │  ┕━ Reading library file [ 116µs | 0.56% ] path: miden/examples/logger/lib/logger_lib.masl
INFO     ┝━ Reading program file [ 85.7µs | 0.21% / 0.41% ] path: miden/examples/logger/logger.masm
INFO     │  ┕━ Parsing program [ 42.8µs | 0.21% ]
WARN     │     ┕━ 🚧 [warn]: warning: unused import: "logger_lib::module2"
INFO     ┝━ Compiling program [ 3.37ms | 15.85% / 16.25% ]
INFO     │  ┕━ Compile AST [ 83.2µs | 0.24% / 0.40% ]
TRACE    │     ┕━ Compiling module [ 33.1µs | 0.16% ] module: "logger_lib::module1"
INFO     ┝━ Reading input file [ 62.8µs | 0.30% ]
INFO     ┝━ Proving program [ 15.3ms | 71.41% / 73.60% ]
INFO     │  ┝━ Executing program [ 454µs | 2.19% ] hash: 74184a73e531e907b5568906c1c2b53732bebcdcd7e197892694aba1d6ce197d
DEBUG    │  ┝━ 🐛 [debug]: Generated execution trace of 70 columns and 64 steps (26% padded) in 0 ms | log.target: "miden_prover" | log.module_path: "miden_prover" | log.file: "prover/src/lib.rs" | log.line: 71
DEBUG    │  ┝━ 🐛 [debug]: Built domain of 2^9 elements in 0 ms | log.target: "winter_prover" | log.module_path: "winter_prover" | log.file: "/Users/fumuran/.cargo/registry/src/index.crates.io-6f17d22bba15001f/winter-prover-0.7.1/src/lib.rs" | log.line: 264
DEBUG    │  ┝━ 🐛 [debug]: Extended execution trace of 70 columns from 2^6 to 2^9 steps (8x blowup) in 0 ms | log.target: "winter_prover::trace::trace_lde::default" | log.module_path: "winter_prover::trace::trace_lde::default" | log.file: "/Users/fumuran/.cargo/registry/src/index.crates.io-6f17d22bba15001f/winter-prover-0.7.1/src/trace/trace_lde/default/mod.rs" | log.line: 242
DEBUG    │  ┝━ 🐛 [debug]: Computed execution trace commitment (Merkle tree of depth 9) in 0 ms | log.target: "winter_prover::trace::trace_lde::default" | log.module_path: "winter_prover::trace::trace_lde::default" | log.file: "/Users/fumuran/.cargo/registry/src/index.crates.io-6f17d22bba15001f/winter-prover-0.7.1/src/trace/trace_lde/default/mod.rs" | log.line: 256
DEBUG    │  ┝━ 🐛 [debug]: Built auxiliary trace segment of 7 columns and 2^6 steps in 0 ms | log.target: "winter_prover" | log.module_path: "winter_prover" | log.file: "/Users/fumuran/.cargo/registry/src/index.crates.io-6f17d22bba15001f/winter-prover-0.7.1/src/lib.rs" | log.line: 297
DEBUG    │  ┝━ 🐛 [debug]: Extended execution trace of 7 columns from 2^6 to 2^9 steps (8x blowup) in 0 ms | log.target: "winter_prover::trace::trace_lde::default" | log.module_path: "winter_prover::trace::trace_lde::default" | log.file: "/Users/fumuran/.cargo/registry/src/index.crates.io-6f17d22bba15001f/winter-prover-0.7.1/src/trace/trace_lde/default/mod.rs" | log.line: 242
DEBUG    │  ┝━ 🐛 [debug]: Computed execution trace commitment (Merkle tree of depth 9) in 0 ms | log.target: "winter_prover::trace::trace_lde::default" | log.module_path: "winter_prover::trace::trace_lde::default" | log.file: "/Users/fumuran/.cargo/registry/src/index.crates.io-6f17d22bba15001f/winter-prover-0.7.1/src/trace/trace_lde/default/mod.rs" | log.line: 256
DEBUG    │  ┝━ 🐛 [debug]: Evaluated constraints over domain of 2^9 elements in 2 ms | log.target: "winter_prover" | log.module_path: "winter_prover" | log.file: "/Users/fumuran/.cargo/registry/src/index.crates.io-6f17d22bba15001f/winter-prover-0.7.1/src/lib.rs" | log.line: 337
DEBUG    │  ┝━ 🐛 [debug]: Converted constraint evaluations into 8 composition polynomial columns of degree 63 in 0 ms | log.target: "winter_prover" | log.module_path: "winter_prover" | log.file: "/Users/fumuran/.cargo/registry/src/index.crates.io-6f17d22bba15001f/winter-prover-0.7.1/src/lib.rs" | log.line: 504
DEBUG    │  ┝━ 🐛 [debug]: Evaluated 8 composition polynomial columns over LDE domain (2^9 elements) in 0 ms | log.target: "winter_prover" | log.module_path: "winter_prover" | log.file: "/Users/fumuran/.cargo/registry/src/index.crates.io-6f17d22bba15001f/winter-prover-0.7.1/src/lib.rs" | log.line: 519
DEBUG    │  ┝━ 🐛 [debug]: Computed constraint evaluation commitment (Merkle tree of depth 9) in 0 ms | log.target: "winter_prover" | log.module_path: "winter_prover" | log.file: "/Users/fumuran/.cargo/registry/src/index.crates.io-6f17d22bba15001f/winter-prover-0.7.1/src/lib.rs" | log.line: 532
DEBUG    │  ┝━ 🐛 [debug]: Built DEEP composition polynomial of degree 62 in 7 ms | log.target: "winter_prover" | log.module_path: "winter_prover" | log.file: "/Users/fumuran/.cargo/registry/src/index.crates.io-6f17d22bba15001f/winter-prover-0.7.1/src/lib.rs" | log.line: 392
DEBUG    │  ┝━ 🐛 [debug]: Evaluated DEEP composition polynomial over LDE domain (2^9 elements) in 0 ms | log.target: "winter_prover" | log.module_path: "winter_prover" | log.file: "/Users/fumuran/.cargo/registry/src/index.crates.io-6f17d22bba15001f/winter-prover-0.7.1/src/lib.rs" | log.line: 413
DEBUG    │  ┝━ 🐛 [debug]: Computed 0 FRI layers from composition polynomial evaluations in 0 ms | log.target: "winter_prover" | log.module_path: "winter_prover" | log.file: "/Users/fumuran/.cargo/registry/src/index.crates.io-6f17d22bba15001f/winter-prover-0.7.1/src/lib.rs" | log.line: 425
DEBUG    │  ┝━ 🐛 [debug]: Determined 26 unique query positions in 1 ms | log.target: "winter_prover" | log.module_path: "winter_prover" | log.file: "/Users/fumuran/.cargo/registry/src/index.crates.io-6f17d22bba15001f/winter-prover-0.7.1/src/lib.rs" | log.line: 441
DEBUG    │  ┕━ 🐛 [debug]: Built proof object in 0 ms | log.target: "winter_prover" | log.module_path: "winter_prover" | log.file: "/Users/fumuran/.cargo/registry/src/index.crates.io-6f17d22bba15001f/winter-prover-0.7.1/src/lib.rs" | log.line: 471
INFO     ┝━ Writing data to proof file [ 1.21ms | 5.85% ] path: miden/examples/logger/logger.proof | size: "31 KB"
INFO     ┝━ Writing data to output file [ 464µs | 2.24% ] path: miden/examples/logger/logger.outputs
INFO     ┕━ ｉ [info]: Output: [3, 7, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]

There are a lot of additional information while calling prove with debug or trace logging level, but I decided to leave it as it is, since this information could be helpful for debugging (I already used it once).

bobbinth

Looks cool! Thank you! I left a couple of minor comments inline - but there are two more general comments:

First, I think we should separate logging output from "regular" output. Basically, regular output is something we'd like to see even if we turn the logging off completely. For example, for run command, it could be something like:

===============================================================================
Run program: miden/examples/fib/fib.masm
-------------------------------------------------------------------------------
Executed program with hash 78d31702eb946e1817e3c0881fcb3739562f08fbddf202de2eae241b9968ab3b in 1 ms
Output: [11112721240812633725]
VM cycles: 3045 extended to 4096 steps (25% padding).
├── Stack rows: 3045
├── Range checker rows: 39
└── Chiplets rows: 337
    ├── Hash chiplet rows: 336
    ├── Bitwise chiplet rows: 0
    ├── Memory chiplet rows: 0
    └── Kernel ROM rows: 0

So, I would print the above using regular println and would use logging for everything else. If we do this, we can set logging default back to WARN. Basically, if people want to see more detail, they can enable lower levels of logging. With logging enabled, it might looks something like this:

===============================================================================
Run program: miden/examples/fib/fib.masm
-------------------------------------------------------------------------------
INFO     ┝━ Reading library files [ 102µs | 0.27% / 2.33% ]
INFO     │  ┕━ Reading library file [ 90.4µs | 2.05% ] path: miden/examples/logger/lib/logger_lib.masl
INFO     ┝━ Reading program file [ 81.3µs | 0.88% / 1.85% ] path: miden/examples/logger/logger.masm
INFO     │  ┕━ Parsing program [ 42.7µs | 0.97% ]
WARN     │     ┕━ 🚧 [warn]: warning: unused import: "logger_lib::module2"
INFO     ┝━ Compiling program [ 3.35ms | 74.15% / 76.04% ]
INFO     │  ┕━ Compile AST [ 83.4µs | 1.14% / 1.89% ]
TRACE    │     ┕━ Compiling module [ 33.0µs | 0.75% ] module: "logger_lib::module1"
INFO     ┝━ Reading input file [ 67.0µs | 1.52% ]
INFO     ┕━ Executing program [ 635µs | 14.41% ]
Executed program with hash 78d31702eb946e1817e3c0881fcb3739562f08fbddf202de2eae241b9968ab3b in 1 ms
Output: [11112721240812633725]
VM cycles: 3045 extended to 4096 steps (25% padding).
├── Stack rows: 3045
├── Range checker rows: 39
└── Chiplets rows: 337
    ├── Hash chiplet rows: 336
    ├── Bitwise chiplet rows: 0
    ├── Memory chiplet rows: 0
    └── Kernel ROM rows: 0

We should do the same for other commands as well (obviously, what we consider "regular" will differ from command to command).

Second, for log output formatting, could we do the following:

Not show the left column with INFO, WARN etc. labels?
For winterfell output, note show the very verbose file location etc. to the right of the message?

assembly/Cargo.toml

processor/Cargo.toml

assembly/src/library/path.rs

bobbinth · 2023-12-27T10:19:24Z

So, for the run command, it would be awesome if the output (with logging enabled) looked something like:

===============================================================================
Run program: miden/examples/fib/fib.masm
-------------------------------------------------------------------------------
┝━ Reading library files [ 102µs | 0.27% / 2.33% ]
│  ┕━ Reading library file [ 90.4µs | 2.05% ] path: miden/examples/logger/lib/logger_lib.masl
┝━ Reading program file [ 81.3µs | 0.88% / 1.85% ] path: miden/examples/logger/logger.masm
│  ┕━ Parsing program [ 42.7µs | 0.97% ]
│     ┕━ 🚧 [warn]: warning: unused import: "logger_lib::module2"
┝━ Compiling program [ 3.35ms | 74.15% / 76.04% ]
│  ┕━ Compile AST [ 83.4µs | 1.14% / 1.89% ]
│     ┕━ Compiling module [ 33.0µs | 0.75% ] module: "logger_lib::module1"
┝━ Reading input file [ 67.0µs | 1.52% ]
┕━ Executing program [ 635µs | 14.41% ]
Executed program with hash 78d31702eb946e1817e3c0881fcb3739562f08fbddf202de2eae241b9968ab3b in 1 ms
Output: [11112721240812633725]
VM cycles: 3045 extended to 4096 steps (25% padding).
├── Stack rows: 3045
├── Range checker rows: 39
└── Chiplets rows: 337
    ├── Hash chiplet rows: 336
    ├── Bitwise chiplet rows: 0
    ├── Memory chiplet rows: 0
    └── Kernel ROM rows: 0

Fumuran · 2024-01-09T23:27:31Z

After the update output looks like this:

run with disabled logging:

% MIDEN_LOG=off target/optimized/miden run -i miden/examples/logger/logger.inputs -a miden/examples/logger/logger.masm -l miden/examples/logger/lib/logger_lib.masl 
===============================================================================
Run program: miden/examples/logger/logger.masm
-------------------------------------------------------------------------------
Executed the program with hash 74184a73e531e907b5568906c1c2b53732bebcdcd7e197892694aba1d6ce197d in 6 ms
Output: [3, 7, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
VM cycles: 47 extended to 64 steps (26% padding).
├── Stack rows: 11
├── Range checker rows: 47
└── Chiplets rows: 9
    ├── Hash chiplet rows: 8
    ├── Bitwise chiplet rows: 0
    ├── Memory chiplet rows: 0
    └── Kernel ROM rows: 0

run with default (warn) logging level:

% target/optimized/miden run -i miden/examples/logger/logger.inputs -a miden/examples/logger/logger.masm -l miden/examples/logger/lib/logger_lib.masl 
===============================================================================
Run program: miden/examples/logger/logger.masm
-------------------------------------------------------------------------------
WARN     🚧 [warn]: unused import: "logger_lib::module2"
Executed the program with hash 74184a73e531e907b5568906c1c2b53732bebcdcd7e197892694aba1d6ce197d in 2 ms
Output: [3, 7, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
VM cycles: 47 extended to 64 steps (26% padding).
├── Stack rows: 11
├── Range checker rows: 47
└── Chiplets rows: 9
    ├── Hash chiplet rows: 8
    ├── Bitwise chiplet rows: 0
    ├── Memory chiplet rows: 0
    └── Kernel ROM rows: 0

run with trace logging level:

% MIDEN_LOG=trace target/optimized/miden run -i miden/examples/logger/logger.inputs -a miden/examples/logger/logger.masm -l miden/examples/logger/lib/logger_lib.masl
===============================================================================
Run program: miden/examples/logger/logger.masm
-------------------------------------------------------------------------------
INFO     Running program [ 4.41ms | 2.89% / 100.00% ]
INFO     ┝━ Reading library files [ 114µs | 0.53% / 2.59% ]
INFO     │  ┕━ Reading library file [ 90.8µs | 2.06% ] path: miden/examples/logger/lib/logger_lib.masl
INFO     ┝━ Reading program file [ 98.9µs | 0.70% / 2.24% ] path: miden/examples/logger/logger.masm
INFO     │  ┕━ Parsing program [ 68.2µs | 1.55% ]
WARN     │     ┕━ 🚧 [warn]: unused import: "logger_lib::module2"
INFO     ┝━ Compiling program [ 3.41ms | 74.10% / 77.34% ]
INFO     │  ┕━ Compile AST [ 143µs | 2.28% / 3.25% ]
TRACE    │     ┕━ Compiling module [ 42.7µs | 0.97% ] module: "logger_lib::module1"
INFO     ┝━ Reading input file [ 57.4µs | 1.30% ]
INFO     ┕━ Executing program [ 602µs | 13.64% ]
Executed the program with hash 74184a73e531e907b5568906c1c2b53732bebcdcd7e197892694aba1d6ce197d in 4 ms
Output: [3, 7, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
VM cycles: 47 extended to 64 steps (26% padding).
├── Stack rows: 11
├── Range checker rows: 47
└── Chiplets rows: 9
    ├── Hash chiplet rows: 8
    ├── Bitwise chiplet rows: 0
    ├── Memory chiplet rows: 0
    └── Kernel ROM rows: 0

Output of the prove and verify looks similar.

However, there are still several problems:

There is no way we can disable printing the logging level at the beginning of the line (INFO, WARN etc.) without rewriting the whole tree-like output: these levels are placed in the core of this tree. Potentially I can rewrite the whole tree, but I'm not sure that it is worth it.
I shortened the unnecessarily detailed lines in the DEBUG output of the prover (the ones that were in the VM repo), but most of them are printed from the winterfell implementation of the prover. So to make them all short I need to implement Tracing in the winterfell too, but I'm not sure we want to do that now. Anyway, I can create an issue for that.

bobbinth

Looks great! Thank you! I left some comments inline - but they are pretty small.

There is no way we can disable printing the logging level at the beginning of the line (INFO, WARN etc.) without rewriting the whole tree-like output: these levels are placed in the core of this tree. Potentially I can rewrite the whole tree, but I'm not sure that it is worth it.

Yeah - what we have is fine, no need to spend more time on this.

I shortened the unnecessarily detailed lines in the DEBUG output of the prover (the ones that were in the VM repo), but most of them are printed from the winterfell implementation of the prover. So to make them all short I need to implement Tracing in the winterfell too, but I'm not sure we want to do that now. Anyway, I can create an issue for that.

I'd like to see how the output of prove looks like but we probably don't need to do anything else here, and once Winterfell implements tracing, it will all look good again.

prover/src/lib.rs

prover/src/gpu.rs

miden/src/main.rs

miden/src/cli/verify.rs

miden/src/cli/prove.rs

verifier/Cargo.toml

bobbinth

Looks great! Thank you! Just a couple of minor comments and we can merge.

bobbinth · 2024-01-10T17:59:02Z

docs/src/intro/usage.md

@@ -62,7 +62,7 @@ Similar to Metal acceleration, SVE/AVX2 acceleration is currently applicable onl
 ### Running Miden VM
 Once the executable has been compiled, you can run Miden VM like so:
 ```
-./target/optimized/miden [subcommand] [parameters]
+[level] ./target/optimized/miden [subcommand] [parameters]


I would roll back this change.

bobbinth · 2024-01-10T18:23:47Z

docs/src/intro/usage.md

@@ -83,6 +83,12 @@ For example:
 ./target/optimized/miden prove --help
 ```

+It is possible to specify the logging level at the beginning of the script. To set the level the value of the `MIDEN_LOG` environment variable should be specified. For example:


I would put a a sub-header above this and change the text as follows:

#### Enabling logging You can use `MIDEN_LOG` environment variable to control how much logging output the VM produces. For example:

Fumuran requested a review from bobbinth November 6, 2023 20:25

Fumuran linked an issue Nov 6, 2023 that may be closed by this pull request

Warn of unused imports #515

Closed

Fumuran force-pushed the andrew-assembler-logging branch from 92c2f9b to 9559364 Compare November 6, 2023 20:42

bobbinth requested changes Nov 8, 2023

View reviewed changes

miden/src/cli/prove.rs Outdated Show resolved Hide resolved

assembly/src/ast/mod.rs Outdated Show resolved Hide resolved

miden/src/cli/data.rs Outdated Show resolved Hide resolved

assembly/src/assembler/mod.rs Outdated Show resolved Hide resolved

miden/src/main.rs Show resolved Hide resolved

Fumuran force-pushed the andrew-assembler-logging branch from 9559364 to c27c5fc Compare November 13, 2023 21:33

Fumuran force-pushed the andrew-assembler-logging branch 2 times, most recently from 171259a to b9906a3 Compare November 20, 2023 15:27

Fumuran requested a review from bobbinth November 20, 2023 16:15

Fumuran force-pushed the andrew-assembler-logging branch from b9906a3 to 33e7e20 Compare November 22, 2023 13:32

Fumuran force-pushed the andrew-assembler-logging branch from 33e7e20 to 035511b Compare December 11, 2023 13:07

bobbinth requested changes Dec 12, 2023

View reviewed changes

bobbinth reviewed Dec 13, 2023

View reviewed changes

miden/src/cli/prove.rs Outdated Show resolved Hide resolved

Fumuran force-pushed the andrew-assembler-logging branch from 035511b to cd2aa78 Compare December 14, 2023 15:24

Fumuran force-pushed the andrew-assembler-logging branch from cd2aa78 to 2fbf62d Compare December 14, 2023 15:30

Fumuran requested a review from bobbinth December 14, 2023 15:39

Fumuran force-pushed the andrew-assembler-logging branch from c149976 to 8735dde Compare December 26, 2023 20:51

bobbinth reviewed Dec 27, 2023

View reviewed changes

assembly/Cargo.toml Outdated Show resolved Hide resolved

processor/Cargo.toml Outdated Show resolved Hide resolved

assembly/src/library/path.rs Outdated Show resolved Hide resolved

Fumuran force-pushed the andrew-assembler-logging branch 2 times, most recently from d034374 to 6f73999 Compare January 9, 2024 22:41

Fumuran requested a review from bobbinth January 9, 2024 23:27

bobbinth approved these changes Jan 10, 2024

View reviewed changes

bobbinth reviewed Jan 10, 2024

View reviewed changes

verifier/Cargo.toml Outdated Show resolved Hide resolved

Fumuran force-pushed the andrew-assembler-logging branch from 6f73999 to 1d4cabd Compare January 10, 2024 13:17

Fumuran force-pushed the andrew-assembler-logging branch 4 times, most recently from 72c366c to 9c30144 Compare January 10, 2024 17:54

bobbinth approved these changes Jan 10, 2024

View reviewed changes

feat: add Tracing logger to the VM

124e026

Fumuran force-pushed the andrew-assembler-logging branch from 9c30144 to 124e026 Compare January 10, 2024 18:47

Fumuran merged commit 78608e5 into next Jan 10, 2024
15 checks passed

Fumuran deleted the andrew-assembler-logging branch January 10, 2024 19:02

Fumuran mentioned this pull request Jan 10, 2024

Add logging to the assembler #1106

Closed

bobbinth mentioned this pull request Jan 11, 2024

Warn of unused imports #515

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add logging to the assembler #1139

Add logging to the assembler #1139

Fumuran commented Nov 6, 2023 •

edited

Loading

bobbinth left a comment

Fumuran commented Nov 10, 2023

Fumuran commented Nov 20, 2023

Fumuran commented Nov 20, 2023

bobbinth left a comment

Fumuran commented Dec 14, 2023

Fumuran commented Dec 26, 2023

bobbinth left a comment

bobbinth commented Dec 27, 2023

Fumuran commented Jan 9, 2024

bobbinth left a comment

bobbinth left a comment

bobbinth Jan 10, 2024

bobbinth Jan 10, 2024

Add logging to the assembler #1139

Add logging to the assembler #1139

Conversation

Fumuran commented Nov 6, 2023 • edited Loading

bobbinth left a comment

Choose a reason for hiding this comment

Fumuran commented Nov 10, 2023

Fumuran commented Nov 20, 2023

Fumuran commented Nov 20, 2023

bobbinth left a comment

Choose a reason for hiding this comment

Fumuran commented Dec 14, 2023

Fumuran commented Dec 26, 2023

bobbinth left a comment

Choose a reason for hiding this comment

bobbinth commented Dec 27, 2023

Fumuran commented Jan 9, 2024

bobbinth left a comment

Choose a reason for hiding this comment

bobbinth left a comment

Choose a reason for hiding this comment

bobbinth Jan 10, 2024

Choose a reason for hiding this comment

bobbinth Jan 10, 2024

Choose a reason for hiding this comment

Fumuran commented Nov 6, 2023 •

edited

Loading