2

I have very long running tests in my maven build. These tests are integration tests run with failsafe plugin (mvn verify).

I try to profile these tests using JProfiler.

The tests runs correctly but I don't see anything useful in JProfiler as if JProfiler was filtering them out.

I'm on openSUSE 13.1 x64, with Maven 3.2.1 and JProfiler 8.0.5

The JProfiler session settings are the default ones with two modifications :

  • Start CPU profiling automatically at start
  • Keep the VM alive when the execution is finished (to enable backtracing info)

I launch the profiled build using this command :

MAVEN_OPTS="-agentpath:/opt/jprofiler8/bin/linux-x64/libjprofilerti.so=port=8849" mvn verify

Maven and JProfiler run on the same machine (local profiling).

The build starts normally :

$ MAVEN_OPTS="-agentpath:/opt/jprofiler8/bin/linux-x64/libjprofilerti.so=port=8849" mvn verify
JProfiler> Protocol version 39
JProfiler> Using JVMTI
JProfiler> JVMTI version 1.1 detected.
JProfiler> 64-bit library
JProfiler> Listening on port: 8849.
JProfiler> Instrumenting native methods.
JProfiler> Can retransform classes.
JProfiler> Can retransform any class.
JProfiler> Native library initialized
JProfiler> VM initialized
JProfiler> Waiting for a connection from the JProfiler GUI ...
JProfiler> Using dynamic instrumentation
JProfiler> Time measurement: elapsed time
JProfiler> CPU profiling enabled
[INFO] Scanning for projects...
[INFO] 
[INFO] Using the builder org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder with a thread count of 1
[INFO]                                                                         
[INFO] ------------------------------------------------------------------------
[INFO] Building...
[...]

and also ends normally :

[...]
Results :

Tests run: 2766, Failures: 0, Errors: 0, Skipped: 0

[WARNING] File encoding has not been set, using platform encoding UTF-8, i.e. build is platform dependent!
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 19:31 min
[INFO] Finished at: 2014-06-18T11:38:49+01:00
[INFO] Final Memory: 21M/107M
[INFO] ------------------------------------------------------------------------
JProfiler> Keeping VM alive until frontend disconnects.

JProfiler Hot Spots CPU view show me this :

enter image description here

As for me, it is useless stuff, only maven related methods (zipping, class loading).

When I try to go through (open an hotspot backtrace), I don't find anything related to the tests I run.

Moreover the mesured elapsed time (if I add the top 10 hotspots inherent time) is largely insignificant (~10s) compared to the actual total time (~19 mins 30s).

EDIT:

At first, I ran the tests profiling with my IDE (IntelliJ IDEA) and the JProfiler plugin but I stopped because of a strange behavior. It seemed like the tests were running forever without doing anything. I supposed this was coming from the IDE (or the plugin) because the tests run fine through maven.

EDIT 2:

Thanks to @IngoKegel suggestion, if I select "All states" I have more information :

enter image description here

I see 4 more hot spots. However, they still don't give me usable information :

  1. is a "filtered/direct call" to j.u.c.ThreadPoolExecutor$Worker.run
  2. is a single call from Maven (plexus) to j.l.r.Method.invoke (+ insignificant calls)
  3. and 4. are "filtered/direct call" to o.a.maven.p.surefire.booterclient.o.ThreadStreamConsumer$Pumper.run

The elapsed time is a lot better, but I still don't see anything coming from "my" classes.

Why are my classes still filtered ? Is there a way to see them ?

Additionally, I don't fully understand why these hot spots don't show when selecting "Runnable" states. Moreover it's the default option...

Surprisingly, if I add the these top 4 elapsed time it gives me ~1h but execution is ~19min 20s as if some Hotspots were overlapping. I think it's a side effect of the "All states" option.

superbob
  • 1,628
  • 13
  • 24
  • 1
    Have you tried to set the thread status selector in the upper right corner to "All states"? – Ingo Kegel Jun 18 '14 at 13:02
  • @IngoKegel, thanks for your suggestion, I tried it, please, take a look at my _EDIT 2:_. – superbob Jun 19 '14 at 08:58
  • Currently, the only working option I have is to run the tests individually with JUnit (without Maven) using a command such as : _java -agentpath:... -cp ... org.junit.runner.JUnitCore _, that way I see useful information in JProfiler, but has a lot of disadvantages (need to run each test individually, cannot have global indicators, impractical command line...) – superbob Jun 19 '14 at 13:12
  • You see the sum of the elapsed times in all threads, so if you have multiple threads, it's always more than the wall clock time. What are your filter settings? You should define inclusive filters for your top-level packages. – Ingo Kegel Jun 19 '14 at 20:20
  • 1
    I found it, it's a Maven trick : integration tests in maven are run in a separate VM. And MAVEN_OPTS are ignored in this VM. The solution is to configure the failsafe plugin to use "jprofiler options". With the correct setup I see useful results in the profiling. I will write a clean answer to my question to explain that. – superbob Jun 23 '14 at 12:33

1 Answers1

1

The trick is that Maven failsafe plugin runs integration tests in a separate JVM :

A typical Maven build with unit tests and integration tests can easily use 3 different JVMs :

  • Maven main JVM (compile, package), launched by the mvn command
    • Surefire JVM (unit tests), launched by the Maven main JVM
    • Failsafe JVM (integration tests), launched by the Maven main JVM

Profiling the Maven main JVM will never show information on the work done inside the Failsafe JVM. Moreover, options specified in the MAVEN_OPTS are only passed to the Maven main JVM.

To profile one of the other JVMs, you have to configure it separately using plugins configuration in the pom.xml file.

To answer the question, it requires the following plugin configuration :

<plugins>
    [...]
    <plugin>
        <artifactId>maven-failsafe-plugin</artifactId>
        <version>2.17</version>
        <executions>
            <execution>
                <goals>
                    <goal>integration-test</goal>
                    <goal>verify</goal>
                    <!-- to exclude IT from main build, comment the 'verify' goal -->
                </goals>
            </execution>
        </executions>
        <configuration>
            <argLine>${failsafeArgLine}</argLine>
        </configuration>
    </plugin>
    [...]
</plugin>

The important part here is <argLine>${failsafeArgLine}</argLine>

Then, JProfiler agent options can be specified through the failsafeArgLine argument :

mvn verify -DfailsafeArgLine="-agentpath:/opt/jprofiler8/bin/linux-x64/libjprofilerti.so=port=8849"

Running this command will start the Maven build normally (without profiling), then when the integration tests phase begins, it asks for a JProfiler connection :

[...]
[INFO] 
[INFO] --- maven-failsafe-plugin:2.17:integration-test (default) @ project ---
[INFO] Failsafe report directory: /home/user/Repositories/project/target/failsafe-reports

-------------------------------------------------------
 T E S T S
-------------------------------------------------------
JProfiler> Protocol version 39
JProfiler> Using JVMTI
JProfiler> JVMTI version 1.1 detected.
JProfiler> 64-bit library
JProfiler> Listening on port: 8849.
JProfiler> Instrumenting native methods.
JProfiler> Can retransform classes.
JProfiler> Can retransform any class.
JProfiler> Native library initialized
JProfiler> VM initialized
JProfiler> Waiting for a connection from the JProfiler GUI ...
JProfiler> Using dynamic instrumentation
JProfiler> Time measurement: elapsed time
JProfiler> CPU profiling enabled
[...]

Failsafe VM arguments could also have been specified directly in the pom.xml file (instead of using a failsafeArgLine property), but I prefer to use it that way.

superbob
  • 1,628
  • 13
  • 24