You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@kudu.apache.org by ad...@apache.org on 2017/06/10 00:29:23 UTC
[4/4] kudu git commit: KUDU-1442 log number of open log block
containers
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 <ad...@cloudera.com>
Tested-by: Adar Dembo <ad...@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 <sa...@cloudera.com>
Authored: Wed Jun 7 17:36:10 2017 -0700
Committer: Adar Dembo <ad...@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