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