Stephen provided Alexander and myself with debug output. I quickly wrote a little script to parse the output looking for the session timestamps, what commands were executed for each RPC, and computed the duration of the RPC. Note the timestamps only have 1 second resolution, something which would be easy to fix, so bear that in mind when looking at the output of the script.

The script first lists every command executed in the RPC (including internal commands), which is then followed by the duration for the RPC.

From the error_log it appears as if the session cache is being used for all RPC commands.


--
John Dennis <jden...@redhat.com>

Looking to carve out IT costs?
www.redhat.com/carveoutcosts/


commands:
batch(({u'params': [[], {}], u'method': u'i18n_messages'}, {u'params': [[], 
{u'all': True, u'whoami': True}], u'method': u'user_find'}, {u'params': [[], 
{}], u'method': u'env'}, {u'params': [[], {}], u'method': u'dns_is_enabled'}))
i18n_messages()
user_find(None, whoami=True, all=True)
env(None)
dns_is_enabled()
command duration: 0:00:02

commands:
json_metadata(None, None, command=u'all')
json_metadata(None, None, object=u'all')
command duration: 0:00:03

commands:
user_find(None, sizelimit=0, pkey_only=True)
command duration: 0:00:01

commands:
batch(({u'params': [[u'admin'], {u'all': True}], u'method': u'user_show'}, 
{u'params': [[u'alyce'], {u'all': True}], u'method': u'user_show'}, {u'params': 
[[u'apickens'], {u'all': True}], u'method': u'user_show'}, {u'params': 
[[u'carolyn'], {u'all': True}], u'method': u'user_show'}, {u'params': 
[[u'carolynvm'], {u'all': True}], u'method': u'user_show'}, {u'params': 
[[u'cwoodring'], {u'all': True}], u'method': u'user_show'}, {u'params': 
[[u'cyrus'], {u'all': True}], u'method': u'user_show'}, {u'params': 
[[u'dawnselleck'], {u'all': True}], u'method': u'user_show'}, {u'params': 
[[u'doug'], {u'all': True}], u'method': u'user_show'}, {u'params': [[u'erika'], 
{u'all': True}], u'method': u'user_show'}, {u'params': [[u'jbn'], {u'all': 
True}], u'method': u'user_show'}, {u'params': [[u'jessica'], {u'all': True}], 
u'method': u'user_show'}, {u'params': [[u'jimmy'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'john'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'jschiefer'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'jshirkani'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'kaline'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'kaline2'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'kbiorac'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'ken'], {u'all': True}], u'method': 
u'user_show'}))
user_show(u'admin', all=True)
user_show(u'alyce', all=True)
user_show(u'apickens', all=True)
user_show(u'carolyn', all=True)
user_show(u'carolynvm', all=True)
user_show(u'cwoodring', all=True)
user_show(u'cyrus', all=True)
user_show(u'dawnselleck', all=True)
user_show(u'doug', all=True)
user_show(u'erika', all=True)
user_show(u'jbn', all=True)
user_show(u'jessica', all=True)
user_show(u'jimmy', all=True)
user_show(u'john', all=True)
user_show(u'jschiefer', all=True)
user_show(u'jshirkani', all=True)
user_show(u'kaline', all=True)
user_show(u'kaline2', all=True)
user_show(u'kbiorac', all=True)
user_show(u'ken', all=True)
command duration: 0:00:01

commands:
user_find(None, sizelimit=0, pkey_only=True)
command duration: 0:00:01

commands:
batch(({u'params': [[u'kenbrisbin'], {u'all': True}], u'method': u'user_show'}, 
{u'params': [[u'lbrown'], {u'all': True}], u'method': u'user_show'}, 
{u'params': [[u'lew'], {u'all': True}], u'method': u'user_show'}, {u'params': 
[[u'lisa'], {u'all': True}], u'method': u'user_show'}, {u'params': [[u'liz'], 
{u'all': True}], u'method': u'user_show'}, {u'params': [[u'manerriza'], 
{u'all': True}], u'method': u'user_show'}, {u'params': [[u'mastering'], 
{u'all': True}], u'method': u'user_show'}, {u'params': [[u'mustangsally27'], 
{u'all': True}], u'method': u'user_show'}, {u'params': [[u'nancy'], {u'all': 
True}], u'method': u'user_show'}, {u'params': [[u'ngimblin'], {u'all': True}], 
u'method': u'user_show'}, {u'params': [[u'om'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'orderskb'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'pmccuin'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'reinmiller'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'reinmiller2'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'renee'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'robertson'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'robertson2'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'royer'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'ruben'], {u'all': True}], u'method': 
u'user_show'}))
user_show(u'kenbrisbin', all=True)
user_show(u'lbrown', all=True)
user_show(u'lew', all=True)
user_show(u'lisa', all=True)
user_show(u'liz', all=True)
user_show(u'manerriza', all=True)
user_show(u'mastering', all=True)
user_show(u'mustangsally27', all=True)
user_show(u'nancy', all=True)
user_show(u'ngimblin', all=True)
user_show(u'om', all=True)
user_show(u'orderskb', all=True)
user_show(u'pmccuin', all=True)
user_show(u'reinmiller', all=True)
user_show(u'reinmiller2', all=True)
user_show(u'renee', all=True)
user_show(u'robertson', all=True)
user_show(u'robertson2', all=True)
user_show(u'royer', all=True)
user_show(u'ruben', all=True)
command duration: 0:00:01

commands:
user_find(None, sizelimit=0, pkey_only=True)
command duration: 0:00:01

commands:
batch(({u'params': [[u'scalvert'], {u'all': True}], u'method': u'user_show'}, 
{u'params': [[u'snunez'], {u'all': True}], u'method': u'user_show'}, 
{u'params': [[u'srazai'], {u'all': True}], u'method': u'user_show'}, 
{u'params': [[u'stephen'], {u'all': True}], u'method': u'user_show'}, 
{u'params': [[u'steve'], {u'all': True}], u'method': u'user_show'}, {u'params': 
[[u'tchatterfield'], {u'all': True}], u'method': u'user_show'}, {u'params': 
[[u'tim'], {u'all': True}], u'method': u'user_show'}, {u'params': [[u'todd'], 
{u'all': True}], u'method': u'user_show'}, {u'params': [[u'vinnyr'], {u'all': 
True}], u'method': u'user_show'}))
user_show(u'scalvert', all=True)
user_show(u'snunez', all=True)
user_show(u'srazai', all=True)
user_show(u'stephen', all=True)
user_show(u'steve', all=True)
user_show(u'tchatterfield', all=True)
user_show(u'tim', all=True)
user_show(u'todd', all=True)
user_show(u'vinnyr', all=True)
command duration: 0:00:02

commands:
user_find(None, sizelimit=0, pkey_only=True)
command duration: 0:00:01

commands:
batch(({u'params': [[u'kenbrisbin'], {u'all': True}], u'method': u'user_show'}, 
{u'params': [[u'lbrown'], {u'all': True}], u'method': u'user_show'}, 
{u'params': [[u'lew'], {u'all': True}], u'method': u'user_show'}, {u'params': 
[[u'lisa'], {u'all': True}], u'method': u'user_show'}, {u'params': [[u'liz'], 
{u'all': True}], u'method': u'user_show'}, {u'params': [[u'manerriza'], 
{u'all': True}], u'method': u'user_show'}, {u'params': [[u'mastering'], 
{u'all': True}], u'method': u'user_show'}, {u'params': [[u'mustangsally27'], 
{u'all': True}], u'method': u'user_show'}, {u'params': [[u'nancy'], {u'all': 
True}], u'method': u'user_show'}, {u'params': [[u'ngimblin'], {u'all': True}], 
u'method': u'user_show'}, {u'params': [[u'om'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'orderskb'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'pmccuin'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'reinmiller'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'reinmiller2'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'renee'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'robertson'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'robertson2'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'royer'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'ruben'], {u'all': True}], u'method': 
u'user_show'}))
user_show(u'kenbrisbin', all=True)
user_show(u'lbrown', all=True)
user_show(u'lew', all=True)
user_show(u'lisa', all=True)
user_show(u'liz', all=True)
user_show(u'manerriza', all=True)
user_show(u'mastering', all=True)
user_show(u'mustangsally27', all=True)
user_show(u'nancy', all=True)
user_show(u'ngimblin', all=True)
user_show(u'om', all=True)
user_show(u'orderskb', all=True)
user_show(u'pmccuin', all=True)
user_show(u'reinmiller', all=True)
user_show(u'reinmiller2', all=True)
user_show(u'renee', all=True)
user_show(u'robertson', all=True)
user_show(u'robertson2', all=True)
user_show(u'royer', all=True)
user_show(u'ruben', all=True)
command duration: 0:00:02

commands:
user_find(None, sizelimit=0, pkey_only=True)
command duration: 0:00:01

commands:
batch(({u'params': [[u'admin'], {u'all': True}], u'method': u'user_show'}, 
{u'params': [[u'alyce'], {u'all': True}], u'method': u'user_show'}, {u'params': 
[[u'apickens'], {u'all': True}], u'method': u'user_show'}, {u'params': 
[[u'carolyn'], {u'all': True}], u'method': u'user_show'}, {u'params': 
[[u'carolynvm'], {u'all': True}], u'method': u'user_show'}, {u'params': 
[[u'cwoodring'], {u'all': True}], u'method': u'user_show'}, {u'params': 
[[u'cyrus'], {u'all': True}], u'method': u'user_show'}, {u'params': 
[[u'dawnselleck'], {u'all': True}], u'method': u'user_show'}, {u'params': 
[[u'doug'], {u'all': True}], u'method': u'user_show'}, {u'params': [[u'erika'], 
{u'all': True}], u'method': u'user_show'}, {u'params': [[u'jbn'], {u'all': 
True}], u'method': u'user_show'}, {u'params': [[u'jessica'], {u'all': True}], 
u'method': u'user_show'}, {u'params': [[u'jimmy'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'john'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'jschiefer'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'jshirkani'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'kaline'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'kaline2'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'kbiorac'], {u'all': True}], u'method': 
u'user_show'}, {u'params': [[u'ken'], {u'all': True}], u'method': 
u'user_show'}))
user_show(u'admin', all=True)
user_show(u'alyce', all=True)
user_show(u'apickens', all=True)
user_show(u'carolyn', all=True)
user_show(u'carolynvm', all=True)
user_show(u'cwoodring', all=True)
user_show(u'cyrus', all=True)
user_show(u'dawnselleck', all=True)
user_show(u'doug', all=True)
user_show(u'erika', all=True)
user_show(u'jbn', all=True)
user_show(u'jessica', all=True)
user_show(u'jimmy', all=True)
user_show(u'john', all=True)
user_show(u'jschiefer', all=True)
user_show(u'jshirkani', all=True)
user_show(u'kaline', all=True)
user_show(u'kaline2', all=True)
user_show(u'kbiorac', all=True)
user_show(u'ken', all=True)
command duration: 0:00:01

commands:
host_find(None, sizelimit=0, pkey_only=True)
command duration: 0:00:01

commands:
batch(({u'params': [[u'ec2-50-112-97-127.us-west-2.compute.amazonaws.com'], 
{u'all': True}], u'method': u'host_show'}, {u'params': 
[[u'ec2-50-112-98-233.us-west-2.compute.amazonaws.com'], {u'all': True}], 
u'method': u'host_show'}, {u'params': [[u'imap.host17.net'], {u'all': True}], 
u'method': u'host_show'}, {u'params': [[u'imap1.host17.net'], {u'all': True}], 
u'method': u'host_show'}, {u'params': [[u'imap2.host17.net'], {u'all': True}], 
u'method': u'host_show'}, {u'params': [[u'imap2r.host17.net'], {u'all': True}], 
u'method': u'host_show'}, {u'params': [[u'ipa1.host17.net'], {u'all': True}], 
u'method': u'host_show'}, {u'params': [[u'murder.host17.net'], {u'all': True}], 
u'method': u'host_show'}, {u'params': [[u'mx1.host17.net'], {u'all': True}], 
u'method': u'host_show'}, {u'params': [[u'policy1.host17.net'], {u'all': 
True}], u'method': u'host_show'}, {u'params': [[u'shared1.host17.net'], 
{u'all': True}], u'method': u'host_show'}, {u'params': 
[[u'sitebuilder.host17.net'], {u'all': True}], u'method': u'host_show'}, 
{u'params': [[u'smtp.host17.net'], {u'all': True}], u'method': u'host_show'}, 
{u'params': [[u'smtp1.host17.net'], {u'all': True}], u'method': u'host_show'}, 
{u'params': [[u'smtp2.host17.net'], {u'all': True}], u'method': u'host_show'}, 
{u'params': [[u'sso.host17.net'], {u'all': True}], u'method': u'host_show'}, 
{u'params': [[u'webmail.host17.net'], {u'all': True}], u'method': 
u'host_show'}))
host_show(u'ec2-50-112-97-127.us-west-2.compute.amazonaws.com', all=True)
host_show(u'ec2-50-112-98-233.us-west-2.compute.amazonaws.com', all=True)
host_show(u'imap.host17.net', all=True)
host_show(u'imap1.host17.net', all=True)
host_show(u'imap2.host17.net', all=True)
host_show(u'imap2r.host17.net', all=True)
host_show(u'ipa1.host17.net', all=True)
host_show(u'murder.host17.net', all=True)
host_show(u'mx1.host17.net', all=True)
host_show(u'policy1.host17.net', all=True)
host_show(u'shared1.host17.net', all=True)
host_show(u'sitebuilder.host17.net', all=True)
host_show(u'smtp.host17.net', all=True)
host_show(u'smtp1.host17.net', all=True)
host_show(u'smtp2.host17.net', all=True)
host_show(u'sso.host17.net', all=True)
host_show(u'webmail.host17.net', all=True)
command duration: 0:00:02

commands:
service_find(None, sizelimit=0, pkey_only=True)
command duration: 0:00:01

_______________________________________________
Freeipa-devel mailing list
Freeipa-devel@redhat.com
https://www.redhat.com/mailman/listinfo/freeipa-devel

Reply via email to