diff options
Diffstat (limited to 'contrib/systemtap')
| -rw-r--r-- | contrib/systemtap/dp_request.stp | 85 | ||||
| -rw-r--r-- | contrib/systemtap/id_perf.stp | 167 | ||||
| -rw-r--r-- | contrib/systemtap/ldap_perf.stp | 114 | ||||
| -rw-r--r-- | contrib/systemtap/nested_group_perf.stp | 333 |
4 files changed, 699 insertions, 0 deletions
diff --git a/contrib/systemtap/dp_request.stp b/contrib/systemtap/dp_request.stp new file mode 100644 index 0000000..0fa1082 --- /dev/null +++ b/contrib/systemtap/dp_request.stp @@ -0,0 +1,85 @@ +/* Start Run with: + * stap -v dp_request.stp + * + * Then reproduce slow login or id/getent in another terminal. + * Ctrl-C running stap once login completes. + * + * Probe tapsets are in /usr/share/systemtap/tapset/sssd.stp + */ + + +global num_dp_requests + +global time_in_dp_req +global elapsed_time +global dp_req_send_start +global dp_req_send_end + +/* Used for tracking slowest request as tz_ctime() only converts seconds, not ms */ +global dp_req_send_sec_start +global dp_req_send_sec_end + +global slowest_req_name +global slowest_req_target +global slowest_req_method +global slowest_req_time = 0 +global slowest_req_start_time +global slowest_req_end_time + +function print_report() +{ + printf("\nEnding Systemtap Run - Providing Summary\n") + printf("Total Number of DP requests: [%d]\n", num_dp_requests) + printf("Total time in DP requests: [%s]\n", msecs_to_string(time_in_dp_req)) + printf("Slowest request data:\n") + printf("\tRequest: [%s]\n", slowest_req_name) + printf("\tTarget: [%s]\n", dp_target_str(slowest_req_target)) + printf("\tMethod: [%s]\n", dp_method_str(slowest_req_method)) + printf("\tStart Time: [%s]\n", tz_ctime(slowest_req_start_time)) + printf("\tEnd Time: [%s]\n", tz_ctime(slowest_req_end_time)) + printf("\tDuration: [%s]\n\n", msecs_to_string(slowest_req_time)) +} + +probe dp_req_send +{ + dp_req_send_start = gettimeofday_ms() + dp_req_send_sec_start = gettimeofday_s() + + printf("\t--> DP Request [%s] sent for domain [%s]\n", dp_req_name, dp_req_domain) + printf("\t--> Target: [%s] - Method: [%s]\n", dp_target_str(dp_req_target), dp_method_str(dp_req_method)) + + num_dp_requests++ +} + +probe dp_req_done +{ + dp_req_send_end = gettimeofday_ms() + dp_req_send_sec_end = gettimeofday_s() + elapsed_time = (dp_req_send_end - dp_req_send_start) + + printf("\t\t DP Request [%s] finished with return code [%d]: [%s]\n", + dp_req_name, dp_ret, dp_errorstr) + printf("\t\t Elapsed time [%s]\n\n", msecs_to_string(elapsed_time)) + + /* Track slowest request information */ + if (elapsed_time > slowest_req_time) { + slowest_req_time = elapsed_time + slowest_req_name = dp_req_name + slowest_req_method = dp_req_method + slowest_req_target = slowest_req_target + slowest_req_start_time = dp_req_send_sec_start + slowest_req_end_time = dp_req_send_sec_end + } + + time_in_dp_req += (dp_req_send_end - dp_req_send_start) +} + +probe begin +{ + printf("\t*** Beginning run! ***\n") +} + +probe end +{ + print_report() +} diff --git a/contrib/systemtap/id_perf.stp b/contrib/systemtap/id_perf.stp new file mode 100644 index 0000000..a778975 --- /dev/null +++ b/contrib/systemtap/id_perf.stp @@ -0,0 +1,167 @@ +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 + } + } + + if (max_trans_time > 0) { + 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]) + } +} diff --git a/contrib/systemtap/ldap_perf.stp b/contrib/systemtap/ldap_perf.stp new file mode 100644 index 0000000..dd24ab5 --- /dev/null +++ b/contrib/systemtap/ldap_perf.stp @@ -0,0 +1,114 @@ +/* Start Run with: + * + * stap ldap_perf.stp + * + * Then reproduce slow operation in another terminal. + * Ctrl-C running stap once login completes. + * + * This script watches all sssd_be processes. This can be limited by + * specifying sssd_be process id + * + * stap -G sssd_be_pid=1234 ldap_perf.stp + * + * Probe tapsets are in /usr/share/systemtap/tapset/sssd.stp + */ + +global start_time; +global sdap_attributes; +global query_attributes; +global sssd_be_pid=0; + +global slowest_request_time; +global slowest_request_filter; +global slowest_request_scope; +global slowest_request_base; +global slowest_request_attrs; + +probe begin +{ + printf("===== ldap queries probe started =====\n"); + id = pid(); + start_time[id] = gettimeofday_us(); + query_attributes[id] = ""; + slowest_request_time = 0; + slowest_request_filter = ""; + slowest_request_scope = 0; + slowest_request_base = ""; + slowest_request_attrs = ""; +} + +probe sdap_parse_entry +{ + id = pid(); + if (sssd_be_pid == 0 || sssd_be_pid == id) { + idx = 0; + while ([id, attr, idx] in sdap_attributes) { + idx++; + } + sdap_attributes[id, attr, idx] = value; + } +} + +probe sdap_parse_entry_done +{ + id = pid(); + if (sssd_be_pid == 0 || sssd_be_pid == id) { + dn = sdap_attributes[id, "OriginalDN", 0]; + printf("[%d] <- dn: %s\n", id, dn); + delete sdap_attributes[id, "OriginalDN", *]; + foreach ([x, attr, idx] in sdap_attributes[id,*,*]) { + printf("[%d] <- %s: %s\n", id, attr, sdap_attributes[x, attr, idx]); + } + delete sdap_attributes[id, *, *]; + } +} + +probe sdap_search_send +{ + id = pid(); + if (sssd_be_pid == 0 || sssd_be_pid == id) { + printf("[%d] -> ldap request: basedn '%s', scope %d, filter '%s'\n", + id, base, scope, filter); + printf("[%d] -> attrs: %s\n", id, attrs); + query_attributes[id] = attrs; + start_time[id] = gettimeofday_ms(); + delete sdap_attributes[id, *, *]; + } +} + + +probe sdap_search_recv +{ + id = pid(); + if (sssd_be_pid == 0 || sssd_be_pid == id) { + delta = gettimeofday_ms() - start_time[id]; + printf("[%d] ldap response to request: basedn '%s', scope %d, filter '%s'\n", + id, base, scope, filter); + printf("[%d] took: %d ms\n", id, delta); + printf("[%d]--------------------------------------------------\n", id); + + if (slowest_request_time < delta) { + slowest_request_time = delta; + slowest_request_base = base; + slowest_request_scope = scope; + slowest_request_filter = filter; + slowest_request_attrs = query_attributes[id]; + } + } +} + +probe process("/usr/libexec/sssd/sssd_be").end +{ + printf("done\n"); +} + +probe end +{ + printf("\n===== slowest ldap request =====\n"); + printf("base: '%s'\nscope: %d\nfilter: '%s'\nattrs: %s\ntook: %d ms\n", + slowest_request_base, + slowest_request_scope, + slowest_request_filter, + slowest_request_attrs, + slowest_request_time); +} diff --git a/contrib/systemtap/nested_group_perf.stp b/contrib/systemtap/nested_group_perf.stp new file mode 100644 index 0000000..0c7ff03 --- /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() +} |