12 Replies Latest reply on Jan 21, 2003 11:44 AM by sseaman

    Query taking to long

      I've got a piece of code that sets a rleationship between two entity objects. For some reason JBoss seems to be doing a query that isn't really needed. On top of that, the query takes over 2 minutes to run so it is killing my performance.

      Here is the code snippit:
      Context ctx = new InitialContext();
      ContactTypeHome contactTypeHome = (ContactTypeHome)ctx.lookup(EJBConstants.JNDI.CONTACT_TYPE);
      ContactType contactType = contactTypeHome.findByPrimaryKey(_contactTypePK);
      logger.debug("ContactInfo retrieved");

      logger.debug("Creating UserContactInfo");
      UserContactInfoHome userContactInfoHome = (UserContactInfoHome)ctx.lookup(EJBConstants.JNDI.USER_CONTACT_INFO);
      Integer pk = (Integer)pkp.getNextPrimaryKeyValue(UserContactInfo.class);
      UserContactInfo userContactInfo = userContactInfoHome.create(pk, _info);
      logger.debug("UserContactInfo created");

      logger.debug("Setting contact type "+contactType.getType()+ " id "+contactType.getContactTypeId());

      // this is the line causing the 2 minute query
      userContactInfo.setContactType(contactType);
      logger.debug("Contact type set");


      Here is the ejb-jar relationship between the two objects:
      <ejb-relation>
      <ejb-relation-name>userContactInfo-contactType</ejb-relation-name>
      <ejb-relationship-role>
      userContactInfo
      <ejb-relationship-role-name>UserContactInfoRelationshipRole</ejb-relationship-role-name>
      Many
      <relationship-role-source>
      userContactInfo
      <ejb-name>UserContactInfo</ejb-name>
      </relationship-role-source>
      <cmr-field>
      contactType
      <cmr-field-name>contactType</cmr-field-name>
      </cmr-field>
      </ejb-relationship-role>
      <ejb-relationship-role>
      contactType
      <ejb-relationship-role-name>ContactTypeRelationshipRole</ejb-relationship-role-name>
      One
      <relationship-role-source>
      contactType
      <ejb-name>ContactType</ejb-name>
      </relationship-role-source>
      </ejb-relationship-role>
      </ejb-relation>


      And here is a snippit from the JBoss log:
      2003-01-14 11:24:58,465 DEBUG [com.schedulestar.leaguecentral.ejb.session.UserManagementBean] Setting contact type
      2003-01-14 11:24:58,465 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCLoadEntityCommand.ContactType] Executing SQL: SELECT contactTypeId,type FROM ContactType WHERE (contactTypeId=?) OR (contactTypeId=?) OR (contactTypeId=?) OR (contactTypeId=?) OR (contactTypeId=?) OR (contactTypeId=?) OR (contactTypeId=?) OR (contactTypeId=?) OR (contactTypeId=?) OR (contactTypeId=?) OR (contactTypeId=?)
      // This is the one taking 2 minutes
      2003-01-14 11:24:58,465 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCLoadRelationCommand.ContactType] Executing SQL: SELECT contactType, userContactInfoId FROM UserContactInfo WHERE (contactType=?) OR (contactType=?) OR (contactType=?) OR (contactType=?) OR (contactType=?) OR (contactType=?) OR (contactType=?) OR (contactType=?) OR (contactType=?) OR (contactType=?) OR (contactType=?)
      2003-01-14 11:27:01,812 DEBUG [com.schedulestar.leaguecentral.ejb.session.UserManagementBean] Contact type set


      Can someone tell me why this is happening? I can't figure it out.

      Thanks!

        • 1. Re: Query taking to long
          lorensrosen

          Can we first try commenting out the line
          logger.debug("Setting contact type "+contactType.getType()+ " id "+contactType.getContactTypeId());

          or at least the two get calls? I want to be sure they're
          not the culprit. I'm suspicious because I see the "Setting
          contact type" part of the output, but not the rest of the
          line.

          • 2. Re: Query taking to long

            The line you mention is not the culprit as I added that line after I figured out what line was causeing the issue.

            I should prob. note that the first time this code runs it executes within a few seconds. The second time results in a few minutes...

            Here is the output w/ the line removed:

            2003-01-16 11:24:49,987 DEBUG [com.schedulestar.leaguecentral.servlet.UserContactInfoAdd] Running doPost()
            2003-01-16 11:24:49,987 DEBUG [com.schedulestar.leaguecentral.servlet.UserContactInfoAdd] Retrieved all parameters
            2003-01-16 11:24:49,987 DEBUG [com.schedulestar.leaguecentral.servlet.UserContactInfoAdd] Getting UserManagement
            2003-01-16 11:24:49,987 DEBUG [com.schedulestar.leaguecentral.servlet.UserContactInfoAdd] Got UserManagement
            2003-01-16 11:24:49,987 DEBUG [com.schedulestar.leaguecentral.servlet.UserContactInfoAdd] Adding contact info
            2003-01-16 11:24:49,987 DEBUG [com.schedulestar.leaguecentral.ejb.session.UserManagementBean] Retrieving ContactInfo
            2003-01-16 11:24:49,987 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCFindByPrimaryKeyQuery.ContactType.findByPrimaryKey] Executing SQL: SELECT contactTypeId FROM ContactType WHERE contactTypeId=?
            2003-01-16 11:24:49,987 DEBUG [com.schedulestar.leaguecentral.ejb.session.UserManagementBean] ContactInfo retrieved
            2003-01-16 11:24:49,987 DEBUG [com.schedulestar.leaguecentral.ejb.session.UserManagementBean] Creating UserContactInfo
            2003-01-16 11:24:49,987 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCCreateEntityCommand.UserContactInfo] Create: pk=com.schedulestar.leaguecentral.ejb.entity.UserContactInfoPK@eda5
            2003-01-16 11:24:49,987 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCCreateEntityCommand.UserContactInfo] Executing SQL: SELECT COUNT(*) FROM UserContactInfo WHERE userContactInfoId=?
            2003-01-16 11:24:49,987 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCCreateEntityCommand.UserContactInfo] Executing SQL: INSERT INTO UserContactInfo (userContactInfoId, info, preferred, User_userContactInfo, contactType) VALUES (?, ?, ?, ?, ?)
            2003-01-16 11:24:49,987 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCCreateEntityCommand.UserContactInfo] Rows affected = 1
            2003-01-16 11:24:49,987 DEBUG [com.schedulestar.leaguecentral.ejb.session.UserManagementBean] UserContactInfo created
            2003-01-16 11:24:49,987 DEBUG [com.schedulestar.leaguecentral.ejb.session.UserManagementBean] Setting Contact type
            2003-01-16 11:24:49,987 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCLoadEntityCommand.ContactType] Executing SQL: SELECT contactTypeId,type FROM ContactType WHERE (contactTypeId=?) OR (contactTypeId=?) OR (contactTypeId=?) OR (contactTypeId=?) OR (contactTypeId=?) OR (contactTypeId=?) OR (contactTypeId=?) OR (contactTypeId=?) OR (contactTypeId=?) OR (contactTypeId=?) OR (contactTypeId=?)
            2003-01-16 11:24:49,997 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCLoadRelationCommand.ContactType] Executing SQL: SELECT contactType, userContactInfoId FROM UserContactInfo WHERE (contactType=?) OR (contactType=?) OR (contactType=?) OR (contactType=?) OR (contactType=?) OR (contactType=?) OR (contactType=?) OR (contactType=?) OR (contactType=?) OR (contactType=?) OR (contactType=?)
            2003-01-16 11:25:33,319 DEBUG [org.jboss.ejb.plugins.LRUEnterpriseContextCachePolicy] Resized cache for bean Formula: old capacity = 1000000, new capacity = 50
            2003-01-16 11:26:47,346 DEBUG [com.schedulestar.leaguecentral.ejb.session.UserManagementBean] Contact type set
            2003-01-16 11:26:47,346 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCStoreEntityCommand.UserContactInfo] Executing SQL: UPDATE UserContactInfo SET preferred=?, contactType=? WHERE userContactInfoId=?
            2003-01-16 11:26:47,346 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCStoreEntityCommand.UserContactInfo] Rows affected = 1
            2003-01-16 11:26:47,346 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCFindByPrimaryKeyQuery.User.findByPrimaryKey] Executing SQL: SELECT userId FROM User WHERE userId=?
            2003-01-16 11:26:47,356 DEBUG [com.schedulestar.leaguecentral.ejb.session.UserManagementBean] Adding contact info to user
            2003-01-16 11:26:47,356 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCLoadEntityCommand.User] Executing SQL: SELECT emailAddress, password, lastLoginDate, firstName, lastName, address1, address2, city, postalCode, title, notes, active, middleName, suffix, certifications, userType, athleticDirector, Boards_user, official, officialsAssigner, state, scheduleManager, parent, leagueContact FROM User WHERE (userId=?)
            2003-01-16 11:26:47,356 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCLoadRelationCommand.User] Executing SQL: SELECT userContactInfoId FROM UserContactInfo WHERE (User_userContactInfo=?)
            2003-01-16 11:26:47,396 DEBUG [com.schedulestar.leaguecentral.ejb.session.UserManagementBean] Contact info added
            2003-01-16 11:26:47,396 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCStoreEntityCommand.UserContactInfo] Executing SQL: UPDATE UserContactInfo SET User_userContactInfo=? WHERE userContactInfoId=?
            2003-01-16 11:26:47,396 DEBUG [org.jboss.ejb.plugins.cmp.jdbc.JDBCStoreEntityCommand.UserContactInfo] Rows affected = 1
            2003-01-16 11:26:47,396 DEBUG [com.schedulestar.leaguecentral.servlet.UserContactInfoAdd] Contact info added


            Here is the whole chunk of code:

            public UserContactInfo addContactInfo(UserPK _userPK, ContactTypePK _contactTypePK,
            String _info, Boolean _preferred)
            throws CreateException
            {
            try {
            logger.debug("Retrieving ContactInfo");
            Context ctx = new InitialContext();
            ContactTypeHome contactTypeHome = (ContactTypeHome)ctx.lookup(EJBConstants.JNDI.CONTACT_TYPE);
            ContactType contactType = contactTypeHome.findByPrimaryKey(_contactTypePK);
            logger.debug("ContactInfo retrieved");

            logger.debug("Creating UserContactInfo");
            UserContactInfoHome userContactInfoHome = (UserContactInfoHome)ctx.lookup(EJBConstants.JNDI.USER_CONTACT_INFO);
            Integer pk = (Integer)pkp.getNextPrimaryKeyValue(UserContactInfo.class);
            UserContactInfo userContactInfo = userContactInfoHome.create(pk, _info);
            logger.debug("UserContactInfo created");

            if (_preferred != null) userContactInfo.setPreferred(_preferred);
            logger.debug("Setting Contact type");
            //logger.debug("Setting contact type "+contactType.getType()+ " id "+contactType.getContactTypeId());
            // This line takes 2 minutes to work sometimes....
            userContactInfo.setContactType(contactType);
            logger.debug("Contact type set");

            UserHome userHome = (UserHome)ctx.lookup(EJBConstants.JNDI.USER);
            User user = userHome.findByPrimaryKey(_userPK);
            logger.debug("Adding contact info to user");
            Collection uci = user.getUserContactInfo();
            uci.add(userContactInfo);
            logger.debug("Contact info added");
            return userContactInfo;
            }
            catch (Exception e) {
            throw new CreateException(e.getMessage());
            }
            }

            Any help would be great!

            • 3. Re: Query taking to long
              lorensrosen

              First, I'm going to assume that the line "Resized cache..." is just coincidence or is a side-effect.

              I don't see anything thus far that would cause this behavior. The next thing to look at is the definition of the relationship between the UserContactInfo and ContactType beans. Can you extract the relevant parts of the deployment descriptors?

              A workaround would be to simply make the queries faster rather than try to get rid of them. That would probably be straightforward and might suffice for the moment if you're in a rush.

              • 4. Re: Query taking to long

                Here is the DD snippit:
                <ejb-relation>
                <ejb-relation-name>userContactInfo-contactType</ejb-relation-name>
                <ejb-relationship-role>
                userContactInfo
                <ejb-relationship-role-name>UserContactInfoRelationshipRole</ejb-relationship-role-name>
                Many
                <relationship-role-source>
                userContactInfo
                <ejb-name>UserContactInfo</ejb-name>
                </relationship-role-source>
                <cmr-field>
                contactType
                <cmr-field-name>contactType</cmr-field-name>
                </cmr-field>
                </ejb-relationship-role>
                <ejb-relationship-role>
                contactType
                <ejb-relationship-role-name>ContactTypeRelationshipRole</ejb-relationship-role-name>
                One
                <relationship-role-source>
                contactType
                <ejb-name>ContactType</ejb-name>
                </relationship-role-source>
                </ejb-relationship-role>
                </ejb-relation>


                For right now I would love a quick workaround because this issue is on a production machine. How does one make them "faster"? I've got this thing on a 2.2 ghz machine w/ 500meg memory and a raid 1,5 w/ 15,000 rpm scsi disks... And it is currently running only jboss and mysql for this app.

                Thanks for the help so far!

                • 5. Re: Query taking to long
                  lorensrosen

                  Well at first glance that part looks okay. The next piece of the puzzle is the corresponding part of the jbosscmp-jdbc.xml file. Or perhaps if it's not too big you could zip up and attach the relevant beans and deployment descriptors.

                  Speeding up the query is a database issue, and a task for your DBA, if you've got one. Briefly, though, you would use the EXPLAIN command to mysql, look at the results, and then probably add an index. For more than that, we should probably take it off-line, or over to some mysql forum.

                  • 6. Re: Query taking to long
                    lafr

                    The long running query is triggered by read-ahead.
                    You may disable read-ahead for your relation.
                    Add
                    <read-ahead>
                    none
                    </read-ahead>

                    to your <relation-ship-role>'s.

                    • 7. Re: Query taking to long

                      Added the tags like so:

                      <ejb-relation>
                      <ejb-relation-name>userContactInfo-contactType</ejb-relation-name>
                      <ejb-relationship-role>
                      userContactInfo
                      <ejb-relationship-role-name>UserContactInfoRelationshipRole</ejb-relationship-role-name>
                      Many
                      <relationship-role-source>
                      userContactInfo
                      <ejb-name>UserContactInfo</ejb-name>
                      <read-ahead>
                      none
                      </read-ahead>

                      </relationship-role-source>
                      <cmr-field>
                      contactType
                      <cmr-field-name>contactType</cmr-field-name>
                      </cmr-field>
                      </ejb-relationship-role>
                      <ejb-relationship-role>
                      contactType
                      <ejb-relationship-role-name>ContactTypeRelationshipRole</ejb-relationship-role-name>
                      One
                      <relationship-role-source>
                      contactType
                      <ejb-name>ContactType</ejb-name>
                      <read-ahead>
                      none
                      </read-ahead>
                      </relationship-role-source>
                      </ejb-relationship-role>
                      </ejb-relation>

                      Didn't help.

                      Thanks though!

                      • 8. Re: Query taking to long

                        I don't have a DBA so that isn't going to help. :(

                        Don't know the EXPLAIN tag. I will research it though.

                        I've attached a few beans and some xml files. Hope it is what you were looking for.

                        The UserManagement session bean does the actual work. The rest are the entity beans that I use (generated by JBuilder)

                        Again, thanks for the help!

                        • 9. Re: Query taking to long

                          I added a few indexes on the primary keys of the userContactInfo table and the contactType table.

                          I also added an index on the contactType field of the userContactInfo table.

                          Didn't help a bit.

                          The EXPLAIN dumped the following:
                          +-----------------+------+---------------+------+--------+------+-------+------------+
                          | table | type | possible_keys | key | key_len | ref | rows | Extra |
                          +-----------------+------+---------------+------+--------+------+-------+------------+
                          | UserContactInfo | ALL | NULL | NULL | NULL | NULL | 60834 | where used |
                          +-----------------+------+---------------+------+--------+------+-------+------------+

                          I can see how this gets nasty, but I don't see how to really optimize it.

                          • 10. Re: Query taking to long
                            lorensrosen

                            After adding the index, you should do an ANALYZE TABLE.

                            But it's possible the index just won't help. This is probably the case if the query must look at a large fraction of the rows of the table. Are there a lot of different
                            contact types, or just the 11 it appears to be asking about?

                            You probably don't need to explicitly create indexes on the primary keys-- by definition a primary key is unique meaning the database must create an index to validate the uniqueness. In other words the primary key declaration implicitly creates an index.

                            • 11. Re: Query taking to long
                              lafr

                              I said <read-ahead> is a sub-Tag to <ejb-relationship-role>.
                              You've put it in into <relationship-role-source>.

                              And I forgot to say that this is for jbosscmp-jdbc.xml not for ejb-jar.xml.

                              So you may try it again.

                              • 12. Re: Query taking to long

                                That did it!!!

                                Thank you both for all the help. I would have never figured it out.