This is a trace of executing just a simple load() method on an
OperatorSession object, which has got three fields of 'serializable' type.
To improve performance, serialization was rewritten as custom readObject()/writeObject() methods.
What I see here is a little bit embarassing:
- OperatorSessionFactory - Loading operator session id='123'
- SessionImpl - loading [OperatorSession#123]
- SessionImpl - attempting to resolve [OperatorSession>
- ReadWriteCache - Cache lookup: 123
- Plugin - key: 123
- MemoryStore - OperatorSessionCache: MemoryStore miss>
- Cache - OperatorSession cache - Miss
- Plugin - Element for 123 is null
- ReadWriteCache - Cache miss: 123
- SessionImpl - object not resolved in any cache [Oper>
Ok, we haven't found it in the cache, let's go to database
- EntityPersister - Materializing entity: [OperatorSession>
- BatcherImpl - about to open: 0 open PreparedStatements, 0 open ResultSets
- SQL - select operatorse0_.id as id0_, operatorse0_.operatorName as operator>
- BatcherImpl - preparing statement
- StringType - binding '123' to parameter: 1
- Loader - processing result set
- Loader - result row: 123
- Loader - Initializing object from ResultSet: 123
- Loader - Hydrating entity: OperatorSession#123
- StringType - returning null as column: operator2_0_
- StringType - returning '123456' as column: terminal3_0_
- StringType - returning null as column: candidat4_0_
- TimestampType - returning '23 April 2004 17:54:57' as column: created0_
- TimestampType - returning '23 April 2004 17:54:57' as column: accessed0_
- BooleanType - returning 'false' as column: justResu7_0_
- OperatorSession - OperatorSession$ScriptState state recovered: /false////
..deserialized...
- OperatorSession - OperatorSession$ScriptState state saved: /false////
..serialized...
- SerializableType - returning '2c6d8085f3f280bae3efedaef6efe3efe7eee9f4e9efeeaeebe5f2eee5>
- OperatorSession - OperatorSession$ScriptState state recovered: /false////
..deserialized...
- OperatorSession - OperatorSession$ScriptState state saved: /false////
..serialized...
- SerializableType - returning '2c6d8085f3f280bae3efedaef6efe3efe7eee9f4e9efeeaeebe5f2eee5>
- OperatorSession - OperatorSession$ScriptState state recovered: /false////
..deserialized...
- OperatorSession - OperatorSession$ScriptState state saved: /false////
..serialized...
Deserialization I could understand but why were those fields serialized again?
- SerializableType - returning '2c6d8085f3f280bae3efedaef6efe3efe7eee9f4e9efeeaeebe5f2eee5>
- SerializableType - returning '2c6d8085f3f28091eae1f6e1aef5f4e9ecaec8e1f3e8cde1f085875a41>
- StringType - returning null as column: environ12_0_
- SerializableType - returning null as column: assignment0_
- SerializableType - returning '2c6d8085f3f28091eae1f6e1aef5f4e9ecaec8e1f3e8d3e5f43ac40515>
- Loader - done processing result set (1 rows)
- BatcherImpl - done closing: 0 open PreparedStatements, 0 open ResultSets
- BatcherImpl - closing statement
- Loader - total objects hydrated: 1
Hurray, finally object is loaded.
- SessionImpl - resolving associations for [OperatorSe>
- SessionImpl - adding entity to second-level cache [O>
Let's add it to cache just in case.
- OperatorSession - OperatorSession$ScriptState state saved: /false////
- OperatorSession - OperatorSession$ScriptState state saved: /false////
- OperatorSession - OperatorSession$ScriptState state saved: /false////
Serialize it again (!) - why, I might be well using local in-memory cache?
I understand that for distributed cache it's necessary to serialize, but why not let cache plug-in implementation to decide whether serialize or not?
- ReadWriteCache - Caching: 123
- Plugin - key: 123
- MemoryStore - OperatorSessionCache: MemoryStore miss>
- Cache - OperatorSession cache - Miss
- Plugin - Element for 123 is null
- ReadWriteCache - Saved to cache: 123
- OperatorSession - OperatorSession$ScriptState state saved: /false////
- OperatorSession - OperatorSession$ScriptState state recovered: /false////
- OperatorSession - OperatorSession$ScriptState state saved: /false////
- OperatorSession - OperatorSession$ScriptState state recovered: /false////
- OperatorSession - OperatorSession$ScriptState state saved: /false////
- OperatorSession - OperatorSession$ScriptState state recovered: /false////
After being saved to cache, every field is three times serialized/deserialized.
- SessionImpl - done materializing entity [OperatorSes>
- SessionImpl - initializing non-lazy collections
- OperatorSessionFactory - [78 ms] Operator session loaded
Yes it took 78 milliseconds to do a lot of those strange things.
I'm not very sure about application performance in this case: there were _three_ serializations and two deserializations. My plain stupid hand-made Entity BMP was doing it with just one deserialization. Why all that? Serialization is expensive, why do it again and again?
This is mapping file (excerpt):
<hibernate-mapping>
<class
name="OperatorSession"
table="OPERATOR_SESSION"
dynamic-update="true"
dynamic-insert="true"
>
<cache usage="read-write" />
<id
name="id"
column="id"
type="java.lang.String"
length="20"
>
<generator class="assigned">
</generator>
</id>
<property
name="operatorName"
type="java.lang.String"
update="true"
insert="true"
column="operatorName"
length="20"
/>
<property
name="mainScriptState"
type="serializable"
update="true"
insert="true"
>
<column
name="mainScriptState"
sql-type="binary"
/>
</property>
<property
name="subroutineScriptState"
type="serializable"
update="true"
insert="true"
>
<column
name="subroutineScriptState"
sql-type="binary"
/>
</property>
<property
name="switchingScriptState"
type="serializable"
update="true"
insert="true"
>
<column
name="switchingScriptState"
sql-type="binary"
/>
</property>
</class>
</hibernate-mapping>
Login
FAQ
Search
