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

@@ -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:

ir/stat/statev.c

@@ -32,181 +32,129 @@
 #include <string.h>
 #include <stdio.h>
 #include <stdlib.h>
-
-#include <libcore/lc_timing.h>
+#include <stdarg.h>
 
 #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 <zlib.h>
 
-#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 <regex.h>
+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(&regex, filt, REG_EXTENDED) == 0)
+			filter = &regex;
+#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;
 }

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 <stdio.h>
+#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
 

ir/stat/timing.c

+
+#include <stdio.h>
+#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 */

ir/stat/timing.h

+
+#ifndef _TICKS_H
+#define _TICKS_H
+
+/*
+ * To use the Pentium RDTSC timer
+ * define TIMING_USE_RDTSC when including
+ */
+#define TIMING_USE_RDTSC
+
+#include <unistd.h>
+#include <time.h>
+#include <sys/time.h>
+
+/* define GNU macro for processor affinity stuff if on linux */
+#if defined __linux__ && !defined __USE_GNU
+#define __USE_GNU
+#endif
+#include <sched.h>
+
+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.