Measures impact of fancy timestamps in logging

log_timestamp_perf.c

/*
gtd format: ss:usec  ... raw time of day format .. difficult to read .. 
whitefield format: ss:ms .. eases timestamp reading cuz ms format used
cooja format: hh:mm:ss.ms ... most easiest to read

./a.out 7 // show sample test of all timestamps with print
./a.out 1 1 // perf-test gettimeofday only
./a.out 2 1 // perf-test whitefield style
./a.out 4 1 // perf-test cooja style

---------[Performance data]-----------------------------
# cooja style
❯ for ((i=0; i< 5; i++)); do time ./a.out 4 1; done 
./a.out 4 1  32.91s user 0.00s system 96% cpu 33.927 total
./a.out 4 1  37.63s user 0.00s system 97% cpu 38.632 total
./a.out 4 1  37.50s user 0.00s system 97% cpu 38.496 total
./a.out 4 1  37.51s user 0.00s system 97% cpu 38.511 total
./a.out 4 1  37.50s user 0.01s system 97% cpu 38.542 total

# raw gettimeofday
❯ for ((i=0; i< 5; i++)); do time ./a.out 1 1; done
./a.out 1 1  21.83s user 0.01s system 95% cpu 22.863 total
./a.out 1 1  23.98s user 0.00s system 95% cpu 24.985 total
./a.out 1 1  24.53s user 0.00s system 95% cpu 25.564 total
./a.out 1 1  24.93s user 0.00s system 96% cpu 25.928 total
./a.out 1 1  24.36s user 0.00s system 96% cpu 25.361 total

# Whitefield style
❯ for ((i=0; i< 5; i++)); do time ./a.out 2 1; done
./a.out 2 1  23.04s user 0.00s system 95% cpu 24.040 total
./a.out 2 1  26.27s user 0.02s system 96% cpu 27.299 total
./a.out 2 1  27.05s user 0.00s system 96% cpu 28.055 total
./a.out 2 1  26.49s user 0.00s system 96% cpu 27.493 total
./a.out 2 1  27.23s user 0.00s system 96% cpu 28.237 total

--------------------------------------------------------------
Findings:
Whitefield format introduces marginal processing overhead 17% that of gtd.
Cooja introduces significant overhead more than 60% that of gtd.

However, Cooja style is definitely more fancy and easy to read format.

Notes:
1. calling gettimeofday by itself is not costly because of vdso syscall.
2. the overhead might still be marginal in the grand scheme of your application.
3. overhead might be even more higher when combined with real-world application because 
   cooja-style introduces additional processing impacting cache-lines.
4. the time output shows that the overhead is pure-cpu
*/

#include <stdio.h>
#include <stdint.h>
#include <stdlib.h>
#include <unistd.h>
#include <sys/time.h>

#define ms2hh 3600000 // (60*60*1000)
#define ms2mm 60000   // (60*1000)
#define ms2ss 1000

#define USE_GTD (1<<0)   // default gettimeofday ss:usec
#define USE_WF  (1<<1)   // whitefield style> ss:ms ... ss and ms are rounded down
#define USE_CJ  (1<<2)   // cooja style>>  hh:mm:ss.ms

int do_print = 1;
int use = USE_GTD | USE_WF | USE_CJ;

struct timeval stv;

static inline void gtd(struct timeval *tv)
{
    if(do_print)
        printf("Normally(sec:usec) %6ld:%ld\n", tv->tv_sec, tv->tv_usec);
}

static inline void wf_gtd(struct timeval *tv)
{
    uint32_t ss, ms;

    ss = tv->tv_sec % 100000;
    ms = tv->tv_usec / 1000;
    if(do_print)
        printf("Whitefield(sec:msec) %u:%u\n", ss, ms);
}

static inline void cj_gtd(struct timeval *tv)
{
    uint32_t ms;    // will overflow in 49 days
    uint32_t hh, mm, ss;

    ms = ((tv->tv_sec - stv.tv_sec) * 1000) + ((tv->tv_usec - stv.tv_usec) / 1000);
    hh = ms / (ms2hh); ms = ms % (ms2hh);
    mm = ms / (ms2mm); ms = ms % (ms2mm);
    ss = ms / (ms2ss); ms = ms % (ms2ss);
    if(do_print)
        printf("Cooja(hh:mm:ss.msec) %02u:%02u:%02u.%03u\n", hh, mm, ss, ms);
}

void test(void)
{
    struct timeval tv;

    gettimeofday(&tv, NULL);

    if (use & USE_GTD)
        gtd(&tv);
    if (use & USE_WF)
        wf_gtd(&tv);
    if (use & USE_CJ)
        cj_gtd(&tv);
}

void perf_test(void)
{
    uint32_t i;

    do_print = 0;
    for(i = 0; i < 0x3fffffff; ++i) {
        test();
    }
}

int main(int argc, char *argv[])
{
    gettimeofday(&stv, NULL);
    sleep(1);
    if(argc > 1) {
        use = atoi(argv[1]);
    }
    if (argc > 2) {
        perf_test();
    } else {
        test();
    }
    return 0;
}