FWD » Core Development » Runtime Infrastructure

~1% of resources for 3.6 million executions sounds great to me!

Jokes aside...

We can lower it to 1.8 million executions removing the unnecessary if (LOG.isLoggable(Level.FINE)) that hides concatenation, that can be reworked as passing in the formatting arguments directly to the formatting logger method.

Galya B wrote:

We can lower it to 1.8 million executions removing the unnecessary if (LOG.isLoggable(Level.FINE)) that hides concatenation, that can be reworked as passing in the formatting arguments directly to the formatting logger method.

We need to remove the map lookup. The log level needs to be cached at the logger instance.

Constantin Asofiei wrote:

We need to remove the map lookup. The log level needs to be cached at the logger instance.

Prejudice! There is no map lookup, it's cached.

Actually the cache map should have been the first lookup in the method. This is my bad.

And we know the complexity of accessing string keyed map. Do you think the concurrency of the map adds to the CPU usage?

There is no free lunch, it's either the CPU or the RAM. If I need to work on this task, I'll remove isLoggable from the logger interface and make sure all concatenations and formattings outside of the logger are moved to the logger after the check is performed. Then I'm sure we will have achieved 0.5%.

Also let's not forget that resource consumption is part of execution of applications and this feature was not existing before, so it's expected the usage to raise somewhat.

That being said, I've been against the excessive use of isLoggable since the beginning.

Constantin, what is the logging level you tested with on this screenshot?

This is the entire logging node. The loggers levels is the same from before testing with CentralLogger.

        <node class="container" name="logging">
          <node class="container" name="file">
            <node class="string" name="path">
              <node-attribute name="value" value="server_%g.log"/>
            </node>
            <node class="integer" name="rotationLimit">
              <node-attribute name="value" value="0"/>
            </node>
            <node class="integer" name="rotationCount">
              <node-attribute name="value" value="1"/>
            </node>
          </node>
          <node class="container" name="loggers">
            <node class="string" name="com.goldencode.p2j.util">
              <node-attribute name="value" value="INFO"/>
            </node>
            <node class="string" name="com.goldencode.p2j">
              <node-attribute name="value" value="WARNING"/>
            </node>
            <node class="string" name="com.goldencode.p2j.net">
              <node-attribute name="value" value="INFO"/>
            </node>
            <node class="string" name="com.goldencode.p2j.persist">
              <node-attribute name="value" value="INFO"/>
            </node>
          </node>
        </node>

Bypassing everything but the logging level check has served us well. There is a performance reason those checks were there. Yes, they are ugly. But they are fast. And the cached local flags are even faster. This is why I mentioned that an approach where we use local flags and a listener model to notify in the (very rare case) where the logging levels change is something we need to consider.

Galya, the problem is not isLoggable being called excessively. canLog relies too on isLoggable, so getting rid of isLoggable will not solve anything, this will just mean that log will call canLog which will call isLoggable.

The solution is to cache the logging level at the logger instance, and not only for the logger's name. It doesn't matter if the same logger name is being used by multiple logger instances, the logger instance must have its level precomputed.

Regarding map usage: maps are slow 'by design', and concurrent maps just adds more overhead. And where we can do without maps, we must do so.

Keep in mind that 3.6 million calls for isLoggable is not from stress testing this application, you can consider this 'normal usage'.

Greg Shah wrote:

Bypassing everything but the logging level check has served us well. There is a performance reason those checks were there. Yes, they are ugly. But they are fast. And the cached local flags are even faster. This is why I mentioned that an approach where we use local flags and a listener model to notify in the (very rare case) where the logging levels change is something we need to consider.

I understand, but I don't understand. I need to understand to comply.

1. Have you done performance testing on Java isLoggable implementation? Think about it carefully.
2. What is the performance reason? Memory consumption as far as I know. That is concatenation and formatting. I solved that in a better way that removes one invocation of the same method, when the level is enabled.
3. Local flags and listeners are objects, they take up memory and create non-standard (in that context) complex design. And we don't like objects (I mean lambdas).

I know what you want, but I fear implementing it myself, the same way I feared implementing hundreds of isLoggable calls.

"Performance" should be measurable. I don't see any base measurement here, because noone measured Java isLoggable.

Constantin Asofiei wrote:

It doesn't matter if the same logger name is being used by multiple logger instances, the logger instance must have its level precomputed.

It has it pre-computed in CACHED_LOGGER_NAME_LEVELS. It's in a static field of type map in the same class. I did a mistake for some reason though. I had to make the check to the cached map as a first statement in getLevel.

Regarding map usage: maps are slow 'by design', and concurrent maps just adds more overhead.

I can agree about the concurrent part, because I haven't measure it. I don't agree about the map part. Red-black trees in Java 8 are quick, but let's not get into sorting, because getting a String key is with complexity of 0(1).

Keep in mind that 3.6 million calls for isLoggable is not from stress testing this application, you can consider this 'normal usage'.

The number is striking, but not more than the number of calls to these base methods, so the percentage will be a constant even with stress testing.

Even if I bend due to pure pressure and implement it, I don't recommend using isLoggable just for the sake of looking safe especially with high logging levels like WARNING and SEVERE.

isLoggable is meant to be used when there is a cost with resolving the arguments passed to the log method. That's why I insisted on it - even passing a lambda expression is costly.

Will something like this work with current implementation? (ignore the listener approach required if the parent changes the logging level).

--- old/src/com/goldencode/p2j/util/logging/CentralLogger.java
+++ new/src/com/goldencode/p2j/util/logging/CentralLogger.java
@@ -226,6 +226,9 @@
    /** Flag to prevent deadlock on SecurityManager. */
    private boolean excludeSMContext;

+   /** Cached logging level. */
+   private Level level;
+
    /** The bootstrap config reader. */
    private static BootstrapConfig bc;

@@ -244,6 +247,8 @@
       this.loggerName = loggerName;
       this.checkParentLevels = checkParentLevels;
       this.excludeSMContext = excludeSMContext;
+      
+      this.level = getLevel();
    }

    /**
@@ -1035,8 +1040,7 @@
     */
    public boolean isLoggable(Level logLevel)
    {
-      Level loggerLevel = getLevel();
-      return loggerLevel == null || logLevel.intValue() >= loggerLevel.intValue();
+      return level == null || logLevel.intValue() >= level.intValue();
    }

    /**

Constantin, I started with a similar implementation, where the state also included the level, but there are other caveats as well. The level comes late for any process - only after the configs are resolved, so we support dynamic levels for that purpose. Also there are (only one for the moment I think) classes that set their own levels.

Give me 1h to rework TransactionManager to my liking and see if it fixes something.

Do we have a branch here?

Galya B wrote:

Give me 1h to rework TransactionManager to my liking and see if it fixes something.

Reworking code is not the way to go. The fix must be in CentralLogger.

The level comes late for any process - only after the configs are resolved, so we support dynamic levels for that purpose. Also there are (only one for the moment I think) classes that set their own levels.

OK, then we need this implemented, too.

To me removing 50% of the calls sounds quite right. Or am I misreading your screenshot?

Also as I've said, I have a mistake to fix.

Galya B wrote:

To me removing 50% of the calls sounds quite right. Or am I misreading your screenshot?

I didn't say it right. Improving 50% of the calls.

I made an expensive mistake, that removed will improve things 3 times... Now getLevel checks in 3 concurrent maps, while it should check only one. That will make the duration about 7614 (22842 / 3).

Also Java logger has a tree :( I wanted to implement a tree as well, but didn't have the capacity of a Java team.

What I'm trying to say is that listeners and more state are a bad idea. It should be implemented with WeakReference although most instances are saved in static fields, but this shouldn't be presumed. And do push of the change instead of listening. Then also consider the implications on all logger methods, especially in the context of logger wrapper classes like CentralLoggerNoModeWrapper.

I'm not sure if that got understood, but all loggers should listen to the change, this means a few hundred objects wrapped in WeakReference objects. Not that getting someone scared by empty numbers is my goal here. Just mentioning.

Galya, beside the FWD server startup, what are the condition under which a logger's level can be changed? Here I mean in existing FWD trunk, not the new feature which will allow to change the logging level at runtime, for any logger.

1. Have you done performance testing on Java isLoggable implementation? Think about it carefully.

All of our previous code and now these new changes are being profiled extensively.

2. What is the performance reason? Memory consumption as far as I know.

No, this is not about memory. It is 100% about reducing CPU cycles to do the same 4GL compatible work.

Some day, we will worry about memory but not until we've solved known CPU cycle issues. Eliminating map lookups and string concatenation has been proven to make a measurable difference in real application code. That is why we are focused on these specific things.

3. Local flags and listeners are objects, they take up memory and create non-standard (in that context) complex design. And we don't like objects (I mean lambdas).

The costly part of lambdas is when there is variable capture, especially where that capture is of instance data. Regardless of the concerns we have with lambdas, the listener approach for this use case is quite excellent since nearly every server run will have 0 calls to dynamically set levels after server startup. Even if we set the levels once or twice during a server run, who cares? It won't be millions of times. On the other hand, long running servers will have billions of calls to map lookups or string concat that are not needed if only we precalculate and cache the logging levels.

Galya, beside the FWD server startup, what are the condition under which a logger's level can be changed? Here I mean in existing FWD trunk, not the new feature which will allow to change the logging level at runtime, for any logger.

Even after we implement it, the dynamic levels will almost never be used. We do not need to worry about that case.

When invalidating the levels in all instances that will be a performance bottleneck, because all loggers will need to access the concurrent map to get their new levels. If I've implemented a tree for the loggers it would be way better. But I kind of don't want to get into creating a red-black tree in Java myself...

Galya B wrote:

When invalidating the levels in all instances that will be a performance bottleneck, because all loggers will need to access the concurrent map to get their new levels. If I've implemented a tree for the loggers it would be way better. But I kind of don't want to get into creating a red-black tree in Java myself...

This is a non-issue because it will almost never be called. In other words, we are OK if this notification/reset levels is slow.

What can't be slow or even as slow as a single map lookup is the isLoggable().

Galya B wrote:

7443a r14628 based on trunk r14627 tested and ready for review.

The changes look reasonable, but they need to be tested.

Alexandru: please apply (locally) the 7443a changes to 7156b and run a new round of testing.

Constantin Asofiei wrote:

Alexandru: please apply (locally) the 7443a changes to 7156b and run a new round of testing.

Sure. Enqueuing now.

7443a/rev. 14628 doesn't compile:

[ant:javac] /home/al2/gcd/branches/7443a/src/com/goldencode/p2j/ui/chui/ThinClient.java:16177: error: exception ConfigurationException is never thrown in body of corresponding try statement
[ant:javac]       catch (ConfigurationException e)

I temporarily removed the catch block to be able to profile.

I pushed r14629 to fix the compilation error. I haven't rebuilt with all.

r14630 reverts LogHelper#createThreadName, requested in #7143-234.

Code Review Task Branch 7443a Revision 14630

The change is good. I like that the code is in Utils instead of CentralLogger. Perhaps it would be better for it to be in the security package but Utils is OK for now.

I've done one set of profiling tests and got a slight improvement comparing to the state before #7443 (which was +3.1%), but still not close to the original trunk code before CentralLogger (still +1.9%).

However, I did a second set of profiling tests: in the first round of tests, I got a ~26MB log file. I commented an WARNING (that is already fixed on another branch) that popped a lot of times and got to ~5MB of log file. With this second profiling round that generated ~5MB of logs, I got a result that is a bit slower than my trunk base-line before CentralLogger (only +0.45%). If I disable logging, I reach the times I had before CentralLogger, but of course this is not the solution here.

Even if this mostly seems like an IO slow-down, I haven't done any tracing similar to #7443-2 to confirm the cause. Could this be related to more complex formatting than before? We certainly have more detailed logging now (including thread, session, user) and this may cost us time.

Alexandru Lungu wrote:

I commented an WARNING (that is already fixed on another branch)

Is this already in trunk?

Even if this mostly seems like an IO slow-down,

I'll do another set of profiling and see what happens.

Constantin Asofiei wrote:

Alexandru Lungu wrote:

I commented an WARNING (that is already fixed on another branch)

Is this already in trunk?

It is about BaseDataTypeFactory instantiating ObjectVar and it is not in trunk - only in 7026e. Without it, you may see lots of Type class com.goldencode.p2j.util.ObjectVar instantiated via reflection, as it is not registered in BaseDataTypeFactory.

=== modified file 'src/com/goldencode/p2j/util/BaseDataTypeFactory.java'
--- old/src/com/goldencode/p2j/util/BaseDataTypeFactory.java    2023-05-26 14:37:01 +0000
+++ new/src/com/goldencode/p2j/util/BaseDataTypeFactory.java    2023-06-01 13:09:20 +0000
@@ -8,6 +8,7 @@
 ** 001 RAA 20230525 Created initial version. 
 **     AL2 20230525 Ordered types alphabetically.
 **     AL2 20230525 Moved to CentralLogger.
+** 002 RAA 20230601 Added check for ObjectVar. 
 */

 /*
@@ -163,6 +164,10 @@
       {
          return (T) new object<>();
       }
+      else if (cls == ObjectVar.class)
+      {
+         return (T) new ObjectVar<>();
+      }
       else if (cls == raw.class)
       {
          return (T) new raw();

Even if this mostly seems like an IO slow-down,

I'll do another set of profiling and see what happens.

Thank you!

Alexandru Lungu wrote:

Constantin Asofiei wrote:

Alexandru Lungu wrote:

I commented an WARNING (that is already fixed on another branch)

Is this already in trunk?

It is about BaseDataTypeFactory instantiating ObjectVar and it is not in trunk - only in 7026e. Without it, you may see lots of Type class com.goldencode.p2j.util.ObjectVar instantiated via reflection, as it is not registered in BaseDataTypeFactory.

Alexandru, please commit this change to 7443a. I expect 7443a to be merged to trunk before 7026e.

Alexandru, please commit this change to 7443a. I expect 7443a to be merged to trunk before 7026e.

Done! Committed #7443-47 to 7443a as rev. 14631.

Alexandru, can you please try to run with the following configs:

        <node class="container" name="logging">
          <node class="boolean" name="serverSide">
            <node-attribute name="value" value="TRUE"/>
          </node>
        </node>

I'm curious to see the difference in performance.

Alexandru Lungu wrote:

I got a result that is a bit slower than my trunk base-line before CentralLogger (only +0.45%).

Is someone surprised that using logger is more expensive than System.err.print with +0.45%?

Can I run the profiling procedure myself?

Let's set the requirements first before jumping into fixing. If I make CentralLogger#describeContext (24,755%) and CentralLogFormatter#format (12,948%) take no time in execution, this will be an improvement of 37,703% of the +0.45% or the performance degradation of using logger instead of System.err will come down to +0,28035% (improvement with +0.1696635%). If we're happy with that number, then I'm on it to make those two methods take 0ms.

Did I get the task right?

P.S. Numbers edited.

• the LogTest modified program with CentralLogger and 7443a
• the LogTest modified program with FWD before CentraLogger (using what was before CentraLogger)

This will give us an idea of the time differences.

Constantin Asofiei wrote:

using what was before CentraLogger

You mean System.err? server.log was "generated" by System.err

I don't understand what you mean by System.err. Previously, FWD was using java.util.logging for logging support on server-side.

What we need to compare is com.goldencode.p2j.util.LogHelper.getLogger and CentraLogger. And we need to improve any parts from CentralLogger that can be improved, to get to as close as possible to java logging.

A little bit of history:

Once upon a time FWD used direct System.err.print and throwable.printStackTrace() statements excessively. It also used java.util.logging.Logger here and there with a ConsoleHandler that by default does System.err.print. server.log was "generated" by redirecting stderr to a file. Files were never generated by java.util.logging.Logger, nor all logs were logged by java.util.logging.Logger.

System.err compensated for java.util.logging.Logger bad performance giving a good result on average.

In that utopic environment CentralLogger appeared and ruined the performance of System.err by introducing file writes, but in reality it wanted to save FWD from java.util.logging.Logger poor performance.

From your results, are you saying that Java logger is 33seconds and CentraLogger is 14seconds?

Constantin Asofiei wrote:

From your results, are you saying that Java logger is 33seconds and CentraLogger is 14seconds?

Please read the story carefully and then we'll discuss my supposedly heretic statement again.

What I'm implying is: Console writes seem quite expensive, so the java logger performed poorly before, but the day was saved by the fact it wasn't used everywhere. CentralLogger is less performant than java logger in writing files, which unfortunately wasn't the way java logger was used. But I'll add more info in a few min, since I haven't tested java logger with our formatter.

• CentraLogger with console: 21037ms
• CentraLogger with file: 17032ms
• Java logging with stderr: 10649ms

Please spend your effort to find how to improve CentralLogger further. For example, can String.format be replaced with something else, which parses the format string only once? I understand that CentraLogger adds new features to logging which didn't exist before, and these add an overhead, but we must try to improve it.

Biased is a synonym for isolated? I have no idea what settings you use in your tests, while I shared my samples. Aren't then your tests biased?

I asked a while ago what percentage of improvement is expected from reworking the formatting. I haven't heard on it ever since.

Constantin Asofiei wrote:

For example, can String.format be replaced with something else, which parses the format string only once?

Biased is the word I have for this statement. Let me prove you why.

java.util.logging.ConsoleHandler:

public class ConsoleHandler extends StreamHandler {
    // Private method to configure a ConsoleHandler from LogManager
    // properties and/or default values as specified in the class
    // javadoc.
    private void configure() {
        LogManager manager = LogManager.getLogManager();

        [..]

        setFormatter(manager.getFormatterProperty(cname +".formatter", new SimpleFormatter()));

        [..]
    }

java.util.logging.SimpleFormatter:

public class SimpleFormatter extends Formatter {

    [..]

    public synchronized String format(LogRecord record) {
        [..]

        String message = formatMessage(record);
        [..]

        return String.format(format,
                             dat,
                             source,
                             record.getLoggerName(),
                             record.getLevel().getLocalizedLevelName(),
                             message,
                             throwable);
    }
}

• CentralLogger (used in new trunk) is 300% slower than System.err redirected to file (used in old trunk).
• java.util.logging.Logger with ConsoleHandler redirected to a file (used in old trunk) is 480% slower than System.err redirected to file (used in old trunk).

Sorry for the edits.

If we blindly introduce "improvements" in iterations without any clearly expressed expectations, this may not work asap as requested.

Constantin Asofiei wrote:

Galya, I think your tests are biased because they do not use the FWD runtime. My point was to test from within the FWD server. I've used the program I posted and:

• CentraLogger with console: 21037ms
• CentraLogger with file: 17032ms
• Java logging with stderr: 10649ms

If you haven't yet understood, I'll do another summary:
stderr (+/- Java logging with stderr) < file (CentraLogger with file), aka 10649 < 17032
stderr (+/- Java logging with stderr) < stderr + file (CentraLogger with console), aka 10649 < (17032 + 10649) 21037

I'll test it in a unbiased way now, in FWD. Wait for results.

Galya B wrote:

If we blindly introduce "improvements" in iterations without any clearly expressed expectations, this may not work asap as requested.

• reduce the total number of allocated objects by CentralLogger during logging a message (string format comes into play here)
• reduce the overall total time - you can use a profiler in trace mode (VisualVM works).

Convert this logtest.p program:

def var i as int.

do i = 1 to 10000000:
   message i.
end.

package com.goldencode.testcases;

import static com.goldencode.p2j.util.BlockManager.externalProcedure;

import java.util.logging.Level;
import java.util.logging.Logger;

import com.goldencode.p2j.util.Block;
import com.goldencode.p2j.util.Body;
import com.goldencode.p2j.util.InternalEntry.Type;
import com.goldencode.p2j.util.LegacySignature;
import com.goldencode.p2j.util.logging.CentralLogger;

public class Logtest
{
   /** Logger */
   private static final CentralLogger LOG1 = CentralLogger.get(Logtest.class);

   private static final Logger LOG2 = Logger.getLogger(Logtest.class.getName());

   @LegacySignature(type = Type.MAIN, name = "logtest.p")
   public void execute()
   {
      externalProcedure(Logtest.this, new Block((Body) () -> 
      {
         long n1 = System.nanoTime();
         for (int i = 0; i < 1_000_000; i++)
         {
            LOG1.log(Level.WARNING, "something");
            // LOG2.log(Level.WARNING, "something");
         }
         long n2 = System.nanoTime();
         System.out.println((n2 - n1) / 1_000_000l);
      }));
   }
}

Run it from the FWD server via the FWD client using logtest.p program. Uncomment and run the LOG2 line separately. We are interested in profiling only the LOG1 (CentraLogger), LOG2 (java logging) is only to get a 'reference time' to which we need to get close.

r14632 16% improvement of the +0.45% degradation by replacing String.format in formatting logging context.

I also tried to replace SimpleDateFormat with DateTimeFormatter (popular as a better implementation), but it led to worse numbers.
I also tried to move around FileHandler.flush() which unexpectedly didn't lead to any change in numbers.

What else?

Please do a profiling and see what else stands out which can be improved.

r14633:

The appserver kept the spawner live, which kept the stderr parsing / logging loop on the server live. It probably contributed to the numbers, but I'm not sure how much exactly. To stop it the spawner now sends a message before launching the client process, that will trigger a timer and stop the logging after 2min. The client is supposed to log itself, so the stderr forwarding should not be relevant after the client is started. It seems winspawn.c has some retry logic and I'm not sure if it works well there, but it is tested and works for Linux.

If it's not a trouble, can we have a perf test running now, while I wonder what else to change.

P.S. with updated spawner

• CentraLogger - please leave only 006 number and remove 007 and 008 (leave the user initials, date and message there, for both '007' and '008' lines; remove just the numbers, we need to have only one history number per branch). The same for CentralLoggerServer.
• CentraLogger.logStream
  • I don't really like that we have this if (line.equals("started")) condition from the spawner. It seems fragile. At least add comments to both the native spawner code and here that they are linked (i.e. changing in one place it must be changed in the other place, too).
  • the 'self distruct' timeout I think should be the same as ClientSpawner.TIME_OUT.
  • what is the purpose of TimeUnit.MILLISECONDS.sleep(0);? 0 just does nothing.
• CentraLogger.invalidateLoggerTreeLevelCache - shouldn't logger.loggerName.contains(loggerName) be logger.loggerName.startsWith(loggerName)? AFAIK the logger hierarchy is log1 is parent for log1.log2.log3, but not for log2.log1.
• LoggingUtil.addLeadingSymbols - instead of doing:
  

  new String(new char[leadingSymbolsCount]).replace('\0', symbol);
  

  
  try Arrays.fill(char[], symbol), to avoid String.replace overhead.

Eugenie: please review the native changes.

Alexandru: please do another round of performance testing with 7156b + 7443a. Please note that I've rebased 7156b.

Constantin Asofiei wrote:

Alexandru: please do another round of performance testing with 7156b + 7443a. Please note that I've rebased 7156b.

With this in mind, please use this patch (the app is not yet reconverted with rebased 7156b):

=== modified file 'src/com/goldencode/p2j/util/BlockManager.java'
--- old/src/com/goldencode/p2j/util/BlockManager.java   2023-06-15 09:30:19 +0000
+++ new/src/com/goldencode/p2j/util/BlockManager.java   2023-06-23 14:25:16 +0000
@@ -7097,7 +7097,19 @@

       throw lex;
    }
-   
+      /**
+    * Trigger a rollback of the current block and then throw a legacy condition.
+    * 
+    * @param    label
+    *           The name of the block that is the target of the undo and throw operations.
+    * @param    error
+    *           The legacy error to throw.
+    */
+   public static void undoThrow(String label, object<? extends LegacyError> error)
+   {
+      undoThrow(error);
+   }
+
    /**
     * Trigger a rollback of the current block and then throw a legacy condition.
     * 

Constantin Asofiei wrote:

Eugenie: please review the native changes.

I have no objection for code itself. However the comment log in file history confuses me a bit:

** 018 GBB 20230623 Adding "started" print to stderr to notify the server logger to stop listening for logs.

I see the log call used when process started, not stopped. So it is not clear for me why words ...to stop listening... are used here.

Eugenie Lyzenko wrote:

I see the log call used when process started, not stopped. So it is not clear for me why words ...to stop listening... are used here.

The loop in the listening Thread created by CentralLogger#logStream stops work when isProcessRunning is false, which happens on receiving the keyword started from the spawner.
Have I missed to cleanup something else?

Eugenie Lyzenko wrote:

I see the log call used when process started, not stopped. So it is not clear for me why words ...to stop listening... are used here.

Ah, I got it. The problem is that the message can be send only before the client process is started and it's indicating the process is started, while the logger Thread decides to stop listen on this event, because client processes like appserver are keeping the logging loop alive for unnecessarily long time otherwise.

P.S. It's not like command from the spawner to the listener, but an event.

Constantin Asofiei wrote:

we need to have only one history number per branch

You say that often, but when I add headers for each change (for code reviews), I forget the previous one was on the same branch. Thanks for pointing out the needed changes.

• I don't really like that we have this if (line.equals("started")) condition from the spawner.

I don't too. The alternative solution is to separate spawner logs in their own files, but from usability perspective it might be better to keep this imperfect solution.

At least add comments to both the native spawner code and here that they are linked (i.e. changing in one place it must be changed in the other place, too).

OK, added.

• the 'self distruct' timeout I think should be the same as ClientSpawner.TIME_OUT.

I lowered it to ClientSpawner.TIME_OUT which is 30 sec. The reason for the 2min was that I'm not sure if less will be enough for the retry in winspawn.c. I don't understand the retry there, because appserver launcher has its own retry mechanism in Java.

• what is the purpose of TimeUnit.MILLISECONDS.sleep(0);? 0 just does nothing.

Leftover, removing it.

• CentraLogger.invalidateLoggerTreeLevelCache - shouldn't logger.loggerName.contains(loggerName) be logger.loggerName.startsWith(loggerName)?

Right.

try Arrays.fill(char[], symbol), to avoid String.replace overhead.

Done.

r14635 up.

Galya, one more small optimization, please: this test in LoggingUtil.addLeadingSymbols can be leadingSymbolsCount <= 0:

      if (leadingSymbolsCount < 0)
      {
         return originalValue;
      }

Constantin Asofiei wrote:

Galya, one more small optimization, please: this test in LoggingUtil.addLeadingSymbols can be leadingSymbolsCount <= 0:

Up in r14636.

Attempting to profile with rev. 14636. I've got:

[ant:javac] /media/al2/gcd/branches/7443a/src/com/goldencode/p2j/util/logging/CentralLogger.java:393: error: exception InterruptedException is never thrown in body of corresponding try statement
[ant:javac]             catch (InterruptedException ignored)

Compilation error fixed with r14637.

Greg: I think we can merge this to trunk. Alexandru reported a 3.5% improvement for 7443a (from a 3.5% loss without it).

Please merge 7443a to trunk. Good work!

Task branch 7443a was merged to trunk as rev 14633 and archived.

Constantin Asofiei wrote:

Greg: I think we can merge this to trunk. Alexandru reported a 3.5% improvement for 7443a (from a 3.5% loss without it).

This is just to document some findings in the last two days: in trunk rev 14629, there was a bug introduced which leaked a RETURN statement to the caller block - thus the caller block was returning early, and skipping application code which should have been executed; it's weird that this did not appear in normal regression tests like ETF. This bug was related to #7300 (7300a branch).

In trunk rev 14649, for #7450, this bug was partially fixed; with this fix, there was a performance loss in an application, because this 'skipped application code' was being executed (correctly) again. It took me a while to find this explanation, and the conclusion was the changes in trunk rev 14629 as the problem. The full fix will be merged via 7300b.

• the previous '3.5% additional improvement from the 3.5% loss' was incorrect and was due to the 7300a bug
• there are no more spikes for CentraLogger or LOG-MANAGER usage; so we are 'on par' (or better) with the previous Java logging

Galya B wrote:

r14634: Fixed Java (java.util.logging.LogRecord#needToInferCaller set with reflection to stop heavy checks unused by CentralLogger).

Performance of CentralLogger is 3+ times quicker now.

After all changes the function that initially took ~14510ms now takes ~4200ms.

May I ask why such decision was taken instead of creating custom LogRecord that does not do inferCaller as JDK LogRecord does ?
Setting private field of LogRecord violated access constraints and causes issues starting from JDK 17+.
Was is to minimize code refactoring ?
EDIT: I found CentralLogRecord.

Tomasz Domin wrote:

Galya B wrote:

r14634: Fixed Java (java.util.logging.LogRecord#needToInferCaller set with reflection to stop heavy checks unused by CentralLogger).

Performance of CentralLogger is 3+ times quicker now.

After all changes the function that initially took ~14510ms now takes ~4200ms.

May I ask why such decision was taken instead of creating custom LogRecord that does not do inferCaller as JDK LogRecord does ?
Setting private field of LogRecord violated access constraints and causes issues starting from JDK 17+.

Replacing "simply" LogRecord means implementing a new FileHandler. This is work that is to be scheduled with upgrading to a new version of Java. It's been discussed. I can show references, if any concerns.

Galya B wrote:

Tomasz Domin wrote:

Galya B wrote:

r14634: Fixed Java (java.util.logging.LogRecord#needToInferCaller set with reflection to stop heavy checks unused by CentralLogger).

Performance of CentralLogger is 3+ times quicker now.

After all changes the function that initially took ~14510ms now takes ~4200ms.

May I ask why such decision was taken instead of creating custom LogRecord that does not do inferCaller as JDK LogRecord does ?
Setting private field of LogRecord violated access constraints and causes issues starting from JDK 17+.

Replacing "simply" LogRecord means implementing a new FileHandler. This is work that is to be scheduled with upgrading to a new version of Java. It's been discussed. I can show references, if any concerns.

Please do, I am in a process of upgrading FWD to support new Java versions, probably that needs to be done as this is the only stopper in entire FWD now.

#7143-253, #7143-255.

Instead of replacing java.util.logging.LogRecord there could be another option, extend it and Override getSourceClassName and getSourceMethodName to return the values without calling inferCaller. Then replace new LogRecord with the new object in CentralLogger and CentralLogRecord. Potentially even in the SQL loggers.

And finally the block in CentralLogFormatter can be removed:

try
      {
         Field f1 = record.getClass().getDeclaredField("needToInferCaller");
         f1.setAccessible(true);
         f1.set(record, false);
      }
      catch (NoSuchFieldException | IllegalAccessException ignored)
      {
      }

Then performance tests need to be run again.

The new class should in be in the package com.goldencode.p2j.util.logging. As for the name (since CentralLogRecord is already used), it can be PerformantLogRecord or ExtendedLogRecord.

Galya B wrote:

The new class should in be in the package com.goldencode.p2j.util.logging. As for the name (since CentralLogRecord is already used), it can be PerformantLogRecord or ExtendedLogRecord.

Thank you Galya very much.

I was considering that option but it seems java.util.logging.LogRecord was not really meant for extending it as it has all fields private so overriding class cant access nor modify them directly.

Have you considered calling setSourceClassName and setSourceMethodName unconditionally (even when they are set to null) in ultimateLog ? That would clear needToInferCaller flag.

Another possible solution might be to make use of serialization and generate log message on LogRecord serialization, but there would be some overhead related to that.

I guess I will try both.

Tomasz Domin wrote:

Galya B wrote:
I was considering that option but it seems java.util.logging.LogRecord was not really meant for extending it as it has all fields private so overriding class cant access nor modify them directly.

The field needToInferCaller is private indeed, but it doesn't have to be overridden itself, if the methods that use it are overridden. Please try the method described in #7443-98.

Galya B wrote:

Tomasz Domin wrote:

Galya B wrote:
I was considering that option but it seems java.util.logging.LogRecord was not really meant for extending it as it has all fields private so overriding class cant access nor modify them directly.

The field needToInferCaller is private indeed, but it doesn't have to be overridden itself, if the methods that use it are overridden. Please try the method described in #7443-98.

The issue is not only needToInferCaller being private but also all other java.util.logging.LogRecord fields being private, so there is no way to read them except calling superclass getters. So simple overriding of getSourceClassName wont let access overriding class to access private String sourceMethodName, it still needs to get it via super.getSourceClassName(), which still will check needToInferCaller.
I could override private fields with superclass fields, but that would lead to loosing all benefits of using a standard java.util.logging.LogRecord, most probably also issues with serialization for distributed use cases.

Tomasz Domin wrote:

Galya B wrote:

Tomasz Domin wrote:

Galya B wrote:
I was considering that option but it seems java.util.logging.LogRecord was not really meant for extending it as it has all fields private so overriding class cant access nor modify them directly.

The field needToInferCaller is private indeed, but it doesn't have to be overridden itself, if the methods that use it are overridden. Please try the method described in #7443-98.

The issue is not only needToInferCaller being private but also all other java.util.logging.LogRecord fields being private, so there is no way to read them except calling superclass getters. So simple overriding of getSourceClassName wont let access overriding class to access private String sourceMethodName, it still needs to get it via super.getSourceClassName(), which still will check needToInferCaller.
I could override private fields with superclass fields, but that would lead to loosing all benefits of using a standard java.util.logging.LogRecord, most probably also issues with serialization for distributed use cases.

We'll be overriding only those two methods, the rest can continue working as it was before. But you're right that we'll also need setters for sourceMethodName and sourceClassName and declaration of the two fields in the new class.

Tomasz Domin wrote:

As calling to LogRecord.setSourceClassName or LogRecord.setSourceMethodName implicitly clears inferLogger flag I allowed it to be set even when it would be set to NULL

Nice find. The diff looks good. Now the reflection can be removed from CentralLogFormatter.