[kudu-CR] Add some additional info to ScanRequest traces
Will Berkeley has submitted this change and it was merged. (
http://gerrit.cloudera.org:8080/11361 )
Change subject: Add some additional info to ScanRequest traces
..
Add some additional info to ScanRequest traces
This patch makes two improvements to ScanRequest traces:
* It adds the tablet id to the trace in a couple of places. This is
useful because otherwise it's hard to tell which tablet is actually
being scanned.
* It adds a metric "rowset_iterators" for the number of rowsets the
scanner will iterate over. This is useful because I've seen a number
of scan problems where the underlying issue was a lot of uncompacted
rowsets.
Here's how a ScanRequest trace on /rpcz looks now:
{
"method_name": "kudu.tserver.ScanRequestPB",
"samples": [
{
"header": {
"call_id": 3,
"remote_method": {
"service_name": "kudu.tserver.TabletServerService",
"method_name": "Scan"
},
"timeout_millis": 2
},
"trace": "0830 10:58:57.936549 (+ 0us) service_pool.cc:162]
Inserting onto call queue\n0830 10:58:57.936585 (+36us)
service_pool.cc:221] Handling call\n0830 10:58:57.936763 (+ 178us)
tablet_service.cc:1684] Created scanner f4c9f70b5da64a84b3059832fe087362 for
tablet 1b1fee4fd7b244ec9ccadd55a812f855\n0830 10:58:57.936912 (+ 149us)
tablet_service.cc:1760] Creating iterator\n0830 10:58:57.936952 (+40us)
tablet_service.cc:2092] Waiting safe time to advance\n0830 10:58:57.936976 (+
24us) tablet_service.cc:2100] Waiting for operations to commit\n0830
10:58:57.936999 (+23us) tablet_service.cc:2114] All operations in snapshot
committed. Waited for 35 microseconds\n0830 10:58:57.937022 (+23us)
tablet_service.cc:1790] Iterator created\n0830 10:58:57.937371 (+ 349us)
tablet_service.cc:1804] Iterator init: OK\n0830 10:58:57.937395 (+24us)
tablet_service.cc:1853] has_more: true\n0830 10:58:57.937403 (+ 8us)
tablet_service.cc:1868] Continuing scan request\n0830 10:58:57.937438 (+
35us) tablet_service.cc:1916] Found scanner f4c9f70b5da64a84b3059832fe087362
for tablet 1b1fee4fd7b244ec9ccadd55a812f855\n0830 10:58:57.943861 (+ 6423us)
inbound_call.cc:162] Queueing success response\n",
"duration_ms": 7,
"metrics": [
{
"key": "rowset_iterators",
"value": 1
},
{
"key": "threads_started",
"value": 1
},
{
"key": "thread_start_us",
"value": 72
},
{
"key": "compiler_manager_pool.run_cpu_time_us",
"value": 120300
},
{
"key": "compiler_manager_pool.run_wall_time_us",
"value": 144585
},
{
"key": "compiler_manager_pool.queue_time_us",
"value": 142
}
]
}
]
},
The new/improved trace messages are hidden in the block of text. They are:
10:58:57.936763 (+ 178us) tablet_service.cc:1684] Created scanner
f4c9f70b5da64a84b3059832fe087362 for tablet 1b1fee4fd7b244ec9ccadd55a812f855
and
10:58:57.937438 (+35us) tablet_service.cc:1916] Found scanner
f4c9f70b5da64a84b3059832fe087362 for tablet 1b1fee4fd7b244ec9ccadd55a812f855
Note that both appear because our scanner code reuses the "continue
scanning" code path even for the first scan after the scanner is created.
Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8
Reviewed-on: http://gerrit.cloudera.org:8080/11361
Tested-by: Will Berkeley
Reviewed-by: Alexey Serbin
---
M src/kudu/tablet/tablet.cc
M src/kudu/tserver/tablet_service.cc
2 files changed, 3 insertions(+), 2 deletions(-)
Approvals:
Will Berkeley: Verified
Alexey Serbin: Looks good to me, approved
--
To view, visit http://gerrit.cloudera.org:8080/11361
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: merged
Gerrit-Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8
Gerrit-Change-Number: 11361
Gerrit-PatchSet: 5
Gerrit-Owner: Will Berkeley
Gerrit-Reviewer: Alexey Serbin
Gerrit-Reviewer: Andrew Wong
Gerrit-Reviewer: Mike Percy
Gerrit-Reviewer: Todd Lipcon
Gerrit-Reviewer: Will Berkeley
[kudu-CR] Add some additional info to ScanRequest traces
Alexey Serbin has posted comments on this change. (
http://gerrit.cloudera.org:8080/11361 )
Change subject: Add some additional info to ScanRequest traces
..
Patch Set 4: Code-Review+2
(1 comment)
http://gerrit.cloudera.org:8080/#/c/11361/2/src/kudu/tserver/tablet_service.cc
File src/kudu/tserver/tablet_service.cc:
http://gerrit.cloudera.org:8080/#/c/11361/2/src/kudu/tserver/tablet_service.cc@1684
PS2, Line 1684: TRACE("Created scanner $0 for tablet $1", scanner->id(),
scanner->tablet_id());
> What do you think regarding tracing of registration of a scanner instead of
We discussed this offline and it seems in case of unregistration due to an
error in this method it will be possible to track that using just error
messages and scanner identifier.
--
To view, visit http://gerrit.cloudera.org:8080/11361
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8
Gerrit-Change-Number: 11361
Gerrit-PatchSet: 4
Gerrit-Owner: Will Berkeley
Gerrit-Reviewer: Alexey Serbin
Gerrit-Reviewer: Andrew Wong
Gerrit-Reviewer: Mike Percy
Gerrit-Reviewer: Todd Lipcon
Gerrit-Reviewer: Will Berkeley
Gerrit-Comment-Date: Fri, 31 Aug 2018 18:27:26 +
Gerrit-HasComments: Yes
[kudu-CR] Add some additional info to ScanRequest traces
Alexey Serbin has posted comments on this change. (
http://gerrit.cloudera.org:8080/11361 )
Change subject: Add some additional info to ScanRequest traces
..
Patch Set 2:
(1 comment)
http://gerrit.cloudera.org:8080/#/c/11361/2/src/kudu/tserver/tablet_service.cc
File src/kudu/tserver/tablet_service.cc:
http://gerrit.cloudera.org:8080/#/c/11361/2/src/kudu/tserver/tablet_service.cc@1684
PS2, Line 1684: TRACE("Created scanner $0 for tablet $1", scanner->id(),
scanner->tablet_id());
> Wouldn't it be useful to trace registration of the new scanner instead? In
What do you think regarding tracing of registration of a scanner instead of
just creation?
--
To view, visit http://gerrit.cloudera.org:8080/11361
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8
Gerrit-Change-Number: 11361
Gerrit-PatchSet: 2
Gerrit-Owner: Will Berkeley
Gerrit-Reviewer: Alexey Serbin
Gerrit-Reviewer: Andrew Wong
Gerrit-Reviewer: Mike Percy
Gerrit-Reviewer: Todd Lipcon
Gerrit-Reviewer: Will Berkeley
Gerrit-Comment-Date: Fri, 31 Aug 2018 01:56:23 +
Gerrit-HasComments: Yes
[kudu-CR] Add some additional info to ScanRequest traces
Will Berkeley has posted comments on this change. ( http://gerrit.cloudera.org:8080/11361 ) Change subject: Add some additional info to ScanRequest traces .. Patch Set 4: Verified+1 Unrelated flake. -- To view, visit http://gerrit.cloudera.org:8080/11361 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: kudu Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8 Gerrit-Change-Number: 11361 Gerrit-PatchSet: 4 Gerrit-Owner: Will Berkeley Gerrit-Reviewer: Alexey Serbin Gerrit-Reviewer: Andrew Wong Gerrit-Reviewer: Mike Percy Gerrit-Reviewer: Todd Lipcon Gerrit-Reviewer: Will Berkeley Gerrit-Comment-Date: Thu, 30 Aug 2018 22:01:58 + Gerrit-HasComments: No
[kudu-CR] Add some additional info to ScanRequest traces
Will Berkeley has removed Kudu Jenkins from this change. ( http://gerrit.cloudera.org:8080/11361 ) Change subject: Add some additional info to ScanRequest traces .. Removed reviewer Kudu Jenkins with the following votes: * Verified-1 by Kudu Jenkins (120) -- To view, visit http://gerrit.cloudera.org:8080/11361 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: kudu Gerrit-Branch: master Gerrit-MessageType: deleteReviewer Gerrit-Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8 Gerrit-Change-Number: 11361 Gerrit-PatchSet: 4 Gerrit-Owner: Will Berkeley Gerrit-Reviewer: Alexey Serbin Gerrit-Reviewer: Andrew Wong Gerrit-Reviewer: Mike Percy Gerrit-Reviewer: Todd Lipcon Gerrit-Reviewer: Will Berkeley
[kudu-CR] Add some additional info to ScanRequest traces
Alexey Serbin has posted comments on this change. (
http://gerrit.cloudera.org:8080/11361 )
Change subject: Add some additional info to ScanRequest traces
..
Patch Set 2:
(2 comments)
http://gerrit.cloudera.org:8080/#/c/11361/2/src/kudu/tablet/tablet.cc
File src/kudu/tablet/tablet.cc:
http://gerrit.cloudera.org:8080/#/c/11361/2/src/kudu/tablet/tablet.cc@1790
PS2, Line 1790: TRACE_COUNTER_INCREMENT("rowset_iterators", ret.size());
> This sounds like a good idea in the current implementation, but that would
It seems with PS4 this is no longer relevant.
http://gerrit.cloudera.org:8080/#/c/11361/2/src/kudu/tablet/tablet.cc@1805
PS2, Line 1805: // Swap results into the parameters.
> nit: please either move this one line down or remove the comment at all.
It seems with PS4 this is no longer relevant.
--
To view, visit http://gerrit.cloudera.org:8080/11361
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8
Gerrit-Change-Number: 11361
Gerrit-PatchSet: 2
Gerrit-Owner: Will Berkeley
Gerrit-Reviewer: Alexey Serbin
Gerrit-Reviewer: Andrew Wong
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Mike Percy
Gerrit-Reviewer: Todd Lipcon
Gerrit-Reviewer: Will Berkeley
Gerrit-Comment-Date: Thu, 30 Aug 2018 21:42:37 +
Gerrit-HasComments: Yes
[kudu-CR] Add some additional info to ScanRequest traces
Alexey Serbin has posted comments on this change. (
http://gerrit.cloudera.org:8080/11361 )
Change subject: Add some additional info to ScanRequest traces
..
Patch Set 2:
(3 comments)
http://gerrit.cloudera.org:8080/#/c/11361/2/src/kudu/tablet/tablet.cc
File src/kudu/tablet/tablet.cc:
http://gerrit.cloudera.org:8080/#/c/11361/2/src/kudu/tablet/tablet.cc@1790
PS2, Line 1790: TRACE_COUNTER_INCREMENT("rowset_iterators", ret.size());
> nit: could these be coalesced and put down in the Tablet::Iterator right a
This sounds like a good idea in the current implementation, but that would look
a bit fragile to me if some new parts of the code start calling
CaptureConsistentIterators.
http://gerrit.cloudera.org:8080/#/c/11361/2/src/kudu/tablet/tablet.cc@1805
PS2, Line 1805: // Swap results into the parameters.
nit: please either move this one line down or remove the comment at all.
http://gerrit.cloudera.org:8080/#/c/11361/2/src/kudu/tserver/tablet_service.cc
File src/kudu/tserver/tablet_service.cc:
http://gerrit.cloudera.org:8080/#/c/11361/2/src/kudu/tserver/tablet_service.cc@1684
PS2, Line 1684: TRACE("Created scanner $0 for tablet $1", scanner->id(),
scanner->tablet_id());
Wouldn't it be useful to trace registration of the new scanner instead? In
case of an error, this scanner would not be registered (i.e. unreg_scanner will
do its job), so the fact that the scanner was created but not registered will
not be easy to track in that case, no?
--
To view, visit http://gerrit.cloudera.org:8080/11361
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8
Gerrit-Change-Number: 11361
Gerrit-PatchSet: 2
Gerrit-Owner: Will Berkeley
Gerrit-Reviewer: Alexey Serbin
Gerrit-Reviewer: Andrew Wong
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Mike Percy
Gerrit-Reviewer: Todd Lipcon
Gerrit-Reviewer: Will Berkeley
Gerrit-Comment-Date: Thu, 30 Aug 2018 21:41:03 +
Gerrit-HasComments: Yes
[kudu-CR] Add some additional info to ScanRequest traces
Hello Mike Percy, Alexey Serbin, Kudu Jenkins, Andrew Wong, Todd Lipcon,
I'd like you to reexamine a change. Please visit
http://gerrit.cloudera.org:8080/11361
to look at the new patch set (#4).
Change subject: Add some additional info to ScanRequest traces
..
Add some additional info to ScanRequest traces
This patch makes two improvements to ScanRequest traces:
* It adds the tablet id to the trace in a couple of places. This is
useful because otherwise it's hard to tell which tablet is actually
being scanned.
* It adds a metric "rowset_iterators" for the number of rowsets the
scanner will iterate over. This is useful because I've seen a number
of scan problems where the underlying issue was a lot of uncompacted
rowsets.
Here's how a ScanRequest trace on /rpcz looks now:
{
"method_name": "kudu.tserver.ScanRequestPB",
"samples": [
{
"header": {
"call_id": 3,
"remote_method": {
"service_name": "kudu.tserver.TabletServerService",
"method_name": "Scan"
},
"timeout_millis": 2
},
"trace": "0830 10:58:57.936549 (+ 0us) service_pool.cc:162]
Inserting onto call queue\n0830 10:58:57.936585 (+36us)
service_pool.cc:221] Handling call\n0830 10:58:57.936763 (+ 178us)
tablet_service.cc:1684] Created scanner f4c9f70b5da64a84b3059832fe087362 for
tablet 1b1fee4fd7b244ec9ccadd55a812f855\n0830 10:58:57.936912 (+ 149us)
tablet_service.cc:1760] Creating iterator\n0830 10:58:57.936952 (+40us)
tablet_service.cc:2092] Waiting safe time to advance\n0830 10:58:57.936976 (+
24us) tablet_service.cc:2100] Waiting for operations to commit\n0830
10:58:57.936999 (+23us) tablet_service.cc:2114] All operations in snapshot
committed. Waited for 35 microseconds\n0830 10:58:57.937022 (+23us)
tablet_service.cc:1790] Iterator created\n0830 10:58:57.937371 (+ 349us)
tablet_service.cc:1804] Iterator init: OK\n0830 10:58:57.937395 (+24us)
tablet_service.cc:1853] has_more: true\n0830 10:58:57.937403 (+ 8us)
tablet_service.cc:1868] Continuing scan request\n0830 10:58:57.937438 (+
35us) tablet_service.cc:1916] Found scanner f4c9f70b5da64a84b3059832fe087362
for tablet 1b1fee4fd7b244ec9ccadd55a812f855\n0830 10:58:57.943861 (+ 6423us)
inbound_call.cc:162] Queueing success response\n",
"duration_ms": 7,
"metrics": [
{
"key": "rowset_iterators",
"value": 1
},
{
"key": "threads_started",
"value": 1
},
{
"key": "thread_start_us",
"value": 72
},
{
"key": "compiler_manager_pool.run_cpu_time_us",
"value": 120300
},
{
"key": "compiler_manager_pool.run_wall_time_us",
"value": 144585
},
{
"key": "compiler_manager_pool.queue_time_us",
"value": 142
}
]
}
]
},
The new/improved trace messages are hidden in the block of text. They are:
10:58:57.936763 (+ 178us) tablet_service.cc:1684] Created scanner
f4c9f70b5da64a84b3059832fe087362 for tablet 1b1fee4fd7b244ec9ccadd55a812f855
and
10:58:57.937438 (+35us) tablet_service.cc:1916] Found scanner
f4c9f70b5da64a84b3059832fe087362 for tablet 1b1fee4fd7b244ec9ccadd55a812f855
Note that both appear because our scanner code reuses the "continue
scanning" code path even for the first scan after the scanner is created.
Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8
---
M src/kudu/tablet/tablet.cc
M src/kudu/tserver/tablet_service.cc
2 files changed, 3 insertions(+), 2 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/61/11361/4
--
To view, visit http://gerrit.cloudera.org:8080/11361
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8
Gerrit-Change-Number: 11361
Gerrit-PatchSet: 4
Gerrit-Owner: Will Berkeley
Gerrit-Reviewer: Alexey Serbin
Gerrit-Reviewer: Andrew Wong
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Mike Percy
Gerrit-Reviewer: Todd Lipcon
Gerrit-Reviewer: Will Berkeley
[kudu-CR] Add some additional info to ScanRequest traces
Will Berkeley has posted comments on this change. (
http://gerrit.cloudera.org:8080/11361 )
Change subject: Add some additional info to ScanRequest traces
..
Patch Set 2:
(1 comment)
http://gerrit.cloudera.org:8080/#/c/11361/2/src/kudu/tablet/tablet.cc
File src/kudu/tablet/tablet.cc:
http://gerrit.cloudera.org:8080/#/c/11361/2/src/kudu/tablet/tablet.cc@1790
PS2, Line 1790: TRACE_COUNTER_INCREMENT("rowset_iterators", ret.size());
> nit: could these be coalesced and put down in the Tablet::Iterator right a
Done
--
To view, visit http://gerrit.cloudera.org:8080/11361
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8
Gerrit-Change-Number: 11361
Gerrit-PatchSet: 2
Gerrit-Owner: Will Berkeley
Gerrit-Reviewer: Alexey Serbin
Gerrit-Reviewer: Andrew Wong
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Mike Percy
Gerrit-Reviewer: Todd Lipcon
Gerrit-Reviewer: Will Berkeley
Gerrit-Comment-Date: Thu, 30 Aug 2018 21:37:36 +
Gerrit-HasComments: Yes
[kudu-CR] Add some additional info to ScanRequest traces
Hello Mike Percy, Alexey Serbin, Kudu Jenkins, Andrew Wong, Todd Lipcon,
I'd like you to reexamine a change. Please visit
http://gerrit.cloudera.org:8080/11361
to look at the new patch set (#3).
Change subject: Add some additional info to ScanRequest traces
..
Add some additional info to ScanRequest traces
This patch makes two improvements to ScanRequest traces:
* It adds the tablet id to the trace in a couple of places. This is
useful because otherwise it's hard to tell which tablet is actually
being scanned.
* It adds a metric "rowset_iterators" for the number of rowsets the
scanner will iterate over. This is useful because I've seen a number
of scan problems where the underlying issue was a lot of uncompacted
rowsets.
Here's how a ScanRequest trace on /rpcz looks now:
{
"method_name": "kudu.tserver.ScanRequestPB",
"samples": [
{
"header": {
"call_id": 3,
"remote_method": {
"service_name": "kudu.tserver.TabletServerService",
"method_name": "Scan"
},
"timeout_millis": 2
},
"trace": "0830 10:58:57.936549 (+ 0us) service_pool.cc:162]
Inserting onto call queue\n0830 10:58:57.936585 (+36us)
service_pool.cc:221] Handling call\n0830 10:58:57.936763 (+ 178us)
tablet_service.cc:1684] Created scanner f4c9f70b5da64a84b3059832fe087362 for
tablet 1b1fee4fd7b244ec9ccadd55a812f855\n0830 10:58:57.936912 (+ 149us)
tablet_service.cc:1760] Creating iterator\n0830 10:58:57.936952 (+40us)
tablet_service.cc:2092] Waiting safe time to advance\n0830 10:58:57.936976 (+
24us) tablet_service.cc:2100] Waiting for operations to commit\n0830
10:58:57.936999 (+23us) tablet_service.cc:2114] All operations in snapshot
committed. Waited for 35 microseconds\n0830 10:58:57.937022 (+23us)
tablet_service.cc:1790] Iterator created\n0830 10:58:57.937371 (+ 349us)
tablet_service.cc:1804] Iterator init: OK\n0830 10:58:57.937395 (+24us)
tablet_service.cc:1853] has_more: true\n0830 10:58:57.937403 (+ 8us)
tablet_service.cc:1868] Continuing scan request\n0830 10:58:57.937438 (+
35us) tablet_service.cc:1916] Found scanner f4c9f70b5da64a84b3059832fe087362
for tablet 1b1fee4fd7b244ec9ccadd55a812f855\n0830 10:58:57.943861 (+ 6423us)
inbound_call.cc:162] Queueing success response\n",
"duration_ms": 7,
"metrics": [
{
"key": "rowset_iterators",
"value": 1
},
{
"key": "threads_started",
"value": 1
},
{
"key": "thread_start_us",
"value": 72
},
{
"key": "compiler_manager_pool.run_cpu_time_us",
"value": 120300
},
{
"key": "compiler_manager_pool.run_wall_time_us",
"value": 144585
},
{
"key": "compiler_manager_pool.queue_time_us",
"value": 142
}
]
}
]
},
The new/improved trace messages are hidden in the block of text. They are:
10:58:57.936763 (+ 178us) tablet_service.cc:1684] Created scanner
f4c9f70b5da64a84b3059832fe087362 for tablet 1b1fee4fd7b244ec9ccadd55a812f855
and
10:58:57.937438 (+35us) tablet_service.cc:1916] Found scanner
f4c9f70b5da64a84b3059832fe087362 for tablet 1b1fee4fd7b244ec9ccadd55a812f855
Note that both appear because our scanner code reuses the "continue
scanning" code path even for the first scan after the scanner is created.
Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8
---
M src/kudu/tablet/tablet.cc
M src/kudu/tserver/tablet_service.cc
2 files changed, 4 insertions(+), 2 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/61/11361/3
--
To view, visit http://gerrit.cloudera.org:8080/11361
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8
Gerrit-Change-Number: 11361
Gerrit-PatchSet: 3
Gerrit-Owner: Will Berkeley
Gerrit-Reviewer: Alexey Serbin
Gerrit-Reviewer: Andrew Wong
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Mike Percy
Gerrit-Reviewer: Todd Lipcon
[kudu-CR] Add some additional info to ScanRequest traces
Andrew Wong has posted comments on this change. (
http://gerrit.cloudera.org:8080/11361 )
Change subject: Add some additional info to ScanRequest traces
..
Patch Set 2: Code-Review+1
(1 comment)
http://gerrit.cloudera.org:8080/#/c/11361/2/src/kudu/tablet/tablet.cc
File src/kudu/tablet/tablet.cc:
http://gerrit.cloudera.org:8080/#/c/11361/2/src/kudu/tablet/tablet.cc@1790
PS2, Line 1790: TRACE_COUNTER_INCREMENT("rowset_iterators", ret.size());
nit: could these be coalesced and put down in the Tablet::Iterator right after
the call to CaptureConsistentIterators at L2323?
--
To view, visit http://gerrit.cloudera.org:8080/11361
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8
Gerrit-Change-Number: 11361
Gerrit-PatchSet: 2
Gerrit-Owner: Will Berkeley
Gerrit-Reviewer: Alexey Serbin
Gerrit-Reviewer: Andrew Wong
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Mike Percy
Gerrit-Reviewer: Todd Lipcon
Gerrit-Comment-Date: Thu, 30 Aug 2018 20:37:56 +
Gerrit-HasComments: Yes
[kudu-CR] Add some additional info to ScanRequest traces
Todd Lipcon has posted comments on this change. ( http://gerrit.cloudera.org:8080/11361 ) Change subject: Add some additional info to ScanRequest traces .. Patch Set 2: Code-Review+1 great idea, thanks for doing this -- To view, visit http://gerrit.cloudera.org:8080/11361 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: kudu Gerrit-Branch: master Gerrit-MessageType: comment Gerrit-Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8 Gerrit-Change-Number: 11361 Gerrit-PatchSet: 2 Gerrit-Owner: Will Berkeley Gerrit-Reviewer: Alexey Serbin Gerrit-Reviewer: Andrew Wong Gerrit-Reviewer: Kudu Jenkins Gerrit-Reviewer: Mike Percy Gerrit-Reviewer: Todd Lipcon Gerrit-Comment-Date: Thu, 30 Aug 2018 18:43:16 + Gerrit-HasComments: No
[kudu-CR] Add some additional info to ScanRequest traces
Hello Mike Percy, Alexey Serbin, Kudu Jenkins, Andrew Wong,
I'd like you to reexamine a change. Please visit
http://gerrit.cloudera.org:8080/11361
to look at the new patch set (#2).
Change subject: Add some additional info to ScanRequest traces
..
Add some additional info to ScanRequest traces
This patch makes two improvements to ScanRequest traces:
* It adds the tablet id to the trace in a couple of places. This is
useful because otherwise it's hard to tell which tablet is actually
being scanned.
* It adds a metric "rowset_iterators" for the number of rowsets the
scanner will iterate over. This is useful because I've seen a number
of scan problems where the underlying issue was a lot of uncompacted
rowsets.
Here's how a ScanRequest trace on /rpcz looks now:
{
"method_name": "kudu.tserver.ScanRequestPB",
"samples": [
{
"header": {
"call_id": 3,
"remote_method": {
"service_name": "kudu.tserver.TabletServerService",
"method_name": "Scan"
},
"timeout_millis": 2
},
"trace": "0830 10:58:57.936549 (+ 0us) service_pool.cc:162]
Inserting onto call queue\n0830 10:58:57.936585 (+36us)
service_pool.cc:221] Handling call\n0830 10:58:57.936763 (+ 178us)
tablet_service.cc:1684] Created scanner f4c9f70b5da64a84b3059832fe087362 for
tablet 1b1fee4fd7b244ec9ccadd55a812f855\n0830 10:58:57.936912 (+ 149us)
tablet_service.cc:1760] Creating iterator\n0830 10:58:57.936952 (+40us)
tablet_service.cc:2092] Waiting safe time to advance\n0830 10:58:57.936976 (+
24us) tablet_service.cc:2100] Waiting for operations to commit\n0830
10:58:57.936999 (+23us) tablet_service.cc:2114] All operations in snapshot
committed. Waited for 35 microseconds\n0830 10:58:57.937022 (+23us)
tablet_service.cc:1790] Iterator created\n0830 10:58:57.937371 (+ 349us)
tablet_service.cc:1804] Iterator init: OK\n0830 10:58:57.937395 (+24us)
tablet_service.cc:1853] has_more: true\n0830 10:58:57.937403 (+ 8us)
tablet_service.cc:1868] Continuing scan request\n0830 10:58:57.937438 (+
35us) tablet_service.cc:1916] Found scanner f4c9f70b5da64a84b3059832fe087362
for tablet 1b1fee4fd7b244ec9ccadd55a812f855\n0830 10:58:57.943861 (+ 6423us)
inbound_call.cc:162] Queueing success response\n",
"duration_ms": 7,
"metrics": [
{
"key": "rowset_iterators",
"value": 1
},
{
"key": "threads_started",
"value": 1
},
{
"key": "thread_start_us",
"value": 72
},
{
"key": "compiler_manager_pool.run_cpu_time_us",
"value": 120300
},
{
"key": "compiler_manager_pool.run_wall_time_us",
"value": 144585
},
{
"key": "compiler_manager_pool.queue_time_us",
"value": 142
}
]
}
]
},
The new/improved trace messages are hidden in the block of text. They are:
10:58:57.936763 (+ 178us) tablet_service.cc:1684] Created scanner
f4c9f70b5da64a84b3059832fe087362 for tablet 1b1fee4fd7b244ec9ccadd55a812f855
and
10:58:57.937438 (+35us) tablet_service.cc:1916] Found scanner
f4c9f70b5da64a84b3059832fe087362 for tablet 1b1fee4fd7b244ec9ccadd55a812f855
Note that both appear because our scanner code reuses the "continue
scanning" code path even for the first scan after the scanner is created.
Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8
---
M src/kudu/tablet/tablet.cc
M src/kudu/tserver/tablet_service.cc
2 files changed, 5 insertions(+), 1 deletion(-)
git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/61/11361/2
--
To view, visit http://gerrit.cloudera.org:8080/11361
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8
Gerrit-Change-Number: 11361
Gerrit-PatchSet: 2
Gerrit-Owner: Will Berkeley
Gerrit-Reviewer: Alexey Serbin
Gerrit-Reviewer: Andrew Wong
Gerrit-Reviewer: Kudu Jenkins
Gerrit-Reviewer: Mike Percy
[kudu-CR] Add some additional info to ScanRequest traces
Will Berkeley has uploaded this change for review. (
http://gerrit.cloudera.org:8080/11361
Change subject: Add some additional info to ScanRequest traces
..
Add some additional info to ScanRequest traces
This patch makes two improvements to ScanRequest traces:
* It adds the tablet id to the trace in a couple of places. This is
useful because otherwise it's hard to tell which tablet is actually
being scanned.
* It adds a metric "rowset_iterators" for the number of rowsets the
scanner will iterate over. This is useful because I've seen a number
of scan problems where the underlying issue was a lot of uncompacted
rowsets.
Here's how a ScanRequest trace on /rpcz looks now:
{
"method_name": "kudu.tserver.ScanRequestPB",
"samples": [
{
"header": {
"call_id": 3,
"remote_method": {
"service_name": "kudu.tserver.TabletServerService",
"method_name": "Scan"
},
"timeout_millis": 2
},
"trace": "0830 10:58:57.936549 (+ 0us) service_pool.cc:162]
Inserting onto call queue\n0830 10:58:57.936585 (+36us)
service_pool.cc:221] Handling call\n0830 10:58:57.936763 (+ 178us)
tablet_service.cc:1684] Created scanner f4c9f70b5da64a84b3059832fe087362 for
tablet 1b1fee4fd7b244ec9ccadd55a812f855\n0830 10:58:57.936912 (+ 149us)
tablet_service.cc:1760] Creating iterator\n0830 10:58:57.936952 (+40us)
tablet_service.cc:2092] Waiting safe time to advance\n0830 10:58:57.936976 (+
24us) tablet_service.cc:2100] Waiting for operations to commit\n0830
10:58:57.936999 (+23us) tablet_service.cc:2114] All operations in snapshot
committed. Waited for 35 microseconds\n0830 10:58:57.937022 (+23us)
tablet_service.cc:1790] Iterator created\n0830 10:58:57.937371 (+ 349us)
tablet_service.cc:1804] Iterator init: OK\n0830 10:58:57.937395 (+24us)
tablet_service.cc:1853] has_more: true\n0830 10:58:57.937403 (+ 8us)
tablet_service.cc:1868] Continuing scan request\n0830 10:58:57.937438 (+
35us) tablet_service.cc:1916] Found scanner f4c9f70b5da64a84b3059832fe087362
for tablet 1b1fee4fd7b244ec9ccadd55a812f855\n0830 10:58:57.943861 (+ 6423us)
inbound_call.cc:162] Queueing success response\n",
"duration_ms": 7,
"metrics": [
{
"key": "rowset_iterators",
"value": 1
},
{
"key": "threads_started",
"value": 1
},
{
"key": "thread_start_us",
"value": 72
},
{
"key": "compiler_manager_pool.run_cpu_time_us",
"value": 120300
},
{
"key": "compiler_manager_pool.run_wall_time_us",
"value": 144585
},
{
"key": "compiler_manager_pool.queue_time_us",
"value": 142
}
]
}
]
},
The new/improved trace messages are hidden in the block of text. They are:
10:58:57.936763 (+ 178us) tablet_service.cc:1684] Created scanner
f4c9f70b5da64a84b3059832fe087362 for tablet 1b1fee4fd7b244ec9ccadd55a812f855
and
10:58:57.937438 (+35us) tablet_service.cc:1916] Found scanner
f4c9f70b5da64a84b3059832fe087362 for tablet 1b1fee4fd7b244ec9ccadd55a812f855
Note that both appear because our scanner code reuses the "continue
scanning" even for the first scan after the scanner is created.
Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8
---
M src/kudu/tablet/tablet.cc
M src/kudu/tserver/tablet_service.cc
2 files changed, 5 insertions(+), 1 deletion(-)
git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/61/11361/1
--
To view, visit http://gerrit.cloudera.org:8080/11361
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: kudu
Gerrit-Branch: master
Gerrit-MessageType: newchange
Gerrit-Change-Id: I61792b6989c54a4e0578fe9255d769fe071e52f8
Gerrit-Change-Number: 11361
Gerrit-PatchSet: 1
Gerrit-Owner: Will Berkeley
