Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

JVM Metaspace keeps growing with @RequestScope, AOP and @Validated because of proxying. #27395

Closed
legzo opened this issue Sep 13, 2021 · 5 comments
Assignees
Labels
status: duplicate A duplicate of another issue

Comments

@legzo
Copy link

legzo commented Sep 13, 2021

Affects: spring-framework >= v5.3.1


Problem:

The JVM Metaspace keeps growing with each call to a controller and after a while the JVM crashes. It is linked to the fact that new class definitions are created without being deleted for proxies around controllers.


How to reproduce:

The problem occurs when you have a controller :

  • @RequestScope or @SessionScope
  • @Validated
  • with any kind of aspect around it

Here is a sample Spring Boot app that exhibits the problem :

package com.example.demo

import org.aspectj.lang.ProceedingJoinPoint
import org.aspectj.lang.annotation.Around
import org.aspectj.lang.annotation.Aspect
import org.springframework.boot.autoconfigure.SpringBootApplication
import org.springframework.boot.runApplication
import org.springframework.stereotype.Component
import org.springframework.validation.annotation.Validated
import org.springframework.web.bind.annotation.GetMapping
import org.springframework.web.bind.annotation.RestController
import org.springframework.web.context.annotation.RequestScope

@SpringBootApplication
class DemoApplication

fun main(args: Array<String>) {
    runApplication<DemoApplication>(*args)
}

@Component
@Aspect
class MyCustomAspect {

    @Around("execution(* com.example.demo..*(..)))")
    fun before(proceedingJoinPoint: ProceedingJoinPoint): Any {
        println("before")
        return proceedingJoinPoint.proceed()
    }
}

@RestController
@RequestScope
@Validated
class Controller {

    @GetMapping("/hey")
    fun greet(): String {
        return "Hey!"
    }
}

If you launch a couple of requests to the endpoint, you can witness that a large number of proxy class definitions are added to the Metaspace.

for i in (seq 0 50); curl -s localhost:8080/hey >> /dev/null ; end ; jmap -clstats (ps aux |grep java | grep "demo/out" | tr -s " " | cut -d " " -f2)| grep -i demo.controller

(this is fish shell, but the bash equivalent should be straightforward, I'm just sending 50 requests, then getting the PID of the Spring app and querying the loaded classes definitions)

Result :

  392  7953       832        656           0     1464           7       484      1544     1160     2704     3864 com.example.demo.Controller$$FastClassBySpringCGLIB$$fdcabab6
 1385  4011        48        936           0     6128          52      2159      9808     6880    11352    18232 com.example.demo.Controller$$EnhancerBySpringCGLIB$$4e4beb4d
 2433  7953        16        656           0     6072           7      4248      5312     5440     6800    12240 com.example.demo.Controller$$EnhancerBySpringCGLIB$$4e4beb4d$$FastClassBySpringCGLIB$$4bf361ef
 2434  7953        16        656           0     5712           7      3962      5016     5104     6480    11584 com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8$$FastClassBySpringCGLIB$$d8727a09
 2435  7953        16        656           0     5712           7      3962      5016     5104     6480    11584 com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_10$$FastClassBySpringCGLIB$$31c8c815
 2436  7953        16        656           0     5712           7      3962      5016     5104     6480    11584 com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_11$$FastClassBySpringCGLIB$$31c8c816
 2437  7953        16        656           0     5712           7      3962      5016     5104     6480    11584 com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_12$$FastClassBySpringCGLIB$$31c8c817
 2438  7953        16        656           0     5712           7      3962      5016     5104     6480    11584 com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_13$$FastClassBySpringCGLIB$$31c8c818
 2439  7953        16        656           0     5712           7      3962      5016     5104     6480    11584 com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_14$$FastClassBySpringCGLIB$$31c8c819
 2440  7953        16        656           0     5712           7      3962      5016     5104     6480    11584 com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_15$$FastClassBySpringCGLIB$$31c8c81a
 2441  7953        16        656           0     5712           7      3962      5016     5104     6480    11584 com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_16$$FastClassBySpringCGLIB$$31c8c81b
 2442  7953        16        656           0     5712           7      3962      5016     5104     6480    11584 com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_17$$FastClassBySpringCGLIB$$31c8c81c
// shortened there are 50 definitions for com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_1$$FastClassBySpringCGLIB$$31c8c81c to com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_50$$FastClassBySpringCGLIB$$31c8c81c
 4011    13         0        536         112      520           2         8       368      400     1280     1680 com.example.demo.Controller
 4012  4011         0        904           0     5584          48      1947      9000     6184    10464    16648 com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8
 4013  4011         0        904           0     5584          48      1947      9000     6184    10464    16648 com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_10
 4014  4011         0        904           0     5584          48      1947      9000     6184    10464    16648 com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_11
 4015  4011         0        904           0     5584          48      1947      9000     6184    10464    16648 com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_12
 4016  4011         0        904           0     5584          48      1947      9000     6184    10464    16648 com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_13
 4017  4011         0        904           0     5584          48      1947      9000     6184    10464    16648 com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_14
 4018  4011         0        904           0     5584          48      1947      9000     6184    10464    16648 com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_15
 4019  4011         0        904           0     5584          48      1947      9000     6184    10464    16648 com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_16
 4020  4011         0        904           0     5584          48      1947      9000     6184    10464    16648 com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_17
// shortened there are 50 definitions for com.example.demo.Controller$$EnhancerBySpringCGLIB$$e35965c8_1 to _50

We discovered this problem on a large scale application when we updated Spring from 5.2.15.RELEASE to 5.3.9. As I said, the phenomenon causes Metaspace to grow until JVM crashes.

I tried with different versions of Spring and found out that 5.3.0 is OK but there is a problem with 5.3.1. So my guess is that it is linked to this commit : 10bff05 and this issue : #26019. But I might be wrong, my knowledge on this topic is very limited :)

Here is the build.gradle.kts used for the demo project (spring boot 2.4.0 -> spring 5.3.1) :

import org.jetbrains.kotlin.gradle.tasks.KotlinCompile

plugins {
    id("org.springframework.boot") version "2.4.0"
    id("io.spring.dependency-management") version "1.0.11.RELEASE"
    war
    kotlin("jvm") version "1.5.21"
    kotlin("plugin.spring") version "1.5.21"
}

group = "com.example"
version = "0.0.1-SNAPSHOT"
java.sourceCompatibility = JavaVersion.VERSION_11

repositories {
    mavenCentral()
}

dependencies {
    implementation("org.springframework.boot:spring-boot-starter-web")
    implementation("org.springframework.boot:spring-boot-starter-aop")
    implementation("org.springframework.boot:spring-boot-starter-validation")

    implementation("com.fasterxml.jackson.module:jackson-module-kotlin")
    implementation("org.jetbrains.kotlin:kotlin-reflect")
    implementation("org.jetbrains.kotlin:kotlin-stdlib-jdk8")
}

tasks.withType<KotlinCompile> {
    kotlinOptions {
        freeCompilerArgs = listOf("-Xjsr305=strict")
        jvmTarget = "11"
    }
}

tasks.withType<Test> {
    useJUnitPlatform()
}

Forcing spring to 5.3.0 fixes the behaviour :

val springVersion = "5.3.1"

dependencies {
    implementation("org.springframework.boot:spring-boot-starter-web")
    implementation("org.springframework.boot:spring-boot-starter-aop")
    implementation("org.springframework.boot:spring-boot-starter-validation")

    implementation("org.springframework:spring-aop") { version { strictly(springVersion) } }
    implementation("org.springframework:spring-beans") { version { strictly(springVersion) } }
    implementation("org.springframework:spring-context") { version { strictly(springVersion) } }
    implementation("org.springframework:spring-core") { version { strictly(springVersion) } }
    implementation("org.springframework:spring-expression") { version { strictly(springVersion) } }
    implementation("org.springframework:spring-jcl") { version { strictly(springVersion) } }
    implementation("org.springframework:spring-web") { version { strictly(springVersion) } }
    implementation("org.springframework:spring-webmvc") { version { strictly(springVersion) } }

    implementation("com.fasterxml.jackson.module:jackson-module-kotlin")
    implementation("org.jetbrains.kotlin:kotlin-reflect")
    implementation("org.jetbrains.kotlin:kotlin-stdlib-jdk8")
}

Gives the following result :

for i in (seq 0 50); curl -s localhost:8080/hey >> /dev/null ; end ;and jmap -clstats (ps aux |grep java | grep "demo/out" | tr -s " " | cut -d " " -f2)| grep -i demo.controller

 1370  3895        48        920           0     6064          51      2128      9632     6768    11192    17960 com.example.demo.Controller$$EnhancerBySpringCGLIB$$cd82741
 1733  7794        32        656           0     1464           7       484      1544     1160     2704     3864 com.example.demo.Controller$$FastClassBySpringCGLIB$$fdcabab6
 2425  7794        16        656           0     5624           7      3883      4944     5024     6400    11424 com.example.demo.Controller$$EnhancerBySpringCGLIB$$943709c4$$FastClassBySpringCGLIB$$2f1c737c
 2426  7794        16        656           0     5984           7      4169      5240     5360     6720    12080 com.example.demo.Controller$$EnhancerBySpringCGLIB$$cd82741$$FastClassBySpringCGLIB$$7d56a356
 3895    13         0        536         112      520           2         8       368      400     1280     1680 com.example.demo.Controller
 3896  3895         0        888           0     5528          47      1916      8824     6080    10304    16384 com.example.demo.Controller$$EnhancerBySpringCGLIB$$943709c4

I also tried removing the aspect, or the @Validated on the controller, or the @RequestScope and each of these modifications fixes the problem. Unfortunately, it is not so simple on our real life application...

Do not hesitate to ask for more info !

Cheers,
Julien

@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged or decided on label Sep 13, 2021
@jhoeller
Copy link
Contributor

Looks like the CGLIB proxy class leak to be fixed by this PR that we're about to merge for 5.3.10: #27375

@jhoeller
Copy link
Contributor

Closing this one based on the assumption that #27375 covers your scenario as well. Please give the 5.3.10 release a try, it's available in snapshots already and will be officially released tomorrow!

@legzo
Copy link
Author

legzo commented Sep 14, 2021

Yep yep yep, behavior is normal with 5.3.10-SNAPSHOT

for i in (seq 0 50); curl -s localhost:8080/hey >> /dev/null ; end ;and jmap -clstats (ps aux |grep java | grep "demo/out" | tr -s " " | cut -d " " -f2)| grep -i demo.controller
 1385  3912        48        936           0     6128          52      2159      9808     6880    11352    18232 com.example.demo.Controller$$EnhancerBySpringCGLIB$$a08aa040
 1750  7809        32        656           0     1464           7       484      1544     1160     2704     3864 com.example.demo.Controller$$FastClassBySpringCGLIB$$fdcabab6
 2439  7809        16        656           0     5712           7      3962      5016     5104     6480    11584 com.example.demo.Controller$$EnhancerBySpringCGLIB$$7ccbe311$$FastClassBySpringCGLIB$$69fd863c
 2440  7809        16        656           0     6072           7      4248      5312     5440     6800    12240 com.example.demo.Controller$$EnhancerBySpringCGLIB$$a08aa040$$FastClassBySpringCGLIB$$a1a0be46
 3912    13         0        536         112      520           2         8       368      400     1280     1680 com.example.demo.Controller
 3913  3912         0        904           0     5584          48      1947      9000     6184    10464    16648 com.example.demo.Controller$$EnhancerBySpringCGLIB$$7ccbe311

👍🏼 thanks

@jhoeller
Copy link
Contributor

Good to hear, thanks for the immediate feedback!

@jhoeller jhoeller self-assigned this Sep 14, 2021
@jhoeller jhoeller added status: duplicate A duplicate of another issue and removed status: waiting-for-triage An issue we've not yet triaged or decided on labels Sep 14, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
status: duplicate A duplicate of another issue
Projects
None yet
Development

No branches or pull requests

4 participants