[coldbox-4.0][cborm-"1.0.0+00009"] odd ORM issue

Communities ColdBox HMVC
1

i’m having a problem after creating a new model and handler. it seems ORM just locks up completely or takes 5+ minutes to return when calling get(). ive tried replacing the virtualservice with just an EntityLoad(“CampaignAd”,rc.ad_id) and get same behavior. i have a feeling it’s an ORM issue…but not sure where to look. ormlogging it turned on but I don’t see anything in coldfusion-out.log?

what’s even wierder is that i have another model written for another table and that one works just fine…

any ideas how to figure out what’s wrong? I’m guessing something configuration since it works for everyone else…but don’t know where to even start looking.

models/CampaignAd.cfc:
`
component persistent=“true” name=“CampaignAd” table=“campaignad” accessors=“true” extends=“cborm.models.ActiveEntity”
{
property name=“ad_id” column=“ad_id” type=“numeric” fieldtype=“id” generator=“sequence” params="{sequence=‘ad_seqno’}";
property name=“product_cd” column=“product_cd” type=“string”;
…(100 diff columnns)

public void function init() {
super.init(useQueryCaching=false);
};
}

`

handlers/CampaignAdService.cfc

`
component output=“false” accessors=“true”
{

property name=“campaignAdService” inject=“entityService:CampaignAd”;

function get(event, rc, prc) output=“true” hint=“Get existing ad”
{
prc.response=getModel(“ResponseObject”);
try {

param name=“rc.ad_id” default=“0”;
prc.response.add(campaignAdService.get(rc.ad_id));

} catch (any e) {
prc.response.error(“ERROR_CAMPAIGN_GET”);
prc.response.addError(e.message & e.detail & " code " & ListFirst(ListLast(e.tagContext[1].template,"/"),".") & “-” & e.tagContext[1].line);
}
event.setView(“WS_JSON”);
}

}

`

2

Pull a stack trace to see what the server is doing while it “locks up”.

Thanks!

~Brad

ColdBox Platform Evangelist
Ortus Solutions, Corp

E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com

3

If you have 100 different columns(!) in your CampaignAd model and table, as stated below, you’re going to have issues with loading recordsets from that model in to memory - especially if you have relationship properties to other models.

Adjusting the following two ORM settings to what’s shown below will help a bit, but you might want to re-think your table storage and its relationships.

dbcreate = "none",
useDBForMapping=false,

Jon

4

100+ wide table seems like a concern to me. You can see the generated SQL if you view the console. My guess is that you have unexpected/undesired querying taking place.

5

already have those two settings. it’s existing db that i’m trying to apply cb/orm onto.

6

with cf debug, it’s spending 96seconds in VirtualEntityService.cfc which is crazy.

i’ve also reduced the model to just 5 fields to try it out, did a ormReload() still same thing.

the model+table that works fine only has 5 fields in the model but about 70 fields in the table. i don’t see the huge difference from 1second to 96seconds

Execution Time

Total Time Avg Time Count Template
97049 ms 97049 ms 1 CFC[ /home/tcprod/yruan/projects/5.1.3_Winter_Games_coldbox/dmp/Application.cfc | onRequestStart(/dmp/index_cb.cfm) ] from /home/tcprod/yruan/projects/5.1.3_Winter_Games_coldbox/dmp/Application.cfc
96667 ms 96667 ms 1 CFC[ /home/tcprod/yruan/projects/5.1.3_Winter_Games_coldbox/coldbox/system/web/Controller.cfc | runEvent(defaultEvent = true) ] from /home/tcprod/yruan/projects/5.1.3_Winter_Games_coldbox/coldbox/system/web/Controller.cfc
96428 ms 96428 ms 1 CFC[ /home/tcprod/yruan/projects/5.1.3_Winter_Games_coldbox/dmp/HANDLERS/InsertionService.cfc | _privateInvoker(argCollection = [complex value], method = get) ] from /home/tcprod/yruan/projects/5.1.3_Winter_Games_coldbox/dmp/HANDLERS/InsertionService.cfc
96371 ms 96371 ms 1 CFC[ /home/tcprod/yruan/projects/5.1.3_Winter_Games_coldbox/coldbox/modules/cborm/models/VirtualEntityService.cfc | get(3803679) ] from /home/tcprod/yruan/projects/5.1.3_Winter_Games_coldbox/coldbox/modules/cborm/models/VirtualEntityService.cfc

7

Uh oh on the legacy database design. I’ve been there. The best suggestion I can give you, for the benefit of your app, is to refactor your schema for that table out to a better relational model. That may not be an option, though.

The other option is to set those properties that are non-essential on every load of that model as persistent=false and use a separate helper function to load them separately from a query when you need them. (e.g. - this.getExtraFields() )

The reason your 5 property/ 70 columns model works so fast is because hibernate doesn’t have to deal with those columns in HQL generation or and VirtualEntityService doesn’t have to deal with them either in property mapping and scoping, they are loaded with the query because they just exist in the table.

If you’re mainly working with query objects, then removing the non-essential columns as ORM properties will speed things up.

HTH, Jon

8

Turn off “report page execution times”. That could be your problem right there. That setting is bad, bad news and should never be enabled.

Thanks!

~Brad

ColdBox Platform Evangelist
Ortus Solutions, Corp

E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com

9

The number of properties is important, but the type of properties is arguably more important. You said that you experienced the same slowness by using entityLoad() directly, and I suggest you troubleshoot this without VirtualEntityService in the mix at all. As I said, look at the generated SQL. You might find a fetching strategy on one or more relationships is causing unnecessary querying.

10

one of the slow loading ones.

`

12:54:36.125 [ajp-bio-8016-exec-7] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 14235944761
12:54:36.127 [ajp-bio-8016-exec-7] DEBUG org.hibernate.loader.Loader - loading entity: [Insertion#3803679.0]
12:54:36.127 [ajp-bio-8016-exec-7] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:54:36.127 [ajp-bio-8016-exec-7] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:54:36.128 [ajp-bio-8016-exec-7] DEBUG org.hibernate.SQL -
select
insertion0_.insertion_id as insertion1_122_0_,
insertion0_.product_cd as product2_122_0_,
insertion0_.start_dt as start3_122_0_,
insertion0_.end_dt as end4_122_0_
from
insertion insertion0_
where
insertion0_.insertion_id=?
Hibernate:
select
insertion0_.insertion_id as insertion1_122_0_,
insertion0_.product_cd as product2_122_0_,
insertion0_.start_dt as start3_122_0_,
insertion0_.end_dt as end4_122_0_
from
insertion insertion0_
where
insertion0_.insertion_id=?
12:56:17.727 [ajp-bio-8016-exec-7] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
12:56:17.728 [ajp-bio-8016-exec-7] DEBUG org.hibernate.loader.Loader - result row: EntityKey[Insertion#3803679.0]
12:56:17.739 [ajp-bio-8016-exec-7] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
12:56:17.740 [ajp-bio-8016-exec-7] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:56:17.740 [ajp-bio-8016-exec-7] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:56:17.740 [ajp-bio-8016-exec-7] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:56:17.740 [ajp-bio-8016-exec-7] DEBUG org.hibernate.engine.TwoPhaseLoad - resolving associations for [Insertion#3803679.0]
12:56:17.740 [ajp-bio-8016-exec-7] DEBUG org.hibernate.engine.TwoPhaseLoad - done materializing entity [Insertion#3803679.0]
12:56:17.740 [ajp-bio-8016-exec-7] DEBUG o.h.e.StatefulPersistenceContext - initializing non-lazy collections
12:56:17.740 [ajp-bio-8016-exec-7] DEBUG org.hibernate.loader.Loader - done entity load
12:56:17.740 [ajp-bio-8016-exec-7] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection

`

a fast one…looks…pretty same

`
12:57:51.791 [ajp-bio-8016-exec-9] DEBUG org.hibernate.impl.SessionImpl - initializing proxy: [Contact#10000.0]
12:57:51.791 [ajp-bio-8016-exec-9] DEBUG org.hibernate.loader.Loader - loading entity: [Contact#10000.0]
12:57:51.791 [ajp-bio-8016-exec-9] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:57:51.791 [ajp-bio-8016-exec-9] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:57:51.791 [ajp-bio-8016-exec-9] DEBUG org.hibernate.SQL -
select
contact0_.contact_id as contact1_125_0_,
contact0_.company_id as company2_125_0_,
contact0_.first_name as first3_125_0_,
contact0_.last_name as last4_125_0_,
contact0_.email as email125_0_,
contact0_.title as title125_0_,
contact0_.last_mod_ts as last7_125_0_
from
contact contact0_
where
contact0_.contact_id=?
Hibernate:
select
contact0_.contact_id as contact1_125_0_,
contact0_.company_id as company2_125_0_,
contact0_.first_name as first3_125_0_,
contact0_.last_name as last4_125_0_,
contact0_.email as email125_0_,
contact0_.title as title125_0_,
contact0_.last_mod_ts as last7_125_0_
from
contact contact0_
where
contact0_.contact_id=?
12:57:52.125 [ajp-bio-8016-exec-9] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
12:57:52.125 [ajp-bio-8016-exec-9] DEBUG org.hibernate.loader.Loader - result row: EntityKey[Contact#10000.0]
12:57:52.128 [ajp-bio-8016-exec-9] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
12:57:52.128 [ajp-bio-8016-exec-9] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:57:52.128 [ajp-bio-8016-exec-9] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:57:52.128 [ajp-bio-8016-exec-9] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:57:52.128 [ajp-bio-8016-exec-9] DEBUG org.hibernate.engine.TwoPhaseLoad - resolving associations for [Contact#10000.0]
12:57:52.129 [ajp-bio-8016-exec-9] DEBUG org.hibernate.engine.TwoPhaseLoad - done materializing entity [Contact#10000.0]
12:57:52.129 [ajp-bio-8016-exec-9] DEBUG o.h.e.StatefulPersistenceContext - initializing non-lazy collections
12:57:52.129 [ajp-bio-8016-exec-9] DEBUG org.hibernate.loader.Loader - done entity load

`

11

is the actual SQL statement taking the time, or the CF processing after the SQL? If it’s the SQL, try it out in SSMS and analyze the query plan. If it’s the CF processing after, pull stack traces.

Also, did you disable the report execution times setting in debugging.

Thanks!

~Brad

ColdBox Platform Evangelist
Ortus Solutions, Corp

E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com

12

how would i find that? for sure if i run the sql statement in either oracle sql developer or even in a cfquery, it runs super fast. how would i do a stack trace?

13
  • ColdFusion Enterprise will pull a stack trace from the server monitor.
  • Tools such as Fusion Reactor or SeeFusion will also pull them for you
  • You can do it from the CommandLine with the Java process.

I recommend Fusion Reactor. 30-day trial. Look at several thread traces while it’s executing to get an idea of what parts of the code are getting the most amount of time spent on them.

Did you turn off the page execution time in your debugging?

An extra sentence just in case you don’t aren’t reading the last sentence in my E-mails.

Thanks!

~Brad

ColdBox Platform Evangelist
Ortus Solutions, Corp

E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com

14

yea i did turn off debug execution times. i’ll check server monitor. i’ve used fusionreactor before too. might install and see.

15

`
// Get existing insertion.
function get(event, rc, prc) output=“true” hint=“Get existing insertion”
{
prc.response=getModel(“ResponseObject”);

try {
param name=“rc.universal_id” default=“0”;
prc.insertion=entityLoad(“Insertion”,3803679);
prc.response.success(prc.insertion);

} catch (any e) {
prc.response.error(“ERROR_INSERTION_GET”);
prc.response.addError(e.message & e.detail & " code " & ListFirst(ListLast(e.tagContext[1].template,"/"),".") & “-” & e.tagContext[1].line);
}

}
`

stacktrace. it doesn’t seem like provides much info. yea i’m doing the EntityLoad for 90+ seconds and then everything returns. it feels like waiting for a timeout. i’ll try fusionreactor and see if that provides me with more detail

16

Sorry, that’s not a full stack trace, just a tag stack. The difference is a tag stack only shows you the sequence of CF files processed, whereas a full stack traces shows you all the way down to the Java code running behind the scenes.

Thanks!

~Brad

ColdBox Platform Evangelist
Ortus Solutions, Corp

E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com

17

channeling mel brooks aha!

property name=“insertion_id” column=“insertion_id” type=“numeric” fieldtype=“id” generator=“sequence” params="{sequence=‘insertion_seqno’}" ormtype=“double”;

if i remove ormtype=“double”, it speeds up. but i’m reading docs and that’ll default to string. so that’s not what we want. i chose ormtype=“integer” instead and it stills seems to be fast! i hope that’s it…