I was asked to provide further details of the performance issues I'm facing.
I have a simple grails app that logs a user into the app (with valid role
permissions) and performs simple CRUD operations on object entities. The
below output is the login sql generated during the login attempt. I am
fetching a user object and saving it to http session. The query is simple,
but takes way too long.
The groovy code is as follows:
def findUserAndRoles(String username, String password) {
def usernameCriteria = ExpressionFactory.matchExp("uid", username)
//def roleCriteria = ExpressionFactory.noMatchExp("roles", null)
def pwdCriteria = [ExpressionFactory.matchExp("pwd",
Rot13.encrypt(password))]
pwdCriteria << ExpressionFactory.matchExp("pwd",
BCrypt.hashpw(password, BCrypt.gensalt()))
def criteria = ExpressionFactory.joinExp(Expression.OR,
pwdCriteria).andExp(usernameCriteria)
def query = new SelectQuery(AppUser, criteria)
query.addPrefetch("roles")//.setSemantics(PrefetchTreeNode.JOINT_PREFETCH_SEMANTICS)
//will return null if no row is found; will throw an exception if
more than 1 row is found
Cayenne.objectForQuery(context, query)
//context.performQuery(query)
}
The output is:
2013-12-16 23:17:51,508 [http-bio-8080-exec-10] INFO
log.CommonsJdbcEventLogger - Opening connection: jdbc:sqlserver://REDACTED
Login: cf_user
Password: *******
2013-12-16 23:17:52,295 [http-bio-8080-exec-10] INFO
log.CommonsJdbcEventLogger - +++ Connecting: SUCCESS.
2013-12-16 23:17:52,325 [http-bio-8080-exec-10] INFO
log.CommonsJdbcEventLogger - Detected and installed adapter:
org.apache.cayenne.dba.sqlserver.SQLServerAdapter
2013-12-16 23:17:52,338 [http-bio-8080-exec-10] INFO
log.CommonsJdbcEventLogger - SELECT t0.ADDRESS_GUID, t0.ARCHIVE_DT,
t0.COUNTRY_CODE, t0.CREATE_DT, t0.CREATE_ID, t0.EMAIL, t0.ENTITY_TYPE_GUID,
t0.FAX_PHONE, t0.FIRST_NAME, t0.ISDELETED, t0.LANGUAGE_CODE,
t0.LAST_ACTIVITY_DT, t0.LAST_NAME, t0.MAIN_PHONE, t0.MIDDLE_NAME,
t0.PUBLIC_KEY, t0.PWD, t0.REGION_CODE, t0.SECURITY_QUESTION_ANSWER,
t0.SECURITY_QUESTION_GUID, t0.SITE_GUID, t0.SSOCODE, t0.TZOFFSET, t0.UID,
t0.UPDATE_DT, t0.UPDATE_ID, t0.APP_USER_GUID FROM EDU_SEC.dbo.APP_USER t0
WHERE ((t0.PWD = ?) OR (t0.PWD = ?)) AND (t0.UID = ?) [bind:
1->PWD:'REDACTED', 2->PWD:'$REDACTED...', 3->UID:'michael.hatch'] -
prepared in 7 ms.
2013-12-16 23:18:21,864 [http-bio-8080-exec-10] INFO
log.CommonsJdbcEventLogger - === returned 1 row. - took 29535 ms.
2013-12-16 23:18:21,872 [http-bio-8080-exec-10] INFO
log.CommonsJdbcEventLogger - SELECT DISTINCT t0.ASSIGN_ALL_SITES,
t0.CODE, t0.CREATE_DT, t0.CREATE_ID, t0.DEFAULT_ROLE, t0.DESCRIPTION,
t0.isExclusive, t0.PERMISSION_BIT_CODE, t0.PRODUCT_GUID, t0.SORT_ORDER,
t0.UPDATE_DT, t0.UPDATE_ID, t0.ROLE_GUID, t2.APP_USER_GUID FROM
EDU_SEC.dbo.ROLE t0 JOIN EDU_SEC.dbo.USER_ROLE t1 ON (t0.ROLE_GUID =
t1.ROLE_GUID) JOIN EDU_SEC.dbo.APP_USER t2 ON (t1.APP_USER_GUID =
t2.APP_USER_GUID) WHERE ((t2.PWD = ?) OR (t2.PWD = ?)) AND (t2.UID = ?)
[bind: 1->PWD:'REDACTED', 2->PWD:'$REDACTED...', 3->UID:'michael.hatch'] -
prepared in 7 ms.
2013-12-16 23:18:25,488 [http-bio-8080-exec-10] INFO
log.CommonsJdbcEventLogger - === returned 9 rows. - took 3623 ms.
2013-12-16 23:18:25,488 [http-bio-8080-exec-10] INFO
log.CommonsJdbcEventLogger - +++ no commit - transaction controlled
externally.
The first sql statement is fetching the user info, while the second sql is
for inflating the roles relationship. I understand the documentation
explicitly states that prefetching will inflate relationships for you, but
it still does so via multiple sql commands per relationship, instead of via
a single sql statement with an inner join. Did I simply do something wrong
somewhere?
cayenne-server 3.2M1
sqlServer2012
microsoft sqlserver driver
Hi Michael,
> This email is probably not the best medium to voice my concerns.
I am forwarding this to the user list, so that others can participate in
this discussion. Make sure you don’t miss the replies either by subscribing
or by following the archives:
http://cayenne.apache.org/mailing-lists.html
> That's when I decided to modify the source and it worked.
Maybe you can post a diff with your change?
> The site lists success stories, does that include success with legacy
schemas?
Absolutely. I have a bunch of those.
> Having a terribly difficult time getting solid performance. I dump the
generated SQL to my console log and the simplest of queries take a few
seconds. If I throw in a join it's worse.
Performance problem can be caused by many things. From SQL not hitting the
indexes, to slow network, to large number of rows returned in a single
query, etc. Could you provide more details - type and version of the DB,
the number of rows returned, any special network details? Maybe a sample of
your Cayenne log..
