[hibernate-dev] SessionEventsListener feature (HHH-8654)

[Steve Ebersole]

I wanted to highlight a new feature in 4.3 as it came about from 
performance testing efforts.  Its a way to hopefully help track down 
potential performance problems in applications that use Hibernate. In 
this way it is similar to statistics, but it operates per-Session 
(though certainly custom impls could role the metrics up to a SF level).

It revolves around the SessionEventsListener[1] interface which 
essentially defines a number of start/end pairs for the interesting 
events (for example starting to prepare a JDBC statement and ending that 
preparation).

Multiple SessionEventsListener instances can be associated with the 
Session simultaneously.  You can add them programatically to a Session 
using Session#addEventsListeners(SessionEventsListener...) method.  They 
can also be added to the Session up-front via the 
SessionFactory#withOptions API for building Sessions.

Additionally there are 2 settings that allow SessionEventsListener impls 
to be applied to all Sessions created:

* 'hibernate.session.events.auto' allows you to name any arbitrary 
SessionEventsListener class to apply to all Sessions.
* 'hibernate.session.events.log' refers to a particular built-in 
implementation of SessionEventsListener that applies some timings across 
the start/end pairs 
(org.hibernate.engine.internal.LoggingSessionEventsListener).  In fact 
this listener is added by default if (a) stats are enabled and (b) the 
log level (currently INFO) of LoggingSessionEventsListener is enabled.  
Below[2] is some sample output of LoggingSessionEventsListener.

There is also a org.hibernate.EmptySessionEventsListener (no-op) class 
to help develop custom ones.

Anyway, as much as anything I wanted to point it out so people can try 
it out and to get feedback.  I think the API covers most of the 
interesting events.  If you feel there are any missing, lets discuss 
here or on a Jira issue.


[1] https://gist.github.com/sebersole/7438250

[2]
14:40:20,017  INFO LoggingSessionEventsListener:275 - Session Metrics {
     9762 nanoseconds spent acquiring 1 JDBC connections;
     0 nanoseconds spent releasing 0 JDBC connections;
     1020726 nanoseconds spent preparing 4 JDBC statements;
     1442351 nanoseconds spent executing 4 JDBC statements;
     0 nanoseconds spent executing 0 JDBC batches;
     0 nanoseconds spent executing 0 L2C puts;
     0 nanoseconds spent executing 0 L2C hits;
     0 nanoseconds spent executing 0 L2C misses;
     2766689 nanoseconds spent executing 1 flushes (flushing a total of 
3 entities and 1 collections);
     1096552384585007 nanoseconds spent executing 2 partial-flushes 
(flushing a total of 3 entities and 3 collections)
}