WT-2920 New eviction statistics (#3076)

* WT-2920 New eviction statistics

Add "application_eviction" statistic, the usecs application threads
spent doing eviction.

* Add a finer grained timer around eviction as well.

5 files changed, 70 insertions, 32 deletions

diff --git a/dist/stat_data.py b/dist/stat_data.py
index 5087afa44dc..53156985fcd 100644
--- a/dist/stat_data.py
+++ b/dist/stat_data.py
@@ -381,6 +381,8 @@ connection_stats = [
     ##########################################
     # Yield statistics
     ##########################################
+    YieldStat('application_cache_time', 'application thread time waiting for cache (usecs)'),
+    YieldStat('application_evict_time', 'application thread time evicting (usecs)'),
     YieldStat('page_busy_blocked', 'page acquire busy blocked'),
     YieldStat('page_forcible_evict_blocked', 'page acquire eviction blocked'),
     YieldStat('page_locked_blocked', 'page acquire locked blocked'),
diff --git a/src/evict/evict_lru.c b/src/evict/evict_lru.c
index 91cc64e7d27..331467cbcce 100644
--- a/src/evict/evict_lru.c
+++ b/src/evict/evict_lru.c
@@ -1715,15 +1715,19 @@ __evict_get_ref(
 static int
 __evict_page(WT_SESSION_IMPL *session, bool is_server)
 {
+	struct timespec enter, leave;
 	WT_BTREE *btree;
 	WT_CACHE *cache;
 	WT_DECL_RET;
 	WT_REF *ref;
+	bool app_timer;
 
 	WT_RET(__evict_get_ref(session, is_server, &btree, &ref));
 	WT_ASSERT(session, ref->state == WT_REF_LOCKED);
 
+	app_timer = false;
 	cache = S2C(session)->cache;
+
 	/*
 	 * An internal session flags either the server itself or an eviction
 	 * worker thread.
@@ -1739,6 +1743,10 @@ __evict_page(WT_SESSION_IMPL *session, bool is_server)
 			WT_STAT_CONN_INCR(session, cache_eviction_app_dirty);
 		WT_STAT_CONN_INCR(session, cache_eviction_app);
 		cache->app_evicts++;
+		if (WT_STAT_ENABLED(session)) {
+			app_timer = true;
+			WT_RET(__wt_epoch(session, &enter));
+		}
 	}
 
 	/*
@@ -1756,6 +1764,9 @@ __evict_page(WT_SESSION_IMPL *session, bool is_server)
 
 	(void)__wt_atomic_subv32(&btree->evict_busy, 1);
 
+	if (ret == 0 && app_timer && __wt_epoch(session, &leave) == 0)
+		WT_STAT_CONN_INCRV(session,
+		    application_evict_time, WT_TIMEDIFF_US(leave, enter));
 	return (ret);
 }
 
@@ -1767,6 +1778,7 @@ __evict_page(WT_SESSION_IMPL *session, bool is_server)
 int
 __wt_cache_eviction_worker(WT_SESSION_IMPL *session, bool busy, u_int pct_full)
 {
+	struct timespec enter, leave;
 	WT_CACHE *cache;
 	WT_CONNECTION_IMPL *conn;
 	WT_DECL_RET;
@@ -1792,9 +1804,11 @@ __wt_cache_eviction_worker(WT_SESSION_IMPL *session, bool busy, u_int pct_full)
 	/* Wake the eviction server if we need to do work. */
 	__wt_evict_server_wake(session);
 
-	init_evict_count = cache->pages_evict;
+	/* Track how long application threads spend doing eviction. */
+	if (WT_STAT_ENABLED(session) && !F_ISSET(session, WT_SESSION_INTERNAL))
+		WT_RET(__wt_epoch(session, &enter));
 
-	for (;;) {
+	for (init_evict_count = cache->pages_evict;; ret = 0) {
 		/*
 		 * A pathological case: if we're the oldest transaction in the
 		 * system and the eviction server is stuck trying to find space,
@@ -1804,7 +1818,7 @@ __wt_cache_eviction_worker(WT_SESSION_IMPL *session, bool busy, u_int pct_full)
 		if (__wt_cache_stuck(session) && __wt_txn_am_oldest(session)) {
 			--cache->evict_aggressive_score;
 			WT_STAT_CONN_INCR(session, txn_fail_cache);
-			return (WT_ROLLBACK);
+			WT_ERR(WT_ROLLBACK);
 		}
 
 		/*
@@ -1825,7 +1839,7 @@ __wt_cache_eviction_worker(WT_SESSION_IMPL *session, bool busy, u_int pct_full)
 		if (!__wt_eviction_needed(session, busy, &pct_full) ||
 		    (pct_full < 100 &&
 		    cache->pages_evict > init_evict_count + max_pages_evicted))
-			return (0);
+			break;
 
 		/*
 		 * Don't make application threads participate in scrubbing for
@@ -1842,7 +1856,7 @@ __wt_cache_eviction_worker(WT_SESSION_IMPL *session, bool busy, u_int pct_full)
 		switch (ret = __evict_page(session, false)) {
 		case 0:
 			if (busy)
-				return (0);
+				goto err;
 			/* FALLTHROUGH */
 		case EBUSY:
 			break;
@@ -1853,9 +1867,17 @@ __wt_cache_eviction_worker(WT_SESSION_IMPL *session, bool busy, u_int pct_full)
 			cache->app_waits++;
 			break;
 		default:
-			return (ret);
+			goto err;
 		}
 	}
+
+err:	if (WT_STAT_ENABLED(session) &&
+	    !F_ISSET(session, WT_SESSION_INTERNAL) &&
+	    __wt_epoch(session, &leave) == 0)
+		WT_STAT_CONN_INCRV(session,
+		    application_cache_time, WT_TIMEDIFF_US(leave, enter));
+
+	return (ret);
 	/* NOTREACHED */
 }
 
diff --git a/src/include/stat.h b/src/include/stat.h
index cd0cae16826..ca02a070d4d 100644
--- a/src/include/stat.h
+++ b/src/include/stat.h
@@ -420,6 +420,8 @@ struct __wt_connection_stats {
 	int64_t thread_fsync_active;
 	int64_t thread_read_active;
 	int64_t thread_write_active;
+	int64_t application_evict_time;
+	int64_t application_cache_time;
 	int64_t page_busy_blocked;
 	int64_t page_forcible_evict_blocked;
 	int64_t page_locked_blocked;
diff --git a/src/include/wiredtiger.in b/src/include/wiredtiger.in
index c6d9f241a7a..4608277fa0f 100644
--- a/src/include/wiredtiger.in
+++ b/src/include/wiredtiger.in
@@ -4589,67 +4589,71 @@ extern int wiredtiger_extension_terminate(WT_CONNECTION *connection);
 #define	WT_STAT_CONN_THREAD_READ_ACTIVE			1186
 /*! thread-state: active filesystem write calls */
 #define	WT_STAT_CONN_THREAD_WRITE_ACTIVE		1187
+/*! thread-yield: application thread time evicting (usecs) */
+#define	WT_STAT_CONN_APPLICATION_EVICT_TIME		1188
+/*! thread-yield: application thread time waiting for cache (usecs) */
+#define	WT_STAT_CONN_APPLICATION_CACHE_TIME		1189
 /*! thread-yield: page acquire busy blocked */
-#define	WT_STAT_CONN_PAGE_BUSY_BLOCKED			1188
+#define	WT_STAT_CONN_PAGE_BUSY_BLOCKED			1190
 /*! thread-yield: page acquire eviction blocked */
-#define	WT_STAT_CONN_PAGE_FORCIBLE_EVICT_BLOCKED	1189
+#define	WT_STAT_CONN_PAGE_FORCIBLE_EVICT_BLOCKED	1191
 /*! thread-yield: page acquire locked blocked */
-#define	WT_STAT_CONN_PAGE_LOCKED_BLOCKED		1190
+#define	WT_STAT_CONN_PAGE_LOCKED_BLOCKED		1192
 /*! thread-yield: page acquire read blocked */
-#define	WT_STAT_CONN_PAGE_READ_BLOCKED			1191
+#define	WT_STAT_CONN_PAGE_READ_BLOCKED			1193
 /*! thread-yield: page acquire time sleeping (usecs) */
-#define	WT_STAT_CONN_PAGE_SLEEP				1192
+#define	WT_STAT_CONN_PAGE_SLEEP				1194
 /*! transaction: number of named snapshots created */
-#define	WT_STAT_CONN_TXN_SNAPSHOTS_CREATED		1193
+#define	WT_STAT_CONN_TXN_SNAPSHOTS_CREATED		1195
 /*! transaction: number of named snapshots dropped */
-#define	WT_STAT_CONN_TXN_SNAPSHOTS_DROPPED		1194
+#define	WT_STAT_CONN_TXN_SNAPSHOTS_DROPPED		1196
 /*! transaction: transaction begins */
-#define	WT_STAT_CONN_TXN_BEGIN				1195
+#define	WT_STAT_CONN_TXN_BEGIN				1197
 /*! transaction: transaction checkpoint currently running */
-#define	WT_STAT_CONN_TXN_CHECKPOINT_RUNNING		1196
+#define	WT_STAT_CONN_TXN_CHECKPOINT_RUNNING		1198
 /*! transaction: transaction checkpoint generation */
-#define	WT_STAT_CONN_TXN_CHECKPOINT_GENERATION		1197
+#define	WT_STAT_CONN_TXN_CHECKPOINT_GENERATION		1199
 /*! transaction: transaction checkpoint max time (msecs) */
-#define	WT_STAT_CONN_TXN_CHECKPOINT_TIME_MAX		1198
+#define	WT_STAT_CONN_TXN_CHECKPOINT_TIME_MAX		1200
 /*! transaction: transaction checkpoint min time (msecs) */
-#define	WT_STAT_CONN_TXN_CHECKPOINT_TIME_MIN		1199
+#define	WT_STAT_CONN_TXN_CHECKPOINT_TIME_MIN		1201
 /*! transaction: transaction checkpoint most recent time (msecs) */
-#define	WT_STAT_CONN_TXN_CHECKPOINT_TIME_RECENT		1200
+#define	WT_STAT_CONN_TXN_CHECKPOINT_TIME_RECENT		1202
 /*! transaction: transaction checkpoint scrub dirty target */
-#define	WT_STAT_CONN_TXN_CHECKPOINT_SCRUB_TARGET	1201
+#define	WT_STAT_CONN_TXN_CHECKPOINT_SCRUB_TARGET	1203
 /*! transaction: transaction checkpoint scrub time (msecs) */
-#define	WT_STAT_CONN_TXN_CHECKPOINT_SCRUB_TIME		1202
+#define	WT_STAT_CONN_TXN_CHECKPOINT_SCRUB_TIME		1204
 /*! transaction: transaction checkpoint total time (msecs) */
-#define	WT_STAT_CONN_TXN_CHECKPOINT_TIME_TOTAL		1203
+#define	WT_STAT_CONN_TXN_CHECKPOINT_TIME_TOTAL		1205
 /*! transaction: transaction checkpoints */
-#define	WT_STAT_CONN_TXN_CHECKPOINT			1204
+#define	WT_STAT_CONN_TXN_CHECKPOINT			1206
 /*! transaction: transaction failures due to cache overflow */
-#define	WT_STAT_CONN_TXN_FAIL_CACHE			1205
+#define	WT_STAT_CONN_TXN_FAIL_CACHE			1207
 /*!
  * transaction: transaction fsync calls for checkpoint after allocating
  * the transaction ID
  */
-#define	WT_STAT_CONN_TXN_CHECKPOINT_FSYNC_POST		1206
+#define	WT_STAT_CONN_TXN_CHECKPOINT_FSYNC_POST		1208
 /*!
  * transaction: transaction fsync duration for checkpoint after
  * allocating the transaction ID (usecs)
  */
-#define	WT_STAT_CONN_TXN_CHECKPOINT_FSYNC_POST_DURATION	1207
+#define	WT_STAT_CONN_TXN_CHECKPOINT_FSYNC_POST_DURATION	1209
 /*! transaction: transaction range of IDs currently pinned */
-#define	WT_STAT_CONN_TXN_PINNED_RANGE			1208
+#define	WT_STAT_CONN_TXN_PINNED_RANGE			1210
 /*! transaction: transaction range of IDs currently pinned by a checkpoint */
-#define	WT_STAT_CONN_TXN_PINNED_CHECKPOINT_RANGE	1209
+#define	WT_STAT_CONN_TXN_PINNED_CHECKPOINT_RANGE	1211
 /*!
  * transaction: transaction range of IDs currently pinned by named
  * snapshots
  */
-#define	WT_STAT_CONN_TXN_PINNED_SNAPSHOT_RANGE		1210
+#define	WT_STAT_CONN_TXN_PINNED_SNAPSHOT_RANGE		1212
 /*! transaction: transaction sync calls */
-#define	WT_STAT_CONN_TXN_SYNC				1211
+#define	WT_STAT_CONN_TXN_SYNC				1213
 /*! transaction: transactions committed */
-#define	WT_STAT_CONN_TXN_COMMIT				1212
+#define	WT_STAT_CONN_TXN_COMMIT				1214
 /*! transaction: transactions rolled back */
-#define	WT_STAT_CONN_TXN_ROLLBACK			1213
+#define	WT_STAT_CONN_TXN_ROLLBACK			1215
 
 /*!
  * @}
diff --git a/src/support/stat.c b/src/support/stat.c
index 7150223e6cb..fd833446e60 100644
--- a/src/support/stat.c
+++ b/src/support/stat.c
@@ -706,6 +706,8 @@ static const char * const __stats_connection_desc[] = {
 	"thread-state: active filesystem fsync calls",
 	"thread-state: active filesystem read calls",
 	"thread-state: active filesystem write calls",
+	"thread-yield: application thread time evicting (usecs)",
+	"thread-yield: application thread time waiting for cache (usecs)",
 	"thread-yield: page acquire busy blocked",
 	"thread-yield: page acquire eviction blocked",
 	"thread-yield: page acquire locked blocked",
@@ -950,6 +952,8 @@ __wt_stat_connection_clear_single(WT_CONNECTION_STATS *stats)
 		/* not clearing thread_fsync_active */
 		/* not clearing thread_read_active */
 		/* not clearing thread_write_active */
+	stats->application_evict_time = 0;
+	stats->application_cache_time = 0;
 	stats->page_busy_blocked = 0;
 	stats->page_forcible_evict_blocked = 0;
 	stats->page_locked_blocked = 0;
@@ -1242,6 +1246,10 @@ __wt_stat_connection_aggregate(
 	to->thread_fsync_active += WT_STAT_READ(from, thread_fsync_active);
 	to->thread_read_active += WT_STAT_READ(from, thread_read_active);
 	to->thread_write_active += WT_STAT_READ(from, thread_write_active);
+	to->application_evict_time +=
+	    WT_STAT_READ(from, application_evict_time);
+	to->application_cache_time +=
+	    WT_STAT_READ(from, application_cache_time);
 	to->page_busy_blocked += WT_STAT_READ(from, page_busy_blocked);
 	to->page_forcible_evict_blocked +=
 	    WT_STAT_READ(from, page_forcible_evict_blocked);