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