r3507: - added deferred replies on sharing violation in pvfs open. The

  deferred reply is short-circuited immediately when the file is
  closed by another user, allowing it to be opened by the waiting user.

- added a sane set of timeval manipulation routines

- converted all the events code and code that uses it to use struct
  timeval instead of time_t, which allows for microsecond resolution
  instead of 1 second resolution. This was needed for doing the pvfs
  deferred open code, and is why the patch is so big.
(This used to be commit 0d51511d408d91eb5f68a35e980e0875299b1831)

10 files changed, 76 insertions, 65 deletions

diff --git a/source4/torture/basic/dir.c b/source4/torture/basic/dir.c
index 5d3ac8d1de..7921b3eb03 100644
--- a/source4/torture/basic/dir.c
+++ b/source4/torture/basic/dir.c
@@ -35,9 +35,9 @@ BOOL torture_dirtest1(void)
 	int i;
 	struct smbcli_state *cli;
 	int fnum;
-	double t1;
 	BOOL correct = True;
 	extern int torture_numops;
+	struct timeval tv;
 
 	printf("starting dirtest1\n");
 
@@ -48,6 +48,7 @@ BOOL torture_dirtest1(void)
 	printf("Creating %d random filenames\n", torture_numops);
 
 	srandom(0);
+	tv = timeval_current();
 	for (i=0;i<torture_numops;i++) {
 		char *fname;
 		asprintf(&fname, "\\%x", (int)random());
@@ -61,13 +62,11 @@ BOOL torture_dirtest1(void)
 		free(fname);
 	}
 
-	t1 = end_timer();
-
 	printf("Matched %d\n", smbcli_list(cli->tree, "a*.*", 0, list_fn, NULL));
 	printf("Matched %d\n", smbcli_list(cli->tree, "b*.*", 0, list_fn, NULL));
 	printf("Matched %d\n", smbcli_list(cli->tree, "xyzabc", 0, list_fn, NULL));
 
-	printf("dirtest core %g seconds\n", end_timer() - t1);
+	printf("dirtest core %g seconds\n", timeval_elapsed(&tv));
 
 	srandom(0);
 	for (i=0;i<torture_numops;i++) {
diff --git a/source4/torture/gentest.c b/source4/torture/gentest.c
index 07ad0929de..310dec1bc7 100644
--- a/source4/torture/gentest.c
+++ b/source4/torture/gentest.c
@@ -189,7 +189,7 @@ static BOOL connect_servers(void)
 			}
 
 			smbcli_oplock_handler(servers[i].cli[j]->transport, oplock_handler, NULL);
-			smbcli_transport_idle_handler(servers[i].cli[j]->transport, idle_func, 1, NULL);
+			smbcli_transport_idle_handler(servers[i].cli[j]->transport, idle_func, 50000, NULL);
 		}
 	}
 
diff --git a/source4/torture/local/messaging.c b/source4/torture/local/messaging.c
index c0dab06cca..303ffa8fe9 100644
--- a/source4/torture/local/messaging.c
+++ b/source4/torture/local/messaging.c
@@ -58,6 +58,7 @@ static BOOL test_ping_speed(TALLOC_CTX *mem_ctx)
 	int ping_count = 0;
 	int pong_count = 0;
 	BOOL ret = True;
+	struct timeval tv;
 
 	if (fork() == 0) {
 		struct messaging_context *msg_ctx2 = messaging_init(mem_ctx, 1, ev);
@@ -83,10 +84,10 @@ static BOOL test_ping_speed(TALLOC_CTX *mem_ctx)
 
 	messaging_register(msg_ctx, &pong_count, MY_PONG, pong_message);
 
-	start_timer();
+	tv = timeval_current();
 
 	printf("Sending pings for 10 seconds\n");
-	while (end_timer() < 10.0) {
+	while (timeval_elapsed(&tv) < 10.0) {
 		DATA_BLOB data;
 		NTSTATUS status1, status2;
 
@@ -113,7 +114,7 @@ static BOOL test_ping_speed(TALLOC_CTX *mem_ctx)
 
 	printf("waiting for %d remaining replies (done %d)\n", 
 	       ping_count - pong_count, pong_count);
-	while (end_timer() < 30 && pong_count < ping_count) {
+	while (timeval_elapsed(&tv) < 30 && pong_count < ping_count) {
 		event_loop_once(ev);
 	}
 
@@ -125,7 +126,8 @@ static BOOL test_ping_speed(TALLOC_CTX *mem_ctx)
 		ret = False;
 	}
 
-	printf("ping rate of %.0f messages/sec\n", (ping_count+pong_count)/end_timer());
+	printf("ping rate of %.0f messages/sec\n", 
+	       (ping_count+pong_count)/timeval_elapsed(&tv));
 
 	talloc_free(msg_ctx);
 
diff --git a/source4/torture/local/talloc.c b/source4/torture/local/talloc.c
index 332312200a..348b037753 100644
--- a/source4/torture/local/talloc.c
+++ b/source4/torture/local/talloc.c
@@ -36,18 +36,18 @@
 #ifdef _STANDALONE_
 typedef enum {False=0,True=1} BOOL;
 
-static struct timeval tp1,tp2;
-
-static void start_timer(void)
+static struct timeval current_time(void)
 {
-	gettimeofday(&tp1,NULL);
+	struct timeval tv;
+	GetTimeOfDay(&tv);
+	return tv;
 }
 
-static double end_timer(void)
+static double elapsed_time(struct timeval *tv)
 {
-	gettimeofday(&tp2,NULL);
-	return((tp2.tv_sec - tp1.tv_sec) + 
-	       (tp2.tv_usec - tp1.tv_usec)*1.0e-6);
+	struct timeval tv2 = current_time();
+	return (tv2.tv_sec - tv->tv_sec) + 
+	       (tv2.tv_usec - tv->tv_usec)*1.0e-6;
 }
 #endif /* _STANDALONE_ */
 
@@ -642,10 +642,11 @@ static BOOL test_speed(void)
 {
 	void *ctx = talloc(NULL, 0);
 	unsigned count;
+	struct timeval tv;
 
 	printf("MEASURING TALLOC VS MALLOC SPEED\n");
 
-	start_timer();
+	tv = timeval_current();
 	count = 0;
 	do {
 		void *p1, *p2, *p3;
@@ -654,13 +655,13 @@ static BOOL test_speed(void)
 		p3 = talloc(p1, 300);
 		talloc_free(p1);
 		count += 3;
-	} while (end_timer() < 5.0);
+	} while (timeval_elapsed(&tv) < 5.0);
 
-	printf("talloc: %.0f ops/sec\n", count/end_timer());
+	printf("talloc: %.0f ops/sec\n", count/timeval_elapsed(&tv));
 
 	talloc_free(ctx);
 
-	start_timer();
+	tv = timeval_current();
 	count = 0;
 	do {
 		void *p1, *p2, *p3;
@@ -671,9 +672,9 @@ static BOOL test_speed(void)
 		free(p2);
 		free(p3);
 		count += 3;
-	} while (end_timer() < 5.0);
+	} while (timeval_elapsed(&tv) < 5.0);
 
-	printf("malloc: %.0f ops/sec\n", count/end_timer());
+	printf("malloc: %.0f ops/sec\n", count/timeval_elapsed(&tv));
 
 	return True;	
 }
diff --git a/source4/torture/nbench/nbench.c b/source4/torture/nbench/nbench.c
index 0b4bf4bbf1..1c90658f49 100644
--- a/source4/torture/nbench/nbench.c
+++ b/source4/torture/nbench/nbench.c
@@ -37,6 +37,9 @@ static BOOL run_netbench(struct smbcli_state *cli, int client)
 	fstring params[20];
 	const char *p;
 	BOOL correct = True;
+	struct timeval tv;
+
+	tv = timeval_current();
 
 	nb_setup(cli, client, warmup);
 
@@ -52,15 +55,15 @@ static BOOL run_netbench(struct smbcli_state *cli, int client)
 again:
 	while (fgets(line, sizeof(line)-1, f)) {
 		NTSTATUS status;
-		double t = end_timer();
 
-		if (warmup && t >= warmup) {
+		if (warmup && 
+		    timeval_elapsed(&tv) >= warmup) {
 			warmup = 0;
 			nb_warmup_done();
-			start_timer();
+			tv = timeval_current();
 		}
 
-		if (end_timer() >= timelimit) {
+		if (timeval_elapsed(&tv) >= timelimit) {
 			goto done;
 		}
 
diff --git a/source4/torture/nbench/nbio.c b/source4/torture/nbench/nbio.c
index 98b1c08c97..98967f2523 100644
--- a/source4/torture/nbench/nbio.c
+++ b/source4/torture/nbench/nbio.c
@@ -31,6 +31,7 @@ static int nbio_id;
 static int nprocs;
 static BOOL bypass_io;
 static int warmup;
+static struct timeval tv;
 
 struct ftable {
 	struct ftable *next, *prev;
@@ -76,7 +77,7 @@ void nb_alarm(int sig)
 		if (!children[i].done) num_clients++;
 	}
 
-	t = end_timer();
+	t = timeval_elapsed(&tv);
 
 	if (warmup) {
 		printf("%4d  %8d  %.2f MB/sec  warmup %.0f sec   \n", 
@@ -91,7 +92,7 @@ void nb_alarm(int sig)
 	}
 
 	if (warmup && t >= warmup) {
-		start_timer();
+		tv = timeval_current();
 		warmup = 0;
 	}
 
@@ -156,7 +157,7 @@ void nb_setup(struct smbcli_state *cli, int id, int warmupt)
 	warmup = warmupt;
 	nbio_id = id;
 	c = cli;
-	start_timer();
+	tv = timeval_current();
 	if (children) {
 		children[nbio_id].done = 0;
 	}
diff --git a/source4/torture/raw/mux.c b/source4/torture/raw/mux.c
index c184fb79a7..c02045817e 100644
--- a/source4/torture/raw/mux.c
+++ b/source4/torture/raw/mux.c
@@ -42,6 +42,8 @@ static BOOL test_mux_open(struct smbcli_state *cli, TALLOC_CTX *mem_ctx)
 	int fnum;
 	BOOL ret = True;
 	struct smbcli_request *req;
+	struct timeval tv;
+	double d;
 
 	printf("testing multiplexed open/open/close\n");
 
@@ -64,14 +66,25 @@ static BOOL test_mux_open(struct smbcli_state *cli, TALLOC_CTX *mem_ctx)
 	CHECK_STATUS(status, NT_STATUS_OK);
 	fnum = io.ntcreatex.out.fnum;
 
+	tv = timeval_current();
+
 	/* send an open that will conflict */
 	io.ntcreatex.in.open_disposition = NTCREATEX_DISP_OPEN;
 	status = smb_raw_open(cli->tree, mem_ctx, &io);
 	CHECK_STATUS(status, NT_STATUS_SHARING_VIOLATION);
 
+	d = timeval_elapsed(&tv);
+	if (d < 0.5 || d > 1.5) {
+		printf("bad timeout for conflict - %.2f should be 1.0\n", d);
+		ret = False;
+	} else {
+		printf("open delay %.2f\n", d);
+	}
+
 	/*
 	  same request, but async
 	*/
+	tv = timeval_current();
 	req = smb_raw_open_send(cli->tree, &io);
 	
 	/* and close the file */
@@ -81,6 +94,14 @@ static BOOL test_mux_open(struct smbcli_state *cli, TALLOC_CTX *mem_ctx)
 	status = smb_raw_open_recv(req, mem_ctx, &io);
 	CHECK_STATUS(status, NT_STATUS_OK);
 
+	d = timeval_elapsed(&tv);
+	if (d > 0.25) {
+		printf("bad timeout for async conflict - %.2f should be <0.25\n", d);
+		ret = False;
+	} else {
+		printf("async open delay %.2f\n", d);
+	}
+
 	smbcli_close(cli->tree, io.ntcreatex.out.fnum);
 
 done:
diff --git a/source4/torture/raw/open.c b/source4/torture/raw/open.c
index 81681bbd74..c810984900 100644
--- a/source4/torture/raw/open.c
+++ b/source4/torture/raw/open.c
@@ -266,6 +266,7 @@ static BOOL test_openx(struct smbcli_state *cli, TALLOC_CTX *mem_ctx)
 	int fnum = -1, fnum2;
 	BOOL ret = True;
 	int i;
+	struct timeval tv;
 	struct {
 		uint16_t open_func;
 		BOOL with_file;
@@ -398,13 +399,13 @@ static BOOL test_openx(struct smbcli_state *cli, TALLOC_CTX *mem_ctx)
 	fnum = io.openx.out.fnum;
 
 	io.openx.in.timeout = 20000;
-	start_timer();
+	tv = timeval_current();
 	io.openx.in.open_mode = OPENX_MODE_ACCESS_RDWR | OPENX_MODE_DENY_NONE;
 	status = smb_raw_open(cli->tree, mem_ctx, &io);
 	CHECK_STATUS(status, NT_STATUS_SHARING_VIOLATION);
-	if (end_timer() > 3) {
-		printf("(%s) Incorrect timing in openx with timeout - waited %d seconds\n",
-		       __location__, (int)end_timer());
+	if (timeval_elapsed(&tv) > 3.0) {
+		printf("(%s) Incorrect timing in openx with timeout - waited %.2f seconds\n",
+		       __location__, timeval_elapsed(&tv));
 		ret = False;
 	}
 	smbcli_close(cli->tree, fnum);
diff --git a/source4/torture/torture.c b/source4/torture/torture.c
index 656607d934..19dc311dd9 100644
--- a/source4/torture/torture.c
+++ b/source4/torture/torture.c
@@ -937,22 +937,19 @@ static BOOL run_deferopen(struct smbcli_state *cli, int dummy)
 		int fnum = -1;
 
 		do {
-			struct timeval tv_start, tv_end;
-			GetTimeOfDay(&tv_start);
+			struct timeval tv;
+			tv = timeval_current();
 			fnum = smbcli_nt_create_full(cli->tree, fname, 0, GENERIC_RIGHTS_FILE_ALL_ACCESS,
 				FILE_ATTRIBUTE_NORMAL, NTCREATEX_SHARE_ACCESS_NONE,
 				NTCREATEX_DISP_OPEN_IF, 0, 0);
 			if (fnum != -1) {
 				break;
 			}
-			GetTimeOfDay(&tv_end);
 			if (NT_STATUS_EQUAL(smbcli_nt_error(cli->tree),NT_STATUS_SHARING_VIOLATION)) {
-				/* Sharing violation errors need to be 1 second apart. */
-				int64_t tdif = usec_time_diff(&tv_end, &tv_start);
-				if (tdif < 500000 || tdif > 1500000) {
-					fprintf(stderr,"Timing incorrect %lld.%lld for share violation\n",
-						tdif / (int64_t)1000000, 
-						tdif % (int64_t)1000000);
+				double e = timeval_elapsed(&tv);
+				if (e < 0.5 || e > 1.5) {
+					fprintf(stderr,"Timing incorrect %.2f violation\n",
+						e);
 				}
 			}
 		} while (NT_STATUS_EQUAL(smbcli_nt_error(cli->tree),NT_STATUS_SHARING_VIOLATION));
@@ -2269,6 +2266,7 @@ double torture_create_procs(BOOL (*fn)(struct smbcli_state *, int), BOOL *result
 	char **unc_list = NULL;
 	const char *p;
 	int num_unc_names = 0;
+	struct timeval tv;
 
 	synccount = 0;
 
@@ -2300,7 +2298,7 @@ double torture_create_procs(BOOL (*fn)(struct smbcli_state *, int), BOOL *result
 		child_status_out[i] = True;
 	}
 
-	start_timer();
+	tv = timeval_current();
 
 	for (i=0;i<torture_nprocs;i++) {
 		procnum = i;
@@ -2364,18 +2362,18 @@ double torture_create_procs(BOOL (*fn)(struct smbcli_state *, int), BOOL *result
 		}
 		if (synccount == torture_nprocs) break;
 		msleep(100);
-	} while (end_timer() < start_time_limit);
+	} while (timeval_elapsed(&tv) < start_time_limit);
 
 	if (synccount != torture_nprocs) {
 		printf("FAILED TO START %d CLIENTS (started %d)\n", torture_nprocs, synccount);
 		*result = False;
-		return end_timer();
+		return timeval_elapsed(&tv);
 	}
 
 	printf("Starting %d clients\n", torture_nprocs);
 
 	/* start the client load */
-	start_timer();
+	tv = timeval_current();
 	for (i=0;i<torture_nprocs;i++) {
 		child_status[i] = 0;
 	}
@@ -2398,7 +2396,7 @@ double torture_create_procs(BOOL (*fn)(struct smbcli_state *, int), BOOL *result
 			*result = False;
 		}
 	}
-	return end_timer();
+	return timeval_elapsed(&tv);
 }
 
 #define FLAG_MULTIPROC 1
@@ -2557,12 +2555,12 @@ static BOOL run_test(const char *name)
 				}
 					 
 			} else {
-				start_timer();
+				struct timeval tv = timeval_current();
 				if (!torture_ops[i].fn()) {
 					ret = False;
 					printf("TEST %s FAILED!\n", torture_ops[i].name);
 				}
-				t = end_timer();
+				t = timeval_elapsed(&tv);
 			}
 			printf("%s took %g secs\n\n", torture_ops[i].name, t);
 		}
diff --git a/source4/torture/torture_util.c b/source4/torture/torture_util.c
index 0c0464507d..22aa9ffedd 100644
--- a/source4/torture/torture_util.c
+++ b/source4/torture/torture_util.c
@@ -24,21 +24,6 @@
 #include "system/time.h"
 
 
-static struct timeval tp1,tp2;
-
-void start_timer(void)
-{
-	gettimeofday(&tp1,NULL);
-}
-
-double end_timer(void)
-{
-	gettimeofday(&tp2,NULL);
-	return((tp2.tv_sec - tp1.tv_sec) + 
-	       (tp2.tv_usec - tp1.tv_usec)*1.0e-6);
-}
-
-
 /*
   create a directory, returning a handle to it
 */