lock verifier.

git-svn-id: file:///svn/unbound/trunk@183 be551aaa-1e26-0410-a405-d3ace91eadb9

doc/Changelog

@@ -1,3 +1,6 @@
+16 March 2007: Wouter
+	- lock-verifier, checks consistent order of locking.
+
 14 March 2007: Wouter
 	- hash table insert (and subroutines) and lookup implemented.
 	- hash table remove.

testcode/checklocks.c

@@ -46,7 +46,7 @@
  * are passed to thread_create to make the thread numbers here the same as 
  * those used for logging which is nice.
  *
- * Todo: - check global ordering of instances of locks.
+ * Todo: 
  *	 - refcount statistics.
  *	 - debug status print, of thread lock stacks, and current waiting.
  */

testcode/lock_verify.c

@@ -48,29 +48,52 @@
 #include "util/rbtree.h"
 
 /* --- data structures --- */
+struct lock_ref;
+
+/** key for lock lookup */
+struct order_id {
+	/** the thread id that created it */
+	int thr;
+	/** the instance number of creation */
+	int instance;
+};
 
 /** a lock */
 struct order_lock {
 	/** rbnode in all tree */
 	rbnode_t node;
-	/** the thread id that created it */
+	/** lock id */
-	int thr;
+	struct order_id id;
-	/** the instance number of creation */
-	int instance;
 	/** the creation file */
 	char* create_file;
 	/** creation line */
 	int create_line;
 	/** set of all locks that are smaller than this one (locked earlier) */
 	rbtree_t* smaller;
+	/** during depthfirstsearch, this is a linked list of the stack 
+	 * of locks. points to the next lock bigger than this one. */
+	struct lock_ref* dfs_next;
+	/** if lock has been visited (all smaller locks have been compared to
+	 * this lock), only need to compare this with all unvisited(bigger) 
+	 * locks */
+	int visited;
 };
 
 /** reference to a lock in a rbtree set */
 struct lock_ref {
-	/** rbnode, key is an order_lock ptr */
+	/** rbnode, key is an order_id ptr */
 	rbnode_t node;
+	/** the lock referenced */
+	struct order_lock* lock;
+	/** why is this ref */
+	char* file;
+	/** line number */
+	int line;
 };
 
+/** count of errors detected */
+static int errors_detected = 0;
+
 /** print program usage help */
 static void
 usage()
@@ -78,11 +101,11 @@ usage()
 	printf("lock_verify <trace files>\n");
 }
 
-/** compare two order_locks */
+/** compare two order_ids */
 int order_lock_cmp(const void* e1, const void* e2)
 {
-	struct order_lock* o1 = (struct order_lock*)e1;
+	struct order_id* o1 = (struct order_id*)e1;
-	struct order_lock* o2 = (struct order_lock*)e2;
+	struct order_id* o2 = (struct order_id*)e2;
 	if(o1->thr < o2->thr) return -1;
 	if(o1->thr > o2->thr) return 1;
 	if(o1->instance < o2->instance) return -1;
@@ -90,8 +113,11 @@ int order_lock_cmp(const void* e1, const void* e2)
 	return 0;
 }
 
-/** read header entry */
+/** read header entry. 
-static void read_header(FILE* in)
+ * @param in: file to read header of.
+ * @return: False if it does not belong to the rest. */
+static int 
+read_header(FILE* in)
 {
 	time_t t;
 	pid_t p;
@@ -113,24 +139,30 @@ static void read_header(FILE* in)
 		memset(threads, 0, 256*sizeof(int));
 		threads[thrno] = 1;
 		have_values = 1;
-		printf("Trace from pid %u on %s", (unsigned)p, ctime(&t));
+		printf(" trace %d from pid %u on %s", thrno, 
+			(unsigned)p, ctime(&t));
 	} else {
-		if(the_pid != p)
+		if(the_pid != p) {
-			fatal_exit("different pids in input files");
+			printf(" has pid %u, not %u. Skipped.\n",
+				(unsigned)p, (unsigned)the_pid);
+			return 0;
+		}
 		if(threads[thrno])
 			fatal_exit("same threadno in two files");
 		threads[thrno] = 1;
-		if( abs(the_time - t) > 3600)
+		if( abs((int)(the_time - t)) > 3600)
 			fatal_exit("input files from different times: %u %u",
 				(unsigned)the_time, (unsigned)t);
+		printf(" trace of thread %d\n", thrno);
 	}
-	printf("reading trace of thread %d\n", thrno);
+	return 1;
 }
 
+/** max length of strings: filenames and function names. */
+#define STRMAX 1024
 /** read a string from file, false on error */
 static int readup_str(char** str, FILE* in)
 {
-#define STRMAX 1024
 	char buf[STRMAX];
 	int len = 0;
 	int c;
@@ -153,21 +185,45 @@ static void read_create(rbtree_t* all, FILE* in)
 {
 	struct order_lock* o = calloc(1, sizeof(struct order_lock));
 	if(!o) fatal_exit("malloc failure");
-	if(fread(&o->thr, sizeof(int), 1, in) != 1 ||	
+	if(fread(&o->id.thr, sizeof(int), 1, in) != 1 ||	
-	   fread(&o->instance, sizeof(int), 1, in) != 1 ||	
+	   fread(&o->id.instance, sizeof(int), 1, in) != 1 ||	
 	   !readup_str(&o->create_file, in) ||
 	   fread(&o->create_line, sizeof(int), 1, in) != 1)
 		fatal_exit("fread: %s", strerror(errno));
 	o->smaller = rbtree_create(order_lock_cmp);
-	o->node.key = o;
+	o->node.key = &o->id;
-	rbtree_insert(all, &o->node);
+	if(!rbtree_insert(all, &o->node))
-	printf("read create %s %d\n", o->create_file, o->create_line);
+		fatal_exit("lock created twice");
+	if(1) printf("read create %s %d\n", o->create_file, o->create_line);
 }
 
 /** read lock entry */
 static void read_lock(rbtree_t* all, FILE* in, int val)
 {
-	
+	struct order_id prev_id, now_id;
+	struct lock_ref* ref;
+	struct order_lock* prev, *now;
+	ref = (struct lock_ref*)calloc(1, sizeof(struct lock_ref));
+	if(!ref) fatal_exit("malloc failure");
+	prev_id.thr = val;
+	if(fread(&prev_id.instance, sizeof(int), 1, in) != 1 ||	
+	   fread(&now_id.thr, sizeof(int), 1, in) != 1 ||	
+	   fread(&now_id.instance, sizeof(int), 1, in) != 1 ||	
+	   !readup_str(&ref->file, in) ||
+	   fread(&ref->line, sizeof(int), 1, in) != 1)
+		fatal_exit("fread: %s", strerror(errno));
+	if(1) printf("read lock %s %d\n", ref->file, ref->line);
+	/* find the two locks involved */
+	prev = (struct order_lock*)rbtree_search(all, &prev_id);
+	now = (struct order_lock*)rbtree_search(all, &now_id);
+	if(!prev || !now)
+		fatal_exit("Could not find locks involved.");
+	ref->lock = prev;
+	ref->node.key = &prev->id;
+	if(!rbtree_insert(now->smaller, &ref->node)) {
+		free(ref->file);
+		free(ref);
+	}
 }
 
 /** read input file */
@@ -179,8 +235,11 @@ static void readinput(rbtree_t* all, char* file)
 		perror(file);
 		exit(1);
 	}
-	printf("reading file %s\n", file);
+	printf("file %s", file);
-	read_header(in);
+	if(!read_header(in)) {
+		fclose(in);
+		return;
+	}
 	while(fread(&fst, sizeof(fst), 1, in) == 1) {
 		if(fst == -1)
 			read_create(all, in);
@@ -189,12 +248,110 @@ static void readinput(rbtree_t* all, char* file)
 	fclose(in);
 }
 
+/** print cycle message */
+static void found_cycle(struct lock_ref* visit, int level)
+{
+	struct lock_ref* p;
+	int i = 0;
+	errors_detected++;
+	printf("Found inconsistent locking order of length %d\n", level);
+	printf("for lock %d %d created %s %d", 
+		visit->lock->id.thr, visit->lock->id.instance,
+		visit->lock->create_file, visit->lock->create_line);
+	printf("sequence is:\n");
+	p = visit;
+	while(p) {
+		struct order_lock* next = 
+			p->lock->dfs_next?p->lock->dfs_next->lock:visit->lock;
+		printf("[%d] is locked at line %s %d before lock %d %d\n",
+			i, visit->file, visit->line, 
+			next->id.thr, next->id.instance);
+		printf("[%d] lock %d %d is created at %s %d\n",
+			i, next->id.thr, next->id.instance,
+			next->create_file, next->create_line); 
+		i++;
+		p = p->lock->dfs_next;
+		if(p && p->lock == visit->lock)
+			break;
+	}
+}
+
+/** Detect cycle by comparing visited now with all (unvisited) bigger nodes. */
+static int detect_cycle(struct lock_ref* visit, struct lock_ref* from)
+{
+	struct lock_ref* p = from;
+	while(p) {
+		if(p->lock == visit->lock)
+			return 1;
+		p = p->lock->dfs_next;
+	}
+	return 0;
+}
+
+/** recursive function to depth first search for cycles.
+ * @param visit: the lock visited at this step.
+ *	its dfs_next pointer gives the visited lock up in recursion.
+ * 	same as lookfor at level 0.
+ * @param level: depth of recursion. 0 is start.
+ * @param from: search for matches from unvisited node upwards.
+ */
+static void search_cycle(struct lock_ref* visit, int level, 
+	struct lock_ref* from)
+{
+	struct lock_ref* ref;
+	/* check for cycle */
+	if(detect_cycle(visit, from) && level != 0) {
+		found_cycle(visit, level);
+		return;
+	}
+	/* recurse */
+	if(!visit->lock->visited)
+		from = visit;
+	RBTREE_FOR(ref, struct lock_ref*, visit->lock->smaller) {
+		ref->lock->dfs_next = visit;
+		search_cycle(ref, level+1, from);
+	}
+	visit->lock->visited = 1;
+}
+
+/** Check ordering of one lock */
+static void check_order_lock(struct order_lock* lock)
+{
+	struct lock_ref start;
+	if(lock->visited) return;
+
+	start.node.key = &lock->id;
+	start.lock = lock;
+	start.file = lock->create_file;
+	start.line = lock->create_line;
+
+	/* depth first search to find cycle with this lock at head */
+	lock->dfs_next = NULL;
+	search_cycle(&start, 0, &start);
+}
+
+/** Check ordering of locks */
+static void check_order(rbtree_t* all_locks)
+{
+	/* check each lock */
+	struct order_lock* lock;
+	int i=0;
+	RBTREE_FOR(lock, struct order_lock*, all_locks) {
+		if(1) printf("[%d/%d] Checking lock %d %d %s %d\n",
+			i++, (int)all_locks->count,
+			lock->id.thr, lock->id.instance, 
+			lock->create_file, lock->create_line);
+		check_order_lock(lock);
+	}
+}
+
 /** main program to verify all traces passed */
 int
 main(int argc, char* argv[])
 {
 	rbtree_t* all_locks;
 	int i;
+	time_t starttime = time(NULL);
 	if(argc <= 1) {
 		usage();
 		return 1;
@@ -203,6 +360,7 @@ main(int argc, char* argv[])
 	log_ident_set("lock-verify");
 	/* init */
 	all_locks = rbtree_create(order_lock_cmp);
+	errors_detected = 0;
 
 	/* read the input files */
 	for(i=1; i<argc; i++) {
@@ -210,7 +368,12 @@ main(int argc, char* argv[])
 	}
 
 	/* check ordering */
+	check_order(all_locks);
 
 	/* do not free a thing, OS will do it */
+	printf("checked %d locks in %d seconds with %d errors.\n", 
+		(int)all_locks->count, (int)(time(NULL)-starttime),
+		errors_detected);
+	if(errors_detected) return 1;
 	return 0;
 }