WT-3672 Test format failure with commit timestamp older than oldest timestamp (#3747)

* Test format failure with commit timestamp older than oldest timestamp

When validating a timestamp, include the type of timestamp with any
error message, we validate read timestamps as well as commit timestamps.

* Don't update the thread's information until after the commit, otherwise
we could race with the timestamp thread and try to commit a change at a
timestamp earlier than the "oldest" timestamp.

* Rework the timestamp() function so we can't read the global timestamp
counter until after we've read the latest-commit timestamp value from
the running threads.

Rework for clarity, and assert the expected relationship between the
thread timestamp values and the global timestamp counter.

5 files changed, 32 insertions, 18 deletions

diff --git a/src/include/extern.h b/src/include/extern.h
index 71bda687659..5ffae3111cc 100644
--- a/src/include/extern.h
+++ b/src/include/extern.h
@@ -821,7 +821,7 @@ extern int __wt_txn_parse_timestamp(WT_SESSION_IMPL *session, const char *name,
 extern int __wt_txn_global_query_timestamp( WT_SESSION_IMPL *session, char *hex_timestamp, const char *cfg[]) WT_GCC_FUNC_DECL_ATTRIBUTE((warn_unused_result));
 extern int __wt_txn_update_pinned_timestamp(WT_SESSION_IMPL *session) WT_GCC_FUNC_DECL_ATTRIBUTE((warn_unused_result));
 extern int __wt_txn_global_set_timestamp(WT_SESSION_IMPL *session, const char *cfg[]) WT_GCC_FUNC_DECL_ATTRIBUTE((warn_unused_result));
-extern int __wt_timestamp_validate(WT_SESSION_IMPL *session, wt_timestamp_t *ts, WT_CONFIG_ITEM *cval, bool cmp_oldest, bool cmp_stable, bool cmp_commit) WT_GCC_FUNC_DECL_ATTRIBUTE((warn_unused_result));
+extern int __wt_timestamp_validate(WT_SESSION_IMPL *session, const char *name, wt_timestamp_t *ts, WT_CONFIG_ITEM *cval, bool cmp_oldest, bool cmp_stable, bool cmp_commit) WT_GCC_FUNC_DECL_ATTRIBUTE((warn_unused_result));
 extern int __wt_txn_set_timestamp(WT_SESSION_IMPL *session, const char *cfg[]) WT_GCC_FUNC_DECL_ATTRIBUTE((warn_unused_result));
 extern void __wt_txn_set_commit_timestamp(WT_SESSION_IMPL *session);
 extern void __wt_txn_clear_commit_timestamp(WT_SESSION_IMPL *session);
diff --git a/src/txn/txn.c b/src/txn/txn.c
index cfdb7d26498..ab8aa039594 100644
--- a/src/txn/txn.c
+++ b/src/txn/txn.c
@@ -446,7 +446,7 @@ __wt_txn_config(WT_SESSION_IMPL *session, const char *cfg[])
 
 		WT_RET(__wt_txn_parse_timestamp(session, "read", &ts, &cval));
 		WT_RET(__wt_timestamp_validate(session,
-		    &ts, &cval, true, false, false));
+		    "read", &ts, &cval, true, false, false));
 		__wt_timestamp_set(&txn->read_timestamp, &ts);
 		__wt_txn_set_read_timestamp(session);
 		txn->isolation = WT_ISO_SNAPSHOT;
@@ -586,7 +586,7 @@ __wt_txn_commit(WT_SESSION_IMPL *session, const char *cfg[])
 #ifdef HAVE_TIMESTAMPS
 		WT_ERR(__wt_txn_parse_timestamp(session, "commit", &ts, &cval));
 		WT_ERR(__wt_timestamp_validate(session,
-		    &ts, &cval, true, true, true));
+		    "commit", &ts, &cval, true, true, true));
 		__wt_timestamp_set(&txn->commit_timestamp, &ts);
 		__wt_txn_set_commit_timestamp(session);
 #else
diff --git a/src/txn/txn_timestamp.c b/src/txn/txn_timestamp.c
index 8f90afeb8b4..0201036684d 100644
--- a/src/txn/txn_timestamp.c
+++ b/src/txn/txn_timestamp.c
@@ -481,8 +481,9 @@ __wt_txn_global_set_timestamp(WT_SESSION_IMPL *session, const char *cfg[])
  *	global stable and/or running transaction commit timestamp.
  */
 int
-__wt_timestamp_validate(WT_SESSION_IMPL *session, wt_timestamp_t *ts,
-    WT_CONFIG_ITEM *cval, bool cmp_oldest, bool cmp_stable, bool cmp_commit)
+__wt_timestamp_validate(WT_SESSION_IMPL *session, const char *name,
+    wt_timestamp_t *ts, WT_CONFIG_ITEM *cval,
+    bool cmp_oldest, bool cmp_stable, bool cmp_commit)
 {
 	WT_TXN *txn = &session->txn;
 	WT_TXN_GLOBAL *txn_global = &S2C(session)->txn_global;
@@ -503,12 +504,12 @@ __wt_timestamp_validate(WT_SESSION_IMPL *session, wt_timestamp_t *ts,
 
 	if (older_than_oldest_ts)
 		WT_RET_MSG(session, EINVAL,
-		    "commit timestamp %.*s older than oldest timestamp",
-		    (int)cval->len, cval->str);
+		    "%s timestamp %.*s older than oldest timestamp",
+		    name, (int)cval->len, cval->str);
 	if (older_than_stable_ts)
 		WT_RET_MSG(session, EINVAL,
-		    "commit timestamp %.*s older than stable timestamp",
-		    (int)cval->len, cval->str);
+		    "%s timestamp %.*s older than stable timestamp",
+		    name, (int)cval->len, cval->str);
 
 	/*
 	 * Compare against the commit timestamp of the current transaction.
@@ -520,9 +521,9 @@ __wt_timestamp_validate(WT_SESSION_IMPL *session, wt_timestamp_t *ts,
 		WT_RET(__wt_timestamp_to_hex_string(
 		    session, hex_timestamp, &txn->first_commit_timestamp));
 		WT_RET_MSG(session, EINVAL,
-		    "commit timestamp %.*s older than the first "
+		    "%s timestamp %.*s older than the first "
 		    "commit timestamp %s for this transaction",
-		    (int)cval->len, cval->str, hex_timestamp);
+		    name, (int)cval->len, cval->str, hex_timestamp);
 	}
 
 	return (0);
@@ -554,7 +555,7 @@ __wt_txn_set_timestamp(WT_SESSION_IMPL *session, const char *cfg[])
 			    "to set a commit_timestamp");
 		WT_RET(__wt_txn_parse_timestamp(session, "commit", &ts, &cval));
 		WT_RET(__wt_timestamp_validate(session,
-		    &ts, &cval, true, true, true));
+		    "commit", &ts, &cval, true, true, true));
 		__wt_timestamp_set(&txn->commit_timestamp, &ts);
 		__wt_txn_set_commit_timestamp(session);
 #else
diff --git a/test/format/ops.c b/test/format/ops.c
index 607dd43a8f3..4c5576654d2 100644
--- a/test/format/ops.c
+++ b/test/format/ops.c
@@ -499,8 +499,13 @@ commit_transaction(TINFO *tinfo, WT_SESSION *session)
 		testutil_check(
 		    session->commit_transaction(session, config_buf));
 
-		/* After the commit, update our last timestamp. */
-		tinfo->timestamp = ts;
+		/*
+		 * Update the thread's last-committed timestamp. Don't let the
+		 * compiler re-order this statement, if we were to race with
+		 * the timestamp thread, it might see our thread update before
+		 * the transaction commit.
+		 */
+		WT_PUBLISH(tinfo->timestamp, ts);
 	} else
 		testutil_check(session->commit_transaction(session, NULL));
 	++tinfo->commit;
diff --git a/test/format/util.c b/test/format/util.c
index 9ea44a29801..83ddf307cc9 100644
--- a/test/format/util.c
+++ b/test/format/util.c
@@ -607,7 +607,10 @@ timestamp(void *arg)
 	 * once every 15 seconds.
 	 */
 	while (!g.workers_finished) {
-		/* Find the lowest committed timestamp. */
+		/*
+		 * Find the lowest committed timestamp. The timestamp thread
+		 * starts before the operational threads, wait for them.
+		 */
 		oldest_timestamp = UINT64_MAX;
 		for (i = 0; i < g.c_threads; ++i) {
 			tinfo = tinfo_list[i];
@@ -615,15 +618,20 @@ timestamp(void *arg)
 			    tinfo->timestamp < oldest_timestamp)
 				oldest_timestamp = tinfo->timestamp;
 		}
+		if (oldest_timestamp == UINT64_MAX) {
+			__wt_sleep(1, 0);
+			continue;
+		}
 
 		/*
 		 * Don't get more than 100 transactions or more than 15 seconds
 		 * out of date.
 		 */
-		if (oldest_timestamp >= g.timestamp ||
-		    g.timestamp - oldest_timestamp < 100) {
+		WT_READ_BARRIER();
+		testutil_assert(oldest_timestamp <= g.timestamp);
+		if (g.timestamp - oldest_timestamp < 100) {
 			__wt_seconds((WT_SESSION_IMPL *)session, &now);
-			if (g.timestamp == 0 || difftime(now, last) < 15) {
+			if (difftime(now, last) < 15) {
 				__wt_sleep(1, 0);
 				continue;
 			}