EntitySave EXTREMELY slow in production

[Brian H.]

Here is an odd problem. The exact same script creating entities and
calling EntitySave runs about 100 times slower (literally) on my
production machine than on my development workstation!

I have a ORM powered app that has a loop that creates invoice
entities, each containing a large number of other nested entities. On
my development workstation, a 2.8GHz Core2 Duo with 6GB of ram, the
EntitySave() step in the loop takes 40ms each to run.

On two separate production machines tested (both same config), 2.66GHz
Core2 Quad with 4GB of ram, the EntitySave step takes about 1.4
seconds per call!

I am measuring this by using a trace before and after the EntitySave()
code.

-Both Coldfusion instances are 9.0.1.274733.
-Both use same JRE: v1.6.0_17, VM v14.3-b01
-Dev is Windows 7, Prod is Windows 2003, both 64bit
-Dev is MySQL 5.1.48 while Prod is 5.0.91.
-Database structure (indexes) are identical
-Debugging is disabled on both machines.
-CF Admin server monitoring / profiling / memory tracing is disabled
on both machines.

One thing that is strange is while this loop is running VERY slowly,
the CPU usage on the server is dead (like 5%). Also, the rest of the
site on the production machine seems fine.

To isolate the problem I wrote a basic test script that loops and
creates simple flat entities and saves them, 1000 times. On my local
machine, it takes 755ms to create and save 1000 entities, while on the
server, it takes 72 seconds!!! Again, the Child entity is VERY basic
so should save without a problem.

Here is my test script:

<cfset ChildService =
application.servicefactory.getBean("ChildService")>
<cfset tick = getTickCount()>
<cfloop from="1" to="1000" index="i">
<cfset child = EntityNew("Child")>
<cfset child.setFirstName("child#i#")>
<cfset EntitySave(child)>
</cfloop>
<cfthrow message="Time: #getTickCount() - tick#ms">

Any help would be appreciated.

-Brian

[John Whish]

Could be an issue with the database trying to get a lock to get the
new identifier (as your CPU is so slow). Other things to look for are
database triggers and I assume you're testing on your dev box with an
export of the production database as more records may cause issues.
Also are you clustering the database / missing indexes etc.

> --
> You received this message because you are subscribed to the Google Groups "cf-orm-dev" group.
> To post to this group, send email to cf-or...@googlegroups.com.
> To unsubscribe from this group, send email to cf-orm-dev+...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/cf-orm-dev?hl=en.
>
>

[Brian H.]

Dev and Production JVM Arguments are identical:

-server -Dsun.io.useCanonCaches=false -XX:MaxPermSize=192m -XX:
+UseParallelGC -Xbatch -Dcoldfusion.rootDir={application.home}/../ -
Dcoldfusion.libPath={application.home}/../lib

Dev: Maximum JVM Heap Size: 512MB
Prod: Maximum JVM Heap Size: 1024MB

-Brian

[Brian H.]

Hey John.

Thanks for the suggestions. I am running an identical DB with exactly
the same records, indexes, etc. No DB triggers. The CPU of my
workstation and server are almost identical, so that shouldn't be an
issue. No clustering involved.

Any suggestions as to how I would determine if the DB is hanging up?

-Brian

On Jun 29, 4:22 am, John Whish <john.wh...@googlemail.com> wrote:
> Could be an issue with the database trying to get a lock to get the
> new identifier (as your CPU is so slow). Other things to look for are
> database triggers and I assume you're testing on your dev box with an
> export of the production database as more records may cause issues.
> Also are you clustering the database / missing indexes etc.
>

[John Whish]

I've heard good things about http://www.jetprofiler.com/ for MySQL
profiling, so that could be a good place to start.

[Brian H.]

Interesting. You might be right John. I turned on MySQL logging to
see the SQL that ORM was creating and it is this:

SET NAMES latin1;
SET character_set_results = NULL;
SET SESSION TRANSACTION ISOLATION LEVEL READ COMMITTED;
INSERT INTO Child (firstName, lastName, sex, dateOfBirth,
healthCardNumber, medicalConditions, otherAllergies, sickDaysAllowed,
vacationDaysAllowed, depositRequested, deleted, copayType,
copayAmount, Facility_id, Doctor_id, DefaultLocation_id) VALUES
('child1', NULL, NULL, NULL, NULL, NULL, NULL, NULL, NULL, NULL, 0,
'No', NULL, NULL, NULL, NULL);

I execute this locally and it runs with no measurable amount of time.
On the server however, it takes anywhere from 16ms to 47ms. Seems like
MySQL on the server runs inserts 10x slower! That's not cool.

I have an Intel Solid State drive on my workstation. Hopefully that
hasn't been giving me an unrealistic view of real-world DB
performance.....

I added another test loop to my test script to get cfquery based SQL
along side the ORM and I got almost the same DB performance! So it
looks like crappy DB performance after all : ( 2000ms to perform 100
inserts!

<cfset tick = getTickCount()>
<cfloop from="1" to="100" index="i">

<cfset child = EntityNew("Child")>
<cfset child.setFirstName("child#i#")>
<cfset EntitySave(child)>
</cfloop>

<cfset endtick = getTickCount()>

<cfset tick2 = getTickCount()>
<cfloop from="1" to="100" index="i">
<cfquery>
INSERT INTO Child (firstName, lastName, sex, dateOfBirth,
healthCardNumber, medicalConditions, otherAllergies, sickDaysAllowed,
vacationDaysAllowed, depositRequested, deleted, copayType,
copayAmount, Facility_id, Doctor_id, DefaultLocation_id) VALUES
('child1', NULL, NULL, NULL, NULL, NULL, NULL, NULL, NULL, NULL, 0,
'No', NULL, NULL, NULL, NULL);
</cfquery>
</cfloop>

<cfthrow message="Time for ORM: #endTick - tick#ms and Time for Query:
#getTickCount() - tick2#">


-Brian


On Jun 29, 4:37 am, John Whish <john.wh...@googlemail.com> wrote:
> I've heard good things abouthttp://www.jetprofiler.com/for MySQL

> profiling, so that could be a good place to start.
>

[John Whish]

From what you were describing it did sound like a database issue -
don't blame ColdFusion! :P

You should check the defragmentation of the production server (I
schedule defragmention on Window servers using defraggler). May be
worth downgraded MySQL locally to the same as the production server to
see if it's a problem that's already been fixed in MySQL.

[Brian H.]

Thanks John. Going to try a defrag and an upgrade to 5.1.57.

In your experience, 2000ms for 100 indexed (3 indexes) inserts for a
simple query like I have above is not normal, correct?

-Brian

On Jun 29, 5:14 am, John Whish <john.wh...@googlemail.com> wrote:
> From what you were describing it did sound like a database issue -
> don't blame ColdFusion! :P
>
> You should check the defragmentation of the production server (I
> schedule defragmention on Window servers using defraggler). May be
> worth downgraded MySQL locally to the same as the production server to
> see if it's a problem that's already been fixed in MySQL.
>

[Brian H.]

Turns out innoDB INSERT performance was slow as by default it was set
to full ACID compliance mode (writing out log way too often).

Adjusting the MySQL config setting innodb_flush_log_at_trx_commit from
1 to 0 caused a tremendous performance improvement (2 orders of
magnitude).

From the config:

# If set to 1, InnoDB will flush (fsync) the transaction logs to the
# disk at each commit, which offers full ACID behavior. If you are
# willing to compromise this safety, and you are running small
# transactions, you may set this to 0 or 2 to reduce disk I/O to the
# logs. Value 0 means that the log is only written to the log file and
# the log file flushed to disk approximately once per second. Value 2
# means the log is written to the log file at each commit, but the log
# file is only flushed to disk approximately once per second.

Again, not a CF or an ORM problem.

-Brian