Excessive prepareStatement probe overhead in EAP

Questions about YourKit Java Profiler
Post Reply
dthomas
Posts: 13
Joined: Mon Jun 09, 2014 4:47 pm

Excessive prepareStatement probe overhead in EAP

Post by dthomas »

Hope this is the right place to report issues with the EAP. It's looking great so far, the UI is more responsive than ever, and the new features are great.

One not so nice change is that I'm seeing a lot more overhead than I'm used to from prepareStatement calls with CPU profiling enabled, specifically: com.yourkit.probes.builtin.Databases$Connection_prepareStatement_Probe.onEnter()

Is this a known issue?
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Excessive prepareStatement probe overhead in EAP

Post by Anton Katilin »

Hi,

Do you use the latest EAP build?

With which version do you compare? Is it v2013?
How do you measure the overhead? Could you please provide the numbers, what it was and what it is now.

Could you please make sure you specify the same agent startup options for both versions.

It's known that the probes add overhead which can be eliminated by turning them off, but we are not aware of regressions in the EAP version comparing with v2013.

Best regards,
Anton
dthomas
Posts: 13
Joined: Mon Jun 09, 2014 4:47 pm

Re: Excessive prepareStatement probe overhead in EAP

Post by dthomas »

Hi Anton,

That's right: YourKit 2014 build 14060, Java 1.7.0_60.

Thankfully it's easy to reproduce - it's by far away the top consumer of time when sampling of a JDBC based application, so it's bubbling to the top and skewing results. Here's a quick comparison between no agent, agents with no options and sampling, on Mac OS with JMH:

Code: Select all

Benchmark                      Mode   Samples        Score  Score error    Units
Baseline                      thrpt        20  3153144.913   448483.596   ops/ms
2013 Agent                    thrpt        20   441568.866     8597.291   ops/ms
2014 Agent                    thrpt        20   440193.374     6290.117   ops/ms
2013 Sampling                 thrpt        20   430578.975     4573.058   ops/ms
2014 Sampling                 thrpt        20       66.734       38.889   ops/ms
Here's the Maven project with the benchmark already compiled:

https://www.dropbox.com/s/ocwt4m4brsihj ... tement.zip

Run using the following command to get the same result as the 2014 Sampling result above. Only the jvmArgs differed for each test:

Code: Select all

java -jar target/microbenchmarks.jar -i 20 -wi 10 -f 1 -jvmArgs -agentpath:/Applications/YourKit.app/bin/mac/libyjpagent.jnilib=sampling
Cheers,
Danny
dthomas
Posts: 13
Joined: Mon Jun 09, 2014 4:47 pm

Re: Excessive prepareStatement probe overhead in EAP

Post by dthomas »

Oh, I should add:
  • Presumably, the difference between the baseline and the agent indicates that there's quite a bit of overhead with the agent, even when not sampling, though there's no regression there
  • To compile the project yourself:

    Code: Select all

    mvn install
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Excessive prepareStatement probe overhead in EAP

Post by Anton Katilin »

Hi Danny

Thank you for providing the detail.

We managed to reproduce the problem.

Our first observation is that v2013 did not handle most of the events in the test.

We have slightly modified the example, and indeed see some performance degradation in v2014.
We're investigating which changes are responsible, and how to fix it.

I'll inform you informed of the results.

Best regards,
Anton
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Excessive prepareStatement probe overhead in EAP

Post by Anton Katilin »

Hi Danny

Could you please try the latest build 14062:
http://www.yourkit.com/eap

Probe overhead has been reduced.
The modified test (see detail below) now works with v2014 faster than with v2013 in multithreaded mode. In a single thread mode v2014 is still slightly slower, but this is expected: the optimizations in v2014 were targeted at improving profiling of multithreaded applications, which is the most important and popular case.

The test needed a modification to make comparison fair. The problem with v2013 was that it simply ignored all events in DummyConnection because it was not created via one of "predefined" ways v2013 can recognize - DataSource or Driver. In contrast, version 2014 handles such connections, thus its overhead in your original test was much higher - the version 2013's probes were almost no-ops.

To make v2013 and v2014 register the same set of events (that is, to make events visible to v2013), we've added a dummy DataSource to create DummyConnection instead of directly calling new DummyConnection() in the benchmark:

Code: Select all

public class DummyDataSource implements DataSource {
  @Override
  public Connection getConnection() throws SQLException {
    return new DummyConnection();
  }

  @Override
  public Connection getConnection(final String username, final String password) throws SQLException {
    return null;
  }

  @Override
  public PrintWriter getLogWriter() throws SQLException {
    return null;
  }

  @Override
  public void setLogWriter(final PrintWriter out) throws SQLException {
  }

  @Override
  public void setLoginTimeout(final int seconds) throws SQLException {
  }

  @Override
  public int getLoginTimeout() throws SQLException {
    return 0;
  }

  @Override
  public Logger getParentLogger() throws SQLFeatureNotSupportedException {
    return null;
  }

  @Override
  public <T> T unwrap(final Class<T> iface) throws SQLException {
    return null;
  }

  @Override
  public boolean isWrapperFor(final Class<?> iface) throws SQLException {
    return false;
  }
}
The benchmark main class is:

Code: Select all

public class MyBenchmark {
  private static final ThreadLocal<Connection> DUMMY_CONNECTION = new ThreadLocal<Connection>() {
    @Override
    protected Connection initialValue() {
      try {
        return new DummyDataSource().getConnection();
      }
      catch (SQLException e) {
        System.exit(-1);
        return null;
      }
    }
  };

  @GenerateMicroBenchmark
  public void testMethod() throws SQLException {
    final PreparedStatement stmt = DUMMY_CONNECTION.get().prepareStatement("SELECT * FROM table");
    stmt.close();
  }
}
DataSource is created per-thread and is stored as a thread local.
We also added calls to Statement.close() to better measure probe impact.

Please also note that running without sampling makes no sense in this test, since the Databases probe activity mode is Auto by default, i.e. it's active only when CPU sampling or tracing is running:
http://www.yourkit.com/docs/java/help/r ... probes.jsp

Best regards,
Anton
dthomas
Posts: 13
Joined: Mon Jun 09, 2014 4:47 pm

Re: Excessive prepareStatement probe overhead in EAP

Post by dthomas »

Hi Anton,

Definitely improved in terms of raw throughput, about twice the overhead of 2013 using your test approach on a single threaded test. The individual iteration throughput varies a lot, thus the high score error. It'd probably be more reliable test to sleep/spin for some time to simulate the normal overhead of preparing a statement; I guess it's unreasonable to expect that the probes would be able to keep up with so much activity:

Code: Select all

Benchmark                            Mode   Samples        Score  Score error    Units
No agent                            thrpt        20   361463.717     4853.858   ops/ms
Agent                               thrpt        20     1735.598     1482.994   ops/ms
Agent with sampling                 thrpt        20      315.739      181.982   ops/ms
2013 Agent with sampling            thrpt        20      649.419      310.372   ops/ms
The reason I mentioned the performance of agent without sampling, is because the results show a massive difference between having an agent and none on probed methods. Any insight into why there is such high overhead without active probes or sampling?

Danny
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Excessive prepareStatement probe overhead in EAP

Post by Anton Katilin »

Difference between "No agent" and "Agent": the probe callbacks which are inactive (please see the link in my previous message about probe activity modes). They are almost negligible in real life, but can make a difference when applied to empty DummyConnection methods. Adding small code to a real method is almost invisible, but adding it to an empty method body significantly increases the method time: almost-zero plus something is many times bigger than almost-zero. Furthermore, JVM effectively inlines empty prepareStatement() method making its execution impact even more negligible, but it cannot do this when the probe inserts its callbacks. Should it be a real life method doing something useful (or if we added sleep/spin as you suggested), the picture would change: the inactive probe callbacks would not be such a huge impact on the test results.

You can try specifying startup option "probe_disable=*" to totally eliminate the probes. You can additionally disable CPU tracing instrumentation with "disabletracing" to ensure the method remains empty.

Difference between "Agent" and "Agent with sampling": sampling makes the probes in Auto mode active, and they start working.

Alternatively to starting sampling, you can change the probe activity mode from Auto to On with the startup option "probe_on=*" (and without "sampling"). I can't test right now, but I guess the result will be similar to what you have got for "Agent with sampling".

Best regards,
Anton
dthomas
Posts: 13
Joined: Mon Jun 09, 2014 4:47 pm

Re: Excessive prepareStatement probe overhead in EAP

Post by dthomas »

Thanks for your help Anton. It's definitely better with the later build, and I'm now setting all of the probes off by default for this application, and I'll turn them on when I need them (and I'll disable them when I really need low overhead).

It's not always obvious from the CPU data which methods are covered by probes - perhaps as a future enhancement you could mark methods that match active/on probes in the UI?
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Excessive prepareStatement probe overhead in EAP

Post by Anton Katilin »

Hello Danny

We've just released build 14064 with more improvements.
perhaps as a future enhancement you could mark methods that match active/on probes in the UI?
Thank you for the suggestion. I've added a feature request.

Best regards,
Anton
Post Reply