Collectives™ on Stack Overflow
Find centralized, trusted content and collaborate around the technologies you use most.
Learn more about Collectives
Teams
Q&A for work
Connect and share knowledge within a single location that is structured and easy to search.
Learn more about Teams
Ask Question
The Spring Boot application uses
camunda-bpm-spring-boot-starter-rest
that supplies the Hibernate/Entity Manager to the application. In order to set up the Spring Boot Actuator Prometheus (Actuator) Metrics, we have added this line to our
application.properties
:
spring.jpa.properties.hibernate.generate_statistics=true
After that the following details started to be output to the stdout:
2020-11-16 16:14:49.923 INFO 1345328 --- [ingJobExecutor]] i.StatisticalLoggingSessionEventListener : Session Metrics {
547400 nanoseconds spent acquiring 1 JDBC connections;
0 nanoseconds spent releasing 0 JDBC connections;
0 nanoseconds spent preparing 0 JDBC statements;
0 nanoseconds spent executing 0 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
0 nanoseconds spent performing 0 L2C puts;
0 nanoseconds spent performing 0 L2C hits;
0 nanoseconds spent performing 0 L2C misses;
0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
None ot them contains statistics for something except acquiring the JDBC connection being non-zero, while the JDBC statements are actually prepared and executed. So what are the events that trigger this kind of logs, while never actually writing the couns of the jdbc statements that were executed?
In the Spring Boot apps that are configured correctly, that stuff is logged according to the expectation, like:
17:18:59.313 [http-nio-8080-exec-3] INFO o.h.e.i.StatisticalLoggingSessionEventListener - Session Metrics {
1063300 nanoseconds spent acquiring 1 JDBC connections;
0 nanoseconds spent releasing 0 JDBC connections;
117600 nanoseconds spent preparing 1 JDBC statements;
739400 nanoseconds spent executing 1 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
0 nanoseconds spent performing 0 L2C puts;
0 nanoseconds spent performing 0 L2C hits;
0 nanoseconds spent performing 0 L2C misses;
1182400 nanoseconds spent executing 1 flushes (flushing a total of 14 entities and 0 collections);
5700 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
As for the metrics, output to the /actuator/prometheus, it also looks missing some details, while not empty at all, with some contradictory output:
# HELP hibernate_transactions_total The number of transactions we know to have been successful
# TYPE hibernate_transactions_total counter
hibernate_transactions_total{entityManagerFactory="entityManagerFactory",result="success",} 2231.0
hibernate_transactions_total{entityManagerFactory="entityManagerFactory",result="failure",} 1.0
# HELP hibernate_collections_recreates_total The number of collections recreated
# TYPE hibernate_collections_recreates_total counter
hibernate_collections_recreates_total{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_cache_natural_id_puts_total The number of cacheable naturalId lookups put in cache
# TYPE hibernate_cache_natural_id_puts_total counter
hibernate_cache_natural_id_puts_total{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_cache_update_timestamps_requests_total The number of timestamps successfully retrieved from cache
# TYPE hibernate_cache_update_timestamps_requests_total counter
hibernate_cache_update_timestamps_requests_total{entityManagerFactory="entityManagerFactory",result="miss",} 0.0
hibernate_cache_update_timestamps_requests_total{entityManagerFactory="entityManagerFactory",result="hit",} 0.0
# HELP hibernate_sessions_open_total Sessions opened
# TYPE hibernate_sessions_open_total counter
hibernate_sessions_open_total{entityManagerFactory="entityManagerFactory",} 2232.0
# HELP hibernate_entities_inserts_total The number of entity inserts
# TYPE hibernate_entities_inserts_total counter
hibernate_entities_inserts_total{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_cache_update_timestamps_puts_total The number of timestamps put in cache
# TYPE hibernate_cache_update_timestamps_puts_total counter
hibernate_cache_update_timestamps_puts_total{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_cache_query_puts_total The number of cacheable queries put in cache
# TYPE hibernate_cache_query_puts_total counter
hibernate_cache_query_puts_total{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_statements_total The number of prepared statements that were acquired
# TYPE hibernate_statements_total counter
hibernate_statements_total{entityManagerFactory="entityManagerFactory",status="closed",} 0.0
hibernate_statements_total{entityManagerFactory="entityManagerFactory",status="prepared",} 0.0
# HELP hibernate_second_level_cache_puts_total The number of cacheable entities/collections put in the cache
# TYPE hibernate_second_level_cache_puts_total counter
hibernate_second_level_cache_puts_total{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_second_level_cache_requests_total The number of cacheable entities/collections successfully retrieved from the cache
# TYPE hibernate_second_level_cache_requests_total counter
hibernate_second_level_cache_requests_total{entityManagerFactory="entityManagerFactory",result="miss",} 0.0
hibernate_second_level_cache_requests_total{entityManagerFactory="entityManagerFactory",result="hit",} 0.0
# HELP hibernate_entities_loads_total The number of entity loads
# TYPE hibernate_entities_loads_total counter
hibernate_entities_loads_total{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_entities_deletes_total The number of entity deletes
# TYPE hibernate_entities_deletes_total counter
hibernate_entities_deletes_total{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_query_natural_id_executions_max_seconds The maximum query time for naturalId queries executed against the database
# TYPE hibernate_query_natural_id_executions_max_seconds gauge
hibernate_query_natural_id_executions_max_seconds{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_cache_natural_id_requests_total The number of cached naturalId lookups successfully retrieved from cache
# TYPE hibernate_cache_natural_id_requests_total counter
hibernate_cache_natural_id_requests_total{entityManagerFactory="entityManagerFactory",result="miss",} 0.0
hibernate_cache_natural_id_requests_total{entityManagerFactory="entityManagerFactory",result="hit",} 0.0
# HELP hibernate_sessions_closed_total Sessions closed
# TYPE hibernate_sessions_closed_total counter
hibernate_sessions_closed_total{entityManagerFactory="entityManagerFactory",} 2232.0
# HELP hibernate_flushes_total The global number of flushes executed by sessions (either implicit or explicit)
# TYPE hibernate_flushes_total counter
hibernate_flushes_total{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_query_executions_total The number of executed queries
# TYPE hibernate_query_executions_total counter
hibernate_query_executions_total{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_collections_fetches_total The number of collection fetches
# TYPE hibernate_collections_fetches_total counter
hibernate_collections_fetches_total{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_optimistic_failures_total The number of StaleObjectStateExceptions that have occurred
# TYPE hibernate_optimistic_failures_total counter
hibernate_optimistic_failures_total{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_entities_fetches_total The number of entity fetches
# TYPE hibernate_entities_fetches_total counter
hibernate_entities_fetches_total{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_cache_query_requests_total The number of cached queries successfully retrieved from cache
# TYPE hibernate_cache_query_requests_total counter
hibernate_cache_query_requests_total{entityManagerFactory="entityManagerFactory",result="miss",} 0.0
hibernate_cache_query_requests_total{entityManagerFactory="entityManagerFactory",result="hit",} 0.0
# HELP hibernate_collections_deletes_total The number of collection deletes
# TYPE hibernate_collections_deletes_total counter
hibernate_collections_deletes_total{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_query_executions_max_seconds The time of the slowest query
# TYPE hibernate_query_executions_max_seconds gauge
hibernate_query_executions_max_seconds{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_connections_obtained_total Get the global number of connections asked by the sessions (the actual number of connections used may be much smaller depending whether you use a connection pool or not)
# TYPE hibernate_connections_obtained_total counter
hibernate_connections_obtained_total{entityManagerFactory="entityManagerFactory",} 2232.0
# HELP hibernate_entities_updates_total The number of entity updates
# TYPE hibernate_entities_updates_total counter
hibernate_entities_updates_total{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_collections_loads_total The number of collection loads
# TYPE hibernate_collections_loads_total counter
hibernate_collections_loads_total{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_collections_updates_total The number of collection updates
# TYPE hibernate_collections_updates_total counter
hibernate_collections_updates_total{entityManagerFactory="entityManagerFactory",} 0.0
# HELP hibernate_query_natural_id_executions_total The number of naturalId queries executed against the database
# TYPE hibernate_query_natural_id_executions_total counter
hibernate_query_natural_id_executions_total{entityManagerFactory="entityManagerFactory",} 0.0
so, only the sessions counter is realistic one, while others are missing
hibernate_query_executions_max_seconds{entityManagerFactory="entityManagerFactory",} 0.0
looks inconsistent here, if there were so much transactions, so how the slowest one could be 0-long?
So, that is all propably like because of EntityManager initialization withing the bpm-camunda-starter, not the our application beans itself? And how to work it around and to have those merics being correctly picked up? May be the metrics collector could be injected there somehow?
I have tried to check what I do have in EntitymanagerFactory and try to update it with new values. According to the docs it requires hibernate.metrics to be true.
package com.example.demo;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Component;
import javax.annotation.PostConstruct;
import javax.persistence.EntityManagerFactory;
import java.util.logging.Logger;
@Component
public class HibernatePropertiesInterceptor {
private static final Logger LOG
= Logger.getLogger(HibernatePropertiesInterceptor.class.getName());
@Autowired
private EntityManagerFactory entityManagerFactory;
@PostConstruct
public void init() {
LOG.info("Changing hibernate metrics-related properties");
LOG.info("Current hibernate properties are "+entityManagerFactory.getProperties().keySet());
LOG.info("Current hibernate.generate_statistics value is "+entityManagerFactory.getProperties().get("hibernate.generate_statistics"));
entityManagerFactory.getProperties().put("hibernate.generate_statistics","true");
LOG.info("Updated hibernate properties are "+entityManagerFactory.getProperties().keySet());
LOG.info("Updated hibernate.generate_statistics value is "+entityManagerFactory.getProperties().get("hibernate.generate_statistics"));
And it has turned out, that hibernate.metrics is already true! So, I have no idea what to check and how to instrument it to show the true stats. It looks like the EntityManager really do all what is expected, so may that's all because camunda don't use that entity manager for the most stuff? Or what?
I also think it is because EntityManager is not bean that is managed by spring context. Can you try creating configuration class with a bean of EntityManager like other beans are created in SpringProcessEngineServiceConfiguration by getting it from ProcessEngine?
like below:
@Bean
public EntityManagerFactory getEntityManagerFactory(ProcessEngineConfiguration engineConfiguration) {
return engineConfiugration.getSessionFactories().get(EntityManagerSession.class);
P.S this is just trial and error I have not tried it but atleast it should give you bean of EntityManager. Refer initJpa() method of ProcessEngineConfigurationImpl.java class.
–
–
–
Thanks for contributing an answer to Stack Overflow!
- Please be sure to answer the question. Provide details and share your research!
But avoid …
- Asking for help, clarification, or responding to other answers.
- Making statements based on opinion; back them up with references or personal experience.
To learn more, see our tips on writing great answers.
