Performance Issue when upgrading from 0.3.3 to 0.4.1

[mattdornfeld]

Please make sure that this is a bug. As per our GitHub Policy, we only address code/doc bugs, performance issues, feature requests and build/installation issues on GitHub. tag:bug_template

System information

• Have I written custom code (as opposed to using a stock example script provided in TensorFlow):
  Code is based one examples in tests found in Tensorflow 0.3.3
• OS Platform and Distribution (e.g., Linux Ubuntu 16.04 x86_64):
  Method profiling is done on MacOS 12.4 x86_64. Resource profiling is done on Ubuntu 18.04 x86_64
• TensorFlow installed from (source or binary):
  Installed from binary using Gradle
• TensorFlow version (use command below):
  Tensorflow 2.4.1
• Java version (i.e., the output of java -version):
  Compiled with Java 11 run with Java 17
• Java command line flags (e.g., GC parameters):
  -XX:+UseG1GC
• Python version (if transferring a model trained in Python):
  Python 3.7

Describe the current behavior
I'm trying to upgrade from Tensorflow Java 0.3.3 to 0.4.1 and am seeing significant performance degradation when doing the upgrade. I've done a good amount of profiling to help diagnose the issue and I was hoping someone might be able to help me understand what's going on. On a high level these performance tests are constructing a HashMap of tf.Tensor objects from input data and feeding them to a trained Logistic Regression model for inference. Note that this profiling shows a downgrade from 0.4.1 back to 0.3.3 (so earlier is the newer version and later is the older versioon)

When downgrading from 0.4.1 to 0.3.1 I see a significant decrease in p50 latency (measured in ms)

I also see increased CPU usage

Decreased memory usage

And increased Young Generation Garbage collection

Using method level profiling with Intellij I was able to see a CPU hotspot in the Tensor creation code. The newer version 0.4.1 has significantly more CPU samples than the older version 0.3.3

I was also able to see a memory hot spot in the inference step. The newer version 0.4.1 has significantly more memory samples than the older version 0.3.3

Describe the expected behavior
I'm having a hard time diagnosing the cause of this issue since I would expect a version upgrade to not have significantly different performance. Happy to hear any ideas on what might be causing this.

Code to reproduce the issue
It's difficult to supply a self contained code snippet since this is a prod system with many different classes, but I can supply more code as needed.

[Craigacp]

Do you have a flame graph for the 0.3.3 code to compare? Is the performance delta consistent between the two versions on macOS and Linux (which are presumably different hardware platforms too, do they support different SIMD instruction sets)?

There were a lot of changes in TF-Java from 0.3 to 0.4, and we also moved from TF 2.4 to 2.7 which changed the native code quite a bit, but I wouldn't expect a large performance degradation so we'll try to help run it down.

[mattdornfeld]

@Craigacp Sure! Here's the CPU flame graph of the Tensor creation process on 0.3.3

Unfortunately we do not have the same data on Linux since we don't currently have a profiling tool that's capable of running in the cloud (still waiting for that to go through purchasing). We only have the more system level performance metrics I posted above.

[saudet]

For best performance, make sure that the "org.bytedeco.javacpp.nopointergc" system property has been set to "true".

[mattdornfeld]

@saudet Thanks for the suggestion. Just tried setting the flag and didn't see any noticeable performance difference.

[Craigacp]

Turning off the pointer GC should remove the native call in Pointer.physicalBytes() which seems to be taking a bunch of time in that flame graph, so it should have made things faster (though possibly made both of them faster).

I can't actually see any major differences between the two graphs which is odd, though Tensor creation didn't get as much of a do-over as functions did between 0.3 and 0.4.

Is it possible to get a JFR trace from both 0.3 and 0.4?

[karllessard]

@mattdornfeld , in your last diagram here, I see that you are calling both SessionFunction.call and ConcreteFunction.call, is it on 0.4.1?

That is something that has changed drastically in 0.4.x, the concrete functions are now built as native graph that could be called by another graph, like Python does. If you call it directly from your code, it will run eagerly, which is much slower and resource consuming. Though looking at your flame graph, it looks like it is run by a session, which surprises me.

Do you have any code to share that shows what's happening here?

[mattdornfeld]

@karllessard Thank you that's helpful. The flame graph shows the diff between 0.4.1 and 0.3.3. The way to interpret it is that the 0.4.1 test is using SessionFunction and the 0.3.3 test is using ConcreteFunction. Do you think that could be the source of the performance issue?

[karllessard]

Ah I see... no I don't think that's the issue then, SessionFunction in 0.4.1 is pretty much the equivalent of ConcreteFunction in 0.3.3.

What I'm noticing though is that a substantial amount of time is also spent in Graph.initializers and that is something else that has been added in 0.4.x, so that could be the cause. I'll need to investigate this part a bit more though to understand what can happen in there.

[mattdornfeld]

@Craigacp Here's a zip file containing jfr files for the performance test for both 0.3.3 and 0.4.1 https://www.dropbox.com/s/aykejkzsug1g1te/tensorflowjavajfr.zip?dl=0.

I also tried experimenting more with setting org.bytedeco.javacpp.nopointergc=true and found that doing so did not completely remove the call to Pointer.PhysicalBytes which is puzzling...

[karllessard]

Hi @mattdornfeld , I know that this issue has been opened awhile ago but do you by any chance still have these performance tests ready to run? I was wondering if you can see an improvement in performance in the latest 0.5.0-SNAPSHOT after committing some simplifications around the initializer mechanisms introduced in 0.4.x

[mattdornfeld]

Hi @karllessard sorry I didn't post this earlier but I was actually able to solve the performance problems by decreasing the concurrency level on the service. It seems that having that # of qps to the model was okay for the previous version but not for the newer version.

I'll also try running with the latest version and let you know what I find.

[karllessard]

Ah ok great! 👍

I still do expect that you'll observe additional improvements in the performance with the latest version, looking at your previous graphs. The doInit part should now be negligible.

I'll close this issue now but please share any new results in here, thank you