10 Replies Latest reply on Jan 31, 2006 1:05 PM by Tim Fox

    log.isTraceEnabled()

    Tim Fox Master

      One other (easy) change I would really appreciate being in remoting before jboss messaging 1.0 is released, is, (in SocketClientInvoker and SocketServerInvoker especially) is to use the following idiom:

      public void foo()
      {
       private boolean trace = log.isTraceEnabled();
      
       if (trace)
       {
       log.trace("whatever");
       }
      }
      


      as opposed to:

      
      if (log.isTraceEnabled())
      {
       log.trace("whatever");
      }
      
      


      Believe it or not, this make about a 4-5% difference on our bottom line performance :)



        • 1. Re: log.isTraceEnabled()
          Tim Fox Master

          To state the obvious, the first example should, of course read:

          
          private boolean trace = log.isTraceEnabled();
          
          
          public void foo()
          {
          
           if (trace)
           {
           log.trace("whatever");
           }
          }
          
          



          • 2. Re: log.isTraceEnabled()
            Ovidiu Feodorov Master

            This will make impossible run-time logging re-configuration.

            • 3. Re: log.isTraceEnabled()
              Scott Stark Master

              Its a tradeoff between performance and being able to configure this dynamically.

              • 4. Re: log.isTraceEnabled()
                Tim Fox Master

                Well... I guess we could change the value of trace at runtime by listening for redeployments of the logging config., checking a member should be quicker than a stack jump.

                BTW, overall in JBossMessaging (not just remoting) calls to log.isTraceEnabled() contribute about 15% to the overall time for running threads in my test case (if I remember the profiler results rightly), so this is not something we should ignore IMHO.

                • 5. Re: log.isTraceEnabled()
                  Adrian Brock Master

                  Unless you are doing something ridiculous like calling
                  log.isTraceEnabled()
                  inside an inner loop,
                  I refuse to believe that this is taking 15% of the time of a network call or database operation.

                  Sounds to me that there is something like :-)

                  // Write a byte to the network
                  public void writeByte(byte byte)
                  {
                   if (log.isTraceEnabled())
                   log.trace("Writing byte " + byte);
                  }
                  


                  • 6. Re: log.isTraceEnabled()
                    Adrian Brock Master

                     

                    "timfox" wrote:
                    Well... I guess we could change the value of trace at runtime by listening for redeployments of the logging config., checking a member should be quicker than a stack jump.


                    If that was a real problem, hotspot should inline the method, to avoid the stack push/pop.
                    I'm assuming that only one implementation of the Logger interface is loaded
                    so it can discard polymorphic considerations.


                    • 7. Re: log.isTraceEnabled()
                      Adrian Brock Master

                      Also, profiling with exaggerate simple methods that are called a lot.

                      // Profiler disables optimizations
                      public boolean isTraceEnabled()
                      {
                       // profiler logs entry
                       return true;
                       // profiler logs exit
                      }
                      


                      Most of the time it taken in the profiler, not the method.

                      • 8. Re: log.isTraceEnabled()
                        Tim Fox Master

                        The differences are observed where we have a jms producer in one vm, sending to a server in other vm but on the same box.

                        The messages are non persistent so there is no db access but there are calls to socket.write/read although they don't actually go across the network.

                        Most of the time is obviously spent in socket.write and socket.read.

                        The messages are small with no payload.

                        The stack is pretty deep with all the interceptors and other stuff, most of which call log.isTraceEnabled() at least once, and some many times.

                        So each message send corresponds to many invocations of log.isTraceEnabled().

                        I also verified there was a difference without using a profiler so I don't think it's due to influence of the profiler.

                        I'm going to double check though, in case I have been hallucinating or something :)

                        • 9. Re: log.isTraceEnabled()
                          Tim Fox Master

                          I have just retested without a profiler.

                          Ok, it's not 15%, it's about 4.5%


                          with if (trace): (msgs/sec)

                          5150
                          5224
                          5289
                          5229
                          5246
                          5289
                          5182
                          5224

                          mean: 5229

                          with if (log.isTraceEnabled())

                          4812
                          5059
                          5018
                          4980
                          5100
                          5039
                          5018
                          5000

                          mean: 5003

                          % difference = 4.5%

                          So smaller than i thought (maybe the profiler was making a difference) but significant nevertheless.

                          BTW we are not calling log.isTraceEnabled() in any inner loops.

                          • 10. Re: log.isTraceEnabled()
                            Tim Fox Master

                            Moved to:

                            http://www.jboss.com/index.html?module=bb&op=viewtopic&p=3920740#3920740

                            Since this is not exclusively about remoting any more