Generating timing stats for ntlm_auth

[Phil Mayers]

All,

We're seeing bursts of:

Thu Oct 10 11:52:14 2013 : Info: WARNING: Child is hung for request 
47516341 in component authenticate module peap.

Thu Oct 10 11:52:16 2013 : Info: WARNING: Module rlm_eap became 
unblocked for request 47516341

...since the return of our students this year.

I am 99% sure this is ntlm_auth being slow, and I have a strong 
suspicion this is related to some changes in our AD infrastructure over 
the summer.

In order to prove this to the AD team, I need to gather some timing 
stats for ntlm_auth; can anyone think of an easy way to do this within 
FreeRADIUS?

AFAIK there aren't any xlat that back onto gettimeofday; the various 
request time attribute all expand to the static "request->timestamp" 
value, whereas I want to do wallclock timing.

I could wrap ntlm_auth in a script that times it and lots the info, but 
I'm slightly wary of that - it might perturb the timings.

Any obvious/easy thing I'm missing?

Still on 2.2.0 here... anything in 3.0 I could use?

Cheers,
Phil