You are viewing a plain text version of this content. The canonical link for it is here.
Posted to reviews@kudu.apache.org by "Sam Okrent (Code Review)" <ge...@cloudera.org> on 2017/06/08 00:41:44 UTC

[kudu-CR] KUDU-1442 log number of open log block containers

Sam Okrent has uploaded a new change for review.

  http://gerrit.cloudera.org:8080/7111

Change subject: 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:

I0607 16:23:05.822599 27752 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
I0607 16:23:05.822681 27752 log_block_manager.cc:1498] Limiting containers on data directory /data/8/samuel.okrent/kudu/build/debug/data2/data to 1353 blocks
I0607 16:23:05.822835 27752 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
I0607 16:23:05.822851 27752 log_block_manager.cc:1498] Limiting containers on data directory /data/8/samuel.okrent/kudu/build/debug/data3/data to 1353 blocks
I0607 16:23:05.822892 27752 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
I0607 16:23:05.822903 27752 log_block_manager.cc:1498] Limiting containers on data directory /data/8/samuel.okrent/kudu/build/debug/data4/data to 1353 blocks
I0607 16:23:05.824937 27759 log_block_manager.cc:2019] Opened 1 log block containers in /data/8/samuel.okrent/kudu/build/debug/data2/data
I0607 16:23:05.825098 27760 log_block_manager.cc:2019] Opened 1 log block containers in /data/8/samuel.okrent/kudu/build/debug/data3/data
I0607 16:23:05.825115 27761 log_block_manager.cc:2019] Opened 1 log block containers in /data/8/samuel.okrent/kudu/build/debug/data4/data
I0607 16:23:05.826077 27759 log_block_manager.cc:2019] Opened 3 log block containers in /data/8/samuel.okrent/kudu/build/debug/data2/data
I0607 16:23:05.826352 27760 log_block_manager.cc:2019] Opened 3 log block containers in /data/8/samuel.okrent/kudu/build/debug/data3/data
I0607 16:23:05.826354 27761 log_block_manager.cc:2019] Opened 3 log block containers in /data/8/samuel.okrent/kudu/build/debug/data4/data
I0607 16:23:05.827477 27752 fs_manager.cc:265] Time spent opening block manager: real 0.008s  user 0.002s sys 0.002s

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
---
M src/kudu/fs/log_block_manager.cc
1 file changed, 10 insertions(+), 0 deletions(-)


  git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/11/7111/1
-- 
To view, visit http://gerrit.cloudera.org:8080/7111
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings

Gerrit-MessageType: newchange
Gerrit-Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Gerrit-PatchSet: 1
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-Owner: Sam Okrent <sa...@cloudera.com>

[kudu-CR] KUDU-1442 log number of open log block containers

Posted by "Sam Okrent (Code Review)" <ge...@cloudera.org>.
Sam Okrent has posted comments on this change.

Change subject: KUDU-1442 log number of open log block containers
......................................................................


Patch Set 4:

(1 comment)

http://gerrit.cloudera.org:8080/#/c/7111/3//COMMIT_MSG
Commit Message:

Line 20: 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
> Looks like you reverted this to the older format?
An accident, my bad


-- 
To view, visit http://gerrit.cloudera.org:8080/7111
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings

Gerrit-MessageType: comment
Gerrit-Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Gerrit-PatchSet: 4
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-Owner: Sam Okrent <sa...@cloudera.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Sam Okrent <sa...@cloudera.com>
Gerrit-HasComments: Yes

[kudu-CR] KUDU-1442 log number of open log block containers

Posted by "Adar Dembo (Code Review)" <ge...@cloudera.org>.
Adar Dembo has posted comments on this change.

Change subject: KUDU-1442 log number of open log block containers
......................................................................


Patch Set 1:

(3 comments)

http://gerrit.cloudera.org:8080/#/c/7111/1/src/kudu/fs/log_block_manager.cc
File src/kudu/fs/log_block_manager.cc:

Line 2019:     // Log number of containers opened every 10 seconds
Nit: if you do use KLOG_EVERY_N_SECS() you don't need this comment; it'll be obvious from the code.


Line 2022:       LOG(INFO) << Substitute("Opened $0 log block containers in $1",
Nit: how about formatting it as:

  Substitute("$0: opened $1 log block containers", dir->dir(), container_count);

That way the directories are all aligned with one another and it's a little easier to differentiate between them.


PS1, Line 2020:     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;
              :     }
> Would just
Agreed, unless KLOG_EVERY_N_SECS() will log at the 0th second mark as well as every n seconds. It'd be nice to avoid the 0th second statement since that'll be emitted all the time, even for super fast (or empty) deployments.


-- 
To view, visit http://gerrit.cloudera.org:8080/7111
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings

Gerrit-MessageType: comment
Gerrit-Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Gerrit-PatchSet: 1
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-Owner: Sam Okrent <sa...@cloudera.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins
Gerrit-HasComments: Yes

[kudu-CR] KUDU-1442 log number of open log block containers

Posted by "Adar Dembo (Code Review)" <ge...@cloudera.org>.
Adar Dembo has posted comments on this change.

Change subject: KUDU-1442 log number of open log block containers
......................................................................


Patch Set 6: Code-Review+2

-- 
To view, visit http://gerrit.cloudera.org:8080/7111
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings

Gerrit-MessageType: comment
Gerrit-Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Gerrit-PatchSet: 6
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-Owner: Sam Okrent <sa...@cloudera.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Sam Okrent <sa...@cloudera.com>
Gerrit-HasComments: No

[kudu-CR] KUDU-1442 log number of open log block containers

Posted by "Adar Dembo (Code Review)" <ge...@cloudera.org>.
Adar Dembo has submitted this change and it was merged.

Change subject: 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>
---
M src/kudu/fs/log_block_manager.cc
1 file changed, 10 insertions(+), 0 deletions(-)

Approvals:
  Adar Dembo: Looks good to me, approved; Verified



-- 
To view, visit http://gerrit.cloudera.org:8080/7111
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings

Gerrit-MessageType: merged
Gerrit-Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Gerrit-PatchSet: 7
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-Owner: Sam Okrent <sa...@cloudera.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Sam Okrent <sa...@cloudera.com>

[kudu-CR] KUDU-1442 log number of open log block containers

Posted by "Adar Dembo (Code Review)" <ge...@cloudera.org>.
Adar Dembo has posted comments on this change.

Change subject: KUDU-1442 log number of open log block containers
......................................................................


Patch Set 4: Code-Review+2

-- 
To view, visit http://gerrit.cloudera.org:8080/7111
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings

Gerrit-MessageType: comment
Gerrit-Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Gerrit-PatchSet: 4
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-Owner: Sam Okrent <sa...@cloudera.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Sam Okrent <sa...@cloudera.com>
Gerrit-HasComments: No

[kudu-CR] KUDU-1442 log number of open log block containers

Posted by "Sam Okrent (Code Review)" <ge...@cloudera.org>.
Hello Adar Dembo, Kudu Jenkins,

I'd like you to reexamine a change.  Please visit

    http://gerrit.cloudera.org:8080/7111

to look at the new patch set (#5).

Change subject: 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:

I0607 16:23:05.822599 27752 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
I0607 16:23:05.822681 27752 log_block_manager.cc:1498] Limiting containers on data directory /data/8/samuel.okrent/kudu/build/debug/data2/data to 1353 blocks
I0607 16:23:05.822835 27752 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
I0607 16:23:05.822851 27752 log_block_manager.cc:1498] Limiting containers on data directory /data/8/samuel.okrent/kudu/build/debug/data3/data to 1353 blocks
I0607 16:23:05.822892 27752 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
I0607 16:23:05.822903 27752 log_block_manager.cc:1498] Limiting containers on data directory /data/8/samuel.okrent/kudu/build/debug/data4/data to 1353 blocks
I0607 16:23:05.824937 27759 log_block_manager.cc:2019] Opened 1 log block containers in /data/8/samuel.okrent/kudu/build/debug/data2/data
I0607 16:23:05.825098 27760 log_block_manager.cc:2019] Opened 1 log block containers in /data/8/samuel.okrent/kudu/build/debug/data3/data
I0607 16:23:05.825115 27761 log_block_manager.cc:2019] Opened 1 log block containers in /data/8/samuel.okrent/kudu/build/debug/data4/data
I0607 16:23:05.826077 27759 log_block_manager.cc:2019] Opened 3 log block containers in /data/8/samuel.okrent/kudu/build/debug/data2/data
I0607 16:23:05.826352 27760 log_block_manager.cc:2019] Opened 3 log block containers in /data/8/samuel.okrent/kudu/build/debug/data3/data
I0607 16:23:05.826354 27761 log_block_manager.cc:2019] Opened 3 log block containers in /data/8/samuel.okrent/kudu/build/debug/data4/data
I0607 16:23:05.827477 27752 fs_manager.cc:265] Time spent opening block manager: real 0.008s  user 0.002s sys 0.002s

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
---
M src/kudu/fs/log_block_manager.cc
1 file changed, 10 insertions(+), 0 deletions(-)


  git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/11/7111/5
-- 
To view, visit http://gerrit.cloudera.org:8080/7111
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings

Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Gerrit-PatchSet: 5
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-Owner: Sam Okrent <sa...@cloudera.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Sam Okrent <sa...@cloudera.com>

[kudu-CR] KUDU-1442 log number of open log block containers

Posted by "Alexey Serbin (Code Review)" <ge...@cloudera.org>.
Alexey Serbin has posted comments on this change.

Change subject: KUDU-1442 log number of open log block containers
......................................................................


Patch Set 1:

(1 comment)

http://gerrit.cloudera.org:8080/#/c/7111/1/src/kudu/fs/log_block_manager.cc
File src/kudu/fs/log_block_manager.cc:

PS1, Line 2020:     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;
              :     }
> KLOG_EVERY_N_SECS() does log for the first container opened no matter how l
Fine, that sounds good to me. If it's preferred to have some custom behavior, then KLOG_EVERY_N_SECS() is not the best options, probably.


-- 
To view, visit http://gerrit.cloudera.org:8080/7111
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings

Gerrit-MessageType: comment
Gerrit-Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Gerrit-PatchSet: 1
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-Owner: Sam Okrent <sa...@cloudera.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Sam Okrent <sa...@cloudera.com>
Gerrit-HasComments: Yes

[kudu-CR] KUDU-1442 log number of open log block containers

Posted by "Sam Okrent (Code Review)" <ge...@cloudera.org>.
Hello Adar Dembo, Kudu Jenkins,

I'd like you to reexamine a change.  Please visit

    http://gerrit.cloudera.org:8080/7111

to look at the new patch set (#6).

Change subject: 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
---
M src/kudu/fs/log_block_manager.cc
1 file changed, 10 insertions(+), 0 deletions(-)


  git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/11/7111/6
-- 
To view, visit http://gerrit.cloudera.org:8080/7111
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings

Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Gerrit-PatchSet: 6
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-Owner: Sam Okrent <sa...@cloudera.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Sam Okrent <sa...@cloudera.com>

[kudu-CR] KUDU-1442 log number of open log block containers

Posted by "Alexey Serbin (Code Review)" <ge...@cloudera.org>.
Alexey Serbin has posted comments on this change.

Change subject: KUDU-1442 log number of open log block containers
......................................................................


Patch Set 1:

(1 comment)

http://gerrit.cloudera.org:8080/#/c/7111/1/src/kudu/fs/log_block_manager.cc
File src/kudu/fs/log_block_manager.cc:

PS1, Line 2020:     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;
              :     }
Would just

KLOG_EVERY_N_SECS(INFO, 10) << Substitute("Opened $0 log block containers in $1", local_report.stats.lbm_container_count, dir->dir());

suffice?


-- 
To view, visit http://gerrit.cloudera.org:8080/7111
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings

Gerrit-MessageType: comment
Gerrit-Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Gerrit-PatchSet: 1
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-Owner: Sam Okrent <sa...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins
Gerrit-HasComments: Yes

[kudu-CR] KUDU-1442 log number of open log block containers

Posted by "Sam Okrent (Code Review)" <ge...@cloudera.org>.
Hello Kudu Jenkins,

I'd like you to reexamine a change.  Please visit

    http://gerrit.cloudera.org:8080/7111

to look at the new patch set (#3).

Change subject: 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:

I0607 16:23:05.822599 27752 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
I0607 16:23:05.822681 27752 log_block_manager.cc:1498] Limiting containers on data directory /data/8/samuel.okrent/kudu/build/debug/data2/data to 1353 blocks
I0607 16:23:05.822835 27752 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
I0607 16:23:05.822851 27752 log_block_manager.cc:1498] Limiting containers on data directory /data/8/samuel.okrent/kudu/build/debug/data3/data to 1353 blocks
I0607 16:23:05.822892 27752 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
I0607 16:23:05.822903 27752 log_block_manager.cc:1498] Limiting containers on data directory /data/8/samuel.okrent/kudu/build/debug/data4/data to 1353 blocks
I0607 16:23:05.824937 27759 log_block_manager.cc:2019] Opened 1 log block containers in /data/8/samuel.okrent/kudu/build/debug/data2/data
I0607 16:23:05.825098 27760 log_block_manager.cc:2019] Opened 1 log block containers in /data/8/samuel.okrent/kudu/build/debug/data3/data
I0607 16:23:05.825115 27761 log_block_manager.cc:2019] Opened 1 log block containers in /data/8/samuel.okrent/kudu/build/debug/data4/data
I0607 16:23:05.826077 27759 log_block_manager.cc:2019] Opened 3 log block containers in /data/8/samuel.okrent/kudu/build/debug/data2/data
I0607 16:23:05.826352 27760 log_block_manager.cc:2019] Opened 3 log block containers in /data/8/samuel.okrent/kudu/build/debug/data3/data
I0607 16:23:05.826354 27761 log_block_manager.cc:2019] Opened 3 log block containers in /data/8/samuel.okrent/kudu/build/debug/data4/data
I0607 16:23:05.827477 27752 fs_manager.cc:265] Time spent opening block manager: real 0.008s  user 0.002s sys 0.002s

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
---
M src/kudu/fs/log_block_manager.cc
1 file changed, 10 insertions(+), 0 deletions(-)


  git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/11/7111/3
-- 
To view, visit http://gerrit.cloudera.org:8080/7111
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings

Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Gerrit-PatchSet: 3
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-Owner: Sam Okrent <sa...@cloudera.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Sam Okrent <sa...@cloudera.com>

[kudu-CR] KUDU-1442 log number of open log block containers

Posted by "Adar Dembo (Code Review)" <ge...@cloudera.org>.
Adar Dembo has posted comments on this change.

Change subject: KUDU-1442 log number of open log block containers
......................................................................


Patch Set 5:

(1 comment)

http://gerrit.cloudera.org:8080/#/c/7111/5//COMMIT_MSG
Commit Message:

Line 26: I0607 16:23:05.824937 27759 log_block_manager.cc:2019] Opened 1 log block containers in /data/8/samuel.okrent/kudu/build/debug/data2/data
The format has reverted back.


-- 
To view, visit http://gerrit.cloudera.org:8080/7111
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings

Gerrit-MessageType: comment
Gerrit-Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Gerrit-PatchSet: 5
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-Owner: Sam Okrent <sa...@cloudera.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Sam Okrent <sa...@cloudera.com>
Gerrit-HasComments: Yes

[kudu-CR] KUDU-1442 log number of open log block containers

Posted by "Adar Dembo (Code Review)" <ge...@cloudera.org>.
Adar Dembo has posted comments on this change.

Change subject: KUDU-1442 log number of open log block containers
......................................................................


Patch Set 6: Verified+1

Overriding Jenkins, one of the Java or Python tests left behind a minidump. Unrelated to Sam's change.

-- 
To view, visit http://gerrit.cloudera.org:8080/7111
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings

Gerrit-MessageType: comment
Gerrit-Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Gerrit-PatchSet: 6
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-Owner: Sam Okrent <sa...@cloudera.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Sam Okrent <sa...@cloudera.com>
Gerrit-HasComments: No

[kudu-CR] KUDU-1442 log number of open log block containers

Posted by "Adar Dembo (Code Review)" <ge...@cloudera.org>.
Adar Dembo has posted comments on this change.

Change subject: KUDU-1442 log number of open log block containers
......................................................................


Patch Set 3:

(1 comment)

http://gerrit.cloudera.org:8080/#/c/7111/3//COMMIT_MSG
Commit Message:

Line 20: I0607 16:23:05.822599 27752 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
Looks like you reverted this to the older format?


-- 
To view, visit http://gerrit.cloudera.org:8080/7111
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings

Gerrit-MessageType: comment
Gerrit-Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Gerrit-PatchSet: 3
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-Owner: Sam Okrent <sa...@cloudera.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Sam Okrent <sa...@cloudera.com>
Gerrit-HasComments: Yes

[kudu-CR] KUDU-1442 log number of open log block containers

Posted by "Sam Okrent (Code Review)" <ge...@cloudera.org>.
Hello Kudu Jenkins,

I'd like you to reexamine a change.  Please visit

    http://gerrit.cloudera.org:8080/7111

to look at the new patch set (#4).

Change subject: 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
---
M src/kudu/fs/log_block_manager.cc
1 file changed, 10 insertions(+), 0 deletions(-)


  git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/11/7111/4
-- 
To view, visit http://gerrit.cloudera.org:8080/7111
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings

Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Gerrit-PatchSet: 4
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-Owner: Sam Okrent <sa...@cloudera.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Sam Okrent <sa...@cloudera.com>

[kudu-CR] KUDU-1442 log number of open log block containers

Posted by "Adar Dembo (Code Review)" <ge...@cloudera.org>.
Adar Dembo has posted comments on this change.

Change subject: KUDU-1442 log number of open log block containers
......................................................................


Patch Set 2:

(2 comments)

http://gerrit.cloudera.org:8080/#/c/7111/2/src/kudu/fs/log_block_manager.cc
File src/kudu/fs/log_block_manager.cc:

Line 1845:   MonoTime last_opened_container_log_time = MonoTime::Now();
Nit: remove the "log" infix; it's not clear what a "container log" is, or "log time". But "last_opened_container_time" is pretty clear.


Line 2019:     // Log number of containers opened every 10 seconds
Nit: terminate the comment with a period.

Also, I'd adjust the comment to generalize a little bit and clarify intent: "Periodically log the number of opened containers so as to provide a progress update." By removing "10 seconds" from the comment there's one less line of code to update if we decide to change 10 to 15 or whatever.


-- 
To view, visit http://gerrit.cloudera.org:8080/7111
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings

Gerrit-MessageType: comment
Gerrit-Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Gerrit-PatchSet: 2
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-Owner: Sam Okrent <sa...@cloudera.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Sam Okrent <sa...@cloudera.com>
Gerrit-HasComments: Yes

[kudu-CR] KUDU-1442 log number of open log block containers

Posted by "Sam Okrent (Code Review)" <ge...@cloudera.org>.
Hello Kudu Jenkins,

I'd like you to reexamine a change.  Please visit

    http://gerrit.cloudera.org:8080/7111

to look at the new patch set (#2).

Change subject: 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
---
M src/kudu/fs/log_block_manager.cc
1 file changed, 10 insertions(+), 0 deletions(-)


  git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/11/7111/2
-- 
To view, visit http://gerrit.cloudera.org:8080/7111
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings

Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Gerrit-PatchSet: 2
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-Owner: Sam Okrent <sa...@cloudera.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins

[kudu-CR] KUDU-1442 log number of open log block containers

Posted by "Sam Okrent (Code Review)" <ge...@cloudera.org>.
Sam Okrent has posted comments on this change.

Change subject: KUDU-1442 log number of open log block containers
......................................................................


Patch Set 2:

(1 comment)

http://gerrit.cloudera.org:8080/#/c/7111/1/src/kudu/fs/log_block_manager.cc
File src/kudu/fs/log_block_manager.cc:

PS1, Line 2020:     MonoTime now = MonoTime::Now();
              :     if ((now - last_opened_container_log_time).ToSeconds() > 10) {
              :       LOG(INFO) << Substitute("$0: opened $1 log block containers",
              :                               dir->dir(), local_report.stats.lbm_container_count);
              :       last_opened_container_log_time = now;
              :     }
> Agreed, unless KLOG_EVERY_N_SECS() will log at the 0th second mark as well 
KLOG_EVERY_N_SECS() does log for the first container opened no matter how long it takes. In the new commit I'm not using it - let me know if you think I should.


-- 
To view, visit http://gerrit.cloudera.org:8080/7111
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings

Gerrit-MessageType: comment
Gerrit-Change-Id: I3dd5eccd166ae81be26d0aa75758539f84d62656
Gerrit-PatchSet: 2
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-Owner: Sam Okrent <sa...@cloudera.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Sam Okrent <sa...@cloudera.com>
Gerrit-HasComments: Yes