Code timing instrumentation

[jon-chuang]

I think it would be nice to have a feature that when activated, will print out the timings for various sub-procedures. A nice standardised format for printing the name of the function and the line numbers could be nice.

When the feature is not activated, this code is not compiled.

The thing I find most annoying is uninstrumenting code, only to discover I want to look at some sub function timings, and I have to reinstrument the code...

[jon-chuang]

Will be included in celo-org/zexe#4 with the following interface:

    let now = timing!();
    dlsd_radixsort(bucket_positions, 8);
    timing_println!(now, "radixsort");

and following output:
--features "timing"

[ radixsort ] 2168us

--features "timing_detailed"

batch_bucketed_add in bucketed_add.rs 50:51 [ radixsort ] 11532us

[jon-chuang]

Code uses macros:

#[macro_export]
macro_rules! timing_println {
    ($now: ident, $string: expr) => {
        #[cfg(feature = "timing")]
        {
            println!("[ {} ] {}us", $string, $now.1.elapsed().as_micros(),);
        }

        #[cfg(feature = "timing_detailed")]
        {
            macro_rules! function {
                () => {{
                    fn f() {}
                    fn type_name_of<T>(_: T) -> &'static str {
                        core::any::type_name::<T>()
                    }
                    let name = type_name_of(f);
                    &name[..name.len() - 3]
                }};
            }
            println!(
                "{} in {} {}:{} [ {} ] {}us",
                String::from(function!()).split("::").last().unwrap(),
                String::from(file!()).split("/").last().unwrap(),
                $now.0,
                line!() - 1,
                $string,
                $now.1.elapsed().as_micros(),
            );
        }
    };
}

#[macro_export]
macro_rules! timing {
    () => {{
        #[cfg(any(feature = "timing", feature = "timing_detailed"))]
        let now = (line!(), std::time::Instant::now());

        #[cfg(not(any(feature = "timing", feature = "timing_detailed")))]
        let now = ();
        now
    }};
}

[jon-chuang]

The next step is to use proc macros to define which specific invocation of a function ought to compile with timing instrumentation using an attribute like

#[timing(on)]
batch_affine_add(..)

#[timing(off)]
batch_affine_double(..)

[Pratyush]

This already exists with the bench-utils crate

[jon-chuang]

Hmm I see. Thats cool. I will work on mine a bit and see if we can combine some features. One thing I can do is to identify the function in which the timer is called, so that one can blacklist functions from emiting log msgs

[Pratyush]

Longer term I plan to move to infrastructure based on tracing, which would allow similar blacklisting (and has many more features to boot!)

[jon-chuang]

Hmm looks really interesting, looking forward to using tracing!