Optionally dump statistics for a list of objects as part of statistics

logging.

10 files changed, 162 insertions, 42 deletions

diff --git a/dist/api_data.py b/dist/api_data.py
index 4ab749a8e32..de2655492f6 100644
--- a/dist/api_data.py
+++ b/dist/api_data.py
@@ -578,6 +578,11 @@ methods = {
 		Config('clear', 'true', r'''
 		reset statistics counters after each set of log records are
 		written''', type='boolean'),
+		Config('objects', '', r'''
+		if non-empty, include statistics for the list of objects.  No
+		statistics that require traversing a tree are reported, as if
+		the \c statistics_fast configuration string were set''',
+		type='list'),
 		Config('path', '"WiredTigerStat.%H"', r'''
 		the pathname to a file into which the log records are written,
 		may contain strftime conversion specifications.  If the value
diff --git a/examples/c/ex_all.c b/examples/c/ex_all.c
index 8ca118649a5..69f9c8ca27a 100644
--- a/examples/c/ex_all.c
+++ b/examples/c/ex_all.c
@@ -1113,6 +1113,15 @@ main(void)
 	if (ret == 0)
 		(void)conn->close(conn, NULL);
 
+	/*! [Statistics logging with objects] */
+	ret = wiredtiger_open(home, NULL,
+	    "create,"
+	    "statistics_log=(objects=(\"table:table1\",\"table:table2\"))",
+	    &conn);
+	/*! [Statistics logging with objects] */
+	if (ret == 0)
+		(void)conn->close(conn, NULL);
+
 #ifdef MIGHT_NOT_RUN
 	/*
 	 * This example code gets run, and a non-existent log file path might
diff --git a/src/config/config_def.c b/src/config/config_def.c
index fda40121674..7a863e1bc54 100644
--- a/src/config/config_def.c
+++ b/src/config/config_def.c
@@ -424,9 +424,9 @@ __wt_confdfl_wiredtiger_open =
 	",eviction_trigger=95,extensions=,hazard_max=1000,logging=0,"
 	"lsm_merge=,mmap=,multiprocess=0,session_max=50,"
 	"shared_cache=(chunk=10MB,name=pool,reserve=0,size=500MB),"
-	"statistics=0,statistics_log=(clear=,path=\"WiredTigerStat.%H\","
-	"timestamp=\"%b %d %H:%M:%S\",wait=0),sync=,transactional=,"
-	"use_environment_priv=0,verbose=";
+	"statistics=0,statistics_log=(clear=,objects=,"
+	"path=\"WiredTigerStat.%H\",timestamp=\"%b %d %H:%M:%S\",wait=0),"
+	"sync=,transactional=,use_environment_priv=0,verbose=";
 
 WT_CONFIG_CHECK
 __wt_confchk_checkpoint_subconfigs[] = {
@@ -438,6 +438,7 @@ __wt_confchk_checkpoint_subconfigs[] = {
 WT_CONFIG_CHECK
 __wt_confchk_statistics_log_subconfigs[] = {
 	{ "clear", "boolean", NULL, NULL },
+	{ "objects", "list", NULL, NULL },
 	{ "path", "string", NULL, NULL },
 	{ "timestamp", "string", NULL, NULL },
 	{ "wait", "int", "min=5,max=100000", NULL },
diff --git a/src/conn/conn_stat.c b/src/conn/conn_stat.c
index a24c3055422..85fa076d86e 100644
--- a/src/conn/conn_stat.c
+++ b/src/conn/conn_stat.c
@@ -35,8 +35,11 @@ __wt_conn_stat_init(WT_SESSION_IMPL *session, uint32_t flags)
 static int
 __statlog_config(WT_SESSION_IMPL *session, const char **cfg, int *runp)
 {
-	WT_CONFIG_ITEM cval;
+	WT_CONFIG objectconf;
+	WT_CONFIG_ITEM cval, k, v;
 	WT_CONNECTION_IMPL *conn;
+	WT_DECL_RET;
+	int cnt;
 
 	conn = S2C(session);
 
@@ -57,6 +60,40 @@ __statlog_config(WT_SESSION_IMPL *session, const char **cfg, int *runp)
 	WT_RET(__wt_config_gets(session, cfg, "statistics_log.clear", &cval));
 	conn->stat_clear = cval.val != 0;
 
+	WT_RET(__wt_config_gets(session, cfg, "statistics_log.objects", &cval));
+	WT_RET(__wt_config_subinit(session, &objectconf, &cval));
+	for (cnt = 0; (ret = __wt_config_next(&objectconf, &k, &v)) == 0; ++cnt)
+		;
+	WT_RET_NOTFOUND_OK(ret);
+	if (cnt != 0) {
+		WT_RET(
+		    __wt_calloc_def(session, cnt * 2 + 1, &conn->stat_objects));
+		WT_RET(__wt_config_subinit(session, &objectconf, &cval));
+		for (cnt = 0;
+		    (ret = __wt_config_next(&objectconf, &k, &v)) == 0;) {
+			/*
+			 * We close and re-open each statistics cursor each time
+			 * we dump statistics (the object may or may not exist
+			 * underneath at any point, and I don't want this code
+			 * to break if/when the lifetime of an underlying object
+			 * changes).  Create pairs of strings: the first is the
+			 * object uri, written into the output, the second is
+			 * the enhanced uri used to open the statistics cursor.
+			 */
+			WT_RET(__wt_strndup(session,
+			    k.str, k.len, &conn->stat_objects[cnt]));
+			++cnt;
+
+			WT_RET(__wt_calloc_def(session,
+			    strlen("statistics:") + k.len + 1,
+			    &conn->stat_objects[cnt]));
+			strcpy(conn->stat_objects[cnt], "statistics:");
+			strncat(conn->stat_objects[cnt], k.str, k.len);
+			++cnt;
+		}
+		WT_RET_NOTFOUND_OK(ret);
+	}
+
 	WT_RET(__wt_config_gets(session, cfg, "statistics_log.path", &cval));
 	WT_RET(__wt_nfilename(session, cval.str, cval.len, &conn->stat_path));
 
@@ -68,6 +105,48 @@ __statlog_config(WT_SESSION_IMPL *session, const char **cfg, int *runp)
 }
 
 /*
+ * __stat_server_dump --
+ *	Dump a single set of statistics.
+ */
+static int
+__stat_server_dump(WT_SESSION_IMPL *session,
+    const char *name, const char *cursor_uri, const char *stamp, FILE *fp)
+{
+	WT_CURSOR *cursor;
+	WT_DECL_RET;
+	WT_SESSION *wt_session;
+	uint64_t value;
+	const char *config, *desc, *pdesc;
+
+	wt_session = (WT_SESSION *)session;
+	config = S2C(session)->stat_clear ?
+	    "statistics_clear,statistics_fast" : "statistics_fast";
+
+	/*
+	 * If we don't find an underlying object, silently ignore it, the object
+	 * may exist only intermittently.  User-level APIs return ENOENT instead
+	 * of WT_NOTFOUND for missing files, check both, as well as for EBUSY if
+	 * the handle is exclusively locked at the moment.
+	 */
+	ret = wt_session->open_cursor(
+	    wt_session, cursor_uri, NULL, config, &cursor);
+	if (ret == EBUSY || ret == ENOENT || ret == WT_NOTFOUND)
+		return (0);
+	WT_RET(ret);
+
+	while ((ret = cursor->next(cursor)) == 0 &&
+	    (ret = cursor->get_value(cursor, &desc, &pdesc, &value)) == 0)
+		WT_ERR_TEST((fprintf(fp,
+		    "%s %" PRIu64 " %s %s\n",
+		    stamp, value, name, desc) < 0), __wt_errno());
+	WT_ERR_NOTFOUND_OK(ret);
+
+err:	WT_TRET(cursor->close(cursor));
+
+	return (ret);
+}
+
+/*
  * __stat_server --
  *	The statistics server thread.
  */
@@ -78,21 +157,16 @@ __stat_server(void *arg)
 	struct tm *tm, _tm;
 	FILE *fp;
 	WT_CONNECTION_IMPL *conn;
-	WT_CURSOR *cursor;
 	WT_ITEM path, tmp;
 	WT_DECL_RET;
-	WT_SESSION *wt_session;
 	WT_SESSION_IMPL *session;
-	uint64_t value;
-	const char *config, *desc, *pdesc;
+	char **p;
 
 	session = arg;
 	conn = S2C(session);
-	wt_session = (WT_SESSION *)session;
 
 	WT_CLEAR(path);
 	WT_CLEAR(tmp);
-	config = conn->stat_clear ? "statistics_clear" : NULL;
 	fp = NULL;
 
 	/*
@@ -152,17 +226,17 @@ __stat_server(void *arg)
 			WT_ERR_MSG(
 			    session, ENOMEM, "strftime timestamp conversion");
 
-		/* Dump the statistics. */
-		WT_ERR(wt_session->open_cursor(
-		    wt_session, "statistics:", NULL, config, &cursor));
-		while ((ret = cursor->next(cursor)) == 0 &&
-		    (ret =
-		    cursor->get_value(cursor, &desc, &pdesc, &value)) == 0)
-			WT_ERR_TEST((fprintf(fp,
-			    "%s %" PRIu64 " %s\n",
-			    (char *)tmp.mem, value, desc) < 0), __wt_errno());
-		WT_ERR_NOTFOUND_OK(ret);
-		WT_ERR(cursor->close(cursor));
+		/* Dump the connection statistics. */
+		WT_ERR(__stat_server_dump(
+		    session, conn->home, "statistics:", tmp.mem, fp));
+
+		/* Dump the object list statistics. */
+		if ((p = conn->stat_objects) != NULL)
+			for (; *p != NULL; p += 2)
+				WT_ERR(__stat_server_dump(
+				    session, p[0], p[1], tmp.mem, fp));
+
+		/* Flush. */
 		WT_ERR(fflush(fp) == 0 ? 0 : __wt_errno());
 
 		/* Wait until the next event. */
@@ -233,6 +307,7 @@ __wt_statlog_destroy(WT_CONNECTION_IMPL *conn)
 	WT_DECL_RET;
 	WT_SESSION *wt_session;
 	WT_SESSION_IMPL *session;
+	char **p;
 
 	session = conn->default_session;
 
@@ -244,6 +319,11 @@ __wt_statlog_destroy(WT_CONNECTION_IMPL *conn)
 	if (conn->stat_cond != NULL)
 		WT_TRET(__wt_cond_destroy(session, conn->stat_cond));
 
+	if ((p = conn->stat_objects) != NULL) {
+		for (; *p != NULL; ++p)
+			__wt_free(session, *p);
+		__wt_free(session, conn->stat_objects);
+	}
 	__wt_free(session, conn->stat_path);
 	__wt_free(session, conn->stat_stamp);
 
diff --git a/src/docs/spell.ok b/src/docs/spell.ok
index 3aff5b4dedc..62551104925 100644
--- a/src/docs/spell.ok
+++ b/src/docs/spell.ok
@@ -205,6 +205,7 @@ mutexes
 mutexing
 mvcc
 mygcc
+mytable
 namespace
 ndary
 ndbm
diff --git a/src/docs/statistics.dox b/src/docs/statistics.dox
index e14b82dc8db..0258ae2d59d 100644
--- a/src/docs/statistics.dox
+++ b/src/docs/statistics.dox
@@ -20,23 +20,42 @@ The following example logs statistics every 30 seconds:
 
 @snippet ex_all.c Statistics logging
 
-Each statistics record is formatted as a space-separated timestamp,
-unsigned 64-bit value and a variable length string which describes
-the statistic.  For example:
-
-@code
-Mar 08 11:38:23 463 pthread mutex condition wait calls
-Mar 08 11:38:23 0 files currently open
-Mar 08 11:38:23 1855437 total heap memory allocations
-Mar 08 11:38:23 1856622 total heap memory frees
-Mar 08 11:38:23 1 total heap memory re-allocations
-Mar 08 11:38:23 472 total read I/Os
-@endcode
+Each record is formatted as a space-separated timestamp, unsigned 64-bit
+value and a variable length string which describes the statistic.
 
 The timestamp format may be changed with the \c statistics_log.timestamp
 configuration string.  The \c timestamp value may contain ISO C90 standard
 strftime conversion specifications.
 
+By default, only the system's connection statistics are logged, but
+statistics may be optionally reported for underlying objects by adding
+a list of URIs to the \c statistics_log configuration string:
+
+@snippet ex_all.c Statistics logging with objects
+
+When database statistics are logged, the database home will be the first
+space-separated entry for each record in the log file.  For example:
+
+@code
+Mar 08 11:38:23 463 /database/home pthread mutex condition wait calls
+Mar 08 11:38:23 0 /database/home files currently open
+Mar 08 11:38:23 1855437 /database/home total heap memory allocations
+Mar 08 11:38:23 1856622 /database/home total heap memory frees
+Mar 08 11:38:23 1 /database/home total heap memory re-allocations
+Mar 08 11:38:23 472 /database/home total read I/Os
+@endcode
+
+When object statistics are logged, the object URI will be the first
+space-separated entry for each record in the log file.  For example:
+
+@code
+Mar 20 10:42:36 21 table:mytable compressed pages written
+Mar 20 10:42:36 0 table:mytable page written failed to compress
+Mar 20 10:42:36 5 table:mytable page written was too small to compress
+Mar 20 10:42:36 586 table:mytable cursor insert calls
+Mar 20 10:42:36 0 table:mytable bulk-loaded cursor-insert calls
+@endcode
+
 The location of the log files may be changed with the \c statistics_log.path
 configuration string.  The \c path value value may contain ISO C90 standard
 strftime conversion specifications.  WiredTiger will not create non-existent
diff --git a/src/include/connection.h b/src/include/connection.h
index 3bc1f500307..44bce3c2a17 100644
--- a/src/include/connection.h
+++ b/src/include/connection.h
@@ -148,6 +148,7 @@ struct __wt_connection_impl {
 	int		 stat_tid_set;	/* Statistics log thread set */
 	WT_CONDVAR	*stat_cond;	/* Statistics log wait mutex */
 	int		 stat_clear;	/* Statistics log clear */
+	char	       **stat_objects;	/* Statistics list of objects */
 	const char	*stat_path;	/* Statistics log path format */
 	const char	*stat_stamp;	/* Statistics log timestamp format */
 	long		 stat_usecs;	/* Statistics log period */
diff --git a/src/include/wiredtiger.in b/src/include/wiredtiger.in
index 6e79243d72f..209185f21e5 100644
--- a/src/include/wiredtiger.in
+++ b/src/include/wiredtiger.in
@@ -1305,12 +1305,15 @@ struct __wt_connection {
  * statistics_log for more information.,a set of related configuration options
  * defined below.}@config{&nbsp;&nbsp;&nbsp;&nbsp;clear, reset statistics
  * counters after each set of log records are written.,a boolean flag; default
- * \c true.}@config{&nbsp;&nbsp;&nbsp;&nbsp;path, the pathname to a file into
- * which the log records are written\, may contain strftime conversion
- * specifications.  If the value is not an absolute path name\, the file is
- * created relative to the database home.,a string; default \c
- * "WiredTigerStat.%H".}@config{&nbsp;&nbsp;&nbsp;&nbsp;timestamp, a timestamp
- * prepended to each log record\, may contain strftime conversion
+ * \c true.}@config{&nbsp;&nbsp;&nbsp;&nbsp;objects, if non-empty\, include
+ * statistics for the list of objects.  No statistics that require traversing a
+ * tree are reported\, as if the \c statistics_fast configuration string were
+ * set.,a list of strings; default empty.}@config{&nbsp;&nbsp;&nbsp;&nbsp;path,
+ * the pathname to a file into which the log records are written\, may contain
+ * strftime conversion specifications.  If the value is not an absolute path
+ * name\, the file is created relative to the database home.,a string; default
+ * \c "WiredTigerStat.%H".}@config{&nbsp;&nbsp;&nbsp;&nbsp;timestamp, a
+ * timestamp prepended to each log record\, may contain strftime conversion
  * specifications.,a string; default \c "%b %d
  * %H:%M:%S".}@config{&nbsp;&nbsp;&nbsp;&nbsp;wait, seconds to wait between each
  * write of the log records; setting this value configures \c statistics and
diff --git a/test/format/wts.c b/test/format/wts.c
index f67d5e4d514..31a8f1b5e85 100644
--- a/test/format/wts.c
+++ b/test/format/wts.c
@@ -78,7 +78,7 @@ wts_open(void)
 	    "create,cache_size=%" PRIu32 "MB,"
 	    "error_prefix=\"%s\","
 	    "extensions=[\"%s\", \"%s\", \"%s\", \"%s\", \"%s\"],%s,%s,"
-	    "statistics=true,statistics_log=(wait=5),"
+	    "statistics=true,statistics_log=(objects=(\"%s\"),wait=5),"
 	    "sync=false,",
 	    g.c_cache,
 	    g.progname,
@@ -89,7 +89,8 @@ wts_open(void)
 	    access(BZIP_PATH, R_OK) == 0) ? RAW_PATH : "",
 	    access(SNAPPY_PATH, R_OK) == 0 ? SNAPPY_PATH : "",
 	    g.c_config_open == NULL ? "" : g.c_config_open,
-	    g.config_open == NULL ? "" : g.config_open);
+	    g.config_open == NULL ? "" : g.config_open,
+	    g.uri);
 
 	if ((ret =
 	    wiredtiger_open("RUNDIR", &event_handler, config, &conn)) != 0)
diff --git a/tools/statlog.py b/tools/statlog.py
index 2ca04c30a62..79e50a21c46 100644
--- a/tools/statlog.py
+++ b/tools/statlog.py
@@ -32,7 +32,7 @@ from subprocess import call
 
 # Plot a set of entries for a title.
 def plot(title, entries, num):
-    # Ignore entries with identical values.
+    # Ignore entries where the value never changes.
     skip = 1
     v = entries[0][1]
     for entry in entries: