CONTRIB: Add a systemstap script to measure nested group code performance

When all the dependencies are installed, run the script using systemtap:

You'll see an output such as:
 # stap /usr/share/sssd/systemtap/nested_group_perf.stp
    ^CTime spent in group sssd_be searches: 600
    Time spent in sdap_nested_group_send/recv: 65 ms (ratio: 10.83%)
    Time spent in zero-level sysdb transactions: 6813 ms (ratio: 1135.50%)

    Breakdown of sdap_nested_group req (total: 65 ms)
        sdap_nested_group_process req: 64
            sdap_nested_group_process_split req: 22
                sdap_nested_group_check_cache: 21
                    sdap_nested_group_sysdb_search_users: 10
                    sdap_nested_group_sysdb_search_groups: 9
            ldap request breakdown of total 60
                sdap_nested_group_deref req: 24
                    sdap_deref_search_send req 24
                    processing deref results: 0
                sdap_nested_group_lookup_user req: 18
                sdap_nested_group_lookup_group req: 0
                Time spent refreshing unknown members: 18

    Breakdown of results processing (total 6813)
        Time spent populating nested members: 10
            Time spent searching ldb while populating nested members: 5
        Time spent saving nested members: 110
        Time spent writing to the ldb: 678 ms

Please note that since the script is supposed to be used in scenarios such as
tracing "id" performance, which typically involve multiple group requests.
Therefore, the variables are not zeroed out and you need to interrupt the
script manually with Ctrl+C.

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

2 files changed, 334 insertions, 0 deletions

diff --git a/Makefile.am b/Makefile.am
index 9c1ae1ca9..25130b105 100644
--- a/Makefile.am
+++ b/Makefile.am
@@ -1092,6 +1092,7 @@ dist_systemtap_tap_DATA = \
 
 dist_sssdtapscript_DATA = \
     contrib/systemtap/id_perf.stp \
+    contrib/systemtap/nested_group_perf.stp \
     $(NULL)
 
 stap_generated_probes.h: $(srcdir)/src/systemtap/sssd_probes.d
diff --git a/contrib/systemtap/nested_group_perf.stp b/contrib/systemtap/nested_group_perf.stp
new file mode 100644
index 000000000..0c7ff0332
--- /dev/null
+++ b/contrib/systemtap/nested_group_perf.stp
@@ -0,0 +1,333 @@
+global time_in_populate
+global populate_start_time
+global populate_end_time
+
+global time_in_save
+global save_start_time
+global save_end_time
+
+global time_in_groupreq
+global groupreq_start
+global groupreq_end
+
+global user_req_index = 0
+global group_req_index = 1
+global unknown_req_index = 2
+global deref_req_index = 3
+global ldap_req_times
+
+global user_req_start
+global user_req_end
+
+global group_req_start
+global group_req_end
+
+global unknown_req_start
+global unknown_req_end
+
+global deref_req_start
+global deref_req_end
+
+global time_in_deref_nested
+global deref_req_nested_start
+global deref_req_nested_end
+
+global time_in_deref_process
+global deref_req_process_start
+global deref_req_process_end
+
+global time_in_transactions
+global trans_start_time
+global trans_end_time
+
+global time_in_ldb
+global ldb_start_time
+global ldb_end_time
+
+global time_in_nested_gr_req
+global nested_gr_req_start_time
+global nested_gr_req_end_time
+
+global time_in_nested_gr_process_req
+global nested_gr_process_req_start_time
+global nested_gr_process_req_end_time
+
+global time_in_split_members
+global split_members_start
+global split_members_end
+
+global time_in_check_cache
+global check_cache_start
+global check_cache_end
+
+global time_in_search_users
+global search_users_start
+global search_users_end
+
+global time_in_search_groups
+global search_groups_start
+global search_groups_end
+
+global time_in_populate_search_users
+global populate_search_users_start
+global populate_search_users_end
+
+function print_report()
+{
+    user_req_total = @sum(ldap_req_times[user_req_index])
+    group_req_total = @sum(ldap_req_times[group_req_index])
+    unknown_req_total = @sum(ldap_req_times[unknown_req_index])
+    deref_req_total = @sum(ldap_req_times[deref_req_index])
+    all_req_total = user_req_total + group_req_total + unknown_req_total + deref_req_total
+
+    # systemtap doesn't handle floating point numbers..
+    trans_rate = 10000 * time_in_transactions / time_in_groupreq
+    nested_rate = 10000 * time_in_nested_gr_req / time_in_groupreq
+
+    printf("Time spent in group sssd_be searches: %d\n", time_in_groupreq)
+    printf("Time spent in sdap_nested_group_send/recv: %d ms (ratio: %d.%02d%%)\n",
+            time_in_nested_gr_req, nested_rate/100, nested_rate%100)
+    printf("Time spent in zero-level sysdb transactions: %d ms (ratio: %d.%02d%%)\n",
+            time_in_transactions, trans_rate/100, trans_rate%100)
+    printf("\n")
+
+    printf("Breakdown of sdap_nested_group req (total: %d ms)\n", time_in_nested_gr_req);
+    printf("\tsdap_nested_group_process req: %d\n", time_in_nested_gr_process_req)
+    printf("\t\tsdap_nested_group_process_split req: %d\n", time_in_split_members)
+    printf("\t\t\tsdap_nested_group_check_cache: %d\n", time_in_check_cache)
+    printf("\t\t\t\tsdap_nested_group_sysdb_search_users: %d\n", time_in_search_users)
+    printf("\t\t\t\tsdap_nested_group_sysdb_search_groups: %d\n", time_in_search_groups)
+    printf("\t\tldap request breakdown of total %d\n", all_req_total)
+    printf("\t\t\tsdap_nested_group_deref req: %d\n", time_in_deref_nested)
+    printf("\t\t\t\tsdap_deref_search_send req %d\n", deref_req_total)
+    printf("\t\t\t\tprocessing deref results: %d\n", time_in_deref_process)
+    printf("\t\t\tsdap_nested_group_lookup_user req: %d\n", user_req_total)
+    printf("\t\t\tsdap_nested_group_lookup_group req: %d\n", group_req_total)
+    printf("\t\t\tTime spent refreshing unknown members: %d\n", unknown_req_total)
+    printf("\n")
+
+    printf("Breakdown of results processing (total %d)\n", time_in_transactions);
+    printf("\tTime spent populating nested members: %d\n", time_in_populate)
+    printf("\t\tTime spent searching ldb while populating nested members: %d\n", time_in_populate_search_users)
+    printf("\tTime spent saving nested members: %d\n", time_in_save)
+    printf("\tTime spent writing to the ldb: %d ms\n", time_in_ldb)
+    printf("\n")
+}
+
+probe sssd_transaction_start
+{
+    if (nesting == 0) {
+        num_transactions++
+        trans_start_time = gettimeofday_ms()
+    }
+}
+
+probe sssd_transaction_commit_before
+{
+    if (nesting == 0) {
+        ldb_start_time = gettimeofday_ms()
+    }
+}
+
+probe sssd_transaction_commit_after
+{
+    if (nesting == 0) {
+        trans_end_time = gettimeofday_ms()
+        time_in_transactions += (trans_end_time-trans_start_time)
+
+        ldb_end_time = gettimeofday_ms()
+        time_in_ldb += (ldb_end_time - ldb_start_time)
+    }
+}
+
+probe sdap_deref_send
+{
+    deref_req_start = gettimeofday_ms()
+}
+
+probe sdap_deref_recv
+{
+    deref_req_end = gettimeofday_ms()
+    ldap_req_times[deref_req_index] <<< (deref_req_end - deref_req_start)
+}
+
+probe sdap_nested_group_lookup_user_send
+{
+    user_req_start = gettimeofday_ms()
+}
+
+probe sdap_nested_group_lookup_user_recv
+{
+    user_req_end = gettimeofday_ms()
+    ldap_req_times[user_req_index] <<< (user_req_end - user_req_start)
+}
+
+probe sdap_nested_group_lookup_group_send
+{
+    group_req_start = gettimeofday_ms()
+}
+
+probe sdap_nested_group_lookup_group_recv
+{
+    group_req_end = gettimeofday_ms()
+    ldap_req_times[group_req_index] <<< (group_req_end - group_req_start)
+}
+
+probe sdap_nested_group_lookup_unknown_send
+{
+    unknown_req_start = gettimeofday_ms()
+}
+
+probe sdap_nested_group_lookup_unknown_recv
+{
+    unknown_req_end = gettimeofday_ms()
+    ldap_req_times[unknown_req_index] <<< (unknown_req_end - unknown_req_start)
+}
+
+probe sdap_nested_group_deref_send
+{
+    deref_req_nested_start = gettimeofday_ms()
+}
+
+probe sdap_nested_group_deref_recv
+{
+    deref_req_nested_end = gettimeofday_ms()
+    time_in_deref_nested += (deref_req_nested_end - deref_req_nested_start)
+}
+
+probe sdap_nested_group_deref_process_pre
+{
+    deref_req_process_start = gettimeofday_ms()
+}
+
+probe sdap_nested_group_deref_process_post
+{
+    deref_req_process_end = gettimeofday_ms()
+    time_in_deref_process += (deref_req_process_end - deref_req_process_start)
+}
+
+probe sdap_nested_group_populate_pre
+{
+    populate_start_time = gettimeofday_ms()
+}
+
+probe sdap_nested_group_populate_post
+{
+    populate_end_time = gettimeofday_ms()
+    time_in_populate += (populate_end_time - populate_start_time)
+}
+
+probe sdap_nested_group_save_pre
+{
+    save_start_time = gettimeofday_ms()
+}
+
+probe sdap_nested_group_save_post
+{
+    save_end_time = gettimeofday_ms()
+    time_in_save += (save_end_time - save_start_time)
+}
+
+probe sdap_nested_group_send
+{
+    nested_gr_req_start_time = gettimeofday_ms()
+}
+
+probe sdap_nested_group_recv
+{
+    nested_gr_req_end_time = gettimeofday_ms()
+    time_in_nested_gr_req += (nested_gr_req_end_time - nested_gr_req_start_time)
+}
+
+probe sdap_nested_group_process_send
+{
+    nested_gr_process_req_start_time = gettimeofday_ms()
+}
+
+probe sdap_nested_group_process_recv
+{
+    nested_gr_process_req_end_time = gettimeofday_ms()
+    time_in_nested_gr_process_req += (nested_gr_process_req_end_time - nested_gr_process_req_start_time)
+}
+
+probe sdap_nested_group_process_split_pre
+{
+    split_members_start = gettimeofday_ms()
+}
+
+probe sdap_nested_group_process_split_post
+{
+    split_members_end = gettimeofday_ms()
+    time_in_split_members += (split_members_end - split_members_start)
+}
+
+probe sdap_nested_group_check_cache_pre
+{
+    check_cache_start = gettimeofday_ms()
+}
+
+probe sdap_nested_group_check_cache_post
+{
+    check_cache_end = gettimeofday_ms()
+    time_in_check_cache += (check_cache_end - check_cache_start)
+}
+
+probe sdap_nested_group_sysdb_search_users_pre
+{
+    search_users_start = gettimeofday_ms()
+}
+
+probe sdap_nested_group_sysdb_search_users_post
+{
+    search_users_end = gettimeofday_ms()
+    time_in_search_users += (search_users_end - search_users_start)
+}
+
+probe sdap_nested_group_sysdb_search_groups_pre
+{
+    search_groups_start = gettimeofday_ms()
+}
+
+probe sdap_nested_group_sysdb_search_groups_post
+{
+    search_groups_end = gettimeofday_ms()
+    time_in_search_groups += (search_groups_end - search_groups_start)
+}
+
+probe sdap_nested_group_populate_search_users_pre
+{
+    populate_search_users_start = gettimeofday_ms()
+}
+
+probe sdap_nested_group_populate_search_users_post
+{
+    populate_search_users_end = gettimeofday_ms()
+    time_in_populate_search_users += (populate_search_users_end - populate_search_users_start)
+}
+
+probe sdap_acct_req_send
+{
+    if (entry_type == 0x0002) {
+        groupreq_start = gettimeofday_ms()
+    }
+}
+
+probe sdap_acct_req_recv
+{
+    if (entry_type == 0x0002) {
+        groupreq_end = gettimeofday_ms()
+        time_in_groupreq += (groupreq_end - groupreq_start)
+    }
+}
+
+probe begin
+{
+    time_in_populate = 0
+    time_in_save = 0
+    time_in_transactions = 0
+}
+
+probe end
+{
+    print_report()
+}