feat(logging): add extended log filtering

[cagatay-y]

The new environment variable HERMIT_LOG_EXTENDED_FILTER allows log
filters of different levels to be applied on a per module basis. It also
allows filtering by regex.

The new filter depends on the env_filter crate that was originally developed for the env_logger crate. Given it is from the Rust CLI WG and the crate is not particularly big I think it is a reasonable inclusion. Alternatively, we can consider parsing the filter ourselves. The PR currently enables the regex filter from the crate. Since it pulls in a larger crate with it, we may consider disabling that. Lastly, we can also consider making the whole thing an optional feature. I wanted to go with the simplest proof of concept for now.

Some changes were needed to the env_filter crate for it to work with no_std. I think they are non-intrusive enough to be acceptable for the upstream.

The PR also includes changes to things that I noticed while reading the module.

[github-actions]

Benchmark Results

Details

Benchmark	Current: 5282a6a	Previous: 977c7aa	Performance Ratio
startup_benchmark Build Time	90.88 s	87.35 s	1.04 ❗
startup_benchmark File Size	0.84 MB	0.75 MB	1.11 ❗
Startup Time - 1 core	0.79 s (±0.04 s)	0.79 s (±0.03 s)	1.00
Startup Time - 2 cores	0.81 s (±0.03 s)	0.79 s (±0.03 s)	1.02
Startup Time - 4 cores	0.80 s (±0.03 s)	0.81 s (±0.02 s)	0.99
multithreaded_benchmark Build Time	86.09 s	88.73 s	0.97 ❗
multithreaded_benchmark File Size	0.92 MB	0.85 MB	1.08 ❗
Multithreaded Pi Efficiency - 2 Threads	90.19 % (±8.43 %)	86.18 % (±6.26 %)	1.05
Multithreaded Pi Efficiency - 4 Threads	45.59 % (±3.49 %)	45.00 % (±3.06 %)	1.01
Multithreaded Pi Efficiency - 8 Threads	26.03 % (±1.89 %)	25.97 % (±1.90 %)	1.00
micro_benchmarks Build Time	93.74 s	97.16 s	0.96 ❗
micro_benchmarks File Size	0.93 MB	0.86 MB	1.08 ❗
Scheduling time - 1 thread	70.71 ticks (±5.02 ticks)	69.04 ticks (±3.62 ticks)	1.02
Scheduling time - 2 threads	39.26 ticks (±4.79 ticks)	37.13 ticks (±3.83 ticks)	1.06
Micro - Time for syscall (getpid)	2.91 ticks (±0.22 ticks)	2.95 ticks (±0.27 ticks)	0.99
Memcpy speed - (built_in) block size 4096	82566.56 MByte/s (±57089.11 MByte/s)	75664.19 MByte/s (±52406.71 MByte/s)	1.09
Memcpy speed - (built_in) block size 1048576	29998.62 MByte/s (±24448.46 MByte/s)	30853.09 MByte/s (±25355.22 MByte/s)	0.97
Memcpy speed - (built_in) block size 16777216	28569.90 MByte/s (±23575.85 MByte/s)	22556.98 MByte/s (±18789.09 MByte/s)	1.27
Memset speed - (built_in) block size 4096	82654.46 MByte/s (±57155.61 MByte/s)	75313.99 MByte/s (±52155.50 MByte/s)	1.10
Memset speed - (built_in) block size 1048576	30757.87 MByte/s (±24886.53 MByte/s)	31621.45 MByte/s (±25786.30 MByte/s)	0.97
Memset speed - (built_in) block size 16777216	29342.10 MByte/s (±24026.00 MByte/s)	23322.73 MByte/s (±19354.13 MByte/s)	1.26
Memcpy speed - (rust) block size 4096	70910.05 MByte/s (±49851.81 MByte/s)	67665.40 MByte/s (±47205.94 MByte/s)	1.05
Memcpy speed - (rust) block size 1048576	29938.31 MByte/s (±24458.62 MByte/s)	30555.78 MByte/s (±25106.83 MByte/s)	0.98
Memcpy speed - (rust) block size 16777216	28373.88 MByte/s (±23397.25 MByte/s)	24353.42 MByte/s (±20250.39 MByte/s)	1.17
Memset speed - (rust) block size 4096	71645.10 MByte/s (±50352.30 MByte/s)	67852.68 MByte/s (±47325.77 MByte/s)	1.06
Memset speed - (rust) block size 1048576	30694.53 MByte/s (±24900.24 MByte/s)	31300.15 MByte/s (±25521.14 MByte/s)	0.98
Memset speed - (rust) block size 16777216	29162.13 MByte/s (±23866.28 MByte/s)	25023.27 MByte/s (±20666.83 MByte/s)	1.17
alloc_benchmarks Build Time	92.69 s	93.13 s	1.00 ❗
alloc_benchmarks File Size	0.91 MB	0.82 MB	1.10 ❗
Allocations - Allocation success	100.00 %	100.00 %	1
Allocations - Deallocation success	100.00 %	100.00 %	1
Allocations - Pre-fail Allocations	100.00 %	100.00 %	1
Allocations - Average Allocation time	7990.83 Ticks (±120.28 Ticks)	6015.92 Ticks (±68.06 Ticks)	1.33 ❗
Allocations - Average Allocation time (no fail)	7990.83 Ticks (±120.28 Ticks)	6015.92 Ticks (±68.06 Ticks)	1.33 ❗
Allocations - Average Deallocation time	1322.23 Ticks (±177.51 Ticks)	1322.04 Ticks (±90.21 Ticks)	1.00
mutex_benchmark Build Time	92.20 s	89.96 s	1.02 ❗
mutex_benchmark File Size	0.93 MB	0.86 MB	1.08 ❗
Mutex Stress Test Average Time per Iteration - 1 Threads	13.14 ns (±0.72 ns)	12.86 ns (±0.72 ns)	1.02
Mutex Stress Test Average Time per Iteration - 2 Threads	23.58 ns (±16.47 ns)	15.08 ns (±8.18 ns)	1.56

This comment was automatically generated by workflow using github-action-benchmark.

[mkroening]

Thanks for working on this. I've been wanting to use env_logger for a long time. It's great that you chose to tackle this! :)

I did not have a look at the code yet but wanted to propose a different set of environment variables:

• The run-time environment variable HERMIT_LOG controls the logging. This works exactly like env_logger's RUST_LOG.
• The build-time environment variable HERMIT_LOG_DEFAULT controls the default value of HERMIT_LOG if it is not set at runtime. HERMIT_LOG_LEVEL_FILTER is a deprecated alias to this. This should be backwards compatible if I am not mistaken.
• The build-time environment variable HERMIT_LOG_STATIC_MAX_LEVEL sets the corresponding log crate features via xtask to properly avoid any runtime overhead of statically excluded log levels.

This is a long-term plan, though and should be worked towards in small PRs. What are you thoughts on this proposal?

[cagatay-y]

I wanted to keep the existing filter so that we are able to avoid the costs associated with the filter look-up when finer grained filters are not in use. We may need to profile in order to see if it actually would be a problem. For the rest of the proposal, they make sense to me but if I understand correctly they are mostly in addition to using the env_logger filters, right?

[mkroening]

I wanted to keep the existing filter so that we are able to avoid the costs associated with the filter look-up when finer grained filters are not in use. We may need to profile in order to see if it actually would be a problem.

We should use HERMIT_LOG to set_max_level as env_logger does: rust-cli/env_logger/src/logger.rs#L505

That way, we should have the exact same performance as before. And HERMIT_LOG_STATIC_MAX_LEVEL should give us a performance or size improvement when used.

For the rest of the proposal, they make sense to me but if I understand correctly they are mostly in addition to using the env_logger filters, right?

If I understood correctly, HERMIT_LOG_EXTENDED_FILTER would become HERMIT_LOG_DEFAULT. Logically, HERMIT_LOG would be the base variable, but HERMIT_LOG_DEFAULT should be easy to add on top. HERMIT_LOG_STATIC_MAX_LEVEL would be completely separate.

Does this make sense?