FWD » Core Development » Runtime Infrastructure

In RemoteObject, the LOG instance gets created and RemoteObject$RemoteAccess.tracing flag gets set before the logging is configured - and as by default isLoggable returns true, then the 'tracing' flag gets set to true, via this stacktrace:

CentralLoggerNoModeWrapper(CentralLogger).isLoggable(Level) line: 1057    
RemoteObject$RemoteAccess.<init>(Session, int) line: 1429    
RemoteObject.obtainNetworkInstance(Class<?>[], Session, int) line: 1045    
RemoteObject.obtainNetworkInstance(Class<?>, Session) line: 914    
DirectoryManager.initRemote(Session) line: 95    
ClientCore.initialize(InitStruct, boolean, BootstrapConfig, Supplier<String>, String) line: 306    
ClientCore.start(BootstrapConfig, boolean, Supplier<String>) line: 479    
ClientDriver.start(BootstrapConfig) line: 270    
ClientDriver(CommonDriver).process(String[]) line: 539    
ClientDriver.process(String[]) line: 347    
ClientDriver.main(String[]) line: 390    

We need a way to refresh this flag once the logging has initialized.

Code Review 7635a Revision 14669

The change is fine. The cost is 3 extra method calls (isLoggable() and inside there are two calls to Level.intValue() which is just returning a final int value). This should not matter (especially if it gets inlined in the JIT results).

In the future, please add your history entry before the code review.

You can merge to trunk.

The same fix needs to be done at Dispatcher.tracing.

Constantin, I see you often merge branches. Can you make those small updates to logs, you're most well familiar with, in your own branches? I was expecting tweaking to be required after the initial merge, but it involves the whole system and everyone can take over it.

Constantin Asofiei wrote:

The same fix needs to be done at Dispatcher.tracing.

7635b r15275 based on trunk r15274 ready for review.

Code Review Task Branch 7635b Revision 14275

In the short term, the change is OK. Long term, I would still prefer a listener design where the logging/tracing code can avoid the extra isLoggable() method calls and just read a boolean. This is such a sensitive area performance-wise. But for now it is OK.

Greg Shah wrote:

Code Review Task Branch 7635b Revision 14275

In the short term, the change is OK. Long term, I would still prefer a listener design where the logging/tracing code can avoid the extra isLoggable() method calls and just read a boolean. This is such a sensitive area performance-wise. But for now it is OK.

Do we consider comparison of two integers heavy computing?

According to my test one million calls to CentralLogger.isLoggable is one millisecond slower than one million calls to a a boolean:

   private static volatile Level level = Level.FINER;
   private static volatile boolean isLoggable = true;

   public static void main(String[] args)
   {
      long start = System.currentTimeMillis();
      for (int i = 0; i < 1_000_000; i++)
      {
         if (isLoggable(Level.SEVERE))
         {
            // ends in 0.004 - 0.009 sec, avg of 0.006 sec
         }
         if (isLoggable)
         {
            // ends in 0.004 - 0.006 sec, avg of 0.005 sec
         }
      }
      long end = System.currentTimeMillis();
      System.out.println((end - start) / 1000f + " sec");
   }

   public static boolean isLoggable(Level logLevel)
   {
      return level == null || logLevel.intValue() >= level.intValue();
   }

My personal opinion is that this should never be a focus of FWD's performance optimization. I would suggest other improvements.

Let me know if 7635b needs to be merged.

Do we consider comparison of two integers heavy computing?

It is the 3 virtual method calls that I don't like. They are unnecessary and can easily be optimized out. Consider that across the FWD project, we use isLoggable() everywhere and this could actually add up. The only reason to use isLoggable() everywhere is because we don't have a listener model which notifies when logging levels change. Considering that we can't ever change logging levels today, this is especially silly.

There is a reason that the old code did not call isLoggable() directly. When you do it in thousands of places, it adds up over the lifetime of the server. Many of these places are performance sensitive and will be called billions or trillions of times.

I don't disagree that there are other more important things to optimize. But in this case, we have de-optimized something that was already there. My point is simply to remind everyone that we will indeed reverse this at some point.

Greg Shah wrote:

Do we consider comparison of two integers heavy computing?

It is the 3 virtual method calls that I don't like. They are unnecessary and can easily be optimized out. Consider that across the FWD project, we use isLoggable() everywhere and this could actually add up. The only reason to use isLoggable() everywhere is because we don't have a listener model which notifies when logging levels change. Considering that we can't ever change logging levels today, this is especially silly.

There is a reason that the old code did not call isLoggable() directly. When you do it in thousands of places, it adds up over the lifetime of the server. Many of these places are performance sensitive and will be called billions or trillions of times.

I don't disagree that there are other more important things to optimize. But in this case, we have de-optimized something that was already there. My point is simply to remind everyone that we will indeed reverse this at some point.

I don't believe in free lunch. Filling the memory with objects is not a free lunch. The old code was: a) System.err; b) Java logger unoptimized calls. Since the performance tests clearly showed no regression, I wonder how CentralLogger became the breaking piece for FWD. If that's true, I need to focus on it immediately and fix the flaw.