Kotlin Hibernate OneToOne fetchtype.LAZY immediately running all queries

Question

I'm working on a training where the trainer is using Java, and I'm using Kotlin. Until now we had the same results everywhere but here I can't get it to work.

There are 2 entity classes:

@Entity
data class Student(
        @Id
        @GeneratedValue
        var id: Long = 0,

        @Column(nullable = false)
        var name: String = "",

        @OneToOne()
        var passport: Passport? = null
)

@Entity
data class Passport(
        @Id
        @GeneratedValue
        var id: Long = 0,

        @Column(nullable = false)
        var number: String = ""
)

And in a test class I use the entity manager to do a query.

@RunWith(SpringRunner::class)
@SpringBootTest
class StudentRepositoryTest {
    val logger = LoggerFactory.getLogger(this.javaClass)

    @Autowired
    lateinit var studentRepository: StudentRepository

    @Autowired
    lateinit var entityManager: EntityManager

    @Test
    fun retrieveStudentAndPasswordDetails() {
        val student: Student? = entityManager.find(Student::class.java, 20001L)

        logger.info("Student -> $student")
        logger.info("Passport -> `${student?.passport}")
    }
}

When I run the test this way the output is as expected

Hibernate: 
    select
        student0_.id as id1_3_0_,
        student0_.name as name2_3_0_,
        student0_.passport_id as passport3_3_0_,
        passport1_.id as id1_1_1_,
        passport1_.number as number2_1_1_ 
    from
        student student0_ 
    left outer join
        passport passport1_ 
            on student0_.passport_id=passport1_.id 
    where
        student0_.id=?
2017-12-29 20:51:04.258 TRACE 17233 --- [           main] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [BIGINT] - [20001]
2017-12-29 20:51:04.263 TRACE 17233 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([id1_1_1_] : [BIGINT]) - [40001]
2017-12-29 20:51:04.265 TRACE 17233 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([name2_3_0_] : [VARCHAR]) - [Ranga]
2017-12-29 20:51:04.266 TRACE 17233 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([passport3_3_0_] : [BIGINT]) - [40001]
2017-12-29 20:51:04.267 TRACE 17233 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([number2_1_1_] : [VARCHAR]) - [E123456]
2017-12-29 20:51:04.269  INFO 17233 --- [           main] i.StatisticalLoggingSessionEventListener : Session Metrics {
    19949 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    1097216 nanoseconds spent preparing 1 JDBC statements;
    227119 nanoseconds spent executing 1 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
}
2017-12-29 20:51:04.269  INFO 17233 --- [           main] c.i.j.h.j.r.StudentRepositoryTest        : Student -> Student(id=20001, name=Ranga, passport=Passport(id=40001, number=E123456))
2017-12-29 20:51:04.269  INFO 17233 --- [           main] c.i.j.h.j.r.StudentRepositoryTest        : Passport -> `Passport(id=40001, number=E123456)

This looks really nice. A query is called with a join, and both log outputs are displayed.

Using FetchType.LAZY

Here I add FetchType.LAZY to the OneToOne annotation which should make retrieval of the passport data wait until it is actually required.

@Entity
data class Student(
        @Id
        @GeneratedValue
        var id: Long = 0,

        @Column(nullable = false)
        var name: String = "",

        @OneToOne(fetch = FetchType.LAZY)
        var passport: Passport? = null
)

This is where I see some unexpected behaviour.

What I would expect is to see the query to retrieve student data, then log output for student data. Next query to retrieve passport data and lastly the log for passport data.

When lazy loading would have been ignored completely then I would have expected to still see the join, but instead there are 2 separate queries, which seems to make things worse then without lazy loading.

Hibernate: 
    select
        student0_.id as id1_3_0_,
        student0_.name as name2_3_0_,
        student0_.passport_id as passport3_3_0_ 
    from
        student student0_ 
    where
        student0_.id=?
2017-12-29 21:03:53.401 TRACE 17380 --- [           main] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [BIGINT] - [20001]
2017-12-29 21:03:53.411 TRACE 17380 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([name2_3_0_] : [VARCHAR]) - [Ranga]
2017-12-29 21:03:53.412 TRACE 17380 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([passport3_3_0_] : [BIGINT]) - [40001]
Hibernate: 
    select
        passport0_.id as id1_1_0_,
        passport0_.number as number2_1_0_ 
    from
        passport passport0_ 
    where
        passport0_.id=?
2017-12-29 21:03:53.413 TRACE 17380 --- [           main] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [BIGINT] - [40001]
2017-12-29 21:03:53.415 TRACE 17380 --- [           main] o.h.type.descriptor.sql.BasicExtractor   : extracted value ([number2_1_0_] : [VARCHAR]) - [E123456]
2017-12-29 21:03:53.427  INFO 17380 --- [           main] i.StatisticalLoggingSessionEventListener : Session Metrics {
    33422 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    569626 nanoseconds spent preparing 2 JDBC statements;
    1612599 nanoseconds spent executing 2 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
}
2017-12-29 21:03:53.427  INFO 17380 --- [           main] c.i.j.h.j.r.StudentRepositoryTest        : Student -> Student(id=20001, name=Ranga, passport=Passport(id=40001, number=E123456))
2017-12-29 21:03:53.427  INFO 17380 --- [           main] c.i.j.h.j.r.StudentRepositoryTest        : Passport -> `Passport(id=40001, number=E123456)

@Transactional annotation

Something else: when the trainer is running the tests without @Transacional on the on the test method, an exception is thrown.
In my case, it makes no difference whether I use this annotation or not.

Answer 1

I faced this problem today and after a lot of research and tests (Hibernate compile time instrumentation) the solution I found was:

• Add optional = false to my OneToOne
• Add @LazyToOne(LazyToOneOption.PROXY) to my attribute
• Make the child class open and all attributes of child also open

After these steps hibernate stopped fetching automatically.