6

Using JProfiler, I've identified a hot spot in my Java code that I cannot make sense of. JProfiler explains that this method takes 150μs (674μs without warmup) on average, not including the time it takes to call descendant methods. 150μs may not seem much, but in this application it adds up (and is experienced by my users) and also it seems a lot, compared to other methods that seem more complex to me than this one. Hence it matters to me.

private boolean assertReadAuthorizationForFields(Object entity, Object[] state,
        String[] propertyNames) {
    boolean changed = false;
    final List<Field> fields = FieldUtil.getAppropriatePropertyFields(entity, propertyNames);
    // average of 14 fields to iterate over
    for (final Field field : fields) {
        // manager.getAuthorization returns an enum type
        // manager is a field referencing another component
        if (manager.getAuthorization(READ, field).isDenied()) {
            FieldUtil.resetField(field.getName(), state, propertyNames);
            changed = true;
        }
    }
    return changed;
}

I have for myself minimized this method in different directions, but it never teaches me much useful. I cannot stress enough that the JProfiler-reported duration (150μs) is merely about the code in this method and does not include the time it takes to execute getAuthorization, isDenied, resetField and such. That is also why I start of by just posting this snippet, without much context, since the issue seems to be with this code and not its subsequent descendant method calls.

Maybe you can argue why – if you feel I'm seeing ghosts :) Anyhow, thanks for your time!

Raedwald
  • 46,613
  • 43
  • 151
  • 237
Sander Verhagen
  • 8,540
  • 4
  • 41
  • 63
  • 1
    Profiling requires a warmup period (for JIT). Are you warming up? Is JIT disabled? – Java42 Mar 17 '13 at 04:01
  • That is a good point. Although I knew about this, I may have dropped the ball there. I'll update my post, and with the amount of time it takes after some warm-up rounds, I am divided about whether or not I am still of the opinion that it's excessive... maybe I should delete the question ... maybe not :) – Sander Verhagen Mar 17 '13 at 04:10
  • 2
    Are you using CPU sampling or dynamic instrumentation with JProfiler? – jonathan.cone Mar 17 '13 at 04:14
  • 2
    Don't delete. You can answer your own question if you solve the mystery. – Java42 Mar 17 '13 at 04:15
  • I'm looking at Call Tree and Hot Spots respectively. "Dynamic Instrumentation" is in fact configured for my session. – Sander Verhagen Mar 17 '13 at 04:18
  • What kind of List does FieldUtil.getAppropriatePropertyFields() return? If the average is 14, what is the minimum/maximum number that can be returned? I imagine that almost all the time is spent in the loop. – bchurchill Mar 17 '13 at 04:18
  • 1
    At 150µs it would take 600+ invocations for this to contribute 0.1 seconds to response time. Maybe the question to ask is whether you need to invoke it so many times. – Jim Garrison Mar 17 '13 at 04:23
  • The method `getAppropriatePropertyFields` returns `List`. The profile sample involves me refreshing a web page upon which user info is read from the database first, then a list of 594 data records is fetched, both of which involve this method, i.e. 595 calls in total. The user data may involve a little less fields, the 14 pertains to these 594 data records. – Sander Verhagen Mar 17 '13 at 04:24
  • Are you using `Reflection` (i.e. `java.lang.reflect`)? This can be terribly slow! `SecurityManager` can introduce delays. If the Fields represent primitives there is implicit boxing/wrapping incurred when you access their values. – gb96 Apr 04 '13 at 05:34
  • I'm sorry, but I had to take away focus from this particular question. I may or may not revisit it in the future, but the debugging is costing me a lot of time that doesn't past the effort/result criteria at this time. – Sander Verhagen Apr 27 '13 at 03:32
  • possible duplicate of [Java Reflection Performance](http://stackoverflow.com/questions/435553/java-reflection-performance) – Raedwald Jun 15 '13 at 12:36

3 Answers3

1

Candidate behaviour that could slow you down:

  • Major effect: Obviously iteration. If you have lots of fields... You say 14 on average, which is fairly significant
  • Major effect: hotspot inlining would mean called methods are included in your times - and this could be noticeable because your method call(s) use reflection. getAppropriatePropertyFields introspects on class field definition metadata; resetField dynamically invokes setter methods (possibly using Method.invoke()??). If you are desperate for performance, you could use a cache via a HashSet (mapping ElementClass->FieldMetadataAndMethodHandle) This could contain field metadata and MethodHandles of setter methods (instead of using method.invoke, which is slow). Then you would only reflect during application startup and would use the JVM's fast dynamicInvoke support.
  • Minor effect - but multiplied by number of iterations: if you have very large arrays for state and property names, and they use primitive fields, then they would involve some degree of copying during method invocations (method parameters pass-by-'value' actually means pass-by-reference/pass-by-copy-of-primitives)
Glen Best
  • 22,769
  • 3
  • 58
  • 74
0

I suggest you time the method yourself as the profiler doesn't always give accurate timing.

Create a micro-benchmark with just this code and time it for at least 2 second. To work out how much difference method calls make, comment them out and hard code the values they return.

Peter Lawrey
  • 525,659
  • 79
  • 751
  • 1,130
  • 1
    Two reasons for the occasionally inaccurate timings reported by sampling profilers: 1) If the JIT chooses to inline a method, that method will never be reported independently. Are the called methods also reported independently (even after warmup)? If not, they may be inlined, in which case their time will be inaccurately attributed to assertReadAuthorizationForFields(). 2) It can take quite a long run before the sampling settles down to report a stable time. Are the timings you're seeing from JProfiler stable from 1 run to the next? – AaronD Mar 18 '13 at 16:52
0

I think the issue is that FieldUtil is using Reflection and doesn't cache the fields it's using.

jontejj
  • 2,800
  • 1
  • 25
  • 27