Анализ закрытого закрытого соединения в приложении Spring/JPA/Mysql/Tomcat

Ответ 1

Это ужасно поздно для OP, но, возможно, это поможет кому-то еще в будущем:

Я столкнулся с чем-то похожим на это в производственной среде с длительными пакетными заданиями. Проблема в том, что ваш код требует подключения дольше, указанного в свойстве:

name="removeAbandonedTimeout" value="60

и вы включили:

<property name="removeAbandoned" value="true" />

то он будет отключен во время обработки через 60 секунд. Одним из возможных способов обхода (который не работает для меня) является включение перехватчика:

jdbcInterceptors="ResetAbandonedTimer"

Это будет reset заброшенный таймер для этого соединения для каждого чтения/записи. К сожалению, в моем случае обработка иногда по-прежнему занимает больше времени, чем таймаут, прежде чем что-либо будет прочитано/записано в базу данных. Поэтому я был вынужден либо увеличить длину таймаута, либо отключить removeAbandonded (я выбрал первое решение).

Надеюсь, это поможет кому-то другому, если они столкнутся с чем-то подобным!

Ответ 2

В коде используется GenericDao, который расширяется в каждом классе Dao. GenericDao использует Spring JpaTemplate для извлечения экземпляра EntityManager, который, в свою очередь, используется для всех операций БД. Я понимаю, что использование JpaTemplate обрабатывает nitty gritty закрытия внутренних соединений DB.

Это, вероятно, корень вашей проблемы, вы не должны использовать JpaTemplate для получения EntityManager, это даст вам неуправляемый EntityManager. На самом деле вы не должны использовать JpaTemplate вообще.

Рекомендуется писать daos на основе простого API EntityManager и просто вводить EntityManager, как вы обычно делали (с @PersistenceContext).

Если вы действительно хотите использовать JpaTemplate, используйте метод execute и передайте в JpaCallback, который даст вам управляемый EntityManager.

Также убедитесь, что вы правильно настроили транзакции без правильного подключения к tx, не будут закрыты, так как Spring не знает, что он должен закрыть соединение.

Ответ 3

Недавно меня попросили исследовать, почему система производства иногда падает. Я хотел поделиться своими выводами, поскольку он связан с корреляцией событий, чтобы принять приложение Tomcat JVM с проблемами JDBC, как описано выше, чтобы фактически свернуть приложение. Это использует mysql как бэкэнд, поэтому, вероятно, наиболее полезно для этого сценария, но если проблема попала на другую платформу, вероятно, будет одинаковой.

Простое закрытие соединения не означает, что приложение сломано

Это приложение grails, но оно будет относиться ко всем приложениям, связанным с JVM:

tomcat/context.xml db, обратите внимание на очень небольшой пул db и   removeAbandonedTimeout="10" Вы правы, мы хотим, чтобы что-то сломалось

<Resource
 name="jdbc/TestDB"  auth="Container" type="javax.sql.DataSource"
              driverClassName="com.mysql.jdbc.Driver"
              url="jdbc:mysql://127.0.0.1:3306/test"
              username="XXXX"
              password="XXXX"
              testOnBorrow="true"
              testWhileIdle="true"
              testOnReturn="true"
              factory="org.apache.tomcat.jdbc.pool.DataSourceFactory"
              removeAbandoned="true"
              logAbandoned="true"
              removeAbandonedTimeout="10"
              maxWait="5000"
              initialSize="1"
              maxActive="2"
              maxIdle="2"
              minIdle="2"
              validationQuery="Select 1" />

Работа кварца, которая запускается каждую минуту, а не то, что важно для приложения, которое, как я думаю, умирает при первой попытке:

class Test2Job {
    static  triggers = {
               cron name: 'test2', cronExpression: "0 0/1 * * * ?"
        }
        def testerService
        def execute() {
        println "starting job2 ${new Date()}"
        testerService.basicTest3()

    }

}

Теперь наш тестовый сервис с комментариями, пожалуйста, следуйте комментариям:

def dataSource

  /**
   * When using this method in quartz all the jdbc settings appear to get ignored
   * the job actually completes notice huge sleep times compared to basicTest
   * strange and very different behaviour.
   * If I add Tester t = Tester.get(1L) and then execute below query I will get
   * connection pool closed error
   * @return
   */
  def basicTest2() {
      int i=1
      while (i<21) {
          def sql = new Sql(dataSource)
          def query="""select id as id  from tester t
                  where id=:id"""
          def instanceList = sql.rows(query,[id:i as Long],[timeout:90])
          sleep(11000)
          println "-- working on ${i}"
          def sql1 = new Sql(dataSource)
          sql1.executeUpdate(
                  "update tester t set t.name=? where t.id=?",
                  ['aa '+i.toString()+' aa', i as Long])

          i++
          sleep(11000)
      }
      println "run ${i} completed"
  }


  /**
   * This is described in above oddity
   * so if this method is called instead you will see connection closed issues
   */
  def basicTest3() {
      int i=1
      while (i<21) {
          def t = Tester.get(i)
          println "--->>>> test3 t ${t.id}"

          /**
           * APP CRASHER - This is vital and most important
           * Without this declared lots of closed connections and app is working
           * absolutely fine,
           * The test was originally based on execRun() which returns 6650 records or something
           * This test query is returned in time and does not appear to crash app
           *
           * The moment this method is called and please check what it is currently doing. It is simply
           * running a huge query which go beyond the time out values and as explained in previous emails MYSQL states
           *
           * The app is then non responsive and logs clearly show application is broke 
           */
          execRun2()


          def sql1 = new Sql(dataSource)
          sleep(10000)
          sql1.executeUpdate("update tester t set t.name=? where t.id=?",['aa '+i.toString()+' aa', t.id])
          sleep(10000)
          i++
      }

  }


  def execRun2() {
      def query="""select new map (t as tester) from Tester t left join t.children c
left join t.children c
                  left join c.childrena childrena
                  left join childrena.childrenb childrenb
                  left join childrenb.childrenc childrenc , Tester t2 left join t2.children c2 left join t2.children c2
                  left join c2.childrena children2a
                  left join children2a.childrenb children2b
                  left join children2b.childrenc children2c
             where ((c.name like (:name) or
                  childrena.name like (:name) or
                  childrenb.name like (:name) or (childrenc is null or childrenc.name like (:name))) or
                  (
                  c2.name like (:name) or
                  children2a.name like (:name) or
                  children2b.name like (:name) or (children2c is null or children2c.name like (:name))
      ))

          """
      //println "query $query"
      def results = Tester.executeQuery(query,[name:'aa'+'%'],[timeout:90])
      println "Records: ${results.size()}"

      return results
  }


  /**
   * This is no different to basicTest2 and yet
   * this throws a connection closed error and notice it is 20 not 20000
   * quite instantly a connection closed error is thrown when a .get is used vs
   * sql = new Sql(..) is a manuall connection
   *
   */
  def basicTest() {
      int i=1
      while (i<21) {
          def t = Tester.get(i)
          println "--- t ${t.id}"
          sleep(20)
          //println "publishing event ${event}"
          //new Thread({
          //    def event=new PurchaseOrderPaymentEvent(t,t.id)
          //    publishEvent(event)
          //} as Runnable ).start()

          i++
      }
  }

Только тогда, когда запрос занимает больше времени, чем ожидалось, но должен быть другой элемент, сам запрос должен ударить по сидению на MYSQL, даже если он был убит. MYSQL убирает его, обрабатывая его.

Я думаю, что происходит,

job 1 - hits app -> hits mysql ->    (9/10 left)
         {timeout} -> app killed  -> mysql running (9/10)
 job 2 - hits app -> hits mysql ->    (8/10 left)
         {timeout} -> app killed  -> mysql running (8/10) 
.....
 job 10 - hits app -> hits mysql ->    (10/10 left)
         {timeout} -> app killed  -> mysql running (10/10)
 job 11 - hits app -> 

Если к этому времени job1 не завершился, тогда у нас ничего не осталось в пуле, приложение просто просто сломалось сейчас. jdbc ошибки бросили и т.д.. неважно, если он завершится после сбоя..

Вы можете отслеживать, что происходит, проверять mysql Похоже, что он работает в течение более длительного периода, который идет вразрез с тем, что они предположили, что это значение должно делать, но опять же, возможно, это на самом деле не основано ни на одном из них и не связано с проблемой в другом месте.

Хотя тестирование показало наличие двух состояний: отправка данных/отправка клиенту:

|  92 | root | localhost:58462 | test | Query   |   80 | Sending data      | select tester0_.id as col_0_0_ from tester tester0_ left outer join tester_childa children1_ on test |
|  95 | root | localhost:58468 | test | Query   |  207 | Sending to client | select tester0_.id as col_0_0_ from tester tester0_ left outer join tester_childa children1_ on test |
|  96 | root | localhost:58470 | test | Query   |  147 | Sending data      | select tester0_.id as col_0_0_ from tester tester0_ left outer join tester_childa children1_ on test |
|  97 | root | localhost:58472 | test | Query   |  267 | Sending data      | select tester0_.id as col_0_0_ from tester tester0_ left outer join tester_childa children1_ on test |
|  98 | root | localhost:58474 | test | Sleep   |   18 |                   | NULL                                                                                                 |
|  99 | root | localhost:58476 | test | Query   |  384 | Sending to client | select tester0_.id as col_0_0_ from tester tester0_ left outer join tester_childa children1_ on test |
| 100 | root | localhost:58478 | test | Query   |  327 | Sending data      | select tester0_.id as col_0_0_ from tester tester0_ left outer join tester_childa children1_ on test |

Через несколько секунд:

|  91 | root | localhost:58460 | test | Query   |   67 | Sending to client | select tester0_.id as col_0_0_ from tester tester0_ left outer join tester_childa children1_ on test |
|  92 | root | localhost:58462 | test | Query   |  148 | Sending to client | select tester0_.id as col_0_0_ from tester tester0_ left outer join tester_childa children1_ on test |
|  97 | root | localhost:58472 | test | Query   |  335 | Sending to client | select tester0_.id as col_0_0_ from tester tester0_ left outer join tester_childa children1_ on test | |
| 100 | root | localhost:58478 | test | Query   |  395 | Sending to client | select tester0_.id as col_0_0_ from tester tester0_ left outer join tester_childa children1_ on test |

Seconds after that: (all dead)
|  58 | root | localhost       | NULL | Query   |    0 | starting | show processlist |
|  93 | root | localhost:58464 | test | Sleep   |  167 |          | NULL             |
|  94 | root | localhost:58466 | test | Sleep   |  238 |          | NULL             |
|  98 | root | localhost:58474 | test | Sleep   |   74 |          | NULL             |
| 101 | root | localhost:58498 | test | Sleep   |   52 |          | NULL             |

Возможно, требуется создать script для мониторинга списка процессов и, возможно, более глубокого набора результатов, содержащего точные запросы, которые будут работать, чтобы определить, какой из ваших запросов вызывает убийство вашего приложения.