format user counter as timing information

[Jerry-Ma]

Hi,

I would like to add some more timings to the output, so I added some user counters, and in the function to be benchmarked, I record some timing information for certain block of code.

The output looks like:

--------------------------------------------------------------------------------------------------------------------------
Benchmark                                               Time             CPU   Iterations        cor        eig        reg
--------------------------------------------------------------------------------------------------------------------------
spectra/10/40/2/2/process_time/real_time            0.012 ms        0.012 ms        63176   1.56285m    7.6555m   994.525u
spectra/10/40/2/4/process_time/real_time            0.016 ms        0.017 ms        41991   1.55633m  0.0126054   1018.47u
spectra/10/40/2/6/process_time/real_time            0.022 ms        0.022 ms        32986   1.56102m  0.0183076   1019.17u
spectra/10/40/2/8/process_time/real_time            0.028 ms        0.028 ms        25630    1.5661m  0.0236718    1021.9u
spectra/10/40/2/10/process_time/real_time           0.034 ms        0.034 ms        20381   1.53995m   0.029994   997.325u

As it shows, the custom counter values are shown as counts, which are not intuitive. I think it would be good to introduce a flag to format the counter as timing, and output in the same format and unit as the Time and CPU section.

[dmah42]

Can you share the benchmark code?

I'm curious if you should be using 'manual timing' instead of user counters.

On Wed, Jun 12, 2019 at 2:46 PM Jerry-Ma notifications@github.com wrote:

Hi,

I would like to add some more timings to the output, so I added some user counters, and in the function to be benchmarked, I record some timing information for certain block of code.

The output looks like:

---

Benchmark Time CPU Iterations cor eig reg

spectra/10/40/2/2/process_time/real_time 0.012 ms 0.012 ms 63176 1.56285m 7.6555m 994.525u spectra/10/40/2/4/process_time/real_time 0.016 ms 0.017 ms 41991 1.55633m 0.0126054 1018.47u spectra/10/40/2/6/process_time/real_time 0.022 ms 0.022 ms 32986 1.56102m 0.0183076 1019.17u spectra/10/40/2/8/process_time/real_time 0.028 ms 0.028 ms 25630 1.5661m 0.0236718 1021.9u spectra/10/40/2/10/process_time/real_time 0.034 ms 0.034 ms 20381 1.53995m 0.029994 997.325u

As it shows, the custom counter values are shown as counts, which are not intuitive. I think it would be good to introduce a flag to format the counter as timing, and output in the same format and unit as the Time and CPU section.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/google/benchmark/issues/831?email_source=notifications&email_token=AAD4QMUPVTX4Z63ERJM3O7DP2D44PA5CNFSM4HXJFD62YY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4GZCFPYA, or mute the thread https://github.com/notifications/unsubscribe-auth/AAD4QMSB7P5K3A5TLEAZCJDP2D44PANCNFSM4HXJFD6Q .

[Jerry-Ma]

template <pca::Backend backend>
void BM_pca(benchmark::State &state, int cidx) {

    SPDLOG_DEBUG("run clean with {}", backend);
    state.SetComplexityN(state.range(cidx));

    Eigen::Index nt = state.range(0); // nsamples
    Eigen::Index nd = state.range(1); // ndetectors
    Eigen::Index nc = state.range(2); // neigtocut
    Eigen::MatrixXd ptcdata(nt, nd);
    ptcdata.setRandom();

    auto clean = [&]() {
        using Clean = typename pca::Clean_t<backend>::type;
        if constexpr (backend == pca::Backend::spectra) {
            int ne = state.range(3); // neigtocalc for spectra backend
            return Clean(ne);
        } else {
            return Clean();
        }
    }();

    // stores some extra timing
    std::vector<double> timer{clean.timer};
    // start bench
    for (auto _ : state) {
        // bench
        clean.run(ptcdata, nc);
        // accumulate the timings
        state.PauseTiming();
        std::transform(clean.timer.begin(), clean.timer.end(), timer.begin(),
                       timer.begin(), std::plus<double>());
        state.ResumeTiming();
    }
    // setup counters
    for (std::size_t i = 0; i < clean.timer_names.size(); ++i) {
        state.counters[clean.timer_names[i]] =
            benchmark::Counter(timer[i], benchmark::Counter::kAvgIterations);
    }
}

My current counter approach is to setup a timer member (a vector of doubles) to the clean functor, which are populated after clean.run() call.

I checked the manual timing example, but it seems that it does not produce more timings, but just to control the existing single timing.

[LebedevRI]

I suspect this is yet another example that actual custom timers are needed.

[dmah42]

Was this resolved with the addition of kIsRate to the benchmark::Counter enum?