Identify performance bottlenecks

[dr0i]

@blackwinter experienced a serious decline of performance when comparing a comprehensive (~ 20M documents) ETL workflow using fix in comparison to a similar morph. Factor was about 100 34 between 34 and 100.
It's very likely that there are a few bottlenecks which we should able be get rid off once identified.
A common approach is to use a profiler to identify bottlenecks.

With #198 there is a possibility to get a Memory Snapshot (hprof) which can be analyzed e.g. further tools like e.g. MAT.
Unfortunately the produced hprofs via #198 are somehow faulty and cannot be loaded into MAT (or the native jhat). It's not clear if this is caused by using gradle (e.g. in conjunction with a preliminary cut-off writing the whole hprof) or a bug in java 1.8 or configuration error (tried several ones - i.a. of course using binary format, and heap=all etc). However, to identify a bottleneck we have to use real workflows with (lots of) real data. I am confident that such a Memory Snapshot is computable by e.g. MAT.

[dr0i]

@blackwinter can you run your ETL workflow and produce statistics of the memory by using jmap, say after running 1/2h ? The command is:

jmap -dump:file=<file_name> <pid> 

Where <pid> is the pid of the java process running the ETL workflow?
Expect "1GB<dumped_file_size<10GB".

[blackwinter]

Unfortunately the produced hprofs via #198 are somehow faulty and cannot be loaded into MAT (or the native jhat).

Note that the default configuration only tracks allocation sites (heap=sites) not allocated objects, so jhat doesn't have anything to analyze. With heap=dump and format=b (along with changing the file extension from txt to bin for consistency) everything works fine.

[blackwinter]

@blackwinter experienced a serious decline of performance when comparing a comprehensive (~ 20M documents) ETL workflow using fix in comparison to a similar morph. Factor was about 100.

I have a more realistic data point by now: When running our workflow as it's supposed to apply to all our Alma libraries soon, we get a factor of about 34 (20 GB input file with approx. 23.5m records, filtered for a single library with approx 1.6m records).

• Metamorph: 1h 51m (final RSS: 510 MB)
• Metafix: 62h 45m (final RSS: 968 MB)

[And just for comparison, our legacy workflow (hbz-toolbox) takes about 30m for a similar workload.]

[dr0i]

heap=dump and format=b

Did that, it's consumable by jhat but not with MAT. jhat does not help me.
I do this:

[~/git/metafacture-fix/metafix]
./gradlew --no-daemon  -p $PWD  :metafix-runner:run --args=$PWD/src/test/resources/org/metafacture/metafix/integration/bind/fromJson/toJson/listArrayOfObjectsAndMoveSubfield/test.flux -Pprofile=pchbz

[blackwinter]

Did that, it's consumable by jhat but not with MAT.

I don't know MAT. What does it say when you load the dump file?

jhat does not help me.

What are you trying to achieve anyway? Shouldn't we concentrate on runtime performance first? Memory consumption is not an issue ATM. It only seems relevant insofar as it affects time spent in GC.

[dr0i]

It says "NPE". Whatever - I have a used MAT sometimes , and it is nice to i.a. see how many Objects are created and this is often a good clue where the problem is coming to performance.
Crucial is to have a real workflow hprof - could you provide that ?

[blackwinter]

Crucial is to have a real workflow hprof - could you provide that ?

Here you go (after running above mentioned workflow for 90m):

$ jmap -dump:file=heap-$(date +%s).bin.gz,gz=6 $pid
Dumping heap to [...]/heap-1648468519.bin.gz ...
Heap dump file created [52987440 bytes in 2.473 secs]

[dr0i]

Just a note here - MAT (also tried YourKit-JavaProfiler) doesn't reveal any obvious stupid (memory/performance) bottlenecks.
Following Objects are IMO the most significant , having a high Object count:

java.util.HashMap$KeyIterator
java.util.HashMap$Node
org.eclipse.xtext.nodemodel.impl.LeafNode

indicating that some kind of caching of HashMap-Paths may be the rescue, as @fsteeg also imagined offline before.

Will try out jprofiler to hopefully gain more insights.

[dr0i]

Used jprofiler trial version to identify CPU usage of methods.
Clone limetrans and checkout branch metafix. I increased the input file defined in src/conf/test/alma-hbz.json by reusing the alma.xml by simply copying the content 10 times to have a long enough running process, That process is started with ./gradlew -Dhbz.limetrans.type=fix testAlmaHBZ . In jprofiler you can attach a running JVM process to the profiler. Go to CPU Views->Hot Spots). Wait a bit. Have a look at the screenshot:

Interesting thing is not the overall time the methods consumes (which changes depending on the how long the transformation is running) but the relation between these methods (in percent. It will not change significantly Correction: after 1h the first entry WildcardTrie.get increased even to 51% while CharMap.get decreased to 12% et cetera.). It shows the CPU consuming methods. As a comparison see the last entry of AbstractSaxParser just to get a bit of feeling about the time.
ETL of 1.3k records was about 1.5h on my laptop. Using morph (``./gradlew -Dhbz.limetrans.type=morph testAlmaHBZ took only 90s (was hard to attach the JVM and use the properHot Spot`fast enough), which shows far less usage of `WildcardTrie` and the respective usage of `HashSet` operations.

So, in general the bottleneck seems to be identified (i.e. the excessive use of WildcardTrie).
Note that clearly the way to go is to reduce the usage of WildcardTrie.
(As a sidenote, it seems to be possible to implement a Trie using HashMap which would be much faster. I will try to implement this, but doubt that, even if it is possible, the performance gain would be of factor 50).