ORM EntityLoad() taking forever- Tomcat correctly logs actual time taken but Lucee debug says fast

Lucee 4.5 on Windows 10.

I have a FW/1 application. I’ve narrowed this down to (for example) a
single simple entity load in the controller:

rc.companies = entityLoad(“Company”, {active = 1}, “name asc”);

This entity has around 100 records. There’s around 1000 in a linked
“Members” entity.

With this in the controller and nothing else, it takes 60-250 seconds, even
if it is the only thing in the controller and I output nothing in the view.

It’s inconsistent, sometimes it will actually come back fast, sometimes 60
secs, sometimes 250, occasionally goes to 300 and times out. But usually
60-75. No obvious pattern.

Lucee in the debug information can’t see it is taking this long, it is
telling me the page is taking one second or less.

Tomcat when set to log page duration logs it correctly- 60-70 seconds. So
Lucee is missing, or not recording something here.

The entity does have children. If I set lazy=“true” on the relationships,
the load will come back reasonably fast- like 3-4 seconds. I DO think this
is still slow, and indicates something wrong, but it’s faster. But the
problem then comes back when I put the output back, it’s back to glacial.

It’s not specific to this one, though, I’ve seen the same behaviour with
another simple pair of entities which were just Countries (250 or so) and
States (80 or so). It seems to affect anything with 100+ records, it slows
to a crawl. Possibly only an issue if relationships are involved.

Now the bizarre stuff- the exact same code is running fine in production on
Railo 4.2 (on Linux) and comes back quickly (under a second).

If I take this line OUT of the FW/1 app in my Lucee 4.5 dev environment and
just run it by itself, it comes back quick, under a second. That’s with all
the output, it’s fast.

So it is some interaction of Lucee, FW/1, and whatever else we have in the
app.

Any ideas? It is driving me mad. Pointers to things to try/look at
appreciated.

If your entities all have relationships with lazy = false, the issue could
possibly be that you are trying to load too many objects and you simply
don’t have sufficient memory available.

That said, on a practical basis, I would not use ORM to load more than a
single instance of an entity, but simply get the data you need using sql.
My guess is that you are displaying a list of active companies, but by
using ORM for this, you are loading, it seems, at least 1100 objects in
memory including the linked Members, and Members may be linked to other
entities if lazy loading is set to false - which could graph out to a
significant chunk of the database with all the methods that are included in
an ORM object. I would ask why. Do you need the methods on all those object
available for what you are trying to accomplish? My guess would be that you
don’t.

As to why it worked before and it doesn’t work now, you may have more
memory in production, or it may be that under the covers, a newer version
of hibernate, or the code between hibernate and Railo / Lucee, is handling
this differently. Memory you can figure out, the stuff under the covers is
practically inaccessible in the sense that if it isn’t working, you can’t
do much about it. The fact that it is nicely abstracted away is a
double-edged sword.

Sql isn’t abstracted away, so you write “select id, name from Company where
active = 1 order by name” and use that instead, and your performance will
likely be significantly better, and reliably so, even with little memory
available, and no matter what happens with hibernate or the code
integrating it with Lucee.

Could be completely off base without direct access to your code and
requirements, so my apologies in advance if this is the case.

Aria Media Sagl
+41 (0)76 303 4477 cell
skype: ariamediaOn Sat, Sep 3, 2016 at 6:26 PM, Ivan McAvinchey <@Ivan_McAvinchey> wrote:

Lucee 4.5 on Windows 10.

I have a FW/1 application. I’ve narrowed this down to (for example) a
single simple entity load in the controller:

rc.companies = entityLoad(“Company”, {active = 1}, “name asc”);

This entity has around 100 records. There’s around 1000 in a linked
“Members” entity.

With this in the controller and nothing else, it takes 60-250 seconds,
even if it is the only thing in the controller and I output nothing in the
view.

It’s inconsistent, sometimes it will actually come back fast, sometimes 60
secs, sometimes 250, occasionally goes to 300 and times out. But usually
60-75. No obvious pattern.

Lucee in the debug information can’t see it is taking this long, it is
telling me the page is taking one second or less.

Tomcat when set to log page duration logs it correctly- 60-70 seconds. So
Lucee is missing, or not recording something here.

The entity does have children. If I set lazy=“true” on the relationships,
the load will come back reasonably fast- like 3-4 seconds. I DO think this
is still slow, and indicates something wrong, but it’s faster. But the
problem then comes back when I put the output back, it’s back to glacial.

It’s not specific to this one, though, I’ve seen the same behaviour with
another simple pair of entities which were just Countries (250 or so) and
States (80 or so). It seems to affect anything with 100+ records, it slows
to a crawl. Possibly only an issue if relationships are involved.

Now the bizarre stuff- the exact same code is running fine in production
on Railo 4.2 (on Linux) and comes back quickly (under a second).

If I take this line OUT of the FW/1 app in my Lucee 4.5 dev environment
and just run it by itself, it comes back quick, under a second. That’s with
all the output, it’s fast.

So it is some interaction of Lucee, FW/1, and whatever else we have in the
app.

Any ideas? It is driving me mad. Pointers to things to try/look at
appreciated.


Get 10% off of the regular price for this years CFCamp in Munich, Germany
(Oct. 20th & 21st) with the Lucee discount code Lucee@cfcamp. 189€
instead of 210€. Visit https://ti.to/cfcamp/cfcamp-
2016/discount/Lucee@cfcamp

You received this message because you are subscribed to the Google Groups
“Lucee” group.
To unsubscribe from this group and stop receiving emails from it, send an
email to lucee+unsubscribe@googlegroups.com.
To post to this group, send email to lucee@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/
msgid/lucee/84049170-e72e-44f5-99ac-285727639fe4%40googlegroups.com
https://groups.google.com/d/msgid/lucee/84049170-e72e-44f5-99ac-285727639fe4%40googlegroups.com?utm_medium=email&utm_source=footer
.
For more options, visit https://groups.google.com/d/optout.

@Nando-

Jochem had the answer to my problem on another thread- it’s the debug
output. If I turn that off it comes back quick; that’s the relevant
difference between production and my dev environment. It’s the debug output
enumerating over the scopes at the end of the request that is the issue.

I noticed looking at this in the debug output I had 730MB in my request
scope- so the difference between running this IN the FW/1 framework and
outside it was that FW/1 copies anything you put in rc. into the request
scope. And then the Lucee debug tries to enumerate that scope. When it was
all in my one test page rc. wasn’t getting copied into the request scope
and so Lucee debug didn’t have anything in there to enumerate. So no
problem.

So- follow up question, and your thoughts are much appreciated- is it
inherently a problem to have the guts of a gig in my request scope? I am
presuming this is the entity and a load of children. Are they all really
“there” in the first place, or do they only materialise themselves when
Lucee debug tries to enumerate the scope? With debug off, if I look at
process explorer while loading the page, memory use (private bytes) only
jumps up briefly by 30MB, so I’m wondering if this 730MB is really there at
all or rather is an artefact of the debugger looping over the entire scope
to enumerate it.

And if it IS a problem, what should I do to avoid it-

What I do is use SQL. As an experiment, you might try reworking the company
list using SQL and then check and compare memory consumption, since you are
in the middle of this. Then you’ll have some data to help make a decision,
or at least to better understand how much overhead loading all those
objects takes.

You might also time the request using getTickCount() before and after the
data call in your controller, subtracting the difference to get a result.

I’m thinking lazy loading and using a HQL SELECT to specify exactly what I
want and get that back only, not “everything”.

You can give this a try as well and again compare memory consumption and
time.

Report back if you like.On Sun, Sep 4, 2016 at 2:56 PM, Ivan McAvinchey <@Ivan_McAvinchey> wrote:


Get 10% off of the regular price for this years CFCamp in Munich, Germany
(Oct. 20th & 21st) with the Lucee discount code Lucee@cfcamp. 189€
instead of 210€. Visit https://ti.to/cfcamp/cfcamp-
2016/discount/Lucee@cfcamp

You received this message because you are subscribed to the Google Groups
“Lucee” group.
To unsubscribe from this group and stop receiving emails from it, send an
email to lucee+unsubscribe@googlegroups.com.
To post to this group, send email to lucee@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/
msgid/lucee/4f943ce8-5826-4477-80d7-1bf350f6c3e1%40googlegroups.com
https://groups.google.com/d/msgid/lucee/4f943ce8-5826-4477-80d7-1bf350f6c3e1%40googlegroups.com?utm_medium=email&utm_source=footer
.

For more options, visit https://groups.google.com/d/optout.

@Nando-

Jochem had the answer to my problem on another thread- it’s the debug
output. If I turn that off it comes back quick; that’s the relevant
difference between production and my dev environment. It’s the debug output
enumerating over the scopes at the end of the request that is the issue.

I noticed looking at this in the debug output I had 730MB in my request
scope- so the difference between running this IN the FW/1 framework and
outside it was that FW/1 copies anything you put in rc. into the request
scope. And then the Lucee debug tries to enumerate that scope. When it was
all in my one test page rc. wasn’t getting copied into the request scope
and so Lucee debug didn’t have anything in there to enumerate. So no
problem.

So- follow up question, and your thoughts are much appreciated- is it
inherently a problem to have the guts of a gig in my request scope? I am
presuming this is the entity and a load of children. Are they all really
“there” in the first place, or do they only materialise themselves when
Lucee debug tries to enumerate the scope? With debug off, if I look at
process explorer while loading the page, memory use (private bytes) only
jumps up briefly by 30MB, so I’m wondering if this 730MB is really there at
all or rather is an artefact of the debugger looping over the entire scope
to enumerate it.

And if it IS a problem, what should I do to avoid it- I’m thinking lazy
loading and using a HQL SELECT to specify exactly what I want and get that
back only, not “everything”.

You can add lazy=true to the related properties and that should help.

Mark Drew

  • Sent by typing with my thumbs.> On 4 Sep 2016, at 07:56, Ivan McAvinchey <@Ivan_McAvinchey> wrote:

@Nando-

Jochem had the answer to my problem on another thread- it’s the debug output. If I turn that off it comes back quick; that’s the relevant difference between production and my dev environment. It’s the debug output enumerating over the scopes at the end of the request that is the issue.

I noticed looking at this in the debug output I had 730MB in my request scope- so the difference between running this IN the FW/1 framework and outside it was that FW/1 copies anything you put in rc. into the request scope. And then the Lucee debug tries to enumerate that scope. When it was all in my one test page rc. wasn’t getting copied into the request scope and so Lucee debug didn’t have anything in there to enumerate. So no problem.

So- follow up question, and your thoughts are much appreciated- is it inherently a problem to have the guts of a gig in my request scope? I am presuming this is the entity and a load of children. Are they all really “there” in the first place, or do they only materialise themselves when Lucee debug tries to enumerate the scope? With debug off, if I look at process explorer while loading the page, memory use (private bytes) only jumps up briefly by 30MB, so I’m wondering if this 730MB is really there at all or rather is an artefact of the debugger looping over the entire scope to enumerate it.

And if it IS a problem, what should I do to avoid it- I’m thinking lazy loading and using a HQL SELECT to specify exactly what I want and get that back only, not “everything”.

Get 10% off of the regular price for this years CFCamp in Munich, Germany (Oct. 20th & 21st) with the Lucee discount code Lucee@cfcamp. 189€ instead of 210€. Visit https://ti.to/cfcamp/cfcamp-2016/discount/Lucee@cfcamp

You received this message because you are subscribed to the Google Groups “Lucee” group.
To unsubscribe from this group and stop receiving emails from it, send an email to lucee+unsubscribe@googlegroups.com.
To post to this group, send email to lucee@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/lucee/4f943ce8-5826-4477-80d7-1bf350f6c3e1%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Some good food for thought there, thanks.

I am still sceptical about ORM myself, I can assure you, but this isn’t an
application or framework that I wrote to start with so I have to work with
what is there and conventions and standards that precede me.

I’ve already moved to using SQL rather than ORM for stuff like reporting
queries which was an absolute clusterfuck in ORM but if you could suspend
your specific antipathy towards ORM for a second, *at least theoretically *it
should be possible to load an entity with one hundred records and a
thousand (total) children and then reference them, no? Like this isn’t an
extreme case, surely. If it was SQL and a query object this would be no
issue.

I don’t need all the relationships and methods, no- so what’s the
alternative here? Specify exactly what I do want and that only using a
SELECT in HQL rather than using EntityLoad()?

I’ve already moved to using SQL rather than ORM for stuff like reporting
queries which was an absolute clusterfuck in ORM but if you could suspend
your specific antipathy towards ORM for a second, *at least theoretically
*it should be possible to load an entity with one hundred records and a
thousand (total) children and then reference them, no? Like this isn’t an
extreme case, surely.

It’s not antipathy, just experience and practicality that gives rise to my
suggestion to use SQL to get the data you need for multiple objects,
because …

If it was SQL and a query object this would be no issue.

Exactly.

Theoretically, you should be able to use ORM for everything. But that’s as
far as it goes. Practically. you’re consuming many times more server
resources than necessary by doing so. Today’s issue with this construct was
your inability to use debug output. Tomorrow’s may be memory issues under a
bit more load than normal, which shouldn’t really happen on a view
displaying a hundred item list.

I find ORM convenient, within limits, when dealing with a single entity.
That said, I’ve run into various intractable issues with it, so my overall
opinion is mixed. I don’t think I will use it for a major project again.

I noticed looking at this in the debug output I had 730MB in my request
scope- so the difference between running this IN the FW/1 framework and
outside it was that FW/1 copies anything you put in rc. into the request
scope.

rc is a reference to request.context, so it isn’t really a copy.

So- follow up question, and your thoughts are much appreciated- is it
inherently a problem to have the guts of a gig in my request scope?

I do not believe you actually have a gig in your request scope. That
is again debug output messing things up. I would recommend enabling
all your GC logging options and run some request 100 times. Then from
the GC logging calculate how much memory was cleared during garbage
collection divide by 100 and you have a much more accurate number.

JochemOn Sun, Sep 4, 2016 at 2:56 PM, Ivan McAvinchey wrote:


Jochem van Dieten
http://jochem.vandieten.net/

I need to figure out what I am doing wrong with the ORM that it is so much
slower and resource hungry.

You aren’t doing anything wrong. Loading hundreds to thousands of ORM
entities is simply much slower and more resource hungry.

Send 100 Japanese salarymen to work on the public transit system in Tokyo,
and they get there as efficiently as possible. Require them to all use
campers or buses (objects), pack their extended families into them,
including young children and grandparents (unneeded properties), with all
the supplies they need for the day, water, food, cooking supplies, tables,
chairs (unneeded methods), and the process slows considerably.

Sorry for the dumb analogy. I can’t think of anything else to say at this
point. Always using objects may be much faster in an object oriented
language like Java. It’s not in CFML. Setting lazy=true will help, but
you’re still travelling by car to work, just without having to pick up the
family members that live in other apartments or houses (and possibly all
their family members as well). If and when performance becomes an issue,
you’ve created an unnecessary bottleneck by requiring everyone travel by
car, with all the functionality they need for the day when at home.

By the way, I would not suspect there to be a significant difference in
memory consumption because the data is “copied” to rc scope. That process
is by reference, so there should only be pointers in rc referencing the
data passed into your controllers. In this case:

rc.companies = entityLoad(“Company”, {active = 1}, “name asc”);

I believe that would generate a single pointer in the rc struct,
negligible. If my assumption is wrong, someone here can point it out.

Having debug output turned on is like having a checkpoint on the Japanese
road where all the salarymen and their extended families and all the crap
they’ve brought with them have to get out of the car again so the powers
that be can take inventory. That of course will take time and resources.

Sorry again for the dumb analogy …

@Mark- thanks for the suggestion, I’m going to look at lazy loading but the
converse problem there is that if you actually need the children (and I do)
then you end up generating thousands of queries, which is hardly any better.

@Nando- I’m highly sceptical about using ORM for everything myself but this
isn’t an application or framework I wrote myself and I need to deal with it
according to the coding standards already in place. And that means
understanding how to make it work using ORM, insofar as that is possible. I
know how to do this quickly and efficiently using SQL, I need to figure out
how to do it quickly and efficiently, insofar as that is possible, using
ORM. I’m relatively new to ORM and need to get my head around it fully; I
can accept that it simply isn’t a good choice for the likes of complex
reporting queries (I rewrote one ORM report we had that generated over ten
thousand queries in the background into SQL already) but something like a
simple listing it should surely be able to handle, I just need to know the
things to look at regarding configuration (such as the relationships, lazy
loading, joins in HQL, fetching strategy and so on). I know if I reworked
this in SQL it would be much quicker and use much less memory. I need to
figure out what I am doing wrong with the ORM that it is so much slower and
resource hungry.