Hmm this is neat and could be pretty damn useful. 

What about making this happen using a request control? Meaning if an operation is issued with the TRACE request control then turn on the production and output to the logs of such trace information? The control is a simple marker control. This would reduce the amount of noise and logging overhead if your'e interested in specific operations.

What would be uber bad-assery would be to collect this information and report it not only in the logs but to return it in a buffer with a response control. This makes sense to inspect production system issues that are misbehaving without a shutdown. 

Another idea in leu or in addition would be to enable some parameters in the configuration that could hot enable/disable this feature.

In both cases, you would not have to shutdown the server and would still have fine grained control over the quantity of logs produced with trace information.

Just some thoughts.



On Thu, May 16, 2013 at 2:28 PM, Pierre-Arnaud Marcelot <pa@marcelot.net> wrote:
Hi Emmanuel,

That's an interesting option.

Regards,
Pierre-Arnaud

On 8 mai 2013, at 12:48, Emmanuel Lécharny <elecharny@gmail.com> wrote:

> Hi guys,
>
> FYI, I have added some timing for each operation. This is not activated
> by default you have to modify the log4j.properties to get it :
>
> log4j.logger.org.apache.directory.server.OPERATION_TIME=DEBUG
>
> will produces such logs :
>
> [12:41:28] DEBUG [org.apache.directory.server.OPERATION_TIME] - Add
> operation took 28404000 ns
> [12:41:28] DEBUG [org.apache.directory.server.OPERATION_TIME] - Lookup
> operation took 500000 ns
> [12:41:28] DEBUG [org.apache.directory.server.OPERATION_TIME] - Lookup
> operation took 278000 ns
> [12:41:28] DEBUG [org.apache.directory.server.OPERATION_TIME] - Lookup
> operation took 590000 ns
> [12:41:28] DEBUG [org.apache.directory.server.OPERATION_TIME] - Bind
> operation took 7820000 ns
> [12:41:28] DEBUG [org.apache.directory.server.OPERATION_TIME] - Unbind
> operation took 81000 ns
> [12:41:28] DEBUG [org.apache.directory.server.OPERATION_TIME] - Lookup
> operation took 305000 ns
> [12:41:28] DEBUG [org.apache.directory.server.OPERATION_TIME] - Bind
> operation took 94000 ns
> [12:41:28] DEBUG [org.apache.directory.server.OPERATION_TIME] - Unbind
> operation took 22000 ns
> ...
>
> This could be useful for gathering the operation and tell how much time
> it took to process eah operation.
>
> I'm considering offering more information, like the specific operation,
> but this would be much verbose.
>
> I will commit that soon.
>
> --
> Regards,
> Cordialement,
> Emmanuel Lécharny
> www.iktek.com
>




--
Best Regards,
-- Alex