Why does my application execute more queries with Eager fetching activated?

Hi everyone,

In my master thesis I’ve implemented a small tool for autogenerating query hints for associations based on statistics. In order to evaluate my tool, I’ve set up a small benchmark on an application within my company that I’m running against a non-tuned version of the application, a handtuned version of the application, and finally a version of the application running my tool.

One thing that got me a little bit confused however, is that I first ran the application without any fetch strategies set, ending up with this console output:

[20:04:15:148]  INFO 119ED5C6BFD2BBC8DDE30515E3D7EE1B org.hibernate.engine.internal.StatisticalLoggingSessionEventListener: Session Metrics {
    115600 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    35127300 nanoseconds spent preparing 17 JDBC statements;
    30999600 nanoseconds spent executing 17 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;
    43755700 nanoseconds spent executing 1 flushes (flushing a total of 50 entities and 16 collections);
    184200 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}

Then I ran the same thing but with the version with some handtuned associations (some associations set to FetchType.EAGER basically) and I end up with this:

[13:04:58:968]  INFO 1C0F742FBC5119015415F455DC2CFB23 org.hibernate.engine.internal.StatisticalLoggingSessionEventListener: Session Metrics {
    107700 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    32007900 nanoseconds spent preparing 25 JDBC statements;
    49463800 nanoseconds spent executing 25 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;
    27471600 nanoseconds spent executing 1 flushes (flushing a total of 4945 entities and 16 collections);
    6800 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}

I thought that the whole purpose of eager fetching was to load the associations together with the root in the same query. So with eagerly fetched associations we end up with more queries being executed. How can this even be possible?

That could be because of JPQL queries which don’t have the JOIN FETCH clause, so secondary queries are executed to ensure the EAGER fetching strategy.

1 Like

Is there a way to enforce that the generated JPQL queries uses JOIN FETCH, or is that something you have to modify for yourself in each case?

By the way, I’m a little bit confused by the console output when running the application. We have the queries that was executed by Hibernate, and then also the JPQL like this:

Hibernate: 
    select
        partnerpnr0_.NR_NUM as NR_NUM1_8_0_,
        partnerpnr0_.OWNER_KNZ as OWNER_KN2_8_0_,
        partnernap1_.FK_PNR_NR_NUM as FK_PNR_N1_6_1_,
        partnernap1_.FK_PNR_OWNER_KNZ as FK_PNR_O2_6_1_,
        partnerpnr0_.AKQUISE_A_TXT as AKQUISE_3_8_0_,
        partnerpnr0_.ALLFINANZ_CDA as ALLFINAN4_8_0_,
        partnerpnr0_.ANREDE_CDN as ANREDE_C5_8_0_,
        partnerpnr0_.DKV_STAATSANG_CDA as DKV_STAA6_8_0_,
        partnerpnr0_.EINKOMMENSART_CDA as EINKOMME7_8_0_,
        partnerpnr0_.EINKOMMEN_CDA as EINKOMME8_8_0_,
        partnerpnr0_.EINKOMMEN_KZ_CDA as EINKOMME9_8_0_,
        partnerpnr0_.ERREICHBAR_TXT as ERREICH10_8_0_,
        partnerpnr0_.GEBURTSDATUM_DAT as GEBURTS11_8_0_,
        partnerpnr0_.GEWERBE_CDN as GEWERBE12_8_0_,
        partnerpnr0_.HH_GROESSE_KNZ as HH_GROE13_8_0_,
        partnerpnr0_.HOBBY_TXT as HOBBY_T14_8_0_,
        partnerpnr0_.JUPA_NAPA_KNZ as JUPA_NA15_8_0_,
        partnerpnr0_.KONZERN_YSN as KONZERN16_8_0_,
        partnerpnr0_.MONEINK_BRUTTO_MNY as MONEINK17_8_0_,
        partnerpnr0_.MONEINK_NETTO_MNY as MONEINK18_8_0_,
        partnerpnr0_.POS_AEND_GRUND_CDA as POS_AEN19_8_0_,
        partnerpnr0_.SORTNAME_TXT as SORTNAM20_8_0_,
        partnerpnr0_.SPORT_CDA as SPORT_C21_8_0_,
        partnerpnr0_.STAATSANGEHOER_CDA as STAATSA22_8_0_,
        partnerpnr0_.STERBEDATUM_DAT as STERBED23_8_0_,
        partnerpnr0_.VERMITTLER_YSN as VERMITT24_8_0_,
        partnerpnr0_.VIP_KNZ as VIP_KNZ25_8_0_,
        partnerpnr0_.WOHNVERHLT_CDA as WOHNVER26_8_0_,
        partnernap1_.ADELSTITEL_TXT as ADELSTIT3_6_1_,
        partnernap1_.AKAD_TITEL_TXT as AKAD_TIT4_6_1_,
        partnernap1_.BERUF_TXT as BERUF_TX5_6_1_,
        partnernap1_.ERWERBSART_CDA as ERWERBSA6_6_1_,
        partnernap1_.FAMSTAND_CDA as FAMSTAND7_6_1_,
        partnernap1_.FUNKTION_TXT as FUNKTION8_6_1_,
        partnernap1_.NACHSATZ_TXT as NACHSATZ9_6_1_,
        partnernap1_.NAME_TXT as NAME_TX10_6_1_,
        partnernap1_.SONST_TITEL_TXT as SONST_T11_6_1_,
        partnernap1_.VORNAME_TXT as VORNAME12_6_1_,
        partnernap1_.VORSATZ_TXT as VORSATZ13_6_1_ 
    from
        AGRP.APA_PNR partnerpnr0_ 
    left outer join
        AGRP.APA_NAPA partnernap1_ 
            on partnerpnr0_.NR_NUM=partnernap1_.FK_PNR_NR_NUM 
            and partnerpnr0_.OWNER_KNZ=partnernap1_.FK_PNR_OWNER_KNZ 
    where
        partnerpnr0_.NR_NUM=? 
        and partnerpnr0_.OWNER_KNZ=?
Hibernate: 
    select
        partnerpad0_.NR_NUM as NR_NUM1_7_0_,
        partnerpad0_.OWNER_KNZ as OWNER_KN2_7_0_,
        partnerpad0_.AENDERUNG_ZST as AENDERUN3_7_0_,
        partnerpad0_.AKQUISE_YSN as AKQUISE_4_7_0_,
        partnerpad0_.ALTE_HOST_NUM as ALTE_HOS5_7_0_,
        partnerpad0_.GESPRAEMIE_MNY as GESPRAEM6_7_0_,
        partnerpad0_.KLASS_BT_GI_KNZ as KLASS_BT7_7_0_,
        partnerpad0_.KLASS_BT_LIFE_KNZ as KLASS_BT8_7_0_,
        partnerpad0_.KLASS_VT_GI_KNZ as KLASS_VT9_7_0_,
        partnerpad0_.KLASS_VT_LIFE_KNZ as KLASS_V10_7_0_,
        partnerpad0_.NAMENZEILE_1_TXT as NAMENZE11_7_0_,
        partnerpad0_.NAMENZEILE_2_TXT as NAMENZE12_7_0_,
        partnerpad0_.ORIGINALNR_NUM as ORIGINA13_7_0_,
        partnerpad0_.PER_ID_ADIS_TXT as PER_ID_14_7_0_,
        partnerpad0_.POLICEN_ANZ as POLICEN15_7_0_,
        partnerpad0_.POSTFACH_NR_TXT as POSTFAC16_7_0_,
        partnerpad0_.POSTFACH_PLZ_TXT as POSTFAC17_7_0_,
        partnerpad0_.POS_AENDSTATUS_CDA as POS_AEN18_7_0_,
        partnerpad0_.STATUS_CDA as STATUS_19_7_0_,
        partnerpad0_.VERTRAEGE_ANZ as VERTRAE20_7_0_,
        partnerpad0_.FK_ADR_NR_NUM as FK_ADR_21_7_0_,
        partnerpad0_.FK_ADR_OWNER_KNZ as FK_ADR_22_7_0_,
        partnerpad0_.FK_PNR_NR_NUM as FK_PNR_23_7_0_,
        partnerpad0_.FK_PNR_OWNER_KNZ as FK_PNR_24_7_0_ 
    from
        AGRP.APA_PADR partnerpad0_ 
    where
        partnerpad0_.NR_NUM=? 
        and partnerpad0_.OWNER_KNZ=?
Hibernate: 
    select
        partnerkon0_.NR_NUM as NR_NUM1_14_1_,
        partnerkon0_.OWNER_KNZ as OWNER_KN2_14_1_,
        partnerkon0_.BANKNAME_TXT as BANKNAME3_14_1_,
        partnerkon0_.BIC_TXT as BIC_TXT4_14_1_,
        partnerkon0_.BLZ_NUM as BLZ_NUM5_14_1_,
        partnerkon0_.EINMALMANDAT_YSN as EINMALMA6_14_1_,
        partnerkon0_.ERSTABBUCHUNG_YSN as ERSTABBU7_14_1_,
        partnerkon0_.FK_PADR_NR_NUM as FK_PADR24_14_1_,
        partnerkon0_.FK_PADR_OWNER_KNZ as FK_PADR25_14_1_,
        partnerkon0_.GLAEUBIGER_ID_TXT as GLAEUBIG8_14_1_,
        partnerkon0_.GUELTIG_AB_DAT as GUELTIG_9_14_1_,
        partnerkon0_.GUELTIG_BIS_DAT as GUELTIG10_14_1_,
        partnerkon0_.IBAN_TXT as IBAN_TX11_14_1_,
        partnerkon0_.INHABER_TXT as INHABER12_14_1_,
        partnerkon0_.KONTOART_CDN as KONTOAR13_14_1_,
        partnerkon0_.KONTO_NR_NUM as KONTO_N14_14_1_,
        partnerkon0_.MANDATSREF_NR_TXT as MANDATS15_14_1_,
        partnerkon0_.MANDAT_STATUS_CDA as MANDAT_16_14_1_,
        partnerkon0_.MANUELL_BEGRENZT_YSN as MANUELL17_14_1_,
        partnerkon0_.RE_LKZ_CDA as RE_LKZ_18_14_1_,
        partnerkon0_.RE_ORT_TXT as RE_ORT_19_14_1_,
        partnerkon0_.RE_PLZ_TXT as RE_PLZ_20_14_1_,
        partnerkon0_.RE_POSTFACH_TXT as RE_POST21_14_1_,
        partnerkon0_.RE_STRASSE_TXT as RE_STRA22_14_1_,
        partnerkon0_.SEPA_BANKNAME_TXT as SEPA_BA23_14_1_,
        partnerpad1_.NR_NUM as NR_NUM1_7_0_,
        partnerpad1_.OWNER_KNZ as OWNER_KN2_7_0_,
        partnerpad1_.AENDERUNG_ZST as AENDERUN3_7_0_,
        partnerpad1_.AKQUISE_YSN as AKQUISE_4_7_0_,
        partnerpad1_.ALTE_HOST_NUM as ALTE_HOS5_7_0_,
        partnerpad1_.GESPRAEMIE_MNY as GESPRAEM6_7_0_,
        partnerpad1_.KLASS_BT_GI_KNZ as KLASS_BT7_7_0_,
        partnerpad1_.KLASS_BT_LIFE_KNZ as KLASS_BT8_7_0_,
        partnerpad1_.KLASS_VT_GI_KNZ as KLASS_VT9_7_0_,
        partnerpad1_.KLASS_VT_LIFE_KNZ as KLASS_V10_7_0_,
        partnerpad1_.NAMENZEILE_1_TXT as NAMENZE11_7_0_,
        partnerpad1_.NAMENZEILE_2_TXT as NAMENZE12_7_0_,
        partnerpad1_.ORIGINALNR_NUM as ORIGINA13_7_0_,
        partnerpad1_.PER_ID_ADIS_TXT as PER_ID_14_7_0_,
        partnerpad1_.POLICEN_ANZ as POLICEN15_7_0_,
        partnerpad1_.POSTFACH_NR_TXT as POSTFAC16_7_0_,
        partnerpad1_.POSTFACH_PLZ_TXT as POSTFAC17_7_0_,
        partnerpad1_.POS_AENDSTATUS_CDA as POS_AEN18_7_0_,
        partnerpad1_.STATUS_CDA as STATUS_19_7_0_,
        partnerpad1_.VERTRAEGE_ANZ as VERTRAE20_7_0_,
        partnerpad1_.FK_ADR_NR_NUM as FK_ADR_21_7_0_,
        partnerpad1_.FK_ADR_OWNER_KNZ as FK_ADR_22_7_0_,
        partnerpad1_.FK_PNR_NR_NUM as FK_PNR_23_7_0_,
        partnerpad1_.FK_PNR_OWNER_KNZ as FK_PNR_24_7_0_ 
    from
        AGRP.AVT_KONTO partnerkon0_ 
    left outer join
        AGRP.APA_PADR partnerpad1_ 
            on partnerkon0_.FK_PADR_NR_NUM=partnerpad1_.NR_NUM 
            and partnerkon0_.FK_PADR_OWNER_KNZ=partnerpad1_.OWNER_KNZ 
    where
        partnerkon0_.FK_PADR_NR_NUM=? 
        and partnerkon0_.FK_PADR_OWNER_KNZ=?
Hibernate: 
    select
        partnerjup0_.FK_PNR_NR_NUM as FK_PNR_N1_5_0_,
        partnerjup0_.FK_PNR_OWNER_KNZ as FK_PNR_O2_5_0_,
        partnerjup0_.BILANZSUMME_BTR as BILANZSU3_5_0_,
        partnerjup0_.GESFORM_CDA as GESFORM_4_5_0_,
        partnerjup0_.MITARBEITER_ANZ as MITARBEI5_5_0_,
        partnerjup0_.NAME_1_TXT as NAME_6_5_0_,
        partnerjup0_.NAME_2_TXT as NAME_7_5_0_,
        partnerjup0_.NETTOUMSATZ_BTR as NETTOUMS8_5_0_,
        partnerjup0_.SIC_CDA as SIC_CDA9_5_0_,
        partnerjup0_.WAEHRUNG_CDA as WAEHRUN10_5_0_ 
    from
        AGRP.APA_JUPA partnerjup0_ 
    where
        partnerjup0_.FK_PNR_NR_NUM=? 
        and partnerjup0_.FK_PNR_OWNER_KNZ=?
[14:52:44:933] DEBUG 80E60877F7967F04F9560C1EC64CAEC5 org.hibernate.stat.internal.ConcurrentStatisticsImpl: HHH000117: HQL: from com.zurich.tas.persistency.direct.tables.PartnerPnr entity left outer join fetch entity.partnerNapa af0 where entity.id = :id, time: 8ms, rows: 1
[14:52:44:934]  INFO 80E60877F7967F04F9560C1EC64CAEC5 org.hibernate.engine.internal.StatisticalLoggingSessionEventListener: Session Metrics {
    98899 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    2315599 nanoseconds spent preparing 4 JDBC statements;
    1975401 nanoseconds spent executing 4 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);
    2800 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}

My question is how does the JPQL relate to the SQL here? Does the JPQL generate the underlying SQL queries? For some reason the tool seems to generate more queries than if everything is lazy loaded, which is strange because all that I’m doing is the following (if the probability of loading a specific association is higher than 50%):

    public static Object getResult(List<Path> prefetchPaths, String classname,
                                   Serializable id, LockMode lm, Session sess) {
        StringBuilder queryStr = new StringBuilder();
        queryStr.append("from ").append(classname).append(" entity");
        Map<Path, String> pathAliases = new HashMap<>();
        int aliasCnt = 0;
        pathAliases.put(new Path(), "entity");

        // Assumes prefetchPaths is ordered such larger paths appear after smaller ones.
        // Also assumes all prefixes of a path are present except the empty prefix.
        for (Path p : prefetchPaths) {
            String oldAlias = pathAliases.get(p.removeLastTraversal());
            String newAlias = "af" + (aliasCnt++);
            String lastField = p.traversals().get(p.size() - 1);
            pathAliases.put(p, newAlias);
            queryStr.append(" left outer join fetch ");
            queryStr.append(oldAlias).append(".").append(lastField).append(" ").append(newAlias);
        }
        queryStr.append(" where entity.id = :id");

        if (log.isDebugEnabled()) {
            log.debug("Autofetched Query: " + queryStr);
        }

        Query q = sess.createQuery(queryStr.toString());
        q.setLockMode("entity", lm);
        q.setFlushMode(FlushMode.MANUAL);
        q.setParameter("id", id);

        long startTimeMillis = System.currentTimeMillis();
        Object o = q.uniqueResult();
        if (log.isDebugEnabled()) {
            log.debug("Query execution time: " +
                    (System.currentTimeMillis() - startTimeMillis));
        }
        return o;
    }
}

This generates the query:

org.hibernate.stat.internal.ConcurrentStatisticsImpl: HHH000117: HQL: from com.zurich.tas.persistency.direct.tables.PartnerPnr entity left outer join fetch entity.partnerNapa af0 where entity.id = :id, time: 8ms, rows: 1

This is being called instead of the normal load method in the LoadListener. For me it seems strange that we generate more queries this way when all we’re doing is to add JOIN FETCH directives to the query. Any ideas?

There’s no generated JPQL. JPQL is the query you write yourself.

My question is how does the JPQL relate to the SQL here? Does the JPQL generate the underlying SQL queries?

Yes, JPQL is parsed to SQL.

For some reason the tool seems to generate more queries than if everything is lazy loaded, which is strange because all that I’m doing is the following (if the probability of loading a specific association is higher than 50%):

The way you are building the JPQL dynamically is wrong. You should use Criteria API instead and avoid SQL injection attacks.

For me it seems strange that we generate more queries this way when all we’re doing is to add JOIN FETCH directives to the query. Any ideas?

The User Guide provides a very detailed explanation for this behavior that surprises you.

1 Like

Thanks for the explanation. However, I don’t quite understand when you say the following:

Yes, it is not according to standard and the criteria API would be a better solution, but still the application still runs. I mean, if I change to Criteria API it won’t change the number of queries being executed in my test case right?

I don’t know exactly what you refer to, I am comparing a run of only lazy loaded association to a version with lazy loaded associations but with my tool, which loads using FETCH JOIN. From what I see in the User guide ( 11.5. Dynamic fetching via queries), in the case of FETCH JOIN we should only execute one query.

Thanks again for taking the time Vlad!

No. It will not generate less SQL, but your app will be more secure even after you fix the extra SQL issue.

I don’t know exactly what you refer to, I am comparing a run of only lazy loaded association to a version with lazy loaded associations but with my tool, which loads using FETCH JOIN. From what I see in the User guide ( 11.5. Dynamic fetching via queries), in the case of FETCH JOIN we should only execute one query.

You said EAGER fetching in the title, but now you are saying that associations are lazy. Anyway, it’s impossible to tell what’s wrong since I don’t know the mapping or the data access code. The only way for you t find the issue is to debug the code and see why the extra queries are generated.

1 Like

True, I forgot to mention that I started talking about a different test. Well, thanks for the tips, I definitely have some things to think about. Have a good evening!

Thanks, you too. I’m glad I could help.