CPU profiling<\/strong><\/span><\/p>\n\n\n\n See below the execution call tree under-sampling. This diagram indicates that the hot spots are in NettingExecutor and ClassificationEvaluator. Later we spent more time instrumenting the code and figuring patterns in the processed data. In this case, we realized below optimizations were needed:<\/p>\n\n\n\n Bring cache size from 12GB to 4GB<\/strong><\/span><\/strong><\/p>\n\n\n\n Our application was using a lot of memory. We needed to understand where the memory is going and realized that a few in-memory caches were the biggest culprits per the below diagram. We later modified the objects holding the data to reduce memory usage and shared the references between objects using an object pool. With these changes, we could bring the startup memory of the application down to less than 4GB from over 12GB.<\/p>\n\n\n\n Understanding allocation rates of objects per execution<\/span><\/strong><\/p>\n\n\n\n Our application was designed as a stateless service that worked on large data sets where it initialized the data internally, worked on it, and then released the memory. These actions were resulting in frequent GC spikes and pauses. We looked at the allocation call tree to understand areas that executed the most frequent allocations.<\/p>\n\n\n\n Here is another way to look at the allocations to check the objects allocated between two different execution times. As per the below diagram that shows the number of allocations between two times, we realized that we frequently pulled into the process memory a large object over pub-sub. Per below, parsing and transforming that object to POJO took many allocations.<\/p>\n\n\n\n JVisual VM<\/span><\/strong><\/p>\n\n\n\n Here is another excellent and simple tool that shows a high-level overview of memory, threads, and CPU.<\/p>\n\n\n\n Flight recorder<\/span><\/strong><\/p>\n\n\n\n Flight recorder is an excellent tool available via oracle JDK. The below image shows GC activity between two different times and, in addition, the length of GC pauses. This information offers a bird’s eye overview of JVM memory and GC activity.<\/p>\n\n\n\n Understanding TLAB activity<\/span><\/strong><\/p>\n\n\n\n The below diagram shows several objects inside and outside TLAB while connecting to JVM under load. Per below, we see a significant number of objects allocated outside TLAB. Note the slowness in allocations when objects are allocated outside of TLAB.<\/p>\n\n\n\n See below where I analyzed allocation calls resulting in allocations outside TLAB. This occurs while saving a large binary object to a blob in DB and making a call to a service where large JSON objects are being transmitted over wire. In the case of the binary object being allocated and persisted to DB, we modified its design to run asynch, so slowness in its allocation and persistence to DB doesn’t slow down the processing. In addition, the developers should look into trimming down the size of the object transmitted to an external service over JSON.<\/p>\n\n\n\n Analyzing JVM GC logs<\/span><\/strong><\/p>\n\n\n\n GC logs over a long period are massive. Mentally creating a timeline of GC activity over a long period is not easy. GC viewer helps visualize GC activity over a period that is useful to understand how the application performed under a load test. GC viewer is an open-source tool and available at: https:\/\/github.com\/chewiebug\/GCViewer Here is a summary of GC activity that GC viewer displayed.<\/p>\n\n\n\n <\/p>\n\n\n\n Here is an excellent article from uber that describes their performance tuning exercise to improve efficiency in their data streaming pipelines: <\/p>\n\n\n\n https:\/\/eng.uber.com\/building-scalable-streaming-pipelines\/<\/a><\/p>\n","protected":false},"excerpt":{"rendered":" It is essential to understand what is slow before starting to optimize. And understanding the slow pieces in code requires profiling the code to figure out the hot spots and making efforts appropriately to optimize slowness inside the hotspots. I have been writing code and designing systems for two decades now. Even with this experience,Continue reading “Profiling”<\/span><\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"parent":0,"menu_order":0,"comment_status":"closed","ping_status":"closed","template":"","meta":{"footnotes":""},"wf_page_folders":[18],"class_list":["post-670","page","type-page","status-publish","hentry"],"_links":{"self":[{"href":"https:\/\/uqcodewall.com\/index.php?rest_route=\/wp\/v2\/pages\/670","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/uqcodewall.com\/index.php?rest_route=\/wp\/v2\/pages"}],"about":[{"href":"https:\/\/uqcodewall.com\/index.php?rest_route=\/wp\/v2\/types\/page"}],"author":[{"embeddable":true,"href":"https:\/\/uqcodewall.com\/index.php?rest_route=\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/uqcodewall.com\/index.php?rest_route=%2Fwp%2Fv2%2Fcomments&post=670"}],"version-history":[{"count":5,"href":"https:\/\/uqcodewall.com\/index.php?rest_route=\/wp\/v2\/pages\/670\/revisions"}],"predecessor-version":[{"id":2330,"href":"https:\/\/uqcodewall.com\/index.php?rest_route=\/wp\/v2\/pages\/670\/revisions\/2330"}],"wp:attachment":[{"href":"https:\/\/uqcodewall.com\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=670"}],"wp:term":[{"taxonomy":"wf_page_folders","embeddable":true,"href":"https:\/\/uqcodewall.com\/index.php?rest_route=%2Fwp%2Fv2%2Fwf_page_folders&post=670"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}![\"\"](\"https:\/\/uqcodewall.com\/wp-content\/uploads\/2021\/04\/CPUProfiling.jpg\")
<\/p>\n\n\n\n![\"\"](\"https:\/\/uqcodewall.com\/wp-content\/uploads\/2021\/04\/MemoryProfilingBigObjects.jpg\")
<\/p>\n\n\n\n![\"\"](\"https:\/\/uqcodewall.com\/wp-content\/uploads\/2021\/04\/MemoryProfilingAllocationCallTree.jpg\")
<\/p>\n\n\n\n![\"\"](\"https:\/\/uqcodewall.com\/wp-content\/uploads\/2021\/04\/MemoryHotSpotsBetweenTwoTimes-1.jpg\")
<\/p>\n\n\n\n![\"\"](\"https:\/\/uqcodewall.com\/wp-content\/uploads\/2021\/04\/JVisual-Vm.jpg\")
<\/p>\n\n\n\n![\"\"](\"https:\/\/uqcodewall.com\/wp-content\/uploads\/2021\/04\/FlightRecorder.jpg\")
<\/p>\n\n\n\n![\"\"](\"https:\/\/uqcodewall.com\/wp-content\/uploads\/2021\/04\/FlightRecorderTlabInfo.jpg\")
<\/p>\n\n\n\n![\"\"](\"https:\/\/uqcodewall.com\/wp-content\/uploads\/2021\/04\/AllocatoionCallsOutsideTlab.jpg\")
<\/p>\n\n\n\n
See below an image of GC viewer here.<\/p>\n\n\n\n![\"\"](\"https:\/\/uqcodewall.com\/wp-content\/uploads\/2021\/04\/GCViewerGCLogs.jpg\")
<\/p>\n\n\n\n![\"\"](\"https:\/\/uqcodewall.com\/wp-content\/uploads\/2021\/04\/GCViewerSummary.jpg\")
<\/p>\n\n\n\n