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 <[email protected]> Tested-by: Adar Dembo <[email protected]> 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 <[email protected]> Authored: Wed Jun 7 17:36:10 2017 -0700 Committer: Adar Dembo <[email protected]> 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
