From 250966c2abc53e5633ebaf61f847ef006dd53764 Mon Sep 17 00:00:00 2001 From: Jakub Hrozek Date: Mon, 29 Feb 2016 16:32:24 +0100 Subject: [PATCH 07/10] 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 --- Makefile.am | 5 ++ contrib/systemtap/id_perf.stp | 165 ++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 170 insertions(+) create mode 100644 contrib/systemtap/id_perf.stp diff --git a/Makefile.am b/Makefile.am index e0b01190cde7933fdd9cbfb617a201da85f367ab..1d21b97ff56551f680f1a4942f6a2c0bb8be31ef 100644 --- a/Makefile.am +++ b/Makefile.am @@ -54,6 +54,7 @@ endif sssdconfdir = $(sysconfdir)/sssd sssddatadir = $(datadir)/sssd sssdapiplugindir = $(sssddatadir)/sssd.api.d +sssdtapscriptdir = $(sssddatadir)/systemtap dbuspolicydir = $(sysconfdir)/dbus-1/system.d dbusservicedir = $(datadir)/dbus-1/system-services sss_statedir = $(localstatedir)/lib/sss @@ -1108,6 +1109,10 @@ CLEANFILES += stap_generated_probes.h \ $(NULL) endif +dist_sssdtapscript_DATA = \ + contrib/systemtap/id_perf.stp \ + $(NULL) + #################### # Sbus Codegen # #################### diff --git a/contrib/systemtap/id_perf.stp b/contrib/systemtap/id_perf.stp new file mode 100644 index 0000000000000000000000000000000000000000..0ad619506f65cc0cafc4825bc82da509a47bb011 --- /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]) + } +} -- 2.4.11