Joularjx does not profile other Java methods other main() method in Spring Boot application

[pangteckchun]

Hi, great work on Joularjx - an important piece in Green Software hence we are keen to make full use of it.

We are profiling the sample Pet Clinic Spring Boot app and noticed only the main() method gets profiled but other app specific methods are not. This happens even though we have specified the top most package name for the pet clinic app.

1. Please see the config.properties used.
2. And we built the PetClinic jar based on instructions found on https://github.com/spring-projects/spring-petclinic.
   -- Are you able to provide me a location to upload the jar? it is 52MB and does not pass the Github upload restrictions of 25MB.
3. This is all done on my local Windows laptop running Windows 10 Enterprise, 12th Gen Intel Core i7.

In the meantime we will profile a non spring boot app to see and another internal spring boot app to compare.

This issue might be related to this same issue reported: #64

Thank you!
TC

[pangteckchun]

config.properties

# Copyright (c) 2021-2024, Adel Noureddine, Université de Pau et des Pays de l'Adour.
# All rights reserved. This program and the accompanying materials
# are made available under the terms of the
# GNU General Public License v3.0 only (GPL-3.0-only)
# which accompanies this distribution, and is available at
# https://www.gnu.org/licenses/gpl-3.0.en.html
#
# Author : Adel Noureddine

# Get also power and energy for methods starting with this package.class.method name
filter-method-names=org.springframework.samples

# Write runtime methods power consumption in a CSV file
# Setting this option to false won't generate any runtime files
# Allowed values: true, false
save-runtime-data=true

# Overwrite runtime power data file
# Setting it to false will write files for every monitoring cycle (1 sec per cycle)
# Allowed values: true, false
# was true
overwrite-runtime-data=false

# Logging level
# Set to OFF to disable it
# Allowed values: OFF, INFO, WARNING, SEVERE
logger-level=INFO

# Track power consumption evolution of methods
# Setting this option to true will generate one CSV file per monitored method
# Each CSV file will contain the power consumption on every monitored timestamp
# Allowed values: true, fase
track-consumption-evolution=true

# If track-consumption-evolution is set to true, the CSV files will be stored at the given path
# On Windows, please escape slashes twice
evolution-data-path=evolution

# If enabled (true), the consumption of the methods related to any of the agent threads will not be reported.
# Allowed values: true , false
hide-agent-consumption=true

# If set to true, a CSV file will be generated at agent's end, containing the total energy consumption of each call tree.
# Allowed values: true, false
enable-call-trees-consumption=true

# Write runtime call trees power consumption in a CSV file.
# By default, a new CSV file will be generated for each monitoring cycle.
# Setting this option to false won't generate any runtime files
# Allowed values: true, false
save-call-trees-runtime-data=true

# Overwrite runtime call trees power data file. If set to true, only one runtime file will be generated, and it will be overwritten for each monitoring cycle.
# Setting it to false will generate new files for every monitoring cycle (1 sec per cycle). The said files ill include timestamps in their name.
# Allowed values: true, false
# was true
overwrite-call-trees-runtime-data=false

# The sample rate (milliseconds) for the agent to monitor the JVM call
# stack. Lower means more accurate monitoring. Allowable values are
# from 1 to 1000.
stack-monitoring-sample-rate=10

# Path for our power monitor program on Windows
# On Windows, please escape slashes twice
powermonitor-path=D:\\code\\green.software\\joularjx\\PowerMonitor.exe

[pangteckchun]

joularjx-result for PetClinic Spring Boot app - see zip.

Observations for PetClinic:

1. Only main() method is profiled for our PetClinic app.
2. Same for runtime as well as for total for the filtered methods CSVs.
3. The profiling only seemed to happen on app start up time and after which the runtime does not profile or write runtime CSVs anymore, even when we navigate and perform actions on the PetClinic webfront, such as adding a owner, adding a pet or adding a visit for a pet.
   -- This would be a concern as an app/service is expected to run for prolonged periods without shutting down and we would like to profile its methods consumption while the app is in operation.
   -- Please refer to folder: joularjx-result\42204-1709885214480\app\runtime\methods and we have multiple CSVs on the same timestamp (written during app start up). But no other CSVs are written again during interactions with app. Is this expected?

Observations for other JVM methods:

1. During runtime, under all-methods / runtime / methods we noticed the power consumptions have the same values across the different JVM methods. Is this expected? (reference joularJX-42204-1709885257121-all-methods-power.csv).
2. After shutting down the Spring Boot app, the all-methods / total / methods appear to have dynamic profiled values which seemed more 'real'. FYI.

42204-1709885214480.zip

[adelnoureddine]

Thanks for reporting this issue, which needs te be analyzed further to get what's going on and why JoularJX is failing to provide energy data after the initial start.

In the mean time, did you check the proposed tweak in my first comment in issue #64 (putting while true instead of destroyvm)?

[adelnoureddine]

I managed to replicate the issue (no need to send me a jar, I compiled the one from petclinic's git).

If you change destroyvm() with true as in the commit 1dd0a64 (and recompile JoularJX), you should be able to get the energy consumption of other functions than main.

[adelnoureddine]

You could try the proposed fix in branch fixForApplicationServers, just download and recompile with Maven JoularJX in that branch.
I added a compiled binary here: joularjx-2.8.2.zip

There is a new config property for application servers which you need to set to true: application-server=true (by default it is false).

[pangteckchun]

Hi, thank you for the prompt responses. We appreciate this!!!
I downloaded the binary and changed application-server=true in config.properties.

In summary:

1. Runtime CSV is now 0 bytes and no lines are written to it 👎 (so this still a key issue).
2. Upon app shutdown, app / total is written with a CSV containing methods of the Petclinic application energy profiles (hurray! 👍) - but there are inconsistencies.
3. We did the same interactions on the webfront in all cases of testing: Add owner, add a pet, add a visit, browse vets, brown owner.

---

overwrite-runtime-data=false

• The app / runtime folder contains CSVs (32 CSVs written per minute) while the app is still running; this seemed to have corrected the issue of only profiling at start up time; but all the files are 0 bytes and empty.
  

• After app shutdown, the app / total / .csv contains methods called when interacting with PetClinic which looks legit! :-)
  

---

overwrite-runtime-data=true

• The app / runtime folder contains 1 CSV (as expected) but as highlighted, it is 0 bytes and empty. The date/time stamp of the CSV gets updated upon modifications during the interactions 👍

• If it helps, we observe a momentary 1kb --> 0kb change of the CSV upon new file writes.
  

• After app shutdown, however, the app / total / .csv contains MUCH LESS methods calls, compare to setting overwrite-runtime-data=false.
  

---

Hope the above helps in narrowing the issue further!

[adelnoureddine]

Thanks for the detailed update and investigation. I'll try to debug the issue but some of the numbers are expected due to the limitation of JoularJX:

• We check the stacktrace of each thread every 10ms, so methods running shorter or that happen to end before the next observation (or start just after) will not be noticed. Therefore, they will not be allocated energy consumption by our statistical approach.

The petclinic app has many of these small methods, which explains why you have fewer methods in the second run than the first. All the smaller energy methods (0.x) are usually observed once or twice, and might have missed the observation.

[pangteckchun]

Thank you @adelnoureddine!
Noted on the context that some methods may run shorter than 10ms. Useful knowledge.

Looking forward to your further inputs.
If there is any more scenarios you would like us to test, we would be happy to do so.