CONTRIB: Add a systemtap script to analyze the performance of the 'id' command

Run this script using "stap" as root:
    sudo stap /path/to/sssd/contrib/systemtap/id_perf.stp

It is not required to restart the script between successive id runs,
the variables are cleared when systemtap detects id had started or finished.

You should see output as this one:
    Total run time of id was: 112 ms
    Number of zero-level cache transactions: 9
    Time spent in level-0 sysdb transactions: 84 ms
    Time spent writing to LDB: 80 ms
    Number of LDAP searches: 13
    Time spent waiting for LDAP: 11 ms
    LDAP searches breakdown:
        Number of user requests: 1
        Time spent in user requests: 15

        Number of group requests: 6
        Time spent in group requests: 71

        Number of initgroups requests: 1
        Time spent in initgroups requests: 20

    Unaccounted time: 17 ms
    sysdb transaction breakdown:
    1 hits of transaction sysdb_transaction_commit+0x6b [libsss_util.so]
    sdap_save_users+0x2d2 [libsss_ldap_common.so]
    sdap_get_users_done+0x186 [libsss_ldap_common.so]
    sdap_search_user_process+0x2d9 [libsss_ldap_common.so]
    generic_ext_search_handler+0x22f [libsss_ldap_common.so]
    sdap_get_and_parse_generic_done+0x6f [libsss_ldap_common.so]
    sdap_get_generic_op_finished+0x806 [libsss_ldap_common.so]
    sdap_process_message+0x3c4 [libsss_ldap_common.so]
    sdap_process_result+0x33a [libsss_ldap_common.so]
    sdap_ldap_next_result+0x2f [libsss_
    avg:14   min: 14   max: 14   sum: 14

    5 hits of transaction sysdb_transaction_commit+0x6b [libsss_util.so]
    sdap_nested_done+0x2c8 [libsss_ldap_common.so]
    sdap_nested_group_done+0x9b [libsss_ldap_common.so]
    0x7f47a6320be4 [libtevent.so.0.9.26+0x4be4]
    avg:9   min: 9   max: 11   sum: 49

    1 hits of transaction sysdb_transaction_commit+0x6b [libsss_util.so]
    sdap_nested_done+0x2c8 [libsss_ldap_common.so]
    sdap_nested_group_done+0x9b [libsss_ldap_common.so]
    sdap_nested_group_process_done+0x1dc [libsss_ldap_common.so]
    sdap_nested_group_single_done+0x112 [libsss_ldap_common.so]
    sdap_nested_group_recurse_done+0x95 [libsss_ldap_common.so]
    0x7f47a6320be4 [libtevent.so.0.9.26+0x4be4]
    avg:11   min: 11   max: 11   sum: 11

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

1 files changed, 165 insertions, 0 deletions

diff --git a/contrib/systemtap/id_perf.stp b/contrib/systemtap/id_perf.stp
new file mode 100644
index 000000000..0ad619506
--- /dev/null
+++ b/contrib/systemtap/id_perf.stp
@@ -0,0 +1,165 @@
+global in_id
+
+global runtime_start
+global runtime_end
+
+global num_transactions
+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 num_ldap_searches
+global time_in_ldap
+global ldap_start_time
+global ldap_end_time
+
+global acct_req_types
+global acct_req_times
+global acct_req_rtime
+
+global bts
+
+function print_acct_req(req_type)
+{
+    str_req = acct_req_desc(req_type)
+    printf("\tNumber of %s requests: %d\n", str_req, acct_req_types[req_type])
+    printf("\tTime spent in %s requests: %d\n", str_req, acct_req_times[req_type])
+    printf("\n")
+}
+
+function print_report()
+{
+    max_trans_time = 0
+    max_trans_time_bt = ""
+
+    total_time = runtime_end - runtime_start
+    printf("Total run time of id was: %d ms\n", total_time)
+    printf("Number of zero-level cache transactions: %d\n", num_transactions)
+    printf("Time spent in level-0 sysdb transactions: %d ms\n", time_in_transactions)
+    printf("Time spent writing to LDB: %d ms\n", time_in_ldb)
+    printf("Number of LDAP searches: %d\n", num_ldap_searches)
+    printf("Time spent waiting for LDAP: %d ms\n", time_in_ldap)
+
+    printf("LDAP searches breakdown:\n")
+    foreach (req_type in acct_req_types) {
+        print_acct_req(req_type)
+    }
+
+    printf("Unaccounted time: %d ms\n",
+           total_time - time_in_transactions - time_in_ldap)
+
+    printf("sysdb transaction breakdown:\n")
+    foreach ([b] in bts) {
+        printf("%d hits of transaction %s\n", @count(bts[b]), b)
+        printf("avg:%d   min: %d   max: %d   sum: %d\n\n",
+               @avg(bts[b]), @min(bts[b]), @max(bts[b]), @sum(bts[b]))
+
+        if (@max(bts[b]) > max_trans_time) {
+            max_trans_time = @max(bts[b])
+            max_trans_time_bt = b
+        }
+    }
+
+    printf("The most expensive transaction breakdown, per transaction:\n")
+    print(@hist_linear(bts[max_trans_time_bt], 0, 500, 50))
+}
+
+probe process("/usr/bin/id").begin
+{
+    in_id = 1
+
+    num_transactions = 0
+    time_in_transactions = 0
+
+    num_ldap_searches = 0
+    time_in_ldap = 0
+    time_in_ldb = 0
+
+    acct_req_types[0x0001] = 0
+    acct_req_types[0x0002] = 0
+    acct_req_types[0x0003] = 0
+
+    acct_req_times[0x0001] = 0
+    acct_req_times[0x0002] = 0
+    acct_req_times[0x0003] = 0
+
+    acct_req_rtime[0x0001] = 0
+    acct_req_rtime[0x0002] = 0
+    acct_req_rtime[0x0003] = 0
+
+    runtime_start = gettimeofday_ms()
+}
+
+probe process("/usr/bin/id").end
+{
+    in_id = 0
+
+    runtime_end = gettimeofday_ms()
+    print_report()
+
+    delete bts
+}
+
+probe sssd_transaction_start
+{
+    if (nesting == 0 && in_id == 1) {
+        num_transactions++
+        trans_start_time = gettimeofday_ms()
+    }
+}
+
+probe sssd_transaction_commit_before
+{
+    if (nesting == 0 && in_id == 1) {
+        ldb_start_time = gettimeofday_ms()
+    }
+}
+
+probe sssd_transaction_commit_after
+{
+    if (nesting == 0 && in_id == 1) {
+        ldb_end_time = gettimeofday_ms()
+        time_in_ldb += (ldb_end_time-ldb_start_time)
+
+        trans_end_time = gettimeofday_ms()
+        time_in_transactions += (trans_end_time-trans_start_time)
+
+        bt = sprint_ubacktrace()
+        bts[bt] <<< (trans_end_time-trans_start_time)
+    }
+}
+
+probe sdap_search_send
+{
+    if (in_id == 1) {
+        num_ldap_searches++
+        ldap_start_time = gettimeofday_ms()
+    }
+}
+
+probe sdap_search_recv
+{
+    if (in_id == 1) {
+        ldap_end_time = gettimeofday_ms()
+        time_in_ldap += (ldap_end_time-ldap_start_time)
+    }
+}
+
+probe sdap_acct_req_send
+{
+    if (in_id == 1) {
+        acct_req_types[entry_type]++
+        acct_req_rtime[entry_type] = gettimeofday_ms()
+    }
+}
+
+probe sdap_acct_req_recv
+{
+    if (in_id == 1) {
+        acct_req_times[entry_type] += (gettimeofday_ms() - acct_req_rtime[entry_type])
+    }
+}