[Freeipa-devel] slow response

[John Dennis]

Stephen finally got his server patched with my timing instrumentation. 
He sent me his log file and I ran my script to parse it. The results are 
quite interesting.

Basically I timed two things

cmd_duration is the elapsed time to execute the IPA command.

json_duration is the elapsed time to execute the JSON RPC containing the 
IPA command. The difference (delta) between the two is the time we spend 
doing "session bookkeeping". In all but the first RPC we were executing 
from the session cache. Results are below.

What is interesting is every command that executes from the session 
cache seems to have about a 1.5 second constant overhead. The other 
interesting bits are that most commands in the server execute quickly 
(from under a tenth of second to .3 second) and on average the server 
takes 1.5 seconds to respond to RPC (of which most of it appears to be 
in session code).

What is taking so long with session bookkeeping? I don't know yet. I 
would need more timing instrumentation. I will say when I looked at the 
python-krb5 code (which we use to populate the ccache from the session 
and read back to store in the session) seemed to be remarkably 
inefficient. We also elected to use file based ccache rather than 
in-memory ccache (that means there is a bit of file-IO occurring).

Has anyone used a Python profiler? Would that be better than adding 
instrumentation?

BTW, the actual commands were stripped to protect data anonymity.

cmd_duration: 0.107673 json_duration: 3.176758 delta: 3.069085
cmd_duration: 0.020068 json_duration: 1.543135 delta: 1.523067
cmd_duration: 0.387210 json_duration: 1.802954 delta: 1.415744
cmd_duration: 0.024086 json_duration: 1.405276 delta: 1.381190
cmd_duration: 0.342808 json_duration: 1.950365 delta: 1.607557
cmd_duration: 0.019286 json_duration: 1.398786 delta: 1.379500
cmd_duration: 0.200895 json_duration: 1.754358 delta: 1.553463
cmd_duration: 0.020293 json_duration: 1.410701 delta: 1.390408
cmd_duration: 0.383433 json_duration: 1.819478 delta: 1.436045
cmd_duration: 0.020350 json_duration: 1.406038 delta: 1.385688
cmd_duration: 0.346864 json_duration: 1.771281 delta: 1.424417
cmd_duration: 0.015998 json_duration: 1.707743 delta: 1.691745
cmd_duration: 0.314527 json_duration: 1.730894 delta: 1.416367
cmd_duration: 0.025323 json_duration: 1.582828 delta: 1.557505

-- 
John Dennis <jdennis at redhat.com>

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