id_perf.stp revision 150a0cc8fe1936002af136e5552ef6cdd210956f
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherglobal runtime_start
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherglobal runtime_end
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherglobal num_transactions
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherglobal time_in_transactions
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherglobal trans_start_time
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherglobal trans_end_time
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherglobal time_in_ldb
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherglobal ldb_start_time
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherglobal ldb_end_time
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherglobal num_ldap_searches
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherglobal time_in_ldap
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherglobal ldap_start_time
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherglobal ldap_end_time
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherglobal acct_req_types
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherglobal acct_req_times
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherglobal acct_req_rtime
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherfunction print_acct_req(req_type)
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher str_req = acct_req_desc(req_type)
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher printf("\tNumber of %s requests: %d\n", str_req, acct_req_types[req_type])
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher printf("\tTime spent in %s requests: %d\n", str_req, acct_req_times[req_type])
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherfunction print_report()
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher max_trans_time = 0
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher max_trans_time_bt = ""
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher total_time = runtime_end - runtime_start
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher printf("Total run time of id was: %d ms\n", total_time)
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher printf("Number of zero-level cache transactions: %d\n", num_transactions)
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher printf("Time spent in level-0 sysdb transactions: %d ms\n", time_in_transactions)
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher printf("Time spent writing to LDB: %d ms\n", time_in_ldb)
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher printf("Number of LDAP searches: %d\n", num_ldap_searches)
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher printf("Time spent waiting for LDAP: %d ms\n", time_in_ldap)
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher printf("LDAP searches breakdown:\n")
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher foreach (req_type in acct_req_types) {
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher print_acct_req(req_type)
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher printf("Unaccounted time: %d ms\n",
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher total_time - time_in_transactions - time_in_ldap)
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher printf("sysdb transaction breakdown:\n")
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher foreach ([b] in bts) {
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher printf("%d hits of transaction %s\n", @count(bts[b]), b)
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher printf("avg:%d min: %d max: %d sum: %d\n\n",
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher @avg(bts[b]), @min(bts[b]), @max(bts[b]), @sum(bts[b]))
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher if (@max(bts[b]) > max_trans_time) {
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher max_trans_time = @max(bts[b])
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher max_trans_time_bt = b
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher if (max_trans_time > 0) {
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher printf("The most expensive transaction breakdown, per transaction:\n")
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher print(@hist_linear(bts[max_trans_time_bt], 0, 500, 50))
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherprobe process("/usr/bin/id").begin
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher num_transactions = 0
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher time_in_transactions = 0
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher num_ldap_searches = 0
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher time_in_ldap = 0
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher time_in_ldb = 0
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher acct_req_types[0x0001] = 0
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher acct_req_types[0x0002] = 0
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher acct_req_types[0x0003] = 0
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher acct_req_times[0x0001] = 0
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher acct_req_times[0x0002] = 0
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher acct_req_times[0x0003] = 0
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher acct_req_rtime[0x0001] = 0
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher acct_req_rtime[0x0002] = 0
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher acct_req_rtime[0x0003] = 0
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher runtime_start = gettimeofday_ms()
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherprobe process("/usr/bin/id").end
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher runtime_end = gettimeofday_ms()
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher print_report()
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherprobe sssd_transaction_start
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher if (nesting == 0 && in_id == 1) {
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher num_transactions++
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher trans_start_time = gettimeofday_ms()
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherprobe sssd_transaction_commit_before
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher if (nesting == 0 && in_id == 1) {
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher ldb_start_time = gettimeofday_ms()
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherprobe sssd_transaction_commit_after
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher if (nesting == 0 && in_id == 1) {
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher ldb_end_time = gettimeofday_ms()
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher time_in_ldb += (ldb_end_time-ldb_start_time)
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher trans_end_time = gettimeofday_ms()
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher time_in_transactions += (trans_end_time-trans_start_time)
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher bt = sprint_ubacktrace()
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher bts[bt] <<< (trans_end_time-trans_start_time)
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherprobe sdap_search_send
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher if (in_id == 1) {
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher num_ldap_searches++
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher ldap_start_time = gettimeofday_ms()
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherprobe sdap_search_recv
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher if (in_id == 1) {
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher ldap_end_time = gettimeofday_ms()
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher time_in_ldap += (ldap_end_time-ldap_start_time)
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherprobe sdap_acct_req_send
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher if (in_id == 1) {
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher acct_req_types[entry_type]++
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher acct_req_rtime[entry_type] = gettimeofday_ms()
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagherprobe sdap_acct_req_recv
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher if (in_id == 1) {
effcbdb12c7ef892f1fd92a745cb33a08ca4ba30Stephen Gallagher acct_req_times[entry_type] += (gettimeofday_ms() - acct_req_rtime[entry_type])