What you're showing here in the log doesn't seem to have anything to
do with Cayenne peformance problems.
2013-12-16 23:17:52,338 [http-bio-8080-exec-10] INFO
SELECT
[...t0.*...]
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.
You have a single table simple sql query that takes 29.5 seconds to
return a single row.
Maybe there is a performance problem with how the password field
comparisons are being done on the database server, or maybe you have a
networking issue.
The prefetch statement is the next one, and it only took 3.6 seconds
to return 9 rows (using the same password field comparisons) so
perhaps by this time the result has been cached in the database.
One simple change you could make to test is to change your query to
compare against something other than PWD (maybe just UID) and see what
kind of difference that makes. If no difference, then you've got
general server or network problems. If it makes a huge difference,
then the PWD field on your database is likely the cause.
On Tue, Dec 17, 2013 at 12:29 PM, Michael Hatch <mvha...@gmail.com> wrote:
> 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..
