Repository: kudu
Updated Branches:
refs/heads/master eb15beabd -> cf6927cb1
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": 29999
},
"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 r
equest\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 <wdberke...@gmail.com>
Reviewed-by: Alexey Serbin <aser...@cloudera.com>
Project: http://git-wip-us.apache.org/repos/asf/kudu/repo
Commit: http://git-wip-us.apache.org/repos/asf/kudu/commit/4e7f0da4
Tree: http://git-wip-us.apache.org/repos/asf/kudu/tree/4e7f0da4
Diff: http://git-wip-us.apache.org/repos/asf/kudu/diff/4e7f0da4
Branch: refs/heads/master
Commit: 4e7f0da4f2b383383d66f01c27a68dadbd0750eb
Parents: eb15bea
Author: Will Berkeley <wdberke...@gmail.org>
Authored: Thu Aug 30 09:46:42 2018 -0700
Committer: Will Berkeley <wdberke...@gmail.com>
Committed: Fri Aug 31 18:31:56 2018 +0000
----------------------------------------------------------------------
src/kudu/tablet/tablet.cc | 2 +-
src/kudu/tserver/tablet_service.cc | 3 ++-
2 files changed, 3 insertions(+), 2 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/kudu/blob/4e7f0da4/src/kudu/tablet/tablet.cc
----------------------------------------------------------------------
diff --git a/src/kudu/tablet/tablet.cc b/src/kudu/tablet/tablet.cc
index 0c57724..a480c4c 100644
--- a/src/kudu/tablet/tablet.cc
+++ b/src/kudu/tablet/tablet.cc
@@ -2314,9 +2314,9 @@ Status Tablet::Iterator::Init(ScanSpec *spec) {
RETURN_NOT_OK(tablet_->GetMappedReadProjection(projection_, &projection_));
vector<shared_ptr<RowwiseIterator>> iters;
-
RETURN_NOT_OK(tablet_->CaptureConsistentIterators(&projection_, snap_, spec,
order_,
&io_context_, &iters));
+ TRACE_COUNTER_INCREMENT("rowset_iterators", iters.size());
switch (order_) {
case ORDERED:
http://git-wip-us.apache.org/repos/asf/kudu/blob/4e7f0da4/src/kudu/tserver/tablet_service.cc
----------------------------------------------------------------------
diff --git a/src/kudu/tserver/tablet_service.cc
b/src/kudu/tserver/tablet_service.cc
index 89c9562..9be9b85 100644
--- a/src/kudu/tserver/tablet_service.cc
+++ b/src/kudu/tserver/tablet_service.cc
@@ -1681,6 +1681,7 @@ Status
TabletServiceImpl::HandleNewScanRequest(TabletReplica* replica,
rpc_context->requestor_string(),
scan_pb.row_format_flags(),
&scanner);
+ TRACE("Created scanner $0 for tablet $1", scanner->id(),
scanner->tablet_id());
// If we early-exit out of this function, automatically unregister
// the scanner.
@@ -1912,7 +1913,7 @@ Status TabletServiceImpl::HandleContinueScanRequest(const
ScanRequestPB* req,
VLOG(2) << "Found existing scanner " << scanner->id() << " for request: "
<< SecureShortDebugString(*req);
- TRACE("Found scanner $0", scanner->id());
+ TRACE("Found scanner $0 for tablet $1", scanner->id(), scanner->tablet_id());
if (batch_size_bytes == 0 && req->close_scanner()) {
*has_more_results = false;
