Measuring time spent between two points in code

I'm working on a project where I'm instrumenting how long it takes to get from one point in my code to another. I've written an LLVM pass that instruments the IR with calls to a simple timing library I've written. Each point is identified by a 64-bit randomly-generated unique identifier.

Unfortunately, I'm spending a lot of time in the library, so I'm trying to decrease the amount of work done as much as possible. I'm using UTHash for fast accesses/insertions, and I'm preallocating my structs as much as possible.

Does anyone else see any way to speed up the log_point function especially? I need it to be portable across architectures (ARM, x86, PowerPC), hence the expensive call to clock_gettime, but any Linux/POSIX ideas are valid.

Library was compiled using Clang/LLVM 4.0.0, with -O3 optimizations.

#include <inttypes.h>
#include <stdbool.h>
#include <stdint.h>
#include <stdio.h>
#include <stdlib.h>
#include <time.h>

#include "uthash.h"

#include "timing.h"

/*********************************
* Path structures
*********************************/
typedef struct _path_key {
uint64_t    start;  // Starting point
uint64_t    end;    // Ending point
} path_key_t;

typedef struct _path {
path_key_t  key;    // Key

uint64_t    time;   // Total time spent on path
uint64_t    count;  // Number of times path taken

UT_hash_handle hh;
} path_t;

/*********************************
* Global values
*********************************/
#define NUM_PATHS_PREALLOCATED 1024

path_t         *log_;

path_t         *preallocated;
unsigned int    num_paths_available;
unsigned int    num_paths_used;

uint64_t        last_uid;
uint64_t        last_timestamp;

bool            last_uid_initialized;

/*********************************
* Initialize global values
*********************************/
void
initialize_log(void)
{
log_                 = NULL;
last_uid             = 0;
last_timestamp       = 0;
last_uid_initialized = false;

preallocated = malloc(sizeof *preallocated * NUM_PATHS_PREALLOCATED);
if (!preallocated)
exit(EXIT_FAILURE);
num_paths_available = NUM_PATHS_PREALLOCATED;
num_paths_used      = 0;
}

/*********************************
* Log an instrumented code point
*********************************/
void
log_point(uint64_t cur_uid)
{
struct timespec     t;
uint64_t            cur_timestamp;

clock_gettime(CLOCK_MONOTONIC_RAW, &t);
cur_timestamp = (uint64_t)(t.tv_sec * 1000000000 + t.tv_nsec);

if (last_uid_initialized) {
path_t target, *path;

memset(&target, 0, sizeof(target));
target.key.start = last_uid;
target.key.end   = cur_uid;

HASH_FIND(hh, log_, &target.key, sizeof(path_key_t), path);
if (path) {
path->time += (cur_timestamp - last_timestamp);
path->count++;
}
else {
/* Might need to reallocate if all of the preallocated paths used */
if (num_paths_used == num_paths_available) {
path_t *tmp = NULL;
HASH_CLEAR(hh, log_);
num_paths_available *= 2;
tmp = realloc(preallocated,
sizeof *preallocated * num_paths_available);
if (!tmp) {
free(preallocated);
exit(EXIT_FAILURE);
}
else {
preallocated = tmp;
/* Have to re-add all paths to hash table, as the
* addresses changed during realloc */
for (unsigned int i = 0; i < num_paths_used; ++i) {
path = &preallocated[i];
}
}
}
path = &preallocated[num_paths_used++];
path->key.start = last_uid;
path->key.end   = cur_uid;
path->time      = cur_timestamp - last_timestamp;
path->count     = 1;
}
}
else {
last_uid_initialized = true;
}

last_uid       = cur_uid;
last_timestamp = cur_timestamp;
}

/*********************************
* Dump the log to a file
*********************************/
void
dump_log(void)
{
FILE   *outfile = NULL;

if (!(outfile = fopen("./times.txt", "w"))) {
fprintf(stderr, "Error: could not open output file\n");
return;
}

fprintf(outfile, "start,end,avg_time,count\n");

path_t *path, *tmp;
HASH_ITER(hh, log_, path, tmp) {
fprintf(outfile, "%"PRIu64",%"PRIu64",",
path->key.start,
path->key.end);
fprintf(outfile, "%f,%"PRIu64"\n",
path->time / ((float)path->count),
path->count);
HASH_DEL(log_, path);
}

free(preallocated);

fclose(outfile);
}


Some simple benchmarks generated using the FT benchmark of the NASA Parallel Benchmarks (all times in seconds):

Class              S               W               A
---------------------------------------------------------------
vanilla            0.153           0.280           3.973
instrumented       2.876           6.381         112.487
---------------------------------------------------------------
slowdown          ~18.8x          ~22.8x          ~28.3x


I'd really like to improve those slowdowns if possible.

#include <stdint.h>

void intialize_log(void);
void log_EP(uint64_t);
void dump_log(void) __attribute__((destructor));


Let's look at the current code. Couldn't we do a usermode request for TSC more cheaply than a gettime?

clock_gettime(CLOCK_MONOTONIC_RAW, &t);


Then you would mostly be manipulating time deltas in inconvenient units related to clock rate, which occasionally varies to save power. The object would be to call gettime a few orders of magnitude less often, and use those few calls to convert TSC cycles into S.I. seconds.

On a different topic, programs have locality of reference, which caches exploit. I'm sad that this line has poor locality of reference:

    HASH_FIND(hh, log_, &target.key, sizeof(path_key_t), path);


Instead of 64-bit GUIDs, could you maybe use sequentially assigned IDs, and probe a binary tree instead of a hash map? Consider instrumentation points P1 & P2 that are near one another in the code, perhaps in the same loop. My goal for speed is to get the P1 lookup to use the same cache line as the P2 lookup.

I hope you verified that the "/* Might need to reallocate if all of the preallocated paths used */" code uses few cycles as it is seldom run. But I wonder, could you make it disappear completely? Maybe deal with it at compile time, bump up the number of preallocated tags, or explicitly switch from preallocated "phase1 tags" to "phase2 tags" when the target app switches from, say, initialization phase to some heavy looping phase. Maybe view tags as hierarchical, based on return addresses that a program location typically sees in the stack frames above it. Then use the hierarchy to define phases and for switching to tags used during each phase.

I think you used a limited number of tags because you wanted to limit cache thrashing effects, but it would be helpful if you could explicitly comment on such design decisions. Let's ignore for the moment the use of an ordered heap or multi-level tags to reduce footprint. Let's instead suppose that we're willing to store all possible tags in a "large" hash map. Now, to exploit locality, could we maybe have a "small" to "large" 2-level app-layer cache, with the goal of again getting P1 & P2's tags near one another? Or could we maybe frontend the "large" cache with an LRU that reorganizes tags to group P1 & P2 together?

• I looked into using Intel's RDTSC command, but it's not portable to ARM or Power8 (which is a necessity). I suppose I could look into using their built-in timers, but that gets very messy very quickly in my (admittedly limited) experience. – tonysdg Sep 1 '17 at 17:51
• I also originally tried the sequentially assigned IDs with a simple 2-dimensional array of objects -- that allowed me to directly index into the array -- but for multi-file programs, the LLVM pass is reset between files (as each file is compiled using a separate instance/process of the compiler). The only thing I could think of was maybe creating a (hard-coded yet temporary) file where I store the last used ID between compilations, but that seemed clunky and error-prone, so the hash table seemed most appropriate. – tonysdg Sep 1 '17 at 17:54
• Without a temp file, you could e.g. use hash of source file path to come up with a tag prefix. One possible organization is to use that prefix to probe a hash map, and the result gives you all tags corresponding to that source file. That would certainly encourage locality, as "near" P1 & P2 code locations will often occur in the same source file. – J_H Sep 1 '17 at 18:24
• You might have port-specific #ifdef'd code that uses Intel's RDTSC, if only to help you quantify how much that gettime call is costing you, relative to the rest of your code. – J_H Sep 1 '17 at 18:25
• Wanted to let you know I ended up going the per-arch route. Seems to work well enough for x86 and ARM right now; will have to test ppc64le at another time. Thanks again! – tonysdg Sep 1 '17 at 23:54

Bug:

Conversion to uint64_t may be too late to prevent overflow. Perhaps code works for OP as t.tv_sec may be 64-bit. Yet in general, it may be narrower.

// (uint64_t)(t.tv_sec * 1000000000 + t.tv_nsec);
(uint64_t)t.tv_sec*1000000000 + t.tv_nsec;


Pedantically, t.tv_sec may have a negative value,

(int64_t)t.tv_sec*1000000000 + t.tv_nsec;


Not enough of code visible to suggest performance improvements.

• What else would you need to see to be able to suggest performance improvements? (Not meant as a challenge, just curiosity so I can improve the question.) That's the entire library file -- there's a 6-line header file that goes with it, but I'm not sure what else I can provide without adding in my LLVM pass and instructions for compiling/using everything (which I don't think is what CodeReview S.E. is for). – tonysdg Sep 1 '17 at 18:52
• @tonysdg At least: provide timing.h, declaration of hh, key. I am especially interested in how the hash code handles collisions (performance issue). These minor things prevent compiling (not worried about linking) and the use of automated tools. – chux Sep 1 '17 at 19:01
• Will providing a link to the definition of hh suffice? It's not my code (though it's licensed with a BSD-license), so I'm hesitant to just post it. key refers to the path_key_t struct shown. I'll add timing.h. – tonysdg Sep 1 '17 at 19:09
• For reference, I'm using the fairly well-known (I think) uthash library. It reminds me a lot of the hash table structure in the Linux kernel. – tonysdg Sep 1 '17 at 19:13
• @tonysdg To be clear key appears to be an undeclared variable in HASH_ADD(hh, log_, key, sizeof(path_key_t), path); and not a reference to path_key_t – chux Sep 1 '17 at 19:30

an LLVM pass that instruments the IR

Very cool!

Rather than calling your routine every time, maybe you could generate inline code that unconditionally appends an (id, tsc) tuple to a circular buffer? And then, much less frequently than you do now, generate a call to unconditionally empty the buffer, probing the hash table for 64-bit IDs and computing deltas on the Time Stamp Counters. You would have to be able to reason about how many iterations a worst case loop could execute, and generate conditional "should we drain the buffer?" tests often enough to avoid overrun. Alternatively, rather than prove theorems you could just wave your hand saying "next run will be similar to previous historical run" for which you have (expensive) detailed instrumentation on how full the buffer gets, and for a production run you emit different code that relies on the historic pattern plus a safety margin to avoid conditionals within tight loops.