Re: a very long query

From: tnaki..ofthome.net
Date: Wed Apr 20 2005 - 07:55:39 EDT

  • Next message: McDaniel, Joe R.: "RE: a very long query"

    Tore Halset wrote:

    > On Apr 20, 2005, at 10:41, tnaki..ofthome.net wrote:
    >
    >> My devel. environment: Postgre 8.0.x, JDK 1.5, Win. 2k
    >>
    >> I have a query that runs in less than a tenth of a second when I run
    >> it directly, by using the admin interface.
    >> When I run it using cayenne, however, it literally takes 2 minutes -
    >> what's more interesting is it's just one out of several queries all
    >> of which run fairly fast (and all run on views, rather than tables).
    >> Furthermore, it's a very simple query and it returns very little data.
    >
    >
    > Could you give us some more info? Perhaps output from cayenne logging?
    > Have you done any profiling to see where the time are spent?

    It's probably not the best idea, but I depend on the eclipse console for
    logging during development.
    For what it's worth, this is the output I get:
    INFO QueryLogger: --- will run 1 query.
    INFO QueryLogger: --- transaction started.
    INFO QueryLogger: SELECT t0.attrib1 FROM public.my_view_1 t0
    INFO QueryLogger: === returned 1 row. - took 328 ms.
    INFO QueryLogger: +++ transaction committed.
    INFO QueryLogger: --- will run 1 query.
    INFO QueryLogger: --- transaction started.
    INFO QueryLogger: SELECT t0.attrib1FROM public.my_view_2 t0
    INFO QueryLogger: === returned 1 row. - took 172 ms.
    INFO QueryLogger: +++ transaction committed.
    INFO QueryLogger: --- will run 1 query.
    INFO QueryLogger: --- transaction started.
    INFO QueryLogger: SELECT t0.attrib1, t0.attrib2, t0.attrib3,
    t0.attrib4, t0.attrib5, t0.attrib6 FROM public.my_view_3 t0
    INFO QueryLogger: === returned 25 rows. - took 2016 ms.
    INFO QueryLogger: +++ transaction committed.
    INFO QueryLogger: --- will run 1 query.
    INFO QueryLogger: --- transaction started.
    INFO QueryLogger: SELECT t0.attrib1, t0.attrib2 FROM public.my_view_4 t0
    INFO QueryLogger: === returned 47 rows. - took 297 ms.
    INFO QueryLogger: +++ transaction committed.
    INFO QueryLogger: --- will run 1 query.
    INFO QueryLogger: --- transaction started.
    INFO QueryLogger: SELECT t0.attrib1, t0.attrib2 FROM public.my_view_5 t0
    INFO QueryLogger: === returned 52 rows. - took 375 ms.
    INFO QueryLogger: +++ transaction committed.
    INFO QueryLogger: --- will run 1 query.
    INFO QueryLogger: --- transaction started.
    INFO QueryLogger: SELECT t0.attrib1, t0.attrib2, t0.attrib3 FROM
    public.my_view_6 t0
    INFO QueryLogger: === returned 47 rows. - took 672 ms.
    INFO QueryLogger: +++ transaction committed.
    INFO QueryLogger: --- will run 1 query.
    INFO QueryLogger: --- transaction started.
    INFO QueryLogger: SELECT t0.attrib1 FROM public.my_view_7 t0
    INFO QueryLogger: === returned 1 row. - *took 125687 ms*.
    INFO QueryLogger: +++ transaction committed.

    The last query (with the bolded value) is the one making all the
    trouble: again, considering it returns a single row with a single value
    and it runs well under a second from the pgadmin interface, I can't even
    begin to guess as to why this happens.

    The code I execute varies from query to query, but this is the code of
    the last query:
            DataContext dc = p.getContekst();
            List results= dc.performQuery(new SelectQuery(MyView1.class));
            return ((MyView1)results.get(0)).getAttrib1().intValue();

    If it means/helps anything at all, it's a tapestry application with
    tomcat and postgresql in the same LAN - bandwidth between the two is not
    an issue.

    Tomislav



    This archive was generated by hypermail 2.0.0 : Wed Apr 20 2005 - 07:51:07 EDT