understanding scala non-blocking method execution using jvisualvm

Question

I have a very simple scala async method within main Thread that I am trying to see how much it takes to execute so that I can use the same knowledge to profile my actual API.

import scala.concurrent.ExecutionContext.Implicits.global
import scala.concurrent.Future

object ConcurrentTasks {

  def main(args: Array[String]): Unit = {

    println("starting task")
    quickTask()

    println("waiting for 30 secs")
    Thread.sleep(30000)
  }

  private def quickTask(): Future[Int] = {
    for {
      x <- Future {
        Thread.sleep(2000) 
        100
      }
    } yield {
      println("finished computation " + x)
      x
    }
  }

}

The steps I followed for profiling,

open jvisualvm
I run above app using scalac, scala ConcurrentTasks.scala
go to Profile tab of running application in jvisualvm and start CPU profile.
I see following log trace in my running app.

trace

$ scala ConcurrentTasks.scala 
starting task
waiting for 30 secs
finished computation 100
objc[26802]: Class JavaLaunchHelper is implemented in both /Library/Java/JavaVirtualMachines/jdk1.8.0_151.jdk/Contents/Home//bin/java (0x10899d4c0) and /Library/Java/JavaVirtualMachines/jdk1.8.0_151.jdk/Contents/Home/jre/lib/libinstrument.dylib (0x11041e4e0). One of the two will be used. Which one is undefined.
Profiler Agent: JNI OnLoad Initializing...
Profiler Agent: JNI OnLoad Initialized successfully
Profiler Agent: Waiting for connection on port 5140 (Protocol version: 15)
Profiler Agent: Established connection with the tool
Profiler Agent: Local accelerated session
Profiler Agent Warning: JVMTI classLoadHook: class name is null.
Profiler Agent Warning: JVMTI classLoadHook: class name is null.
Profiler Agent Warning: JVMTI classLoadHook: class name is null.
Profiler Agent Warning: JVMTI classLoadHook: class name is null.
Profiler Agent Warning: JVMTI classLoadHook: class name is null.
Profiler Agent Warning: JVMTI classLoadHook: class name is null.
Profiler Agent Warning: JVMTI classLoadHook: class name is null.
Profiler Agent Warning: JVMTI classLoadHook: class name is null.
Profiler Agent: Redefining 100 classes at idx 0, out of total 106 
Profiler Agent: Redefining 6 classes at idx 100, out of total 106 
Profiler Agent Warning: JVMTI classLoadHook: class name is null.
Profiler Agent Warning: JVMTI classLoadHook: class name is null.
Profiler Agent Warning: JVMTI classLoadHook: class name is null.
Profiler Agent Warning: JVMTI classLoadHook: class name is null.
Profiler Agent: Connection with agent closed
Profiler Agent: Connection with agent closed

Once it is completed I get the snapshot where I don't see my application method at all.

I tried both Sampling and Profiling.

It should not matter, I'm using java 1.8.0_151.

My primary question is how do I measure the async scala method execution in jvisualVM?

Just a side note: have you seen https://scalameter.github.io? — Nader Ghanbari, Dec 17 '17 at 01:34
I have not used scalameter. It seems more for perf testing with no visualization on its own. I will need that too at some point. Also not sure if it can instrument all of API, all the traces — prayagupa, Dec 17 '17 at 01:38
I made it `Thread.sleep(10000)` and moved it before calling the `quickTask`, then if you sample cpu you'd be able to look at the snapshot. The thing is here its an async method which just returns to the calling thread almost immediately (hence you'll see probably just 0.000ms. It's tough to measure async calls. One way is to explicitly waiting for their result using await utilities. — Nader Ghanbari, Dec 17 '17 at 02:00
On a side note: you'll have to have the sampling already started when execution reaches the subject method. Otherwise it'll escape the sampler. There are different ways of working around this. A better profiler is an option. — Nader Ghanbari, Dec 17 '17 at 02:04
Right, I can see it showing the execution time for synchronous method. And 1) how can sampler be added to visualvm without knowing the PID of running application? 2) I did not understand what you mean by "A better profiler is an option."? My actual API has tons of scala `Future`s. — prayagupa, Dec 17 '17 at 02:23
I meant a better profiler tool, like YourKit or other profilers. You can simply debug and set a breakpoint, also there is https://visualvm.github.io/startupprofiler.html which helps. You can also suspend your app to wait for the JDWP to be attached. Look at [this thread](https://stackoverflow.com/questions/4434860/how-to-profile-application-startup-with-visualvm) for instance. — Nader Ghanbari, Dec 17 '17 at 02:33
On the async stuff, I believe there's no easy way, you can still profile the app if micro-aspects are your main concern but you'll have to do the math (find the most time consuming part, aggregate, etc.). If the overall performance is what you want to measure, you can consider performance tests and run them multiple times. Also consider the `Await` option to wait for the future result. That's why I mentioned scalameter actually, you can write unit tests to do that. — Nader Ghanbari, Dec 17 '17 at 02:36
1) Ok, If i know the port my app will be running on then I might be able to run profiler earlier but when I run self executing jars maybe not. 2) And my actual API has couple of Future tasks running. For example, get the user information from database, then for each user get images from API1, parallely get user validity from API2 etc etc. I initially added logs all over to get execution time which i thought is a verbose way. It makes sense to log how much my API took to process one request. I use scala actor which times out sometimes because it can not process within configured timeout. — prayagupa, Dec 17 '17 at 02:57
Let us [continue this discussion in chat](http://chat.stackoverflow.com/rooms/161381/discussion-between-nader-hadji-ghanbari-and-prayagupd). — Nader Ghanbari, Dec 17 '17 at 02:59

understanding scala non-blocking method execution using jvisualvm

0 Answers0