1

I have a requirement to log the run time of every single method in the application to the DB using logback and AspectJ. It's an enterprise application with roughly a few thousand classes and on average about 10 methods inside each class.

Am I walking into major performance issues here ? I know it's over the top to log every single method, but let's look past that for now.

AfterWorkGuinness
  • 1,780
  • 4
  • 28
  • 47

1 Answers1

2

Thousands of classes with about ten methods per class and you have to implement trace logging for all of them?

Short answer: Yes.

Long answer: Hell yes.
Your performance will be (more or less) heavily affected. To log run time of methods you'll need (minimally) an around advice that takes the time at method entry and exit, constructs a string and sends that to the logging framework. Depending on what your tens of thousands methods do, for a lot of them that may be even more time consuming than the actual execution of the method - the smaller the method the bigger the overhead.

I can't speak for your application, but upon doing this for one of mine the actual net-performance with activated tracing just about halved. Whether that will hold true for your application as well or qualifies as your 'major performance issues', only you can tell.

Thus my advice would be to simply try it. Weaving a trace advice around every method within a namespace can be done easily enough. Then it's just a matter of comparing performances between the traced and non-traced applications.

sheltem
  • 3,754
  • 1
  • 34
  • 39
  • 1
    But it would be equally time-consuming to do the logging manually via scattered log statements. The great thing about AspectJ is that you can (de)activate the aspect at will, via `if()` pointcut even dynamically during runtime. You can also create an abstract base aspect which does all the tracing magic and then extend several concrete sub-aspects overriding the abstract pointcut which actually defines what type of targets you want to intercept. This way you can prepare for multiple logging, tracing, profiling or debugging scenarios. I just love to do that with AspectJ. – kriegaex Dec 05 '14 at 09:28
  • 1
    BTW, for finding performance bottlenecks on demand, there are dedicated profiling tools (one is even included in the JDK) which can dynamically connect to a running application and produce much less overhead than log statements because the data are collected on a lower JVM level and displaying them is not part of the application but of the profiler. For consistent production logging, AspectJ is your tool though, i.e. if you *always* want to audit execution times. The performance penalty is just a matter of granularity. Challenge the requirement of logging every single call, it makes no sense. – kriegaex Dec 05 '14 at 09:32
  • My answer may provide some potential for misunderstanding, since it tries to keep to the question of whether performance will be affected. What I didn't say is that despite the performance impact, this is still *the best* method of achieving the OPs goal. I still use and develop my tracing aspect and I love the possibilities - though I chose a different (less efficient) way of (de)activating it at runtime: Since all logging happens via logback, the aspect uses its own marker and can be activated and deactivated during runtime via a TurboFilter applied to the logging. – sheltem Dec 05 '14 at 10:11
  • My comments were targetted at the OP rather than at you. It was meant to complement your good answer, not to contradict it. :-) – kriegaex Dec 05 '14 at 10:37
  • Hooray, vindication by SO's own Mr. AspectJ! :D – sheltem Dec 05 '14 at 12:38