panics on versions 0.7 and latest main (0.7.2)

[dpastoor]

Hi - interesting package!

when trying to run on an ubuntu 22.04 LTS x64 server, i am getting the following for any command i attempt to run. I tried both a crates.io install (0.7.0) and just installed from tip to the same effect:

❯ RUST_BACKTRACE=1 ./target/release/intentrace ls
thread 'main' panicked at src/utilities.rs:270:33:
called `Option::unwrap()` on a `None` value
stack backtrace:
   0: rust_begin_unwind
   1: core::panicking::panic_fmt
   2: core::panicking::panic
   3: core::option::unwrap_failed
   4: std::thread::local::LocalKey<T>::try_with
   5: intentrace::one_line_formatter::<impl intentrace::syscall_object::SyscallObject>::one_line_formatter
   6: intentrace::syscall_returned
   7: intentrace::main
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
Cargo.lock  Cargo.toml  intentrace-example.jpg  intentrace-example.png  itrace.png  LICENSE  README.md  src  target

[sectordistrict]

Just tested on the latest commit and a crates.io install, can't seem to replicate, I'm using Ubuntu 24.04 (x86-64)

[tanculau]

Can reproduce

Step 1: use vm (I use Gnome Boxes)
Step 2: Install ubuntu 22.04 LTS x64 server with minimal and no extra features (If you use Gnome Boxes, use the search function)
Step 3: sudo apt install build-essential
Step 4: curl --proto '=https' --tlsv1.2 -sSf https://sh.rustup.rs | sh (everything default)
Step 5: cargo install intentrace
Step 6: intentrace ls
Step 7: crash

[sectordistrict]

I believe latest (6645147) should fix this, it worked for my setup.

Changes pushed to 0.7.4, and available on crates.io

[tanculau]

intentrace 0.7.4 works for me now on ubuntu server

[tanculau]

Why are you using thread_local OnceCell instead of a LazyLock?
Pro:

• You don't need to remeber to init it
• Less code, get_thread_local_color!(STOPPED_COLOR) becomes *STOPPED_COLOR
• Code closer to definition, for example

pub static TERMINAL_THEME : LazyLock<termbg::Theme> = LazyLock::new(|| termbg::theme(std::time::Duration::from_millis(10)).unwrap_or(termbg::Theme::Dark));
pub static  GENERAL_TEXT_COLOR: LazyCell<CustomColor> = LazyCell::new(|| match *TERMINAL_THEME {
        termbg::Theme::Light => CustomColor { r: 64, g: 64, b: 64 },
        termbg::Theme::Dark => CustomColor { r: 160, g: 160, b: 160 },
    });

Con:

• Performance?
• The reason why you did it like that

[sectordistrict]

The reason is colors are initialized once and never modified again, so the lock overhead is unwelcome especially considering how often the colors are accessed even for one syscall line, I'd say on average it's 5x Color accesses per syscall line. I admit that "Code closer to definition" is nicer and I agree that the macro usage is not very pretty.

[tanculau]

Do you have any benchmarks for this?
Run some quick with

use core::{cell::LazyCell, hint::black_box};
use std::sync::LazyLock;

use iai_callgrind::{library_benchmark, library_benchmark_group, main};

pub static A: LazyLock<usize> = LazyLock::new(|| 12);

thread_local! {
    pub static AA : LazyCell<usize> = LazyCell::new(|| 12);
}

fn access_lock() -> usize { black_box(**black_box(&A)) }
fn access_cell() -> usize { black_box(black_box(AA.with(|v| black_box(**black_box(v))))) }

#[library_benchmark]
#[bench::short(100)]
#[bench::long(10000)]
fn lock(value: usize) {
    for _ in 0..value {
        black_box(access_lock());
    }
}
#[library_benchmark]
#[bench::short(100)]
#[bench::long(10000)]
fn cell(value: usize) {
    for _ in 0..value {
        black_box(access_cell());
    }
}

library_benchmark_group!(
    name = bench_group;
    benchmarks = lock, cell
);

main!(library_benchmark_groups = bench_group);

with iai-callgrind = "0.14.0"
and got

my_benchmark::bench_group::lock short:100
  Instructions:                        1198|N/A                  (*********)
  L1 Hits:                             1940|N/A                  (*********)
  L2 Hits:                                3|N/A                  (*********)
  RAM Hits:                              11|N/A                  (*********)
  Total read+write:                    1954|N/A                  (*********)
  Estimated Cycles:                    2340|N/A                  (*********)
my_benchmark::bench_group::lock long:10000
  Instructions:                      110098|N/A                  (*********)
  L1 Hits:                           180140|N/A                  (*********)
  L2 Hits:                                3|N/A                  (*********)
  RAM Hits:                              11|N/A                  (*********)
  Total read+write:                  180154|N/A                  (*********)
  Estimated Cycles:                  180540|N/A                  (*********)
my_benchmark::bench_group::cell short:100
  Instructions:                        2840|N/A                  (*********)
  L1 Hits:                             4557|N/A                  (*********)
  L2 Hits:                                0|N/A                  (*********)
  RAM Hits:                               6|N/A                  (*********)
  Total read+write:                    4563|N/A                  (*********)
  Estimated Cycles:                    4767|N/A                  (*********)
my_benchmark::bench_group::cell long:10000
  Instructions:                      280040|N/A                  (*********)
  L1 Hits:                           450057|N/A                  (*********)
  L2 Hits:                                0|N/A                  (*********)
  RAM Hits:                               6|N/A                  (*********)
  Total read+write:                  450063|N/A                  (*********)
  Estimated Cycles:                  450267|N/A                  (*********)

Obviously the benchmark has problems (like not init before), but it seems that thread local is slower, if I didn't make a mistake.

Also notice that the branch pred in this example has a quite easy job.

But it seems to be a premature opitimization, and (lock short:100) ~23 cycles to retrieve the value don't seem to be that bad for the performance, especially compared to writing to stdout.

[sectordistrict]

First, this is a great write up, thank you for taking the time. For the benchmarks, I notice now that your original comment didn't wrap the actual Color in LazyLock, the LazyLock was used for termbg's output, (the match statement only runs at the beginning of the program), for the colors you actually use a LazyCell, which only differs from OnceCell in initialization semantics, this was your original intent, correct?

Also, I've had thoughts of some optimization strategies in the past for this specific part of intentrace's flow, its mostly about exploiting the fact that most of the slices that get pushed into buffers are slices that won't change colors at runtime, this means we can "prepare" these slices along with their colorization prior to intentrace's run, think of something like a table this avoids the entire color-function-calling.

Also, we currently use a BufWriter, so most of these calls aren't actually writing out to stdout, the buffer is flushed only once per syscall line (the multi-threaded case is handled differently, with the only difference being that they flush twice per syscall)

[tanculau]

for the colors you actually use a LazyCell, which only differs from OnceCell in initialization semantics, this was your original intent, correct?

No, I just forgot to change it also to LazyLock, it needs to be LazyLock or the compiler should complain.

I don't think that there is a big performance gain, so I think that simplifying the code outweighs the performance hit

[sectordistrict]

To be honest performance isn't and shouldn't be that big of a priority at this stage, so I agree regardless of which implementation is faster, if you want to create a pull request, I'll merge.

Also @dpastoor, I'll close this issue as I believe the original problem was fixed

[dpastoor]

Thank you! I will give it a try in the next couple days and can reopen or file another issue if I hit another one. Much appreciate the quick turn around!

[tanculau]

Also, I've had thoughts of some optimization strategies in the past for this specific part of intentrace's flow, its mostly about exploiting the fact that most of the slices that get pushed into buffers are slices that won't change colors at runtime, this means we can "prepare" these slices along with their colorization prior to intentrace's run, think of something like a table this avoids the entire color-function-calling.

I tested with this :
valgrind --tool=callgrind --dump-instr=yes --collect-jumps=yes intentrace -q ls
Instruction count went from 7239817 to 4209468

So a speedup ~40-50%

[sectordistrict]

@tanculau I haven't sat down and read this yet as I've been very busy and this seems like a sizeable PR, but it looks very promising, and as usual thank you for the great work!

[tanculau]

In short, calling "".custom_color(..) allocates 1 String.
If you call Display, the input gets cloned one time and 3 additional (short) Strings are allocated.
With the PR, only the first allocation remains and calling Display does not allocate anymore.