3

I have a query that returns around 1200 elements of a single class. I've profiled the query execution using log4jdbc and the query itself runs in around 70ms; however my dao method (which ends with return query.list()) takes awfully long to return the list of objects to my service (up to 7s), as though the problem was somehow related to the mapping.

This is my class:

@Entity
@Table(name = "unidad_funcional", uniqueConstraints = { @UniqueConstraint(columnNames = { "id_unidad_funcional", "id_subempresa" }) })
public class UnidadFuncional extends AbstractEntity {

    /**
     * 
     */
    private static final long serialVersionUID = 1L;


    @Id
    @Column(name = "id_unidad_funcional_PK")
    @GeneratedValue(strategy = GenerationType.SEQUENCE, generator = "gen_UF")
    @SequenceGenerator(name = "gen_UF", sequenceName = "SEQ_unidad_funcio_id_unidad_fu")
    private Integer idUnidadFuncionalPK;

    @Column(name = "id_unidad_funcional")
    private String idUnidadFuncional;

    @Column(name = "unidad_funcional")
    private String unidadFuncional;

    @ManyToOne(fetch = FetchType.LAZY)
    @JoinColumn(name = "id_subempresa")
    private SubEmpresa subEmpresa;

    @ManyToOne(fetch = FetchType.LAZY)
    @JoinColumn(name = "id_agrupacion_funcional")
    private AgrupacionFuncional agrupacionFuncional;

    @OneToMany(fetch = FetchType.LAZY, mappedBy = "unidadFuncional")
    private Set<Contrato> contratos = new HashSet<Contrato>();

    @ManyToMany(fetch = FetchType.LAZY)
    @JoinTable(name = "up_unidad_funcional", joinColumns = { @JoinColumn(name = "id_unidad_planificacion") }, inverseJoinColumns = { @JoinColumn(name = "id_unidad_funcional") })
    private Set<UnidadPlanificacion> unidadesPlanificacion = new HashSet<UnidadPlanificacion>();

    @ManyToMany(fetch = FetchType.LAZY)
    @JoinTable(name = "unidad_funcional_centro", joinColumns = { @JoinColumn(name = "id_unidad_funcional") }, inverseJoinColumns = { @JoinColumn(name = "id_centro") })
    private Set<Centro> centros = new HashSet<Centro>();

    (....)
}

and this is the query that gets executed:

 select
        distinct unidadfunc0_.id_unidad_funcional_PK as id1_45_,
        unidadfunc0_.borrado as borrado45_,
        unidadfunc0_.fecha_alta as fecha3_45_,
        unidadfunc0_.propietario as propieta4_45_,
        unidadfunc0_.fecha_modificacion as fecha5_45_,
        unidadfunc0_.version as version45_,
        unidadfunc0_.id_agrupacion_funcional as id9_45_,
        unidadfunc0_.id_unidad_funcional as id7_45_,
        unidadfunc0_.id_subempresa as id10_45_,
        unidadfunc0_.unidad_funcional as unidad8_45_ 
    from
        unidad_funcional unidadfunc0_ 
    where
        unidadfunc0_.borrado = ? 
    order by
        lower(unidadfunc0_.unidad_funcional) asc

I know I have a couple of relations but I checked and those are not getting fetched -- so that's not where the problem is.

I feel like somehow 1200 elements is not that much for Hibernate to take that long to map the objects (specially with such a small object), so any hints on where could the problem be would be appreciated.

EDIT: Here's the query code (using queryDSL -- I also tried with a simple criteria with no filtering):

public List<UnidadFuncional> getUnidadesFuncionalesByFiltros(UnidadFuncionalFiltro filtro) {

        final JPAQuery query = new JPAQuery(getEntityManager());
        final JPAQuery subQuerySubEmpresas = new JPAQuery(getEntityManager());
        final QUnidadFuncional qu = QUnidadFuncional.unidadFuncional1;
        final QSubEmpresa qsub = QSubEmpresa.subEmpresa;

        query.from(qu);
        if(filtro.isIncluirDesactivados()) {
            disableFilterByDeleted();
        }
        if(StringUtils.isNotBlank(filtro.getIdCentro())){
            query.where(qu.subEmpresa().centros.any().idCentro.eq(filtro.getIdCentro()));
        }

        if(!filtro.getIdSubempresa().equals("")) {
            query.where(qu.subEmpresa().idSubempresa.eq(Integer.parseInt(filtro.getIdSubempresa())));
        }
        if(!filtro.getIdEmpresa().equals("")){
            subQuerySubEmpresas.from(qsub);
            subQuerySubEmpresas.where(qsub.empresa().idEmpresa.eq(Integer.parseInt(filtro.getIdEmpresa())));
            List<Integer> lista = subQuerySubEmpresas.listDistinct(qsub.idSubempresa);
            if (lista != null && lista.size() > 0) {
                query.where(qu.subEmpresa().idSubempresa.in(lista));
            }
        }
        query.orderBy(qu.unidadFuncional.toLowerCase().asc());
        return query.listDistinct(qu);

PD: By the way, this is just an example but this actually happens iwth most of my entities!

M Rajoy
  • 4,028
  • 14
  • 54
  • 111

1 Answers1

0

Well I would look 3 places.

1) Just because the query finished executing does not mean you are done with IO with the database. If these records are huge or your connection is slow, fetching each record may be causing your speed issues.

2) Are you using show_sql = true to be sure a lot of subqueries aren't being run as you are creating objects?

3) It is somewhere else entirely. I've done something just like this when I was concatenating Strings in a big loop after a query. Switching to appending everything to a StringBuilder produced huge savings.

osoblanco
  • 468
  • 2
  • 10
  • log4jJDBC intercepts the JDBC connection and logs execution time after rows are returned, so I would say the measure is right. My service code is just calling the DAO method -- which I just posted on the original message – M Rajoy Nov 07 '14 at 20:26
  • sorry, forgot to say -- i am indeed using show_sql = true and no further queries are executed – M Rajoy Nov 07 '14 at 20:39
  • Have you tried removing the orderby? or replacing listDistinct with list? – osoblanco Nov 07 '14 at 20:44
  • I have -- I tried with a simple Criteria query that doesn't do any filtering or ordering. – M Rajoy Nov 07 '14 at 20:45
  • Have you tried to further time elements of the DAO method? Perhaps getting the entityManager for the first time is a one-time speed issue? – osoblanco Nov 07 '14 at 21:07
  • I put a break point right on the query.list() method, then on the next executable piece of code. Query gets executed in no time, but my execution does not flow up to the next point until ~7000ms. It's really driving me mad. – M Rajoy Nov 07 '14 at 21:10
  • Have you looked at this? Specifically the complete constructor suggestion may be of interest. http://stackoverflow.com/questions/12163268/why-is-the-hibernate-query-list-slow – osoblanco Nov 07 '14 at 21:21
  • it's the first time i've heard about this being an improvement. Will try though. Thanks. – M Rajoy Nov 08 '14 at 14:47
  • Kelmer, just curious, did the constructor thing help at all? – osoblanco Nov 12 '14 at 14:34
  • 1
    I tried it and at first it seemed like it actually worked but I think it was the cache kicking in. Subsequent queries were just as slow as the ones I was executing before. So, no, I still haven't solved the issue :( – M Rajoy Nov 12 '14 at 15:37