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}