Print

[RyShask]

Hello all,

I'm trying to set up a development environment for 5.2.4, I am using the application template with only with these differences in config/jppf.properties
Building takes only a second, but execution takes 35 seconds. Most of the execution completes in the first 10 or so seconds, but tearing down seems to take the remainder of the time.. The last message in the log file ( with debug enabled ) is '' after which 25 seconds transpire.

This half minute of execution can really add up when writing code. I initially attempted running against a local driver/node. But the result is the same.

16.3.0 Darwin Kernel Version 16.3.0: Thu Nov 17 20:23:58 PST 2016; root:xnu-3789.31.2~1/RELEASE_X86_64 x86_64
Java(TM) SE Runtime Environment (build 1.8.0_121-b13)
Java HotSpot(TM) 64-Bit Server VM (build 25.121-b13, mixed mode)

 
-jppf.drivers = driver1
+#jppf.drivers = driver1
 # jppf.drivers = driver1 driver2
 
 #------------------------------------------------------------------------------#
@@ -118,7 +118,7 @@ org.jppf.resolve.addresses = true
 #------------------------------------------------------------------------------#
 
 # Enable local execution of jobs? Default value is false (disabled)
-#jppf.local.execution.enabled = true
+jppf.local.execution.enabled = true
 
 # Number of threads to use for loacal execution. Defaults to the number of CPUs available to the JVM
 #jppf.local.execution.threads = 4
@@ -129,14 +129,14 @@ org.jppf.resolve.addresses = true
 
 # Enable rmeote execution of jobs? Default value is true (enabled)
 # when disabled, jobs will not be submitted to any remote server
-#jppf.remote.execution.enabled = true
+jppf.remote.execution.enabled = false
 
 #------------------------------------------------------------------------------#
 # Configuration of automatic discovery of JPPF drivers.                        #
 #------------------------------------------------------------------------------#
 
 # Enable or disable discovery of JPPF drivers. Defaults to true (enabled)
-#jppf.discovery.enabled = true
+jppf.discovery.enabled = false
 

 


Apologizes if asked before, I didn't see this specific question asked on these forums.

[lolo]

Hello,

I tried running the application template with your settings, but unfortunately I couldn't reproduce the behavior you described. In my setup, the entire execution takes less than 200 milliseconds.
You mentioned that you set the logging level to debug, is there any way you could zip the resulting log file and provide it as an attachment? I've attached mine to this post, so we can compare.
Could you also please confirm that you made no other changes than those in the configuration file?

Thanks for your time,
-Laurent

[RyShask]

Hello Laurent,

Thank you for taking a look, though this is probably weirdness with macos 10.12 and java 8...
The diff of the config file was from a 'git diff' against a freshly unpacked copy of the application-template. No other changes where made.

[RyShask]

Additionally, when I run a dtruss I see a TON of these messages. Which is the majority of the output I see during execution.

sudo dtruss -ef ./run.sh
...snip...
 2803/0x15533:    50135 psynch_cvwait(0x7FBE52D34568, 0x100000100, 0x0)       = -1 Err#316
 2803/0x15533:        2 gettimeofday(0x7000037B6C88, 0x0, 0x0)       = 0 0
 2803/0x15533:    51929 psynch_cvwait(0x7FBE52D34568, 0x100000100, 0x0)       = -1 Err#316
 2803/0x15533:        5 gettimeofday(0x7000037B6C88, 0x0, 0x0)       = 0 0
 2803/0x15533:    50300 psynch_cvwait(0x7FBE52D34568, 0x100000100, 0x0)       = -1 Err#316
 2803/0x15533:        5 gettimeofday(0x7000037B6C88, 0x0, 0x0)       = 0 0
...snip...

[lolo]

Hello,

Thank you very much for the additional information. In your log, I noticed there are 3 occurrence of a message form the method "org.jppf.utils.SystemUtils.getPID()", and each time there is a 5 seconds delay between this message the previous one. In my log you can see that the delay is only a few milliseconds instead (my test was on Windows). Looking at the JPPF code, I believe this this delay can only be in the getPID() method.

To test this strong hypothesis, would it be possible for you to run the following equivalent code on your MacOS machine:

Code: [Select]

import java.lang.management.ManagementFactory;

public class TestPID {
  public static void main(String[] args) {
    try {
      int pid = -1;
      long start = System.nanoTime();
      String name = ManagementFactory.getRuntimeMXBean().getName();
      long elapsed = System.nanoTime() - start;
      int idx = name.indexOf('@');
      if (idx >= 0) {
        String sub = name.substring(0, idx);
        pid = Integer.valueOf(sub);
      }
      System.out.printf("found PID = %d in %,d ms%n", pid, elapsed / 1_000_000L);
    } catch (Exception e) {
      e.printStackTrace();
    }
  }
}
An example output on my machine is:

Code: [Select]

found PID = 7144 in 8 ms
Additonally, I tried to google this issue and found this related StackOverflow thread, which seems to confirm our suspicions and also that you're not the only one having this problem. Thus, it really seems to be a MacOS-specific issue. Unfortunately, I could not find any hint of a fix or workaround. It might be worth raising a JVM bug ...

Sincerely,
-Laurent

[RyShask]

found PID = 4019 in 5,021 ms

Wow... Thank you VERY much for isolating this problem... I should have dug a little deeper before taxing your time... I greatly appreciate it.

I will see if there is a bug against Apple as well in regards to this function call.

Thank you,

-Jeremy

[RyShask]

It appears that Java 9 fixes the issue with getPID, however there seems to be slowness in the tear down of the process now. Not really sure why. Attaching log so you can see that at least the original issue you uncovered has been addressed in the next release of Java.

Am I reading this bug properly? Is there a better method for doing this now? ( though again, a moot point since the current method appears to work properly in JDK-9 )
http://bugs.java.com/bugdatabase/view_bug.do?bug_id=8003490

 time ./run.sh
client process id: 5290, uuid: 0C1AA0A1-D13B-1993-18E3-CFC5FCE1F7B9
Hello, this is the node executing a template JPPF task
Results for job 'Template blocking job' :
Template blocking job - Template task, execution result: the execution was performed successfully

real   0m26.234s
user   0m2.250s
sys   0m0.197s

[lolo]

Hello,

In your latest log I still see a 5 seconds delay on the first invocation of SystemUtils.getPID() It looks to me that the MXBeans are merely lazily loaded and cached upon the first retrieval in JDK 9 on MacOS.
So that's better, but not completely satisfying.

As to the tear down time, I'm still puzzled. What I'm proposing is to gather additional data by adding measurements to the code, along with programmatically taking and printing a thread dump. Could you give it a try, by replacing the main() method of TemplateApplicationRunner with the following:

Code: [Select]

import java.util.*;
import java.util.concurrent.atomic.AtomicLong;
import org.jppf.client.*;
import org.jppf.management.diagnostics.Diagnostics;
import org.jppf.node.protocol.Task;
import org.jppf.utils.JPPFConfiguration;
import org.jppf.utils.configuration.JPPFProperties;

public class TemplateApplicationRunner {

  public static void main(final String...args) {
    try {
      // used to measure the time between the last program statement and actual termination
      class ShutdownHook extends Thread {
        public long start;

        @Override
        public void run() {
          System.out.printf("hook elapsed time = %,.3f ms%n", (System.nanoTime() - start) / 1e6);
        }
      }
      ShutdownHook hook = new ShutdownHook();
      Runtime.getRuntime().addShutdownHook(hook);
      JPPFConfiguration
        .set(JPPFProperties.REMOTE_EXECUTION_ENABLED, false)
        .set(JPPFProperties.LOCAL_EXECUTION_ENABLED, true);
      final AtomicLong elapsed = new AtomicLong(0L);
      // override close() to measure how long it takes
      class MyClient extends JPPFClient {
        @Override
        public void close() {
          long start = System.nanoTime();
          super.close();
          elapsed.set(System.nanoTime() - start);
        }
      }
      try (JPPFClient jppfClient = new MyClient()) {
        TemplateApplicationRunner runner = new TemplateApplicationRunner();
        runner.executeBlockingJob(jppfClient);
      }
      // take a thread dump after the close()
      Diagnostics diag = new Diagnostics("client");
      System.out.printf("time to close = %,.3f ms, thread dump after close() :%n%s%n", elapsed.get() / 1e6, diag.threadDump());
      hook.start = System.nanoTime();
    } catch(Exception e) {
      e.printStackTrace();
    }
  }

  ...
}
Example output in my setup:

Code: [Select]

client process id: 5652, uuid: 08AE4B6C-6A20-8C54-5963-524D5904722A
Hello, this is the node executing a template JPPF task
Results for job 'Template blocking job' :
Template blocking job - Template task, execution result: the execution was performed successfully
time to close = 0.336 ms, thread dump after close() :
----------
ThreadDump
----------

"main" - 1 - state: RUNNABLE - blocked count: 1 - blocked time: 0 - wait count: 8 - wait time: 0
  at sun.management.ThreadImpl.dumpThreads0(Native Method)
  at sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:454)
  at org.jppf.management.diagnostics.ThreadDump.<init>(ThreadDump.java:46)
  at org.jppf.management.diagnostics.Diagnostics.threadDump(Diagnostics.java:130)
  at test.TemplateApplicationRunner.main(TemplateApplicationRunner.java:68)

"Reference Handler" - 2 - state: WAITING - blocked count: 1 - blocked time: 0 - wait count: 1 - wait time: 0
  at java.lang.Object.wait(Native Method)
  - waiting on java.lang.ref.Reference$Lock@657c8ad9
  at java.lang.Object.wait(Object.java:502)
  at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
  at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"Finalizer" - 3 - state: WAITING - blocked count: 1 - blocked time: 0 - wait count: 2 - wait time: 0
  at java.lang.Object.wait(Native Method)
  - waiting on java.lang.ref.ReferenceQueue$Lock@475e586c
  at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
  at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
  at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Signal Dispatcher" - 4 - state: RUNNABLE - blocked count: 0 - blocked time: 0 - wait count: 0 - wait time: 0

"Attach Listener" - 5 - state: RUNNABLE - blocked count: 0 - blocked time: 0 - wait count: 0 - wait time: 0

"Thread-2" - 14 - state: RUNNABLE - blocked count: 1 - blocked time: 0 - wait count: 0 - wait time: 0 - in native code
  at java.net.NetworkInterface.getAll(Native Method)
  at java.net.NetworkInterface.getNetworkInterfaces(NetworkInterface.java:343)
  at org.jppf.utils.NetworkUtils.getIPAddresses(NetworkUtils.java:129)
  at org.jppf.utils.NetworkUtils.getIPV4Addresses(NetworkUtils.java:71)
  at org.jppf.utils.SystemUtils.getNetwork(SystemUtils.java:228)
  - locked java.lang.Class@6295d394
  at org.jppf.management.JPPFSystemInformation$1.run(JPPFSystemInformation.java:290)
  at java.lang.Thread.run(Thread.java:745)

"ChannelsExecutor-0001" - 15 - state: WAITING - blocked count: 1 - blocked time: 0 - wait count: 4 - wait time: 0
  at sun.misc.Unsafe.park(Native Method)
  - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@143640d5
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
  at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
  at java.lang.Thread.run(Thread.java:745)

hook elapsed time = 29.919 ms
Thanks,
-Laurent