slow remote communication

[justkeys]

I have a stateless facade bean that fetches a deep hierarchic structure from my database using ejb3 with eager-mapped relations. This takes 2 seconds (timed with an ejb interceptor).

On the client, i wrapped the ejb-proxy in a dynamic proxy, to time remote calls: 11 seconds.

What is going on, in between the ejb-interceptor, and the client?

Java-serialisation: i timed this, by serialising the fetched data into a byte-array-stream (and deserialising it again): 140ms.

(using 4.0.4, rc8 and rc9, hsqldb or mysql, all the same)

[justkeys]

Appearently it takes 9 seconds to process flush-time cascades... whatever that may be? I'm only fetching data, it's a query.

2006-09-26 12:29:47,308 INFO [STDOUT] 2218 ms: findLayout ([/Default/giant2.layout]) = null
2006-09-26 12:29:47,308 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] processing flush-time cascades
2006-09-26 12:29:56,808 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] dirty checking collections

[justkeys]

I was able to skip this useless processing of cascades, by clearing the session (entitymanager.clear()) before returning.

Using trace logging, i found out that the 9 seconds were all used to handle about 400 entities. Hibernate, i think you got a little problem here. Note: with trace logging enabled it took over 2 minutes.

2006-09-26 13:01:10,410 TRACE [org.hibernate.transaction.CacheSynchronization] transaction before completion callback
2006-09-26 13:01:10,410 TRACE [org.hibernate.jdbc.JDBCContext] before transaction completion
2006-09-26 13:01:10,410 TRACE [org.hibernate.impl.SessionImpl] before transaction completion
2006-09-26 13:01:10,410 TRACE [org.hibernate.ejb.AbstractEntityManagerImpl] automatically flushing session
2006-09-26 13:01:10,410 TRACE [org.hibernate.impl.SessionImpl] automatically flushing session
2006-09-26 13:01:10,410 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] flushing session
2006-09-26 13:01:10,410 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] processing flush-time cascades
...
2006-09-26 13:03:49,101 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] Processing unreferenced collections
2006-09-26 13:03:49,101 TRACE [org.hibernate.event.def.AbstractFlushingEventListener] Scheduling collection removes/(re)creates/updates
2006-09-26 13:03:49,101 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 insertions, 0 updates, 0 deletions to 418 objects
2006-09-26 13:03:49,101 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 (re)creations, 0 updates, 0 removals to 417 collections
2006-09-26 13:03:49,101 DEBUG [org.hibernate.pretty.Printer] listing entities: