EmbeddedDatabase#drop 30x latency regression between 23.5.1 and 23.6.1 #1234
Description
ArcadeDB Version:
upgrading from 23.5.1 to 23.6.1
OS and JDK Version:
$ java -version
openjdk version "17.0.7" 2023-04-18
OpenJDK Runtime Environment (Red_Hat-17.0.7.0.7-4.fc37) (build 17.0.7+7)
OpenJDK 64-Bit Server VM (Red_Hat-17.0.7.0.7-4.fc37) (build 17.0.7+7, mixed mode, sharing)
$ cat /etc/os-release
NAME="Fedora Linux"
VERSION="37 (Server Edition)"
Expected behavior
Upgrading from 23.5.1 to 23.6.1 should not have regressed Database#drop
screenshot of "slow" 23.6.1 profile showing 904 ms spent in EmbeddedDatabase#drop, w/ 872 ms coming from PageManager#close:
screenshot of "fast" 23.5.1 profile showing 36 ms spent in EmbeddedDatabase#drop:
The only difference between these profiler snapshots is the arcadedb upgrade
Actual behavior
Between upgrading from 23.5.1 to 23.6.1 a single test I have went from executing in ~6 seconds to >24 seconds
faster 23.5.1 test logs show:
5300 [main] [INFO] io.vos.service.graph.database.arcadedb.ArcadeUpsertNodeMutationTest - dropping db:[/tmp/arcadedb-databases/ArcadeUpsertNodeMutationTest-285f7f28-ca71-4f1b-9bf0-ca3b2161cc54]
| | | | | | | duration: 30 ms
| | | | | | | status: [OK] SUCCESSFUL
| | | | | '-- VertexTests finished after 93 ms.
| | | | '-- UpsertNodeMutationTests finished after 5337 ms.
slow 23.6.1 test logs show:
23265 [main] [INFO] io.vos.service.graph.database.arcadedb.ArcadeUpsertNodeMutationTest - dropping db:[/tmp/arcadedb-databases/ArcadeUpsertNodeMutationTest-fad9eea7-ed02-4ae0-9b1f-690f1fc203d0]
| | | | | | | duration: 1031 ms
| | | | | | | status: [OK] SUCCESSFUL
| | | | | '-- VertexTests finished after 3094 ms.
| | | | '-- UpsertNodeMutationTests finished after 24298 ms.
From the above "dropping db" log line, there is a slow down from ~30ms to ~1s per test, where "teardown" is effectively:
logger.info("dropping db:[{}]", dbName);
if (db != null) {
db.drop();
db = null;
}
I have been unable to reproduce this regression on the arcadedb test suites, trying to use com.arcadedb.DocumentTest as a proxy for teardown behavior, but it's 100% repeatable in my test setup.
Profiling the running tests with VisualVM shows the latency regression is 100% located in com.arcadedb.engine.PageManager#close
Steps to reproduce
I'm still working on a simply JUnit test that reproduces the issue, but I"m filing a bug here in case it's obvious where the regression might have come from in the release window.