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": 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 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 <wdberke...@gmail.com> Gerrit-Reviewer: Alexey Serbin <aser...@cloudera.com> Gerrit-Reviewer: Andrew Wong <aw...@cloudera.com> Gerrit-Reviewer: Kudu Jenkins Gerrit-Reviewer: Mike Percy <mpe...@apache.org> Gerrit-Reviewer: Todd Lipcon <t...@apache.org>