You are viewing a plain text version of this content. The canonical link for it is here.
Posted to reviews@kudu.apache.org by "Will Berkeley (Code Review)" <ge...@cloudera.org> on 2019/02/20 23:34:13 UTC
[kudu-CR] Reduce startup log spam
Will Berkeley has uploaded this change for review. ( http://gerrit.cloudera.org:8080/12540
Change subject: Reduce startup log spam
......................................................................
Reduce startup log spam
This eliminates a lot of the messages at startup that really aren't
useful:
1. No more of this:
I0220 13:18:51.160027 372970944 ts_tablet_manager.cc:1007] T 2f7ecbdb5c564106a2646ffe5f21f347 P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
I0220 13:18:51.161830 372970944 ts_tablet_manager.cc:1007] T 27705b0198da406d8301830cd942c7ee P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
I0220 13:18:51.162523 372970944 ts_tablet_manager.cc:1007] T 58f1243dad6346549370fbe50a739563 P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
I0220 13:18:51.163156 372970944 ts_tablet_manager.cc:1007] T c4fc7d7a16e34f4aa87e1af2e1defa2e P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
I0220 13:18:51.163739 372970944 ts_tablet_manager.cc:1007] T 28d12a741054442d988646178daad91f P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
I0220 13:18:51.164413 372970944 ts_tablet_manager.cc:1007] T 0048470f677242dda0277aed2fef7b05 P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
I0220 13:18:51.165114 372970944 ts_tablet_manager.cc:1007] T 2b9dc70391f54e3fbf116b46d86c2c50 P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
...
Instead, just a pair of summary messages:
I0220 15:15:29.755679 323278272 ts_tablet_manager.cc:344] Loading tablet metadata (0/60 complete)
I0220 15:15:29.803109 323278272 ts_tablet_manager.cc:356] Loaded tablet metadata (60 total tablets, 60 live tablets)
2. No more of this:
I0220 13:18:51.200745 372970944 ts_tablet_manager.cc:1175] T 27705b0198da406d8301830cd942c7ee P 0a909baebce949a6aa4cdc0f196ecd00: Registered tablet (data state: TABLET_DATA_READY)
I0220 13:18:51.201200 372970944 ts_tablet_manager.cc:1175] T 58f1243dad6346549370fbe50a739563 P 0a909baebce949a6aa4cdc0f196ecd00: Registered tablet (data state: TABLET_DATA_READY)
I0220 13:18:51.201637 372970944 ts_tablet_manager.cc:1175] T c4fc7d7a16e34f4aa87e1af2e1defa2e P 0a909baebce949a6aa4cdc0f196ecd00: Registered tablet (data state: TABLET_DATA_READY)
I0220 13:18:51.202126 372970944 ts_tablet_manager.cc:1175] T 28d12a741054442d988646178daad91f P 0a909baebce949a6aa4cdc0f196ecd00: Registered tablet (data state: TABLET_DATA_READY)
I0220 13:18:51.202700 372970944 ts_tablet_manager.cc:1175] T 0048470f677242dda0277aed2fef7b05 P 0a909baebce949a6aa4cdc0f196ecd00: Registered tablet (data state: TABLET_DATA_READY)
I0220 13:18:51.203141 372970944 ts_tablet_manager.cc:1175] T 2b9dc70391f54e3fbf116b46d86c2c50 P 0a909baebce949a6aa4cdc0f196ecd00: Registered tablet (data state: TABLET_DATA_READY)
...
Instead, just a pair of summary messages:
I0220 15:15:29.803143 323278272 ts_tablet_manager.cc:362] Registering tablets (0/60 complete)
I0220 15:15:29.822479 323278272 ts_tablet_manager.cc:376] Registered 60 tablets
3. Condense webserver startup messages. Instead of
I0220 13:18:51.234637 372970944 webserver.cc:175] Starting webserver on 127.0.0.1:8050
I0220 13:18:51.234654 372970944 webserver.cc:180] Document root: /Users/wdberkeley/src/kudu/www
I0220 13:18:51.235159 372970944 webserver.cc:313] Webserver started. Bound to: http://127.0.0.1:8050/
just
I0220 15:15:29.834751 323278272 webserver.cc:307] Webserver started at http://127.0.0.1:8050/ using document root /Users/wdberkeley/src/kudu/www and password file <none>
Note that the protocol 'http://' will now correctly show as 'https://'
if the webserver is configured for SSL.
4. I got rid of some of the highest level, lowest info content messages
about the "tablet server starting", because that just means we
finished executed code in tablet_server_main.cc, not that the tablet
server is ready to do anything in particular.
Note that this gets rid of a variety of sorta useful messages about
bootstrapping, e.g.
I0220 13:18:51.359330 230735872 ts_tablet_manager.cc:1030] T 27705b0198da406d8301830cd942c7ee P 0a909baebce949a6aa4cdc0f196ecd00: Bootstrapping tablet
I0220 13:18:51.359630 230735872 tablet_bootstrap.cc:438] T 27705b0198da406d8301830cd942c7ee P 0a909baebce949a6aa4cdc0f196ecd00: Bootstrap starting.
I0220 13:18:51.483634 230735872 tablet_bootstrap.cc:438] T 27705b0198da406d8301830cd942c7ee P 0a909baebce949a6aa4cdc0f196ecd00: Bootstrap replayed 1/1 log segments. Stats: ops{read=63 overwritten=0 applied=63 ignored=62} inserts{seen=0 ignored=0} mutations{seen=0 ignored=0} orphaned_commits=0. Pending: 0 replicates
I0220 13:18:51.484174 230735872 tablet_bootstrap.cc:438] T 27705b0198da406d8301830cd942c7ee P 0a909baebce949a6aa4cdc0f196ecd00: Bootstrap complete.
It does not get rid of the most useful one:
I0220 13:18:51.484905 230735872 ts_tablet_manager.cc:1047] T 27705b0198da406d8301830cd942c7ee P 0a909baebce949a6aa4cdc0f196ecd00: Time spent bootstrapping tablet: real 0.126s user 0.106s sys 0.014s
A follow up will expand this information to provide more metrics on
bootstrap, so don't mourn the loss of the above messages.
Change-Id: I3793a2385612cf920a94e5f62a559c350b8bf461
---
M src/kudu/server/webserver.cc
M src/kudu/tablet/tablet_bootstrap.cc
M src/kudu/tserver/tablet_server_main.cc
M src/kudu/tserver/ts_tablet_manager.cc
4 files changed, 34 insertions(+), 33 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/40/12540/1
--
To view, visit http://gerrit.cloudera.org:8080/12540
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: newchange
Gerrit-Change-Id: I3793a2385612cf920a94e5f62a559c350b8bf461
Gerrit-Change-Number: 12540
Gerrit-PatchSet: 1
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
[kudu-CR] Reduce startup log spam
Posted by "Will Berkeley (Code Review)" <ge...@cloudera.org>.
Hello Tidy Bot, Alexey Serbin, Kudu Jenkins, Andrew Wong, Adar Dembo,
I'd like you to reexamine a change. Please visit
http://gerrit.cloudera.org:8080/12540
to look at the new patch set (#2).
Change subject: Reduce startup log spam
......................................................................
Reduce startup log spam
This eliminates a lot of the messages at startup that really aren't
useful:
1. No more of this:
I0220 13:18:51.160027 372970944 ts_tablet_manager.cc:1007] T 2f7ecbdb5c564106a2646ffe5f21f347 P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
I0220 13:18:51.161830 372970944 ts_tablet_manager.cc:1007] T 27705b0198da406d8301830cd942c7ee P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
I0220 13:18:51.162523 372970944 ts_tablet_manager.cc:1007] T 58f1243dad6346549370fbe50a739563 P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
I0220 13:18:51.163156 372970944 ts_tablet_manager.cc:1007] T c4fc7d7a16e34f4aa87e1af2e1defa2e P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
I0220 13:18:51.163739 372970944 ts_tablet_manager.cc:1007] T 28d12a741054442d988646178daad91f P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
I0220 13:18:51.164413 372970944 ts_tablet_manager.cc:1007] T 0048470f677242dda0277aed2fef7b05 P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
I0220 13:18:51.165114 372970944 ts_tablet_manager.cc:1007] T 2b9dc70391f54e3fbf116b46d86c2c50 P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
...
Instead, just a periodic progress message and a summary message:
I0220 15:15:29.755679 323278272 ts_tablet_manager.cc:344] Loading tablet metadata (0/60 complete)
I0220 15:15:29.803109 323278272 ts_tablet_manager.cc:356] Loaded tablet metadata (60 total tablets, 60 live tablets)
2. No more of this:
I0220 13:18:51.200745 372970944 ts_tablet_manager.cc:1175] T 27705b0198da406d8301830cd942c7ee P 0a909baebce949a6aa4cdc0f196ecd00: Registered tablet (data state: TABLET_DATA_READY)
I0220 13:18:51.201200 372970944 ts_tablet_manager.cc:1175] T 58f1243dad6346549370fbe50a739563 P 0a909baebce949a6aa4cdc0f196ecd00: Registered tablet (data state: TABLET_DATA_READY)
I0220 13:18:51.201637 372970944 ts_tablet_manager.cc:1175] T c4fc7d7a16e34f4aa87e1af2e1defa2e P 0a909baebce949a6aa4cdc0f196ecd00: Registered tablet (data state: TABLET_DATA_READY)
I0220 13:18:51.202126 372970944 ts_tablet_manager.cc:1175] T 28d12a741054442d988646178daad91f P 0a909baebce949a6aa4cdc0f196ecd00: Registered tablet (data state: TABLET_DATA_READY)
I0220 13:18:51.202700 372970944 ts_tablet_manager.cc:1175] T 0048470f677242dda0277aed2fef7b05 P 0a909baebce949a6aa4cdc0f196ecd00: Registered tablet (data state: TABLET_DATA_READY)
I0220 13:18:51.203141 372970944 ts_tablet_manager.cc:1175] T 2b9dc70391f54e3fbf116b46d86c2c50 P 0a909baebce949a6aa4cdc0f196ecd00: Registered tablet (data state: TABLET_DATA_READY)
...
Instead, just a periodic progress message and a summary message:
I0220 15:15:29.803143 323278272 ts_tablet_manager.cc:362] Registering tablets (0/60 complete)
I0220 15:15:29.822479 323278272 ts_tablet_manager.cc:376] Registered 60 tablets
3. Condense webserver startup messages. Instead of
I0220 13:18:51.234637 372970944 webserver.cc:175] Starting webserver on 127.0.0.1:8050
I0220 13:18:51.234654 372970944 webserver.cc:180] Document root: /Users/wdberkeley/src/kudu/www
I0220 13:18:51.235159 372970944 webserver.cc:313] Webserver started. Bound to: http://127.0.0.1:8050/
just
I0220 15:15:29.834751 323278272 webserver.cc:307] Webserver started at http://127.0.0.1:8050/ using document root /Users/wdberkeley/src/kudu/www and password file <none>
Note that the protocol 'http://' will now correctly show as 'https://'
if the webserver is configured for SSL.
4. I got rid of some of the highest level, lowest info content messages
about the "tablet server starting", because that just means we
finished executed code in tablet_server_main.cc, not that the tablet
server is ready to do anything in particular.
Change-Id: I3793a2385612cf920a94e5f62a559c350b8bf461
---
M src/kudu/master/master_main.cc
M src/kudu/server/webserver.cc
M src/kudu/tablet/tablet_bootstrap.cc
M src/kudu/tserver/tablet_server_main.cc
M src/kudu/tserver/ts_tablet_manager.cc
5 files changed, 33 insertions(+), 37 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/40/12540/2
--
To view, visit http://gerrit.cloudera.org:8080/12540
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I3793a2385612cf920a94e5f62a559c350b8bf461
Gerrit-Change-Number: 12540
Gerrit-PatchSet: 2
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Andrew Wong <aw...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Tidy Bot (241)
Gerrit-Reviewer: Will Berkeley <wd...@gmail.com>
[kudu-CR] Reduce startup log spam
Posted by "Will Berkeley (Code Review)" <ge...@cloudera.org>.
Will Berkeley has posted comments on this change. ( http://gerrit.cloudera.org:8080/12540 )
Change subject: Reduce startup log spam
......................................................................
Patch Set 1:
(1 comment)
http://gerrit.cloudera.org:8080/#/c/12540/1//COMMIT_MSG
Commit Message:
http://gerrit.cloudera.org:8080/#/c/12540/1//COMMIT_MSG@66
PS1, Line 66: I0220 13:18:51.483634 230735872 tablet_bootstrap.cc:438] T 27705b0198da406d8301830cd942c7ee P 0a909baebce949a6aa4cdc0f196ecd00: Bootstrap replayed 1/1 log segments. Stats: ops{read=63 overwritten=0 applied=63 ignored=62} inserts{seen=0 ignored=0} mutations{seen=0 ignored=0} orphaned_commits=0. Pending: 0 replicates
> I'm hesitant about removing this one. I'm not a bootstrapping expert, but u
I'm very conflicted about this message and the timing messages. They are per tablet, so there's a lot of them on a busy server, and no one is going to go and look at them all. I think the main purpose of putting all of them in the logs is to make you feel like something is happening when you restart a large cluster and tail -f an INFO log. Extremes and averages can be useful. What I'd like to say is that we should gather outcomes from bootstraps and expose that information somehow. One difficulty is that there isn't a "bootstrap phase" the way there's an LBM startup phase, a tmeta load phase, etc., so there's no moment in time when it's appropriate to stop and say "here's a summary of all the bootstrappin'". There may always be one or more tablets bootstrapping on a server, because of table creation and tablet copies.
From the user's point of view, what would information about bootstrapping be good for? Most of all, I think users want to see when the tserver is roughly "available". The /tablets page shows this by tracking the percentage of live replicas in each state. If they see other statistics, there's not really anything to do about them.
An expert ought to use tracing.html and other advanced tools to see inside a bootstrap, so I think I should double check that tracing of bootstrap is really good. The missing pieces are how to identify that bootstrap in general is really slow and how to identify individual tablets that may be slow to bootstrap. /tablets is pretty ok for the first task. For the second, maybe we ought to expose more metrics or info about outliers? It's not clear how to do that well. One simple thing would be to publish metrics from the open tablet thread pool. This would capture queue times plus run times, where the run time measures bootstrap + start.
A final important point here is that startup problems are hard to reproduce- they require restarting. Slow scans or writes can usually be reproduced whenever, and so examined with /stacks, tracing, metrics, etc much more easily. So maybe excessive logging during startup is justified so that there's evidence to bring to experts.
Anyway, these were just some off the cuff thoughts. Let me know what you think.
--
To view, visit http://gerrit.cloudera.org:8080/12540
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I3793a2385612cf920a94e5f62a559c350b8bf461
Gerrit-Change-Number: 12540
Gerrit-PatchSet: 1
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Andrew Wong <aw...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Tidy Bot (241)
Gerrit-Reviewer: Will Berkeley <wd...@gmail.com>
Gerrit-Comment-Date: Thu, 21 Feb 2019 01:45:30 +0000
Gerrit-HasComments: Yes
[kudu-CR] Reduce startup log spam
Posted by "Will Berkeley (Code Review)" <ge...@cloudera.org>.
Will Berkeley has posted comments on this change. ( http://gerrit.cloudera.org:8080/12540 )
Change subject: Reduce startup log spam
......................................................................
Patch Set 1:
(6 comments)
http://gerrit.cloudera.org:8080/#/c/12540/1//COMMIT_MSG
Commit Message:
http://gerrit.cloudera.org:8080/#/c/12540/1//COMMIT_MSG@66
PS1, Line 66: I0220 13:18:51.483634 230735872 tablet_bootstrap.cc:438] T 27705b0198da406d8301830cd942c7ee P 0a909baebce949a6aa4cdc0f196ecd00: Bootstrap replayed 1/1 log segments. Stats: ops{read=63 overwritten=0 applied=63 ignored=62} inserts{seen=0 ignored=0} mutations{seen=0 ignored=0} orphaned_commits=0. Pending: 0 replicates
> I agree with you re: all of the online tooling that would be better than th
OK. Let's leave this message then. Without doing some more surgery on bootstrap, this means I need to leave the "Boostrap starting" message as well.
http://gerrit.cloudera.org:8080/#/c/12540/1/src/kudu/server/webserver.cc
File src/kudu/server/webserver.cc:
http://gerrit.cloudera.org:8080/#/c/12540/1/src/kudu/server/webserver.cc@167
PS1, Line 167: parts.push_back(addr.ToString() + (IsSecure() ? "s" : ""));
> warning: 'push_back' is called inside a loop; consider pre-allocating the v
Done
http://gerrit.cloudera.org:8080/#/c/12540/1/src/kudu/server/webserver.cc@293
PS1, Line 293: /*styled=*/true, /*on_nav_bar=*/true);
> warning: argument name 'on_nav_bar' in comment does not match parameter nam
Done
http://gerrit.cloudera.org:8080/#/c/12540/1/src/kudu/server/webserver.cc@293
PS1, Line 293: /*styled=*/true, /*on_nav_bar=*/true);
> warning: argument name 'styled' in comment does not match parameter name 'i
Done
http://gerrit.cloudera.org:8080/#/c/12540/1/src/kudu/tablet/tablet_bootstrap.cc
File src/kudu/tablet/tablet_bootstrap.cc:
http://gerrit.cloudera.org:8080/#/c/12540/1/src/kudu/tablet/tablet_bootstrap.cc@438
PS1, Line 438: VLOG(1) << Substitute("T $0 P $1: $2",
> Can use VLOG_WITH_PREFIX here?
Done
http://gerrit.cloudera.org:8080/#/c/12540/1/src/kudu/tserver/tablet_server_main.cc
File src/kudu/tserver/tablet_server_main.cc:
PS1:
> nit: maybe, remove similar messages from master_main.cc as well?
Done
--
To view, visit http://gerrit.cloudera.org:8080/12540
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I3793a2385612cf920a94e5f62a559c350b8bf461
Gerrit-Change-Number: 12540
Gerrit-PatchSet: 1
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Andrew Wong <aw...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Tidy Bot (241)
Gerrit-Reviewer: Will Berkeley <wd...@gmail.com>
Gerrit-Comment-Date: Tue, 26 Feb 2019 18:21:39 +0000
Gerrit-HasComments: Yes
[kudu-CR] Reduce startup log spam
Posted by "Alexey Serbin (Code Review)" <ge...@cloudera.org>.
Alexey Serbin has posted comments on this change. ( http://gerrit.cloudera.org:8080/12540 )
Change subject: Reduce startup log spam
......................................................................
Patch Set 1:
(1 comment)
http://gerrit.cloudera.org:8080/#/c/12540/1/src/kudu/tserver/tablet_server_main.cc
File src/kudu/tserver/tablet_server_main.cc:
PS1:
nit: maybe, remove similar messages from master_main.cc as well?
--
To view, visit http://gerrit.cloudera.org:8080/12540
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I3793a2385612cf920a94e5f62a559c350b8bf461
Gerrit-Change-Number: 12540
Gerrit-PatchSet: 1
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Andrew Wong <aw...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Tidy Bot (241)
Gerrit-Comment-Date: Thu, 21 Feb 2019 01:14:34 +0000
Gerrit-HasComments: Yes
[kudu-CR] Reduce startup log spam
Posted by "Andrew Wong (Code Review)" <ge...@cloudera.org>.
Andrew Wong has posted comments on this change. ( http://gerrit.cloudera.org:8080/12540 )
Change subject: Reduce startup log spam
......................................................................
Patch Set 2: Code-Review+2
--
To view, visit http://gerrit.cloudera.org:8080/12540
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I3793a2385612cf920a94e5f62a559c350b8bf461
Gerrit-Change-Number: 12540
Gerrit-PatchSet: 2
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Andrew Wong <aw...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Tidy Bot (241)
Gerrit-Reviewer: Will Berkeley <wd...@gmail.com>
Gerrit-Comment-Date: Wed, 27 Feb 2019 00:30:00 +0000
Gerrit-HasComments: No
[kudu-CR] Reduce startup log spam
Posted by "Will Berkeley (Code Review)" <ge...@cloudera.org>.
Will Berkeley has removed a vote on this change.
Change subject: Reduce startup log spam
......................................................................
Removed Verified-1 by Kudu Jenkins (120)
--
To view, visit http://gerrit.cloudera.org:8080/12540
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: deleteVote
Gerrit-Change-Id: I3793a2385612cf920a94e5f62a559c350b8bf461
Gerrit-Change-Number: 12540
Gerrit-PatchSet: 2
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Andrew Wong <aw...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Tidy Bot (241)
Gerrit-Reviewer: Will Berkeley <wd...@gmail.com>
[kudu-CR] Reduce startup log spam
Posted by "Will Berkeley (Code Review)" <ge...@cloudera.org>.
Will Berkeley has posted comments on this change. ( http://gerrit.cloudera.org:8080/12540 )
Change subject: Reduce startup log spam
......................................................................
Patch Set 2: Verified+1
--
To view, visit http://gerrit.cloudera.org:8080/12540
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I3793a2385612cf920a94e5f62a559c350b8bf461
Gerrit-Change-Number: 12540
Gerrit-PatchSet: 2
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Andrew Wong <aw...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Tidy Bot (241)
Gerrit-Reviewer: Will Berkeley <wd...@gmail.com>
Gerrit-Comment-Date: Tue, 26 Feb 2019 19:16:46 +0000
Gerrit-HasComments: No
[kudu-CR] Reduce startup log spam
Posted by "Andrew Wong (Code Review)" <ge...@cloudera.org>.
Andrew Wong has posted comments on this change. ( http://gerrit.cloudera.org:8080/12540 )
Change subject: Reduce startup log spam
......................................................................
Patch Set 1:
(1 comment)
http://gerrit.cloudera.org:8080/#/c/12540/1//COMMIT_MSG
Commit Message:
http://gerrit.cloudera.org:8080/#/c/12540/1//COMMIT_MSG@66
PS1, Line 66: I0220 13:18:51.483634 230735872 tablet_bootstrap.cc:438] T 27705b0198da406d8301830cd942c7ee P 0a909baebce949a6aa4cdc0f196ecd00: Bootstrap replayed 1/1 log segments. Stats: ops{read=63 overwritten=0 applied=63 ignored=62} inserts{seen=0 ignored=0} mutations{seen=0 ignored=0} orphaned_commits=0. Pending: 0 replicates
I'm hesitant about removing this one. I'm not a bootstrapping expert, but unlike the others, it has some potentially useful info.
--
To view, visit http://gerrit.cloudera.org:8080/12540
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I3793a2385612cf920a94e5f62a559c350b8bf461
Gerrit-Change-Number: 12540
Gerrit-PatchSet: 1
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Andrew Wong <aw...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Tidy Bot (241)
Gerrit-Comment-Date: Thu, 21 Feb 2019 01:06:12 +0000
Gerrit-HasComments: Yes
[kudu-CR] Reduce startup log spam
Posted by "Will Berkeley (Code Review)" <ge...@cloudera.org>.
Will Berkeley has submitted this change and it was merged. ( http://gerrit.cloudera.org:8080/12540 )
Change subject: Reduce startup log spam
......................................................................
Reduce startup log spam
This eliminates a lot of the messages at startup that really aren't
useful:
1. No more of this:
I0220 13:18:51.160027 372970944 ts_tablet_manager.cc:1007] T 2f7ecbdb5c564106a2646ffe5f21f347 P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
I0220 13:18:51.161830 372970944 ts_tablet_manager.cc:1007] T 27705b0198da406d8301830cd942c7ee P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
I0220 13:18:51.162523 372970944 ts_tablet_manager.cc:1007] T 58f1243dad6346549370fbe50a739563 P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
I0220 13:18:51.163156 372970944 ts_tablet_manager.cc:1007] T c4fc7d7a16e34f4aa87e1af2e1defa2e P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
I0220 13:18:51.163739 372970944 ts_tablet_manager.cc:1007] T 28d12a741054442d988646178daad91f P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
I0220 13:18:51.164413 372970944 ts_tablet_manager.cc:1007] T 0048470f677242dda0277aed2fef7b05 P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
I0220 13:18:51.165114 372970944 ts_tablet_manager.cc:1007] T 2b9dc70391f54e3fbf116b46d86c2c50 P 0a909baebce949a6aa4cdc0f196ecd00: Loading tablet metadata
...
Instead, just a periodic progress message and a summary message:
I0220 15:15:29.755679 323278272 ts_tablet_manager.cc:344] Loading tablet metadata (0/60 complete)
I0220 15:15:29.803109 323278272 ts_tablet_manager.cc:356] Loaded tablet metadata (60 total tablets, 60 live tablets)
2. No more of this:
I0220 13:18:51.200745 372970944 ts_tablet_manager.cc:1175] T 27705b0198da406d8301830cd942c7ee P 0a909baebce949a6aa4cdc0f196ecd00: Registered tablet (data state: TABLET_DATA_READY)
I0220 13:18:51.201200 372970944 ts_tablet_manager.cc:1175] T 58f1243dad6346549370fbe50a739563 P 0a909baebce949a6aa4cdc0f196ecd00: Registered tablet (data state: TABLET_DATA_READY)
I0220 13:18:51.201637 372970944 ts_tablet_manager.cc:1175] T c4fc7d7a16e34f4aa87e1af2e1defa2e P 0a909baebce949a6aa4cdc0f196ecd00: Registered tablet (data state: TABLET_DATA_READY)
I0220 13:18:51.202126 372970944 ts_tablet_manager.cc:1175] T 28d12a741054442d988646178daad91f P 0a909baebce949a6aa4cdc0f196ecd00: Registered tablet (data state: TABLET_DATA_READY)
I0220 13:18:51.202700 372970944 ts_tablet_manager.cc:1175] T 0048470f677242dda0277aed2fef7b05 P 0a909baebce949a6aa4cdc0f196ecd00: Registered tablet (data state: TABLET_DATA_READY)
I0220 13:18:51.203141 372970944 ts_tablet_manager.cc:1175] T 2b9dc70391f54e3fbf116b46d86c2c50 P 0a909baebce949a6aa4cdc0f196ecd00: Registered tablet (data state: TABLET_DATA_READY)
...
Instead, just a periodic progress message and a summary message:
I0220 15:15:29.803143 323278272 ts_tablet_manager.cc:362] Registering tablets (0/60 complete)
I0220 15:15:29.822479 323278272 ts_tablet_manager.cc:376] Registered 60 tablets
3. Condense webserver startup messages. Instead of
I0220 13:18:51.234637 372970944 webserver.cc:175] Starting webserver on 127.0.0.1:8050
I0220 13:18:51.234654 372970944 webserver.cc:180] Document root: /Users/wdberkeley/src/kudu/www
I0220 13:18:51.235159 372970944 webserver.cc:313] Webserver started. Bound to: http://127.0.0.1:8050/
just
I0220 15:15:29.834751 323278272 webserver.cc:307] Webserver started at http://127.0.0.1:8050/ using document root /Users/wdberkeley/src/kudu/www and password file <none>
Note that the protocol 'http://' will now correctly show as 'https://'
if the webserver is configured for SSL.
4. I got rid of some of the highest level, lowest info content messages
about the "tablet server starting", because that just means we
finished executed code in tablet_server_main.cc, not that the tablet
server is ready to do anything in particular.
Change-Id: I3793a2385612cf920a94e5f62a559c350b8bf461
Reviewed-on: http://gerrit.cloudera.org:8080/12540
Tested-by: Will Berkeley <wd...@gmail.com>
Reviewed-by: Andrew Wong <aw...@cloudera.com>
---
M src/kudu/master/master_main.cc
M src/kudu/server/webserver.cc
M src/kudu/tablet/tablet_bootstrap.cc
M src/kudu/tserver/tablet_server_main.cc
M src/kudu/tserver/ts_tablet_manager.cc
5 files changed, 33 insertions(+), 37 deletions(-)
Approvals:
Will Berkeley: Verified
Andrew Wong: Looks good to me, approved
--
To view, visit http://gerrit.cloudera.org:8080/12540
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: merged
Gerrit-Change-Id: I3793a2385612cf920a94e5f62a559c350b8bf461
Gerrit-Change-Number: 12540
Gerrit-PatchSet: 3
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Andrew Wong <aw...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Tidy Bot (241)
Gerrit-Reviewer: Will Berkeley <wd...@gmail.com>
[kudu-CR] Reduce startup log spam
Posted by "Will Berkeley (Code Review)" <ge...@cloudera.org>.
Will Berkeley has posted comments on this change. ( http://gerrit.cloudera.org:8080/12540 )
Change subject: Reduce startup log spam
......................................................................
Patch Set 2:
Unrelated "client connection metrics" failure.
--
To view, visit http://gerrit.cloudera.org:8080/12540
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I3793a2385612cf920a94e5f62a559c350b8bf461
Gerrit-Change-Number: 12540
Gerrit-PatchSet: 2
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Andrew Wong <aw...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Tidy Bot (241)
Gerrit-Reviewer: Will Berkeley <wd...@gmail.com>
Gerrit-Comment-Date: Tue, 26 Feb 2019 23:48:27 +0000
Gerrit-HasComments: No
[kudu-CR] Reduce startup log spam
Posted by "Andrew Wong (Code Review)" <ge...@cloudera.org>.
Andrew Wong has posted comments on this change. ( http://gerrit.cloudera.org:8080/12540 )
Change subject: Reduce startup log spam
......................................................................
Patch Set 1:
(1 comment)
http://gerrit.cloudera.org:8080/#/c/12540/1//COMMIT_MSG
Commit Message:
http://gerrit.cloudera.org:8080/#/c/12540/1//COMMIT_MSG@66
PS1, Line 66: I0220 13:18:51.483634 230735872 tablet_bootstrap.cc:438] T 27705b0198da406d8301830cd942c7ee P 0a909baebce949a6aa4cdc0f196ecd00: Bootstrap replayed 1/1 log segments. Stats: ops{read=63 overwritten=0 applied=63 ignored=62} inserts{seen=0 ignored=0} mutations{seen=0 ignored=0} orphaned_commits=0. Pending: 0 replicates
> I'm very conflicted about this message and the timing messages. They are pe
I agree with you re: all of the online tooling that would be better than the logs. IMO logs in general are helpful for looking at what happened, not what's happening, and so keeping around timing info, markers indicating important state changes, etc. (especially in a sea of other log messages from other tablets, from consensus, etc) _may_ be useful to have.
I agree with most of these changes, since many don't add much info other than where in the code we are, but the timing message seems useful, at least as an indicator of IO. Same with the bootstrapping details -- seems like it's got enough info to be useful, and I'm not well versed enough in bootstrapping to say they'd never be useful again (maybe there are WAL-related bugs in which this logging is useful).
Looking at a history of these logs, https://github.com/apache/kudu/commits/7c6ba1cb34107383077d8985354f716791cc8622, seems like they were introduced when we were fixing/testing WALs.
--
To view, visit http://gerrit.cloudera.org:8080/12540
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I3793a2385612cf920a94e5f62a559c350b8bf461
Gerrit-Change-Number: 12540
Gerrit-PatchSet: 1
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Andrew Wong <aw...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Tidy Bot (241)
Gerrit-Reviewer: Will Berkeley <wd...@gmail.com>
Gerrit-Comment-Date: Thu, 21 Feb 2019 04:12:46 +0000
Gerrit-HasComments: Yes
[kudu-CR] Reduce startup log spam
Posted by "Adar Dembo (Code Review)" <ge...@cloudera.org>.
Adar Dembo has posted comments on this change. ( http://gerrit.cloudera.org:8080/12540 )
Change subject: Reduce startup log spam
......................................................................
Patch Set 1:
(1 comment)
Would also love if you made the FsReport less verbose. Especially for the most "boring" report (empty filesystem); there's no reason to print it at all.
http://gerrit.cloudera.org:8080/#/c/12540/1/src/kudu/tablet/tablet_bootstrap.cc
File src/kudu/tablet/tablet_bootstrap.cc:
http://gerrit.cloudera.org:8080/#/c/12540/1/src/kudu/tablet/tablet_bootstrap.cc@438
PS1, Line 438: VLOG(1) << Substitute("T $0 P $1: $2",
Can use VLOG_WITH_PREFIX here?
--
To view, visit http://gerrit.cloudera.org:8080/12540
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I3793a2385612cf920a94e5f62a559c350b8bf461
Gerrit-Change-Number: 12540
Gerrit-PatchSet: 1
Gerrit-Owner: Will Berkeley <wd...@gmail.com>
Gerrit-Reviewer: Adar Dembo <ad...@cloudera.com>
Gerrit-Reviewer: Alexey Serbin <as...@cloudera.com>
Gerrit-Reviewer: Andrew Wong <aw...@cloudera.com>
Gerrit-Reviewer: Kudu Jenkins (120)
Gerrit-Reviewer: Tidy Bot (241)
Gerrit-Comment-Date: Wed, 20 Feb 2019 23:39:28 +0000
Gerrit-HasComments: Yes