RecordMapper cache contention when projecting complex expressions with DefaultRecordMapper #16606
Comments
|
Could this be related to #7431? |
|
I tried using |
lukaseder
added
C: Functionality
P: Medium
T: Support request
E: All Editions
and removed
T: Defect
labels
|
Thanks for your support request. The only difference between I doubt that this problem is really caused by jOOQ, unless you have actual evidence (e.g. a profiler session would help)? I might be able to help you with your performance problem, though. Can you show your complete query, all the DDL to create the tables involved (including indexes!) |
|
Happy to get you the info that you need. After inspecting several days of telemetry, I feel that I can declare that using It's too bad that jOOQ has no more logging info other than I'm not having issues with the Postgres query per se. As you can see from the above trace, the Postgres query finishes in an acceptable 120.958ms. Manual executions of the query are consistent with what's being reported in the telemetry's traces. The traces were collected via Google Cloud Trace from a Google Cloud SQL Postgres server. I'm a bit busy and will likely have time to collect the profiling session next weekend. |
|
I didn't get a chance to profile this yet, but I have a question. Could there be some kind of Hikari/Postgres JDBC configuration that could cause this kind of behavior? |
If only a profiler could give insight ;-) Perhaps, if you turn on trace logging for everything, there's a high level hint, though logging comes with its own overhead. A primitive way of "profiling" is to use jstack to extract stack traces from running processes: If you do this frequently enough while this happens, you can get some starter insight into where your process is hanging. This would at least help with some assumptions. |
Yep, point taken. I'm being lazy and am hoping that there's some kind of well known, well know to everyone but me :), pathological configuration that wreaks havoc on jOOQ.
As reported above, I have turned on trace level logging and what it's telling me is that jOOQ logs that it has completed fetching the record and yet the thread of control is not returned back to my code for 2-5 seconds. Hence profiling is the "next step".
Thanks! I'll try this as well. |
Does this include logging all activities in the connection pool / driver, including calls to |
It does not. I am only going by what jOOQ logs: and then there's 2-4 seconds of silence. TLDR - It's the caching of the record mapperMy jOOQ query is this gigantic SQL statement with layers and layers of CTEs. When the record mapper gets cached, the jOOQ code visits all the elements of the query; I assume to get an accurate key for the cache. As mentioned above, the jOOQ code is executed via All I want back is a boolean. Thread DumpSo, I've managed to collect thread dumps, captured every 500ms. The jOOQ logging states that the row was fetched in 100ms, but the thread of control is not returned back to my code until after 6.5s. Here's the distributed trace: 
You can see the events that have been generated that mark when the thread dumps occurred. Here is the stack trace. |
lukaseder
added
T: Defect
P: High
and removed
T: Support request
R: Feedback Pending
P: Medium
labels
|
Thanks for the additional investigation, that's very useful. I recently thought about this possibility of there being a potential slowdown in this area. The expression needs to be evaluated once to render the query, but it should obviously be avoided to repeat this operation for every record that is being mapped. Can you work around this by either:
|
|
Thanks. I did the latter and everyone is quite happy. :) |
|
Looking into this now. I don't think that an individual rendering is really the problem here. The rendering has already been done when generating the query, and there it wasn't a problem (or else, jOOQ would have very significant problems in general). But what's going on here is that the cache access is synchronized, e.g.: So it might be the case that multiple of these computations block each other as each one takes maybe 1ms, which starts adding up. |
|
I wonder if we should cache record mappers at all, if they contain projections of expressions like these, at all. We have a marker interface Alternatively, instead of using the |
|
Caching really is essential, though. With this benchmark: @Fork(value = 1, jvmArgsAppend = "-Dorg.jooq.no-logo=true")
@Warmup(iterations = 3, time = 3)
@Measurement(iterations = 7, time = 3)
@State(Scope.Benchmark)
public class BenchmarkRecordMapper {
@State(Scope.Benchmark)
public static class BenchmarkState {
Connection connection;
DSLContext ctx1;
DSLContext ctx2;
Result<?> result1;
Result<?> result2;
@Setup(Level.Trial)
public void setup() throws Exception {
try (InputStream is = BenchmarkState.class.getResourceAsStream("/config.properties")) {
Properties p = new Properties();
p.load(is);
connection = DriverManager.getConnection(
p.getProperty("db.url"),
p.getProperty("db.username"),
p.getProperty("db.password")
);
}
ctx1 = DSL.using(connection, new Settings().withExecuteLogging(false).withRenderQuotedNames(NEVER).withCacheRecordMappers(false));
result1 = ctx1
.select(AUTHOR.FIRST_NAME, AUTHOR.LAST_NAME)
.from(AUTHOR)
.fetch();
ctx2 = DSL.using(connection, new Settings().withExecuteLogging(false).withRenderQuotedNames(NEVER).withCacheRecordMappers(true));
result2 = ctx2
.select(AUTHOR.FIRST_NAME, AUTHOR.LAST_NAME)
.from(AUTHOR)
.fetch();
}
}
static class A1 {
final String firstName;
final String lastName;
A1(String firstName, String lastName) {
this.firstName = firstName;
this.lastName = lastName;
}
}
@Benchmark
public Object intoImmutablePojoNoCache(BenchmarkState state) {
return state.result1.into(A1.class);
}
@Benchmark
public Object intoImmutablePojoCache(BenchmarkState state) {
return state.result2.into(A1.class);
}
}When benchmarking only the mapping as above, then there's a 10x performance improvement with the cache! This is significant for large result sets, where the mapping time can be significant compared to the execution time (this isn't the case for small result sets) |
|
As expected, while there's some overhead rendering the SQL all the time in order to check for equality, it's not as significant (in a benchmark) compared to turning off the cache: The types of queries are these: private Result<?> queryTableFields(DSLContext ctx) {
return ctx
.select(AUTHOR.FIRST_NAME, AUTHOR.LAST_NAME)
.from(AUTHOR)
.fetch();
}
private Result<?> queryExpressions(DSLContext ctx) {
return ctx
.select(
field(select(field(select(field(select(field(select(field(select(AUTHOR.FIRST_NAME)))))))))),
field(select(field(select(field(select(field(select(field(select(AUTHOR.LAST_NAME))))))))))
)
.from(AUTHOR)
.fetch();
}Comparing the immutable pojo mapper with the other ones, there does appear to be an overhead worth looking into separately, as that overhead doesn't reproduce to the same extent with other algorithms (especially compared to the mutable pojos). The benchmark doesn't fully reflect your situation, as we only run 2 queries instead of hundreds to thousands. But it does hint at this being more of a concurrency problem (synchronisation on the cache) than something else. |
lukaseder
changed the title
|
There's also room for improvement here at a different level. The actual In other words, there are On the other hand, mappers that depend on the field name only really work if the field is not an expression, but a
The case you ran into should simply never happen, because an
|
|
There's an even better internal marker interface: |
|
Interestingly, this "improvement" negatively affects almost all mapping benchmarks, possibly due to the extra allocation for each lookup? |
Expected behavior
I have a SQL query that has three CTEs that is essentially
The jOOQ code is executed via
I expect the timing of Java/jOOQ code to closely wrap the execution of the SQL code, e.g. if the query takes roughly 100ms, I expect there to roughly be, at most, an additional 100ms.
Actual behavior
What I'm seeing is that the query takes 100ms and there is an additional 2-3 seconds before the above fetch returns. This is occurring on a fully warmed up JVM where this very code has been executed. Debug level log messages from jOOQ show that jOOQ fetches the result but there is a lag before control is returned back to the caller of
fetchOptionalInto().What we also see is that if the code is intensely uses, then the latency added to the query becomes 100ms. However, after a period of inactivity, e.g. several house, we start seeing the 2-3 second latency again.
Steps to reproduce the problem
If there's nothing obvious, then I shall embark on creating a reproducible example.
jOOQ Version
jOOQ Profesional Edition 3.18.3
Database product and version
PostgreSQL 12.17 on x86_64-pc-linux-gnu, compiled by Debian clang version 12.0.1, 64-bit
Java Version
java version "21.0.2" 2024-01-16 LTS
JDBC / R2DBC driver name and version (include name if unofficial driver)
42.7.2
The text was updated successfully, but these errors were encountered: