[kudu] 01/02: sentry: add trace points

[gr...@apache.org]

This is an automated email from the ASF dual-hosted git repository.

granthenke pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/kudu.git

commit 4cda69f0c29c083147ae7805d124cb95627bde70
Author: Andrew Wong <aw...@apache.org>
AuthorDate: Wed May 29 23:28:45 2019 -0700

    sentry: add trace points
    
    Adds TRACE statements at various points in Sentry authorization that I
    found useful in debugging authorization performance.
    
    With the trace points, we can now identify:
    - whether an RPC is waiting for an in-flight call to Sentry for its
      privileges, or sending a new request to Sentry
    - the time taken to receive privileges from Sentry
    - the time taken to evaluate in-memory privileges
    
    Here's an example of a CreateTable trace pulled from /rpcz (cleaned up
    a bit for the spacing):
    
    "trace": "0529 19:22:26.794605
    (+     0) service_pool.cc:162] Inserting onto call queue
    (+    46) service_pool.cc:221] Handling call
    (+   150) sentry_privileges_fetcher.cc:694] Fetching privileges from Sentry
    (+ 29438) sentry_authz_provider.cc:77] Evaluating privileges
    (+  4071) catalog_manager.cc:1587] Acquired catalog manager lock 19:22:26.828355
    (+    45) catalog_manager.cc:1631] Created new table and tablet info
    (+1107724) catalog_manager.cc:1657] Created new table in HMS catalog
    (+   773) catalog_manager.cc:1680] Wrote table and tablets to system table
    (+    74) catalog_manager.cc:1714] Inserted table and tablets into CatalogManager maps
    (+    36) inbound_call.cc:162] Queueing success response\nRelated trace 'txn':
    (+     0) write_transaction.cc:152] PREPARE: Starting.
    (+    27) write_transaction.cc:332] Acquiring schema lock in shared mode
    (+     1) write_transaction.cc:335] Acquired schema lock
    (+     0) tablet.cc:437] Decoding operations
    (+    20) tablet.cc:459] Acquiring locks for 9 operations
    (+    29) tablet.cc:463] Locks acquired
    (+     0) write_transaction.cc:187] PREPARE: Finished.
    (+     4) write_transaction.cc:197] Start()
    (+     2) write_transaction.cc:202] Timestamp: L: 43236
    (+     0) transaction_driver.cc:325] REPLICATION: Starting.
    (+    31) log.cc:588] Serialized 1331 byte log entry
    (+   187) transaction_driver.cc:438] REPLICATION: Finished.
    (+    55) write_transaction.cc:210] APPLY: Starting.
    (+   147) tablet_metrics.cc:371] ProbeStats: bloom_lookups=9,key_file_lookups=0,delta_file_lookups=0,mrs_lookups=0
    (+     2) write_transaction.cc:221] APPLY: Finished.
    (+    41) log.cc:588] Serialized 72 byte log entry
    (+    10) write_transaction.cc:376] Releasing row and schema locks
    (+     5) write_transaction.cc:341] Released schema lock
    (+     3) write_transaction.cc:258] FINISH: Updating metrics.
    (+     7) write_transaction.cc:376] Releasing row and schema locks
    (+     0) write_transaction.cc:341] Released schema lock
    
    Change-Id: I8ed344aa38437faf4d6cfa9640cad443f38f6bd8
    Reviewed-on: http://gerrit.cloudera.org:8080/13493
    Reviewed-by: Hao Hao <ha...@cloudera.com>
    Reviewed-by: Alexey Serbin <as...@cloudera.com>
    Tested-by: Andrew Wong <aw...@cloudera.com>
---
 src/kudu/master/sentry_authz_provider.cc     | 2 ++
 src/kudu/master/sentry_privileges_fetcher.cc | 3 +++
 2 files changed, 5 insertions(+)

diff --git a/src/kudu/master/sentry_authz_provider.cc b/src/kudu/master/sentry_authz_provider.cc
index 74c88b6..8dec342 100644
--- a/src/kudu/master/sentry_authz_provider.cc
+++ b/src/kudu/master/sentry_authz_provider.cc
@@ -30,6 +30,7 @@
 #include "kudu/security/token.pb.h"
 #include "kudu/sentry/sentry_action.h"
 #include "kudu/sentry/sentry_authorizable_scope.h"
+#include "kudu/util/trace.h"
 
 DECLARE_string(sentry_service_rpc_addresses);
 
@@ -73,6 +74,7 @@ bool IsActionAllowed(SentryAction::Action required_action,
   // privileges with lower scope will also be returned in the response. This contradicts
   // rule (1) mentioned above. Therefore, we need to validate privilege scope, in addition
   // to action and grant option. Otherwise, privilege escalation can happen.
+  TRACE("Evaluating privileges");
   SentryAction action(required_action);
   SentryAuthorizableScope scope(required_scope);
   const auto& privileges = privileges_branch.privileges();
diff --git a/src/kudu/master/sentry_privileges_fetcher.cc b/src/kudu/master/sentry_privileges_fetcher.cc
index 5afdf91..5d54999 100644
--- a/src/kudu/master/sentry_privileges_fetcher.cc
+++ b/src/kudu/master/sentry_privileges_fetcher.cc
@@ -54,6 +54,7 @@
 #include "kudu/util/net/net_util.h"
 #include "kudu/util/slice.h"
 #include "kudu/util/test_util_prod.h"
+#include "kudu/util/trace.h"
 #include "kudu/util/ttl_cache_metrics.h"
 
 DEFINE_string(sentry_service_rpc_addresses, "",
@@ -666,11 +667,13 @@ Status SentryPrivilegesFetcher::GetSentryPrivileges(
     fetched_privileges = pending_request.result;
   }
   if (!is_first_request) {
+    TRACE("Waiting for in-flight request to Sentry");
     RETURN_NOT_OK(sync.Wait());
     *privileges = *fetched_privileges;
     return Status::OK();
   }
 
+  TRACE("Fetching privileges from Sentry");
   const auto s = FetchPrivilegesFromSentry(FLAGS_kudu_service_name,
                                            user, authorizable,
                                            fetched_privileges.get());