From 14df42a9949f65a1e76aca92926d11edd020cfbf Mon Sep 17 00:00:00 2001 From: Sebastian Hack Date: Mon, 10 Sep 2007 19:08:03 +0000 Subject: [PATCH] Improved statev stuff: - can zip files - can give regexes as filters - have stack based timers Rewrote python script to feed dbs: - can read zipped files - sqlite3 - mysql fast csv file import with pipes [r15731] --- ir/be/test/statev_sql.py | 16 ++- ir/stat/statev.c | 220 +++++++++++++++------------------------ ir/stat/statev.h | 106 ++++++++++++++++--- ir/stat/timing.c | 75 +++++++++++++ ir/stat/timing.h | 102 ++++++++++++++++++ 5 files changed, 365 insertions(+), 154 deletions(-) create mode 100644 ir/stat/timing.c create mode 100644 ir/stat/timing.h diff --git a/ir/be/test/statev_sql.py b/ir/be/test/statev_sql.py index 78fa7f2f2..217cbc820 100755 --- a/ir/be/test/statev_sql.py +++ b/ir/be/test/statev_sql.py @@ -124,20 +124,21 @@ class EmitSqlite3(EmitBase): self.conn.execute(self.create_table(ctxcols, 'ctx', 'text', 'unique')) self.conn.execute(self.create_table(evcols, 'ev', 'double', '')) - q = [] + n = max(len(ctxcols), len(evcols)) + 1 + q = ['?'] self.quests = [] - for i in xrange(0, max(len(ctxcols), len(evcols))): + for i in xrange(0, n): self.quests.append(','.join(q)) q.append('?') def ev(self, curr_id, evitems): keys = ','.join(evitems.keys()) - stmt = 'insert into ev (id, %s) values (%s)' % (keys, self.quests[len(evitems) + 1]) + stmt = 'insert into ev (id, %s) values (%s)' % (keys, self.quests[len(evitems)]) self.conn.execute(stmt, (curr_id,) + tuple(evitems.values())) def ctx(self, curr_id, ctxitems): keys = ','.join(ctxitems.keys()) - stmt = 'insert into ctx (id, %s) values (%s)' % (keys, self.quests[len(ctxitems) + 1]) + stmt = 'insert into ctx (id, %s) values (%s)' % (keys, self.quests[len(ctxitems)]) self.conn.execute(stmt, (curr_id,) + tuple(ctxitems.values())) def commit(self): @@ -179,6 +180,7 @@ class Conv: return fileinput.FileInput(files=self.files, openhook=fileinput.hook_compressed) def fill_tables(self): + lineno = 0 ids = 0 curr_id = 0 keystack = [] @@ -189,6 +191,7 @@ class Conv: ctxcols = dict() for line in self.input(): + lineno += 1 items = line.strip().split(';') op = items[0] @@ -210,7 +213,12 @@ class Conv: self.emit.ctx(curr_id, ctxcols) elif op == 'O': + popkey = items[1] key = keystack.pop() + + if popkey != key: + print "unmatched pop in line %d, push key %s, pop key: %s" % (lineno, key, popkey) + idstack.pop() if len(idstack) > 0: if len(evcols) > 0: diff --git a/ir/stat/statev.c b/ir/stat/statev.c index e3d694a92..3831ff3d8 100644 --- a/ir/stat/statev.c +++ b/ir/stat/statev.c @@ -32,181 +32,129 @@ #include #include #include - -#include +#include #include "util.h" -#include "hashptr.h" +#include "timing.h" #include "irprintf.h" -#include "xmalloc.h" - -#define MAX_CTX 128 - -typedef struct { - char key[32]; - char value[96]; - unsigned hash; -} ctx_t; +#include "statev.h" -static ctx_t ctx_stack[MAX_CTX]; +#ifdef HAVE_CONFIG_H +#include "config.h" +#endif -static unsigned long time_in_ev = 0; -static int ctx_sp = -1; -static FILE *file_ev = NULL; +#ifdef HAVE_REGEX_H +#define FIRM_HAVE_REGEX +#endif -static lc_timer_t *timer = NULL; +#if defined HAVE_LIBZ && defined HAVE_ZLIB_H +#define FIRM_HAVE_LIBZ +#endif -int stat_ev_enabled = 0; -typedef struct print_ev_t { - char filter[128]; - struct print_ev_t *next; -} print_ev_t; +#define MAX_TIMER 256 -static print_ev_t *print_events = NULL; -static int ctx_switch_since_last_print = 0; +#ifdef FIRM_HAVE_LIBZ +#include -#define get_time() lc_timer_elapsed_usec(timer) +#define mfprintf gzprintf +static gzFile* stat_ev_file = NULL; -void stat_ev_ctx_push(const char *key, const char *value) -{ - if (file_ev) { - unsigned long start = get_time(); - ctx_t *ctx = &ctx_stack[ctx_sp + 1]; - unsigned hash = firm_fnv_hash_str(key); +#else - hash = HASH_COMBINE(hash, firm_fnv_hash_str(value)); - if (ctx_sp >= 0) - hash = HASH_COMBINE(hash, ctx_stack[ctx_sp].hash); +#define mfprintf fprintf +static FILE* stat_ev_file = NULL; - snprintf(ctx->key, array_size(ctx->key), "%s", key); - snprintf(ctx->value, array_size(ctx->value), "%s", value); - ctx->hash = hash | 1; - ++ctx_sp; +#endif /* FIRM_HAVE_LIBZ */ - fprintf(file_ev, "P %10x %30s %30s\n", ctx->hash, ctx->key, ctx->value); +int stat_ev_enabled = 0; +int stat_ev_timer_sp = 0; +timing_ticks_t stat_ev_timer_elapsed[MAX_TIMER]; +timing_ticks_t stat_ev_timer_start[MAX_TIMER]; +timing_sched_env_t stat_ev_sched_rt; +timing_sched_env_t stat_ev_sched_normal; - ctx_switch_since_last_print = 1; +#ifdef FIRM_HAVE_REGEX +#include +static regex_t regex; +static regex_t *filter = NULL; +static INLINE int key_matches(const char *key) +{ + if (!filter) + return 1; - time_in_ev += get_time() - start; - } + return regexec(filter, key, 0, NULL, 0) == 0; } -void stat_ev_ctx_push_fobj(const char *key, const void *firm_object) +#else +static char filter[128] = { '\0' }; +static INLINE int key_matches(const char *key) { - if (file_ev) { - char buf[96]; - ir_snprintf(buf, sizeof(buf), "%+F", firm_object); - stat_ev_ctx_push(key, buf); - } -} + int i = 0; -void stat_ev_ctx_pop(void) -{ - if (ctx_sp >= 0) { - if (file_ev) { - fprintf(file_ev, "O %10x\n", ctx_stack[ctx_sp].hash); - ctx_switch_since_last_print = 1; - } - --ctx_sp; + for (i = 0; filter[i] != '\0'; ++i) { + if (key[i] != filter[i]) + return 0; } + + return 1; } +#endif /* FIRM_HAVE_REGEX */ -static void maybe_print_context(void) -{ - int i; - if(!ctx_switch_since_last_print) +void stat_ev_printf(char ev, const char *key, const char *fmt, ...) +{ + if (!key_matches(key)) return; - for(i = 0; i <= ctx_sp; ++i) { - if(i > 0) - fputc(':', stderr); - fputs(ctx_stack[i].value, stderr); - } - fputc('\n', stderr); - ctx_switch_since_last_print = 0; -} + mfprintf(stat_ev_file, "%c;%s", ev, key); + if (fmt != NULL) { + char buf[256]; + va_list args; -void stat_ev_emit(const char *name, double value) -{ - if (file_ev) { - unsigned long start = get_time(); - unsigned id = ctx_sp >= 0 ? ctx_stack[ctx_sp].hash : 0; - - fprintf(file_ev, "E %10x %30s %30f %10ld %10ld\n", id, name, value, start, time_in_ev); - - if(print_events != NULL) { - print_ev_t *print_ev = print_events; - while(print_ev != NULL) { - /* maybe wanna use regexes instead of strcmp? */ - if(strstr(name, print_ev->filter) != NULL) { - maybe_print_context(); - fprintf(stderr, "\t%20s %30f\n", name, value); - } - - print_ev = print_ev->next; - } - } - - time_in_ev += get_time() - start; + va_start(args, fmt); + ir_vsnprintf(buf, sizeof(buf), fmt, args); + va_end(args); + mfprintf(stat_ev_file, ";%s", buf); } + mfprintf(stat_ev_file, "\n"); } -void stat_ev_begin(const char *prefix) +void stat_ev_begin(const char *prefix, const char *filt) { char buf[512]; +#ifdef FIRM_HAVE_LIBZ + snprintf(buf, sizeof(buf), "%s.ev.gz", prefix); + stat_ev_file = gzopen(buf, "wt9"); +#else snprintf(buf, sizeof(buf), "%s.ev", prefix); + stat_ev_file = fopen(buf, "wt"); +#endif - stat_ev_enabled = 1; - ctx_sp = -1; - time_in_ev = 0; - print_events = NULL; - file_ev = fopen(buf, "wt"); - timer = lc_timer_register("stat_ev", "firm stat event timer"); - - lc_timer_start(timer); -} - -void stat_ev_end(void) -{ - print_ev_t *print_ev, *next; - - if (timer) - lc_timer_stop(timer); - if (file_ev) - fclose(file_ev); - - for (print_ev = print_events; print_ev != NULL; print_ev = next) { - next = print_ev->next; - free(print_ev); + if (filt && filt[0] != '\0') { +#ifdef FIRM_HAVE_REGEX + filter = NULL; + if (regcomp(®ex, filt, REG_EXTENDED) == 0) + filter = ®ex; +#else + strncpy(filter, filt, sizeof(filter) - sizeof(filter[0])); +#endif /* FIRM_HAVE_REGEX */ } -} -void stat_ev_flush(void) -{ - unsigned long start = get_time(); - if (file_ev) - fflush(file_ev); - time_in_ev += get_time() - start; + stat_ev_enabled = stat_ev_file != NULL; + timing_sched_get(&stat_ev_sched_normal); + timing_sched_prepare_max_prio(&stat_ev_sched_rt); } -void stat_ev_print(const char *filter) +void stat_ev_end(void) { - size_t len; - print_ev_t *print_ev = xmalloc(sizeof(print_ev[0])); - - memset(print_ev, 0, sizeof(print_ev[0])); - - len = strlen(filter) + 1; - if (len >= sizeof(print_ev->filter)) { - fprintf(stderr, "Warning: capping event filter (too long)"); - len = sizeof(print_ev->filter); + if (stat_ev_file) { +#ifdef FIRM_HAVE_LIBZ + gzflush(stat_ev_file, 1); + gzclose(stat_ev_file); +#else + fclose(stat_ev_file); +#endif } - memcpy(print_ev->filter, filter, len); - print_ev->filter[len-1] = 0; - - print_ev->next = print_events; - print_events = print_ev; } diff --git a/ir/stat/statev.h b/ir/stat/statev.h index b8988811d..4357c6d34 100644 --- a/ir/stat/statev.h +++ b/ir/stat/statev.h @@ -31,40 +31,118 @@ #ifndef FIRM_STATISTICS #define stat_ev_do(expr) +#define stat_ev_if if (0) #define stat_ev_dbl(name, val) +#define stat_ev(name) #define stat_ev_cnt_decl(var) #define stat_ev_cnt_inc(var) #define stat_ev_cnt_done(name, var) -#define stat_ev(name) +#define stat_ev_tim_push(var) +#define stat_ev_tim_pop(name) #define stat_ev_ctx_push_fobj(key, firm_object) #define stat_ev_ctx_push(key, value) -#define stat_ev_ctx_pop() +#define stat_ev_ctx_pop(key) #define stat_ev_flush() #else -extern int stat_ev_enabled; +#include +#include "timing.h" -#define stat_ev_do(expr) (stat_ev_enabled ? ((expr), 1) : 0) +extern void stat_ev_printf(char ev_type, const char *key, const char *fmt, ...); + +extern int stat_ev_enabled; +extern int stat_ev_timer_sp; +extern timing_ticks_t stat_ev_timer_elapsed[]; +extern timing_ticks_t stat_ev_timer_start[]; +extern timing_sched_env_t stat_ev_sched_rt; +extern timing_sched_env_t stat_ev_sched_normal; + +static INLINE __attribute__((unused)) void stat_ev_tim_push(void) { + timing_ticks_t temp; + int sp = stat_ev_timer_sp++; + timing_ticks(temp); + if (sp == 0) + timing_sched_set(&stat_ev_sched_rt); + else { + timing_ticks_sub(temp, stat_ev_timer_start[sp - 1]); + timing_ticks_add(stat_ev_timer_elapsed[sp - 1], temp); + } + timing_ticks_init(stat_ev_timer_elapsed[sp]); + timing_ticks(stat_ev_timer_start[sp]); +} + +static INLINE __attribute__((unused)) void stat_ev_tim_pop(const char *name) { + int sp; + timing_ticks_t temp; + timing_ticks(temp); + sp = --stat_ev_timer_sp; + timing_ticks_sub(temp, stat_ev_timer_start[sp]); + timing_ticks_add(stat_ev_timer_elapsed[sp], temp); + if (name != NULL && stat_ev_enabled) + stat_ev_printf('E', name, "%g", timing_ticks_dbl(stat_ev_timer_elapsed[sp])); + if (sp == 0) + timing_sched_set(&stat_ev_sched_normal); + else + timing_ticks(stat_ev_timer_start[sp - 1]); +} + +#define stat_ev_ctx_push_fmt(key, fmt, value) \ + do { \ + if (stat_ev_enabled) { \ + stat_ev_tim_push(); \ + stat_ev_printf('P', key, fmt, (value)); \ + stat_ev_tim_pop(NULL); \ + } \ + } while(0) -#define stat_ev_dbl(name, val) do { if (stat_ev_enabled) { stat_ev_emit(name, val); } } while(0) +#define stat_ev_ctx_pop(key) \ + do { \ + if (stat_ev_enabled) { \ + stat_ev_tim_push(); \ + stat_ev_printf('O', key, NULL); \ + stat_ev_tim_pop(NULL); \ + } \ + } while(0) + +#define stat_ev_emit(name, value) \ + do { \ + if (stat_ev_enabled) { \ + stat_ev_tim_push(); \ + stat_ev_printf('E', name, "%g", (double) (value)); \ + stat_ev_tim_pop(NULL); \ + } \ + } while(0) + +#define stat_ev_ctx_push_fobj(key, firm_object) stat_ev_ctx_push_fmt((key), "%+F", (firm_object)) +#define stat_ev_ctx_push_str(key, str) stat_ev_ctx_push_fmt((key), "%s", (str)) +#define stat_ev_ctx_push(key) stat_ev_ctx_push_fmt((key), "X", NULL) + +#define stat_ev_dbl(name, val) stat_ev_emit((name), (val)) +#define stat_ev(name) stat_ev_emit((name), 0.0) #define stat_ev_cnt_decl(var) int stat_ev_cnt_var_ ## var = 0 #define stat_ev_cnt_inc(var) do { ++stat_ev_cnt_var_ ## var; } while(0) -#define stat_ev_cnt_done(var, name) stat_ev_dbl((name), stat_ev_cnt_var_ ## var) +#define stat_ev_cnt_done(var, name) stat_ev_emit((name), stat_ev_cnt_var_ ## var) -#define stat_ev(name) stat_ev_dbl((name), 0.0) +#define stat_ev_do(expr) (stat_ev_enabled ? ((expr), 1) : 0) +#define stat_ev_if if (stat_ev_enabled) -void stat_ev_ctx_push_fobj(const char *key, const void *firm_object); -void stat_ev_ctx_push(const char *key, const char *value); -void stat_ev_ctx_pop(void); -void stat_ev_emit(const char *name, double val); -void stat_ev_begin(const char *prefix); +/** + * Initialize the stat ev machinery. + * @param filename_prefix The prefix of the filename (.ev or .ev.gz will be appended). + * @param filter All pushes, pops and events will be filtered by this. + * If we have regex support, you can give an extended regex here. + * If not, each key will be matched against this. + * Matched means, we look if the key starts with @p filter. + * If NULL is given, each key passes, ie thefilter is always TRUE. + */ +void stat_ev_begin(const char *filename_prefix, const char *filter); void stat_ev_end(void); -void stat_ev_flush(void); -void stat_ev_print(const char *event_filter); + +#define stat_ev_flush() do { if (stat_ev_enabled) fflush(stat_ev_enabled); } while(0) #endif diff --git a/ir/stat/timing.c b/ir/stat/timing.c new file mode 100644 index 000000000..56c732d95 --- /dev/null +++ b/ir/stat/timing.c @@ -0,0 +1,75 @@ + +#include +#include "timing.h" + +/* we can only use the scheduling stuff, if that macro is defined in unistd.h */ +#ifdef _POSIX_PRIORITY_SCHEDULING + +timing_sched_env_t *timing_sched_get(timing_sched_env_t *env) +{ + int res; + +#ifdef __linux__ + res = sched_getaffinity(0, sizeof(env->affinity), &env->affinity); + if (res < 0) + return NULL; +#endif + + env->scheduler = sched_getscheduler(0); + if (env->scheduler < 0) + return NULL; + + res = sched_getparam(0, &env->params); + if (res < 0) + return NULL; + + return env; +} + +int timing_sched_set(const timing_sched_env_t *env) +{ + int res; + +#ifdef __linux__ + res = sched_setaffinity(0, sizeof(env->affinity), &env->affinity); + if (res < 0) + return 0; +#endif + + res = sched_setscheduler(0, env->scheduler, &env->params); + if (res < 0) + return 0; + + return 1; +} + +timing_sched_env_t *timing_sched_prepare_max_prio(timing_sched_env_t *env) +{ + int policy = SCHED_FIFO; +#ifdef __linux__ + CPU_ZERO(&env->affinity); + CPU_SET(0, &env->affinity); +#endif + env->scheduler = policy; + env->params.sched_priority = sched_get_priority_max(policy); + return env; +} + +#else /* _POSIX_PRIORITY_SCHEDULING */ + +timing_sched_env_t *timing_sched_get(timing_sched_env_t *env) +{ + return NULL; +} + +int timing_sched_set(const timing_sched_env_t *env) +{ + return 0; +} + +timing_sched_env_t *timing_sched_prepare_max_prio(timing_sched_env_t *env) +{ + return env; +} + +#endif /* _POSIX_PRIORITY_SCHEDULING */ diff --git a/ir/stat/timing.h b/ir/stat/timing.h new file mode 100644 index 000000000..b201d7802 --- /dev/null +++ b/ir/stat/timing.h @@ -0,0 +1,102 @@ + +#ifndef _TICKS_H +#define _TICKS_H + +/* + * To use the Pentium RDTSC timer + * define TIMING_USE_RDTSC when including + */ +#define TIMING_USE_RDTSC + +#include +#include +#include + +/* define GNU macro for processor affinity stuff if on linux */ +#if defined __linux__ && !defined __USE_GNU +#define __USE_GNU +#endif +#include + +typedef struct { +#ifdef _POSIX_PRIORITY_SCHEDULING + struct sched_param params; +#endif + int scheduler; +#ifdef __linux__ + cpu_set_t affinity; +#endif +} timing_sched_env_t; + +/* only use rdtsc on GNU C with x86 */ +#if defined TIMING_USE_RDTSC && defined __GNUC__ && defined __i386__ + +typedef unsigned long long timing_ticks_t; +#define timing_ticks(t) __asm__ __volatile__ ("rdtsc" : "=A" (t)) +#define timing_ticks_init(t) ((t) = 0) +#define timing_ticks_cmp(a, b, cmp) ((a) cmp (b)) +#define timing_ticks_sub(r, a) ((r) = (r) - (a)) +#define timing_ticks_add(r, a) ((r) = (r) + (a)) +#define timing_ticks_ulong(t) ((unsigned long) (t)) +#define timing_ticks_dbl(t) ((double) (t)) + +#else + +typedef struct timeval timing_ticks_t; +#define timing_ticks(t) (gettimeofday(&(t), NULL)) +#define timing_ticks_init(t) ((t).tv_sec = 0, (t).tv_usec = 0) + +/* + * This shamelessly stolen and modified from glibc's + * /usr/include/sys/time.h + */ +#define timing_ticks_cmp(a, b, CMP) \ + (((a).tv_sec == (b).tv_sec) ? \ + ((a).tv_usec CMP (b).tv_usec) : \ + ((a).tv_sec CMP (b).tv_sec)) + +#define timing_ticks_add(r, a) \ + do { \ + (r).tv_sec = (r).tv_sec + (a).tv_sec; \ + (r).tv_usec = (r).tv_usec + (a).tv_usec; \ + if ((r).tv_usec >= 1000000) { \ + ++(r).tv_sec; \ + (r).tv_usec -= 1000000; \ + } \ + } while (0) + +#define timing_ticks_sub(r, a) \ + do { \ + (r).tv_sec = (r).tv_sec - (a).tv_sec; \ + (r).tv_usec = (r).tv_usec - (a).tv_usec; \ + if ((r).tv_usec < 0) { \ + --(r).tv_sec; \ + (r).tv_usec += 1000000; \ + } \ + } while (0) + +#define timing_ticks_ulong(t) ((unsigned long) ((t).tv_usec + 1000000 * (t).tv_sec)) +#define timing_ticks_dbl(t) (((t).tv_usec + 1000000.0 * (t).tv_sec)) + +#endif /* TIMING_USE_RDTSC ... */ + +/** + * Set the current schedule parameters. + * @return 1, if succeeded, 0 if not (see errno, for details). + */ +int timing_sched_set(const timing_sched_env_t *env); + +/** + * Get the schedule parameters. + * @return 1, if succeeded, 0 if not (see errno, for details). + */ +timing_sched_env_t *timing_sched_get(timing_sched_env_t *env); + +/** + * Prepare schedule parameters which limit the process on one CPU + * and set the maximum task priority. + * @return The paramter @p env. + */ +timing_sched_env_t *timing_sched_prepare_max_prio(timing_sched_env_t *env); + +#endif /* _TICKS_H */ -- 2.20.1