Le vendredi 06 novembre 2020 à 11:22 -0800, Evgenii Zhuravlev a écrit :
> Hi,
> How many nodes do you have? Can you check the same scenario with one
> node only? How do you run queries? Is client on the same machine as a
> server node?
>
Hello.
I have 2 nodes, running on differents VMs on the same host.
The cache is partitionned on clientId field, which is the same for all
entries in the cache, so all entries must be colocated.
With only one node up, I get the same results.
> I would recommend enabling DEBUG logs
> for org.apache.ignite.cache.hibernate package. DEBUG logs can show
> all get and put operations for hibernate cache.
>
With DEBUG, I have hundreds of puts for Event objects (which I
retrieve)
DEBUG [2020-11-09 09:59:34,496]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Get
[cache=fr.data.wa.db.hb.User, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.User, tenantId=null], val=null]
DEBUG [2020-11-09 09:59:34,507]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.User, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.User, tenantId=null], val=CacheEntry(fr.data.wa.db.h
b.User)]
DEBUG [2020-11-09 09:59:34,508]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Client, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Client, tenantId=null], val=CacheEntry(fr.data.wa.
db.hb.Client)]
DEBUG [2020-11-09 09:59:34,509]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Token, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Token, tenantId=null], val=CacheEntry(fr.data.wa.db
.hb.Token)]
DEBUG [2020-11-09 09:59:34,518]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Role, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Role, tenantId=null], val=CacheEntry(fr.data.wa.db.h
b.Role)]
DEBUG [2020-11-09 09:59:34,519]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Role, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Role, tenantId=null], val=CacheEntry(fr.data.wa.db.h
b.Role)]
INFO [2020-11-09 09:59:34,521]
org.hibernate.engine.internal.StatisticalLoggingSessionEventListener: Session
Metrics {
51258 nanoseconds spent acquiring 1 JDBC connections;
32665 nanoseconds spent releasing 1 JDBC connections;
183511 nanoseconds spent preparing 3 JDBC statements;
8031879 nanoseconds spent executing 3 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
7180813 nanoseconds spent performing 5 L2C puts;
0 nanoseconds spent performing 0 L2C hits;
1474335 nanoseconds spent performing 1 L2C misses;
621965 nanoseconds spent executing 1 flushes (flushing a total of 5
entities and 9 collections);
4300 nanoseconds spent executing 1 partial-flushes (flushing a total of 0
entities and 0 collections)
}
DEBUG [2020-11-09 09:59:35,106]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Get
[cache=fr.data.wa.db.hb.Client, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Client, tenantId=null],
val=CacheEntry(fr.data.wa.db.hb.Client)]
DEBUG [2020-11-09 09:59:35,107]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Event, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Event, tenantId=null],
val=CacheEntry(fr.data.wa.db.hb.Event)]
[...]
DEBUG [2020-11-09 10:00:06,363]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Event, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Event, tenantId=null],
val=CacheEntry(fr.data.wa.db.hb.Event)]
DEBUG [2020-11-09 10:00:06,363]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Event, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Event, tenantId=null],
val=CacheEntry(fr.data.wa.db.hb.Event)]
DEBUG [2020-11-09 10:00:06,363]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Event, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Event, tenantId=null],
val=CacheEntry(fr.data.wa.db.hb.Event)]
DEBUG [2020-11-09 10:00:06,363]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Event, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Event, tenantId=null],
val=CacheEntry(fr.data.wa.db.hb.Event)]
DEBUG [2020-11-09 10:00:06,364]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Event, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Event, tenantId=null],
val=CacheEntry(fr.data.wa.db.hb.Event)]
DEBUG [2020-11-09 10:00:06,364]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Event, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Event, tenantId=null],
val=CacheEntry(fr.data.wa.db.hb.Event)]
DEBUG [2020-11-09 10:00:06,364]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Event, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Event, tenantId=null],
val=CacheEntry(fr.data.wa.db.hb.Event)]
DEBUG [2020-11-09 10:00:06,365]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Event, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Event, tenantId=null],
val=CacheEntry(fr.data.wa.db.hb.Event)]
DEBUG [2020-11-09 10:00:06,365]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Event, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Event, tenantId=null],
val=CacheEntry(fr.data.wa.db.hb.Event)]
DEBUG [2020-11-09 10:00:06,365]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Event, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Event, tenantId=null],
val=CacheEntry(fr.data.wa.db.hb.Event)]
DEBUG [2020-11-09 10:00:06,366]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Event, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Event, tenantId=null],
val=CacheEntry(fr.data.wa.db.hb.Event)]
DEBUG [2020-11-09 10:00:06,366]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Event, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Event, tenantId=null],
val=CacheEntry(fr.data.wa.db.hb.Event)]
DEBUG [2020-11-09 10:00:06,366]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Event, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Event, tenantId=null],
val=CacheEntry(fr.data.wa.db.hb.Event)]
DEBUG [2020-11-09 10:00:06,366]
org.apache.ignite.cache.hibernate.HibernateTransactionalAccessStrategy: Put
[cache=fr.data.wa.db.hb.Event, key=HibernateKeyWrapper
[entry=fr.data.wa.db.hb.Event, tenantId=null],
val=CacheEntry(fr.data.wa.db.hb.Event)]
DEBUG [2020-11-09 10:00:06,389] fr.data.wa.resources.TestResource: got
element#65536
INFO [2020-11-09 10:00:06,465]
org.hibernate.engine.internal.StatisticalLoggingSessionEventListener: Session
Metrics {
24135 nanoseconds spent acquiring 1 JDBC connections;
26856 nanoseconds spent releasing 1 JDBC connections;
44297 nanoseconds spent preparing 1 JDBC statements;
112090383 nanoseconds spent executing 1 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
30735991895 nanoseconds spent performing 100000 L2C puts;
1426335 nanoseconds spent performing 1 L2C hits;
0 nanoseconds spent performing 0 L2C misses;
69531442 nanoseconds spent executing 1 flushes (flushing a total of 100001
entities and 2 collections);
3555 nanoseconds spent executing 1 partial-flushes (flushing a total of 0
entities and 0 collections)
}
The first session is Authentification, which misses the User, and the
second one te Event's get ... This is the second time I called the same
function on this server since it starts.
Regards,
чт, 5 нояб. 2020 г. в 01:59, Bastien Durel <[email protected]>:
> Hello,
>
> I'm using an ignite cluster to back an hibernate-based application.
> I
> configured L2-cache as explained in
>
> https://ignite.apache.org/docs/latest/extensions-and-integrations/hibernate-l2-cache
>
> (config below)
>
> I've ran a test reading a 1M-elements cache with a consumer
> counting
> elements. It's very slow : more than 5 minutes to run.
>
> Session metrics says it was the LC2 puts that takes most time (5
> minutes and 3 seconds of a 5:12" operation)
>
> INFO [2020-11-05 09:51:15,694]
> org.hibernate.engine.internal.StatisticalLoggingSessionEventListene
> r: Session Metrics {
> 33350 nanoseconds spent acquiring 1 JDBC connections;
> 25370 nanoseconds spent releasing 1 JDBC connections;
> 571572 nanoseconds spent preparing 1 JDBC statements;
> 1153110307 nanoseconds spent executing 1 JDBC statements;
> 0 nanoseconds spent executing 0 JDBC batches;
> 303191158712 nanoseconds spent performing 1000000 L2C puts;
> 23593547 nanoseconds spent performing 1 L2C hits;
> 0 nanoseconds spent performing 0 L2C misses;
> 370656057 nanoseconds spent executing 1 flushes (flushing a
> total of 1000001 entities and 2 collections);
> 4684 nanoseconds spent executing 1 partial-flushes (flushing a
> total of 0 entities and 0 collections)
> }
>
> It seems long, event for 1M puts, but ok, let's say the L2C is
> initialized now, and it will be better next time ? So I ran the
> query
> again, but it took 5+ minutes again ...
>
> INFO [2020-11-05 09:58:02,538]
> org.hibernate.engine.internal.StatisticalLoggingSessionEventListene
> r: Session Metrics {
> 28982 nanoseconds spent acquiring 1 JDBC connections;
> 25974 nanoseconds spent releasing 1 JDBC connections;
> 52468 nanoseconds spent preparing 1 JDBC statements;
> 1145821128 nanoseconds spent executing 1 JDBC statements;
> 0 nanoseconds spent executing 0 JDBC batches;
> 303763054228 nanoseconds spent performing 1000000 L2C puts;
> 1096985 nanoseconds spent performing 1 L2C hits;
> 0 nanoseconds spent performing 0 L2C misses;
> 317558122 nanoseconds spent executing 1 flushes (flushing a
> total of 1000001 entities and 2 collections);
> 5500 nanoseconds spent executing 1 partial-flushes (flushing a
> total of 0 entities and 0 collections)
> }
>
> Why does the L2 cache had to be filled again ? Isn't his purpose
> was to
> share it between Sessions ?
>
> Actually, disabling it make the test runs in less that 6 seconds.
>
> Why is L2C working that way ?
>
> Regards,
>
>
> ******
>
> I'm running 2.9.0 from Debian package
>
> Hibernate properties :
> hibernate.cache.use_second_level_cache: true
> hibernate.generate_statistics: true
> hibernate.cache.region.factory_class:
> org.apache.ignite.cache.hibernate.HibernateRegionFactory
> org.apache.ignite.hibernate.ignite_instance_name: ClusterWA
> org.apache.ignite.hibernate.default_access_type: READ_ONLY
>
> Method code:
> @GET
> @Timed
> @UnitOfWork
> @Path("/events/speed")
> public Response getAllEvents(@Auth AuthenticatedUser auth)
> {
> AtomicLong id = new AtomicLong();
> StopWatch watch = new StopWatch();
> watch.start();
> evtDao.findAll().forEach(new Consumer<Event>() {
>
> @Override
> public void accept(Event t) {
> long cur = id.incrementAndGet();
> if (cur % 65536 == 0)
> logger.debug("got
> element#{}", cur);
> }
> });
> watch.stop();
> return Response.ok().header("X-Count",
> Long.toString(id.longValue())).entity(new Time(watch)).build();
> }
>
> Event cache config:
>
>
> <bean
>
> class="org.apache.ignite.configuration.CacheConfiguration">
> <property name="name"
> value="EventCache" />
> <property name="cacheMode"
> value="PARTITIONED" />
> <property
> name="atomicityMode" value="TRANSACTIONAL" />
> <property name="backups"
> value="1" />
> <property
> name="readFromBackup" value="true" />
> <property name="copyOnRead"
> value="true" />
> <property
> name="dataRegionName" value="Disk" />
>
> <property
> name="keyConfiguration">
> <list>
> <bean
> class="org.apache.ignite.cache.CacheKeyConfiguration">
>
> <constructor-arg
>
> value="fr.data.wa.db.ignite.EventKey" />
>
> <constructor-arg value="clientId" />
> </bean>
> </list>
> </property>
>
> <property name="eagerTtl"
> value="true" />
>
> <property
> name="queryEntities">
> <list>
> <bean
> class="org.apache.ignite.cache.QueryEntity">
>
> <property name="keyType"
>
> value="fr.data.wa.db.ignite.EventKey" />
>
> <property name="valueType"
>
> value="fr.data.wa.db.ignite.Event" />
>
> <property name="tableName" value="Event" />
>
>
> <property name="keyFields">
>
> <list>
>
> <value>clientId</value>
>
> <value>eventDate</value>
>
> <value>num</value>
>
> </list>
>
> </property>
>
>
> <property name="fields">
>
> <map>
>
> <entry key="clientId" value="java.lang.Long" />
>
> <entry key="eventDate" value="java.sql.Timestamp" />
>
> <entry key="num" value="java.lang.Long" />
>
> <entry key="type" value="java.lang.String" />
>
> <entry key="source" value="java.lang.String" />
>
> <entry key="entity" value="java.lang.String" />
>
> <entry key="entityId" value="java.lang.Long" />
>
> <entry key="data" value="java.lang.String" />
>
> </map>
>
> </property>
>
>
> <property name="aliases">
>
> <map>
>
> <entry key="eventDate" value="event_date" />
>
> <entry key="clientId" value="client_id" />
>
> <entry key="entityId" value="entity_id" />
>
> </map>
>
> </property>
>
>
> <property name="notNullFields">
>
> <list>
>
> <value>clientId</value>
>
> <value>eventDate</value>
>
> <value>num</value>
>
> <value>type</value>
>
> <value>source</value>
>
> </list>
>
> </property>
>
>
> <property name="indexes">
>
> <list>
>
> <bean class="org.apache.ignite.cache.QueryIndex">
>
> <property name="name" value="event_pk" />
>
> <property name="indexType" value="SORTED" />
>
>
> <property name="fields">
>
> <map>
>
> <entry key="clientId"
> value="true" />
>
> <entry key="eventDate"
> value="true" />
>
> <entry key="num" value="true"
> />
>
> </map>
>
> </property>
>
> </bean>
>
> </list>
>
> </property>
> </bean>
> </list>
> </property>
> </bean>
>
> <bean parent="transactional-cache">
> <property name="name"
> value="fr.data.wa.db.hb.Event" />
> </bean>
>
>
> Hibernate Event entity :
>
> package fr.data.wa.db.hb;
> @Entity(name = "event")
> @Table(name = "\"EventCache\".event")
> @Cacheable
> @org.hibernate.annotations.Cache(usage =
> CacheConcurrencyStrategy.TRANSACTIONAL)
> public class Event implements java.io.Serializable {
> private static final long serialVersionUID = -
> 3536013579696669860L;
>
>
> @Id
> @Column(name = "client_id", insertable = false, updatable =
> false)
> private long clientId;
> @Id
> @Column(name = "event_date")
> private Date eventDate;
> @Id
> @Column
> private long num;
> /* [...] */
> }
>
--
Bastien Durel
DATA
Intégration des données de l'entreprise,
Systèmes d'information décisionnels.
[email protected]
tel : +33 (0) 1 57 19 59 28
fax : +33 (0) 1 57 19 59 73
45 avenue Carnot, 94230 CACHAN France
www.data.fr
