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

[Ivan McAvinchey]

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.

[Nando Breiter]

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: ariamedia

--
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 lu...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/lucee/84049170-e72e-44f5-99ac-285727639fe4%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Ivan McAvinchey]

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()?

[Ivan McAvinchey]

@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".

[Mark Drew]

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

Mark Drew

- Sent by typing with my thumbs. 

--

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+un...@googlegroups.com.

To post to this group, send email to lu...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/lucee/4f943ce8-5826-4477-80d7-1bf350f6c3e1%40googlegroups.com.

[Nando Breiter]

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.

 

--
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 lu...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/lucee/4f943ce8-5826-4477-80d7-1bf350f6c3e1%40googlegroups.com.

[Nando Breiter]

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.

[Ivan McAvinchey]

@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.

[Nando Breiter]

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 ...

[Jochem van Dieten]

On Sun, Sep 4, 2016 at 2:56 PM, Ivan McAvinchey wrote:
> 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.

Jochem

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