Import wiredtiger: 723f5e15d49dbe2caf944ed270b4f22b4fd282d6 from branch mongodb-master

ref: a7f6fa07f9..723f5e15d4
for: 6.3.0-rc0

WT-10197 Track eviction timeline

Author: lukech

src/third_party/wiredtiger/dist/stat_data.py

@@ -265,7 +265,8 @@ def __init__(self, name, desc, flags=''):
     CacheStat('cache_eviction_internal_pages_already_queued', 'internal pages seen by eviction walk that are already queued'),
     CacheStat('cache_eviction_internal_pages_queued', 'internal pages queued for eviction'),
     CacheStat('cache_eviction_internal_pages_seen', 'internal pages seen by eviction walk'),
-    CacheStat('cache_eviction_maximum_page_size', 'maximum page size at eviction', 'no_clear,no_scale,size'),
+    CacheStat('cache_eviction_maximum_page_size', 'maximum page size seen at eviction', 'no_clear,no_scale,size'),
+    CacheStat('cache_eviction_maximum_seconds', 'maximum seconds spent at a single eviction', 'no_clear,no_scale,size'),
     CacheStat('cache_eviction_pages_already_queued', 'pages seen by eviction walk that are already queued'),
     CacheStat('cache_eviction_pages_in_parallel_with_checkpoint', 'pages evicted in parallel with checkpoint'),
     CacheStat('cache_eviction_pages_queued', 'pages queued for eviction'),
@@ -499,6 +500,8 @@ def __init__(self, name, desc, flags=''):
     ##########################################
     # Reconciliation statistics
     ##########################################
+    RecStat('rec_maximum_hs_wrapup_seconds', 'maximum seconds spent in moving updates to the history store in a reconciliation', 'no_clear,no_scale,size'),
+    RecStat('rec_maximum_image_build_seconds', 'maximum seconds spent in building a disk image in a reconciliation', 'no_clear,no_scale,size'),
     RecStat('rec_maximum_seconds', 'maximum seconds spent in a reconciliation call', 'no_clear,no_scale,size'),
     RecStat('rec_overflow_key_leaf', 'leaf-page overflow keys'),
     RecStat('rec_pages_with_prepare', 'page reconciliation calls that resulted in values with prepared transaction metadata'),

src/third_party/wiredtiger/import.data

@@ -2,5 +2,5 @@
     "vendor": "wiredtiger",
     "github": "wiredtiger/wiredtiger.git",
     "branch": "mongodb-master",
-    "commit": "a7f6fa07f90d701b73206a768ae0cc6fb50ff9b4"
+    "commit": "723f5e15d49dbe2caf944ed270b4f22b4fd282d6"
 }

src/third_party/wiredtiger/src/conn/conn_cache.c

@@ -320,6 +320,7 @@ __wt_cache_stats_update(WT_SESSION_IMPL *session)
     WT_STAT_SET(session, stats, cache_bytes_updates, __wt_cache_bytes_updates(cache));
 
     WT_STAT_SET(session, stats, cache_eviction_maximum_page_size, cache->evict_max_page_size);
+    WT_STAT_SET(session, stats, cache_eviction_maximum_seconds, cache->evict_max_seconds);
     WT_STAT_SET(
       session, stats, cache_pages_dirty, cache->pages_dirty_intl + cache->pages_dirty_leaf);
 
@@ -338,6 +339,9 @@ __wt_cache_stats_update(WT_SESSION_IMPL *session)
     if (conn->evict_server_running)
         WT_STAT_SET(session, stats, cache_eviction_walks_active, cache->walk_session->nhazard);
 
+    WT_STAT_SET(session, stats, rec_maximum_hs_wrapup_seconds, conn->rec_maximum_hs_wrapup_seconds);
+    WT_STAT_SET(
+      session, stats, rec_maximum_image_build_seconds, conn->rec_maximum_image_build_seconds);
     WT_STAT_SET(session, stats, rec_maximum_seconds, conn->rec_maximum_seconds);
 }
 

src/third_party/wiredtiger/src/evict/evict_page.c

@@ -104,14 +104,15 @@ __wt_evict(WT_SESSION_IMPL *session, WT_REF *ref, uint8_t previous_state, uint32
     WT_CONNECTION_IMPL *conn;
     WT_DECL_RET;
     WT_PAGE *page;
-    uint64_t time_start, time_stop;
+    uint64_t eviction_time, eviction_time_seconds;
     bool clean_page, closing, force_evict_hs, inmem_split, local_gen, tree_dead;
 
     conn = S2C(session);
     page = ref->page;
     closing = LF_ISSET(WT_EVICT_CALL_CLOSING);
     force_evict_hs = false;
     local_gen = false;
+    eviction_time = eviction_time_seconds = 0;
 
     __wt_verbose(
       session, WT_VERB_EVICT, "page %p (%s)", (void *)page, __wt_page_type_string(page->type));
@@ -129,13 +130,14 @@ __wt_evict(WT_SESSION_IMPL *session, WT_REF *ref, uint8_t previous_state, uint32
         __wt_session_gen_enter(session, WT_GEN_EVICT);
     }
 
+    WT_CLEAR(session->reconcile_timeline);
+    WT_CLEAR(session->evict_timeline);
+    session->evict_timeline.evict_start = __wt_clock(session);
     /*
-     * Track how long forcible eviction took. Immediately increment the forcible eviction counter,
-     * we might do an in-memory split and not an eviction, which skips the other statistics.
+     * Immediately increment the forcible eviction counter, we might do an in-memory split and not
+     * an eviction, which skips the other statistics.
      */
-    time_start = 0;
     if (LF_ISSET(WT_EVICT_CALL_URGENT)) {
-        time_start = __wt_clock(session);
         WT_STAT_CONN_INCR(session, cache_eviction_force);
 
         /*
@@ -227,19 +229,18 @@ __wt_evict(WT_SESSION_IMPL *session, WT_REF *ref, uint8_t previous_state, uint32
      * We have loaded the new disk image and updated the tree structure. We can no longer fail after
      * this point.
      */
-
-    if (time_start != 0) {
-        time_stop = __wt_clock(session);
+    session->evict_timeline.evict_finish = __wt_clock(session);
+    eviction_time =
+      WT_CLOCKDIFF_US(session->evict_timeline.evict_finish, session->evict_timeline.evict_start);
+    if (LF_ISSET(WT_EVICT_CALL_URGENT)) {
         if (force_evict_hs)
             WT_STAT_CONN_INCR(session, cache_eviction_force_hs_success);
         if (clean_page) {
             WT_STAT_CONN_INCR(session, cache_eviction_force_clean);
-            WT_STAT_CONN_INCRV(
-              session, cache_eviction_force_clean_time, WT_CLOCKDIFF_US(time_stop, time_start));
+            WT_STAT_CONN_INCRV(session, cache_eviction_force_clean_time, eviction_time);
         } else {
             WT_STAT_CONN_INCR(session, cache_eviction_force_dirty);
-            WT_STAT_CONN_INCRV(
-              session, cache_eviction_force_dirty_time, WT_CLOCKDIFF_US(time_stop, time_start));
+            WT_STAT_CONN_INCRV(session, cache_eviction_force_dirty_time, eviction_time);
         }
     }
     if (clean_page)
@@ -255,20 +256,32 @@ __wt_evict(WT_SESSION_IMPL *session, WT_REF *ref, uint8_t previous_state, uint32
 err:
         if (!closing)
             __evict_exclusive_clear(session, ref, previous_state);
-
-        if (time_start != 0) {
-            time_stop = __wt_clock(session);
+        session->evict_timeline.evict_finish = __wt_clock(session);
+        eviction_time = WT_CLOCKDIFF_US(
+          session->evict_timeline.evict_finish, session->evict_timeline.evict_start);
+        if (LF_ISSET(WT_EVICT_CALL_URGENT)) {
             if (force_evict_hs)
                 WT_STAT_CONN_INCR(session, cache_eviction_force_hs_fail);
             WT_STAT_CONN_INCR(session, cache_eviction_force_fail);
-            WT_STAT_CONN_INCRV(
-              session, cache_eviction_force_fail_time, WT_CLOCKDIFF_US(time_stop, time_start));
+            WT_STAT_CONN_INCRV(session, cache_eviction_force_fail_time, eviction_time);
         }
 
         WT_STAT_CONN_DATA_INCR(session, cache_eviction_fail);
     }
 
 done:
+    eviction_time_seconds = eviction_time / WT_MILLION;
+    if (eviction_time_seconds > conn->cache->evict_max_seconds)
+        conn->cache->evict_max_seconds = eviction_time_seconds;
+    if (eviction_time_seconds > 60)
+        __wt_verbose_warning(session, WT_VERB_EVICT,
+          "Eviction took more than 1 minute (%" PRIu64 "). Building disk image took %" PRIu64
+          "us. History store wrapup took %" PRIu64 "us.",
+          eviction_time,
+          WT_CLOCKDIFF_US(session->reconcile_timeline.image_build_finish,
+            session->reconcile_timeline.image_build_start),
+          WT_CLOCKDIFF_US(session->reconcile_timeline.hs_wrapup_finish,
+            session->reconcile_timeline.hs_wrapup_start));
     /* Leave any local eviction generation. */
     if (local_gen)
         __wt_session_gen_leave(session, WT_GEN_EVICT);

src/third_party/wiredtiger/src/include/cache.h

@@ -98,6 +98,7 @@ struct __wt_cache {
     uint64_t app_evicts; /* Pages evicted by user threads */
 
     uint64_t evict_max_page_size; /* Largest page seen at eviction */
+    uint64_t evict_max_seconds;   /* Longest seconds spent at a single eviction */
     struct timespec stuck_time;   /* Stuck time */
 
     /*

src/third_party/wiredtiger/src/include/connection.h

@@ -414,7 +414,10 @@ struct __wt_connection_impl {
     uint32_t stat_flags; /* Options declared in flags.py */
 
     /* Connection statistics */
-    uint64_t rec_maximum_seconds; /* Maximum seconds reconciliation took. */
+    uint64_t
+      rec_maximum_hs_wrapup_seconds; /* Maximum seconds moving updates to history store took. */
+    uint64_t rec_maximum_image_build_seconds; /* Maximum seconds building disk image took. */
+    uint64_t rec_maximum_seconds;             /* Maximum seconds reconciliation took. */
     WT_CONNECTION_STATS *stats[WT_COUNTER_SLOTS];
     WT_CONNECTION_STATS *stat_array;
 

src/third_party/wiredtiger/src/include/session.h

@@ -141,6 +141,25 @@ struct __wt_session_impl {
     } * scratch_track;
 #endif
 
+    /* Record the important timestamps of each stage in an reconciliation. */
+    struct __wt_reconcile_timeline {
+        uint64_t reconcile_start;
+        uint64_t image_build_start;
+        uint64_t image_build_finish;
+        uint64_t hs_wrapup_start;
+        uint64_t hs_wrapup_finish;
+        uint64_t reconcile_finish;
+    } reconcile_timeline;
+
+    /*
+     * Record the important timestamps of each stage in an eviction. If an eviction takes a long
+     * time and times out, we can trace the time usage of each stage from this information.
+     */
+    struct __wt_evict_timeline {
+        uint64_t evict_start;
+        uint64_t evict_finish;
+    } evict_timeline;
+
     WT_ITEM err; /* Error buffer */
 
     WT_TXN_ISOLATION isolation;

src/third_party/wiredtiger/src/include/stat.h

@@ -487,6 +487,7 @@ struct __wt_connection_stats {
     int64_t cache_eviction_split_leaf;
     int64_t cache_bytes_max;
     int64_t cache_eviction_maximum_page_size;
+    int64_t cache_eviction_maximum_seconds;
     int64_t cache_eviction_dirty;
     int64_t cache_eviction_app_dirty;
     int64_t cache_timed_out_ops;
@@ -743,6 +744,8 @@ struct __wt_connection_stats {
     int64_t rec_page_delete_fast;
     int64_t rec_overflow_key_leaf;
     int64_t rec_maximum_seconds;
+    int64_t rec_maximum_image_build_seconds;
+    int64_t rec_maximum_hs_wrapup_seconds;
     int64_t rec_pages;
     int64_t rec_pages_eviction;
     int64_t rec_pages_with_prepare;