Uploaded image for project: 'Sakai'
  1. Sakai
  2. SAK-40892

Nested SqlService calls can lead to pool connection deadlock under certain conditions

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: OPEN
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 12.4, 19.0, 20.0 [Tentative]
    • Fix Version/s: None
    • Component/s: Kernel
    • Labels:
      None
    • Test Plan:
      Hide

      Please add a Test Plan here.

      Show
      Please add a Test Plan here.

      Description

      Under certain conditions, a deadlock can be created where request threads are unable to complete because insufficient database connections are available.

      This can happen when:

      • The Tomcat connector maxThreads (conf/server.xml) is larger than the Hikari CP maximum pool size (maximumPoolSize@javax.sql.BaseDataSource)
      • The volume of requests equals or exceeds maxThreads, so that all Tomcat request threads are busy
      • The requests involve retrieving a set of announcements, or other resources that use specific SqlService calls.

      For example:

      maximumPoolSize@javax.sql.BaseDataSource=100
      idleTimeout@javax.sql.BaseDataSource=600000
      leakDetectionThreshold@javax.sql.BaseDataSource=15000
      connectionTimeout@javax.sql.BaseDataSource=120000
      

      with maxThreads in conf/server.xml set to 120.

      The stack trace below is provided by enabling Hikari leakDetection.

      First, BaseAnnouncementService.getMessages() retrieves a set of messages. This involves getting a pool connection in BasicSqlService.dbRead(). Then a result set is iterated through (while the db connection is open). The process of creating an announcement object for a result triggers in a BaseUserDirectoryService.getUser() call, which itself calls SqlService.dbRead() and requests another nested database connection from the pool.

      Each request thread therefore uses two pool connections. However, because the number of pool connections available is close to the number of request threads, the inner connection requests cannot be satisfied, so the connection request blocks waiting for pool connections to be free. However, these connections are never freed because they're held by the outer call which is waiting for the inner call to conclude.

      After the connectionTimeout period is exceeded, the pool connection requests fail and an exception is thrown for the request.

      To avoid this, the same connection should probably be re-used. The situation can be avoided by configuration by ensuring that maximumPoolSize is slightly larger than maxThreads (e.g. maximumPoolSize=maxThreads+10)

      2018-11-06 13:42:51,899  WARN ajp-nio-8009-exec-41 org.sakaiproject.db.impl.BasicSqlService - Sql.dbRead: sql: select SAKAI_USER.USER_ID,SAKAI_USER.EMAIL,SAKAI_USER.EMAIL_LC,SAKAI_USER.FIRST_NAME,SAKAI_USER.LAST_NAME,SAKAI_USER.TYPE,SAKAI_USER.PW,SAKAI_USER.CREATEDBY,SAKAI_USER.MODIFIEDBY,SAKAI_USER.CREATEDON,SAKAI_USER.MODIFIEDON from SAKAI_USER where ( USER_ID = ? ) 14085e39-ce5d-4d36-8699-161ae4103612
      java.sql.SQLTransientConnectionException: sakai - Connection is not available, request timed out after 120011ms.
              at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:601)
              at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:194)
              at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:144)
              at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:112)
              at org.sakaiproject.db.impl.BasicSqlService.borrowConnection(BasicSqlService.java:260)
              at org.sakaiproject.db.impl.BasicSqlService.dbRead(BasicSqlService.java:540)
              at org.sakaiproject.util.BaseDbFlatStorage.getResource(BaseDbFlatStorage.java:338)
              at org.sakaiproject.util.BaseDbFlatStorage.getResource(BaseDbFlatStorage.java:318)
              at org.sakaiproject.user.impl.DbUserService$DbStorage.getById(DbUserService.java:235)
              at org.sakaiproject.user.impl.BaseUserDirectoryService.getUser(BaseUserDirectoryService.java:827)
              at org.sakaiproject.message.util.BaseMessage$BaseMessageHeaderEdit.<init>(BaseMessage.java:3839)
              at org.sakaiproject.announcement.impl.BaseAnnouncementService$BaseAnnouncementMessageHeaderEdit.<init>(BaseAnnouncementService.java:1800)
              at org.sakaiproject.announcement.impl.BaseAnnouncementService.newMessageHeader(BaseAnnouncementService.java:517)
              at org.sakaiproject.message.util.BaseMessage$BaseMessageEdit.<init>(BaseMessage.java:3398)
              at org.sakaiproject.announcement.impl.BaseAnnouncementService$BaseAnnouncementMessageEdit.<init>(BaseAnnouncementService.java:1739)
              at org.sakaiproject.announcement.impl.BaseAnnouncementService.newResource(BaseAnnouncementService.java:308)
              at org.sakaiproject.util.BaseDbDoubleStorage.readResource(BaseDbDoubleStorage.java:735)
              at org.sakaiproject.util.BaseDbDoubleStorage$SearchFilterReader.readSqlResultRecord(BaseDbDoubleStorage.java:1112)
              at org.sakaiproject.db.impl.BasicSqlService.dbRead(BasicSqlService.java:584)
              at org.sakaiproject.db.impl.BasicSqlService.dbRead(BasicSqlService.java:471)
              at org.sakaiproject.util.BaseDbDoubleStorage.getAllResources(BaseDbDoubleStorage.java:1043)
              at org.sakaiproject.util.BaseDbDoubleStorage.getAllResources(BaseDbDoubleStorage.java:952)
              at org.sakaiproject.util.BaseDbDoubleStorage.getAllResources(BaseDbDoubleStorage.java:879)
              at org.sakaiproject.announcement.impl.DbAnnouncementService$DbStorage.getMessages(DbAnnouncementService.java:305)
              at org.sakaiproject.message.util.BaseMessage$BaseMessageChannelEdit.findMessages(BaseMessage.java:3144)
              at org.sakaiproject.message.util.BaseMessage$BaseMessageChannelEdit.findFilterMessages(BaseMessage.java:3164)
              at org.sakaiproject.message.util.BaseMessage$BaseMessageChannelEdit.getMessages(BaseMessage.java:2422)
              at org.sakaiproject.announcement.impl.BaseAnnouncementService$BaseAnnouncementChannelEdit.getMessages(BaseAnnouncementService.java:1517)
              at org.sakaiproject.announcement.impl.BaseAnnouncementService.getMessages(BaseAnnouncementService.java:1114)
              at org.sakaiproject.announcement.entityprovider.AnnouncementEntityProviderImpl.getAnnouncements(AnnouncementEntityProviderImpl.java:225)
              at org.sakaiproject.announcement.entityprovider.AnnouncementEntityProviderImpl.getAnnouncementsForUser(AnnouncementEntityProviderImpl.java:546)
      
      

        Gliffy Diagrams

          Attachments

            Activity

              People

              • Assignee:
                maintenanceteam Core Team
                Reporter:
                smarquard Stephen Marquard
              • Votes:
                0 Vote for this issue
                Watchers:
                5 Start watching this issue

                Dates

                • Created:
                  Updated:

                  Git Source Code