[Freeipa-devel] slow response

[Stephen Ingram]

On Mon, Jul 30, 2012 at 3:27 PM, John Dennis <jdennis at redhat.com> wrote:
> 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).

Just out of curiosity, were any, or, all of these, changes from the
way things were handled in 2.1?

> 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

Steve