Open
Description
The new dacapo benchmark spring non-deterministically hangs with GenCopy. When it doesn't hang, it errors with a very long list of stack frame lists where errors occur. I tried GenImmix too. It didn't deadlock when I tried it, but had similar long lists of errors. I have attached a sample file of such lists of errors here: spring-errors-output.txt
Deadlock command:
MMTK_PLAN=GenCopy ./build/linux-x86_64-normal-server-$DEBUG_LEVEL/jdk/bin/java -XX:+UseThirdPartyHeap -XX:MetaspaceSize=500M -jar /usr/share/benchmarks/dacapo/dacapo-evaluation-git-29a657f.jar -t 12 spring
Output:
[2022-02-23T03:09:50Z INFO mmtk::memory_manager] Initialized MMTk with GenCopy
--------------------------------------------------------------------------------
IMPORTANT NOTICE: This is NOT a release build of the DaCapo suite.
Since it is not an official release of the DaCapo suite, care must be taken when
using the suite, and any use of the build must be sure to note that it is not an
offical release, and should note the relevant git hash.
Feedback is greatly appreciated. The preferred mode of feedback is via github.
Please use our github page to create an issue or a pull request.
https://github.com/dacapobench/dacapobench.
--------------------------------------------------------------------------------
Using scaled threading model. 24 processors detected, 12 threads used to drive the workload, in a possible range of [1,unlimited]
[2022-02-23T03:09:52Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:09:52Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:09:52Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:09:52Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:09:53Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:09:53Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:09:54Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:09:54Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:09:55Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:09:55Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:09:56Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:09:56Z INFO mmtk::scheduler::gc_work] End of GC
|\ _,,,--,,_
/,`.-'`' ._ \-;;,_
_______ __|,4- ) )_ .;.(__`'-'__ ___ __ _ ___ _______
| | '---''(_/._)-'(_\_) | | | | | | | | |
| _ | ___|_ _| | | | | |_| | | | __ _ _
| |_| | |___ | | | | | | | | | | \ \ \ \
| ___| ___| | | | _| |___| | _ | | _| \ \ \ \
| | | |___ | | | |_| | | | | | | |_ ) ) ) )
|___| |_______| |___| |_______|_______|___|_| |__|___|_______| / / / /
==================================================================/_/_/_/
:: Built with Spring Boot :: 2.4.5
[2022-02-23T03:09:57Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:09:57Z INFO mmtk::scheduler::gc_work] End of GC
2022-02-23 14:09:57.543 INFO 3683 --- [ main] o.s.s.petclinic.PetClinicApplication : Starting PetClinicApplication v2.4.5 using Java 11.0.11-internal on rat with PID 3683 (/usr/share/benchmarks/dacapo/dacapo-evaluation-git-29a657f/jar/spring/spring-petclinic-2.4.5.jar started by kiph in /home/kiph/mmtk/mmtk-openjdk/repos/openjdk)
2022-02-23 14:09:57.577 INFO 3683 --- [ main] o.s.s.petclinic.PetClinicApplication : No active profile set, falling back to default profiles: default
[2022-02-23T03:09:58Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:09:58Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:09:58Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:09:58Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:09:59Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:09:59Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:09:59Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:09:59Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:09:59Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:09:59Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:00Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:00Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:01Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:01Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:02Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:02Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:02Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:02Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:03Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:04Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:04Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:04Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:05Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:05Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:06Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:06Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:08Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:08Z INFO mmtk::scheduler::gc_work] End of GC
2022-02-23 14:10:08.263 INFO 3683 --- [ main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2022-02-23 14:10:08.971 INFO 3683 --- [ main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 602 ms. Found 4 JPA repository interfaces.
[2022-02-23T03:10:09Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:09Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:10Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:11Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:12Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:12Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:14Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:14Z INFO mmtk::scheduler::gc_work] End of GC
2022-02-23 14:10:14.706 INFO 3683 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)
2022-02-23 14:10:14.868 INFO 3683 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2022-02-23 14:10:14.869 INFO 3683 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.45]
2022-02-23 14:10:15.496 INFO 3683 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2022-02-23 14:10:15.496 INFO 3683 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 17548 ms
[2022-02-23T03:10:16Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:16Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:18Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:18Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:20Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:20Z INFO mmtk::scheduler::gc_work] End of GC
2022-02-23 14:10:20.821 INFO 3683 --- [ main] org.ehcache.core.EhcacheManager : Cache 'vets' created in EhcacheManager.
2022-02-23 14:10:20.979 INFO 3683 --- [ main] org.ehcache.jsr107.Eh107CacheManager : Registering Ehcache MBean javax.cache:type=CacheStatistics,CacheManager=urn.X-ehcache.jsr107-default-config,Cache=vets
2022-02-23 14:10:21.031 INFO 3683 --- [ main] org.ehcache.jsr107.Eh107CacheManager : Registering Ehcache MBean javax.cache:type=CacheStatistics,CacheManager=urn.X-ehcache.jsr107-default-config,Cache=vets
[2022-02-23T03:10:21Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:21Z INFO mmtk::scheduler::gc_work] End of GC
2022-02-23 14:10:21.636 INFO 3683 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting...
[2022-02-23T03:10:23Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:23Z INFO mmtk::scheduler::gc_work] End of GC
2022-02-23 14:10:24.241 INFO 3683 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed.
[2022-02-23T03:10:24Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:25Z INFO mmtk::scheduler::gc_work] End of GC
2022-02-23 14:10:25.589 INFO 3683 --- [ main] o.hibernate.jpa.internal.util.LogHelper : HHH000204: Processing PersistenceUnitInfo [name: default]
2022-02-23 14:10:26.382 INFO 3683 --- [ main] org.hibernate.Version : HHH000412: Hibernate ORM core version 5.4.30.Final
[2022-02-23T03:10:26Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:26Z INFO mmtk::scheduler::gc_work] End of GC
2022-02-23 14:10:28.445 INFO 3683 --- [ main] o.hibernate.annotations.common.Version : HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
[2022-02-23T03:10:28Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:28Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:30Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:30Z INFO mmtk::scheduler::gc_work] End of GC
2022-02-23 14:10:30.860 INFO 3683 --- [ main] org.hibernate.dialect.Dialect : HHH000400: Using dialect: org.hibernate.dialect.H2Dialect
[2022-02-23T03:10:32Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:33Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:34Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:34Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:36Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:36Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:39Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:39Z INFO mmtk::scheduler::gc_work] End of GC
2022-02-23 14:10:40.558 INFO 3683 --- [ main] o.h.e.t.j.p.i.JtaPlatformInitiator : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2022-02-23 14:10:40.716 INFO 3683 --- [ main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
[2022-02-23T03:10:41Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:41Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:43Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:43Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:45Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:45Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:47Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:47Z INFO mmtk::scheduler::gc_work] End of GC
2022-02-23 14:10:48.540 INFO 3683 --- [ main] o.s.s.concurrent.ThreadPoolTaskExecutor : Initializing ExecutorService 'applicationTaskExecutor'
[2022-02-23T03:10:48Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:48Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:50Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:50Z INFO mmtk::scheduler::gc_work] End of GC
[2022-02-23T03:10:51Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:51Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:51Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:51Z INFO mmtk::plan::global] [POLL] nursery: Triggering collection
[2022-02-23T03:10:51Z INFO mmtk::scheduler::gc_work] End of GC
At which point it hung.