kudu-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From a...@apache.org
Subject [4/4] kudu git commit: KUDU-1442 log number of open log block containers
Date Sat, 10 Jun 2017 00:29:23 GMT
KUDU-1442 log number of open log block containers

Tservers with large numbers of log block containers can appear to
hang for a long time without logging anything during initialization.
This commit adds a log message every 10 seconds per data dir thread
stating how many containers have been opened.

No automated tests were added because this change only affects the
contents of INFO logs, and no existing log block manager tests check
log output. It was tested manually by running a tserver with 3 data
dirs, creating a table with 5,000,000 rows, restarting the tserver,
and inspecting its log output, which contained these lines:

I0608 11:30:39.587874  6090 log_block_manager.cc:1488] Data dir /data/8/samuel.okrent/kudu/build/debug/data2/data
is on an ext4 filesystem vulnerable to KUDU-1508 with block size 2048
I0608 11:30:39.587934  6090 log_block_manager.cc:1498] Limiting containers on data directory
/data/8/samuel.okrent/kudu/build/debug/data2/data to 1353 blocks
I0608 11:30:39.588039  6090 log_block_manager.cc:1488] Data dir /data/8/samuel.okrent/kudu/build/debug/data3/data
is on an ext4 filesystem vulnerable to KUDU-1508 with block size 2048
I0608 11:30:39.588049  6090 log_block_manager.cc:1498] Limiting containers on data directory
/data/8/samuel.okrent/kudu/build/debug/data3/data to 1353 blocks
I0608 11:30:39.588080  6090 log_block_manager.cc:1488] Data dir /data/8/samuel.okrent/kudu/build/debug/data4/data
is on an ext4 filesystem vulnerable to KUDU-1508 with block size 2048
I0608 11:30:39.588088  6090 log_block_manager.cc:1498] Limiting containers on data directory
/data/8/samuel.okrent/kudu/build/debug/data4/data to 1353 blocks
I0608 11:30:39.590297  6097 log_block_manager.cc:2022] /data/8/samuel.okrent/kudu/build/debug/data2/data:
opened 1 log block containers
I0608 11:30:39.590458  6098 log_block_manager.cc:2022] /data/8/samuel.okrent/kudu/build/debug/data3/data:
opened 1 log block containers
I0608 11:30:39.590482  6099 log_block_manager.cc:2022] /data/8/samuel.okrent/kudu/build/debug/data4/data:
opened 1 log block containers
I0608 11:30:39.591612  6097 log_block_manager.cc:2022] /data/8/samuel.okrent/kudu/build/debug/data2/data:
opened 3 log block containers
I0608 11:30:39.591668  6098 log_block_manager.cc:2022] /data/8/samuel.okrent/kudu/build/debug/data3/data:
opened 3 log block containers
I0608 11:30:39.591806  6099 log_block_manager.cc:2022] /data/8/samuel.okrent/kudu/build/debug/data4/data:
opened 3 log block containers
I0608 11:30:39.593066  6090 fs_manager.cc:263] Time spent opening block manager: real 0.007s
 user 0.003s sys 0.001s

This test was run with a logging interval of 1ms instead of 10s (by
changing the hardcoded value in log_block_manager.cc, due to the size
of the dataset needed to delay initialization by 10s). This resulted
in periodic logging from each data dir thread of how many containers
had been opened. When the same test was run with the normal parameter
of 10s, the usual output was produced, without any of the
"Opened x log block containers..." messages

Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Reviewed-on: http://gerrit.cloudera.org:8080/7111
Reviewed-by: Adar Dembo <adar@cloudera.com>
Tested-by: Adar Dembo <adar@cloudera.com>


Project: http://git-wip-us.apache.org/repos/asf/kudu/repo
Commit: http://git-wip-us.apache.org/repos/asf/kudu/commit/65c1edaf
Tree: http://git-wip-us.apache.org/repos/asf/kudu/tree/65c1edaf
Diff: http://git-wip-us.apache.org/repos/asf/kudu/diff/65c1edaf

Branch: refs/heads/master
Commit: 65c1edaf054ba1772a7fd2c5e46c78168cd325fe
Parents: 8e04eeb
Author: Sam Okrent <samuel.okrent@cloudera.com>
Authored: Wed Jun 7 17:36:10 2017 -0700
Committer: Adar Dembo <adar@cloudera.com>
Committed: Sat Jun 10 00:28:43 2017 +0000

----------------------------------------------------------------------
 src/kudu/fs/log_block_manager.cc | 10 ++++++++++
 1 file changed, 10 insertions(+)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/kudu/blob/65c1edaf/src/kudu/fs/log_block_manager.cc
----------------------------------------------------------------------
diff --git a/src/kudu/fs/log_block_manager.cc b/src/kudu/fs/log_block_manager.cc
index c73bd49..8ca0a16 100644
--- a/src/kudu/fs/log_block_manager.cc
+++ b/src/kudu/fs/log_block_manager.cc
@@ -48,6 +48,7 @@
 #include "kudu/util/locks.h"
 #include "kudu/util/malloc.h"
 #include "kudu/util/metrics.h"
+#include "kudu/util/monotime.h"
 #include "kudu/util/mutex.h"
 #include "kudu/util/path_util.h"
 #include "kudu/util/pb_util.h"
@@ -1838,6 +1839,7 @@ void LogBlockManager::OpenDataDir(DataDir* dir,
         "Could not list children of $0", dir->dir()));
     return;
   }
+  MonoTime last_opened_container_log_time = MonoTime::Now();
   for (const string& child : children) {
     string container_name;
     if (!TryStripSuffixString(
@@ -2011,6 +2013,14 @@ void LogBlockManager::OpenDataDir(DataDir* dir,
     local_report.stats.live_block_count += container->live_blocks();
     local_report.stats.lbm_container_count++;
 
+    // Log number of containers opened every 10 seconds
+    MonoTime now = MonoTime::Now();
+    if ((now - last_opened_container_log_time).ToSeconds() > 10) {
+      LOG(INFO) << Substitute("Opened $0 log block containers in $1",
+                              local_report.stats.lbm_container_count, dir->dir());
+      last_opened_container_log_time = now;
+    }
+
     next_block_id_.StoreMax(max_block_id + 1);
 
     // Under the lock, merge this map into the main block map and add


Mime
View raw message