Spring / JPA / Mysql / Tomcat 앱에서 Connection Closed Exception 분석하기

문제

필자는 최근 작성된 코드와 함께 Java 웹 응용 프로그램을 담당했습니다. 앱은 적당히 높은 트래픽을 받고 매일 오전 11 시부 터 오후 3시 사이에 트래픽이 피크 시간대입니다. 응용 프로그램은 Spring, JPA (Hibernate), MYSQL DB를 사용합니다. Spring은 tomcat jdbc 연결 풀을 사용하여 DB에 연결하도록 구성되었습니다. (게시물 끝에 구성의 세부 사항)

지난 며칠 동안 애플리케이션의 최고로드 시간 동안 요청에 응답하지 않는 바람둥이로 인해 애플리케이션이 다운되었습니다. 그것은 tomcat을 여러 번 다시 시작해야했습니다.

바람둥이 catalina.out 통나무를지나면서, 나는 전체의 제비 뽑기를 알아 차렸다

Caused by: java.sql.SQLException: Connection has already been closed.
    at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:117)
    at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
    at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:80)
    at com.sun.proxy.$Proxy28.prepareStatement(Unknown Source)
    at org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:505)
    at org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:423)
    at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:139)
    at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1547)
    at org.hibernate.loader.Loader.doQuery(Loader.java:673)
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:236)
    at org.hibernate.loader.Loader.loadCollection(Loader.java:1994)
    ... 115 more

이들은 충돌 직전에 자주 나타납니다.

이러한 예외가 발생하기 전에 더 일찍, Connection Closed 예외가 발생하기 직전에 많은 Connections가 포기 된 것으로 나타났습니다.

WARNING: Connection has been abandoned PooledConnection[com.mysql.jdbc.Connection@543c2ab5]:java.lang.Exception
    at org.apache.tomcat.jdbc.pool.ConnectionPool.getThreadDump(ConnectionPool.java:1065)
    at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:782)
    at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:618)
    at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:188)
    at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:128)
    at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:47)
    at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:423)
    at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
    at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:139)

이는 연결 종료 예외가 발생하기 바로 전에 자주 나타나는 것처럼 보입니다. 그리고 이것들은 로그에 임박한 운명의 첫 징후 인 것 같습니다.

분석

로그를 살펴보면서 문제를 일으킬 수있는 연결 풀 구성 / mysql 구성이 있는지 살펴 보았습니다. 프로덕션 환경에서 풀을 튜닝하는 훌륭한 몇 가지 기사를 읽었습니다. 링크 1 및 2

이 기사들을 살펴보면 다음과 같은 사실을 알게되었습니다.

내가 시도한 것

따라서 기사의 권장 사항에 따라 다음 두 가지를 수행했습니다.

이것은 도움이되지 않았다.

다음날, 피크 시간대에 다음과 같은 관찰이 이루어졌습니다.

마침내, 내 질문 :

DB 연결이 앱 서버에서 이루어지는 방식에 문제가있는 것처럼 보입니다. 그래서 나는이 분석을 앞으로 할 두 가지 방향을 가지고있다.

제 질문은 이것들 중 어느 것을 복용해야합니까?

1.이 문제는 연결 풀 설정과 관련이 없습니다. 코드가 문제의 원인입니다.

DB 연결이 닫히지 않는 코드의 위치가있을 수 있습니다. 이로 인해 많은 수의 연결이 열리고 있습니다.

이 코드는 모든 Dao 클래스에서 확장 된 GenericDao를 사용합니다. GenericDao는 Spring의 JpaTemplate을 사용하여 모든 DB 작업에 사용되는 EntityManager 인스턴스를 가져옵니다. 나의 이해는 JpaTemplate을 사용하여 내부적으로 DB 커넥션을 닫는 것입니다.

그렇다면 연결 누출 가능성을 정확히 찾아야하는 곳은 어디입니까?

2.이 문제는 connections pool / mysql 구성 매개 변수에 있습니다. 그러나 내가 추가 한 최적화는 더 조정해야합니다.

그렇다면 어떤 매개 변수를보고 있습니까? 내 연결 풀에 더 적합한 값을 결정하는 데 사용할 일부 데이터를 수집해야합니다. (예 : max_active, max_idle, max_connections)

부록 : 완전한 연결 풀 구성

   <bean id="dataSource" class="org.apache.tomcat.jdbc.pool.DataSource" destroy-method="close">
        <property name="driverClassName" value="com.mysql.jdbc.Driver" />
        <property name="url" value="jdbc:mysql://xx.xx.xx.xx" />
        <property name="username" value="xxxx" />
        <property name="password" value="xxxx" />
        <property name="initialSize" value="10" />
        <property name="maxActive" value="350" />
        <property name="maxIdle" value="250" />
        <property name="minIdle" value="90" />
        <property name="timeBetweenEvictionRunsMillis" value="30000" />
        <property name="removeAbandoned" value="true" />
        <property name="removeAbandonedTimeout" value="60" />
        <property name="abandonWhenPercentageFull" value="100" />
        <property name="testOnBorrow" value="true" />
        <property name="validationQuery" value="SELECT 1" />
        <property name="validationInterval" value="30000" />
        <property name="logAbandoned" value="true" />
        <property name="jmxEnabled" value="true" />
    </bean>

해결법

==============================
1.이것은 OP를 위해 비참하게 늦었지만 어쩌면 미래에 다른 사람을 도울 것입니다.

이것은 OP를 위해 비참하게 늦었지만 어쩌면 미래에 다른 사람을 도울 것입니다.

장기 실행 일괄 처리 작업 환경에서 이와 비슷한 문제가 발생했습니다. 문제는 코드가 property에 지정된 시간보다 긴 연결을 필요로하는 경우입니다.

name = "removeAbandonedTimeout"value = "60

다음을 사용하도록 설정했습니다.

60 초 후 처리 중에 연결이 끊어집니다. 가능한 한 해결 방법 (저에게 맞지 않는)은 인터셉터를 활성화하는 것입니다.

jdbcInterceptors = "ResetAbandonedTimer"

이것은 발생하는 모든 읽기 / 쓰기에 대해 해당 연결에 대한 버려진 타이머를 재설정합니다. 불행히도 제 경우에는 처리가 때때로 시간 초과보다 오래 걸리므로 데이터베이스에 읽기 / 쓰기가 이루어집니다. 그래서 timeout 길이를 늘리거나 removeAbandonded를 비활성화해야했습니다 (이전 솔루션을 선택했습니다).

비슷한 일이 생기면 다른 사람들에게 도움이되기를 바랍니다.

==============================

2.나는 최근 생산 시스템이 때때로 무너지는 지 조사하도록 요청 받았다. JVM 바람둥이 앱에 앞서 설명한 JDBC 문제가있는 이벤트를 상호 연관시켜 실제로 오류가 발생했기 때문에 결과를 공유하고 싶었습니다. 이것은 백엔드로 mysql을 사용하고 있습니다. 아마도이 시나리오에서 가장 유용 할 것입니다.하지만 다른 플랫폼에서 문제가 발생할 가능성이 같은 경우가 발생할 수 있습니다.

나는 최근 생산 시스템이 때때로 무너지는 지 조사하도록 요청 받았다. JVM 바람둥이 앱에 앞서 설명한 JDBC 문제가있는 이벤트를 상호 연관시켜 실제로 오류가 발생했기 때문에 결과를 공유하고 싶었습니다. 이것은 백엔드로 mysql을 사용하고 있습니다. 아마도이 시나리오에서 가장 유용 할 것입니다.하지만 다른 플랫폼에서 문제가 발생할 가능성이 같은 경우가 발생할 수 있습니다.

단순히 연결을 닫으면 응용 프로그램이 고장 났음을 의미하지는 않습니다.

이것은 grails 애플리케이션하에 있지만 모든 JVM 관련 애플리케이션에 상대적입니다 :

tomcat / context.xml db 설정, 매우 작은 DB 풀 및 removeAbandonedTimeout = "10"ye 우리는 일을 깨고 싶다.

<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()

    }

}

이제 코멘트가있는 testService가 있으므로 의견을 따르십시오.

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             |

프로세스 목록을 모니터하기 위해 스크립트를 작성해야 할 수도 있고 쿼리 이벤트 중 어떤 것이 앱을 죽이는 지 확인하기 위해 실행중인 정확한 쿼리를 포함하는 더 깊은 결과 세트 일 수도 있습니다

==============================
3.이것은 아마 당신의 문제의 뿌리 일 것입니다. JpaTemplate을 사용하여 EntityManager를 얻지 말아야합니다. 관리되지 않는 Entitymanager를 제공 할 것입니다. 사실 JpaTemplate을 전혀 사용하지 말아야합니다.

이것은 아마 당신의 문제의 뿌리 일 것입니다. JpaTemplate을 사용하여 EntityManager를 얻지 말아야합니다. 관리되지 않는 Entitymanager를 제공 할 것입니다. 사실 JpaTemplate을 전혀 사용하지 말아야합니다.

평범한 EntityManager API를 기반으로 작성된 daos를 작성하고 평소와 마찬가지로 @PersistenceContext를 사용하여 EntityManager를 삽입하는 것이 좋습니다.

JpaTemplate을 실제로 사용하려면 execute 메소드를 사용하고 JpaCallback을 전달하면 관리되는 EntityManager가 제공됩니다.

또한 적절한 tx 설정 연결을 사용하지 않고 트랜잭션을 올바르게 설정했는지 확인하십시오. 스프링이 연결을 닫아야한다는 것을 모르기 때문에 연결이 닫히지 않습니다.

from https://stackoverflow.com/questions/21698675/analyzing-connection-closed-exception-in-spring-jpa-mysql-tomcat-app by cc-by-sa and MIT license

'SPRING' 카테고리의 다른 글

[SPRING] Spring & annotation을 사용하여 속성 주입 @Value (0)	2019.02.05
[SPRING] JSTL을 사용하여 jsp 내부의 목록 요소를 얻는 방법? (0)	2019.02.05
[SPRING] 스프링 MVC를 사용하여 jsp에서 모델 속성을 표시하는 방법은 무엇입니까? (0)	2019.02.05
[SPRING] 스프링 부트 - 개발 중에 @Cachable을 비활성화하는 방법은 무엇입니까? (0)	2019.02.05
[SPRING] 스프링 부트 : webapp 폴더를 찾으려면 구성하십시오. (0)	2019.02.05

복붙노트

[SPRING] Spring / JPA / Mysql / Tomcat 앱에서 Connection Closed Exception 분석하기

Spring / JPA / Mysql / Tomcat 앱에서 Connection Closed Exception 분석하기

해결법

1.이것은 OP를 위해 비참하게 늦었지만 어쩌면 미래에 다른 사람을 도울 것입니다.

3.이것은 아마 당신의 문제의 뿌리 일 것입니다. JpaTemplate을 사용하여 EntityManager를 얻지 말아야합니다. 관리되지 않는 Entitymanager를 제공 할 것입니다. 사실 JpaTemplate을 전혀 사용하지 말아야합니다.

'SPRING' 카테고리의 다른 글

티스토리툴바