TypeHandlerRegistry#getTypeHandler is slow

classic Classic list List threaded Threaded
16 messages Options
Reply | Threaded
Open this post in threaded view
|

TypeHandlerRegistry#getTypeHandler is slow

Jatin Puri

I have been spending some time lately to look at performance statistics of our application (normally by sampling on jvisualvm). There can always be an error associated with sampling, but it does provide the right direction to detect slow method calls.


For quite sometime, I have been observing below patterns where `org.apache.ibatis.type.TypeHandlerRegistry#getTypeHandler(java.lang.reflect.Type, org.apache.ibatis.type.JdbcType)` seems to consume large amount of time. Note that the number of records returned by database is quite large (100k - 200k). But many a times, the time taken to query is found faster than `TypeHandlerRegistry#getTypeHandler`. 

The slowness is consistent in the application. Ranging from 3-8 seconds. Sample snapshot below:







My batis version being used: 3.2.8. Java8. Database: Sql Server 2014

Thanks

--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: TypeHandlerRegistry#getTypeHandler is slow

Jatin Puri
Would explicitly specifying `jdbcType` help? (From from what I understand in code, it wont)

--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: TypeHandlerRegistry#getTypeHandler is slow

Iwao AVE!
In reply to this post by Jatin Puri
Hi Jatin,

The attached image seems to indicate that java.util.HashMap.get() consumed the time.
Does it actually take 10 seconds to execute the query on production? or just when profiling?
What exact version of Java 8 are you using?

Regards,
Iwao


2016-08-25 21:06 GMT+09:00 Jatin Puri <[hidden email]>:

I have been spending some time lately to look at performance statistics of our application (normally by sampling on jvisualvm). There can always be an error associated with sampling, but it does provide the right direction to detect slow method calls.


For quite sometime, I have been observing below patterns where `org.apache.ibatis.type.TypeHandlerRegistry#getTypeHandler(java.lang.reflect.Type, org.apache.ibatis.type.JdbcType)` seems to consume large amount of time. Note that the number of records returned by database is quite large (100k - 200k). But many a times, the time taken to query is found faster than `TypeHandlerRegistry#getTypeHandler`. 

The slowness is consistent in the application. Ranging from 3-8 seconds. Sample snapshot below:







My batis version being used: 3.2.8. Java8. Database: Sql Server 2014

Thanks


--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: TypeHandlerRegistry#getTypeHandler is slow

Jatin Puri
Hi Iwao.

Thanks for the response. Appreciate it.

So to share the stats from production. The query takes 4-5 seconds to fetch (The response time is based on running the query via sql studio. This is also confirmed by jvisualvm. Though sometimes depending on the load, it also response in 2-3 seconds). But TypeHandlerRegistry#getTypeHandler does consume significant amount of time. 

For example, fetching latest stats:


So as per this, the query execution time was ~1sec. But TypeHandlerRegistry#getTypeHandler took ~12 seconds.

If it helps, the resultMap is of form:
    <resultMap type="com.some.Class" id="unit">
<id property="X" column="x" />
<result property="XX" column="xx" javaType="java.lang.Double"/>
<result property="XXX" column="xxx" javaType="java.lang.Double"/>
<result property="a.X" column="ww" />
<result property="a.name" column="xxxx" />
<result property="a.isException" column="is_exception" />
<result property="b"  column="n" />
        <result property="c"    column="m" />
        <result property="d" column="e" />
        <result property="e"   column="q" />
        
       <discriminator javaType="int" column="qwerty">
<case value="1" resultMap="Q"/>
<case value="2" resultMap="QQ"/>
<case value="3" resultMap="QQQ"/>
<case value="4" resultMap="W"/>
            <case value="6" resultMap="WW"/>
            <case value="7" resultMap="WWW"/>
<case value="8" resultMap="E"/>
<case value="10" resultMap="EE"/>
<case value="11" resultMap="EEE"/>
<case value="15" resultMap="T"/>
<case value="13" resultMap="TT"/>
<case value="16" resultMap="TTT"/>
<case value="17" resultMap="TTTT"/>
</discriminator>
</resultMap>

So I would say, there would be around 30-50 columns per record. 
Note that the time taken is not only during fetch. But also during insert (based on similar profiling).

Java version:
JVM: Java HotSpot(TM) 64-Bit Server VM (25.60-b23, mixed mode)
Java: version 1.8.0_60, vendor Oracle Corporation

Thanks for the help. I know it might be frustrating from limited data. Please feel free to ask from any specific kind of data.

Jatin

PS: Based on looking at code, I dont think manually specifying jdbcType helps as in whatever case it would still have to do HashMap#get. I am not sure what can be done here to reduce this duration.

--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: TypeHandlerRegistry#getTypeHandler is slow

Iwao AVE!
Thanks for the info!
Both images didn't include the invocation count, but how many were they?



2016-08-29 23:21 GMT+09:00 Jatin Puri <[hidden email]>:
Hi Iwao.

Thanks for the response. Appreciate it.

So to share the stats from production. The query takes 4-5 seconds to fetch (The response time is based on running the query via sql studio. This is also confirmed by jvisualvm. Though sometimes depending on the load, it also response in 2-3 seconds). But TypeHandlerRegistry#getTypeHandler does consume significant amount of time. 

For example, fetching latest stats:


So as per this, the query execution time was ~1sec. But TypeHandlerRegistry#getTypeHandler took ~12 seconds.

If it helps, the resultMap is of form:
    <resultMap type="com.some.Class" id="unit">
<id property="X" column="x" />
<result property="XX" column="xx" javaType="java.lang.Double"/>
<result property="XXX" column="xxx" javaType="java.lang.Double"/>
<result property="a.X" column="ww" />
<result property="a.name" column="xxxx" />
<result property="a.isException" column="is_exception" />
<result property="b"  column="n" />
        <result property="c"    column="m" />
        <result property="d" column="e" />
        <result property="e"   column="q" />
        
       <discriminator javaType="int" column="qwerty">
<case value="1" resultMap="Q"/>
<case value="2" resultMap="QQ"/>
<case value="3" resultMap="QQQ"/>
<case value="4" resultMap="W"/>
            <case value="6" resultMap="WW"/>
            <case value="7" resultMap="WWW"/>
<case value="8" resultMap="E"/>
<case value="10" resultMap="EE"/>
<case value="11" resultMap="EEE"/>
<case value="15" resultMap="T"/>
<case value="13" resultMap="TT"/>
<case value="16" resultMap="TTT"/>
<case value="17" resultMap="TTTT"/>
</discriminator>
</resultMap>

So I would say, there would be around 30-50 columns per record. 
Note that the time taken is not only during fetch. But also during insert (based on similar profiling).

Java version:
JVM: Java HotSpot(TM) 64-Bit Server VM (25.60-b23, mixed mode)
Java: version 1.8.0_60, vendor Oracle Corporation

Thanks for the help. I know it might be frustrating from limited data. Please feel free to ask from any specific kind of data.

Jatin

PS: Based on looking at code, I dont think manually specifying jdbcType helps as in whatever case it would still have to do HashMap#get. I am not sure what can be done here to reduce this duration.

--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: TypeHandlerRegistry#getTypeHandler is slow

Iwao AVE!
I should have been clearer, but what I was trying to say is that the bad performance is caused by HashMap#get() and not by MyBatis code if we trust the profile.
Assuming that the invocation count was one million, a code like below should take 12 seconds in your application (it might be possible with > a billion invocation).

Map<Type, JdbcType> map = new HashMap<Type, JdbcType>();
map.put(String.class, JdbcType.VARCHAR);
for (int i = 0; i < 1000000; i++) {
  map.get(Integer.class);
}

The common reason that slows down HashMap#get() is hashCode() method of the key object, but the keys used in TypeHandlerRegistry#getTypeHandler() are java.lang.reflect.Type and the enum JdbcType, so it's unlikely.
Does anyone have any idea?

Regards,
Iwao


2016-08-30 0:23 GMT+09:00 Iwao AVE! <[hidden email]>:
Thanks for the info!
Both images didn't include the invocation count, but how many were they?



2016-08-29 23:21 GMT+09:00 Jatin Puri <[hidden email]>:
Hi Iwao.

Thanks for the response. Appreciate it.

So to share the stats from production. The query takes 4-5 seconds to fetch (The response time is based on running the query via sql studio. This is also confirmed by jvisualvm. Though sometimes depending on the load, it also response in 2-3 seconds). But TypeHandlerRegistry#getTypeHandler does consume significant amount of time. 

For example, fetching latest stats:


So as per this, the query execution time was ~1sec. But TypeHandlerRegistry#getTypeHandler took ~12 seconds.

If it helps, the resultMap is of form:
    <resultMap type="com.some.Class" id="unit">
<id property="X" column="x" />
<result property="XX" column="xx" javaType="java.lang.Double"/>
<result property="XXX" column="xxx" javaType="java.lang.Double"/>
<result property="a.X" column="ww" />
<result property="a.name" column="xxxx" />
<result property="a.isException" column="is_exception" />
<result property="b"  column="n" />
        <result property="c"    column="m" />
        <result property="d" column="e" />
        <result property="e"   column="q" />
        
       <discriminator javaType="int" column="qwerty">
<case value="1" resultMap="Q"/>
<case value="2" resultMap="QQ"/>
<case value="3" resultMap="QQQ"/>
<case value="4" resultMap="W"/>
            <case value="6" resultMap="WW"/>
            <case value="7" resultMap="WWW"/>
<case value="8" resultMap="E"/>
<case value="10" resultMap="EE"/>
<case value="11" resultMap="EEE"/>
<case value="15" resultMap="T"/>
<case value="13" resultMap="TT"/>
<case value="16" resultMap="TTT"/>
<case value="17" resultMap="TTTT"/>
</discriminator>
</resultMap>

So I would say, there would be around 30-50 columns per record. 
Note that the time taken is not only during fetch. But also during insert (based on similar profiling).

Java version:
JVM: Java HotSpot(TM) 64-Bit Server VM (25.60-b23, mixed mode)
Java: version 1.8.0_60, vendor Oracle Corporation

Thanks for the help. I know it might be frustrating from limited data. Please feel free to ask from any specific kind of data.

Jatin

PS: Based on looking at code, I dont think manually specifying jdbcType helps as in whatever case it would still have to do HashMap#get. I am not sure what can be done here to reduce this duration.

--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.


--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: TypeHandlerRegistry#getTypeHandler is slow

Jatin Puri
The snapshot above if via sampling and not profiling (profiling is far expensive). Sampling doesn't provide the invocation count.

Its difficult to provide invocations based on dev because the data isn't same. 

For the above image, it is based on one db call and not a summary of many calls. The stats shared was for a single database call which fetched ~150k objects. And each record had close to ~40 columns.

>>bad performance is caused by HashMap#get() and not by MyBatis code if we trust the profile.

I agree to it. Sampling can give different results at different times (as it takes diffs between quick thread dumps). Because it is giving similar snapshots each time (over a month now), I suspect the cause is with the HashMap there. 
What is surprising is that the contents of HashMap is not very large (~35 pairs in above case). Neither for the nested HashMap (normally less than 5). So I am equally surprised at the behavior. But it is dampening the experience. (If hashcode is time-consuming, most of the times it does also say that. But its native in this case, so not sure. Not sure if java8 hashmap changes has a role here)

Any hacks around it? So that the call itself could be avoided. 

A question: Does it call `getTypeHandler`/`hasTypeHandler` for each record. Or only once per query? Can using `discriminator` be the cause of it? Does `discriminator` have any known performance impacts?

Thanks,
Jatin



On Tuesday, 30 August 2016 07:12:40 UTC+5:30, Iwao AVE! wrote:
I should have been clearer, but what I was trying to say is that the bad performance is caused by HashMap#get() and not by MyBatis code if we trust the profile.
Assuming that the invocation count was one million, a code like below should take 12 seconds in your application (it might be possible with > a billion invocation).

Map<Type, JdbcType> map = new HashMap<Type, JdbcType>();
map.put(String.class, JdbcType.VARCHAR);
for (int i = 0; i < 1000000; i++) {
  map.get(Integer.class);
}

The common reason that slows down HashMap#get() is hashCode() method of the key object, but the keys used in TypeHandlerRegistry#getTypeHandler() are java.lang.reflect.Type and the enum JdbcType, so it's unlikely.
Does anyone have any idea?

Regards,
Iwao


2016-08-30 0:23 GMT+09:00 Iwao AVE! <<a href="javascript:" target="_blank" gdf-obfuscated-mailto="XP3KA88cBwAJ" rel="nofollow" onmousedown="this.href=&#39;javascript:&#39;;return true;" onclick="this.href=&#39;javascript:&#39;;return true;">hara...@...>:
Thanks for the info!
Both images didn't include the invocation count, but how many were they?



2016-08-29 23:21 GMT+09:00 Jatin Puri <<a href="javascript:" target="_blank" gdf-obfuscated-mailto="XP3KA88cBwAJ" rel="nofollow" onmousedown="this.href=&#39;javascript:&#39;;return true;" onclick="this.href=&#39;javascript:&#39;;return true;">puri...@...>:
Hi Iwao.

Thanks for the response. Appreciate it.

So to share the stats from production. The query takes 4-5 seconds to fetch (The response time is based on running the query via sql studio. This is also confirmed by jvisualvm. Though sometimes depending on the load, it also response in 2-3 seconds). But TypeHandlerRegistry#getTypeHandler does consume significant amount of time. 

For example, fetching latest stats:

<a href="https://lh3.googleusercontent.com/-STHVRQhyZc0/V8RC-moyq8I/AAAAAAAAR6k/GMbB1hbQLesaslWawAlkZILY6u4w6hvmQCLcB/s1600/batis3.png" style="margin-left:1em;margin-right:1em" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://lh3.googleusercontent.com/-STHVRQhyZc0/V8RC-moyq8I/AAAAAAAAR6k/GMbB1hbQLesaslWawAlkZILY6u4w6hvmQCLcB/s1600/batis3.png&#39;;return true;" onclick="this.href=&#39;https://lh3.googleusercontent.com/-STHVRQhyZc0/V8RC-moyq8I/AAAAAAAAR6k/GMbB1hbQLesaslWawAlkZILY6u4w6hvmQCLcB/s1600/batis3.png&#39;;return true;">


So as per this, the query execution time was ~1sec. But TypeHandlerRegistry#getTypeHandler took ~12 seconds.

If it helps, the resultMap is of form:
    <resultMap type="com.some.Class" id="unit">
<id property="X" column="x" />
<result property="XX" column="xx" javaType="java.lang.Double"/>
<result property="XXX" column="xxx" javaType="java.lang.Double"/>
<result property="a.X" column="ww" />
<result property="<a href="http://a.name" target="_blank" rel="nofollow" onmousedown="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2Fa.name\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNFTYJ_MbdQGVbl9uOo0kx8w3rqSMA&#39;;return true;" onclick="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2Fa.name\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNFTYJ_MbdQGVbl9uOo0kx8w3rqSMA&#39;;return true;">a.name" column="xxxx" />
<result property="a.isException" column="is_exception" />
<result property="b"  column="n" />
        <result property="c"    column="m" />
        <result property="d" column="e" />
        <result property="e"   column="q" />
        
       <discriminator javaType="int" column="qwerty">
<case value="1" resultMap="Q"/>
<case value="2" resultMap="QQ"/>
<case value="3" resultMap="QQQ"/>
<case value="4" resultMap="W"/>
            <case value="6" resultMap="WW"/>
            <case value="7" resultMap="WWW"/>
<case value="8" resultMap="E"/>
<case value="10" resultMap="EE"/>
<case value="11" resultMap="EEE"/>
<case value="15" resultMap="T"/>
<case value="13" resultMap="TT"/>
<case value="16" resultMap="TTT"/>
<case value="17" resultMap="TTTT"/>
</discriminator>
</resultMap>

So I would say, there would be around 30-50 columns per record. 
Note that the time taken is not only during fetch. But also during insert (based on similar profiling).

Java version:
JVM: Java HotSpot(TM) 64-Bit Server VM (25.60-b23, mixed mode)
Java: version 1.8.0_60, vendor Oracle Corporation

Thanks for the help. I know it might be frustrating from limited data. Please feel free to ask from any specific kind of data.

Jatin

PS: Based on looking at code, I dont think manually specifying jdbcType helps as in whatever case it would still have to do HashMap#get. I am not sure what can be done here to reduce this duration.

--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to <a href="javascript:" target="_blank" gdf-obfuscated-mailto="XP3KA88cBwAJ" rel="nofollow" onmousedown="this.href=&#39;javascript:&#39;;return true;" onclick="this.href=&#39;javascript:&#39;;return true;">mybatis-user...@googlegroups.com.
For more options, visit <a href="https://groups.google.com/d/optout" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://groups.google.com/d/optout&#39;;return true;" onclick="this.href=&#39;https://groups.google.com/d/optout&#39;;return true;">https://groups.google.com/d/optout.


--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: TypeHandlerRegistry#getTypeHandler is slow

Brian Pontarelli
In my experience, these types of results are almost always caused by something else. Have you looked for GCs or locking or something else that could cause such long pauses?

Sent from my iPhone

On Aug 30, 2016, at 4:32 AM, Jatin Puri <[hidden email]> wrote:

The snapshot above if via sampling and not profiling (profiling is far expensive). Sampling doesn't provide the invocation count.

Its difficult to provide invocations based on dev because the data isn't same. 

For the above image, it is based on one db call and not a summary of many calls. The stats shared was for a single database call which fetched ~150k objects. And each record had close to ~40 columns.

>>bad performance is caused by HashMap#get() and not by MyBatis code if we trust the profile.

I agree to it. Sampling can give different results at different times (as it takes diffs between quick thread dumps). Because it is giving similar snapshots each time (over a month now), I suspect the cause is with the HashMap there. 
What is surprising is that the contents of HashMap is not very large (~35 pairs in above case). Neither for the nested HashMap (normally less than 5). So I am equally surprised at the behavior. But it is dampening the experience. (If hashcode is time-consuming, most of the times it does also say that. But its native in this case, so not sure. Not sure if java8 hashmap changes has a role here)

Any hacks around it? So that the call itself could be avoided. 

A question: Does it call `getTypeHandler`/`hasTypeHandler` for each record. Or only once per query? Can using `discriminator` be the cause of it? Does `discriminator` have any known performance impacts?

Thanks,
Jatin



On Tuesday, 30 August 2016 07:12:40 UTC+5:30, Iwao AVE! wrote:
I should have been clearer, but what I was trying to say is that the bad performance is caused by HashMap#get() and not by MyBatis code if we trust the profile.
Assuming that the invocation count was one million, a code like below should take 12 seconds in your application (it might be possible with > a billion invocation).

Map<Type, JdbcType> map = new HashMap<Type, JdbcType>();
map.put(String.class, JdbcType.VARCHAR);
for (int i = 0; i < 1000000; i++) {
  map.get(Integer.class);
}

The common reason that slows down HashMap#get() is hashCode() method of the key object, but the keys used in TypeHandlerRegistry#getTypeHandler() are java.lang.reflect.Type and the enum JdbcType, so it's unlikely.
Does anyone have any idea?

Regards,
Iwao


2016-08-30 0:23 GMT+09:00 Iwao AVE! <<a href="javascript:" target="_blank" gdf-obfuscated-mailto="XP3KA88cBwAJ" rel="nofollow" onmousedown="this.href='javascript:';return true;" onclick="this.href='javascript:';return true;">hara...@...>:
Thanks for the info!
Both images didn't include the invocation count, but how many were they?



2016-08-29 23:21 GMT+09:00 Jatin Puri <<a href="javascript:" target="_blank" gdf-obfuscated-mailto="XP3KA88cBwAJ" rel="nofollow" onmousedown="this.href='javascript:';return true;" onclick="this.href='javascript:';return true;">puri...@...>:
Hi Iwao.

Thanks for the response. Appreciate it.

So to share the stats from production. The query takes 4-5 seconds to fetch (The response time is based on running the query via sql studio. This is also confirmed by jvisualvm. Though sometimes depending on the load, it also response in 2-3 seconds). But TypeHandlerRegistry#getTypeHandler does consume significant amount of time. 

For example, fetching latest stats:

<a href="https://lh3.googleusercontent.com/-STHVRQhyZc0/V8RC-moyq8I/AAAAAAAAR6k/GMbB1hbQLesaslWawAlkZILY6u4w6hvmQCLcB/s1600/batis3.png" style="margin-left:1em;margin-right:1em" target="_blank" rel="nofollow" onmousedown="this.href='https://lh3.googleusercontent.com/-STHVRQhyZc0/V8RC-moyq8I/AAAAAAAAR6k/GMbB1hbQLesaslWawAlkZILY6u4w6hvmQCLcB/s1600/batis3.png';return true;" onclick="this.href='https://lh3.googleusercontent.com/-STHVRQhyZc0/V8RC-moyq8I/AAAAAAAAR6k/GMbB1hbQLesaslWawAlkZILY6u4w6hvmQCLcB/s1600/batis3.png';return true;">


So as per this, the query execution time was ~1sec. But TypeHandlerRegistry#getTypeHandler took ~12 seconds.

If it helps, the resultMap is of form:
    <resultMap type="com.some.Class" id="unit">
<id property="X" column="x" />
<result property="XX" column="xx" javaType="java.lang.Double"/>
<result property="XXX" column="xxx" javaType="java.lang.Double"/>
<result property="a.X" column="ww" />
<result property="<a href="http://a.name" target="_blank" rel="nofollow" onmousedown="this.href='http://www.google.com/url?q\x3dhttp%3A%2F%2Fa.name\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNFTYJ_MbdQGVbl9uOo0kx8w3rqSMA';return true;" onclick="this.href='http://www.google.com/url?q\x3dhttp%3A%2F%2Fa.name\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNFTYJ_MbdQGVbl9uOo0kx8w3rqSMA';return true;">a.name" column="xxxx" />
<result property="a.isException" column="is_exception" />
<result property="b"  column="n" />
        <result property="c"    column="m" />
        <result property="d" column="e" />
        <result property="e"   column="q" />
        
       <discriminator javaType="int" column="qwerty">
<case value="1" resultMap="Q"/>
<case value="2" resultMap="QQ"/>
<case value="3" resultMap="QQQ"/>
<case value="4" resultMap="W"/>
            <case value="6" resultMap="WW"/>
            <case value="7" resultMap="WWW"/>
<case value="8" resultMap="E"/>
<case value="10" resultMap="EE"/>
<case value="11" resultMap="EEE"/>
<case value="15" resultMap="T"/>
<case value="13" resultMap="TT"/>
<case value="16" resultMap="TTT"/>
<case value="17" resultMap="TTTT"/>
</discriminator>
</resultMap>

So I would say, there would be around 30-50 columns per record. 
Note that the time taken is not only during fetch. But also during insert (based on similar profiling).

Java version:
JVM: Java HotSpot(TM) 64-Bit Server VM (25.60-b23, mixed mode)
Java: version 1.8.0_60, vendor Oracle Corporation

Thanks for the help. I know it might be frustrating from limited data. Please feel free to ask from any specific kind of data.

Jatin

PS: Based on looking at code, I dont think manually specifying jdbcType helps as in whatever case it would still have to do HashMap#get. I am not sure what can be done here to reduce this duration.

--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to <a href="javascript:" target="_blank" gdf-obfuscated-mailto="XP3KA88cBwAJ" rel="nofollow" onmousedown="this.href='javascript:';return true;" onclick="this.href='javascript:';return true;">mybatis-user...@googlegroups.com.
For more options, visit <a href="https://groups.google.com/d/optout" target="_blank" rel="nofollow" onmousedown="this.href='https://groups.google.com/d/optout';return true;" onclick="this.href='https://groups.google.com/d/optout';return true;">https://groups.google.com/d/optout.


--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: TypeHandlerRegistry#getTypeHandler is slow

Jatin Puri
Thing is, the results of extra time taken in TypeHandler are consistent over a few weeks now. GC might cause delay a few times, but not every time.

Instrumentation? It can be. But sampling does show the instrumentation block in case it was the culprit. It consistently shows `HashMap.get`. Any other Ideas?

On Tuesday, 30 August 2016 20:21:53 UTC+5:30, Brian Pontarelli wrote:
In my experience, these types of results are almost always caused by something else. Have you looked for GCs or locking or something else that could cause such long pauses?

Sent from my iPhone

On Aug 30, 2016, at 4:32 AM, Jatin Puri <<a href="javascript:" target="_blank" gdf-obfuscated-mailto="9VG2Q-BHBwAJ" rel="nofollow" onmousedown="this.href=&#39;javascript:&#39;;return true;" onclick="this.href=&#39;javascript:&#39;;return true;">puri...@...> wrote:

The snapshot above if via sampling and not profiling (profiling is far expensive). Sampling doesn't provide the invocation count.

Its difficult to provide invocations based on dev because the data isn't same. 

For the above image, it is based on one db call and not a summary of many calls. The stats shared was for a single database call which fetched ~150k objects. And each record had close to ~40 columns.

>>bad performance is caused by HashMap#get() and not by MyBatis code if we trust the profile.

I agree to it. Sampling can give different results at different times (as it takes diffs between quick thread dumps). Because it is giving similar snapshots each time (over a month now), I suspect the cause is with the HashMap there. 
What is surprising is that the contents of HashMap is not very large (~35 pairs in above case). Neither for the nested HashMap (normally less than 5). So I am equally surprised at the behavior. But it is dampening the experience. (If hashcode is time-consuming, most of the times it does also say that. But its native in this case, so not sure. Not sure if java8 hashmap changes has a role here)

Any hacks around it? So that the call itself could be avoided. 

A question: Does it call `getTypeHandler`/`hasTypeHandler` for each record. Or only once per query? Can using `discriminator` be the cause of it? Does `discriminator` have any known performance impacts?

Thanks,
Jatin



On Tuesday, 30 August 2016 07:12:40 UTC+5:30, Iwao AVE! wrote:
I should have been clearer, but what I was trying to say is that the bad performance is caused by HashMap#get() and not by MyBatis code if we trust the profile.
Assuming that the invocation count was one million, a code like below should take 12 seconds in your application (it might be possible with > a billion invocation).

Map<Type, JdbcType> map = new HashMap<Type, JdbcType>();
map.put(String.class, JdbcType.VARCHAR);
for (int i = 0; i < 1000000; i++) {
  map.get(Integer.class);
}

The common reason that slows down HashMap#get() is hashCode() method of the key object, but the keys used in TypeHandlerRegistry#getTypeHandler() are java.lang.reflect.Type and the enum JdbcType, so it's unlikely.
Does anyone have any idea?

Regards,
Iwao


2016-08-30 0:23 GMT+09:00 Iwao AVE! <[hidden email]>:
Thanks for the info!
Both images didn't include the invocation count, but how many were they?



2016-08-29 23:21 GMT+09:00 Jatin Puri <[hidden email]>:
Hi Iwao.

Thanks for the response. Appreciate it.

So to share the stats from production. The query takes 4-5 seconds to fetch (The response time is based on running the query via sql studio. This is also confirmed by jvisualvm. Though sometimes depending on the load, it also response in 2-3 seconds). But TypeHandlerRegistry#getTypeHandler does consume significant amount of time. 

For example, fetching latest stats:

<a href="https://lh3.googleusercontent.com/-STHVRQhyZc0/V8RC-moyq8I/AAAAAAAAR6k/GMbB1hbQLesaslWawAlkZILY6u4w6hvmQCLcB/s1600/batis3.png" style="margin-left:1em;margin-right:1em" rel="nofollow" target="_blank" onmousedown="this.href=&#39;https://lh3.googleusercontent.com/-STHVRQhyZc0/V8RC-moyq8I/AAAAAAAAR6k/GMbB1hbQLesaslWawAlkZILY6u4w6hvmQCLcB/s1600/batis3.png&#39;;return true;" onclick="this.href=&#39;https://lh3.googleusercontent.com/-STHVRQhyZc0/V8RC-moyq8I/AAAAAAAAR6k/GMbB1hbQLesaslWawAlkZILY6u4w6hvmQCLcB/s1600/batis3.png&#39;;return true;">


So as per this, the query execution time was ~1sec. But TypeHandlerRegistry#getTypeHandler took ~12 seconds.

If it helps, the resultMap is of form:
    <resultMap type="com.some.Class" id="unit">
<id property="X" column="x" />
<result property="XX" column="xx" javaType="java.lang.Double"/>
<result property="XXX" column="xxx" javaType="java.lang.Double"/>
<result property="a.X" column="ww" />
<result property="<a href="http://a.name" rel="nofollow" target="_blank" onmousedown="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2Fa.name\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNFTYJ_MbdQGVbl9uOo0kx8w3rqSMA&#39;;return true;" onclick="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2Fa.name\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNFTYJ_MbdQGVbl9uOo0kx8w3rqSMA&#39;;return true;">a.name" column="xxxx" />
<result property="a.isException" column="is_exception" />
<result property="b"  column="n" />
        <result property="c"    column="m" />
        <result property="d" column="e" />
        <result property="e"   column="q" />
        
       <discriminator javaType="int" column="qwerty">
<case value="1" resultMap="Q"/>
<case value="2" resultMap="QQ"/>
<case value="3" resultMap="QQQ"/>
<case value="4" resultMap="W"/>
            <case value="6" resultMap="WW"/>
            <case value="7" resultMap="WWW"/>
<case value="8" resultMap="E"/>
<case value="10" resultMap="EE"/>
<case value="11" resultMap="EEE"/>
<case value="15" resultMap="T"/>
<case value="13" resultMap="TT"/>
<case value="16" resultMap="TTT"/>
<case value="17" resultMap="TTTT"/>
</discriminator>
</resultMap>

So I would say, there would be around 30-50 columns per record. 
Note that the time taken is not only during fetch. But also during insert (based on similar profiling).

Java version:
JVM: Java HotSpot(TM) 64-Bit Server VM (25.60-b23, mixed mode)
Java: version 1.8.0_60, vendor Oracle Corporation

Thanks for the help. I know it might be frustrating from limited data. Please feel free to ask from any specific kind of data.

Jatin

PS: Based on looking at code, I dont think manually specifying jdbcType helps as in whatever case it would still have to do HashMap#get. I am not sure what can be done here to reduce this duration.

--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mybatis-user...@googlegroups.com.
For more options, visit <a href="https://groups.google.com/d/optout" rel="nofollow" target="_blank" onmousedown="this.href=&#39;https://groups.google.com/d/optout&#39;;return true;" onclick="this.href=&#39;https://groups.google.com/d/optout&#39;;return true;">https://groups.google.com/d/optout.


--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to <a href="javascript:" target="_blank" gdf-obfuscated-mailto="9VG2Q-BHBwAJ" rel="nofollow" onmousedown="this.href=&#39;javascript:&#39;;return true;" onclick="this.href=&#39;javascript:&#39;;return true;">mybatis-user...@googlegroups.com.
For more options, visit <a href="https://groups.google.com/d/optout" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://groups.google.com/d/optout&#39;;return true;" onclick="this.href=&#39;https://groups.google.com/d/optout&#39;;return true;">https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: TypeHandlerRegistry#getTypeHandler is slow

Iwao AVE!
Hi Jatin,

> Any hacks around it? So that the call itself could be avoided. 

I am afraid not because it is supposed to be a fast operation.

> Can using `discriminator` be the cause of it? Does `discriminator` have any known performance impacts?

I don't think so because INSERT which does not use discriminator also is slow, right?

> A question: Does it call `getTypeHandler`/`hasTypeHandler` for each record. Or only once per query?

There may be several calls per each row.
Trying to solve this issue by avoiding hasTypeHandler call does not seem to be the right approach, though.

I would try to reproduce the issue only with HashMap and the actual Class parameter.
It might also be a good idea to update Java version to the latest 8u101.

If you could provide a demo app that can reproduce the issue, I would look into it when I have the time.

Regards,
Iwao

2016-08-31 13:49 GMT+09:00 Jatin Puri <[hidden email]>:
Thing is, the results of extra time taken in TypeHandler are consistent over a few weeks now. GC might cause delay a few times, but not every time.

Instrumentation? It can be. But sampling does show the instrumentation block in case it was the culprit. It consistently shows `HashMap.get`. Any other Ideas?

--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: TypeHandlerRegistry#getTypeHandler is slow

Jatin Puri
In reply to this post by Iwao AVE!
Hi Iwao,

  1. So I tried getting the # of invocations of TypeHandlerRegistry#getTypeHandler (Hail Byte Buddy!), for 200_000 rows and (~100 columns) on some other sample project. Surprisingly there were ~217 million invocations.
  2. I then tried fetching 200_000 records with 1 column only. There were 3.8 million invocations. 
    1. 200_000 records with 2 columns have 5.8 million invocations.
    2. 200_000 records with 3 columns have 7.8 million invocations.
    3. so on...
3.8m invocations for 200,000 rows for a single column (a reasonable scenario I believe) is high I believe.

Thanks for the time and energy. Appreciate it.


PS: The code based on which the above results were made is available at: https://github.com/purijatin/sqlserver-staging-testers/tree/hashmap (branch: hashmap)
PPS: When I try running this:

On my windows machine (16gb ram. i5@3.3Ghz), it prints `3-4 sec` for each `type1` loop (Roughly ~4sec for different types. Nothing different for any class).
So this might slightly explain the production behavior. (May be sometimes there are more number of rows during fetch or higher cpu usage in prod and my desktop virtually had no other app running). Or I dont know.

And the running time is same for 1.8.0_60 and 1.8.0_102




On Tuesday, 30 August 2016 07:12:40 UTC+5:30, Iwao AVE! wrote:
I should have been clearer, but what I was trying to say is that the bad performance is caused by HashMap#get() and not by MyBatis code if we trust the profile.
Assuming that the invocation count was one million, a code like below should take 12 seconds in your application (it might be possible with > a billion invocation).

Map<Type, JdbcType> map = new HashMap<Type, JdbcType>();
map.put(String.class, JdbcType.VARCHAR);
for (int i = 0; i < 1000000; i++) {
  map.get(Integer.class);
}

The common reason that slows down HashMap#get() is hashCode() method of the key object, but the keys used in TypeHandlerRegistry#getTypeHandler() are java.lang.reflect.Type and the enum JdbcType, so it's unlikely.
Does anyone have any idea?

Regards,
Iwao


2016-08-30 0:23 GMT+09:00 Iwao AVE! <<a href="javascript:" target="_blank" gdf-obfuscated-mailto="XP3KA88cBwAJ" rel="nofollow" onmousedown="this.href=&#39;javascript:&#39;;return true;" onclick="this.href=&#39;javascript:&#39;;return true;">hara...@...>:
Thanks for the info!
Both images didn't include the invocation count, but how many were they?



2016-08-29 23:21 GMT+09:00 Jatin Puri <<a href="javascript:" target="_blank" gdf-obfuscated-mailto="XP3KA88cBwAJ" rel="nofollow" onmousedown="this.href=&#39;javascript:&#39;;return true;" onclick="this.href=&#39;javascript:&#39;;return true;">puri...@...>:
Hi Iwao.

Thanks for the response. Appreciate it.

So to share the stats from production. The query takes 4-5 seconds to fetch (The response time is based on running the query via sql studio. This is also confirmed by jvisualvm. Though sometimes depending on the load, it also response in 2-3 seconds). But TypeHandlerRegistry#getTypeHandler does consume significant amount of time. 

For example, fetching latest stats:

<a href="https://lh3.googleusercontent.com/-STHVRQhyZc0/V8RC-moyq8I/AAAAAAAAR6k/GMbB1hbQLesaslWawAlkZILY6u4w6hvmQCLcB/s1600/batis3.png" style="margin-left:1em;margin-right:1em" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://lh3.googleusercontent.com/-STHVRQhyZc0/V8RC-moyq8I/AAAAAAAAR6k/GMbB1hbQLesaslWawAlkZILY6u4w6hvmQCLcB/s1600/batis3.png&#39;;return true;" onclick="this.href=&#39;https://lh3.googleusercontent.com/-STHVRQhyZc0/V8RC-moyq8I/AAAAAAAAR6k/GMbB1hbQLesaslWawAlkZILY6u4w6hvmQCLcB/s1600/batis3.png&#39;;return true;">


So as per this, the query execution time was ~1sec. But TypeHandlerRegistry#getTypeHandler took ~12 seconds.

If it helps, the resultMap is of form:
    <resultMap type="com.some.Class" id="unit">
<id property="X" column="x" />
<result property="XX" column="xx" javaType="java.lang.Double"/>
<result property="XXX" column="xxx" javaType="java.lang.Double"/>
<result property="a.X" column="ww" />
<result property="<a href="http://a.name" target="_blank" rel="nofollow" onmousedown="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2Fa.name\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNFTYJ_MbdQGVbl9uOo0kx8w3rqSMA&#39;;return true;" onclick="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2Fa.name\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNFTYJ_MbdQGVbl9uOo0kx8w3rqSMA&#39;;return true;">a.name" column="xxxx" />
<result property="a.isException" column="is_exception" />
<result property="b"  column="n" />
        <result property="c"    column="m" />
        <result property="d" column="e" />
        <result property="e"   column="q" />
        
       <discriminator javaType="int" column="qwerty">
<case value="1" resultMap="Q"/>
<case value="2" resultMap="QQ"/>
<case value="3" resultMap="QQQ"/>
<case value="4" resultMap="W"/>
            <case value="6" resultMap="WW"/>
            <case value="7" resultMap="WWW"/>
<case value="8" resultMap="E"/>
<case value="10" resultMap="EE"/>
<case value="11" resultMap="EEE"/>
<case value="15" resultMap="T"/>
<case value="13" resultMap="TT"/>
<case value="16" resultMap="TTT"/>
<case value="17" resultMap="TTTT"/>
</discriminator>
</resultMap>

So I would say, there would be around 30-50 columns per record. 
Note that the time taken is not only during fetch. But also during insert (based on similar profiling).

Java version:
JVM: Java HotSpot(TM) 64-Bit Server VM (25.60-b23, mixed mode)
Java: version 1.8.0_60, vendor Oracle Corporation

Thanks for the help. I know it might be frustrating from limited data. Please feel free to ask from any specific kind of data.

Jatin

PS: Based on looking at code, I dont think manually specifying jdbcType helps as in whatever case it would still have to do HashMap#get. I am not sure what can be done here to reduce this duration.

--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to <a href="javascript:" target="_blank" gdf-obfuscated-mailto="XP3KA88cBwAJ" rel="nofollow" onmousedown="this.href=&#39;javascript:&#39;;return true;" onclick="this.href=&#39;javascript:&#39;;return true;">mybatis-user...@googlegroups.com.
For more options, visit <a href="https://groups.google.com/d/optout" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://groups.google.com/d/optout&#39;;return true;" onclick="this.href=&#39;https://groups.google.com/d/optout&#39;;return true;">https://groups.google.com/d/optout.


--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: TypeHandlerRegistry#getTypeHandler is slow

Jatin Puri
Hi Iwao,

Do you think this is a good enough thing to be logged as an Issue? 

Based on the results, it looks as if in (row * column) matrix, for each cell `getTypeHandler` is being called atleast 10 times. May be if we could reduce it, it would significantly reduce the number of invocations (though in a linear order).

Thanks,
Jatin

On Wednesday, 31 August 2016 18:23:54 UTC+5:30, Jatin Puri wrote:
Hi Iwao,

  1. So I tried getting the # of invocations of TypeHandlerRegistry#getTypeHandler (Hail Byte Buddy!), for 200_000 rows and (~100 columns) on some other sample project. Surprisingly there were ~217 million invocations.
  2. I then tried fetching 200_000 records with 1 column only. There were 3.8 million invocations. 
    1. 200_000 records with 2 columns have 5.8 million invocations.
    2. 200_000 records with 3 columns have 7.8 million invocations.
    3. so on...
3.8m invocations for 200,000 rows for a single column (a reasonable scenario I believe) is high I believe.

Thanks for the time and energy. Appreciate it.


PS: The code based on which the above results were made is available at: <a href="https://github.com/purijatin/sqlserver-staging-testers/tree/hashmap" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fgithub.com%2Fpurijatin%2Fsqlserver-staging-testers%2Ftree%2Fhashmap\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNG_d4jVh6N1sgVxTxaXhZYfJWh8Fg&#39;;return true;" onclick="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fgithub.com%2Fpurijatin%2Fsqlserver-staging-testers%2Ftree%2Fhashmap\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNG_d4jVh6N1sgVxTxaXhZYfJWh8Fg&#39;;return true;">https://github.com/purijatin/sqlserver-staging-testers/tree/hashmap (branch: hashmap)
PPS: When I try running <a href="https://github.com/purijatin/sqlserver-staging-testers/blob/hashmap/src/test/java/com/kilo/dao/StageDAOTest.java#L134" target="_blank" rel="nofollow" onmousedown="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fgithub.com%2Fpurijatin%2Fsqlserver-staging-testers%2Fblob%2Fhashmap%2Fsrc%2Ftest%2Fjava%2Fcom%2Fkilo%2Fdao%2FStageDAOTest.java%23L134\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNEE1hvtzfpF_zcXAFzT_v9oouRGAw&#39;;return true;" onclick="this.href=&#39;https://www.google.com/url?q\x3dhttps%3A%2F%2Fgithub.com%2Fpurijatin%2Fsqlserver-staging-testers%2Fblob%2Fhashmap%2Fsrc%2Ftest%2Fjava%2Fcom%2Fkilo%2Fdao%2FStageDAOTest.java%23L134\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNEE1hvtzfpF_zcXAFzT_v9oouRGAw&#39;;return true;">this:

On my windows machine (16gb ram. i5@3.3Ghz), it prints `3-4 sec` for each `type1` loop (Roughly ~4sec for different types. Nothing different for any class).
So this might slightly explain the production behavior. (May be sometimes there are more number of rows during fetch or higher cpu usage in prod and my desktop virtually had no other app running). Or I dont know.

And the running time is same for 1.8.0_60 and 1.8.0_102




On Tuesday, 30 August 2016 07:12:40 UTC+5:30, Iwao AVE! wrote:
I should have been clearer, but what I was trying to say is that the bad performance is caused by HashMap#get() and not by MyBatis code if we trust the profile.
Assuming that the invocation count was one million, a code like below should take 12 seconds in your application (it might be possible with > a billion invocation).

Map<Type, JdbcType> map = new HashMap<Type, JdbcType>();
map.put(String.class, JdbcType.VARCHAR);
for (int i = 0; i < 1000000; i++) {
  map.get(Integer.class);
}

The common reason that slows down HashMap#get() is hashCode() method of the key object, but the keys used in TypeHandlerRegistry#getTypeHandler() are java.lang.reflect.Type and the enum JdbcType, so it's unlikely.
Does anyone have any idea?

Regards,
Iwao


2016-08-30 0:23 GMT+09:00 Iwao AVE! <[hidden email]>:
Thanks for the info!
Both images didn't include the invocation count, but how many were they?



2016-08-29 23:21 GMT+09:00 Jatin Puri <[hidden email]>:
Hi Iwao.

Thanks for the response. Appreciate it.

So to share the stats from production. The query takes 4-5 seconds to fetch (The response time is based on running the query via sql studio. This is also confirmed by jvisualvm. Though sometimes depending on the load, it also response in 2-3 seconds). But TypeHandlerRegistry#getTypeHandler does consume significant amount of time. 

For example, fetching latest stats:

<a href="https://lh3.googleusercontent.com/-STHVRQhyZc0/V8RC-moyq8I/AAAAAAAAR6k/GMbB1hbQLesaslWawAlkZILY6u4w6hvmQCLcB/s1600/batis3.png" style="margin-left:1em;margin-right:1em" rel="nofollow" target="_blank" onmousedown="this.href=&#39;https://lh3.googleusercontent.com/-STHVRQhyZc0/V8RC-moyq8I/AAAAAAAAR6k/GMbB1hbQLesaslWawAlkZILY6u4w6hvmQCLcB/s1600/batis3.png&#39;;return true;" onclick="this.href=&#39;https://lh3.googleusercontent.com/-STHVRQhyZc0/V8RC-moyq8I/AAAAAAAAR6k/GMbB1hbQLesaslWawAlkZILY6u4w6hvmQCLcB/s1600/batis3.png&#39;;return true;">


So as per this, the query execution time was ~1sec. But TypeHandlerRegistry#getTypeHandler took ~12 seconds.

If it helps, the resultMap is of form:
    <resultMap type="com.some.Class" id="unit">
<id property="X" column="x" />
<result property="XX" column="xx" javaType="java.lang.Double"/>
<result property="XXX" column="xxx" javaType="java.lang.Double"/>
<result property="a.X" column="ww" />
<result property="<a href="http://a.name" rel="nofollow" target="_blank" onmousedown="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2Fa.name\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNFTYJ_MbdQGVbl9uOo0kx8w3rqSMA&#39;;return true;" onclick="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2Fa.name\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNFTYJ_MbdQGVbl9uOo0kx8w3rqSMA&#39;;return true;">a.name" column="xxxx" />
<result property="a.isException" column="is_exception" />
<result property="b"  column="n" />
        <result property="c"    column="m" />
        <result property="d" column="e" />
        <result property="e"   column="q" />
        
       <discriminator javaType="int" column="qwerty">
<case value="1" resultMap="Q"/>
<case value="2" resultMap="QQ"/>
<case value="3" resultMap="QQQ"/>
<case value="4" resultMap="W"/>
            <case value="6" resultMap="WW"/>
            <case value="7" resultMap="WWW"/>
<case value="8" resultMap="E"/>
<case value="10" resultMap="EE"/>
<case value="11" resultMap="EEE"/>
<case value="15" resultMap="T"/>
<case value="13" resultMap="TT"/>
<case value="16" resultMap="TTT"/>
<case value="17" resultMap="TTTT"/>
</discriminator>
</resultMap>

So I would say, there would be around 30-50 columns per record. 
Note that the time taken is not only during fetch. But also during insert (based on similar profiling).

Java version:
JVM: Java HotSpot(TM) 64-Bit Server VM (25.60-b23, mixed mode)
Java: version 1.8.0_60, vendor Oracle Corporation

Thanks for the help. I know it might be frustrating from limited data. Please feel free to ask from any specific kind of data.

Jatin

PS: Based on looking at code, I dont think manually specifying jdbcType helps as in whatever case it would still have to do HashMap#get. I am not sure what can be done here to reduce this duration.

--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mybatis-user...@googlegroups.com.
For more options, visit <a href="https://groups.google.com/d/optout" rel="nofollow" target="_blank" onmousedown="this.href=&#39;https://groups.google.com/d/optout&#39;;return true;" onclick="this.href=&#39;https://groups.google.com/d/optout&#39;;return true;">https://groups.google.com/d/optout.


--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: TypeHandlerRegistry#getTypeHandler is slow

Iwao AVE!
Hi Jatin,

Thank you for the detailed info and the demo project!
Those numbers are totally unexpected, so let me check the demo first.

Regards,
Iwao


2016-09-01 23:17 GMT+09:00 Jatin Puri <[hidden email]>:
Hi Iwao,

Do you think this is a good enough thing to be logged as an Issue? 

Based on the results, it looks as if in (row * column) matrix, for each cell `getTypeHandler` is being called atleast 10 times. May be if we could reduce it, it would significantly reduce the number of invocations (though in a linear order).

Thanks,
Jatin


On Wednesday, 31 August 2016 18:23:54 UTC+5:30, Jatin Puri wrote:
Hi Iwao,

  1. So I tried getting the # of invocations of TypeHandlerRegistry#getTypeHandler (Hail Byte Buddy!), for 200_000 rows and (~100 columns) on some other sample project. Surprisingly there were ~217 million invocations.
  2. I then tried fetching 200_000 records with 1 column only. There were 3.8 million invocations. 
    1. 200_000 records with 2 columns have 5.8 million invocations.
    2. 200_000 records with 3 columns have 7.8 million invocations.
    3. so on...
3.8m invocations for 200,000 rows for a single column (a reasonable scenario I believe) is high I believe.

Thanks for the time and energy. Appreciate it.


PS: The code based on which the above results were made is available at: https://github.com/purijatin/sqlserver-staging-testers/tree/hashmap (branch: hashmap)
PPS: When I try running this:

On my windows machine (16gb ram. i5@3.3Ghz), it prints `3-4 sec` for each `type1` loop (Roughly ~4sec for different types. Nothing different for any class).
So this might slightly explain the production behavior. (May be sometimes there are more number of rows during fetch or higher cpu usage in prod and my desktop virtually had no other app running). Or I dont know.

And the running time is same for 1.8.0_60 and 1.8.0_102

--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

TypeHandlerRegistry#getTypeHandler is slow

Iwao AVE!
Hi again,

The test project is for measuring TypeHandlerRegistry#hasTypeHandler() performance, is that correct?
As it is safe to assume that HashMap#get() consumes a lot of time because of excessive getTypeHandler() invocations, I am now trying to figure out why getTypeHandler() is called so many times.

To test a theory, could you try turning off auto-mapping and see if it improves the performance?
With discriminator, there may be some columns that are not mapped to the result map.
MyBatis tries to auto-map these columns and this process involves type handler resolution.

To turn off auto-mapping globally, set autoMappingBehavior="NONE" in MyBatis config.
If it's difficult to turn off auto-mapping globally, add autoMapping="false" to every result map referenced from inside discriminator.

This theory won't be applied to INSERT, but let's focus on SELECT for now.

Regards,
Iwao


2016-09-02 0:37 GMT+09:00 Iwao AVE! <[hidden email]>:
Hi Jatin,

Thank you for the detailed info and the demo project!
Those numbers are totally unexpected, so let me check the demo first.

Regards,
Iwao


2016-09-01 23:17 GMT+09:00 Jatin Puri <[hidden email]>:
Hi Iwao,

Do you think this is a good enough thing to be logged as an Issue? 

Based on the results, it looks as if in (row * column) matrix, for each cell `getTypeHandler` is being called atleast 10 times. May be if we could reduce it, it would significantly reduce the number of invocations (though in a linear order).

Thanks,
Jatin


On Wednesday, 31 August 2016 18:23:54 UTC+5:30, Jatin Puri wrote:
Hi Iwao,

  1. So I tried getting the # of invocations of TypeHandlerRegistry#getTypeHandler (Hail Byte Buddy!), for 200_000 rows and (~100 columns) on some other sample project. Surprisingly there were ~217 million invocations.
  2. I then tried fetching 200_000 records with 1 column only. There were 3.8 million invocations. 
    1. 200_000 records with 2 columns have 5.8 million invocations.
    2. 200_000 records with 3 columns have 7.8 million invocations.
    3. so on...
3.8m invocations for 200,000 rows for a single column (a reasonable scenario I believe) is high I believe.

Thanks for the time and energy. Appreciate it.


PS: The code based on which the above results were made is available at: https://github.com/purijatin/sqlserver-staging-testers/tree/hashmap (branch: hashmap)
PPS: When I try running this:

On my windows machine (16gb ram. i5@3.3Ghz), it prints `3-4 sec` for each `type1` loop (Roughly ~4sec for different types. Nothing different for any class).
So this might slightly explain the production behavior. (May be sometimes there are more number of rows during fetch or higher cpu usage in prod and my desktop virtually had no other app running). Or I dont know.

And the running time is same for 1.8.0_60 and 1.8.0_102

--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: TypeHandlerRegistry#getTypeHandler is slow

Jatin Puri
>>To turn off auto-mapping globally, set autoMappingBehavior="NONE" in MyBatis config.
>>If it's difficult to turn off auto-mapping globally, add autoMapping="false" to every result map referenced from inside discriminator.

I tried doing it. I see no change in the number of invocations of `getTypeHandler`.

On a side note,

private <T> TypeHandler<T> getTypeHandler(Type type, JdbcType jdbcType) {
Map<JdbcType, TypeHandler<?>> jdbcHandlerMap = TYPE_HANDLER_MAP.get(type);
TypeHandler<?> handler = null;
if (jdbcHandlerMap != null) {
handler = jdbcHandlerMap.get(jdbcType);
if (handler == null) {
handler = jdbcHandlerMap.get(null); //Line-a
}
}
if (handler == null && type != null && type instanceof Class && Enum.class.isAssignableFrom((Class<?>) type)) {
handler = new EnumTypeHandler((Class<?>) type);
}
@SuppressWarnings("unchecked")
// type drives generics here
TypeHandler<T> returned = (TypeHandler<T>) handler;
return returned;
}


I do not have data to support it (as it is very difficult to do it without updating mybatis source): I find that `jdbcHandlerMap` has `null` as key in most of the cases. In fact the block `Line-a` seems to execute much more. So may be I was wondering, if we could do:
    handler = jdbcHandlerMap.get(null);
if (handler == null) {
handler = jdbcHandlerMap.get(jdbcType); //Line-a
}

But this might not be technically correct. The idea is: If we know that we are going to call `jdbcHandlerMap.get(null)` a lot of times, we might 
give it priority. 


I still find that this method is consuming significant amount of time in production (even after restart. Mentioning restart because who knows that the previous hashcodes were creating too many collisions)

Thanks,
Jatin

PS: In my previous post, the number of invocation count is slightly incorrect as it was also accounting overloaded methods. I have fixed it and the count did get reduce. But not trivial definitely.
May be we can see on what could be done to make the method even faster or reduce # of invocations by avoiding this (hasTypeHandler calls getTypeHandler. And we specifically call getTypeHandler again later)

--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: TypeHandlerRegistry#getTypeHandler is slow

Iwao AVE!
Hi Jatin,

Thank you for trying!

It is still unclear why getTypeHandler() invocation count depends on the column count and we need to find the reason before considering code optimization.
Here is the project that I used to count getTypeHandler() calls by simply setting break points.

Running the JUnit test SimpleTest#shouldGetUnits(), there are some getTypeHandler() calls during the parsing phase, but only 3 calls for each row in the mapping phase regardless of the number of columns in the result.
Please modify the project so that it can reproduce the excessive invocations depending on the column count.

> I find that `jdbcHandlerMap` has `null` as key in most of the cases.

This is true with the current implementation, but I plan to change it after the recent discussion with Rick [1].
Nothing concrete yet, but after the change, type handler lookup will be performed with the actual jdbcType of the result column.


Regards,
Iwao

2016-09-07 21:58 GMT+09:00 Jatin Puri <[hidden email]>:
>>To turn off auto-mapping globally, set autoMappingBehavior="NONE" in MyBatis config.
>>If it's difficult to turn off auto-mapping globally, add autoMapping="false" to every result map referenced from inside discriminator.

I tried doing it. I see no change in the number of invocations of `getTypeHandler`.

On a side note,

private <T> TypeHandler<T> getTypeHandler(Type type, JdbcType jdbcType) {
Map<JdbcType, TypeHandler<?>> jdbcHandlerMap = TYPE_HANDLER_MAP.get(type);
TypeHandler<?> handler = null;
if (jdbcHandlerMap != null) {
handler = jdbcHandlerMap.get(jdbcType);
if (handler == null) {
handler = jdbcHandlerMap.get(null); //Line-a
}
}
if (handler == null && type != null && type instanceof Class && Enum.class.isAssignableFrom((Class<?>) type)) {
handler = new EnumTypeHandler((Class<?>) type);
}
@SuppressWarnings("unchecked")
// type drives generics here
TypeHandler<T> returned = (TypeHandler<T>) handler;
return returned;
}


I do not have data to support it (as it is very difficult to do it without updating mybatis source): I find that `jdbcHandlerMap` has `null` as key in most of the cases. In fact the block `Line-a` seems to execute much more. So may be I was wondering, if we could do:
    handler = jdbcHandlerMap.get(null);
if (handler == null) {
handler = jdbcHandlerMap.get(jdbcType); //Line-a
}

But this might not be technically correct. The idea is: If we know that we are going to call `jdbcHandlerMap.get(null)` a lot of times, we might 
give it priority. 


I still find that this method is consuming significant amount of time in production (even after restart. Mentioning restart because who knows that the previous hashcodes were creating too many collisions)

Thanks,
Jatin

PS: In my previous post, the number of invocation count is slightly incorrect as it was also accounting overloaded methods. I have fixed it and the count did get reduce. But not trivial definitely.
May be we can see on what could be done to make the method even faster or reduce # of invocations by avoiding this (hasTypeHandler calls getTypeHandler. And we specifically call getTypeHandler again later)


--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
For more options, visit https://groups.google.com/d/optout.