feat(logging): add extented 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: 18c0fb6	Previous: 9f7322b	Performance Ratio
startup_benchmark Build Time	98.35 s	85.88 s	1.15 ❗
startup_benchmark File Size	0.82 MB	0.75 MB	1.09 ❗
Startup Time - 1 core	0.93 s (±0.04 s)	0.94 s (±0.04 s)	0.99
Startup Time - 2 cores	0.96 s (±0.03 s)	0.95 s (±0.03 s)	1.01
Startup Time - 4 cores	0.94 s (±0.02 s)	0.94 s (±0.03 s)	1.00
multithreaded_benchmark Build Time	95.38 s	88.07 s	1.08 ❗
multithreaded_benchmark File Size	0.91 MB	0.86 MB	1.07 ❗
Multithreaded Pi Efficiency - 2 Threads	88.32 % (±7.37 %)	88.63 % (±8.04 %)	1.00
Multithreaded Pi Efficiency - 4 Threads	44.46 % (±2.89 %)	43.38 % (±3.45 %)	1.03
Multithreaded Pi Efficiency - 8 Threads	25.70 % (±1.81 %)	25.20 % (±1.80 %)	1.02
micro_benchmarks Build Time	93.14 s	94.04 s	0.99 ❗
micro_benchmarks File Size	0.92 MB	0.86 MB	1.07 ❗
Scheduling time - 1 thread	68.95 ticks (±4.47 ticks)	65.35 ticks (±4.26 ticks)	1.06
Scheduling time - 2 threads	39.47 ticks (±4.96 ticks)	35.89 ticks (±3.71 ticks)	1.10
Micro - Time for syscall (getpid)	4.11 ticks (±0.58 ticks)	3.00 ticks (±0.23 ticks)	1.37 ❗
Memcpy speed - (built_in) block size 4096	66434.84 MByte/s (±47358.71 MByte/s)	65860.77 MByte/s (±46845.85 MByte/s)	1.01
Memcpy speed - (built_in) block size 1048576	29451.86 MByte/s (±24229.10 MByte/s)	29576.49 MByte/s (±24431.93 MByte/s)	1.00
Memcpy speed - (built_in) block size 16777216	28656.18 MByte/s (±23848.90 MByte/s)	28311.09 MByte/s (±23599.33 MByte/s)	1.01
Memset speed - (built_in) block size 4096	67106.28 MByte/s (±47790.62 MByte/s)	66744.29 MByte/s (±47481.33 MByte/s)	1.01
Memset speed - (built_in) block size 1048576	30242.59 MByte/s (±24680.65 MByte/s)	30393.81 MByte/s (±24910.59 MByte/s)	1.00
Memset speed - (built_in) block size 16777216	29430.80 MByte/s (±24291.66 MByte/s)	29111.57 MByte/s (±24069.85 MByte/s)	1.01
Memcpy speed - (rust) block size 4096	60155.40 MByte/s (±44366.98 MByte/s)	59011.76 MByte/s (±43397.34 MByte/s)	1.02
Memcpy speed - (rust) block size 1048576	29411.85 MByte/s (±24202.47 MByte/s)	29563.17 MByte/s (±24538.23 MByte/s)	0.99
Memcpy speed - (rust) block size 16777216	28361.75 MByte/s (±23581.30 MByte/s)	28365.88 MByte/s (±23635.44 MByte/s)	1.00
Memset speed - (rust) block size 4096	61342.22 MByte/s (±45133.14 MByte/s)	59323.20 MByte/s (±43549.67 MByte/s)	1.03
Memset speed - (rust) block size 1048576	30227.77 MByte/s (±24673.56 MByte/s)	30357.47 MByte/s (±24994.77 MByte/s)	1.00
Memset speed - (rust) block size 16777216	29146.48 MByte/s (±24035.36 MByte/s)	29162.11 MByte/s (±24104.49 MByte/s)	1.00
alloc_benchmarks Build Time	92.19 s	91.81 s	1.00 ❗
alloc_benchmarks File Size	0.89 MB	0.82 MB	1.08 ❗
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	4901.46 Ticks (±145.76 Ticks)	15902.44 Ticks (±330.83 Ticks)	0.31 ❗
Allocations - Average Allocation time (no fail)	4901.46 Ticks (±145.76 Ticks)	15902.44 Ticks (±330.83 Ticks)	0.31 ❗
Allocations - Average Deallocation time	756.14 Ticks (±51.95 Ticks)	1433.42 Ticks (±676.51 Ticks)	0.53
mutex_benchmark Build Time	91.90 s	90.98 s	1.01 ❗
mutex_benchmark File Size	0.92 MB	0.86 MB	1.07 ❗
Mutex Stress Test Average Time per Iteration - 1 Threads	12.82 ns (±0.74 ns)	13.06 ns (±0.76 ns)	0.98
Mutex Stress Test Average Time per Iteration - 2 Threads	89.96 ns (±4.28 ns)	20.38 ns (±8.77 ns)	4.41 ❗

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?