Hibernate cache layer 2 with Hazelcast doesn't work

[vudangngoc]

Overview of the issue

I create a new project with default configuration of Jhipster with MySQL, Hibernate and Hazelcast as cache layer 2. It seems that Hibernate cannot read from its layer 2 cache but put a lot of entities, the image bellow is screenshot of cache statistic

Could you please give me some clues to fix this issue? Thank you in advance!

JHipster configuration

JHipster Version(s)

crowdsourcing@0.0.1-SNAPSHOT /home/fatguy/git/crowdsourcing
└── generator-jhipster@6.7.1 

JHipster configuration, a .yo-rc.json file generated in the root folder

.yo-rc.json file

{
  "generator-jhipster": {
    "promptValues": {
      "packageName": "com.x.dps.cs",
      "nativeLanguage": "en"
    },
    "jhipsterVersion": "6.7.1",
    "applicationType": "monolith",
    "baseName": "crowdsourcing",
    "packageName": "com.x.dps.cs",
    "packageFolder": "com/x/dps/cs",
    "serverPort": "8080",
    "authenticationType": "jwt",
    "cacheProvider": "hazelcast",
    "enableHibernateCache": true,
    "websocket": false,
    "databaseType": "sql",
    "devDatabaseType": "h2Memory",
    "prodDatabaseType": "mysql",
    "searchEngine": "elasticsearch",
    "messageBroker": false,
    "serviceDiscoveryType": "eureka",
    "buildTool": "maven",
    "enableSwaggerCodegen": true,
    "jwtSecretKey": "bXktc2VjcmV0LXRva2VuLXRvLWNoYW5nZS1pbi1wcm9kdWN0aW9uLWFuZC10by1rZWVwLWluLWEtc2VjdXJlLXBsYWNl",
    "embeddableLaunchScript": false,
    "useSass": true,
    "clientPackageManager": "npm",
    "clientFramework": "angularX",
    "clientTheme": "none",
    "clientThemeVariant": "",
    "creationTimestamp": 1584083137628,
    "testFrameworks": [],
    "jhiPrefix": "jhi",
    "entitySuffix": "",
    "dtoSuffix": "DTO",
    "otherModules": [],
    "enableTranslation": true,
    "nativeLanguage": "en",
    "languages": ["en", "vi"],
    "blueprints": []
  }
}

JDL for the Entity configuration(s) entityName.json files generated in the .jhipster directory

JDL entity definitions

entity TaskGroup {
  taskGroupName String,
  description String
}
entity TaskType {
  title String,
  description String,
  keywords String,
  reward BigDecimal min(0),
  assignmentDurationInSeconds Integer min(0),
  autoApprovalDelayInSeconds Integer min(0)
}
entity QualificationRequirement {
  title String,
  businessRule String required
}
entity Worker {
  totalTask Integer required min(0),
  totalEarning BigDecimal,
  accepted Integer required,
  rejected Integer required,
  abadoned Integer required
}
entity RequesterDepartment {
  name String,
  description String
}
entity Requester {
  name String,
  userName String,
  hashPassword String,
  email String,
  phone String
}
entity TaskTemplate {
  name String
}
entity Task {
  creationTime ZonedDateTime,
  title String,
  description String,
  keywords String,
  status TaskStatus,
  reward BigDecimal,
  assignmentDurationInSeconds Integer min(0),
  maxAssignments Integer min(0),
  autoApprovalDelayInSeconds Integer min(0),
  expiration ZonedDateTime,
  question String,
  requesterAnnotation String,
  taskReviewStatus TaskReviewStatus,
  numberofAssignmentsPending Integer min(0),
  numberofAssignmentsAvailable Integer min(0),
  numberofAssignmentsCompleted Integer min(0),
  lifeTimeInSeconds Integer min(0)
}
entity Assignment {
  assignmentStatus AssignmentStatus,
  autoApprovalTime ZonedDateTime,
  acceptTime ZonedDateTime,
  submitTime ZonedDateTime,
  approvalTime ZonedDateTime,
  rejectionTime ZonedDateTime,
  deadline ZonedDateTime,
  answer String,
  requesterFeedback String,
  n String,
  processTime Integer,
  abadonedTime ZonedDateTime,
  reviewTime ZonedDateTime
}
entity Project {
  name String required,
  title String required,
  description String required,
  keywords String,
  rewardPerAssignment BigDecimal required min(0),
  numberAssignments Integer required min(0),
  timeAllottedPerAssignment Integer required min(0),
  taskExpiresIn Integer required min(0),
  autoApprovalIn Integer required min(0),
  remainBudget BigDecimal required,
  deadline ZonedDateTime,
  startDate ZonedDateTime required,
  expectedFinishTasks Long
}
entity Batch {
  title String required,
  description String required,
  taskExpiresIn Integer required min(0),
  autoApprovalIn Integer required min(0),
  numberTasks Integer required min(0),
  rewardPerAssignment BigDecimal,
  timeAllottedPerAssignment Integer,
  maxAssignments Integer min(0),
  status BatchStatus required,
  expireTime ZonedDateTime,
  resourcePaths String
}
entity WorkerStatistic {
  percentAcceptedTask Integer required min(0),
  percentRejectedTask Integer required min(0),
  totalTask Integer required min(0)
}
entity Template {
  genericInfo TextBlob,
  questionTemplate TextBlob,
  isGlobal Boolean required,
  description String required
}
entity ProjectTemplate {
  genericInfo TextBlob,
  questionTemplate TextBlob,
  description String required
}
entity ReportWorkerDaily {
  total_earning BigDecimal required min(0),
  submittedNumber Integer required,
  approvedNumber Integer required min(0),
  rejectedNumber Integer required,
  pendingNumber Integer required,
  date ZonedDateTime required
}
entity Report {
  typeReport TypeReport,
  assignmentId Long,
  workerId Long,
  comment String,
  reply String,
  creationTime ZonedDateTime
}
entity Chart_project_assignment_by_date {
  project_id Long,
  assignment_time ZonedDateTime,
  submit_quantity Integer,
  accept_quantity Integer
}
enum TaskStatus {
  ASSIGNABLE,
  UNASSIGNABLE,
  REVIEWABLE,
  REVIEWING,
  DISPOSED
}
enum TaskReviewStatus {
  NOTREVIEWED,
  MARKEDFORREVIEW,
  REVIEWEDAPPROPRIATE,
  REVIEWEDINAPPROPRIATE
}
enum AssignmentStatus {
  SUBMITTED,
  APPROVED,
  REJECTED
}
enum BatchStatus {
  PROCESSING,
  READY_TO_REVIEW,
  REVIEWED
}
enum TypeReport {
  POLICY_INVOLATION,
  BROKEN_CONTENT,
  OTHER
}

relationship ManyToOne {
  QualificationRequirement{requesterDepartment(name) required} to RequesterDepartment,
  Worker{user(login) required} to User,
  Requester{requesterDepartment(name) required} to RequesterDepartment,
  Requester{user(login) required} to User,
  Task{taskType(title)} to TaskType,
  Task{taskGroup(taskGroupName)} to TaskGroup,
  Task{batch(title) required} to Batch,
  Task{qualificationRequirement(title)} to QualificationRequirement,
  Assignment{worker(userName)} to Worker,
  Assignment{task(title) required} to Task,
  Project{requesterDepartment(name) required} to RequesterDepartment,
  Project{qualificationRequirement(title)} to QualificationRequirement,
  Batch{project(title) required} to Project,
  Batch{qualificationRequirement(title)} to QualificationRequirement,
  WorkerStatistic{user(login) required} to User,
  Template{requesterDepartment(name)} to RequesterDepartment,
  ProjectTemplate{template(description) required} to Template,
  ProjectTemplate{project(name) required} to Project,
  ReportWorkerDaily{user(login) required} to User
}

search TaskGroup, TaskType, QualificationRequirement, Worker, RequesterDepartment, Requester, TaskTemplate, Task, Assignment, Project, Batch, WorkerStatistic, Template, ProjectTemplate, ReportWorkerDaily, Chart_project_assignment_by_date with elasticsearch
paginate QualificationRequirement, Worker, RequesterDepartment, Requester, TaskTemplate, Task, Assignment, Project, Batch, WorkerStatistic, Template, ProjectTemplate, Report with pagination
service QualificationRequirement, Worker, Requester, TaskTemplate, Task, Assignment, Project, Batch, ReportWorkerDaily, Chart_project_assignment_by_date with serviceImpl
dto Chart_project_assignment_by_date with mapstruct

Environment and Tools

java version "11.0.6" 2020-01-14 LTS
Java(TM) SE Runtime Environment 18.9 (build 11.0.6+8-LTS)
Java HotSpot(TM) 64-Bit Server VM 18.9 (build 11.0.6+8-LTS, mixed mode)

git version 2.7.4

node: v12.16.1

npm: 6.14.4

INFO! Congratulations, JHipster execution is complete!

Entity configuration(s) entityName.json files generated in the .jhipster directory

Browsers and Operating System

• Checking this box is mandatory (this is just to show you read everything)

[vudangngoc]

Hi @pascalgrimaud ,
I create a brand new simple project with default configuration of Jhipster. It contains Hibernate, Hazelcast and H2 (for debug mode). I login as admin/admin and try to load entity Task several times, then move to Application Metrics to check cache statistic. The cache get number is NaN and the cache put number is nearly equals with the cache hit number.
Could you please take a look? Thank you in advance!
https://github.com/vudangngoc/testJhipster

[pascalgrimaud]

@vudangngoc : thanks for sharing your project. It will help for reproducing your issue. Then about me, I don't have time to have a look at your problem. I simply put labels here.
Just be patient.

[alansegar]

I'm new to JHipster so unfortunately don't have any history on what the expected behaviour is but I've done some investigation which will hopefully be useful. I can potentially investigate further if someone can clarify what the expected behaviour is.

• I've run https://github.com/vudangngoc/testJhipster locally and confirmed that I can replicate this but the screenshots show a high number of cache hits which seems to conflict somewhat with reporting that the cache does not work as to me if the cache is hit then it's working
• I've upgraded that repo locally to the latest JHipster 6.10.1 (it's on 6.8.0 currently) and confirmed the behaviour remains the same
• I've generated a new application using a different cache for comparison (Ehcache) and the behaviour is slightly different but there is some overlap

With Hazelcast I've found that CacheConfiguration.hazelcastInstance contains this line:
config.getMapConfigs().put("com.mycompany.myapp.domain.*", initializeDomainMapConfig(jHipsterProperties));

and for ehcache CacheConfiguration.cacheManagerCustomizer the equivalent line is
createCache(cm, com.mycompany.myapp.domain.Task.class.getName());

https://www.jhipster.tech/using-cache/ states

Spring Cache and the Hibernate 2nd-level cache will use the same caching solution, but do not work at the same level: we do not recommend to use both for the same objects, as this will make cache invalidation issues even more complex. Instead, we recommend you use:
• Spring Cache for higher-level or aggregate objects, like you typically have with DTOs
• The Hibernate 2nd-level cache for entities mapped to the database, in order to reduce the number of SQL requests

UPDATE - since first adding this comment I've found that the name used in CacheConfiguration is probably the same name that hibernate would use for the 2nd level cache if it were creating the cache itself based on the Entity class name so it's probably a way to customise the 2nd level cache rather than being a separate Spring Cache.

application-dev.yml has the hazelcast management-centre disabled by default and links to http://docs.hazelcast.org/docs/management-center/3.9/manual/html/Deploying_and_Starting.html which I've followed to enable it (using the same version as JHipster (3.12.7 as it's not compatible with the latest 4.x). I had to set the following VM options when starting the Spring Boot app --add-modules java.se --add-exports java.base/jdk.internal.ref=ALL-UNNAMED --add-opens java.base/java.lang=ALL-UNNAMED --add-opens java.base/java.nio=ALL-UNNAMED --add-opens java.base/sun.nio.ch=ALL-UNNAMED --add-opens java.management/sun.management=ALL-UNNAMED --add-opens jdk.management/com.sun.management.internal=ALL-UNNAMED to get it to start with management-center.enabled set to true. This gives an alternative view of the cache statistics to the JHipster application metrics UI and the cache gets is shown as a number there rather than NaN.
I also enabled hibernate SQL logging to tell when the DB was being used rather than the cache.
I'm not sure which caches the JHipster Application metrics page Cache statistics section is supposed to show but it currently seems to vary depending on whether the 2nd level cache was created manually in CacheConfiguration (is shown) or automatically by hibernate (not shown) - this may be specific to ehcache.

It may be worth splitting this into multiple issues / tasks when it's better understood:

• One for the NaN, zero and blank columns shown in the Cache statistics UI when using Hazelcast (this doesn't affect ehcache) as this may be a statistics reporting / UI issue separate to what is actually happening in the cache (more detail in later comments below)
• One for the number of cache hits (it increases when a page of entities is viewed despite SQL getting logged every time which selects all columns on the entity table, not just the id). I'm unsure whether there's actually an issue here but it would be good to document the expected behaviour at least.

This issue says

try to load entity Task several times

which based on the wording I think is viewing an individual entity e.g. this url http://localhost:9000/task/10/view rather than viewing a page of entities / Tasks http://localhost:9000/task but it would be useful to clarify this as the hibernate query cache is disabled by default in application.yml hibernate.cache.use_query_cache: false. I'm unsure on the finer detail of how hibernate uses the 2nd level and query caches (if enabled) but from brief research of https://docs.jboss.org/hibernate/orm/5.4/userguide/html_single/Hibernate_User_Guide.html#caching-query

For entity queries, the query cache does not cache the state of the actual entities. Instead, it stores the entity identifiers, and when the query result is fetched from the cache, the entity state is going to be loaded from the second-level cache entity regions.

I think the query cache would rely on the 2nd level cache rather than storing the full entity state itself which could explain why the entity cache gets populated during findAll.

The screenshot of the statistics shows numbers that are exactly multiples of 10 (the number of faker items generated by default) so I think it's important to clarify whether there is an expectation that a query cache will be available or not rather than just a hibernate 2nd level cache without a query cache.

[alansegar]

The default page size is 20 but only 10 faker entities seem to get created so there's only half a page when an application is first generated.

ehcache with CacheConfiguration line deleted:

• 2nd level cache appears to work based on SQL only being logged the first time a specific single entity is viewed (find by id)
• no cache related to entity is visible in either JMX or http://localhost:9000/admin/metrics but based on the SQL logging there appears to be a correctly functioning 2nd level cache somewhere despite it not showing statistics (possible explanation of why in later comments).
• I'm not sure that deleting this line is necessary / beneficial (more detail below)

ehcache with CacheConfiguration unchanged:

• 2nd level cache appears to work based on SQL only being logged the first time a given entity is viewed (find by id)
• Potentially the line in CacheConfiguration is actually the same cache that hibernate would have created itself had there not been one manually created (I found something in the old 2.x ehcache documentation about how hibernate names the 2nd level cache based on the entity class name) rather than a separate / conflicting cache as I originally thought.
• cache shows in JMX and http://localhost:9000/admin/metrics as com.mycompany.myapp.domain.MyEntity but the number of hits appears to include query results despite hibernate.cache.use_query_cache being set to false e.g. when viewing the first page of 10 entities hits increases by 10 each time once the cache has been populated. More detail in later comments on this, it's potentially expected behaviour.

hazelcast with CacheConfiguration unchanged:

• 2nd level cache appears to work based on SQL only being logged the first time a given entity is viewed (find by id)
• query caching is disabled in the configuration by default so when viewing a page of entities (rather than a single entity), the cache is not used (despite the statistics page indicating otherwise)
• Cache statistics in /admin/metrics includes entity page query results as hits which seems odd as it goes to the DB every time to get query results based on the SQL logging and hibernate.cache.use_query_cache being set to false
• Cache statistics in /admin/metrics “Cache Misses”, “Cache Removals”, "Cache Evictions" columns are blank (not sure if this is expected)
• Cache statistics in /admin/metrics “Cache Gets” column in NaN (seems wrong)
• Cache statistics in /admin/metrics “Cache Hit %” and “Cache Miss %” are always zero despite there having been some puts, hits and misses.

[alansegar]

I've added the following code into TaskResource.getAllTasks and used a debugger to see exactly what is inside the cache and it turns out that despite the query cache being turned OFF, all 10 Tasks on the first page are put in the cache when viewing the page of results. Despite this the SQL is run every time to get the results even though they are already in the cache. Based on query cache being turned off I wasn't expecting them to get cached and I've not yet figured out what causes them to get cached when viewing a page of entities.

IMap<Object, Object> taskCache = Hazelcast.getHazelcastInstanceByName("testJ").getMap("com.mycompany.myapp.domain.Task");
log.debug("Hazelcast Task cache size {}", taskCache.size());

The SQL run each time is org.hibernate.SQL : select task0_.id as id1_5_, task0_.date as date2_5_, task0_.description as descript3_5_, task0_.name as name4_5_ from task task0_ order by task0_.id asc limit ?

Is this the expected behaviour of JHipster to cache the entities for all results when doing a findAll despite not using the cache and running SQL for future findAll operations?
The cache entries created by the findAll ARE used when viewing an individual entity from the page so there can be some benefit but I'm unsure whether it's expected behaviour and am also curious to find out what is causing the cache to get populated during the findAll.

[alansegar]

https://github.com/jhipster/jhipster/blob/master/jhipster-framework/src/main/java/io/github/jhipster/config/metric/JHipsterMetricsEndpoint.java#L182 doesn't put cache.gets.miss in resultsCache when using Hazelcast which means that https://github.com/jhipster/ng-jhipster/blob/master/src/component/metrics/jhi-metrics-cache.component.ts#L45 which relies on cache.gets.miss being present outputs NaN for {{ entry.value['cache.gets.hit'] + entry.value['cache.gets.miss'] }}.
The hit and miss columns seem to use filterNaN to avoid a similar issue but they then report zero rather than NaN which is still incorrect.
Maybe the UI could report Not Available or N/A if no data is available so it's more obvious that some columns will never get populated for certain cache types.

When using Hazelcast, JHipsterMetricsEndpoint has cache.partition.gets available which could potentially be used to populate the Cache Gets column but that would require a change to the UI logic which would potentially be Hazelcast specific.
An alternative may be to derive the cache.gets.miss value from the 3 values which are available (cache.partition.gets, cache.gets.hit and cache.puts) but I'm not sure if there's a reliable way to do that.
I've also noticed that the Hazelcast Management Center also doesn't show misses and hazelcast/hazelcast#3009 (open issue / enhancement request) describes LocalMapStats.getMisses() having been inadvertently removed between Hazelcast 2.x and 3.x.

Comparison of statistics available in JHipsterMetricsEndpoint for ehcache and Hazelcast:
Hazelcast:
cache.gets.hit
cache.partition.gets
cache.puts

ehcache, caffeine:
cache.gets.hit
cache.gets.miss
cache.puts
cache.removals
cache.evictions

I found these useful when investigating:
https://docs.spring.io/spring-boot/docs/current/reference/htmlsingle/#production-ready-metrics-cache (may explain why there are no statistics when a cache is auto-generated after startup)
http://localhost:8080/management/prometheus (search for cache_)

[vudangngoc]

to avoid this issue, I have to rewrite persistence layer, migrate to Ignite and sql2o

[alansegar]

@vudangngoc are you able to provide more clarification on exactly what the issue is from your perspective?

• is the 2nd level cache actually not working / not being used? If so, can you provide more detail on how you are sure that is the case as from the research I've done I can't find any evidence that the 2nd level cache isn't populated and used.
• Are you talking about only the 2nd level cache here or are you also wanting to use the hibernate query cache (which is turned off currently in your repo)?
• do you think that this is more than just a cache statistics reporting issue?

[vudangngoc]

@alansegar

• The 2nd level cache doesn't work, I tried to debug and see that Hibernate always puts items to cache and the performance is very poor. When I disable caching, the performance increase, processing time reduce to a half.
• We don't use query cache
• IMHO, there are more issues in Hibernate, for example, 1st level cache some time doesn't working too cause us several business issues.

[alansegar]

@vudangngoc Thanks for the additional information.

• For "The 2nd level cache doesn't work", I'm still not sure what the expected behaviour is from your perspective. You've confirmed that the cache is being populated (and I've confirmed that it's also read from by Hibernate rather than running SQL when viewing a single entity). To me that implies the cache is working i.e. it's saving a trip to the database when a given entity is already in the cache. Is it the poor performance (slow processing time) for your specific application that is the main / only issue?
• When you say "Hibernate always puts items to cache", can you explain what you think it should do instead. Is it that it's putting all entities from a page of search results into the cache but you would expect it to only populate the cache when viewing a single entity (not when viewing a page of results)? If so, can you point me to the Hibernate documentation which makes you think it should behave differently. If it's something else, please provide more detail on what it is.
• On the performance increase when disabling the cache, have you been able to identify the root cause of this? For example can you see excessive garbage collection / high memory usage when the cache is enabled?
• Have you looked at different concurrency strategies e.g. READ_ONLY if the data is static reference data https://www.baeldung.com/hibernate-second-level-cache#cacheConcurrencyStrategy
• If the cache is growing larger than you want / have resources for, have you looked into configuring it differently? e.g. https://www.baeldung.com/hibernate-second-level-cache#Management

"If expiration and eviction policies are not defined, the cache could grow indefinitely and eventually consume all of available memory"

https://www.jhipster.tech/using-cache/ explains how to change the configuration to limit the size of the cache time-to-live-seconds and max-entries for ehcache. For Hazelcast I can't see the max-entries option via JHipster config but you can set time-to-live-seconds that way and https://docs.cloud.hazelcast.com/docs/map-configurations#max-size or https://docs.hazelcast.org/docs/3.12.7/manual/html-single/index.html#map-eviction may guide you to how to limit the max size.
If you look in the JHipster generated CacheConfiguration.initializeDefaultMapConfig method, you'll see the following when using Hazelcast which is setting a max size of zero / infinite:

        /*
        Valid values are:
        NONE (no eviction),
        LRU (Least Recently Used),
        LFU (Least Frequently Used).
        NONE is the default.
        */
        mapConfig.setEvictionPolicy(EvictionPolicy.LRU);

        /*
        Maximum size of the map. When max size is reached,
        map is evicted based on the policy defined.
        Any integer between 0 and Integer.MAX_VALUE. 0 means
        Integer.MAX_VALUE. Default is 0.
        */
        mapConfig.setMaxSizeConfig(new MaxSizeConfig(0, MaxSizeConfig.MaxSizePolicy.USED_HEAP_SIZE));

• How many members do you have in your Hazelcast cluster? Do you definitely need Hazelcast / a distributed cache? The Hazelcast documentation I've linked to above explains the max size options for a distributed cache but if you don't need a distributed cache it may be quicker / easier for you to use a simpler cache e.g. ehcache / caffeine where you can simply specify a max number of items that you want in the cache via the JHipster config. There's a way to do this in Hazelcast but it's per node so if you've got multiple nodes in the cluster the total per node isn't the same as the total number of items in the cache. Also, it's not currently exposed via JHipster config so you'd need to edit CacheConfiguration.

• Are any of the issues you are reporting specific to JHipster or do you think they would happen when using Hibernate even without JHipster? If they are not specific to JHipster it may be better to raise them against Hibernate / Hazelcast directly if you're sure they are bugs and can provide enough detail for someone to be able to replicate them and understand what the expected and actual behaviours are.
  If you're not sure they are bugs and think they could be resolved by using different configuration it may be more appropriate to ask questions on stackoverflow.com / similar.

[vudangngoc]

@alansegar Thank you for your very detail information

• When I said "2nd level cache doesn't work", it means that Hibernate always connect to data base (MySQL) to fetch the data. The expected behavior should be "Hibernate fetch the data then put to Hazelcast, the next reading should fetch data from Hazelcast". When I tried to debug, I see the first part is done, Hibernate always put items to Hazelcast with every reading operation. But putting items to Hazelcast is a costly operation, I guest because of indexing mechanism of Hazelcast. The consequently, performance of our service decrease, processing time for each request is double.
• Maybe I'm misunderstanding and all current behaviors of Hibernate and Hazelcast are normal according to their documents. I'm just looking for a distributed cache solution can work well with a SQL to object mapping, what can be provided by jhipster with few configuration. But I see some issues and the performance isn't good. Our project has to move on and I don't have effort to dig deeper, so that I rewrite the persistence layer with Ignite and sql2o.

[mraible]

It's been a month since this issue had any activity. I'm closing it. Please create a PR and re-open it if you have a solution.