LDAP: Decorate the hot paths in the LDAP provider with systemtap probes

During performance analysis, the LDAP provider and especially its nested
group code proved to be the place where we spend the most time during
account requests. Therefore, I decorated the LDAP provider with
systemtap probes to be able to observe where the time is spent.

The code allows passing of search properties (base, filter, ...) from
marks to probes. Where applicable, the probes pass on these arguments to
functions and build a human-readable string representation.

Reviewed-by: Lukáš Slebodník <lslebodn@redhat.com>

5 files changed, 81 insertions, 0 deletions

diff --git a/src/providers/ldap/ldap_id.c b/src/providers/ldap/ldap_id.c
index 8923e7e0c..ee5b374db 100644
--- a/src/providers/ldap/ldap_id.c
+++ b/src/providers/ldap/ldap_id.c
@@ -27,6 +27,7 @@
 #include <sys/time.h>
 
 #include "util/util.h"
+#include "util/probes.h"
 #include "util/strtonum.h"
 #include "util/cert.h"
 #include "db/sysdb.h"
@@ -1509,6 +1510,11 @@ sdap_handle_acct_req_send(TALLOC_CTX *mem_ctx,
         goto done;
     }
 
+    PROBE(SDAP_ACCT_REQ_SEND,
+          state->ar->entry_type & BE_REQ_TYPE_MASK,
+          state->ar->filter_type, state->ar->filter_value,
+          PROBE_SAFE_STR(state->ar->extra_value));
+
     switch (ar->entry_type & BE_REQ_TYPE_MASK) {
     case BE_REQ_USER: /* user */
         subreq = users_get_send(state, be_ctx->ev, id_ctx,
@@ -1730,6 +1736,11 @@ sdap_handle_acct_req_recv(struct tevent_req *req,
 
     state = tevent_req_data(req, struct sdap_handle_acct_req_state);
 
+    PROBE(SDAP_ACCT_REQ_RECV,
+          state->ar->entry_type & BE_REQ_TYPE_MASK,
+          state->ar->filter_type, state->ar->filter_value,
+          PROBE_SAFE_STR(state->ar->extra_value));
+
     if (_dp_error) {
         *_dp_error = state->dp_error;
     }
diff --git a/src/providers/ldap/sdap_async.c b/src/providers/ldap/sdap_async.c
index d15a2215a..0c67e54c8 100644
--- a/src/providers/ldap/sdap_async.c
+++ b/src/providers/ldap/sdap_async.c
@@ -23,6 +23,7 @@
 #include <ctype.h>
 #include "util/util.h"
 #include "util/strtonum.h"
+#include "util/probes.h"
 #include "providers/ldap/sdap_async_private.h"
 
 #define REPLY_REALLOC_INCREMENT 10
@@ -1295,6 +1296,9 @@ sdap_get_generic_ext_send(TALLOC_CTX *memctx,
     }
     state->serverctrls[i] = NULL;
 
+    PROBE(SDAP_GET_GENERIC_EXT_SEND, state->search_base,
+          state->scope, state->filter);
+
     ret = sdap_get_generic_ext_step(req);
     if (ret != EOK) {
         tevent_req_error(req, ret);
@@ -1632,6 +1636,9 @@ sdap_get_generic_ext_recv(struct tevent_req *req,
     struct sdap_get_generic_ext_state *state =
             tevent_req_data(req, struct sdap_get_generic_ext_state);
 
+    PROBE(SDAP_GET_GENERIC_EXT_RECV, state->search_base,
+          state->scope, state->filter);
+
     TEVENT_REQ_RETURN_ON_ERROR(req);
 
     if (ref_count) {
@@ -2773,6 +2780,9 @@ enum sdap_deref_type {
 
 struct sdap_deref_search_state {
     struct sdap_handle *sh;
+    const char *base_dn;
+    const char *deref_attr;
+
     size_t reply_count;
     struct sdap_deref_attrs **reply;
     enum sdap_deref_type deref_type;
@@ -2868,6 +2878,10 @@ sdap_deref_search_send(TALLOC_CTX *memctx,
     state->sh = sh;
     state->reply_count = 0;
     state->reply = NULL;
+    state->base_dn = base_dn;
+    state->deref_attr = deref_attr;
+
+    PROBE(SDAP_DEREF_SEARCH_SEND, state->base_dn, state->deref_attr);
 
     if (sdap_is_control_supported(sh, LDAP_SERVER_ASQ_OID)) {
         DEBUG(SSSDBG_TRACE_INTERNAL, "Server supports ASQ\n");
@@ -2962,6 +2976,9 @@ int sdap_deref_search_recv(struct tevent_req *req,
 {
     struct sdap_deref_search_state *state = tevent_req_data(req,
                                             struct sdap_deref_search_state);
+
+    PROBE(SDAP_DEREF_SEARCH_RECV, state->base_dn, state->deref_attr);
+
     TEVENT_REQ_RETURN_ON_ERROR(req);
 
     *reply_count = state->reply_count;
diff --git a/src/providers/ldap/sdap_async_groups.c b/src/providers/ldap/sdap_async_groups.c
index f4633a69c..86f0a7d6e 100644
--- a/src/providers/ldap/sdap_async_groups.c
+++ b/src/providers/ldap/sdap_async_groups.c
@@ -22,6 +22,7 @@
 */
 
 #include "util/util.h"
+#include "util/probes.h"
 #include "db/sysdb.h"
 #include "providers/ldap/sdap_async_private.h"
 #include "providers/ldap/ldap_common.h"
@@ -2371,16 +2372,20 @@ static void sdap_nested_done(struct tevent_req *subreq)
     }
     in_transaction = true;
 
+    PROBE(SDAP_NESTED_GROUP_POPULATE_PRE);
     ret = sdap_nested_group_populate_users(state, state->sysdb,
                                            state->dom, state->opts,
                                            users, user_count, &ghosts);
+    PROBE(SDAP_NESTED_GROUP_POPULATE_POST);
     if (ret != EOK) {
         goto fail;
     }
 
+    PROBE(SDAP_NESTED_GROUP_SAVE_PRE);
     ret = sdap_save_groups(state, state->sysdb, state->dom, state->opts,
                            groups, group_count, false, ghosts, true,
                            &state->higher_usn);
+    PROBE(SDAP_NESTED_GROUP_SAVE_POST);
     if (ret != EOK) {
         goto fail;
     }
@@ -2539,8 +2544,10 @@ static errno_t sdap_nested_group_populate_users(TALLOC_CTX *mem_ctx,
             ret = ENOMEM;
             goto done;
         }
+        PROBE(SDAP_NESTED_GROUP_POPULATE_SEARCH_USERS_PRE);
         ret = sysdb_search_users(tmp_ctx, user_dom, filter,
                                  search_attrs, &count, &msgs);
+        PROBE(SDAP_NESTED_GROUP_POPULATE_SEARCH_USERS_POST);
         talloc_zfree(filter);
         talloc_zfree(clean_orig_dn);
         if (ret != EOK && ret != ENOENT) {
diff --git a/src/providers/ldap/sdap_async_nested_groups.c b/src/providers/ldap/sdap_async_nested_groups.c
index a1690d7bd..1ebf66067 100644
--- a/src/providers/ldap/sdap_async_nested_groups.c
+++ b/src/providers/ldap/sdap_async_nested_groups.c
@@ -30,6 +30,7 @@
 #include <time.h>
 
 #include "util/util.h"
+#include "util/probes.h"
 #include "db/sysdb.h"
 #include "providers/ldap/ldap_common.h"
 #include "providers/ldap/sdap_async.h"
@@ -479,7 +480,9 @@ sdap_nested_group_check_cache(struct sdap_options *opts,
     member_domain = sdap_domain == NULL ? domain : sdap_domain->dom;
 
     /* search in users */
+    PROBE(SDAP_NESTED_GROUP_SYSDB_SEARCH_USERS_PRE);
     ret = sdap_nested_group_sysdb_search_users(member_domain, filter);
+    PROBE(SDAP_NESTED_GROUP_SYSDB_SEARCH_USERS_POST);
     if (ret == EOK || ret == EAGAIN) {
         /* user found */
         *_type = SDAP_NESTED_GROUP_DN_USER;
@@ -490,7 +493,9 @@ sdap_nested_group_check_cache(struct sdap_options *opts,
     }
 
     /* search in groups */
+    PROBE(SDAP_NESTED_GROUP_SYSDB_SEARCH_GROUPS_PRE);
     ret = sdap_nested_group_sysdb_search_groups(member_domain, filter);
+    PROBE(SDAP_NESTED_GROUP_SYSDB_SEARCH_GROUPS_POST);
     if (ret == EOK || ret == EAGAIN) {
         /* group found */
         *_type = SDAP_NESTED_GROUP_DN_GROUP;
@@ -620,8 +625,10 @@ sdap_nested_group_split_members(TALLOC_CTX *mem_ctx,
         }
 
         /* check sysdb */
+        PROBE(SDAP_NESTED_GROUP_CHECK_CACHE_PRE);
         ret = sdap_nested_group_check_cache(group_ctx->opts, group_ctx->domain,
                                             dn, &type);
+        PROBE(SDAP_NESTED_GROUP_CHECK_CACHE_POST);
         if (ret == EOK) {
             /* found and valid */
             DEBUG(SSSDBG_TRACE_ALL, "[%s] found in cache, skipping\n", dn);
@@ -795,6 +802,8 @@ sdap_nested_group_send(TALLOC_CTX *mem_ctx,
     errno_t ret;
     int i;
 
+    PROBE(SDAP_NESTED_GROUP_SEND);
+
     req = tevent_req_create(mem_ctx, &state, struct sdap_nested_group_state);
     if (req == NULL) {
         DEBUG(SSSDBG_CRIT_FAILURE, "tevent_req_create() failed\n");
@@ -935,6 +944,7 @@ errno_t sdap_nested_group_recv(TALLOC_CTX *mem_ctx,
 
     state = tevent_req_data(req, struct sdap_nested_group_state);
 
+    PROBE(SDAP_NESTED_GROUP_RECV);
     TEVENT_REQ_RETURN_ON_ERROR(req);
 
     ret = sdap_nested_group_extract_hash_table(state, state->group_ctx->users,
@@ -1035,6 +1045,7 @@ sdap_nested_group_process_send(TALLOC_CTX *mem_ctx,
     }
 
     DEBUG(SSSDBG_TRACE_INTERNAL, "About to process group [%s]\n", orig_dn);
+    PROBE(SDAP_NESTED_GROUP_PROCESS_SEND, state->group_dn);
 
     /* get member list, both direct and external */
     state->ext_members = sdap_nested_group_ext_members(state->group_ctx->opts,
@@ -1052,11 +1063,13 @@ sdap_nested_group_process_send(TALLOC_CTX *mem_ctx,
     }
 
     /* get members that need to be refreshed */
+    PROBE(SDAP_NESTED_GROUP_PROCESS_SPLIT_PRE);
     ret = sdap_nested_group_split_members(state, state->group_ctx,
                                           state->nesting_level, members,
                                           &state->missing,
                                           &state->num_missing_total,
                                           &state->num_missing_groups);
+    PROBE(SDAP_NESTED_GROUP_PROCESS_SPLIT_POST);
     if (ret != EOK) {
         DEBUG(SSSDBG_CRIT_FAILURE, "Unable to split member list "
                                     "[%d]: %s\n", ret, sss_strerror(ret));
@@ -1178,6 +1191,13 @@ done:
 
 static errno_t sdap_nested_group_process_recv(struct tevent_req *req)
 {
+#ifdef HAVE_SYSTEMTAP
+    struct sdap_nested_group_process_state *state = NULL;
+    state = tevent_req_data(req, struct sdap_nested_group_process_state);
+
+    PROBE(SDAP_NESTED_GROUP_PROCESS_RECV, state->group_dn);
+#endif
+
     TEVENT_REQ_RETURN_ON_ERROR(req);
 
     return EOK;
@@ -1683,6 +1703,8 @@ sdap_nested_group_lookup_user_send(TALLOC_CTX *mem_ctx,
         return NULL;
     }
 
+    PROBE(SDAP_NESTED_GROUP_LOOKUP_USER_SEND);
+
     if (group_ctx->opts->schema_type == SDAP_SCHEMA_IPA_V1) {
         /* if the schema is IPA, then just shortcut and guess the name */
         ret = sdap_nested_group_get_ipa_user(state, member->dn,
@@ -1799,6 +1821,8 @@ static errno_t sdap_nested_group_lookup_user_recv(TALLOC_CTX *mem_ctx,
     struct sdap_nested_group_lookup_user_state *state = NULL;
     state = tevent_req_data(req, struct sdap_nested_group_lookup_user_state);
 
+    PROBE(SDAP_NESTED_GROUP_LOOKUP_USER_RECV);
+
     TEVENT_REQ_RETURN_ON_ERROR(req);
 
     if (_user != NULL) {
@@ -1830,6 +1854,8 @@ sdap_nested_group_lookup_group_send(TALLOC_CTX *mem_ctx,
      char *oc_list;
      errno_t ret;
 
+     PROBE(SDAP_NESTED_GROUP_LOOKUP_GROUP_SEND);
+
      req = tevent_req_create(mem_ctx, &state,
                              struct sdap_nested_group_lookup_group_state);
      if (req == NULL) {
@@ -1941,6 +1967,8 @@ static errno_t sdap_nested_group_lookup_group_recv(TALLOC_CTX *mem_ctx,
      struct sdap_nested_group_lookup_group_state *state = NULL;
      state = tevent_req_data(req, struct sdap_nested_group_lookup_group_state);
 
+     PROBE(SDAP_NESTED_GROUP_LOOKUP_GROUP_RECV);
+
      TEVENT_REQ_RETURN_ON_ERROR(req);
 
      if (_group != NULL) {
@@ -1982,6 +2010,8 @@ sdap_nested_group_lookup_unknown_send(TALLOC_CTX *mem_ctx,
         return NULL;
     }
 
+    PROBE(SDAP_NESTED_GROUP_LOOKUP_UNKNOWN_SEND);
+
     state->ev = ev;
     state->group_ctx = group_ctx;
     state->member = member;
@@ -2109,6 +2139,8 @@ sdap_nested_group_lookup_unknown_recv(TALLOC_CTX *mem_ctx,
     struct sdap_nested_group_lookup_unknown_state *state = NULL;
     state = tevent_req_data(req, struct sdap_nested_group_lookup_unknown_state);
 
+    PROBE(SDAP_NESTED_GROUP_LOOKUP_UNKNOWN_RECV);
+
     TEVENT_REQ_RETURN_ON_ERROR(req);
 
     if (_entry != NULL) {
@@ -2161,6 +2193,8 @@ sdap_nested_group_deref_send(TALLOC_CTX *mem_ctx,
         return NULL;
     }
 
+    PROBE(SDAP_NESTED_GROUP_DEREF_SEND);
+
     state->ev = ev;
     state->group_ctx = group_ctx;
     state->members = members;
@@ -2262,6 +2296,7 @@ sdap_nested_group_deref_direct_process(struct tevent_req *subreq)
         goto done;
     }
 
+    PROBE(SDAP_NESTED_GROUP_DEREF_PROCESS_PRE);
     for (i = 0; i < num_entries; i++) {
         ret = sysdb_attrs_get_string(entries[i]->attrs,
                                      SYSDB_ORIG_DN, &orig_dn);
@@ -2364,6 +2399,7 @@ sdap_nested_group_deref_direct_process(struct tevent_req *subreq)
             continue;
         }
     }
+    PROBE(SDAP_NESTED_GROUP_DEREF_PROCESS_POST);
 
     /* adjust size of nested groups array */
     if (state->num_groups > 0) {
@@ -2453,6 +2489,8 @@ static void sdap_nested_group_deref_done(struct tevent_req *subreq)
 
 static errno_t sdap_nested_group_deref_recv(struct tevent_req *req)
 {
+    PROBE(SDAP_NESTED_GROUP_DEREF_RECV);
+
     TEVENT_REQ_RETURN_ON_ERROR(req);
 
     return EOK;
diff --git a/src/providers/ldap/sdap_async_users.c b/src/providers/ldap/sdap_async_users.c
index 480bbc203..c74d2aa8a 100644
--- a/src/providers/ldap/sdap_async_users.c
+++ b/src/providers/ldap/sdap_async_users.c
@@ -22,6 +22,7 @@
 */
 
 #include "util/util.h"
+#include "util/probes.h"
 #include "db/sysdb.h"
 #include "providers/ldap/sdap_async_private.h"
 #include "providers/ldap/ldap_common.h"
@@ -840,6 +841,7 @@ struct sdap_get_users_state {
     struct sysdb_ctx *sysdb;
     struct sdap_options *opts;
     struct sss_domain_info *dom;
+    const char *filter;
 
     char *higher_usn;
     struct sysdb_attrs **users;
@@ -872,6 +874,9 @@ struct tevent_req *sdap_get_users_send(TALLOC_CTX *memctx,
     state->opts = opts;
     state->dom = dom;
 
+    state->filter = filter;
+    PROBE(SDAP_SEARCH_USER_SEND, state->filter);
+
     subreq = sdap_search_user_send(state, ev, dom, opts, search_bases,
                                    sh, attrs, filter, timeout, lookup_type);
     if (subreq == NULL) {
@@ -907,10 +912,12 @@ static void sdap_get_users_done(struct tevent_req *subreq)
         return;
     }
 
+    PROBE(SDAP_SEARCH_USER_SAVE_BEGIN, state->filter);
     ret = sdap_save_users(state, state->sysdb,
                           state->dom, state->opts,
                           state->users, state->count,
                           &state->higher_usn);
+    PROBE(SDAP_SEARCH_USER_SAVE_END, state->filter);
     if (ret) {
         DEBUG(SSSDBG_OP_FAILURE, "Failed to store users [%d][%s].\n",
               ret, sss_strerror(ret));
@@ -929,6 +936,7 @@ int sdap_get_users_recv(struct tevent_req *req,
     struct sdap_get_users_state *state = tevent_req_data(req,
                                             struct sdap_get_users_state);
 
+    PROBE(SDAP_SEARCH_USER_RECV, state->filter);
     TEVENT_REQ_RETURN_ON_ERROR(req);
 
     if (usn_value) {