001/*
002 *  Licensed to the Apache Software Foundation (ASF) under one
003 *  or more contributor license agreements.  See the NOTICE file
004 *  distributed with this work for additional information
005 *  regarding copyright ownership.  The ASF licenses this file
006 *  to you under the Apache License, Version 2.0 (the
007 *  "License"); you may not use this file except in compliance
008 *  with the License.  You may obtain a copy of the License at
009 * 
010 *    http://www.apache.org/licenses/LICENSE-2.0
011 * 
012 *  Unless required by applicable law or agreed to in writing,
013 *  software distributed under the License is distributed on an
014 *  "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
015 *  KIND, either express or implied.  See the License for the
016 *  specific language governing permissions and limitations
017 *  under the License.
018 * 
019 */
020package org.apache.directory.server.core.logger;
021
022
023import java.util.concurrent.atomic.AtomicInteger;
024import java.util.concurrent.atomic.AtomicLong;
025
026import org.apache.directory.api.ldap.model.constants.Loggers;
027import org.apache.directory.api.ldap.model.entry.Entry;
028import org.apache.directory.api.ldap.model.exception.LdapException;
029import org.apache.directory.server.core.api.DirectoryService;
030import org.apache.directory.server.core.api.filtering.EntryFilteringCursor;
031import org.apache.directory.server.core.api.interceptor.BaseInterceptor;
032import org.apache.directory.server.core.api.interceptor.context.AddOperationContext;
033import org.apache.directory.server.core.api.interceptor.context.BindOperationContext;
034import org.apache.directory.server.core.api.interceptor.context.CompareOperationContext;
035import org.apache.directory.server.core.api.interceptor.context.DeleteOperationContext;
036import org.apache.directory.server.core.api.interceptor.context.GetRootDseOperationContext;
037import org.apache.directory.server.core.api.interceptor.context.HasEntryOperationContext;
038import org.apache.directory.server.core.api.interceptor.context.LookupOperationContext;
039import org.apache.directory.server.core.api.interceptor.context.ModifyOperationContext;
040import org.apache.directory.server.core.api.interceptor.context.MoveAndRenameOperationContext;
041import org.apache.directory.server.core.api.interceptor.context.MoveOperationContext;
042import org.apache.directory.server.core.api.interceptor.context.RenameOperationContext;
043import org.apache.directory.server.core.api.interceptor.context.SearchOperationContext;
044import org.apache.directory.server.core.api.interceptor.context.UnbindOperationContext;
045import org.slf4j.Logger;
046import org.slf4j.LoggerFactory;
047
048
049/**
050 * An interceptor used to log times to process each operation.
051 * 
052 * The way it works is that it gathers the time to process an operation
053 * into a global counter, which is logged every 1000 operations (when
054 * using the OPERATION_STATS logger). It's also possible to get the time for
055 * each single operation if activating the OPERATION_TIME logger.
056 * 
057 * Thos two loggers must be set to DEBUG.
058 * 
059 * @author <a href="mailto:dev@directory.apache.org">Apache Directory Project</a>
060 */
061public class TimerInterceptor extends BaseInterceptor
062{
063    /** A aggregating logger */
064    private static final Logger OPERATION_STATS = LoggerFactory.getLogger( Loggers.OPERATION_STAT.getName() );
065
066    /** An operation logger */
067    private static final Logger OPERATION_TIME = LoggerFactory.getLogger( Loggers.OPERATION_TIME.getName() );
068
069    /** Speedup for logs */
070    private static final boolean IS_DEBUG_STATS = OPERATION_STATS.isDebugEnabled();
071    private static final boolean IS_DEBUG_TIME = OPERATION_TIME.isDebugEnabled();
072
073    /** Stats for the add operation */
074    private static AtomicLong totalAdd = new AtomicLong( 0 );
075    private static AtomicInteger nbAddCalls = new AtomicInteger( 0 );
076
077    /** Stats for the bind operation */
078    private static AtomicLong totalBind = new AtomicLong( 0 );
079    private static AtomicInteger nbBindCalls = new AtomicInteger( 0 );
080
081    /** Stats for the compare operation */
082    private static AtomicLong totalCompare = new AtomicLong( 0 );
083    private static AtomicInteger nbCompareCalls = new AtomicInteger( 0 );
084
085    /** Stats for the delete operation */
086    private static AtomicLong totalDelete = new AtomicLong( 0 );
087    private static AtomicInteger nbDeleteCalls = new AtomicInteger( 0 );
088
089    /** Stats for the GetRootDse operation */
090    private static AtomicLong totalGetRootDse = new AtomicLong( 0 );
091    private static AtomicInteger nbGetRootDseCalls = new AtomicInteger( 0 );
092
093    /** Stats for the HasEntry operation */
094    private static AtomicLong totalHasEntry = new AtomicLong( 0 );
095    private static AtomicInteger nbHasEntryCalls = new AtomicInteger( 0 );
096
097    /** Stats for the lookup operation */
098    private static AtomicLong totalLookup = new AtomicLong( 0 );
099    private static AtomicInteger nbLookupCalls = new AtomicInteger( 0 );
100
101    /** Stats for the modify operation */
102    private static AtomicLong totalModify = new AtomicLong( 0 );
103    private static AtomicInteger nbModifyCalls = new AtomicInteger( 0 );
104
105    /** Stats for the move operation */
106    private static AtomicLong totalMove = new AtomicLong( 0 );
107    private static AtomicInteger nbMoveCalls = new AtomicInteger( 0 );
108
109    /** Stats for the moveAndRename operation */
110    private static AtomicLong totalMoveAndRename = new AtomicLong( 0 );
111    private static AtomicInteger nbMoveAndRenameCalls = new AtomicInteger( 0 );
112
113    /** Stats for the rename operation */
114    private static AtomicLong totalRename = new AtomicLong( 0 );
115    private static AtomicInteger nbRenameCalls = new AtomicInteger( 0 );
116
117    /** Stats for the search operation */
118    private static AtomicLong totalSearch = new AtomicLong( 0 );
119    private static AtomicInteger nbSearchCalls = new AtomicInteger( 0 );
120
121    /** Stats for the unbind operation */
122    private static AtomicLong totalUnbind = new AtomicLong( 0 );
123    private static AtomicInteger nbUnbindCalls = new AtomicInteger( 0 );
124
125
126    /**
127     * 
128     * Creates a new instance of TimerInterceptor.
129     *
130     * @param name This interceptor's getName()
131     */
132    public TimerInterceptor( String name )
133    {
134        super( name );
135    }
136
137
138    /**
139     * {@inheritDoc}
140     */
141    @Override
142    public void init( DirectoryService directoryService ) throws LdapException
143    {
144    }
145
146
147    /**
148     * {@inheritDoc}
149     */
150    @Override
151    public void add( AddOperationContext addContext ) throws LdapException
152    {
153        long t0 = System.nanoTime();
154        next( addContext );
155        long delta = System.nanoTime() - t0;
156
157        if ( IS_DEBUG_STATS )
158        {
159            nbAddCalls.incrementAndGet();
160            totalAdd.getAndAdd( delta );
161
162            if ( nbAddCalls.get() % 1000 == 0 )
163            {
164                long average = totalAdd.get() / ( nbAddCalls.get() * 1000 );
165                OPERATION_STATS.debug( "{} : Average add = {} microseconds, nb adds = {}", getName(), average,
166                    nbAddCalls.get() );
167            }
168        }
169
170        if ( IS_DEBUG_TIME )
171        {
172            OPERATION_TIME.debug( "{} : Delta add = {}", getName(), delta );
173        }
174    }
175
176
177    /**
178     * {@inheritDoc}
179     */
180    @Override
181    public void bind( BindOperationContext bindContext ) throws LdapException
182    {
183        long t0 = System.nanoTime();
184        next( bindContext );
185        long delta = System.nanoTime() - t0;
186
187        if ( IS_DEBUG_STATS )
188        {
189            nbBindCalls.incrementAndGet();
190            totalBind.getAndAdd( delta );
191
192            if ( nbBindCalls.get() % 1000 == 0 )
193            {
194                long average = totalBind.get() / ( nbBindCalls.get() * 1000 );
195                OPERATION_STATS.debug( "{} : Average bind = {} microseconds, nb binds = {}", getName(), average,
196                    nbBindCalls.get() );
197            }
198        }
199
200        if ( IS_DEBUG_TIME )
201        {
202            OPERATION_TIME.debug( "{} : Delta bind = {}", getName(), delta );
203        }
204    }
205
206
207    /**
208     * {@inheritDoc}
209     */
210    @Override
211    public boolean compare( CompareOperationContext compareContext ) throws LdapException
212    {
213        long t0 = System.nanoTime();
214        boolean compare = next( compareContext );
215        long delta = System.nanoTime() - t0;
216
217        if ( IS_DEBUG_STATS )
218        {
219            nbCompareCalls.incrementAndGet();
220            totalCompare.getAndAdd( delta );
221
222            if ( nbCompareCalls.get() % 1000 == 0 )
223            {
224                long average = totalCompare.get() / ( nbCompareCalls.get() * 1000 );
225                OPERATION_STATS.debug( "{} : Average compare = {} microseconds, nb compares = {}", getName(), average,
226                    nbCompareCalls.get() );
227            }
228        }
229
230        if ( IS_DEBUG_TIME )
231        {
232            OPERATION_TIME.debug( "{} : Delta compare = {}", getName(), delta );
233        }
234
235        return compare;
236    }
237
238
239    /**
240     * {@inheritDoc}
241     */
242    @Override
243    public void delete( DeleteOperationContext deleteContext ) throws LdapException
244    {
245        long t0 = System.nanoTime();
246        next( deleteContext );
247        long delta = System.nanoTime() - t0;
248
249        if ( IS_DEBUG_STATS )
250        {
251            nbDeleteCalls.incrementAndGet();
252            totalDelete.getAndAdd( delta );
253
254            if ( nbDeleteCalls.get() % 1000 == 0 )
255            {
256                long average = totalDelete.get() / ( nbDeleteCalls.get() * 1000 );
257                OPERATION_STATS.debug( "{} : Average delete = {} microseconds, nb deletes = {}", getName(), average,
258                    nbDeleteCalls.get() );
259            }
260        }
261
262        if ( IS_DEBUG_TIME )
263        {
264            OPERATION_TIME.debug( "{} : Delta delete = {}", getName(), delta );
265        }
266    }
267
268
269    /**
270     * {@inheritDoc}
271     */
272    @Override
273    public Entry getRootDse( GetRootDseOperationContext getRootDseContext ) throws LdapException
274    {
275        long t0 = System.nanoTime();
276        Entry rootDse = next( getRootDseContext );
277        long delta = System.nanoTime() - t0;
278
279        if ( IS_DEBUG_STATS )
280        {
281            nbGetRootDseCalls.incrementAndGet();
282            totalGetRootDse.getAndAdd( delta );
283
284            if ( nbGetRootDseCalls.get() % 1000 == 0 )
285            {
286                long average = totalGetRootDse.get() / ( nbGetRootDseCalls.get() * 1000 );
287                OPERATION_STATS.debug( "{} : Average getRootDSE = {} microseconds, nb getRootDSEs = {}", getName(),
288                    average, nbGetRootDseCalls.get() );
289            }
290        }
291
292        if ( IS_DEBUG_TIME )
293        {
294            OPERATION_TIME.debug( "{} : Delta getRootDSE = {}", getName(), delta );
295        }
296
297        return rootDse;
298    }
299
300
301    /**
302     * {@inheritDoc}
303     */
304    @Override
305    public boolean hasEntry( HasEntryOperationContext hasEntryContext ) throws LdapException
306    {
307        long t0 = System.nanoTime();
308        boolean hasEntry = next( hasEntryContext );
309        long delta = System.nanoTime() - t0;
310
311        if ( IS_DEBUG_STATS )
312        {
313            nbHasEntryCalls.incrementAndGet();
314            totalHasEntry.getAndAdd( delta );
315
316            if ( nbHasEntryCalls.get() % 1000 == 0 )
317            {
318                long average = totalHasEntry.get() / ( nbHasEntryCalls.get() * 1000 );
319                OPERATION_STATS.debug( "{} : Average hasEntry = {} microseconds, nb hasEntrys = {}", getName(), average,
320                    nbHasEntryCalls.get() );
321            }
322        }
323
324        if ( IS_DEBUG_TIME )
325        {
326            OPERATION_TIME.debug( "{} : Delta hasEntry = {}", getName(), delta );
327        }
328
329        return hasEntry;
330    }
331
332
333    /**
334     * {@inheritDoc}
335     */
336    @Override
337    public Entry lookup( LookupOperationContext lookupContext ) throws LdapException
338    {
339        long t0 = System.nanoTime();
340        Entry entry = next( lookupContext );
341        long delta = System.nanoTime() - t0;
342
343        if ( IS_DEBUG_STATS )
344        {
345            nbLookupCalls.incrementAndGet();
346            totalLookup.getAndAdd( delta );
347
348            if ( nbLookupCalls.get() % 1000 == 0 )
349            {
350                long average = totalLookup.get() / ( nbLookupCalls.get() * 1000 );
351                OPERATION_STATS.debug( "{} : Average lookup = {} microseconds, nb lookups = {}", getName(), average,
352                    nbLookupCalls.get() );
353            }
354        }
355
356        if ( IS_DEBUG_TIME )
357        {
358            OPERATION_TIME.debug( "{} : Delta lookup = {}", getName(), delta );
359        }
360
361        return entry;
362    }
363
364
365    /**
366     * {@inheritDoc}
367     */
368    @Override
369    public void modify( ModifyOperationContext modifyContext ) throws LdapException
370    {
371        long t0 = System.nanoTime();
372        next( modifyContext );
373        long delta = System.nanoTime() - t0;
374
375        if ( IS_DEBUG_STATS )
376        {
377            nbModifyCalls.incrementAndGet();
378            totalModify.getAndAdd( delta );
379
380            if ( nbModifyCalls.get() % 1000 == 0 )
381            {
382                long average = totalModify.get() / ( nbModifyCalls.get() * 1000 );
383                OPERATION_STATS.debug( "{} : Average modify = {} microseconds, nb modifys = {}", getName(), average,
384                    nbModifyCalls.get() );
385            }
386        }
387
388        if ( IS_DEBUG_TIME )
389        {
390            OPERATION_TIME.debug( "{} : Delta modify = {}", getName(), delta );
391        }
392    }
393
394
395    /**
396     * {@inheritDoc}
397     */
398    @Override
399    public void move( MoveOperationContext moveContext ) throws LdapException
400    {
401        long t0 = System.nanoTime();
402        next( moveContext );
403        long delta = System.nanoTime() - t0;
404
405        if ( IS_DEBUG_STATS )
406        {
407            nbMoveCalls.incrementAndGet();
408            totalMove.getAndAdd( delta );
409
410            if ( nbMoveCalls.get() % 1000 == 0 )
411            {
412                long average = totalMove.get() / ( nbMoveCalls.get() * 1000 );
413                OPERATION_STATS.debug( "{} : Average move = {} microseconds, nb moves = {}", getName(), average,
414                    nbMoveCalls.get() );
415            }
416        }
417
418        if ( IS_DEBUG_TIME )
419        {
420            OPERATION_TIME.debug( "{} : Delta move = {}", getName(), delta );
421        }
422    }
423
424
425    /**
426     * {@inheritDoc}
427     */
428    @Override
429    public void moveAndRename( MoveAndRenameOperationContext moveAndRenameContext ) throws LdapException
430    {
431        long t0 = System.nanoTime();
432        next( moveAndRenameContext );
433        long delta = System.nanoTime() - t0;
434
435        if ( IS_DEBUG_STATS )
436        {
437            nbMoveAndRenameCalls.incrementAndGet();
438            totalMoveAndRename.getAndAdd( delta );
439
440            if ( nbMoveAndRenameCalls.get() % 1000 == 0 )
441            {
442                long average = totalMoveAndRename.get() / ( nbMoveAndRenameCalls.get() * 1000 );
443                OPERATION_STATS.debug(
444                    "{} : Average moveAndRename = {} microseconds, nb moveAndRenames = {}", getName(), average,
445                    nbMoveAndRenameCalls.get() );
446            }
447        }
448
449        if ( IS_DEBUG_TIME )
450        {
451            OPERATION_TIME.debug( "{} : Delta moveAndRename = {}", getName(), delta );
452        }
453    }
454
455
456    /**
457     * {@inheritDoc}
458     */
459    @Override
460    public void rename( RenameOperationContext renameContext ) throws LdapException
461    {
462        long t0 = System.nanoTime();
463        next( renameContext );
464        long delta = System.nanoTime() - t0;
465
466        if ( IS_DEBUG_STATS )
467        {
468            nbRenameCalls.incrementAndGet();
469            totalRename.getAndAdd( delta );
470
471            if ( nbRenameCalls.get() % 1000 == 0 )
472            {
473                long average = totalRename.get() / ( nbRenameCalls.get() * 1000 );
474                OPERATION_STATS.debug( "{} : Average rename = {} microseconds, nb renames = {}", getName(), average,
475                    nbRenameCalls.get() );
476            }
477        }
478
479        if ( IS_DEBUG_TIME )
480        {
481            OPERATION_TIME.debug( "{} : Delta rename = {}", getName(), delta );
482        }
483    }
484
485
486    /**
487     * {@inheritDoc}
488     */
489    @Override
490    public EntryFilteringCursor search( SearchOperationContext searchContext ) throws LdapException
491    {
492        long t0 = System.nanoTime();
493        EntryFilteringCursor cursor = next( searchContext );
494        long delta = System.nanoTime() - t0;
495
496        if ( IS_DEBUG_STATS )
497        {
498            nbSearchCalls.incrementAndGet();
499            totalSearch.getAndAdd( delta );
500
501            if ( nbSearchCalls.get() % 1000 == 0 )
502            {
503                long average = totalSearch.get() / ( nbSearchCalls.get() * 1000 );
504                OPERATION_STATS.debug( "{} : Average search = {} microseconds, nb searches = {}", getName(), average, nbSearchCalls.get() );
505            }
506        }
507
508        if ( IS_DEBUG_TIME )
509        {
510            OPERATION_TIME.debug( "{} : Delta search = {}", getName(), delta );
511        }
512
513        return cursor;
514    }
515
516
517    /**
518     * {@inheritDoc}
519     */
520    @Override
521    public void unbind( UnbindOperationContext unbindContext ) throws LdapException
522    {
523        long t0 = System.nanoTime();
524        next( unbindContext );
525        long delta = System.nanoTime() - t0;
526
527        if ( IS_DEBUG_STATS )
528        {
529            nbUnbindCalls.incrementAndGet();
530            totalUnbind.getAndAdd( delta );
531
532            if ( nbUnbindCalls.get() % 1000 == 0 )
533            {
534                long average = totalUnbind.get() / ( nbUnbindCalls.get() * 1000 );
535                OPERATION_STATS.debug( "{} : Average unbind = {} microseconds, nb unbinds = {}", getName(), average,
536                    nbUnbindCalls.get() );
537            }
538        }
539
540        if ( IS_DEBUG_TIME )
541        {
542            OPERATION_TIME.debug( "{} : Delta unbind = {}", getName(), delta );
543        }
544    }
545}