Closed n1b0r closed 5 years ago
Well yes, ideally we would need to compare the time that would take without the mapping not just the execute query. Also I would need some profiling information using a sampler visualvm has one that should work just fine there.
Also to be sure that it’s the mapping that is slow we prob need the time to the first object. It’s possible the executequery does not wait for the query to be finished before returning but that rs.next does
quick question? how many case do you have on this? currently the case finding is not that optimised, the cost of growing number of case would be linear but that could have an impact there.
class C
{
Integer id;
}
class B
{
Integer id;
String type;
}
class B1 extends B
{
C c;
}
abstract class A
{
Integer id;
String name;
String type;
B b;
}
class A1 extends A
{
}
String query = "....";
L.info("execute : {}", query);
long start = System.currentTimeMillis();
List<A> objects2 = new ArrayList<>();
try (PreparedStatement ps = this.datasource.getConnection().prepareStatement(query);
ResultSet rs = ps.executeQuery()) {
L.info("execute in {} ms", System.currentTimeMillis() - start);
start = System.currentTimeMillis();
while (rs.next())
{
A m = new A1();
Integer b_c_id = rs.getInt(1);
String b_type = rs.getString(2);
String b_d_name = rs.getString(3);
String type = rs.getString(4);
Integer id = rs.getInt(5);
Integer b_id = rs.getInt(6);
String name = rs.getString(7);
switch (type)
{
case "A1":
m = new A1();
break;
case "A2":
m = new A2();
break;
...... (42 cases later)
}
m.id = id;
m.name = name;
switch (b_type)
{
case "B1":
m.b = new B1();
C c = new C();
c.id = b_c_id;
((B1) m.b).setC(storage);
break;
case "B2":
m.b = new B2();
break;
......
}
m.b.id = b_id;
objects2.add(m);
}
L.info("next in {} ms", System.currentTimeMillis() - start);
L.info("objects2 " + objects2.size());
} catch (SQLException e) {
L.error("impossible to map the result set", e);
}
List<A> objects = new ArrayList();
try (
PreparedStatement ps = this.datasource.getConnection().prepareStatement(query);
ResultSet rs = ps.executeQuery()) {
L.info("execute in {} ms", System.currentTimeMillis() - start);
start = System.currentTimeMillis();
objects = mapper.stream(rs).collect(Collectors.toList());
L.info("mapped in {} ms", System.currentTimeMillis() - start);
L.info("objects " + objects.size());
} catch (SQLException e) {
L.error("impossible to map the result set", e);
}
This outputs :
execute in 291 ms next in 92 ms objects2 103700 execute in 403 ms mapped in 5389 ms objects 103700
I do not know if this test without mapper is enough but the difference between timing seems very huge.
What do you think ?
Yes Will have a look
quick question? how many case do you have on this? currently the case finding is not that optimised, the cost of growing number of case would be linear but that could have an impact there.
42 cases for A, and 20 for B
so I did a small test using a csv, it did not show the same cost - 3-4x more costly -, but I suspect that might be due to the call to the result set. I'm pushing a new version with an optimisation in 6.0.6 for one column -> to multiple constant value, as in your case. that should makes things better. it should be available in maven central in 30 minutes. could you try it out when you have time and tell me what's the impact on your case?
with a first quick test i have the same timings. I will try to do more test today and let you know. Thanks for your time.
Would be nice to get some sampling profiling info to find where it spends its time. There must be something weird happening... not sure it's discriminator related. a quick visualvm sampling should pin point to where the problem is. visualvm is free and shipped with java8.
I'm new to visualvm. Here are the relevant results :
" com.OFUSCATED.dao.MeasureDAO.main ()","114,198 ms (-0%)","5,903 ms (-0%)","37"
" java.lang.Thread.sleep[native] ()","108,294 ms (-0%)","0.0 ms (0%)","31"
" com.OFUSCATED.dao.MeasureDAO.search ()","5,802 ms (-0%)","5,802 ms (-0%)","7"
" java.util.stream.ReferencePipeline.collect ()","5,001 ms (-0%)","5,001 ms (-0%)","7"
" java.util.stream.AbstractPipeline.evaluate ()","5,001 ms (-0%)","5,001 ms (-0%)","7"
" java.util.stream.ReduceOps$ReduceOp.evaluateSequential ()","5,001 ms (-0%)","5,001 ms (-0%)","7"
" java.util.stream.AbstractPipeline.wrapAndCopyInto ()","5,001 ms (-0%)","5,001 ms (-0%)","7"
" java.util.stream.AbstractPipeline.copyInto ()","5,001 ms (-0%)","5,001 ms (-0%)","7"
" org.simpleflatmapper.util.EnumerableSpliterator.forEachRemaining ()","5,001 ms (-0%)","5,001 ms (-0%)","7"
" org.simpleflatmapper.map.mapper.JoinMapperEnumerable.next ()","4,496 ms (-0%)","4,496 ms (-0%)","11"
" org.simpleflatmapper.map.context.impl.BreakDetectorMappingContext.broke ()","4,297 ms (-0%)","4,297 ms (-0%)","12"
" org.simpleflatmapper.map.context.impl.BreakDetector.handleSource ()","4,297 ms (-0%)","4,297 ms (-0%)","11"
" org.simpleflatmapper.map.context.KeyDefinition.getValues ()","4,297 ms (-0%)","4,297 ms (-0%)","11"
" org.simpleflatmapper.map.context.KeyDefinition.singleValueKeys ()","4,297 ms (-0%)","4,297 ms (-0%)","11"
" org.simpleflatmapper.jdbc.impl.JdbcKeySourceGetter.getValue ()","4,193 ms (-0%)","4,193 ms (-0%)","12"
" org.simpleflatmapper.jdbc.impl.JdbcKeySourceGetter.getValue ()","4,193 ms (-0%)","4,193 ms (-0%)","12"
" org.apache.commons.dbcp.DelegatingResultSet.getObject ()","4,193 ms (-0%)","4,193 ms (-0%)","12"
" org.apache.commons.dbcp.DelegatingResultSet.getObject ()","4,193 ms (-0%)","4,193 ms (-0%)","12"
" org.postgresql.jdbc.PgResultSet.getObject ()","4,193 ms (-0%)","4,193 ms (-0%)","12"
" Self time","0.0 ms (0%)","0.0 ms (0%)","12"
" Self time","0.0 ms (0%)","0.0 ms (0%)","12"
" Self time","0.0 ms (0%)","0.0 ms (0%)","12"
" Self time","0.0 ms (0%)","0.0 ms (0%)","12"
" Self time","103 ms (-0%)","103 ms (-0%)","11"
" Self time","0.0 ms (0%)","0.0 ms (0%)","11"
" Self time","0.0 ms (0%)","0.0 ms (0%)","11"
" Self time","0.0 ms (0%)","0.0 ms (0%)","12"
" org.simpleflatmapper.map.mapper.ContextualSourceFieldMapperImpl.map ()","199 ms (-0%)","199 ms (-0%)","2"
" org.simpleflatmapper.map.mapper.AbstractMapper.map ()","199 ms (-0%)","199 ms (-0%)","2"
" org.simpleflatmapper.map.mapper.DiscriminatorConstantSourceMapperBuilder$DiscriminatorGenericBuilderMapper.mapFields ()","199 ms (-0%)","199 ms (-0%)","2"
" org.simpleflatmapper.map.mapper.DiscriminatorConstantSourceMapperBuilder$DiscriminatorGenericBuilderMapper.mapFields ()","199 ms (-0%)","199 ms (-0%)","2"
" org.simpleflatmapper.map.mapper.GenericBuilder.mapFrom ()","199 ms (-0%)","199 ms (-0%)","2"
" org.simpleflatmapper.map.fieldmapper.MapperFieldMapper.mapTo ()","199 ms (-0%)","199 ms (-0%)","2"
" org.simpleflatmapper.map.mapper.TransformSourceFieldMapper.map ()","199 ms (-0%)","199 ms (-0%)","2"
" org.simpleflatmapper.map.mapper.AbstractMapper.map ()","199 ms (-0%)","199 ms (-0%)","2"
" org.simpleflatmapper.map.mapper.DiscriminatorConstantSourceMapperBuilder$DiscriminatorGenericBuilderMapper.mapFields ()","100 ms (-0%)","100 ms (-0%)","1"
" org.simpleflatmapper.map.mapper.DiscriminatorConstantSourceMapperBuilder$DiscriminatorGenericBuilderMapper.mapFields ()","100 ms (-0%)","100 ms (-0%)","1"
" org.simpleflatmapper.map.mapper.GenericBuilder.mapFrom ()","100 ms (-0%)","100 ms (-0%)","1"
" org.simpleflatmapper.map.mapper.DefaultConstantSourceMapperBuilder$PropertyFieldMeta$1.mapTo ()","100 ms (-0%)","100 ms (-0%)","1"
" org.simpleflatmapper.map.mapper.DefaultConstantSourceMapperBuilder$PropertyFieldMeta$1.mapTo ()","100 ms (-0%)","100 ms (-0%)","1"
" org.simpleflatmapper.map.fieldmapper.FieldMapperGetterWithConverter.get ()","100 ms (-0%)","100 ms (-0%)","1"
" org.simpleflatmapper.map.getter.ContextualGetterAdapter.get ()","100 ms (-0%)","100 ms (-0%)","1"
" org.simpleflatmapper.jdbc.impl.getter.StringResultSetGetter.get ()","100 ms (-0%)","100 ms (-0%)","1"
" org.simpleflatmapper.jdbc.impl.getter.StringResultSetGetter.get ()","100 ms (-0%)","100 ms (-0%)","1"
" org.apache.commons.dbcp.DelegatingResultSet.getString ()","100 ms (-0%)","100 ms (-0%)","1"
" org.apache.commons.dbcp.DelegatingResultSet.getString ()","100 ms (-0%)","100 ms (-0%)","1"
" org.postgresql.jdbc.PgResultSet.getString ()","100 ms (-0%)","100 ms (-0%)","1"
" org.postgresql.core.Encoding.decode ()","100 ms (-0%)","100 ms (-0%)","1"
If I understand correctly, I spend 4K ms in the org.postgresql.jdbc.PgResultSet.getObject ()
method.
If you have any thought, I continue investigating...
What I find weird, is that I do not have same timings with different sql query.
SELECT
a.id as id,
a.type as type,
b.type as b_type,
c.id as b_c_id
FROM a
LEFT JOIN b on a.b_id=b.id
LEFT JOIN b_d on b.id=b_d.d_id
LEFT JOIN b_c on b.id=b_c.b_id
LEFT JOIN c on b_c.c_id=c.id
gives me results :
execute in 528 ms mapped in 5919 ms
SELECT
b.type as target_type,
a.type as type,
a.id as id
FROM a
LEFT JOIN b on a.b_id=b.id
LEFT JOIN b_d on b.id=b_d.d_id
LEFT JOIN b_c on b.id=b_c.c_id
execute in 491 ms mapped in 949 ms
Thanks!! that will help. which version of postgres driver are you using? I'll check the source code, I'm using getObject to detect null and deal with aggregation, but I should be able to replace it with the proper call as we should have the type with the metadata. I might also add the possibility of providing a getter for the key if all fail.
<dependency>
<groupId>org.postgresql</groupId>
<artifactId>postgresql</artifactId>
<version>42.2.5</version>
</dependency>
getObject looks fine, I wonder if there is some safepoint biais in there. will try to create a benchmark using postgres.
discriminators seems to perform good, the problem occurs when I add the b_c_id
column to the query which may make the mapper instantiate a new C object (which is not part of the discriminator mechanism) if the Child B (B1 in our case) class has a c
attribute.
Please tell me if this is not clear.
so the time is spent checking the key for breaks and null. I have a feeling that for each type the key is added which would increase the number of checks being made. validating that now.
yep looks like it, I should be able to fix that.
Benchmark Mode Cnt Score Error Units
DiscriminatorBenchmark.testNoDiscriminator avgt 5 48.025 ± 5.033 ms/op
DiscriminatorBenchmark.testWithDiscriminator avgt 5 93.178 ± 4.201 ms/op
DiscriminatorBenchmark.testWithDiscriminatorWithKeys avgt 5 10041.184 ± 841.473 ms/op
and that will be with last fix
Benchmark Mode Cnt Score Error Units
DiscriminatorBenchmark.testNoDiscriminator avgt 5 40.451 ± 0.391 ms/op
DiscriminatorBenchmark.testWithDiscriminator avgt 5 82.501 ± 1.028 ms/op
DiscriminatorBenchmark.testWithDiscriminatorWithKeys avgt 5 129.344 ± 1.659 ms/op
there was a combinatorial effect the break detector, meaning with b_c_id it would have more than 800 detectors slowing everything down. the codes now will merge does if they have the same key. giving a constant 3. I change the keypredicates to also merge better.
just pushed 6.0.7 to maven central. hopefully that should be it. should be there in 30 minutes.
PS : scores are to be taken with a pinch of salt it's the magnitude that matter there, as it ran on my laptop
As a quick first test, i still have the problem, the timings are the same.
The visualvm log seems to have changed.
" com.OBFUSCATED.dao.MeasureDAO.main ()","108,389 ms (-0%)","5,990 ms (-0%)","11"
" java.lang.Thread.sleep[native] ()","102,398 ms (-0%)","0.0 ms (0%)","6"
" com.OBFUSCATED.dao.MeasureDAO.search ()","5,698 ms (-0%)","5,698 ms (-0%)","7"
" java.util.stream.ReferencePipeline.collect ()","5,201 ms (-0%)","5,201 ms (-0%)","6"
" java.util.stream.AbstractPipeline.evaluate ()","5,201 ms (-0%)","5,201 ms (-0%)","6"
" java.util.stream.ReduceOps$ReduceOp.evaluateSequential ()","5,201 ms (-0%)","5,201 ms (-0%)","6"
" java.util.stream.AbstractPipeline.wrapAndCopyInto ()","5,201 ms (-0%)","5,201 ms (-0%)","6"
" java.util.stream.AbstractPipeline.copyInto ()","5,201 ms (-0%)","5,201 ms (-0%)","6"
" org.simpleflatmapper.util.EnumerableSpliterator.forEachRemaining ()","5,201 ms (-0%)","5,201 ms (-0%)","6"
" org.simpleflatmapper.map.mapper.JoinMapperEnumerable.next ()","5,002 ms (-0%)","5,002 ms (-0%)","8"
" org.simpleflatmapper.map.context.impl.BreakDetectorMappingContext.broke ()","4,903 ms (-0%)","4,903 ms (-0%)","9"
" org.simpleflatmapper.map.context.impl.BreakDetector.handleSource ()","4,602 ms (-0%)","4,602 ms (-0%)","10"
" org.simpleflatmapper.map.context.KeyDefinition.getValues ()","4,602 ms (-0%)","4,602 ms (-0%)","10"
" org.simpleflatmapper.map.context.KeyDefinition.singleValueKeys ()","4,602 ms (-0%)","4,602 ms (-0%)","10"
" org.simpleflatmapper.jdbc.impl.JdbcKeySourceGetter.getValue ()","4,602 ms (-0%)","4,602 ms (-0%)","10"
" org.simpleflatmapper.jdbc.impl.JdbcKeySourceGetter.getValue ()","4,602 ms (-0%)","4,602 ms (-0%)","10"
" org.apache.commons.dbcp.DelegatingResultSet.getObject ()","4,501 ms (-0%)","4,501 ms (-0%)","11"
" org.apache.commons.dbcp.DelegatingResultSet.getObject ()","4,501 ms (-0%)","4,501 ms (-0%)","11"
" org.postgresql.jdbc.PgResultSet.getObject ()","4,501 ms (-0%)","4,501 ms (-0%)","11"
" org.postgresql.jdbc.PgResultSet.internalGetObject ()","2,997 ms (-0%)","2,997 ms (-0%)","16"
" org.postgresql.jdbc.PgResultSet.getSQLType ()","2,796 ms (-0%)","2,796 ms (-0%)","15"
" Self time","2,796 ms (-0%)","2,796 ms (-0%)","15"
" org.postgresql.jdbc.PgResultSet.initSqlType ()","0.0 ms (0%)","0.0 ms (0%)","1"
" org.postgresql.jdbc.PgResultSet.getInt ()","201 ms (-0%)","201 ms (-0%)","2"
" org.postgresql.jdbc.PgResultSet.getFastInt ()","201 ms (-0%)","201 ms (-0%)","2"
" Self time","0.0 ms (0%)","0.0 ms (0%)","2"
" Self time","0.0 ms (0%)","0.0 ms (0%)","16"
" Self time","1,504 ms (-0%)","1,504 ms (-0%)","11"
" Self time","0.0 ms (0%)","0.0 ms (0%)","11"
" Self time","0.0 ms (0%)","0.0 ms (0%)","11"
" Self time","100 ms (-0%)","100 ms (-0%)","10"
" Self time","0.0 ms (0%)","0.0 ms (0%)","10"
" Self time","0.0 ms (0%)","0.0 ms (0%)","10"
" Self time","0.0 ms (0%)","0.0 ms (0%)","10"
" Self time","0.0 ms (0%)","0.0 ms (0%)","10"
" org.simpleflatmapper.map.context.impl.BreakDetector.markRootAsBroken ()","201 ms (-0%)","201 ms (-0%)","1"
" org.simpleflatmapper.map.context.impl.KeyObjectStore.clear ()","201 ms (-0%)","201 ms (-0%)","1"
" java.util.Arrays.fill ()","201 ms (-0%)","201 ms (-0%)","2"
" Self time","0.0 ms (0%)","0.0 ms (0%)","1"
" Self time","0.0 ms (0%)","0.0 ms (0%)","1"
" org.simpleflatmapper.map.context.impl.BreakDetector.broke ()","99.8 ms (-0%)","99.8 ms (-0%)","1"
" org.simpleflatmapper.map.context.KeyDefinition.getValues ()","99.8 ms (-0%)","99.8 ms (-0%)","1"
" org.simpleflatmapper.map.context.KeyDefinition.singleValueKeys ()","99.8 ms (-0%)","99.8 ms (-0%)","1"
" org.simpleflatmapper.jdbc.impl.JdbcKeySourceGetter.getValue ()","99.8 ms (-0%)","99.8 ms (-0%)","1"
" org.simpleflatmapper.jdbc.impl.JdbcKeySourceGetter.getValue ()","99.8 ms (-0%)","99.8 ms (-0%)","1"
" org.apache.commons.dbcp.DelegatingResultSet.getObject ()","99.8 ms (-0%)","99.8 ms (-0%)","1"
" org.apache.commons.dbcp.DelegatingResultSet.getObject ()","99.8 ms (-0%)","99.8 ms (-0%)","1"
" org.postgresql.jdbc.PgResultSet.getObject ()","99.8 ms (-0%)","99.8 ms (-0%)","1"
" org.postgresql.jdbc.PgResultSet.internalGetObject ()","99.8 ms (-0%)","99.8 ms (-0%)","1"
" org.postgresql.jdbc.PgResultSet.getSQLType ()","99.8 ms (-0%)","99.8 ms (-0%)","1"
" Self time","0.0 ms (0%)","0.0 ms (0%)","1"
" Self time","0.0 ms (0%)","0.0 ms (0%)","1"
" Self time","0.0 ms (0%)","0.0 ms (0%)","1"
" Self time","0.0 ms (0%)","0.0 ms (0%)","1"
" Self time","0.0 ms (0%)","0.0 ms (0%)","1"
" Self time","0.0 ms (0%)","0.0 ms (0%)","1"
" Self time","0.0 ms (0%)","0.0 ms (0%)","1"
" Self time","0.0 ms (0%)","0.0 ms (0%)","1"
" Self time","0.0 ms (0%)","0.0 ms (0%)","1"
" Self time","0.0 ms (0%)","0.0 ms (0%)","9"
" org.simpleflatmapper.map.mapper.ContextualSourceFieldMapperImpl.map ()","99.7 ms (-0%)","99.7 ms (-0%)","1"
" org.simpleflatmapper.map.mapper.AbstractMapper.map ()","99.7 ms (-0%)","99.7 ms (-0%)","1"
" org.simpleflatmapper.map.mapper.DiscriminatorConstantSourceMapperBuilder$DiscriminatorGenericBuilderMapper.mapFields ()","99.7 ms (-0%)","99.7 ms (-0%)","1"
" org.simpleflatmapper.map.mapper.DiscriminatorConstantSourceMapperBuilder$DiscriminatorGenericBuilderMapper.mapFields ()","99.7 ms (-0%)","99.7 ms (-0%)","1"
" org.simpleflatmapper.map.mapper.GenericBuilder.mapFrom ()","99.7 ms (-0%)","99.7 ms (-0%)","1"
" Self time","0.0 ms (0%)","0.0 ms (0%)","1"
" Self time","0.0 ms (0%)","0.0 ms (0%)","1"
" Self time","0.0 ms (0%)","0.0 ms (0%)","1"
" Self time","0.0 ms (0%)","0.0 ms (0%)","1"
" Self time","0.0 ms (0%)","0.0 ms (0%)","8"
" Self time","198 ms (-0%)","198 ms (-0%)","6"
" Self time","0.0 ms (0%)","0.0 ms (0%)","6"
" Self time","0.0 ms (0%)","0.0 ms (0%)","6"
" Self time","0.0 ms (0%)","0.0 ms (0%)","6"
" Self time","0.0 ms (0%)","0.0 ms (0%)","6"
" Self time","0.0 ms (0%)","0.0 ms (0%)","6"
Did you do your tests with pure jdbc ? Maybe I should try to do it using pure jdbc, I'm using dbcp datasource wich may cause something...
I will perform others tests, and let you know.
Once again, thanks for your time.
just to confirm it's the same problem could you try without specifying the keys?
what do you means ? which keys ?
Without the addKeys call on the mapper
Do you have only the “id” column in the keys could also try with addKeys(“id”, “b_id”, “b_c_id”)?
Good point !
with
.addKeys("id", "target_id", "target_host_id")
execute in 505 ms
mapped in 930 ms
and with
without addKeys
execute in 449 ms
mapped in 644 ms
I thought I only need to use addKeys for column mapping to *2many relationships. Should I put every relationship column in the addKeys ?
the keys are use for null checking and x-to-many mapping yes, but in 6.0.7 it does some optimisation of the sub context only when keys are set - it matters only for mapper with discriminators -, I just need to find a way to do it better soon to come in 6.0.8. when the keys are not set it does not do null check or break detection so no perf impact there.
if you don't need the null check - ie id b_c_id is null then c is null - the you don't need the keys. but Ideally, it should not matter.
I thought I quickly fixed in 6.0.8 but no... so avoid that one ...
6.0.9 now available in maven central should address the no keys, keys or partial keys perf issue.
thanks a lot for your support !
Hello,
Im using this kind of mapper :
I have a resultset which contains 100K row with 7 columns.
Here is the code mapping rs to list :
my timings are : execute in 288 ms mapped in 5103 ms
How can I help you troubleshoot this ?